3

I will try to explain the problem I am facing:

When I restore one client's backup that uses two "volumes", I get this error:

bacula-dir JobId 48945: Fatal error: Bad response to Storage command: wanted 2000 OK storage, got 2800 End Job TermCode=69 JobFiles=32293 ReadBytes=8946396913 JobBytes=10298059235 Errors=1 VSS=0 Encrypt=0 CommBytes=232 CompressCommBytes=232

I have tried to find a solution for this issue. Some people say that is a NFS error, but only occurs when the restore touches more than one volume.

If I run a restore job from a single volume, the restore works well.

When I run bacula-fd in debug mode (bacula-fd -v -c /etc/bacula/bacula-fd.conf -f -d 100) the output is:

bacula: restore.c:540-49097 === msglen=155 attrExlen=0 msg=287476 3 /var/www/midomain.com/shared/src/uploads/downloads/eusk706.mp3
bacula: create_file.c:208-49097 Create=/tmp/bacula-restores/var/www/midomain.com/shared/src/uploads/downloads/eusk706.mp3
bacula: attribs.c:558-49097 File size of restored file /tmp/bacula-restores/var/www/midomain.com/shared/src/uploads/downloads/eusk706.mp3 not correct. Original 2581274, restored 131072.
bacula: restore.c:1034-49097 End Do Restore. Files=19300 Bytes=7333538565
bacula: heartbeat.c:141-49097 Send kill to heartbeat id
bacula: job.c:2534-49097 filed>stored: read close session 160
bacula: job.c:2548-49097 Done in job.c
bacula: job.c:2551-49097 2000 OK storage end
bacula: job.c:2576-49097 end_restore_cmd
bacula: job.c:333-49097 Quit command loop. Canceled=1
bacula: job.c:456-49097 Calling term_find_files
bacula: job.c:459-49097 Done with term_find_files
bacula: jcr.c:174-49097 write_last_jobs seek to 192
bacula: job.c:462-0 Done with free_jcr

Can this be caused by a configuration error? Any other options?

I started having this problem on Bacula 7.0.4. I have upgraded Bacula to version 9.0.5, but the issue still persists.

The clients are located in different networks and I have one storage configured for each network.

Config files:

Client

Client {
    Name = myServer
    Address = 192.168.2.222
    Catalog = MyCatalog
    Password = "***"
    File Retention = 15 days
    Job Retention = 15 days
    Autoprune = yes
    Maximum Concurrent Jobs = 6
}

Job {
    Name = "myServer"
    Type = Backup
    Client = myServer
    FileSet = "myServer"
    Storage = FileRedDos
    Messages = Standard
    Pool = File
    Schedule = Miercoles
    Maximum Concurrent Jobs = 4
}

FileSet {
    Name = "myServer"
    Include {
        File = /var/www
        File = /etc
        Options {
            signature = MD5
            compression = GZIP
        }
    }
    Exclude {
    }
}

Storage

Storage {
    Name = FileRedDos
    Address = 192.168.2.25
    SDPort = 9103
    Password = "***"
    Device = Freenas
    Media Type = File
    Maximum Concurrent Jobs = 20
}

Pool

Pool {
    Name = File
    Pool Type = Backup
    Recycle = yes
    AutoPrune = yes
    Volume Retention = 30 days
    Maximum Volume Bytes = 10G
    Maximum Volumes = 1000
    Label Format = "VolBacula-"
}

Schedule

Schedule {
    Name = Miercoles
    Run = Full wednesday at 03:00
    Run = Incremental thursday-tuesday at 01:00
}

Device

Device {
  Name = Freenas
  Media Type = File
  Archive Device = /backup/baculaVolumes
  LabelMedia = yes;
  Random Access = Yes;
  RemovableMedia = no;
  Maximum Concurrent Jobs = 20
}

EDIT:

Option 1 - Configuration error

Firstly, have you done a restore before with this configuration?

Yes, so far everything worked fine, we could recover any server.

Our Restore Job:

Job {
  Name = "RestoreFiles"
  Type = Restore
  Client=bacula-fd
  FileSet="Full Set"
  Storage = File
  Pool = File
  Messages = Standard
  Where = /tmp/bacula-restores
}

Option 2 - Protocol Error

from inconsistent name resolution (e.g. server and client have different ideas about what the name of each is), or

The name servers and IPs have not been changed. Anyway, i can restore some files, it only crashes when volume storage changes.

protocol errors (e.g. or one is set for IPv4 whereas the other defaults to IPv6) or

We change this nothing about IPv protocol. All configuration files have only IPv4 IPs, we don't use DNS resolution.

version errors (server and client need to be compatible versions)

All client versions are 7.0.5 (28 July 2014) and the server versions (fd, sd, dir) are: 9.0.5 (02 November 2017)

There has been discussion about this particular scenario on the mailing list but, from my experience, it always boils down to one of these 3 (or 4) things.

We read some about this, but we have not found any solution.

EDIT 2 - All in debug -:

can you include logs before Fatal Error server-side

bacula-fd error:

bacula: restore.c:540-50582 === msglen=163 attrExlen=0 msg=293522 3 /var/www/myhostname/shared/src/uploads/2012/05/frChicago_Built_0853_GP_PR.jpeg
bacula: create_file.c:208-50582 Create=/tmp/bacula-restores/var/www/myhostname/shared/src/uploads/2012/05/frChicago_Built_0853_GP_PR.jpeg
bacula: attribs.c:558-50582 File size of restored file /tmp/bacula-restores/var/www/myhostname/shared/src/uploads/2012/05/frChicago_Built_0853_GP_PR.jpeg not correct. Original 245356, restored 196608.
bacula: restore.c:1034-50582 End Do Restore. Files=28688 Bytes=9807931793
bacula: heartbeat.c:141-50582 Send kill to heartbeat id
bacula: job.c:2534-50582 filed>stored: read close session 1
bacula: job.c:2548-50582 Done in job.c
bacula: job.c:2551-50582 2000 OK storage end
bacula: job.c:2576-50582 end_restore_cmd
bacula: job.c:333-50582 Quit command loop. Canceled=1
bacula: job.c:456-50582 Calling term_find_files
bacula: job.c:459-50582 Done with term_find_files
bacula: jcr.c:174-50582 write_last_jobs seek to 192
bacula: job.c:462-0 Done with free_jcr

bacula-dir error:

Not appears an error, I attach you some traces:

bacula-dir: mysql.c:113-0 DB REopen bacula
bacula-dir: next_vol.c:111-0 find_next_vol_for_append: JobId=0 PoolId=2, MediaType=File index=1 create=0 prune=0
bacula-dir: sql_find.c:454-0 fnextvol=SELECT MediaId,VolumeName,VolJobs,VolFiles,VolBlocks,VolBytes,VolMounts,VolErrors,VolWrites,MaxVolBytes,VolCapacityBytes,MediaType,VolStatus,PoolId,VolRetention,VolUseDuration,MaxVolJobs,MaxVolFiles,Recycle,Slot,FirstWritten,LastWritten,InChanger,EndFile,EndBlock,VolType,VolParts,VolCloudParts,LastPartBytes,LabelType,LabelDate,StorageId,Enabled,LocationId,RecycleCount,InitialWrite,ScratchPoolId,RecyclePoolId,VolReadTime,VolWriteTime,ActionOnPurge,CacheRetention FROM Media WHERE PoolId=2 AND MediaType='File' AND Enabled=1 AND VolStatus='Append'    ORDER BY LastWritten IS NULL,LastWritten DESC,MediaId LIMIT 1
bacula-dir: sql_find.c:536-0 Rtn numrows=1
bacula-dir: next_vol.c:227-0 VolJobs=4 FirstWritten=1511755556
bacula-dir: next_vol.c:320-0 Vol=VolBacula-0315 expired=0
bacula-dir: next_vol.c:242-0 return ok=1 find_next_vol
bacula-dir: mysql.c:325-0 closedb ref=1 connected=1 db=7f9bd404ca80
bacula-dir: job.c:1760-0 wstorage=FileRedDos
bacula-dir: job.c:1769-0 wstore=FileRedDos where=Job resource
bacula-dir: ua_output.c:938-0 complete_jcr open db
bacula-dir: mysql.c:113-0 DB REopen bacula
bacula-dir: next_vol.c:111-0 find_next_vol_for_append: JobId=0 PoolId=2, MediaType=File index=1 create=0 prune=0
bacula-dir: sql_find.c:454-0 fnextvol=SELECT MediaId,VolumeName,VolJobs,VolFiles,VolBlocks,VolBytes,VolMounts,VolErrors,VolWrites,MaxVolBytes,VolCapacityBytes,MediaType,VolStatus,PoolId,VolRetention,VolUseDuration,MaxVolJobs,MaxVolFiles,Recycle,Slot,FirstWritten,LastWritten,InChanger,EndFile,EndBlock,VolType,VolParts,VolCloudParts,LastPartBytes,LabelType,LabelDate,StorageId,Enabled,LocationId,RecycleCount,InitialWrite,ScratchPoolId,RecyclePoolId,VolReadTime,VolWriteTime,ActionOnPurge,CacheRetention FROM Media WHERE PoolId=2 AND MediaType='File' AND Enabled=1 AND VolStatus='Append'    ORDER BY LastWritten IS NULL,LastWritten DESC,MediaId LIMIT 1
bacula-dir: sql_find.c:536-0 Rtn numrows=1
bacula-dir: next_vol.c:227-0 VolJobs=4 FirstWritten=1511755556
bacula-dir: next_vol.c:320-0 Vol=VolBacula-0315 expired=0
bacula-dir: next_vol.c:242-0 return ok=1 find_next_vol
bacula-dir: mysql.c:325-0 closedb ref=1 connected=1 db=7f9bd404ca80
bacula-dir: job.c:1760-0 wstorage=FileRedTres
bacula-dir: job.c:1769-0 wstore=FileRedTres where=Job resource
bacula-dir: ua_output.c:938-0 complete_jcr open db
bacula-dir: mysql.c:113-0 DB REopen bacula
bacula-dir: next_vol.c:111-0 find_next_vol_for_append: JobId=0 PoolId=2, MediaType=File index=1 create=0 prune=0
bacula-dir: sql_find.c:454-0 fnextvol=SELECT MediaId,VolumeName,VolJobs,VolFiles,VolBlocks,VolBytes,VolMounts,VolErrors,VolWrites,MaxVolBytes,VolCapacityBytes,MediaType,VolStatus,PoolId,VolRetention,VolUseDuration,MaxVolJobs,MaxVolFiles,Recycle,Slot,FirstWritten,LastWritten,InChanger,EndFile,EndBlock,VolType,VolParts,VolCloudParts,LastPartBytes,LabelType,LabelDate,StorageId,Enabled,LocationId,RecycleCount,InitialWrite,ScratchPoolId,RecyclePoolId,VolReadTime,VolWriteTime,ActionOnPurge,CacheRetention FROM Media WHERE PoolId=2 AND MediaType='File' AND Enabled=1 AND VolStatus='Append'    ORDER BY LastWritten IS NULL,LastWritten DESC,MediaId LIMIT 1
bacula-dir: sql_find.c:536-0 Rtn numrows=1
bacula-dir: next_vol.c:227-0 VolJobs=4 FirstWritten=1511755556
bacula-dir: next_vol.c:320-0 Vol=VolBacula-0315 expired=0
bacula-dir: next_vol.c:242-0 return ok=1 find_next_vol
bacula-dir: mysql.c:325-0 closedb ref=1 connected=1 db=7f9bd404ca80
bacula-dir: job.c:1760-0 wstorage=FileRedDos
bacula-dir: job.c:1769-0 wstore=FileRedDos where=Job resource
bacula-dir: ua_output.c:938-0 complete_jcr open db
bacula-dir: mysql.c:113-0 DB REopen bacula
bacula-dir: next_vol.c:111-0 find_next_vol_for_append: JobId=0 PoolId=2, MediaType=File index=1 create=0 prune=0
bacula-dir: sql_find.c:454-0 fnextvol=SELECT MediaId,VolumeName,VolJobs,VolFiles,VolBlocks,VolBytes,VolMounts,VolErrors,VolWrites,MaxVolBytes,VolCapacityBytes,MediaType,VolStatus,PoolId,VolRetention,VolUseDuration,MaxVolJobs,MaxVolFiles,Recycle,Slot,FirstWritten,LastWritten,InChanger,EndFile,EndBlock,VolType,VolParts,VolCloudParts,LastPartBytes,LabelType,LabelDate,StorageId,Enabled,LocationId,RecycleCount,InitialWrite,ScratchPoolId,RecyclePoolId,VolReadTime,VolWriteTime,ActionOnPurge,CacheRetention FROM Media WHERE PoolId=2 AND MediaType='File' AND Enabled=1 AND VolStatus='Append'    ORDER BY LastWritten IS NULL,LastWritten DESC,MediaId LIMIT 1
bacula-dir: sql_find.c:536-0 Rtn numrows=1
bacula-dir: next_vol.c:227-0 VolJobs=4 FirstWritten=1511755556
bacula-dir: next_vol.c:320-0 Vol=VolBacula-0315 expired=0
bacula-dir: next_vol.c:242-0 return ok=1 find_next_vol
bacula-dir: mysql.c:325-0 closedb ref=1 connected=1 db=7f9bd404ca80
bacula-dir: job.c:1760-0 wstorage=FileRedDos
bacula-dir: job.c:1769-0 wstore=FileRedDos where=Job resource
bacula-dir: ua_output.c:938-0 complete_jcr open db
bacula-dir: mysql.c:113-0 DB REopen bacula
bacula-dir: next_vol.c:111-0 find_next_vol_for_append: JobId=0 PoolId=2, MediaType=File index=1 create=0 prune=0
bacula-dir: sql_find.c:454-0 fnextvol=SELECT MediaId,VolumeName,VolJobs,VolFiles,VolBlocks,VolBytes,VolMounts,VolErrors,VolWrites,MaxVolBytes,VolCapacityBytes,MediaType,VolStatus,PoolId,VolRetention,VolUseDuration,MaxVolJobs,MaxVolFiles,Recycle,Slot,FirstWritten,LastWritten,InChanger,EndFile,EndBlock,VolType,VolParts,VolCloudParts,LastPartBytes,LabelType,LabelDate,StorageId,Enabled,LocationId,RecycleCount,InitialWrite,ScratchPoolId,RecyclePoolId,VolReadTime,VolWriteTime,ActionOnPurge,CacheRetention FROM Media WHERE PoolId=2 AND MediaType='File' AND Enabled=1 AND VolStatus='Append'    ORDER BY LastWritten IS NULL,LastWritten DESC,MediaId LIMIT 1
bacula-dir: sql_find.c:536-0 Rtn numrows=1
bacula-dir: next_vol.c:227-0 VolJobs=4 FirstWritten=1511755556
bacula-dir: next_vol.c:320-0 Vol=VolBacula-0315 expired=0
bacula-dir: next_vol.c:242-0 return ok=1 find_next_vol
bacula-dir: mysql.c:325-0 closedb ref=1 connected=1 db=7f9bd404ca80
bacula-dir: job.c:1760-0 wstorage=FileRedDos
bacula-dir: job.c:1769-0 wstore=FileRedDos where=Job resource
bacula-dir: ua_output.c:938-0 complete_jcr open db

bacula-sd error

I attach you all log:

bacula-sd: label.c:987-50582 reclen=195 recdata=Bacula 1.0 immortal
bacula-sd: label.c:989-50582 reclen=195 recdata=Bacula 1.0 immortal

Volume Label:
Adata             : 0
Id                : Bacula 1.0 immortal
VerNo             : 11
VolName           : VolBacula-0553
PrevVolName       :
VolFile           : 0
LabelType         : VOL_LABEL
LabelSize         : 195
PoolName          : File
MediaType         : File
PoolType          : Backup
HostName          : myhostname
Date label written: 12-jun-2016 00:56
bacula-sd: label.c:1027-50582 Leave: bool unser_volume_label(DEVICE*, DEV_RECORD*)
bacula-sd: label.c:149-50582 VolHdr.Id OK: Bacula 1.0 immortal

bacula-sd: label.c:188-50582 VolHdr.VerNum=11 OK.

Volume Label:
Adata             : 0
Id                : Bacula 1.0 immortal
VerNo             : 11
VolName           : VolBacula-0553
PrevVolName       :
VolFile           : 0
LabelType         : VOL_LABEL
LabelSize         : 195
PoolName          : File
MediaType         : File
PoolType          : Backup
HostName          : myhostname
Date label written: 12-jun-2016 00:56
bacula-sd: label.c:258-50582 Leave read_volume_label() VOL_OK
bacula-sd: file_dev.c:71-50582 Enter: virtual bool DEVICE::rewind(DCR*)
bacula-sd: label.c:271-50582 Call reserve_volume=VolBacula-0553
bacula-sd: label.c:284-50582 Leave: virtual int DEVICE::read_dev_volume_label(DCR*)
bacula-sd: acquire.c:246-50582 Got correct volume. VOL_OK: VolBacula-0553
bacula-sd: acquire.c:354-50582 dcr=7fc86c008c48 dev=7fc86c001208
bacula-sd: acquire.c:355-50582 MediaType dcr=File dev=File
bacula-sd: acquire.c:357-50582 Leave: bool acquire_device_for_read(DCR*)
bacula-sd: file_dev.c:107-50582 ===== lseek to 6001227206
bacula-sd: file_dev.c:107-50582 ===== lseek to 6999808230
bacula-sd: file_dev.c:107-50582 ===== lseek to 8999744649
bacula-sd: file_dev.c:107-50582 ===== lseek to 9999422519
bacula-sd: block.c:563-50582 block.c:560 Read zero bytes Vol=VolBacula-0553 at 10737375259 on device "Freenas" (/backup/baculaVolumes).
bacula-sd: block.c:563-50582 block.c:560 Read zero bytes Vol=VolBacula-0553 at 10737375259 on device "Freenas" (/backup/baculaVolumes).
bacula-sd: mount.c:858-50582 NumReadVolumes=2 CurReadVolume=1
bacula-sd: dev.c:271-50582 close_dev vol=VolBacula-0553 fd=7 dev=7fc86c001208 adata=0 dev="Freenas" (/backup/baculaVolumes)
bacula-sd: file_dev.c:71-50582 Enter: virtual bool DEVICE::rewind(DCR*)
bacula-sd: dev.c:252-50582 Clear volhdr vol=VolBacula-0553
bacula-sd: acquire.c:54-50582 Enter: bool acquire_device_for_read(DCR*)
bacula-sd: acquire.c:58-50582 dcr=7fc86c008c48 dev=7fc86c001208
bacula-sd: acquire.c:59-50582 MediaType dcr=File dev=File
bacula-sd: acquire.c:92-50582 Want Vol=VolBacula-0294 Slot=0
bacula-sd: acquire.c:106-50582 MediaType dcr=File dev=File
bacula-sd: acquire.c:183-50582 MediaType dcr=File dev=File
bacula-sd: acquire.c:200-50582 dir_get_volume_info vol=VolBacula-0294
bacula-sd: mount.c:636-50582 No swap_dev set. dev->vol=0
bacula-sd: mount.c:591-50582 Must load dev="Freenas" (/backup/baculaVolumes)
bacula-sd: autochanger.c:105-50582 Device "Freenas" (/backup/baculaVolumes) is not an autochanger
bacula-sd: acquire.c:231-50582 open vol=VolBacula-0294
bacula-sd: file_dev.c:138-50582 Enter: virtual bool file_dev::open_device(DCR*, int)
bacula-sd: file_dev.c:184-50582 open disk: mode=OPEN_READ_ONLY open(/backup/baculaVolumes/VolBacula-0294, 0x0, 0640)
bacula-sd: file_dev.c:194-50582 Did open(/backup/baculaVolumes/VolBacula-0294,OPEN_READ_ONLY,0640)
bacula-sd: file_dev.c:211-50582 open dev: disk fd=7 opened
bacula-sd: file_dev.c:214-50582 Leave: virtual bool file_dev::open_device(DCR*, int)
bacula-sd: acquire.c:239-50582 opened dev "Freenas" (/backup/baculaVolumes) OK
bacula-sd: acquire.c:242-50582 calling read-vol-label
bacula-sd: label.c:72-50582 Enter: virtual int DEVICE::read_dev_volume_label(DCR*)
bacula-sd: label.c:75-50582 Enter read_volume_label adata=0 res=1 device="Freenas" (/backup/baculaVolumes) vol=VolBacula-0294 dev_Vol=*NULL*
bacula-sd: file_dev.c:71-50582 Enter: virtual bool DEVICE::rewind(DCR*)
bacula-sd: label.c:970-50582 Enter: bool unser_volume_label(DEVICE*, DEV_RECORD*)
bacula-sd: label.c:987-50582 reclen=195 recdata=Bacula 1.0 immortal
bacula-sd: label.c:989-50582 reclen=195 recdata=Bacula 1.0 immortal

Volume Label:
Adata             : 0
Id                : Bacula 1.0 immortal
VerNo             : 11
VolName           : VolBacula-0294
PrevVolName       :
VolFile           : 0
LabelType         : VOL_LABEL
LabelSize         : 195
PoolName          : File
MediaType         : File
PoolType          : Backup
HostName          : myhostname
Date label written: 22-may-2016 19:10
bacula-sd: label.c:1027-50582 Leave: bool unser_volume_label(DEVICE*, DEV_RECORD*)
bacula-sd: label.c:149-50582 VolHdr.Id OK: Bacula 1.0 immortal

bacula-sd: label.c:188-50582 VolHdr.VerNum=11 OK.

Volume Label:
Adata             : 0
Id                : Bacula 1.0 immortal
VerNo             : 11
VolName           : VolBacula-0294
PrevVolName       :
VolFile           : 0
LabelType         : VOL_LABEL
LabelSize         : 195
PoolName          : File
MediaType         : File
PoolType          : Backup
HostName          : myhostname
Date label written: 22-may-2016 19:10
bacula-sd: label.c:258-50582 Leave read_volume_label() VOL_OK
bacula-sd: file_dev.c:71-50582 Enter: virtual bool DEVICE::rewind(DCR*)
bacula-sd: label.c:271-50582 Call reserve_volume=VolBacula-0294
bacula-sd: label.c:284-50582 Leave: virtual int DEVICE::read_dev_volume_label(DCR*)
bacula-sd: acquire.c:246-50582 Got correct volume. VOL_OK: VolBacula-0294
bacula-sd: acquire.c:354-50582 dcr=7fc86c008c48 dev=7fc86c001208
bacula-sd: acquire.c:355-50582 MediaType dcr=File dev=File
bacula-sd: acquire.c:357-50582 Leave: bool acquire_device_for_read(DCR*)
bacula-sd: label.c:970-50582 Enter: bool unser_volume_label(DEVICE*, DEV_RECORD*)
bacula-sd: label.c:987-50582 reclen=195 recdata=Bacula 1.0 immortal
bacula-sd: label.c:989-50582 reclen=195 recdata=Bacula 1.0 immortal

Volume Label:
Adata             : 0
Id                : Bacula 1.0 immortal
VerNo             : 11
VolName           : VolBacula-0294
PrevVolName       :
VolFile           : 0
LabelType         : VOL_LABEL
LabelSize         : 195
PoolName          : File
MediaType         : File
PoolType          : Backup
HostName          : myhostname
Date label written: 22-may-2016 19:10
bacula-sd: label.c:1027-50582 Leave: bool unser_volume_label(DEVICE*, DEV_RECORD*)
bacula-sd: file_dev.c:107-50582 ===== lseek to 129255
bacula-sd: file_dev.c:107-50582 ===== lseek to 1999987714
bacula-sd: file_dev.c:107-50582 ===== lseek to 3999924136
bacula-sd: file_dev.c:107-50582 ===== lseek to 4999795602
bacula-sd: file_dev.c:107-50582 ===== lseek to 5999731550
bacula-sd: file_dev.c:107-50582 ===== lseek to 6999602969
bacula-sd: file_dev.c:107-50582 ===== lseek to 9999604340
bacula-sd: mount.c:858-50582 NumReadVolumes=2 CurReadVolume=2
bacula-sd: mount.c:878-50582 End of Device reached.
bacula-sd: acquire.c:490-50582 release_device device "Freenas" (/backup/baculaVolumes) is disk
bacula-sd: askdir.c:452-50582 Update cat VolBytes=10737363502 VolABytes=0 Status=Full Vol=VolBacula-0294
bacula-sd: askdir.c:491-50582 >dird CatReq JobId=50582 UpdateMedia VolName=VolBacula-0294 VolJobs=1 VolFiles=2 VolBlocks=166440 VolBytes=10737363502 VolABytes=0 VolHoleBytes=0 VolHoles=0 VolMounts=25 VolErrors=0 VolWrites=3328862 MaxVolBytes=10737418240 EndTime=1511797676 VolStatus=Full Slot=0 relabel=0 InChanger=0 VolReadTime=65066085 VolWriteTime=4039786913 VolFirstWritten=0 VolType=1 VolParts=0 VolCloudParts=0 LastPartBytes=0 Enabled=1
bacula-sd: askdir.c:506-50582 get_volume_info() 1000 OK VolName=VolBacula-0294 VolJobs=1 VolFiles=2 VolBlocks=166440 VolBytes=10737363502 VolABytes=0 VolHoleBytes=0 VolHoles=0 VolMounts=25 VolErrors=0 VolWrites=3328862 MaxVolBytes=10737418240 VolCapacityBytes=0 VolStatus=Full Slot=0 MaxVolJobs=0 MaxVolFiles=0 InChanger=0 VolReadTime=65066085 VolWriteTime=4039786913 EndFile=2 EndBlock=2101947949 VolType=1 LabelType=0 MediaId=294 ScratchPoolId=0 VolParts=0 VolCloudParts=0 LastPartBytes=0 Enabled=1
bacula-sd: acquire.c:552-50582 0 writers, 0 reserve, dev="Freenas" (/backup/baculaVolumes)
bacula-sd: dev.c:271-50582 close_dev vol=VolBacula-0294 fd=7 dev=7fc86c001208 adata=0 dev="Freenas" (/backup/baculaVolumes)
bacula-sd: file_dev.c:71-50582 Enter: virtual bool DEVICE::rewind(DCR*)
bacula-sd: dev.c:252-50582 Clear volhdr vol=VolBacula-0294
bacula-sd: acquire.c:571-50582 JobId=50582 broadcast wait_device_release at 27-nov-2017 16:47:56
bacula-sd: acquire.c:594-50582 Device "Freenas" (/backup/baculaVolumes) released by JobId=50582
bacula-sd: read.c:109-50582 Done reading.
bacula-sd: fd_cmds.c:178-50582 ==== 3099 Job RestoreFiles.2017-11-27_16.45.41_37 end JobStatus=84 JobFiles=28688 JobBytes=8470379438 JobErrors=0 ErrMsg=
bacula-sd: jcr.c:174-50582 write_last_jobs seek to 192
bacula-sd: bnet.c:569-0 socket=5 who=client host=192.168.2.25 port=9103
bacula-sd: dircmd.c:188-0 Got a DIR connection at 27-nov-2017 16:47:56
bacula-sd: cram-md5.c:69-0 send: auth cram-md5 challenge <1387407682.1511797676@bacula-sd> ssl=0
bacula-sd: cram-md5.c:133-0 cram-get received: auth cram-md5 <1407650774.1511797676@bacula-dir> ssl=0
bacula-sd: cram-md5.c:157-0 sending resp to challenge: B4+pbn/l8w4jP8xP80/l5C
bacula-sd: dircmd.c:214-0 Message channel init completed.
bacula-sd: job.c:78-0 <dird: JobId=50582 job=RestoreFiles.2017-11-27_16.45.41_37 job_name=RestoreFiles client_name=bacula-fd type=82 level=70 FileSet=FullSet NoAttr=0 SpoolAttr=1 FileSetMD5=**Dummy** SpoolData=0 WritePartAfterJob=1 PreferMountedVols=1 SpoolSize=0 rerunning=0 VolSessionId=1 VolSessionTime=1511797387 sd_client=0 Authorization=
bacula-sd: job.c:100-0 rerunning=0 VolSesId=1 VolSesTime=1511797387
bacula-sd: acquire.c:658-50582 Attach 0x64001518 to dev "Freenas" (/backup/baculaVolumes)
bacula-sd: job.c:188-50582 sd_calls_client=0 sd_client=0
bacula-sd: job.c:210-50582 RestoreFiles.2017-11-27_16.45.41_37 waiting 1800 sec for FD to contact SD key=NPDJ-IBIL-AHLK-MBOI-NDGF-AKIF-BEPM-KEAK
bacula-sd: bnet.c:569-0 socket=6 who=client host=192.168.2.25 port=9103
bacula-sd: dircmd.c:188-0 Got a DIR connection at 27-nov-2017 16:47:57
bacula-sd: cram-md5.c:69-0 send: auth cram-md5 challenge <1037254028.1511797677@bacula-sd> ssl=0
bacula-sd: cram-md5.c:133-0 cram-get received: auth cram-md5 <600107543.1511797677@bacula-dir> ssl=0
bacula-sd: cram-md5.c:157-0 sending resp to challenge: sm/O5V/6O+5GC++Qb6/J9D
bacula-sd: dircmd.c:214-0 Message channel init completed.
bacula-sd: job.c:228-50582 === Auth=50582 jid=0 canceled=1 errstat=0
bacula-sd: jcr.c:174-0 write_last_jobs seek to 192
Sakrow
  • 81
  • 7

1 Answers1

1

Option 1 - Configuration error

Firstly, have you done a restore before with this configuration? I have a "RestoreFiles" job to make this work which looks like this:

Job {
  Name = "RestoreFiles"
  Description = "Standard Restore template. Only one such job is needed for all standard Jobs/Clients/Storage ..."
  Type = Restore
  Client = bareos-fd
  FileSet = "Linux All"
  Storage = File
  Pool = Incremental
  Messages = Standard
  Where = /tmp/bareos-restores
}

Option 2 - Protocol Error

Secondly, more information is needed. The communication between the sd server and the fd client uses a protocol that needs to be in sync. Frequently, a wanted 2000 OK storage, got 2800 End Job error is a result of a protocol mismatch which could be:

  • from inconsistent name resolution (e.g. server and client have different ideas about what the name of each is), or
  • protocol errors (e.g. or one is set for IPv4 whereas the other defaults to IPv6) or
  • version errors (server and client need to be compatible versions)

There will be more further up the logs to explain which this is, e.g.

21-Jan 00:07 xxxxxx-dir JobId 1199: Start Restore Job RestoreFiles.2016-01-21_00.07.44_16
21-Jan 00:07 xxxxxx-dir JobId 1199: Error: bsock.c:221 Socket open error. proto=28 port=9103. ERR=Protocol not supported
21-Jan 00:07 xxxxxx-dir JobId 1199: Using Device "DAT160" to read.
21-Jan 00:07 xxxxxx-sd JobId 1199: Ready to read from volume "Tape009" on tape device "DAT160" (/dev/nsa0).
21-Jan 00:07 xxxxxx-sd JobId 1199: Forward spacing Volume "Tape009" to file:block 12:0.
21-Jan 00:07 xxxxxx-fd JobId 1199: Error: bsock.c:221 Socket open error. proto=28 port=9103. ERR=Protocol not supported
21-Jan 00:55 xxxxxx-sd JobId 1199: Elapsed time=00:47:30, Transfer rate=6.099 M Bytes/second
21-Jan 00:07 xxxxxx-dir JobId 1199: Error: bsock.c:221 Socket open error. proto=28 port=9102. ERR=Protocol not supported
21-Jan 00:55 xxxxxx-dir JobId 1199: Using Device "Backup" to read.
21-Jan 00:55 xxxxxx-dir JobId 1199: Fatal error: Bad response to Storage command: wanted 2000 OK storage, got 2800 End Job TermCode=69 JobFiles=147756 ReadBytes=17353960553 JobBytes=17353960553 Errors=1 VSS=0 Encrypt=0 CommBytes=0 CompressCommBytes=0

**Note the ERR=Protocol not supported which, in this case was a client resolving (incorrectly) via IPv6.

There has been discussion about this particular scenario on the mailing list but, from my experience, it always boils down to one of these 3 (or 4) things.

Also, don't forget that after any server-side configuration change, you need to restart both the Director and the Storage Manager or they may not have the same idea about the configuration and random errors like this can creep in.

I'll revise this answer based on what additional information can be provided. :)

tudor -Reinstate Monica-
  • 1,805
  • 18
  • 36
  • I updated the question with new information – Sakrow Nov 20 '17 at 11:49
  • Can you include the logs before the `Fatal Error:` server-side as well? – tudor -Reinstate Monica- Nov 20 '17 at 22:39
  • Also, since you upgraded the server and not the clients, you may have compounded the issue rather than made it better. If it is an `fd` error client-side, why did you not upgrade the client as well? – tudor -Reinstate Monica- Nov 20 '17 at 22:41
  • We have had different versions for a long time between the clients and the server without any problem (older versions). That is not the error, The documentation says: `Older File Daemons should be compatible with the 9.0.0 Director and Storage daemons. There should be no need to upgrade older File Daemons.` https://blog.bacula.org/release-9-0-0/. But if you like i can update client `bacula-fd` and try again. – Sakrow Nov 20 '17 at 22:52
  • I would absolutely be trying that. It's a fairly standard thing in Open Source to expect the user to have tried the current version to see if it's fixed. If the newer version works and the previous doesn't, then the developers are more likely to be able to reproduce the problem. – tudor -Reinstate Monica- Nov 21 '17 at 03:09
  • I tried restore with `bacula-client`in last version and nothing, same error. Can I give you some more information? – Sakrow Nov 21 '17 at 07:20
  • Yes, can you include logs before Fatal Error server-side? Either `bacula-dir` or `bacula-sd` should be throwing an error because the volume management decision is them and not `bacula-fd`. `bacula-fd` is just saying it was unable to for whatever reason, but it's not the one that makes those decisions. You may also want to try cleaning up your catalog, as the logs are saying the size is wrong and that could be creating a problem. – tudor -Reinstate Monica- Nov 27 '17 at 04:04
  • I attach you some more information – Sakrow Nov 27 '17 at 16:15