• Synchronet 3.18b high CPU usage during FidoNet Poll

    From Afsfigueiredo@1:103/705 to All on Sat Apr 10 10:39:33 2021
    Hi !

    I'm SoftSolutions SysOp ( now back to life after 28 years in the dark ).

    I've installed Synchronet 3.18 , and configured the FidoNet using Binkit.

    Every time a Poll event happens, the SBBS Services consumes two vCPU fully of the
    system CPU resources available ( doesn't matter the hardware host, nor how many

    vCPU are allocatted , if 1 or 2 vCPUs are allocated, the system stop responding ).


    When SoftSolutions receives an event from the RBT FidoNet Hub , the process happens completelly , no issues :

    4/9 06:08:48p 1832 BINKP connection accepted from: 172.16.121.2 port 42326
    4/9 06:08:48p 1832 BINKP BinkIT/2.39 invoked with options:
    4/9 06:08:48p 1832 BINKP JSBinkP/1.123 inbound connection from 172.16.121.2:42326
    4/9 06:08:48p 1832 BINKP Peer version: Mystic/1.12A46 binkp/1.0
    4/9 06:08:48p 1832 BINKP Remote addresses: 4:80/1@fidonet 4:801/0@fidonet 4:80/0@fidonet
    4/9 06:08:48p 1832 BINKP Inbound session for: 4:80/1@fidonet
    4/9 06:08:48p 1832 BINKP Plain-text password match for 4:80/1@fidonet
    4/9 06:08:49p 1832 BINKP service thread terminated (0 clients remain, 0 total, 1 served)

    When a poll event happens due schedulling or manual forcing, it stops, it seems,
    during the communication process :

    4/10 10:13:03a BINKPOLL Running timed event: BINKPOLL
    4/10 10:13:03a BINKPOLL BinkIT/2.39 invoked with options: -p
    4/10 10:13:03a BINKPOLL Attempting poll for node 4:80/1@fidonet
    4/10 10:13:03a BINKPOLL JSBinkP/1.123 callout to 4:80/1@fidonet started
    4/10 10:13:03a BINKPOLL Connecting to 4:80/1@fidonet at fido.rbt.net.br:24554
    4/10 10:13:03a BINKPOLL Will encrypt session.
    4/10 10:13:03a BINKPOLL Peer version: BinkIT/2.39,JSBinkP/1.123,sbbs3.18b/Win32 binkp/1.1
    4/10 10:13:03a BINKPOLL Authentication successful: non-secure

    4/10 09:00:04a 0932 BINKP connection accepted from: 172.16.121.2 port 56714
    4/10 09:00:04a 0932 BINKP BinkIT/2.39 invoked with options:
    4/10 09:00:04a 0932 BINKP JSBinkP/1.123 inbound connection from 172.16.121.2:56714
    4/10 09:00:04a 0932 BINKP Will encrypt session.
    4/10 09:00:04a 0932 BINKP Peer version: BinkIT/2.39,JSBinkP/1.123,sbbs3.18b/Win32 binkp/1.1
    4/10 09:00:04a 0932 BINKP Remote addresses: 4:801/10@fidonet

    Calling from command line :

    C:\sbbs\exec>jsexec binkit -p

    JSexec v3.18b-Win32 (rev 1.217) - Execute Synchronet JavaScript Module
    Compiled Sep 20 2020 18:56:02 with MSC 1927

    Loading configuration files from C:\sbbs\ctrl
    JavaScript-C 1.8.5 2011-03-31
    JavaScript: Creating runtime: 8388608 bytes
    JavaScript: Initializing context (stack: 16384 bytes)

    Reading script from C:\sbbs\exec\binkit.js
    C:\sbbs\exec\binkit.js compiled in 0.00 seconds
    BinkIT/2.39 invoked with options: -p
    Attempting poll for node 4:80/1@fidonet
    JSBinkP/1.123 callout to 4:80/1@fidonet started
    Connecting to 4:80/1@fidonet at fido.rbt.net.br:24554
    Will encrypt session.
    Peer version: BinkIT/2.39,JSBinkP/1.123,sbbs3.18b/Win32 binkp/1.1 Authentication successful: non-secure


    And then the high CPU usage begins, until i recycle the service. Disabling the polling
    seases the issue.

    I've tried using Windows XP, Windows 2003, Windows 2008 and now Windows 2012R2 all had the same behavior, when it start a FidoNet Poll Binkit event it uses two vCPU fully.

    Using the Process Explorer i see that two threads of the the sbbsNTsvcs appears to be in
    some kind of loop (this explains the 2 vCPU being fully used), on the Microsoft C Runtime :
    Start Address ucrtbase.DLL!_crt_at_quick_exit+0x20

    both threads in this "loop" are using a full vCPU resource according the process explorer.

    The only way to stop is recycling the server or kill the service.

    I've made a full review on sbbsecho.ini and found nothing that is out of order, tinkit.ini is
    not set (empty) on my system.

    Have anyone seen this kind of behavior ? or have any tips where i can research/fix this issue ?

    Regards,

    AFSFigueiredo

    ---
    þ Synchronet þ SoftSolutions - telnet://bbs.softsolutions.net.br:2023
    * Origin: Vertrauen - [vert/cvs/bbs].synchro.net (1:103/705)
  • From Digital Man@1:103/705 to Afsfigueiredo on Sat Apr 10 14:44:29 2021
    Re: Synchronet 3.18b high CPU usage during FidoNet Poll
    By: Afsfigueiredo to All on Sat Apr 10 2021 10:39 am

    I've installed Synchronet 3.18 , and configured the FidoNet using Binkit.

    Every time a Poll event happens, the SBBS Services consumes two vCPU fully of the
    system CPU resources available ( doesn't matter the hardware host, nor how many

    vCPU are allocatted , if 1 or 2 vCPUs are allocated, the system stop responding ).

    Try enabling debug-level log output and get/provide more detail about what's happening at the time of high CPU utilization.
    --
    digital man

    Sling Blade quote #13:
    Karl: He lives inside of his own heart. That's an awful big place to live in. Norco, CA WX: 79.1øF, 45.0% humidity, 9 mph ENE wind, 0.00 inches rain/24hrs --- SBBSecho 3.14-Linux
    * Origin: Vertrauen - [vert/cvs/bbs].synchro.net (1:103/705)
  • From Afsfigueiredo@1:103/705 to Digital Man on Sat Apr 10 21:57:31 2021
    Re: Synchronet 3.18b high CPU usage during FidoNet Poll
    By: Digital Man to Afsfigueiredo on Sat Apr 10 2021 14:44:29

    vCPU are allocatted , if 1 or 2 vCPUs are allocated, the system stop responding ).

    Try enabling debug-level log output and get/provide more detail about what's happening at the time of high CPU utilization.
    --

    Hi !

    It is set as debugging , but its not generating the sbbsecho.log , the ini has these :
    LogFile = ../data/sbbsecho.log
    LogTimeFormat = %Y-%m-%d %H:%M:%S
    LogLevel = Debugging

    The output are the same i sent on the first message on the command and the Control Panel .

    As polling is not vital , i'll leave it disabled for now .

    Thanks !

    ---
    þ Synchronet þ SoftSolutions - telnet://bbs.softsolutions.net.br:2023
    * Origin: Vertrauen - [vert/cvs/bbs].synchro.net (1:103/705)
  • From Digital Man@1:103/705 to Afsfigueiredo on Sat Apr 10 18:15:09 2021
    Re: Synchronet 3.18b high CPU usage during FidoNet Poll
    By: Afsfigueiredo to Digital Man on Sat Apr 10 2021 09:57 pm

    Re: Synchronet 3.18b high CPU usage during FidoNet Poll
    By: Digital Man to Afsfigueiredo on Sat Apr 10 2021 14:44:29

    vCPU are allocatted , if 1 or 2 vCPUs are allocated, the system stop responding ).

    Try enabling debug-level log output and get/provide more detail about what's happening at the time of high CPU utilization.
    --

    Hi !

    It is set as debugging , but its not generating the sbbsecho.log , the ini has these :
    LogFile = ../data/sbbsecho.log
    LogTimeFormat = %Y-%m-%d %H:%M:%S
    LogLevel = Debugging

    The output are the same i sent on the first message on the command and the Control Panel .

    As polling is not vital , i'll leave it disabled for now .

    I was referring to the BinkP output, not SBBSecho log output.
    --
    digital man

    Synchronet "Real Fact" #37:
    Synchronet's Windows Control Panel is built with Borland C++ Builder.
    Norco, CA WX: 69.6øF, 55.0% humidity, 10 mph ESE wind, 0.00 inches rain/24hrs --- SBBSecho 3.14-Linux
    * Origin: Vertrauen - [vert/cvs/bbs].synchro.net (1:103/705)
  • From Afsfigueiredo@1:103/705 to Digital Man on Sat Apr 10 22:49:35 2021
    Re: Synchronet 3.18b high CPU usage during FidoNet Poll
    By: Digital Man to Afsfigueiredo on Sat Apr 10 2021 18:15:09

    I was referring to the BinkP output, not SBBSecho log output.
    --
    digital man
    Ops, sorry ... i tried setting the binkd.cfg ( as described on the wiki ) :
    log sP/binkd.log
    loglevel 4

    And also on the sbbsecho.ini ( this one was an wild guess ) :
    BinkpLogFile = ../data/binkd.log
    BinkpLogLevel = 4

    Also
    BinkpLogFile = ../data/binkd.log
    BinkpLogLevel = Debugging


    But it seems no effect at all, still no log file generated ( noob feeling ) , is there some page on the wiki that help on setting the log level ¨?

    ---
    þ Synchronet þ SoftSolutions - telnet://bbs.softsolutions.net.br:2023
    * Origin: Vertrauen - [vert/cvs/bbs].synchro.net (1:103/705)
  • From Digital Man@1:103/705 to Afsfigueiredo on Sat Apr 10 19:11:28 2021
    Re: Synchronet 3.18b high CPU usage during FidoNet Poll
    By: Afsfigueiredo to Digital Man on Sat Apr 10 2021 10:49 pm

    Re: Synchronet 3.18b high CPU usage during FidoNet Poll
    By: Digital Man to Afsfigueiredo on Sat Apr 10 2021 18:15:09

    I was referring to the BinkP output, not SBBSecho log output.

    Ops, sorry ... i tried setting the binkd.cfg ( as described on the wiki ) : log sP/binkd.log
    loglevel 4

    BinkD is a different program. I don't think you're using it.

    And also on the sbbsecho.ini ( this one was an wild guess ) :
    BinkpLogFile = ../data/binkd.log
    BinkpLogLevel = 4

    Also
    BinkpLogFile = ../data/binkd.log
    BinkpLogLevel = Debugging

    None of that will have any effect. Bink the BINKPOLL event is a timed event (configured in SCFG->External Programs->Timed Events) and runs in terminal server's event thread. So you need to configured the terminal server's log level (i.e. "LogLevel" in the [BBS] section of your ctrl/sbbs.ini file).

    But it seems no effect at all, still no log file generated ( noob feeling ) , is there some page on the wiki that help on setting the log level ­?

    You also have the source code (exec/binkit.js and load/binkp.js), so feel free to add more log lines to help isolate the cause.
    --
    digital man

    Sling Blade quote #16:
    Karl Childers (to Doyle, re: lawn mower blade): I aim to kill you with it. Mmm. Norco, CA WX: 65.9øF, 59.0% humidity, 6 mph ENE wind, 0.00 inches rain/24hrs --- SBBSecho 3.14-Linux
    * Origin: Vertrauen - [vert/cvs/bbs].synchro.net (1:103/705)
  • From Afsfigueiredo@1:103/705 to Digital Man on Sat Apr 10 23:17:22 2021
    Re: Synchronet 3.18b high CPU usage during FidoNet Poll
    By: Digital Man to Afsfigueiredo on Sat Apr 10 2021 19:11:28

    None of that will have any effect. Bink the BINKPOLL event is a timed event (configured in SCFG->External Programs->Timed Events) and runs in terminal server's event thread. So you need to configured the terminal server's log level (i.e. "LogLevel" in the [BBS] section of your ctrl/sbbs.ini file).

    But it seems no effect at all, still no log file generated ( noob feeling , is there some page on the wiki that help on setting the log level ­?

    You also have the source code (exec/binkit.js and load/binkp.js), so feel fr to add more log lines to help isolate the cause.
    --
    digital man
    Thanks ! I'll research further based on your comments.

    ---
    þ Synchronet þ SoftSolutions - telnet://bbs.softsolutions.net.br:2023
    * Origin: Vertrauen - [vert/cvs/bbs].synchro.net (1:103/705)
  • From Afsfigueiredo@1:103/705 to Digital Man on Sat Apr 10 23:39:36 2021
    Re: Synchronet 3.18b high CPU usage during FidoNet Poll
    By: Afsfigueiredo to Digital Man on Sat Apr 10 2021 23:17:22

    None of that will have any effect. Bink the BINKPOLL event is a timed eve (configured in SCFG->External Programs->Timed Events) and runs in termina server's event thread. So you need to configured the terminal server's lo level (i.e. "LogLevel" in the [BBS] section of your ctrl/sbbs.ini file).
    Now i got the detailed log :

    4/10 11:32:01p 1740 BINKP connection accepted from: 172.16.121.2 port 49288
    4/10 11:32:01p 1740 BINKP JavaScript service thread started
    4/10 11:32:01p 1740 BINKP BinkIT/2.39 invoked with options:
    4/10 11:32:01p 1740 BINKP JSBinkP/1.123 inbound connection from 172.16.121.2:49288
    4/10 11:32:01p 1740 BINKP Sending M_NUL command args: OPT CRAM-MD5-09fc77782a00bc2d7970b6492541bfe4 CRYPT
    4/10 11:32:01p 1740 BINKP Sent M_NUL command
    4/10 11:32:01p 1740 BINKP Got M_NUL command args: OPT CRYPT
    4/10 11:32:01p 1740 BINKP Will encrypt session.
    4/10 11:32:01p 1740 BINKP Sending M_NUL command args: SYS Soft Solutions
    4/10 11:32:01p 1740 BINKP Sent M_NUL command
    4/10 11:32:01p 1740 BINKP Sending M_NUL command args: ZYZ AFSFigueiredo
    4/10 11:32:01p 1740 BINKP Sent M_NUL command
    4/10 11:32:01p 1740 BINKP Sending M_NUL command args: LOC Santana de Parnaiba, SP
    4/10 11:32:01p 1740 BINKP Sent M_NUL command
    4/10 11:32:01p 1740 BINKP Sending M_NUL command args: NDL 115200,TCP,BINKP
    4/10 11:32:01p 1740 BINKP Sent M_NUL command
    4/10 11:32:01p 1740 BINKP Sending M_NUL command args: TIME Sat Apr 10 2021 23:32:01 GMT-0300
    4/10 11:32:01p 1740 BINKP Sent M_NUL command
    4/10 11:32:01p 1740 BINKP Sending M_NUL command args: VER BinkIT/2.39,JSBinkP/1.123,sbbs3.18b/Win32 binkp/1.1
    4/10 11:32:01p 1740 BINKP Sent M_NUL command
    4/10 11:32:01p 1740 BINKP Sending M_ADR command args: 4:801/10@fidonet
    4/10 11:32:01p 1740 BINKP Sent M_ADR command
    4/10 11:32:01p 1740 BINKP Got M_NUL command args: SYS Soft Solutions
    4/10 11:32:01p 1740 BINKP Got M_NUL command args: ZYZ AFSFigueiredo
    4/10 11:32:01p 1740 BINKP Got M_NUL command args: LOC Santana de Parnaiba, SP
    4/10 11:32:01p 1740 BINKP Got M_NUL command args: NDL 115200,TCP,BINKP
    4/10 11:32:01p 1740 BINKP Got M_NUL command args: TIME Sat Apr 10 2021 23:32:01 GMT-0300
    4/10 11:32:01p 1740 BINKP Got M_NUL command args: VER BinkIT/2.39,JSBinkP/1.123,sbbs3.18b/Win32 binkp/1.1
    4/10 11:32:01p 1740 BINKP Peer version: BinkIT/2.39,JSBinkP/1.123,sbbs3.18b/Win32 binkp/1.1
    4/10 11:32:01p 1740 BINKP Got M_ADR command args: 4:801/10@fidonet
    4/10 11:32:01p 1740 BINKP Got M_PWD command args: CRAM-MD5-ca1feec93a5c02a944092ff3f903cacf
    4/10 11:32:01p 1740 BINKP Remote addresses: 4:801/10@fidonet
    4/10 11:32:01p 1740 BINKP Unconfigured address 4:801/10@fidonet
    4/10 11:32:01p 1740 BINKP Adding outbound files for 4:801/10@fidonet (object)
    4/10 11:32:01p 1740 BINKP Sending M_OK command args: non-secure
    4/10 11:32:01p 1740 BINKP Sent M_OK command
    4/10 11:32:01p 1740 BINKP Sending M_EOB command args:
    4/10 11:32:01p 1740 BINKP Sent M_EOB command

    After this "Sent M_EOB command" , the process halt and the high CPU usage begins..

    What should happen after this last log ? i think the next step is causing the issue.

    /A

    ---
    þ Synchronet þ SoftSolutions - telnet://bbs.softsolutions.net.br:2023
    * Origin: Vertrauen - [vert/cvs/bbs].synchro.net (1:103/705)
  • From Digital Man@1:103/705 to Afsfigueiredo on Sat Apr 10 19:48:34 2021
    Re: Synchronet 3.18b high CPU usage during FidoNet Poll
    By: Afsfigueiredo to Digital Man on Sat Apr 10 2021 11:39 pm

    Re: Synchronet 3.18b high CPU usage during FidoNet Poll
    By: Afsfigueiredo to Digital Man on Sat Apr 10 2021 23:17:22

    None of that will have any effect. Bink the BINKPOLL event is a timed eve (configured in SCFG->External Programs->Timed Events) and runs in termina server's event thread. So you need to configured the terminal server's lo level (i.e. "LogLevel" in the [BBS] section of your ctrl/sbbs.ini file).
    Now i got the detailed log :

    4/10 11:32:01p 1740 BINKP connection accepted from: 172.16.121.2 port 49288

    That's an incoming connection. I think you said the problem was happening for BINKPOLL (which makes outbound connections). (?)

    4/10 11:32:01p 1740 BINKP JavaScript service thread started
    4/10 11:32:01p 1740 BINKP BinkIT/2.39 invoked with options:
    4/10 11:32:01p 1740 BINKP JSBinkP/1.123 inbound connection from 172.16.121.2:49288
    4/10 11:32:01p 1740 BINKP Sending M_NUL command args: OPT CRAM-MD5-09fc77782a00bc2d7970b6492541bfe4 CRYPT
    4/10 11:32:01p 1740 BINKP Sent M_NUL command
    4/10 11:32:01p 1740 BINKP Got M_NUL command args: OPT CRYPT
    4/10 11:32:01p 1740 BINKP Will encrypt session.
    4/10 11:32:01p 1740 BINKP Sending M_NUL command args: SYS Soft Solutions
    4/10 11:32:01p 1740 BINKP Sent M_NUL command
    4/10 11:32:01p 1740 BINKP Sending M_NUL command args: ZYZ AFSFigueiredo
    4/10 11:32:01p 1740 BINKP Sent M_NUL command
    4/10 11:32:01p 1740 BINKP Sending M_NUL command args: LOC Santana de Parnaiba, SP
    4/10 11:32:01p 1740 BINKP Sent M_NUL command
    4/10 11:32:01p 1740 BINKP Sending M_NUL command args: NDL 115200,TCP,BINKP
    4/10 11:32:01p 1740 BINKP Sent M_NUL command
    4/10 11:32:01p 1740 BINKP Sending M_NUL command args: TIME Sat Apr 10 2021 23:32:01 GMT-0300
    4/10 11:32:01p 1740 BINKP Sent M_NUL command
    4/10 11:32:01p 1740 BINKP Sending M_NUL command args: VER BinkIT/2.39,JSBinkP/1.123,sbbs3.18b/Win32 binkp/1.1
    4/10 11:32:01p 1740 BINKP Sent M_NUL command
    4/10 11:32:01p 1740 BINKP Sending M_ADR command args: 4:801/10@fidonet
    4/10 11:32:01p 1740 BINKP Sent M_ADR command
    4/10 11:32:01p 1740 BINKP Got M_NUL command args: SYS Soft Solutions
    4/10 11:32:01p 1740 BINKP Got M_NUL command args: ZYZ AFSFigueiredo
    4/10 11:32:01p 1740 BINKP Got M_NUL command args: LOC Santana de Parnaiba, SP
    4/10 11:32:01p 1740 BINKP Got M_NUL command args: NDL 115200,TCP,BINKP
    4/10 11:32:01p 1740 BINKP Got M_NUL command args: TIME Sat Apr 10 2021 23:32:01 GMT-0300
    4/10 11:32:01p 1740 BINKP Got M_NUL command args: VER BinkIT/2.39,JSBinkP/1.123,sbbs3.18b/Win32 binkp/1.1
    4/10 11:32:01p 1740 BINKP Peer version: BinkIT/2.39,JSBinkP/1.123,sbbs3.18b/Win32 binkp/1.1
    4/10 11:32:01p 1740 BINKP Got M_ADR command args: 4:801/10@fidonet
    4/10 11:32:01p 1740 BINKP Got M_PWD command args: CRAM-MD5-ca1feec93a5c02a944092ff3f903cacf
    4/10 11:32:01p 1740 BINKP Remote addresses: 4:801/10@fidonet
    4/10 11:32:01p 1740 BINKP Unconfigured address 4:801/10@fidonet
    4/10 11:32:01p 1740 BINKP Adding outbound files for 4:801/10@fidonet (object)
    4/10 11:32:01p 1740 BINKP Sending M_OK command args: non-secure
    4/10 11:32:01p 1740 BINKP Sent M_OK command
    4/10 11:32:01p 1740 BINKP Sending M_EOB command args:
    4/10 11:32:01p 1740 BINKP Sent M_EOB command

    After this "Sent M_EOB command" , the process halt and the high CPU usage begins..

    What should happen after this last log ? i think the next step is causing the issue.

    I don't know off the top of my head - but see that "Unconfigured address" line? That seems to indicate that you do not have 4:801/10 configured as a linked node in EchoCfg. Is that expected?
    --
    digital man

    Synchronet/BBS Terminology Definition #50:
    MUD = Multi-User Dungeon
    Norco, CA WX: 64.5øF, 62.0% humidity, 5 mph NE wind, 0.00 inches rain/24hrs
    --- SBBSecho 3.14-Linux
    * Origin: Vertrauen - [vert/cvs/bbs].synchro.net (1:103/705)
  • From Afsfigueiredo@1:103/705 to Digital Man on Mon Apr 12 14:37:26 2021
    Re: Synchronet 3.18b high CPU usage during FidoNet Poll
    By: Digital Man to Afsfigueiredo on Sat Apr 10 2021 07:48 pm

    I don't know off the top of my head - but see that "Unconfigured address" li That seems to indicate that you do not have 4:801/10 configured as a linked node in EchoCfg. Is that expected?
    --
    digital man


    Hi!
    I've deployed the SoftSolutions , again, using Linux , and now all is working as expected :)

    As part of this reinstall, i've configured all from scratch , so i can't confirm if it was something related to the settings , VM, or Windows .

    Now with Debian 10 everything is working as expected !

    Thank you !

    ---
    þ Synchronet þ My Brand-New BBS
    * Origin: Vertrauen - [vert/cvs/bbs].synchro.net (1:103/705)