Menu

No sender protocol (T.30 T1 timeout)

Help
2011-05-18
2013-05-28
  • Charly Burk

    Charly Burk - 2011-05-18

    Hi!

    I'm trying to use T38modem 2.0 with Hylafax and a Cisco AS5400 router to receive faxes. Most of the faxes are received ok, but randomly I receive diferent erros in Hylafax logs ( "RSPREC error/got DCN (sender abort)", "No sender protocol (T.30 T1 timeout)", "T.30 T2 timeout, expected signal not received", "Failed to properly detect high-speed data carrier.", "V.21 signal reception timeout; expected page possibly not received in full").

    The most repetitive error is "No sender protocol (T.30 T1 timeout)", I can see this error in the 10% of the received calls, and I think are so many errors to put the system in a production environment.

    I will apreciate if somebody can help me ¿maybe I have some error in my config or in t38 command line?

    Sorry for my bad english

    My command line of t38modem is like this:

    /usr/local/bin/t38modem -o /var/log/t38modem_1.log -ports rtp:32002-42000 -no-h323 -sip-audio G.711-ALaw-64k -sip-listen udp\$*:5060 -route "modem:.*=sip:<dn>@SIP_GATEWAY" -route "sip:.*=modem:<dn>" -p +/dev/ttyT100,+/dev/ttyT101,+/dev/ttyT102,+/dev/ttyT103,+/dev/ttyT104,+/dev/ttyT105,+/dev/ttyT106,+/dev/ttyT107,+/dev/ttyT108,+/dev/ttyT109,+/dev/ttyT110,+/dev/ttyT111,+/dev/ttyT112,+/dev/ttyT113,+/dev/ttyT114,+/dev/ttyT115,+/dev/ttyT116,+/dev/ttyT117,+/dev/ttyT118,+/dev/ttyT119,+/dev/ttyT120,+/dev/ttyT121,+/dev/ttyT122,+/dev/ttyT123,+/dev/ttyT124,+/dev/ttyT125,+/dev/ttyT126,+/dev/ttyT127,+/dev/ttyT128,+/dev/ttyT129,+/dev/ttyT130,+/dev/ttyT131,+/dev/ttyT132,+/dev/ttyT133,+/dev/ttyT134,+/dev/ttyT135,+/dev/ttyT136,+/dev/ttyT137,+/dev/ttyT138,+/dev/ttyT139,+/dev/ttyT140,+/dev/ttyT141,+/dev/ttyT142,+/dev/ttyT143,+/dev/ttyT144

    In CiscoAs5400:
    voice service voip
    fax protocol t38 ls-redundancy 1 hs-redundancy 1 fallback pass-through g711alaw

    dial-peer voice 1050 voip
    destination-pattern HIDDEN_FOR_PRIVACY
    voice-class codec 1
    session protocol sipv2
    session target ipv4:HIDDEN_FOR_PRIVACY
    dtmf-relay h245-signal
    fax rate 14400
    fax protocol t38 ls-redundancy 0 hs-redundancy 0 fallback pass-through g711alaw
    no vad

    in Hylafax logs I can see:

    xferfaxlog:
    05/18/11 17:21  CALL    000009568       ttyT107         ""      fax     "5505933"       ""      0       0       0:00:45 0:00:45 "No sender protocol (T.30 T1 timeout)"  "number_hidden_for_privacy@SIP_GATEWAY"       "number_hidden_for_privacy"     "number_hidden_for_privacy"     ""      ""

    Complete Hylafax log:
    May 18 12:03:18.88: : SESSION BEGIN 000009418 HIDDEN_FOR_PRIVACY
    May 18 12:03:18.88: : HylaFAX ™ Version 6.0.5
    May 18 12:03:18.88: : CallID: "HIDDEN_FOR_PRIVACY" "HIDDEN_FOR_PRIVACY@HIDDEN_FOR_PRIVACY" "HIDDEN_FOR_PRIVACY"
    May 18 12:03:18.88: : DynamicConfig: bin/dynconf.php "/dev/ttyT132" "HIDDEN_FOR_PRIVACY" "HIDDEN_FOR_PRIVACY@HIDDEN_FOR_PRIVACY" "HIDDEN_FOR_PRIVACY"
    May 18 12:03:19.08: : <-
    May 18 12:03:23.23: : ->
    May 18 12:03:23.23: : ANSWER: FAX CONNECTION  DEVICE '/dev/ttyT132'
    May 18 12:03:23.23: : RECV FAX: begin
    May 18 12:03:23.24: : <- data
    May 18 12:03:23.24: : <- data
    May 18 12:03:25.13: : ->
    May 18 12:03:25.13: : <- data
    May 18 12:03:25.13: : <- data
    May 18 12:03:25.85: : ->
    May 18 12:03:25.85: : <- data
    May 18 12:03:25.85: : <- data
    May 18 12:03:26.33: : ->
    May 18 12:03:26.33: : <-
    May 18 12:03:29.74: : ->
    May 18 12:03:32.08: : ->
    May 18 12:03:32.08: : RECV recv CRP (command repeat)
    May 18 12:03:32.08: : <-
    May 18 12:03:32.09: : ->
    May 18 12:03:32.09: : <- data
    May 18 12:03:32.09: : <- data
    May 18 12:03:33.93: : ->
    May 18 12:03:33.93: : <- data
    May 18 12:03:33.93: : <- data
    May 18 12:03:34.65: : ->
    May 18 12:03:34.65: : <- data
    May 18 12:03:34.65: : <- data
    May 18 12:03:35.13: : ->
    May 18 12:03:35.13: : <-
    May 18 12:03:38.54: : ->
    May 18 12:03:40.89: : ->
    May 18 12:03:40.89: : RECV recv CRP (command repeat)
    May 18 12:03:40.89: : <-
    May 18 12:03:40.90: : ->
    May 18 12:03:40.90: : <- data
    May 18 12:03:40.90: : <- data
    May 18 12:03:42.71: : ->
    May 18 12:03:42.71: : <- data
    May 18 12:03:42.71: : <- data
    May 18 12:03:43.43: : ->
    May 18 12:03:43.43: : <- data
    May 18 12:03:43.43: : <- data
    May 18 12:03:43.91: : ->
    May 18 12:03:43.91: : <-
    May 18 12:03:47.31: : ->
    May 18 12:03:49.67: : ->
    May 18 12:03:49.67: : RECV recv CRP (command repeat)
    May 18 12:03:49.67: : <-
    May 18 12:03:49.67: : ->
    May 18 12:03:49.67: : <- data
    May 18 12:03:49.67: : <- data
    May 18 12:03:51.51: : ->
    May 18 12:03:51.51: : <- data
    May 18 12:03:51.51: : <- data
    May 18 12:03:52.23: : ->
    May 18 12:03:52.23: : <- data
    May 18 12:03:52.23: : <- data
    May 18 12:03:52.71: : ->
    May 18 12:03:52.71: : <-
    May 18 12:03:56.12: : ->
    May 18 12:03:58.46: : ->
    May 18 12:03:58.46: : RECV recv CRP (command repeat)
    May 18 12:03:58.46: : <-
    May 18 12:03:58.47: : ->
    May 18 12:03:58.47: : <- data
    May 18 12:03:58.47: : <- data
    May 18 12:04:00.31: : ->
    May 18 12:04:00.31: : <- data
    May 18 12:04:00.31: : <- data
    May 18 12:04:01.03: : ->
    May 18 12:04:01.03: : <- data
    May 18 12:04:01.03: : <- data
    May 18 12:04:01.51: : ->
    May 18 12:04:01.51: : <-
    May 18 12:04:04.91: : ->
    May 18 12:04:07.27: : ->
    May 18 12:04:07.27: : RECV recv CRP (command repeat)
    May 18 12:04:07.27: : RECV FAX: No sender protocol (T.30 T1 timeout)
    May 18 12:04:07.27: : RECV FAX: end
    May 18 12:04:07.27: : No sender protocol (T.30 T1 timeout)
    May 18 12:04:07.27: : SESSION END

    Hylafax modem config:
    # $Id$
    #
    # HylaFAX configuration for a T38FAX Pseudo Modem
    #
    # This file was originally sourced with permission from
    # Vyacheslav Frolov's t38modem software in OpenH323 package.
    #

    #
    CountryCode:            34
    AreaCode:               HIDDEN_FOR_PRIVACY
    FAXNumber:              HIDDEN_FOR_PRIVACY
    LongDistancePrefix:     0
    InternationalPrefix:    00
    DialStringRules:        etc/dialrules
    ServerTracing:          1
    SessionTracing:         11
    RecvFileMode:           0600
    LogFileMode:            0600
    DeviceMode:             0600
    RingsBeforeAnswer:      2
    SpeakerVolume:          off
    GettyArgs:              "-h %l dx_%s"
    LocalIdentifier:        "NothingSetup"
    TagLineFont:            etc/lutRS18.pcf
    TagLineFormat:          "From %%l|%c|Page %%P of %%T"
    MaxRecvPages:           300
    #

    ModemType:              Class1          # use class 1 interface
    ModemFlowControl:       rtscts          # default

    ModemRevQueryCmd:       AT+FREV?

    #
    # If you're using a version earlier than 0.7.0 enable this.
    #
    #Class1FrameOverhead:   2               # does not include FCS

    #
    # AT#CID=10 enables ANI/DNIS reporting between the
    # first and second RINGs in the form:
    #
    #   RING
    #   NMBR = <calling number>
    #   NDID = <called number>
    #   RING
    #
    ModemResetCmds: "AT#CID=10"     # enable ANI/DNIS reporting
    RingsBeforeAnswer:      2               # collect info between two RINGs
    CallIDPattern:          "NMBR = "       # pattern string for calling number
    CallIDPattern:          "NAME = "       # pattern string for name of remote (not supported)
    CallIDPattern:          "NDID = "       # pattern string for called number

    #
    # T.38 dial modifiers
    #
    # F - enable T.38 mode request after dialing
    # V - disable T.38 mode request after dialing (remote host should do it)
    #
    # calling/called number dial modifiers
    #
    # L - reset and begin of calling number
    # D - continue of called number
    #
    #ModemDialCmd:          ATDF%s          # user can override F by dial V
    #ModemDialCmd:          ATDV%s          # user can override V by dial F
    #ModemDialCmd:          ATD%sF          # user can't override F
    #ModemDialCmd:          ATD%sV          # user can't override V
    #ModemDialCmd:          ATD%sVL         # user can't override V or calling number
    ModemDialCmd:           ATDLHIDDEN_FOR_PRIVACYT%s

    #
    ## AvantFAX
    #
    FaxRcvdCmd:     bin/faxrcvd.php
    DynamicConfig:  bin/dynconf.php
    UseJobTSI:      true

     
  • Vyacheslav Frolov

    The t38modem sends HDLC frames to the remote and the remote says that received frames were corrupted (fax machine or Cisco sends CRP). If it's because the IP network problem (packet lost) then you can try -sip-t38-udptl-redundancy option.

    > in Hylafax logs I can see:

    The Hylafax logs are not helpful. The trace level 4 (-tttt) of t38modem is required.

     
  • Charly Burk

    Charly Burk - 2011-05-19

    Thanks for your reply Vyacheslav,

    I have now a full debug (tttt) for a failured fax but is it a little big file to post it here (176K) and has some private info (DIDs and private IPs only). May I send it to you in a private message?

    I post here the last part of the file, please tell me  if more info can be helpfull:

    2011/05/19 13:47:45.793    OnRelease:0xb35cbb70 ModemEngineBody::OnEngineCallback T38Engine cbpUpdateState (6, stRecv)
    2011/05/19 13:47:45.793    OnRelease:0xb35cbb70 Media   Closing stream T38ModemMediaStream-Source-T.38
    2011/05/19 13:47:45.793  Media Patch:0xb3710b70 Patch   Thread ended because source read failed
    2011/05/19 13:47:45.793  Media Patch:0xb3710b70 Patch   Thread ended for Patch T38ModemMediaStream-Source-T.38
    2011/05/19 13:47:45.793    OnRelease:0xb35cbb70 Media   Disconnecting T38ModemMediaStream-Source-T.38 from patch thread Patch T38ModemMediaStream-Source-T.38
    2011/05/19 13:47:45.793    OnRelease:0xb35cbb70 Patch   Closing media patch Patch T38ModemMediaStream-Source-T.38
    2011/05/19 13:47:45.793    OnRelease:0xb35cbb70 Patch   Setting media patch bypass to 0 on Patch T38ModemMediaStream-Source-T.38
    2011/05/19 13:47:45.793    OnRelease:0xb35cbb70 Patch   Waiting for media patch thread to stop Patch T38ModemMediaStream-Source-T.38
    2011/05/19 13:47:45.793  Media Patch:0xb3710b70 PTLib   Thread ended: name="Media Patch:0xb3710b70", real=10.525, kernel=0.000 (0%), user=0.020 (0.1%), both=0.020 (0.1%)
    2011/05/19 13:47:45.804    OnRelease:0xb35cbb70 OpalCon Removed media stream T38ModemMediaStream-Source-T.38
    2011/05/19 13:47:45.804    OnRelease:0xb35cbb70 OpalCon Media streams closed.
    2011/05/19 13:47:45.804    OnRelease:0xb35cbb70 OpalCon SetPhase from ReleasingPhase to ReleasedPhase for Call-EP<sip>
    2011/05/19 13:47:45.804    OnRelease:0xb35cbb70 OpalCon OnReleased Call-EP<sip>
    2011/05/19 13:47:45.804    OnRelease:0xb35cbb70 OpalEP  OnReleased Call-EP<sip>
    2011/05/19 13:47:45.804    OnRelease:0xb35cbb70 OpalMan OnReleased Call-EP<sip>
    2011/05/19 13:47:45.804    OnRelease:0xb35cbb70 Call    OnReleased Call-EP<sip>
    2011/05/19 13:47:45.804    OnRelease:0xb35cbb70 OpalCon SetPhase from EstablishedPhase to ReleasingPhase for Call-EP<modem>
    2011/05/19 13:47:45.804    OnRelease:0xb35cbb70 OpalCon Releasing Call-EP<modem>
    2011/05/19 13:47:45.804    OnRelease:0xb35cbb70 OpalCon Call end reason for Call-EP<modem> set to EndedByRemoteUser
    2011/05/19 13:47:45.804    OnRelease:0xb35cbb70 ModemConnection::OnReleased Call-EP<modem>
    2011/05/19 13:47:45.804    OnRelease:0xb35cbb70 OpalCon OnReleased Call-EP<modem>
    :

    2011/05/19 13:47:45.804    OnRelease:0xb35cbb70 OpalEP  OnReleased Call-EP<modem>
    2011/05/19 13:47:45.804    OnRelease:0xb35cbb70 OpalMan OnReleased Call-EP<modem>
    2011/05/19 13:47:45.804    OnRelease:0xb35cbb70 Call    OnReleased Call-EP<modem>
    2011/05/19 13:47:45.804    OnRelease:0xb35cbb70 Call cleared (EndedByRemoteUser)
    2011/05/19 13:47:45.804    OnRelease:0xb35cbb70 OpalMan OnClearedCall Call from "sip:HIDDEN_FOR_PRIVACY" to "modem:HIDDEN_FOR_PRIVACY"
    2011/05/19 13:47:45.804    OnRelease:0xb35cbb70 OpalCon Media streams closed.
    2011/05/19 13:47:45.804    OnRelease:0xb35cbb70 OpalCon Media streams closed.
    2011/05/19 13:47:45.805    OnRelease:0xb35cbb70 Opal    Transport clean up on termination
    2011/05/19 13:47:45.805    OnRelease:0xb35cbb70 Opal    Transport Close
    2011/05/19 13:47:45.805    OnRelease:0xb35cbb70 Opal    Transport clean up on termination
    2011/05/19 13:47:45.805    OnRelease:0xb35cbb70 Opal    Transport Close
    2011/05/19 13:47:45.805    OnRelease:0xb35cbb70 Opal    Deleted transport udp$HIDDEN_FOR_PRIVACY:49799<if=udp$HIDDEN_FOR_PRIVACY:5060>
    2011/05/19 13:47:45.805    OnRelease:0xb35cbb70 OpalCon OnRelease thread completed for Call-EP<sip>
    2011/05/19 13:47:45.805    OnRelease:0xb35cbb70 PTLib   Thread ended: name="OnRelease:0xb35cbb70", real=0.015, kernel=0.000 (0%), user=0.000 (0%), both=0.000 (0%)
    2011/05/19 13:47:46.064 Opal Garbage:0xb6a8cb70 ModemConnection::~ModemConnection Call-EP<modem> EndedByRemoteUser
    2011/05/19 13:47:46.064 Opal Garbage:0xb6a8cb70 PseudoModemQ::Enqueue ttyT138
    2011/05/19 13:47:46.064 Opal Garbage:0xb6a8cb70 ModemEngineBody::Request: stRecv request={
    calltoken=modem:HIDDEN_FOR_PRIVACY/C8877339c219/0
    command=clearcall
    }
    2011/05/19 13:47:46.064 Opal Garbage:0xb6a8cb70 ModemEngineBody::SetCallState: off-hook cstReleasing.0 stRecv
    2011/05/19 13:47:46.064 Opal Garbage:0xb6a8cb70 ModemEngineBody::OnTimerCallback stRecv Timeout 1
    2011/05/19 13:47:46.064 Opal Garbage:0xb6a8cb70 ttyT138 AudioEngine RecvOnIdle dtBusy
    2011/05/19 13:47:46.064 ttyT138(e)…0xb3eefb70 ModemEngineBody::SetCallSubState: off-hook cstReleasing.1 stRecv
    2011/05/19 13:47:46.064 Opal Garbage:0xb6a8cb70 OpalCon Connection Call-EP<modem> destroyed.
    2011/05/19 13:47:46.064 ttyT138(e)…0xb3eefb70 ttyT138 T38Engine EnableFakeIn: enable
    2011/05/19 13:47:46.064 ttyT138(e)…0xb3eefb70 ttyT138 T38Engine OnChangeEnableFakeIn modStreamIn->lastBuf != NULL
    2011/05/19 13:47:46.064 Opal Garbage:0xb6a8cb70 SIP     Deleted connection.
    2011/05/19 13:47:46.064 ttyT138(e)…0xb3eefb70 ModemEngineBody::OnEngineCallback T38Engine cbp6 (6, stRecv)
    2011/05/19 13:47:46.064 ttyT138(e)…0xb3eefb70 <- v21frame too short {
    }
    2011/05/19 13:47:46.064 ttyT138(e)…0xb3eefb70 ModemEngineBody::SetState: off-hook cstReleasing.1 stCommand
    2011/05/19 13:47:46.064 Opal Garbage:0xb6a8cb70 RTP     Closing session 1
    2011/05/19 13:47:46.065 ttyT138(e)…0xb3eefb70 <-  {
      0d 0a 4e 4f 20 43 41 52  52 49 45 52 0d 0a         ..NO CARRIER.. }
    2011/05/19 13:47:46.065 Opal Garbage:0xb6a8cb70 RTP     Deleting session 1
    2011/05/19 13:47:46.065 ttyT138(e)…0xb3eefb70 ttyT138 T38Engine EnableFakeIn: disable
    2011/05/19 13:47:46.065 Opal Garbage:0xb6a8cb70 RTP_UDP Session 1, read already shut down .
    2011/05/19 13:47:46.065 Opal Garbage:0xb6a8cb70 RTP_UDP Session 1, read already shut down .
    2011/05/19 13:47:46.065 Opal Garbage:0xb6a8cb70 RTP_UDP Session 1, write already shut down .
    2011/05/19 13:47:46.065 Opal Garbage:0xb6a8cb70 RTP     Session 1, final statistics:
        packetsSent        = 77
        octetsSent         = 425
        averageSendTime    = 0
        maximumSendTime    = 0
        minimumSendTime    = 0
        packetsLostByRemote= 0
        jitterLevelOnRemote= 0
        packetsReceived    = 5
        octetsReceived     = 5
        packetsLost        = 0
        packetsTooLate     = 0
        packetOverruns     = 0
        packetsOutOfOrder  = 118
        averageReceiveTime = 0
        maximumReceiveTime = 0
        minimumReceiveTime = 0
        averageJitter      = 1074
        maximumJitter      = 1074
    2011/05/19 13:47:46.065 Opal Garbage:0xb6a8cb70 OpalCon Connection Call-EP<sip> destroyed.

     

Log in to post a comment.