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)