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.
