I've been testing out the Mystic NNTP server recently and noticed some odd behavior while accessing it though Thunderbird.

Thunderbird has been asking me if I want to subscribe to the numerical msgid
of a message on every one viewed as though it were a newsgroup. If I click on Yes it unsurprisingly fails to find a newsgroup named, for example, "1067"
and then asks if I want to unsubscribe. I'm not sure what it's seeing or misinterpreting in the NNTP traffic from Mystic that's causing it to do this.

If I view a message in one group with a particular ID (eg: msg #1 in FSX_BBS) and then view a message in a different group with the same ID (eg: msg #1 in FSX_BOT) it gives me the previous message instead. It will continue to do
this in every subsequent group, displaying the message with the ID from the first group it was retrieved from instead.

After using NNTP for a while it eventually gets into a state where the NNTP server reports no new messages in any group (even if there are) and the next message you try to view no longer exists (even if it does). Immediately after the first "423 No such article" response, authentication breaks the moment
any other article is accessed. The server sends the client a "450 Auth required" message, which Thunderbird responds to with authinfo user and pass and gets a "482 Bad authentication sequence" response.

I also discovered completely by accident that BINKP somehow broke as well
when this occurred. While in the middle of testing this, Todd Zieman's system connected to mine to drop off mail and this happened:

+ 2017.12.31 03:08:01 BINKP > Connect on slot 1/6
+ 2017.12.31 03:08:01 BINKP 1-Address 108.204.225.235
+ 2017.12.31 03:08:01 BINKP 1-HostName Unknown
+ 2017.12.31 03:08:02 BINKP 1-S: NUL OPT CRAM-MD5-e689261c4a8428460e1166c5eec + 2017.12.31 03:08:02 BINKP 1-S: NUL SYS Subcarrier BBS
+ 2017.12.31 03:08:02 BINKP 1-S: NUL ZYZ Static
+ 2017.12.31 03:08:02 BINKP 1-S: NUL VER Mystic/1.12A36 binkp/1.0
+ 2017.12.31 03:08:02 BINKP 1-S: ADR 1:249/400@fidonet 21:2/140@fsxnet 80:774 + 2017.12.31 03:08:02 BINKP 1-C: NUL SYS fsxHUB Tholian [NET2]
+ 2017.12.31 03:08:02 BINKP 1-System fsxHUB Tholian [NET2]
+ 2017.12.31 03:08:02 BINKP 1-C: NUL ZYZ Todd Zieman
+ 2017.12.31 03:08:02 BINKP 1-SysOp Todd Zieman
+ 2017.12.31 03:08:02 BINKP 1-C: NUL VER Mystic/1.12A37 binkp/1.0
+ 2017.12.31 03:08:02 BINKP 1-Mailer Mystic/1.12A37 binkp/1.0
+ 2017.12.31 03:08:02 BINKP 1-C: ADR 21:2/0@fsxnet 21:2/100@fsxnet
+ 2017.12.31 03:08:02 BINKP 1-C: PWD
+ 2017.12.31 03:08:02 BINKP 1-Unable to open nodes: 4
+ 2017.12.31 03:08:02 BINKP 1-Cannot authenticate client
+ 2017.12.31 03:08:02 BINKP 1-S: ERR Bad address or password
+ 2017.12.31 03:08:02 BINKP 1-Client thread shutting down

MIS had to be shut down and restarted to correct the state it had gotten into.

--- Mystic BBS v1.12 A36 2017/12/03 (Linux/64)
* Origin: Subcarrier BBS (21:2/140)

I get very similar issues when just subscribing to new newsgroups (message bases)

I think he was at some point going to re work all of the NNTP server.

On 21:14 30/12 , Static wrote:

I've been testing out the Mystic NNTP server recently and noticed some odd >behavior while accessing it though Thunderbird.

Thunderbird has been asking me if I want to subscribe to the numerical msgid >of a message on every one viewed as though it were a newsgroup. If I click on >Yes it unsurprisingly fails to find a newsgroup named, for example, "1067" >and then asks if I want to unsubscribe. I'm not sure what it's seeing or >misinterpreting in the NNTP traffic from Mystic that's causing it to do this.

If I view a message in one group with a particular ID (eg: msg #1 in FSX_BBS) >and then view a message in a different group with the same ID (eg: msg #1 in >FSX_BOT) it gives me the previous message instead. It will continue to do >this in every subsequent group, displaying the message with the ID from the >first group it was retrieved from instead.

After using NNTP for a while it eventually gets into a state where the NNTP >server reports no new messages in any group (even if there are) and the next >message you try to view no longer exists (even if it does). Immediately after >the first "423 No such article" response, authentication breaks the moment >any other article is accessed. The server sends the client a "450 Auth >required" message, which Thunderbird responds to with authinfo user and pass >and gets a "482 Bad authentication sequence" response.

I also discovered completely by accident that BINKP somehow broke as well >when this occurred. While in the middle of testing this, Todd Zieman's system >connected to mine to drop off mail and this happened:

+ 2017.12.31 03:08:01 BINKP > Connect on slot 1/6
+ 2017.12.31 03:08:01 BINKP 1-Address 108.204.225.235
+ 2017.12.31 03:08:01 BINKP 1-HostName Unknown
+ 2017.12.31 03:08:02 BINKP 1-S: NUL OPT CRAM-MD5-e689261c4a8428460e1166c5eec >+ 2017.12.31 03:08:02 BINKP 1-S: NUL SYS Subcarrier BBS
+ 2017.12.31 03:08:02 BINKP 1-S: NUL ZYZ Static
+ 2017.12.31 03:08:02 BINKP 1-S: NUL VER Mystic/1.12A36 binkp/1.0
+ 2017.12.31 03:08:02 BINKP 1-S: ADR 1:249/400@fidonet 21:2/140@fsxnet 80:774 >+ 2017.12.31 03:08:02 BINKP 1-C: NUL SYS fsxHUB Tholian [NET2]
+ 2017.12.31 03:08:02 BINKP 1-System fsxHUB Tholian [NET2]
+ 2017.12.31 03:08:02 BINKP 1-C: NUL ZYZ Todd Zieman
+ 2017.12.31 03:08:02 BINKP 1-SysOp Todd Zieman
+ 2017.12.31 03:08:02 BINKP 1-C: NUL VER Mystic/1.12A37 binkp/1.0
+ 2017.12.31 03:08:02 BINKP 1-Mailer Mystic/1.12A37 binkp/1.0
+ 2017.12.31 03:08:02 BINKP 1-C: ADR 21:2/0@fsxnet 21:2/100@fsxnet
+ 2017.12.31 03:08:02 BINKP 1-C: PWD
+ 2017.12.31 03:08:02 BINKP 1-Unable to open nodes: 4
+ 2017.12.31 03:08:02 BINKP 1-Cannot authenticate client
+ 2017.12.31 03:08:02 BINKP 1-S: ERR Bad address or password
+ 2017.12.31 03:08:02 BINKP 1-Client thread shutting down

MIS had to be shut down and restarted to correct the state it had gotten into.

--- Mystic BBS v1.12 A36 2017/12/03 (Linux/64)
* Origin: Subcarrier BBS (21:2/140)

--
yrNews Usenet Reader for iOS
http://appstore.com/yrNewsUsenetReader

--- Mystic BBS/NNTP v1.12 A37 2017/12/30 (Linux/64)
* Origin: -=The ByteXchange BBS : bbs.thebytexchange.com=- (21:1/107)

I've been testing out the Mystic NNTP server recently and noticed some
odd behavior while accessing it though Thunderbird.

MIS had to be shut down and restarted to correct the state it had gotten into.

Error code 4 is too many files open which is configurable in Linux. I think Linux has a "hard" and "soft" limit of files. Hard meaning the total number of files that can be opened at one time, and a soft limit being the total number of files that a user can open in total.

If either of these are set conservatively then I believe your server will more or less be "sabotaged" by Linux when either limit is reached. Keep in mind this isn't specific to a process, but to the user and whatever else is running too.

It could also mean a file is not being closed somewhere by Mystic (or something else non-Mystic related too) which I will be looking into right away. Another thing to check would be the open files used by MIS. This should show us if a bunch of files are being left open:

You can get the MIS PID by doing a cat of semaphore/mis.bsy and then do a lsof -p <PID>. I think you probably know this stuff as I remember that you seem pretty technical, but I figured I'd type it out anyway.

Anyway this is great I finally have something to go on here, so I will look into it today and see if I can find a spot in the NNTP server where its
leaking file handles.

--- Mystic BBS v1.12 A37 2017/12/30 (Windows/32)
* Origin: Sector 7 [Mystic BBS WHQ] (21:1/108)

I get very similar issues when just subscribing to new newsgroups
(message bases)

I think he was at some point going to re work all of the NNTP server.

I did redo some of it already when moving to MIS and so that I could pull out error codes. In your case I don't think I ever saw logging after I added in the error codes.

If your error is also 4, then the issue is that you have too many open files. This could be your defaults in Linux are set to conservatively or that there is a file leak either in Mystic or something else you're running.

I am going to assume that you were also getting error 4 so that finally gives me something to go on. I'll see what I can figure out today.

--- Mystic BBS v1.12 A37 2017/12/30 (Windows/32)
* Origin: Sector 7 [Mystic BBS WHQ] (21:1/108)

On 12/31/17, g00r00 said the following...

Error code 4 is too many files open which is configurable in Linux.

That does sound make it sound like file handle leaks.

If either of these are set conservatively then I believe your server
will more or less be "sabotaged" by Linux when either limit is reached.

I can confirm the file limits are definitely not conservative on the system
the BBS is running on. They're defaulted to 2048/8192 which IIRC is double
the norm.

$ ulimit -Sn
2048
$ ulimit -Hn
8192
$ cat /proc/sys/fs/file-max
3261928

think Linux has a "hard" and "soft" limit of files. Hard meaning the
total number of files that can be opened at one time, and a soft limit being the total number of files that a user can open in total.

Hard and soft limits are both just for the user. Unless the user deliberately issues a ulimit command to extend their soft limit up to a max of their hard limit, the default soft limit is enforced. The entire system has its own limit controlled by fs.file-max in the kernel. A user's hard limit is essentially just headroom for emergencies.

$ ulimit -n 8192
$ ulimit -Sn
8192
$ ulimit -n 31337
-bash: ulimit: open files: cannot modify limit: Operation not permitted

Another thing to check would be the open files used by MIS.
This should show us if a bunch of files are being left open:

The mysticbbs user basically only runs Mystic on the system it's on.

Before using NNTP and encountering the first "message not found" error.
$ lsof -p $(cat semaphore/mis.bsy) | wc -l
30
Well that escalated quickly:
lsof -p $(cat semaphore/mis.bsy) | wc -l
2066

--- Mystic BBS v1.12 A36 2017/12/03 (Linux/64)
* Origin: Subcarrier BBS (21:2/140)

I can confirm the file limits are definitely not conservative on the system the BBS is running on. They're defaulted to 2048/8192 which IIRC
is double the norm.

Yep that should easily be fine as you say. Mystic itself only ever has a handful of files open at any given time, so it should never be an issue even with conservative defaults unless that user is running a bunch of other things as well.

Even the 30 you mentioned is probably exaggerated because each server listening will count as a file as well as each virtual TTY, and so on. The actual number of files kept open by Mystic are slim to none... Except you know, when I try to blow up the system by leaking handles ;)

Anyway... this was great it gave me some direction seeing an actual error number, and I was able to find a leak in the NNTP server in a few places. I patched it up in the latest prealpha that is now on the FTP site, so hopefully that will clear up the issues.

Happy new year!

--- Mystic BBS v1.12 A37 2017/12/31 (Windows/32)
* Origin: Sector 7 [Mystic BBS WHQ] (21:1/108)

On 12/31/17, g00r00 said the following...

Even the 30 you mentioned is probably exaggerated because each server listening will count as a file as well as each virtual TTY, and so on.

Yeah, running the output of lsof through wc is ballpark since it's literally just counting the number of lines lsof outputs. It counts cwd/rtd, ttys, devices, ports, accessed libraries and even the line with the column headers. Most of the descriptors held open by an idle mis instance are just the shared libraries.

--- Mystic BBS v1.12 A36 2017/12/03 (Linux/64)
* Origin: Subcarrier BBS (21:2/140)

Anyway... this was great it gave me some direction seeing an actual error number, and I was able to find a leak in the NNTP server in a few
places. I patched it up in the latest prealpha that is now on the FTP site, so hopefully that will clear up the issues.

Happy new year!

I'll see if this fixes my issue as well. I have nothing open on my system except MIS. Its a dedicated server.



-Nugax

--- Mystic BBS v1.12 A37 2017/12/31 (Linux/64)
* Origin: -=The ByteXchange BBS : bbs.thebytexchange.com=- (21:1/107)

g00r00,

YOu wont believe this, but whatever you fixed for him fixed my issues with NNTP! Yes!

Client works now.

I added an area and immediately pulled 97 messages. No errors.


Thanks!



-Nugax

--- Mystic BBS v1.12 A37 2017/12/31 (Linux/64)
* Origin: -=The ByteXchange BBS : bbs.thebytexchange.com=- (21:1/107)

YOu wont believe this, but whatever you fixed for him fixed my issues
with NNTP! Yes!

Client works now.

Good to hear :)

Yep his error number gave it away, so I was able to find the issue. I wasn't totally sure it'd fix your issue but I thought it probably would!

--- Mystic BBS v1.12 A37 2017/12/31 (Windows/32)
* Origin: Sector 7 [Mystic BBS WHQ] (21:1/108)

Thanks. Happy New Year James.

On 14:59 31/12 , g00r00 wrote:

YOu wont believe this, but whatever you fixed for him fixed my issues with NNTP! Yes!

Client works now.

Good to hear :)

Yep his error number gave it away, so I was able to find the issue. I wasn't >totally sure it'd fix your issue but I thought it probably would!

--- Mystic BBS v1.12 A37 2017/12/31 (Windows/32)
* Origin: Sector 7 [Mystic BBS WHQ] (21:1/108)

--
yrNews Usenet Reader for iOS
http://appstore.com/yrNewsUsenetReader

--- Mystic BBS/NNTP v1.12 A37 2017/12/31 (Linux/64)
* Origin: -=The ByteXchange BBS : bbs.thebytexchange.com=- (21:1/107)

On 12/31/17, g00r00 said the following...

Yep his error number gave it away, so I was able to find the issue. I wasn't totally sure it'd fix your issue but I thought it probably would!

I just updated to A37 and I can confirm NNTP is no longer leaking file descriptors. lsof is now reporting the messagebase files opened and then
closed as soon as they're done being accessed.

Now I just need to figure out why the first viewed message with a given ID is displayed across all subsequent newsgroups in Thunderbird... Looking at the message headers, it's probably because the message-id sent to the client
isn't unique on the server and it's required to be by the RFC. Normally this
is accomplished by a combination of hashing and appending the poster's domain. eg:

$ date +%s | base64 | sha1sum
f7ee7cc8625fd73582518c47749dc6a5e3f12545 -
Truncated for length and domain appended:
Message ID <f7ee7cc8625f@f215.n129.z1.binkp.net>

Though for Mystic's purposes it would probably be sufficient to just append the base name: Message ID <1@FSX_GEN>

--- Mystic BBS v1.12 A37 2017/12/31 (Linux/64)
* Origin: Subcarrier BBS (21:2/140)

On 12/31/17, Nugax said the following...

YOu wont believe this, but whatever you fixed for him fixed my issues
with NNTP! Yes!

Top posting still sucks in BBS related stuff though. ;)

Regards,
Nick

--- Mystic BBS v1.12 A37 2017/12/31 (Linux/64)
* Origin: _thePharcyde telnet://bbs.pharcyde.org (Wisconsin) (21:1/200)