• A36 fidopoll.log info

    From bcw142@21:1/145 to All on Tuesday, November 07, 2017 08:54:46
    Trying to figure out what is causing the problems now that I've install A36 11/06/2017 version. Seems I connect but it doesn't verify things correctly.
    Now on the Hub end is A35 release on a Pi. When I do fidopoll I see:
    $ ./fidopoll 21:1/145

    FIDOPOLL Version 1.12 A36

    Scanning 21:1/145
    Queued 0 files (0 bytes) to 21:1/145
    Polling BINKP node 21:1/145
    Connecting to bcw142.zapto.org:24556
    Connected
    System Mystic Pi BBS
    SysOp bcw142
    Mailer Mystic/1.12A35 binkp/1.0
    Receiving: 00000003.fr2 (58,316 bytes)
    Session timeout
    Session complete (0 sent, 0 rcvd, 0 skip)

    So got a timeout and need to check the logs. /mystic/logs/fidopoll.log shows:

    Nov 07 07:25:33 FIDOPOLL Version 1.12 A36
    Nov 07 07:25:33 Scanning 21:1/145
    Nov 07 07:25:33 Queued 0 files (0 bytes) to 21:1/145
    Nov 07 07:25:33 Polling BINKP node 21:1/145
    Nov 07 07:25:33 Connecting to bcw142.zapto.org:24556
    Nov 07 07:25:34 Connected
    Nov 07 07:25:34 Authorization State: 1 Have:FALSE Need:TRUE
    Nov 07 07:25:34 Sent Frame: NUL SYS Workpoint - U can't get here
    Nov 07 07:25:34 Sent Frame: NUL ZYZ bcw142
    Nov 07 07:25:34 Sent Frame: NUL VER Mystic/1.12A36 binkp/1.0
    Nov 07 07:25:34 Sent Frame: ADR 21:1/145.3@fsxnet
    Nov 07 07:25:34 Authorization State: 2 Have:FALSE Need:TRUE

    Authorization seems to fail Have:FALSE Need:TRUE then correct data,
    then another Authorization Have:FALSE Need:TRUE Any idea what this is
    really saying? There is a password all caps, same one on both ends.
    Why should this fail and isn't that so important that it's really dead
    at this point? It continues to check:

    Nov 07 07:25:34 Begin command frame: NUL (Size=45)
    Nov 07 07:25:34 End Command frame: NUL OPT CRAM-MD5-7888bcc5eba07504bb7b92ee740d120a
    Nov 07 07:25:34 Authorization State: 2 Have:TRUE Need:FALSE
    Nov 07 07:25:34 Received challenge (7888bcc5eba07504bb7b92ee740d120a)
    Nov 07 07:25:34 Begin command frame: NUL (Size=17)
    Nov 07 07:25:34 End Command frame: NUL SYS Mystic Pi BBS
    Nov 07 07:25:34 System Mystic Pi BBS
    Nov 07 07:25:34 Begin command frame: NUL (Size=10)
    Nov 07 07:25:34 End Command frame: NUL ZYZ bcw142
    Nov 07 07:25:34 SysOp bcw142
    Nov 07 07:25:34 Begin command frame: NUL (Size=28)
    Nov 07 07:25:34 End Command frame: NUL VER Mystic/1.12A35 binkp/1.0
    Nov 07 07:25:34 Mailer Mystic/1.12A35 binkp/1.0
    Nov 07 07:25:34 Begin command frame: ADR (Size=33)
    Nov 07 07:25:34 End Command frame: ADR 21:1/145@fsxnet 80:603/0@retronet
    Nov 07 07:25:34 Sent Frame: PWD CRAM-MD5-8f76532ab4d6e6131227c6600b21a429
    Nov 07 07:25:34 Authorization State: 5 Have:FALSE Need:TRUE
    Nov 07 07:25:34 Begin command frame: OK (Size=6)
    Nov 07 07:25:34 End Command frame: OK secure
    Nov 07 07:25:34 Authorization State: 5 Have:TRUE Need:FALSE
    Nov 07 07:25:34 State Rx:WaitFile Tx:NextFile Have:FALSE Need:TRUE
    Nov 07 07:25:34 Sent Frame: EOB
    Nov 07 07:25:34 Begin command frame: FILE (Size=31)
    Nov 07 07:25:34 End Command frame: FILE 00000003.fr2 58316 1509750936 0
    Nov 07 07:25:34 State Rx:WaitFile Tx:Done Have:TRUE Need:FALSE
    Nov 07 07:25:34 File exists [Remote size=58316 Local size=0] [Remote date=1264826866 Local date=1264826866]
    Nov 07 07:25:34 Sent Frame: GET 00000003.fr2 58316 1509750936 0
    Nov 07 07:25:34 Resuming file at offset 0
    Nov 07 07:25:34 Receiving: 00000003.fr2 (58,316 bytes)
    Nov 07 07:25:34 State Rx:GetData Tx:Done Have:FALSE Need:TRUE
    Nov 07 07:25:34 Begin command frame: �b]���������wb0�b@�b��bТ@ �@Т@Т@��@��@��@��@Т@Т@Т@Т@� (Size=-1)
    Nov 07 07:25:34 GetDataStr size mismatch. Expected:-1 Actual:0
    Nov 07 07:25:34 End Command frame: �b]���������wb0�b@�b��bТ@ �@Т@Т@��@��@��@��@Т@Т@Т@Т@�
    Nov 07 07:25:34 State Rx:GetData Tx:Done Have:TRUE Need:FALSE
    Nov 07 07:27:04 Session timeout
    Nov 07 07:27:04 Session complete (0 sent, 0 rcvd, 0 skip)

    So again Authorization State: 5 Have:TRUE Need:FALSE fails and
    Rx:WaitFile Tx:NextFile Have:FALSE Need:TRUE the packet didn't see the end.
    So bad packet and I should go kill it on the Hub?
    On the Hub:
    pi@npie:/mystic $ ls -la echomail/in
    total 64
    drwxr-xr-x 3 pi pi 4096 Nov 6 18:20 .
    drwxr-xr-x 4 pi pi 4096 Sep 3 10:45 ..
    -rw-r--r-- 1 pi pi 0 Nov 7 07:11 0000ffd3.tu5
    -rw-r--r-- 1 pi pi 52152 Oct 23 00:15 fsxinfo.1.zip
    drwxr-xr-x 2 pi pi 4096 Sep 3 10:45 unsecure
    pi@npie:/mystic $ ls echomail/out/fidonet
    00010064.flo 00010091.pnt 03f2c103.pkt 03f83f39.pkt
    pi@npie:/mystic $ ls echomail/out/fidonet/00010091.pnt
    00000003.fr2 00000003.mo0 00000003.su0 00000004.mo0
    00000003.hlo 00000003.sa0 00000004.flo 00000004.su8
    pi@npie:/mystic $ ls filebox/_z0n0n0

    So the filebox has nothing and there are no .bsy in outgoing, incoming or fidopoll. Now one thing that is going on is this point 3 system is behind
    a firewall, but the typical one so it polls out to the Hub which has it on hold waiting for it, which is why it connects above. Any idea what to try next?
    I've polled a few times, same results. The fidopoll.log on the hub shows nothing at 07:25, only a poll at 07:20 from point 1 and another at 07:30
    from point 2 which is VER Mystic/1.12A36 binkp/1.0 another x64 11/06 A36
    that works and uses the internal address to get to the hub.

    --- Mystic BBS v1.12 A35 (Raspberry Pi/32)
    * Origin: Mystic Pi BBS bcw142.zapto.org (21:1/145)