connection issues / quits without reason with ip232+VICE

mrdudz commented 1 year ago

I have seen various strange issues in my tests... i will add more logs when i stumble about them again.

i always start tcpser like this:

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

Then i start VICE like this:

x64sc -default -rsdev3ip232 -rsdev3baud "300" -rsuserbaud "300" -rsuserdev "2" -userportdevice "2"

now tcpser produces a log like this

2023-06-25 21:19:34:139691083523904:INFO:Server socket bound to port
2023-06-25 21:19:34:139691083523904:INFO:Server socket listening for connections
2023-06-25 21:19:34:139691083523904:INFO:Creating modem #0
2023-06-25 21:19:34:139691083519680:INFO:Opening ip232 device
2023-06-25 21:19:34:139691083519680:INFO:Server socket bound to port
2023-06-25 21:19:34:139691083519680:INFO:Server socket listening for connections
2023-06-25 21:19:34:139691083519680:INFO:ip232 device configured
2023-06-25 21:19:34:139691083519680:INFO:Control Lines: DSR:1 DCD:0 CTS:1 RI:0
2023-06-25 21:19:38:139691075126976:INFO:Connection accepted from 127.0.0.1
2023-06-25 21:19:38:139690992727744:INFO:Link has come up
2023-06-25 21:19:38:139691083519680:TRACE:RS<-|0000|ff                                             |.               |
2023-06-25 21:19:38:139691083519680:TRACE:RS<-|0000|01                                             |.               |
2023-06-25 21:19:38:139691083519680:TRACE:RS<-|0000|ff                                             |.               |
2023-06-25 21:19:38:139691083519680:TRACE:RS<-|0000|00                                             |.               |
2023-06-25 21:19:38:139691083519680:INFO:No ip232 socket data read, assume closed peer
2023-06-25 21:19:38:139691075126976:INFO:Connection accepted from 127.0.0.1

the funky part is, when i connect to tcpser using

telnet 127.0.0.1 6400

it will show

2023-06-25 21:20:52:139691083519680:INFO:Control Lines: DSR:1 DCD:0 CTS:1 RI:1
2023-06-25 21:20:52:139691083519680:TRACE:RS->|0000|0d 0a                                          |..              |

and then tcpser terminates, with no error message whatsoever .... how can this happen? As i understand it, there is no way tcpser can - or even should - do this. But it does :)

go4retro commented 1 year ago

Can you turn on logging? -l7

THat might help.

mrdudz commented 1 year ago

OK, here is a full log

started tcpser
started vice
in vice load+started the bbs program i am toying with. the bbs incorrectly sees DCD active, so i pressed reset and started it again (i think this causes VICE to reconnect to tcpser). now the bbs sees DCD inactive as it should be.
telnet to local port 6400, telnet quits with "connection closed by foreign host"
tcpser has terminated itself

again, i don't see how this can happen at all...

$ ./tcpser -p 6400 -S 300 -v 25232 -l 7 -tmM -i"s5=20 s0=1 s39=1"
2023-07-02 13:50:06:139734767576896:DEBUG:Read configuration for 1 serial port(s)
2023-07-02 13:50:06:139734767576896:ENTER_EXIT:Exitting init function
2023-07-02 13:50:06:139734767576896:ENTER_EXIT:Entering ip_init_server_conn function
2023-07-02 13:50:06:139734767576896:DEBUG:Creating server socket
2023-07-02 13:50:06:139734767576896:DEBUG:Binding server socket to port 6400
2023-07-02 13:50:06:139734767576896:INFO:Server socket bound to port
2023-07-02 13:50:06:139734767576896:INFO:Server socket listening for connections
2023-07-02 13:50:06:139734767576896:ENTER_EXIT:Exitting ip_init_server_conn function
2023-07-02 13:50:06:139734767576896:INFO:Creating modem #0
2023-07-02 13:50:06:139734767576896:DEBUG_X:BRIDGE thread ID = 139734767572672
2023-07-02 13:50:06:139734767576896:DEBUG_X:Waiting for incoming connections and/or indicators
2023-07-02 13:50:06:139734767572672:ENTER_EXIT:Entering bridge_task function
2023-07-02 13:50:06:139734767572672:ENTER_EXIT:Entering dce_connect function
2023-07-02 13:50:06:139734767572672:ENTER_EXIT:Entering ip232_init_conn function
2023-07-02 13:50:06:139734767572672:INFO:Opening ip232 device
2023-07-02 13:50:06:139734767572672:ENTER_EXIT:Entering ip_init_server_conn function
2023-07-02 13:50:06:139734767572672:DEBUG:Creating server socket
2023-07-02 13:50:06:139734767572672:DEBUG:Binding server socket to port 25232
2023-07-02 13:50:06:139734767572672:INFO:Server socket bound to port
2023-07-02 13:50:06:139734767572672:INFO:Server socket listening for connections
2023-07-02 13:50:06:139734767572672:ENTER_EXIT:Exitting ip_init_server_conn function
2023-07-02 13:50:06:139734767572672:DEBUG_X:IP232 thread ID = 139734759179968
2023-07-02 13:50:06:139734767572672:INFO:ip232 device configured
2023-07-02 13:50:06:139734767572672:ENTER_EXIT:Exitting ip232_init_conn function
2023-07-02 13:50:06:139734767572672:ENTER_EXIT:Exitting dce_connect function
2023-07-02 13:50:06:139734759179968:ENTER_EXIT:Entering ip232_thread function
2023-07-02 13:50:06:139734759179968:DEBUG_X:Waiting for incoming ip232 connections
2023-07-02 13:50:06:139734680598208:ENTER_EXIT:Entering ctrl_thread function
2023-07-02 13:50:06:139734680598208:ENTER_EXIT:Entering dce_check_control_lines function
2023-07-02 13:50:06:139734767572672:DEBUG_X:CTRL thread ID = 139734680598208
2023-07-02 13:50:06:139734767572672:DEBUG_X:IP thread ID = 139734672205504
2023-07-02 13:50:06:139734767572672:INFO:Control Lines: DSR:1 DCD:0 CTS:1 RI:0
2023-07-02 13:50:06:139734767572672:ENTER_EXIT:Entering dce_set_control_lines function
2023-07-02 13:50:06:139734767572672:DEBUG_X:Setting DCD pin low
2023-07-02 13:50:06:139734767572672:DEBUG_X:Setting RI pin low
2023-07-02 13:50:06:139734767572672:DEBUG:ip232 control line state dcd:0 ri:0
2023-07-02 13:50:06:139734767572672:ENTER_EXIT:Exitting dce_set_control_lines function
2023-07-02 13:50:06:139734767572672:ENTER_EXIT:Entering mdm_parse_cmd function
2023-07-02 13:50:06:139734767572672:DEBUG:Evaluating ATs5=20 s0=1 s39=1
2023-07-02 13:50:06:139734672205504:ENTER_EXIT:Entering ip_thread function
2023-07-02 13:50:06:139734767572672:DEBUG:Command: S (83), Flags: 0, index=5, num=5, data=3-5
2023-07-02 13:50:06:139734767572672:DEBUG:Command: S (83), Flags: 0, index=10, num=0, data=9-10
2023-07-02 13:50:06:139734767572672:DEBUG:Command: S (83), Flags: 0, index=16, num=39, data=15-16
2023-07-02 13:50:06:139734767572672:DEBUG:Command:   (-1), Flags: -1, index=16, num=0, data=0-0
2023-07-02 13:50:06:139734767572672:DEBUG:Sending OK response to modem
2023-07-02 13:50:06:139734767572672:DEBUG_X:Sending text response
2023-07-02 13:50:06:139734767572672:DEBUG_X:Waiting for modem/control line/timer/socket activity
2023-07-02 13:50:06:139734767572672:DEBUG_X:CMD:1, DCE:0, LINE:0, TYPE:0, HOOK:0
2023-07-02 13:50:37:139734759179968:DEBUG:Incoming ip232 connection
2023-07-02 13:50:37:139734759179968:ENTER_EXIT:Entering ip_accept function
2023-07-02 13:50:37:139734759179968:INFO:Connection accepted from 127.0.0.1
2023-07-02 13:50:37:139734759179968:ENTER_EXIT:Exitting ip_accept function
2023-07-02 13:50:37:139734759179968:DEBUG_X:Waiting for incoming ip232 connections
2023-07-02 13:50:37:139734680598208:ENTER_EXIT:Exitting dce_check_control_lines function
2023-07-02 13:50:37:139734680598208:DEBUG:Control Line Change
2023-07-02 13:50:37:139734680598208:INFO:Link has come up
2023-07-02 13:50:37:139734680598208:ENTER_EXIT:Entering dce_check_control_lines function
2023-07-02 13:50:37:139734767572672:DEBUG:Received L from control line watch task
2023-07-02 13:50:37:139734767572672:DEBUG_X:Waiting for modem/control line/timer/socket activity
2023-07-02 13:50:37:139734767572672:DEBUG_X:CMD:1, DCE:1, LINE:0, TYPE:0, HOOK:0
2023-07-02 13:50:37:139734767572672:DEBUG:Data available on serial port
2023-07-02 13:50:37:139734767572672:ENTER_EXIT:Entering ip232_read function
2023-07-02 13:50:37:139734767572672:DEBUG:Read 1 bytes from ip232 socket
2023-07-02 13:50:37:139734767572672:TRACE:RS<-|0000|ff                                             |.               |
2023-07-02 13:50:37:139734767572672:ENTER_EXIT:Exitting ip232_read function
2023-07-02 13:50:37:139734767572672:DEBUG_X:Waiting for modem/control line/timer/socket activity
2023-07-02 13:50:37:139734767572672:DEBUG_X:CMD:1, DCE:1, LINE:0, TYPE:0, HOOK:0
2023-07-02 13:50:37:139734767572672:DEBUG:Data available on serial port
2023-07-02 13:50:37:139734767572672:ENTER_EXIT:Entering ip232_read function
2023-07-02 13:50:37:139734767572672:DEBUG:Read 1 bytes from ip232 socket
2023-07-02 13:50:37:139734767572672:TRACE:RS<-|0000|01                                             |.               |
2023-07-02 13:50:37:139734767572672:DEBUG:Virtual DTR line up
2023-07-02 13:50:37:139734767572672:ENTER_EXIT:Exitting ip232_read function
2023-07-02 13:50:37:139734767572672:DEBUG_X:Waiting for modem/control line/timer/socket activity
2023-07-02 13:50:37:139734767572672:DEBUG_X:CMD:1, DCE:1, LINE:0, TYPE:0, HOOK:0
2023-07-02 13:50:37:139734767572672:DEBUG:Data available on serial port
2023-07-02 13:50:37:139734767572672:ENTER_EXIT:Entering ip232_read function
2023-07-02 13:50:37:139734767572672:DEBUG:Read 1 bytes from ip232 socket
2023-07-02 13:50:37:139734767572672:TRACE:RS<-|0000|ff                                             |.               |
2023-07-02 13:50:37:139734767572672:ENTER_EXIT:Exitting ip232_read function
2023-07-02 13:50:37:139734767572672:DEBUG_X:Waiting for modem/control line/timer/socket activity
2023-07-02 13:50:37:139734767572672:DEBUG_X:CMD:1, DCE:1, LINE:0, TYPE:0, HOOK:0
2023-07-02 13:50:37:139734767572672:DEBUG:Data available on serial port
2023-07-02 13:50:37:139734767572672:ENTER_EXIT:Entering ip232_read function
2023-07-02 13:50:37:139734767572672:DEBUG:Read 1 bytes from ip232 socket
2023-07-02 13:50:37:139734767572672:TRACE:RS<-|0000|00                                             |.               |
2023-07-02 13:50:37:139734767572672:DEBUG:Virtual DTR line down
2023-07-02 13:50:37:139734767572672:ENTER_EXIT:Exitting ip232_read function
2023-07-02 13:50:37:139734767572672:DEBUG_X:Waiting for modem/control line/timer/socket activity
2023-07-02 13:50:37:139734767572672:DEBUG_X:CMD:1, DCE:1, LINE:0, TYPE:0, HOOK:0
2023-07-02 13:50:37:139734767572672:DEBUG:Data available on serial port
2023-07-02 13:50:37:139734767572672:ENTER_EXIT:Entering ip232_read function
2023-07-02 13:50:37:139734767572672:INFO:No ip232 socket data read, assume closed peer
2023-07-02 13:50:37:139734767572672:ENTER_EXIT:Exitting ip232_read function
2023-07-02 13:50:37:139734767572672:DEBUG_X:Waiting for modem/control line/timer/socket activity
2023-07-02 13:50:37:139734767572672:DEBUG_X:CMD:1, DCE:0, LINE:0, TYPE:0, HOOK:0
2023-07-02 13:50:37:139734759179968:DEBUG:Incoming ip232 connection
2023-07-02 13:50:37:139734759179968:ENTER_EXIT:Entering ip_accept function
2023-07-02 13:50:37:139734759179968:INFO:Connection accepted from 127.0.0.1
2023-07-02 13:50:37:139734759179968:ENTER_EXIT:Exitting ip_accept function
2023-07-02 13:50:37:139734759179968:DEBUG_X:Waiting for incoming ip232 connections
2023-07-02 13:54:35:139734759179968:DEBUG:Incoming ip232 connection
2023-07-02 13:54:35:139734759179968:ENTER_EXIT:Entering ip_accept function
2023-07-02 13:54:35:139734759179968:INFO:Connection accepted from 127.0.0.1
2023-07-02 13:54:35:139734759179968:ENTER_EXIT:Exitting ip_accept function
2023-07-02 13:54:35:139734759179968:DEBUG:Already have ip232 connection, rejecting new
2023-07-02 13:54:35:139734759179968:DEBUG_X:Waiting for incoming ip232 connections
2023-07-02 13:55:32:139734767576896:DEBUG:Incoming connection pending
2023-07-02 13:55:32:139734767576896:DEBUG:Sending incoming connection to listening modem #0
2023-07-02 13:55:32:139734767576896:DEBUG:Sending incoming connection to non-connected modem #0
2023-07-02 13:55:32:139734767576896:DEBUG_X:Waiting for incoming connections and/or indicators
2023-07-02 13:55:32:139734767572672:DEBUG:Data available on incoming IPC pipe
2023-07-02 13:55:32:139734767572672:ENTER_EXIT:Entering accept_connection function
2023-07-02 13:55:32:139734767572672:ENTER_EXIT:Entering ip_accept function
2023-07-02 13:55:32:139734767572672:INFO:Connection accepted from 127.0.0.1
2023-07-02 13:55:32:139734767572672:ENTER_EXIT:Exitting ip_accept function
2023-07-02 13:55:32:139734767572672:DEBUG_X:Connection accepted
2023-07-02 13:55:32:139734767572672:DEBUG:Sending 'RING' to modem
2023-07-02 13:55:32:139734767572672:DEBUG:Sending RING response to modem
2023-07-02 13:55:32:139734767572672:TRACE:RS->|0000|0d 0a                                          |..              |
2023-07-02 13:55:32:139734767572672:DEBUG_X:Sending text response
2023-07-02 13:55:32:139734767572672:TRACE:RS->|0000|52 49 4e 47                                    |RING            |

go4retro commented 1 year ago

There must be a place where I am not catching a condition. I'll see if I can find what si supposed to be the next piece of text after the send of the RING.

Try the newest code, though, perhaps I fixed it while fixing other issues.,

mrdudz commented 1 year ago

Whats so baffling is... there is no way the program can exit like this. every exit() call (as far as i can see) is preceded by some message, which we do not see in the log.

mrdudz commented 1 year ago

Try the newest code, though, perhaps I fixed it while fixing other issues.

It still happens :( Not all the time though. And apparently Windows and Linux behave differently.

go4retro / tcpser

connection issues / quits without reason with ip232+VICE #25