Hello,
I'm running a very small amanda installation to create regular backups
of local files and also involves archiving at some point. For archiving
files, I run a full backup that ends up in holding and then I run
amvault twice to write the backup set to two different disk changers.
Finally, I set no-reuse on the created media and delete the backup from
holding.
However, for quite some time now, amvault does not work anymore. I
believe it was after the upgrade to 3.5.1 that it stopped working.
amvault hangs at:
"Reading
'/nfs/Daten/.amanda/holding/archive/20221122112256/localhost._etc.0':
FILE: date 20221122112256 host localhost disk /etc lev 0 comp N program
APPLICATION crypt enc server_encrypt /usr/sbin/amcrypt
server_decrypt_option -d"
amvault debug output below.
Backup and restore work just fine as well as reading from and writing to
the diskchanger.
Any ideas what else I could check?
$ cat amvault.20221122155617.debug
Tue Nov 22 15:56:17.725618208 2022: pid 766: thd-0x556fc692c000:
amvault: pid 766 ruid 34 euid 34 version 3.5.1: start at Tue Nov 22
15:56:17 2022
Tue Nov 22 15:56:17.725705654 2022: pid 766: thd-0x556fc692c000:
amvault: Arguments: --dest-storage archive archive localhost /etc
20221122112256
Tue Nov 22 15:56:17.726486391 2022: pid 766: thd-0x556fc692c000:
amvault: reading config file /etc/amanda/archive/amanda.conf
Tue Nov 22 15:56:17.729550131 2022: pid 766: thd-0x556fc692c000:
amvault: pid 766 ruid 34 euid 34 version 3.5.1: rename at Tue Nov 22
15:56:17 2022
Tue Nov 22 15:56:17.730812990 2022: pid 766: thd-0x556fc692c000:
amvault:
/usr/lib/x86_64-linux-gnu/amanda/perl/Amanda/Vault.pm:218:info:2500001
The amdump log file is '/amanda/archive/state/log/amdump.20221122155617'
Tue Nov 22 15:56:17.731009586 2022: pid 766: thd-0x556fc692c000:
amvault:
/usr/lib/x86_64-linux-gnu/amanda/perl/Amanda/Vault.pm:224:info:2500000
The trace log file is '/amanda/archive/state/log/log.20221122155617.0'
Tue Nov 22 15:56:17.731288444 2022: pid 766: thd-0x556fc692c000:
amvault: event: loop: enter: nonblockg=0, eh=(nil)
Tue Nov 22 15:56:17.744031927 2022: pid 766: thd-0x556fc692c000:
amvault: chg-disk: Dir /diskchanger
Tue Nov 22 15:56:17.744058652 2022: pid 766: thd-0x556fc692c000:
amvault: chg-disk: Using statefile '/diskchanger/state'
Tue Nov 22 15:56:21.386868157 2022: pid 766: thd-0x556fc692c000:
amvault: chg-disk: Dir /diskchanger
Tue Nov 22 15:56:21.386898125 2022: pid 766: thd-0x556fc692c000:
amvault: chg-disk: Using statefile '/diskchanger/state'
Tue Nov 22 15:56:21.395246165 2022: pid 766: thd-0x556fc692c000:
amvault: Amanda::Taper::Scribe: starting
Tue Nov 22 15:56:21.396022194 2022: pid 766: thd-0x556fc692c000:
amvault: Amanda::Taper::Scan::traditional stage 1: search for oldest
reusable volume
Tue Nov 22 15:56:21.396094535 2022: pid 766: thd-0x556fc692c000:
amvault: Amanda::Taper::Scan::traditional no oldest reusable volume
Tue Nov 22 15:56:21.396211695 2022: pid 766: thd-0x556fc692c000:
amvault: Amanda::Taper::Scan::traditional stage 2: scan for any reusable
volume
Tue Nov 22 15:56:21.397554166 2022: pid 766: thd-0x556fc692c000:
amvault: dir_name: /diskchanger/slot3/
Tue Nov 22 15:56:21.398814689 2022: pid 766: thd-0x556fc692c000:
amvault: Slot 3 with label archive-0019 is usable
Tue Nov 22 15:56:21.398878953 2022: pid 766: thd-0x556fc692c000:
amvault: Amanda::Taper::Scan::traditional result: 'archive-0019' on
file:/diskchanger/slot3 slot 3, mode 2
Tue Nov 22 15:56:21.400791345 2022: pid 766: thd-0x556fc692c000:
amvault:
/usr/lib/x86_64-linux-gnu/amanda/perl/Amanda/Vault.pm:1196:info:2500017
Reading
'/nfs/Daten/.amanda/holding/archive/20221122112256/localhost._etc.0':
FILE: date 20221122112256 host localhost disk /etc lev 0 comp N program
APPLICATION crypt enc server_encrypt /usr/sbin/amcrypt
server_decrypt_option -d
Tue Nov 22 15:56:21.401162236 2022: pid 766: thd-0x556fc692c000:
amvault: Amanda::Recovery::Clerk: successfully located holding file for
recovery
Tue Nov 22 15:56:21.401313530 2022: pid 766: thd-0x556fc692c000:
amvault: start_recovery called
Tue Nov 22 15:56:21.402874620 2022: pid 766: thd-0x556fc692c000:
amvault: Amanda::Taper::Scribe preparing to write, part size 0, using
LEOM detection (no caching) (splitter) (LEOM supported)
Tue Nov 22 15:56:21.403502114 2022: pid 766: thd-0x556fc692c000:
amvault: Starting <Xfer@0x556fc82b6060
(<XferSourceHolding@0x556fc8430030> ->
<XferDestTaperSplitter@0x556fc8434030>)>
Tue Nov 22 15:56:21.403531842 2022: pid 766: thd-0x556fc692c000:
amvault: Final linkage: <XferSourceHolding@0x556fc8430030> -(MEM_RING)->
<XferDestTaperSplitter@0x556fc8434030>
Tue Nov 22 15:56:21.403653339 2022: pid 766: thd-0x556fc692c000:
amvault: Amanda::Recovery::Clerk: starting recovery
Tue Nov 22 15:56:21.403925478 2022: pid 766: thd-0x556fc692c000:
amvault: Amanda::Taper::Scribe: trying to start part
Tue Nov 22 15:56:21.404001144 2022: pid 766: thd-0x556fc692c000:
amvault: Amanda::Taper::Scribe: got new volume; writing new label
Tue Nov 22 15:56:21.404220438 2022: pid 766: thd-0x556fc692c000:
amvault: XDTS: use_device(file:/diskchanger/slot3) (no change)
Tue Nov 22 15:56:21.404745935 2022: pid 766: thd-0x556fc83f5050:
amvault: XSH: (this is the holding thread)
Tue Nov 22 15:56:21.404849681 2022: pid 766: thd-0x556fc83f5000:
amvault: XDTS: (this is the device thread)
Tue Nov 22 15:56:21.405798658 2022: pid 766: thd-0x556fc692c000:
amvault: start_recovery called
Tue Nov 22 15:56:21.406232272 2022: pid 766: thd-0x556fc83f5000:
amvault: XDTS: device_thread waiting to be unpaused
