One of multiple parallel IMAP connections to the server always fails. GetPassword failed
Categories
(MailNews Core :: Networking: IMAP, defect)
Tracking
(Not tracked)
People
(Reporter: Peiquee6Ahchier4, Unassigned)
References
Details
(Whiteboard: [dupme])
Attachments
(5 files)
image.png
|
||
Updated•9 years ago
|
|
|
||
Comment 1•8 years ago
|
||
|
|
||
Comment 2•7 years ago
|
||
|
|
||
Comment 4•7 years ago
|
||
|
|
||
Comment 6•4 years ago
|
||
Thunderbird tries to open multiple IMAP connections to the server in parallel, but exactly one of them always fails with the error message "IMAP: password prompt failed or user canceled it". Note that there is no password prompt dialog popping up. The effect is reproducible: The timing may change, especially concurrent threads may have different timing, but it seems that always exactly one of the parallel IMAP connections fails.
Don't we have another bug where responses were not reliably getting back to the correct request?
|
||
Comment 7•4 years ago
|
||
Don't we have another bug where responses were not reliably getting back to the correct request?
That doesn't ring a bell.
However, this does have something in common with bug 1690093 in that the log indicates that the user cancelled the login but that didn't actually occur. What happens in that bug is the URL has no "window" to display the password prompt since the server was never logged into before doing a copy to it. I don't think this bug is that because per the attached log, just a the normal startup connections are failing to login.
Another thing this reminds me of is the a problem with yahoo imap where the use had to reduce the number of cached connection from default 5 down to 3 because some server instances wouldn't accept more than 3 connections. The reporter here indicates they always see some failed connections. However, that shouldn't cause folder re-downloads.
If the reporter is still using tb and if the problem is still occurring, will probably need more info and a full IMAP:5 log attached.
These are the first ~6000 lines of a IMAP:5 log, now from Thunderbird 78.8.1.
The log still has this "IMAP: password prompt failed or user canceled it" and later many "failed creating protocol instance to play queued".
|
|
||
Comment 10•4 years ago
|
||
Reporter Snowflake, Thanks for the log. Yes, something doesn't look right. Can you tell me exactly what you were doing while recording the log? That may help in duplicating the problem. Also, other than the log errors, are you still seeing other problems that correlate to the logged errors?
I have an account on a local Dovecot server that I test with. When I connected to it I see 4 connections via STARTTLS and no problems after that, operationally or in the tb log. So I thought maybe somehow your Dovecot server might be limiting the number of connections from you IP address. So I changed my dovecot's mail_max_userip_connections from 10 down to 2 while keeping tb's number of cached connections (set in Server Settings->Advanced) at 5. I still don't see the type of errors your log shows. I do see explicit login errors and login prompts occur that I expect. But when I reduce the max number of cached connection at tb's server-settings/advance down to 2, the login problems go away.
Although it doesn't seem related to your problem, what do you have your dovecot's account cached connection in TB set to? Also, do you have access to internal dovecot settings or the dovecot log (dovecot log may also have a hint as to the problem).
|
Reporter | |
Comment 11•4 years ago
|
||
Thanks for looking into it.
When recording the log, I launched Thunderbird, waited until inbox updated, and then triggered "download/sync now" on some folders to stress the application a little bit.
I don't see other problems right now. In fact, compared to the time when I originally reported the problem, it "feels better" now: I don't have these constant re-downloading of folders all the time. (One speculation is that the connection/login problem still exists, but other changes in TB over time reduced the effect of that problem.)
In TB, the IMAP account has "Maximum number of server connections to cache" set to 5. I have full access to dovecot. Dovecot has: mail_max_userip_connections = 50. doveadm log errors doesn't show any errors for the time when I created the log. Syslog has:
Mar 20 09:44:20 xxxxxxxx dovecot: imap-login: Login: user=<xxxxxxxxxx>, method=PLAIN, rip=xxxxxxxx, lip=xxxxxxxx, mpid=6322, TLS, session=<xxxxxxxx>
Mar 20 09:44:21 xxxxxxxx dovecot: imap-login: Login: user=<xxxxxxxxxx>, method=PLAIN, rip=xxxxxxxx, lip=xxxxxxxx, mpid=6323, TLS, session=<xxxxxxxx>
Mar 20 09:44:26 xxxxxxxx dovecot: imap-login: Login: user=<xxxxxxxxxx>, method=PLAIN, rip=xxxxxxxx, lip=xxxxxxxx, mpid=6327, TLS, session=<xxxxxxxx>
Mar 20 09:44:26 xxxxxxxx dovecot: imap-login: Login: user=<xxxxxxxxxx>, method=PLAIN, rip=xxxxxxxx, lip=xxxxxxxx, mpid=6328, TLS, session=<xxxxxxxx>
Mar 20 09:44:26 xxxxxxxx dovecot: imap-login: Login: user=<xxxxxxxxxx>, method=PLAIN, rip=xxxxxxxx, lip=xxxxxxxx, mpid=6329, TLS, session=<xxxxxxxx>
Mar 20 09:51:14 xxxxxxxx dovecot: imap(xxxxxxxxxx): Logged out in=597 out=22297
Mar 20 09:51:14 xxxxxxxx dovecot: imap(xxxxxxxxxx): Logged out in=164029 out=77510647
Mar 20 09:51:14 xxxxxxxx dovecot: imap(xxxxxxxxxx): Logged out in=505543 out=178467251
Mar 20 09:51:14 xxxxxxxx dovecot: imap(xxxxxxxxxx): Logged out in=151875 out=168562661
Mar 20 09:51:14 xxxxxxxx dovecot: imap(xxxxxxxxxx): Logged out in=294112 out=3938884
Interestingly, assuming that "in=" and "out=" represents the number of received and sent bytes, the first connection has not much traffic. This may indicated that a connection is established, but TB is not really using it, which may align with the connection error in the TB log file.
|
|
||
Comment 12•4 years ago
|
||
When recording the log, I launched Thunderbird, waited until inbox updated, and then triggered "download/sync now" on some folders to stress the application a little bit.
Are you referring to the "Get Messages" button as "download/sync now"? Just want to be sure.
Looking at the log, it appears that 2 connection are trying to "select" inbox. Not sure why since there should only be one connection to the server's Inbox mailbox. Also, 2 connection are trying to do "folderstatus" on two different mailbox, one redacted and the other Entw%26APw-rfe. I'm not sure what the folderstatus does and I don't see it on my system at tb startup.
Maybe there is more than one account in the log?
Do you have tb setup to check for new mail in folders other than Inbox? By default, only Inbox is checked for new mail. That may explain the "folderstatus" occurrence.
Do you have any other non-standard settings with config editor? Typically new mail is checked by sending an imap no-op. However there is a config editor setting to change it. It is called mail.imap.use_status_for_biff. This defaults to true so not sure if it matters. How is yours set?
|
|
Reporter | |
Comment 13•4 years ago
|
||
No, I mean in the "File" menu the item "Offline", the sub item "Download/sync now". See the attached screenshot.
Yes, in fact there are two IMAP accounts involved. I had forgotten about that, sorry for that.
Fortunately it seems that you can distinguish them in the anonymized log:
The first IMAP account "378DF800" is to the dovecot server I have control over.
The second IMAP account "32612800" is to a commercial mail provider I don't have any control over.
Yes, I have multiple (but not all) folders enabled for being synched.
The "mail.imap.use_status_for_biff" has the default value, which is "true".
|
|
||
Comment 15•3 years ago
|
||
Look at it again today and still don't see anything the should cause a problem. I do see that the servers are using STARTTLS and the reporter says it's working better now. Don't know what version he's up to.
Looking at the attached log, it kind of does appear that there is a failure on the CAPABILITY response after a successful STARTTLS imap command. This may indicate a handshake error occurred during TLS negotiation but not possible to tell just from imap log; need something like wireshark to tell.
One thing to try might be to change the imap security setting on the problem account to SSL/TLS and the port to 993 and restart tb. If the server doesn't support it, no connection will happen and there will be an immediate failure, so go back to STARTTLS and port 143 and restart tb.
Or if the reporter has access to the openssl application, he can check TLS availability without changing tb setup with this:
openssl s_client -connect <server-name>:993 -crlf
If you see a lot of stuff scroll by and the last line is something like * OK IMAP4 ready it's working OK and can set tb to use TLS instead of STARTTLS.
This bug might be the same or related to this: Bug 1747733
|
|
Reporter | |
Comment 16•3 years ago
|
||
|
|
Reporter | |
Comment 17•3 years ago
|
||
Look at it again today and still don't see anything the should cause a problem. I do see that the servers are using STARTTLS and the reporter says it's working better now. Don't know what version he's up to.
I'm currently using Thunderbird 91.4.1 (32-bit).
Looking at the attached log, it kind of does appear that there is a failure on the CAPABILITY response after a successful STARTTLS imap command. This may indicate a handshake error occurred during TLS negotiation but not possible to tell just from imap log; need something like wireshark to tell.
I see the value of that approach, but so far I never used wireshark yet, and don't have it installed right now. Maybe there are easier options to try first?
One thing to try might be to change the imap security setting on the problem account to SSL/TLS and the port to 993 and restart tb. If the server doesn't support it, no connection will happen and there will be an immediate failure, so go back to STARTTLS and port 143 and restart tb.
When switching to SSL/TLS, I get the following error:
https://bug1282182.bmoattachments.org/attachment.cgi?id=9258001
Or if the reporter has access to the openssl application, he can check TLS availability without changing tb setup with this:
openssl s_client -connect <server-name>:993 -crlfIf you see a lot of stuff scroll by and the last line is something like * OK IMAP4 ready it's working OK and can set tb to use TLS instead of STARTTLS.
The output of openssl is the following:
xxxx:~$ openssl s_client -connect xxxxx:xxxxx -crlf
CONNECTED(00000003)
139668714632320:error:1408F10B:SSL routines:ssl3_get_record:wrong version number:../ssl/record/ssl3_record.c:332:
---
no peer certificate available
---
No client certificate CA names sent
---
SSL handshake has read 5 bytes and written 322 bytes
Verification: OK
---
New, (NONE), Cipher is (NONE)
Secure Renegotiation IS NOT supported
Compression: NONE
Expansion: NONE
No ALPN negotiated
Early data was not sent
Verify return code: 0 (ok)
---
xxxxx:~$
This bug might be the same or related to this: Bug 1747733
|
|
||
Comment 18•3 years ago
|
||
The output of openssl is the following: ...
I'm not an expert on the details of TLS, but I would think if your server supports STARTTLS over port 143 and allows connection to port 993 then it would also support pure TLS on port 993 and wouldn't complain about certificates. Does this check for STARTTLS work to the same server?
openssl s_client -starttls imap -crlf -connect <server name>:143
I run a dovecot server just for tb test purposes only on my home network and it listens on both port 143 and 993 and works with no security on port 143, STARTTLS on 143 and pure TLS on port 993. The certificate is just self signed.
FWIW, if I try to connect pure TLS to port 143 like this
openssl s_client -connect wally.dbnet.lan:143 -crlf
I get the same errors as you. But when I use port 993 it works OK, I can enter imap NOOP and the server responds:
openssl s_client -connect wally.dbnet.lan:993 -crlf
Also, be sure you are using the same full server name that TB is using which should be the same name as on the certificate. This may or may not be important, depending on your certificate setup; mine works with any name, even just the IP address in the openssl command.
|
|
Reporter | |
Comment 19•3 years ago
|
||
(In reply to gene smith from comment #18)
The output of openssl is the following: ...
I'm not an expert on the details of TLS, but I would think if your server supports STARTTLS over port 143 and allows connection to port 993 then it would also support pure TLS on port 993 and wouldn't complain about certificates. Does this check for STARTTLS work to the same server?
openssl s_client -starttls imap -crlf -connect <server name>:143
This works: It connects successfully and I can enter IMAP commands.
xxxxx@xxxxx:/tmp# openssl s_client -starttls imap -crlf -connect xxxxx:143
CONNECTED(00000003)
xxxxxxxxxx
...
xxxxxxxxxx
---
. OK Pre-login capabilities listed, post-login capabilities have more.
aaabbbccc
aaabbbccc BAD Error in IMAP command received by server.
* BAD Error in IMAP command received by server.
* BYE Too many invalid IMAP commands.
closed
xxxxx@xxxxx:/tmp#
I run a dovecot server just for tb test purposes only on my home network and it listens on both port 143 and 993 and works with no security on port 143, STARTTLS on 143 and pure TLS on port 993. The certificate is just self signed.
FWIW, if I try to connect pure TLS to port 143 like this
openssl s_client -connect wally.dbnet.lan:143 -crlfI get the same errors as you.
This still gives, as expected (after your explanations):
/tmp#
xxxxx@xxxxx:/tmp# openssl s_client -connect xxxxx:143 -crlf
CONNECTED(00000003)
xxxxxxxxxx
...
xxxxxxxxxx
---
no peer certificate available
---
No client certificate CA names sent
---
SSL handshake has read 5 bytes and written 176 bytes
Verification: OK
---
xxxxxxxxxx
...
xxxxxxxxxx
---
xxxxx@xxxxx:/tmp#
But when I use port 993 it works OK, I can enter imap NOOP and the server responds:
openssl s_client -connect wally.dbnet.lan:993 -crlf
This seems to work again:
xxxxx@xxxxx:/tmp# openssl s_client -connect xxxxx:993 -crlf
CONNECTED(00000003)
xxxxxxxxxx
...
xxxxxxxxxx
---
* OK [CAPABILITY IMAP4rev1 LITERAL+ SASL-IR LOGIN-REFERRALS ID ENABLE IDLE AUTH=PLAIN] Dovecot ready.
aaabbbccc
aaabbbccc BAD Error in IMAP command received by server.
* BAD Error in IMAP command received by server.
* BYE Too many invalid IMAP commands.
closed
xxxxx@xxxxx:/tmp#
Also, be sure you are using the same full server name that TB is using which should be the same name as on the certificate. This may or may not be important, depending on your certificate setup; mine works with any name, even just the IP address in the openssl command.
When configuring Thunderbird to use TSL over port 993, then the IMAP log seems to contain still the same errors as reported before, e.g.:
2022-01-13 XX:XX:XX.055000 UTC - [Parent 16860: IMAP]: E/IMAP IMAP: password prompt failed or user canceled it
2022-01-13 XX:XX:XX.055000 UTC - [Parent 16860: IMAP]: E/IMAP login failed entirely
This all together seems to indicate that SSL is not the problem, but there is an problem related to the IMAP password authentication?
|
|
||
Comment 20•3 years ago
•
|
||
I agree that it doesn't seem to be a tls problem when you see the same error with pure tls on port 993 too.
Looking at your original attached log and the pasted log in comment 0, it appears that something is happening to the 2nd dovecot connection before the login is attempted. It is wanting to do a folderstatus on your Entw%26APw-rfe folder (Drafts in mutf7 encoding). Not sure why a "folderstatus" URL is happening first but the log was recorded with tb 45 so maybe that was typical then. Maybe an updated log would help using your current version of tb.
A possible The best way to determine what is going on would be for you to provide me with a temporary test account on the same server. If that's possible you can send the credential via my bugzilla profile email address.
If that's not possible, could you record a new IMAP:5 log with accounts on non-problem servers disabled by un-setting "check for new mail on startup", "check for new mail every x minutes" and "immediate notification". Select Inbox on the problem dovecot account and shutdown tb and then restart tb with the env. vars set to record the log file as described here: https://wiki.mozilla.org/MailNews:Logging. Don't select any folders in the non-problem accounts while recording the log. Let tb come up selected on Inbox of the problem dovecot account. Then move to another folder (maybe Entw%26APw-rfe or whatever) until you see the error. If no errors seen, shutdown tb and try again until you record a log with the error.
If and when you attach the log, please described what you were doing while recording it.
It looks to me like either the server or tb is dropping the connection before the authentication even occurs. But it's not clear to me if you are seeing a prompt to enter the password or what the user-level indication of the problem is.
|
|
Reporter | |
Comment 21•3 years ago
|
||
A possibleThe best way to determine what is going on would be for you to provide me with a temporary test account on the same server. If that's possible you can send the credential via my bugzilla profile email address.
I will contact you.
|
|
||
Comment 22•3 years ago
|
||
I set up the test account and, so far, don't see a problem. I copied some old bugzilla messages into inbox to stress it some but doesn't seems to matter. I haven't seen the "login failed entirely" error, at least yet. How often does it happen for you and when does it happen? I can get 5 tb connections to 5 folders with no problem. So far I've only used STARTTLS on port 143. I've stopped and started TB several times, will try some more.
FWIW, I did have to "override" the certificate after I clicked "get mail".
|
|
Reporter | |
Comment 23•3 years ago
|
||
Well, I get these errors every time when enabling IMAP logging.
Maybe the difference is that I have a huge number of emails, and possibly more importantly, organized in nested folder down to four or five levels. The local email folder is 55 GB in 7600 files, which I think means 3800 Thunderbird email folders. (Don't worry, I'm not insane, not sorted in by hand, but using some server-side email sorting tool.)
Some longer time, ago, with an older Thunderbird version, when having more serious problems, I think I came to the conclusion at that time that the problems are related to the nesting depth, but I don't remember the details of how I came to this conclusion. I vaguely remember that my impression was that nested folders somehow trigger parallel recursive email fetch jobs, which cause trouble for deeper nesting.
|
|
||
Comment 24•3 years ago
|
||
Correct me if I'm wrong, but sounds like you are saying you see the error in the IMAP log but otherwise it doesn't cause any user problems?
Not sure about the "folder depth" theory.
Anyhow, I don't see it with your test account but I do see it when I try to copy a folder from my ISP account into your test account, but I see it on my normal ISP account, charter. The copy is usually not working either, so I'm looking at it right now.
If you can provide and updated IP address it would be good to keep testing with your account.
Thanks.
|
|
||
Comment 25•3 years ago
|
||
I think the problem is closely related to this: Bug 1690093 The problem is that tb refuses to fetch a stored password or pop-up a request for a password if the email command (a URL) has no "window" associated with it. This is to prevent unattended operations like mail filters or biff checks (checks for new mail on timed interval) from requesting a password entry and freezing up the system, I think.
I've tried a few things like I did in Bug 1690093 by passing in a "window" variable but so far it hasn't helped.
I did notice in your original log from tb 45 that the first URL that occurred was "folderstatus". Typically, the first URL is "select" which has a window unlike folderstatus. I'm wondering what causes folderstatus as first URL for you? Do you have local TB filters in addition to the "server side" filters you mention? Do you still still see "folderstatus" as the first URL in the log?
Probably an attached log would still be helpful, or at least just let me know if you see the "folderstatus" URL fairly early in the log.
|
|
Reporter | |
Comment 26•3 years ago
|
||
|
|
Reporter | |
Comment 27•3 years ago
|
||
Correct me if I'm wrong, but sounds like you are saying you see the error in the IMAP log but otherwise it doesn't cause any user problems?
Yes.
In older Thunderbird versions it felt much more serious (see https://bugzilla.mozilla.org/show_bug.cgi?id=1282182#c0) than now (see https://bugzilla.mozilla.org/show_bug.cgi?id=1282182#c11).
Not sure about the "folder depth" theory.
This was just speculation.
Anyhow, I don't see it with your test account but I do see it when I try to copy a folder from my ISP account into your test account, but I see it on my normal ISP account, charter. The copy is usually not working either, so I'm looking at it right now.
If you can provide and updated IP address it would be good to keep testing with your account.
Thanks.
I sent you a mail again.
I think the problem is closely related to this: Bug 1690093 The problem is that tb refuses to fetch a stored password or pop-up a request for a password if the email command (a URL) has no "window" associated with it. This is to prevent unattended operations like mail filters or biff checks (checks for new mail on timed interval) from requesting a password entry and freezing up the system, I think.
I've tried a few things like I did in Bug 1690093 by passing in a "window" variable but so far it hasn't helped.
I did notice in your original log from tb 45 that the first URL that occurred was "folderstatus". Typically, the first URL is "select" which has a window unlike folderstatus. I'm wondering what causes folderstatus as first URL for you? Do you have local TB filters in addition to the "server side" filters you mention?
The only addon I have installed is "CardBook".
Do you still still see "folderstatus" as the first URL in the log?
Probably an attached log would still be helpful, or at least just let me know if you see the "folderstatus" URL fairly early in the log.
Yes, I see "folderstatus" quite early.
See the redacted beginning of an IMAP log: https://bugzilla.mozilla.org/attachment.cgi?id=9259275
If you need more log, tell me.
|
|
Reporter | |
Comment 28•3 years ago
|
||
Sorry for messing up with https://bugzilla.mozilla.org/show_bug.cgi?id=1282182#c26, I had used the bugzilla attachment offer dialog in the wrong way.
|
|
||
Comment 29•3 years ago
|
||
The only addon I have installed is "CardBook".
Not familiar with CardBook but it sounds like it wouldn't have any effect on imap. You might try temporarily disabling it to see if the early "folderstatus" goes away.
The main usage for "folderstatus" is to check for new mail in non-Inbox folders. Maybe also autosync, not sure. I guess if it fails due to happening before the folder is selected it just happens later and no harm is done, at least in your case.
I mentioned tb filters that may trigger folderstatus. It's not an addon but the built-in feature to copy or move messages to a certain folder on receipt.
What I see is that if all the connections have timed out for an account (typically after about 30m inactivity) and a folder is right clicked and and copied or dragged to another account, there is a failure to copy due to the the failure of "folderstatus" to authenticate. Unlike what you see, this is not innocuous and causes a real failure (nothing gets copied).
I did finally find a possible fix to authenticate with a "windowless" url like we are seeing, i.e., "folderstatus". It only works if the user has stored a password but not if the user is set up to enter an account or master password at tb startup each time.
|
|
Reporter | |
Comment 30•3 years ago
|
||
The following is a IMAP log with CardBook disabled, therefore no extensions enabled at all. There's still an early "folterstatus":
2022-01-25 15:11:57.024000 UTC - [Parent 17068: IMAP]: D/IMAP ImapThreadMainLoop entering [this=1b169000]
2022-01-25 15:11:57.027000 UTC - [Parent 17068: IMAP]: D/IMAP ImapThreadMainLoop entering [this=23b05000]
2022-01-25 15:11:57.263000 UTC - [Parent 17068: IMAP]: D/IMAP ImapThreadMainLoop entering [this=24a89800]
2022-01-25 15:12:04.639000 UTC - [Parent 17068: IMAP]: D/IMAP ImapThreadMainLoop entering [this=25927800]
2022-01-25 15:12:04.641000 UTC - [Parent 17068: IMAP]: D/IMAP ImapThreadMainLoop entering [this=25928000]
2022-01-25 15:12:04.643000 UTC - [Parent 17068: IMAP]: D/IMAP ImapThreadMainLoop entering [this=25929000]
2022-01-25 15:12:05.561000 UTC - [Parent 17068: IMAP]: D/IMAP ImapThreadMainLoop entering [this=25933000]
2022-01-25 15:12:05.564000 UTC - [Parent 17068: IMAP]: D/IMAP ImapThreadMainLoop entering [this=2592d000]
2022-01-25 15:12:05.565000 UTC - [Parent 17068: IMAP]: D/IMAP ImapThreadMainLoop entering [this=2592a800]
2022-01-25 15:12:13.887000 UTC - [Parent 17068: Main Thread]: I/IMAP 1b169000:xxxxx:NA:SetupWithUrlCallback: clearing IMAP_CONNECTION_IS_OPEN
2022-01-25 15:12:13.888000 UTC - [Parent 17068: IMAP]: I/IMAP 1b169000:xxxxx:NA:ProcessCurrentURL: entering
2022-01-25 15:12:13.888000 UTC - [Parent 17068: IMAP]: I/IMAP 1b169000:xxxxx:NA:ProcessCurrentURL:imap://xxxxx@xxxxx:xxxxx/discoverallboxes: = currentUrl
2022-01-25 15:12:13.888000 UTC - [Parent 17068: Main Thread]: I/IMAP 23b05000:xxxxx:NA:SetupWithUrlCallback: clearing IMAP_CONNECTION_IS_OPEN
2022-01-25 15:12:13.888000 UTC - [Parent 17068: IMAP]: I/IMAP 23b05000:xxxxx:NA:ProcessCurrentURL: entering
2022-01-25 15:12:13.888000 UTC - [Parent 17068: IMAP]: I/IMAP 23b05000:xxxxx:NA:ProcessCurrentURL:imap://xxxxx@xxxxx:xxxxx/select%3E.INBOX: = currentUrl
2022-01-25 15:12:13.900000 UTC - [Parent 17068: Main Thread]: I/IMAP 24a89800:xxxxx:NA:SetupWithUrlCallback: clearing IMAP_CONNECTION_IS_OPEN
2022-01-25 15:12:13.901000 UTC - [Parent 17068: IMAP]: I/IMAP 24a89800:xxxxx:NA:ProcessCurrentURL: entering
2022-01-25 15:12:13.901000 UTC - [Parent 17068: IMAP]: I/IMAP 24a89800:xxxxx:NA:ProcessCurrentURL:imap://xxxxx@xxxxx:xxxxx/folderstatus%3E.xxxxx: = currentUrl
Is the "windowless authentication" issue a possible explanation for all reported errors? Meaning, the early "folderstatus" wouldn't cause any problems when having the fix of the "windowless authentication" issue you mentioned?
|
|
Reporter | |
Comment 31•3 years ago
|
||
I mean:
Even if you cannot reproduce the "login failed entirely" error:
Is the "windowless authentication" issue a possible explanation for the "login failed entirely" error?
Meaning, is there a possibility that your "possible fix" of the "windowless authentication" may also resolve the "login failed entirely" error?
|
|
||
Comment 32•3 years ago
|
||
Is the "windowless authentication" issue a possible explanation for the "login failed entirely" error?
Yes, I think it is.
Looking at the log fragment above, I assume this must be more than one account starting up because I see 9 entries into the "main loop" first. Typically a single account will only have 2 or 3 entries at startup.
Also, I do see the expected "discover folders" and "select" URLs and then the folder status on a separate connection, which is OK.
I asked before if you have other built-in activities enabled like filters for incoming messages which might be causing the initial "folder status".
Anyhow, I need to attach my proposed fix so I don't forget about it.
|
|
||
Comment 33•3 years ago
•
|
||
This diff attempts to get a window for url "folderstatus" but one was never associated with it, AFAICT. So those code changes should probably be removed from the patch.
This also has a change to obtain a stored password for a "windowless" url like folderstatus. This avoids aborting the login attempt as now occurs and you see in the log "login failed entirely", e.g., if folderstatus is the first URL.
So if the url doesn't have a window we no longer always abort the login. If a password is stored, we go ahead and use it instead of going into a function that potentially prompts for the password if one is not stored. With the new proposed method, if no password is stored there is still a login failure for windowless URLs.
In some cases the "login failed entirely" log line seems innocuous (as the reporter is seeing). In other cases it is not, like when copying a folder or messages to/from a currently disconnected imap account.
|
|
Reporter | |
Comment 34•3 years ago
|
||
(In reply to gene smith from comment #32)
Is the "windowless authentication" issue a possible explanation for the "login failed entirely" error?
Yes, I think it is.
Sounds promising!
So a plausible strategy may be simply to see if the problems go away with that fix.
Looking at the log fragment above, I assume this must be more than one account starting up because I see 9 entries into the "main loop" first. Typically a single account will only have 2 or 3 entries at startup.
Yes, there are multiple accounts involved.
Also, I do see the expected "discover folders" and "select" URLs and then the folder status on a separate connection, which is OK.
I asked before if you have other built-in activities enabled like filters for incoming messages which might be causing the initial "folder status".
I don't use filters, and I'm not aware of any other built-in activities.
Anyhow, I need to attach my proposed fix so I don't forget about it.
👍
|
|
||
Comment 35•3 years ago
•
|
||
I still see the error (only in the imap log) when a folderstatus is attempted on a newly created imap connection and there is no window open on the account. So I guess the proposed patch above is still relevant. No prompt for password occurred (it's stored) and no credentials were sent to the server.
D/IMAP Try to log in
D/IMAP IMAP auth: server caps 0x40042625, pref 0x1006, failed 0x0, avail caps 0x4
D/IMAP (GSSAPI = 0x1000000, CRAM = 0x20000, NTLM = 0x100000, MSN = 0x200000, PLAIN = 0x1000, LOGIN = 0x2, old-style IMAP login = 0x4, auth external IMAP login = 0x20000000, OAUTH2 = 0x800000000)
D/IMAP Trying auth method 0x4
E/IMAP IMAP: password prompt failed or user canceled it
E/IMAP login failed entirely
|
|
||
Comment 36•2 years ago
|
||
Snowflake,
I've never been able to duplicate what you see where "windowless" URL folderstatus occurs first. However another problem was reported where windowless URL ensureExists occurs first and hangs up Daily and possibly the current release 102.* (bug 1793599). I've been able to duplicate this URL occurring first and have a proposed fix. I don't know if you are using latest 102 version or Daily but, if you are, do you see a problem?
Thanks,
gene
|
|
Reporter | |
Comment 37•2 years ago
|
||
I'm using 102.3.2 (64-bit).
This should include fix for bug 1690093, but not fix for bug 1793599 yet, is this correct?
In the IMAP log, I don't see any "password prompt failed or user canceled it" error anymore.
And I also don't see any folderstatus entries at all. None. Is this possible? Or do I miss(configure) something?
Subjectively everything also seems to work well:
None of the problems reported in the original report.
In short, I don't see (IMAP log) or feel a problem with the above version.
|
|
||
Comment 38•2 years ago
|
||
(In reply to Snowflake from comment #37)
I'm using 102.3.2 (64-bit).
This should include fix for bug 1690093, but not fix for bug 1793599 yet, is this correct?
Yes, that's right. bug 1690093 is in 91. bug 1793599 is new and it's fix is not even in daily yet.
In the IMAP log, I don't see any "password prompt failed or user canceled it" error anymore.
And I also don't see any folderstatus entries at all. None. Is this possible? Or do I miss(configure) something?
I only know two condition the folderstatus occurs. It will occur on the timed interval for checking for new mail in Inbox and any other folder you have set to be checked for new mail. It should also occur in the background by "autosync" that scans through the folders and checks if anything needs to be downloaded into the local offline storage files. Autosync is also done on the same time base as checking for new mail but only occurs when tb goes from an active state to idle (no mouse/keyboard activity). So I would think you would see the folderstatus mentioned in the imap log but if your are already authenticated it shouldn't cause the problem of bug 1793599.
I'm also working a bug in autosync that cause the autosync process to stop, so it's possible that's why you don't see folderstatus.
What I see in your log fragment in comment 0 above would cause the problem in bug 1793599 since "windowless" URL folderstatus occur first. But looking at your later log fragment at comment 30 and comment 26, I see folderstatus occurring later, so if you see no folderstatus or see folderstatus like in comment 30 and 26 you are OK.
Subjectively everything also seems to work well:
None of the problems reported in the original report.In short, I don't see (IMAP log) or feel a problem with the above version.
Ok, good to know. Other than the reporter of bug 1793599 I haven't heard of any other problems. But your log sequence of comment 0 looked like it would cause a problem so I just thought I would ask you. Thanks a lot for the quick reply!
|
||
Updated•2 years ago
|
|
|
Reporter | |
Comment 39•2 years ago
|
||
So in order to see folderstatus entries, I have to run Thunderbird idle (no mouse/keyboard activity) for some time.
How long roughly?
Does it make sense to test longer idle times to get a folderstatus?
Or woudn't change this anything regarding potential bug analyzis anyway?
Or in short:
Anything I can do to help you guys right now?
|
|
||
Comment 40•2 years ago
|
||
If you are have marked any non-Inbox folders to be checked for new mail on the timed interval (with right-click context menu), you should see a folderstatus URL in the log at the check for new mail timed interval.
With autosync, the folderstatus for other "offline" folders should also occur on the same timed interval but only after you've been active in TB for a while and then go idle, and if you don't have offline storage for a folder you won't see it since it's not checked. However, there are some bugs in autosync that may cause it to not do folderstatus (see bug 1776823 and the attached PDF describing autosync).
Anything I can do to help you guys right now?
Not sure. But if you see anything wrong, go ahead and report it. Thanks!
|
|
Reporter | |
Comment 41•2 years ago
|
||
Where exactly can I find the setting for checking for new mail on a timed interval?
I dind't find something which looks like that when right-clicking a folder or when going to the properties of this folder.
I'm using version 102.3.3.
|
|
||
Comment 42•2 years ago
|
||
The timed interval defaults to 10 minutes. It is found by right-click on the account name, choose Settings, then choose "Server Settings" and in there you will see a "Check for new messages every X minutes" where the default for new account setups is 10 minutes.
By default, new messages are only checked for on Inbox. If you want another folder Y to be checked too on the same time interval, right-click Y, choose Properties and on the "General Information" page you select "When getting new messages for this account, always check this folder". Note that you won't see this when you look at Inbox properties since Inbox is always checked.
Every folder that is checked for new mail periodically will receive the imap "folderstatus" URL. This usually causes an imap STATUS if the folder isn't in imap SELECTed state. If it is SELECTed, the "folderstatus" will cause an imap NOOP.
You may also see folderstatus for other folders with offline store due to autosync as I mentioned before. But the above described folderstatus will be more regular and on the "check for new messages" time base and doesn't depend on TB going into "idle" state.
|
|
Reporter | |
Comment 43•2 years ago
|
||
Ok, I logged for about five hours, including idle times.
And indeed, now the log file contains various "folderstatus" requests, for example:
[Parent 18320: IMAP]: I/IMAP 169e4d22900:xxx:A:ProcessCurrentURL: entering
[Parent 18320: IMAP]: I/IMAP 169e4d22900:xxx:A:ProcessCurrentURL:imap://xxx@xxx:xxx/folderstatus%3E.xxx: = currentUrl
[Parent 18320: IMAP]: I/IMAP 169e4d22900:xxx:A:SendData: 4405 STATUS "xxx" (UIDNEXT MESSAGES UNSEEN RECENT)
[Parent 18320: IMAP]: D/IMAP ReadNextLine [rv=0x0 stream=169e9d0b700 nb=58 needmore=0]
[Parent 18320: IMAP]: I/IMAP 169e4d22900:xxx:A:CreateNewLineFromSocket: * STATUS xxx (MESSAGES 0 RECENT 0 UIDNEXT 1 UNSEEN 0)
[Parent 18320: IMAP]: D/IMAP SetConnectionStatus(0x0)
[Parent 18320: IMAP]: D/IMAP ReadNextLine [rv=0x0 stream=169e9d0b700 nb=48 needmore=0]
[Parent 18320: IMAP]: I/IMAP 169e4d22900:xxx:A:CreateNewLineFromSocket: 4405 OK Status completed (0.000 + 0.000 secs).
[Parent 18320: IMAP]: D/IMAP SetConnectionStatus(0x0)
[Parent 18320: Main Thread]: D/IMAP proposed url = xxx.xxx folder for connection INBOX has To Wait = false can run = false
[Parent 18320: Main Thread]: I/IMAP 169e4d22900:xxx:A:SetupSinkProxy: got m_imapMailFolderSink
These "folderstatus" look to me.
And more importantly, I still don't see any "login failed" or "password prompt failed" in the whole log file anymore.
So I suggest to close this ticket as being fixed successfully.
Thanks to all of you for your excellent work, both regarding this issue specifically and Thunderbird in general!
|
|
Reporter | |
Comment 44•2 years ago
|
||
These "folderstatus" look to me.
-> ... look good to me
|
|
||
Comment 45•2 years ago
•
|
||
Ok, thanks for verifying that it is OK now. I'm sure you saw an issue before but I'm not sure what fixed it since I wasn't able to duplicate exactly what you saw. I didn't submit a patch that was formally approved for this bug, so I can't mark it resolved as FIXED. Also, I don't want to say it is INVALID and I don't think it is an exact DUPLICATE of another bug (but maybe closely related to ones in the "See Also" link above). So I'll just close it as WORKSFORME since I have to pick something.
Thanks again!
|
|
Reporter | |
Comment 46•2 years ago
|
||
Well, I would attribute the fix (at least partially) to your "windowless authentication" fix, which was a good idea in any case.
Description
•