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 <[email protected]> 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.
[email protected]
