1824377 - Cannot do NNTP with mailnews.nntp.jsmodule = TRUE using newsxs.nl

Status: RESOLVED FIXED

(MailNews Core :: Networking: NNTP, defect)

Description

[PeterO]

User Agent: Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:104.0) Gecko/20100101 Firefox/104.0

Steps to reproduce:

Using TB 102.7.1 (64-bit) accessing NTTP server with (standard) mailnews.nntp.jsmodule set to TRUE

Actual results:

Nothing, newgroups are not recreshed, accessed nor accessible.
remoeving, adding or reset TB or account, has no effect.

Expected results:

Reading newsgroups & contents that adhere to strict NNTP standards.
By setting mailnews.nntp.jsmodule = FALSE , I can access newserver and groups.

Comment 1

[Wayne Mery (:wsmwk)]

Please specify the exact server and all settings and newsgroups being specified.

Comment 2

[Wayne Mery (:wsmwk)]

And, what you see in Tools > Dev > error console

Comment 3

[PeterO]

Well, I'm using in a standard way the server at adress 'reader2.newsxs.nl: 119'

When I activate mailnews.nntp.jsmodule = TRUE , nothing relevants is seen toolsin error console. I've done also a packet-trace and the're zero/zip/nada packet. It appears to me that except a waiting-mouse, nothing i happening at any level.
Note: also creating/removing account(s), restarts and so on, has no effect.

When I deactivate mailnews.nntp.jsmodule = FALSE , nothing relevants is seen error console and the normal NNTP conversation (packet trace) sequence appears:
641 2023-03-24 18:09:40,238618430 94.232.116.122 192.168.1.88 NNTP 89 ✓ Response: 200 Welcome to Newsxs
711 2023-03-24 18:09:40,295040566 192.168.1.88 94.232.116.122 NNTP 79 ✓ Request: MODE READER
714 2023-03-24 18:09:40,296630798 94.232.116.122 192.168.1.88 NNTP 108 ✓ Response: 480 Authentication required for command.
763 2023-03-24 18:09:40,310000988 192.168.1.88 94.232.116.122 NNTP 99 ✓ Request: AUTHINFO user [e-mail]
777 2023-03-24 18:09:40,317307315 94.232.116.122 192.168.1.88 NNTP 82 ✓ Response: 381 Need more.
796 2023-03-24 18:09:40,340924191 192.168.1.88 94.232.116.122 NNTP 88 ✓ Request: AUTHINFO pass password
878 2023-03-24 18:09:40,461951148 94.232.116.122 192.168.1.88 NNTP 125 ✓ Response: 281 Authentication accepted, xxx bytes remaining.
888 2023-03-24 18:09:40,556858578 192.168.1.88 94.232.116.122 NNTP 79 ✓ Request: MODE READER
890 2023-03-24 18:09:40,558341988 94.232.116.122 192.168.1.88 NNTP 77 ✓ Response: 200 Sure.
898 2023-03-24 18:09:40,563757548 192.168.1.88 94.232.116.122 NNTP 99 ✓ Request: AUTHINFO user [e-mail]
901 2023-03-24 18:09:40,565465866 94.232.116.122 192.168.1.88 NNTP 82 ✓ Response: 381 Need more.
906 2023-03-24 18:09:40,646889647 192.168.1.88 94.232.116.122 NNTP 88 ✓ Request: AUTHINFO passpassword
907 2023-03-24 18:09:40,648748620 94.232.116.122 192.168.1.88 NNTP 80 ✓ Response: 281 Welcome.
985 2023-03-24 18:09:40,708852509 192.168.1.88 94.232.116.122 NNTP 88 ✓ Request: GROUP group
and so on. ... ...

Comment 4

[Wayne Mery (:wsmwk)]

Apparently newsxs has not been working for a long time. Bug 1795662 - After updating to Thunderbird 102.3.3 newsgroups do no work any more (reader2.newsxs.nl)

To get a more complete log, please set mailnews.nntp.loglevel to "All", reference https://wiki.mozilla.org/MailNews:Logging

Comment 5

[PeterO]

Attachment: console-export-2023-3-25_16-17-39_mailnews.txt

Retrieved with mailnews.nntp.loglevel = All, newsread is unresponsive after accessing a function or item with mailnews.nntp.jsmodule = TRUE

Comment 6

[PeterO]

I got somewhat more messages as were seen while doing packettracing.
Whatever I do, with mailnews.nntp.jsmodule = TRUE , action on/for NNTP are waiting for ever without any response.

Interesting is that each time I try to access an already existing NNTP entry, from a previous session, the logs shows "asyncOpen":
16:10:44.710 mailnews.nntp: asyncOpen news://reader2.newsxs.nl:119/gh24phllip06r2gsoel83kvm1ev1t4lplm%404ax.com?group=xs4all.general&

16:10:44.710 mailnews.nntp: asyncOpen news://reader2.newsxs.nl:119/gh24phllip06r2gsoel83kvm1ev1t4lplm%404ax.com?group=xs4all.general&key=302713 NntpChannel.jsm:146:18
16:12:56.355 mailnews.nntp: Connection closed. 2 NntpClient.jsm:228:18

Comment 7

[Alfred Peters [:infofrommozilla]]

(In reply to PeterO from comment #6)

Interesting is that each time I try to access an already existing NNTP entry, from a previous session, the logs shows "asyncOpen":
16:10:44.710 mailnews.nntp: asyncOpen news://reader2.newsxs.nl:119/gh24phllip06r2gsoel83kvm1ev1t4lplm%404ax.com?group=xs4all.general&

16:10:44.710 mailnews.nntp: asyncOpen news://reader2.newsxs.nl:119/gh24phllip06r2gsoel83kvm1ev1t4lplm%404ax.com?group=xs4all.general&key=302713 NntpChannel.jsm:146:18
16:12:56.355 mailnews.nntp: Connection closed. 2 NntpClient.jsm:228:18

This means TB has fetched the news article from the cache or if enabled from the offline store.

Comment 8

[Alfred Peters [:infofrommozilla]]

(In reply to PeterO from comment #5)

Created attachment 9325044 [details]
console-export-2023-3-25_16-17-39_mailnews.txt

Retrieved with mailnews.nntp.loglevel = All, newsread is unresponsive after accessing a function or item with mailnews.nntp.jsmodule = TRUE

The authentication has been completed successfully.
This should be followed by a GROUP command. Strange that this is missing.
What happens in the log when you update the group manually:

Menu: File -> Get New Messages for... -> Current Account [F5]

Comment 9

[PeterO]

Interesting..... refresh aka F5 does not deliver any (group or other) result. The panel stays indefintely waiting with circling mouse.
When I press/do F5, the log is extended with the two lines as previously stated.....

16:10:44.703 mailnews.nntp: DisplayMessage news-message://reader2.newsxs.nl/xs4all.general#302713 NntpMessageService.jsm:40:18
16:10:44.710 mailnews.nntp: asyncOpen news://reader2.newsxs.nl:119/gh24phllip06r2gsoel83kvm1ev1t4lplm%404ax.com?group=xs4all.general&key=302713 NntpChannel.jsm:146:18

Good catch... the GROUP request is not seen/fired with mailnews.nntp.jsmodule = TRUE which might explain the wait forever (at this newsserver).

Comment 10

[Alfred Peters [:infofrommozilla]]

"reader2.newsxs.nl" responds to the MODE READER command rejecting with 480 Authentication required for command.. This seems to confuse TB somehow.

As you can see in Comment #3, the CPP module repeats the command after logging in. The JS module does not.

I am not aware of any other server that requires authentication for this. After reprogramming my local server to also return the 480 message, TB gets stuck after login here too.

https://searchfox.org/comm-central/source/mailnews/news/src/NntpClient.jsm#527

But it is TB who is blocking here and not the server. Because at least my server ignores the command anyway.

Comment 11

[PeterO]

Attachment: PCAP summary while mailnews.nntp.jsmodule = TRUE

PCAP copy summary with mailnews.nntp.jsmodule = TRUE
tldr; sequence: access Newsxs --> MODE READER --> AUTHINFO userid --> AUTHINFO pass

Comment 12

[PeterO]

Attachment: PCAP summary while mailnews.nntp.jsmodule = FALSE

PCAP copy summary with mailnews.nntp.jsmodule = FALSE
tldr; sequence: access Newsxs --> MODE READER --> AUTHINFO userid --> AUTHINFO pass
followed by (2nd) --> MODE READER --> AUTHINFO user --> AUTHINFO pass --> GROUP --> ARTICLE
(thereafter the normal response and TB shows NNTP output)

Comment 13

[PeterO]

Great find. This might enlighthen things where de javascript does not respond (well) to an unexpected additonal authentication.

I've redone the wireshark traces and confirm that

1. with "mailnews.nntp.jsmodule" (= TRUE) , TB will do only "Newsxs --> MODE READER --> AUTHINFO userid --> AUTHINFO pass"
   .... attached pcap_summary newsxs_summary_jsmodule_26mar23_21u25.txt
2. and for "mailnews.nntp.jsmodule" (= FALSE) (again doing) --> MODE READER --> AUTHINFO user --> AUTHINFO pass --> GROUP --> ARTICLE
   .... attached newsxs_jsmodule_26mar23_21u25.txt.pcapng

So wihout jsmodule TB is acting differently in response to the NNTP server.
Question now is... how en wat could cause this......
Let me know what details one need to investigate this further.

Comment 14

[PeterO]

Attachment: telnet_newsxs_session26mar23_22u21.txt

Telnet session to involved NNTP server, showing the normal behavior
Access NewsSXS --> MODE READER --> AUTHINFO user --> AUTHINFO pass --> GROUP --> ARTICLE

Comment 15

[PeterO]

I've also done a manual access to my newsxs server and found that the choice doing a dual mode-reader (aka. mailnews.nntp.jsmodule = FALSE) is a choice of TB.
Why TB with mailnews.nntp.jsmodule =TRUE does not continue after authentication .... with GROUP and ARTICLE ... , appears to be the problem.

The NNTP server is IMO acting normal(ly) and does not require subsequent authentication.
The fact TB is requesting is doing a secondary MODE READER followed by self initiated re-authentication is superfluous and not required nor requested by the NNTP server.

Comment 16

[PeterO]

Sniffing some code... it appears to me that the JavaScript NNTP client code as stored in omni.ja JAR file (containing javascript routines) in Thunderbird clearly does not properly handle the standard NNTP sequence. As said before, disabling the JS version reads nntp without any problem.

I identified NntpMessageService.jsm (which f.e. DisplayMessage , reading an article) via --> NntpChannel.jsm (requesting asyncOpen) -->, NntpMessageService.jsm (executing asyncOpen) as partnered cause.
The "DisplayMessage" is NOT requesting or preceded by for example the nntp GROUP/ARTICLE command which in turn (of course) will not result in any data returned to be processed. The end result is - as observed - a long wait. The same happens for subscribing to groups, the routine is not requesting the "LIST" command which in turn (of course) will not result in a datastream which than is processed.

I wonder how and against to what specific/type NNTP server, the Javascript-module implementation was tested (and apparently accepted as OK) ?

Comment 17

[Alfred Peters [:infofrommozilla]]

(In reply to Alfred Peters from comment #10)

https://searchfox.org/comm-central/source/mailnews/news/src/NntpClient.jsm#527

      this._sendCommand("MODE READER");
      this._inReadingMode = true;
      this._nextAction = () => {
        if (this._server.pushAuth && !this._authenticated) {
          this._currentAction = nextAction;
          this._actionAuthUser();
        } else {
          nextAction();
        }
      };

This is the fishy way to force authentication after the MODE READER command.
But because of the 480 response, authentication is already performed when data is received in the _onData call:
https://searchfox.org/comm-central/source/mailnews/news/src/NntpClient.jsm#171

 _onData = event => {
    [...]
    switch (res.status) {
      case AUTH_REQUIRED:
        this._currentGroupName = null;
        this._actionAuthUser();

In _actionAuthResult() the previous command is then repeated by calling this._currentAction?.();:
https://searchfox.org/comm-central/source/mailnews/news/src/NntpClient.jsm#831

  _actionAuthResult({ status }) {
    switch (status) {
      case AUTH_ACCEPTED:
        this._authenticated = true;
        this._currentAction?.();

But _currentAction was not set here at all. Therefore the processing is finished here.

Comment 18

[PeterO]

:+1 Sharp!! That condition seems to explain the observed situation.

Note: I think the MODEREADER & 480 is only performed one and after doing the AUTHenciation for it, things goes into "nothing left to do"
The multiple MODEREADER sequences in (my) debug-report were because I rightclick to try to enforce a subsequent next action.
So the observed standstill raises after MODE READER, receiving the 480 that goes into AUTHentication and; as you've found, nothing more tod (as actionlist is cleared). Thereafter a user action on the TB screen does not result in any action other than Display

Somewhere somehow, something must progress a subsequent "_action" after doing the MODE READER and (fishy :-) Authentication for it.
Perhaps the original "_nextAction" contents should be saved first before using this routine for doing the inserted AUTHentication sequence.

Unfortunately, I'm not familiair enough with the TB structure and specific JSM code to change/test things.

Comment 19

[Alfred Peters [:infofrommozilla]]

Attachment: Take into account the authentication request response during the MODE READER command.

I have successfully tested the patch locally.

@PeterO: It would be great if you could test this with with "newsxs.nl". Can you manage to modify the NntpClient.jsm file in the omni.ja JAR file?

Then before testing please call:
Menu -> Help -> Troubleshooting Information
=> [Clear Startupcache...]

Or do we need a test build?

Comment 20

[PeterO]

@AlfredP LGTM :1+:
Your patch works beautifully.

I've edited NntpClient.jsm into /usr/lib/thunderbird/omni.ja, set mailnews.nntp.jsmodule to false & cleared cache (which restarted TB.
*** NntpClient_org.jsm 2009-12-31 23:00:00.000000000 +0100
--- NntpClient.jsm 2023-04-10 21:11:33.937920419 +0200
***************
*** 464,469 ****
--- 464,472 ----
nextAction();
} else {
this._sendCommand("MODE READER");
+ this._currentAction = () => {
+ this._actionModeReader(nextAction);
+ };
this._inReadingMode = true;
this._nextAction = () => {
if (this._server.pushAuth && !this._authenticated) {

In this JS mode, news groups of NNTP server newsxs.nl can be accessed, groups read, can be subscribed, articles viewed , ignored and so on.
See attached console log (stripped mailnews) /media/Rdisk/Info/debug/tb.news/tb_mailnews_console_10apr23_21u19.log for reference.

Well done !!!

Comment 21

[PeterO]

Attachment: tb_mailnews_console_10apr23_21u19.log

Console log for patched NntpClient.jsm to verify/test patch to fix bug.

Comment 22

[Alfred Peters [:infofrommozilla]]

Thank you very much. But please do not be hasty. The patch needs a review first.

Comment 23

[PeterO]

(In reply to Alfred Peters from comment #22)

Thank you very much. But please do not be hasty. The patch needs a review first.
Appologies, I was not aware of formalities ;-) and THX for giving this attention !!!!

Comment 24

[MM]

I've edited NntpClient.jsm into /usr/lib/thunderbird/omni.ja, set mailnews.nntp.jsmodule to false ...

You mean true, right? If you really set it to false, you switched off the modified code and didn't test it.

Comment 25

[PeterO]

(In reply to MM from comment #24)

I've edited NntpClient.jsm into /usr/lib/thunderbird/omni.ja, set mailnews.nntp.jsmodule to false ...

You mean true, right? If you really set it to false, you switched off the modified code and didn't test it.
Yes, correct. See my console log for result that also proofs this TRUE setting, mailnews was set to TRUE.
21:19:48.133 mailnews.nntp: Connected NntpClient.jsm:140:18

Comment 26

[PeterO]

Comment on attachment 9327829 [details]
tb_mailnews_console_10apr23_21u19.log

As mentioned by @MM , mailnews.nntp.jsmodule set to true in config editor.
The text in file comment should be read as mailnews.nntp.jsmodule set to true in config editor

Comment 27

[Alfred Peters [:infofrommozilla]]

Attachment: Take into account the authentication request response during the MODE READER command.

We still need to repeat the MODE READER command:

00:24:06.468 mailnews.nntp: S: 200 NNTP-Server Classic Hamster Version 2.1 (Build 2.1.0.1547) (post ok) on gammasigma.xy says: Hi! NntpClient.jsm:165:18
00:24:06.469 mailnews.nntp: C: MODE READER NntpClient.jsm:280:20
00:24:06.475 mailnews.nntp: S: 480 Authentication required for command. NntpClient.jsm:165:18
00:24:06.477 mailnews.nntp: C: Logging suppressed (it probably contained auth information) NntpClient.jsm:274:20
00:24:06.479 mailnews.nntp: S: 381 More authentication information required NntpClient.jsm:165:18
00:24:06.479 mailnews.nntp: C: Logging suppressed (it probably contained auth information) NntpClient.jsm:274:20
00:24:06.481 mailnews.nntp: S: 281 Authentication accepted NntpClient.jsm:165:18
00:24:06.481 mailnews.nntp: C: MODE READER NntpClient.jsm:280:20
00:24:06.482 mailnews.nntp: S: 200 ignored NntpClient.jsm:165:18
00:24:06.482 mailnews.nntp: C: GROUP [...]

Comment 28

[Magnus Melin [:mkmelin]]

Comment on attachment 9327840 [details]
Take into account the authentication request response during the MODE READER command.

Looks good, thanks Alfred! r=mkmelin

Comment 29

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/comm-central/rev/ff69102b65b9
Take into account the auth request response during the MODE READER command. r=mkmelin

Comment 30

[Wayne Mery (:wsmwk)]

Comment on attachment 9327840 [details]
Take into account the authentication request response during the MODE READER command.

[Triage Comment]
Approved for beta

Comment 31

[Daniel Darnell [:dandarnell]]

Thunderbird 113.0b2:
https://hg.mozilla.org/releases/comm-beta/rev/0f0e34f0a8e8

Comment 33

[Alfred Peters [:infofrommozilla]]

As a workaround for TB102 you can switch back from the JS module to the old C++ module.

For this you have to set the pref mailnews.nntp.jsmodule to FALSE.

How - see: https://support.mozilla.org/en-US/kb/config-editor

Comment 34

[Alfred Peters [:infofrommozilla]]

Unfortunately, the bug mainly affects paid servers.
I think we should consider the uplift to the next TB102 version!?

Comment 35

[Magnus Melin [:mkmelin]]

Comment on attachment 9327840 [details]
Take into account the authentication request response during the MODE READER command.

[Approval Request Comment]
Regression caused by (bug #): nntp-js
User impact if declined: can't use at least some servers where auth is required
Testing completed (on c-c, etc.): c-c,beta
Risk to taking this patch (and alternatives if risky): not super risky

Comment 36

[Wayne Mery (:wsmwk)]

Comment on attachment 9327840 [details]
Take into account the authentication request response during the MODE READER command.

[Triage Comment]
Approved for esr102 - eventhough "not super risky" isn't too inspiring

Comment 37

[Rob Lemley [:rjl]]

Thunderbird 102.11.1:
https://hg.mozilla.org/releases/comm-esr102/rev/8163ab81cd39