Bill Arlofski via Bacula-users schrieb am 05.06.24 um 08:49:
On 6/5/24 12:08 AM, Dr. Thorsten Brandau wrote:
Hi,
I get from time to time errors when backup up via my LTO-9
autochanger. This happens mostly when I do a full backup (ca. 30 TB
data), sometimes when using differential backup.
I am using the updated mtx-changer-script by Bill Arlofski, as the
one out of the box was always running in timeouts when tape changing
was needed.
This error popped up recently. And persisted now for several full
backups, now additionally for a differential one.
Anyone any idea where the problem is and how to solve it?
Thank you.
Cheers
Hello Dr. Thorsten Brandau,
What does my script log at this time?
the log file shows.... nothing. I am at debug level 50, what level would
be approriate?
->->->
2024-06-04 00:57:15 - Job: Media.2024-06-01_00.30.01_49 - ----------[
Starting /usr/libexec/bacula/mtx-changer-python.py ]----------
2024-06-04 00:57:15 - Job: Media.2024-06-01_00.30.01_49 - Config File:
/usr/libexec/bacula/mtx-changer-python.conf
2024-06-04 00:57:15 - Job: Media.2024-06-01_00.30.01_49 - Config
Section: DEFAULT
2024-06-04 00:57:15 - Job: Media.2024-06-01_00.30.01_49 - Changer Name:
No chgr_name specified
2024-06-04 00:57:15 - Job: Media.2024-06-01_00.30.01_49 - Job Name:
Media.2024-06-01_00.30.01_49
2024-06-04 00:57:15 - Job: Media.2024-06-01_00.30.01_49 - Changer
Device: /dev/sg7
2024-06-04 00:57:15 - Job: Media.2024-06-01_00.30.01_49 - Drive Device:
/dev/nst0
2024-06-04 00:57:15 - Job: Media.2024-06-01_00.30.01_49 - Command: unload
2024-06-04 00:57:15 - Job: Media.2024-06-01_00.30.01_49 - Drive Index: 0
2024-06-04 00:57:15 - Job: Media.2024-06-01_00.30.01_49 - Slot: 5
2024-06-04 00:57:15 - Job: Media.2024-06-01_00.30.01_49 - ----------
2024-06-04 00:57:16 - Job: Media.2024-06-01_00.30.01_49 - Unloading
volume (000002L9) from drive device /dev/nst0 (drive index: 0) to slot 5.
2024-06-04 01:02:12 - Job: Media.2024-06-01_00.30.01_49 - ----------[
Starting /usr/libexec/bacula/mtx-changer-python.py ]----------
2024-06-04 01:02:12 - Job: Media.2024-06-01_00.30.01_49 - Config File:
/usr/libexec/bacula/mtx-changer-python.conf
2024-06-04 01:02:12 - Job: Media.2024-06-01_00.30.01_49 - Config
Section: DEFAULT
2024-06-04 01:02:12 - Job: Media.2024-06-01_00.30.01_49 - Changer Name:
No chgr_name specified
2024-06-04 01:02:12 - Job: Media.2024-06-01_00.30.01_49 - Job Name:
Media.2024-06-01_00.30.01_49
2024-06-04 01:02:12 - Job: Media.2024-06-01_00.30.01_49 - Changer
Device: /dev/sg7
2024-06-04 01:02:12 - Job: Media.2024-06-01_00.30.01_49 - Drive Device:
/dev/nst0
2024-06-04 01:02:12 - Job: Media.2024-06-01_00.30.01_49 - Command: loaded
2024-06-04 01:02:12 - Job: Media.2024-06-01_00.30.01_49 - Drive Index: 0
2024-06-04 01:02:12 - Job: Media.2024-06-01_00.30.01_49 - Slot: 6
2024-06-04 01:02:12 - Job: Media.2024-06-01_00.30.01_49 - ----------
2024-06-04 01:02:30 - Job: Media.2024-06-01_00.30.01_49 - Checking if
drive device /dev/nst0 (drive index: 0) is loaded.
2024-06-04 01:02:30 - Job: Media.2024-06-01_00.30.01_49 - Drive device
/dev/nst0 (drive index: 0) is empty.
2024-06-04 01:02:30 - Job: Media.2024-06-01_00.30.01_49 - ----------[
Starting /usr/libexec/bacula/mtx-changer-python.py ]----------
2024-06-04 01:02:30 - Job: Media.2024-06-01_00.30.01_49 - Config File:
/usr/libexec/bacula/mtx-changer-python.conf
2024-06-04 01:02:30 - Job: Media.2024-06-01_00.30.01_49 - Config
Section: DEFAULT
2024-06-04 01:02:30 - Job: Media.2024-06-01_00.30.01_49 - Changer Name:
No chgr_name specified
2024-06-04 01:02:30 - Job: Media.2024-06-01_00.30.01_49 - Job Name:
Media.2024-06-01_00.30.01_49
2024-06-04 01:02:30 - Job: Media.2024-06-01_00.30.01_49 - Changer
Device: /dev/sg7
2024-06-04 01:02:30 - Job: Media.2024-06-01_00.30.01_49 - Drive Device:
/dev/nst0
2024-06-04 01:02:30 - Job: Media.2024-06-01_00.30.01_49 - Command: load
2024-06-04 01:02:30 - Job: Media.2024-06-01_00.30.01_49 - Drive Index: 0
2024-06-04 01:02:30 - Job: Media.2024-06-01_00.30.01_49 - Slot: 6
2024-06-04 01:02:30 - Job: Media.2024-06-01_00.30.01_49 - ----------
2024-06-04 01:02:31 - Job: Media.2024-06-01_00.30.01_49 - Loading volume
(000005L9) to drive device /dev/nst0 (drive index: 0) from slot 6.
2024-06-04 01:42:32 - Job: BackupCatalog.2024-05-31_23.10.00_48 -
----------[ Starting /usr/libexec/bacula/mtx-changer-python.py ]----------
2024-06-04 01:42:32 - Job: BackupCatalog.2024-05-31_23.10.00_48 - Config
File: /usr/libexec/bacula/mtx-changer-python.conf
2024-06-04 01:42:32 - Job: BackupCatalog.2024-05-31_23.10.00_48 - Config
Section: DEFAULT
2024-06-04 01:42:32 - Job: BackupCatalog.2024-05-31_23.10.00_48 -
Changer Name: No chgr_name specified
2024-06-04 01:42:32 - Job: BackupCatalog.2024-05-31_23.10.00_48 - Job
Name: BackupCatalog.2024-05-31_23.10.00_48
2024-06-04 01:42:32 - Job: BackupCatalog.2024-05-31_23.10.00_48 -
Changer Device: /dev/sg7
2024-06-04 01:42:32 - Job: BackupCatalog.2024-05-31_23.10.00_48 - Drive
Device: /dev/nst0
2024-06-04 01:42:32 - Job: BackupCatalog.2024-05-31_23.10.00_48 -
Command: loaded
2024-06-04 01:42:32 - Job: BackupCatalog.2024-05-31_23.10.00_48 - Drive
Index: 0
2024-06-04 01:42:32 - Job: BackupCatalog.2024-05-31_23.10.00_48 - Slot: 6
2024-06-04 01:42:32 - Job: BackupCatalog.2024-05-31_23.10.00_48 -
----------
2024-06-04 01:42:32 - Job: BackupCatalog.2024-05-31_23.10.00_48 -
Checking if drive device /dev/nst0 (drive index: 0) is loaded.
2024-06-04 01:42:33 - Job: BackupCatalog.2024-05-31_23.10.00_48 - Drive
index 0 is loaded with volume 000005L9 from slot 6.
<-<-<-
Most likely the mtx unload command is failing due to an issue with the
change/library. Just a guess of course, but a guess based on
experience. :)
I am not disagreeing here. However, the change is pretty new, same as
the tapes. It startet to happen on full backups previously only, so
anything could be the source...
Also, thanks for letting me know you are using this script. I have no
idea who has even tested it in the wild.
Me for example, we have been in contact due to the change timeout
problem I was having with the original script (could only handle it with
commenting the "exit" routine in the oringinal script).
Keep in mind, you can increase the logging level in the config file if
necessary, but I am still going with an mtx changer error, and I think
this might get logged, regardless.
What level would be appropriate?
And, who knows, it seems like you might also be reaching the Bacula
SD's Device 'MaximumChangerWait' timeout, and my script is being
killed by the SD. Perhaps sometimes the time it takes your library to
change a tape is right on the edge of the default for this Bacula SD
timeout threshold and all that needs to be done is to increase that
timeout.
But as I read, I see that the default for this timeout is 5 mins, and
your log paste seems to show that your SD kills my script at about the
8 minute mark. Close enough for horseshoes and hand grenades? Maybe
but seems a bit off for computers. :)🤷
So... to short? I can set it to 600s.
And, FYI keep an eye on the Gitlab repository because I have been
making changes/improvements to it. ;)
and the repository can be found at....?
Cheers
TB
_______________________________________________
Bacula-users mailing list
Bacula-users@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/bacula-users
