Amanda-Users

Re: more of the dreaded 'missing size line from sendbackup'

2008-01-18 14:47:44
Subject: Re: more of the dreaded 'missing size line from sendbackup'
From: Jean-Francois Malouin <Jean-Francois.Malouin AT bic.mni.mcgill DOT ca>
To: "O'Brien MJ" <mobrien AT sgul.ac DOT uk>
Date: Fri, 18 Jan 2008 14:40:50 -0500
* O'Brien MJ <mobrien AT sgul.ac DOT uk> [20080118 11:01]:
> Hi Jean
> 
> As I mentioned in a previous mail this week, my problems miraculously
> disappeared when I upgrade the client to 2.5.2p1, still touching wood
> about that...

Both server and client are at 2.5.2p1....

Now that I investigated a little more I found out that the client
issued a few warnings in its syslog right at the time sendbackup

Jan 17 12:15:42 6A:yorick unix: NFS server: reply error 11
Jan 17 12:15:46 4A:yorick unix: WARNING: NFSTCP: service send error 11 on socket

error 11 in <sys/errno.h> is 

#define EAGAIN  11      /* Resource temporarily unavailable     */

Dunno which one is the chicken or the egg though or maybe
both (amanda and syslog warnings) are just the effects of
a deeper problem. 

Thanks
jf

> 
> I'd believed the problem was relate to 
> 
> >From the sendsize debug log:
> 
> sendsize[1907]: time 24.758: child 1911 terminated with signal 4
> 
> Which I'd seen mentioned somewhere as a linux kernel process signal
> handling change, hacked all binary outcome checks to include and convert
> the signal '4' to something sensible in sendmail and sendbackup source
> code. recompiled but to no avail. Then the upgrade cornered the goose :)
> 
> I still think that signal 4 is/was guilty.
> 
> Cheers
> 
> Marc O'Brien
> 
> ----- Original Message -----
> From: Jean-Francois Malouin <Jean-Francois.Malouin AT bic.mni.mcgill DOT ca>
> Date: Thursday, January 17, 2008 7:41 pm
> Subject: more of the dreaded 'missing size line from sendbackup'
> To: AMANDA users <amanda-users AT amanda DOT org>
> 
> > Hello again,
> > 
> > Yet another case of the driver reporting 'missing size line from
> > sendbackup' just before the DLE (~1TB) was entirely in the holddisk...
> > 
> > Here's what the server (2.5.2p1) logs show: 
> > 
> > log:
> > 
> > FAIL dumper yorick /data/nih/nih1 20080116 0 [missing size line 
> > from sendbackup]
> >  sendbackup: start [yorick:/data/nih/nih1 level 0]
> >  sendbackup: info BACKUP=/usr/freeware/bin/tar
> >  sendbackup: info RECOVER_CMD=/usr/freeware/bin/tar -xpGf - ...
> >  sendbackup: info end
> >  ? dumper: strange [missing size line from sendbackup]
> > PARTIAL chunker yorick /data/nih/nih1 20080116 0 [sec 49050.184 kb 
> > 933151530 kps 19024.4]
> > 
> > amdump:
> > 
> > driver: state time 50745.505 free kps: 1003626 space: 979020896 
> > taper: idle idle-dumpers: 11 qlen tapeq: 0 run q: 0 roomq: 0 
> > wakeup: 0 driver-idle: no-dumpers
> > driver: interface-state time 50745.505 if default: free 1002226 if 
> > local: free 1000 if le0: free 400
> > driver: hdisk-state time 50745.505 hdisk 0: free 979020896 dumpers 1
> > driver: result time 50745.522 from dumper1: FAILED 01-00002 
> > "[missing size line from sendbackup]"
> > driver: send-cmd time 50745.522 to chunker1: FAILED 01-00002
> > driver: state time 50745.522 free kps: 1003626 space: 979020896 
> > taper: idle idle-dumpers: 11 qlen tapeq: 0 runq: 0 roomq: 0 wakeup: 
> > 0 driver-idle: no-dumpers
> > driver: interface-state time 50745.522 if default: free 1002226 if 
> > local: free 1000 if le0: free 400
> > driver: hdisk-state time 50745.522 hdisk 0: free 979020896 dumpers 1
> > driver: result time 50745.522 from chunker1: PARTIAL 01-00002 
> > 933151530 "[sec 49050.184 kb 933151530 kps 19024.4]"
> > driver: finished-cmd time 50745.522 chunker1 chunked 
> > yorick:/data/nih/nih1
> > On the client (2.5.2p1), the amandad/sendbackup/runtar debug files:
> > 
> > amandad.20080116223817.debug:
> > 
> > amandad: time 49049.651: security_stream_seterr(1003ca70, write 
> > error to :
> > Resource temporarily unavailable)
> > amandad: time 49049.663: sending NAK pkt:
> > <<<<<
> > ERROR write error on stream 499999: write error to : Resource 
> > temporarilyunavailable
> > >>>>>
> > 
> > sendbackup.20080116223817.debug:
> > 
> > sendbackup-gnutar: time 724.655: /opt/amanda/av24-2/libexec/runtar: 
> > pid 7955181
> > sendbackup: time 724.656: started backup
> > sendbackup: time 49049.606: index tee cannot write [Broken pipe]
> > sendbackup: time 49049.616: pid 7963340 finish time Thu Jan 17 
> > 12:15:46 2008
> > 
> > 
> > runtar.20080116225021.debug:
> > 
> > runtar: debug 1 pid 7955181 ruid 666 euid 0: start at Wed Jan 16 
> > 22:50:21 2008
> > runtar: time 0.001: version 2.5.2p1
> > /usr/freeware/bin/tar version: tar (GNU tar) 1.13.25
> > 
> > config: left2
> > runtar: debug 1 pid 7955181 ruid 0 euid 0: rename at Wed Jan 16 
> > 22:50:21 2008
> > running: /usr/freeware/bin/tar: 'gtar' '--create' '--file' '-' '--
> > directory''/data/nih/nih1' '--one-file-system' '--listed-incremental'
> > '/opt/amanda-av24-2/var/amanda/left2/gnutar-
> > lists/yorick_data_nih_nih1_0.new''--sparse' '--ignore-failed-read' 
> > '--totals' '.' 
> > runtar: time 0.017: pid 7955181 finish time Wed Jan 16 22:50:21 2008
> > 
> > 
> > Looks like another goose chase to me...
> > Any ideas on how to debug and track this issue?
> > 
> > regards,
> > jf
> > -- 
> > <° ><
> > 

-- 
<° ><

<Prev in Thread] Current Thread [Next in Thread>