Re: amvault hanging

Orion,

Use attachment to attach the debug files. cut&paste are too much hard to 
read because the lines wrap.
Can you get a stracktrace of all thread using gdb?
   thread apply all bt

Jean-Louis

On 18/05/17 06:20 PM, Orion Poplawski wrote:
> Just updated my backup server to EL7.3 and built amanda-3.4.4 on it. 
> Trying
> to run amvault but it's hanging. strace shows:
>
> [pid 1015] futex(0x36f6c58, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
> [pid 1014] futex(0x3c605a8, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
> [pid 1006] restart_syscall(<... resuming interrupted call ...>) = 0
> [pid 1006] lseek(7, 0, SEEK_SET) = 0
> [pid 1006] lseek(7, 0, SEEK_CUR) = 0
> [pid 1006] write(7, "0 ", 6) = 6
> [pid 1006] poll([{fd=4, events=POLLIN}], 1, 14999) = 0 (Timeout)
> [pid 1006] lseek(7, 0, SEEK_SET) = 0
> [pid 1006] lseek(7, 0, SEEK_CUR) = 0
> [pid 1006] write(7, "0 ", 6) = 6
> [pid 1006] poll([{fd=4, events=POLLIN}], 1, 15000
>
> amvault 1006 amandabackup 0r CHR 1,3 0t0 2052 /dev/null
> amvault 1006 amandabackup 1w REG 253,57 34042 4864
> /var/lib/amanda/offsite-vault.log
> amvault 1006 amandabackup 2w REG 253,57 34042 4864
> /var/lib/amanda/offsite-vault.log
> amvault 1006 amandabackup 3w REG 253,57 0 14693639
> /var/lib/amanda/Offsite/amdump.20170518155701
> amvault 1006 amandabackup 4u a_inode 0,9 0 6935 [eventfd]
> amvault 1006 amandabackup 5r REG 8,49 6288303908968 976684770
> /mnt/amanda/data/00005.alxdisk1ib._export_clouds.0
> amvault 1006 amandabackup 6r REG 253,3 68654 1062575
> /usr/share/perl5/vendor_perl/JSON.pm
> amvault 1006 amandabackup 7u REG 253,23 6 3673456
> /var/log/amanda/taper_status_file_PP1UyF
> amvault 1006 amandabackup 8u REG 8,17 32768 212626
> /mnt/vault/slot1/00001.alxdisk1ib._export_clouds.0
> amvault 1006 amandabackup 10w REG 253,23 5300 50721
> /var/log/amanda/server/Offsite/amvault.20170518155701.debug
>
> So it looks like it's waiting for something from it's eventfd ? Not 
> sure what
> to check for now.
>
> # cat /var/log/amanda/server/Offsite/amvault.20170518155701.debug
> Thu May 18 15:57:01.356176952 2017: pid 1006: thd-0x2246800: amvault: 
> pid 1006
> ruid 27120 euid 27120 version 3.4.4: start at Thu May 18 15:57:01 2017
> Thu May 18 15:57:01.356276295 2017: pid 1006: thd-0x2246800: amvault:
> Arguments: --exact-match --fulls-only Offsite alxdisk1ib /export/clouds
> 20170513031353 0
> Thu May 18 15:57:01.357081813 2017: pid 1006: thd-0x2246800: amvault: 
> reading
> config file /etc/amanda/Offsite/amanda.conf
> Thu May 18 15:57:01.357208800 2017: pid 1006: thd-0x2246800: amvault: 
> reading
> config file /etc/amanda/Offsite/../vault.conf
> Thu May 18 15:57:01.357554736 2017: pid 1006: thd-0x2246800: amvault: 
> reading
> config file /etc/amanda/Offsite/../dumptypes.conf
> Thu May 18 15:57:01.360352028 2017: pid 1006: thd-0x2246800: amvault: 
> pid 1006
> ruid 27120 euid 27120 version 3.4.4: rename at Thu May 18 15:57:01 2017
> Thu May 18 15:57:01.368312889 2017: pid 1006: thd-0x2246800: amvault:
> /usr/lib64/perl5/vendor_perl/Amanda/Vault.pm:218:info:2500001 The 
> amdump log
> file is '/var/lib/amanda/Offsite/amdump.20170518155701'
> Thu May 18 15:57:01.368531509 2017: pid 1006: thd-0x2246800: amvault:
> /usr/lib64/perl5/vendor_perl/Amanda/Vault.pm:224:info:2500000 The 
> trace log
> file is '/var/lib/amanda/Offsite/log.20170518155701.0'
> Thu May 18 15:57:01.374962138 2017: pid 1006: thd-0x2246800: amvault:
> dir_name: /mnt/amanda/data/
> Thu May 18 15:57:01.425375866 2017: pid 1006: thd-0x2246800: amvault:
> chg-disk: Dir /mnt/vault
> Thu May 18 15:57:01.425398497 2017: pid 1006: thd-0x2246800: amvault:
> chg-disk: Using statefile '/mnt/vault/state'
> Thu May 18 15:57:01.432150840 2017: pid 1006: thd-0x2246800: amvault:
> Amanda::Taper::Scan::traditional stage 1: search for oldest reusable 
> volume
> Thu May 18 15:57:01.432566852 2017: pid 1006: thd-0x2246800: amvault:
> Amanda::Taper::Scan::traditional no oldest reusable volume
> Thu May 18 15:57:01.432721323 2017: pid 1006: thd-0x2246800: amvault:
> Amanda::Taper::Scan::traditional stage 2: scan for any reusable volume
> Thu May 18 15:57:01.433899554 2017: pid 1006: thd-0x2246800: amvault:
> dir_name: /mnt/vault/slot1/
> Thu May 18 15:57:01.434413898 2017: pid 1006: thd-0x2246800: amvault: 
> Device
> file:/mnt/vault/slot1 error = 'File 0 not found'
> Thu May 18 15:57:01.434445620 2017: pid 1006: thd-0x2246800: amvault: 
> Device
> file:/mnt/vault/slot1 setting status flag(s): 
> DEVICE_STATUS_VOLUME_UNLABELED
> Thu May 18 15:57:01.435240699 2017: pid 1006: thd-0x2246800: amvault: 
> Slot 1
> without label can be labeled
> Thu May 18 15:57:01.436413235 2017: pid 1006: thd-0x2246800: amvault:
> Amanda::Taper::Scan::traditional result: 'OVault-045' on 
> file:/mnt/vault/slot1
> slot 1, mode 2
> Thu May 18 15:57:01.436991733 2017: pid 1006: thd-0x2246800: amvault:
> Amanda::Recovery::Clerk: loading volume 'Offsite-01'
> Thu May 18 15:57:01.437282951 2017: pid 1006: thd-0x2246800: amvault:
> find_volume labeled 'Offsite-01'
> Thu May 18 15:57:01.437408911 2017: pid 1006: thd-0x2246800: amvault:
> parse_inventory: load slot 1
> Thu May 18 15:57:01.437564433 2017: pid 1006: thd-0x2246800: amvault:
> /usr/lib64/perl5/vendor_perl/Amanda/Recovery/Scan.pm:420:info:1200000 
> slot 1
> Thu May 18 15:57:01.437840627 2017: pid 1006: thd-0x2246800: amvault:
> dir_name: /mnt/amanda/data/
> Thu May 18 15:57:01.439155575 2017: pid 1006: thd-0x2246800: amvault:
> /usr/lib64/perl5/vendor_perl/Amanda/Recovery/Scan.pm:459:info:1200001 
> Offsite-01
> Thu May 18 15:57:05.163649337 2017: pid 1006: thd-0x2246800: amvault:
> Amanda::Recovery::Clerk: successfully located first part for recovery
> Thu May 18 15:57:05.164245159 2017: pid 1006: thd-0x2246800: amvault:
> Amanda::Taper::Scribe preparing to write, part size 0, using LEOM 
> detection
> (no caching) (splitter) (LEOM supported)
> Thu May 18 15:57:05.165573737 2017: pid 1006: thd-0x2246800: amvault: 
> Starting
> <Xfer@0x3ac7e60 (<XferSourceRecovery@0x3c68000> ->
> <XferDestTaperSplitter@0x3c69000>)>
> Thu May 18 15:57:05.165636216 2017: pid 1006: thd-0x2246800: amvault: 
> Final
> linkage: <XferSourceRecovery@0x3c68000> -(PULL_BUFFER)->
> <XferElementGlue@0x3c6d030> -(PUSH_BUFFER)-> 
> <XferDestTaperSplitter@0x3c69000>
> Thu May 18 15:57:05.165656538 2017: pid 1006: thd-0x2246800: amvault:
> setup_impl: 3, 5
> Thu May 18 15:57:05.165790153 2017: pid 1006: thd-0x2246800: amvault:
> xfer_queue_message: MSG: <XMsg@0x3c5f700 type=XMSG_READY
> elt=<XferSourceRecovery@0x3c68000> version=0>
> Thu May 18 15:57:05.165849314 2017: pid 1006: thd-0x2246800: amvault:
> Amanda::Recovery::Clerk: starting recovery
> Thu May 18 15:57:05.165998194 2017: pid 1006: thd-0x3c5f850: amvault:
> pull_and_push
> Thu May 18 15:57:05.170351738 2017: pid 1006: thd-0x2246800: amvault: 
> Building
> type TAPESTART header of 32768-32768 bytes with name='OVault-045' disk=''
> dumplevel=0 and blocksize=32768
> Thu May 18 15:57:05.173511208 2017: pid 1006: thd-0x3c5f800: amvault: 
> Building
> type FILE header of 32768-32768 bytes with name='alxdisk1ib'
> disk='/export/clouds' dumplevel=0 and blocksize=32768
> Thu May 18 15:57:05.174957340 2017: pid 1006: thd-0x2246800: amvault:
> /usr/lib64/perl5/vendor_perl/Amanda/Vault.pm:1177:info:2500016 Reading
> Offsite-01:5: FILE: date 20170513031353 host alxdisk1ib disk 
> /export/clouds
> lev 0 comp cust program APPLICATION server_custom_compress
> /usr/local/bin/pigz-fast
> Thu May 18 15:57:05.175402191 2017: pid 1006: thd-0x2246800: amvault:
> Amanda::Recovery::Clerk: reading file 5 on 'Offsite-01'
>
> -- 
> Orion Poplawski
> Technical Manager 720-772-5637
> NWRA, Boulder/CoRA Office FAX: 303-415-9702
> 3380 Mitchell Lane [email protected]
> Boulder, CO 80301 http://www.nwra.com 
> <http://www.nwra.com>
This message is the property of CARBONITE, INC. and may contain confidential or privileged information.
If this message has been delivered to you by mistake, then do not copy or deliver this message to anyone.  Instead, destroy it and notify me by reply e-mail