The saga continues..... I changed my debugging statements to the Amanda::Debug::debug method as your suggested, so my messages are the SGC:'s in the taper debug log file below. I also added some of these debug calls to the Amanda::Taper::Scribe routines, but I don't see much more information.
It still seems to hang right after the message about the 'Final linkage'. That is coming from the link_elements() subroutine in xfer-src/xfer.c. I am not sure what to do next to get more evidence. Sep 19 11:49:19 2010: taper: pid 3545 ruid 601 euid 601 version 3.1.2: rename at Sun Sep 19 11:49:19 2010 Sun Sep 19 11:49:19 2010: taper: SGC: main::Controller::new() Sun Sep 19 11:49:19 2010: taper: SGC: main::Controller::start() Sun Sep 19 11:49:19 2010: taper: SGC: main::Controller::_assert_in_state(init) Sun Sep 19 11:49:19 2010: taper: Amanda::Changer::compat initialized with script /usr/local/libexec/amanda/chg-disk, temporary directory /usr/local/etc/amanda/daily Sun Sep 19 11:49:19 2010: taper: SGC: Amanda::Taper::Scribe::new() Sun Sep 19 11:49:19 2010: taper: SGC: Amanda::Taper::Scribe::Dev_Handling::new() Sun Sep 19 11:49:19 2010: taper: driver/taper << START-TAPER 20100919114917 Sun Sep 19 11:49:19 2010: taper: SGC: main::Controller::_assert_in_state(init) Sun Sep 19 11:49:19 2010: taper: SGC: Amanda::Taper::Scribe::start() Sun Sep 19 11:49:19 2010: taper: Amanda::Taper::Scribe: starting Sun Sep 19 11:49:19 2010: taper: SGC: Amanda::Taper::Scribe::Dev_Handling::start() Sun Sep 19 11:49:19 2010: taper: SGC: Amanda::Taper::Scribe::Dev_Handling::_start_scanning() Sun Sep 19 11:49:19 2010: taper: Amanda::Taper::Scan::traditional stage 1: search for oldest reusable volume Sun Sep 19 11:49:19 2010: taper: Amanda::Taper::Scan::traditional no oldest reusable volume Sun Sep 19 11:49:19 2010: taper: Amanda::Taper::Scan::traditional stage 2: scan for any reusable volume Sun Sep 19 11:49:19 2010: taper: Amanda::Changer::compat: invoking /usr/local/libexec/amanda/chg-disk with -info Sun Sep 19 11:49:21 2010: taper: Amanda::Changer::compat: Got response '1 12 1' with exit status 0 Sun Sep 19 11:49:21 2010: taper: Amanda::Changer::compat: invoking /usr/local/libexec/amanda/chg-disk with -slot current Sun Sep 19 11:49:22 2010: taper: Amanda::Changer::compat: Got response '1 file:/amanda/vtl/daily' with exit status 0 Sun Sep 19 11:49:22 2010: taper: Amanda::Taper::Scan::traditional result: 'DAILY-1' on file:/amanda/vtl/daily slot 1, mode 2 Sun Sep 19 11:49:22 2010: taper: SGC: Amanda::Taper::Scribe::Dev_Handling::_maybe_callback() Sun Sep 19 11:49:22 2010: taper: SGC: main::Controller::_scribe_started_cb() Sun Sep 19 11:49:22 2010: taper: driver/taper >> TAPER-OK Sun Sep 19 11:50:12 2010: taper: driver/taper << FILE-WRITE 00-00002 /amanda/holding-b/20100919114917/galadriel.corbesero.net._.2 galadriel.corbesero.net / 2 20100919114917 0 130875 Sun Sep 19 11:50:12 2010: taper: SGC: main::Controller::_assert_in_state(idle) Sun Sep 19 11:50:12 2010: taper: SGC: main::Controller::setup_and_start_dump() Sun Sep 19 11:50:12 2010: taper: SGC: main::Controller::_assert_in_state(idle) Sun Sep 19 11:50:12 2010: taper: SGC: main::Controller::get_splitting_config() Sun Sep 19 11:50:12 2010: taper: warning: Use of uninitialized value $params{"data_path"} in string eq at /usr/local/libexec/amanda/taper line 606. Sun Sep 19 11:50:12 2010: taper: SGC: Amanda::Taper::Scribe::get_xfer_dest() Sun Sep 19 11:50:12 2010: taper: Amanda::Taper::Scribe: get_xfer_dest(split_method=none) Sun Sep 19 11:50:12 2010: taper: Amanda::Taper::Scribe setting up a transfer with split method none Sun Sep 19 11:50:12 2010: taper: SGC: Amanda::Taper::Scribe::get_device() Sun Sep 19 11:50:12 2010: taper: SGC: Amanda::Taper::Scribe::Dev_Handling::peek_device() -> Amanda::Device::Device=HASH(0x29f7c71c) Sun Sep 19 11:50:12 2010: taper: XDT thd-0x298ecf70: using slab_size 32768 and max_slabs 2 Sun Sep 19 11:50:12 2010: taper: Starting <x...@0x29f178e0 (<xfersourcehold...@0x284cac00> -> <xferdesttapersplit...@0x29a37820>)> Sun Sep 19 11:50:12 2010: taper: Final linkage: <xfersourcehold...@0x284cac00> -(PULL_BUFFER)-> <xferelementg...@0x29a38038> -(PUSH_BUFFER)-> <xferdesttapersplit...@0x29a37820> On Sat, Sep 18, 2010 at 04:43:53PM -0500, Dustin J. Mitchell wrote: > On Sat, Sep 18, 2010 at 4:17 PM, Stephen Corbesero <corbes...@ptd.net> wrote: > > Also, if it is worth anything, the state of the process is listed as > > 'umtxn' from top/ps. (This is a FreeBSD 8.1 system.) > > Huh, so that sounds like a kernel lock: > http://old.nabble.com/what-is-umtxn-td20860047.html > > Can you identify further the last few lines of perl executed? You > should use Amanda::Debug::debug instead, so that your logging will be > intermixed with the other information from taper_debug, in the taper > debug log. You mentioned that you enabled taper_debug, but never sent > along the debug log - can you do that now? > -- Stephen Corbesero It's always darkest Bethlehem, PA 18015 before pitch black. corbes...@ptd.net