1. Forum
  2. FidoNet
  3. MYSTIC

  • session timeouts

    From Edmund Wong@1:153/7083 to All on Tue Nov 30 18:07:50 2021
    Hi,

    I think I'm having some issues with my binkp connection wrt TICs.
    Here's a sample of the log:

    2021.11.28 03:08:58 BINKP 1-Receiving: DB4G.ZIP (2,531,781 bytes)
    2021.11.28 03:09:29 BINKP 1-Session timeout
    2021.11.28 03:09:29 BINKP 1-Session ended (0 sent, 0 rcvd, 0 skip)
    ...
    (Another attempt at sending by my uplink)
    ...
    2021.11.28 03:09:58 BINKP 1-Renaming file DB4G.ZIP to DB4G.1.ZIP
    2021.11.28 03:09:58 BINKP 1-Receiving: DB4G.1.ZIP (2,531,781 bytes)
    2021.11.28 03:10:30 BINKP 1-Session timeout
    2021.11.28 03:10:30 BINKP 1-Session ended (0 sent, 0 rcvd, 0 skip)
    ...
    (next try I get the following...)
    ...
    2021.11.28 03:14:58 BINKP 1-Renaming file DB4G.ZIP to DB4G.1.ZIP
    2021.11.28 03:14:58 BINKP 1-Renaming file DB4G.ZIP to DB4G.2.ZIP
    2021.11.28 03:14:58 BINKP 1-Renaming file DB4G.ZIP to DB4G.3.ZIP
    2021.11.28 03:14:58 BINKP 1-Receiving: DB4G.3.ZIP (2,531,781 bytes)
    2021.11.28 03:15:31 BINKP 1-Session timeout
    2021.11.28 03:15:31 BINKP 1-Session ended (0 sent, 0 rcvd, 0 skip)
    ...

    *eventually* @ 03:21:27

    2021.11.28 03:21:18 BINKP 1-Renaming file DB4G.ZIP to DB4G.7.ZIP
    2021.11.28 03:21:18 BINKP 1-Receiving: DB4G.7.ZIP (2,531,781 bytes)
    2021.11.28 03:21:27 BINKP 1-Receiving: 61472b96.tic (699 bytes)
    2021.11.28 03:21:27 BINKP 1-Receiving: DB4S.ZIP (2,531,421 bytes)
    2021.11.28 03:21:31 BINKP 1-Receiving: 61472b98.tic (699 bytes)
    2021.11.28 03:21:31 BINKP 1-Receiving: 0000e74a.saa (812 bytes)
    2021.11.28 03:21:31 BINKP 1-Session ended (0 sent, 5 rcvd, 0 skip)
    ..

    So right now, I have a bunch of files in my echomail/in that
    I'll sort out; but I'd like to ask what might be going on
    with my system?

    Any help appreciated

    Edmund

    ... How do I set my laser printer to stun?

    --- Mystic BBS v1.12 A47 2021/11/22 (Linux/32)
    * Origin: Eagle's BBS (1:153/7083)
  • From Al@1:153/757 to Edmund Wong on Tue Nov 30 05:09:28 2021
    Hello Edmund,

    I think I'm having some issues with my binkp connection wrt TICs.
    Here's a sample of the log:

    2021.11.28 03:08:58 BINKP 1-Receiving: DB4G.ZIP (2,531,781 bytes) 2021.11.28 03:09:29 BINKP 1-Session timeout
    2021.11.28 03:09:29 BINKP 1-Session ended (0 sent, 0 rcvd, 0 skip)
    ...

    Here is my log from a failed session when sending these files.


    ==== Begin: "log.txt" ====
    27-Nov-2021 11:18:40 mbcico[29940] MBCICO v1.0.7.22
    27-Nov-2021 11:18:40 mbcico[29940] Cmd: mbcico f7083.n153.z1.fidonet
    + 27-Nov-2021 11:18:40 mbcico[29940] Options: Call WaZOO EMSI Freqs Zmodem ZedZap Hydra PLZ GZ/BZ2 NoNR CRC
    + 27-Nov-2021 11:18:40 mbcico[29940] Calling 1:153/7083@fidonet (Eagles's BBS, phone (null))
    + 27-Nov-2021 11:18:40 mbcico[29940] Open TCP connection to "bbs.seabot.space:24554"
    + 27-Nov-2021 11:18:40 mbcico[29940] Trying IPv4 223.255.146.70 port 24554
    + 27-Nov-2021 11:18:40 mbcico[29940] Established IBN/TCP IPv4 connection with 223.255.146.70, port 24554
    + 27-Nov-2021 11:18:40 mbcico[29940] GeoIP location: Hong Kong, HK AS
    + 27-Nov-2021 11:18:40 mbcico[29940] Start outbound Binkp session with 1:153/7083@fidonet
    + 27-Nov-2021 11:18:40 mbcico[29940] Binkp: start session
    + 27-Nov-2021 11:18:40 mbcico[29940] Binkp: node 1:153/7083@fidonet
    + 27-Nov-2021 11:18:41 mbcico[29940] Options : CRAM-MD5-dbf32f237a350dbca448394d400cf448
    + 27-Nov-2021 11:18:41 mbcico[29940] System : Eagle's BBS
    + 27-Nov-2021 11:18:41 mbcico[29940] Sysop : Edmund Wong
    + 27-Nov-2021 11:18:41 mbcico[29940] Time : Sun, 28 Nov 2021 03:18:57 +0800 + 27-Nov-2021 11:18:41 mbcico[29940] Uses : Mystic/1.12A47 binkp/1.0
    + 27-Nov-2021 11:18:41 mbcico[29940] Binkp: M_NUL "BUILD 2021/11/22 11:43:05 Linux/32"
    + 27-Nov-2021 11:18:41 mbcico[29940] address : 1:153/7083@FidoNet
    + 27-Nov-2021 11:18:41 mbcico[29940] address : 27:1/0@pwnet
    + 27-Nov-2021 11:18:41 mbcico[29940] address : 1:153/757.23@FidoNet
    + 27-Nov-2021 11:18:41 mbcico[29940] Binkp: MD5 protected session
    + 27-Nov-2021 11:18:41 mbcico[29940] Binkp: mail 0, files 5065412 bytes
    + 27-Nov-2021 11:18:41 mbcico[29940] Binkp: send "/opt/mbse/ftp/pub/bbs/dbridge/DB4G.ZIP" as "DB4G.ZIP"
    + 27-Nov-2021 11:18:41 mbcico[29940] Binkp: size 2531781 bytes, dated Nov 27 11:05:08, comp No
    + 27-Nov-2021 11:18:41 mbcico[29940] Binkp: M_NUL "QSIZE 0 files 0 bytes"
    ! 27-Nov-2021 11:19:12 mbcico[29940] tty_read: error flag
    ? 27-Nov-2021 11:19:12 mbcico[29940] Binkp: receiver status Error
    + 27-Nov-2021 11:19:12 mbcico[29940] Binkp: session finished, rc=108
    + 27-Nov-2021 11:19:14 mbcico[29940] Closing TCP connection, connected 34.00s
    + 27-Nov-2021 11:19:14 mbcico[29940] Call to 1:153/7083@fidonet failed (rc=108)
    + 27-Nov-2021 11:19:14 mbcico[29940] Terminated with error 108
    + 27-Nov-2021 11:19:14 mbcico[29940] Sent 614400 bytes, received 0 bytes, avg 19200 cps
    + 27-Nov-2021 11:19:14 mbcico[29940] Connected 34.00s
    27-Nov-2021 11:19:14 mbcico[29940] MBCICO finished in 34.00s
    ==== End: "log.txt" ====

    If you look 9 lines up there is an tty_read error. Looking up error 108 in the MBSE documentation that is listed as a file transfer error.

    I also send these files to my own Mystic BBS and I have never had this kind of error when transferring files.

    I am also linked to three Mystic BBSs and these errors never happen when transferring mail/files. At least I haven't seen it and it hasn't been reported to me.

    And here is the following session that looks successful.

    ==== Begin: "log.txt" ====
    27-Nov-2021 11:21:01 mbcico[29941] MBCICO v1.0.7.22
    27-Nov-2021 11:21:01 mbcico[29941] Cmd: mbcico f7083.n153.z1.fidonet
    + 27-Nov-2021 11:21:01 mbcico[29941] Options: Call WaZOO EMSI Freqs Zmodem ZedZap Hydra PLZ GZ/BZ2 NoNR CRC
    + 27-Nov-2021 11:21:01 mbcico[29941] Calling 1:153/7083@fidonet (Eagles's BBS, phone (null))
    + 27-Nov-2021 11:21:01 mbcico[29941] Open TCP connection to "bbs.seabot.space:24554"
    + 27-Nov-2021 11:21:01 mbcico[29941] Trying IPv4 223.255.146.70 port 24554
    + 27-Nov-2021 11:21:01 mbcico[29941] Established IBN/TCP IPv4 connection with 223.255.146.70, port 24554
    + 27-Nov-2021 11:21:01 mbcico[29941] GeoIP location: Hong Kong, HK AS
    + 27-Nov-2021 11:21:01 mbcico[29941] Start outbound Binkp session with 1:153/7083@fidonet
    + 27-Nov-2021 11:21:01 mbcico[29941] Binkp: start session
    + 27-Nov-2021 11:21:01 mbcico[29941] Binkp: node 1:153/7083@fidonet
    + 27-Nov-2021 11:21:01 mbcico[29941] Options : CRAM-MD5-7ed3cdb5b4ac4e35b34b6f23936d19bb
    + 27-Nov-2021 11:21:01 mbcico[29941] System : Eagle's BBS
    + 27-Nov-2021 11:21:01 mbcico[29941] Sysop : Edmund Wong
    + 27-Nov-2021 11:21:01 mbcico[29941] Time : Sun, 28 Nov 2021 03:21:17 +0800 + 27-Nov-2021 11:21:01 mbcico[29941] Uses : Mystic/1.12A47 binkp/1.0
    + 27-Nov-2021 11:21:01 mbcico[29941] Binkp: M_NUL "BUILD 2021/11/22 11:43:05 Linux/32"
    + 27-Nov-2021 11:21:01 mbcico[29941] address : 1:153/7083@FidoNet
    + 27-Nov-2021 11:21:01 mbcico[29941] address : 27:1/0@pwnet
    + 27-Nov-2021 11:21:01 mbcico[29941] address : 1:153/757.23@FidoNet
    + 27-Nov-2021 11:21:02 mbcico[29941] Binkp: MD5 protected session
    + 27-Nov-2021 11:21:02 mbcico[29941] Binkp: mail 0, files 5065412 bytes
    + 27-Nov-2021 11:21:02 mbcico[29941] Binkp: send "/opt/mbse/ftp/pub/bbs/dbridge/DB4G.ZIP" as "DB4G.ZIP"
    + 27-Nov-2021 11:21:02 mbcico[29941] Binkp: size 2531781 bytes, dated Nov 27 11:05:08, comp No
    + 27-Nov-2021 11:21:02 mbcico[29941] Binkp: M_NUL "QSIZE 0 files 0 bytes"
    + 27-Nov-2021 11:21:05 mbcico[29941] Binkp: OK 2531781 bytes sent in 2.740 seconds (902.351 Kb/s)
    + 27-Nov-2021 11:21:05 mbcico[29941] Binkp: send "/opt/mbse/var/ticqueue/61472b96.tic" as "61472b96.tic"
    + 27-Nov-2021 11:21:05 mbcico[29941] Binkp: size 699 bytes, dated Nov 27 11:07:56, comp No
    + 27-Nov-2021 11:21:05 mbcico[29941] Binkp: OK 699 bytes sent in 0.001 seconds (682.617 Kb/s)
    + 27-Nov-2021 11:21:05 mbcico[29941] Binkp: send "/opt/mbse/ftp/pub/bbs/dbridge/DB4S.ZIP" as "DB4S.ZIP"
    + 27-Nov-2021 11:21:05 mbcico[29941] Binkp: size 2531421 bytes, dated Nov 27 11:05:09, comp No
    + 27-Nov-2021 11:21:11 mbcico[29941] Binkp: OK 2531421 bytes sent in 5.995 seconds (412.359 Kb/s)
    + 27-Nov-2021 11:21:11 mbcico[29941] Binkp: send "/opt/mbse/var/ticqueue/61472b98.tic" as "61472b98.tic"
    + 27-Nov-2021 11:21:11 mbcico[29941] Binkp: size 699 bytes, dated Nov 27 11:07:57, comp No
    + 27-Nov-2021 11:21:11 mbcico[29941] Binkp: OK 699 bytes sent in 0.001 seconds (682.617 Kb/s)
    + 27-Nov-2021 11:21:11 mbcico[29941] Binkp: send "/opt/mbse/var/bso/outbound/0000e74a.saa" as "0000e74a.saa"
    + 27-Nov-2021 11:21:11 mbcico[29941] Binkp: size 812 bytes, dated Nov 27 11:10:17, comp No
    + 27-Nov-2021 11:21:11 mbcico[29941] Binkp: OK 812 bytes sent in 0.001 seconds (792.969 Kb/s)
    + 27-Nov-2021 11:21:11 mbcico[29941] Binkp: M_GOT "DB4G.ZIP 2531781 1638039908"
    + 27-Nov-2021 11:21:11 mbcico[29941] Binkp: remote GOT "DB4G.ZIP"
    + 27-Nov-2021 11:21:11 mbcico[29941] Binkp: M_GOT "61472b96.tic 699 1638040076"
    + 27-Nov-2021 11:21:11 mbcico[29941] Binkp: remote GOT "61472b96.tic"
    + 27-Nov-2021 11:21:15 mbcico[29941] Binkp: M_GOT "DB4S.ZIP 2531421 1638039909"
    + 27-Nov-2021 11:21:15 mbcico[29941] Binkp: remote GOT "DB4S.ZIP"
    + 27-Nov-2021 11:21:15 mbcico[29941] Binkp: M_GOT "61472b98.tic 699 1638040077"
    + 27-Nov-2021 11:21:15 mbcico[29941] Binkp: remote GOT "61472b98.tic"
    + 27-Nov-2021 11:21:15 mbcico[29941] Binkp: M_GOT "0000e74a.saa 812 1638040217"
    + 27-Nov-2021 11:21:15 mbcico[29941] Binkp: remote GOT "0000e74a.saa"
    + 27-Nov-2021 11:21:15 mbcico[29941] Binkp: session finished, rc=0
    + 27-Nov-2021 11:21:17 mbcico[29941] Closing TCP connection, connected 16.00s
    + 27-Nov-2021 11:21:17 mbcico[29941] Call to 1:153/7083@fidonet successful (rc=0)
    + 27-Nov-2021 11:21:17 mbcico[29941] Sent 5065412 bytes, received 0 bytes, avg 361815 cps
    + 27-Nov-2021 11:21:17 mbcico[29941] Connected 16.00s
    27-Nov-2021 11:21:17 mbcico[29941] MBCICO finished in 16.00s
    ==== End: "log.txt" ====

    So right now, I have a bunch of files in my echomail/in that
    I'll sort out; but I'd like to ask what might be going on
    with my system?

    Any help appreciated

    Anyone know why this would happen?

    I am at a loss as to where to look next or what the issue might be.

    Ttyl :-),
    Al

    ... If you don't think women are explosive, drop one!
    --- GoldED+/LNX 1.1.5-b20180707
    * Origin: The Rusty MailBox - Penticton, BC Canada (1:153/757)
  • From g00r00@1:129/215 to Edmund Wong on Wed Dec 1 11:24:58 2021
    2021.11.28 03:09:58 BINKP 1-Renaming file DB4G.ZIP to DB4G.1.ZIP 2021.11.28 03:09:58 BINKP 1-Receiving: DB4G.1.ZIP (2,531,781 bytes) 2021.11.28 03:10:30 BINKP 1-Session timeout

    It looks like Mystic is waiting for something from the server and but the connection goes dead causing it to timeout the connection.

    Its too hard to see more with the limited logging. I have a debug logging that I will enable in a new pre-alpha build if you are willing to install it and give it another go. It should create a much more detailed and confusing log to sort through ;)

    To upgrade download from the prealpha directory on the website, then shut everything down and do an "install replace /mystic" to replace the old with the new.

    If I had to guess it might be something with the file renaming process.

    ... The person who snores the loudest will fall asleep first

    --- Mystic BBS v1.12 A47 2021/11/24 (Windows/64)
    * Origin: Sector 7 * Mystic WHQ (1:129/215)
  • From Edmund Wong@1:153/7083 to g00r00 on Thu Dec 2 08:14:50 2021
    Hi g00r00,

    Its too hard to see more with the limited logging. I have a debug
    logging that I will enable in a new pre-alpha build if you are willing
    to install it and give it another go. It should create a much more detailed and confusing log to sort through ;)


    I just upgraded the binaries. Will monitor the logs to see what's going on.
    As I had thought it was binkp's timeout setting; but something buggered
    up yesterday while I wasn't looking and I found two bad files in
    the badfiles directory.

    Thanks

    Edmund

    ... As I said before, I never repeat myself

    --- Mystic BBS v1.12 A47 2021/12/01 (Linux/32)
    * Origin: Eagle's BBS (1:153/7083)
  • From g00r00@1:129/215 to Edmund Wong on Thu Dec 2 11:12:44 2021
    I just upgraded the binaries. Will monitor the logs to see what's going on. As I had thought it was binkp's timeout setting; but something buggered up yesterday while I wasn't looking and I found two bad files
    in the badfiles directory.

    Thanks hopefully that will give me a better indicator of where its getting stuck so we can determine which end is confused.

    ... Why is the man who invests all your money called a broker?

    --- Mystic BBS v1.12 A47 2021/11/24 (Windows/64)
    * Origin: Sector 7 * Mystic WHQ (1:129/215)