Still not solved. Cisco

ffacilities · ‎12-13-2013

We have T.37 onramp fax set up with incoming calls arriving on a T1 line into a Cisco 2811, and SMTP emails with fax attachments going out to our custom mailserver. We have many of these systems in the field. Most of the time onramp faxes work fine, but we sometimes see the 2811 sending an empty attachment to the mailserver. We have captured the incoming audio and decoded the fax using the Asterisk PBX utilities, with no errors at all.

What could cause a 2811 to send an empty fax attachment even though the incoming fax is good?

Here is the SMTP conversation (with names and numbers changed) -- red from the 2811, blue from the mailserver:

220-svr02.company.com Simple Mail Transfer Service Ready

220 ESMTP spoken here.

EHLO faxgateway.company.com

250-svr02.company.com

250-CHUNKING

250-DSN

250-AUTH CRAM-MD5 LOGIN PLAIN

250-AUTH=CRAM-MD5 LOGIN PLAIN

250-X-DCL-SOURCE

250-X-DCL-CALLID

250-X-DCL-DSN

250-X-DCL-REPLACE

250-X-DCL-TRANSCRIPT

250-X-DCL-SENT-ITEMS

250-X-DCL-GHOST

250-X-MSW-NOTIFY-SUPPRESS

250-X-MSW-OP

250 SIZE 0

MAIL FROM:<faxadmin@company.net>

250 OK

RCPT TO:<FAX=1231231234@company.com>

250 OK

DATA

354 Start mail input, end with <CRLF>.<CRLF>

Received: by faxgateway.company.com for <FAX=1231231234@company.com> (with Cisco NetWorks); Thu, 21 Nov 2013 16:22:01 -0500

To: "1231231234" <FAX=1231231234@company.com>

Message-ID: <7FD02013162201927@faxgateway.company.com>

Date: Thu, 21 Nov 2013 16:22:01 -0500

Subject: Fax

X-Mailer: Technical Support: http://www.cisco

MIME-Version: 1.0

Content-Type: multipart/fax-message;

boundary="yradnuoB=_7FCF2013162201695.faxgateway.company.com"

From: "2342342345" <faxadmin@company.net>

X-Account-Id: 0

--yradnuoB=_7FCF2013162201695.faxgateway.company.com

Content-ID: <7FD12013162213931@faxgateway.company.com>

Content-Type: image/tiff; name="Cisco_fax.tif"; application=faxbw

Content-Disposition: attachment

Content-Transfer-Encoding: base64

--yradnuoB=_7FCF2013162201695.faxgateway.company.com--

.

550 Fax message contains 0 pages

Note that our custom mailserver rejects these empty fax attachments because we want the sending fax machine to see a failure in this case. (If the mailserver were to accept the empty attachment, then the sender would see success but the receiver would receive no fax.)

The 2811 is running IOS 12.4(25d) and non-default DSP software 26.4.501 (updated to fix a problem with the DIS tones). But we've been seeing this problem since 12.4(6)T7 with no DSP firmware patch.

We've enabled all the relevant fax debug logs we can find, and here's the debug output for a 'zero-page fax' call from the point where the T1 connection is established, down to the point where the empty attachment is sent and the mailserver rejects it (names and numbers changed as before):

Nov 21 21:21:53.511: ISDN Se1/0:23 Q931: TX -> CALL_PROC pd = 8 callref = 0xAA14

Channel ID i = 0xA98382

Exclusive, Channel 2

Nov 21 21:21:53.511: ISDN Se1/0:23 Q931: TX -> CONNECT pd = 8 callref = 0xAA14

Nov 21 21:21:53.539: ISDN Se1/0:23 Q931: RX <- CONNECT_ACK pd = 8 callref = 0x2A14

Nov 21 21:21:53.543: %ISDN-6-CONNECT: Interface Serial1/0:1 is now connected to N/A N/A

Nov 21 21:21:56.511: //50796/C6DA8CB3B86D/FMSP/fax2_phaseB_receive:

CSI_PACKET(1231231234)

DIS_PACKET(speed=5, resolution=1, encoding=1)

Nov 21 21:21:56.511: //50796/C6DA8CB3B86D/FMSP/fax2_phaseB_receive:

fax2_response_receive, PROCESSING

Nov 21 21:21:59.399: //50796/C6DA8CB3B86D/FMSP/t30_rx_flag:

received flag of modulation: 0

Nov 21 21:21:59.399: //50796/C6DA8CB3B86D/FMSP/fax2_phaseB_receive:

fax2_response_receive, PROCESSING

Nov 21 21:21:59.739: //50796/C6DA8CB3B86D/FMSP/t30_rx_flag:

received flag of modulation: 0

Nov 21 21:22:00.719: //50796/C6DA8CB3B86D/FMSP/fax2_phaseB_receive:

fax2_response_receive, PROCESSING

Nov 21 21:22:01.311: //50796/C6DA8CB3B86D/FMSP/fax2_response_receive:

msg dump (size=23):

FF C0 C2 1C EC 8C 2C 8C 2C 4C 6C AC 4C 04 04 04 04 04 04 04

04 04 04

Nov 21 21:22:01.311: //50796/C6DA8CB3B86D/FMSP/fax2_response_receive:

received=TSI, remote id string:= 2342342345

Nov 21 21:22:01.311: //50796/C6DA8CB3B86D/FMSP/fax2_phaseB_receive:

fax2_response_receive, PROCESSING

Nov 21 21:22:01.407: //50796/C6DA8CB3B86D/FMSP/fax2_phaseB_receive:

fax2_response_receive, PROCESSING

Nov 21 21:22:01.647: //50796/C6DA8CB3B86D/FMSP/fax2_response_receive:

msg dump (size=10):

FF C8 C1 00 45 1F 01 01 01 00

Nov 21 21:22:01.647: //50796/C6DA8CB3B86D/FMSP/fax2_phaseB_receive:

fax2_response_receive, PROCESSING

Nov 21 21:22:01.691: //50796/C6DA8CB3B86D/FMSP/fax2_response_receive:

in response receive WAIT FOR CD

Nov 21 21:22:01.691: //50796/C6DA8CB3B86D/CCAPI/cc_api_event_indication:

Event=36, Call Id=50796

Nov 21 21:22:01.691: //50796/C6DA8CB3B86D/FMSP/fax2_phaseB_receive:

received DCS_PACKET, BR=9, resolution=0,encoding=1, remote_id_string= 2342342345

Nov 21 21:22:01.691: //50796/C6DA8CB3B86D/FMSP/fax2_phaseB_receive:

wait for ready for data from application

Nov 21 21:22:01.691: //50796/C6DA8CB3B86D/FOIP_ON/lapp_on_application:

Event(Tag=36, Name=CC_EV_FROM_FMSP_ON_CALL_DETAIL, Disposition=0)

Call Record(Call State=LAPP_ON_CS_FMSP_CALL_DETAIL(2))

Nov 21 21:22:01.691: //50795/C6DA8CB3B86D/FOIP_ON/lapp_on_validate_context:exit@984

Nov 21 21:22:01.691: //50795/C6DA8CB3B86D/FOIP_ON/lapp_on_msp_event:

Event(Tag=36, Name=CC_EV_FROM_FMSP_ON_CALL_DETAIL)

Nov 21 21:22:01.691: //50795/C6DA8CB3B86D/FOIP_ON/lapp_on_setup_mspi:

Prepare MSPI Call Setup Request

Nov 21 21:22:01.691: //50795/C6DA8CB3B86D/FOIP_ON/lapp_on_setup_mspi:

Envelope From=faxadmin@copmany.net

Nov 21 21:22:01.691: //50795/C6DA8CB3B86D/FOIP_ON/lapp_on_setup_mspi:

Envelope To=FAX=1231231234@company.com

Nov 21 21:22:01.691: //50795/C6DA8CB3B86D/FOIP_ON/lapp_on_setup_mspi:

RFC822 To Comment=1231231234

Nov 21 21:22:01.691: //50795/C6DA8CB3B86D/FOIP_ON/lapp_on_setup_mspi:

Faxmail Subject=Fax

Nov 21 21:22:01.691: //50795/C6DA8CB3B86D/FOIP_ON/lapp_on_setup_mspi:

Disposition Notification=

Nov 21 21:22:01.691: //50795/C6DA8CB3B86D/FOIP_ON/lapp_on_setup_mspi:

Originator TSI=RFC822 From Comment=2342342345

Nov 21 21:22:01.691: //50795/C6DA8CB3B86D/FOIP_ON/lapp_on_setup_mspi:

Auth/Account ID: `0'

Nov 21 21:22:01.691: //50795/C6DA8CB3B86D/FOIP_ON/lapp_on_setup_mspi:

Call Setup Request To MSPI

Nov 21 21:22:01.691: //50795/C6DA8CB3B86D/CCAPI/ccCallSetupRequest:

Destination=, Calling IE Present=FALSE, Mode=0,

Outgoing Dial-peer=3, Params=0x45E136F0, Progress Indication=NULL(0)

Nov 21 21:22:01.691: //50795/C6DA8CB3B86D/CCAPI/ccCallSetupRequest:

Destination Pattern=.T, Called Number=1231231234, Digit Strip=FALSE

Nov 21 21:22:01.691: //50795/C6DA8CB3B86D/CCAPI/ccCallSetupRequest:

Calling Number=(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed),

Called Number=1231231234(TON=Unknown, NPI=Unknown),

Redirect Number=, Display Info=

Account Number=, Final Destination Flag=TRUE,

Guid=C6DA8CB3-5229-11E3-B86D-58BC273896C0, Outgoing Dial-peer=3

Nov 21 21:22:01.695: //50795/C6DA8CB3B86D/CCAPI/cc_api_display_ie_subfields:

ccCallSetupRequest:

cisco-username=

----- ccCallInfo IE subfields -----

cisco-ani=

cisco-anitype=0

cisco-aniplan=0

cisco-anipi=0

cisco-anisi=0

dest=1231231234

cisco-desttype=0

cisco-destplan=0

cisco-rdie=FFFFFFFF

cisco-rdn=

cisco-rdntype=-1

cisco-rdnplan=-1

cisco-rdnpi=-1

cisco-rdnsi=-1

cisco-redirectreason=-1

Nov 21 21:22:01.695: //50795/C6DA8CB3B86D/CCAPI/ccIFCallSetupRequestPrivate:

Interface=0x453B5564, Interface Type=19, Destination=, Mode=0x0,

Call Params(Calling Number=(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Al lowed),

Called Number=1231231234(TON=Unknown, NPI=Unknown), Calling Translated=FALSE,

Subscriber Type Str=RegularLine, FinalDestinationFlag=TRUE, Outgoing Dial-peer=3, Call Count On=FALSE,

Source Trkgrp Route Label=, Target Trkgrp Route Label=, tg_label_flag=0, Application Call Id= )

Nov 21 21:22:01.695: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_new_context_guid:exit@2190

Nov 21 21:22:01.695: //50797/C6DA8CB3B86D/MSPI_ON/mspi_call_setup_request:

Outgoing Peer Tag=3

Envelope From=faxadmin@company.net

Envelope To=FAX=1231231234@company.com

Mime Outer Type=2

Nov 21 21:22:01.695: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_open:

from=faxadmin@company.net, to=FAX=1231231234@company.com

Nov 21 21:22:01.695: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_open:exit@1881

Nov 21 21:22:01.695: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_add_headers:

from_comment=2342342345

Nov 21 21:22:01.695: //50795/C6DA8CB3B86D/VTSP:(1/0:23):1:1:1/vtsp_spi_event_handler:

Event Category=1, Event=138

Nov 21 21:22:01.695: //50797/C6DA8CB3B86D/CCAPI/ccIFCallSetupRequestPrivate:

SPI Call Setup Request Is Success; Interface Type=19, FlowMode=1

Nov 21 21:22:01.695: //50797/C6DA8CB3B86D/CCAPI/ccCallSetContext:

Context=0x44047884

Nov 21 21:22:01.695: //50797/C6DA8CB3B86D/FOIP_ON/lapp_on_setup_mspi:exit@791

Nov 21 21:22:01.695: //50795/C6DA8CB3B86D/FOIP_ON/lapp_on_conference_fmsp_dmsp:

Starting Conference with FMSP and DMSP

Nov 21 21:22:01.695: //50795/C6DA8CB3B86D/FOIP_ON/lapp_on_conference_fmsp_dmsp:

Tiff File Created; Time=2013:11:21 16:22:01

Nov 21 21:22:01.699: //50798/C6DA8CB3B86D/DMSP/docmsp_call_setup_request:

ramp data dir=ONRAMP, conf dir=DEST

Nov 21 21:22:01.699: //50796/xxxxxxxxxxxx/CCAPI/ccConferenceCreate:

(confID=0x440478F0, callID1=0xC66C, callID2=0xC66E, tag=0x0)

Nov 21 21:22:01.699: //50796/C6DA8CB3B86D/CCAPI/ccConferenceCreate:

Conference Id=0x440478F0, Call Id1=50796, Call Id2=50798, Tag=0x0

Nov 21 21:22:01.699: //50796/xxxxxxxxxxxx/CCAPI/cc_api_bridge_done:

Conference Id=0x8B2C, Source Interface=0x45F255A0, Source Call Id=50796,

Destination Call Id=50798, Disposition=0x0, Tag=0x0

Nov 21 21:22:01.699: //50796/C6DA8CB3B86D/CCAPI/cc_api_caps_ind:

Destination Interface=0x45F2554C, Destination Call Id=50798, Source Call Id=50796,

Caps(Codec=0x4, Fax Rate=0x2, Vad=0x2,

Modem=0x0, Codec Bytes=20, Signal Type=2)

Nov 21 21:22:01.699: //50796/C6DA8CB3B86D/CCAPI/cc_api_caps_ind:

Caps(Playout Mode=1, Playout Initial=60(ms), Playout Min=40(ms),

Playout Max=250(ms), Fax Nom=300(ms))

Nov 21 21:22:01.699: //50798/C6DA8CB3B86D/DMSP/docmsp_caps_ind:

CallId=50798, srcCallId=50796

Nov 21 21:22:01.699: //50798/C6DA8CB3B86D/DMSP/docmsp_bridge:

conf id=0x8B2C, srcCallId=50798, dstCallId=50796,

ramp data dir=ONRAMP, conf dir=DEST, encode out=0

Nov 21 21:22:01.699: //50798/xxxxxxxxxxxx/CCAPI/cc_api_bridge_done:

Conference Id=0x8B2C, Source Interface=0x45F2554C, Source Call Id=50798,

Destination Call Id=50796, Disposition=0x0, Tag=0x0

Nov 21 21:22:01.699: //50796/C6DA8CB3B86D/CCAPI/cc_generic_bridge_done:

Conference Id=0x8B2C, Source Interface=0x45F2554C, Source Call Id=50798,

Destination Call Id=50796, Disposition=0x0, Tag=0x0

Nov 21 21:22:01.699: //50798/C6DA8CB3B86D/DMSP/docmsp_bridge:

Bridge done

Nov 21 21:22:01.699: //50796/C6DA8CB3B86D/CCAPI/ccConferenceCreate:

Call Entry(Conference Id=0x8B2C, Destination Call Id=50795)

Nov 21 21:22:01.699: //50798/C6DA8CB3B86D/CCAPI/ccConferenceCreate:

Call Entry(Conference Id=0x8B2C, Destination Call Id=50796)

Nov 21 21:22:01.699: //50798/C6DA8CB3B86D/CCAPI/ccCallSetContext:

Context=0x44047884

Nov 21 21:22:01.699: //50795/C6DA8CB3B86D/FOIP_ON/lapp_on_change_state:

Old State=LAPP_ON_CS_FMSP_CALL_DETAIL(2),

New State=LAPP_ON_CS_FMSP_DMSP_CONFERENCING(3)

Nov 21 21:22:01.699: //50795/C6DA8CB3B86D/FOIP_ON/lapp_on_msp_event:exit@2079

Nov 21 21:22:01.699: //50796/C6DA8CB3B86D/FOIP_ON/lapp_on_application:

Event(Tag=29, Name=CC_EV_CONF_CREATE_DONE, Disposition=0)

Call Record(Call State=LAPP_ON_CS_FMSP_DMSP_CONFERENCING(3))

Nov 21 21:22:01.699: //50795/C6DA8CB3B86D/FOIP_ON/lapp_on_validate_context:exit@984

Nov 21 21:22:01.699: //50796/C6DA8CB3B86D/FOIP_ON/lapp_on_conference_created:

FMSP and DMSP Are Conferenced

Nov 21 21:22:01.699: //50796/C6DA8CB3B86D/FOIP_ON/lapp_on_conference_created:

Sending RECEIVE ENABLE to FMSP

Nov 21 21:22:01.699: //50796/C6DA8CB3B86D/CCAPI/ccDeliverEvent:

Event Category=0, Call Id=50796

Nov 21 21:22:01.699: //50795/C6DA8CB3B86D/FOIP_ON/lapp_on_change_state:

Old State=LAPP_ON_CS_FMSP_DMSP_CONFERENCING(3),

New State=LAPP_ON_CS_FMSP_PAGE_ACCEPT_REQUESTED(4)

Nov 21 21:22:01.699: //50796/C6DA8CB3B86D/FMSP/fax2_phaseB_receive:

send CFR_PACKET

Nov 21 21:22:01.703: //50796/C6DA8CB3B86D/FMSP/fax2_phaseB_receive:

fax2_configure_rx_data, STILL_LOOKING, T2 timer not expired

Nov 21 21:22:01.703: //50796/C6DA8CB3B86D/CCAPI/cc_process_notify_bridge_done:

Conference Id=0x8B2C, Call Id1=50796, Call Id2=50798

Nov 21 21:22:01.847: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_work_routine:

socket 0 readable for first time

Nov 21 21:22:01.863: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_work_routine:

socket 0 readable for first time

Nov 21 21:22:01.863: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_getln:

(C)R: 220-svr02.company.com Simple Mail Transfer Service Ready

Nov 21 21:22:01.863: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_work_routine:

socket 0 readable for first time

Nov 21 21:22:01.863: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_getln:

(C)R: 220 ESMTP spoken here.

Nov 21 21:22:01.863: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_writeln:

(C)S: EHLO faxgateway.company.com

Nov 21 21:22:01.863: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_write:

return code=0

Nov 21 21:22:01.875: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_getln:

(C)R: 250-svr02.company.com