open https://gitlab.synchro.net/main/sbbs/-/issues/1104

Howdy @Deuce

I'm tracking down why my session with clrghouz are finishing failed - and it appears only with Synchronet binkit.

I think its because binkit advertises 1.1, but it doesnt send a final round of EOB and wait for EOB.

In the following outbound session:

```
root@alterant:/opt/sbbs# jsexec -L10 binkit -l 516:1/0

JSexec v3.21a-Linux master/b7d3db6c3 - Execute Synchronet JavaScript Module Compiled Sep 28 2025 18:57 with GCC 10.2.1
...
Connection to clrghouz.bbs.dege.au:24564 successful
Sending M_NUL command args: OPT CRYPT
Sent M_NUL command
Sending M_NUL command args: SYS Alterant
Sent M_NUL command
Sending M_NUL command args: ZYZ deon
Sent M_NUL command
Sending M_NUL command args: LOC Parkdale, VIC
Sent M_NUL command
Sending M_NUL command args: NDL 115200,TCP,BINKP
Sent M_NUL command
Sending M_NUL command args: TIME Tue Mar 24 2026 15:34:07 GMT+1100 (AEDT)
Sent M_NUL command
Sending M_NUL command args: VER BinkIT/2.41,JSBinkP/4,sbbs3.21a/Linux binkp/1.1 Sent M_NUL command
...
Sending file: ../fido/outbound.204/69c2140e.pkt (0.5KB)
Sending M_FILE command args: 69c2140e.pkt 529 1774326798 0
Sent M_FILE command
Sending 529 bytes of data
Sent file: ../fido/outbound.204/69c2140e.pkt (0.5KB)
Sending M_EOB command args:
Sent M_EOB command
Got M_NUL command args: OPT NR MB EXTCMD NZ BZ2 GZ ZSTD BROTLI CRC
Got M_EOB command args:
We got an M_EOB, but there are still 1 files pending M_GOT
Got M_GOT command args: 69c2140e.pkt 529 1774326798
Deleted file: /opt/sbbs/fido/outbound.204/00010000.clo
Got M_FILE command args: 000e5343.pkt 1937 1774326849 0
Receiving file: /opt/sbbs/temp/000e5343.pkt (1.9KB)
Got data frame length 1937
Received file: /opt/sbbs/temp/000e5343.pkt (1.9KB)
Moving '/opt/sbbs/temp/000e5343.pkt' to '../fido/inbound/000e5343.pkt'.
Sending M_GOT command args: 000e5343.pkt 1937 1774326849
Sent M_GOT command
Got M_EOB command args:
...
```

Since it received a file from me `000e5343.pkt` shouldnt it have sent another S_EOB indicating that there is nothing else (in case it processed that file)? (This is what I see other BINKP implementations do - I always see two EOBs from the remote).

I see the same problem on an inbound session - binkit tears down the session before sending a final round of EOBs.

From: FSP-1024
`The binkp/1.1 protocol defines multiple batches, this means that
after a batch ends (M_EOB frame sent) the mailer checks the
outbound for new files and starts a new batchs if files are found.`
--- SBBSecho 3.37-Linux
* Origin: Vertrauen - [vert/cvs/bbs].synchro.net (1:103/705)

https://gitlab.synchro.net/main/sbbs/-/issues/1104#note_8672

BinkIT is 1.1 compliant. The most obvious possibility is that the other end does not advertise itself as binkp 1.1. Further, you're not showing all the way to the end, so it doesn't clearly show a lack of M_EOB. The extra scan has specific circumstances on when it happens, it's not a blanket "Always send an extra M_EOB" or there would be issues with infinite loops.
--- SBBSecho 3.37-Linux
* Origin: Vertrauen - [vert/cvs/bbs].synchro.net (1:103/705)

https://gitlab.synchro.net/main/sbbs/-/issues/1104#note_8673

So, I'm the other end (ie: my software) - and yes both advertises and interacts with other binkp 1.1 mailers.

The last round of EOB's, as I understand it, is a round of EOBs when there are no transfers - so it wouldnt be infinit. The session stops when one end says I got nothing, and the other end says I also got nothing.

Here is the complete transfer:
```
Adding '../fido/outbound.204/69c2140e.pkt' as '69c2140e.pkt'
Initializing crypt keys.
Sending file: ../fido/outbound.204/69c2140e.pkt (0.5KB)
Sending M_FILE command args: 69c2140e.pkt 529 1774326798 0
Sent M_FILE command
Sending 529 bytes of data
Sent file: ../fido/outbound.204/69c2140e.pkt (0.5KB)
Sending M_EOB command args:
Sent M_EOB command
Got M_NUL command args: OPT NR MB EXTCMD NZ BZ2 GZ ZSTD BROTLI CRC
Got M_EOB command args:
We got an M_EOB, but there are still 1 files pending M_GOT
Got M_GOT command args: 69c2140e.pkt 529 1774326798
Deleted file: /opt/sbbs/fido/outbound.204/00010000.clo
Got M_FILE command args: 000e5343.pkt 1937 1774326849 0
Receiving file: /opt/sbbs/temp/000e5343.pkt (1.9KB)
Got data frame length 1937
Received file: /opt/sbbs/temp/000e5343.pkt (1.9KB)
Moving '/opt/sbbs/temp/000e5343.pkt' to '../fido/inbound/000e5343.pkt'.
Sending M_GOT command args: 000e5343.pkt 1937 1774326849
Sent M_GOT command
Got M_EOB command args:
Deleted file: ../fido/outbound.204/69c2140e.pkt
Unlocking /opt/sbbs/fido/outbound.204/00010000.bsy.
Touching semaphore file: /opt/sbbs/data/fidoin.now
/opt/sbbs/exec/binkit.js executed in 4.09 seconds
```

IE: There wasnt a round of your EOB and my EOB and no files were sent between those messages - which is what I thought binkp 1.1 was?
--- SBBSecho 3.37-Linux
* Origin: Vertrauen - [vert/cvs/bbs].synchro.net (1:103/705)

https://gitlab.synchro.net/main/sbbs/-/issues/1104#note_8675

Ok, so these logs still don't have the messages that are required to enter 1.1 mode in them, I'll need the **full** set of messages in both directions to trace through the BinkIT behaviour. If you don't want to make them public, feel free to email them to me shurd@sasktel.net or upload to sysop on my BBS at bbsdev.net.

Next, it looks like your software is ending the batch early. The binkp spec has strict non-obvious requirements on who goes first and such. It's too late for me to dig into the spec tonight, but I can take a look once I have the complete session to look at.

The line:

We got an M_EOB, but there are still 1 files pending M_GOT

Is a warning, and may be jogging BinkITs elbow so it enters a failsafe state. --- SBBSecho 3.37-Linux
* Origin: Vertrauen - [vert/cvs/bbs].synchro.net (1:103/705)

https://gitlab.synchro.net/main/sbbs/-/issues/1104#note_8676

Oh, are you wanting to see these lines:

```
Will encrypt session.
Got M_ADR command args: 885:2/1.0@bbsdev
Sending M_PWD command args: CRAM-MD5-57ba39092587fa825ede654653390977
Sent M_PWD command
Got M_NUL command args: SYS Clearing Houz
Got M_NUL command args: ZYZ Deon George
Got M_NUL command args: LOC Parkdale AUS AUS
Got M_NUL command args: NDL IBN,IFC,ICM
Got M_NUL command args: TIME Tue, 24 Mar 2026 17:43:48 +1100
Got M_NUL command args: TRNS clrghouz-dev.bbs.dege.au/11514
Got M_NUL command args: VER clrghouz/dev binkp/1.1
Got M_OK command args: secure
Authentication successful: secure
```

You can see it directly, just make a poll to clrhgouz.bbs.dege.au - we have session details defined for `bbsdev`.

Port 24564 is my `dev` environment where I've turned up the debugging. The main mailer is on 24554.

If you give me the number in the `TRNS` line, I can give you the log for that session (on the dev server).
--- SBBSecho 3.37-Linux
* Origin: Vertrauen - [vert/cvs/bbs].synchro.net (1:103/705)

https://gitlab.synchro.net/main/sbbs/-/issues/1104#note_8676

Oh, are you wanting to see these lines:

```
Will encrypt session.
Got M_ADR command args: 911:613/0.0@zeronet 1337:2/100.0@tqwnet 80:774/34.0@retronet 10:1/1.0@private 10:1/0.0@private 10:0/0.0@private 314:413/34.0@pinet 86:600/1.0@nixnet 86:600/0.0@nixnet 86:60/0.0@nixnet 954:700/1.0@hobbynet 999:700/1.0@health 21:3/100.0@fsxnet 3:633/2744.0@fidonet 12:12/0.0@dovenet 12:1/1.0@dovenet 64:500/34.0@cnet 885:2/1.0@bbsdev 516:1/0.0@videotex
Sending M_PWD command args: CRAM-MD5-aa8509062cd8750d86e04c13ba1fa6ff
Sent M_PWD command
Got M_NUL command args: SYS Clearing Houz
Got M_NUL command args: ZYZ Deon George
Got M_NUL command args: LOC Parkdale AUS AUS
Got M_NUL command args: NDL IBN,IFC,ICM
Got M_NUL command args: TIME Tue, 24 Mar 2026 15:34:07 +1100
Got M_NUL command args: TRNS clrghouz-dev.bbs.dege.au/10d84
Got M_NUL command args: VER clrghouz/dev binkp/1.1
Got M_OK command args: secure
Authentication successful: secure
```

Here is my side:
```
[2026-03-24 15:34:07] DEBUG: P--:- Starting [App\Mailer\Binkp] with [::ffff:115.70.0.125] {"pid":68996}
[2026-03-24 15:34:07] DEBUG: PB-:+ Starting BINKP handshake {"pid":68996} [2026-03-24 15:34:07] INFO: PB-:= Sending CRAM-MD5 request [098178627da2484ec1b44718f422a20b] {"pid":68996}
[2026-03-24 15:34:07] DEBUG: PB-:- Sending (App\Mailer\Binkp\NUL) to remote with size [54] {"pid":68996,"crypt":false,"msg":"OPT CRAM-MD5-098178627da2484ec1b44718f42..."}
[2026-03-24 15:34:07] INFO: PB-:- NUL:Message [OPT CRYPT] {"pid":68996} [2026-03-24 15:34:07] INFO: PB-:- Remote wants CRYPT mode {"pid":68996} [2026-03-24 15:34:07] DEBUG: PB-:- BINKP pre-auth processing {"pid":68996} [2026-03-24 15:34:07] DEBUG: PB-:/ NR Mode Available {"pid":68996}
[2026-03-24 15:34:07] INFO: PB-:- NUL:Message [SYS Alterant] {"pid":68996} [2026-03-24 15:34:07] INFO: PB-:- NUL:Message [ZYZ deon] {"pid":68996} [2026-03-24 15:34:07] INFO: PB-:- NUL:Message [LOC Parkdale, VIC] {"pid":68996} [2026-03-24 15:34:07] INFO: PB-:- NUL:Message [NDL 115200,TCP,BINKP] {"pid":68996}
[2026-03-24 15:34:07] INFO: PB-:- NUL:Message [TIME Tue Mar 24 2026 15:34:07 GMT+1100 (AEDT)] {"pid":68996}
[2026-03-24 15:34:07] INFO: PB-:- NUL:Message [VER BinkIT/2.41,JSBinkP/4,sbbs3.21a/Linux binkp/1.1] {"pid":68996}
[2026-03-24 15:34:07] INFO: PB-:- ADR:Message [516:1/1@videotex 885:2/2@bbsdev 64:500/34.1@cnet 12:1/2@dovenet 3:633/509@fidonet 21:2/116@fsxnet 999:700/2@health 954:700/22@hobbynet 25:25/23@metronet 618:510/2@micronet 86:600/10@nixnet 314:413/34.1@pinet 10:1/4@private 80:774/34.1@retronet 1337:2/101@tqwnet 911:613/0.1@zeronet] {"pid":68996}
[2026-03-24 15:34:07] INFO: BM1:- Got AKA [516:1/1.0@videotex] from [2] {"pid":68996}
[2026-03-24 15:34:07] INFO: BM1:- Got AKA [885:2/2.0@bbsdev] from [2] {"pid":68996}
[2026-03-24 15:34:07] INFO: BM1:- Got AKA [64:500/34.1@cnet] from [2] {"pid":68996}
[2026-03-24 15:34:07] INFO: BM1:- Got AKA [12:1/2.0@dovenet] from [2] {"pid":68996}
[2026-03-24 15:34:07] INFO: BM1:- Got AKA [3:633/509.0@fidonet] from [2] {"pid":68996}
[2026-03-24 15:34:07] INFO: BM1:- Got AKA [21:2/116.0@fsxnet] from [2] {"pid":68996}
[2026-03-24 15:34:07] INFO: BM1:- Got AKA [999:700/2.0@health] from [2] {"pid":68996}
[2026-03-24 15:34:07] INFO: BM1:- Got AKA [954:700/22.0@hobbynet] from [2] {"pid":68996}
[2026-03-24 15:34:07] INFO: BM1:- Got AKA [25:25/23.0@metronet] from [2] {"pid":68996}
[2026-03-24 15:34:07] INFO: BM1:- Got AKA [618:510/2.0@micronet] from [2] {"pid":68996}
[2026-03-24 15:34:07] INFO: BM1:- Got AKA [86:600/10.0@nixnet] from [2] {"pid":68996}
[2026-03-24 15:34:07] INFO: BM1:- Got AKA [314:413/34.1@pinet] from [2] {"pid":68996}
[2026-03-24 15:34:07] INFO: BM1:- Got AKA [10:1/4.0@private] from [2] {"pid":68996}
[2026-03-24 15:34:07] INFO: BM1:- Got AKA [80:774/34.1@retronet] from [2] {"pid":68996}
[2026-03-24 15:34:07] INFO: BM1:- Got AKA [1337:2/101.0@tqwnet] from [2] {"pid":68996}
[2026-03-24 15:34:07] INFO: BM1:- Got AKA [911:613/0.1@zeronet] from [2] {"pid":68996}
[2026-03-24 15:34:07] DEBUG: PB-:- Sending (App\Mailer\Binkp\ADR) to remote with size [353] {"pid":68996,"crypt":false,"msg":"911:613/0.0@zeronet 1337:2/100.0@tqwnet..."}
[2026-03-24 15:34:07] DEBUG: PB-:- Sending (App\Mailer\Binkp\NUL) to remote with size [20] {"pid":68996,"crypt":false,"msg":"SYS Clearing Houz"}
[2026-03-24 15:34:07] DEBUG: PB-:- Sending (App\Mailer\Binkp\NUL) to remote with size [18] {"pid":68996,"crypt":false,"msg":"ZYZ Deon George"}
[2026-03-24 15:34:07] DEBUG: PB-:- Sending (App\Mailer\Binkp\NUL) to remote with size [23] {"pid":68996,"crypt":false,"msg":"LOC Parkdale AUS AUS"}
[2026-03-24 15:34:07] DEBUG: PB-:- Sending (App\Mailer\Binkp\NUL) to remote with size [18] {"pid":68996,"crypt":false,"msg":"NDL IBN,IFC,ICM"}
[2026-03-24 15:34:07] DEBUG: PB-:- Sending (App\Mailer\Binkp\NUL) to remote with size [39] {"pid":68996,"crypt":false,"msg":"TIME Tue, 24 Mar 2026 15:34:07 +1100"}
[2026-03-24 15:34:07] DEBUG: PB-:- Sending (App\Mailer\Binkp\NUL) to remote with size [38] {"pid":68996,"crypt":false,"msg":"TRNS clrghouz-dev.bbs.dege.au/10d84"}
[2026-03-24 15:34:07] DEBUG: PB-:- Sending (App\Mailer\Binkp\NUL) to remote with size [29] {"pid":68996,"crypt":false,"msg":"VER clrghouz/dev binkp/1.1"}
[2026-03-24 15:34:07] INFO: PB-:- PWD:Message [CRAM-MD5-aa8509062cd8750d86e04c13ba1fa6ff] {"pid":68996}
[2026-03-24 15:34:07] DEBUG: BM2:= We authed [15] addresses from [Alterant] {"pid":68996}
[2026-03-24 15:34:07] DEBUG: PB-:- Sending (App\Mailer\Binkp\OK) to remote with size [9] {"pid":68996,"crypt":false,"msg":"secure"}
[2026-03-24 15:34:07] INFO: PB-:% Session in CRYPT mode with [Alterant] {"pid":68996}
2026-03-24 15:34:07] DEBUG: PB-:/ Sending options [ NR MB EXTCMD NZ BZ2 GZ ZSTD BROTLI CRC] {"pid":68996}
[2026-03-24 15:34:07] DEBUG: PB-:- Sending (App\Mailer\Binkp\NUL) to remote with size [45] {"pid":68996,"crypt":true,"msg":"OPT NR MB EXTCMD NZ BZ2 GZ ZSTD BROTLI C..."}
[2026-03-24 15:34:07] INFO: PB-:= We authed [516:1/1.0@videotex,885:2/2.0@bbsdev,64:500/34.1@cnet,12:1/2.0@dovenet,3:633/509.0@fidonet,21:2/116.0@fsxnet,999:700/2.0@health,954:700/22.0@hobbynet,618:510/2.0@micronet,86:600/10.0@nixnet,314:413/34.1@pinet,10:1/4.0@private,80:774/34.1@retronet,1337:2/101.0@tqwnet,911:613/0.1@zeronet] {"pid":68996}
[2026-03-24 15:34:07] INFO: PB-:+ Check for items to send to [Alterant] (516:1/1.0@videotex,885:2/2.0@bbsdev,64:500/34.1@cnet,12:1/2.0@dovenet,3:633/509.0@fidonet,21:2/116.0@fsxnet,999:700/2.0@health,954:700/22.0@hobbynet,618:510/2.0@micronet,86:600/10.0@nixnet,314:413/34.1@pinet,10:1/4.0@private,80:774/34.1@retronet,1337:2/101.0@tqwnet,911:613/0.1@zeronet) {"pid":68996}
[2026-03-24 15:34:09] DEBUG: PB-:- Sent EOB {"pid":68996,"recv_eob":false,"sent_eob":false,"next_batch":false}
[2026-03-24 15:34:09] DEBUG: PB-:- Sending (App\Mailer\Binkp\EOB) to remote with size [3] {"pid":68996,"crypt":true,"msg":""}
[2026-03-24 15:34:09] DEBUG: PB-:/ MB mode enabled, because we agree to MB mode, or I want MB and the remote is version [1.1] {"pid":68996}
[2026-03-24 15:34:09] DEBUG: PB-:- Received FILE [69c2140e.pkt 529 1774326798 0] {"pid":68996}
[2026-03-24 15:34:09] DEBUG: PB-:* Read [529] {"pid":68996,"rx_size":529} [2026-03-24 15:34:09] DEBUG: MBD:/ Inbound data [529] (UNCOMPRESSED) (UNENCRYPTED) {"pid":68996}
[2026-03-24 15:34:09] DEBUG: RI-:- Closing [69c2140e.pkt], received in [0], CRC [] {"pid":68996}
[2026-03-24 15:34:09] DEBUG: RI-:= Setting file [/app/storage/app/fido/03F7-1774326798-69c2140e.pkt] to time [1774326798] {"pid":68996}
[2026-03-24 15:34:09] INFO: RT-:- Processing TEST message from (deon) [516:1/1.0@videotex] in [VTX_TEST] {"pid":68996}
[2026-03-24 15:34:09] INFO: NNP:+ Creating TEST echomail in [VTX_TEST] {"pid":68996}
[2026-03-24 15:34:09] INFO: ME-:- Exporting message [938819] to [1015,1365] {"pid":68996}
[2026-03-24 15:34:09] DEBUG: PB-:/ Set NEXT_BATCH so we need a clear round of EOBS to end the session {"pid":68996}
[2026-03-24 15:34:09] DEBUG: PB-:- Sending (App\Mailer\Binkp\GOTSKIP) to remote with size [30] {"pid":68996,"crypt":true,"msg":"69c2140e.pkt 529 1774326798"}
[2026-03-24 15:34:09] DEBUG: PB-:- Received EOB {"pid":68996,"recv_eob":false,"sent_eob":true,"next_batch":true}
[2026-03-24 15:34:09] DEBUG: PB-:- Resetting SEND_EOB/RECV_EOB as we are dealing with a Binkp 1.1 remote {"pid":68996}
[2026-03-24 15:34:09] INFO: PB-:+ Check for items to send to [Alterant] (...) {"pid":68996}
[2026-03-24 15:34:09] INFO: MS-:= Got [1] echomails for [Alterant] for sending {"pid":68996}
[2026-03-24 15:34:09] DEBUG: IS-:+ Adding new file [0] to queue [000e5343] with size [0] {"pid":68996}
[2026-03-24 15:34:09] DEBUG: PB-:- Sending FILE [000e5343.pkt] {"pid":68996} [2026-03-24 15:34:09] DEBUG: IS-:- Content Read [1937] bytes, pos now [1937] {"pid":68996}
[2026-03-24 15:34:09] DEBUG: MBD:/ Outbound data [1937] (UNCOMPRESSED) (UNENCRYPTED) {"pid":68996}
[2026-03-24 15:34:09] DEBUG: PB-:- Sending (App\Mailer\Binkp\FILE) to remote with size [34] {"pid":68996,"crypt":true,"msg":"000e5343.pkt 1937 1774326849 0 "}
[2026-03-24 15:34:09] DEBUG: PB-:- Sending (App\Mailer\Binkp\DATA) to remote with size [1939] {"pid":68996,"crypt":true,"msg":"\u0000\u0000\u0001\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0002\u0000\u0002\u0000\u0001\u0000\u0001\u0000?\u0000L1NUCU5\u0000\u0004\u0002\u0004\u0002vi..."}
[2026-03-24 15:34:09] INFO: PB-:+ File sent, waiting for GOT for [000e5343.pkt] {"pid":68996}
[2026-03-24 15:34:09] INFO: PB-:- File Sent GOTSKIP [000e5343.pkt 1937 1774326849] {"pid":68996}
[2026-03-24 15:34:09] DEBUG: FSM:- Close [000e5343.pkt] - SUCCESSFUL {"pid":68996}
[2026-03-24 15:34:09] DEBUG: PB-:/ Set NEXT_BATCH so we need a clear round of EOBS to end the session {"pid":68996}
[2026-03-24 15:34:09] INFO: PB-:+ Check for items to send to [Alterant] (...) {"pid":68996}
[2026-03-24 15:34:10] DEBUG: PB-:- Sent EOB {"pid":68996,"recv_eob":false,"sent_eob":false,"next_batch":true}
[2026-03-24 15:34:10] DEBUG: PB-:- Sending (App\Mailer\Binkp\EOB) to remote with size [3] {"pid":68996,"crypt":true,"msg":""}
[2026-03-24 15:34:10] NOTICE: P--:! Remote closed the session? [Unable to read from socket] {"pid":68996}
[2026-03-24 15:34:10] DEBUG: P--:- Ending new [App\Mailer\Binkp] [] {"pid":68996}
[2026-03-24 15:34:10] INFO: P--:= Total: [2:Alterant] - 0:00:02 online, (1) 1937b sent, (1) 529b received - Failed (::ffff:115.70.0.125) {"pid":68996}
```

You can see it directly, just make a poll to clrhgouz.bbs.dege.au - we have session details defined for `bbsdev`.

Port 24564 is my `dev` environment where I've turned up the debugging. The main mailer is on 24554.

If you give me the number in the `TRNS` line, I can give you the log for that session (on the dev server).
--- SBBSecho 3.37-Linux
* Origin: Vertrauen - [vert/cvs/bbs].synchro.net (1:103/705)