1646901 - Error: Channel closing: too late to send/recv, messages will be lost

Status: NEW

(Thunderbird :: General, defect)

Description

[ISHIKAWA, Chiaki]

I am using 64-bit thunderbird 68.9.0 (64-bit) under linux amd64 (Debian GNU/Linux.)

I saw the following messages on the tty window where I start TB manually from the command line.

###!!! [Child][MessageChannel] Error: (msgtype=0x6B0029,name=PNecko::Msg_RemoveRequestContext) Channel closing: too late to send/recv, messages will be lost
###!!! [Child][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
###!!! [Child][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
###!!! [Child][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
###!!! [Child][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
###!!! [Child][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost

I am not sure when/why the message especially, the "messages will be lost" line appears.
I saw them before and I believe I saw them in mochitest/xpcshell-tests logs, too.

I think I often saw them when I was about to shutdown TB. But this time, I saw the message from a running TB. (Oh wait, strictly speaking, I have run this instance of TB since yesterday under linux that runs inside VirtualBox hosted under Windows 10.
I kept both Windows 10 and virtualbox running overnight.)

Honestly speaking, a mere mortal cannot figure out what the message means. It tells me "Message will be lost", but it does not suggest WHAT CHANNEL is closing and so there is nothing I can try to mitigate the issue if any serious harm is done.

Beside, so far, I have no idea if an e-mail message has been lost or not (if a message is lost there is no way a user can tell because TB does not tell us about it as far as I can see.)

In a nutshell, the error message ought be modified for the better to state

• what communication channel is closing,
• and for what purpose the send/recv was used,
• what messages will be lost (are these e-mail messages [if so, very bad] or interprocess communication messages or what?),
• what exactly bad things may happen if, say, interprocess communication channel is closed, etc.

The messages are disturbing enough and so a better/clear description
is desirable.

Comment 1

[Magnus Melin [:mkmelin]]

I think this is referring to the Inter Process Communcation, and has nothing to do with mails.
Could be very expected at shutdown. Anyway, not much Thunderbird could/would do about this.

Comment 2

[ISHIKAWA, Chiaki]

(In reply to Magnus Melin [:mkmelin] from comment #1)

I think this is referring to the Inter Process Communcation, and has nothing to do with mails.
Could be very expected at shutdown. Anyway, not much Thunderbird could/would do about this.

I see. Thank you for the clarification.
I checked and I realized the error messages last fall.
Mozilla software (FF and TB alike) needs better shutdown sequences IMHO.

Because of the frequent crash during shutdown, I keep TB running under Windows (by sleeping windows if necessary).
Only under linux, I sometimes shut it down due to some debugging reasons.

Anyway, I keep this bug opened so that whoever is responsible for IPC handling may realize this and make the shutdown process cleaner one way or the other.
(I mean the callers of the low-level IPC need to be shutdown first, by cancelling send/recv operations in flight if necessary, and THEN
low-level IPC mechanism be shutdown next.)

Looking at the log of mochitest with DEBUG BUILD of TB during shutdown makes one dizzy. There are so many warnings. No wonder real world crash happened often before during shutdown time. :-(

Comment 3

[Intermittent Failures Robot]

1 failures in 4100 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform breakdown:

• linux1804-64-qr: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1646901&startday=2020-08-17&endday=2020-08-23&tree=all

Comment 4

[Intermittent Failures Robot]

1 failures in 1479 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform breakdown:

• linux1804-64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1646901&startday=2020-11-23&endday=2020-11-29&tree=all

Comment 5

[Wayne Mery (:wsmwk)]

Does this reproduce with a newer version?

Comment 6

[ISHIKAWA, Chiaki]

I observed the particular errors in my local log in May 13 of 2023, this year.
THAT particular messages are not seen in June 11 of 2023 and later (!)
So far, so good.

HOWEVER, the following similar messages persist until last month and I have not been able to run full local tests adequately due to day time work and the merging of BenC's patch for uniform "From:" line handling, etc.

Mochitest:

65:54.18 GECKO(605436) [Child 608411, Main Thread] WARNING: IPC Connection Error: [Child][PContentChild] Send(msgname=PContent::Msg_AsyncMessage) Channel closing: too late to send, messages will be lost: file /NEW-SSD/NREF-COMM-CENTRAL/mozilla/ipc/glue/MessageChannel.cpp:1933

xpcshell-test

02:56.02 pid:122493 [Child 122650, Main Thread] WARNING: IPC Connection Error: [Child][PContentChild] Send(msgname=PContent::Msg_AsyncMessage) Channel closing: too late to send, messages will be lost: file /NEW-SSD/NREF-COMM-CENTRAL/mozilla/ipc/glue/MessageChannel.cpp:1933

Not that many this time around. Only 4 for Mochitest, and 2 for xpcshell test.
Manageable or may be easy to debug for someone in the know.

Comment 7

[ISHIKAWA, Chiaki]

For those curious, the following shows the tests that produced the messages in the last xpcshell and mochitest log that show the errors in November.

egrep -a "(TEST[-_]START|TEST[-_]END|TEST[-_]OK|too late to send)" log1613-mochitest.txt log1610-xpcshell.txt  | gawk -f ~/Dropbox/TB-DIR/ignore-immediate-test-start-and-end-pairs.awk

log1613-mochitest.txt:65:42.86 TEST_START: comm/mail/components/extensions/test/browser/browser_ext_commands_execute_message_display_action.js
log1613-mochitest.txt:65:54.18 GECKO(605436) [Child 608411, Main Thread] WARNING: IPC Connection Error: [Child][PContentChild] Send(msgname=PContent::Msg_AsyncMessage) Channel closing: too late to send, messages will be lost: file /NEW-SSD/NREF-COMM-CENTRAL/mozilla/ipc/glue/MessageChannel.cpp:1933
log1613-mochitest.txt:65:55.09 TEST_END: Test OK. Subtests passed 19/19. Unexpected 0
log1613-mochitest.txt:67:59.85 TEST_START: comm/mail/components/extensions/test/browser/browser_ext_composeScripts.js
log1613-mochitest.txt:68:23.72 GECKO(605436) [Child 610084, Main Thread] WARNING: IPC Connection Error: [Child][PContentChild] Send(msgname=PContent::Msg_AsyncMessage) Channel closing: too late to send, messages will be lost: file /NEW-SSD/NREF-COMM-CENTRAL/mozilla/ipc/glue/MessageChannel.cpp:1933
log1613-mochitest.txt:68:30.15 TEST_END: Test OK. Subtests passed 119/119. Unexpected 0
log1613-mochitest.txt:70:29.64 TEST_START: comm/mail/components/extensions/test/browser/browser_ext_compose_begin_forward.js
log1613-mochitest.txt:70:54.18 GECKO(605436) [Child 610822, Main Thread] WARNING: IPC Connection Error: [Child][PContentChild] Send(msgname=PContent::Msg_AsyncMessage) Channel closing: too late to send, messages will be lost: file /NEW-SSD/NREF-COMM-CENTRAL/mozilla/ipc/glue/MessageChannel.cpp:1933
log1613-mochitest.txt:70:55.13 TEST_END: Test OK. Subtests passed 77/77. Unexpected 0
log1613-mochitest.txt:75:20.70 TEST_START: comm/mail/components/extensions/test/browser/browser_ext_compose_saveTemplate.js
log1613-mochitest.txt:75:39.09 GECKO(605436) [Child 612391, Main Thread] WARNING: IPC Connection Error: [Child][PContentChild] Send(msgname=PContent::Msg_AsyncMessage) Channel closing: too late to send, messages will be lost: file /NEW-SSD/NREF-COMM-CENTRAL/mozilla/ipc/glue/MessageChannel.cpp:1933
log1613-mochitest.txt:76:03.76 TEST_END: Test OK. Subtests passed 122/122. Unexpected 0
log1610-xpcshell.txt:02:53.32 TEST_START: xpcshell-local.ini:comm/mail/components/extensions/test/xpcshell/test_ext_folders_mv3.js
log1610-xpcshell.txt:02:56.02 pid:122493 [Child 122650, Main Thread] WARNING: IPC Connection Error: [Child][PContentChild] Send(msgname=PContent::Msg_AsyncMessage) Channel closing: too late to send, messages will be lost: file /NEW-SSD/NREF-COMM-CENTRAL/mozilla/ipc/glue/MessageChannel.cpp:1933
log1610-xpcshell.txt:02:57.52 TEST_END: Test PASS. Subtests passed 1518/1518. Unexpected 0
log1610-xpcshell.txt:03:16.59 TEST_START: xpcshell-local.ini:comm/mail/components/extensions/test/xpcshell/test_ext_messages_get.js
log1610-xpcshell.txt:03:18.23 pid:123475 [Child 123603, Main Thread] WARNING: IPC Connection Error: [Child][PContentChild] Send(msgname=PContent::Msg_AsyncMessage) Channel closing: too late to send, messages will be lost: file /NEW-SSD/NREF-COMM-CENTRAL/mozilla/ipc/glue/MessageChannel.cpp:1933
log1610-xpcshell.txt:03:20.85 TEST_END: Test PASS. Subtests passed 716/716. Unexpected 0
ishikawa@ip030:/FF-NEW$ ishikawa@ip030:/FF-NEW$ 

Comment 8

[ISHIKAWA, Chiaki]

The comment here may shed some light on the issue: well, at least, how to debug this possibly.
https://searchfox.org/comm-central/source/mozilla/ipc/docs/processes.rst#1144

Comment 9

[ISHIKAWA, Chiaki]

(In reply to ISHIKAWA, Chiaki from comment #6)

I observed the particular errors in my local log in May 13 of 2023, this year.
THAT particular messages are not seen in June 11 of 2023 and later (!)
So far, so good.

Actually, my observation was premature.
It came back with vengeance.
The following list shows the log files and its time stamp when the messages were observed. I list the files created after June 2023.

   ...
Jul 17  2023 log1593-xpcshell.txt
Jul 20  2023 log1595-mochitest.txt
Jul 28  2023 log1596-mochitest.txt
Jul 28  2023 log1597-mochitest.txt
Aug  3  2023 log1599-mochitest.txt
Oct 10  2023 log1600-xpcshell.txt
Oct 12  2023 log1601-mochitest.txt
Oct 16  2023 log1602-xpcshell.txt
Oct 17  2023 log1603-mochitest.txt
Oct 21  2023 log1604-mochitest.txt
Nov  4  2023 log1605-mochitest.txt
Oct 26  2023 log1605-xpcshell.txt
Nov  5  2023 log1608-mochitest.txt
Nov 12  2023 log1609-mochitest.txt
Nov 17  2023 log1610-xpcshell.txt
Nov 19  2023 log1611-mochitest.txt
Nov 24  2023 log1612-mochitest.txt
Nov 28  2023 log1613-mochitest.txt
Jan 10  2024 log1625-xpcshell-gcc-buffered.txt
Jan 28  2024 log1627-xpcshell.txt
Jan 28  2024 log1628-mq22-xpcshell.txt
Jan 29  2024 log1631-mq22-xpcshell-partial.txt
Jan 29  2024 log1632-mq55-xpcshell-partial.txt
Jan 30  2024 log1635-mq35-xpcshell-partial.txt
Feb  3  2024 log1639-mq23-xpcshell-partial.txt
Feb  5  2024 log1640-mq35-xpcshell-partial.txt
Feb 13  2024 log1644-mq23-xpcshell-partial.txt
Feb 19  2024 log1648-mq24-xpcshell-partial.txt
Feb 22  2024 log1650-mqALL-xpcshell-partial.txt
Mar 23  2024 log1658-mochitest.txt
Jun  7 06:13 log1659-mochitest.txt
Apr  8  2024 log1661-xpcshell-faulure-rerun.txt
Apr 23  2024 log1663-xpcshell-add.txt
May  3  2024 log1665-xpcshell.txt
May  9 11:05 log1667-xpcshell-rerun.txt
May 31 04:05 log1670-xpcshell.txt
Jun  7 17:35 log1674-mochitest.txt
Jun 21 00:48 log1682-xpcshell.txt
Jun 25 10:38 log1685-mochitest.txt
Jul  5 11:58 log1687-xpcshell-rerun.txt
Jul  9 17:46 log1690-short-read-mochitest.txt
Jul 11 10:10 log1697-mochitest.txt
Jul 14 02:27 log1700-xpcshell-add.txt
Jul 18 01:31 log1701-xpcshell.txt
Jul 18 01:58 log1702-xpcshell-rerun.txt
Jul 24 11:37 log1707-mochitest.txt

This is from my local test under Debian GNU/Linux.
Funny, I have not seen the message(s) since the end of July this year. My local log file is now at log1766 and so it is quite likely
somehow the message under linux has been suppressed for now.
(There are a timestamp reversal. The date/time of the modification/creation does not follow the lexicographical order.
This is because sometimes while I am looking at the log files, I accidentally touch the content.)
The message may be likely to be persistent on other platforms like macos or windows as the comment in the link in comment 8 suggests.