• Polling Loop?

    From Jeff Smith@1:282/1031 to All/Kim on Tuesday, March 12, 2019 09:22:02
    Hello There,

    Here is something I have noticed that has happened occasionally for awhile now.
    BBBS will get stuck in a continuous polling loop. It doesn't always involve the same remote system or even the same FTN. This round of polling continued until
    I seen it happening and issued the command 'bbbs bom d 1:14/5'. Any thoughts on
    what might be causing this behavior? It's like BBBS doesn't detect that the connection was completed and tries again and again and again. Or Mystic isn't expressing that the connection was completed and so BBBS retries. This also happened on previous versions of BBBS.

    190312 07:34 Calling The Twisted Balloon, ftn.region14.org
    190312 07:34 CONNECT 57600/RAW
    190312 07:34 BinkP mail session
    190312 07:34 Region 14 IP Server, 1:14/5
    190312 07:34 AKA: 1:14/0
    190312 07:34 SysOp: Jeff Smith
    190312 07:34 From: Anoka, MN, USA
    190312 07:34 Using: binkd/1.0.4/Linux binkp/1.1
    190312 07:34 Flags: 115200,TCP,BINKP
    190312 07:34 Mail session completed
    190312 07:34 --------------------------

    [...] Another 32 consecutive and continuous polls

    190312 07:37 --------------------------
    190312 07:37 Calling The Twisted Balloon, ftn.region14.org
    190312 07:37 CONNECT 57600/RAW
    190312 07:37 BinkP mail session
    190312 07:37 Region 14 IP Server, 1:14/5
    190312 07:37 AKA: 1:14/0
    190312 07:37 SysOp: Jeff Smith
    190312 07:37 From: Anoka, MN, USA
    190312 07:37 Using: binkd/1.0.4/Linux binkp/1.1
    190312 07:37 Flags: 115200,TCP,BINKP
    190312 07:37 Mail session completed


    Jeff

    --- BBBS/Li6 v4.10 Toy-4
    * Origin: Fidoneet: The Ouija Board - Anoka, MN -bbs.ouijabrd.net (1:282/1031)
  • From Alan Ianson@1:153/757 to Jeff Smith on Tuesday, March 12, 2019 12:31:24
    Hello There,

    Here is something I have noticed that has happened occasionally for awhile now >BBBS will get stuck in a continuous polling loop. It doesn't always involve th >same remote system or even the same FTN. This round of polling continued unti >I seen it happening and issued the command 'bbbs bom d 1:14/5'. Any thoughts o
    what might be causing this behavior? It's like BBBS doesn't detect that the connection was completed and tries again and again and again. Or Mystic isn't expressing that the connection was completed and so BBBS retries. This also happened on previous versions of BBBS.

    I've seen this too, not continuous polling but I sometimes press <alt> p from BBBS to poll a node and the poll will complete successfully but the poll isn't removed so BBBS polls the node a second time. I see that at times when polling a link running Mystic or binkd.

    I'm also seeing something odd about seen-bys in zone 21.. some 0/??? lines. Does your BBBS receive mail in Z21 and have you seen that?

    --- BBBS/Li6 v4.10 Toy-4
    * Origin: The Rusty MailBox - Penticton, BC Canada (1:153/757)
  • From Jeff Smith@1:282/1031 to Alan Ianson on Tuesday, March 12, 2019 15:37:54
    Hello Alan,

    Here is something I have noticed that has happened occasionally for awhile no >>BBBS will get stuck in a continuous polling loop Or Mystic isn't
    expressing that the connection was completed and so BBBS retries. This also >> happened on previous versions of BBBS.

    I've seen this too, not continuous polling but I sometimes press <alt> p from
    BBBS to poll a node and the poll will complete successfully but the poll isn't >removed so BBBS polls the node a second time. I see that at times when polling
    a link running Mystic or binkd.

    I did some checking of my saved logs from last year and I am thinking it is a relationship
    between BBBS and Mystic as the majority of times it has happened it involved a Mystic
    system. Currently last time it happened was with my Mystic 1:14/5 system and according
    to the logs the next previous time was with Paul's 21:1/100 Mystic system. In testing it
    doesn't look to happen if Mystic initiates the poll to BBBS. But is likely to happen if
    BBBS initiates the poll to the Mystic system. I will also be providing my findings to
    the Mystic author James Coyle.

    Jeff

    --- BBBS/Li6 v4.10 Toy-4
    * Origin: Fidoneet: The Ouija Board - Anoka, MN -bbs.ouijabrd.net (1:282/1031)
  • From Paul Hayton@3:770/100 to Jeff Smith on Thursday, March 14, 2019 21:16:13
    On 12 Mar 2019 at 03:37p, Jeff Smith pondered and said...

    system. Currently last time it happened was with my Mystic 1:14/5 system and according
    to the logs the next previous time was with Paul's 21:1/100 Mystic
    system. In testing it

    Jeff, just reaching out here. I can see problems with you polling the Z21 NET
    1 HUB looks like no correct AKAs are being presented?

    [snip]

    + 2019.03.14 18:23:54 BINKP > Connect on slot 1/25 (65.103.12.161)
    + 2019.03.14 18:23:54 BINKP 1-HostName Unknown
    + 2019.03.14 18:23:54 BINKP 1-S: NUL OPT CRAM-MD5-f66e688ea332a93cb8dbb22a174cf960
    + 2019.03.14 18:23:54 BINKP 1-S: NUL SYS fsxHUB Risa [NET1]
    + 2019.03.14 18:23:54 BINKP 1-S: NUL ZYZ Avon
    + 2019.03.14 18:23:54 BINKP 1-S: NUL TIME Thu, 14 Mar 2019 18:23:54 1300
    + 2019.03.14 18:23:54 BINKP 1-S: NUL VER Mystic/1.12A43 binkp/1.0
    + 2019.03.14 18:23:54 BINKP 1-S: NUL BUILD 2019/03/03 01:35:01 Windows/32
    + 2019.03.14 18:23:54 BINKP 1-S: ADR 21:1/100@fsxnet 21:1/3@fsxnet 21:1/2@fsxnet 21:1/0@fsxnet 21:0/0@fsxnet
    + 2019.03.14 18:23:55 BINKP 1-R: NUL ZYZ Jeff Smith
    + 2019.03.14 18:23:55 BINKP 1-SysOp Jeff Smith
    + 2019.03.14 18:23:55 BINKP 1-R: NUL LOC Anoka, MN - bbs.ouijabrd.net
    + 2019.03.14 18:23:55 BINKP 1-Location Anoka, MN - bbs.ouijabrd.net
    + 2019.03.14 18:23:55 BINKP 1-R: NUL VER BBBS/Li6 v4.10 Toy-4 binkp/1.0
    + 2019.03.14 18:23:55 BINKP 1-Mailer BBBS/Li6 v4.10 Toy-4 binkp/1.0
    + 2019.03.14 18:23:55 BINKP 1-R: NUL NDL CM,IBM,IFT,INA
    + 2019.03.14 18:23:55 BINKP 1-Info NDL CM,IBM,IFT,INA
    + 2019.03.14 18:23:55 BINKP 1-R: ADR 1:282/1031.0@fidonet 21:1/128.1@fsxnet 1:299/0.0@fidonet 1:300/0.0@fidonet 1:290/0.0@fidonet
    + 2019.03.14 18:23:55 BINKP 1-R: PWD
    + 2019.03.14 18:23:55 BINKP 1-No matching address to authenticate
    + 2019.03.14 18:23:55 BINKP 1-Cannot authenticate client
    + 2019.03.14 18:23:55 BINKP 1-S: ERR Bad address or password
    + 2019.03.14 18:23:55 BINKP 1-Client shutting down

    [snip]

    On the face of it you're presenting a point address when the hub is looking
    for a full address?

    Best, Paul

    Best, Paul

    --- E:avon@bbs.nz ------ W:bbs.nz ---
    --- K:keybase.io/avon --------------

    --- Mystic BBS v1.12 A43 2019/03/03 (Windows/32)
    * Origin: Agency BBS | Dunedin, New Zealand | agency.bbs.nz (3:770/100)
  • From Jeff Smith@1:282/1031 to Paul Hayton on Thursday, March 14, 2019 08:37:44
    Hello Paul,


    Jeff, just reaching out here. I can see problems with you polling the Z21 NET 1 HUB looks like no correct AKAs are being presented?
    [snip]
    + 2019.03.14 18:23:54 BINKP > Connect on slot 1/25 (65.103.12.161)
    + 2019.03.14 18:23:54 BINKP 1-HostName Unknown
    + 2019.03.14 18:23:54 BINKP 1-S: NUL OPT CRAM-MD5-f66e688ea332a93cb8dbb22a174cf960
    + 2019.03.14 18:23:54 BINKP 1-S: NUL SYS fsxHUB Risa [NET1]
    + 2019.03.14 18:23:54 BINKP 1-S: NUL ZYZ Avon
    + 2019.03.14 18:23:54 BINKP 1-S: NUL TIME Thu, 14 Mar 2019 18:23:54 1300
    + 2019.03.14 18:23:54 BINKP 1-S: NUL VER Mystic/1.12A43 binkp/1.0
    + 2019.03.14 18:23:54 BINKP 1-S: NUL BUILD 2019/03/03 01:35:01 Windows/32
    + 2019.03.14 18:23:54 BINKP 1-S: ADR 21:1/100@fsxnet 21:1/3@fsxnet

    That is because I switched 21:1/128 over to Mystic at bbs.twisted-balloon.org (65.103.12.163) and now BBBS bbs.ouijabrd.net (65.103.12.161) is now 21:1/128.1.
    I have been polling you from Mystic and can connect to you fine. I had just completed
    the actual switch over and was testing the connection. I sent you an email regarding
    the switchover so that you could make any necessary adjustments on your end.

    The polling loop situation currently exists between 1:282/1031 BBBS and 1:14/5 Mystic.
    And in the past did exist between 21:1/128 BBBS and you 21:1/100 Mystic. That is
    where I think the confusion came from. I did notice that the problem happens when
    BBBS polls Mystic but doesn't seem to happen if Mystic polls BBBS. I suspect that the
    problem stems from either the way BBBS is detecting a completed connection or the way
    that Mystic is expressing a completed connection.

    Jeff

    --- BBBS/Li6 v4.10 Toy-4
    * Origin: Fidoneet: The Ouija Board - Anoka, MN -bbs.ouijabrd.net (1:282/1031)
  • From Kim Heino@2:222/2 to Jeff Smith on Friday, March 15, 2019 18:41:52
    This round of polling continued until I seen it happening and issued
    the command 'bbbs bom d 1:14/5'.

    190312 07:34 Region 14 IP Server, 1:14/5
    190312 07:34 AKA: 1:14/0

    Polling loop can happen if:

    1) You have crashmail to nodenumber X, but remote doesn't present that nodenumber as primary / AKA.

    2) Mail session is not fully completed and that poll message still exists.

    If your above "bbbs bom d 1:14/5" helps then it's not case #1, as primary is 1:14/5.

    Unfortunately BBBS doesn't log enough to see if it's case #2. Can you get debug
    logs from remote site? Does it disconnect incoming connection for some reason?

    --- BBBS/Li6 v4.10 Toy-4
    * Origin: * BCG-Box, On The Air Since 11th February 1987! * (2:222/2)
  • From Jeff Smith@1:282/1031 to Kim Heino on Friday, March 15, 2019 17:46:02
    Hello Kim,

    This round of polling continued until I seen it happening and issued
    the command 'bbbs bom d 1:14/5'.

    Polling loop can happen if:
    1) You have crashmail to nodenumber X, but remote doesn't present that nodenumber as primary / AKA.

    Fortunately in this particular situation both systems are under my control. Heck, the
    PC's are sitting next to each other. :-)

    In this case actual crash mail isn't necessary. All I have to do is tell BBBS to poll
    1:14/5 which is the primary AKA that Mystic presents and it will poll. And according
    to the logs complete the poll. Then immediately poll again, and again...

    2) Mail session is not fully completed and that poll message still exists.
    If your above "bbbs bom d 1:14/5" helps then it's not case #1, as primary is 1:14/5.

    Yes, entering the "bbbs bom d 1:14/5" looks to stop the polling loop.

    Unfortunately BBBS doesn't log enough to see if it's case #2. Can you get debug
    logs from remote site? Does it disconnect incoming connection for some reason?

    With Mystic there are several levels of logging which includes "Debug". I will increase
    the log level and see what it can tell me and keep you posted.

    I did also notice that this only happens when BBBS polls a Mystic system. If mystic
    polls BBBS no such polling loop occurs. As a temporary workaround I started having
    Mystic do the polling. Which I will change back for testing purposes.

    Jeff

    --- BBBS/Li6 v4.10 Toy-4
    * Origin: Fidoneet: The Ouija Board - Anoka, MN -bbs.ouijabrd.net (1:282/1031)
  • From Jeff Smith@1:282/1031 to Kim Heino on Sunday, March 17, 2019 03:16:14
    Hello Kim,

    Unfortunately BBBS doesn't log enough to see if it's case #2. Can you get debu >logs from remote site? Does it disconnect incoming connection for some reason?

    In talking with James Coyle it seems that Mystic also doesn't log enough to provide the needed info on the actual connection process. It looks to provide debug logging for other system operations though. If the situation changes or an update becomes available that allows for increased logging I will let you know on what information that I acquire regarding the situation.

    Jeff

    --- BBBS/Li6 v4.10 Toy-4
    * Origin: Fidoneet: The Ouija Board - Anoka, MN -bbs.ouijabrd.net (1:282/1031)