Closed Bug 575915 Opened 14 years ago Closed 13 years ago

pop3 not getting email after first download (perdition 1.17.1 is used for POP3S proxy)

Categories

(MailNews Core :: Networking: POP, defect)

1.9.2 Branch
x86_64
Linux
defect
Not set
major

Tracking

(Not tracked)

RESOLVED INVALID

People

(Reporter: marco.morandini, Unassigned)

Details

Attachments

(9 files)

User-Agent:       Mozilla/5.0 (X11; U; Linux i686 (x86_64); en-US; rv:1.9.2.6) Gecko/20100625 Firefox/3.6.6
Build Identifier: Mozilla/5.0 (X11; U; Linux i686 (x86_64); en-US; rv:1.9.2.4) Gecko/20100608 Lightning/1.0b2 Thunderbird/3.1

After upgrading from 3.0.5 to 3.1 I have to shut down and restart thunderbird in order to be able to get emails. Account settings:
pop3
connection security SSL/TLS
port 995
auth method normal password
check for new messages at startup
check for new messages every 1 minutes
automatically download new messages


Reproducible: Always

Steps to Reproduce:
1. start thunderbird and download new messages
2. send a new message to myself
3. try to download the new message: nothing happens (while, checking with webmail, the message is there, ready to be downloaded)
4. shutdown and restart thunderbird: the message is downloaded succesfully
Actual Results:  
New messages are not downloaded

Expected Results:  
New messages get downloaded

I've tried with -safe-mode without success.
I'll attach a log obtained with NSPR_LOG_MODULES=pop3:5
Component: General → Networking: POP
Product: Thunderbird → MailNews Core
QA Contact: general → networking.pop
Version: unspecified → 1.9.2 Branch
(In reply to comment #0)
> check for new messages at startup
> check for new messages every 1 minutes

Can you check with both settings disabled? (no need of log)
1. Restart Tb, 2. Send mail to you, 3. GetMsgs, 4. Send mail to you, 5. GetMsgs.
(time between step 3 and step 5 : check with 5 minutes or longer, please.)

Does your POP3 server support connection without SSL/TLS(port 110 usually)? If yes, can you check with Connection Security: None?
Cnfirming per POP3 log.
Status: UNCONFIRMED → NEW
Ever confirmed: true
> Can you check with both settings disabled? (no need of log)

I've done the following:

disabled settings
restarted thunderbird
sent mail
getMsg -> thunderbird asks for passwd, connects and download msg
sent mail
wain 20 minutes
sent mail
gemMsg -> thunderbird says "no messages to download"


> Does your POP3 server support connection without SSL/TLS(port 110 usually)? 

No.
I've also re-created the thunderbird account, without noticing any improvement

> If yes, can you check with Connection Security: None?

If you need it I can try with a different account that I usually read only using webmail. But,
as I've neved used pop3 with them, I will not be able to confirm a regression from thunderbird 3.0.
(In reply to comment #4)
> disabled settings
> restarted thunderbird
> sent mail, getMsg -> thunderbird asks for passwd, connects and download msg

Do you disable "Save Password" for the POP3 user?

> sent mail, wait 20 minutes, sent mail
> gemMsg -> thunderbird says "no messages to download"

"No messages to download" is usually shown after successful login and successful LIST/UIDL command. (as DELE is issued, you disable "Leave Messages on server").

Can you get POP3 log with timestamp for above two manual Get Msgs opertions?
> https://wiki.mozilla.org/MailNews:Logging
> NSPR_LOG_MODULES=timestamp,pop3:5
> 3 to 5 minutes is sufficient for checking, I think. 

> > Does your POP3 server support connection without SSL/TLS(port 110 usually)? 
> No.

No need to check with other account. It's to see difference of behaviour of the POP3 server between SSL/TLS and None.
> > sent mail, getMsg -> thunderbird asks for passwd, connects and download msg
> 
> Do you disable "Save Password" for the POP3 user?
> 

No completely sure to understand what you mean here
because I do not see any option
for storing passwd in the pop3 account setting window.
But I can confirm that I do not use a master password
(preferences->security->passwords), and that I usually
re-type my passwd each and every time I start thunderbird.
But I've never had to retype it again, after the first time, 
with a running thunderbird.

I've checked the config, filtering for "pass".
Everything is default, only pref.privacy.disable_button.view_passwords 
is user_set to false.
I've tried to reset it, restarted thunderbird. I'm still
not being asked for passwd on the second get mail, and I'm still not able
to get the mail the second time. Re-checking the config I see that
pref.privacy.disable_button.view_passwords is again  user set to false.
Don't know what this means, or if this can be of any help.

> "No messages to download" is usually shown after successful login and
> successful LIST/UIDL command. (as DELE is issued, you disable "Leave Messages
> on server").

Yes, i never leave messages on server.

> 
> Can you get POP3 log with timestamp for above two manual Get Msgs opertions?

Attached, same steps of comment #4 (obtained playing with pref.privacy.disable_button.view_passwords)
> Attached, same steps of comment #4 (obtained playing with
> pref.privacy.disable_button.view_passwords)

Sorry, obtained _not_ playing with pref.privacy.disable_button.view_passwords!
(In reply to comment #7)
> NSPR_LOG_MODULES=timestamp,pop3:5

Same log as your first attached log. After first successful login/LIST/UIDL/RETR/DELE/QUIT, next attempts of login is not invoked because of error status.
 after

Log after QUIT.
> 2010-07-02 10:05:14.863011 UTC - -163928224[f6110060]: Clearing server busy in OnStopRequest
deliver mode: 0

Next looks something wrong after SSL session clearing.
> 2010-07-02 10:05:30.155066 UTC - -163928224[f6110060]: Calling ReleaseFolderLock from ~nsPop3Sink
> 2010-07-02 10:05:30.155153 UTC - -163928224[f6110060]: ReleaseFolderLock haveSemaphore = FALSE
deliver mode: 0

Next looks log for second "Get Msgs", and it looks somehow failed.
> 2010-07-02 10:13:05.221774 UTC - -163928224[f6110060]: Setting server busy in nsPop3Protocol::LoadUrl
2010-07-02 10:13:05.232755 UTC - -163928224[f6110060]: Entering NET_ProcessPop3 0
> 2010-07-02 10:13:05.232809 UTC - -163928224[f6110060]: POP3: Entering state: 24
> 2010-07-02 10:13:05.232821 UTC - -163928224[f6110060]: POP3: Entering state: 25

See next document for POP3 state:, please.
> http://kb.mozillazine.org/Session_logging_for_mail/news
>   0	READ_PASSWORD 
>   24  ERROR_DONE
>   25	FREE

> > Do you disable "Save Password" for the POP3 user?
> No completely sure to understand what you mean here because I do not see
> any option for storing passwd in the pop3 account setting window.

I talked about checkbox of "Save password or not" at password prompt dialog.
Does your problem occur even if password is saved at password dialog?
> I talked about checkbox of "Save password or not" at password prompt dialog.
> Does your problem occur even if password is saved at password dialog?

No such checkbox here - see passwd_prompt1.png
(In reply to comment #10)
> > I talked about checkbox of "Save password or not" at password prompt dialog.
> > Does your problem occur even if password is saved at password dialog?
> 
> No such checkbox here - see passwd_prompt1.png

Found it, sorry. First, I created a brand new profile. 
There is a save passwd when the initial account is set.
Then, with this new profile, the passwd prompt has the checkbox. Unfortunately,
even checking it (so that restating thunderbird I do not have to re-type the passwd) 
the problem remains: the first download works, subsequent ones no.

One additional information. My email is morandini@aero.polimi.it, while my username on the pop3 server (mail.aero.polimi.it) is morandin . I don't think this could make any difference, but who knows.
(In reply to comment #12)
> One additional information. My email is morandini@aero.polimi.it, while my
> username on the pop3 server (mail.aero.polimi.it) is morandin .

It's not problem. Password manager uses hostname+userName in prefs.js as key of Password Manager's DB. POP3 uses realhostname(if non-existent, use hostname) and realuserName(if non-existent, user userName) for login.
I recently changed mail-address(and UserID too) of a POP3 account. So next happened, but no problem occurrs.
  hostname=realhostname=pop3.x.y.z
  userName=abc@x.y.z, realuserName=def@x.y.z
  Password Manager entry is still pop3.x.y.z + abc@x.y.z.

I simply tried to rule out phenomenon by next issue.
  Once login failed with wrong password and Tb remebers wrong password,
  login with new/correct password is imposible until restart of Tb,
  if POP3 server violates RFC(kill connection after a login error).
Such issue has been found irrelevant to your problem. 

> Then, with this new profile, the passwd prompt has the checkbox.
> Unfortunately, even checking it (so that restating thunderbird
> I do not have to re-type the passwd) 
> the problem remains: the first download works, subsequent ones no.

Even connection to POP3 server is not executed(POP3 log say so), was "no messages to download" shown at status bar upon second Get Mails?

(First Get Mails)
> 2010-07-02 10:05:07.718091 UTC - -163928224[f6110060]: Setting server busy in nsPop3Protocol::LoadUrl
> 2010-07-02 10:05:07.799428 UTC - -163928224[f6110060]: Entering NET_ProcessPop3 32
> 2010-07-02 10:05:07.799473 UTC - -163928224[f6110060]: POP3: Entering state: 1
> 2010-07-02 10:05:07.799484 UTC - -163928224[f6110060]: POP3: Entering state: 2
> 2010-07-02 10:05:07.799493 UTC - -163928224[f6110060]: POP3: Entering state: 4
> 2010-07-02 10:05:07.799509 UTC - -163928224[f6110060]: RECV: +OK POP3 Ready spmsrv 0001d06d
> 2010-07-02 10:05:07.799523 UTC - -163928224[f6110060]: POP3: Entering state: 26

(Second Get Mails)
> 2010-07-02 10:13:05.221774 UTC - -163928224[f6110060]: Setting server busy in nsPop3Protocol::LoadUrl
> 2010-07-02 10:13:05.232755 UTC - -163928224[f6110060]: Entering NET_ProcessPop3 0
> 2010-07-02 10:13:05.232809 UTC - -163928224[f6110060]: POP3: Entering state: 24
> 2010-07-02 10:13:05.232821 UTC - -163928224[f6110060]: POP3: Entering state: 25
> 2010-07-02 10:13:05.232832 UTC - -163928224[f6110060]: Clearing server busy in POP3_FREE

Greeting is not logged(nn in "NET_ProcessPop3 nn" looks data length passed to Tb) for second Get Mails. It may be connection error(rejection etc.)

Can you get DNS lookup log/Socket log too?
> https://wiki.mozilla.org/MailNews:Logging
> https://developer.mozilla.org/en/HTTP_Logging
> SET NSPR_LOG_MODULES=timestamp,pop3:5,nsSocketTransport:5,nsHostResolver:5
(In reply to comment #13)
> > Then, with this new profile, the passwd prompt has the checkbox.
> > Unfortunately, even checking it (so that restating thunderbird
> > I do not have to re-type the passwd) 
> > the problem remains: the first download works, subsequent ones no.
> 
> Even connection to POP3 server is not executed(POP3 log say so), was "no
> messages to download" shown at status bar upon second Get Mails?

Yes.

> Greeting is not logged(nn in "NET_ProcessPop3 nn" looks data length passed to
> Tb) for second Get Mails. It may be connection error(rejection etc.)

I'm going to look with our sysadm to the pop3 logs 
(I think it's a courier mail server, debian). Let me know if
you think we can find some useful info there and/or if you
know what we should look for.

> Can you get DNS lookup log/Socket log too?

Attached. Obtained with my default profile:

-start thunderbird
-send mail
-get mail (->passwd prompt, ok, mail received)
-immediately send mail
-wait approx 5 minutes and send a third mail
-get mail (->no messages to donwload)
-quit thunderbird
From Tb's view, it looks "no greeting from server within a reasonable time, or connection loss upon second Get Mails". However, something funny after first QUIT is seen, and, after error upon the second Get Mails, Tb3.1 issues "no messages to download" even though login to server is not done when second Get Mails. It indicates that something wrong exists in Tb 3.1.

(1) Can you check Tb3.1 behaviour with next? (no log is neede, if it works)
    Work Offline then Work Online, before second Get Msgs. (It should work...) 
(2) Can you check server side log?
    Is Tb3.1's behaviour upon second Get Mails correct?
(3) Can you compare log(pop3/socket/host resolver) of Tb 3.1(fails) with log of Tb 3.0.x(no error)?
Socket log is merely log for send/receive at socket level, so it's hard to know what data is sent/received. But it's useful to guess Tb's behaviour if POP3 log is obtained at same time, and is useful to know when Tb detects error.
Comparison of "logs after first QUIT" and "logs around second Get Mails" may provide valuable data for problem analysis.
Attached file log going offline
> Can you check Tb3.1 behaviour with next? (no log is neede, if it works)
> Work Offline then Work Online, before second Get Msgs. (It should work...) 

Not working, NSPR_LOG_MODULES=timestamp,pop3:5,nsSocketTransport:5,nsHostResolver:5

-start thunderbird
-send &get msg
-send msg
-go offline (toggle file->offlline->workoffline) & wait few minutes
-go online (toggle file->offlline->workoffline) & get msg (->no messages to donwload)
-quit
Some help/info from our sysadm.

1) our standard access point is a pop3/imap proxy: perdition, from debian lenny. 

2) the error on the server side, corresponding to the attached thunderbird log, is only.
I have nothing more.

Jul  5 16:00:40 spmsrv perdition[30082]: Connect:
131.175.154.10->xxx.xxx.xxx.xxx
Jul  5 16:00:40 spmsrv perdition[30082]: Fatal error establishing SSL
connection to client

3) if my sysadm relaxes the firewall rules and allows me to bypass the proxy and to access
    directly the real mail server then everything works.

At this point I don't know where the bug is: perdition or thunderbird. It's however clear that there is a bug somewhere. I still think that thunderbird should be able to re-authenticate itself.

Hope this helps.
Obtained using the pop3 proxy, i.e. the same settings that fail with thunderbird 3.1.
I've not waited 5 minutes between the subsequent gets.
Quick comparison of Tb 3.0.5 and Tb 3.1.
(Problem-1) SSL negotiation looks to always fail upon second Get Mails
            in your environment, due to ErrorAccordingToNSPR.
            Example of ErrorAccordingToNSPR:
               Retry count of TCP retransmission exceeded limit.
               No Ack for packets can produce this kind of error.
            Due to proxy?
            SSL clean up error after previous QUIT?
(Problem-2) Tb 3.1 doesn't retry when Problem-1 happens.
(Problem-3) Tb 3.1 wrongly considers the error as "no new mail at POP3 server".

(1) Following error occurs upon second Get Mails.
    (log by Tb 3.1. same log by Tb 3.0. poling log is omitted)

> 2010-07-05 07:25:23.677578 UTC - -175113360[f6110690]: ErrorAccordingToNSPR [in=-5961 out=804b0014]
> 2010-07-05 07:25:23.677590 UTC - -175113360[f6110690]: nsSocketTransport::OnMsgInputClosed [this=ed70f2f0 reason=804b0014]
> 2010-07-05 07:25:23.677602 UTC - -175113360[f6110690]: nsSocketInputStream::CloseWithStatus [this=ed70f3d0 reason=0]
> 2010-07-05 07:25:23.677615 UTC - -175113360[f6110690]: nsSocketInputStream::CloseWithStatus [this=ed70f3d0 reason=80470002]
> 2010-07-05 07:25:23.677677 UTC - -175113360[f6110690]: nsSocketTransportService::DetachSocket [handler=ed70f2f0]
> 2010-07-05 07:25:23.677689 UTC - -175113360[f6110690]: nsSocketTransport::OnSocketDetached [this=ed70f2f0 cond=804b0014]
> 2010-07-05 07:25:23.677701 UTC - -175113360[f6110690]: nsSocketTransport::RecoverFromError [this=ed70f2f0 state=4 cond=804b0014]
> 2010-07-05 07:25:23.677713 UTC - -175113360[f6110690]: nsSocketInputStream::OnSocketReady [this=ed70f3d0 cond=804b0014]
> 2010-07-05 07:25:23.677726 UTC - -175113360[f6110690]: nsSocketOutputStream::OnSocketReady [this=ed70f3f0 cond=804b0014]
> 2010-07-05 07:25:23.677754 UTC - -175113360[f6110690]: nsSocketTransport: calling PR_Close [this=ed70f2f0]
> 2010-07-05 07:25:23.677915 UTC - -175113360[f6110690]: nsSocketTransportService::RemoveFromPollList [handler=0]
> 2010-07-05 07:25:23.678053 UTC - -175113360[f6110690]: nsSocketOutputStream::AsyncWait [this=ed70f3f0]
> 2010-07-05 07:25:23.679658 UTC - -163670176[f6110060]: nsSocketTransport::PostEvent [this=ed70f2f0 type=3 status=0 param=0]
> 2010-07-05 07:25:23.679733 UTC - -175113360[f6110690]: nsSocketTransport::OnSocketEvent [this=ed70f2f0 type=3 status=0 param=0]
> 2010-07-05 07:25:23.679746 UTC - -175113360[f6110690]:   blocking event [condition=804b0014]
> 2010-07-05 07:25:23.679758 UTC - -175113360[f6110690]: nsSocketInputStream::OnSocketReady [this=ed70f3d0 cond=804b0014]
> 2010-07-05 07:25:23.679771 UTC - -175113360[f6110690]: nsSocketOutputStream::OnSocketReady [this=ed70f3f0 cond=804b0014]
> 2010-07-05 07:25:23.679866 UTC - -175113360[f6110690]: nsSocketOutputStream::AsyncWait [this=ed70f3f0]
> 2010-07-05 07:25:23.680274 UTC - -175113360[f6110690]: nsSocketOutputStream::CloseWithStatus [this=ed70f3f0 reason=0]
> 2010-07-05 07:25:23.680288 UTC - -175113360[f6110690]: nsSocketOutputStream::CloseWithStatus [this=ed70f3f0 reason=80470002]
> 2010-07-05 07:25:23.680451 UTC - -163670176[f6110060]: nsSocketInputStream::CloseWithStatus [this=ed70f3d0 reason=804b0002]
> 2010-07-05 07:25:23.680490 UTC - -163670176[f6110060]: nsSocketOutputStream::CloseWithStatus [this=ed70f3f0 reason=804b0002]
> 2010-07-05 07:25:23.680504 UTC - -163670176[f6110060]: destroying nsSocketTransport @ed70f2f0


(2-A) Tb 3.0.5. 

(2-A-1) Redrives connection.

> 2010-07-05 14:38:31.504849 UTC - -164251808[f6110060]: creating nsSocketTransport @daa7f410
> 2010-07-05 14:38:31.504951 UTC - -164251808[f6110060]: nsSocketTransport::Init [this=daa7f410 host=mail.aero.polimi.it:995 proxy=:0]
> 2010-07-05 14:38:31.504987 UTC - -164251808[f6110060]: nsSocketTransport::PostEvent [this=daa7f410 type=3 status=0 param=0]
> 2010-07-05 14:38:31.505081 UTC - -186651792[f6110a00]: nsSocketTransport::OnSocketEvent [this=daa7f410 type=3 status=0 param=0]

(2-A-2) Finaly, connection is established.
 
> 2010-07-05 14:38:31.555433 UTC - -164251808[f6110060]: Entering NET_ProcessPop3 32
> 2010-07-05 14:38:31.555450 UTC - -164251808[f6110060]: POP3: Entering state: 1
> 2010-07-05 14:38:31.555466 UTC - -164251808[f6110060]: POP3: Entering state: 2
> 2010-07-05 14:38:31.555480 UTC - -164251808[f6110060]: POP3: Entering state: 4
> 2010-07-05 14:38:31.555503 UTC - -164251808[f6110060]: RECV: +OK POP3 Ready spmsrv 0001d06d
> 2010-07-05 14:38:31.555533 UTC - -164251808[f6110060]: POP3: Entering state: 28


(2-B) Tb 3.1 doesn't enter retrying. Stops connecting.

> 2010-07-05 07:25:23.680530 UTC - -163670176[f6110060]: Entering NET_ProcessPop3 0
> 2010-07-05 07:25:23.680542 UTC - -163670176[f6110060]: POP3: Entering state: 24
> 2010-07-05 07:25:23.680554 UTC - -163670176[f6110060]: POP3: Entering state: 25
(For Problem-1)
ErrorAccordingToNSPR look for me being produced by existence of your proxy, as it occurs always upon next connection request after previous QUIT.
(For Problem-2)
I don't know retry should be executed or shouldn't be executed in this bug's case. I guess infinite retry loop can happen if retry is executed.
See bug 566548 comment #14 for log of ErrorAccordingToNSPR. (bug 566548 is no ack case)
(In reply to comment #22)
> Abug found by Google search for "perdition ssl".
> > http://us.generation-nt.com/bug-561885-perdition-ssl-port-993-995-connections-dont-timeout-help-168953511.html
> perdition releases. Which release do you use?

1.17.1

btw, crawling bugzilla for the changes from 1.3 to 1.31 I've noticed https://bugzilla.mozilla.org/show_bug.cgi?id=525238 where the auth code was changed (hope this is not noise)
Does problem depend on POP3 server? Problem occurs with any POP3S server?
Can you check with Gmail's POP3 server using perdition 1.17.1 and Tb 3.1?
> http://mail.google.com/support/bin/answer.py?answer=86399
> Gmail's POP3 supports(requests) SSL.

Can you test with newer perdition 1.18 shipped on 27th November 2009 shortly?
(In reply to comment #17)
> log going offline
> 
> > Can you check Tb3.1 behaviour with next? (no log is neede, if it works)
> > Work Offline then Work Online, before second Get Msgs. (It should work...) 
> Not working,

Even after Offline/Online(socket is re-initialized by Tb. same behavior as Tb 3.0.5 after error), ErrorAccordingToNSPR happens.
It indicates next;
 - garbage at proxy remains after QUIT
 - upon error of ErrorAccordingToNSPR, garbage is cleared
 - after it, if socket is re-initialized by Tb(Tb 3.0.5 does do it),
   proxy can handle SSL request normally, as first request after restart of Tb.
Can you check next? (no log is needed, even if error occurs)
 1. Resart Tb
 2. Send mail, first Get Mails => OK, QUIT
 3. Send mail
 4. Work Offline, Work Online, second Get Mails=>ErrorAccordingToNSPR=>fails
 5. Work Offline, Work Online, third Get Mails => ???
(In reply to comment #25)
>Does problem depend on POP3 server? Problem occurs with any POP3S server?
as noted on comment #18, point 3), if I access directly the real pop3s server, bypassing the proxy,
then everything works.

>Can you check with Gmail's POP3 server using perdition 1.17.1 and Tb 3.1?
>Can you test with newer perdition 1.18 shipped on 27th November 2009 shortly?
I'm building right now perdition 1.17.1 and 1.18 on my pc (no hope to test using our real mail proxy), will let you know if I succeed installing them and setting them up.
(In reply to comment #26)
>  5. Work Offline, Work Online, third Get Mails => ???
=> fails
Summary: pop3 not getting email after first download → pop3 not getting email after first download (perdition 1.17.1 is used for POP3S proxy)
How about next? (Emulation of Tb 3.0's behaviour)
1. Restart Tb, first Get Mails, LIST/UIDL/QUIT => garbage probably remains.
2. Second Get Mails, tries to connect using SAME sockect as step 1 => Error
3. Emulation of re-drive of connection process of Tb 3.0.x. 
   Work Offline, Work Online, third Get Mails => ???
(In reply to comment #29)
> How about next? (Emulation of Tb 3.0's behaviour)
> 1. Restart Tb, first Get Mails, LIST/UIDL/QUIT => garbage probably remains.
> 2. Second Get Mails, tries to connect using SAME sockect as step 1 => Error
> 3. Emulation of re-drive of connection process of Tb 3.0.x. 
>    Work Offline, Work Online, third Get Mails => ???

=> fails, log attached
> I'm building right now perdition 1.17.1 and 1.18 on my pc (no hope to test
> using our real mail proxy), will let you know if I succeed installing them and
> setting them up.

I've asked for help on the perdition mailing list:
http://lists.vergenet.net/pipermail/perdition-users/2010-July/002329.html
Still no success for me in intalling perdition, but
a second user has the same problem, and was able to verify that it occurs
even with the latest perdition versions, 1.18.
See http://lists.vergenet.net/pipermail/perdition-users/2010-July/002336.html
for details and perdition logs.
I believe that the following patch resolves things on the perdition side of things
and I'm not entirely sure that there is anything to be done on the Thunderbird side,
though thats not my call.

At this stage I am intending to include this patch in perdition 1.19-rc3.
Testing and review would be gratefully received.
Works with new Perdition.
Status: NEW → RESOLVED
Closed: 13 years ago
Resolution: --- → INVALID
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: