1727971 - "Rate limit hit" error from Yahoo IMAP server

Status: RESOLVED WORKSFORME

(MailNews Core :: Networking: IMAP, defect)

Description

[Ray Satiro]

User Agent: Mozilla/5.0 (Windows NT 6.1; Win64; x64; rv:90.0) Gecko/20100101 Firefox/90.0

Steps to reproduce:

Since upgrading to 91 I've been seeing lots of drop outs connecting to yahoo imap. According to the debug log the server says "BYE IMAP4rev1 Server logging out" followed by "NO [LIMIT] CAPABILITY Rate limit hit."

Actual results:

2021-08-28 07:10:58.461000 UTC - [Parent 54380: Main Thread]: I/IMAP retrying  url:imap://[e-mail]@imap.mail.yahoo.com:993/select>/Bulk Mail
2021-08-28 07:10:58.461000 UTC - [Parent 54380: IMAP]: D/IMAP ImapThreadMainLoop entering [this=1f92c000]
2021-08-28 07:10:58.461000 UTC - [Parent 54380: IMAP]: D/IMAP ImapThreadMainLoop leaving [this=23e15000]
2021-08-28 07:10:58.461000 UTC - [Parent 54380: Main Thread]: I/IMAP 1f92c000:imap.mail.yahoo.com:NA:SetupWithUrlCallback: clearing IMAP_CONNECTION_IS_OPEN
2021-08-28 07:10:58.461000 UTC - [Parent 54380: IMAP]: I/IMAP 1f92c000:imap.mail.yahoo.com:NA:ProcessCurrentURL: entering
2021-08-28 07:10:58.461000 UTC - [Parent 54380: IMAP]: I/IMAP 1f92c000:imap.mail.yahoo.com:NA:ProcessCurrentURL:imap://[e-mail]:993/select%3E/Bulk%20Mail:  = currentUrl
2021-08-28 07:10:58.570000 UTC - [Parent 54380: IMAP]: D/IMAP ReadNextLine [rv=0x0 stream=1747c160 nb=174 needmore=0]
2021-08-28 07:10:58.570000 UTC - [Parent 54380: IMAP]: I/IMAP 1f92c000:imap.mail.yahoo.com:NA:CreateNewLineFromSocket: * OK [CAPABILITY IMAP4rev1 SASL-IR AUTH=PLAIN AUTH=XOAUTH2 AUTH=OAUTHBEARER ID MOVE NAMESPACE XYMHIGHESTMODSEQ UIDPLUS LITERAL+ CHILDREN X-MSG-EXT OBJECTID] IMAP4rev1 Hello

2021-08-28 07:10:58.570000 UTC - [Parent 54380: IMAP]: D/IMAP SetConnectionStatus(0x0)
2021-08-28 07:10:58.570000 UTC - [Parent 54380: IMAP]: D/IMAP SetConnectionStatus(0x0)
2021-08-28 07:10:58.571000 UTC - [Parent 54380: IMAP]: D/IMAP Try to log in
2021-08-28 07:10:58.571000 UTC - [Parent 54380: IMAP]: D/IMAP IMAP auth: server caps 0x840007625, pref 0x800000000, failed 0x0, avail caps 0x800000000
2021-08-28 07:10:58.571000 UTC - [Parent 54380: IMAP]: 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)
2021-08-28 07:10:58.571000 UTC - [Parent 54380: IMAP]: D/IMAP Trying auth method 0x800000000
2021-08-28 07:10:58.571000 UTC - [Parent 54380: IMAP]: D/IMAP IMAP: trying auth method 0x800000000
2021-08-28 07:10:58.571000 UTC - [Parent 54380: IMAP]: D/IMAP XOAUTH2 auth
2021-08-28 07:10:58.737000 UTC - [Parent 54380: IMAP]: I/IMAP 1f92c000:imap.mail.yahoo.com:NA:SendData: Logging suppressed for this command (it probably contained authentication information)
2021-08-28 07:10:59.505000 UTC - [Parent 54380: IMAP]: D/IMAP ReadNextLine [rv=0x0 stream=1747c160 nb=29 needmore=0]
2021-08-28 07:10:59.505000 UTC - [Parent 54380: IMAP]: I/IMAP 1f92c000:imap.mail.yahoo.com:NA:CreateNewLineFromSocket: 3 OK AUTHENTICATE completed

2021-08-28 07:10:59.505000 UTC - [Parent 54380: IMAP]: D/IMAP SetConnectionStatus(0x0)
2021-08-28 07:10:59.505000 UTC - [Parent 54380: IMAP]: D/IMAP login succeeded
2021-08-28 07:10:59.505000 UTC - [Parent 54380: IMAP]: I/IMAP 1f92c000:imap.mail.yahoo.com:A:SendData: 4 capability

2021-08-28 07:11:03.641000 UTC - [Parent 54380: IMAP]: D/IMAP ReadNextLine [rv=0x0 stream=1747c160 nb=36 needmore=0]
2021-08-28 07:11:03.641000 UTC - [Parent 54380: IMAP]: I/IMAP 1f92c000:imap.mail.yahoo.com:A:CreateNewLineFromSocket: * BYE IMAP4rev1 Server logging out

2021-08-28 07:11:03.641000 UTC - [Parent 54380: IMAP]: D/IMAP SetConnectionStatus(0x0)
2021-08-28 07:11:03.641000 UTC - [Parent 54380: IMAP]: I/IMAP 1f92c000:imap.mail.yahoo.com:NA:SendData: 5 ID ("name" "Thunderbird" "version" "91.0.3")

2021-08-28 07:11:03.641000 UTC - [Parent 54380: IMAP]: D/IMAP ReadNextLine [rv=0x0 stream=1747c160 nb=41 needmore=0]
2021-08-28 07:11:03.641000 UTC - [Parent 54380: IMAP]: I/IMAP 1f92c000:imap.mail.yahoo.com:NA:CreateNewLineFromSocket: 4 NO [LIMIT] CAPABILITY Rate limit hit.

2021-08-28 07:11:03.641000 UTC - [Parent 54380: IMAP]: D/IMAP SetConnectionStatus(0x0)
2021-08-28 07:11:03.641000 UTC - [Parent 54380: IMAP]: I/IMAP 1f92c000:imap.mail.yahoo.com:NA:SendData: 6 select "Bulk Mail"

2021-08-28 07:11:03.641000 UTC - [Parent 54380: IMAP]: D/IMAP ReadNextLine [rv=0x80470002 stream=1747c160 nb=0 needmore=0]
2021-08-28 07:11:03.655000 UTC - [Parent 54380: IMAP]: I/IMAP 1f92c000:imap.mail.yahoo.com:NA:CreateNewLineFromSocket: clearing IMAP_CONNECTION_IS_OPEN - rv = 80470002
2021-08-28 07:11:03.657000 UTC - [Parent 54380: IMAP]: I/IMAP 1f92c000:imap.mail.yahoo.com:NA:TellThreadToDie: close socket connection
2021-08-28 07:11:03.657000 UTC - [Parent 54380: IMAP]: I/IMAP 1f92c000:imap.mail.yahoo.com:NA:CreateNewLineFromSocket: (null)
2021-08-28 07:11:03.657000 UTC - [Parent 54380: IMAP]: D/IMAP SetConnectionStatus(0x80470002)
2021-08-28 07:11:03.657000 UTC - [Parent 54380: IMAP]: D/IMAP URL failed with code 0x80470002 (imap://[e-mail]:993/select%3E/Bulk%20Mail)
2021-08-28 07:11:03.660000 UTC - [Parent 54380: IMAP]: I/IMAP 1f92c000:imap.mail.yahoo.com:NA:ProcessCurrentURL: aborting queued urls
2021-08-28 07:11:03.662000 UTC - [Parent 54380: IMAP]: D/IMAP ImapThreadMainLoop leaving [this=1f92c000]

Expected results:

I don't know if it is Thunderbird or Yahoo that's causing the problem. I've only seen this happen consistently since I switched from 78 to 91.

Comment 1

[Wayne Mery (:wsmwk)]

Many of imap fixes delivered in the last 8 months were also sent out in version 78, so I suspect the odds of this being a new bug in Thunderbird are not high.

Comment 2

[gene smith]

Looks like this may be an unintended consequence of bug 1611624. In the log above what's happening is the login/authentication to yahoo is OK but yahoo doesn't send any capabilities with the authenticate response. Apparently the yahoo server doesn't like to send capabilities in quick succession or redundant capabilities since it had already sent them in the "greeting" when the connection is made within the TLS tunnel.
Yahoo responds to the capability request after authenticate with untagged "Bye", then the "NO [LIMIT] and then drops the connection.

Another possibility is that the capability request is too close in time to the next ID request and triggers the [LIMIT] error, but I doubt it.

What I'm not sure about is how this manifests itself to the user? Is there just a pop-up error and then TB recovers and no harm is done, or does it cause some other problem?
It appears from the log fragment above that an attempt to select the "Bulk Mail" folder was attempted but I'm not sure what happens later in the snipped part of the log. The URL may be retried and succeed the 2nd time (i.e., no yahoo complaints about LIMIT).
It might be helpful to attach a more complete log using the "Attach new file" button above.

Comment 3

[gene smith]

The same thing is reported here for Apple's "mail" app:
https://superuser.com/questions/1669791/macos-mail-delay-when-fetching-from-yahoo-via-imap-related-to-no-limit-capa
It makes sense that apple mail app would see this too in order to work correctly with their own icloud server (which was the subject of bug 1611624).

Comment 4

[gene smith]

I've duplicated the error with a test aol account (which along with others like at&t, and compuserve also use the yahoo servers). The extra capability seems to be a red-herring. If I comment out sending it, the failure occurs on the next command, imap ID, and the server disconnects on it.
To see the problem I start tb and select several folders in the aol account in quick succession. This does 3 successful connections and then has the problem with connection 4 and 5.

This seems very similar to the problem reported here: Bug 1595169. This was back at tb 68 and the user saw yahoo refusing or dropping connection. We found that yahoo sometimes didn't like more than 3 connections while TB attempts to create up to default 5. When the user reduces the number of "cached connection" in Advanced server settings down to 3 the problem went away.

When I reduce my number of cached connections for the aol account down to 3, the problem also goes away. It doesn't complain about the LIMIT and I can move between folders with less waiting on the "spinner".

On thing I noticed is that with the extra capability being sent (not commented out) and 5 connections that there is a generic pop-up saying "Server imap.aol.com has disconnected. The server may have gone down or there may be a network problem." With the the extra capability removed (commented out) I don't see this message, but otherwise the behavior is the same per the IMAP:5 log.

Comment 5

[Matt]

There have been issues reported in support where rate limiting Thunderbird to 3 connections stops the error.

Comment 6

[Wayne Mery (:wsmwk)]

related to bug 1738046 ?

Comment 7

[gene smith]

(In reply to Wayne Mery (:wsmwk) from comment #6)

related to bug 1738046 ?

I don't think so. That bug is HTTP or maybe oauth2 and google related. This bug is IMAP and yahoo related.

Did reducing the cached connnections from 5 to 3 fix the problem for the reporter?

Comment 8

[Ray Satiro]

(In reply to gene smith from comment #7)

Did reducing the cached connnections from 5 to 3 fix the problem for the reporter?

Yes, it seems to have worked. I have Thunderbird open now and in the debug log I do not see any rate limit entries. Also I haven't noticed any problems recently.

Comment 9

[Wayne Mery (:wsmwk)]

If regressed by bug 1611624 then this regression goes back to v78 .

Comment 10

[gene smith]

Here's an possible fix by using an experimental "staging" server provided by yahoo/aol: bug 1745205 comment 58

Comment 11

[Wayne Mery (:wsmwk)]

(In reply to gene smith from comment #10)

Here's an possible fix by using an experimental "staging" server provided by yahoo/aol: bug 1745205 comment 58

Ray, is this problem gone for you?

Comment 12

[Ray Satiro]

I'm still using 3 cached connections instead of 5 and have not noticed the problem since, or if I did I don't remember because it's been a long time.

Comment 13

[Wayne Mery (:wsmwk)]

Thanks for the update.