Ray Van Dolson wrote:
> On Wed, Jul 25, 2007 at 07:35:58PM -0400, Ugo Bellavance wrote:
>> Ugo Bellavance wrote:
>>> Brett Schroeder wrote:
>>>> Ugo Bellavance wrote:
>>>>> Hi,
>>>>>
>>>>> I installed sendmail on a centos-4 openvz VM. I set up SMTP-AUTH
>>>>> and when I try to send mail using this server, there is a big delay in
>>>>> which my e-mail client (Mozilla Thunderbird) just hangs. The server, on
>>>>> the other hand, is idle at the same time. It does that no matter if I
>>>>> use no encryption, TLS, or SSL. When the client is 'hung' sendmail, on
>>>>> the server side haven't logged anything yet for this connection.
>>>>>
>>>>> Any idea?
>>>> Since nothing is logged on the server, it sounds like there is a
>>>> firewall (or
>>>> other networking problem) in the way. You should use WireShark (or
>>>> tcpdump) on
>>>> the client to capture the network traffic.
>> I disabled the firewall on the server, no luck. I tried sniffing, I see
>> nothing weird.
>>
>> 5.512292 74.59.221.180 -> 72.55.149.51 TCP 17274 > submission [PSH,
>> ACK] Seq=350 Ack=10923 Win=17461 Len=53
>> 5.512984 72.55.149.51 -> 74.59.221.180 TCP submission > 17274 [PSH,
>> ACK] Seq=10923 Ack=403 Win=7504 Len=277
>> 5.724172 74.59.221.180 -> 72.55.149.51 TCP 17274 > submission [ACK]
>> Seq=403 Ack=11200 Win=17184 Len=0
>> 22.884013 74.59.221.180 -> 72.55.149.51 TCP 17274 > submission [PSH,
>> ACK] Seq=403 Ack=11200 Win=17184 Len=53
>> 22.884918 72.55.149.51 -> 74.59.221.180 TCP submission > 17274 [PSH,
>> ACK] Seq=11200 Ack=456 Win=7504 Len=85
>> 22.970714 74.59.221.180 -> 72.55.149.51 TLSv1 Application Data
>> 22.971120 72.55.149.51 -> 74.59.221.180 TLSv1 Application Data
>>
>
> Can you run strace on sendmail during a connection and see what it's
> doing? DNS is often the culprit when delays are concerned, so look for
> anything along those lines.
>
> Ray
Here is an interesting part, but I can't tell why it took 2.292863
seconds to do that:
09:07:47 time(NULL) = 1185455267 <0.000007>
09:07:47 rt_sigprocmask(SIG_UNBLOCK, [ALRM], [ALRM], 8) = 0 <0.000008>
09:07:47 select(8, [4 5 6 7], NULL, NULL, {5, 0}) = 1 (in [6], left {2,
707000}) <2.292863>
09:07:49 accept(6, {sa_family=AF_INET, sin_port=htons(25919),
sin_addr=inet_addr("74.59.221.180")}, [16]) = 9 <0.000023>
09:07:49 rt_sigprocmask(SIG_BLOCK, [ALRM], [], 8) = 0 <0.000010>
09:07:49 time(NULL) = 1185455269 <0.000007>
09:07:49 pipe([10, 11]) = 0 <0.000021>
09:07:49 rt_sigprocmask(SIG_BLOCK, [CHLD], [ALRM], 8) = 0 <0.000008>
09:07:49 clone(Process 16312 attached
Some operations are unfinished like this one:
[pid 31853] 09:07:49 select(8, [4 5 6 7], NULL, NULL, {5, 0} <unfinished
...>
There is a 5-second gap here (from one PID to the other, weird):
[pid 16312] 09:07:49 time(NULL) = 1185455269 <0.000010>
[pid 16312] 09:07:49 read(9, 0x8968260, 5) = -1 EAGAIN (Resource
temporarily unavailable) <0.000012>
[pid 16312] 09:07:49 time(NULL) = 1185455269 <0.000009>
[pid 16312] 09:07:49 select(10, [9], NULL, [9], {3600, 0} <unfinished ...>
[pid 31853] 09:07:54 <... select resumed> ) = 0 (Timeout) <4.999631>
[pid 31853] 09:07:54 rt_sigprocmask(SIG_BLOCK, [ALRM], [], 8) = 0 <0.000008>
[pid 31853] 09:07:54 time(NULL) = 1185455274 <0.000008>
[pid 31853] 09:07:54 open("/proc/loadavg", O_RDONLY) = 9 <0.000037>
[pid 31853] 09:07:54 fstat64(9, {st_mode=S_IFREG|0444, st_size=0, ...})
= 0 <0.000008>
[pid 31853] 09:07:54 read(9, "0.01 0.02 0.00 3/49 16395\n", 1024) = 26
<0.000015>
[pid 31853] 09:07:54 close(9) = 0 <0.000013>
[pid 31853] 09:07:54 time(NULL) = 1185455274 <0.000007>
[pid 31853] 09:07:54 open("/proc/loadavg", O_RDONLY) = 9 <0.000015>