it seems that this happens when a job is interrupted ( cancel or due to error ) during spooling cycle. could it be that bareos doesn't flush the spool if the job fails during spooling? as far as I can see, it doesn't happen if job fails during despooling.
could anyone confirm this? On Monday, January 2, 2017 at 4:17:19 PM UTC+1, Robert N wrote: > Hi Guys, > > Happy New Year! > > Any clues on this behavior? > > Thanks, > Robert > > On Wednesday, December 28, 2016 at 11:39:23 PM UTC+1, Robert N wrote: > > On Wednesday, December 28, 2016 at 10:14:02 PM UTC+1, Robert N wrote: > > > Hi, > > > > > > I'm running Bareos 15.2.3 on centos 6. > > > > > > configured 60G spool size, but seems like bareos actually uses 1M and 2M > > > spoolsize. I'm not able to find a pattern, but also seen 7M and 8M > > > spoolsizes. > > > > > > here are the messages from logs: > > > > > > 28-Dec 08:19 muc1pro-backup-1-sd JobId 9648: Spooling data ... > > > 28-Dec 08:19 muc1pro-backup-1-sd JobId 9648: Forward spacing Volume > > > "Incr-3618" to file:block 0:220. > > > 28-Dec 08:19 muc1pro-backup-1-sd JobId 9648: User specified Device spool > > > size reached: DevSpoolSize=60,020,128,434 MaxDevSpoolSize=60,000,000,000 > > > 28-Dec 08:19 muc1pro-backup-1-sd JobId 9648: Writing spooled data to > > > Volume. Despooling 1,048,588 bytes ... > > > 28-Dec 08:19 muc1pro-backup-1-sd JobId 9648: Despooling elapsed time = > > > 00:00:01, Transfer rate = 1.048 M Bytes/second > > > 28-Dec 08:19 muc1pro-backup-1-sd JobId 9648: Spooling data again ... > > > 28-Dec 08:19 muc1pro-backup-1-sd JobId 9648: User specified Device spool > > > size reached: DevSpoolSize=60,021,177,022 MaxDevSpoolSize=60,000,000,000 > > > 28-Dec 08:19 muc1pro-backup-1-sd JobId 9648: Writing spooled data to > > > Volume. Despooling 2,097,176 bytes ... > > > 28-Dec 08:19 muc1pro-backup-1-sd JobId 9648: Despooling elapsed time = > > > 00:00:02, Transfer rate = 1.048 M Bytes/second > > > 28-Dec 08:19 muc1pro-backup-1-sd JobId 9648: Spooling data again ... > > > 28-Dec 08:19 muc1pro-backup-1-sd JobId 9648: User specified Device spool > > > size reached: DevSpoolSize=60,021,177,022 MaxDevSpoolSize=60,000,000,000 > > > 28-Dec 08:19 muc1pro-backup-1-sd JobId 9648: Writing spooled data to > > > Volume. Despooling 2,097,176 bytes ... > > > 28-Dec 08:19 muc1pro-backup-1-sd JobId 9648: Despooling elapsed time = > > > 00:00:01, Transfer rate = 2.097 M Bytes/second > > > 28-Dec 08:19 muc1pro-backup-1-sd JobId 9648: Spooling data again ... > > > 28-Dec 08:19 muc1pro-backup-1-sd JobId 9648: User specified Device spool > > > size reached: DevSpoolSize=60,021,177,022 MaxDevSpoolSize=60,000,000,000 > > > 28-Dec 08:19 muc1pro-backup-1-sd JobId 9648: Writing spooled data to > > > Volume. Despooling 2,097,176 bytes ... > > > 28-Dec 08:19 muc1pro-backup-1-sd JobId 9648: Despooling elapsed time = > > > 00:00:01, Transfer rate = 2.097 M Bytes/second > > > > > > Some of the jobs fail after a while with the following errors: > > > > > > 28-Dec 08:19 muc1pro-backup-1-sd JobId 9648: Spooling data again ... > > > 28-Dec 08:19 muc1pro-backup-1-sd JobId 9648: End of Volume at file 0 on > > > device "DiskDeviceIncr1" (/data/bareos-storage/Incr), Volume "Incr-3618" > > > 28-Dec 08:19 muc1pro-backup-1-sd JobId 9648: Ready to read from volume > > > "Incr-3621" on device "DiskDeviceIncr1" (/data/bareos-storage/Incr). > > > 28-Dec 08:19 muc1pro-backup-1-sd JobId 9648: Forward spacing Volume > > > "Incr-3621" to file:block 0:999959905. > > > 28-Dec 08:19 muc1pro-backup-1-sd JobId 9648: Error: block.c:286 Volume > > > data error at 0:999959905! Wanted ID: "BB02", got " al". Buffer > > > discarded. > > > 28-Dec 08:19 muc1pro-backup-1-sd JobId 9648: Fatal error: mac.c:636 Fatal > > > append error on device "DriveDevice" (/dev/nst0): ERR= > > > 28-Dec 08:19 muc1pro-backup-1-sd JobId 9648: Elapsed time=00:00:14, > > > Transfer rate=20.81 M Bytes/second > > > 28-Dec 08:19 muc1pro-backup-1-dir JobId 9648: Error: bsock_tcp.c:422 > > > Write error sending 371 bytes to Storage > > > daemon:muc1pro-backup-1.adm.financial.com:9103: ERR=Broken pipe > > > > > > Before setting the spoolsize to 60GB, it was 512GB and didn't see > > > behavior/erros like these. the spooling process was either filling up to > > > 512G oder up to job size if less than 512GB. > > > > > > Any clues why the spooling doesn't work correctly? > > > > > > Thank you. > > > Robert > > > > > > here some more details from another job + debug info: > > > > 28-Dec 23:07 muc1pro-backup-1-sd JobId 9813: Ready to read from volume > > "Incr-3874" on device "DiskDeviceIncr1" (/data/bareos-storage/Incr). > > 28-Dec 23:07 muc1pro-backup-1-sd JobId 9813: Forward spacing Volume > > "Incr-3874" to file:block 0:121089224. > > 28-Dec 23:07 muc1pro-backup-1-sd JobId 9813: Error: block.c:286 Volume data > > error at 0:121089224! Wanted ID: "BB02", got "×áÚp". Buffer discarded. > > 28-Dec 23:07 muc1pro-backup-1-sd JobId 9813: Fatal error: mac.c:636 Fatal > > append error on device "DriveDevice" (/dev/nst0): ERR= > > 28-Dec 23:07 muc1pro-backup-1-sd JobId 9813: Elapsed time=00:00:24, > > Transfer rate=249.9 M Bytes/second > > 28-Dec 23:07 muc1pro-backup-1-dir JobId 9813: Error: bsock_tcp.c:422 Write > > error sending 369 bytes to Storage > > daemon:muc1pro-backup-1.adm.financial.com:9103: ERR=Broken pipe > > 28-Dec 23:07 muc1pro-backup-1-dir JobId 9813: Error: Bareos > > muc1pro-backup-1-dir 15.2.3 > > > > and the debug: > > > > muc1pro-backup-1-sd (100): acquire.c:64-9813 MediaType dcr=FileIncr > > dev=FileIncr > > muc1pro-backup-1-sd (100): acquire.c:92-9813 Want Vol=Incr-3874 Slot=0 > > muc1pro-backup-1-sd (100): acquire.c:106-9813 MediaType dcr=FileIncr > > dev=FileIncr > > muc1pro-backup-1-sd (100): acquire.c:174-9813 MediaType dcr=FileIncr > > dev=FileIncr > > muc1pro-backup-1-sd (100): acquire.c:193-9813 dir_get_volume_info > > vol=Incr-3874 > > muc1pro-backup-1-sd (50): askdir.c:248-9813 >dird CatReq > > Job=CopyToTape.2016-12-28_23.07.17_30 GetVolInfo VolName=Incr-3874 write=0 > > muc1pro-backup-1-sd (50): askdir.c:177-9813 <dird 1000 OK VolName=Incr-3874 > > VolJobs=1 VolFiles=0 VolBlocks=31001 VolBytes=1999882588 VolMounts=2 > > VolErrors=0 VolWr > > ites=197443 MaxVolBytes=10737418240 VolCapacityBytes=0 VolStatus=Used > > Slot=0 MaxVolJobs=1 MaxVolFiles=0 InChanger=0 VolReadTime=103350 > > VolWriteTime=32620114 EndFi > > le=0 EndBlock=1999753563 LabelType=0 MediaId=3874 EncryptionKey= > > MinBlocksize=0 MaxBlocksize=0 > > muc1pro-backup-1-sd (50): askdir.c:213-9813 do_get_volume_info return true > > slot=0 Volume=Incr-3874, VolminBlocksize=0 VolMaxBlocksize=0 > > muc1pro-backup-1-sd (50): askdir.c:215-9813 setting dcr->VolMinBlocksize(0) > > to vol.VolMinBlocksize(0) > > muc1pro-backup-1-sd (50): askdir.c:217-9813 setting dcr->VolMaxBlocksize(0) > > to vol.VolMaxBlocksize(0) > > muc1pro-backup-1-sd (100): mount.c:650-9813 No swap_dev set > > muc1pro-backup-1-sd (100): mount.c:600-9813 Must load "DiskDeviceIncr1" > > (/data/bareos-storage/Incr) > > muc1pro-backup-1-sd (100): autochanger.c:99-9813 Device "DiskDeviceIncr1" > > (/data/bareos-storage/Incr) is not an autochanger > > muc1pro-backup-1-sd (100): acquire.c:235-9813 stored: open vol=Incr-3874 > > muc1pro-backup-1-sd (100): dev.c:561-9813 open dev: type=1 > > dev_name="DiskDeviceIncr1" (/data/bareos-storage/Incr) vol=Incr-3874 > > mode=OPEN_READ_ONLY > > muc1pro-backup-1-sd (100): dev.c:572-9813 call open_device > > mode=OPEN_READ_ONLY > > muc1pro-backup-1-sd (100): dev.c:646-9813 open disk: mode=OPEN_READ_ONLY > > open(/data/bareos-storage/Incr/Incr-3874, 0x0, 0640) > > muc1pro-backup-1-sd (100): dev.c:662-9813 open dev: disk fd=6 opened > > muc1pro-backup-1-sd (100): dev.c:580-9813 preserve=0x29ff57c0 fd=6 > > muc1pro-backup-1-sd (100): acquire.c:243-9813 opened dev "DiskDeviceIncr1" > > (/data/bareos-storage/Incr) OK > > muc1pro-backup-1-sd (100): acquire.c:257-9813 calling read-vol-label > > muc1pro-backup-1-sd (100): dev.c:502-9813 setting minblocksize to 64512, > > maxblocksize to label_block_size=64512, on device "DiskDeviceIncr1" > > (/data/bareos-storage > > /Incr) > > muc1pro-backup-1-sd (100): label.c:76-9813 Enter read_volume_label res=1 > > device="DiskDeviceIncr1" (/data/bareos-storage/Incr) vol=Incr-3874 > > dev_Vol=*NULL* max_blo > > cksize=64512 > > muc1pro-backup-1-sd (100): label.c:251-9813 Call reserve_volume=Incr-3874 > > muc1pro-backup-1-sd (100): dev.c:432-9813 Device "DiskDeviceIncr1" > > (/data/bareos-storage/Incr) has dev->device->max_block_size of 0 and > > dev->max_block_size of 645 > > 12, dcr->VolMaxBlocksize is 0 > > muc1pro-backup-1-sd (100): dev.c:474-9813 set minblocksize to 64512, > > maxblocksize to 64512 on device "DiskDeviceIncr1" > > (/data/bareos-storage/Incr) > > muc1pro-backup-1-sd (100): acquire.c:263-9813 Got correct volume. > > muc1pro-backup-1-sd (100): acquire.c:370-9813 dcr=7f021012a9c8 > > dev=7f02240016d8 > > muc1pro-backup-1-sd (100): acquire.c:371-9813 MediaType dcr=FileIncr > > dev=FileIncr > > muc1pro-backup-1-sd (100): dev.c:892-9813 ===== lseek to 121089224 > > muc1pro-backup-1-sd (50): block.c:287-9813 block.c:286 Volume data error at > > 0:121089224! Wanted ID: "BB02", got "<D7><E1><DA>p". Buffer discarded. > > muc1pro-backup-1-sd (100): mac.c:629-9813 ok=0 > > muc1pro-backup-1-sd (100): mac.c:637-9813 Set ok=FALSE after > > write_block_to_device. > > muc1pro-backup-1-sd (100): spool.c:119-9813 Data spooling discarded > > muc1pro-backup-1-sd (100): spool.c:205-9813 Deleted spool file: > > /data/bareos-storage/spool/muc1pro-backup-1-sd.data.9813.CopyToTape.2016-12-28_23.07.17_30.DriveDevice.spool > > muc1pro-backup-1-sd (100): acquire.c:504-9813 release_device device > > "DriveDevice" (/dev/nst0) is tape > > muc1pro-backup-1-sd (100): acquire.c:528-9813 There are 0 writers in > > release_device > > muc1pro-backup-1-sd (50): askdir.c:366-9813 Update cat VolBytes=217 > > muc1pro-backup-1-sd (50): askdir.c:391-9813 >dird CatReq > > Job=CopyToTape.2016-12-28_23.07.17_30 UpdateMedia VolName=000019L6 > > VolJobs=31 VolFiles=1 VolBlocks=0 VolBytes=217 VolMounts=72 VolErrors=0 > > VolWrites=385987 MaxVolBytes=0 EndTime=1482962864 VolStatus=Append Slot=12 > > relabel=0 InChanger=1 VolReadTime=0 VolWriteTime=930001999 VolFirstWritten=0 > > muc1pro-backup-1-sd (100): acquire.c:568-9813 0 writers, 0 reserve, > > dev="DriveDevice" (/dev/nst0) > > muc1pro-backup-1-sd (100): dev.c:933-9813 close_dev "DriveDevice" > > (/dev/nst0) > > muc1pro-backup-1-sd (100): dev.c:1043-9813 Enter unmount > > muc1pro-backup-1-sd (100): dev.c:921-9813 Clear volhdr vol=000019L6 > > muc1pro-backup-1-sd (100): acquire.c:626-9813 JobId=9813 broadcast > > wait_device_release at 28-Dec-2016 23:07:44 > > muc1pro-backup-1-sd (100): acquire.c:648-9813 Device "DriveDevice" > > (/dev/nst0) released by JobId=9813 > > muc1pro-backup-1-sd (100): spool.c:823-9813 Close attr spool file at > > 28-Dec-2016 23:07:44 > > muc1pro-backup-1-sd (100): acquire.c:504-9813 release_device device > > "DiskDeviceIncr1" (/data/bareos-storage/Incr) is disk > > muc1pro-backup-1-sd (50): askdir.c:366-9813 Update cat VolBytes=1999882588 > > muc1pro-backup-1-sd (50): askdir.c:391-9813 >dird CatReq > > Job=CopyToTape.2016-12-28_23.07.17_30 UpdateMedia VolName=Incr-3874 > > VolJobs=1 VolFiles=0 VolBlocks=31001 VolBytes=1999882588 VolMounts=2 > > VolErrors=0 VolWrites=197443 MaxVolBytes=10737418240 EndTime=1482962864 > > VolStatus=Used Slot=0 relabel=0 InChanger=0 VolReadTime=103405 > > VolWriteTime=32620114 VolFirstWritten=0 > > muc1pro-backup-1-sd (100): acquire.c:568-9813 0 writers, 0 reserve, > > dev="DiskDeviceIncr1" (/data/bareos-storage/Incr) > > muc1pro-backup-1-sd (100): dev.c:933-9813 close_dev "DiskDeviceIncr1" > > (/data/bareos-storage/Incr) > > muc1pro-backup-1-sd (100): dev.c:1043-9813 Enter unmount > > muc1pro-backup-1-sd (100): dev.c:921-9813 Clear volhdr vol=Incr-3874 > > muc1pro-backup-1-sd (100): acquire.c:626-9813 JobId=9813 broadcast > > wait_device_release at 28-Dec-2016 23:07:44 > > muc1pro-backup-1-sd (100): acquire.c:648-9813 Device "DiskDeviceIncr1" > > (/data/bareos-storage/Incr) released by JobId=9813 > > muc1pro-backup-1-sd (30): mac.c:681-9813 Done reading. > > muc1pro-backup-1-sd (100): mac.c:691-9813 3099 Job > > CopyToTape.2016-12-28_23.07.17_30 end JobStatus=69 JobFiles=34277 > > JobBytes=5998087648 JobErrors=15223688 > > muc1pro-backup-1-sd (100): jcr.c:184-9813 write_last_jobs seek to 192 > > > > thanks, > > Robert -- You received this message because you are subscribed to the Google Groups "bareos-users" group. To unsubscribe from this group and stop receiving emails from it, send an email to [email protected]. To post to this group, send email to [email protected]. For more options, visit https://groups.google.com/d/optout.
