Re: Warning: Unexpected stream="0"
Martin Simmons <[email protected]>
| Newsgroups | gmane.comp.bacula.user |
|---|---|
| Message-ID | <[email protected]> |
Try running the bacula-fd with -d 300 to capture much more information when it fails. Also, what is the FileSet definition? Is the Storage Daemon also running Bacula version 15.0.2? __Martin >>>>> On Thu, 5 Sep 2024 19:44:40 +0200, Dragan Milivojević said: > > Hi all > > An issue with Bacula version 15.0.2, basically Bacula fails to save files, all that is > stored is file names and no data, not even metadata. > > For example: > > > *list jobid=81 > +-------+------------+---------------------+------+-------+----------+----------+-----------+ > | jobid | name | starttime | type | level | jobfiles | jobbytes | jobstatus | > +-------+------------+---------------------+------+-------+----------+----------+-----------+ > | 81 | GalileoJob | 2024-09-03 21:29:10 | B | I | 480 | 9,459 | T | > +-------+------------+---------------------+------+-------+----------+----------+-----------+ > *list files jobid=81 > +----------------------------------------------------------------------------------------------------+ > | filename | > +----------------------------------------------------------------------------------------------------+ > | /boot/grub2/grubenv | > | /home/galileo/.local/share/keybase/kbfs_settings/v1/kbfsSettings.leveldb/004100.log | > > > Clipped for verbosity ... > > | /home/galileo/.config/google-chrome/CertificateRevocation/9084/manifest.json | > | /home/hs/tmp/drvo/ | > | /home/hs/tmp/drvo/drvo_notes.txt | > | /home/hs/tmp/drvo/fplrn008.pdf | > | /home/galileo/.config/google-chrome/TrustTokenKeyCommitments/2024.9.3.1/_metadata/ | > | /home/galileo/.config/google-chrome/TrustTokenKeyCommitments/2024.9.3.1/_metadata/verified_contents.json | > | /home/galileo/.config/google-chrome/CertificateRevocation/9082/_metadata/ | > | /home/galileo/.config/google-chrome/CertificateRevocation/9082/_metadata/verified_contents.json | > | /home/galileo/.config/google-chrome/Profile 1/blob_storage/dfd7d552-d0fb-4fdd-8b75-ef7a9d27db71/ | > | /home/galileo/.config/google-chrome/TrustTokenKeyCommitments/2024.9.3.1/ | > | /home/galileo/.config/google-chrome/TrustTokenKeyCommitments/2024.9.3.1/LICENSE | > | /home/galileo/.config/google-chrome/TrustTokenKeyCommitments/2024.9.3.1/keys.json | > | /home/galileo/.config/google-chrome/TrustTokenKeyCommitments/2024.9.3.1/manifest.fingerprint | > | /home/galileo/.config/google-chrome/TrustTokenKeyCommitments/2024.9.3.1/manifest.json | > | /home/galileo/.config/google-chrome/TpcdMetadata/2024.9.2.1/_metadata/ | > | /home/galileo/.config/google-chrome/TpcdMetadata/2024.9.2.1/_metadata/verified_contents.json | > | /home/galileo/.config/google-chrome/TpcdMetadata/2024.9.2.1/ | > | /home/galileo/.config/google-chrome/TpcdMetadata/2024.9.2.1/manifest.fingerprint | > | /home/galileo/.config/google-chrome/TpcdMetadata/2024.9.2.1/manifest.json | > | /home/galileo/.config/google-chrome/TpcdMetadata/2024.9.2.1/metadata.pb | > +----------------------------------------------------------------------------------------------------+ > +-------+------------+---------------------+------+-------+----------+----------+-----------+ > | jobid | name | starttime | type | level | jobfiles | jobbytes | jobstatus | > +-------+------------+---------------------+------+-------+----------+----------+-----------+ > | 81 | GalileoJob | 2024-09-03 21:29:10 | B | I | 480 | 9,459 | T | > +-------+------------+---------------------+------+-------+----------+----------+-----------+ > *restore jobid=81 > You have selected the following JobId: 81 > > Building directory tree for JobId(s) 81 ... +++++ > 54 files inserted into the tree. > > You are now entering file selection mode where you add (mark) and > remove (unmark) files to be restored. No files are initially added, unless > you used the "all" keyword on the command line. > Enter "done" to leave this mode. > > cwd is: / > $ c/home/hs/tmp/drvo/o/ > cwd is: /home/hs/tmp/drvo/ > $ dir > ---------- 0 root root 0 1970-01-01 01:00:00 /home/hs/tmp/drvo/drvo_notes.txt/ > ---------- 0 root root 0 1970-01-01 01:00:00 /home/hs/tmp/drvo/fplrn008.pdf/ > > > > $ mark drvo_notes.txt > 1 file marked. > $ done > Bootstrap records written to /var/spool/bacula/bacula-dir.restore.7.bsr > > The Job will require the following (*=>InChanger): > Volume(s) Storage(s) SD Device(s) > =========================================================================== > > Incr-Pool_Volume-001 DirectorAutochanger LocalFileChgr0 > > Volumes marked with "*" are in the Autochanger. > > > 2 files selected to be restored. > > Defined Clients: > 1: bacula-fd > 2: galileo-fd > Select the Client (1-2): 1 > Run Restore job > JobName: RestoreFiles > Bootstrap: /var/spool/bacula/bacula-dir.restore.7.bsr > Where: /bacula/restores > Replace: Always > FileSet: ServersFS > Backup Client: bacula-fd > Restore Client: bacula-fd > Storage: DirectorAutochanger > When: 2024-09-05 00:42:55 > Catalog: MyCatalog > Priority: 10 > Plugin Options: *None* > OK to run? (Yes/mod/no): y > Job queued. JobId=105 > *m > 05-Sep 00:43 bacula-dir JobId 105: Start Restore Job RestoreFiles.2024-09-05_00.42.58_04 > 05-Sep 00:43 bacula-dir JobId 105: Restoring files from JobId(s) 81 > 05-Sep 00:43 bacula-dir JobId 105: Connected to Storage "DirectorAutochanger" at 10.1.0.93:9103 with TLS > 05-Sep 00:43 bacula-dir JobId 105: Using Device "LocalFileChgr0-Dev1" to read. > 05-Sep 00:43 bacula-dir JobId 105: Connected to Client "bacula-fd" at localhost:9102 with TLS > 05-Sep 00:43 bacula-fd JobId 105: Connected to Storage at 10.1.0.93:9103 with TLS > 05-Sep 00:43 bacula-sd JobId 105: Ready to read from volume "Incr-Pool_Volume-001" on File device "LocalFileChgr0-Dev1" (/bacula/storage/LocalFile/). > 05-Sep 00:43 bacula-sd JobId 105: Forward spacing Volume "Incr-Pool_Volume-001" to addr=2742713 > 05-Sep 00:43 bacula-sd JobId 105: Elapsed time=00:00:01, Transfer rate=220 Bytes/second > 05-Sep 00:43 bacula-fd JobId 105: Warning: Unexpected stream="0" ignored. This shouldn't happen! > 05-Sep 00:43 bacula-fd JobId 105: Warning: Unexpected stream="0" ignored. This shouldn't happen! > 05-Sep 00:43 bacula-dir JobId 105: Bacula bacula-dir 15.0.2 (21Mar24): > Build OS: x86_64-redhat-linux-gnu redhat Enterprise 9.4 > JobId: 105 > Job: RestoreFiles.2024-09-05_00.42.58_04 > Restore Client: "bacula-fd" 15.0.2 (21Mar24) x86_64-redhat-linux-gnu,redhat,Enterprise 9.4 > Where: /bacula/restores > Replace: Always > Start time: 05-Sep-2024 00:43:00 > End time: 05-Sep-2024 00:43:00 > Elapsed time: 1 sec > Files Expected: 2 > Files Restored: 2 > Bytes Restored: 0 (0 B) > Rate: 0.0 KB/s > FD Errors: 0 > FD termination status: OK > SD termination status: OK > Termination: Restore OK > > 05-Sep 00:43 bacula-dir JobId 105: Begin pruning Jobs older than 1 month 5 days . > 05-Sep 00:43 bacula-dir JobId 105: No Jobs found to prune. > 05-Sep 00:43 bacula-dir JobId 105: Begin pruning Files. > 05-Sep 00:43 bacula-dir JobId 105: No Files found to prune. > 05-Sep 00:43 bacula-dir JobId 105: End auto prune. > > > > > > > I ran a new job last nigh with bacula-fd in debug mode but nothing useful was produced. > > > > > > bacula-fd -f -c /etc/bacula/bacula-fd.conf -u root -g root -d 9 -v -m > > > galileo-fd: events.c:48-106 Events: code=FJ0001 daemon=galileo-fd ref=0x7ff3cc01cf08 type=job source=bacula-dir text=Job Start jobid=106 job=GalileoJob.2024-09-05_03.34.59_05 > galileo-fd: metaplugin.cpp:3159-106 kubernetes: handlePluginEvent (3) pContext = 7ff3cc01aab8 thid = 7ff3df4006c0 > galileo-fd: events.c:48-106 Events: code=FJ0002 daemon=galileo-fd ref=0x7ff3cc01cf08 type=job source=bacula-dir text=Job End jobid=106 job=GalileoJob.2024-09-05_03.34.59_05 > galileo-fd: metaplugin.cpp:3159-106 kubernetes: handlePluginEvent (4) pContext = 7ff3cc01aab8 thid = 7ff3df4006c0 > galileo-fd: metaplugin.cpp:3159-106 kubernetes: handlePluginEvent (2) pContext = 7ff3cc01aab8 thid = 7ff3df4006c0 > galileo-fd: events.c:48-106 Events: code=FC0001 daemon=galileo-fd ref=0x7ff3cc01cf08 type=connection source=bacula-dir text=Director disconnection > galileo-fd: metaplugin.cpp:3113-106 kubernetes: freePlugin this=7ff3cc01aab8 > > > > *estimate job=GalileoJob level=Incremental accurate=yes listing > Using Catalog "MyCatalog" > Connecting to Client galileo-fd at 10.8.0.8:9102 > -rw-r--r-- 1 root root 1180 2024-09-05 01:26:37 /root/bacula_exclude.list > -rw------- 1 root root 16116 2024-09-05 01:26:37 /root/.viminfo > dr-xr-x--- 29 root root 4096 2024-09-05 01:26:37 /root > > > > Clipped for verbosity ... > > > > srwxr-xr-x 1 galileo galileo 0 2024-02-28 19:35:18 /home/galileo/.electrum/daemon_rpc_socket > -rw-r--r-- 1 galileo galileo 524288 2024-09-05 03:33:36 /home/hs/tmp/bacula_test/test3.bin > drwxr-xr-x 2 galileo galileo 74 2024-09-05 03:33:36 /home/hs/tmp/bacula_test > 2000 OK estimate files=52 bytes=5,374,912 > * > * > *run job=GalileoJob level=Incremental accurate=yes > Run Backup job > JobName: GalileoJob > Level: Incremental > Client: galileo-fd > FileSet: WorkStationsFS > Pool: Incr-Pool (From Job resource) > Storage: DirectorAutochanger (From Pool resource) > When: 2024-09-05 03:34:57 > Priority: 10 > OK to run? (Yes/mod/no): y > Job queued. JobId=106 > * > You have messages. > *m > 05-Sep 03:35 bacula-dir JobId 106: Start Backup JobId 106, Job=GalileoJob.2024-09-05_03.34.59_05 > 05-Sep 03:35 bacula-dir JobId 106: Connected to Storage "DirectorAutochanger" at 10.1.0.93:9103 with TLS > 05-Sep 03:35 bacula-dir JobId 106: Using Device "LocalFileChgr0-Dev1" to write. > 05-Sep 03:35 bacula-dir JobId 106: Connected to Client "galileo-fd" at 10.8.0.8:9102 with TLS > 05-Sep 03:35 galileo-fd JobId 106: Connected to Storage at 10.1.0.93:9103 with TLS > 05-Sep 03:35 bacula-dir JobId 106: Sending Accurate information to the FD. > 05-Sep 03:35 bacula-sd JobId 106: Volume "Incr-Pool_Volume-004" previously written, moving to end of data. > 05-Sep 03:35 bacula-sd JobId 106: Ready to append to end of Volume "Incr-Pool_Volume-004" size=10,677,763 > 05-Sep 03:35 bacula-sd JobId 106: Elapsed time=00:00:14, Transfer rate=2.884 K Bytes/second > 05-Sep 03:35 bacula-sd JobId 106: Sending spooled attrs to the Director. Despooling 53,484 bytes ... > 05-Sep 03:35 bacula-dir JobId 106: Bacula bacula-dir 15.0.2 (21Mar24): > Build OS: x86_64-redhat-linux-gnu redhat Enterprise 9.4 > JobId: 106 > Job: GalileoJob.2024-09-05_03.34.59_05 > Backup Level: Incremental, since=2024-09-05 00:46:06 > Client: "galileo-fd" 15.0.2 (21Mar24) x86_64-redhat-linux-gnu,redhat, > FileSet: "WorkStationsFS" 2024-08-16 01:21:39 > Pool: "Incr-Pool" (From Job resource) > Catalog: "MyCatalog" (From Client resource) > Storage: "DirectorAutochanger" (From Pool resource) > Scheduled time: 05-Sep-2024 03:34:57 > Start time: 05-Sep-2024 03:35:01 > End time: 05-Sep-2024 03:35:53 > Elapsed time: 52 secs > Priority: 10 > FD Files Written: 269 > SD Files Written: 269 > FD Bytes Written: 3,479 (3.479 KB) > SD Bytes Written: 40,379 (40.37 KB) > Rate: 0.1 KB/s > Software Compression: 99.2% 120.6:1 > Comm Line Compression: 11.9% 1.1:1 > Snapshot/VSS: no > Encryption: no > Accurate: yes > Volume name(s): Incr-Pool_Volume-004 > Volume Session Id: 45 > Volume Session Time: 1725159919 > Last Volume Bytes: 10,722,402 (10.72 MB) > Non-fatal FD errors: 0 > SD Errors: 0 > FD termination status: OK > SD termination status: OK > Termination: Backup OK > > 05-Sep 03:35 bacula-dir JobId 106: Begin pruning Jobs older than 1 month 5 days . > 05-Sep 03:35 bacula-dir JobId 106: No Jobs found to prune. > 05-Sep 03:35 bacula-dir JobId 106: Begin pruning Files. > 05-Sep 03:35 bacula-dir JobId 106: No Files found to prune. > 05-Sep 03:35 bacula-dir JobId 106: End auto prune. > > *restore jobid=106 > Using Catalog "MyCatalog" > You have selected the following JobId: 106 > > Building directory tree for JobId(s) 106 ... + > 11 files inserted into the tree. > > You are now entering file selection mode where you add (mark) and > remove (unmark) files to be restored. No files are initially added, unless > you used the "all" keyword on the command line. > Enter "done" to leave this mode. > > cwd is: / > $ cd /home/hs/tmp/bacula_tests > cwd is: /home/hs/tmp/bacula_test/ > $ dir > ---------- 0 root root 0 1970-01-01 01:00:00 /home/hs/tmp/bacula_test/test3.bin/ > $ mark test3.binin > 1 file marked. > $ done > Bootstrap records written to /var/spool/bacula/bacula-dir.restore.8.bsr > > The Job will require the following (*=>InChanger): > Volume(s) Storage(s) SD Device(s) > =========================================================================== > > Incr-Pool_Volume-004 DirectorAutochanger LocalFileChgr0 > > Volumes marked with "*" are in the Autochanger. > > > 1 file selected to be restored. > > Defined Clients: > 1: bacula-fd > 2: galileo-fd > Select the Client (1-2): 1 > Run Restore job > JobName: RestoreFiles > Bootstrap: /var/spool/bacula/bacula-dir.restore.8.bsr > Where: /bacula/restores > Replace: Always > FileSet: ServersFS > Backup Client: bacula-fd > Restore Client: bacula-fd > Storage: DirectorAutochanger > When: 2024-09-05 03:37:02 > Catalog: MyCatalog > Priority: 10 > Plugin Options: *None* > OK to run? (Yes/mod/no): y > Job queued. JobId=107 > * > You have messages. > *m > 05-Sep 03:37 bacula-dir JobId 107: Start Restore Job RestoreFiles.2024-09-05_03.37.04_06 > 05-Sep 03:37 bacula-dir JobId 107: Restoring files from JobId(s) 106 > 05-Sep 03:37 bacula-dir JobId 107: Connected to Storage "DirectorAutochanger" at 10.1.0.93:9103 with TLS > 05-Sep 03:37 bacula-dir JobId 107: Using Device "LocalFileChgr0-Dev1" to read. > 05-Sep 03:37 bacula-dir JobId 107: Connected to Client "bacula-fd" at localhost:9102 with TLS > 05-Sep 03:37 bacula-fd JobId 107: Connected to Storage at 10.1.0.93:9103 with TLS > 05-Sep 03:37 bacula-sd JobId 107: Ready to read from volume "Incr-Pool_Volume-004" on File device "LocalFileChgr0-Dev1" (/bacula/storage/LocalFile/). > 05-Sep 03:37 bacula-sd JobId 107: Forward spacing Volume "Incr-Pool_Volume-004" to addr=10677763 > 05-Sep 03:37 bacula-sd JobId 107: Elapsed time=00:00:01, Transfer rate=117 Bytes/second > 05-Sep 03:37 bacula-fd JobId 107: Warning: Unexpected stream="0" ignored. This shouldn't happen! > 05-Sep 03:37 bacula-dir JobId 107: Bacula bacula-dir 15.0.2 (21Mar24): > Build OS: x86_64-redhat-linux-gnu redhat Enterprise 9.4 > JobId: 107 > Job: RestoreFiles.2024-09-05_03.37.04_06 > Restore Client: "bacula-fd" 15.0.2 (21Mar24) x86_64-redhat-linux-gnu,redhat,Enterprise 9.4 > Where: /bacula/restores > Replace: Always > Start time: 05-Sep-2024 03:37:06 > End time: 05-Sep-2024 03:37:06 > Elapsed time: 1 sec > Files Expected: 1 > Files Restored: 1 > Bytes Restored: 0 (0 B) > Rate: 0.0 KB/s > FD Errors: 0 > FD termination status: OK > SD termination status: OK > Termination: Restore OK > > 05-Sep 03:37 bacula-dir JobId 107: Begin pruning Jobs older than 1 month 5 days . > 05-Sep 03:37 bacula-dir JobId 107: No Jobs found to prune. > 05-Sep 03:37 bacula-dir JobId 107: Begin pruning Files. > 05-Sep 03:37 bacula-dir JobId 107: No Files found to prune. > 05-Sep 03:37 bacula-dir JobId 107: End auto prune. > > > > Unfortunately the issue seems to be intermittent, I can't construct a repeatable test case. > 2 days ago I did practically the same and there were no issues. Few days before that the issue was repeatable. > > I created a new test job with a new file set (just a few files in a test folder) but I wasn't able to trigger the issue. > Only hint so far was that if I disable accurate backups it seems to fix it but that was only one run so far, so not confirmed. > > When I first setup this backup server (I was previously using an ancient Bacula v5 for about 13 years) I noticed other issues: > > When setting this server I ran the initial full backup and a couple of incrementals. > Every time I ran a new incremental bacula would include ancient files from my various archived projects that haven't changed > in years and it constantly includes socket files that haven't been touched. > > So has anyone seen anything like this before and how to proceed with debugging this? > > Thanks > Dragan > > > > _______________________________________________ > Bacula-users mailing list > [email protected] > https://lists.sourceforge.net/lists/listinfo/bacula-users > _______________________________________________ Bacula-users mailing list [email protected] https://lists.sourceforge.net/lists/listinfo/bacula-users