Closed Bug 1580262 Opened 5 years ago Closed 4 years ago

startup crash in [@ nsImapUrl::UnescapeSlashes] when using an alternative separator, for example dot separator (UK2.net)

Categories

(MailNews Core :: Networking: IMAP, defect, P2)

Product:
MailNews Core
Component:
Networking: IMAP
Platform:
x86
All
Type:
defect

Tracking

(thunderbird_esr68+ wontfix, thunderbird_esr78? fixed)

Status:
RESOLVED FIXED
Milestone:
86 Branch
Tracking Flags:
Tracking Status
thunderbird_esr68 + wontfix
thunderbird_esr78 ? fixed

People

(Reporter: wsmwk, Assigned: benc)

References

(
URL
)

Details

(Keywords: crash, regression, regressionwindow-wanted, Whiteboard: [regression:tb68][startup crash])

Crash Data

Attachments

(5 files, 1 obsolete file)

new imap-seperator details
3.84 MB, text/plain
Details
1580262.patch (landed)
4.11 KB, patch
mkmelin
: review+
Details | Diff | Splinter Review
1580262-off-by-one.patch (landed)
709 bytes, patch
mkmelin
: review+
Details | Diff | Splinter Review
1580262-move-assignment.patch (landed)
922 bytes, patch
benc
: review+
Details | Diff | Splinter Review
bug1580262-esr78.patch
4.17 KB, patch
wsmwk
: approval-comm-esr78+
Details | Diff | Splinter Review

Most crashes are in the first minute. Compact related? Or is the stack totally hosed?

#47 crash for version 68.0. Earliest crash is bp-bf6c6079-fe28-4327-8460-fd5a00190626 66.0b0 buildid 20190209112700

This bug is for crash report bp-e453d4bc-0c19-4304-9049-6145d0190910.

Top 10 frames of crashing thread:

0 xul.dll nsImapUrl::UnescapeSlashes comm/mailnews/imap/src/nsImapUrl.cpp:757
1 xul.dll nsImapIncomingServer::PossibleImapMailbox comm/mailnews/imap/src/nsImapIncomingServer.cpp:1108
2 xul.dll nsresult `anonymous namespace'::SyncRunnable4<nsIImapServerSink, const nsTSubstring<char>&, char, int, bool*>::Run comm/mailnews/imap/src/nsSyncRunnableHelpers.cpp:184
3 xul.dll nsThread::ProcessNextEvent xpcom/threads/nsThread.cpp:1175
4 xul.dll NS_ProcessNextEvent xpcom/threads/nsThreadUtils.cpp:486
5 xul.dll nsXULWindow::ShowModal xpfe/appshell/nsXULWindow.cpp:385
6 xul.dll nsContentTreeOwner::ShowAsModal xpfe/appshell/nsContentTreeOwner.cpp:450
7 xul.dll nsWindowWatcher::OpenWindowInternal toolkit/components/windowwatcher/nsWindowWatcher.cpp:1246
8 xul.dll nsWindowWatcher::OpenWindow toolkit/components/windowwatcher/nsWindowWatcher.cpp:290
9 xul.dll NS_InvokeByIndex

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

Most crashes are in the first minute.

Specifically 60% are 10 seconds or less, another 20+% less than 20 seconds.

This is particularly onerous because, based on install time, looks like the average user crashes 4-5 times https://crash-stats.mozilla.com/signature/?product=Thunderbird&signature=nsImapUrl%3A%3AUnescapeSlashes&date=%3E%3D2019-08-30T09%3A10%3A00.000Z&date=%3C2019-09-13T09%3A10%3A00.000Z&_columns=date&_columns=version&_columns=platform&_columns=address&_columns=uptime&_columns=install_time&_sort=install_time&_sort=uptime&_sort=-date&page=2

Flags: needinfo?(mkmelin+mozilla)
Keywords: regression, regressionwindow-wanted, topcrash-thunderbird
OS: Windows 10 → All
Summary: Crash in [@ nsImapUrl::UnescapeSlashes] → startup crash in [@ nsImapUrl::UnescapeSlashes]
Whiteboard: [startup crash]

No longer a topcrash

Keywords: topcrash-thunderbird
Version: unspecified → 68

From https://support.mozilla.org/en-US/questions/1276739#answer-1279252 it looks like "folder names with a \ " having looked at bp-cd63bb4b-82ae-427c-861b-489e20200108

Definitely a regression from looking at crash stats

status-thunderbird_esr68: --- → affected
tracking-thunderbird_esr68: --- → ?
Flags: needinfo?(mkmelin+mozilla)
Flags: needinfo?(benc)
Whiteboard: [startup crash] → [regression:tb68][startup crash]

I don't think it's related to folder names with a backslash '\' in them.

nsImapUrl::EscapeSlashes() and nsImapUrl::UnescapeSlashes() deal with replacing forward slashes '/' with '^'.
Both of those functions look sound to me, from a memory-safety point of view. (they're broken in other ways - see Bug 1608318).
I'm pretty sure the crashing function, UnescapeSlashes(), is dying because it's being passed a bad input pointer by the caller, nsImapIncomingServer::PossibleImapMailbox().

I've been trying to trigger the bug by throwing odd IMAP folder names at it (see some of my other findings here: https://bugzilla.mozilla.org/show_bug.cgi?id=773579#c12), but haven't yet got it to crash.

Just realised something as I was writing this: nsImapIncomingServer::PossibleImapMailbox() only ever calls nsImapUrl::UnescapeSlashes() if the IMAP separator is not '/'. So any reproducible test case is most likely to be using an alternative separator...

Flags: needinfo?(benc)
Flags: needinfo?(mkmelin+mozilla)
Assignee: nobody → benc

Ben, the oldest crash reports are

If you need a regression range, zaggie1 may be in a good position to find it.

Flags: needinfo?(benc)
tracking-thunderbird_esr68: ? → +
Priority: -- → P2

(In reply to Ben Campbell from comment #6)

...
Just realised something as I was writing this: nsImapIncomingServer::PossibleImapMailbox() only ever calls nsImapUrl::UnescapeSlashes() if the IMAP separator is not '/'. So any reproducible test case is most likely to be using an alternative separator...

zaga can you comment on what imap separator is being used?
You may need a short IMAP:5 log using instructions at https://wiki.mozilla.org/MailNews:Logging

Flags: needinfo?(zaga1)

Wayne wsmsk, not sure what seperator is used but I had previously created an IMAP log and attached results file at bug 1609389 - attachment 9121603 [details] (Comments 36-38), I hope that is useful, otherwise I can run again?

Flags: needinfo?(zaga1)

(In reply to zaggie1 from comment #12)

Wayne wsmsk, not sure what seperator is used but I had previously created an IMAP log and attached results file at bug 1609389 - attachment 9121603 [details] (Comments 36-38), I hope that is useful, otherwise I can run again?

depends on what Ben and Magnus need.

Flags: needinfo?(mkmelin+mozilla)

(In reply to zaggie1 from comment #12)

Wayne wsmsk, not sure what seperator is used but I had previously created an IMAP log and attached results file at bug 1609389 - attachment 9121603 [details] (Comments 36-38), I hope that is useful, otherwise I can run again?

Zaggie, The attachment stops (tb crashes?) before useful info about separator appears. So if you could run it again it might help. You can attach it on at this bug. Thanks.

New log file now attached ("new imap-seperator details").

Looks like the separator for the chimail.uk2 account is a period (dot) and not a slash like for the other accounts.
One thing I noticed is that the chimail.uk2 account does 12 imap connections. That's a lot of connections! I assume that the number of "cached" connections set in the server "advanced" settings is 12 instead of the default 5? Zaggie1, if you are still having crash problems, you might try reducing this number down to 5 or less and see if it helps.

Flags: needinfo?(mkmelin+mozilla)

The "cached" connections setting was already set to the default of 5, so I guess that not the cause of the problem? Or is that accopunt just completely corrupt?

zaggie1, Looking at the log again there are indeed 12 connections going to the chimail account. Then each connection "selects" to INBOX. This is really weird and I've never seen anything like this looking at imap:5 logs!
I assume you only have one account for chimail, right? It almost looks like you have 12 accounts with the name chimail running in tb. Is that possible?

Assuming you only have one chimail accout, I would suggest going to the advanced server setting and setting the number of cached connections down to 1 and restart tb. Then set the number of cached back to 5 and shutdown tb. Then run tb and record the log like you did before and attach it. Maybe that will fix the problem with 12 connection to chimail.

You might also check using the "Config Editor" (under advanced options/preferences) and check the item called mail.server.serverX.max_cached_connections and make sure it agrees with what you entered in the advanced server setting (default 5). This limits the number of connections that tb makes to the imap server and the settings should agree. (Note: X is the account index so you will see server items called mail.server.server1.max_cached_connections, mail.server.server2.max_cached_connections etc. I can't tell you exactly which account index corresponds to chimail.)

Gene, yes I do have several chimail accounts (11). I just realised that I had the problematic account (dvd@...) turned off when I ran the last IMAP log. I have re-ran the log with just that account accessing online mail and it crashes as before (which is why the first log I uploaded was partial as the log stopped running when TB crashed).

I notice that in the Profile folder, for that Imap account there are multiple INBOX.msf files:
Profile folder > ImapMail
chimail.uk2-2.net
INBOX-5.msf
80a829ba.sbd.msf
INBOX-4.msf
INBOX-3.msf
INBOX-2.msf
INBOX-1.msf
INBOX.msf
80a829ba.msf
Spam.msf
filterlog.html
msgFilterRules.dat

In config editor there is no info for mail.server.server2.max_cached_connections.
I notice that TB mail.server.server2.directory seems to have lost link for that account's directory folder "/Users/•••••••••/Library/Thunderbird/Profiles/4u4lz6yw.default/Mail/Local Folders" - could this be the problem?

Below are all the details from new log before it crashes:
2020-05-18 10:44:01.021713 UTC - [(null) 1145: Unnamed thread 0x12f3f2410]: D/IMAP ImapThreadMainLoop entering [this=0x12f0f1000]
2020-05-18 10:44:01.117708 UTC - [(null) 1145: Main Thread]: I/IMAP 0x12f0f1000:chimail.uk2.net:NA:SetupWithUrlCallback: clearing IMAP_CONNECTION_IS_OPEN
2020-05-18 10:44:01.117817 UTC - [(null) 1145: Unnamed thread 0x12f3f2410]: I/IMAP 0x12f0f1000:chimail.uk2.net:NA:ProcessCurrentURL: entering
2020-05-18 10:44:01.117823 UTC - [(null) 1145: Unnamed thread 0x12f3f2410]: I/IMAP 0x12f0f1000:chimail.uk2.net:NA:ProcessCurrentURL:imap://dvd%40••••••••••••%2Euk@chimail.uk2.net:993/select%3E.INBOX: = currentUrl
2020-05-18 10:44:01.784326 UTC - [(null) 1145: Unnamed thread 0x12f3f2410]: D/IMAP ReadNextLine [stream=0x12f4b0280 nb=18 needmore=0]
2020-05-18 10:44:01.784338 UTC - [(null) 1145: Unnamed thread 0x12f3f2410]: I/IMAP 0x12f0f1000:chimail.uk2.net:NA:CreateNewLineFromSocket: * OK IMAP4 ready
2020-05-18 10:44:01.790374 UTC - [(null) 1145: Unnamed thread 0x12f3f2410]: I/IMAP 0x12f0f1000:chimail.uk2.net:NA:SendData: 1 capability
2020-05-18 10:44:01.895420 UTC - [(null) 1145: Unnamed thread 0x12f3f2410]: D/IMAP ReadNextLine [stream=0x12f4b0280 nb=73 needmore=0]
2020-05-18 10:44:01.895428 UTC - [(null) 1145: Unnamed thread 0x12f3f2410]: I/IMAP 0x12f0f1000:chimail.uk2.net:NA:CreateNewLineFromSocket: * CAPABILITY IMAP4rev1 LITERAL+ SASL-IR LOGIN-REFERRALS IDLE AUTH=PLAIN
2020-05-18 10:44:01.895558 UTC - [(null) 1145: Unnamed thread 0x12f3f2410]: D/IMAP ReadNextLine [stream=0x12f4b0280 nb=16 needmore=0]
2020-05-18 10:44:01.895562 UTC - [(null) 1145: Unnamed thread 0x12f3f2410]: I/IMAP 0x12f0f1000:chimail.uk2.net:NA:CreateNewLineFromSocket: 1 OK completed
2020-05-18 10:44:01.895576 UTC - [(null) 1145: Unnamed thread 0x12f3f2410]: D/IMAP Try to log in
2020-05-18 10:44:01.895582 UTC - [(null) 1145: Unnamed thread 0x12f3f2410]: D/IMAP IMAP auth: server caps 0x85025, pref 0x1006, failed 0x0, avail caps 0x1004
2020-05-18 10:44:01.895585 UTC - [(null) 1145: Unnamed thread 0x12f3f2410]: 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)
2020-05-18 10:44:01.895586 UTC - [(null) 1145: Unnamed thread 0x12f3f2410]: D/IMAP Trying auth method 0x1000
2020-05-18 10:44:39.919807 UTC - [(null) 1145: Unnamed thread 0x12f3f2410]: D/IMAP got new password
2020-05-18 10:44:39.952499 UTC - [(null) 1145: Unnamed thread 0x12f3f2410]: D/IMAP IMAP: trying auth method 0x1000
2020-05-18 10:44:39.952508 UTC - [(null) 1145: Unnamed thread 0x12f3f2410]: D/IMAP PLAIN auth
2020-05-18 10:44:39.952515 UTC - [(null) 1145: Unnamed thread 0x12f3f2410]: I/IMAP 0x12f0f1000:chimail.uk2.net:NA:SendData: 2 authenticate PLAIN
2020-05-18 10:44:40.055501 UTC - [(null) 1145: Unnamed thread 0x12f3f2410]: D/IMAP ReadNextLine [stream=0x12f4b0280 nb=4 needmore=0]
2020-05-18 10:44:40.055509 UTC - [(null) 1145: Unnamed thread 0x12f3f2410]: I/IMAP 0x12f0f1000:chimail.uk2.net:NA:CreateNewLineFromSocket: +
2020-05-18 10:44:40.055529 UTC - [(null) 1145: Unnamed thread 0x12f3f2410]: I/IMAP 0x12f0f1000:chimail.uk2.net:NA:SendData: Logging suppressed for this command (it probably contained authentication information)
2020-05-18 10:44:40.968645 UTC - [(null) 1145: Unnamed thread 0x12f3f2410]: D/IMAP ReadNextLine [stream=0x12f4b0280 nb=374 needmore=0]
2020-05-18 10:44:40.968654 UTC - [(null) 1145: Unnamed thread 0x12f3f2410]: I/IMAP 0x12f0f1000:chimail.uk2.net:NA:CreateNewLineFromSocket: 2 OK [CAPABILITY IMAP4rev1 LITERAL+ SASL-IR LOGIN-REFERRALS ID ENABLE IDLE SORT SORT=DISPLAY THREAD=REFERENCES THREAD=REFS THREAD=ORDEREDSUBJECT MULTIAPPEND URL-PARTIAL CATENATE UNSELECT CHILDREN NAMESPACE UIDPLUS LIST-EXTENDED I18NLEVEL=1 CONDSTORE QRESYNC ESEARCH ESORT SEARCHRES WITHIN CONTEXT=SEARCH LIST-STATUS BINARY MOVE SPECIAL-USE QUOTA ACL RIGHTS=texk] Logged in
2020-05-18 10:44:44.220762 UTC - [(null) 1145: Unnamed thread 0x12f3f2410]: D/IMAP login succeeded
2020-05-18 10:44:45.049142 UTC - [(null) 1145: Unnamed thread 0x12f3f

CORRECTION: Sorry, I looked at the wrong server info for "mail.server.serverX.max_cached_connections" It is mail.server.server3.max_cached_connections - it is set at default 5. Also ignore bit about lost directory link too!
[I don't know how to edit my previous message]

zaggie, Thanks for clearing that up that you really have multiple (11) chimail accounts. You say only one is causing the crash? I suspect it has non-ascii or unicode folder names, right? Does comment 20 above list all the folder for the crashing account? If not, can you reveal the names for the folders for the crashing account. If you prefer not to post them here you might consider emailing them to me.

I suspect somehow tb is choking when it goes through your folders in an attempts to replace any possible ^ with a /. But, I doubt that there are any ^'s or /'s in any of your folder names. However, it appears when it gets done checking and it terminates the string, *dst = 0, it is crashing like a buffer overrun or something.

Also, in comment 20 I dont' think the extra INBOX-X files are a big problem. Tb just uses the most recent one, INBOX-5. These may be a symptom of the various crashes that left the original INBOX in a corrupted state and tb created a new one. You can delete all but the highest numbered one. But even if you delete it, tb will re-download the headers and re-create it.
Edit: It may also be helpful to know the character set used for your non-ascii folders. I think you can see it by right-clicking the folder and accessing Properties | Fallback text encoding.

Gene, logging into the online chimail.net account, the folders for this account are: Inbox, Draft Items, Spam, Deleted Items, Archives, Junk, Reports.
For some reason, TB creates an additional folder named "/" (I mentioned previously re Comment 6). I have tried deleting this folder but it just reappears on relaunching TB.
Fallback text encoding used for this non-ascii folder is Western ISO5589-1 (incidentally when accessing the properties for this folder TB crashed)
The other accounts' folders are also Western ISO5589-1, but none of the other accounts create this "/" folder.

zaggie, still crashing?

reporter in https://support.mozilla.org/en-US/questions/1277570 and https://support.mozilla.org/en-US/questions/1281424 are also both uk2.net. The later wrote "created a new profile ... same crash still occurs"

Flags: needinfo?(benc) → needinfo?(zaga1)
Summary: startup crash in [@ nsImapUrl::UnescapeSlashes] → startup crash in [@ nsImapUrl::UnescapeSlashes] when using an alternative separator (UK2.net)

Wayne, Yes still crashing with that particular account (dvd@...) I have deleted that account from TB and set it up in another app (Postbox) and have no problems running that account from Postbox.

Flags: needinfo?(zaga1)

PS: I have not tried TB v.78 yet. I will update and re-introduce dvd@ account and post an update.

Still crashes in v78.
Also crashes in a new test profile.

OSX Console messages:
21/09/2020 14:22:18.700 PhotoUploaderFinderSync[493]: Request badge for: file:///Users/***/Library/Thunderbird/Profiles/ynd4vyjm.test/
21/09/2020 14:22:57.892 thunderbird[723]: NextSurface returning false because of invalid mSize (0, 0).
21/09/2020 14:22:57.893 thunderbird[723]: NextSurface returning false because of invalid mSize (0, 0).
21/09/2020 14:22:57.893 thunderbird[723]: NextSurface returning false because of invalid mSize (0, 0).
21/09/2020 14:22:57.893 thunderbird[723]: NextSurface returning false because of invalid mSize (0, 0).
21/09/2020 14:22:57.894 thunderbird[723]: NextSurface returning false because of invalid mSize (0, 0).
21/09/2020 14:23:01.087 thunderbird[723]: NextSurface returning false because of invalid mSize (0, 0).
21/09/2020 14:23:08.411 thunderbird[723]: NextSurface returning false because of invalid mSize (0, 0).
21/09/2020 14:27:00.423 thunderbird[723]: NextSurface returning false because of invalid mSize (0, 0).

Could this also impact Bug 773579 - Separator in IMAP-System is used wrong (^ instead of / is used, if folder hiearchy delimiter of IMAP server is ".") ?

Flags: needinfo?(gds)
Summary: startup crash in [@ nsImapUrl::UnescapeSlashes] when using an alternative separator (UK2.net) → startup crash in [@ nsImapUrl::UnescapeSlashes] when using an alternative separator, for example dot separator (UK2.net)

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

Could this also impact Bug 773579 - Separator in IMAP-System is used wrong (^ instead of / is used, if folder hiearchy delimiter of IMAP server is ".") ?

I have a patch that is probably rotting that allow slashes in folder names that seems to work. I did a lot of work with it and never saw a crash. It involve a lot of the function the Ben points out in comment 6.
I need to revisit this again shortly.

Flags: needinfo?(gds)

Hi,
Have you been able to look at this any further? This is causing a serious issue and effecting more and more of our branches. The latest crash ID is
bp-3834d69f-aa65-4076-93ab-141550210119

Thank you in advance.

Ash

(In reply to Ashley Walker from comment #31)

Hi,
Have you been able to look at this any further? This is causing a serious issue and effecting more and more of our branches. The latest crash ID is
bp-3834d69f-aa65-4076-93ab-141550210119

Thank you in advance.

Ash

The tb developers and testers have been unable to duplicate the this crash you and a few other see so haven't been able to fix the problem yet. Maybe you can provide more info such as what user activity precipitated the crash? If clicking on folder, what was the folder name; did it have any unusual characters in the name? Can you tell us the type of IMAP server you connect to? Was tb just started up or had it been running a while? An IMAP:5 log might also be helpful that records what is happening before and during the crash (see https://wiki.mozilla.org/MailNews:Logging).

Hi,
Thank you for the quick response. The crashes seem to start happening at random, but once it starts the client never works properly again until you manually remove the email account.

You launch the application, it appears to authenticate and then says checking folders. It then crashes before anything else happens. I've run the IMAP:5 log option 3 times, please see below.

ATTEMPT 3

2021-01-19 23:57:41.844000 UTC - [(null) 2932: IMAP]: D/IMAP ImapThreadMainLoop entering [this=166E7800]
2021-01-19 23:57:41.921000 UTC - [(null) 2932: Main Thread]: I/IMAP 166E7800:mail.uk2.net:NA:SetupWithUrlCallback: clearing IMAP_CONNECTION_IS_OPEN
2021-01-19 23:57:41.921000 UTC - [(null) 2932: IMAP]: I/IMAP 166E7800:mail.uk2.net:NA:ProcessCurrentURL: entering
2021-01-19 23:57:41.921000 UTC - [(null) 2932: IMAP]: I/IMAP 166E7800:mail.uk2.net:NA:ProcessCurrentURL:imap://victorynorthpoint%40trafalgarleisure%2Eco%2Euk@mail.uk2.net:993/select%3E%5E%5E%5E%5E%5EINBOX: = currentUrl
2021-01-19 23:57:42.281000 UTC - [(null) 2932: IMAP]: D/IMAP ReadNextLine [rv=0x0 stream=205DEAC0 nb=18 needmore=0]
2021-01-19 23:57:42.281000 UTC - [(null) 2932: IMAP]: I/IMAP 166E7800:mail.uk2.net:NA:CreateNewLineFromSocket: * OK IMAP4 ready

2021-01-19 23:57:42.281000 UTC - [(null) 2932: IMAP]: D/IMAP SetConnectionStatus(0x0)
2021-01-19 23:57:42.281000 UTC - [(null) 2932: IMAP]: D/IMAP SetConnectionStatus(0x0)
2021-01-19 23:57:42.281000 UTC - [(null) 2932: IMAP]: I/IMAP 166E7800:mail.uk2.net:NA:SendData: 1 capability

2021-01-19 23:57:42.389000 UTC - [(null) 2932: IMAP]: D/IMAP ReadNextLine [rv=0x0 stream=205DEAC0 nb=73 needmore=0]
2021-01-19 23:57:42.389000 UTC - [(null) 2932: IMAP]: I/IMAP 166E7800:mail.uk2.net:NA:CreateNewLineFromSocket: * CAPABILITY IMAP4rev1 LITERAL+ SASL-IR LOGIN-REFERRALS IDLE AUTH=PLAIN

2021-01-19 23:57:42.389000 UTC - [(null) 2932: IMAP]: D/IMAP SetConnectionStatus(0x0)
2021-01-19 23:57:42.389000 UTC - [(null) 2932: IMAP]: D/IMAP ReadNextLine [rv=0x0 stream=205DEAC0 nb=16 needmore=0]
2021-01-19 23:57:42.389000 UTC - [(null) 2932: IMAP]: I/IMAP 166E7800:mail.uk2.net:NA:CreateNewLineFromSocket: 1 OK completed

2021-01-19 23:57:42.389000 UTC - [(null) 2932: IMAP]: D/IMAP SetConnectionStatus(0x0)
2021-01-19 23:57:42.389000 UTC - [(null) 2932: IMAP]: D/IMAP Try to log in
2021-01-19 23:57:42.389000 UTC - [(null) 2932: IMAP]: D/IMAP IMAP auth: server caps 0x85025, pref 0x1006, failed 0x0, avail caps 0x1004
2021-01-19 23:57:42.389000 UTC - [(null) 2932: 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-01-19 23:57:42.389000 UTC - [(null) 2932: IMAP]: D/IMAP Trying auth method 0x1000
2021-01-19 23:57:42.397000 UTC - [(null) 2932: IMAP]: D/IMAP got new password
2021-01-19 23:57:42.397000 UTC - [(null) 2932: IMAP]: D/IMAP IMAP: trying auth method 0x1000
2021-01-19 23:57:42.397000 UTC - [(null) 2932: IMAP]: D/IMAP PLAIN auth
2021-01-19 23:57:42.397000 UTC - [(null) 2932: IMAP]: I/IMAP 166E7800:mail.uk2.net:NA:SendData: 2 authenticate PLAIN

2021-01-19 23:57:42.503000 UTC - [(null) 2932: IMAP]: D/IMAP ReadNextLine [rv=0x0 stream=205DEAC0 nb=4 needmore=0]
2021-01-19 23:57:42.503000 UTC - [(null) 2932: IMAP]: I/IMAP 166E7800:mail.uk2.net:NA:CreateNewLineFromSocket: +

2021-01-19 23:57:42.503000 UTC - [(null) 2932: IMAP]: D/IMAP SetConnectionStatus(0x0)
2021-01-19 23:57:42.503000 UTC - [(null) 2932: IMAP]: I/IMAP 166E7800:mail.uk2.net:NA:SendData: Logging suppressed for this command (it probably contained authentication information)
2021-01-19 23:57:42.696000 UTC - [(null) 2932: IMAP]: D/IMAP ReadNextLine [rv=0x0 stream=205DEAC0 nb=395 needmore=0]
2021-01-19 23:57:42.696000 UTC - [(null) 2932: IMAP]: I/IMAP 166E7800:mail.uk2.net:NA:CreateNewLineFromSocket: 2 OK [CAPABILITY IMAP4rev1 SASL-IR LOGIN-REFERRALS ID ENABLE IDLE SORT SORT=DISPLAY THREAD=REFERENCES THREAD=REFS THREAD=ORDEREDSUBJECT MULTIAPPEND URL-PARTIAL CATENATE UNSELECT CHILDREN NAMESPACE UIDPLUS LIST-EXTENDED I18NLEVEL=1 CONDSTORE QRESYNC ESEARCH ESORT SEARCHRES WITHIN CONTEXT=SEARCH LIST-STATUS BINARY MOVE SNIPPET=FUZZY LITERAL+ NOTIFY SPECIAL-USE QUOTA ACL RIGHTS=texk] Logged in

2021-01-19 23:57:42.696000 UTC - [(null) 2932: IMAP]: D/IMAP SetConnectionStatus(0x0)
2021-01-19 23:57:42.696000 UTC - [(null) 2932: IMAP]: D/IMAP login succeeded
2021-01-19 23:57:42.696000 UTC - [(null) 2932: IMAP]: I/IMAP 166E7800:mail

ATTEMPT 2

2021-01-19 23:56:29.990000 UTC - [(null) 11192: IMAP]: D/IMAP ImapThreadMainLoop entering [this=168E8000]
2021-01-19 23:56:30.042000 UTC - [(null) 11192: Main Thread]: I/IMAP 168E8000:mail.uk2.net:NA:SetupWithUrlCallback: clearing IMAP_CONNECTION_IS_OPEN
2021-01-19 23:56:30.042000 UTC - [(null) 11192: IMAP]: I/IMAP 168E8000:mail.uk2.net:NA:ProcessCurrentURL: entering
2021-01-19 23:56:30.042000 UTC - [(null) 11192: IMAP]: I/IMAP 168E8000:mail.uk2.net:NA:ProcessCurrentURL:imap://victorynorthpoint%40trafalgarleisure%2Eco%2Euk@mail.uk2.net:993/select%3E%5E%5E%5E%5E%5EINBOX: = currentUrl
2021-01-19 23:56:30.421000 UTC - [(null) 11192: IMAP]: D/IMAP ReadNextLine [rv=0x0 stream=16BF1220 nb=18 needmore=0]
2021-01-19 23:56:30.421000 UTC - [(null) 11192: IMAP]: I/IMAP 168E8000:mail.uk2.net:NA:CreateNewLineFromSocket: * OK IMAP4 ready

2021-01-19 23:56:30.421000 UTC - [(null) 11192: IMAP]: D/IMAP SetConnectionStatus(0x0)
2021-01-19 23:56:30.421000 UTC - [(null) 11192: IMAP]: D/IMAP SetConnectionStatus(0x0)
2021-01-19 23:56:30.422000 UTC - [(null) 11192: IMAP]: I/IMAP 168E8000:mail.uk2.net:NA:SendData: 1 capability

2021-01-19 23:56:30.529000 UTC - [(null) 11192: IMAP]: D/IMAP ReadNextLine [rv=0x0 stream=16BF1220 nb=73 needmore=0]
2021-01-19 23:56:30.529000 UTC - [(null) 11192: IMAP]: I/IMAP 168E8000:mail.uk2.net:NA:CreateNewLineFromSocket: * CAPABILITY IMAP4rev1 LITERAL+ SASL-IR LOGIN-REFERRALS IDLE AUTH=PLAIN

2021-01-19 23:56:30.529000 UTC - [(null) 11192: IMAP]: D/IMAP SetConnectionStatus(0x0)
2021-01-19 23:56:30.529000 UTC - [(null) 11192: IMAP]: D/IMAP ReadNextLine [rv=0x0 stream=16BF1220 nb=16 needmore=0]
2021-01-19 23:56:30.529000 UTC - [(null) 11192: IMAP]: I/IMAP 168E8000:mail.uk2.net:NA:CreateNewLineFromSocket: 1 OK completed

2021-01-19 23:56:30.529000 UTC - [(null) 11192: IMAP]: D/IMAP SetConnectionStatus(0x0)
2021-01-19 23:56:30.529000 UTC - [(null) 11192: IMAP]: D/IMAP Try to log in
2021-01-19 23:56:30.529000 UTC - [(null) 11192: IMAP]: D/IMAP IMAP auth: server caps 0x85025, pref 0x1006, failed 0x0, avail caps 0x1004
2021-01-19 23:56:30.529000 UTC - [(null) 11192: 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-01-19 23:56:30.529000 UTC - [(null) 11192: IMAP]: D/IMAP Trying auth method 0x1000
2021-01-19 23:56:30.535000 UTC - [(null) 11192: IMAP]: D/IMAP got new password
2021-01-19 23:56:30.535000 UTC - [(null) 11192: IMAP]: D/IMAP IMAP: trying auth method 0x1000
2021-01-19 23:56:30.535000 UTC - [(null) 11192: IMAP]: D/IMAP PLAIN auth
2021-01-19 23:56:30.535000 UTC - [(null) 11192: IMAP]: I/IMAP 168E8000:mail.uk2.net:NA:SendData: 2 authenticate PLAIN

2021-01-19 23:56:30.641000 UTC - [(null) 11192: IMAP]: D/IMAP ReadNextLine [rv=0x0 stream=16BF1220 nb=4 needmore=0]
2021-01-19 23:56:30.641000 UTC - [(null) 11192: IMAP]: I/IMAP 168E8000:mail.uk2.net:NA:CreateNewLineFromSocket: +

2021-01-19 23:56:30.641000 UTC - [(null) 11192: IMAP]: D/IMAP SetConnectionStatus(0x0)
2021-01-19 23:56:30.641000 UTC - [(null) 11192: IMAP]: I/IMAP 168E8000:mail.uk2.net:NA:SendData: Logging suppressed for this command (it probably contained authentication information)
2021-01-19 23:56:31.228000 UTC - [(null) 11192: IMAP]: D/IMAP ReadNextLine [rv=0x0 stream=16BF1220 nb=395 needmore=0]
2021-01-19 23:56:31.228000 UTC - [(null) 11192: IMAP]: I/IMAP 168E8000:mail.uk2.net:NA:CreateNewLineFromSocket: 2 OK [CAPABILITY IMAP4rev1 SASL-IR LOGIN-REFERRALS ID ENABLE IDLE SORT SORT=DISPLAY THREAD=REFERENCES THREAD=REFS THREAD=ORDEREDSUBJECT MULTIAPPEND URL-PARTIAL CATENATE UNSELECT CHILDREN NAMESPACE UIDPLUS LIST-EXTENDED I18NLEVEL=1 CONDSTORE QRESYNC ESEARCH ESORT SEARCHRES WITHIN CONTEXT=SEARCH LIST-STATUS BINARY MOVE SNIPPET=FUZZY LITERAL+ NOTIFY SPECIAL-USE QUOTA ACL RIGHTS=texk] Logged in

2021-01-19 23:56:31.228000 UTC - [(null) 11192: IMAP]: D/IMAP SetConnectionStatus(0x0)
2021-01-19 23:56:31.228000 UTC - [(null) 11192: IMAP]: D/IMAP login succeeded
2021-01-19 23:56:31.229000 UTC - [(null) 11

ATTEMPT 1

2021-01-19 23:53:28.397000 UTC - [(null) 8496: IMAP]: D/IMAP ImapThreadMainLoop entering [this=16C36000]
2021-01-19 23:53:28.473000 UTC - [(null) 8496: Main Thread]: I/IMAP 16C36000:mail.uk2.net:NA:SetupWithUrlCallback: clearing IMAP_CONNECTION_IS_OPEN
2021-01-19 23:53:28.474000 UTC - [(null) 8496: IMAP]: I/IMAP 16C36000:mail.uk2.net:NA:ProcessCurrentURL: entering
2021-01-19 23:53:28.474000 UTC - [(null) 8496: IMAP]: I/IMAP 16C36000:mail.uk2.net:NA:ProcessCurrentURL:imap://victorynorthpoint%40trafalgarleisure%2Eco%2Euk@mail.uk2.net:993/select%3E%5E%5E%5E%5E%5EINBOX: = currentUrl
2021-01-19 23:53:28.905000 UTC - [(null) 8496: IMAP]: D/IMAP ReadNextLine [rv=0x0 stream=293FEBE0 nb=18 needmore=0]
2021-01-19 23:53:28.905000 UTC - [(null) 8496: IMAP]: I/IMAP 16C36000:mail.uk2.net:NA:CreateNewLineFromSocket: * OK IMAP4 ready

2021-01-19 23:53:28.926000 UTC - [(null) 8496: IMAP]: D/IMAP SetConnectionStatus(0x0)
2021-01-19 23:53:28.926000 UTC - [(null) 8496: IMAP]: D/IMAP SetConnectionStatus(0x0)
2021-01-19 23:53:28.926000 UTC - [(null) 8496: IMAP]: I/IMAP 16C36000:mail.uk2.net:NA:SendData: 1 capability

2021-01-19 23:53:29.033000 UTC - [(null) 8496: IMAP]: D/IMAP ReadNextLine [rv=0x0 stream=293FEBE0 nb=73 needmore=0]
2021-01-19 23:53:29.033000 UTC - [(null) 8496: IMAP]: I/IMAP 16C36000:mail.uk2.net:NA:CreateNewLineFromSocket: * CAPABILITY IMAP4rev1 LITERAL+ SASL-IR LOGIN-REFERRALS IDLE AUTH=PLAIN

2021-01-19 23:53:29.033000 UTC - [(null) 8496: IMAP]: D/IMAP SetConnectionStatus(0x0)
2021-01-19 23:53:29.033000 UTC - [(null) 8496: IMAP]: D/IMAP ReadNextLine [rv=0x0 stream=293FEBE0 nb=16 needmore=0]
2021-01-19 23:53:29.033000 UTC - [(null) 8496: IMAP]: I/IMAP 16C36000:mail.uk2.net:NA:CreateNewLineFromSocket: 1 OK completed

2021-01-19 23:53:29.033000 UTC - [(null) 8496: IMAP]: D/IMAP SetConnectionStatus(0x0)
2021-01-19 23:53:29.033000 UTC - [(null) 8496: IMAP]: D/IMAP Try to log in
2021-01-19 23:53:29.033000 UTC - [(null) 8496: IMAP]: D/IMAP IMAP auth: server caps 0x85025, pref 0x1006, failed 0x0, avail caps 0x1004
2021-01-19 23:53:29.033000 UTC - [(null) 8496: 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-01-19 23:53:29.033000 UTC - [(null) 8496: IMAP]: D/IMAP Trying auth method 0x1000
2021-01-19 23:53:29.037000 UTC - [(null) 8496: IMAP]: D/IMAP got new password
2021-01-19 23:53:29.037000 UTC - [(null) 8496: IMAP]: D/IMAP IMAP: trying auth method 0x1000
2021-01-19 23:53:29.037000 UTC - [(null) 8496: IMAP]: D/IMAP PLAIN auth
2021-01-19 23:53:29.037000 UTC - [(null) 8496: IMAP]: I/IMAP 16C36000:mail.uk2.net:NA:SendData: 2 authenticate PLAIN

2021-01-19 23:53:29.242000 UTC - [(null) 8496: IMAP]: D/IMAP ReadNextLine [rv=0x0 stream=293FEBE0 nb=4 needmore=0]
2021-01-19 23:53:29.242000 UTC - [(null) 8496: IMAP]: I/IMAP 16C36000:mail.uk2.net:NA:CreateNewLineFromSocket: +

2021-01-19 23:53:29.242000 UTC - [(null) 8496: IMAP]: D/IMAP SetConnectionStatus(0x0)
2021-01-19 23:53:29.260000 UTC - [(null) 8496: IMAP]: I/IMAP 16C36000:mail.uk2.net:NA:SendData: Logging suppressed for this command (it probably contained authentication information)
2021-01-19 23:53:29.874000 UTC - [(null) 8496: IMAP]: D/IMAP ReadNextLine [rv=0x0 stream=293FEBE0 nb=395 needmore=0]
2021-01-19 23:53:29.874000 UTC - [(null) 8496: IMAP]: I/IMAP 16C36000:mail.uk2.net:NA:CreateNewLineFromSocket: 2 OK [CAPABILITY IMAP4rev1 SASL-IR LOGIN-REFERRALS ID ENABLE IDLE SORT SORT=DISPLAY THREAD=REFERENCES THREAD=REFS THREAD=ORDEREDSUBJECT MULTIAPPEND URL-PARTIAL CATENATE UNSELECT CHILDREN NAMESPACE UIDPLUS LIST-EXTENDED I18NLEVEL=1 CONDSTORE QRESYNC ESEARCH ESORT SEARCHRES WITHIN CONTEXT=SEARCH LIST-STATUS BINARY MOVE SNIPPET=FUZZY LITERAL+ NOTIFY SPECIAL-USE QUOTA ACL RIGHTS=texk] Logged in

2021-01-19 23:53:29.874000 UTC - [(null) 8496: IMAP]: D/IMAP SetConnectionStatus(0x0)
2021-01-19 23:53:29.874000 UTC - [(null) 8496: IMAP]: D/IMAP login succeeded
2021-01-19 23:53:29.874000 UTC - [(null) 8496: IMAP]: I/IMAP 16C36000:mail

Well, that looks pretty typical except it just stops right after it logs in, due to the crash no doubt. So can't tell much from the logs.
I still think it might be due to an unusual folder name that tb can't handle. Can you tell us some names you use? Maybe some start with or contain "non-english" letters or contain punctuation like commas, periods, or other symbols like /,\,#,^,% etc. Tb should be able to handle this but there may be patterns that aren't processed right and confuse tb.

Then again, the folder names may not have anything to do with this. This crash seems to be reported often by users of uk2 so still may be something about the server that tb doesn't like. An often effective way to debug this type of possibly server specific problem is to provide us with a temporary test account with uk2. Would that be possible?

UnescapeSlashes looks a bit hairy, although I don't think it's incorrect. I can see that if it was used on an nsACString rather than a nsCString/nsAutoCString there's potential for it to overwrite memory (nsACString isn't necessarily nul-terminated). But I don't see that here.

In any case, that code makes me a bit nervous, so this patch adds in a more robust version. It might fix the crash (fingers crossed)!

Magnus: I've flagged it for review because I suspect landing it might be the quickest way to get a build to Ashley for testing.

The old UnescapeSlashes() is still there and used in a couple of places, but I'll do a followup patch to get rid of it when I get the chance.

Attachment #9198081 - Flags: review?(mkmelin+mozilla)
Keywords: leave-open
Attachment #9198081 - Flags: review?(mkmelin+mozilla)

Is this patch something I can add ?

Looks like I came up with a similar fix in bug 1687727.

Comment on attachment 9198081 [details] [diff] [review] 1580262-robustify-UnescapeSlashes-1.patch Review of attachment 9198081 [details] [diff] [review]: ----------------------------------------------------------------- Seems bugzilla ate my review comment. ::: mailnews/imap/src/nsImapUrl.cpp @@ +758,5 @@ > > *dst = 0; > +} > + > +/* static */ void nsImapUrl::UnescapeSlashes(nsACString& path) { Can we make one of these call the other so we don't need two implementations? Or is one going to be removed soon? ::: mailnews/imap/src/nsImapUrl.h @@ +46,5 @@ > char onlineDelimiter, > char** resultingCanonicalPath); > static nsresult EscapeSlashes(const char* sourcePath, char** resultPath); > + static void UnescapeSlashes(char* path); > + static void UnescapeSlashes(nsACString& path); Wouldn't it be nicer to return the modified string? Modifying in place is always a bit unexpected.... Compare to EscapeSlashes above.

Can we make one of these call the other so we don't need two implementations?

I think the patch for bug 1687727 does that.

Yes, see attachment 9198225 [details] [diff] [review] which I came up with independently.

Wouldn't it be nicer to return the modified string?

They wanted to be super smart and not allocate more memory. It's possible since un-escaping shrinks whereas escaping grows.

Here's the code from bug 1687727.

Attachment #9198761 - Flags: review?(mkmelin+mozilla)
Attachment #9198761 - Flags: feedback?(benc)
Comment on attachment 9198761 [details] [diff] [review] 1580262.patch (landed) Review of attachment 9198761 [details] [diff] [review]: ----------------------------------------------------------------- Looks good. I'll go ahead and land this, as the landing queue is empty. Likely we're busted on windows though, judging from try.
Attachment #9198761 - Flags: review?(mkmelin+mozilla) → review+
Status: NEW → ASSIGNED
Target Milestone: --- → 86 Branch
Pushed by mkmelin@iki.fi: https://hg.mozilla.org/comm-central/rev/5be4c64ee5ae Add a more robust nsImapUrl::UnescapeSlashes(). r=mkmelin

Thanks for the quick review. On a second look, *newLength = dst - start - 1; is wrong, the -1 needs to go :-(

The try bustage seems build related (mozbuild.configure.options.InvalidOptionError: WINCHECKSEC is not available in this configuration), sadly nothing a C++ coder can fix.

Terribly sorry :-(

dst is where the null byte is written, so if that's written at start then the length is 0, not -1. I guess you will have a lot of test failures now.

Attachment #9198810 - Flags: review?(mkmelin+mozilla)
Comment on attachment 9198810 [details] [diff] [review] 1580262-off-by-one.patch (landed) Review of attachment 9198810 [details] [diff] [review]: ----------------------------------------------------------------- Makes sense
Attachment #9198810 - Flags: review?(mkmelin+mozilla) → review+

This is a little urgent since without the second patch, IMAP is pretty much broken, the Inbox shows as INBO together with an error :-(

Regressions: 1688433

Gah, yeah, latest daily is broken because of that off-by-one...

Pushed by emilio@crisal.io:
https://hg.mozilla.org/comm-central/rev/c6ff68524e48
Fix off by one in nsImapUrl::unescapeSlashes. r=mkmelin,emilio

Keywords: checkin-needed-tb

Thanks, Emilio.

Magnus and Ben, you want this left open? I guess so, since the offending line (see comment #2) is still there:
https://searchfox.org/comm-central/rev/a2afcaf776f3bbff0fe6c2db4c4190942aadca12/mailnews/imap/src/nsImapUrl.cpp#757

Now it dawns on me why Ben duplicated the code. His duplicate didn't have the offending setting of the null byte *dst = 0. So setting that could crash if this is called with a string class which is not null-terminated. I checked the two call sites and they are both nsAutoCStrings, but what got landed now isn't any more robust :-( - Sorry.

Are there any recent crash reports to see what the stack is? The ones from the old comments seem to have gone.

Sorry again, hopefully third time lucky. This is what Ben must have had in mind.

Attachment #9198853 - Flags: review?(benc)
Comment on attachment 9198853 [details] [diff] [review] 1580262-move-assignment.patch (landed) Review of attachment 9198853 [details] [diff] [review]: ----------------------------------------------------------------- Yes! I believe this patch addresses my original concern: that adding the null terminator would overrun the buffer by one byte if it was used on one of the string classes that don't use null-termination. I'm not at all confident that this is the cause of the crash, but it matches the symptoms in the crash report. So it'll be interesting to see if it helps... I say leave this open for now. Reasons: 1. As Magnus mentioned in comment 38, we should unify these functions (my original patch left the old function in place because I was pressed for time, and wanted to see if it fixed things for Ashley). 2. We don't yet know if this will fix the crash :-)
Attachment #9198853 - Flags: review?(benc) → review+

Thanks, and sorry again for the mess.

Keywords: checkin-needed-tb
Attachment #9198081 - Attachment is obsolete: true
Attachment #9198761 - Attachment description: 1580262.patch → 1580262.patch (landed)
Attachment #9198761 - Flags: feedback?(benc)
Attachment #9198810 - Attachment description: 1580262-off-by-one.patch → 1580262-off-by-one.patch (landed)

Thanks everyone for looking into this for me. Just let me know if you’d like me to test anything :)

Ash

The "final" fix should be in tomorrow's Daily. Are you using Daily? Can you reliably reproduce the crash?
Looking at the crash stack from comment #31, the crash is on nsImapUrl::UnescapeSlashes(folderName.BeginWriting()); so the hacky invocation. Maybe folderName is empty and doesn't even have a null byte allocated, or no buffer at all?

Pushed by geoff@darktrojan.net:
https://hg.mozilla.org/comm-central/rev/f26eb6e2e0c5
Move assigning null byte. r=benc

Keywords: checkin-needed-tb
Attachment #9198853 - Attachment description: 1580262-move-assignment.patch → 1580262-move-assignment.patch (landed)

I can confirm this patch appears to have fixed the startup bug. I've now updated 3 systems to use the daily release and all 3 are now working again. How long do you think it will be until this is released into a stable version?
I've noticed an extra issue where the the folder menu does not appears / update when you add a new mail account. It works fine once you restart the application.

I've noticed an extra issue where the the folder menu does not appear ... when you add a new mail account.

Like bug 1685449? That should be fixed in the Daily of yesterday and soon by TB 86 beta 1. Otherwise, please file a new bug. Miscellaneous mentions of other issues are not usually processed.

Here is the merged/folded patch of the three landed changesets. Needed slight rebasing.

[Approval Request Comment]
Regression caused by (bug #): Unknown.
User impact if declined: Crash :-(
Testing completed (on c-c, etc.): Yes, see comment #57
Risk to taking this patch (and alternatives if risky):
Not risky, just refactored existing code and provided a code path that doesn't write into memory that wasn't allocated.

Attachment #9199413 - Flags: approval-comm-esr78?

Closing this based on comment #57. I suggest to open a new bug if the crash signature persists.

Status: ASSIGNED → RESOLVED
Closed: 4 years ago
Keywords: leave-open
Resolution: --- → FIXED

Comment on attachment 9199413 [details] [diff] [review]
bug1580262-esr78.patch

[Triage Comment]
Approved for esr78

Attachment #9199413 - Flags: approval-comm-esr78? → approval-comm-esr78+
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: