26-Sep-2022 15:00:06.302354 bareos-sd (50): stored/dir_cmd.cc:437-0 level=1000 trace=1 timestamp=1 tracefilename=/var/lib/bareos/bareos-sd.trace 26-Sep-2022 15:00:06.302696 bareos-sd (250): stored/sd_plugins.cc:313-0 No bplugin_list: GeneratePluginEvent ignored. 26-Sep-2022 15:00:06.302711 bareos-sd (580): lib/message.cc:328-0 Close_msg jcr=7fec1c00a370 26-Sep-2022 15:00:06.302717 bareos-sd (200): stored/job.cc:389-0 Start stored FreeJcr 26-Sep-2022 15:00:06.302722 bareos-sd (800): stored/job.cc:390-0 End Job JobId=0 7fec1c00a370 26-Sep-2022 15:00:06.302727 bareos-sd (800): stored/job.cc:393-0 Send Terminate jid=0 7fec1c00a370 26-Sep-2022 15:00:06.302732 bareos-sd (200): stored/job.cc:500-0 End stored FreeJcr 26-Sep-2022 15:00:06.302737 bareos-sd (100): lib/jcr.cc:273-0 FreeCommonJcr: 7fec1c00a370 26-Sep-2022 15:00:06.302744 bareos-sd (800): lib/watchdog.cc:193-0 Registered watchdog 7fec1c009fa0, interval 120 one shot 26-Sep-2022 15:00:06.302916 bareos-sd (900): lib/btimers.cc:177-0 Start bsock timer 7fec1c014f20 tid=0x0000007fec2ba4f7 for 120 secs at 1664197206 26-Sep-2022 15:00:06.302949 bareos-sd (900): lib/btimers.cc:193-0 Stop bsock timer 7fec1c014f20 tid=0x0000007fec2ba4f7 at 1664197206. 26-Sep-2022 15:00:06.302956 bareos-sd (800): lib/watchdog.cc:214-0 Unregistered watchdog 7fec1c009fa0 26-Sep-2022 15:00:06.303125 bareos-sd (800): lib/watchdog.cc:193-0 Registered watchdog 7fec1c009fa0, interval 2 one shot 26-Sep-2022 15:00:06.303294 bareos-sd (900): lib/btimers.cc:177-0 Start bsock timer 7fec1c014f20 tid=0x0200007fec2ba4f7 for 2 secs at 1664197206 26-Sep-2022 15:00:06.303309 bareos-sd (900): lib/btimers.cc:193-0 Stop bsock timer 7fec1c014f20 tid=0x0000007fec2ba4f7 at 1664197206. 26-Sep-2022 15:00:06.303314 bareos-sd (800): lib/watchdog.cc:214-0 Unregistered watchdog 7fec1c009fa0 26-Sep-2022 15:00:06.303497 bareos-sd (100): lib/tls_openssl_private.cc:96-0 Destruct TlsOpenSslPrivate 26-Sep-2022 15:00:06.303541 bareos-sd (100): lib/bsock.cc:136-0 Destruct BareosSocket 26-Sep-2022 15:00:06.303549 bareos-sd (580): lib/message.cc:328-0 Close_msg jcr=0 26-Sep-2022 15:00:06.303554 bareos-sd (850): lib/message.cc:350-0 ===Begin close msg resource at a3e840 26-Sep-2022 15:00:06.303570 bareos-sd (850): lib/message.cc:455-0 Done walking message chain. 26-Sep-2022 15:00:06.303575 bareos-sd (850): lib/message.cc:462-0 ===End close msg resource 26-Sep-2022 15:00:06.303580 bareos-sd (800): lib/thread_list.cc:207-0 Finished WorkerThread. 26-Sep-2022 15:02:51.765994 bareos-sd (100): lib/bsock.cc:84-0 Construct BareosSocket 26-Sep-2022 15:02:51.766124 bareos-sd (800): lib/thread_list.cc:243-0 Run WorkerThread successfully. 26-Sep-2022 15:02:51.766698 bareos-sd (100): lib/tls_openssl_private.cc:65-0 Construct TlsOpenSslPrivate 26-Sep-2022 15:02:51.766937 bareos-sd (100): lib/tls_openssl_private.cc:600-0 Set tcp filedescriptor: <8> 26-Sep-2022 15:02:51.766946 bareos-sd (100): lib/tls_openssl_private.cc:612-0 Set protocol: <> 26-Sep-2022 15:02:51.766951 bareos-sd (100): lib/tls_openssl_private.cc:546-0 Set ca_certfile: <> 26-Sep-2022 15:02:51.766956 bareos-sd (100): lib/tls_openssl_private.cc:552-0 Set ca_certdir: <> 26-Sep-2022 15:02:51.766960 bareos-sd (100): lib/tls_openssl_private.cc:558-0 Set crlfile_: <> 26-Sep-2022 15:02:51.766965 bareos-sd (100): lib/tls_openssl_private.cc:564-0 Set certfile_: <> 26-Sep-2022 15:02:51.766969 bareos-sd (100): lib/tls_openssl_private.cc:570-0 Set keyfile_: <> 26-Sep-2022 15:02:51.766974 bareos-sd (100): lib/tls_openssl_private.cc:588-0 Set dhfile_: <> 26-Sep-2022 15:02:51.766979 bareos-sd (100): lib/tls_openssl_private.cc:606-0 Set cipherlist: <> 26-Sep-2022 15:02:51.766983 bareos-sd (100): lib/tls_openssl_private.cc:594-0 Set Verify Peer: 26-Sep-2022 15:02:51.766988 bareos-sd (50): lib/tls_openssl.cc:79-0 Preparing TLS_PSK SERVER callback 26-Sep-2022 15:02:51.767117 bareos-sd (100): lib/tls_openssl_private.cc:466-0 psk_server_cb. identitiy: R_DIRECTOR bareos-dir. 26-Sep-2022 15:02:51.767131 bareos-sd (100): lib/tls_openssl_private.cc:487-0 psk_server_cb. result: 32. 26-Sep-2022 15:02:51.767670 bareos-sd (50): lib/bnet.cc:140-0 TLS server negotiation established. 26-Sep-2022 15:02:51.767703 bareos-sd (110): stored/socket_server.cc:97-0 Conn: Hello Director bareos-dir calling 26-Sep-2022 15:02:51.767712 bareos-sd (110): stored/socket_server.cc:114-0 Got a DIR connection at 26-Sep-2022 15:02:51 26-Sep-2022 15:02:51.767719 bareos-sd (100): lib/jcr.cc:191-0 Construct JobControlRecord 26-Sep-2022 15:02:51.767725 bareos-sd (800): lib/jcr.cc:778-0 setJobStatus(*System*, C) 26-Sep-2022 15:02:51.767730 bareos-sd (800): lib/jcr.cc:788-0 OnEntry JobStatus= newJobstatus=C 26-Sep-2022 15:02:51.767735 bareos-sd (800): lib/jcr.cc:798-0 Set new stat. old: ,0 new: C,0 26-Sep-2022 15:02:51.767740 bareos-sd (800): lib/jcr.cc:804-0 leave setJobStatus old= new=C 26-Sep-2022 15:02:51.767747 bareos-sd (250): stored/sd_plugins.cc:601-0 === enter NewPlugins === 26-Sep-2022 15:02:51.767752 bareos-sd (250): stored/sd_plugins.cc:603-0 No sd plugin list! 26-Sep-2022 15:02:51.767757 bareos-sd (1000): stored/dir_cmd.cc:278-0 stored in start_job 26-Sep-2022 15:02:51.767766 bareos-sd (800): lib/watchdog.cc:193-0 Registered watchdog 7fec1c013260, interval 600 one shot 26-Sep-2022 15:02:51.767947 bareos-sd (900): lib/btimers.cc:177-0 Start bsock timer 7fec1c00a7b0 tid=0x5800007fec2ba4f7 for 600 secs at 1664197371 26-Sep-2022 15:02:51.767963 bareos-sd (50): lib/cram_md5.cc:106-0 send: auth cram-md5 <1396831710.1664197371@R_STORAGE::bareos-sd> ssl=1 26-Sep-2022 15:02:51.768153 bareos-sd (100): lib/cram_md5.cc:166-0 cram-get received: auth cram-md5 <1591089078.1664197371@R_DIRECTOR::bareos-dir> ssl=1 26-Sep-2022 15:02:51.768164 bareos-sd (50): lib/cram_md5.cc:62-0 my_name: - challenge_name: 26-Sep-2022 15:02:51.768193 bareos-sd (99): lib/cram_md5.cc:231-0 sending resp to challenge: T6QRqg+8F89fM0/1N/+6XC 26-Sep-2022 15:02:51.768252 bareos-sd (900): lib/btimers.cc:193-0 Stop bsock timer 7fec1c00a7b0 tid=0x4400007fec2ba4f7 at 1664197371. 26-Sep-2022 15:02:51.768260 bareos-sd (800): lib/watchdog.cc:214-0 Unregistered watchdog 7fec1c013260 26-Sep-2022 15:02:51.768461 bareos-sd (90): stored/dir_cmd.cc:288-0 Message channel init completed. 26-Sep-2022 15:02:51.768514 bareos-sd (199): stored/dir_cmd.cc:295-0 max_block_size) 26-Sep-2022 15:02:51.768552 bareos-sd (650): stored/block.cc:144-0 Returning new block=1c002c48 26-Sep-2022 15:02:51.768570 bareos-sd (500): stored/acquire.cc:771-0 JobId=0 enter AttachDcrToDev 26-Sep-2022 15:02:51.768576 bareos-sd (90): stored/dir_cmd.cc:1162-0 0 waiter dev_block=2. doing unmount 26-Sep-2022 15:02:51.768581 bareos-sd (100): stored/dev.cc:980-0 close_dev "tapedrive-0" (/dev/tape/by-id/scsi-350050763121a063c-nst) 26-Sep-2022 15:02:51.769448 bareos-sd (100): stored/dev.cc:1082-0 Enter unmount 26-Sep-2022 15:02:51.769456 bareos-sd (250): stored/sd_plugins.cc:313-0 No bplugin_list: GeneratePluginEvent ignored. 26-Sep-2022 15:02:51.769461 bareos-sd (100): stored/dev.cc:968-0 Clear volhdr vol=NIX416L6 26-Sep-2022 15:02:51.769466 bareos-sd (250): stored/sd_plugins.cc:313-0 No bplugin_list: GeneratePluginEvent ignored. 26-Sep-2022 15:02:51.769472 bareos-sd (150): stored/vol_mgr.cc:766-0 No vol on dev "tapedrive-0" (/dev/tape/by-id/scsi-350050763121a063c-nst) 26-Sep-2022 15:02:51.769514 bareos-sd (500): stored/acquire.cc:789-0 Enter DetachDcrFromDev 26-Sep-2022 15:02:51.769522 bareos-sd (999): stored/block.cc:176-0 FreeBlock buffer 1c027f28 26-Sep-2022 15:02:51.769527 bareos-sd (999): stored/block.cc:178-0 FreeBlock block 1c002c48 26-Sep-2022 15:02:51.769532 bareos-sd (950): stored/record.cc:573-0 Enter FreeRecord. 26-Sep-2022 15:02:51.769537 bareos-sd (950): stored/record.cc:575-0 Data buf is freed. 26-Sep-2022 15:02:51.769546 bareos-sd (950): stored/record.cc:577-0 Leave FreeRecord. 26-Sep-2022 15:02:51.809802 bareos-sd (250): stored/sd_plugins.cc:313-0 No bplugin_list: GeneratePluginEvent ignored. 26-Sep-2022 15:02:51.809820 bareos-sd (580): lib/message.cc:328-0 Close_msg jcr=7fec1c026400 26-Sep-2022 15:02:51.809826 bareos-sd (200): stored/job.cc:389-0 Start stored FreeJcr 26-Sep-2022 15:02:51.809831 bareos-sd (800): stored/job.cc:390-0 End Job JobId=0 7fec1c026400 26-Sep-2022 15:02:51.809835 bareos-sd (800): stored/job.cc:393-0 Send Terminate jid=0 7fec1c026400 26-Sep-2022 15:02:51.809841 bareos-sd (200): stored/job.cc:500-0 End stored FreeJcr 26-Sep-2022 15:02:51.809846 bareos-sd (100): lib/jcr.cc:273-0 FreeCommonJcr: 7fec1c026400 26-Sep-2022 15:02:51.809853 bareos-sd (800): lib/watchdog.cc:193-0 Registered watchdog 7fec1c013260, interval 120 one shot 26-Sep-2022 15:02:51.810031 bareos-sd (900): lib/btimers.cc:177-0 Start bsock timer 7fec1c00a7b0 tid=0x7800007fec2ba4f7 for 120 secs at 1664197371 26-Sep-2022 15:02:51.810065 bareos-sd (900): lib/btimers.cc:193-0 Stop bsock timer 7fec1c00a7b0 tid=0x7800007fec2ba4f7 at 1664197371. 26-Sep-2022 15:02:51.810072 bareos-sd (800): lib/watchdog.cc:214-0 Unregistered watchdog 7fec1c013260 26-Sep-2022 15:02:51.810253 bareos-sd (800): lib/watchdog.cc:193-0 Registered watchdog 7fec1c013260, interval 2 one shot 26-Sep-2022 15:02:51.810431 bareos-sd (900): lib/btimers.cc:177-0 Start bsock timer 7fec1c00a7b0 tid=0x0200007fec2ba4f7 for 2 secs at 1664197371 26-Sep-2022 15:02:51.810448 bareos-sd (900): lib/btimers.cc:193-0 Stop bsock timer 7fec1c00a7b0 tid=0x0000007fec2ba4f7 at 1664197371. 26-Sep-2022 15:02:51.810453 bareos-sd (800): lib/watchdog.cc:214-0 Unregistered watchdog 7fec1c013260 26-Sep-2022 15:02:51.810639 bareos-sd (100): lib/tls_openssl_private.cc:96-0 Destruct TlsOpenSslPrivate 26-Sep-2022 15:02:51.810676 bareos-sd (100): lib/bsock.cc:136-0 Destruct BareosSocket 26-Sep-2022 15:02:51.810683 bareos-sd (580): lib/message.cc:328-0 Close_msg jcr=0 26-Sep-2022 15:02:51.810689 bareos-sd (850): lib/message.cc:350-0 ===Begin close msg resource at a3e840 26-Sep-2022 15:02:51.810694 bareos-sd (850): lib/message.cc:455-0 Done walking message chain. 26-Sep-2022 15:02:51.810699 bareos-sd (850): lib/message.cc:462-0 ===End close msg resource 26-Sep-2022 15:02:51.810703 bareos-sd (800): lib/thread_list.cc:207-0 Finished WorkerThread. 26-Sep-2022 15:03:56.730617 bareos-sd (400): stored/wait.cc:119-28099 Wokeup from sleep on device status=110 blocked=BST_UNMOUNTED_WAITING_FOR_SYSOP 26-Sep-2022 15:03:56.730661 bareos-sd (400): stored/wait.cc:111-28099 I'm going to sleep on device "tapedrive-0" (/dev/tape/by-id/scsi-350050763121a063c-nst). HB=0 rem_wait=3000 add_wait=3000 26-Sep-2022 15:09:17.153946 bareos-sd (100): lib/bsock.cc:84-0 Construct BareosSocket 26-Sep-2022 15:09:17.154195 bareos-sd (800): lib/thread_list.cc:243-0 Run WorkerThread successfully. 26-Sep-2022 15:09:17.155346 bareos-sd (100): lib/tls_openssl_private.cc:65-0 Construct TlsOpenSslPrivate 26-Sep-2022 15:09:17.155603 bareos-sd (100): lib/tls_openssl_private.cc:600-0 Set tcp filedescriptor: <6> 26-Sep-2022 15:09:17.155616 bareos-sd (100): lib/tls_openssl_private.cc:612-0 Set protocol: <> 26-Sep-2022 15:09:17.155621 bareos-sd (100): lib/tls_openssl_private.cc:546-0 Set ca_certfile: <> 26-Sep-2022 15:09:17.155626 bareos-sd (100): lib/tls_openssl_private.cc:552-0 Set ca_certdir: <> 26-Sep-2022 15:09:17.155631 bareos-sd (100): lib/tls_openssl_private.cc:558-0 Set crlfile_: <> 26-Sep-2022 15:09:17.155635 bareos-sd (100): lib/tls_openssl_private.cc:564-0 Set certfile_: <> 26-Sep-2022 15:09:17.155640 bareos-sd (100): lib/tls_openssl_private.cc:570-0 Set keyfile_: <> 26-Sep-2022 15:09:17.155644 bareos-sd (100): lib/tls_openssl_private.cc:588-0 Set dhfile_: <> 26-Sep-2022 15:09:17.155649 bareos-sd (100): lib/tls_openssl_private.cc:606-0 Set cipherlist: <> 26-Sep-2022 15:09:17.155654 bareos-sd (100): lib/tls_openssl_private.cc:594-0 Set Verify Peer: 26-Sep-2022 15:09:17.155658 bareos-sd (50): lib/tls_openssl.cc:79-0 Preparing TLS_PSK SERVER callback 26-Sep-2022 15:09:17.155780 bareos-sd (100): lib/tls_openssl_private.cc:466-0 psk_server_cb. identitiy: R_DIRECTOR bareos-dir. 26-Sep-2022 15:09:17.155794 bareos-sd (100): lib/tls_openssl_private.cc:487-0 psk_server_cb. result: 32. 26-Sep-2022 15:09:17.156586 bareos-sd (50): lib/bnet.cc:140-0 TLS server negotiation established. 26-Sep-2022 15:09:17.156696 bareos-sd (110): stored/socket_server.cc:97-0 Conn: Hello Director bareos-dir calling 26-Sep-2022 15:09:17.156706 bareos-sd (110): stored/socket_server.cc:114-0 Got a DIR connection at 26-Sep-2022 15:09:17 26-Sep-2022 15:09:17.156713 bareos-sd (100): lib/jcr.cc:191-0 Construct JobControlRecord 26-Sep-2022 15:09:17.156719 bareos-sd (800): lib/jcr.cc:778-0 setJobStatus(*System*, C) 26-Sep-2022 15:09:17.156724 bareos-sd (800): lib/jcr.cc:788-0 OnEntry JobStatus= newJobstatus=C 26-Sep-2022 15:09:17.156729 bareos-sd (800): lib/jcr.cc:798-0 Set new stat. old: ,0 new: C,0 26-Sep-2022 15:09:17.156734 bareos-sd (800): lib/jcr.cc:804-0 leave setJobStatus old= new=C 26-Sep-2022 15:09:17.156741 bareos-sd (250): stored/sd_plugins.cc:601-0 === enter NewPlugins === 26-Sep-2022 15:09:17.156746 bareos-sd (250): stored/sd_plugins.cc:603-0 No sd plugin list! 26-Sep-2022 15:09:17.156751 bareos-sd (1000): stored/dir_cmd.cc:278-0 stored in start_job 26-Sep-2022 15:09:17.156760 bareos-sd (800): lib/watchdog.cc:193-0 Registered watchdog 7fec1c0141f0, interval 600 one shot 26-Sep-2022 15:09:17.156944 bareos-sd (900): lib/btimers.cc:177-0 Start bsock timer 7fec1c008e60 tid=0x5800007fec2ba4f7 for 600 secs at 1664197757 26-Sep-2022 15:09:17.156962 bareos-sd (50): lib/cram_md5.cc:106-0 send: auth cram-md5 <1786761688.1664197757@R_STORAGE::bareos-sd> ssl=1 26-Sep-2022 15:09:17.157268 bareos-sd (100): lib/cram_md5.cc:166-0 cram-get received: auth cram-md5 <1373741968.1664197757@R_DIRECTOR::bareos-dir> ssl=1 26-Sep-2022 15:09:17.157279 bareos-sd (50): lib/cram_md5.cc:62-0 my_name: - challenge_name: 26-Sep-2022 15:09:17.157310 bareos-sd (99): lib/cram_md5.cc:231-0 sending resp to challenge: L3+iuVZRNC+mL+lj64IvbB 26-Sep-2022 15:09:17.157425 bareos-sd (900): lib/btimers.cc:193-0 Stop bsock timer 7fec1c008e60 tid=0x4400007fec2ba4f7 at 1664197757. 26-Sep-2022 15:09:17.157432 bareos-sd (800): lib/watchdog.cc:214-0 Unregistered watchdog 7fec1c0141f0 26-Sep-2022 15:09:17.157594 bareos-sd (90): stored/dir_cmd.cc:288-0 Message channel init completed. 26-Sep-2022 15:09:17.157728 bareos-sd (199): stored/dir_cmd.cc:295-0 max_block_size) 26-Sep-2022 15:09:17.157781 bareos-sd (650): stored/block.cc:144-0 Returning new block=1c014ee8 26-Sep-2022 15:09:17.157793 bareos-sd (500): stored/acquire.cc:771-0 JobId=0 enter AttachDcrToDev 26-Sep-2022 15:09:17.157799 bareos-sd (100): stored/dir_cmd.cc:984-0 mount cmd blocked=5 MustUnload=1 26-Sep-2022 15:09:17.157804 bareos-sd (100): stored/dir_cmd.cc:1003-0 Unmounted changer=0 slot=0 26-Sep-2022 15:09:17.157812 bareos-sd (100): stored/dev.cc:622-0 open dev: type=2 archive_device_string="tapedrive-0" (/dev/tape/by-id/scsi-350050763121a063c-nst) vol= mode=OPEN_READ_ONLY 26-Sep-2022 15:09:17.157818 bareos-sd (250): stored/sd_plugins.cc:313-0 No bplugin_list: GeneratePluginEvent ignored. 26-Sep-2022 15:09:17.157823 bareos-sd (100): stored/dev.cc:639-0 call OpenDevice mode=OPEN_READ_ONLY 26-Sep-2022 15:09:17.157835 bareos-sd (190): stored/dev.cc:1052-0 Enter mount 26-Sep-2022 15:09:17.157840 bareos-sd (250): stored/sd_plugins.cc:313-0 No bplugin_list: GeneratePluginEvent ignored. 26-Sep-2022 15:09:17.157850 bareos-sd (100): backends/generic_tape_device.cc:58-0 Open dev: device is tape 26-Sep-2022 15:09:17.157856 bareos-sd (100): backends/generic_tape_device.cc:67-0 Try open "tapedrive-0" (/dev/tape/by-id/scsi-350050763121a063c-nst) mode=OPEN_READ_ONLY 26-Sep-2022 15:09:17.160948 bareos-sd (100): backends/generic_tape_device.cc:89-0 Rewind after open 26-Sep-2022 15:09:21.702543 bareos-sd (100): backends/generic_tape_device.cc:936-0 In SetOsDeviceParameters 26-Sep-2022 15:09:21.702606 bareos-sd (100): backends/generic_tape_device.cc:134-0 open dev: tape 8 opened 26-Sep-2022 15:09:21.702616 bareos-sd (100): stored/dev.cc:645-0 preserve=5351165346 fd=8 26-Sep-2022 15:09:21.702627 bareos-sd (100): stored/dev.cc:566-0 setting minblocksize to 64512, maxblocksize to label_block_size=64512, on device "tapedrive-0" (/dev/tape/by-id/scsi-350050763121a063c-nst) 26-Sep-2022 15:09:21.702636 bareos-sd (100): stored/label.cc:91-0 Enter ReadVolumeLabel res=1 device="tapedrive-0" (/dev/tape/by-id/scsi-350050763121a063c-nst) vol= dev_Vol=*NULL* max_blocksize=64512 26-Sep-2022 15:09:21.702645 bareos-sd (400): backends/generic_tape_device.cc:1048-0 rewind res=1 fd=8 "tapedrive-0" (/dev/tape/by-id/scsi-350050763121a063c-nst) 26-Sep-2022 15:09:21.707675 bareos-sd (250): stored/sd_plugins.cc:313-0 No bplugin_list: GeneratePluginEvent ignored. 26-Sep-2022 15:09:21.707703 bareos-sd (130): stored/label.cc:146-0 Big if statement in ReadVolumeLabel 26-Sep-2022 15:09:21.707722 bareos-sd (250): stored/block.cc:956-0 Full read in ReadBlockFromDevice() len=64512 26-Sep-2022 15:09:21.810236 bareos-sd (250): stored/block.cc:1017-0 Read device got 64512 bytes at 0:0 26-Sep-2022 15:09:21.810297 bareos-sd (390): stored/block.cc:318-0 unSerBlockHeader block_len=203 26-Sep-2022 15:09:21.810310 bareos-sd (390): stored/block.cc:329-0 Read binbuf = 179 24 block_len=203 26-Sep-2022 15:09:21.810325 bareos-sd (250): stored/block.cc:1163-0 At end of read block 26-Sep-2022 15:09:21.810337 bareos-sd (250): stored/block.cc:1177-0 Exit read_block read_len=64512 block_len=203 26-Sep-2022 15:09:21.810351 bareos-sd (450): stored/record.cc:895-0 Block=0 Ver=2 size=203 26-Sep-2022 15:09:21.810363 bareos-sd (450): stored/record.cc:904-0 Enter read_record_block: remlen=179 data_len=0 rem=0 blkver=2 26-Sep-2022 15:09:21.810392 bareos-sd (450): stored/record.cc:968-0 rd_rec_blk() got FI=VOL_LABEL SessId=25 Strm=1 len=167 remlen=167 data_len=0 26-Sep-2022 15:09:21.810406 bareos-sd (450): stored/record.cc:1032-0 Rtn full rd_rec_blk FI=VOL_LABEL SessId=25 Strm=1 len=167 26-Sep-2022 15:09:21.810422 bareos-sd (190): stored/label.cc:755-0 unser_vol_label Volume Label: Id : Bareos 2.0 immortal VerNo : 20 VolName : NIX417L6 PrevVolName : VolFile : 0 LabelType : VOL_LABEL LabelSize : 167 PoolName : Scratch MediaType : LTO PoolType : Backup HostName : igms07.vision.local Date label written: 05-Nov-2018 11:42 26-Sep-2022 15:09:21.810475 bareos-sd (950): stored/record.cc:573-0 Enter FreeRecord. 26-Sep-2022 15:09:21.810487 bareos-sd (950): stored/record.cc:575-0 Data buf is freed. 26-Sep-2022 15:09:21.810498 bareos-sd (950): stored/record.cc:577-0 Leave FreeRecord. 26-Sep-2022 15:09:21.810510 bareos-sd (130): stored/label.cc:220-0 Compare Vol names: VolName= hdr=NIX417L6 Volume Label: Id : Bareos 2.0 immortal VerNo : 20 VolName : NIX417L6 PrevVolName : VolFile : 0 LabelType : VOL_LABEL LabelSize : 167 PoolName : Scratch MediaType : LTO PoolType : Backup HostName : igms07.vision.local Date label written: 05-Nov-2018 11:42 26-Sep-2022 15:09:21.810540 bareos-sd (130): stored/label.cc:241-0 Leave ReadVolumeLabel() VOL_OK 26-Sep-2022 15:09:21.810553 bareos-sd (400): backends/generic_tape_device.cc:1048-0 rewind res=1 fd=8 "tapedrive-0" (/dev/tape/by-id/scsi-350050763121a063c-nst) 26-Sep-2022 15:09:21.821038 bareos-sd (100): stored/label.cc:252-0 Call reserve_volume=NIX417L6 26-Sep-2022 15:09:21.821081 bareos-sd (150): stored/vol_mgr.cc:377-0 enter reserve_volume=NIX417L6 drive="tapedrive-0" (/dev/tape/by-id/scsi-350050763121a063c-nst) 26-Sep-2022 15:09:21.821092 bareos-sd (150): stored/vol_mgr.cc:272-0 new Vol=NIX417L6 at 7fec1c018d20 dev="tapedrive-0" (/dev/tape/by-id/scsi-350050763121a063c-nst) 26-Sep-2022 15:09:21.821098 bareos-sd (150): stored/vol_mgr.cc:544-0 === set in_use. vol=NIX417L6 dev="tapedrive-0" (/dev/tape/by-id/scsi-350050763121a063c-nst) 26-Sep-2022 15:09:21.821104 bareos-sd (150): stored/vol_mgr.cc:579-0 Inc walk_start UseCount=2 volname=NIX417L6 26-Sep-2022 15:09:21.821113 bareos-sd (150): stored/vol_mgr.cc:251-0 List end new volume: NIX417L6 in_use=1 swap=0 on device "tapedrive-0" (/dev/tape/by-id/scsi-350050763121a063c-nst) 26-Sep-2022 15:09:21.821119 bareos-sd (250): stored/sd_plugins.cc:313-0 No bplugin_list: GeneratePluginEvent ignored. 26-Sep-2022 15:09:21.821125 bareos-sd (100): stored/dev.cc:486-0 Device "tapedrive-0" (/dev/tape/by-id/scsi-350050763121a063c-nst) has dev->device->max_block_size of 1048576 and dev->max_block_size of 64512, dcr->VolMaxBlocksize is 0 26-Sep-2022 15:09:21.821130 bareos-sd (100): stored/dev.cc:493-0 setting dev->max_block_size to dev->device_resource->max_block_size=1048576 on device "tapedrive-0" (/dev/tape/by-id/scsi-350050763121a063c-nst) because dcr->VolMaxBlocksize is 0 26-Sep-2022 15:09:21.821135 bareos-sd (100): stored/dev.cc:534-0 set minblocksize to 0, maxblocksize to 1048576 on device "tapedrive-0" (/dev/tape/by-id/scsi-350050763121a063c-nst) 26-Sep-2022 15:09:21.821140 bareos-sd (100): stored/dev.cc:544-0 created new block of buf_len: 1048576 on device "tapedrive-0" (/dev/tape/by-id/scsi-350050763121a063c-nst) 26-Sep-2022 15:09:21.821145 bareos-sd (999): stored/block.cc:176-0 FreeBlock buffer 1c026fd8 26-Sep-2022 15:09:21.821151 bareos-sd (999): stored/block.cc:178-0 FreeBlock block 1c014ee8 26-Sep-2022 15:09:21.821156 bareos-sd (100): stored/block.cc:137-0 created new block of blocksize 1048576 (dev->max_block_size) 26-Sep-2022 15:09:21.821179 bareos-sd (650): stored/block.cc:144-0 Returning new block=1c014ee8 26-Sep-2022 15:09:21.821184 bareos-sd (100): stored/dev.cc:549-0 created new block of buf_len: 1048576 on device "tapedrive-0" (/dev/tape/by-id/scsi-350050763121a063c-nst), freeing block 26-Sep-2022 15:09:21.821189 bareos-sd (100): stored/dir_cmd.cc:1026-0 Unmounted waiting for mount. Attempting to wake thread 26-Sep-2022 15:09:21.821293 bareos-sd (100): stored/dir_cmd.cc:1041-0 JobId=0 broadcast wait_device_release 26-Sep-2022 15:09:21.821303 bareos-sd (500): stored/acquire.cc:789-0 Enter DetachDcrFromDev 26-Sep-2022 15:09:21.821308 bareos-sd (999): stored/block.cc:176-0 FreeBlock buffer 1c026fd8 26-Sep-2022 15:09:21.821313 bareos-sd (999): stored/block.cc:178-0 FreeBlock block 1c014ee8 26-Sep-2022 15:09:21.821317 bareos-sd (950): stored/record.cc:573-0 Enter FreeRecord. 26-Sep-2022 15:09:21.821318 26-Sep-2022 15:09:21.821323 bareos-sd (950): stored/record.cc:575-0 Data buf is freed. 26-Sep-2022 15:09:21.821332 bareos-sd (950): stored/record.cc:577-0 Leave FreeRecord. bareos-sd (400): stored/wait.cc:119-28099 Wokeup from sleep on device status=0 blocked=BST_MOUNT 26-Sep-2022 15:09:21.821357 bareos-sd (400): stored/wait.cc:160-28099 poll return in wait blocked=BST_MOUNT 26-Sep-2022 15:09:21.821362 bareos-sd (400): stored/wait.cc:205-28099 set BST_DOING_ACQUIRE 26-Sep-2022 15:09:21.821367 bareos-sd (400): stored/wait.cc:207-28099 Exit blocked=BST_DOING_ACQUIRE 26-Sep-2022 15:09:21.821373 bareos-sd (50): stored/askdir.cc:584-28099 Back from WaitForSysop status=3 26-Sep-2022 15:09:21.821379 bareos-sd (50): stored/askdir.cc:587-28099 Poll timeout in mount vol on device "tapedrive-0" (/dev/tape/by-id/scsi-350050763121a063c-nst) 26-Sep-2022 15:09:21.821386 bareos-sd (50): stored/askdir.cc:588-28099 Blocked=BST_DOING_ACQUIRE 26-Sep-2022 15:09:21.821391 bareos-sd (800): lib/jcr.cc:778-28099 setJobStatus(RestoreFiles.2022-09-26_08.55.04_22, R) 26-Sep-2022 15:09:21.821396 bareos-sd (800): lib/jcr.cc:788-28099 OnEntry JobStatus=M newJobstatus=R 26-Sep-2022 15:09:21.821408 bareos-sd (800): lib/jcr.cc:798-28099 Set new stat. old: M,0 new: R,0 26-Sep-2022 15:09:21.821413 bareos-sd (800): lib/jcr.cc:804-28099 leave setJobStatus old=M new=R 26-Sep-2022 15:09:21.821474 bareos-sd (50): stored/askdir.cc:617-28099 leave DirAskSysopToMountVolume 26-Sep-2022 15:09:21.821485 bareos-sd (150): stored/acquire.cc:366-28099 DirGetVolumeInfo vol=NIX417L6 26-Sep-2022 15:09:21.821526 bareos-sd (50): stored/askdir.cc:177-28099 >dird CatReq Job=RestoreFiles.2022-09-26_08.55.04_22 GetVolInfo VolName=NIX417L6 write=0 26-Sep-2022 15:09:21.822375 bareos-sd (50): stored/askdir.cc:106-28099 VolMinBlocksize(0) to vol.VolMinBlocksize(0) 26-Sep-2022 15:09:21.822402 bareos-sd (50): stored/askdir.cc:147-28099 setting dcr->VolMaxBlocksize(1048576) to vol.VolMaxBlocksize(1048576) 26-Sep-2022 15:09:21.822408 bareos-sd (250): stored/sd_plugins.cc:313-28099 No bplugin_list: GeneratePluginEvent ignored. 26-Sep-2022 15:09:21.822413 bareos-sd (100): stored/mount.cc:644-28099 No swap_dev set 26-Sep-2022 15:09:21.822418 bareos-sd (100): stored/mount.cc:596-28099 Must load "tapedrive-0" (/dev/tape/by-id/scsi-350050763121a063c-nst) 26-Sep-2022 15:09:21.822423 bareos-sd (100): stored/autochanger.cc:130-28099 Device "tapedrive-0" (/dev/tape/by-id/scsi-350050763121a063c-nst) is not attached to an autochanger 26-Sep-2022 15:09:21.822762 bareos-sd (250): stored/sd_plugins.cc:313-28099 No bplugin_list: GeneratePluginEvent ignored. 26-Sep-2022 15:09:21.822771 bareos-sd (100): stored/acquire.cc:281-28099 stored: open vol=NIX417L6 26-Sep-2022 15:09:21.822778 bareos-sd (100): stored/acquire.cc:290-28099 opened dev "tapedrive-0" (/dev/tape/by-id/scsi-350050763121a063c-nst) OK 26-Sep-2022 15:09:21.822784 bareos-sd (100): stored/acquire.cc:308-28099 Got correct volume. 26-Sep-2022 15:09:21.822800 bareos-sd (850): lib/message.cc:1252-28099 Enter Jmsg type=6 26-Sep-2022 15:09:21.822809 bareos-sd (850): lib/message.cc:614-28099 Enter DispatchMessage type=6 msg=bareos-sd JobId 28099: Ready to read from volume "NIX417L6" on device "tapedrive-0" (/dev/tape/by-id/scsi-350050763121a063c-nst). 26-Sep-2022 15:09:21.822817 bareos-sd (850): lib/message.cc:860-28099 DIRECTOR for following msg: bareos-sd JobId 28099: Ready to read from volume "NIX417L6" on device "tapedrive-0" (/dev/tape/by-id/scsi-350050763121a063c-nst). 26-Sep-2022 15:09:21.822872 bareos-sd (150): stored/reserve.cc:149-28099 Dec reserve=0 dev="tapedrive-0" (/dev/tape/by-id/scsi-350050763121a063c-nst) 26-Sep-2022 15:09:21.822882 bareos-sd (300): stored/lock.cc:265-28099 unblock BST_DOING_ACQUIRE from ../../../../core/src/stored/lock.cc:136 26-Sep-2022 15:09:21.822888 bareos-sd (100): stored/acquire.cc:408-28099 dcr=7fec24018690 dev=7fec240022e0 26-Sep-2022 15:09:21.822894 bareos-sd (100): stored/acquire.cc:410-28099 MediaType dcr=LTO dev=LTO 26-Sep-2022 15:09:21.822900 bareos-sd (250): stored/block.cc:923-28099 Enter ReadBlockFromDevice 26-Sep-2022 15:09:21.822906 bareos-sd (250): stored/block.cc:956-28099 Full read in ReadBlockFromDevice() len=64512 26-Sep-2022 15:09:21.831058 bareos-sd (250): stored/block.cc:1017-28099 Read device got 64512 bytes at 0:0 26-Sep-2022 15:09:21.831099 bareos-sd (390): stored/block.cc:318-28099 unSerBlockHeader block_len=203 26-Sep-2022 15:09:21.831105 bareos-sd (390): stored/block.cc:329-28099 Read binbuf = 179 24 block_len=203 26-Sep-2022 15:09:21.831114 bareos-sd (250): stored/block.cc:1163-28099 At end of read block 26-Sep-2022 15:09:21.831133 bareos-sd (250): stored/block.cc:1177-28099 Exit read_block read_len=64512 block_len=203 26-Sep-2022 15:09:21.831140 bareos-sd (250): stored/block.cc:927-28099 Leave ReadBlockFromDevice 26-Sep-2022 15:09:21.831147 bareos-sd (450): stored/record.cc:895-28099 Block=0 Ver=2 size=203 26-Sep-2022 15:09:21.831152 bareos-sd (450): stored/record.cc:904-28099 Enter read_record_block: remlen=179 data_len=0 rem=0 blkver=2 26-Sep-2022 15:09:21.831162 bareos-sd (450): stored/record.cc:968-28099 rd_rec_blk() got FI=VOL_LABEL SessId=25 Strm=1 len=167 remlen=167 data_len=0 26-Sep-2022 15:09:21.831169 bareos-sd (450): stored/record.cc:1032-28099 Rtn full rd_rec_blk FI=VOL_LABEL SessId=25 Strm=1 len=167 26-Sep-2022 15:09:21.831191 bareos-sd (190): stored/label.cc:755-28099 unser_vol_label Volume Label: Id : Bareos 2.0 immortal VerNo : 20 VolName : NIX417L6 PrevVolName : VolFile : 0 LabelType : VOL_LABEL LabelSize : 167 PoolName : Scratch MediaType : LTO PoolType : Backup HostName : igms07.vision.local Date label written: 05-Nov-2018 11:42 26-Sep-2022 15:09:21.831209 bareos-sd (500): stored/read_record.cc:85-28099 Volume Label Record: VolSessionId=25 VolSessionTime=1541740509 JobId=1 DataLen=167 26-Sep-2022 15:09:21.831216 bareos-sd (950): stored/record.cc:573-28099 Enter FreeRecord. 26-Sep-2022 15:09:21.831222 bareos-sd (950): stored/record.cc:575-28099 Data buf is freed. 26-Sep-2022 15:09:21.831227 bareos-sd (950): stored/record.cc:577-28099 Leave FreeRecord. 26-Sep-2022 15:09:21.831233 bareos-sd (500): stored/bsr.cc:259-28099 use_pos=1 repos=1 26-Sep-2022 15:09:21.831249 bareos-sd (500): stored/bsr.cc:545-28099 MatchVolume=NIX417L6 26-Sep-2022 15:09:21.831258 bareos-sd (500): stored/bsr.cc:545-28099 MatchVolume=NIX417L6 26-Sep-2022 15:09:21.831263 bareos-sd (500): stored/bsr.cc:545-28099 MatchVolume=NIX417L6 26-Sep-2022 15:09:21.831269 bareos-sd (500): stored/bsr.cc:545-28099 MatchVolume=NIX417L6 26-Sep-2022 15:09:21.831274 bareos-sd (500): stored/bsr.cc:545-28099 MatchVolume=NIX417L6 26-Sep-2022 15:09:21.831280 bareos-sd (500): stored/bsr.cc:545-28099 MatchVolume=NIX417L6 26-Sep-2022 15:09:21.831285 bareos-sd (500): stored/bsr.cc:545-28099 MatchVolume=NIX417L6 26-Sep-2022 15:09:21.831291 bareos-sd (500): stored/bsr.cc:545-28099 MatchVolume=NIX417L6 26-Sep-2022 15:09:21.831296 bareos-sd (500): stored/bsr.cc:545-28099 MatchVolume=NIX417L6 26-Sep-2022 15:09:21.831301 bareos-sd (500): stored/bsr.cc:545-28099 MatchVolume=NIX417L6 26-Sep-2022 15:09:21.831307 bareos-sd (500): stored/bsr.cc:545-28099 MatchVolume=NIX417L6 26-Sep-2022 15:09:21.831312 bareos-sd (500): stored/bsr.cc:545-28099 MatchVolume=NIX417L6 26-Sep-2022 15:09:21.831318 bareos-sd (500): stored/bsr.cc:545-28099 MatchVolume=NIX417L6 26-Sep-2022 15:09:21.831323 bareos-sd (500): stored/bsr.cc:545-28099 MatchVolume=NIX417L6 26-Sep-2022 15:09:21.831328 bareos-sd (500): stored/bsr.cc:545-28099 MatchVolume=NIX417L6 26-Sep-2022 15:09:21.831334 bareos-sd (500): stored/bsr.cc:545-28099 MatchVolume=NIX417L6 26-Sep-2022 15:09:21.831341 bareos-sd (850): lib/message.cc:1252-28099 Enter Jmsg type=6 26-Sep-2022 15:09:21.831351 bareos-sd (850): lib/message.cc:614-28099 Enter DispatchMessage type=6 msg=bareos-sd JobId 28099: Forward spacing Volume "NIX417L6" to file:block 0:1. 26-Sep-2022 15:09:21.831359 bareos-sd (850): lib/message.cc:860-28099 DIRECTOR for following msg: bareos-sd JobId 28099: Forward spacing Volume "NIX417L6" to file:block 0:1. 26-Sep-2022 15:09:21.831412 bareos-sd (100): backends/generic_tape_device.cc:1296-28099 Reposition from 0:1 to 0:1 26-Sep-2022 15:09:21.831419 bareos-sd (250): stored/block.cc:923-28099 Enter ReadBlockFromDevice 26-Sep-2022 15:09:21.831425 bareos-sd (250): stored/block.cc:956-28099 Full read in ReadBlockFromDevice() len=64512 26-Sep-2022 15:09:21.831950 bareos-sd (250): stored/block.cc:999-28099 Read device got: ERR=Cannot allocate memory 26-Sep-2022 15:09:21.831976 bareos-sd (250): stored/sd_plugins.cc:313-28099 No bplugin_list: GeneratePluginEvent ignored. 26-Sep-2022 15:09:21.831988 bareos-sd (850): lib/message.cc:1252-28099 Enter Jmsg type=4 26-Sep-2022 15:09:21.831998 bareos-sd (850): lib/message.cc:614-28099 Enter DispatchMessage type=4 msg=bareos-sd JobId 28099: Error: stored/block.cc:1004 Read error on fd=8 at file:blk 0:1 on device "tapedrive-0" (/dev/tape/by-id/scsi-350050763121a063c-nst). ERR=Cannot allocate memory. 26-Sep-2022 15:09:21.832005 bareos-sd (850): lib/message.cc:860-28099 DIRECTOR for following msg: bareos-sd JobId 28099: Error: stored/block.cc:1004 Read error on fd=8 at file:blk 0:1 on device "tapedrive-0" (/dev/tape/by-id/scsi-350050763121a063c-nst). ERR=Cannot allocate memory. 26-Sep-2022 15:09:21.832028 bareos-sd (250): stored/block.cc:927-28099 Leave ReadBlockFromDevice Bareos status: file=0 block=1 Device status: ONLINE IM_REP_EN file=0 block=2 26-Sep-2022 15:09:21.832058 bareos-sd (950): stored/record.cc:573-28099 Enter FreeRecord. 26-Sep-2022 15:09:21.832064 bareos-sd (950): stored/record.cc:575-28099 Data buf is freed. 26-Sep-2022 15:09:21.832069 bareos-sd (950): stored/record.cc:577-28099 Leave FreeRecord. 26-Sep-2022 15:09:21.832123 bareos-sd (850): lib/message.cc:1252-28099 Enter Jmsg type=6 26-Sep-2022 15:09:21.832133 bareos-sd (850): lib/message.cc:614-28099 Enter DispatchMessage type=6 msg=bareos-sd JobId 28099: Releasing device "tapedrive-0" (/dev/tape/by-id/scsi-350050763121a063c-nst). 26-Sep-2022 15:09:21.832139 bareos-sd (850): lib/message.cc:860-28099 DIRECTOR for following msg: bareos-sd JobId 28099: Releasing device "tapedrive-0" (/dev/tape/by-id/scsi-350050763121a063c-nst). 26-Sep-2022 15:09:21.832155 bareos-sd (300): stored/lock.cc:254-28099 set blocked=BST_RELEASING from ../../../../core/src/stored/acquire.cc:551 26-Sep-2022 15:09:21.832162 bareos-sd (100): stored/acquire.cc:557-28099 releasing device "tapedrive-0" (/dev/tape/by-id/scsi-350050763121a063c-nst) 26-Sep-2022 15:09:21.832168 bareos-sd (150): stored/acquire.cc:567-28099 dir_update_vol_info. label=1 Vol=NIX417L6 26-Sep-2022 15:09:21.832174 bareos-sd (50): stored/askdir.cc:294-28099 Update cat VolBytes=3855636189184 26-Sep-2022 15:09:21.832190 bareos-sd (50): stored/askdir.cc:315-28099 >dird CatReq Job=RestoreFiles.2022-09-26_08.55.04_22 UpdateMedia VolName=NIX417L6 VolJobs=28 VolFiles=121 VolBlocks=3677044 VolBytes=3855636189184 VolMounts=28 VolErrors=0 VolWrites=3677045 MaxVolBytes=0 EndTime=1664197761 VolStatus=Used Slot=0 relabel=0 InChanger=0 VolReadTime=20412052749 VolWriteTime=7613319379 VolFirstWritten=0 26-Sep-2022 15:09:21.861821 bareos-sd (250): stored/sd_plugins.cc:313-0 No bplugin_list: GeneratePluginEvent ignored. 26-Sep-2022 15:09:21.861843 bareos-sd (580): lib/message.cc:328-0 Close_msg jcr=7fec1c0129e0 26-Sep-2022 15:09:21.861849 bareos-sd (200): stored/job.cc:389-0 Start stored FreeJcr 26-Sep-2022 15:09:21.861854 bareos-sd (800): stored/job.cc:390-0 End Job JobId=0 7fec1c0129e0 26-Sep-2022 15:09:21.861859 bareos-sd (800): stored/job.cc:393-0 Send Terminate jid=0 7fec1c0129e0 26-Sep-2022 15:09:21.861866 bareos-sd (200): stored/job.cc:500-0 End stored FreeJcr 26-Sep-2022 15:09:21.861870 bareos-sd (100): lib/jcr.cc:273-0 FreeCommonJcr: 7fec1c0129e0 26-Sep-2022 15:09:21.861878 bareos-sd (800): lib/watchdog.cc:193-0 Registered watchdog 7fec1c0141f0, interval 120 one shot 26-Sep-2022 15:09:21.862065 bareos-sd (900): lib/btimers.cc:177-0 Start bsock timer 7fec1c008e60 tid=0x7800007fec2ba4f7 for 120 secs at 1664197761 26-Sep-2022 15:09:21.862099 bareos-sd (900): lib/btimers.cc:193-0 Stop bsock timer 7fec1c008e60 tid=0x7800007fec2ba4f7 at 1664197761. 26-Sep-2022 15:09:21.862107 bareos-sd (800): lib/watchdog.cc:214-0 Unregistered watchdog 7fec1c0141f0 26-Sep-2022 15:09:21.862291 bareos-sd (800): lib/watchdog.cc:193-0 Registered watchdog 7fec1c0141f0, interval 2 one shot 26-Sep-2022 15:09:21.862476 bareos-sd (900): lib/btimers.cc:177-0 Start bsock timer 7fec1c008e60 tid=0x0200007fec2ba4f7 for 2 secs at 1664197761 26-Sep-2022 15:09:21.862495 bareos-sd (900): lib/btimers.cc:193-0 Stop bsock timer 7fec1c008e60 tid=0x0000007fec2ba4f7 at 1664197761. 26-Sep-2022 15:09:21.862511 bareos-sd (800): lib/watchdog.cc:214-0 Unregistered watchdog 7fec1c0141f0 26-Sep-2022 15:09:21.862709 bareos-sd (100): lib/tls_openssl_private.cc:96-0 Destruct TlsOpenSslPrivate 26-Sep-2022 15:09:21.862765 bareos-sd (100): lib/bsock.cc:136-0 Destruct BareosSocket 26-Sep-2022 15:09:21.862773 bareos-sd (580): lib/message.cc:328-0 Close_msg jcr=0 26-Sep-2022 15:09:21.862778 bareos-sd (850): lib/message.cc:350-0 ===Begin close msg resource at a3e840 26-Sep-2022 15:09:21.862783 bareos-sd (850): lib/message.cc:455-0 Done walking message chain. 26-Sep-2022 15:09:21.862788 bareos-sd (850): lib/message.cc:462-0 ===End close msg resource 26-Sep-2022 15:09:21.862793 bareos-sd (800): lib/thread_list.cc:207-0 Finished WorkerThread. 26-Sep-2022 15:09:21.868848 bareos-sd (50): stored/askdir.cc:106-28099 VolMinBlocksize(0) to vol.VolMinBlocksize(0) 26-Sep-2022 15:09:21.868875 bareos-sd (50): stored/askdir.cc:147-28099 setting dcr->VolMaxBlocksize(1048576) to vol.VolMaxBlocksize(1048576) 26-Sep-2022 15:09:21.868881 bareos-sd (420): stored/askdir.cc:325-28099 get_volume_info() 1000 OK VolName=NIX417L6 VolJobs=28 VolFiles=121 VolBlocks=3677044 VolBytes=3855636189184 VolMounts=28 VolErrors=0 VolWrites=3677045 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Used Slot=0 MaxVolJobs=0 MaxVolFiles=0 InChanger=0 VolReadTime=20412052749 VolWriteTime=7613319379 EndFile=120 EndBlock=0 LabelType=0 MediaId=39 EncryptionKey= MinBlocksize=0 MaxBlocksize=1048576 26-Sep-2022 15:09:21.868891 bareos-sd (150): stored/vol_mgr.cc:190-28099 remove_read_vol=NIX417L6 JobId=28099 found=1 26-Sep-2022 15:09:21.868898 bareos-sd (150): stored/vol_mgr.cc:724-28099 === clear in_use vol=NIX417L6 26-Sep-2022 15:09:21.868903 bareos-sd (150): stored/vol_mgr.cc:746-28099 === set not reserved vol=NIX417L6 num_writers=0 dev_reserved=0 dev="tapedrive-0" (/dev/tape/by-id/scsi-350050763121a063c-nst) 26-Sep-2022 15:09:21.868908 bareos-sd (100): stored/acquire.cc:619-28099 0 writers, 0 reserve, dev="tapedrive-0" (/dev/tape/by-id/scsi-350050763121a063c-nst) 26-Sep-2022 15:09:21.868914 bareos-sd (250): stored/sd_plugins.cc:313-28099 No bplugin_list: GeneratePluginEvent ignored. 26-Sep-2022 15:09:21.868922 bareos-sd (100): stored/acquire.cc:677-28099 JobId=28099 broadcast wait_device_release at 26-Sep-2022 15:09:21 26-Sep-2022 15:09:21.868928 bareos-sd (300): stored/lock.cc:265-28099 unblock BST_RELEASING from ../../../../core/src/stored/lock.cc:136 26-Sep-2022 15:09:21.868933 bareos-sd (500): stored/acquire.cc:789-28099 Enter DetachDcrFromDev 26-Sep-2022 15:09:21.868938 bareos-sd (200): stored/acquire.cc:797-28099 Detach Jid=28099 dcr=7fec24018690 size=1 to dev="tapedrive-0" (/dev/tape/by-id/scsi-350050763121a063c-nst) 26-Sep-2022 15:09:21.868944 bareos-sd (999): stored/block.cc:176-28099 FreeBlock buffer 2401bd78 26-Sep-2022 15:09:21.868949 bareos-sd (999): stored/block.cc:178-28099 FreeBlock block 2401a858 26-Sep-2022 15:09:21.868954 bareos-sd (950): stored/record.cc:573-28099 Enter FreeRecord. 26-Sep-2022 15:09:21.868959 bareos-sd (950): stored/record.cc:575-28099 Data buf is freed. 26-Sep-2022 15:09:21.868964 bareos-sd (950): stored/record.cc:577-28099 Leave FreeRecord. 26-Sep-2022 15:09:21.868970 bareos-sd (100): stored/acquire.cc:696-28099 Device "tapedrive-0" (/dev/tape/by-id/scsi-350050763121a063c-nst) released by JobId=28099 26-Sep-2022 15:09:21.868975 bareos-sd (30): stored/read.cc:101-28099 Done reading. 26-Sep-2022 15:09:21.868997 bareos-sd (850): lib/message.cc:1252-28099 Enter Jmsg type=3 26-Sep-2022 15:09:21.869006 bareos-sd (800): lib/jcr.cc:778-28099 setJobStatus(RestoreFiles.2022-09-26_08.55.04_22, f) 26-Sep-2022 15:09:21.869011 bareos-sd (800): lib/jcr.cc:788-28099 OnEntry JobStatus=R newJobstatus=f 26-Sep-2022 15:09:21.869015 bareos-sd (800): lib/jcr.cc:798-28099 Set new stat. old: R,0 new: f,9 26-Sep-2022 15:09:21.869020 bareos-sd (800): lib/jcr.cc:804-28099 leave setJobStatus old=R new=f 26-Sep-2022 15:09:21.869025 bareos-sd (850): lib/message.cc:614-28099 Enter DispatchMessage type=3 msg=bareos-sd JobId 28099: Fatal error: stored/fd_cmds.cc:219 Command error with FD, hanging up. Wrong Volume mounted on device "tapedrive-0" (/dev/tape/by-id/scsi-350050763121a063c-nst): Wanted NIX417L6 have NIX416L6 26-Sep-2022 15:09:21.869032 bareos-sd (850): lib/message.cc:860-28099 DIRECTOR for following msg: bareos-sd JobId 28099: Fatal error: stored/fd_cmds.cc:219 Command error with FD, hanging up. Wrong Volume mounted on device "tapedrive-0" (/dev/tape/by-id/scsi-350050763121a063c-nst): Wanted NIX417L6 have NIX416L6 26-Sep-2022 15:09:21.869064 bareos-sd (800): lib/jcr.cc:778-28099 setJobStatus(RestoreFiles.2022-09-26_08.55.04_22, E) 26-Sep-2022 15:09:21.869072 bareos-sd (800): lib/jcr.cc:788-28099 OnEntry JobStatus=f newJobstatus=E 26-Sep-2022 15:09:21.869127 bareos-sd (800): lib/jcr.cc:778-28099 setJobStatus(RestoreFiles.2022-09-26_08.55.04_22, T) 26-Sep-2022 15:09:21.869142 bareos-sd (800): lib/jcr.cc:788-28099 OnEntry JobStatus=f newJobstatus=T 26-Sep-2022 15:09:21.869148 bareos-sd (250): stored/sd_plugins.cc:313-28099 No bplugin_list: GeneratePluginEvent ignored. 26-Sep-2022 15:09:21.869182 bareos-sd (800): stored/job.cc:241-28099 Done jid=28099 7fec24017480 26-Sep-2022 15:09:21.869189 bareos-sd (190): stored/dir_cmd.cc:312-28099 Command run requests quit 26-Sep-2022 15:09:21.869194 bareos-sd (250): stored/sd_plugins.cc:313-28099 No bplugin_list: GeneratePluginEvent ignored. 26-Sep-2022 15:09:21.869205 bareos-sd (580): lib/message.cc:328-28099 Close_msg jcr=7fec24017480 26-Sep-2022 15:09:21.869211 bareos-sd (200): stored/job.cc:389-28099 Start stored FreeJcr 26-Sep-2022 15:09:21.869215 bareos-sd (800): stored/job.cc:390-28099 End Job JobId=28099 7fec24017480 26-Sep-2022 15:09:21.869220 bareos-sd (800): stored/job.cc:393-28099 Send Terminate jid=28099 7fec24017480 26-Sep-2022 15:09:21.869235 bareos-sd (800): lib/watchdog.cc:193-28099 Registered watchdog 7fec24015580, interval 120 one shot 26-Sep-2022 15:09:21.869416 bareos-sd (900): lib/btimers.cc:177-28099 Start bsock timer 7fec2401a780 tid=0x7800007fec2ce607 for 120 secs at 1664197761 26-Sep-2022 15:09:21.869437 bareos-sd (900): lib/btimers.cc:193-28099 Stop bsock timer 7fec2401a780 tid=0x7800007fec2ce607 at 1664197761. 26-Sep-2022 15:09:21.869443 bareos-sd (800): lib/watchdog.cc:214-28099 Unregistered watchdog 7fec24015580 26-Sep-2022 15:09:21.869580 bareos-sd (800): lib/watchdog.cc:193-28099 Registered watchdog 7fec24015580, interval 2 one shot 26-Sep-2022 15:09:21.869766 bareos-sd (900): lib/btimers.cc:177-28099 Start bsock timer 7fec2401a780 tid=0x0200007fec2ce607 for 2 secs at 1664197761 26-Sep-2022 15:09:21.869788 bareos-sd (900): lib/btimers.cc:193-28099 Stop bsock timer 7fec2401a780 tid=0x0000007fec2ce607 at 1664197761. 26-Sep-2022 15:09:21.869795 bareos-sd (800): lib/watchdog.cc:214-28099 Unregistered watchdog 7fec24015580 26-Sep-2022 15:09:21.869982 bareos-sd (100): lib/tls_openssl_private.cc:96-28099 Destruct TlsOpenSslPrivate 26-Sep-2022 15:09:21.870035 bareos-sd (100): lib/bsock.cc:136-28099 Destruct BareosSocket 26-Sep-2022 15:09:21.870083 bareos-sd (150): stored/vol_mgr.cc:190-28099 remove_read_vol=NIX416L6 JobId=28099 found=1 26-Sep-2022 15:09:21.870286 bareos-sd (100): lib/bsys.cc:677-28099 write_last_jobs seek to 192 26-Sep-2022 15:09:21.870318 bareos-sd (200): stored/job.cc:500-28099 End stored FreeJcr 26-Sep-2022 15:09:21.870324 bareos-sd (100): lib/jcr.cc:273-28099 FreeCommonJcr: 7fec24017480 26-Sep-2022 15:09:21.870332 bareos-sd (800): lib/watchdog.cc:193-0 Registered watchdog 7fec1c001c70, interval 120 one shot 26-Sep-2022 15:09:21.870509 bareos-sd (900): lib/btimers.cc:177-0 Start bsock timer 7fec1c0015f0 tid=0x7800007fec2ce607 for 120 secs at 1664197761 26-Sep-2022 15:09:21.870527 bareos-sd (900): lib/btimers.cc:193-0 Stop bsock timer 7fec1c0015f0 tid=0x7800007fec2ce607 at 1664197761. 26-Sep-2022 15:09:21.870533 bareos-sd (800): lib/watchdog.cc:214-0 Unregistered watchdog 7fec1c001c70 26-Sep-2022 15:09:21.870708 bareos-sd (800): lib/watchdog.cc:193-0 Registered watchdog 7fec1c001c70, interval 2 one shot 26-Sep-2022 15:09:21.870890 bareos-sd (900): lib/btimers.cc:177-0 Start bsock timer 7fec1c0015f0 tid=0x0200007fec2ce607 for 2 secs at 1664197761 26-Sep-2022 15:09:23.870850 bareos-sd (900): lib/btimers.cc:220-0 thread timer 7fec1c001c70 kill bsock tid=7fec2c65ecf0 at 1664197763. 26-Sep-2022 15:09:23.870891 bareos-sd (900): lib/btimers.cc:223-0 killed JobId=28099 Job=RestoreFiles.2022-09-26_08.55.04_22 26-Sep-2022 15:09:23.870942 bareos-sd (900): lib/btimers.cc:193-0 Stop bsock timer 7fec1c0015f0 tid=0x0000007fec2ce607 at 1664197763. 26-Sep-2022 15:09:23.870974 bareos-sd (800): lib/watchdog.cc:223-0 Unregistered inactive watchdog 7fec1c001c70 26-Sep-2022 15:09:23.871223 bareos-sd (100): lib/tls_openssl_private.cc:96-0 Destruct TlsOpenSslPrivate 26-Sep-2022 15:09:23.871330 bareos-sd (100): lib/bsock.cc:136-0 Destruct BareosSocket 26-Sep-2022 15:09:23.871348 bareos-sd (580): lib/message.cc:328-0 Close_msg jcr=0 26-Sep-2022 15:09:23.871361 bareos-sd (850): lib/message.cc:350-0 ===Begin close msg resource at a3e840 26-Sep-2022 15:09:23.871373 bareos-sd (850): lib/message.cc:455-0 Done walking message chain. 26-Sep-2022 15:09:23.871384 bareos-sd (850): lib/message.cc:462-0 ===End close msg resource 26-Sep-2022 15:09:23.871397 bareos-sd (800): lib/thread_list.cc:207-0 Finished WorkerThread. 26-Sep-2022 15:13:27.066164 bareos-sd (100): lib/bsock.cc:84-0 Construct BareosSocket 26-Sep-2022 15:13:27.068750 bareos-sd (800): lib/thread_list.cc:243-0 Run WorkerThread successfully. 26-Sep-2022 15:13:27.069465 bareos-sd (100): lib/tls_openssl_private.cc:65-0 Construct TlsOpenSslPrivate 26-Sep-2022 15:13:27.071194 bareos-sd (100): lib/tls_openssl_private.cc:600-0 Set tcp filedescriptor: <5> 26-Sep-2022 15:13:27.071229 bareos-sd (100): lib/tls_openssl_private.cc:612-0 Set protocol: <> 26-Sep-2022 15:13:27.071243 bareos-sd (100): lib/tls_openssl_private.cc:546-0 Set ca_certfile: <> 26-Sep-2022 15:13:27.071255 bareos-sd (100): lib/tls_openssl_private.cc:552-0 Set ca_certdir: <> 26-Sep-2022 15:13:27.071266 bareos-sd (100): lib/tls_openssl_private.cc:558-0 Set crlfile_: <> 26-Sep-2022 15:13:27.071278 bareos-sd (100): lib/tls_openssl_private.cc:564-0 Set certfile_: <> 26-Sep-2022 15:13:27.071289 bareos-sd (100): lib/tls_openssl_private.cc:570-0 Set keyfile_: <> 26-Sep-2022 15:13:27.071301 bareos-sd (100): lib/tls_openssl_private.cc:588-0 Set dhfile_: <> 26-Sep-2022 15:13:27.071312 bareos-sd (100): lib/tls_openssl_private.cc:606-0 Set cipherlist: <> 26-Sep-2022 15:13:27.071324 bareos-sd (100): lib/tls_openssl_private.cc:594-0 Set Verify Peer: 26-Sep-2022 15:13:27.071336 bareos-sd (50): lib/tls_openssl.cc:79-0 Preparing TLS_PSK SERVER callback 26-Sep-2022 15:13:27.074636 bareos-sd (100): lib/tls_openssl_private.cc:466-0 psk_server_cb. identitiy: R_DIRECTOR bareos-dir. 26-Sep-2022 15:13:27.074714 bareos-sd (100): lib/tls_openssl_private.cc:487-0 psk_server_cb. result: 32. 26-Sep-2022 15:13:27.076302 bareos-sd (50): lib/bnet.cc:140-0 TLS server negotiation established. 26-Sep-2022 15:13:27.076330 bareos-sd (110): stored/socket_server.cc:97-0 Conn: Hello Director bareos-dir calling 26-Sep-2022 15:13:27.076337 bareos-sd (110): stored/socket_server.cc:114-0 Got a DIR connection at 26-Sep-2022 15:13:27 26-Sep-2022 15:13:27.076349 bareos-sd (100): lib/jcr.cc:191-0 Construct JobControlRecord 26-Sep-2022 15:13:27.076356 bareos-sd (800): lib/jcr.cc:778-0 setJobStatus(*System*, C) 26-Sep-2022 15:13:27.076361 bareos-sd (800): lib/jcr.cc:788-0 OnEntry JobStatus= newJobstatus=C 26-Sep-2022 15:13:27.076372 bareos-sd (800): lib/jcr.cc:798-0 Set new stat. old: ,0 new: C,0 26-Sep-2022 15:13:27.076377 bareos-sd (800): lib/jcr.cc:804-0 leave setJobStatus old= new=C 26-Sep-2022 15:13:27.076389 bareos-sd (250): stored/sd_plugins.cc:601-0 === enter NewPlugins === 26-Sep-2022 15:13:27.076394 bareos-sd (250): stored/sd_plugins.cc:603-0 No sd plugin list! 26-Sep-2022 15:13:27.076399 bareos-sd (1000): stored/dir_cmd.cc:278-0 stored in start_job 26-Sep-2022 15:13:27.076413 bareos-sd (800): lib/watchdog.cc:193-0 Registered watchdog 7fec2401a5e0, interval 600 one shot 26-Sep-2022 15:13:27.076576 bareos-sd (900): lib/btimers.cc:177-0 Start bsock timer 7fec24012b00 tid=0x5800007fec2ce607 for 600 secs at 1664198007 26-Sep-2022 15:13:27.076596 bareos-sd (50): lib/cram_md5.cc:106-0 send: auth cram-md5 <1470352125.1664198007@R_STORAGE::bareos-sd> ssl=1 26-Sep-2022 15:13:27.077342 bareos-sd (100): lib/cram_md5.cc:166-0 cram-get received: auth cram-md5 <1385876241.1664198007@R_DIRECTOR::bareos-dir> ssl=1 26-Sep-2022 15:13:27.077354 bareos-sd (50): lib/cram_md5.cc:62-0 my_name: - challenge_name: 26-Sep-2022 15:13:27.077390 bareos-sd (99): lib/cram_md5.cc:231-0 sending resp to challenge: T+/2WC/No0sSR/+Ua0/dPA 26-Sep-2022 15:13:27.077491 bareos-sd (900): lib/btimers.cc:193-0 Stop bsock timer 7fec24012b00 tid=0x4400007fec2ce607 at 1664198007. 26-Sep-2022 15:13:27.077498 bareos-sd (800): lib/watchdog.cc:214-0 Unregistered watchdog 7fec2401a5e0 26-Sep-2022 15:13:27.077700 bareos-sd (90): stored/dir_cmd.cc:288-0 Message channel init completed. 26-Sep-2022 15:13:27.077763 bareos-sd (199): stored/dir_cmd.cc:295-0 26-Sep-2022 15:27:59.047578 bareos-sd (100): lib/tls_openssl_private.cc:612-0 Set protocol: <> 26-Sep-2022 15:27:59.047584 bareos-sd (100): lib/tls_openssl_private.cc:546-0 Set ca_certfile: <> 26-Sep-2022 15:27:59.047590 bareos-sd (100): lib/tls_openssl_private.cc:552-0 Set ca_certdir: <> 26-Sep-2022 15:27:59.047595 bareos-sd (100): lib/tls_openssl_private.cc:558-0 Set crlfile_: <> 26-Sep-2022 15:27:59.047601 bareos-sd (100): lib/tls_openssl_private.cc:564-0 Set certfile_: <> 26-Sep-2022 15:27:59.047606 bareos-sd (100): lib/tls_openssl_private.cc:570-0 Set keyfile_: <> 26-Sep-2022 15:27:59.047611 bareos-sd (100): lib/tls_openssl_private.cc:588-0 Set dhfile_: <> 26-Sep-2022 15:27:59.047617 bareos-sd (100): lib/tls_openssl_private.cc:606-0 Set cipherlist: <> 26-Sep-2022 15:27:59.047622 bareos-sd (100): lib/tls_openssl_private.cc:594-0 Set Verify Peer: 26-Sep-2022 15:27:59.047628 bareos-sd (50): lib/tls_openssl.cc:79-0 Preparing TLS_PSK SERVER callback 26-Sep-2022 15:27:59.047789 bareos-sd (100): lib/tls_openssl_private.cc:466-0 psk_server_cb. identitiy: R_DIRECTOR bareos-dir. 26-Sep-2022 15:27:59.047806 bareos-sd (100): lib/tls_openssl_private.cc:487-0 psk_server_cb. result: 32. 26-Sep-2022 15:27:59.048417 bareos-sd (50): lib/bnet.cc:140-0 TLS server negotiation established. 26-Sep-2022 15:27:59.049040 bareos-sd (110): stored/socket_server.cc:97-0 Conn: Hello Director bareos-dir calling 26-Sep-2022 15:27:59.049058 bareos-sd (110): stored/socket_server.cc:114-0 Got a DIR connection at 26-Sep-2022 15:27:59 26-Sep-2022 15:27:59.049067 bareos-sd (100): lib/jcr.cc:191-0 Construct JobControlRecord 26-Sep-2022 15:27:59.049074 bareos-sd (800): lib/jcr.cc:778-0 setJobStatus(*System*, C) 26-Sep-2022 15:27:59.049079 bareos-sd (800): lib/jcr.cc:788-0 OnEntry JobStatus= newJobstatus=C 26-Sep-2022 15:27:59.049084 bareos-sd (800): lib/jcr.cc:798-0 Set new stat. old: ,0 new: C,0 26-Sep-2022 15:27:59.049088 bareos-sd (800): lib/jcr.cc:804-0 leave setJobStatus old= new=C 26-Sep-2022 15:27:59.049102 bareos-sd (250): stored/sd_plugins.cc:601-0 === enter NewPlugins === 26-Sep-2022 15:27:59.049107 bareos-sd (250): stored/sd_plugins.cc:603-0 No sd plugin list! 26-Sep-2022 15:27:59.049112 bareos-sd (1000): stored/dir_cmd.cc:278-0 stored in start_job 26-Sep-2022 15:27:59.049126 bareos-sd (800): lib/watchdog.cc:193-0 Registered watchdog 7fec2401a5e0, interval 600 one shot 26-Sep-2022 15:27:59.049324 bareos-sd (900): lib/btimers.cc:177-0 Start bsock timer 7fec24012b00 tid=0x5800007fec2ce607 for 600 secs at 1664198879 26-Sep-2022 15:27:59.049343 bareos-sd (50): lib/cram_md5.cc:106-0 send: auth cram-md5 <1916802694.1664198879@R_STORAGE::bareos-sd> ssl=1 26-Sep-2022 15:27:59.049693 bareos-sd (100): lib/cram_md5.cc:166-0 cram-get received: auth cram-md5 <550114651.1664198879@R_DIRECTOR::bareos-dir> ssl=1 26-Sep-2022 15:27:59.049708 bareos-sd (50): lib/cram_md5.cc:62-0 my_name: - challenge_name: 26-Sep-2022 15:27:59.049742 bareos-sd (99): lib/cram_md5.cc:231-0 sending resp to challenge: R+/Eyw/kBAACFD++Y/Z4KC 26-Sep-2022 15:27:59.049871 bareos-sd (900): lib/btimers.cc:193-0 Stop bsock timer 7fec24012b00 tid=0x4400007fec2ce607 at 1664198879. 26-Sep-2022 15:27:59.049879 bareos-sd (800): lib/watchdog.cc:214-0 Unregistered watchdog 7fec2401a5e0 26-Sep-2022 15:27:59.050086 bareos-sd (90): stored/dir_cmd.cc:288-0 Message channel init completed. 26-Sep-2022 15:27:59.050173 bareos-sd (199): stored/dir_cmd.cc:295-0