RI does not work correctly

mrdudz commented 1 year ago

Whatever you did there when merging the RI stuff - it does not work correctly :)

When S0 is 1, then it connects immediately on first ring, but RI never becomes 1. When S0 is 2, it does not even connect anymore, it keeps ringing and RI still never becomes 1.

./tcpser -p 6400 -S 300 -v 25232 -l 7 -tmM -i"s5=20 s0=1 s39=1"

...
2023-07-02 14:20:32:140737351743168:ENTER_EXIT:Exitting ip_accept function
2023-07-02 14:20:32:140737351743168:DEBUG_X:Connection accepted
2023-07-02 14:20:32:140737351743168:DEBUG:Sending 'RING' to modem
2023-07-02 14:20:32:140737351743168:DEBUG:Sending RING response to modem
2023-07-02 14:20:32:140737351743168:TRACE:RS->|0000|0d 0a                                          |..              |
2023-07-02 14:20:32:140737351743168:DEBUG_X:Sending text response
2023-07-02 14:20:32:140737351743168:TRACE:RS->|0000|52 49 4e 47                                    |RING            |
2023-07-02 14:20:32:140737351743168:TRACE:RS->|0000|0d 0a                                          |..              |
2023-07-02 14:20:32:140737351743168:DEBUG_X:Sent #1 ring
2023-07-02 14:20:32:140737351743168:INFO:taking modem off hook
2023-07-02 14:20:32:140737351743168:INFO:Control Lines: DSR:1 DCD:1 CTS:1 RI:0
2023-07-02 14:20:32:140737351743168:ENTER_EXIT:Entering dce_set_control_lines function
2023-07-02 14:20:32:140737351743168:DEBUG_X:Setting DCD pin high
2023-07-02 14:20:32:140737351743168:DEBUG_X:Setting RI pin low
2023-07-02 14:20:32:140737351743168:DEBUG:ip232 control line state dcd:1 ri:0
2023-07-02 14:20:32:140737351743168:DEBUG:reconfiguring virtual DCD/RI
2023-07-02 14:20:32:140737351743168:ENTER_EXIT:Exitting dce_set_control_lines function
2023-07-02 14:20:32:140737351743168:DEBUG:Sending CONNECT response to modem
2023-07-02 14:20:32:140737351743168:TRACE:RS->|0000|0d 0a                                          |..              |
2023-07-02 14:20:32:140737351743168:DEBUG_X:Sending text response
2023-07-02 14:20:32:140737351743168:TRACE:RS->|0000|43 4f 4e 4e 45 43 54                           |CONNECT         |
2023-07-02 14:20:32:140737351743168:TRACE:RS->|0000|0d 0a                                          |..              |
2023-07-02 14:20:32:140737351743168:DEBUG:Informing parent task that I am busy
2023-07-02 14:20:32:140737351743168:ENTER_EXIT:Exitting accept_connection function
2023-07-02 15:18:52:140186997364416:DEBUG_X:Connection status change, handling
2023-07-02 15:18:52:140186997368640:DEBUG:modem core #0 sent response 'B'
2023-07-02 15:18:52:140186997368640:DEBUG_X:Waiting for incoming connections and/or indicators
2023-07-02 15:18:52:140186972186304:DEBUG:IP thread notified
2023-07-02 15:18:52:140186997364416:DEBUG_X:Waiting for modem/control line/timer/socket activity
2023-07-02 15:18:52:140186997364416:DEBUG_X:CMD:0, DCE:0, LINE:1, TYPE:2, HOOK:1
2023-07-02 15:18:52:140186997364416:DEBUG_X:Setting timer for break delay
2023-07-02 15:18:53:140186997364416:DEBUG:Initial Break Delay detected
2023-07-02 15:18:53:140186997364416:INFO:Control Lines: DSR:1 DCD:1 CTS:1 RI:0
2023-07-02 15:18:53:140186997364416:ENTER_EXIT:Entering dce_set_control_lines function
2023-07-02 15:18:53:140186997364416:DEBUG_X:Setting DCD pin high
2023-07-02 15:18:53:140186997364416:DEBUG_X:Setting RI pin low
2023-07-02 15:18:53:140186997364416:DEBUG:ip232 control line state dcd:1 ri:0
2023-07-02 15:18:53:140186997364416:ENTER_EXIT:Exitting dce_set_control_lines function

you can use this program: https://sourceforge.net/p/vice-emu/code/HEAD/tree/testprogs/RS232/ for testing in VICE

mrdudz commented 1 year ago

Now on a second attempt with S0=2 ... RI becomes 1, and stays 1 all the time, and tcpser still does not connect.

mrdudz commented 1 year ago

https://github.com/go4retro/tcpser/blob/14ab39c7ebbfd4fee7e329f7c398ff0e89fcc405/src/bridge.c#L368

That block doesn't initiate the first ring as it should - it is executed AFTER the first ring was already sent, which in case of S0=1 means AFTER it connected. This is obviously wrong :)

go4retro commented 1 year ago

Thanks for the test. I see one bug, fixing now.

Jim

go4retro commented 1 year ago

Though I wrote the code, I forgot part of how it worked. Stupid mistake, fixed. See if the code behaves now. Testing appears to be good from this end.

mrdudz commented 1 year ago

Its still broken the same way, doesn't work with S0=1

2023-07-02 23:44:55:139849751271104:ENTER_EXIT:Entering dce_set_control_lines function
2023-07-02 23:44:55:139849751271104:DEBUG_X:Setting DCD pin low
2023-07-02 23:44:55:139849751271104:DEBUG_X:Setting RI pin low
2023-07-02 23:44:55:139849751271104:DEBUG:ip232 control line state dcd:0 ri:0
2023-07-02 23:44:55:139849751271104:ENTER_EXIT:Exitting dce_set_control_lines function
2023-07-02 23:44:55:139849751271104:DEBUG:Sending 'RING' to modem
2023-07-02 23:44:55:139849751271104:DEBUG:Sending RING response to modem
2023-07-02 23:44:55:139849751271104:TRACE:RS->|0000|0d 0a                                          |..              |
2023-07-02 23:44:55:139849751271104:DEBUG_X:Sending text response
2023-07-02 23:44:55:139849751271104:TRACE:RS->|0000|52 49 4e 47                                    |RING            |
2023-07-02 23:44:55:139849751271104:TRACE:RS->|0000|0d 0a                                          |..              |
2023-07-02 23:44:55:139849751271104:DEBUG_X:Sent #1 ring
2023-07-02 23:44:55:139849751271104:INFO:taking modem off hook
2023-07-02 23:44:55:139849751271104:INFO:Control Lines: DSR:1 DCD:1 CTS:1 RI:0
2023-07-02 23:44:55:139849751271104:ENTER_EXIT:Entering dce_set_control_lines function
2023-07-02 23:44:55:139849751271104:DEBUG_X:Setting DCD pin high
2023-07-02 23:44:55:139849751271104:DEBUG_X:Setting RI pin low
2023-07-02 23:44:55:139849751271104:DEBUG:ip232 control line state dcd:1 ri:0
2023-07-02 23:44:55:139849751271104:DEBUG:reconfiguring virtual DCD/RI
2023-07-02 23:44:55:139849751271104:ENTER_EXIT:Exitting dce_set_control_lines function
2023-07-02 23:44:55:139849751271104:DEBUG:Sending CONNECT response to modem
2023-07-02 23:44:55:139849751271104:TRACE:RS->|0000|0d 0a                                          |..              |
2023-07-02 23:44:55:139849751271104:DEBUG_X:Sending text response
2023-07-02 23:44:55:139849751271104:TRACE:RS->|0000|43 4f 4e 4e 45 43 54                           |CONNECT         |
2023-07-02 23:44:55:139849751271104:TRACE:RS->|0000|0d 0a                                          |..              |
2023-07-02 23:44:55:139849751271104:DEBUG:Informing parent task that I am busy
2023-07-02 23:44:55:139849751271104:ENTER_EXIT:Exitting accept_connection function

with S0=2 it doesnt ring forever anymore, but also no activity on the RI line:

2023-07-02 23:47:03:140520440665792:DEBUG:ip232 control line state dcd:0 ri:0
2023-07-02 23:47:03:140520440665792:ENTER_EXIT:Exitting dce_set_control_lines function
2023-07-02 23:47:03:140520440665792:DEBUG:Sending 'RING' to modem
2023-07-02 23:47:03:140520440665792:DEBUG:Sending RING response to modem
2023-07-02 23:47:03:140520440665792:TRACE:RS->|0000|0d 0a                                          |..              |
2023-07-02 23:47:03:140520440665792:DEBUG_X:Sending text response
2023-07-02 23:47:03:140520440665792:TRACE:RS->|0000|52 49 4e 47                                    |RING            |
2023-07-02 23:47:03:140520440665792:TRACE:RS->|0000|0d 0a                                          |..              |
2023-07-02 23:47:03:140520440665792:DEBUG_X:Sent #1 ring
2023-07-02 23:47:03:140520440665792:DEBUG:Informing parent task that I am busy
2023-07-02 23:47:03:140520440665792:ENTER_EXIT:Exitting accept_connection function
2023-07-02 23:47:03:140520440665792:DEBUG_X:Waiting for modem/control line/timer/socket activity
2023-07-02 23:47:03:140520440665792:DEBUG_X:CMD:1, DCE:0, LINE:1, TYPE:0, HOOK:0
2023-07-02 23:47:03:140520440665792:DEBUG_X:Setting timer for rings
2023-07-02 23:47:03:140520440670016:DEBUG:modem core #0 sent response 'B'
2023-07-02 23:47:03:140520440670016:DEBUG_X:Waiting for incoming connections and/or indicators
2023-07-02 23:47:04:140520440665792:INFO:Control Lines: DSR:1 DCD:0 CTS:1 RI:0
2023-07-02 23:47:04:140520440665792:ENTER_EXIT:Entering dce_set_control_lines function
2023-07-02 23:47:04:140520440665792:DEBUG_X:Setting DCD pin low
2023-07-02 23:47:04:140520440665792:DEBUG_X:Setting RI pin low
2023-07-02 23:47:04:140520440665792:DEBUG:ip232 control line state dcd:0 ri:0
2023-07-02 23:47:04:140520440665792:ENTER_EXIT:Exitting dce_set_control_lines function
2023-07-02 23:47:04:140520440665792:DEBUG_X:Waiting for modem/control line/timer/socket activity
2023-07-02 23:47:04:140520440665792:DEBUG_X:CMD:1, DCE:0, LINE:1, TYPE:0, HOOK:0
2023-07-02 23:47:04:140520440665792:DEBUG_X:Setting timer for rings
2023-07-02 23:47:07:140520440665792:DEBUG:Sending 'RING' to modem
2023-07-02 23:47:07:140520440665792:DEBUG:Sending RING response to modem
2023-07-02 23:47:07:140520440665792:TRACE:RS->|0000|0d 0a                                          |..              |
2023-07-02 23:47:07:140520440665792:DEBUG_X:Sending text response
2023-07-02 23:47:07:140520440665792:TRACE:RS->|0000|52 49 4e 47                                    |RING            |
2023-07-02 23:47:07:140520440665792:TRACE:RS->|0000|0d 0a                                          |..              |
2023-07-02 23:47:07:140520440665792:DEBUG_X:Sent #2 ring
2023-07-02 23:47:07:140520440665792:INFO:taking modem off hook
2023-07-02 23:47:07:140520440665792:INFO:Control Lines: DSR:1 DCD:1 CTS:1 RI:0
2023-07-02 23:47:07:140520440665792:ENTER_EXIT:Entering dce_set_control_lines function
2023-07-02 23:47:07:140520440665792:DEBUG_X:Setting DCD pin high
2023-07-02 23:47:07:140520440665792:DEBUG_X:Setting RI pin low
2023-07-02 23:47:07:140520440665792:DEBUG:ip232 control line state dcd:1 ri:0
2023-07-02 23:47:07:140520440665792:DEBUG:reconfiguring virtual DCD/RI
2023-07-02 23:47:07:140520440665792:ENTER_EXIT:Exitting dce_set_control_lines function
2023-07-02 23:47:07:140520440665792:DEBUG:Sending CONNECT response to modem
2023-07-02 23:47:07:140520440665792:TRACE:RS->|0000|0d 0a                                          |..              |
2023-07-02 23:47:07:140520440665792:DEBUG_X:Sending text response
2023-07-02 23:47:07:140520440665792:TRACE:RS->|0000|43 4f 4e 4e 45 43 54                           |CONNECT         |
2023-07-02 23:47:07:140520440665792:TRACE:RS->|0000|0d 0a                                          |..              |
2023-07-02 23:47:07:140520440665792:INFO:Control Lines: DSR:1 DCD:1 CTS:1 RI:0
2023-07-02 23:47:07:140520440665792:ENTER_EXIT:Entering dce_set_control_lines function
2023-07-02 23:47:07:140520440665792:DEBUG_X:Setting DCD pin high
2023-07-02 23:47:07:140520440665792:DEBUG_X:Setting RI pin low
2023-07-02 23:47:07:140520440665792:DEBUG:ip232 control line state dcd:1 ri:0
2023-07-02 23:47:07:140520440665792:ENTER_EXIT:Exitting dce_set_control_lines function
2023-07-02 23:47:07:140520440665792:DEBUG_X:Connection status change, handling
2023-07-02 23:47:07:140520440665792:DEBUG_X:Waiting for modem/control line/timer/socket activity
2023-07-02 23:47:07:140520440665792:DEBUG_X:CMD:0, DCE:0, LINE:1, TYPE:2, HOOK:1

go4retro commented 1 year ago

The issue was that is_ringing is set in mdm_send_ring(), and set_control_lines() needs it to set RI corectly, but when you call send_ring() first, it answers immediately on S0=1, so is_ringing=1 is never seen by set_control_lines. I know I said I'd prefer set_control_lines not be in send_ring, but I see no other way to easily fix. setting is_ringing outside of modem_core breaks where all that gets set/reset, moving the connect out of send_ring breaks other things, so it appears it has to be this way. Try it now.

mrdudz commented 1 year ago

now it seems to work as it should - cheers

go4retro commented 1 year ago

Sorry it took so long, it's been a bit since I worked in the code.

go4retro / tcpser

RI does not work correctly #27