Solved: Re: Issues with new fax server

kylebrogers · ‎06-27-2018

So this all started when the customer changed fax server companies (on prem server). We had no issues with the old one. This one is having intermittent issues.

Diagram:
PRI --- Cisco H323 VGW -- CUCM 10.x -- VoIP-based Fax server (T.38)

So it's an H323 gateway, but CUCM is involved because we're using route patterns to direct fax calls instead of dial peers. There are a lot of fax numbers and they're not contiguous so it's a lot easier to deal with them this way than to use dial peers on the gateway for the fax numbers.

The issues are intermittent and inconsistent, so testing is a problem. In the end, I turned on some debugs on the gateway and pointed it to a syslog server. That way I could coordinate errors in the fax server to errors in the debugs.

The output below is a call that was incomplete according to the fax server. I have pasted more below, but I believe the issue is in these lines:
====================================
2018-05-08 08:12:25 Local7.Debug 10.14.114.10 648047: May 8 08:11:48 CDT: 0/0/0:23 744416714 fr-entered=10(ms)
2018-05-08 08:12:27 Local7.Debug 10.14.114.10 648048:
2018-05-08 08:12:27 Local7.Debug 10.14.114.10 648049: timestamp=744419342 fr-msg-tx DIS
2018-05-08 08:12:31 Local7.Debug 10.14.114.10 648050:
2018-05-08 08:12:31 Local7.Debug 10.14.114.10 648051: timestamp=744423032 FR_BAD_CRC_LS_DATA 0x0 bytes
2018-05-08 08:12:31 Local7.Debug 10.14.114.10 648052: timestamp=744423032 fr-msg-tx bad crc, 0 bytes
2018-05-08 08:12:33 Local7.Debug 10.14.114.10 648053:
2018-05-08 08:12:33 Local7.Debug 10.14.114.10 648054: timestamp=744425652 fr-msg-tx DIS
2018-05-08 08:12:33 Local7.Debug 10.14.114.10 648055: May 8 08:11:58 CDT: ISDN Se0/0/0:23 Q931: RX <- DISCONNECT pd = 8 callref = 0x25F3
2018-05-08 08:12:33 Local7.Debug 10.14.114.10 648056: Cause i = 0x8290 - Normal call clearing
2018-05-08 08:12:33 Local7.Debug 10.14.114.10 648057: May 8 08:11:58 CDT: ISDN Se0/0/0:23 Q931: TX -> RELEASE pd = 8 callref = 0xA5F3
==============================================

It looks like we're seeing CRC issues. I've checked the interface counters on the gateway for the interface that H.323 is bound to and there are no errors (aside from some unknown protocol drops) so I don't believe that the network is causing issues. Do these CRC errors in this log indicate that the gateway received a packet from the fax server but that the CRC of the data portion of the packet did not pass the CRC check? Or does it mean something else? Any thoughts on what might cause this? I've read several threads where this error is mentioned but I don't see any clear indicator of the cause.

++++++++++++
Longer Debug
++++++++++++

2018-05-08 08:12:20 Local7.Debug 10.14.114.10 647904: May 8 08:11:45 CDT: ISDN Se0/0/0:23 Q931: TX -> CALL_PROC pd = 8 callref = 0xA5F6
2018-05-08 08:12:20 Local7.Debug 10.14.114.10 647905: Channel ID i = 0xA98382
2018-05-08 08:12:20 Local7.Debug 10.14.114.10 647906: Exclusive, Channel 2
2018-05-08 08:12:20 Local7.Debug 10.14.114.10 647907: May 8 08:11:45 CDT: //28402/315AFE1CA578/CCAPI/cc_api_set_called_ccm_detected:
2018-05-08 08:12:20 Local7.Debug 10.14.114.10 647908:
2018-05-08 08:12:20 Local7.Debug 10.14.114.10 647909: CallInfo(called ccm detected=TRUE ccmVersion 3)
2018-05-08 08:12:20 Local7.Debug 10.14.114.10 647910: May 8 08:11:45 CDT: //28402/315AFE1CA578/CCAPI/cc_api_call_proceeding:
2018-05-08 08:12:20 Local7.Debug 10.14.114.10 647911: Interface=0x225ECF4C, Progress Indication=NULL(0)
2018-05-08 08:12:20 Local7.Debug 10.14.114.10 647912: May 8 08:11:45 CDT: //28402/315AFE1CA578/CCAPI/cc_api_set_called_ccm_detected:
2018-05-08 08:12:20 Local7.Debug 10.14.114.10 647913: CallInfo(called ccm detected=TRUE ccmVersion 3)
2018-05-08 08:12:20 Local7.Debug 10.14.114.10 647914: May 8 08:11:45 CDT: //28402/315AFE1CA578/CCAPI/cc_api_set_delay_xport:
2018-05-08 08:12:20 Local7.Debug 10.14.114.10 647915: CallInfo(delay xport=TRUE)
2018-05-08 08:12:20 Local7.Debug 10.14.114.10 647916: May 8 08:11:45 CDT: //28402/315AFE1CA578/CCAPI/cc_api_call_alert:
2018-05-08 08:12:20 Local7.Debug 10.14.114.10 647917: Interface=0x225ECF4C, Progress Indication=NULL(0), Signal Indication=SIGNAL RINGBACK(1)
2018-05-08 08:12:20 Local7.Debug 10.14.114.10 647918: May 8 08:11:45 CDT: //28402/315AFE1CA578/CCAPI/cc_api_call_alert:
2018-05-08 08:12:20 Local7.Debug 10.14.114.10 647919: Call Entry(Retry Count=0, Responsed=TRUE)
2018-05-08 08:12:20 Local7.Debug 10.14.114.10 647920: May 8 08:11:45 CDT: //28402/315AFE1CA578/CCAPI/cc_api_set_called_ccm_detected:
2018-05-08 08:12:20 Local7.Debug 10.14.114.10 647921: CallInfo(called ccm detected=TRUE ccmVersion 3)
2018-05-08 08:12:20 Local7.Debug 10.14.114.10 647922: May 8 08:11:45 CDT: //28402/315AFE1CA578/CCAPI/cc_api_call_notify:
2018-05-08 08:12:20 Local7.Debug 10.14.114.10 647923: Data Bitmask=0x5, Interface=0x225ECF4C, Call Id=28402
2018-05-08 08:12:20 Local7.Debug 10.14.114.10 647924: May 8 08:11:45 CDT: //28401/315AFE1CA578/CCAPI/ccCallAlert:
2018-05-08 08:12:20 Local7.Debug 10.14.114.10 647925: Progress Indication=NULL(0), Signal Indication=SIGNAL RINGBACK(1)
2018-05-08 08:12:20 Local7.Debug 10.14.114.10 647926: May 8 08:11:45 CDT: //28401/315AFE1CA578/CCAPI/ccCallAlert:
2018-05-08 08:12:20 Local7.Debug 10.14.114.10 647927: Call Entry(Responsed=TRUE, Alert Sent=TRUE)
2018-05-08 08:12:20 Local7.Debug 10.14.114.10 647928: May 8 08:11:45 CDT: //28401/315AFE1CA578/CCAPI/ccGenerateToneInfo:
2018-05-08 08:12:20 Local7.Debug 10.14.114.10 647929: Stop Tone On Digit=FALSE, Tone=Ring Back,
2018-05-08 08:12:20 Local7.Debug 10.14.114.10 647930: Tone Direction=Network, Params=0x0, Call Id=28401
2018-05-08 08:12:20 Local7.Debug 10.14.114.10 647931: May 8 08:11:45 CDT: ISDN Se0/0/0:23 Q931: TX -> ALERTING pd = 8 callref = 0xA5F6
2018-05-08 08:12:20 Local7.Debug 10.14.114.10 647932: Progress Ind i = 0x8188 - In-band info or appropriate now available
2018-05-08 08:12:20 Local7.Debug 10.14.114.10 647933: May 8 08:11:45 CDT: //28402/315AFE1CA578/CCAPI/cc_api_get_ssCTreRoutingNotSupported:
2018-05-08 08:12:20 Local7.Debug 10.14.114.10 647934: CallInfo(ssCTreRoutingNotSupported=FALSE)
2018-05-08 08:12:20 Local7.Debug 10.14.114.10 647935: May 8 08:11:45 CDT: //28402/315AFE1CA578/CCAPI/cc_api_get_ccm_detected:
2018-05-08 08:12:20 Local7.Debug 10.14.114.10 647936: CallInfo(ccm detected=TRUE)
2018-05-08 08:12:20 Local7.Debug 10.14.114.10 647937: May 8 08:11:45 CDT: //28401/315AFE1CA578/CCAPI/ccCallNotify:
2018-05-08 08:12:20 Local7.Debug 10.14.114.10 647938: Data Bitmask=0x5, Call Id=28401
2018-05-08 08:12:20 Local7.Debug 10.14.114.10 647939: May 8 08:11:45 CDT: //28402/315AFE1CA578/CCAPI/ccIsInfoRingback:
2018-05-08 08:12:20 Local7.Debug 10.14.114.10 647940: Returning dpRingBack=0
2018-05-08 08:12:20 Local7.Debug 10.14.114.10 647941: May 8 08:11:45 CDT: //28402/315AFE1CA578/CCAPI/cc_api_call_connected:
2018-05-08 08:12:20 Local7.Debug 10.14.114.10 647942:
2018-05-08 08:12:20 Local7.Debug 10.14.114.10 647943: Interface=0x225ECF4C, Data Bitmask=0x0, Progress Indication=NULL(0),
2018-05-08 08:12:20 Local7.Debug 10.14.114.10 647944: Connection Handle=0
2018-05-08 08:12:20 Local7.Debug 10.14.114.10 647945: May 8 08:11:45 CDT: //28402/315AFE1CA578/CCAPI/cc_api_call_connected:
2018-05-08 08:12:20 Local7.Debug 10.14.114.10 647946: Call Entry(Connected=TRUE, Responsed=TRUE, Retry Count=0)
2018-05-08 08:12:20 Local7.Debug 10.14.114.10 647947: May 8 08:11:45 CDT: //28402/315AFE1CA578/CCAPI/cc_api_set_called_ccm_detected:
2018-05-08 08:12:20 Local7.Debug 10.14.114.10 647948: CallInfo(called ccm detected=TRUE ccmVersion 3)
2018-05-08 08:12:20 Local7.Debug 10.14.114.10 647949: May 8 08:11:45 CDT: //28402/315AFE1CA578/CCAPI/cc_api_call_notify:
2018-05-08 08:12:20 Local7.Debug 10.14.114.10 647950: Data Bitmask=0x5, Interface=0x225ECF4C, Call Id=28402
2018-05-08 08:12:20 Local7.Debug 10.14.114.10 647951: May 8 08:11:45 CDT: //28401/315AFE1CA578/CCAPI/ccGenerateToneInfo:
2018-05-08 08:12:21 Local7.Debug 10.14.114.10 647952: Stop Tone On Digit=FALSE, Tone=Null,
2018-05-08 08:12:21 Local7.Debug 10.14.114.10 647953: Tone Direction=Network, Params=0x0, Call Id=28401
2018-05-08 08:12:21 Local7.Debug 10.14.114.10 647954: May 8 08:11:45 CDT: //28401/315AFE1CA578/CCAPI/ccConferenceCreate:
2018-05-08 08:12:21 Local7.Debug 10.14.114.10 647955: (confID=0xFFFFFFFF, callID1=0x6EF1, gcid=315AFE1C-51F811E8-A57878DA-6ED54208, tag=0x0)
2018-05-08 08:12:21 Local7.Debug 10.14.114.10 647956: May 8 08:11:45 CDT: //28402/315AFE1CA578/CCAPI/ccConferenceCreate:
2018-05-08 08:12:21 Local7.Debug 10.14.114.10 647957: (confID=0xFFFFFFFF, callID2=0x6EF2, gcid=315AFE1C-51F811E8-A57878DA-6ED54208, tag=0x0)
2018-05-08 08:12:21 Local7.Debug 10.14.114.10 647958: May 8 08:11:45 CDT: //28401/315AFE1CA578/CCAPI/ccConferenceCreate:
2018-05-08 08:12:21 Local7.Debug 10.14.114.10 647959: Conference Id=0xFFFFFFFF, Call Id1=28401, Call Id2=28402, Tag=0x0
2018-05-08 08:12:21 Local7.Debug 10.14.114.10 647960: May 8 08:11:45 CDT: //28401/315AFE1CA578/CCAPI/cc_api_bridge_done:
2018-05-08 08:12:21 Local7.Debug 10.14.114.10 647961: Conference Id=0x25E8, Source Interface=0xC24D1C64, Source Call Id=28401,
2018-05-08 08:12:21 Local7.Debug 10.14.114.10 647962: Destination Call Id=28402, Disposition=0x0, Tag=0xFFFFFFFF
2018-05-08 08:12:21 Local7.Debug 10.14.114.10 647963: May 8 08:11:45 CDT: //28402/xxxxxxxxxxxx/CCAPI/cc_api_get_xcode_stream:
2018-05-08 08:12:21 Local7.Debug 10.14.114.10 647964:
2018-05-08 08:12:21 Local7.Debug 10.14.114.10 647965: May 8 08:11:45 CDT: cc_api_get_xcode_stream : 4819
2018-05-08 08:12:21 Local7.Debug 10.14.114.10 647966: May 8 08:11:45 CDT: //28402/315AFE1CA578/CCAPI/cc_api_bridge_done:
2018-05-08 08:12:21 Local7.Debug 10.14.114.10 647967: Conference Id=0x25E8, Source Interface=0x225ECF4C, Source Call Id=28402,
2018-05-08 08:12:21 Local7.Debug 10.14.114.10 647968: Destination Call Id=28401, Disposition=0x0, Tag=0x0
2018-05-08 08:12:21 Local7.Debug 10.14.114.10 647969: May 8 08:11:45 CDT: //28401/315AFE1CA578/CCAPI/cc_generic_bridge_done:
2018-05-08 08:12:21 Local7.Debug 10.14.114.10 647970: Conference Id=0x25E8, Source Interface=0x225ECF4C, Source Call Id=28402,
2018-05-08 08:12:21 Local7.Debug 10.14.114.10 647971: Destination Call Id=28401, Disposition=0x0, Tag=0x0
2018-05-08 08:12:21 Local7.Debug 10.14.114.10 647972: May 8 08:11:45 CDT: //28401/315AFE1CA578/CCAPI/ccConferenceCreate:
2018-05-08 08:12:21 Local7.Debug 10.14.114.10 647973: Call Entry(Conference Id=0x25E8, Destination Call Id=28402)
2018-05-08 08:12:21 Local7.Debug 10.14.114.10 647974: May 8 08:11:45 CDT: //28402/315AFE1CA578/CCAPI/ccConferenceCreate:
2018-05-08 08:12:21 Local7.Debug 10.14.114.10 647975: Call Entry(Conference Id=0x25E8, Destination Call Id=28401)
2018-05-08 08:12:21 Local7.Debug 10.14.114.10 647976: May 8 08:11:45 CDT: //28401/315AFE1CA578/CCAPI/ccConferenceCreate:
2018-05-08 08:12:21 Local7.Debug 10.14.114.10 647977:
2018-05-08 08:12:21 Local7.Debug 10.14.114.10 647978: May 8 08:11:45 CDT: confID:0x25E8; callEntry1 callID1:0x6EF1, type:6; callEntry2 callID2:0x6EF2, type:1
2018-05-08 08:12:21 Local7.Debug 10.14.114.10 647979: May 8 08:11:45 CDT: //28401/315AFE1CA578/CCAPI/cc_api_caps_ind:
2018-05-08 08:12:21 Local7.Debug 10.14.114.10 647980: Destination Interface=0x225ECF4C, Destination Call Id=28402, Source Call Id=28401,
2018-05-08 08:12:21 Local7.Debug 10.14.114.10 647981: Caps(Codec=0x1, Fax Rate=0x1, Fax Version:=0, Vad=0x1,
2018-05-08 08:12:21 Local7.Debug 10.14.114.10 647982: Modem=0x2, Codec Bytes=20, Signal Type=3)
2018-05-08 08:12:21 Local7.Debug 10.14.114.10 647983: May 8 08:11:45 CDT: //28401/315AFE1CA578/CCAPI/cc_api_caps_ind:
2018-05-08 08:12:21 Local7.Debug 10.14.114.10 647984:
2018-05-08 08:12:21 Local7.Debug 10.14.114.10 647985: Caps(Playout Mode=1, Playout Initial=60(ms), Playout Min=40(ms),
2018-05-08 08:12:21 Local7.Debug 10.14.114.10 647986: Playout Max=1000(ms), Fax Nom=300(ms))
2018-05-08 08:12:21 Local7.Debug 10.14.114.10 647987: May 8 08:11:45 CDT: //28402/315AFE1CA578/CCAPI/cc_api_get_ssCTreRoutingNotSupported:
2018-05-08 08:12:21 Local7.Debug 10.14.114.10 647988: CallInfo(ssCTreRoutingNotSupported=FALSE)
2018-05-08 08:12:21 Local7.Debug 10.14.114.10 647989: May 8 08:11:45 CDT: //28402/315AFE1CA578/CCAPI/cc_api_get_ccm_detected:
2018-05-08 08:12:21 Local7.Debug 10.14.114.10 647990: CallInfo(ccm detected=TRUE)
2018-05-08 08:12:21 Local7.Debug 10.14.114.10 647991: May 8 08:11:45 CDT: //28401/315AFE1CA578/CCAPI/ccCallNotify:
2018-05-08 08:12:21 Local7.Debug 10.14.114.10 647992: Data Bitmask=0x5, Call Id=28401
2018-05-08 08:12:21 Local7.Debug 10.14.114.10 647993: May 8 08:11:45 CDT: //28401/315AFE1CA578/CCAPI/cc_process_notify_bridge_done:
2018-05-08 08:12:21 Local7.Debug 10.14.114.10 647994: Conference Id=0x25E8, Call Id1=28401, Call Id2=28402
2018-05-08 08:12:21 Local7.Debug 10.14.114.10 647995: May 8 08:11:45 CDT: //28402/315AFE1CA578/CCAPI/cc_api_caps_ind:
2018-05-08 08:12:21 Local7.Debug 10.14.114.10 647996:
2018-05-08 08:12:21 Local7.Debug 10.14.114.10 647997: Destination Interface=0xC24D1C64, Destination Call Id=28401, Source Call Id=28402,
2018-05-08 08:12:21 Local7.Debug 10.14.114.10 647998: Caps(Codec=0x1, Fax Rate=0x10, Fax Version:=0, Vad=0x1,
2018-05-08 08:12:21 Local7.Debug 10.14.114.10 647999: Modem=0x0, Codec Bytes=160, Signal Type=2)
2018-05-08 08:12:21 Local7.Debug 10.14.114.10 648000: May 8 08:11:45 CDT: //28402/315AFE1CA578/CCAPI/cc_api_caps_ind:
2018-05-08 08:12:21 Local7.Debug 10.14.114.10 648001: Caps(Playout Mode=1, Playout Initial=60(ms), Playout Min=40(ms),
2018-05-08 08:12:21 Local7.Debug 10.14.114.10 648002: Playout Max=1000(ms), Fax Nom=300(ms))
2018-05-08 08:12:21 Local7.Debug 10.14.114.10 648003: May 8 08:11:45 CDT: //28402/315AFE1CA578/CCAPI/cc_api_caps_ack:
2018-05-08 08:12:21 Local7.Debug 10.14.114.10 648004: Destination Interface=0xC24D1C64, Destination Call Id=28401, Source Call Id=28402,
2018-05-08 08:12:21 Local7.Debug 10.14.114.10 648005: Caps(Codec=g711ulaw(0x1), Fax Rate=FAX_RATE_7200(0x10), Fax Version:=0, Vad=OFF(0x1),
2018-05-08 08:12:21 Local7.Debug 10.14.114.10 648006: Modem=OFF(0x0), Codec Bytes=160, Signal Type=2, Seq Num Start=3460)
2018-05-08 08:12:21 Local7.Debug 10.14.114.10 648007: May 8 08:11:45 CDT: //28401/315AFE1CA578/CCAPI/cc_api_caps_ack:
2018-05-08 08:12:21 Local7.Debug 10.14.114.10 648008: Destination Interface=0x225ECF4C, Destination Call Id=28402, Source Call Id=28401,
2018-05-08 08:12:21 Local7.Debug 10.14.114.10 648009: Caps(Codec=g711ulaw(0x1), Fax Rate=FAX_RATE_7200(0x10), Fax Version:=0, Vad=OFF(0x1),
2018-05-08 08:12:21 Local7.Debug 10.14.114.10 648010: Modem=OFF(0x0), Codec Bytes=160, Signal Type=2, Seq Num Start=3460)
2018-05-08 08:12:21 Local7.Debug 10.14.114.10 648011: May 8 08:11:45 CDT: //28401/315AFE1CA578/CCAPI/ccCallConnect:
2018-05-08 08:12:21 Local7.Debug 10.14.114.10 648012: Progress Indication=NULL(0), Data Bitmask=0x1
2018-05-08 08:12:21 Local7.Debug 10.14.114.10 648013: May 8 08:11:45 CDT: //28401/315AFE1CA578/CCAPI/ccCallConnect:
2018-05-08 08:12:21 Local7.Debug 10.14.114.10 648014: Call Entry(Connected=TRUE, Responsed=TRUE)
2018-05-08 08:12:21 Local7.Debug 10.14.114.10 648015: May 8 08:11:45 CDT: //28401/315AFE1CA578/CCAPI/cc_api_voice_mode_event:
2018-05-08 08:12:21 Local7.Debug 10.14.114.10 648016: Call Id=28401
2018-05-08 08:12:21 Local7.Debug 10.14.114.10 648017: May 8 08:11:45 CDT: //28401/315AFE1CA578/CCAPI/cc_api_voice_mode_event:
2018-05-08 08:12:21 Local7.Debug 10.14.114.10 648018: Call Entry(Context=0x39E7AC48)
2018-05-08 08:12:21 Local7.Debug 10.14.114.10 648019: May 8 08:11:45 CDT: ISDN Se0/0/0:23 Q931: TX -> CONNECT pd = 8 callref = 0xA5F6
2018-05-08 08:12:21 Local7.Debug 10.14.114.10 648020: May 8 08:11:46 CDT: ISDN Se0/0/0:23 Q931: RX <- CONNECT_ACK pd = 8 callref = 0x25F6
2018-05-08 08:12:24 Local7.Debug 10.14.114.10 648021: May 8 08:11:48 CDT: //28402/315AFE1CA578/CCAPI/cc_api_t38_fax_start:
2018-05-08 08:12:24 Local7.Debug 10.14.114.10 648022: Destination Interface=0xC24D1C64, Destination Call Id=28401, Source Call Id=28402,
2018-05-08 08:12:24 Local7.Debug 10.14.114.10 648023: Caps(Codec=T38Fax(0x10000), Fax Rate=FAX_RATE_7200(0x10),Fax Version:=0, Vad=OFF(0x1),
2018-05-08 08:12:24 Local7.Debug 10.14.114.10 648024: Modem=OFF(0x0), Codec Bytes=40, Signal Type=2)
2018-05-08 08:12:24 Local7.Debug 10.14.114.10 648025: May 8 08:11:48 CDT: //28402/315AFE1CA578/CCAPI/cc_api_t38_fax_start:
2018-05-08 08:12:24 Local7.Debug 10.14.114.10 648026: Destination Interface=0xC24D1C64, Destination Call Id=28401, Source Call Id=28402,
2018-05-08 08:12:24 Local7.Debug 10.14.114.10 648027: Caps(Codec=T38Fax(0x10000), Fax Rate=FAX_RATE_7200(0x10),Fax Version:=0, Vad=OFF(0x1),
2018-05-08 08:12:24 Local7.Debug 10.14.114.10 648028: Modem=OFF(0x0), Codec Bytes=40, Signal Type=2)
2018-05-08 08:12:24 Local7.Debug 10.14.114.10 648029: May 8 08:11:48 CDT: //28401/315AFE1CA578/CCAPI/cc_api_remote_codec_dnld_done:
2018-05-08 08:12:24 Local7.Debug 10.14.114.10 648030:
2018-05-08 08:12:24 Local7.Debug 10.14.114.10 648031: Destination Interface=0xC24D1C64, Destination Call Id=28401, Source Call Id=28402, Xmit Function=0x351DE748
2018-05-08 08:12:24 Local7.Debug 10.14.114.10 648032: May 8 08:11:48 CDT: //28401/xxxxxxxxxxxx/CCAPI/cc_api_local_codec_dnld_done:
2018-05-08 08:12:24 Local7.Debug 10.14.114.10 648033: (dstVdbPtr=0x225ECF4C, dstCallId=0x6EF2, srcCallId=0x6EF1)
2018-05-08 08:12:24 Local7.Debug 10.14.114.10 648034: May 8 08:11:48 CDT: //28401/315AFE1CA578/CCAPI/cc_api_local_codec_dnld_done:
2018-05-08 08:12:24 Local7.Debug 10.14.114.10 648035: (dstVdbPtr=0x225ECF4C, dstCallId=0x6EF2, srcCallId=0x6EF1)
2018-05-08 08:12:24 Local7.Debug 10.14.114.10 648036: May 8 08:11:48 CDT: //28402/315AFE1CA578/CCAPI/cc_api_local_codec_dnld_done:
2018-05-08 08:12:24 Local7.Debug 10.14.114.10 648037: Destination Interface=0x225ECF4C, Destination Call Id=28402, Source Call Id=28401
2018-05-08 08:12:24 Local7.Debug 10.14.114.10 648038: May 8 08:11:48 CDT: //28401/xxxxxxxxxxxx/CCAPI/cc_api_local_codec_dnld_done:
2018-05-08 08:12:24 Local7.Debug 10.14.114.10 648039:
2018-05-08 08:12:25 Local7.Debug 10.14.114.10 648040: (dstVdbPtr=0x225ECF4C, dstCallId=0x6EF2, srcCallId=0x6EF1)
2018-05-08 08:12:25 Local7.Debug 10.14.114.10 648041: May 8 08:11:48 CDT: //28401/315AFE1CA578/CCAPI/cc_api_local_codec_dnld_done:
2018-05-08 08:12:25 Local7.Debug 10.14.114.10 648042: (dstVdbPtr=0x225ECF4C, dstCallId=0x6EF2, srcCallId=0x6EF1)
2018-05-08 08:12:25 Local7.Debug 10.14.114.10 648043: May 8 08:11:48 CDT: //28402/315AFE1CA578/CCAPI/cc_api_local_codec_dnld_done:
2018-05-08 08:12:25 Local7.Debug 10.14.114.10 648044: Destination Interface=0x225ECF4C, Destination Call Id=28402, Source Call Id=28401
2018-05-08 08:12:25 Local7.Debug 10.14.114.10 648045: May 8 08:11:48 CDT: //28402/315AFE1CA578/CCAPI/cc_api_set_fax_mode:
2018-05-08 08:12:25 Local7.Debug 10.14.114.10 648046: Destination Interface=0x225ECF4C, Destination Call Id=28402, Source Call Id=28401
2018-05-08 08:12:25 Local7.Debug 10.14.114.10 648047: May 8 08:11:48 CDT: 0/0/0:23 744416714 fr-entered=10(ms)
2018-05-08 08:12:27 Local7.Debug 10.14.114.10 648048:
2018-05-08 08:12:27 Local7.Debug 10.14.114.10 648049: timestamp=744419342 fr-msg-tx DIS
2018-05-08 08:12:31 Local7.Debug 10.14.114.10 648050:
2018-05-08 08:12:31 Local7.Debug 10.14.114.10 648051: timestamp=744423032 FR_BAD_CRC_LS_DATA 0x0 bytes
2018-05-08 08:12:31 Local7.Debug 10.14.114.10 648052: timestamp=744423032 fr-msg-tx bad crc, 0 bytes
2018-05-08 08:12:33 Local7.Debug 10.14.114.10 648053:
2018-05-08 08:12:33 Local7.Debug 10.14.114.10 648054: timestamp=744425652 fr-msg-tx DIS
2018-05-08 08:12:33 Local7.Debug 10.14.114.10 648055: May 8 08:11:58 CDT: ISDN Se0/0/0:23 Q931: RX <- DISCONNECT pd = 8 callref = 0x25F3
2018-05-08 08:12:33 Local7.Debug 10.14.114.10 648056: Cause i = 0x8290 - Normal call clearing
2018-05-08 08:12:33 Local7.Debug 10.14.114.10 648057: May 8 08:11:58 CDT: ISDN Se0/0/0:23 Q931: TX -> RELEASE pd = 8 callref = 0xA5F3
2018-05-08 08:12:33 Local7.Debug 10.14.114.10 648058: May 8 08:11:58 CDT: //28395/F4F7E776A575/CCAPI/cc_api_call_disconnected:
2018-05-08 08:12:33 Local7.Debug 10.14.114.10 648059: Cause Value=16, Interface=0xC24D1C64, Call Id=28395
2018-05-08 08:12:33 Local7.Debug 10.14.114.10 648060: May 8 08:11:58 CDT: //28395/F4F7E776A575/CCAPI/cc_api_call_disconnected:
2018-05-08 08:12:33 Local7.Debug 10.14.114.10 648061: Call Entry(Responsed=TRUE, Cause Value=16, Retry Count=0)
2018-05-08 08:12:33 Local7.Debug 10.14.114.10 648062: May 8 08:11:58 CDT: //28395/F4F7E776A575/CCAPI/ccConferenceDestroy:
2018-05-08 08:12:33 Local7.Debug 10.14.114.10 648063: Conference Id=0x25E5, Tag=0x0
2018-05-08 08:12:33 Local7.Debug 10.14.114.10 648064: May 8 08:11:58 CDT: //28395/F4F7E776A575/CCAPI/ccConferenceDestroy:
2018-05-08 08:12:33 Local7.Debug 10.14.114.10 648065:
2018-05-08 08:12:33 Local7.Debug 10.14.114.10 648066: May 8 08:11:58 CDT: confID:0x25E5; callEntry1 callID1:0x6EEB, type:6; callEntry2 callID2:0x6EEC, type:1
2018-05-08 08:12:33 Local7.Debug 10.14.114.10 648067: May 8 08:11:58 CDT: //28395/F4F7E776A575/CCAPI/cc_api_bridge_drop_done:
2018-05-08 08:12:33 Local7.Debug 10.14.114.10 648068: Conference Id=0x25E5, Source Interface=0xC24D1C64, Source Call Id=28395,
2018-05-08 08:12:33 Local7.Debug 10.14.114.10 648069: Destination Call Id=28396, Disposition=0x0, Tag=0x0
2018-05-08 08:12:33 Local7.Debug 10.14.114.10 648070: May 8 08:11:58 CDT: //28396/F4F7E776A575/CCAPI/cc_api_bridge_drop_done:
2018-05-08 08:12:33 Local7.Debug 10.14.114.10 648071: Conference Id=0x25E5, Source Interface=0x225ECF4C, Source Call Id=28396,
2018-05-08 08:12:33 Local7.Debug 10.14.114.10 648072: Destination Call Id=28395, Disposition=0x0, Tag=0x0
2018-05-08 08:12:33 Local7.Debug 10.14.114.10 648073: May 8 08:11:58 CDT: //28395/F4F7E776A575/CCAPI/cc_generic_bridge_done:
2018-05-08 08:12:33 Local7.Debug 10.14.114.10 648074:
2018-05-08 08:12:33 Local7.Debug 10.14.114.10 648075: Conference Id=0x25E5, Source Interface=0x225ECF4C, Source Call Id=28396,
2018-05-08 08:12:33 Local7.Debug 10.14.114.10 648076: Destination Call Id=28395, Disposition=0x0, Tag=0x0
2018-05-08 08:12:33 Local7.Debug 10.14.114.10 648077: May 8 08:11:58 CDT: //28395/F4F7E776A575/CCAPI/ccCallDisconnect:
2018-05-08 08:12:33 Local7.Debug 10.14.114.10 648078: Cause Value=16, Tag=0x0, Call Entry(Previous Disconnect Cause=0, Disconnect Cause=16)
2018-05-08 08:12:33 Local7.Debug 10.14.114.10 648079: May 8 08:11:58 CDT: //28395/F4F7E776A575/CCAPI/ccCallDisconnect:
2018-05-08 08:12:33 Local7.Debug 10.14.114.10 648080: Cause Value=16, Call Entry(Responsed=TRUE, Cause Value=16)
2018-05-08 08:12:33 Local7.Debug 10.14.114.10 648081: May 8 08:11:58 CDT: //28395/F4F7E776A575/CCAPI/cc_api_get_transfer_info:
2018-05-08 08:12:33 Local7.Debug 10.14.114.10 648082: Transfer Number=NULL
2018-05-08 08:12:33 Local7.Debug 10.14.114.10 648083: May 8 08:11:58 CDT: //28396/F4F7E776A575/CCAPI/ccCallDisconnect:
2018-05-08 08:12:33 Local7.Debug 10.14.114.10 648084: Cause Value=16, Tag=0x0, Call Entry(Previous Disconnect Cause=0, Disconnect Cause=0)
2018-05-08 08:12:33 Local7.Debug 10.14.114.10 648085: May 8 08:11:58 CDT: //28396/F4F7E776A575/CCAPI/ccCallDisconnect:
2018-05-08 08:12:33 Local7.Debug 10.14.114.10 648086: Cause Value=16, Call Entry(Responsed=TRUE, Cause Value=16)
2018-05-08 08:12:33 Local7.Debug 10.14.114.10 648087: May 8 08:11:58 CDT: //28396/F4F7E776A575/CCAPI/cc_api_get_transfer_info:
2018-05-08 08:12:33 Local7.Debug 10.14.114.10 648088: Transfer Number=NULL
2018-05-08 08:12:33 Local7.Debug 10.14.114.10 648089: May 8 08:11:58 CDT: //28396/F4F7E776A575/CCAPI/cc_api_get_transfer_info:
2018-05-08 08:12:33 Local7.Debug 10.14.114.10 648090: Transfer Number=NULL
2018-05-08 08:12:33 Local7.Debug 10.14.114.10 648091: May 8 08:11:58 CDT: //28396/F4F7E776A575/CCAPI/cc_api_call_disconnect_done:
2018-05-08 08:12:33 Local7.Debug 10.14.114.10 648092: Disposition=0, Interface=0x225ECF4C, Tag=0x0, Call Id=28396,
2018-05-08 08:12:33 Local7.Debug 10.14.114.10 648093: Call Entry(Disconnect Cause=16, Voice Class Cause Code=0, Retry Count=0)
2018-05-08 08:12:33 Local7.Debug 10.14.114.10 648094: May 8 08:11:58 CDT: //28396/F4F7E776A575/CCAPI/cc_api_call_disconnect_done:
2018-05-08 08:12:33 Local7.Debug 10.14.114.10 648095: Call Disconnect Event Sent
2018-05-08 08:12:33 Local7.Debug 10.14.114.10 648096: May 8 08:11:58 CDT: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:
2018-05-08 08:12:33 Local7.Debug 10.14.114.10 648097:
2018-05-08 08:12:33 Local7.Debug 10.14.114.10 648098: May 8 08:11:58 CDT: :cc_free_feature_vsa freeing 42B2E3B0
2018-05-08 08:12:33 Local7.Debug 10.14.114.10 648099: May 8 08:11:58 CDT: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:
2018-05-08 08:12:33 Local7.Debug 10.14.114.10 648100:
2018-05-08 08:12:33 Local7.Debug 10.14.114.10 648101: May 8 08:11:58 CDT: vsacount in free is 11
2018-05-08 08:12:33 Local7.Debug 10.14.114.10 648102: May 8 08:11:58 CDT: ISDN Se0/0/0:23 Q931: RX <- RELEASE_COMP pd = 8 callref = 0x25F3
2018-05-08 08:12:33 Local7.Debug 10.14.114.10 648103: May 8 08:11:58 CDT: //28395/F4F7E776A575/CCAPI/cc_api_call_disconnect_done:
2018-05-08 08:12:33 Local7.Debug 10.14.114.10 648104: Disposition=0, Interface=0xC24D1C64, Tag=0x0, Call Id=28395,
2018-05-08 08:12:33 Local7.Debug 10.14.114.10 648105: Call Entry(Disconnect Cause=16, Voice Class Cause Code=0, Retry Count=0)
2018-05-08 08:12:33 Local7.Debug 10.14.114.10 648106: May 8 08:11:58 CDT: //28395/F4F7E776A575/CCAPI/cc_api_call_disconnect_done:
2018-05-08 08:12:33 Local7.Debug 10.14.114.10 648107: Call Disconnect Event Sent
2018-05-08 08:12:34 Local7.Debug 10.14.114.10 648108: May 8 08:11:58 CDT: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:
2018-05-08 08:12:34 Local7.Debug 10.14.114.10 648109:
2018-05-08 08:12:34 Local7.Debug 10.14.114.10 648110: May 8 08:11:58 CDT: :cc_free_feature_vsa freeing 42B2DF50
2018-05-08 08:12:34 Local7.Debug 10.14.114.10 648111: May 8 08:11:58 CDT: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:
2018-05-08 08:12:34 Local7.Debug 10.14.114.10 648112:
2018-05-08 08:12:34 Local7.Debug 10.14.114.10 648113: May 8 08:11:58 CDT: vsacount in free is 10

R0g22 · ‎06-28-2018

T.38 relay debugs show up as "fr" since the DSP are able to modulate/demodulate the actual fax tone/message on the TDM leg. These are the Rx. The Tx are the ones being received on the IP leg and then being modulated/demodulated and sent out over TDM. This isn't coming from your fax server.
From these logs, yes, I can see a DCS and then a CFR. There would be a train done at this point on the modulation speed that was negotiated during DIS and DCS. Instead, we see a bad frame.

View solution in original post

R0g22 · ‎06-27-2018

GW sends a DIS (Digital Identification Signal). It should receive a DCS (Digital Command Signal) but it does not. Instead we receive bad frames -

2018-05-08 08:12:27 Local7.Debug 10.14.114.10 648049: timestamp=744419342 fr-msg-tx DIS
2018-05-08 08:12:31 Local7.Debug 10.14.114.10 648051: timestamp=744423032 FR_BAD_CRC_LS_DATA 0x0 bytes
2018-05-08 08:12:31 Local7.Debug 10.14.114.10 648052: timestamp=744423032 fr-msg-tx bad crc, 0 bytes
2018-05-08 08:12:33 Local7.Debug 10.14.114.10 648053:
2018-05-08 08:12:33 Local7.Debug 10.14.114.10 648054: timestamp=744425652 fr-msg-tx DIS

Usually this has something to do with bad line/carrier connection or the originating fax machine is misbehaving.

Have you ensure there are no slips on the circuit ? It not, then the issue seems to be from the far end fax machine or your Telco. The fax negotiation never completes hence it fails.

kylebrogers · ‎06-27-2018

Sorry, I should have noted that in my initial posting but forgot. My first assumption was PRI issues so I checked for slips, etc but it's running clean.

R0g22 · ‎06-28-2018

That's fine. It still is an issue with your Telco or the far end fax machine. I have shared the log analysis already.

kylebrogers · ‎06-28-2018

If I'm on the gateway between the telco and the internal fax server, how can I determine which one is causing the issue? The CRC would be run on a packet arriving either from one or the other, but I don't see a directional indicator.
Here is another call that had an issue:

===============
2018-05-08 08:28:42 Local7.Debug 10.14.114.10 661435: Destination Interface=0xC24D1C64, Destination Call Id=28485, Source Call Id=28486, Xmit Function=0x351DE748
2018-05-08 08:28:42 Local7.Debug 10.14.114.10 661436: May 8 08:28:06 CDT: 0/0/0:23 745394056 fr-entered=10(ms)
2018-05-08 08:28:45 Local7.Debug 10.14.114.10 661437:
2018-05-08 08:28:45 Local7.Debug 10.14.114.10 661438: timestamp=745396686 fr-msg-tx DIS
2018-05-08 08:28:48 Local7.Debug 10.14.114.10 661439:
2018-05-08 08:28:48 Local7.Debug 10.14.114.10 661440: timestamp=745399856 fr-msg-det DCS
2018-05-08 08:28:51 Local7.Debug 10.14.114.10 661441:
2018-05-08 08:28:51 Local7.Debug 10.14.114.10 661442: timestamp=745403596 fr-msg-tx CFR
2018-05-08 08:29:13 Local7.Debug 10.14.114.10 661443:
2018-05-08 08:29:13 Local7.Debug 10.14.114.10 661444: timestamp=745425646 FR_BAD_CRC_LS_DATA 0x0 bytes
2018-05-08 08:29:13 Local7.Debug 10.14.114.10 661445: timestamp=745425646 fr-msg-tx bad crc, 0 bytes
2018-05-08 08:29:13 Local7.Debug 10.14.114.10 661446: May 8 08:28:38 CDT: //28486/77E794DAA58D/CCAPI/cc_api_call_disconnected:
2018-05-08 08:29:13 Local7.Debug 10.14.114.10 661447: Cause Value=16, Interface=0x225ECF4C, Call Id=28486
2018-05-08 08:29:13 Local7.Debug 10.14.114.10 661448: May 8 08:28:38 CDT: //28486/77E794DAA58D/CCAPI/cc_api_call_disconnected:
2018-05-08 08:29:13 Local7.Debug 10.14.114.10 661449: Call Entry(Responsed=TRUE, Cause Value=16, Retry Count=0)

========================

I see a DIS, then a DCS, then a CFR, then the CRC error. But how can I tell whether the CRC error is on data received from the carrier down the PRI or on a packet received on the network interface from the fax server?

R0g22 · ‎06-28-2018

T.38 relay debugs show up as "fr" since the DSP are able to modulate/demodulate the actual fax tone/message on the TDM leg. These are the Rx. The Tx are the ones being received on the IP leg and then being modulated/demodulated and sent out over TDM. This isn't coming from your fax server.
From these logs, yes, I can see a DCS and then a CFR. There would be a train done at this point on the modulation speed that was negotiated during DIS and DCS. Instead, we see a bad frame.

kylebrogers · ‎06-28-2018

So that would be an issue on the PRI side of the gateway (either the telco provider, the sender's telco, or the sender's device)? Is that correct?

R0g22 · ‎06-28-2018

Correct. I would have suggested a PCM to capture the audio off of a b-channel but this is intermittent so that would be hard to do.

kylebrogers · ‎06-28-2018

Thank you for you help.