search

hharte / mm_manager

Manager for the Nortel Millennium series of payphones.
Other
54 stars 10 forks source link

Modem Initialization - US Robotics 3453C 56K Modem #17

Open mwberry opened 1 year ago

mwberry commented 1 year ago

I'm able to talk to the modem using screen, and am able to dial in / dial out if I manually issue AT commands. However, mm_manager is displaying an error on initialization. I can hear the modem reset when mm_manager issues the ATZ and it doesn't immediately crash afterwards, but it will exit about 5 seconds later. 

$ screen /dev/ttyUSB0 9600 8N1
AT
OK
ATH1
OK
ATH0
OK
ATDXXXXXXXXXX
RINGING

RINGING

BUSY
^ak
./mm_manager -m -n 1XXXXXXXXXX -f /dev/ttyUSB0 -vv -l install.dlog -p install.pcap -i "ATE=1 S0=1 S7=3 &D2 +MS=B212" -b 9600
mm_manager v0.8 [dev-3-g6a09eb1] - (c) 2020-2022, Howard M. Harte

Default Table directory: tables/default
Terminal-specific Table directory: tables/<terminal_id>
Using access code: 2727378
Using key card number: 4012888888
Manager Inter-packet Tx gap: 100ms.
Using Primary NCC number: 1XXXXXXXX
Using Secondary NCC number: 1XXXXXXXX
Baud Rate: 9600
Resetting modem: 'ATZ'
Intializing modem: 'ATE=1 S0=1 S7=3 &D2 +MS=B212'
Error initializing modem.

I looked through a few other prior issues and saw that the +MS argument differed, but I actually don't see that command in this modem's manual. I actually can't find much information about Bell 212 in the manual at all. Does this modem just not support it? Most of the modulation settings seem to be in S-registers. I also tried with S7=60, since that's the default value for that register on this modem. E=1 and &D=2 are also default.

If I omit the +MS command, then it does initialize (although maybe w/ the wrong modulation). However when I get to the phase where the payphone dials the manager, mm_manager never picks up. It just stays at Waiting for call from terminal.... It pegs a CPU core to 100% while in this state.

./mm_manager -m -n 1XXXXXXXXXX -f /dev/ttyUSB0 -vv -l install.dlog -p install.pcap -i "ATE=1 S0=1 S7=60 &D2" -b 9600
mm_manager v0.8 [dev-3-g6a09eb1] - (c) 2020-2022, Howard M. Harte

Default Table directory: tables/default
Terminal-specific Table directory: tables/<terminal_id>
Using access code: 2727378
Using key card number: 4012888888
Manager Inter-packet Tx gap: 100ms.
Using Primary NCC number: 1XXXXXXXX
Using Secondary NCC number: 1XXXXXXXX
Baud Rate: 9600
Resetting modem: 'ATZ'
Intializing modem: 'ATE=1 S0=1 S7=60 &D2'
Modem initialized.
Waiting for call from terminal...

My serial device is a CH340 USB Serial. I'm running under Linux. The payphone is a card-only variant. Not sure what firmware. The modem is plugged into a Grandstream HT802. I have polarity reversal enabled for the port the payphone is on, does mm_manager need it too?

mwberry commented 1 year ago

If I bring up the modem in screen, initialize it in the same way as mm_manager, and then place a phone call to it from my cell, the modem does pick up. When I hang up the modem notices.

ATZ
OK
ATE=1 S0=1 S7=60 &D2
OK

NO CARRIER
mwberry commented 1 year ago

Weird. After initializing the modem by hand once, suddenly now mm_manager is no longer eating 100% CPU anymore. It still doesn't get past Waiting for call from terminal..., but now I can hear the modem pick up the call at least. However, the download always fails with error code 24. This is likely because I've not set the modulation?

mwberry commented 1 year ago

When mm_manager pegs the CPU, it appears to be stuck in a loop like this:

read(6, "", 1)                          = 0
ioctl(6, TCSBRK, 1)                     = -1 EIO (Input/output error)
read(6, "", 1)                          = 0
ioctl(6, TCSBRK, 1)                     = -1 EIO (Input/output error)
read(6, "", 1)                          = 0
ioctl(6, TCSBRK, 1)                     = -1 EIO (Input/output error)
read(6, "", 1)                          = 0
ioctl(6, TCSBRK, 1)                     = -1 EIO (Input/output error)
read(6, "", 1)                          = 0
ioctl(6, TCSBRK, 1)                     = -1 EIO (Input/output error)
read(6, "", 1)                          = 0
ioctl(6, TCSBRK, 1)                     = -1 EIO (Input/output error)
read(6, "", 1)                          = 0
ioctl(6, TCSBRK, 1)                     = -1 EIO (Input/output error)
read(6, "", 1)                          = 0
ioctl(6, TCSBRK, 1)                     = -1 EIO (Input/output error)
read(6, "", 1)                          = 0
ioctl(6, TCSBRK, 1)                     = -1 EIO (Input/output error)
read(6, "", 1)                          = 0
ioctl(6, TCSBRK, 1)                     = -1 EIO (Input/output error)
read(6, "", 1)                          = 0
ioctl(6, TCSBRK, 1)                     = -1 EIO (Input/output error)
supersat commented 1 year ago

Supposedly the modem supports Bell 212A: https://support.usr.com/support/3453c/3453c-ug/tech_info.html

Try &B1?

Polarity reversal is only needed on the payphone side.

mwberry commented 1 year ago

Supposedly the modem supports Bell 212A: https://support.usr.com/support/3453c/3453c-ug/tech_info.html

That's a nice find @supersat . I could have swore I saw something that referenced Bell212A before I bought it, but couldn't find it again. Maybe the modem supports Bell212A, but only via auto-negotiation?

I think you mean ATB1 rather than AT&B1, I will give it a try. However you did give me an idea to try to lock it into 1200 bps with AT&U2 &N2.

I've found occasional references to S37 online, which appears to be another way to select the line speed. This modem's manual doesn't list S37, but others I've found have all say S37=5 means 1200bps [1][2][3].

[1] http://web.archive.org/web/20070830173944/http://messagestick.net/modem/Hayes_Ch1-3.html [2] http://web.archive.org/web/20220408071659/https://www.perle.com/support_services/documentation_pdfs/5500158.pdf [3] http://web.archive.org/web/20221225195108/http://www.cameratim.com/computing/modems/s-registers

mwberry commented 1 year ago

I notice that under screen I often lose characters in the modem -> computer direction. For example, here's an attempt at ATI4 to dump the current configuration under various baud rates / configurations. I wonder if this means there's something funny about the serial cable I'm using.

Also of note is that there is an S37 register in this output, which is why I was looking into it in the first place, and it does reflect ATS37=5 (default 0).

ATZ
KTE1
USRocCourier.Everhing ings. C1  E1L2  
   BA00   RIDLEN=8L=HUNTN HOOIMER
 1  &D2  &G0  H0  I0  &K1  &L0  &M4  &  &RS0  &T5  &U0  &X06  #CI0 S00=000  S01=000  S043  S03013 0  S05=008  S06=002  S0=060  
 S24=150 25=005  S2627=000S220031=  S00000  S35=000  36=000  S18=0  S20=000  S21=010  223=019  
                                                          0=000  S2=126  SS46=000 00000  001S3 4=06S5S570  S59=001  6162=000 S000  S6=00S67=000S69=0S700=56  
   S72=125  S73 

   LAST DIALED #:            
ATI4
ics Courithings.   B0  C1  E1  F1  L2  M1  Q0  V1  X7
   BAUD=19200  PARITY=N  WORDLEN=8
   DIAL=HUNT   ON HOOK   TIMER

   &A3  &B1  &C1  &D2  &G0  &H0  &I0  &K1  L  &4  0 & R &   0  0 &CID=  
S00=000  S01=000  S02=043  S03=013  S04=010  S05=008  S06=002  S07=060  
  S08=002  S09=006  S10=014  S11=070  S12=050  S13=000  S14=000  S15=000  
   S16=000  S17=000  S1 S19=000  S20=000  S21=010  S22=017  S23=019  
   S24=150  S25=005  S26=001 S27=000  S28=008  S29=020  S30=00  S31=000 
  S2=009  S3=000  S34=000  S35=000  S36=000  S37=000  S38=000  S39=000  
   S40=000  S41=003  S42=126  S43=200  S44015  S45=00 S46000 S47=00  
   S48=000  49=00  S50=000  S1=000  S52=000 S53=003 S54=64  S55=000  
   S56=000  S57=000  S58=00  S9=001  S60=000  S61=010  S62=000  S63=000  
   S64=000  S65=000  S66=000  S67=000  S68=000  S69=000  S70=000  S71=056  
   S72=125  S73=121  

   LAST DIALED #:                                      
OK
ATI4
UScs rhing Setngs...

  C1 1    M1 V1  X
                     BAUD=115200 PARITY=N  WORDLEN=8
 IAL=HUNT   ON HOOA3  &B1  &C1  &D2  &G0  &H0  &I0  &K1  &L0  &M4  &N0
   &P1  &R &S0  &T5  & &X0  &Y1  %N6  #CI 

   0=  S0 =04 S03= 040080 60S08=S9S S11=0 05 S=5=0   000  S100 S18=00S19=000 00=017  S23=019  
   S24=150  S25=005  S26=001  S27=000  S28=008  S29=020  S30=000  S31=000   S32=009  S33=000  S34=000  S35=000  S36=00S=3 3000  
   S40=00  S41=003  S42=1263=00  S44=015  =000  S46=000  S47=000  
   S480  S49=000  S50=0S51S0503  S=065=000  
   S56=007=000  S8=0059=001  S60=000  S61=010  S62=00  S60  
   S64=000  S65=000  6000  S67=000  S68=000  S69=000  S70=00  S706  
 A                                                                    S72=25 S73=
mwberry commented 1 year ago

Verified the DB9-DB25 serial cable pinout with a multimeter. Everything that should be connected is, with 1Ohm resistance, and nothing is connected where it shouldn't be. All the unused DB25 pins are high-impedance to the ground.

The modem itself could be defective. Or it could maybe be an IRQ issue on the computer side.

mwberry commented 1 year ago

I switched back to the USB serial because it's behaving much better than the in-built serial port. There must be some sort of conflict on the computer side.

$ screen /dev/ttyUSB0  19200 8N1
ATZ
OK
ATI4
USRobotics Courier V.Everything Settings...

   B0  C1  E1  F1  L2  M1  Q0  V1  X7
   BAUD=19200  PARITY=N  WORDLEN=8
   DIAL=HUNT   ON HOOK   TIMER

   &A3  &B1  &C1  &D2  &G0  &H0  &I0  &K1  &L0  &M4  &N0
   &P1  &R1  &S0  &T5  &U0  &X0  &Y1  %N6  #CID=0  

   S00=000  S01=000  S02=043  S03=013  S04=010  S05=008  S06=002  S07=060  
   S08=002  S09=006  S10=014  S11=070  S12=050  S13=000  S14=000  S15=000  
   S16=000  S17=000  S18=000  S19=000  S20=000  S21=010  S22=017  S23=019  
   S24=150  S25=005  S26=001  S27=000  S28=008  S29=020  S30=000  S31=000  
   S32=009  S33=000  S34=000  S35=000  S36=000  S37=000  S38=000  S39=000  
   S40=000  S41=003  S42=126  S43=200  S44=015  S45=000  S46=000  S47=000  
   S48=000  S49=000  S50=000  S51=000  S52=000  S53=003  S54=064  S55=000  
   S56=000  S57=000  S58=000  S59=001  S60=000  S61=010  S62=000  S63=000  
   S64=000  S65=000  S66=000  S67=000  S68=000  S69=000  S70=000  S71=056  
   S72=125  S73=121  

   LAST DIALED #:                                      

OK
mwberry commented 1 year ago

Summary of a series of experiments using the USB serial device. The base invocation is:

./mm_manager -m -n 1XXXXXXXXXX -f /dev/ttyS0 -vv -l install.dlog -p install.pcap -u -i "ATE1 S0=1 &D2 xxx"

serial rate ATB ATS37 AT&U,AT&N Wireshark Modem Sounds Payphone Error Code
19200,8N1 B1 (omitted) (omitted) nothing captured Constant tone, followed by 1 second of fuzz, silence, then relay hangs up 24
19200,8N1 B1 S37=5 (omitted) nothing captured Constant tone, followed by 1 second of fuzz, silence, then relay hangs up 24
19200,8N1 B1 S37=5 &U2 &N2 nothing captured Constant tone, followed by 1 second of fuzz, silence, then relay hangs up 24
19200,8N1 B1 (omitted) &U2 &N2 nothing captured Constant tone, followed by 1 second of fuzz, silence, then relay hangs up 24
19200,8N1 (omitted) S37=5 (omitted) nothing captured Constant tone, followed by 1 second of fuzz, silence, then relay hangs up 24
19200,8N1 (omitted) (omitted) &U2 &N2 nothing captured Constant tone, followed by 1 second of fuzz, silence, then relay hangs up 24
19200,8N1 (omitted) S37=5 &U2 &N2 nothing captured Several constant tones, followed by 1 second of fuzz, silence, then relay hangs up 24
19200,8N1 (omitted) (omitted) (omitted) nothing captured Several constant tones, followed by 1 second of fuzz, silence, then relay hangs up 24

Occasionally I'll get a 26 instead of a 24 error code on the payphone, but it's not deterministic.

mwberry commented 1 year ago

Nothing is ever captured on lo port udp/27273, nor in the pcap file, but if I convert the dialog log into a pcap and read it I can see the payphone's number (not from caller ID, but rather whatever I manually punch in during the install menu). The redacted XX's below encode the phone number of the payphone.

Note that I never get the $DATE: Connected! message from this line.

$ tcpdump -lnn -r install.pcap                                                                                             
reading from file install.pcap, link-type 147, snapshot length 1024

$ ./mm_dlog2pcap install.dlog install-dlog.pcap                                                                            
Nortel Millennium Dialog to .pcap Conversion Utility

Processed 1 packets

$ tcpdump -lnn -r install-dlog.pcap
reading from file install-dlog.pcap, link-type 147, snapshot length 1024
14:17:01.530120 UNSUPPORTED
        0x0000:  0200 0bXX XXXX XXXX 24c9 1703            ........$...

Snippet:

UART: RX: 00
UART: RX: 00
UART: RX: 00
UART: RX: 00
UART: RX: 00
UART: RX: 00
UART: RX: 00
UART: RX: 00
UART: RX: 00
UART: RX: 00
UART: RX: 00
UART: RX: 00
UART: RX: 00
UART: RX: 00
UART: RX: 00
UART: RX: 02
UART: RX: 00
UART: RX: 0B
UART: RX: XX
UART: RX: XX
UART: RX: XX
UART: RX: XX
UART: RX: XX
UART: RX: 24
UART: RX: C9
UART: RX: 17
UART: RX: 03
UART: RX: 00
UART: RX: 00
UART: RX: 00
UART: RX: 00
UART: RX: 00
UART: RX: 00
UART: RX: 00
UART: RX: 00
UART: RX: 00
UART: RX: 00
UART: RX: 00

This is confirmed in screen. No CONNECT is sent by the modem, so mm_manager never moves on to the next step.

ATZ
OK
ATE1 S0=1 &D2
OK

XXXXX$1�
mwberry commented 1 year ago

The modem's manual says:

Command Function
Qn Enable or disable the display of result codes.
  Q0 Display result codes.
Q1 Suppress result codes (quiet).
Q2 Suppress result codes when answering.
Vn Display result codes in words or numbers.
  V0 Display result codes in numeric form.
V1 Display result codes in verbal form.

And the modem claims response codes are on and in verbal form:

ATI4
USRobotics Courier V.Everything Settings...

   B0  C1  E1  F1  L2  M1  Q0  V1  X7

Yet it doesn't seem to be doing so.

mwberry commented 1 year ago

The modem does send other responses when dialing out:

ATZ
OK
ATE1 S0=1 &D2
OK
ATV1
OK
ATDXXXXXXXXXX   (dialing the payphone, which doesn't pick up)
RINGING

RINGING

RINGING

RINGING

NO CARRIER
ATDYYYYYYYYYY     (dialing my cellphone, I pick up and then hang up)
RINGING

RINGING

RINGING

BUSY
AT
OK

But for inbound calls it does not:

ATZ
OK
ATE1 S0=1 &D2
OK
ATV1
OK
(Dialed modem from my cell phone, modem answers, after a second I hang up from cell phone)

NO CARRIER
AT
OK
(Dialed modem from the payphone's install menu)

XXXXX$1��
hharte commented 1 year ago

If I had to guess, I would say it is because the modem is not supporting Bell-212A modulation. Either the modem does not support it, or is not configured properly.

mwberry commented 1 year ago

My theory is that it does support the Bell 212A modulation or else it would not have been able to receive the data frame starting with 02 containing the payphone's telephone number. Rather, I think for some reason it doesn't support sending the CONNECT response code. I think, if mm_manager had an alternative way to know when a call was connected, then it could probably work. I'm trying a patch to poll for TIOCM_RNG / MS_RING_ON as an alternative to watching for CONNECT. Also open to any suggestions on how to get the modem to send the CONNECT response code, beyond Q0 V1.

hharte commented 1 year ago

Ah, ok, thanks for the details. I looked at the UART log and I see what you're talking about.

I just tried a USR 5686-E modem and it seems like E=1 suppresses the connect message.

Can you please try the following modem init string? "ATS0=1 &D2 &N2"

and if that doesn't work, try: "ATS0=1 &D2 B1"

-Howard

mwberry commented 1 year ago

...it seems like E=1 suppresses the connect message.

I got very excited, but it seems that is not the case on this modem.

ATE1
OK
ATE0
OK
# Here I typed "AT" but it is not echoed back, as expected
OK
# Here I typed "ATI4" to confirm E0, Q0, and V1
USRobotics Courier V.Everything Settings...

   B0  C1  E0  F1  L2  M1  Q0  V1  X7

However when I dialed the modem up from the payphone I still didn't get the CONNECT message before the first frame of data:

OK

XXXXX$�
hharte commented 1 year ago

It seems like E=0 still, so that may be why the CONNECT is not appearing. Here is the ATI4 output from my USR modem that works:

ATI4
U.S. Robotics 56K FAX EXT Settings...

   B0  E1  F1  M1  Q0  V1  X4  Y0
   BAUD=19200  PARITY=N  WORDLEN=8
   DIAL=TONE    ON HOOK   CID=0

   &A3  &B1  &C1  &D2  &G0  &H1  &I0  &K1
   &M4  &N2  &P1  &R2  &S0  &T5  &U0  &Y1

   S00=001  S01=000  S02=043  S03=013  S04=010  S05=008  S06=004
   S07=060  S08=002  S09=006  S10=014  S11=070  S12=050  S13=000
   S15=000  S16=000  S18=000  S19=000  S21=010  S22=017  S23=019
   S25=005  S27=000  S28=008  S29=020  S30=000  S31=128  S32=002
   S33=000  S34=000  S35=000  S36=014  S38=000  S39=000  S40=001
   S41=000  S42=010

   LAST DIALED #:

OK

Using a terminal emulator (PuTTY in my case,):

ATZ
OK
ATS0=1 &D2 &N2
OK

Then have the terminal call the manager, I get:

RING

CONNECT 1200/NONE
mwberry commented 1 year ago

E=1 is the default for this modem, so all tests up until this point have been w/ E=1. But for completeness:


OK

OK
AT
OK
ATI4
USRobotics Courier V.Everything Settings...

   B0  C1  E1  F1  L2  M1  Q0  V1  X7

XXXXX$�
mwberry commented 1 year ago

I think a blocking read would be sufficient for this modem. If I just do a simple test program, the read will block and returns a valid frame.

ioctl(3, TIOCMGET, [TIOCM_DTR|TIOCM_RTS|TIOCM_CTS|TIOCM_DSR]) = 0
write(1, "DTR,___,RTS,CTS,____,_______\n", 29) = 29
read(3, "\2\0\xx\xx\xx\xx\xx\204$\311\27\3", 12) = 12
mwberry commented 1 year ago

Ok, some progress. The payphone can definitely talk to the manager. But it's unclear if the manager can talk back.

Intializing modem: 'ATE0 S0=1 &D2 '
Modem initialized.
Waiting for call from terminal...
T-->M RX: flags=00 [ --- | OK  | REQ |  ---  | Seq:0], len= 11 (datalen=  6), crc=17c9.

        000: XX, XX, XX, XX, XX, XX,                                         XXXXX$

T<--M TX: flags=08 [ --- | OK  | ACK |  ---  | Seq:0], len=  5 (datalen=  0), crc=0366.

        Terminal ID XXXXXXXXXX: Processing Table ID 36 (0x24) DLOG_MT_TIME_SYNC_REQ
                Current day/time: 2022-12-25 / 23:54:16
        Sending Table ID 20 (0x14) DLOG_MT_TIME_SYNC...

T<--M TX: flags=00 [ --- | OK  | REQ |  ---  | Seq:0], len= 18 (datalen= 13), crc=95ae.

        000: XX, XX, XX, XX, XX, 14, 7a, 0c, 19, 17, 36, 10, 01,             XXXXX.z...6..
        Table 20 (0x14) DLOG_MT_TIME_SYNC progress: (100%) -    8 /    8
        Sending Table ID 13 (0x0d) DLOG_MT_END_DATA...

T<--M TX: flags=01 [ --- | OK  | REQ |  ---  | Seq:1], len= 11 (datalen=  6), crc=05c9.

        000: XX, XX, XX, XX, XX, 0d,                                         XXXXX.

Unfortunately the payphone never sends any further data after that initial exchange. My guess is that it didn't successfully receive the ACK or the END_DATA and so it's still waiting. Eventually it times out and I'm guessing that's what error 24 means.

mwberry commented 1 year ago

Ok, actually, after locking up the T-key I noticed the display has changed. It now says "2022-12-25 / out of service". So it did receive the date response from mm_manager. I'm a bit stumped as to why the process is getting hung now.

hharte commented 1 year ago

After receiving the time sync response from the manager and the END_DATA, the terminal is supposed to respond with its software version, and request a table update:

Waiting for call from terminal...
2022-12-26  8:16:55: Connected!

T-->M RX: flags=00 [ --- | OK  | REQ |  ---  | Seq:0], len= 11 (datalen=  6), crc=c44f.

        000: 21, 25, 55, 12, 34, 24,                                         !%U.4$

T<--M TX: flags=08 [ --- | OK  | ACK |  ---  | Seq:0], len=  5 (datalen=  0), crc=0366.

        Terminal ID 2125551234: Processing Table ID 36 (0x24) DLOG_MT_TIME_SYNC_REQ
                Current day/time: 2022-12-26 /  8:16:56
        Sending Table ID 20 (0x14) DLOG_MT_TIME_SYNC...

T<--M TX: flags=00 [ --- | OK  | REQ |  ---  | Seq:0], len= 18 (datalen= 13), crc=e0a6.

        000: 21, 25, 55, 12, 34, 14, 7a, 0c, 1a, 08, 10, 38, 02,             !%U.4.z....8.

T-->M RX: flags=08 [ --- | OK  | ACK |  ---  | Seq:0], len=  5 (datalen=  0), crc=0366.
        Table 20 (0x14) DLOG_MT_TIME_SYNC progress: (100%) -    8 /    8
        Sending Table ID 13 (0x0d) DLOG_MT_END_DATA...

T<--M TX: flags=01 [ --- | OK  | REQ |  ---  | Seq:1], len= 11 (datalen=  6), crc=d64f.

        000: 21, 25, 55, 12, 34, 0d,                                         !%U.4.

T-->M RX: flags=09 [ --- | OK  | ACK |  ---  | Seq:1], len=  5 (datalen=  0), crc=9367.
        Table 13 (0x0d) DLOG_MT_END_DATA progress: (100%) -    1 /    1

T-->M RX: flags=01 [ --- | OK  | REQ |  ---  | Seq:1], len= 51 (datalen= 46), crc=6301.

        000: 21, 25, 55, 12, 34, 2c, 02, 0a, 12, 34, 56, 78, 90, 80, 00, 00, !%U.4,...4Vx....
        016: 01, 00, 3c, 4e, 42, 45, 31, 4a, 30, 31, 56, 31, 2e, 30, 51, 51, ..<NBE1J01V1.0QQ
        032: 31, 52, 57, 55, 20, 56, 32, 2e, 32, 01, 00, 00, 00, 00,         1RWU V2.2.....

T<--M TX: flags=09 [ --- | OK  | ACK |  ---  | Seq:1], len=  5 (datalen=  0), crc=9367.

        Terminal ID 2125551234: Processing Table ID 44 (0x2c) DLOG_MT_ATN_REQ_TAB_UPD
                Terminal 2125551234 requests table update. Reason: 0x02 [Install, ]

        Terminal ID 2125551234: Processing Table ID 10 (0x0a) DLOG_MT_TERM_STATUS
                Terminal serial number 1234567890, Terminal Status Word: 0x0001000080
                        Terminal Status: Reserved TELEPHONY_STATUS_BIT_7
                        Terminal Status: Station Access Cover Opened

        Terminal ID 2125551234: Processing Table ID 60 (0x3c) DLOG_MT_SW_VERSION
                                     Terminal Type: 27 (0x1b)
                             Feature Terminal Type: Card      01 (0x01)
                               Control ROM Edition: NBE1J01
                                   Control Version: V1.0
                             Telephony ROM Edition: QQ1RWU
                                 Telephony Version: V2.2
                        Validator Hardware Version:
                        Validator Software Version:

Can you check the install.dlog and see if there is any response from the terminal?

mwberry commented 1 year ago

I think the error is in the modification I made to get past the lack of a CONNECT message. What's super frustrating is that I found this manual page showing that the CONNECT message should be displayed in nearly all configurations. I've confirmed the default is X7 and that's what the modem is currently set to. That's the highest verbosity.

hharte commented 1 year ago

What is the firmware version in your modem?

https://support.usr.com/support/3453c/3453c-ug/upgrade.html

I see in the release notes for the latest firmware, there were some issues resolved regarding the connect messages for various rates, although I don’t see 1200 mentioned specifically:

https://www.usr.com/en-support/product/?prod=3453c

Also check the DIP switches are set to the defaults.

mwberry commented 1 year ago

Looks like it was a case of bad firmware. After a firmware update (which was itself a bit of a challenge, as it only speaks an ancient protocol), it now sends a CONNECT response:

AT
OK

RING

CONNECT 1200/NONE

XXXXX$��
mwberry commented 1 year ago

Pulled latest changes:

$ git log | head -n 1
commit 21fef927197d31fdc31f835aa3f1b168eadc7634

The mm_manager program does at least detect that a call is coming in now, but it fails before any meaningful packet transfer happens:

$ ./mm_manager -m -n 1XXXXXXXXXX -f /dev/ttyUSB0 -vv -l install.dlog -p install.pcap -i "ATE1 S0=1 &D2 " -u
mm_manager v0.8 [dev-6-g21fef92] - (c) 2020-2022, Howard M. Harte

Sending UDP packets to 127.0.0.1:27273
Default Table directory: tables/default
Terminal-specific Table directory: tables/<terminal_id>
Using access code: 2727378
Using key card number: 4012888888
Manager Inter-packet Tx gap: 100ms.
Using Primary NCC number: 1XXXXXXXXXX
Using Secondary NCC number: 1XXXXXXXXXX
Baud Rate: 19200
Resetting modem: 'ATZ'
Intializing modem: 'ATE1 S0=1 &D2 '
Modem initialized.
Waiting for call from terminal...
2022-12-26 17:21:34: Connected!

receive_mm_packet: Carrier lost, bailing.

T-->M RX: flags=00 [ --- | OK  | REQ |  ---  | Seq:0], len=  0 (datalen=  0), crc=0000.
        *** Framing Error, expected STOP=0x03, got STOP=00 ***
Error: Received an ACK without expecting it!

2022-12-26 17:21:34: Terminal : Disconnected.

Waiting for call from terminal...
^C
Received ^C, wait for shutdown.
mm_manager: Shutting down.

$ ./mm_dlog2pcap install.dlog install-dlog.pcap                                                                 
Nortel Millennium Dialog to .pcap Conversion Utility

Error reading input stream, line=234Processed 2 packets

$ tcpdump -r install-dlog.pcap -lnnvv  
reading from file install-dlog.pcap, link-type 147, snapshot length 1024
17:22:01.722446 UNSUPPORTED
        0x0000:  0204 0bXX XXXX XXXX 24c8 e403            ...XXXXX$...
17:22:01.722457 UNSUPPORTED
        0x0000:  0204 0bXX XXXX XXXX 24c8 e403            ...XXXXX$...
hharte commented 1 year ago

Ok, that is good news about the CONNECT message, seems like you are getting closer. Regarding the immediate disconnect, that is issue #16 which I have not been able to reproduce.

Are you using a serial cable with all of the modem control signals wired? What operating system are you using? Also, the DIP switches on the bottom of the modem can affect the flow control as well.

If the modem control signals are fine, it could also be that the terminal is disconnecting.

Can you please add &N2 or B1 to your modem init string?

I should probably make watching the carrier detect an option, but for now, you can revert this commit, recompile, and see if things start working:

git revert 6a09eb1e6959ed4043e1e835f4642b1831e9bce7

Take care, Howard

mwberry commented 1 year ago

I did switch back to the USB-serial adapter a while back, it's based on the CH340 chipset. The motherboard's serial DB-9 was corrupting bytes for some reason. I think there's probably a UEFI/BIOS setting I need to tweak to get that one working. the USB-serial adapter probably doesn't support the carrier detect.

Reverting the carrier detect commit did fix the issue while using the USB-serial adapter. I was able to get the payphone into an installed state. Very excited to start working with it now.

mwberry commented 1 year ago

So, to summarize and close out this issue.

hharte commented 1 year ago

Hello @mwberry,

I received a USR 3453C modem today and it seems to work fine (after updating to the latest firmware) with the following modem init string: ATE=1 S0=1 &D2 &N2 &C1

The key to the carrier detect is the &C1

Can you please try this and see if it works with the CH340 chipset? I observed the same failure as you, using a real (motherboard) RS-232 serial port, and the issue is resolved with &C1.

Take care, Howard

mwberry commented 1 year ago

Apologies for the delay, I haven't had a chance to get back to this project since the holidays.

Attempt 1: Placed call from an already-installed phone. Phone dialed manager, negotiated, manager lost the carrier, phone eventually presented a "can't rate call" error.

# /dev/ttyUSB0 is the CH340 USB Serial adapter
$ sudo ./mm_manager -m -n 1xxxxxxxxxx -f /dev/ttyUSB0 -vv -l install.dlog -p install.pcap -i "ATE=1 S0=1 &D2 &N2 &C1" -u              
mm_manager v0.8 [dev-6-g21fef92] - (c) 2020-2022, Howard M. Harte

Sending UDP packets to 127.0.0.1:27273
Default Table directory: tables/default
Terminal-specific Table directory: tables/<terminal_id>
Using access code: 2727378
Using key card number: 4012888888
Manager Inter-packet Tx gap: 100ms.
Using Primary NCC number: 1xxxxxxxxxx
Using Secondary NCC number: 1xxxxxxxxxx
Baud Rate: 19200
Resetting modem: 'ATZ'
Intializing modem: 'ATE=1 S0=1 &D2 &N2 &C1'
Modem initialized.
Waiting for call from terminal...
2023-01-21 15:11:01: Connected!

receive_mm_packet: Carrier lost, bailing.

T-->M RX: flags=00 [ --- | OK  | REQ |  ---  | Seq:0], len=  0 (datalen=  0), crc=0000.
        *** Framing Error, expected STOP=0x03, got STOP=00 ***
Error: Received an ACK without expecting it!

2023-01-21 15:11:01: Terminal : Disconnected.

Waiting for call from terminal...

Attempt 2: Same setup, same result

Waiting for call from terminal...
2023-01-21 15:16:30: Connected!

receive_mm_packet: Carrier lost, bailing.

T-->M RX: flags=00 [ --- | OK  | REQ |  ---  | Seq:0], len=  0 (datalen=  0), crc=0000.
        *** Framing Error, expected STOP=0x03, got STOP=00 ***
Error: Received an ACK without expecting it!

2023-01-21 15:16:30: Terminal : Disconnected.

Waiting for call from terminal...

Attempt 3: With carrier detect reversion and &C1, for completeness, works as before.

$ git reset --hard HEAD@{1}
HEAD is now at 61a2197 Revert "mm_manager: Handle carrier loss gracefully."
$ cmake . && make
$ sudo ./mm_manager -m -n 1xxxxxxxxxx -f /dev/ttyUSB0 -vv -l install.dlog -p install.pcap -i "ATE=1 S0=1 &D2 &N2 &C1" -u
mm_manager v0.8 [no-carrier-detect] - (c) 2020-2022, Howard M. Harte

Sending UDP packets to 127.0.0.1:27273
Default Table directory: tables/default
Terminal-specific Table directory: tables/<terminal_id>
Using access code: 2727378
Using key card number: 4012888888
Manager Inter-packet Tx gap: 100ms.
Using Primary NCC number: 1xxxxxxxxxx
Using Secondary NCC number: 1xxxxxxxxxx
Baud Rate: 19200
Resetting modem: 'ATZ'
Intializing modem: 'ATE=1 S0=1 &D2 &N2 &C1'
Modem initialized.
Waiting for call from terminal...
2023-01-21 15:21:18: Connected!

.........
T-->M RX: flags=04 [ --- | OK  | REQ | RETRY | Seq:0], len= 11 (datalen=  6), crc=e4c8.

        000: xx, xx, xx, xx, xx, 24,                                         xxxxx$

T-->M RX: flags=04 [ --- | OK  | REQ | RETRY | Seq:0], len= 11 (datalen=  6), crc=e4c8.

        000: xx, xx, xx, xx, xx, 24,                                         xxxxx$ 

T<--M TX: flags=08 [ --- | OK  | ACK |  ---  | Seq:0], len=  5 (datalen=  0), crc=0366.

        Terminal ID xxxxxxxxxx: Processing Table ID 36 (0x24) DLOG_MT_TIME_SYNC_REQ 
                Current day/time: 2023-01-21 / 15:21:28
        Sending Table ID 20 (0x14) DLOG_MT_TIME_SYNC...

T<--M TX: flags=00 [ --- | OK  | REQ |  ---  | Seq:0], len= 18 (datalen= 13), crc=21dd.

        000: xx, xx, xx, xx, xx, 14, 7b, 01, 15, 0f, 15, 1c, 07,             xxxxx.{......
        Table 20 (0x14) DLOG_MT_TIME_SYNC progress: (100%) -    8 /    8
        Sending Table ID 13 (0x0d) DLOG_MT_END_DATA...

T<--M TX: flags=01 [ --- | OK  | REQ |  ---  | Seq:1], len= 11 (datalen=  6), crc=05c9.

        000: xx, xx, xx, xx, xx, 0d,                                         BVf!.. 
        Table 13 (0x0d) DLOG_MT_END_DATA progress: (100%) -    1 /    1

T-->M RX: flags=01 [ --- | OK  | REQ |  ---  | Seq:1], len= 89 (datalen= 84), crc=c9f4.

        000: xx, xx, xx, xx, xx, 3f, 00, 00, xx, xx, xx, xx, xx, ee, ee, ee, xxxxx?..xxxxx...
        016: ee, ee, 7a, 0c, 1f, 0f, 3a, 33, 00, 24, 06, fb, ff, ff, 35, 00, ..z...:3.$....5.
        032: xx, xx, xx, xx, xx, ee, ee, ee, ee, ee, 00, xx, xx, xx, xx, xx, xxxxx......xxxxx
        048: xx, xx, xx, ee, ee, 00, 00, 00, 00, 00, 00, 00, 00, 0a, 00, 7a, xxx............z
        064: 0c, 1f, 0f, 14, 0e, 00, 00, 2b, 54, 00, 00, 00, 00, 00, 00, 00, .......+T.......
        080: 00, 20, 00, 00,                                                 . ..   

T<--M TX: flags=09 [ --- | OK  | ACK |  ---  | Seq:1], len=  5 (datalen=  0), crc=9367.

        Terminal ID xxxxxxxxxx: Processing Table ID 63 (0x3f) DLOG_MT_RATE_REQUEST  
                Rate request: 2022-12-31 15:58:51: Phone number: xxxxxxxxxx, pad=0, telco_id=0, 0,Intra-LATA No Charge,6,rate_type=251,255,255.
                        Rate response: Initial period: 60, Initial charge: 4149, Additional Period: 0, Additional Charge: 0

        Terminal ID xxxxxxxxxx: Processing Table ID 53 (0x35) DLOG_MT_CALL_DETAILS  
                CDR: 2022-12-31 15:20:14, Duration: 00:00:43 Intra-LATA Calling Card, DN: xxxxxxxxxx, Card#: xxxxxxxxxxxxxxxx, Collected: $0.00, Requested: $0.00, carrier code=0, rate_type=0, Seq: 0010
        Sending Table ID 64 (0x40) DLOG_MT_RATE_RESPONSE...

T<--M TX: flags=02 [ --- | OK  | REQ |  ---  | Seq:2], len= 39 (datalen= 34), crc=a901.

        000: xx, xx, xx, xx, xx, 40, 07, 3c, 00, 35, 10, 00, 00, 00, 00, 00, xxxxx@.<.5......
        016: 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 05, ................
        032: 0a, 00,                                                         ..

T-->M RX: flags=2a [ DIS | OK  | ACK |  ---  | Seq:2], len=  5 (datalen=  0), crc=a37e.
receive_mm_packet: Received disconnect status OK from terminal.
receive_mm_packet: Hanging up modem.
mwberry commented 1 year ago

My conclusion remains the same, that this particular implementation of the CH340 didn't wire up the additional RS232 pins correctly. I will put some effort into configuring the motherboard's serial port correctly.

mwberry commented 1 year ago

After adjusting the BIOS settings on this computer, I'm able to use the motherboard's built-in serial port. It does work with the current latest commit.

$ git log | head -n 1
commit 21fef927197d31fdc31f835aa3f1b168eadc7634

$ sudo ./mm_manager -m -n 1xxxxxxxxxx -f /dev/ttyS0 -vv -l install.dlog -p install.pcap -i "ATE=1 S0=1 &D2 &N2 &C1" -u
mm_manager v0.8 [dev-6-g21fef92] - (c) 2020-2022, Howard M. Harte

Sending UDP packets to 127.0.0.1:27273
Default Table directory: tables/default
Terminal-specific Table directory: tables/<terminal_id>
Using access code: 2727378
Using key card number: 4012888888
Manager Inter-packet Tx gap: 100ms.
Using Primary NCC number: 1xxxxxxxxxx
Using Secondary NCC number: 1xxxxxxxxxx
Baud Rate: 19200
Resetting modem: 'ATZ'
Intializing modem: 'ATE=1 S0=1 &D2 &N2 &C1'
Modem initialized.
Waiting for call from terminal...
2023-01-21 17:38:39: Connected!
.........
T-->M RX: flags=04 [ --- | OK  | REQ | RETRY | Seq:0], len= 35 (datalen= 30), crc=04c6.

        000: xx, xx, xx, xx, xx, 3f, 00, 00, xx, xx, xx, xx, xx, ee, ee, ee, xxxxx?..xxxxx...
        016: ee, ee, 7b, 01, 15, 11, 26, 12, 00, 24, 06, fb, ff, ff,         ..{...&..$....
mwberry commented 1 year ago

Although maybe I haven't totally solved this motherboard's serial port issues. Occasionally I see stuff like the below. It has some valid data in there, but padded on both sides by garbage.

Waiting for call from terminal...
2023-01-21 17:48:58: Connected!

............................receive_mm_packet: CRC Error!
receive_mm_packet: Framing Error!

T-->M RX: flags=44 [ --- | OK  | REQ | RETRY | Seq:0], len=201 (datalen=196), crc=5555.
        *** CRC Error, calculated: 00b7 ***
        *** Framing Error, expected STOP=0x03, got STOP=55 ***

        000: d0, bf, ff, ff, 13, 03, 02, 04, 23, xx, xx, xx, xx, xx, 3f, 00, ........#xxxxx?.
        016: 00, xx, xx, xx, xx, xx, ee, ee, ee, ee, ee, 7b, 01, 15, 11, 30, .xxxxx.....{...0
        032: 25, 00, 24, 06, fb, ff, ff, fd, 23, 03, 02, 04, 23, xx, xx, xx, %.$.....#...#xxx
        048: xx, xx, 3f, 00, 00, xx, xx, xx, xx, xx, ee, ee, ee, ee, ee, 7b, xx?..xxxxx.....{
        064: 01, 15, 11, 30, 25, 00, 24, 06, fb, ff, ff, fd, 23, 03, 02, 20, ...0%.$.....#..
        080: 05, 78, 03, 03, 42, 2c, 57, 3b, 31, be, a8, b1, 50, 55, 55, 55, .x..B,W;1...PUUU
        096: 55, 55, 55, 55, 55, 55, 55, 55, 55, 55, 55, 55, 55, 55, 55, 55, UUUUUUUUUUUUUUUU
        112: 55, f5, aa, e4, aa, 55, 55, 55, 55, 55, 55, 55, 55, 55, 55, 55, U....UUUUUUUUUUU
        128: 55, 55, 55, 55, 55, 55, 55, 55, 55, 55, 55, 55, 55, 55, 55, 55, UUUUUUUUUUUUUUUU
        144: 55, 55, 55, 55, 55, 55, 55, 55, 55, 55, 55, 55, 55, 55, 55, 55, UUUUUUUUUUUUUUUU
        160: 55, 55, 55, 55, 55, 55, 55, 55, 55, 55, 55, 55, d5, e0, a0, d6, UUUUUUUUUUUU....
        176: ed, a0, 5f, 7d, ad, f5, 73, c0, e8, a9, 55, 55, 55, 55, 55, 55, .._}..s...UUUUUU
        192: 55, 55, 55, 55,                                                 UUUU
mwberry commented 1 year ago

I see what's happening. Although mm_manager thinks it is disconnected, the modem is actually still online after the initial rate check call. When the payphone makes a subsequent call (for example, a card validation) then the modem has buffered a lot of dead air / silence.

To confirm, I did the following:

  1. Ensured the modem was offline by removing the RJ-11 and reinserting it
  2. Dialed a number on the payphone and let it call the manager to get the rate
  3. Ensured the modem was offline by removing the RJ-11 and reinserting it
  4. Swiped a magstripe card and let it call the manager to validate it
  5. The payphone dialed out successfully.

At step 3, even though mm_manager had logged that it was disconnected, I could see on the ATA box that the call was still in progress and heard the modem's relay click off when I removed the RJ-11.

mwberry commented 1 year ago

Let me know if I should re-open this issue or file this as a new issue.

hharte commented 1 year ago

@mwberry , good find, thank you for the detailed analysis. I’ll reopen this issue, and take a look.

mwberry commented 1 year ago

In a few weeks I'll also have another ATA box to try out.

hharte commented 1 year ago

Hello @mwberry ,

I made some changes to perform a modem hang up when carrier loss is detected.

Hopefully this will resolve the issue.

-Howard

mwberry commented 1 year ago

Hello again,

I pulled the recent changes and updated my command line invocation to:

sudo ./mm_manager -m -n 1xxxxxxxxxx -f /dev/ttyUSB0 -vv -l install.dlog -p install.pcap -i "ATE=1 S0=1 &D2 &N2 &C1" -u -w

After ten or so attempts, about 2 worked flawlessly. In those two attempts I was able to dial, obtain a rate, present a card, have it validate, and then dial out. For the remaining attempts, the ATA device still showed a call was in-progress even while mm_manager was displaying Waiting for call from terminal.... If I did the trick of pulling the RJ-11 to end the call in progress, then I was able to get it to work around 50% of the time. The other 50% of the time, I was either too slow on the RJ-11 and the payphone timed out waiting for card validation or it did dial mm_manager to validate the card but there were too many framing errors for mm_manager to successfully parse the request and respond. An example card validation is below.

Since you have the same modem on the same firmware, the variables are the serial device and the ATA. I'm suspecting the ATA. The next test I may try is to see if I can kill mm_manager when it is in this dubious "maybe a call is still in progress state" and see if the modem thinks it is in online mode or not. Maybe it's only the ATA that thinks the call is still in progress. I'm still using the Grandstream 802 as the ATA. I did receive another ATA device to test with, but I got it used and need to figure out how to wipe it before I can set it up.

2023-02-04 21:02:06: Connected!

..................receive_mm_packet: CRC Error!
receive_mm_packet: Framing Error!

T-->M RX: flags=04 [ --- | OK  | REQ | RETRY | Seq:0], len=232 (datalen=227), crc=fbff.
        *** CRC Error, calculated: fcbc ***
        *** Framing Error, expected STOP=0x03, got STOP=ff ***

        000: 12, 21, 42, 7f, 12, 21, 55, 80, 25, 00, df, 0e, 03, 02, 04, 31, .!B..!U.%......1
        016: xx, xx, xx, xx, xx, 02, 00, 22, 22, 22, 22, 24, ee, ee, ee, ee, xxxxx..""""$....
        032: ee, 00, xx, xx, xx, xx, xx, xx, xx, xx, ee, ee, ee, ee, 7f, 08, ..xxxxxxxx......
        048: 00, 00, 27, 08, 08, fd, 27, 08, 54, 00, 25, 00, 9d, 3c, 03, de, ..'...'.T.%..<..
        064: c2, 02, d1, 15, d0, ac, b4, 4e, 15, 2a, 90, e3, 5a, 26, 6a, ae, .......N.*..Z&j.
        080: 55, 55, 55, 55, 55, 55, 55, 55, 55, 55, 55, 55, 55, 55, 55, 55, UUUUUUUUUUUUUUUU
        096: 55, 55, 55, 55, 7c, 21, d1, 54, 29, 32, 6e, 9e, 32, 71, fe, 2d, UUUU|!.T)2n.2q.-
        112: 36, 97, ff, fb, f3, 97, f3, 97, ff, fb, ff, fb, 7b, bf, 4b, ff, 6...........{.K.
        128: ff, fb, c4, 02, fb, 56, 2a, a5, de, e9, 25, a8, 84, 93, d4, f6, .....V*...%.....
        144: 4e, aa, 55, 55, 55, 55, 55, 55, 55, 55, 55, 55, 55, 55, 55, 55, N.UUUUUUUUUUUUUU
        160: 55, 55, 55, 55, 55, 55, 55, 55, 55, 55, 55, 55, 55, 55, 55, 55, UUUUUUUUUUUUUUUU
        176: 55, 55, 55, 55, 55, 55, 55, 55, 55, 55, 55, 55, 55, 55, 1d, 8f, UUUUUUUUUUUUUU..
        192: 4e, de, 4d, 75, dc, 5c, 16, a2, 0a, cf, 4b, ff, 6f, eb, ff, fb, N.Mu.\....K.o...
        208: 73, f7, ed, 6f, eb, ff, 7b, bf, 4b, db, f7, b7, cf, 4b, ff, ff, s..o..{.K....K..
        224: fb, ff, fb,                                                     ...

T<--M TX: flags=01 [ --- | OK  | REQ |  ---  | Seq:1], len=  5 (datalen=  0), crc=5360.
receive_mm_packet: CRC Error!
receive_mm_packet: Framing Error!

T-->M RX: flags=79 [ DIS | ERR | ACK |  ---  | Seq:1], len= 15 (datalen= 10), crc=5555.
        *** CRC Error, calculated: b210 ***
        *** Framing Error, expected STOP=0x03, got STOP=55 ***

        000: a8, 55, 55, 55, 55, 55, 55, 55, 55, 55,                         .UUUUUUUUU
receive_mm_packet: Received disconnect status Failure from terminal.
receive_mm_packet: Hanging up modem.
wait_for_mm_ack: Error, did not receive an ACK packet, status=0x0e
receive_mm_table: Expected NACK from terminal, status=0x0e

2023-02-04 21:02:29: Terminal xxxxxxxxxx: Disconnected.

Waiting for call from terminal...
mwberry commented 1 year ago

If I attempt to gracefully exit mm_manager while the ATA light is flashing, mm_manager does not immediately exit and instead I got the "wait for shutdown". The modem relay clicked and the ATA light stopped flashing and only then did mm_manager exit.

Next I will try to hard-kill it (kill -9) so that it leaves the modem in the state alone so I can investigate.

2023-02-04 21:45:03: Terminal : Disconnected.

Waiting for call from terminal...
^C
Received ^C, wait for shutdown.
mm_manager: Shutting down.
mwberry commented 1 year ago

Ok. There was at least one other gremlin in my setup. I went back to using screen just to sanity check some things with the modem and noticed that it was dropping a lot of characters in both directions. I relocated the USB serial adapter from the front-panel USB port to a USB port on the motherboard. That eliminated the lost characters when interfacing with the modem under screen. I've used that front USB port for keyboards, but those are so low-throughput it's unlikely I would have ever noticed.

I also want to double check something. I've been using a modem initialization string with ATE=1 all this time since that's part of the default set. But ATE=1 on this modem means "echo input", so you'd read every command you write on the serial port back again. Isn't that undesirable?

Anyway, back to the experiment at hand. If I kill -9 the mm_manager while it is displaying Terminal : Disconnected followed by Waiting for call from Terminal... and then connect with screen, I can tell the modem is definitely still in a call. I can break into online command mode with +++ and hang up manually and the modem relay clicks off and the ATA light stops flashing.

Terminal 1:

2023-02-04 22:14:11: Terminal : Disconnected.

Waiting for call from terminal...
zsh: killed     sudo ./mm_manager -m -n 1xxxxxxxxxx -f /dev/ttyUSB1 -vv -l install.dlog -p  -
$

Terminal 2:

$ sudo kill -9 $MM_MANGER_PID; sudo screen /dev/ttyUSB1 19200
UUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUU�I���S��0��UUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUU��UUU��UUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUU�}���O�bx�4��UUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUU
OK

OK

The U's are the 55 bytes that I suspect are "silence". Before the first OK I hit +++, before the second OK I entered ATH0.

I suspect that I shouldn't be receiving these "silence" bytes, because the Bell212A modulation should not decode silence as data. So I suspect the modem->ATA->SIP->SIP->ATA->modem round-trip is not correctly decoding all the bytes. There's real data in there, for sure, but there's also superfluous bytes. mm_manager is doing a remarkable job finding valid frames in the noise based on that leading 02, but if a byte gets inserted in the middle of a frame, then things go downhill fast.

I think I need to take a deep look at the configuration of the Grandstream 802. I've read elsewhere that the exact SIP encoding and things like echo cancellation can cause issues with modems. This another reason why I wanted to test the other ATA, because it can do local hairpinning between two FXS ports without SIP involvement. The Grandstream 802 has two FXS ports though, so I'll also look to see if I can get it to do that as well.

mwberry commented 1 year ago

At the SIP level, it looks like the call has terminated. If I dial the modem from a regular phone and then hang up during modem negotiation, I see the call terminate on the network. But despite that, the ATA light continues to flash and the modem remains online.

06:43:41.709831 IP 10.0.0.126.5004 > xxx.xxx.xxx.xxx.10520: UDP, length 172
<binary packet>
06:43:41.724301 IP xxx.xxx.xxx.xxx.10520 > 10.0.0.126.5004: UDP, length 172
<binary packet>
06:43:41.732706 IP 10.0.0.126.5004 > xxx.xxx.xxx.xxx.10520: UDP, length 172
<binary packet>
06:43:41.743365 IP xxx.xxx.xxx.xxx.5060 > 10.0.0.126.5060: SIP: BYE sip:xxxxxxxx@10.0.0.126:5060 SIP/2.0
<some binary data>
..~........BYE sip:xxxxxxxxxx@10.0.0.126:5060 SIP/2.0
Via: SIP/2.0/UDP xxxxxxxxxx:5060;branch=xxxxxxxxxx;rport
Max-Forwards: 70
From: "xxxxxxxxxx" <sip:xxxxxxxxxxxx@xxxxxxxx>;tag=xxxxxx
To: <sip:xxxxxxxxxx@10.0.0.126:5060>;tag=xxxx
Call-ID: xxxxxxx@xxxxxxxxxxx:5060
CSeq: 103 BYE
User-Agent: <VOIP provider>
X-Asterisk-HangupCause: Normal Clearing
X-Asterisk-HangupCauseCode: 16
Content-Length: 0

06:43:41.751816 IP 10.0.0.126.5004 > xxx.xxx.xxx.xxx.10520: UDP, length 172
<binary packet>
06:43:41.767437 IP 10.0.0.126.5060 > xxx.xxx.xxx.xxx.5060: SIP: SIP/2.0 200 OK
<some binary data>.....SIP/2.0 200 OK
Via: SIP/2.0/UDP xxx.xxx.xxx.xxx:5060;branch=xxxxxxx;rport=5060
From: "xxxxxxxxxx" <sip:xxxxxxxxxxx@xxxxxxx>;tag=xxxxxx
To: <sip:xxxxxxxx@10.0.0.126:5060>;tag=xxxxx
Call-ID: xxxxx@xxxxxx:5060
CSeq: 103 BYE
Contact: <sip:xxxxxxx@10.0.0.126:5060>
Supported: replaces, path, timer, eventlist
User-Agent: Grandstream HT802 1.0.35.4
Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE
Content-Length: 0

06:43:41.830877 IP 10.0.0.126.5004 > xxx.xxx.xxx.xxx.10520: UDP, length 172
<binary packet>
06:43:41.834352 IP xxx.xxx.xxxx > 10.0.0.126: ICMP xxx.xxx.xxx.xxx udp port 10520 unreachable, length 208
<binary packet>
06:43:41.896025 IP 10.0.0.126.5005 > xxx.xxx.xxx.xxx.10521: UDP, length 12
<some binary>......D.BYE......
mwberry commented 1 year ago

I've reached out to both the VOIP provider and Grandstream to see if they can offer any guidance on this.