On 2018-09-27 11:05 AM, Martin Simmons wrote:
On Wed, 26 Sep 2018 23:38:39 -0400, Gary Dale said:
On 2018-09-26 11:33 AM, Bill Arlofski wrote:
On 09/26/2018 06:22 AM, Martin Simmons wrote:
Try
setdebug level=150 trace=1 Storage
and look for a file matching *.trace (probably in the SD's WorkingDirectory).
...and you can also add options=t to have timestamps in the *.trace file.
Best regards,
Bill
I was waiting for the label command to fail again. It didn't take long.
The bconsole messages were the same. The trace doesn't tell me anything
new. Hopefully you understand it better than I. Here's the output from
the trace:
#cat /var/lib/bacula/bacula-sd.trace
bacula-sd: bnet.c:566-0 who=client host=192.168.1.17 port=9103
bacula-sd: dircmd.c:178-0 Got a DIR connection at 26-Sep-2018 23:30:25
bacula-sd: cram-md5.c:69-0 send: auth cram-md5 challenge
<56845663.1538019025@bacula-sd> ssl=0
bacula-sd: cram-md5.c:133-0 cram-get received: auth cram-md5
<554803286.1538019025@bacula-dir> ssl=0
bacula-sd: cram-md5.c:157-0 sending resp to challenge: cH+vQ7+Fdw/6P7+9R7/jRA
bacula-sd: dircmd.c:204-0 Message channel init completed.
bacula-sd: dircmd.c:806-0 Found device FileStorage
bacula-sd: dircmd.c:850-0 Found device FileStorage
bacula-sd: block_util.c:143-0 New block len=64512 block=7f19c8001160
bacula-sd: acquire.c:673-0 Attach 0xc8001c78 to dev "FileStorage"
(/home/shares/backup)
bacula-sd: vol_mgr.c:657-0 find_read_vol: read_vol_list empty.
bacula-sd: vol_mgr.c:851-0 Vol=weekly-backup-pool-37 not in use.
bacula-sd: vol_mgr.c:381-0 enter reserve_volume=weekly-backup-pool-37
drive="FileStorage" (/home/shares/backup)
bacula-sd: vol_mgr.c:286-0 new Vol=weekly-backup-pool-37 slot=0 at 7f19c8011e88
dev="FileStorage" (/home/shares/backup)
bacula-sd: vol_mgr.c:547-0 set in_use. vol=weekly-backup-pool-37
dev="FileStorage" (/home/shares/backup)
bacula-sd: vol_mgr.c:581-0 Inc walk_start use_count=2
volname=weekly-backup-pool-37
bacula-sd: vol_mgr.c:220-0 List end new volume: weekly-backup-pool-37 in_use=1 swap=0
slot=0 on file device "FileStorage" (/home/shares/backup)
bacula-sd: vol_mgr.c:693-0 Clear in_use vol=weekly-backup-pool-37 slot=0
bacula-sd: vol_mgr.c:710-0 set not reserved vol=weekly-backup-pool-37 slot=0 writers=1
reserves=0 dev="FileStorage" (/home/shares/backup)
bacula-sd: vol_mgr.c:740-0 Clear in_use vol=weekly-backup-pool-37 slot=0
bacula-sd: vol_mgr.c:746-0 Remove volume weekly-backup-pool-37 slot=0
dev="FileStorage" (/home/shares/backup)
bacula-sd: mount.c:384-3298 Again dir_find_next_append...
bacula-sd: mount.c:374-3298 No appendable volume. Calling wait_for_device
bacula-sd: wait.c:270-3298 Enter wait_for_device. busy=1 dcrvol= devvol=
bacula-sd: mount.c:384-3298 Again dir_find_next_append...
bacula-sd: mount.c:374-3298 No appendable volume. Calling wait_for_device
bacula-sd: wait.c:270-3298 Enter wait_for_device. busy=1 dcrvol= devvol=
bacula-sd: mount.c:384-3298 Again dir_find_next_append...
bacula-sd: mount.c:374-3298 No appendable volume. Calling wait_for_device
bacula-sd: wait.c:270-3298 Enter wait_for_device. busy=1 dcrvol= devvol=
Is it still printing
3934 Device ""FileStorage" (/home/shares/backup)" is being initialized.
when the label command fails? If so, then the output of the "status storage"
command might give more information.
__Martin
That message always prints just before the label command fails. It makes
no sense to me because what is there to initialize? It's a folder on a
disk (/home/shares/backup).
I just got an example of another one:
Connecting to Storage daemon File at
molar.dentaloffice.rossland.dental:9103 ...
Sending label command for Volume "weekly-backup-pool-40" Slot 0 ...
3908 Error reserving volume: vol_mgr.c:419 Cannot free Volume
"weekly-backup-pool-37", because it is reserved by someone else.
Label command failed for Volume weekly-backup-pool-40.
Do not forget to mount the drive!!!
You have messages.
Looking at the messages I find:
27-Sep 20:34 bacula-sd JobId 3302: Elapsed time=00:00:24, Transfer
rate=68.80 M Bytes/second
27-Sep 20:34 bacula-sd JobId 3302: Sending spooled attrs to the
Director. Despooling 34,365 bytes ...
27-Sep 20:34 bacula-dir JobId 3302: Bacula bacula-dir 7.4.4 (202Sep16):
Build OS: x86_64-pc-linux-gnu debian 9.0
JobId: 3302
Job: BackupServer.2018-09-27_20.34.14_04
Backup Level: Incremental, since=2018-09-25 23:47:15
Client: "server-fd" 5.2.10 (28Jun12) Microsoft
Windows 7 Professional Service Pack 1 (build 7601),
64-bit,Cross-compile,Win32
FileSet: "ServerFileSet" 2018-09-18 23:05:00
Pool: "DailyBackupPool" (From Job IncPool override)
Catalog: "MyCatalog" (From Client resource)
Storage: "File" (From Pool resource)
Scheduled time: 27-Sep-2018 20:34:10
Start time: 27-Sep-2018 20:34:18
End time: 27-Sep-2018 20:34:49
Elapsed time: 31 secs
Priority: 10
FD Files Written: 156
SD Files Written: 156
FD Bytes Written: 1,651,418,990 (1.651 GB)
SD Bytes Written: 1,651,439,939 (1.651 GB)
Rate: 53271.6 KB/s
Software Compression: None
Snapshot/VSS: no
Encryption: no
Accurate: no
Volume name(s): daily-backup-2
Volume Session Id: 1
Volume Session Time: 1538020797
Last Volume Bytes: 12,690,022,033 (12.69 GB)
Non-fatal FD errors: 0
SD Errors: 0
FD termination status: OK
SD termination status: OK
Termination: Backup OK
27-Sep 20:34 bacula-dir JobId 3302: Begin pruning Jobs older than 6 months .
27-Sep 20:34 bacula-dir JobId 3302: No Jobs found to prune.
27-Sep 20:34 bacula-dir JobId 3302: Begin pruning Files.
27-Sep 20:34 bacula-dir JobId 3302: Pruned Files from 1 Jobs for client
server-fd from catalog.
27-Sep 20:34 bacula-dir JobId 3302: End auto prune.
27-Sep 20:34 bacula-dir JobId 3303: Start Backup JobId 3303,
Job=BackupMolar.2018-09-27_20.34.26_05
27-Sep 20:34 bacula-dir JobId 3303: Using Device "FileStorage" to write.
27-Sep 20:34 bacula-sd JobId 3303: Wrote label to prelabeled Volume
"weekly-backup-pool-37" on file device "FileStorage" (/home/shares/backup)
The first bit is me manually running the BackupServer job (Yes, I know
it's not really a server, but it got called that before I took over).
The last bit is me manually running the BackupMolar job. If we go back
10 days, I moved a lot of data from Server to Molar, which is what
triggered my current urgency in finding out what is causing problems
with the volume labelling - I need a lot of new volumes to handle what
amounts to a full backup of 160G of data now on Molar. 37 is currently
being filled. I also have 38 & 39 labelled but 40 failed.
Prior to this, I was getting labelling failures from time to time but I
didn't consider it to be more than an annoyance.
_______________________________________________
Bacula-users mailing list
Bacula-users@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/bacula-users
