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
Bacula-users@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/bacula-users
