Menu ▾ ▴

T.38 send and receive failures, T.30 with IAXmodem is fine

Help
Hans-Peter Jansen
2018-09-14
2018-11-20

  • Hans-Peter Jansen

    Hans-Peter Jansen - 2018-09-14

    Hi,

    I've tried hard to setup an Asterisk PBX with T38modem, using Pete's current
    releases of ptlib, opan, and t38modem. The IAXmodem setup is doing fine so far,
    e.g.:

    T.30 setup:
    Modem <-> PSTN <-> SIP Trunk Provider <-> Asterisk <-> IAXModem <-> Hylafax: OK

    T.38 setup:
    Modem <-> PSTN <-> SIP Trunk Provider <-> Asterisk <-> T38Modem <-> Hylafax: FAIL

    Both directions are affected. The SIP Trunk Provider handles T.38 correctly.

    The modem is from an old ISDN based setup (Asterisk 1.2.31, Elsa Modem), that is
    doing fine since 10 years.

    Asterisk is at version 15.5.0.

    sip.conf:

    [t38modem]
    context = outbound
    type = friend
    host = 127.0.0.1
    permit = 127.0.0.1
    port = 6060
    allow = all
    canreinvite = yes
    t38pt_udptl = yes

    Here's a send log of T38modem:

    t38modem --no-h323 -o /var/log/t38modem.log -u t38modem --sip-listen udp\$127.0.0.1:6060 --sip-t38-udptl-redundancy 3 --ptty +/dev/ttyT380,+/dev/ttyT381,+/dev/ttyT382 --route "modem:.=sip:<dn>@127.0.0.1" --route "sip:.</dn>=modem:<dn>" --force-fax-mode --force-fax-mode-delay 0</dn>

    T38Modem Version 3.15.3
    (OPAL-3.10.15/3.10.15 (svn:30298), PTLIB-2.10.15/2.10.15 (svn:30295)) by Frolov,Holtschneider,Davidson on Unix Linux (4.12.14-lp150.12.16-default-x86_64)

    T38Modem pid: 30824 ppid: 10067
    Disabled H.323 protocol
    Waiting for incoming SIP calls from udp$127.0.0.1:6060
    Route table:
    modem:.=sip:<dn>@127.0.0.1
    sip:.</dn>    =modem:<dn>
    Call[C27c353f912] from modem:t38modem to 00123456789@+/dev/ttyT380, route to sip:00123456789@127.0.0.1
    Open OpalRTPMediaStream[0x7f8ae4028510]-Source-G.711-uLaw-64k for Call[C27c353f912]
    Open AudioModemMediaStream[0x7f8ae401d270]-Sink-PCM-16 for Call[C27c353f912]
    Open AudioModemMediaStream[0x7f8ae402d2a0]-Source-PCM-16 for Call[C27c353f912]
    Open OpalRTPMediaStream[0x7f8ae402afd0]-Sink-G.711-uLaw-64k for Call[C27c353f912]
    Close AudioModemMediaStream[0x7f8ae402d2a0]-Source-PCM-16 for Call[C27c353f912]
    Close OpalRTPMediaStream[0x7f8ae402afd0]-Sink-G.711-uLaw-64k for Call[C27c353f912]
    Close OpalRTPMediaStream[0x7f8ae4028510]-Source-G.711-uLaw-64k for Call[C27c353f912]
    Close AudioModemMediaStream[0x7f8ae401d270]-Sink-PCM-16 for Call[C27c353f912]
    Open OpalRTPMediaStream[0x7f8ae402ce30]-Source-T.38 for Call[C27c353f912]
    Open T38ModemMediaStream[0x7f8ae400fd80]-Source-T.38 for Call[C27c353f912]
    Open OpalRTPMediaStream[0x7f8ae00139e0]-Sink-T.38 for Call[C27c353f912]
    Open T38ModemMediaStream[0x7f8ae001b450]-Sink-T.38 for Call[C27c353f912]
    Close T38ModemMediaStream[0x7f8ae400fd80]-Source-T.38 for Call[C27c353f912]
    Close OpalRTPMediaStream[0x7f8ae00139e0]-Sink-T.38 for Call[C27c353f912]
    Close OpalRTPMediaStream[0x7f8ae402ce30]-Source-T.38 for Call[C27c353f912]
    Close T38ModemMediaStream[0x7f8ae001b450]-Sink-T.38 for Call[C27c353f912]
    Open OpalRTPMediaStream[0x7f8ae001bb90]-Source-T.38 for Call[C27c353f912]
    Open T38ModemMediaStream[0x7f8ae0013e60]-Sink-T.38 for Call[C27c353f912]
    Open T38ModemMediaStream[0x7f8ae40135b0]-Source-T.38 for Call[C27c353f912]
    Open OpalRTPMediaStream[0x7f8ae4013940]-Sink-T.38 for Call[C27c353f912]
    Close T38ModemMediaStream[0x7f8ae40135b0]-Source-T.38 for Call[C27c353f912]
    Close OpalRTPMediaStream[0x7f8ae4013940]-Sink-T.38 for Call[C27c353f912]
    Close OpalRTPMediaStream[0x7f8ae001bb90]-Source-T.38 for Call[C27c353f912]
    Close T38ModemMediaStream[0x7f8ae0013e60]-Sink-T.38 for Call[C27c353f912]
    Open T38ModemMediaStream[0x7f8ae4013220]-Source-T.38 for Call[C27c353f912]
    Open OpalRTPMediaStream[0x7f8ae4007b00]-Sink-G.711-uLaw-64k for Call[C27c353f912]
    Open OpalRTPMediaStream[0x7f8ae401d270]-Source-G.711-uLaw-64k for Call[C27c353f912]
    Open T38ModemMediaStream[0x7f8ae4021fb0]-Sink-T.38 for Call[C27c353f912]
    Close OpalRTPMediaStream[0x7f8ae4007b00]-Sink-G.711-uLaw-64k for Call[C27c353f912]
    Close T38ModemMediaStream[0x7f8ae4013220]-Source-T.38 for Call[C27c353f912]
    Close OpalRTPMediaStream[0x7f8ae401d270]-Source-G.711-uLaw-64k for Call[C27c353f912]
    Close T38ModemMediaStream[0x7f8ae4021fb0]-Sink-T.38 for Call[C27c353f912]
    Call[C27c353f912] cleared (Remote party cleared call)</dn>

    Sep 14 00:16:04.12: [31522]: SESSION BEGIN 000000393 00123456789
    Sep 14 00:16:04.12: [31522]: HylaFAX (tm) Version 5.6.0
    Sep 14 00:16:04.12: [31522]: SEND FAX: JOB 57 DEST 00123456789 COMMID 000000393 DEVICE '/dev/ttyT380' FROM 'Hans-Peter Jansen hp@local.site' USER hp
    Sep 14 00:16:04.12: [31522]: STATE CHANGE: RUNNING -> SENDING
    Sep 14 00:16:04.12: [31522]: <-- [12:AT+FCLASS=1\r]
    Sep 14 00:16:04.12: [31522]: --> [2:OK]
    Sep 14 00:16:04.19: [31522]: DIAL 00123456789
    Sep 14 00:16:04.19: [31522]: <-- [16:ATDT00123456789\r]
    Sep 14 00:17:06.34: [31522]: --> [10:NO CARRIER]
    Sep 14 00:17:06.34: [31522]: SEND FAILED: JOB 57 DEST 00123456789 ERR No carrier detected {E002}
    Sep 14 00:17:06.34: [31522]: SEND FAILED: JOB 57 DEST 00123456789 ERR No carrier detected {E002}; too many attempts to dial
    Sep 14 00:17:07.34: [31522]: <-- [5:ATH0\r]
    Sep 14 00:17:07.34: [31522]: --> [2:OK]
    Sep 14 00:17:07.34: [31522]: MODEM set DTR OFF
    Sep 14 00:17:07.34: [31522]: MODEM set baud rate: 0 baud (flow control unchanged)
    Sep 14 00:17:07.34: [31522]: STATE CHANGE: SENDING -> MODEMWAIT (timeout 5)
    Sep 14 00:17:07.37: [31522]: SESSION END

    A receive log looks much different, but fails as well:

    t38modem -t --no-h323 -o /var/log/t38modem.log -u t38modem --sip-listen udp\$127.0.0.1:6060 --sip-t38-udptl-redundancy 3 --ptty +/dev/ttyT380,+/dev/ttyT381,+/dev/ttyT382 --route "modem:.=sip:<dn>@127.0.0.1" --route "sip:.</dn>=modem:<dn>" --force-fax-mode --force-fax-mode-delay 0
    T38Modem Version 3.15.3
    (OPAL-3.10.15/3.10.15 (svn:30298), PTLIB-2.10.15/2.10.15 (svn:30295)) by Frolov,Holtschneider,Davidson on Unix Linux (4.12.14-lp150.12.16-default-x86_64)</dn>

    T38Modem pid: 1747 ppid: 10067
    Disabled H.323 protocol
    Waiting for incoming SIP calls from udp$127.0.0.1:6060
    Route table:
    modem:.=sip:<dn>@127.0.0.1
    sip:.</dn>    =modem:<dn>
    Call[C4065d5ca1] from sip:98@127.0.0.1:6060 to sip:98@127.0.0.1:6060, route to modem:98
    Open AudioModemMediaStream[0x7f312800f300]-Source-PCM-16 for Call[C4065d5ca1]
    Open OpalRTPMediaStream[0x7f31280066d0]-Sink-G.711-uLaw-64k for Call[C4065d5ca1]
    Open OpalRTPMediaStream[0x7f3128014320]-Source-G.711-uLaw-64k for Call[C4065d5ca1]
    Open AudioModemMediaStream[0x7f31280146b0]-Sink-PCM-16 for Call[C4065d5ca1]
    Close AudioModemMediaStream[0x7f312800f300]-Source-PCM-16 for Call[C4065d5ca1]
    Close OpalRTPMediaStream[0x7f31280066d0]-Sink-G.711-uLaw-64k for Call[C4065d5ca1]
    Close OpalRTPMediaStream[0x7f3128014320]-Source-G.711-uLaw-64k for Call[C4065d5ca1]
    Close AudioModemMediaStream[0x7f31280146b0]-Sink-PCM-16 for Call[C4065d5ca1]
    Open OpalRTPMediaStream[0x7f3128014b20]-Source-T.38 for Call[C4065d5ca1]
    Open T38ModemMediaStream[0x7f312800fca0]-Source-T.38 for Call[C4065d5ca1]
    Open OpalRTPMediaStream[0x7f311000cba0]-Sink-T.38 for Call[C4065d5ca1]
    Open T38ModemMediaStream[0x7f3110012c20]-Sink-T.38 for Call[C4065d5ca1]
    Close T38ModemMediaStream[0x7f312800fca0]-Source-T.38 for Call[C4065d5ca1]
    Close OpalRTPMediaStream[0x7f311000cba0]-Sink-T.38 for Call[C4065d5ca1]
    Close OpalRTPMediaStream[0x7f3128014b20]-Source-T.38 for Call[C4065d5ca1]
    Close T38ModemMediaStream[0x7f3110012c20]-Sink-T.38 for Call[C4065d5ca1]
    Open OpalRTPMediaStream[0x7f3110013360]-Source-T.38 for Call[C4065d5ca1]
    Open T38ModemMediaStream[0x7f311000cf30]-Sink-T.38 for Call[C4065d5ca1]
    Open T38ModemMediaStream[0x7f311401b850]-Source-T.38 for Call[C4065d5ca1]
    Open OpalRTPMediaStream[0x7f311401bbe0]-Sink-T.38 for Call[C4065d5ca1]
    Close T38ModemMediaStream[0x7f311401b850]-Source-T.38 for Call[C4065d5ca1]
    Close OpalRTPMediaStream[0x7f311401bbe0]-Sink-T.38 for Call[C4065d5ca1]
    Close OpalRTPMediaStream[0x7f3110013360]-Source-T.38 for Call[C4065d5ca1]
    Close T38ModemMediaStream[0x7f311000cf30]-Sink-T.38 for Call[C4065d5ca1]
    Open T38ModemMediaStream[0x7f3114019270]-Source-T.38 for Call[C4065d5ca1]
    Open OpalRTPMediaStream[0x7f311401bf70]-Sink-G.711-uLaw-64k for Call[C4065d5ca1]
    Open OpalRTPMediaStream[0x7f3114026170]-Source-G.711-uLaw-64k for Call[C4065d5ca1]
    Open T38ModemMediaStream[0x7f311402b3f0]-Sink-T.38 for Call[C4065d5ca1]
    Close OpalRTPMediaStream[0x7f311401bf70]-Sink-G.711-uLaw-64k for Call[C4065d5ca1]
    Close T38ModemMediaStream[0x7f3114019270]-Source-T.38 for Call[C4065d5ca1]
    Close OpalRTPMediaStream[0x7f3114026170]-Source-G.711-uLaw-64k for Call[C4065d5ca1]
    Close T38ModemMediaStream[0x7f311402b3f0]-Sink-T.38 for Call[C4065d5ca1]
    Call[C4065d5ca1] cleared (Remote party cleared call)</dn>

    Sep 14 01:01:51.40: [ 1767]: SESSION BEGIN 000000398 +4998765432100
    Sep 14 01:01:51.40: [ 1767]: HylaFAX (tm) Version 5.6.0
    Sep 14 01:01:51.40: [ 1767]: <-- [4:ATA\r]
    Sep 14 01:01:55.57: [ 1767]: --> [7:CONNECT]
    Sep 14 01:01:55.57: [ 1767]: ANSWER: FAX CONNECTION DEVICE '/dev/ttyT380'
    Sep 14 01:01:55.57: [ 1767]: STATE CHANGE: ANSWERING -> RECEIVING
    Sep 14 01:01:55.60: [ 1767]: RECV FAX: begin
    Sep 14 01:01:55.60: [ 1767]: <-- HDLC<32:FF C0 04 B5 00 AA 12 9E 36 86 62 82 1A 04 14 2E B6 94 04 6A A6 4E CE 96 F6 76 0
    4 AC 74 6C 74 0C>
    Sep 14 01:01:55.60: [ 1767]: <-- data [32]
    Sep 14 01:01:55.60: [ 1767]: <-- data [2]
    Sep 14 01:01:57.47: [ 1767]: --> [7:CONNECT]
    Sep 14 01:01:57.47: [ 1767]: <-- HDLC<23:FF C0 02 22 04 34 76 A6 E6 76 96 42 04 34 12 46 B6 E2 04 82 CA 92 32>
    Sep 14 01:01:57.47: [ 1767]: <-- data [23]
    Sep 14 01:01:57.47: [ 1767]: <-- data [2]
    Sep 14 01:01:58.19: [ 1767]: --> [7:CONNECT]
    Sep 14 01:01:58.19: [ 1767]: <-- HDLC<13:FF C8 01 00 77 5F 23 01 FB C1 01 01 18>
    Sep 14 01:01:58.19: [ 1767]: <-- data [13]
    Sep 14 01:01:58.19: [ 1767]: <-- data [2]
    Sep 14 01:01:58.67: [ 1767]: --> [2:OK]
    Sep 14 01:01:58.68: [ 1767]: <-- [9:AT+FRH=3\r]
    Sep 14 01:02:05.68: [ 1767]: --> [0:]
    Sep 14 01:02:05.68: [ 1767]: MODEM <empty line="">
    Sep 14 01:02:05.68: [ 1767]: MODEM TIMEOUT: waiting for v.21 carrier
    Sep 14 01:02:05.68: [ 1767]: <-- data [1]
    Sep 14 01:02:05.68: [ 1767]: --> [2:OK]
    Sep 14 01:02:05.68: [ 1767]: <-- [9:AT+FRS=7\r]
    Sep 14 01:02:05.76: [ 1767]: --> [2:OK]
    Sep 14 01:02:05.76: [ 1767]: <-- [9:AT+FTH=3\r]
    Sep 14 01:02:05.76: [ 1767]: --> [7:CONNECT]
    Sep 14 01:02:05.76: [ 1767]: <-- HDLC<32:FF C0 04 B5 00 AA 12 9E 36 86 62 82 1A 04 14 2E B6 94 04 6A A6 4E CE 96 F6 76 0
    4 AC 74 6C 74 0C>
    Sep 14 01:02:05.76: [ 1767]: <-- data [32]
    Sep 14 01:02:05.76: [ 1767]: <-- data [2]
    Sep 14 01:02:07.55: [ 1767]: --> [7:CONNECT]
    Sep 14 01:02:07.55: [ 1767]: <-- HDLC<23:FF C0 02 22 04 34 76 A6 E6 76 96 42 04 34 12 46 B6 E2 04 82 CA 92 32>
    Sep 14 01:02:07.55: [ 1767]: <-- data [23]
    Sep 14 01:02:07.55: [ 1767]: <-- data [2]
    Sep 14 01:02:08.27: [ 1767]: --> [7:CONNECT]
    Sep 14 01:02:08.27: [ 1767]: <-- HDLC<13:FF C8 01 00 77 5F 23 01 FB C1 01 01 18>
    Sep 14 01:02:08.27: [ 1767]: <-- data [13]
    Sep 14 01:02:08.27: [ 1767]: <-- data [2]
    Sep 14 01:02:08.75: [ 1767]: --> [2:OK]
    Sep 14 01:02:08.75: [ 1767]: <-- [9:AT+FRH=3\r]
    Sep 14 01:02:15.75: [ 1767]: --> [0:]
    Sep 14 01:02:15.75: [ 1767]: MODEM <empty line="">
    Sep 14 01:02:15.75: [ 1767]: MODEM TIMEOUT: waiting for v.21 carrier
    Sep 14 01:02:15.75: [ 1767]: <-- data [1]
    Sep 14 01:02:15.76: [ 1767]: --> [2:OK]
    Sep 14 01:02:15.76: [ 1767]: <-- [9:AT+FRS=7\r]
    Sep 14 01:02:15.83: [ 1767]: --> [2:OK]
    Sep 14 01:02:15.83: [ 1767]: <-- [9:AT+FTH=3\r]
    Sep 14 01:02:15.83: [ 1767]: --> [7:CONNECT]
    Sep 14 01:02:15.84: [ 1767]: <-- HDLC<32:FF C0 04 B5 00 AA 12 9E 36 86 62 82 1A 04 14 2E B6 94 04 6A A6 4E CE 96 F6 76 04 AC 74 6C 74 0C>
    Sep 14 01:02:15.84: [ 1767]: <-- data [32]
    Sep 14 01:02:15.84: [ 1767]: <-- data [2]
    Sep 14 01:02:17.62: [ 1767]: --> [7:CONNECT]
    Sep 14 01:02:17.62: [ 1767]: <-- HDLC<23:FF C0 02 22 04 34 76 A6 E6 76 96 42 04 34 12 46 B6 E2 04 82 CA 92 32>
    Sep 14 01:02:17.62: [ 1767]: <-- data [23]
    Sep 14 01:02:17.62: [ 1767]: <-- data [2]
    Sep 14 01:02:18.34: [ 1767]: --> [7:CONNECT]
    Sep 14 01:02:18.34: [ 1767]: <-- HDLC<13:FF C8 01 00 77 5F 23 01 FB C1 01 01 18>
    Sep 14 01:02:18.34: [ 1767]: <-- data [13]
    Sep 14 01:02:18.34: [ 1767]: <-- data [2]
    Sep 14 01:02:18.82: [ 1767]: --> [2:OK]
    Sep 14 01:02:18.82: [ 1767]: <-- [9:AT+FRH=3\r]
    Sep 14 01:02:25.82: [ 1767]: --> [0:]
    Sep 14 01:02:25.83: [ 1767]: MODEM <empty line="">
    Sep 14 01:02:25.83: [ 1767]: MODEM TIMEOUT: waiting for v.21 carrier
    Sep 14 01:02:25.83: [ 1767]: <-- data [1]
    Sep 14 01:02:25.83: [ 1767]: --> [2:OK]
    Sep 14 01:02:25.83: [ 1767]: <-- [9:AT+FRS=7\r]
    Sep 14 01:02:25.91: [ 1767]: --> [2:OK]
    Sep 14 01:02:25.91: [ 1767]: <-- [9:AT+FTH=3\r]
    Sep 14 01:02:25.91: [ 1767]: --> [7:CONNECT]
    Sep 14 01:02:25.91: [ 1767]: <-- HDLC<32:FF C0 04 B5 00 AA 12 9E 36 86 62 82 1A 04 14 2E B6 94 04 6A A6 4E CE 96 F6 76 04 AC 74 6C 74 0C>
    Sep 14 01:02:25.91: [ 1767]: <-- data [32]
    Sep 14 01:02:25.91: [ 1767]: <-- data [2]
    Sep 14 01:02:27.69: [ 1767]: --> [7:CONNECT]
    Sep 14 01:02:27.69: [ 1767]: <-- HDLC<23:FF C0 02 22 04 34 76 A6 E6 76 96 42 04 34 12 46 B6 E2 04 82 CA 92 32>
    Sep 14 01:02:27.69: [ 1767]: <-- data [23]
    Sep 14 01:02:27.69: [ 1767]: <-- data [2]
    Sep 14 01:02:28.41: [ 1767]: --> [7:CONNECT]
    Sep 14 01:02:28.41: [ 1767]: <-- HDLC<13:FF C8 01 00 77 5F 23 01 FB C1 01 01 18>
    Sep 14 01:02:28.41: [ 1767]: <-- data [13]
    Sep 14 01:02:28.41: [ 1767]: <-- data [2]
    Sep 14 01:02:28.90: [ 1767]: --> [2:OK]
    Sep 14 01:02:28.90: [ 1767]: <-- [9:AT+FRH=3\r]
    Sep 14 01:02:35.90: [ 1767]: --> [0:]
    Sep 14 01:02:35.90: [ 1767]: MODEM <empty line="">
    Sep 14 01:02:35.90: [ 1767]: MODEM TIMEOUT: waiting for v.21 carrier
    Sep 14 01:02:35.90: [ 1767]: <-- data [1]
    Sep 14 01:02:35.90: [ 1767]: --> [2:OK]
    Sep 14 01:02:35.90: [ 1767]: RECV FAX: No sender protocol (T.30 T1 timeout) {E102}
    Sep 14 01:02:35.90: [ 1767]: RECV FAX: end
    Sep 14 01:02:35.90: [ 1767]: No sender protocol (T.30 T1 timeout) {E102}
    Sep 14 01:02:35.90: [ 1767]: <-- [5:ATH0\r]
    Sep 14 01:02:35.91: [ 1767]: --> [2:OK]
    Sep 14 01:02:35.91: [ 1767]: MODEM set DTR OFF
    Sep 14 01:02:35.91: [ 1767]: MODEM set baud rate: 0 baud (flow control unchanged)
    Sep 14 01:02:35.91: [ 1767]: SESSION END</empty></empty></empty></empty>

    As far as I understand, this should work even with old T.30 connections. Doesn't it?

    Any idea, what's wrong here?

    FYI: I do build all my stuff in public, available here:
    https://build.opensuse.org/project/monitor/home:frispete:telephony:asterisk

    Thanks,
    Pete

     

  • Daniel R Keery

    Daniel R Keery - 2018-11-20

    WARNING: SUPER GUESSING HERE

    every error is caused by AT+FRH=3 which it seems as "AT+FRH=3\r"  command. It seems it has something to do with carriage return + newline \r\n. Looks like \r is being treated as \n possibly and then the \n is being seen as a new [empty] line. Not sure this would cause everything jto fail though,, although it might negate the AT+FRH command which specifcally sets the modulation for reciefved data frames to v21 channel 2 to not process. It seems this command should return a screen message in response, so it might actually be getting ignored.
https://support.usr.com/support/5637/5637-ug/ref_fax.html

    Now that there are free versions of this capability, ill be setting this up shortly. If you've already fixed it please update. If not and I get it working, I will.

    Sep 14 01:02:28.90: [ 1767]: <-- [9:AT+FRH=3\r]
    Sep 14 01:02:35.90: [ 1767]: --> [0:]
    Sep 14 01:02:35.90: [ 1767]: MODEM <empty line=""></empty>

     

Log in to post a comment.