Closed Bug 1794997 Opened 2 years ago Closed 2 years ago

Sending of news message fails after going back online

Categories

(MailNews Core :: Networking: NNTP, defect)

Thunderbird 102
defect

Tracking

(thunderbird_esr102+ fixed, thunderbird107 fixed)

RESOLVED FIXED
108 Branch
Tracking Status
thunderbird_esr102 + fixed
thunderbird107 --- fixed

People

(Reporter: b4, Assigned: rnons)

References

(Blocks 1 open bug, Regression)

Details

(Keywords: regression)

Attachments

(2 files)

User Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/106.0.0.0 Safari/537.36

Steps to reproduce:

Start TB, go offline. Compose news message. "Send Later". Go online.

Actual results:

Prompt to send message, when accepted:
Sending of the message failed.
The message could not be posted because connecting to the news server failed. The server may be unavailable or is refusing connections. Please verify that your news server settings are correct and try again.

Error console:
TypeError: this._copyProcess is null sendLater.jsm:236:13
mailnews.send: Sending failed; The message could not be posted because connecting to the news server failed. The server may be unavailable or is refusing connections. Please verify that your news server settings are correct and try again., exitCode=2153066726, originalMsgURI=undefined MessageSend.jsm:335:27

Expected results:

Message should have been sent.

File > Send Unsent Messages mostly doesn't work in this situation at first, the message is sent after several tries.

Blocks: tb102found
Keywords: regression

Seems to work me, sent a message to aioe.test.

We're using eternal-september.org which requires authentication. As we wrote, maybe not 100% reproducible, but certainly happening after a fresh start. Other users on the server complain about the issue, too, in fact, we're just communication their complaints. Besides, the TypeError is very real.

I can confirm that there is something wrong here.

The message in the outbox has the correct ID in the X-Identity-Key: header. But when I go back online (or just do a "Send Unsent Messages"), I get the login dialog for another account that doesn't even carry the group and for which I happen not to have any credentials saved.
Not even the email address matches.

Unfortunately, the NNTP log is not helpful at all.

I can't reproduce it in another profile.

Assignee: nobody → remotenonsense
Status: UNCONFIRMED → ASSIGNED
Ever confirmed: true
Regressed by: nntp-js

The patch fixes comment 3, not sure about the original reported bug.

(In reply to Ping Chen (:rnons) from comment #6)

The patch fixes comment 3, not sure about the original reported bug.

Thanks.
I do not see the error message from comment #0.
Could it be the result of using an invalid or inappropriate ID?

If not, sorry for hijacking the bug.

(In reply to Ping Chen (:rnons) from comment #6)

The patch fixes comment 3, not sure about the original reported bug.

When applying the (rebased) patch to a 102 build, it doesn't fix the problem. Some observations:

Removing that line 269 slightly changes the behaviour reported in comment #0: The TypeError no longer occurs at line 236, but sending still fails. So there seem to be two issues here: 1) For some reason which wasn't addressed yet, only in the JS module sending fails after going back online. 2) After that, the error handling leads to an additional TypeError.

Reproducing the issue with both send and nntp loglevels at All, we see:

10:15:12.007 mailnews.send: Delivering news message MessageSend.jsm:1084:25
10:15:12.007 mailnews.send: notifyListenerOnStartSending MessageSend.jsm:373:25
10:15:12.008 mailnews.nntp: Connecting to news://news.eternal-september.org:119 NntpClient.jsm:103:20
10:15:12.099 mailnews.nntp: Connected NntpClient.jsm:121:18
10:15:12.119 mailnews.nntp: S: 200 reader01.eternal-september.org InterNetNews NNRP server INN 2.8.0 (20220715 snapshot) ready (posting ok)

NntpClient.jsm:144:18
10:15:12.120 mailnews.nntp: C: POST NntpClient.jsm:251:20
10:15:12.161 mailnews.nntp: S: 340 Ok, recommended Message-ID <tidq6f$2k8q6$1@anonymous.dont-email.me>

NntpClient.jsm:144:18
10:15:12.205 mailnews.nntp: S: 441 You are not allowed to post to alt.de.test

NntpClient.jsm:144:18
10:15:12.206 mailnews.nntp: Done with status=2147500037 NntpClient.jsm:829:18
10:15:12.206 mailnews.send: OnStopRunningUrl; exitCode=2147500037 MessageSend.jsm:1329:25
10:15:12.206 mailnews.send: Delivery exit processing; exitCode=2153066726 MessageSend.jsm:552:25
10:15:12.206 mailnews.send: notifyListenerOnStopSending; status=2153066726 MessageSend.jsm:500:25

So the server indeed returns 441 You are not allowed to post to alt.de.test, however, in general, the account is set up to post there, as this successful log shows when posting while already online:

10:20:01.354 mailnews.send: Delivering news message MessageSend.jsm:1084:25
10:20:01.355 mailnews.send: notifyListenerOnStartSending MessageSend.jsm:373:25
10:20:01.355 mailnews.nntp: C: POST NntpClient.jsm:251:20
10:20:01.398 mailnews.nntp: S: 340 Ok, recommended Message-ID <tidqfg$2k8q5$3@dont-email.me>

NntpClient.jsm:144:18
10:20:01.689 mailnews.nntp: S: 240 Article received <tidqfg$2k8q5$3@dont-email.me>

NntpClient.jsm:144:18
10:20:01.689 mailnews.nntp: Done with status=0 NntpClient.jsm:829:18

Adding

    this._userIdentity = userIdentity;
    console.log("=== 1", userIdentity, accountKey);
    this._accountKey = this._getAccountKey(accountKey, userIdentity);
    console.log("=== 2", userIdentity, accountKey);

to createAndSendMessage we see correct identity and account key when sending online and also when coming back from offline. So the wrong identity/account doesn't appear to be the issue here (and yes, the bug was hijacked ;-)).

This is a bit puzzling. Looking closely at the debug output, in the bad case there the connection is established first with server reply S: 200, which doesn't happen in the good case since the connection already exists.

If looks like establishing the connection after going back online doesn't work. This suspicion is also confirmed by:
Go offline, prepare message, send later, go online, send unsent - failing
Go offline, prepare message, send later, go online, do not send unsent yet, get messages, sent unsent messages - working.

Maybe the connection after going back online isn't established with the correct credentials. eternal-september.org offers two sets of newsgroups: Its internal ones for unauthenticated users and the "world's" newsgroups for authenticated users. Unauthenticated users can't post to alt.de.test.

Thanks for the analysis, I updated my patch to authenticate if needed before sending POST request. Please try again.

This works now (after solving minor merge conflict with https://hg.mozilla.org/comm-central/rev/abcaf011c387#l2.211).
Please consider removing
https://searchfox.org/comm-esr102/rev/c98398fe1f2e4652e08c0f369aea13b92a03ff8f/mail/components/activity/modules/sendLater.jsm#269
since this will lead to TypeError in case of a real failure.

Target Milestone: --- → 108 Branch

Pushed by mkmelin@iki.fi:
https://hg.mozilla.org/comm-central/rev/5937332784b7
Get account from identity to prevent sending with the wrong account. r=mkmelin

Status: ASSIGNED → RESOLVED
Closed: 2 years ago
Resolution: --- → FIXED

Comment on attachment 9298732 [details]
Bug 1794997 - Get account from identity to prevent sending with the wrong account. r=mkmelin

[Triage Comment]
Approved for beta

[Approval Request Comment]
Regression caused by (bug #): nntp-js
User impact if declined: Sending offline news messages throws error
Testing completed (on c-c, etc.):
Risk to taking this patch (and alternatives if risky): Medium risk - comment 11 should be addressed prior to esr102 uplift. Ping?

Flags: needinfo?(remotenonsense)
Attachment #9298732 - Flags: approval-comm-esr102?
Attachment #9298732 - Flags: approval-comm-beta+

The patch contains a fix to the TypeError mentioned in comment 11, not the same approach though, thanks.

Flags: needinfo?(remotenonsense)

Comment on attachment 9298732 [details]
Bug 1794997 - Get account from identity to prevent sending with the wrong account. r=mkmelin

[Triage Comment]
Approved for esr102

Attachment #9298732 - Flags: approval-comm-esr102? → approval-comm-esr102+

Ping - The test added in this bug fails on comm-esr102: https://treeherder.mozilla.org/jobs?repo=comm-esr102&selectedTaskRun=fMbgR9agToCjQLzua80pHw.0

JavaScript error: resource:///modules/NntpService.jsm, line 62: NS_NOINTERFACE: Component returned failure code: 0x80004002 (NS_NOINTERFACE) [nsISupports.QueryInterface]

I tried force-setting mailnews.nntp.jsmodule=true in xpcshell.ini for that test file, it didn't help. Can you take a look?

Flags: needinfo?(remotenonsense)
Attached patch 1794997-esr-test-fix.patch (deleted) — Splinter Review

The problem is https://searchfox.org/comm-esr102/rev/ba62f1e53b7cb7c1df37b51c72ffe18dcbf0adf5/mailnews/base/src/nsMsgAccountManager.cpp#945-946 loads NntpService.jsm, but the test needs to use MockNntpService, thanks.

Flags: needinfo?(remotenonsense)
Attachment #9302991 - Flags: review?(rob)
Comment on attachment 9302991 [details] [diff] [review] 1794997-esr-test-fix.patch Review of attachment 9302991 [details] [diff] [review]: ----------------------------------------------------------------- Makes sense. Ran test on a local build to verify. Thanks!
Attachment #9302991 - Flags: review?(rob)
Attachment #9302991 - Flags: review+
Attachment #9302991 - Flags: approval-comm-esr102+
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: