538397 - sending mail slow (due to outgoing mail scanner of anti-virus/personal firewall software)

Status: RESOLVED INVALID

(MailNews Core :: Networking: SMTP, defect)

Description

[seamon2]

User-Agent:       Mozilla/5.0 (Windows; U; Windows NT 5.1; de; rv:1.9.1.7) Gecko/20100104 SeaMonkey/2.0.2
Build Identifier: Mozilla/5.0 (Windows; U; Windows NT 5.1; de; rv:1.9.1.7) Gecko/20100104 SeaMonkey/2.0.2

Sending mail with Seamonkey 2.x or Thunderbird 3 is much slower then with SM 1.x or TB 2.x. 
The progress bar is filled 2-4 times before the mail is sent (2-4 seconds). With SM1.x or TB2.x this took far less then 1 second.

I created a smtp-logfile, but could not detect any errors (see below)
set NSPR_LOG_MODULES=smtp:5
set NSPR_LOG_FILE=c:\temp\smtp.log

Reproducible: Always




0[1724140]: SMTP Connecting to: smtp.example.de
0[1724140]: SMTP entering state: 0
0[1724140]: SMTP Response: 220 smtp.example.de ESMTP Sendmail 8.14.3/8.14.3/Debian-5; Thu, 7 Jan 2010 18:02:11 +0100; (No UCE/UBE) logging access from: client.example.de(OK)-client.example.de [10.1.1.4]
0[1724140]: SMTP entering state: 14
0[1724140]: SMTP Send: EHLO [10.1.1.4]

0[1724140]: SMTP entering state: 0
0[1724140]: SMTP Response: 250-smtp.example.de Hello client.example.de [10.1.1.4], pleased to meet you
0[1724140]: SMTP entering state: 0
0[1724140]: SMTP Response: 250-ENHANCEDSTATUSCODES
0[1724140]: SMTP entering state: 0
0[1724140]: SMTP Response: 250-PIPELINING
0[1724140]: SMTP entering state: 0
0[1724140]: SMTP Response: 250-EXPN
0[1724140]: SMTP entering state: 0
0[1724140]: SMTP Response: 250-VERB
0[1724140]: SMTP entering state: 0
0[1724140]: SMTP Response: 250-8BITMIME
0[1724140]: SMTP entering state: 0
0[1724140]: SMTP Response: 250-SIZE 50000000
0[1724140]: SMTP entering state: 0
0[1724140]: SMTP Response: 250-DSN
0[1724140]: SMTP entering state: 0
0[1724140]: SMTP Response: 250-ETRN
0[1724140]: SMTP entering state: 0
0[1724140]: SMTP Response: 250-STARTTLS
0[1724140]: SMTP entering state: 0
0[1724140]: SMTP Response: 250-DELIVERBY
0[1724140]: SMTP entering state: 0
0[1724140]: SMTP Response: 250 HELP
0[1724140]: SMTP entering state: 4
0[1724140]: SMTP entering state: 21
0[1724140]: SMTP entering state: 3
0[1724140]: SMTP Send: MAIL FROM:<[e-mail]> SIZE=861

0[1724140]: SMTP entering state: 0
0[1724140]: SMTP Response: 250 2.1.0 <[e-mail]>... Sender ok
0[1724140]: SMTP entering state: 5
0[1724140]: SMTP Send: RCPT TO:<[e-mail]>

0[1724140]: SMTP entering state: 0
0[1724140]: SMTP Response: 250 2.1.5 <[e-mail]>... Recipient ok
0[1724140]: SMTP entering state: 6
0[1724140]: SMTP Send: DATA

0[1724140]: SMTP entering state: 0
0[1724140]: SMTP Response: 354 Enter mail, end with "." on a line by itself
0[1724140]: SMTP entering state: 7
0[1724140]: SMTP entering state: 8
0[1724140]: SMTP Send: .

0[1724140]: SMTP entering state: 0
0[1724140]: SMTP Response: 250 2.0.0 o07H2BNl008443 Message accepted for delivery
0[1724140]: SMTP entering state: 9
0[1724140]: SMTP Send: QUIT

0[1724140]: SMTP entering state: 0
0[1724140]: SMTP entering state: 0
0[1724140]: SMTP Response: 221 2.0.0 smtp.example.de closing connection
0[1724140]: SMTP entering state: 10
0[1724140]: SMTP entering state: 12

Comment 1

[seamon2]

I found that it's the Windows-Firewall, which slows down the sending prozess.
2-5 seconds between:
0[1724140]: SMTP Connecting to: smtp.example.de
0[1724140]: SMTP entering state: 0
Defining a Firewall-exception for seamonkey.exe or port 25 does not help, but disabling the firewall does.
This did not occur with SM 1.18.
OS is XP SP3.

Comment 2

[Serge Gautherie (:sgautherie)]

Some wrong with the firewall itself?

Comment 3

[WADA:World Anti-bad-Duping Agency]

(In reply to comment #1)
> 2-5 seconds between:
> 0[1724140]: SMTP Connecting to: smtp.example.de
> 0[1724140]: SMTP entering state: 0

Timestamp of SMTP log will help your diagnosis.
> https://wiki.mozilla.org/MailNews:Logging
> http://www.mozilla.org/projects/nspr/reference/html/prlog.html#25328
> SET NSPR_LOG_MODULES=timestamp,smtp:5
Log for DNS Lookup may help too. 
> http://www.mozilla.org/projects/netlib/http/http-debugging.html
> SET NSPR_LOG_MODULES=timestamp,smtp:5,,nsHostResolver:5
If slowness of each send is suspected, get socket level log.
> SET NSPR_LOG_MODULES=timestamp,smtp:5,,nsHostResolver:5,nsSocketTransport:5

Long DNS lookup time is sometimes caused by IPv6 support. If so, next change may be a solution.
> network.dns.disableIPv6 : false => true
If you use Firefx 3.x, it may be affected by DNS prefetch of Fx, because Fx accesses DNS server many times than usual by the option.

Mail sending roughly consists of;
 1. Create mail data in temp directory
 2. Pass mail data to SMTP server
 3. Write copy of mail data to Sent folder
As Bug 539389 exists, 1. & 3. of Tb3 is slower than Tb2.
Get Process Monitor log for read/write/re-write of mail data by Tb.
> http://technet.microsoft.com/en-us/sysinternals/bb545027.aspx
> Filter : Process Name is thunderbird.exe, Include
>          Path contains \Temp\, Include            (for temp file)
>          Path contains \Unsent Messages, Include  (for Send Later case)
>          Path contains \Sent, Include             (for Sent folder)
Is file/io wihout bufffering one of causes of slowness in your environment?

Comment 4

[seamon2]

(In reply to comment #3)

> Timestamp of SMTP log will help your diagnosis.
...
> If slowness of each send is suspected, get socket level log.
> > SET NSPR_LOG_MODULES=timestamp,smtp:5,,nsHostResolver:5,nsSocketTransport:5
> Long DNS lookup time is sometimes caused by IPv6 support. If so, next change
> may be a solution.
> > network.dns.disableIPv6 : false => true
> If you use Firefx 3.x, it may be affected by DNS prefetch of Fx, because Fx
> accesses DNS server many times than usual by the option.
> 
> Mail sending roughly consists of;
>  1. Create mail data in temp directory
>  2. Pass mail data to SMTP server
>  3. Write copy of mail data to Sent folder
> As Bug 539389 exists, 1. & 3. of Tb3 is slower than Tb2.
> Get Process Monitor log for read/write/re-write of mail data by Tb.
> Is file/io wihout bufffering one of causes of slowness in your environment?

Disabled IPv6-support, no change.
Wrote a logfile with timestamps and nsSocketTransport:5, but could'nt find any errors (see below)
Problem exists, regardless of a copy the message is written to the sent-folder or not.
File i/o should not be the problem here.
We're using Seamonkey 2.0.x, and "Sending mail slow" is definitely related to the Windows-XP-Firewall. 
This did not occure with Seamonkey 1.1.x.
If the firewall is disabled, sending is fast.

extract of logfile:


2010-02-08 12:32:39.605000 UTC - 0[1727140]: SMTP Connecting to: mail
2010-02-08 12:32:39.605000 UTC - 0[1727140]: creating nsSocketTransport @5616040
2010-02-08 12:32:39.605000 UTC - 0[1727140]: nsSocketTransport::Init [this=5616040 host=mail:25 proxy=:0]
2010-02-08 12:32:39.605000 UTC - 0[1727140]: nsSocketTransport::PostEvent [this=5616040 type=3 status=0 param=0]
2010-02-08 12:32:39.605000 UTC - 0[1727140]: STS dispatch [5d7fb80]
2010-02-08 12:32:39.605000 UTC - 280[17273c0]:     ...returned after 130 milliseconds
2010-02-08 12:32:39.605000 UTC - 280[17273c0]: nsSocketTransport::OnSocketEvent [this=5616040 type=3 status=0 param=0]
2010-02-08 12:32:39.605000 UTC - 280[17273c0]:   MSG_TIMEOUT_CHANGED
...
2010-02-08 12:32:39.605000 UTC - 280[17273c0]: STS dispatch [5d7fbc0]
2010-02-08 12:32:39.615000 UTC - 280[17273c0]:   advancing to STATE_RESOLVING
2010-02-08 12:32:39.615000 UTC - 280[17273c0]: STS poll iter [0]
2010-02-08 12:32:39.615000 UTC - 280[17273c0]:   active [0] { handler=246cac0 condition=0 pollflags=5 }
...
2010-02-08 12:32:39.615000 UTC - 280[17273c0]: nsSocketTransport::OnSocketReady [this=5616040 outFlags=2]
2010-02-08 12:32:39.645000 UTC - 280[17273c0]:   advancing to STATE_TRANSFERRING
2010-02-08 12:32:39.645000 UTC - 280[17273c0]: nsSocketTransport::SendStatus [this=5616040 status=804b0004]
2010-02-08 12:32:39.645000 UTC - 280[17273c0]: STS poll iter [1]
2010-02-08 12:32:39.645000 UTC - 280[17273c0]:   active [1] { handler=5616040 condition=0 pollflags=7 }
2010-02-08 12:32:39.645000 UTC - 280[17273c0]:   active [0] { handler=246cac0 condition=0 pollflags=5 }
2010-02-08 12:32:39.645000 UTC - 280[17273c0]:   calling PR_Poll [active=2 idle=0]
2010-02-08 12:32:39.645000 UTC - 280[17273c0]: poll timeout: 100
2010-02-08 12:32:39.645000 UTC - 280[17273c0]:     timeout = 100000 milliseconds
2010-02-08 12:32:39.645000 UTC - 280[17273c0]:     ...returned after 0 milliseconds
2010-02-08 12:32:39.645000 UTC - 280[17273c0]: nsSocketTransport::OnSocketReady [this=5616040 outFlags=2]
2010-02-08 12:32:39.645000 UTC - 280[17273c0]: nsSocketOutputStream::OnSocketReady [this=56160f8 cond=0]
2010-02-08 12:32:39.645000 UTC - 280[17273c0]: STS poll iter [1]
2010-02-08 12:32:39.645000 UTC - 280[17273c0]:   active [1] { handler=5616040 condition=0 pollflags=5 }
2010-02-08 12:32:39.645000 UTC - 280[17273c0]:   active [0] { handler=246cac0 condition=0 pollflags=5 }
2010-02-08 12:32:39.645000 UTC - 280[17273c0]:   calling PR_Poll [active=2 idle=0]
2010-02-08 12:32:39.645000 UTC - 280[17273c0]: poll timeout: 100
2010-02-08 12:32:39.645000 UTC - 280[17273c0]:     timeout = 100000 milliseconds
2010-02-08 12:32:44.632000 UTC - 280[17273c0]:     ...returned after 4988 milliseconds
2010-02-08 12:32:44.632000 UTC - 280[17273c0]: nsSocketTransport::OnSocketReady [this=5616040 outFlags=1]
2010-02-08 12:32:44.632000 UTC - 280[17273c0]: nsSocketInputStream::OnSocketReady [this=56160d8 cond=0]
2010-02-08 12:32:44.632000 UTC - 280[17273c0]: STS dispatch [5d873c8]
2010-02-08 12:32:44.632000 UTC - 280[17273c0]: nsSocketInputStream::Read [this=56160d8 count=4096]
2010-02-08 12:32:44.632000 UTC - 280[17273c0]:   calling PR_Read [count=4096]
2010-02-08 12:32:44.632000 UTC - 280[17273c0]:   PR_Read returned [n=184]
2010-02-08 12:32:44.632000 UTC - 280[17273c0]: nsSocketTransport::SendStatus [this=5616040 status=804b0006]
2010-02-08 12:32:44.632000 UTC - 280[17273c0]: nsSocketInputStream::Read [this=56160d8 count=3912]
2010-02-08 12:32:44.632000 UTC - 280[17273c0]:   calling PR_Read [count=3912]
2010-02-08 12:32:44.632000 UTC - 280[17273c0]:   PR_Read returned [n=-1]
2010-02-08 12:32:44.632000 UTC - 0[1727140]: nsSocketTransport::PostEvent [this=5616040 type=3 status=0 param=0]
2010-02-08 12:32:44.632000 UTC - 0[1727140]: STS dispatch [34bf1c0]
2010-02-08 12:32:44.632000 UTC - 0[1727140]: SMTP entering state: 0

Comment 5

[WADA:World Anti-bad-Duping Agency]

(In reply to comment #4)

[e-mail], (1) Please don't paste long log data. Attach log file to this bug if required, please.
(2) As you saw, nsSocketTransport:5 generates very many log lines. Get log with timestamp,smtp:5 first, and see SMTP level flow first, please.
"Get log for small mail send" may help your first level diagnosis. 
(3) If long DNS lookup time is suspected(long time between "SMTP Connecting to:" and SMTP-AUTH==login followed by EHLO usually), get log with nsHostResolver:5 added.
In your case, it looks around 5sec as you said. So nsHostResolver:5 will help our problem analysis.
(4) If time between first mail data and last "end of mail data"(.[CR][LF] followed by OK response if normal) is longer than expectation, get log with firewall=off, and compare time for mail sending using timestam value of log.
(5) If apparant difference of "times to send" is observed between firewall=on and firewall=off cases, get log with nsSocketTransport:5 added. And compare each response time of a socket level call, please.

Comment 6

[seamon2]

(In reply to comment #5)
Wada, for you again a short logfile. I posted the long one to show that there are no time-problems in DNS-lookup or nsSocketTransport. 
I think the Windows firewall ist to blame, but SM-Users might be annoyed.
XP SP3  Gecko/20100205 SeaMonkey/2.0.3 
Firewall enabled:
2010-02-11 11:31:43.153000 UTC - 0[1727140]: SMTP Connecting to: mail
2010-02-11 11:31:48.250000 UTC - 0[1727140]: SMTP entering state: 0
...
2010-02-11 11:31:48.450000 UTC - 0[1727140]: SMTP Response: 250 2.0.0 o1BBVmpN019558 Message accepted for delivery

Firewall disabled:
2010-02-11 11:56:04.714000 UTC - 0[1727140]: SMTP Connecting to: mail
2010-02-11 11:56:04.824000 UTC - 0[1727140]: SMTP entering state: 0
...
2010-02-11 11:56:04.955000 UTC - 0[1727140]: SMTP Response: 250 2.0.0 o1BBu4gJ026410 Message accepted for delivery

Comment 7

[Wayne Mery (:wsmwk)]

seamon2, are you still of the opinion that windows firewall caused your issue?  

This isn't cited on https://wiki.mozilla.org/Thunderbird:Testing:Antivirus_Related_Performance_Issues#Problem_Antivirus_Packages and http://kb.mozillazine.org/Firewalls#Windows_Firewall indicates outbound activity should not be impacted on XP  (unless I read that incorrectly) and I don't think we've seen recent reports of this.

Comment 8

[seamon2]

Yes, just checked again with Seamonkey 2.0.10, still the same behavior as described above. 
Also tried again the advices of http://kb.mozillazine.org/Firewalls#Windows_Firewall. Those are related to XP SP2, we use Seamonkey on about 80 Workstations XP SP3.

Comment 9

[Wayne Mery (:wsmwk)]

seamon2, there something you think mailnews should be doing differently if firewall is causing this issue?

Comment 10

[Joshua Cranmer [:jcranmer]]

RESOLVED INCOMPLETE due to lack of response to last question. If you feel this change was made in error, please respond to this bug with your reasons why.

Comment 11

[seamon2]

Just checked again using SM 2.6.1 on Windows XP SP3: Still the same behavior. An active Windows(built-in)-Firewall slows down sending mail.

Comment 12

[Wayne Mery (:wsmwk)]

invalid bafeed on comment 6