Amanda-Users

Can't get good backups, where might this timeout be?

2004-02-26 08:16:24
Subject: Can't get good backups, where might this timeout be?
From: stan <stanb AT panix DOT com>
To: amanda users list <amanda-users AT amanda DOT org>
Date: Thu, 26 Feb 2004 08:09:20 -0500
I need some hep figuring out why 2 of my machines sudenly are failing to
backup. 

Here's the scenario. I have an existing Amanda installation that was
working well. I added several disk partitons to the backup set. These
partions are on the dumphost. Tey also are big enough that they have to be
broken up into smaller chunks to fit on the tape.

Since then, I have not gotten a good backup of thes 2 machines in question
(teddy and smokey). Bith report "data timeout" See the report below:


These dumps were to tape DailyDump05.
The next tape Amanda expects to use is: DailyDump06.

FAILURE AND STRANGE DUMP SUMMARY:
  teddy      hda2 lev 0 FAILED [data read: Operation timed out]
  smokey     hda2 lev 1 FAILED [data read: Operation timed out]


STATISTICS:
                          Total       Full      Daily
                        --------   --------   --------
Estimate Time (hrs:min)    0:14
Run Time (hrs:min)         3:39
Dump Time (hrs:min)        6:19       6:00       0:19
Output Size (meg)       11340.5    11064.8      275.7
Original Size (meg)     17396.5    16187.2     1209.3
Avg Compressed Size (%)    65.2       68.4       22.7   (level:#disks ...)
Filesystems Dumped           23         12         11   (1:9 2:1 5:1)
Avg Dump Rate (k/s)       510.9      524.5      250.5

Tape Time (hrs:min)        2:16       2:12       0:04
Tape Size (meg)         11340.8    11065.0      275.8
Tape Used (%)              58.0       56.6        1.4   (level:#disks ...)
Filesystems Taped            23         12         11   (1:9 2:1 5:1)
Avg Tp Write Rate (k/s)  1422.9     1425.9     1310.6

USAGE BY TAPE:
  Label             Time      Size      %    Nb
  DailyDump05       2:16   11340.8   58.0    23


FAILED AND STRANGE DUMP DETAILS:

/-- teddy      hda2 lev 0 FAILED [data read: Operation timed out]
sendbackup: start [teddy:hda2 level 0]
sendbackup: info BACKUP=/bin/tar
sendbackup: info RECOVER_CMD=/bin/gzip -dc |/bin/tar -f... -
sendbackup: info COMPRESS_SUFFIX=.gz
sendbackup: info end
| gtar: ./dev/gpmctl: socket ignored
| gtar: ./dev/lircd: socket ignored
| gtar: ./dev/log: socket ignored
\--------

/-- smokey     hda2 lev 1 FAILED [data read: Operation timed out]
sendbackup: start [smokey:hda2 level 1]
sendbackup: info BACKUP=/bin/tar
sendbackup: info RECOVER_CMD=/bin/gzip -dc |/bin/tar -f... -
sendbackup: info COMPRESS_SUFFIX=.gz
sendbackup: info end
\--------


NOTES:
  planner: black WAVS-lo 20040226 0 [dumps too big, 1910970 KB, full dump 
delayed]
  planner: black MUSIC-lo 20040226 0 [dumps too big, 2385450 KB, full dump 
delayed]
  planner: black MUSIC-hk 20040226 0 [dumps too big, 3231520 KB, full dump 
delayed]
  planner: black WAVS-oz 20040226 0 [dumps too big, 6139790 KB, full dump 
delayed]
  planner: black WAVS-hk 20040226 0 [dumps too big, 6188260 KB, full dump 
delayed]
  planner: black MUSIC-oz 20040226 0 [dumps too big, 6316650 KB, full dump 
delayed]
  planner: black MUSIC-ag 20040226 0 [dumps too big, 8453050 KB, full dump 
delayed]
  planner: black WAVS-ag 20040226 0 [dumps too big, 10952940 KB, full dump 
delayed]
  planner: black spare-rest 20040226 0 [dumps too big, 7510756 KB, full dump 
delayed]
  planner: smokey hda2 20040226 0 [dumps too big, 7748548 KB, full dump delayed]
  planner: yogi hda1 20040226 0 [dumps too big, 15191133 KB, full dump delayed]
  planner: black ad0s1g 20040226 0 [dumps too big, 6442932 KB, full dump 
delayed]
  planner: Full dump of koala:wd0e promoted from 4 days ahead.
  planner: Full dump of cindy:ad0s1e promoted from 4 days ahead.
  planner: Full dump of black:spaer-b promoted from 4 days ahead.
  planner: Full dump of koala:wd0a promoted from 4 days ahead.
  planner: Full dump of cindy:ad0s1a promoted from 4 days ahead.
  planner: Full dump of black:ad0s1f promoted from 4 days ahead.
  planner: Full dump of black:ad0s1a promoted from 4 days ahead.
  planner: Full dump of cindy:ad0s1f promoted from 4 days ahead.
  planner: Full dump of koala:wd0d promoted from 4 days ahead.
  planner: Full dump of cindy:ad0s1g promoted from 4 days ahead.
  planner: Full dump of koala:wd0g promoted from 4 days ahead.
  planner: Full dump of koala:wd0f promoted from 4 days ahead.
  taper: tape DailyDump05 kb 11613728 fm 23 [OK]


DUMP SUMMARY:
                                         DUMPER STATS                    TAPER 
STATS   
HOSTNAME     DISK        L    ORIG-KB     OUT-KB COMP%   MMM:SS  KB/s   MMM:SS  
   KB/s
-------------------------- ------------------------------------------ 
-----------------
black        MUSIC-ag    1        680        704   --      0:05 148.1     0:02  
  298.2
black        MUSIC-hk    1        300        320   --      0:02 158.0     0:02  
  203.1
black        MUSIC-lo    1        270        288   --      0:02 147.8     0:02  
  173.7
black        MUSIC-oz    1        660        672   --      0:05 131.5     0:02  
  355.4
black        WAVS-ag     1        120        128   --      0:03  37.1     0:02  
   70.0
black        WAVS-hk     1         70         96   --      0:01  66.4     0:01  
   64.1
black        WAVS-lo     1         40         64   --      0:00 105.3     0:02  
   42.1
black        WAVS-oz     1         80         96   --      0:01 112.4     0:02  
   59.4
black        ad0s1a      0      85860      22208  25.9     1:28 251.1     0:17  
 1333.3
black        ad0s1f      0       5567       2528  45.4     0:17 149.5     0:03  
  823.0
black        ad0s1g      5    1196861     276992  23.1    15:04 306.4     3:15  
 1417.0
black        spaer-b     0   14344180   10801248  75.3    68:242631.8   125:59  
 1428.8
black        spare-rest  1       1740        128   7.4     0:05  26.6     0:02  
   76.1
cindy        ad0s1a      0      45215      18368  40.6     5:59  51.1     0:13  
 1370.9
cindy        ad0s1e      0       4947        768  15.5     0:12  60.5     0:02  
  463.5
cindy        ad0s1f      0        433         32   7.4     0:02  13.2     0:02  
   13.7
cindy        ad0s1g      0    1349635     310368  23.0   108:46  47.6     3:38  
 1424.3
koala        wd0a        0      31419      12704  40.4     7:12  29.4     0:10  
 1252.4
koala        wd0d        0        341         32   9.4     0:02   7.5     0:02  
   13.9
koala        wd0e        0      19636       4960  25.3     4:51  17.0     0:05  
 1017.0
koala        wd0f        0     688208     157280  22.9   162:45  16.1     1:53  
 1394.9
koala        wd0g        0        232         32  13.8     0:05   4.4     0:01  
   21.7
smokey       hda2        1 FAILED 
-----------------------------------------------------
teddy        hda2        0 FAILED 
-----------------------------------------------------
yogi         hda1        2      37490       2976   7.9     3:20  14.9     0:04  
  673.7

(brought to you by Amanda version 2.4.4)

Here is the senbackup debug from smokey for last night:


sendbackup: debug 1 pid 22028 ruid 1001 euid 1001: start at Wed Feb 25 00:59:21 
2004
/usr/local/amanda/libexec/sendbackup: version 2.4.3b4
  parsed request as: program `GNUTAR'
                     disk `hda2'
                     device `hda2'
                     level 1
                     since 2004:2:13:5:57:8
                     options 
`|;auth=bsd;compress-best;index;exclude-list=/usr/local/lib/amanda/exclude.gtar;'
sendbackup: try_socksize: send buffer size is 65536
sendbackup: time 0.000: stream_server: waiting for connection: 0.0.0.0.37993
sendbackup: time 0.000: stream_server: waiting for connection: 0.0.0.0.37994
sendbackup: time 0.000: stream_server: waiting for connection: 0.0.0.0.37995
sendbackup: time 0.000: waiting for connect on 37993, then 37994, then 37995
sendbackup: time 0.002: stream_accept: connection from 205.159.77.224.3542
sendbackup: time 0.003: stream_accept: connection from 205.159.77.224.3543
sendbackup: time 0.004: stream_accept: connection from 205.159.77.224.3544
sendbackup: time 0.004: got all connections
sendbackup: time 0.005: spawning /bin/gzip in pipeline
sendbackup: argument list: /bin/gzip --best
sendbackup-gnutar: time 0.005: pid 22030: /bin/gzip --best
sendbackup-gnutar: time 0.780: doing level 1 dump as listed-incremental from 
/usr/local/amanda/var/amanda/gnutar-lists/smokeyhda2_0 to 
/usr/local/amanda/var/amanda/gnutar-lists/smokeyhda2_1.new
sendbackup-gnutar: time 0.801: doing level 1 dump from date: 2004-02-13  
5:57:09 GMT
sendbackup: time 0.802: spawning /usr/local/amanda/libexec/runtar in pipeline
sendbackup: argument list: gtar --create --file - --directory / 
--one-file-system --listed-incremental 
/usr/local/amanda/var/amanda/gnutar-lists/smokeyhda2_1.new --sparse 
--ignore-failed-read --totals --exclude-from 
/tmp/amanda/sendbackup.hda2.20040225005922.exclude .
sendbackup-gnutar: time 0.802: /usr/local/amanda/libexec/runtar: pid 22032
sendbackup: time 0.805: started index creator: "/bin/tar -tf - 2>/dev/null | 
sed -e 's/^\.//'"
sendbackup: time 788.081: 124: strange(?): 
sendbackup: time 788.190: index tee cannot write [Broken pipe]
sendbackup: time 788.190: pid 22031 finish time Wed Feb 25 01:12:29 2004
sendbackup: time 788.192: 124: strange(?): gzip: stdout: Connection reset by 
peer

I ssuspect some sort of timeout.

Where should I start looking for this?

-- 
"They that would give up essential liberty for temporary safety deserve
neither liberty nor safety."
                                                -- Benjamin Franklin

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