Amanda-Users

Re: timeout waiting for ACK for our REP

2008-04-23 18:55:58
Subject: Re: timeout waiting for ACK for our REP
From: Jean-Louis Martineau <martineau AT zmanda DOT com>
To: Fran Fabrizio <fran AT cis.uab DOT edu>
Date: Wed, 23 Apr 2008 18:04:22 -0400
Good, your client works as expected.
Do you upgraded something else on the server? or just amanda?
Do the server receive the PREP and REP packet, look in amdump.1 log file.
Disable all firewall on the client and server.
On the 2.5.2 client, add 'debug_auth 1' in /etc/amanda/amanda-client.conf
Use tcpdump on the client and server and watch the packet.

Jean-Louis

Jean-Louis

Fran Fabrizio wrote:

I have my etimeout set to 3600...
$ amgetconf CIS etimeout
3600

Since migrating my server from 2.4.5p1 to 2.5.0p2 I consistently receive the following errors:

olympus.cis.uab.edu /shared/home lev 0 FAILED [disk /shared/home, all estimate timed out] zimbra.cis.uab.edu /etc lev 0 FAILED [disk /etc, all estimate timed out] zimbra.cis.uab.edu /opt/zimbra/backup lev 0 FAILED [disk /opt/zimbra/backup, all estimate timed out]

I looked at the sendsize logs on olympus and zimbra from last night to see how long their estimates were taking, and found that Olympus took 2862 seconds and Zimbra took 863 seconds. So, the estimates completed on time, but the server never received the results. I looked at amandad*debug files, and saw this on Zimbra:

[SNIP]
amandad: time 14.991: sending ACK pkt:
<<<<<
>>>>>
amandad: time 15.003: sending REP pkt:
<<<<<
OPTIONS features=fffffeff9ffeffff07;
>>>>>
amandad: time 15.012: received ACK pkt:
<<<<<
>>>>>
amandad: time 15.013: accept recv REQ pkt:
<<<<<
SERVICE sendsize
OPTIONS features=fffffeff9ffeffff07;maxdumps=1;hostname=zimbra.cis.uab.edu;
GNUTAR /etc  0 1970:1:1:0:0:0 -1  OPTIONS |;auth=BSD;compress-fast;index;
GNUTAR /etc 1 2008:4:18:10:44:21 -1 OPTIONS |;auth=BSD;compress-fast;index; GNUTAR /opt/zimbra/backup 0 1970:1:1:0:0:0 -1 OPTIONS |;auth=BSD;compress-fast;index; GNUTAR /opt/zimbra/backup 1 2008:4:20:7:50:9 -1 OPTIONS |;auth=BSD;compress-fast;index; GNUTAR /opt/zimbra/backup 2 2008:4:21:8:7:29 -1 OPTIONS |;auth=BSD;compress-fast;index;
>>>>>
amandad: time 15.013: creating new service: /usr/lib64/amanda/sendsize
OPTIONS features=fffffeff9ffeffff07;maxdumps=1;hostname=zimbra.cis.uab.edu;
GNUTAR /etc  0 1970:1:1:0:0:0 -1  OPTIONS |;auth=BSD;compress-fast;index;
GNUTAR /etc 1 2008:4:18:10:44:21 -1 OPTIONS |;auth=BSD;compress-fast;index; GNUTAR /opt/zimbra/backup 0 1970:1:1:0:0:0 -1 OPTIONS |;auth=BSD;compress-fast;index; GNUTAR /opt/zimbra/backup 1 2008:4:20:7:50:9 -1 OPTIONS |;auth=BSD;compress-fast;index; GNUTAR /opt/zimbra/backup 2 2008:4:21:8:7:29 -1 OPTIONS |;auth=BSD;compress-fast;index;

amandad: time 15.014: sending ACK pkt:
<<<<<
>>>>>
amandad: time 15.037: sending PREP pkt:
<<<<<
OPTIONS features=fffffeff9ffeffff07;
>>>>>
amandad: time 772.303: sending PREP pkt:
<<<<<
OPTIONS features=fffffeff9ffeffff07;
/opt/zimbra/backup 0 SIZE 88848410
>>>>>
amandad: time 847.114: sending PREP pkt:
<<<<<
OPTIONS features=fffffeff9ffeffff07;
/opt/zimbra/backup 0 SIZE 88848410
/opt/zimbra/backup 1 SIZE 381010
>>>>>
amandad: time 877.217: sending PREP pkt:
<<<<<
OPTIONS features=fffffeff9ffeffff07;
/opt/zimbra/backup 0 SIZE 88848410
/opt/zimbra/backup 1 SIZE 381010
/opt/zimbra/backup 2 SIZE 358270
>>>>>
amandad: time 877.875: sending PREP pkt:
<<<<<
OPTIONS features=fffffeff9ffeffff07;
/opt/zimbra/backup 0 SIZE 88848410
/opt/zimbra/backup 1 SIZE 381010
/opt/zimbra/backup 2 SIZE 358270
/etc 0 SIZE 93230
>>>>>
amandad: time 877.894: sending PREP pkt:
<<<<<
OPTIONS features=fffffeff9ffeffff07;
/opt/zimbra/backup 0 SIZE 88848410
/opt/zimbra/backup 1 SIZE 381010
/opt/zimbra/backup 2 SIZE 358270
/etc 0 SIZE 93230
/etc 1 SIZE 240
>>>>>
amandad: time 877.894: sending REP pkt:
<<<<<
OPTIONS features=fffffeff9ffeffff07;
/opt/zimbra/backup 0 SIZE 88848410
/opt/zimbra/backup 1 SIZE 381010
/opt/zimbra/backup 2 SIZE 358270
/etc 0 SIZE 93230
/etc 1 SIZE 240
>>>>>
amandad: time 887.895: timeout
amandad: time 887.895: sending REP pkt:
<<<<<
OPTIONS features=fffffeff9ffeffff07;
/opt/zimbra/backup 0 SIZE 88848410
/opt/zimbra/backup 1 SIZE 381010
/opt/zimbra/backup 2 SIZE 358270
/etc 0 SIZE 93230
/etc 1 SIZE 240
>>>>>
amandad: time 897.894: timeout
amandad: time 897.894: sending REP pkt:
<<<<<
OPTIONS features=fffffeff9ffeffff07;
/opt/zimbra/backup 0 SIZE 88848410
/opt/zimbra/backup 1 SIZE 381010
/opt/zimbra/backup 2 SIZE 358270
/etc 0 SIZE 93230
/etc 1 SIZE 240
>>>>>
amandad: time 907.895: timeout
amandad: time 907.895: sending REP pkt:
<<<<<
OPTIONS features=fffffeff9ffeffff07;
/opt/zimbra/backup 0 SIZE 88848410
/opt/zimbra/backup 1 SIZE 381010
/opt/zimbra/backup 2 SIZE 358270
/etc 0 SIZE 93230
/etc 1 SIZE 240
>>>>>
amandad: time 917.894: timeout
amandad: time 917.895: sending REP pkt:
<<<<<
OPTIONS features=fffffeff9ffeffff07;
/opt/zimbra/backup 0 SIZE 88848410
/opt/zimbra/backup 1 SIZE 381010
/opt/zimbra/backup 2 SIZE 358270
/etc 0 SIZE 93230
/etc 1 SIZE 240
>>>>>
amandad: time 927.896: timeout
amandad: time 927.896: timeout waiting for ACK for our REP
amandad: time 929.896: pid 8487 finish time Wed Apr 23 02:15:30 2008

So it's trying to send the estimate results to the server but not getting an ACK for the REP pkt. I see similar messages on Olympus. Zimbra is 2.5.0p2 client and Olympus is 2.5.2 client. Any thoughts on why Zimbra can exchange earlier ACK/REP/REQ packets with the server but not later when it tries to send in results?



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