open https://gitlab.synchro.net/main/sbbs/-/issues/814

Regarding commit 04340d911b1e7282cdb7411962eeb2de34c5309e

I noticed after this, I would sometimes go to a message and my nntp client would say that the message could be loaded. I'm using claws-mail.

Just now, Accession asked me I was having this issue and he is using Thunderbird so it looks like the nntpserver may be having issues reopening the message base and reading the requested file.

Please revisit. Thanks.
--- SBBSecho 3.21-Linux
* Origin: Vertrauen - [vert/cvs/bbs].synchro.net (1:103/705)

https://gitlab.synchro.net/main/sbbs/-/issues/814#note_5949

So you're saying this is a duplicate of issue #790?
--- SBBSecho 3.21-Linux
* Origin: Vertrauen - [vert/cvs/bbs].synchro.net (1:103/705)

https://gitlab.synchro.net/main/sbbs/-/issues/814#note_5951

A log from the nntpservice when this issues happens would be helpful.
--- SBBSecho 3.21-Linux
* Origin: Vertrauen - [vert/cvs/bbs].synchro.net (1:103/705)

On Sat, Nov 09 2024 15:29:34 -0600, you wrote:

https://gitlab.synchro.net/main/sbbs/-/issues/814#note_5951

A log from the nntpservice when this issues happens would be
helpful.

Most likely will have to go into debug mode then, as every time it has happened to me there was no log for it in the default logging mode.
Would the safest place to do this be to add "LogLevel=Debug" to the NNTP section of services.ini?

FYI, closing the NNTP client, and reopening it allowed you to view the
message (which I assume causes a full disconnect/reconnect).

Regards,
Nick

... Take my advice, I don't use it anyway.
--- SBBSecho 3.21-Linux
* Origin: _thePharcyde telnet://bbs.pharcyde.org (Wisconsin) (1:154/700)

Re: Re: nntpserver not able to read articles after files closed
By: Nicholas Boel to Rob Swindell on Sat Nov 09 2024 04:27 pm

On Sat, Nov 09 2024 15:29:34 -0600, you wrote:

https://gitlab.synchro.net/main/sbbs/-/issues/814#note_5951

A log from the nntpservice when this issues happens would be
helpful.

Most likely will have to go into debug mode then, as every time it has happened to me there was no log for it in the default logging mode.

The nntpservice.js logs ever received command from the client as an INFO-level log message with a "cmd:" prefix. For example:

11/9 03:38:42p 3744 NNTP cmd: MODE READER
11/9 03:38:42p 3744 NNTP cmd: AUTHINFO user digital man
11/9 03:38:42p 3744 NNTP cmd: AUTHINFO pass youwish
11/9 03:38:43p 3744 NNTP Logging out Guest
11/9 03:38:43p 3744 NNTP [71.95.196.34] Logging in Digital Man
11/9 03:38:43p 3744 NNTP cmd: GROUP fsxNet.FSX_Ads

Would the safest place to do this be to add "LogLevel=Debug" to the NNTP section of services.ini?

Debug-level logging is not needed to log any/all NNTP message received from a news reader/client.

FYI, closing the NNTP client, and reopening it allowed you to view the message (which I assume causes a full disconnect/reconnect).

The log would say.
--
digital man (rob)

Synchronet/BBS Terminology Definition #88:
UART = Universal Asynchronous Receiver/Transmitter
Norco, CA WX: 73.9øF, 23.0% humidity, 7 mph W wind, 0.00 inches rain/24hrs
--- SBBSecho 3.21-Linux
* Origin: Vertrauen - [vert/cvs/bbs].synchro.net (1:103/705)

On Sat, Nov 09 2024 18:01:07 -0600, you wrote:

> > A log from the nntpservice when this issues happens would be
> > helpful.

Good thing, just as I saved the last message in this sub, it happened
when trying to view this message. Here is the log:

Nov 09 20:25:33 reaper synchronet[608]: srvc 0056 NNTP
[Fidonet.SYNC_SYSOPS] cmd: A
Nov 09 20:25:33 reaper synchronet[608]: srvc 0056 NNTP !unknown command
Nov 09 20:25:33 reaper synchronet[608]: srvc 0056 NNTP
[Fidonet.SYNC_SYSOPS] cmd: RTICLE 14218
Nov 09 20:25:33 reaper synchronet[608]: srvc 0056 NNTP !unknown command

Looks like somehow ARTICLE is getting split. This happened once prior
just during that 5 minute session, in the Debate sub. This tends to
happen more times than can be ignored.

Regards,
Nick

... Take my advice, I don't use it anyway.
--- SBBSecho 3.21-Linux
* Origin: _thePharcyde telnet://bbs.pharcyde.org (Wisconsin) (1:154/700)

Re: Re: nntpserver not able to read articles after files closed
By: Nicholas Boel to Digital Man on Sat Nov 09 2024 08:29 pm

On Sat, Nov 09 2024 18:01:07 -0600, you wrote:

> > A log from the nntpservice when this issues happens would be
> > helpful.

Good thing, just as I saved the last message in this sub, it happened
when trying to view this message. Here is the log:

Nov 09 20:25:33 reaper synchronet[608]: srvc 0056 NNTP
[Fidonet.SYNC_SYSOPS] cmd: A
Nov 09 20:25:33 reaper synchronet[608]: srvc 0056 NNTP !unknown command
Nov 09 20:25:33 reaper synchronet[608]: srvc 0056 NNTP
[Fidonet.SYNC_SYSOPS] cmd: RTICLE 14218
Nov 09 20:25:33 reaper synchronet[608]: srvc 0056 NNTP !unknown command

Looks like somehow ARTICLE is getting split. This happened once prior
just during that 5 minute session, in the Debate sub. This tends to
happen more times than can be ignored.

Weird. You could try increasing the timeout values on this line in nntpservice.js and see if that makes any difference:
cmdline = client.socket.recvline(/* maxlen: */1024, /* timeout: */(msgbase && msgbase.is_open) ? 10 : 300);

Those values are in seconds, so I'd be surprised if an NNTP client would send 'A' and then take more than 10 seconds to send the remaining characters of the command, but worth experimenting with. A network packet capture (e.g. with Wireshark) could also help tell what's happening there exactly.
--
digital man (rob)

This Is Spinal Tap quote #35:
Jeanine Pettibone: You don't do heavy metal in Dubly, you know.
Norco, CA WX: 65.7øF, 24.0% humidity, 2 mph NW wind, 0.00 inches rain/24hrs
--- SBBSecho 3.21-Linux
* Origin: Vertrauen - [vert/cvs/bbs].synchro.net (1:103/705)

On Sat, Nov 09 2024 21:04:32 -0600, you wrote:

Weird. You could try increasing the timeout values on this line in nntpservice.js and see if that makes any difference: cmdline = client.socket.recvline(/* maxlen: */1024, /* timeout: */(msgbase && msgbase.is_open) ? 10 : 300);

What would be a good starting point?

Those values are in seconds, so I'd be surprised if an NNTP client
would send 'A' and then take more than 10 seconds to send the
remaining characters of the command, but worth experimenting with.

Agreed. I watched the logs while I clicked the subject. It was all
logged immediately, not even close to 10 seconds later.

A network packet capture (e.g. with Wireshark) could also help tell
what's happening there exactly.

I have no experience with that kind of stuff. Maybe <cough> nelgin would
want to take a crack at it? *nudges nelgin :)

Regards,
Nick

... Take my advice, I don't use it anyway.
---
ï¿­ Synchronet ï¿­ _thePharcyde telnet://bbs.pharcyde.org (Wisconsin)
* Origin: Vertrauen - [vert/cvs/bbs].synchro.net (1:103/705)

https://gitlab.synchro.net/main/sbbs/-/issues/814#note_5956

The actual problem here appears to be the opposite of the original title "nntpserver not able to read articles after files closed":
When the nntpservice has a message base *open*, it uses a short (10 second) timeout while waiting for a command from the NNTP client (news reader). When there is no message base open, nntpservice still uses the long-time 300 second (5 minute) timeout while waiting for a command.

The additional detail was provided by Nick (Accesion) via DOVE-Net:
```
Nov 09 20:25:33 reaper synchronet[608]: srvc 0056 NNTP
[Fidonet.SYNC_SYSOPS] cmd: A
Nov 09 20:25:33 reaper synchronet[608]: srvc 0056 NNTP !unknown command
Nov 09 20:25:33 reaper synchronet[608]: srvc 0056 NNTP
[Fidonet.SYNC_SYSOPS] cmd: RTICLE 14218
Nov 09 20:25:33 reaper synchronet[608]: srvc 0056 NNTP !unknown command
```

The client command appears to have been broken into two parts by Socket.recvline().

I was able to reproduce this and narrowed it down to this situation:

nntpservice.js is waiting for a command from the client, with a short (10 second) timeout because there's a message base already open (and we want to close it relatively quickly when there's no activity from the client). If the news client user waits 8-9 seconds between commands, the first character of the command might arrive (and be received) just before the timeout is to expire. It's an edge case that's new. Socket.recvline() didn't use to behave this way.
https://gitlab.synchro.net/main/sbbs/-/blob/f46ba4d2df43b78a66f2e670875eec5002765dc8/src/sbbs3/js_socket.c
--- SBBSecho 3.21-Linux
* Origin: Vertrauen - [vert/cvs/bbs].synchro.net (1:103/705)