search

go4retro / tcpser

Hayes modem emulator application
106 stars 30 forks source link

Connects, instantly disconnects. #8

Closed geneb closed 4 years ago

geneb commented 4 years ago

Trying to chase down a weird issue. tcpser is set to answer the phone with ats0=1. I telnet in and it connects and instantly disconnects. Here's the output of the session: 2019-12-27 15:05:35:-1224757680:DEBUG:Incoming connection pending 2019-12-27 15:05:35:-1224757680:DEBUG:Sending incoming connection to listening modem #0 2019-12-27 15:05:35:-1224757680:DEBUG:Sending incoming connection to non-connected modem #0 2019-12-27 15:05:35:-1224757680:DEBUG_X:Waiting for incoming connections and/or indicators 2019-12-27 15:05:35:-1226660768:DEBUG:Data available on incoming IPC pipe 2019-12-27 15:05:35:-1226660768:ENTER_EXIT:Entering accept_connection function 2019-12-27 15:05:35:-1226660768:ENTER_EXIT:Entering ip_accept function 2019-12-27 15:05:35:-1226660768:INFO:Connection accepted from 75.145.20.100 2019-12-27 15:05:35:-1226660768:ENTER_EXIT:Exitting ip_accept function 2019-12-27 15:05:35:-1226660768:DEBUG_X:Connection accepted 2019-12-27 15:05:35:-1226660768:DEBUG:Sending 'RING' to modem 2019-12-27 15:05:35:-1226660768:DEBUG:Sending RING response to modem 2019-12-27 15:05:35:-1226660768:DEBUG_X:Sending text response 2019-12-27 15:05:35:-1226660768:DEBUG_X:Sent #1 ring 2019-12-27 15:05:35:-1226660768:INFO:taking modem off hook 2019-12-27 15:05:35:-1226660768:INFO:Control Lines: DSR:1 DCD:1 CTS:1 2019-12-27 15:05:35:-1226660768:ENTER_EXIT:Entering dce_set_control_lines function 2019-12-27 15:05:35:-1226660768:DEBUG_X:Setting CTS pin high 2019-12-27 15:05:35:-1226660768:DEBUG_X:Setting DCD pin high 2019-12-27 15:05:35:-1226660768:ENTER_EXIT:Exitting dce_set_control_lines function 2019-12-27 15:05:35:-1226660768:DEBUG:Sending CONNECT 2400 response to modem 2019-12-27 15:05:35:-1226660768:DEBUG_X:Sending text response 2019-12-27 15:05:35:-1226660768:DEBUG:Informing parent task that I am busy 2019-12-27 15:05:35:-1224757680:DEBUG:modem core #0 sent response 'B' 2019-12-27 15:05:35:-1224757680:DEBUG_X:Waiting for incoming connections and/or indicators 2019-12-27 15:05:35:-1226660768:ENTER_EXIT:Exitting accept_connection function 2019-12-27 15:05:35:-1226660768:DEBUG_X:Connection status change, handling 2019-12-27 15:05:35:-1244666784:DEBUG:IP thread notified 2019-12-27 15:05:35:-1244666784:DEBUG:IP thread notified 2019-12-27 15:05:35:-1226660768:DEBUG_X:Waiting for modem/control line/timer/socket activity 2019-12-27 15:05:35:-1226660768:DEBUG_X:CMD:0, DCE:1, LINE:1, TYPE:2, HOOK:1 2019-12-27 15:05:35:-1226660768:DEBUG_X:Setting timer for break delay 2019-12-27 15:05:35:-1236274080:ENTER_EXIT:Exitting dce_check_control_lines function 2019-12-27 15:05:35:-1236274080:DEBUG:Control Line Change 2019-12-27 15:05:35:-1236274080:ENTER_EXIT:Entering dce_check_control_lines function 2019-12-27 15:05:35:-1226660768:DEBUG:Received D from control line watch task 2019-12-27 15:05:35:-1226660768:ENTER_EXIT:Entering mdm_disconnect function 2019-12-27 15:05:35:-1226660768:INFO:Disconnecting modem 2019-12-27 15:05:35:-1226660768:INFO:Disconnecting line 2019-12-27 15:05:35:-1226660768:INFO:Control Lines: DSR:1 DCD:0 CTS:1 2019-12-27 15:05:35:-1226660768:ENTER_EXIT:Entering dce_set_control_lines function 2019-12-27 15:05:35:-1226660768:DEBUG_X:Setting CTS pin high 2019-12-27 15:05:35:-1226660768:DEBUG_X:Setting DCD pin low 2019-12-27 15:05:35:-1226660768:ENTER_EXIT:Exitting dce_set_control_lines function 2019-12-27 15:05:35:-1226660768:DEBUG:Sending NO CARRIER response to modem 2019-12-27 15:05:35:-1226660768:DEBUG_X:Sending text response 2019-12-27 15:05:35:-1226660768:ENTER_EXIT:Exitting mdm_disconnect function 2019-12-27 15:05:35:-1226660768:DEBUG_X:Connection status change, handling 2019-12-27 15:05:35:-1244666784:DEBUG:IP thread notified 2019-12-27 15:05:35:-1244666784:DEBUG:IP thread notified 2019-12-27 15:05:35:-1226660768:DEBUG_X:Waiting for modem/control line/timer/socket activity 2019-12-27 15:05:35:-1226660768:DEBUG_X:CMD:1, DCE:1, LINE:0, TYPE:0, HOOK:0 2019-12-27 15:05:35:-1236274080:ENTER_EXIT:Exitting dce_check_control_lines function 2019-12-27 15:05:35:-1236274080:DEBUG:Control Line Change 2019-12-27 15:05:35:-1236274080:ENTER_EXIT:Entering dce_check_control_lines function 2019-12-27 15:05:35:-1226660768:DEBUG:Received D from control line watch task 2019-12-27 15:05:35:-1226660768:ENTER_EXIT:Entering mdm_disconnect function 2019-12-27 15:05:35:-1226660768:INFO:Disconnecting modem 2019-12-27 15:05:35:-1226660768:INFO:Disconnecting line 2019-12-27 15:05:35:-1226660768:INFO:Control Lines: DSR:1 DCD:0 CTS:1 2019-12-27 15:05:35:-1226660768:ENTER_EXIT:Entering dce_set_control_lines function 2019-12-27 15:05:35:-1226660768:DEBUG_X:Setting CTS pin high 2019-12-27 15:05:35:-1226660768:DEBUG_X:Setting DCD pin low 2019-12-27 15:05:35:-1226660768:ENTER_EXIT:Exitting dce_set_control_lines function 2019-12-27 15:05:35:-1226660768:DEBUG:Sending OK response to modem 2019-12-27 15:05:35:-1226660768:DEBUG_X:Sending text response 2019-12-27 15:05:35:-1226660768:ENTER_EXIT:Exitting mdm_disconnect function 2019-12-27 15:05:35:-1226660768:DEBUG_X:Waiting for modem/control line/timer/socket activity 2019-12-27 15:05:35:-1226660768:DEBUG_X:CMD:1, DCE:1, LINE:0, TYPE:0, HOOK:0

tcpser is being started with: ./tcpser -d /dev/ttyUSB0 -s 2400 -tm -l7

What am I missing here? :)

Tnx!

g.

geneb commented 4 years ago

An update to this - when I use a "pre built" null modem cable, this behavior doesn't happen. However, when I use the cable I built using the "bi-directional" diagram in the readme file, I get the disconnect behavior. I really need some help here folks.

go4retro commented 4 years ago

My apologies. I need to figure out how to get github to notify me when folks put stuff in here. I will test and see if I can recreate. Can you describe the rest of the config (what is running on the other end of the serial connection, and anything else pertinent.

jim

geneb commented 4 years ago

No worries, thanks Jim! In my most recent test case I was connecting from SyncTERM to a PC running Telix. On connect, sending ATA will answer and instantly disconnect. With the pre-built null modem cable, Telix shows "Online" in the status bar (which I would expect as most commercial cables have DCD wired high. My custom built cable shows as "offline" when not connected. I suspect the state change from offline to online and back to offline happens too quickly for Telix to update the status line.

g.

go4retro commented 4 years ago

I replicated the problem and I think I found the issue. I was checking too many serial control lines, so when I set DTR high on tcpser (to bring DCD on the receiving side up), the control lines thread popped, sent a notification to the main thread, who checked the DSR line (which is still low), and closed the connection. On a normal cable, DSR might be tied to DTR, so the line was high. I think I fixed it, but grab the newest and test.

geneb commented 4 years ago

Just tested with both ATS0=1 and using ATA after ATS0=0 and both work as expected! Thank you SO much for fixing this!