Skip to content

Problem with restoring VM from s3 backend using dplcompat. #2206

New issue
New issue
Closed
Bug
#2240
Closed
Problem with restoring VM from s3 backend using dplcompat.#2206
Bug
#2240
Assignees
arogge
Labels
bugThis addresses a bug
Milestone
25.0.0
@kamkom21

Description

@kamkom21
kamkom21
opened on Mar 11, 2025

Bareos component version

  1. bareos-fd version: 24.0.2~pre11.1b367c590
  2. bareos-dir version: 24.0.2~pre11.1b367c590
  3. bareos-sd version: 24.0.2~pre11.1b367c590
  4. bconsole version: bareos-dir Version: 24.0.2~pre11.1b367c590 (27 February 2025) Fedora 41 redhat Fedora 41
  5. bareos-storage-dplcompat, bareos-vmware-plugin, bareos-webui

Steps to reproduce

  1. Create storage device based on dplcompat using s3cmd
  2. Create backup
  3. Delete machine on Vcenter
  4. Restore machine

Expected results

  1. Complete machine restore without errors in bconsole and webui.
  2. Machine can actually start without kernel panic/bsod

Actual results

Machine fails to restore.
Vm is created in vcenter and some files are restored (for example in linux it boots to grub rescue) but it doesnt restores fully.

Environment

- OS: `Fedora Linux 41 (Server Edition)`
- Storage is based on CEPH 18.2.4 reef (stable) with ha-proxy in front of it.
- s3cmd version 2.4.0
- python3-pyvmomi.noarch 7.0.3-13.fc41 fedora
- esxi version: 7.0.3
- vcenter version: 7.0.3.00300

Relevant log output

#errors from bconsole

11-mar 15:02 bareos-dir JobId 30: Version: 24.0.2~pre11.1b367c590 (27 February 2025) Fedora 41
11-mar 15:02 bareos-dir JobId 30: Start Restore Job RestoreFiles.2025-03-11_15.02.46_32
11-mar 15:02 bareos-dir JobId 30: Connected Storage daemon at bareos-fedora-test:9103, encryption: None
11-mar 15:02 bareos-dir JobId 30:  Encryption: None
11-mar 15:02 bareos-dir JobId 30: Using Device "S3" to read.
11-mar 15:02 bareos-dir JobId 30: Connected Client: bareos-fd at localhost:9102, encryption: None
11-mar 15:02 bareos-dir JobId 30:  Handshake: Cleartext 
11-mar 15:02 bareos-dir JobId 30:  Encryption: None
11-mar 15:02 bareos-fedora-test-fd JobId 30:  Encryption: None
11-mar 15:02 bareos-sd JobId 30: Version: 24.0.2~pre11.1b367c590 (27 February 2025) Fedora 41
11-mar 15:02 bareos-sd JobId 30: Ready to read from volume "Full-0001" on device "S3" (ObjectStorage).
11-mar 15:02 bareos-sd JobId 30: Forward spacing Volume "Full-0001" to file:block 2:1645783175.
11-mar 15:02 bareos-fedora-test-fd JobId 30: Connected Storage daemon at bareos-fedora-test:9103, encryption: None
11-mar 15:02 bareos-fedora-test-fd JobId 30: python3-fd-mod: Successfully connected to VSphere API on host vcenter.kmd.local with user bareos@kmd.local
11-mar 15:02 bareos-fedora-test-fd JobId 30: Version: 24.0.2~pre11.1b367c590 (27 February 2025) Fedora 41
11-mar 15:03 bareos-sd JobId 30: Error: stored/block.cc:1117 Volume data error at 2:1895344262! Short block of 481145 bytes on device "S3" (ObjectStorage) discarded.
11-mar 15:03 bareos-sd JobId 30: Error: stored/read_record.cc:250 stored/block.cc:1117 Volume data error at 2:1895344262! Short block of 481145 bytes on device "S3" (ObjectStorage) discarded.
11-mar 15:03 bareos-sd JobId 30: End of Volume at file 2 on device "S3" (ObjectStorage), Volume "Full-0001"
11-mar 15:03 bareos-sd JobId 30: End of all volumes.
11-mar 15:03 bareos-sd JobId 30: Releasing device "S3" (ObjectStorage).
11-mar 15:04 bareos-fedora-test-fd JobId 30: Fatal error: python3-fd-mod: check_dumper(): bareos_vadp_dumper returncode: -6 error output:
Failed to Prepare For Access: The operation has been disabled by the guest operating system [20005]
bareos_vadp_dumper: ../../../../../core/src/vmware/vadp_dumper/copy_thread.cc:158: bool send_to_copy_thread(size_t, size_t): Assertion `save_data->data_len == nbyte' failed.

11-mar 15:04 bareos-fedora-test-fd JobId 30: Fatal error: python3-fd-mod: plugin_io[IO_CLOSE]: bareos_vadp_dumper returncode: -6

#errors from sd run with debug option



bareos-sd (100): lib/bsock.cc:85-0 Construct BareosSocket
bareos-sd (100): lib/jcr.cc:185-0 Construct JobControlRecord
bareos-sd (50): lib/cram_md5.cc:106-0 send: auth cram-md5 <1040198492.1741701768@R_STORAGE::bareos-sd> ssl=0
bareos-sd (100): lib/cram_md5.cc:167-0 cram-get received: auth cram-md5 <1305225292.1741701768@R_DIRECTOR::bareos-dir> ssl=0
bareos-sd (50): lib/cram_md5.cc:61-0 my_name: <R_STORAGE::bareos-sd> - challenge_name: <R_DIRECTOR::bareos-dir>
bareos-sd (99): lib/cram_md5.cc:232-0 sending resp to challenge: Jh/qO9sOp5cSPR+kc55stB
bareos-sd (90): stored/dir_cmd.cc:276-0 Message channel init completed.
bareos-sd (100): stored/job.cc:90-0 <dird: JobId=30 job=RestoreFiles.2025-03-11_15.02.46_32 job_name=RestoreFiles client_name=bareos-fd type=82 level=32 FileSet=LinuxAll NoAttr=0 SpoolAttr=0 FileSetMD5=**Dummy** SpoolData=0 PreferMountedVols=1 SpoolSize=0 rerunning=0 VolSessionId=0 VolSessionTime=0 Quota=0 Protocol=0 BackupFormat=Native
bareos-sd (100): stored/job.cc:109-0 rerunning=0 VolSesId=0 VolSesTime=0 Protocol=0
bareos-sd (50): stored/job.cc:155-30 Quota set as 0
bareos-sd (50): stored/job.cc:166-30 >dird jid=30: 3000 OK Job SDid=1 SDtime=1741701733 Authorization=BOHG-LPKN-APMH-NDIG-ICDD-AFND-EJEI-MACH
bareos-sd (100): stored/block.cc:137-30 created new block of blocksize 1048576 (dev->max_block_size)
bareos-sd (10): stored/dir_cmd.cc:1276-30 === Bootstrap file ===
bareos-sd (10): stored/dir_cmd.cc:1278-30 Storage="S3"
bareos-sd (10): stored/dir_cmd.cc:1278-30 Volume="Full-0001"
bareos-sd (10): stored/dir_cmd.cc:1278-30 MediaType="S3"
bareos-sd (10): stored/dir_cmd.cc:1278-30 Device="S3"
bareos-sd (10): stored/dir_cmd.cc:1278-30 VolSessionId=2
bareos-sd (10): stored/dir_cmd.cc:1278-30 VolSessionTime=1741694618
bareos-sd (10): stored/dir_cmd.cc:1278-30 VolAddr=10235717767-11235010686
bareos-sd (10): stored/dir_cmd.cc:1278-30 FileIndex=4
bareos-sd (10): stored/dir_cmd.cc:1278-30 FileIndex=6
bareos-sd (10): stored/dir_cmd.cc:1278-30 Count=2
bareos-sd (10): stored/dir_cmd.cc:1278-30 Storage="S3"
bareos-sd (10): stored/dir_cmd.cc:1278-30 Volume="Full-0001"
bareos-sd (10): stored/dir_cmd.cc:1278-30 MediaType="S3"
bareos-sd (10): stored/dir_cmd.cc:1278-30 Device="S3"
bareos-sd (10): stored/dir_cmd.cc:1278-30 VolSessionId=2
bareos-sd (10): stored/dir_cmd.cc:1278-30 VolSessionTime=1741694618
bareos-sd (10): stored/dir_cmd.cc:1278-30 VolAddr=11235010687-11747142295
bareos-sd (10): stored/dir_cmd.cc:1278-30 FileIndex=6
bareos-sd (10): stored/dir_cmd.cc:1278-30 Count=1
bareos-sd (10): stored/dir_cmd.cc:1282-30 === end bootstrap file ===
bareos-sd (100): lib/lex.cc:315-30 glob /var/lib/bareos/bareos-sd.RestoreFiles.2025-03-11_15.02.46_32.1.bootstrap: 1 files
bareos-sd (100): lib/lex.cc:214-30 open config file: /var/lib/bareos/bareos-sd.RestoreFiles.2025-03-11_15.02.46_32.1.bootstrap
Next        : 0x68130470
Root bsr    : 0x6812eee0
VolumeName  : Full-0001
  MediaType : S3
  Device    : S3
  Slot      : 0
SessId      : 2
SessTime    : 1741694618
VolAddr    : 10235717767-11235010686
FileIndex   : 4
FileIndex   : 6
count       : 2
found       : 0
done        : no
positioning : 1
fast_reject : 1

Next        : 0x0
Root bsr    : 0x6812eee0
VolumeName  : Full-0001
  MediaType : S3
  Device    : S3
  Slot      : 0
SessId      : 2
SessTime    : 1741694618
VolAddr    : 11235010687-11747142295
FileIndex   : 6
count       : 1
found       : 0
done        : no
positioning : 0
fast_reject : 0
bareos-sd (50): stored/job.cc:199-30 RestoreFiles.2025-03-11_15.02.46_32 waiting 1800 sec for FD to contact SD key=BOHG-LPKN-APMH-NDIG-ICDD-AFND-EJEI-MACH
bareos-sd (100): lib/bsock.cc:85-0 Construct BareosSocket
bareos-sd (50): stored/fd_cmds.cc:116-0 Found Job RestoreFiles.2025-03-11_15.02.46_32
bareos-sd (50): lib/cram_md5.cc:106-0 send: auth cram-md5 <1546158251.1741701770@R_STORAGE::bareos-sd> ssl=0
bareos-sd (100): lib/cram_md5.cc:167-0 cram-get received: auth cram-md5 <694789742.1741701770@R_CLIENT::bareos-fedora-test-fd> ssl=0
bareos-sd (50): lib/cram_md5.cc:61-0 my_name: <R_STORAGE::bareos-sd> - challenge_name: <R_CLIENT::bareos-fedora-test-fd>
bareos-sd (99): lib/cram_md5.cc:232-0 sending resp to challenge: t41yzThcI8+XE4JBMQsYTD
bareos-sd (50): stored/fd_cmds.cc:141-0 OK Authentication jid=30 Job RestoreFiles.2025-03-11_15.02.46_32
bareos-sd (50): stored/job.cc:213-30 Auth=1 canceled=0
bareos-sd (100): stored/fd_cmds.cc:383-30 ReadOpenSession got: JobId=30 Vol=DummyVolume VolSessId=1 VolSessT=1741701733
bareos-sd (100): stored/fd_cmds.cc:388-30   StartF=0 EndF=0 StartB=0 EndB=0
bareos-sd (20): stored/read.cc:64-30 Start read data.
bareos-sd (100): stored/acquire.cc:106-30 dcr=7f9d6802e720 dev=7f9d68001e40
bareos-sd (100): stored/acquire.cc:107-30 MediaType dcr=S3 dev=S3
bareos-sd (100): stored/acquire.cc:137-30 Want Vol=Full-0001 Slot=0
bareos-sd (100): stored/acquire.cc:149-30 MediaType dcr=S3 dev=S3
bareos-sd (100): stored/acquire.cc:214-30 MediaType dcr=S3 dev=S3
bareos-sd (100): stored/acquire.cc:232-30 DirGetVolumeInfo vol=Full-0001
bareos-sd (50): stored/askdir.cc:185-30 >dird CatReq Job=RestoreFiles.2025-03-11_15.02.46_32 GetVolInfo VolName=Full-0001 write=0
bareos-sd (50): stored/askdir.cc:116-30 <dird 1000 OK VolName=Full-0001 VolJobs=6 VolFiles=2 VolBlocks=11208 VolBytes=11747594501 VolMounts=7 VolErrors=0 VolWrites=11208 MaxVolBytes=53687091200 VolCapacityBytes=0 VolStatus=Append Slot=0 MaxVolJobs=0 MaxVolFiles=0 InChanger=0 VolReadTime=63302587 VolWriteTime=42611786 EndFile=2 EndBlock=3157659908 LabelType=0 MediaId=1 EncryptionKey= MinBlocksize=0 MaxBlocksize=0
bareos-sd (50): stored/askdir.cc:146-30 DoGetVolumeInfo return true slot=0 Volume=Full-0001, VolminBlocksize=0 VolMaxBlocksize=0
bareos-sd (50): stored/askdir.cc:150-30 setting dcr->VolMinBlocksize(0) to vol.VolMinBlocksize(0)
bareos-sd (50): stored/askdir.cc:153-30 setting dcr->VolMaxBlocksize(0) to vol.VolMaxBlocksize(0)
bareos-sd (100): stored/mount.cc:608-30 No swap_dev set
bareos-sd (100): stored/mount.cc:562-30 Must load "S3" (ObjectStorage)
bareos-sd (100): stored/autochanger.cc:125-30 Device "S3" (ObjectStorage) is not attached to an autochanger
bareos-sd (100): stored/acquire.cc:266-30 stored: open vol=Full-0001
bareos-sd (100): stored/dev.cc:510-30 open dev: type=1744838592 archive_device_string="S3" (ObjectStorage) vol=Full-0001 mode=OPEN_READ_ONLY
bareos-sd (100): stored/dev.cc:528-30 call OpenDevice mode=OPEN_READ_ONLY
bareos-sd (100): stored/dev.cc:593-30 open archive: mode=OPEN_READ_ONLY open(ObjectStorage/Full-0001, 00000000, 0640)
bareos-sd (100): backends/chunked_device.cc:106-30 New allocated buffer of 262144000 bytes at 7f9d50400010
bareos-sd (100): stored/dev.cc:614-30 open dev: disk fd=0 opened
bareos-sd (100): stored/dev.cc:534-30 preserve=15547773746 fd=0
bareos-sd (100): stored/acquire.cc:275-30 opened dev "S3" (ObjectStorage) OK
bareos-sd (100): stored/acquire.cc:285-30 calling read-vol-label
bareos-sd (100): stored/dev.cc:453-30 setting minblocksize to 64512, maxblocksize to label_block_size=64512, on device "S3" (ObjectStorage)
bareos-sd (100): stored/block.cc:137-30 created new block of blocksize 64512 (dev->max_block_size)
bareos-sd (100): stored/dev.cc:467-30 created new block of buf_len: 64512 on device "S3" (ObjectStorage)
bareos-sd (100): stored/label.cc:87-30 Enter ReadVolumeLabel res=1 device="S3" (ObjectStorage) vol=Full-0001 dev_Vol=*NULL* max_blocksize=64512
bareos-sd (100): stored/label.cc:244-30 Call reserve_volume=Full-0001
bareos-sd (100): stored/dev.cc:376-30 Device "S3" (ObjectStorage) has dev->device->max_block_size of 1048576 and dev->max_block_size of 64512, dcr->VolMaxBlocksize is 0
bareos-sd (100): stored/dev.cc:385-30 setting dev->max_block_size to dev->device_resource->max_block_size=1048576 on device "S3" (ObjectStorage) because dcr->VolMaxBlocksize is 0
bareos-sd (100): stored/dev.cc:426-30 set minblocksize to 0, maxblocksize to 1048576 on device "S3" (ObjectStorage)
bareos-sd (100): stored/dev.cc:434-30 created new block of buf_len: 1048576 on device "S3" (ObjectStorage)
bareos-sd (100): stored/block.cc:137-30 created new block of blocksize 1048576 (dev->max_block_size)
bareos-sd (100): stored/dev.cc:438-30 created new block of buf_len: 1048576 on device "S3" (ObjectStorage), freeing block
bareos-sd (100): stored/acquire.cc:291-30 Got correct volume.
bareos-sd (100): stored/acquire.cc:387-30 dcr=7f9d6802e720 dev=7f9d68001e40
bareos-sd (100): stored/acquire.cc:388-30 MediaType dcr=S3 dev=S3
bareos-sd (100): stored/dev.cc:846-30 ===== lseek to 1645783175
bareos-sd (100): backends/dplcompat_device.cc:286-30 could not parse data returned by "/usr/lib/bareos/scripts/s3cmd-wrapper.sh" stat "Full-0001" "0040"
bareos-sd (90): stored/mount.cc:872-30 NumReadVolumes=1 CurReadVolume=1
bareos-sd (90): stored/mount.cc:891-30 End of Device reached.
bareos-sd (100): backends/chunked_device.cc:1091-30 volume: Full-0001, RemoteVolumeSize = 11747594501, VolCatInfo.VolCatBytes = 11747594501
bareos-sd (100): stored/acquire.cc:517-30 releasing device "S3" (ObjectStorage)
bareos-sd (50): stored/askdir.cc:299-30 Update cat VolBytes=11747594501
bareos-sd (50): stored/askdir.cc:318-30 >dird CatReq Job=RestoreFiles.2025-03-11_15.02.46_32 UpdateMedia VolName=Full-0001 VolJobs=6 VolFiles=2 VolBlocks=11208 VolBytes=11747594501 VolMounts=7 VolErrors=0 VolWrites=11208 MaxVolBytes=53687091200 EndTime=1741701832 VolStatus=Append Slot=0 relabel=0 InChanger=0 VolReadTime=68340641 VolWriteTime=42611786 VolFirstWritten=0
bareos-sd (50): stored/askdir.cc:116-30 <dird 1000 OK VolName=Full-0001 VolJobs=6 VolFiles=2 VolBlocks=11208 VolBytes=11747594501 VolMounts=7 VolErrors=0 VolWrites=11208 MaxVolBytes=53687091200 VolCapacityBytes=0 VolStatus=Append Slot=0 MaxVolJobs=0 MaxVolFiles=0 InChanger=0 VolReadTime=68340641 VolWriteTime=42611786 EndFile=2 EndBlock=3157659908 LabelType=0 MediaId=1 EncryptionKey= MinBlocksize=0 MaxBlocksize=0
bareos-sd (50): stored/askdir.cc:146-30 DoGetVolumeInfo return true slot=0 Volume=Full-0001, VolminBlocksize=0 VolMaxBlocksize=0
bareos-sd (50): stored/askdir.cc:150-30 setting dcr->VolMinBlocksize(0) to vol.VolMinBlocksize(0)
bareos-sd (50): stored/askdir.cc:153-30 setting dcr->VolMaxBlocksize(0) to vol.VolMaxBlocksize(0)
bareos-sd (100): stored/acquire.cc:581-30 0 writers, 0 reserve, dev="S3" (ObjectStorage)
bareos-sd (100): stored/dev.cc:891-30 close_dev "S3" (ObjectStorage)
bareos-sd (100): backends/chunked_device.cc:115-30 Freeing buffer of 262144000 bytes at 7f9d50400010
bareos-sd (100): stored/dev.cc:984-30 Enter unmount
bareos-sd (100): stored/dev.cc:879-30 Clear volhdr vol=Full-0001
bareos-sd (100): stored/acquire.cc:636-30 JobId=30 broadcast wait_device_release at 11-mar-2025 15:03:52
bareos-sd (100): stored/acquire.cc:656-30 Device "S3" (ObjectStorage) released by JobId=30
bareos-sd (30): stored/read.cc:101-30 Done reading.
bareos-sd (100): lib/jcr.cc:378-30 Destruct JobControlRecord
bareos-sd (100): lib/bsock.cc:137-30 Destruct BareosSocket
bareos-sd (100): lib/bsys.cc:663-30 write_last_jobs seek to 192
bareos-sd (100): lib/jcr.cc:268-30 FreeCommonJcr: 7f9d680008e0 
bareos-sd (100): lib/bsock.cc:137-0 Destruct BareosSocket
bareos-sd (100): lib/bsock.cc:85-0 Construct BareosSocket
bareos-sd (100): lib/jcr.cc:185-0 Construct JobControlRecord
bareos-sd (50): lib/cram_md5.cc:106-0 send: auth cram-md5 <1168851143.1741701852@R_STORAGE::bareos-sd> ssl=0
bareos-sd (100): lib/cram_md5.cc:167-0 cram-get received: auth cram-md5 <1488278457.1741701852@R_DIRECTOR::bareos-dir> ssl=0
bareos-sd (50): lib/cram_md5.cc:61-0 my_name: <R_STORAGE::bareos-sd> - challenge_name: <R_DIRECTOR::bareos-dir>
bareos-sd (99): lib/cram_md5.cc:232-0 sending resp to challenge: B4/Zx++kVU4Kj+lQ75+f3D
bareos-sd (90): stored/dir_cmd.cc:276-0 Message channel init completed.
bareos-sd (100): lib/jcr.cc:378-0 Destruct JobControlRecord
bareos-sd (100): lib/jcr.cc:268-0 FreeCommonJcr: 7f9d680008e0 
bareos-sd (100): lib/bsock.cc:137-0 Destruct BareosSocket

Relevant traces output



Anything else?


No response
Metadata
Metadata
Assignees
Labels
bugThis addresses a bug
Type
Bug
Projects
No projects
Milestone
Relationships
None yet
Development
No branches or pull requests
Issue actions