825513 - crash in nsImapProtocol::GetMessageSize via nsIMAPBodyShell::Generate. m_runningUrl reset for unknown reason and we keep going through nsIMAPBodyShell::Generate

Status: RESOLVED FIXED

(MailNews Core :: Networking: IMAP, defect)

Description

[Wayne Mery (:wsmwk)]

This bug was filed from the Socorro interface and is 
report bp-b10f5e8e-35b9-4bf4-a3f6-0b6572121229 .
============================================================= 
TB19.0a2

0	xul.dll	nsImapProtocol::GetMessageSize	mailnews/imap/src/nsImapProtocol.cpp:4489
1	xul.dll	nsIMAPBodyShell::Generate	mailnews/imap/src/nsIMAPBodyShell.cpp:220
2	xul.dll	nsImapServerResponseParser::ProcessOkCommand	mailnews/imap/src/nsImapServerResponseParser.cpp:430
3	xul.dll	nsImapServerResponseParser::ParseIMAPServerResponse	mailnews/imap/src/nsImapServerResponseParser.cpp:261
4	xul.dll	nsImapProtocol::ParseIMAPandCheckForNewMail	mailnews/imap/src/nsImapProtocol.cpp:1885
5	xul.dll	nsImapProtocol::FetchMessage	mailnews/imap/src/nsImapProtocol.cpp:3573
6	xul.dll	nsImapProtocol::FetchTryChunking	mailnews/imap/src/nsImapProtocol.cpp:3609
7	xul.dll	nsImapProtocol::FallbackToFetchWholeMsg	mailnews/imap/src/nsImapProtocol.cpp:3309
8	xul.dll	nsIMAPBodyShell::Generate	mailnews/imap/src/nsIMAPBodyShell.cpp:223
9	xul.dll	nsImapProtocol::ProcessSelectedStateURL	mailnews/imap/src/nsImapProtocol.cpp:2642
10	xul.dll	nsImapProtocol::ProcessCurrentURL	mailnews/imap/src/nsImapProtocol.cpp:1724
11	xul.dll	nsImapProtocol::ImapThreadMainLoop	mailnews/imap/src/nsImapProtocol.cpp:1345
12	xul.dll	nsImapProtocol::Run	mailnews/imap/src/nsImapProtocol.cpp:1023 

4489 else
4490 m_runningUrl->AllocateCanonicalPath(
4491 folderFromParser,kOnlineHierarchySeparatorUnknown,
4492 &folderName); 

TB19.0a1 bp-3c9b0f14-6649-4152-9d5f-4530a2121119

Earliest crash with this signature is bp-645be617-d667-47a7-9284-252fc2120524 from TB12.  I can't determine that this is a regression or not.

Comment 1

[Scoobidiver (away)]

It's #9 crasher in TB 23.0b1 over the last four weeks.

Comment 2

[Wayne Mery (:wsmwk)]

#16 in TB24.0.  Definitely tracks to version 19.
But *might* be a limited number of users. Will update after socorro is fixed - Socorro column sorting broken and I'm not going to eyeball the list.

bp-75d542a7-032f-4052-b98a-2ff6f2130920
0	xul.dll	nsImapProtocol::GetMessageSize(char const *,bool)	mailnews/imap/src/nsImapProtocol.cpp
1	xul.dll	nsIMAPBodyShell::Generate(char *)	mailnews/imap/src/nsIMAPBodyShell.cpp
2	xul.dll	nsImapServerResponseParser::ProcessOkCommand(char const *)	mailnews/imap/src/nsImapServerResponseParser.cpp
3	xul.dll	nsImapServerResponseParser::ParseIMAPServerResponse(char const *,bool,char *)	mailnews/imap/src/nsImapServerResponseParser.cpp 

hg@0 4426 const char *folderFromParser = GetServerStateParser().GetSelectedMailboxName();
hg@0 4427 if (folderFromParser && messageId)
hg@0 4428 {
hg@0 4429 char *id = (char *)PR_CALLOC(strlen(messageId) + 1);
hg@0 4430 char *folderName;
ehsan@13324 4431 uint32_t size;
hg@0 4432
hg@0 4433 PL_strcpy(id, messageId);
hg@0 4434
mconley@13187 4435 nsIMAPNamespace *nsForMailbox = nullptr;
hg@0 4436 m_hostSessionList->GetNamespaceForMailboxForHost(GetImapServerKey(), folderFromParser,
hg@0 4437 nsForMailbox);
hg@0 4438
hg@0 4439
hg@0 4440 if (nsForMailbox)
hg@0 4441      m_runningUrl->AllocateCanonicalPath(
hg@0 4442           folderFromParser, nsForMailbox->GetDelimiter(),
hg@0 4443               &folderName);

Comment 3

[Wayne Mery (:wsmwk)]

earliest I can track to is build 20130117070400 19.0 beta

irving, can you suggest a cause?

https://bugzilla.mozilla.org/buglist.cgi?f1=OP&o3=anywordssubstr&list_id=8383134&resolution=FIXED&classification=Client%20Software&classification=Components&o2=anywordssubstr&f4=CP&query_format=advanced&j1=OR&f3=keywords&f2=short_desc&component=Account%20Manager&component=Backend&component=Folder%20and%20Message%20Lists&component=Networking&component=Networking%3A%20IMAP&product=MailNews%20Core&product=Thunderbird&target_milestone=Thunderbird%2019.0&target_milestone=Thunderbird%2019.0 are bugs landed for TB19...
But I haven't checked to see if what matches against how this crash is occurring. Bug 495318 ?

bugs to perhaps discount because they landed in TB17 with no known ill effects:
bug 723888
Bug 806760

Comment 4

[:Irving Reid (No longer working on Firefox)]

I can't see anything specific in the bug list that would trigger this. I suppose it could be another symptom of the same underlying problem that caused bug 723788; as with that bug, we're tripping across a null pointer deep in a call tree where we expect the field to always have a value.

We could crash-proof nsImapProtocol::GetMessageSize() by null checking m_runningUrl before the AllocateCanonicalPath() call, but I expect that would just shift the failure somewhere else.

The most unusual thing about this call tree is that we're recursing through nsIMAPBodyShell::Generate around mailnews/imap/src/nsIMAPBodyShell.cpp:220-223, which seems deeply wrong to me, but I don't understand that code well enough to know what really should be happening.

Comment 5

[:Irving Reid (No longer working on Firefox)]

Oops, s/723788/bug 723888/

Comment 6

[Wayne Mery (:wsmwk)]

(#1 imap crash)

(In reply to :Irving Reid from comment #4)
> I can't see anything specific in the bug list that would trigger this. I
> suppose it could be another symptom of the same underlying problem that
> caused bug 723788; as with that bug, we're tripping across a null pointer
> deep in a call tree where we expect the field to always have a value.
> 
> We could crash-proof nsImapProtocol::GetMessageSize() by null checking
> m_runningUrl before the AllocateCanonicalPath() call, but I expect that
> would just shift the failure somewhere else.

Yeah. 

I'll try to get someone to reproduce. Another hard slog - no one from my 10/29 contacts can do it. The only one who had a clue indicated it took a long time to "send" the message which crashed - he sent a couple others while it was in progress

Comment 7

[Wayne Mery (:wsmwk)]

I am not able to find a user testcase thus far.

Comment 8

[Hiroyuki Ikezoe (:hiro)]

(In reply to :Irving Reid from comment #4)
 
> We could crash-proof nsImapProtocol::GetMessageSize() by null checking
> m_runningUrl before the AllocateCanonicalPath() call, but I expect that
> would just shift the failure somewhere else.

I can totally agree.

But nsImapUrl::AllocateCanonicalPath() can be rewritten without m_runningUrl instance.
The method uses only a member variable (m_serverKey) of its class, which is also held in nsImapProtocol.
What do you think?

Comment 9

[:Irving Reid (No longer working on Firefox)]

That doesn't feel like the right approach here; I'm guessing that the problem is some other thread trying to cancel, close or time out this IMAP operation, and resetting m_runningUrl to NULL as part of that. If the operation we're trying to perform is partly cancelled, we should fail rather than trying to find another way to continue.

Comment 10

[Wayne Mery (:wsmwk)]

(In reply to :Irving Reid from comment #4)
> ...
> The most unusual thing about this call tree is that we're recursing through
> nsIMAPBodyShell::Generate around
> mailnews/imap/src/nsIMAPBodyShell.cpp:220-223, which seems deeply wrong to
> me, but I don't understand that code well enough to know what really should
> be happening.

Bienvenu isn't active so removing needinfo.  Irving, do you want to PM him?

Comment 11

[:Irving Reid (No longer working on Firefox)]

Another one where I think we just need to wait for someone to step up and learn the code well enough to fix it.

Comment 12

[Wayne Mery (:wsmwk)]

In case it helps, notable fixes in 

TB19 (not including uplifts)
* bug 495318 add support for LIST (SUBSCRIBED) part of IMAP LIST-EXTENDED command (RFC 5258)
* bug 723888 [regression:tb10] SyncRunnable5<nsIImapMailFolderSink, nsIImapProtocol* ... typically working with folder subscribe
* from https://bugzilla.mozilla.org/buglist.cgi?f1=short_desc&list_id=12000050&o1=nowordssubstr&resolution=FIXED&classification=Client%20Software&classification=Components&query_format=advanced&f2=OP&component=Networking%3A%20IMAP&target_milestone=Thunderbird%2019.0&product=MailNews%20Core&product=Thunderbird

TB18 (not including uplifts)
* bug 471492 [bulkoperations][regression action in 3.1?] crash [@ nsImapMailFolder::CopyMessagesOffline(nsIMsgFolder*, nsIArray*, int, nsIMsgWindow*, nsIMsgCopyServiceListener*)] when moving/deleting/copying many messages
* bug 721316 Use Gmail IMAP Extension of X-GM-MSGID, X-GM-THRID, X-GM-LABELS in addition to XLIST
* from https://bugzilla.mozilla.org/buglist.cgi?f1=short_desc&list_id=12000052&o1=nowordssubstr&resolution=FIXED&classification=Client%20Software&classification=Components&query_format=advanced&f2=OP&component=Networking%3A%20IMAP&target_milestone=Thunderbird%2018.0&product=MailNews%20Core&product=Thunderbird

Comment 13

[Kent James (:rkent)]

(In reply to :Irving Reid (No longer working on Firefox) from comment #4)
> 
> We could crash-proof nsImapProtocol::GetMessageSize() by null checking
> m_runningUrl before the AllocateCanonicalPath() call, but I expect that
> would just shift the failure somewhere else.

m_runningUrl is one of those variables, like the db in the folder, that gets reset for unknown reasons, and so code has typically added a check to prevent crashes. I don't see a good reason not to do that here as well. I'm not claiming that will fix the underlying bug, but in most new code we typically provide defensive checks, so why not here as well? It has very little risk.

Comment 14

[Wayne Mery (:wsmwk)]

m_kato, is this something you could do?

Comment 15

[Makoto Kato [:m_kato]]

null check won't good fix.  Maybe, ReleaseUrlState is called by any reason, then m_runningURl is null.

But I cannot find root cause for this issue.

Comment 16

[Wayne Mery (:wsmwk)]

Alfred, is this something you could look at?

Most crash comments mention attachments

Comment 17

[Wayne Mery (:wsmwk)]

pretty similar to bug 558452

Comment 18

[Richard Leger]

FYI, issue still happening recently...
bp-de868212-79f2-4569-9829-5fc9e2170228   28/02/2017

Comment 19

[Wayne Mery (:wsmwk)]

Richard, are you/your people still seeing crashes?

Comment 20

[Richard Leger]

(In reply to Wayne Mery (:wsmwk) from comment #19)
> Richard, are you/your people still seeing crashes?

Since bug report bp-b7d62762-9429-46c9-8833-477de0180226 26/02/2018 I haven't seen a crash yet. 
The crash occurred while I was trying go move folders in my mailbox (IMAP)... also afterwards I had issue to list content of subfolder but I don't know if it is linked to it or not. Basically clicking on a folder was not changing the view to show the folder content. That happened coupled of time already randomly... forcing me to quit and re-start Thunderbird to fix issue...

Comment 21

[Wayne Mery (:wsmwk)]

Do you have people on beta 59?

Comment 22

[Wayne Mery (:wsmwk)]

> Since bug report bp-b7d62762-9429-46c9-8833-477de0180226 26/02/2018 I haven't seen a crash yet. 

bp-b7d62762-9429-46c9-8833-477de0180226  is  [@ shutdownhang | arena_t::MallocSmall | nsCOMPtr_base::assign_with_AddRef | mozilla::EventQueue::PutEvent ] which does not have a bug report

Richard, do you have people on beta 59?

Comment 23

[Richard Leger]

I am using 59 beta branch on my laptop currently and will upgrade to 60 when available this week... will send bug report if any crash occurs...

Comment 24

[Wayne Mery (:wsmwk)]

(In reply to Richard Leger from comment #23)
> I am using 59 beta branch on my laptop currently and will upgrade to 60 when
> available this week... will send bug report if any crash occurs...

How is it working out?

Comment 25

[Richard Leger]

No crash reported since 19/03/2018... 

I have been using 60.0b5 (32-bit) for one to two weeks (not recalling exactly when update occurred) and no crash yet. 

The LDAP Address-book issue (addressed in a separate bug) has not be solved yet though. 

Also noted but not necessarily introduced in the 60.x branch version Thunderbird performance is obviously not improving. Lag overtime and especially delay at start-up is a real pain... between Inbox indexing and Lightning network calendar items populating in the UI... it takes me easily 8-10mn waiting before I can do anything and read my first email :-(( and that also is not improving over time...

After May 9, 2017 when the Mozilla Foundation had finally decided to serve as the legal and fiscal home for the Thunderbird project, and have Thunderbird migrated off Mozilla Corporation infrastructure, separating the operational aspects of the project, I had great hope for Thunderbird development... but as of today, I don't feel this decision had any impact on improving TB, and I even start to wonder if I should consider testing other email clients and move away from Thunderbird all together... despite great works from developers to keep it afloat...

Comment 26

[Wayne Mery (:wsmwk)]

(In reply to Richard Leger from comment #25)
> No crash reported since 19/03/2018... 
> 
> I have been using 60.0b5 (32-bit) for one to two weeks (not recalling
> exactly when update occurred) and no crash yet. 

That's a nice change :)


> Also noted but not necessarily introduced in the 60.x branch version
> Thunderbird performance is obviously not improving. Lag overtime and
> especially delay at start-up is a real pain... between Inbox indexing and
> Lightning network calendar items populating in the UI... it takes me easily
> 8-10mn waiting before I can do anything and read my first email :-(( and
> that also is not improving over time...

Not related to this bug so we should deal with this elsewhere, but I haven't seen you mention performance issues since 2016 in an old bug report.  A starting point is https://wiki.mozilla.org/Thunderbird:Testing:Memory_Usage_Problems  Note, a testcase where calendar addon is not involved would be more interesting.


> After May 9, 2017 when the Mozilla Foundation had finally decided to serve
> as the legal and fiscal home for the Thunderbird project, and have
> Thunderbird migrated off Mozilla Corporation infrastructure, separating the
> operational aspects of the project, 

It's off topic for this bug, but I don't know why you would think non-code related changes (which all of those are) would impact code development.

Comment 27

[Wayne Mery (:wsmwk)]

(In reply to Wayne Mery (:wsmwk) from comment #26)
> (In reply to Richard Leger from comment #25)
> > No crash reported since 19/03/2018... 
> > 
> > I have been using 60.0b5 (32-bit) for one to two weeks (not recalling
> > exactly when update occurred) and no crash yet. 
> 
> That's a nice change :)

20 days more and no reports as far as I can tell. That's impressive.

But still a #5 crash for 60.0b6 release :(

Comment 28

[Wayne Mery (:wsmwk)]

Several users with this signature also crash OOM. Example  bp-8f31ab8e-ec5d-420c-9bb6-2123e0180613 OOM | small  and bp-ce74a455-f4c0-431d-8bb0-931c40180531  nsImapProtocol::GetMessageSize

Comment 29

[Richard Leger]

FYI, today I have reverted some settings in my TB to their factory default. In case that may have (had) an effect on this bug or not... https://bugzilla.mozilla.org/show_bug.cgi?id=1264302#c26

Comment 30

[Wayne Mery (:wsmwk)]

No change in crash rate of non-release builds in recent months (despite Richard no longer crashing), per graph https://crash-stats.mozilla.com/signature/?release_channel=%21release&signature=nsImapProtocol%3A%3AGetMessageSize&date=%3E%3D2018-04-30T19%3A31%3A31.000Z&date=%3C2018-07-31T19%3A31%3A31.000Z&_columns=date&_columns=product&_columns=version&_columns=build_id&_columns=platform&_columns=reason&_columns=address&_columns=install_time&_sort=-date&page=1#graphs

Comment 31

[Richard Leger]

This crash bp-174944e6-3f59-42c9-b758-c9fcb0180823 occurred in TB 60.0b10 (32-bit) and seems linked to this bug.

After hitting reply button on a message, I was typing text in body while TB crashed unexpectedly...

Before that, TB was very slow and erratic - not loading (blank) or very slow loading of message content in the Inbox view...

Before that, I tried to send a big message that sent ok, but would not save to Sent items again... waited for a long time but still not saving or cancelling processing by itself... finally despite not being disconnected (I could still access server by other means - ping response time to server OK) I restarted my VPN connection (over 4G conn) successfully... and browse multiple folders in my TB Inbox to trigger IMAP conn and login to the server... after a while TB manage to delete my sent msg in Draft (as per status bar indication) which allowed TB to re-attempt automatically to save the sent msg into Sent folder (on the server) which this time worked successfully. No issue reported on the IMAP server at the time.

The slow loading of email content has also been noticed randomly on normal conn (ADSL without VPN), need to switch between multiple message to re-trigger the loading... happens to all type of message, but especially noticed if big attachment are involved in the message... msg content remain blank till attachments are loaded...

Also noted during the same day:
- TB main UI windows disappeared twice by itself (look like closed itself somehow) while other TB windows (edit msg, calender reminders, etc...) remained opened.
- When closing all the remaining Windows and try to re-opened TB, it failed saying it was already running... process still appearing in Task Manager with memory keeping increasing over time... had to kill process in order to be able to re-open TB.

One positive note is that I seems to have notice improvement in speed when TB starts up, Inbox still not updating while Calendar stuff loading but it now seems quicker till the point I can read emails... to be confirmed. Could also be due to some improvement in Windows OS (or video driver?) as my machine has slightly increase in speed recently especially to open software and windows in general (more snappy). Not directly relevant to this bug but worth mentioning...

Hope that help.

Comment 32

[Richard Leger]

(In reply to Richard Leger from comment #31)

> One positive note is that I seems to have notice improvement in speed when
> TB starts up, Inbox still not updating while Calendar stuff loading but it
> now seems quicker till the point I can read emails... to be confirmed. 

Confirmed. It now takes about ~40seconds (still long but workable) from click on TB icon to being able to read first email... compared to many minutes previously... that is a huge improvement. 

I am wondering if reducing the number of emails from ~8000 to ~3500 in Inbox (and ~13000 to ~8000 in Sent) may have helped, as it reduce the indexing requirement at start-up... just a thought... 

Though as noticed, Activity Manager now remains empty during the start-up process so it might mean that TB no longer try to do indexing immediately at start-up anymore...

BIG Thanks to all the developers that work on improving TB performance... you make users happy!

Comment 33

[:aceman]

Those numbers of messages are peanuts to TB, you can easily have 100000 per folder and opening such oflder should take 1-2 seconds. Also there should ideally be NO indexing activity on the startup. New messages should be indexed once upon arrival with the Global indexer (if you have it enabled in Options) and then no more.
Unless there is a bug :)
Or you mean some long synchronizing of IMAP folders with the server.

Comment 34

[Wayne Mery (:wsmwk)]

This and bug 558452 are just as strong in version 60 (no surprise).

As for performance, there should be further imap related speed improvements in the future - hopefully either 60.3.0 or 60.4.0.

Comment 35

[Magnus Melin [:mkmelin]]

(In reply to Richard Leger from comment #31)
> This crash bp-174944e6-3f59-42c9-b758-c9fcb0180823 occurred in TB 60.0b10
> (32-bit) and seems linked to this bug.

https://hg.mozilla.org/releases/comm-esr60/annotate/tip/mailnews/imap/src/nsImapProtocol.cpp#l4575

->  m_hostSessionList->GetNamespaceForMailboxForHost(GetImapServerKey(), folderFromParser,


m_hostSessionList is null then

Comment 36

[Magnus Melin [:mkmelin]]

Attachment: bug825513_GetMessageSize_crash.patch

Add null checks and see where that takes us.

Comment 37

[Jorg K (CEST = GMT+2)]

Attachment: 825513-crash.patch

Can we do a bit of boy-scout clean-up while we're here? This function looked just horrific.

(Unrelated: What happened to bug 1444389. And any cycles for bug 1495898?)

Comment 38

[Magnus Melin [:mkmelin]]

Comment on attachment 9014906 [details] [diff] [review]
825513-crash.patch

Review of attachment 9014906 [details] [diff] [review]:
-----------------------------------------------------------------

Heh, that's quite an ugly function

::: mailnews/imap/src/nsImapProtocol.cpp
@@ +4664,5 @@
>    const char *folderFromParser = GetServerStateParser().GetSelectedMailboxName();
> +  if (!folderFromParser || !messageId || !m_runningUrl || !m_hostSessionList)
> +    return 0;
> +
> +  char *id = (char *)PR_CALLOC(strlen(messageId) + 1);

If you like feel free to clean up the id and folderName to be nsAutoCString too

Comment 39

[Jorg K (CEST = GMT+2)]

Attachment: 825513-crash.patch (v2)

Hmm, I didn't change anything to auto-strings, but I removed the duplicating of the ID passed in :-(

Comment 40

[Jorg K (CEST = GMT+2)]

Attachment: 825513-crash.patch (v2b)

Can be simplified even further.

Comment 41

[Jorg K (CEST = GMT+2)]

Attachment: 825513-crash.patch (v2c)

Initialising the folder name is also a good idea since there is no error checking on the call that populates it.

Comment 42

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/comm-central/rev/cd7b757fff58
Fix crash in nsImapProtocol::GetMessageSize() by adding null check for m_runningUrl && m_hostSessionList. r=jorgk

Comment 43

[Jorg K (CEST = GMT+2)]

TB 60.3 ESR:
https://hg.mozilla.org/releases/comm-esr60/rev/64a6f36df710

Comment 44

[Jorg K (CEST = GMT+2)]

TB 63.0b2:
https://hg.mozilla.org/releases/comm-beta/rev/872d9710ea55

Comment 45

[Wayne Mery (:wsmwk)]

Overall the crash rate has increased 5-10% over the past 6 months.

But, because of their high crash rates, we should have very quick insight with beta 64 (3-4 days) and 60.3.0 (within 1-2 days) as to whether this patch helps.

Comment 46

[Wayne Mery (:wsmwk)]

Preliminary, crsah rate might be down slightly, but certainly not significantly.  That is with only maybe 15-20% of users on 60.3.x.  We have more serious updating to happen
https://crash-stats.mozilla.com/signature/?product=Thunderbird&signature=nsImapProtocol%3A%3AGetMessageSize&date=%3E%3D2018-08-16T04%3A56%3A30.000Z&date=%3C2018-11-16T03%3A56%3A30.000Z#graphs

Comment 47

[Wayne Mery (:wsmwk)]

recent builds
bp-8acb8015-f617-4390-b678-096a20181115 60.3.1
bp-1a474dcf-5cc5-4538-8d42-8dd4f0181115 60.3.0

Comment 48

[Jorg K (CEST = GMT+2)]

uint32_t nsImapProtocol::GetMessageSize(const char * messageId, bool idsAreUids)
{
  const char *folderFromParser = GetServerStateParser().GetSelectedMailboxName();
  if (!folderFromParser || !messageId || !m_runningUrl || !m_hostSessionList)
    return 0;

  char *folderName = nullptr;
  uint32_t size;

  nsIMAPNamespace *nsForMailbox = nullptr;
  m_hostSessionList->GetNamespaceForMailboxForHost(GetImapServerKey(), <=== line 4574
                                                   folderFromParser,
                                                   nsForMailbox);

I don't see how that line can crash now since we're testing for null right above.

But maybe m_hostSessionList has some stale/free'ed value, see the 0xffffffffe5e5e5e5 in the reports.

I don't particularly like this line in the code:
  m_hostSessionList = aHostSessionList; // no ref count...host session list has life time > connection
And in the .h file:
  nsIImapHostSessionList * m_hostSessionList;

Something like this is asking for trouble. So something our forebears didn't consider :-(

Shall we file a new bug now?

Comment 49

[Magnus Melin [:mkmelin]]

Yes please.