On Thu, Jan 19, 2006 at 07:31:08PM -0500, Jean-Louis Martineau wrote:

> The Amanda core team is pleased to announce the release of Amanda
> 2.5.0b2. It is stable and we hope to release 2.5.0 soon. test it and
> report it if you find a bug in this release.

I've found one more problem.  I reported this problem yesterday to the
list, but the mail seems to be lost somehow.  Sorry if this report gets
through twice.

The problem seems to be triggered when runtapes>1 and tape_splitsize is
set.

When the first tape (vtape in my case) is filled up, driver reports that
it goes to degraded mode because of a tape error (how comes with
runtapes>1?).  Taper happily writes out all the remaining chunks to the
second tape.  But since driver (erronously) thinks that there is a
serious tape error, the chunks that taper writes to the second tape are
not removed from the holding disk.

Note that taper writes the remaining chunks after driver said that
it wants to quit.

Here comes the interesting part of the amdump.1 file:

driver: finished-cmd time 2167.114 taper wrote host.do.main:/m/b
driver: state time 4979.062 free kps: 18792 space: 6766464 taper: idle 
idle-dumpers: 9 qlen tapeq: 0 runq: 0 roomq: 0 wakeup: 0 driver-idle: no-dumpers
driver: interface-state time 4979.062 if : free 800 if ETH10: free 800 if 
ETH100: free 8000 if LOCAL: free 9192
driver: hdisk-state time 4979.062 hdisk 0: free 6766464 dumpers 1
driver: result time 4979.092 from chunker0: RQ-MORE-DISK 01-00009
driver: find_diskspace: time 4979.092: want 133536 K
driver: find_diskspace: time 4979.092: find diskspace: size 133536 hf 6766464 
df 6766240 da 133536 ha 133568
driver: find_diskspace: time 4979.092: find diskspace: selected 
/m/amchanger/hold free 6766464 reserved 133568 dumpers 0
driver: assign_holdingdisk: time 4979.092: merging holding disk 
/m/amchanger/hold to disk host.do.main:/, add 133568 for reserved 2804288, left 0
driver: send-cmd time 4979.092 to chunker0: CONTINUE 01-00009 
/m/amchanger/hold/20060203030502/host.do.main._.0 1048576 133568
driver: state time 4979.362 free kps: 18792 space: 6632896 taper: idle 
idle-dumpers: 9 qlen tapeq: 0 runq: 0 roomq: 0 wakeup: 0 driver-idle: no-dumpers
driver: interface-state time 4979.362 if : free 800 if ETH10: free 800 if 
ETH100: free 8000 if LOCAL: free 9192
driver: hdisk-state time 4979.362 hdisk 0: free 6632896 dumpers 1
driver: result time 4979.362 from dumper0: DONE 01-00009 6688750 2671057 3188 
[sec 3188.471 kb 2671057 kps 837.7 orig-kb 6688750]
driver: finished-cmd time 4979.362 dumper0 dumped host.do.main:/
driver: send-cmd time 4979.362 to chunker0: DONE 01-00009
driver: state time 4979.401 free kps: 18792 space: 6632896 taper: idle 
idle-dumpers: 9 qlen tapeq: 0 runq: 0 roomq: 0 wakeup: 0 driver-idle: no-dumpers
driver: interface-state time 4979.401 if : free 800 if ETH10: free 800 if 
ETH100: free 8000 if LOCAL: free 9192
driver: hdisk-state time 4979.401 hdisk 0: free 6632896 dumpers 1
driver: result time 4979.401 from chunker0: DONE 01-00009 2671057 [sec 3188.624 
kb 2671057 kps 837.7]
driver: finished-cmd time 4979.402 chunker0 chunked host.do.main:/
driver: adjust_diskspace: time 4979.499: host.do.main:/ 
/m/amchanger/hold/20060203030502/host.do.main._.0
driver: adjust_diskspace: time 4979.499: hdisk HD done, reserved 2804288 used 
2671153 diff -133135 alloc 2671153 dumpers 0
driver: adjust_diskspace: time 4979.499: after: disk host.do.main:/ used 2671153
driver: send-cmd time 4979.499 to taper: FILE-WRITE 00-00010 
/m/amchanger/hold/20060203030502/host.do.main._.0 host.do.main 
fffffeff9ffeffff03 / 0 20060203 512000
driver: startaflush: LARGESTFIT host.do.main / 2671153 1326289
taper: r: Total dump size should be 2671057kb, chunk size is 512000kb
taper: r: Expecting to split into 6 parts 
driver: state time 4979.500 free kps: 19600 space: 6766031 taper: writing 
idle-dumpers: 10 qlen tapeq: 0 runq: 0 roomq: 0 wakeup: 0 driver-idle: 
no-dumpers
driver: interface-state time 4979.500 if : free 800 if ETH10: free 800 if 
ETH100: free 8000 if LOCAL: free 10000
driver: hdisk-state time 4979.500 hdisk 0: free 6766031 dumpers 0
driver: result time 4979.500 from taper: SPLIT-CONTINUE 00-00010 VOL04
taper: r: end host.do.main./.20060203.0 part 1, splitting chunk that started at 
0kb after 511968kb (next chunk will start at 511968kb)
taper: reader-side: got label VOL04 filenum 10
taper: r: end host.do.main./.20060203.0 part 2, splitting chunk that started at 
512000kb after 511968kb (next chunk will start at 1023968kb)
taper: reader-side: got label VOL04 filenum 11
taper: r: switching to next holding chunk 
'/m/amchanger/hold/20060203030502/host.do.main._.0.1'
taper: writing end marker. [VOL04 ERR kb 4556768 fm 12]
changer: opening pipe to: /usr/local/bin/chg-disk.pl -info
changer: got exit: 0 str: 4 10 1 1
changer_query: changer return was 10 1 1
changer_query: searchable = 1
changer_find: looking for VOL05 changer is searchable = 1
changer_search: VOL05
changer: opening pipe to: /usr/local/bin/chg-disk.pl -search VOL05
changer: got exit: 0 str: 5 file:/m/amchanger
taper: wrote label `VOL05' date `20060203'
taper: r: seeking /m/amchanger/hold/20060203030502/host.do.main._.0 to 1023936 
kb
driver: state time 5069.363 free kps: 19600 space: 6766031 taper: writing 
idle-dumpers: 10 qlen tapeq: 0 runq: 0 roomq: 0 wakeup: 0 driver-idle: 
no-dumpers
driver: interface-state time 5069.363 if : free 800 if ETH10: free 800 if 
ETH100: free 8000 if LOCAL: free 10000
driver: hdisk-state time 5069.363 hdisk 0: free 6766031 dumpers 0
driver: result time 5069.363 from taper: SPLIT-NEEDNEXT 00-00010 1024000
driver: finished-cmd time 5069.363 taper wrote host.do.main:/
dump of driver schedule before start degraded mode:
--------
--------
dump of driver schedule after start degraded mode:
--------
--------
driver: state time 5069.363 free kps: 19600 space: 6766031 taper: DOWN 
idle-dumpers: 10 qlen tapeq: 0 runq: 0 roomq: 0 wakeup: 0 driver-idle: 
no-dumpers
driver: interface-state time 5069.363 if : free 800 if ETH10: free 800 if 
ETH100: free 8000 if LOCAL: free 10000
driver: hdisk-state time 5069.363 hdisk 0: free 6766031 dumpers 0
driver: QUITTING time 5069.363 telling children to quit
driver: send-cmd time 5069.363 to dumper0: QUIT
driver: send-cmd time 5069.363 to dumper1: QUIT
driver: send-cmd time 5069.363 to dumper2: QUIT
driver: send-cmd time 5069.363 to dumper3: QUIT
driver: send-cmd time 5069.363 to dumper4: QUIT
driver: send-cmd time 5069.363 to dumper5: QUIT
driver: send-cmd time 5069.363 to dumper6: QUIT
driver: send-cmd time 5069.363 to dumper7: QUIT
driver: send-cmd time 5069.363 to dumper8: QUIT
driver: send-cmd time 5069.363 to dumper9: QUIT
taper: r: switching to next holding chunk 
'/m/amchanger/hold/20060203030502/host.do.main._.0.1'
taper: r: end host.do.main./.20060203.0 part 3, splitting chunk that started at 
1024000kb after 511968kb (next chunk will start at 1535968kb)
taper: reader-side: got label VOL05 filenum 1
taper: r: end host.do.main./.20060203.0 part 4, splitting chunk that started at 
1536000kb after 511968kb (next chunk will start at 2047968kb)
taper: reader-side: got label VOL05 filenum 2
taper: r: switching to next holding chunk 
'/m/amchanger/hold/20060203030502/host.do.main._.0.2'
taper: r: end host.do.main./.20060203.0 part 5, splitting chunk that started at 
2048000kb after 511968kb (next chunk will start at 2559968kb)
taper: reader-side: got label VOL05 filenum 3
taper: reader-side: got label VOL05 filenum 4
taper: DONE [idle wait: 4472.170 secs]
taper: writing end marker. [VOL05 OK kb 1647296 fm 4]
driver: FINISHED time 5241.829
amdump: end at Fri Feb  3 04:32:24 CET 2006
Scanning /m/amchanger/hold...
  20060203030502: found Amanda directory.