Re: 3.4: eject-volume=yes with interactivity keeps tape device open

Thu, 09 Feb 2017 08:02:12 -0800 

Hi,

Can you try the attached patch.

Jean-Louis

On 08/02/17 12:58 PM, ts...@portrix-systems.de wrote:

Hi,
tried this with: http://www.zmanda.com/downloads/community/Amanda/3.4.2/Redhat_Enterprise_6.0/amanda-backup_server-3.4.2-1.rhel6.x86_64.rpm 
(and also 3.4.1)

Oracle Linux Server release 6.8
# uname -rsv
Linux 4.1.12-61.1.23.el6uek.x86_64 #2 SMP Tue Dec 20 16:51:41 PST 2016


Tapeinfo:
Vendor ID: 'HP      '
Product ID: 'Ultrium 4-SCSI  '
Revision: 'H63Z'
The test backup doesn't fit on one tape. After I get the E-Mail from the interactivity module, I can see with lsof that the taper still has a lock on /dev/nst1: 

> # lsof /dev/nst1

COMMAND  PID         USER   FD   TYPE DEVICE SIZE/OFF    NODE NAME
taper   1168 amandabackup    5u   CHR  9,129      0t0 1812371 /dev/nst1
touching the check-file looks like this in /var/log/amanda/server/ptxhamtest/taper.20170208122530.debug:
Wed Feb 08 16:21:12.035824026 2017: pid 1168: thd-0x240ad70: taper: xfer_queue_message: MSG: <XMsg@0x7ff8bc012390 type=XMSG_PART_DONE elt=<XferDestTaperSplitter@0x24090a0> version=0> Wed Feb 08 16:21:12.036846793 2017: pid 1168: thd-0x240ad70: taper: Building type SPLIT_FILE header of 32768-32768 bytes with name='localhost' disk='/amanda/testbackupsrc' dumplevel=0 and blocksize=32768 Wed Feb 08 16:22:52.113249836 2017: pid 1168: thd-0x240ad70: taper: Device tape:/dev/nst1 error = 'No space left on device' Wed Feb 08 16:22:52.113278102 2017: pid 1168: thd-0x240ad70: taper: Device tape:/dev/nst1 setting status flag(s): DEVICE_STATUS_VOLUME_ERROR Wed Feb 08 16:22:53.101250403 2017: pid 1168: thd-0x240ad70: taper: xfer_queue_message: MSG: <XMsg@0x7ff8bc012670 type=XMSG_PART_DONE elt=<XferDestTaperSplitter@0x24090a0> version=0> Wed Feb 08 16:23:19.976805822 2017: pid 1168: thd-0x1454d20: taper: Will request retry of failed split part. Wed Feb 08 16:23:19.977170240 2017: pid 1168: thd-0x1454d20: taper: tape HAM-M-029-L4 kb 754974720 fm 73 [OK] Wed Feb 08 16:23:19.980883703 2017: pid 1168: thd-0x1454d20: taper: Device is in variable block size Wed Feb 08 16:23:40.882859608 2017: pid 1168: thd-0x1454d20: taper: new Amanda::Changer::Error: type='failed', reason='notfound', message='No acceptable volumes found' Wed Feb 08 16:23:40.882974991 2017: pid 1168: thd-0x1454d20: taper: cmd: /usr/bin/Mail -s AMANDA VOLUME REQUEST: new volume x...@xxx.xxx
Wed Feb 08 16:23:50.888937917 2017: pid 1168: thd-0x1454d20: taper: new Amanda::Changer::Error: type='failed', reason='notfound', message='No acceptable volumes found' Wed Feb 08 16:24:00.960351367 2017: pid 1168: thd-0x1454d20: taper: new Amanda::Changer::Error: type='failed', reason='notfound', message='No acceptable volumes found' Wed Feb 08 16:24:10.960959061 2017: pid 1168: thd-0x1454d20: taper: new Amanda::Changer::Error: type='failed', reason='notfound', message='No acceptable volumes found' 
...
Wed Feb 08 17:20:55.510368422 2017: pid 1168: thd-0x1454d20: taper: new Amanda::Changer::Error: type='failed', reason='notfound', message='No acceptable volumes found' Wed Feb 08 17:21:05.512939917 2017: pid 1168: thd-0x1454d20: taper: new Amanda::Changer::Error: type='failed', reason='notfound', message='No acceptable volumes found' Wed Feb 08 17:21:15.515187884 2017: pid 1168: thd-0x1454d20: taper: new Amanda::Changer::Error: type='failed', reason='notfound', message='No acceptable volumes found' Wed Feb 08 17:21:25.517437824 2017: pid 1168: thd-0x1454d20: taper: Device tape:/dev/nst1 error = 'Can't open tape device /dev/nst1: Device or resource busy' Wed Feb 08 17:21:25.517455484 2017: pid 1168: thd-0x1454d20: taper: Device tape:/dev/nst1 setting status flag(s): DEVICE_STATUS_DEVICE_BUSY Wed Feb 08 17:21:25.517680908 2017: pid 1168: thd-0x1454d20: taper: Slot 1 without label can be labeled Wed Feb 08 17:21:25.517775016 2017: pid 1168: thd-0x1454d20: taper: new Amanda::Changer::Error: type='fatal', message='Can't open tape device /dev/nst1: Device or resource busy' Wed Feb 08 17:21:25.518772880 2017: pid 1168: thd-0x1454d20: taper: cmd: /usr/bin/Mail -s AMANDA VOLUME REQUEST: new volume x...@xxx.xxx
if I remove "eject-volume yes" from amanda.conf, lsof doesn't show /dev/nst1 as open after the mail and logfile looks like this when touching the check-file:
Sun Feb 05 22:01:45.892621331 2017: pid 14498: thd-0x36592a0: taper: xfer_queue_message: MSG: <XMsg@0x7f5770012690 type=XMSG_PART_DONE elt=<XferDestTaperSplitter@0x3226530> version=0> Sun Feb 05 22:01:45.893809646 2017: pid 14498: thd-0x36592a0: taper: Building type SPLIT_FILE header of 32768-32768 bytes with name='localhost' disk='abc-rman' dumplevel=0 and blocksize=32768 Sun Feb 05 22:02:27.050993044 2017: pid 14498: thd-0x36592a0: taper: Device tape:/dev/nst1 error = 'No space left on device' Sun Feb 05 22:02:27.051019886 2017: pid 14498: thd-0x36592a0: taper: Device tape:/dev/nst1 setting status flag(s): DEVICE_STATUS_VOLUME_ERROR Sun Feb 05 22:02:28.006847900 2017: pid 14498: thd-0x36592a0: taper: xfer_queue_message: MSG: <XMsg@0x7f5770016d70 type=XMSG_PART_DONE elt=<XferDestTaperSplitter@0x3226530> version=0> Sun Feb 05 22:02:54.991253275 2017: pid 14498: thd-0x2258610: taper: Will request retry of failed split part. Sun Feb 05 22:02:54.992089576 2017: pid 14498: thd-0x2258610: taper: tape HAM-M-025-L4 kb 804625975 fm 137 [OK] Sun Feb 05 22:02:54.993163873 2017: pid 14498: thd-0x2258610: taper: new Amanda::Changer::Error: type='failed', reason='notfound', message='No acceptable volumes found' Sun Feb 05 22:02:54.993302419 2017: pid 14498: thd-0x2258610: taper: cmd: /usr/bin/Mail -s AMANDA VOLUME REQUEST: new volume x...@xxx.xxx
Sun Feb 05 22:03:04.998826673 2017: pid 14498: thd-0x2258610: taper: new Amanda::Changer::Error: type='failed', reason='notfound', message='No acceptable volumes found' Sun Feb 05 22:03:15.005238432 2017: pid 14498: thd-0x2258610: taper: new Amanda::Changer::Error: type='failed', reason='notfound', message='No acceptable volumes found' Sun Feb 05 22:03:25.009766390 2017: pid 14498: thd-0x2258610: taper: new Amanda::Changer::Error: type='failed', reason='notfound', message='No acceptable volumes found' 
...
Mon Feb 06 09:13:13.437584985 2017: pid 14498: thd-0x2258610: taper: new Amanda::Changer::Error: type='failed', reason='notfound', message='No acceptable volumes found' Mon Feb 06 09:13:23.455771038 2017: pid 14498: thd-0x2258610: taper: new Amanda::Changer::Error: type='failed', reason='notfound', message='No acceptable volumes found' Mon Feb 06 09:13:33.473860747 2017: pid 14498: thd-0x2258610: taper: new Amanda::Changer::Error: type='failed', reason='notfound', message='No acceptable volumes found' Mon Feb 06 09:13:38.596670849 2017: pid 14498: thd-0x2258610: taper: Device is in variable block size Mon Feb 06 09:13:40.734257638 2017: pid 14498: thd-0x2258610: taper: Slot 1 with label HAM-M-026-L4 is usable Mon Feb 06 09:13:45.889592195 2017: pid 14498: thd-0x2258610: taper: Building type TAPESTART header of 32768-32768 bytes with name='HAM-M-026-L4' disk='' dumplevel=0 and blocksize=32768 


Thanks,
Thilo

diff --git a/perl/Amanda/ScanInventory.pm b/perl/Amanda/ScanInventory.pm
index 1727967..a9a5e14 100644
--- a/perl/Amanda/ScanInventory.pm
+++ b/perl/Amanda/ScanInventory.pm
@@ -126,7 +126,7 @@ sub _scan {
     my $poll_src;
     my $scan_running = 0;
     my $interactivity_running = 0;
-    my $restart_scan = 0;
+    my $restart_scan = 0;		# if a scan must be restarted
     my $restart_scan_changer = undef;
     my $abort_scan = undef;
     my $last_err = undef; # keep the last meaningful error, the one reported
@@ -137,6 +137,7 @@ sub _scan {
     my $remove_undef_state = 0;
     my $result_cb = $params{'result_cb'};
     my $new_inventory = 0;
+    my $restart_scan_running = 0;	# if restart_scan is running
 
     my $steps = define_steps
 	cb_ref => \$result_cb;
@@ -157,6 +158,9 @@ sub _scan {
     step restart_scan => sub {
 	$restart_scan = 0;
 
+	return if $restart_scan_running;
+	$restart_scan_running = 1;
+
 	# Reload the tapelist at every scan.
 	$self->{'tapelist'}->reload(0);
 
@@ -473,6 +477,7 @@ sub _scan {
 
     step scan_next => sub {
 	my ($scan_method, $err, $continue_cb) = @_;
+	$restart_scan_running = 0;
 
 	if ($scan_method == SCAN_ASK && !defined $self->{'interactivity'}) {
 	    $scan_method = SCAN_FAIL;

Reply via email to