View Issue Details
| ID | Project | Category | View Status | Date Submitted | Last Update |
|---|---|---|---|---|---|
| 0001372 | bareos-core | General | public | 2021-07-20 09:27 | 2023-09-05 12:00 |
| Reporter | Int | Assigned To | bruno-at-bareos | ||
| Priority | high | Severity | major | Reproducibility | always |
| Status | closed | Resolution | fixed | ||
| Platform | Linux | OS | CentOS | OS Version | 7 |
| Product Version | 19.2.10 | ||||
| Summary | 0001372: Restore/Migrate of job distributed on two tapes fails with ERR=Cannot allocate memory | ||||
| Description | When I try to Restore/Migrate a specific job distributed on two tapes, the first tape is read successfully but when mounting the second tape the job fails with error ``` 20-Jul 08:02 bareos-sd JobId 21833: Ready to read from volume "NIX417L6" on device "tapedrive-0" (/dev/tape/by-id/scsi-350050763121a063c-nst). 20-Jul 08:02 bareos-sd JobId 21833: Forward spacing Volume "NIX417L6" to file:block 0:1. 20-Jul 08:02 bareos-sd JobId 21833: Error: stored/block.cc:1057 Read error on fd=7 at file:blk 0:1 on device "tapedrive-0" (/dev/tape/by-id/scsi-350050763121a063c-nst). ERR=Cannot allocate memory. ``` This only happens on this specific tape. Other jobs distributed on multiple tapes work correctly. I did configure the Bareos Tape device /etc/bareos/bareos-sd.d/device/tapedrive-0.conf with "Maximum Block Size = 1048576" from the very beginning and all tapes were written using this configuration. I started using Bareos after Version 14.2.0 so the new block size handling (label block 64k, data blocks 1M) was used on all tapes. But the error suggests that there is a problem with the block size. This is seconded by /var/log/messages ``` Jul 20 08:02:14 igms07 kernel: st 3:0:0:0: [st0] Failed to read 1048576 byte block with 64512 byte transfer. ``` So it seems that Bareos is trying to read with 64k block size although it is configured otherwise? Further tests showed that I can read the tape label correctly with btape: ``` ]$ btape /dev/tape/by-id/scsi-350050763121a063c-nst Tape block granularity is 1024 bytes. btape: stored/butil.cc:290-0 Using device: "/dev/tape/by-id/scsi-350050763121a063c-nst" for writing. btape: stored/btape.cc:485-0 open device "tapedrive-0" (/dev/tape/by-id/scsi-350050763121a063c-nst): OK *status Bareos status: file=0 block=0 Device status: BOT ONLINE IM_REP_EN file=0 block=0 Device status: TAPE BOT ONLINE IMMREPORT. ERR= *readlabel btape: stored/btape.cc:532-0 Volume label read correctly. 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 ``` I can read the tape with dd with a blocksize of 1M: dd if=/dev/tape/by-id/scsi-350050763121a063c-nst bs=1M btape scan fails with the same error as Bareos: ``` ]$ btape /dev/tape/by-id/scsi-350050763121a063c-nst Tape block granularity is 1024 bytes. btape: stored/butil.cc:290-0 Using device: "/dev/tape/by-id/scsi-350050763121a063c-nst" for writing. btape: stored/btape.cc:485-0 open device "tapedrive-0" (/dev/tape/by-id/scsi-350050763121a063c-nst): OK *rewind btape: stored/btape.cc:581-0 Rewound "tapedrive-0" (/dev/tape/by-id/scsi-350050763121a063c-nst) *scan btape: stored/btape.cc:1901-0 Starting scan at file 0 btape: stored/btape.cc:1909-0 Bad status from read -1. ERR=stored/btape.cc:1907 read error on /dev/tape/by-id/scsi-350050763121a063c-nst. ERR=Cannot allocate memory. ``` but btape scanblocks works fine: ``` ]$ btape /dev/tape/by-id/scsi-350050763121a063c-nst Tape block granularity is 1024 bytes. btape: stored/butil.cc:290-0 Using device: "/dev/tape/by-id/scsi-350050763121a063c-nst" for writing. btape: stored/btape.cc:485-0 open device "tapedrive-0" (/dev/tape/by-id/scsi-350050763121a063c-nst): OK *rewind btape: stored/btape.cc:581-0 Rewound "tapedrive-0" (/dev/tape/by-id/scsi-350050763121a063c-nst) *scanblocks 1 block of 203 bytes in file 0 2213 blocks of 1048576 bytes in file 0 1 block of 1048566 bytes in file 0 1072 blocks of 1048576 bytes in file 0 1 block of 1048568 bytes in file 0 ``` The question is, what is the issue here? And how do I fix it? | ||||
| Tags | No tags attached. | ||||
 |
PS: my device configuration: Device { Name = "tapedrive-0" DeviceType = tape Maximum Concurrent Jobs = 1 # default:0, only required if the autoloader have multiple drives. DriveIndex = 0 ArchiveDevice = /dev/tape/by-id/scsi-350050763121a063c-nst # Quantum LTO-7 standalone drive MediaType = LTO AutoChanger = no # default: no AutomaticMount = yes # default: no MaximumFileSize = 40GB MaximumBlockSize = 1048576 Maximum Spool Size = 40GB Spool Directory = /var/lib/bareos/spool } |
|
|
PPS: When I read other jobs that are also on this tape, the restore/migration works just fine. |
|
|
I am having this same problem on a restore which spans 2 tapes. The file is particularly large, so probably the case here is that a single file spans two tapes. bareos-dir Version: 21.0.0 (21 December 2021) Rocky Linux release 8.4 (Green Obsidian) redhat Rocky Linux release 8.4 (Green Obsidian) [358442.558093] st 9:0:40:0: [st0] Failed to read 262144 byte block with 64512 byte transfer. bareos-sd JobId 81: Error: stored/block.cc:1004 Read error on fd=8 at file:blk 0:1 on device "tapedrive-0" (/dev/nst0). ERR=Cannot allocate memory. See attached job log. Note that despite everything it says, the correct media (LC0004) was inserted and mounted at the correct time. Shortly after mounting LC0004 the job failed. |
|
|
Hello aleigh. We are interested by getting more debugging information, to be able to reproduce 100% of time the problem (if we can, then getting a fix is almost certain). So if you are able to rerun that restore, would you be able to run it with a higher debug level ? You can consult this page to understand how to do this. https://servicedesk.bareos.com/help/en-us/2-support/2-how-do-i-set-the-debug-level here a debug level of 1000 would be nice. director, storage, and concerned client should be activated. We would like to have attached here in text form not picture. mainly the following command on bconsole list joblog jobid=81 (or the new jobid of restore try with debug) and also the initial backup jobid. The whole configuration and logs are a plus do debug the situation. Maybe our support-info tool can be used and run on director see instruction here https://servicedesk.bareos.com/help/en-us/2-support/3-how-to-use-the-bareos-support-info-sh-tool You can attach the result if not too big, as private (all credential being already removed by the tool) |
|
|
Ping, none of you are able to run with a higher debug level ? |
|
|
As a starting point I attached the joblog of the original failing job. My configuration is not the same as back then when I filed this bug a year ago. In the mean time I updated my bareos to version 21, but the used storage device is still the same. I created support-info of my current config with your support-info tool but the generated tgz-file is too large (78MB) to be uploaded here. Let me know how you want to receive the tgz-file instead. Next I will enable debug level of 1000 and will try to reproduce the error with bareos 21. joblog_21833.txt (4,077 bytes)
*list joblog jobid=21833
Automatically selected Catalog: MyCatalog
Using Catalog "MyCatalog"
2021-07-19 10:18:06 bareos-dir JobId 21833: Start Restore Job RestoreFiles.2021-07-19_10.18.04_39
2021-07-19 10:18:06 bareos-dir JobId 21833: Connected Storage daemon at igms07.vision.local:9103, encryption: PSK-AES256-CBC-SHA
2021-07-19 10:18:06 bareos-dir JobId 21833: Using Device "tapedrive-0" to read.
2021-07-19 10:18:06 bareos-dir JobId 21833: Probing client protocol... (result will be saved until config reload)
2021-07-19 10:18:06 bareos-dir JobId 21833: Connected Client: igms00-fd at igms00.vision.local:9102, encryption: PSK-AES256-CBC-SHA
2021-07-19 10:18:06 bareos-dir JobId 21833: Handshake: Immediate TLS 2021-07-19 10:18:06 bareos-dir JobId 21833: Encryption: PSK-AES256-CBC-SHA
2021-07-19 10:18:08 bareos-sd JobId 21833: Ready to read from volume "NIX416L6" on device "tapedrive-0" (/dev/tape/by-id/scsi-350050763121a063c-nst).
2021-07-19 10:18:08 bareos-sd JobId 21833: Forward spacing Volume "NIX416L6" to file:block 0:1.
2021-07-19 10:18:08 igms00-fd JobId 21833: Connected Storage daemon at igms07.vision.local:9103, encryption: PSK-AES256-CBC-SHA
2021-07-20 03:11:32 bareos-sd JobId 21833: End of Volume at file 97 on device "tapedrive-0" (/dev/tape/by-id/scsi-350050763121a063c-nst), Volume "NIX416L6"
2021-07-20 03:11:32 bareos-sd JobId 21833: Warning: stored/acquire.cc:343 Read acquire: Wrong Volume mounted on device "tapedrive-0" (/dev/tape/by-id/scsi-350050763121a063c-nst): Wanted NIX417L6 have NIX416L6
2021-07-20 03:11:32 bareos-sd JobId 21833: Please mount read Volume "NIX417L6" for:
Job: RestoreFiles.2021-07-19_10.18.04_39
Storage: "tapedrive-0" (/dev/tape/by-id/scsi-350050763121a063c-nst)
Pool: Backup_Intego
Media type: LTO
2021-07-20 04:11:32 bareos-sd JobId 21833: Please mount read Volume "NIX417L6" for:
Job: RestoreFiles.2021-07-19_10.18.04_39
Storage: "tapedrive-0" (/dev/tape/by-id/scsi-350050763121a063c-nst)
Pool: Backup_Intego
Media type: LTO
2021-07-20 06:11:33 bareos-sd JobId 21833: Please mount read Volume "NIX417L6" for:
Job: RestoreFiles.2021-07-19_10.18.04_39
Storage: "tapedrive-0" (/dev/tape/by-id/scsi-350050763121a063c-nst)
Pool: Backup_Intego
Media type: LTO
2021-07-20 08:02:14 bareos-sd JobId 21833: Ready to read from volume "NIX417L6" on device "tapedrive-0" (/dev/tape/by-id/scsi-350050763121a063c-nst).
2021-07-20 08:02:14 bareos-sd JobId 21833: Forward spacing Volume "NIX417L6" to file:block 0:1.
2021-07-20 08:02:14 bareos-sd JobId 21833: Error: stored/block.cc:1057 Read error on fd=7 at file:blk 0:1 on device "tapedrive-0" (/dev/tape/by-id/scsi-350050763121a063c-nst). ERR=Cannot allocate memory.
2021-07-20 08:02:14 bareos-sd JobId 21833: Releasing device "tapedrive-0" (/dev/tape/by-id/scsi-350050763121a063c-nst).
2021-07-20 08:02:14 bareos-sd JobId 21833: Fatal error: stored/fd_cmds.cc:232 Command error with FD, hanging up. Wrong Volume mounted on device "tapedrive-0" (/dev/tape/by-id/scsi-350050763121a063c-nst): Wanted NIX417L6 have NIX416L6
2021-07-20 08:02:20 bareos-dir JobId 21833: Error: Bareos bareos-dir 19.2.7 (16Apr20):
Build OS: Linux-3.10.0-1062.18.1.el7.x86_64 redhat CentOS Linux release 7.7.1908 (Core)
JobId: 21833
Job: RestoreFiles.2021-07-19_10.18.04_39
Restore Client: igms00-fd
Start time: 19-Jul-2021 10:18:06
End time: 20-Jul-2021 08:02:19
Elapsed time: 21 hours 44 mins 13 secs
Files Expected: 510,556
Files Restored: 413,004
Bytes Restored: 3,868,628,799,800
Rate: 49437.4 KB/s
FD Errors: 0
FD termination status: OK
SD termination status: Fatal Error
Bareos binary info: bareos.org build: Get official binaries and vendor support on bareos.com
Termination: *** Restore Error ***
|
|
|
Here the joblog of the initial backup job. joblog_5822.txt (6,372 bytes)
*list joblog jobid=5822 Automatically selected Catalog: MyCatalog Using Catalog "MyCatalog" 2018-11-12 15:09:14 bareos-dir JobId 5822: No prior Full backup Job record found. 2018-11-12 15:09:14 bareos-dir JobId 5822: No prior or suitable Full backup found in catalog. Doing FULL backup. 2018-11-12 15:09:16 bareos-dir JobId 5822: Start Backup JobId 5822, Job=archive_bilddaten-igms00-fd.2018-11-12_15.09.14_51 2018-11-12 15:09:16 bareos-sd JobId 5822: 3307 Issuing autochanger "unload slot 14, drive 0" command. 2018-11-12 15:10:04 bareos-dir JobId 5822: Using Volume "NIX416L6" from 'Scratch' pool. 2018-11-12 15:10:04 bareos-dir JobId 5822: Using Device "tapedrive-0" to write. 2018-11-12 15:10:06 bareos-sd JobId 5822: 3304 Issuing autochanger "load slot 11, drive 0" command. 2018-11-12 15:11:10 bareos-sd JobId 5822: 3305 Autochanger "load slot 11, drive 0", status is OK. 2018-11-12 15:11:16 bareos-sd JobId 5822: Wrote label to prelabeled Volume "NIX416L6" on device "tapedrive-0" (/dev/tape/by-id/scsi-35005076312128141-nst) 2018-11-12 15:10:04 igms00-fd JobId 5822: Created 30 wildcard excludes from FilesNotToBackup Registry key 2018-11-12 15:11:19 igms00-fd JobId 5822: Generate VSS snapshots. Driver="Win64 VSS", Drive(s)="D" 2018-11-12 15:11:19 igms00-fd JobId 5822: VolumeMountpoints are not processed as onefs = yes. 2018-11-12 21:52:28 bareos-sd JobId 5822: End of Volume "NIX416L6" at 96:28332 on device "tapedrive-0" (/dev/tape/by-id/scsi-35005076312128141-nst). Write of 1048576 bytes got -1. 2018-11-12 21:52:34 bareos-sd JobId 5822: Re-read of last block succeeded. 2018-11-12 21:52:34 bareos-sd JobId 5822: End of medium on Volume "NIX416L6" Bytes=3,869,610,408,960 Blocks=3,690,348 at 12-Nov-2018 21:52. 2018-11-12 21:52:34 bareos-sd JobId 5822: 3307 Issuing autochanger "unload slot 11, drive 0" command. 2018-11-12 21:55:26 bareos-dir JobId 5822: Using Volume "NIX417L6" from 'Scratch' pool. 2018-11-12 21:55:27 bareos-sd JobId 5822: 3304 Issuing autochanger "load slot 12, drive 0" command. 2018-11-12 21:56:22 bareos-sd JobId 5822: 3305 Autochanger "load slot 12, drive 0", status is OK. 2018-11-12 21:56:28 bareos-sd JobId 5822: Wrote label to prelabeled Volume "NIX417L6" on device "tapedrive-0" (/dev/tape/by-id/scsi-35005076312128141-nst) 2018-11-12 21:56:28 bareos-sd JobId 5822: New volume "NIX417L6" mounted on device "tapedrive-0" (/dev/tape/by-id/scsi-35005076312128141-nst) at 12-Nov-2018 21:56. 2018-11-12 22:58:21 igms00-fd JobId 5822: VSS Writer (BackupComplete): "Task Scheduler Writer", State: 0x1 (VSS_WS_STABLE) 2018-11-12 22:58:21 igms00-fd JobId 5822: VSS Writer (BackupComplete): "VSS Metadata Store Writer", State: 0x1 (VSS_WS_STABLE) 2018-11-12 22:58:21 igms00-fd JobId 5822: VSS Writer (BackupComplete): "Performance Counters Writer", State: 0x1 (VSS_WS_STABLE) 2018-11-12 22:58:21 igms00-fd JobId 5822: VSS Writer (BackupComplete): "System Writer", State: 0x1 (VSS_WS_STABLE) 2018-11-12 22:58:21 igms00-fd JobId 5822: VSS Writer (BackupComplete): "SqlServerWriter", State: 0x1 (VSS_WS_STABLE) 2018-11-12 22:58:21 igms00-fd JobId 5822: VSS Writer (BackupComplete): "ASR Writer", State: 0x1 (VSS_WS_STABLE) 2018-11-12 22:58:21 igms00-fd JobId 5822: VSS Writer (BackupComplete): "Shadow Copy Optimization Writer", State: 0x1 (VSS_WS_STABLE) 2018-11-12 22:58:21 igms00-fd JobId 5822: VSS Writer (BackupComplete): "FRS Writer", State: 0x1 (VSS_WS_STABLE) 2018-11-12 22:58:21 igms00-fd JobId 5822: VSS Writer (BackupComplete): "WMI Writer", State: 0x1 (VSS_WS_STABLE) 2018-11-12 22:58:21 igms00-fd JobId 5822: VSS Writer (BackupComplete): "Registry Writer", State: 0x1 (VSS_WS_STABLE) 2018-11-12 22:58:21 igms00-fd JobId 5822: VSS Writer (BackupComplete): "NPS VSS Writer", State: 0x1 (VSS_WS_STABLE) 2018-11-12 22:58:21 igms00-fd JobId 5822: VSS Writer (BackupComplete): "IIS Config Writer", State: 0x1 (VSS_WS_STABLE) 2018-11-12 22:58:21 igms00-fd JobId 5822: VSS Writer (BackupComplete): "IIS Metabase Writer", State: 0x1 (VSS_WS_STABLE) 2018-11-12 22:58:21 igms00-fd JobId 5822: VSS Writer (BackupComplete): "Dhcp Jet Writer", State: 0x1 (VSS_WS_STABLE) 2018-11-12 22:58:21 igms00-fd JobId 5822: VSS Writer (BackupComplete): "NTDS", State: 0x1 (VSS_WS_STABLE) 2018-11-12 22:58:21 igms00-fd JobId 5822: VSS Writer (BackupComplete): "COM+ REGDB Writer", State: 0x1 (VSS_WS_STABLE) 2018-11-12 22:58:25 bareos-sd JobId 5822: Elapsed time=07:43:15, Transfer rate=162.0 M Bytes/second 2018-11-12 22:58:31 bareos-sd JobId 5822: Sending spooled attrs to the Director. Despooling 250,502,190 bytes ... 2018-11-12 22:58:41 bareos-dir JobId 5822: sql_create.c:872 Insert of attributes batch table done 2018-11-12 22:58:41 bareos-dir JobId 5822: Bareos bareos-dir 17.2.4 (21Sep17): Build OS: x86_64-redhat-linux-gnu redhat CentOS Linux release 7.4.1708 (Core) JobId: 5822 Job: archive_bilddaten-igms00-fd.2018-11-12_15.09.14_51 Backup Level: Full (upgraded from Incremental) Client: "igms00-fd" 17.2.4 (21Sep17) Microsoft Windows Server 2012 Standard Edition (build 9200), 64-bit,Cross-compile,Win64 FileSet: "FileSetIGMS00_Bilddaten_archive" 2018-11-12 15:09:14 Pool: "Archiv_Bilddaten" (From Job resource) Catalog: "MyCatalog" (From Client resource) Storage: "Tape" (From Job resource) Scheduled time: 12-Nov-2018 15:09:14 Start time: 12-Nov-2018 15:10:04 End time: 12-Nov-2018 22:58:41 Elapsed time: 7 hours 48 mins 37 secs Priority: 10 FD Files Written: 510,557 SD Files Written: 510,557 FD Bytes Written: 4,503,733,299,940 (4.503 TB) SD Bytes Written: 4,503,889,327,740 (4.503 TB) Rate: 160178.3 KB/s Software Compression: None VSS: yes Encryption: no Accurate: yes Volume name(s): NIX416L6|NIX417L6 Volume Session Id: 25 Volume Session Time: 1541740509 Last Volume Bytes: 635,273,904,128 (635.2 GB) Non-fatal FD errors: 0 SD Errors: 0 FD termination status: OK SD termination status: OK Termination: Backup OK |
|
|
You can upload the tgz to https://cloud.dass-it.de/index.php/s/Xf9ZH79737iastj with password mantis1372 Before creating the report check if you have any *trace* in /var/lib/bareos they often are old crash and just took place. |
|
|
I uploaded the support-info. |
|
|
Thanks, did you have other jobs stored on both tapes NIX417L6 and NIX416L6 ? If yes are you able to read from them. |
|
|
The failing job 5822 is the only job on tape NIX416L6 and fills it completely, The rest of job 5822 is on tape NIX417L6. There are other jobs on tape NIX417L6 which can be restored successfully. I tried to reproduce the issue with debug level of 1000 set on director, storage, and client but since job 5822 is large (4.5 TB of data) the log files get huge and filled up the free disk space on director and client. This caused the director to crash. I will retry and enable the debugging only shortly before the restore process switches from tape NIX416L6 to tape NIX417L6. Hopefully this will catch the issue while leaving enough free disk space. Or do you have other advice on how to proceed? |
|
|
I think you can set debulevel to 500 on director, (none on fd) but 1000 on SD (which is the failing part). I have to prepare also some instruction to extract block information from the database for those 2 volumes especially around the split. |
|
|
The good new is the error is reproduceable with Bareos 21. I enabled the debug level of 1000 on the SD only after the restore of the first tape was done and the restore job was requesting to load the second tape. I hope this was sufficient since the error happens when bareos tries to read the first sector of the second tape. If not let me know and I will repeat with earlier tracing. I attached the trace file of the SD. The trace file for the director is quite large (3 GB uncompressed). Shall I upload it to https://cloud.dass-it.de/index.php/s/Xf9ZH79737iastj with password mantis1372 again? bareos-sd.trace (57,480 bytes)
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: <false> 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: <R_STORAGE::bareos-sd> - challenge_name: <R_DIRECTOR::bareos-dir> 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 <dird: unmount tapedrive-0 drive=0 26-Sep-2022 15:02:51.768522 bareos-sd (200): stored/dir_cmd.cc:309-0 Do command: unmount 26-Sep-2022 15:02:51.768529 bareos-sd (20): stored/dir_cmd.cc:896-0 Found device tapedrive-0 26-Sep-2022 15:02:51.768533 bareos-sd (100): stored/dir_cmd.cc:950-0 Found device tapedrive-0 26-Sep-2022 15:02:51.768540 bareos-sd (100): stored/block.cc:137-0 created new block of blocksize 64512 (dev->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: <false> 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: <R_STORAGE::bareos-sd> - challenge_name: <R_DIRECTOR::bareos-dir> 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 <dird: mount tapedrive-0 drive=0 26-Sep-2022 15:09:17.157736 bareos-sd (200): stored/dir_cmd.cc:309-0 Do command: mount 26-Sep-2022 15:09:17.157749 bareos-sd (100): stored/dir_cmd.cc:976-0 ok=1 drive=0 slot=0 26-Sep-2022 15:09:17.157757 bareos-sd (20): stored/dir_cmd.cc:896-0 Found device tapedrive-0 26-Sep-2022 15:09:17.157761 bareos-sd (100): stored/dir_cmd.cc:950-0 Found device tapedrive-0 26-Sep-2022 15:09:17.157768 bareos-sd (100): stored/block.cc:137-0 created new block of blocksize 64512 (dev->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 <dird 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=20412044101 VolWriteTime=7613319379 EndFile=120 EndBlock=0 LabelType=0 MediaId=39 EncryptionKey= MinBlocksize=0 MaxBlocksize=1048576 26-Sep-2022 15:09:21.822391 bareos-sd (50): stored/askdir.cc:141-28099 DoGetVolumeInfo return true slot=0 Volume=NIX417L6, VolminBlocksize=0 VolMaxBlocksize=1048576 26-Sep-2022 15:09:21.822397 bareos-sd (50): stored/askdir.cc:144-28099 setting dcr->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 <dird 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.868865 bareos-sd (50): stored/askdir.cc:141-28099 DoGetVolumeInfo return true slot=0 Volume=NIX417L6, VolminBlocksize=0 VolMaxBlocksize=1048576 26-Sep-2022 15:09:21.868870 bareos-sd (50): stored/askdir.cc:144-28099 setting dcr->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: <false> 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: <R_STORAGE::bareos-sd> - challenge_name: <R_DIRECTOR::bareos-dir> 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 <dird: cancel Job=RestoreFiles.2022-09-26_08.55.04_22 26-Sep-2022 15:13:27.077772 bareos-sd (200): stored/dir_cmd.cc:309-0 Do command: cancel 26-Sep-2022 15:13:27.118794 bareos-sd (250): stored/sd_plugins.cc:313-0 No bplugin_list: GeneratePluginEvent ignored. 26-Sep-2022 15:13:27.118832 bareos-sd (580): lib/message.cc:328-0 Close_msg jcr=7fec24017c90 26-Sep-2022 15:13:27.118838 bareos-sd (200): stored/job.cc:389-0 Start stored FreeJcr 26-Sep-2022 15:13:27.118843 bareos-sd (800): stored/job.cc:390-0 End Job JobId=0 7fec24017c90 26-Sep-2022 15:13:27.118847 bareos-sd (800): stored/job.cc:393-0 Send Terminate jid=0 7fec24017c90 26-Sep-2022 15:13:27.118855 bareos-sd (200): stored/job.cc:500-0 End stored FreeJcr 26-Sep-2022 15:13:27.118859 bareos-sd (100): lib/jcr.cc:273-0 FreeCommonJcr: 7fec24017c90 26-Sep-2022 15:13:27.118867 bareos-sd (800): lib/watchdog.cc:193-0 Registered watchdog 7fec2401a5e0, interval 120 one shot 26-Sep-2022 15:13:27.119063 bareos-sd (900): lib/btimers.cc:177-0 Start bsock timer 7fec24012b00 tid=0x7800007fec2ce607 for 120 secs at 1664198007 26-Sep-2022 15:13:27.119138 bareos-sd (900): lib/btimers.cc:193-0 Stop bsock timer 7fec24012b00 tid=0x7800007fec2ce607 at 1664198007. 26-Sep-2022 15:13:27.119155 bareos-sd (800): lib/watchdog.cc:214-0 Unregistered watchdog 7fec2401a5e0 26-Sep-2022 15:13:27.119371 bareos-sd (800): lib/watchdog.cc:193-0 Registered watchdog 7fec2401a5e0, interval 2 one shot 26-Sep-2022 15:13:27.119581 bareos-sd (900): lib/btimers.cc:177-0 Start bsock timer 7fec24012b00 tid=0x0200007fec2ce607 for 2 secs at 1664198007 26-Sep-2022 15:13:27.119622 bareos-sd (900): lib/btimers.cc:193-0 Stop bsock timer 7fec24012b00 tid=0x0000007fec2ce607 at 1664198007. 26-Sep-2022 15:13:27.119636 bareos-sd (800): lib/watchdog.cc:214-0 Unregistered watchdog 7fec2401a5e0 26-Sep-2022 15:13:27.120224 bareos-sd (100): lib/tls_openssl_private.cc:96-0 Destruct TlsOpenSslPrivate 26-Sep-2022 15:13:27.120342 bareos-sd (100): lib/bsock.cc:136-0 Destruct BareosSocket 26-Sep-2022 15:13:27.120362 bareos-sd (580): lib/message.cc:328-0 Close_msg jcr=0 26-Sep-2022 15:13:27.120385 bareos-sd (850): lib/message.cc:350-0 ===Begin close msg resource at a3e840 26-Sep-2022 15:13:27.120652 bareos-sd (850): lib/message.cc:455-0 Done walking message chain. 26-Sep-2022 15:13:27.120681 bareos-sd (850): lib/message.cc:462-0 ===End close msg resource 26-Sep-2022 15:13:27.120697 bareos-sd (800): lib/thread_list.cc:207-0 Finished WorkerThread. 26-Sep-2022 15:27:59.039626 bareos-sd (100): lib/bsock.cc:84-0 Construct BareosSocket 26-Sep-2022 15:27:59.039876 bareos-sd (800): lib/thread_list.cc:243-0 Run WorkerThread successfully. 26-Sep-2022 15:27:59.047216 bareos-sd (100): lib/tls_openssl_private.cc:65-0 Construct TlsOpenSslPrivate 26-Sep-2022 15:27:59.047551 bareos-sd (100): lib/tls_openssl_private.cc:600-0 Set tcp filedescriptor: <5> 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: <false> 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: <R_STORAGE::bareos-sd> - challenge_name: <R_DIRECTOR::bareos-dir> 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 <dird: setdebug=0 trace=0 timestamp=-1 26-Sep-2022 15:27:59.050182 bareos-sd (200): stored/dir_cmd.cc:309-0 Do command: setdebug= 26-Sep-2022 15:27:59.050195 bareos-sd (10): stored/dir_cmd.cc:419-0 SetdebugCmd: setdebug=0 trace=0 timestamp=-1 |
|
|
Yes please upload it there. It has less interest than the SD, but still good to have it somewhere until we can reproduce that problem automatically. I just don't know when I will be able to parse them this week. |
|
|
I uploaded the director trace file. |
|
|
Just to exclude a documented case was the tape labelled with 1M or 64kb ? If you check here https://docs.bareos.org/TasksAndConcepts/AutochangerSupport.html#direct-access-to-volumes-with-with-non-default-block-sizes You will see the memory allocation error. And then maybe you need to adapt the Label Block Size for those tapes ? Thanks for your confirmation. |
|
|
I know about that. My my device configuration has set MaximumBlockSize = 1048576 see my post https://bugs.bareos.org/view.php?id=1372#c4183 and has been configured like this from the beginning when I started using bareos. |
|
|
Hi, is there any progress on this issue? In the mean time I wanted to migrate other older backups of mine from LTO6 tapes to LTO7 tapes, but all migrate jobs fail with error 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. when starting to read from the second tape. One time reading from the first tape of the backup set failed with "Error: stored/block.cc:1004 Read error ..." but on this occasion I had mounted a wrong tape first, so the failing tape was again the second tape accessed in the migrate job. This looks like the migrate process a fundamental problem with the second tape in it's progress. All jobs have in common that they were created with Bareos 17.2.4 At the moment practically all my old backup jobs are useless. |
|
|
PS: If needed I can also send you the physical tapes for further investigation. Best regards and a happy new year! |
|
|
Hello, sorry we didn't have a fix yet. Could you check the following data for example on both tapes failing (the first and second) Using sql module of bconsole or directly psql ``` select mediaid,volumename,minblocksize,maxblocksize from media where mediaid in (); ``` Normally both of them should have the maxblocksize set to 1M is it the case. if not, what happen if you fix the database record of the second one to be 1M? Regards |
|
|
Hi, I checked the data on both tapes failing and both have maxblocksize set to 1M: bareos=# select mediaid,volumename,minblocksize,maxblocksize from media where volumename in ('NIX416L6','NIX417L6'); mediaid | volumename | minblocksize | maxblocksize ---------+------------+--------------+-------------- 38 | NIX416L6 | 0 | 1048576 39 | NIX417L6 | 0 | 1048576 (2 rows) Best regards and thanks for investigating this further. |
|
|
in the forum I read this https://groups.google.com/g/bareos-users/c/71Hg5rcObOg which mentions "there is an automatic workaround being implemented in PR https://github.com/bareos/bareos/pull/1496 right now" Is there a chance that PR https://github.com/bareos/bareos/pull/1496 will also fix this issue? |
|
|
It maybe the case, I was waiting the end of the review to inform here. At least if you want to give it a try, the experimental build are available in https://download.bareos.org/experimental/PR-1496 |
|
|
PR is now merge, SD will automatically increase block size if needed |
| Date Modified | Username | Field | Change |
|---|---|---|---|
| 2021-07-20 09:27 | Int | New Issue | |
| 2021-07-20 10:02 | Int | Note Added: 0004183 | |
| 2021-07-31 09:13 | Int | Note Added: 0004195 | |
| 2022-08-04 22:28 | aleigh | Note Added: 0004714 | |
| 2022-08-04 22:28 | aleigh | File Added: Screen Shot 2022-08-04 at 1.27.33 PM.png | |
| 2022-08-10 11:00 | bruno-at-bareos | Note Added: 0004721 | |
| 2022-09-21 15:07 | bruno-at-bareos | Note Added: 0004751 | |
| 2022-09-21 16:12 | Int | Note Added: 0004756 | |
| 2022-09-21 16:12 | Int | File Added: joblog_21833.txt | |
| 2022-09-21 16:22 | Int | Note Added: 0004757 | |
| 2022-09-21 16:22 | Int | File Added: joblog_5822.txt | |
| 2022-09-21 16:26 | bruno-at-bareos | Note Added: 0004758 | |
| 2022-09-21 16:35 | Int | Note Added: 0004759 | |
| 2022-09-21 16:58 | bruno-at-bareos | Note Added: 0004760 | |
| 2022-09-22 08:59 | Int | Note Added: 0004762 | |
| 2022-09-22 10:00 | bruno-at-bareos | Note Added: 0004764 | |
| 2022-09-26 15:42 | Int | Note Added: 0004775 | |
| 2022-09-26 15:42 | Int | File Added: bareos-sd.trace | |
| 2022-09-26 15:59 | bruno-at-bareos | Assigned To | => bruno-at-bareos |
| 2022-09-26 15:59 | bruno-at-bareos | Status | new => assigned |
| 2022-09-26 16:01 | bruno-at-bareos | Note Added: 0004776 | |
| 2022-09-26 17:41 | Int | Note Added: 0004777 | |
| 2022-09-29 15:48 | bruno-at-bareos | Note Added: 0004787 | |
| 2022-09-29 16:06 | Int | Note Added: 0004788 | |
| 2022-12-28 10:12 | Int | Note Added: 0004846 | |
| 2022-12-28 10:16 | Int | Note Added: 0004847 | |
| 2023-01-12 16:17 | bruno-at-bareos | Note Added: 0004858 | |
| 2023-01-18 16:55 | Int | Note Added: 0004863 | |
| 2023-08-08 11:11 | Int | Note Added: 0005315 | |
| 2023-08-08 11:21 | Int | Note Edited: 0005315 | |
| 2023-08-08 11:45 | bruno-at-bareos | Note Added: 0005316 | |
| 2023-09-05 12:00 | bruno-at-bareos | Status | assigned => closed |
| 2023-09-05 12:00 | bruno-at-bareos | Resolution | open => fixed |
| 2023-09-05 12:00 | bruno-at-bareos | Note Added: 0005374 |
