12-13-2013 06:53 AM - edited 03-19-2019 07:39 AM
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
Nov 21 21:22:01.879: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_getln:
(C)R: 250-CHUNKING
Nov 21 21:22:01.879: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_getln:
(C)R: 250-DSN
Nov 21 21:22:01.879: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_getln:
(C)R: 250-AUTH CRAM-MD5 LOGIN PLAIN
Nov 21 21:22:01.879: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_getln:
(C)R: 250-AUTH=CRAM-MD5 LOGIN PLAIN
Nov 21 21:22:01.879: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_getln:
(C)R: 250-X-DCL-SOURCE
Nov 21 21:22:01.879: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_getln:
(C)R: 250-X-DCL-CALLID
Nov 21 21:22:01.879: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_getln:
(C)R: 250-X-DCL-DSN
Nov 21 21:22:01.879: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_getln:
(C)R: 250-X-DCL-REPLACE
Nov 21 21:22:01.879: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_getln:
(C)R: 250-X-DCL-TRANSCRIPT
Nov 21 21:22:01.879: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_getln:
(C)R: 250-X-DCL-SENT-ITEMS
Nov 21 21:22:01.879: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_getln:
(C)R: 250-X-DCL-GHOST
Nov 21 21:22:01.879: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_getln:
(C)R: 250-X-MSW-NOTIFY-SUPPRESS
Nov 21 21:22:01.879: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_getln:
(C)R: 250-X-MSW-OP
Nov 21 21:22:01.879: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_getln:
(C)R: 250 SIZE 0
Nov 21 21:22:01.879: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_writeln:
(C)S: MAIL FROM:<faxadmin@company.net>
Nov 21 21:22:01.879: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_write:
return code=0
Nov 21 21:22:01.895: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_getln:
(C)R: 250 OK
Nov 21 21:22:01.895: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_writeln:
(C)S: RCPT TO:<FAX=1231231234@company.com>
Nov 21 21:22:01.895: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_write:
return code=0
Nov 21 21:22:01.911: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_getln:
(C)R: 250 OK
Nov 21 21:22:01.911: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_write:
return code=0
Nov 21 21:22:01.927: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_getln:
(C)R: 354 Start mail input, end with <CRLF>.<CRLF>
Nov 21 21:22:01.927: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_writeln:
(C)S: Received: by faxgateway.company.com for <FAX=1231231234@company.com> (with Cisco NetWorks); Thu, 21 Nov 2013 16:22:01 -0500
Nov 21 21:22:01.927: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_write:
return code=0
Nov 21 21:22:01.927: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_writeln:
(C)S: To: "1231231234" <FAX=1231231234@company.com>
Nov 21 21:22:01.927: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_write:
return code=0
Nov 21 21:22:01.927: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_writeln:
(C)S: Message-ID: <7FD02013162201927@faxgateway.company.com>
Nov 21 21:22:01.927: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_write:
return code=0
Nov 21 21:22:01.927: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_writeln:
(C)S: Date: Thu, 21 Nov 2013 16:22:01 -0500
Nov 21 21:22:01.927: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_write:
return code=0
Nov 21 21:22:01.927: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_writeln:
(C)S: Subject: Fax
Nov 21 21:22:01.927: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_write:
return code=0
Nov 21 21:22:01.927: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_writeln:
(C)S: X-Mailer: Technical Support: http://www.cisco
Nov 21 21:22:01.927: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_write:
return code=0
Nov 21 21:22:01.927: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_writeln:
(C)S: MIME-Version: 1.0
Nov 21 21:22:01.927: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_write:
return code=0
Nov 21 21:22:01.927: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_writeln:
(C)S: Content-Type: multipart/fax-message;
Nov 21 21:22:01.927: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_write:
return code=0
Nov 21 21:22:01.927: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_writeln:
(C)S: boundary="yradnuoB=_7FCF2013162201695.faxgateway.company.com"
Nov 21 21:22:01.927: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_write:
return code=0
Nov 21 21:22:01.927: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_writeln:
(C)S: From: "2342342345" <faxadmin@company.net>
Nov 21 21:22:01.927: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_write:
return code=0
Nov 21 21:22:01.931: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_writeln:
(C)S: X-Account-Id: 0
Nov 21 21:22:01.931: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_write:
return code=0
Nov 21 21:22:02.695: //50797/C6DA8CB3B86D/MSPI_ON/mspi_check_connect:
MMccb(Count=0)
Nov 21 21:22:02.695: //50797/C6DA8CB3B86D/MSPI_ON/mspi_check_connect:
SMTP Connected To The Server !
Nov 21 21:22:02.695: //50797/C6DA8CB3B86D/CCAPI/cc_api_call_connected:
Interface=0x453B5564, Data Bitmask=0x0, Progress Indication=NULL(0),
Connection Handle=0
Nov 21 21:22:02.695: //50797/C6DA8CB3B86D/CCAPI/cc_api_call_connected:
Call Entry(Connected=TRUE, Responsed=TRUE, Retry Count=0)
Nov 21 21:22:02.695: //50797/C6DA8CB3B86D/FOIP_ON/lapp_on_application:
Event(Tag=8, Name=CC_EV_CALL_CONNECTED, Disposition=0)
Call Record(Call State=LAPP_ON_CS_FMSP_PAGE_ACCEPT_REQUESTED(4))
Nov 21 21:22:02.695: //50795/C6DA8CB3B86D/FOIP_ON/lapp_on_validate_context:exit@984
Nov 21 21:22:02.695: //50797/C6DA8CB3B86D/FOIP_ON/lapp_on_call_connected:
MSPI call connected:
Start Conferencing DMSP and MSPI
Nov 21 21:22:02.695: //50798/xxxxxxxxxxxx/CCAPI/ccConferenceCreate:
(confID=0x440478F4, callID1=0xC66E, callID2=0xC66D, tag=0x0)
Nov 21 21:22:02.695: //50798/C6DA8CB3B86D/CCAPI/ccConferenceCreate:
Conference Id=0x440478F4, Call Id1=50798, Call Id2=50797, Tag=0x0
Nov 21 21:22:02.695: //50798/C6DA8CB3B86D/DMSP/docmsp_bridge:
conf id=0x8B2D, srcCallId=50798, dstCallId=50797,
ramp data dir=ONRAMP, conf dir=SRC, encode out=0
Nov 21 21:22:02.695: //50798/xxxxxxxxxxxx/CCAPI/cc_api_bridge_done:
Conference Id=0x8B2D, Source Interface=0x45F2554C, Source Call Id=50798,
Destination Call Id=50797, Disposition=0x0, Tag=0x0
Nov 21 21:22:02.695: //50798/C6DA8CB3B86D/DMSP/docmsp_bridge:
Bridge done
Nov 21 21:22:02.695: //50797/C6DA8CB3B86D/MSPI/mspi_bridge:
MMccb(State=CONNECTED, Type=Onramp), Destination Call Id=50798
Nov 21 21:22:02.695: //50797/xxxxxxxxxxxx/CCAPI/cc_api_bridge_done:
Conference Id=0x8B2D, Source Interface=0x453B5564, Source Call Id=50797,
Destination Call Id=50798, Disposition=0x0, Tag=0x0
Nov 21 21:22:02.695: //50798/C6DA8CB3B86D/CCAPI/cc_generic_bridge_done:
Conference Id=0x8B2D, Source Interface=0x453B5564, Source Call Id=50797,
Destination Call Id=50798, Disposition=0x0, Tag=0x0
Nov 21 21:22:02.695: //50798/C6DA8CB3B86D/CCAPI/ccConferenceCreate:
Call Entry(Conference Id=0x8B2D, Destination Call Id=50796)
Nov 21 21:22:02.695: //50797/C6DA8CB3B86D/CCAPI/ccConferenceCreate:
Call Entry(Conference Id=0x8B2D, Destination Call Id=50795)
Nov 21 21:22:02.695: //50797/C6DA8CB3B86D/CCAPI/ccCallSetContext:
Context=0x44047884
Nov 21 21:22:02.695: //50795/C6DA8CB3B86D/FOIP_ON/lapp_on_call_connected:exit@2508
Nov 21 21:22:02.695: //50798/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_PAGE_ACCEPT_REQUESTED(4))
Nov 21 21:22:02.695: //50795/C6DA8CB3B86D/FOIP_ON/lapp_on_validate_context:exit@984
Nov 21 21:22:02.699: //50798/C6DA8CB3B86D/CCAPI/cc_process_notify_bridge_done:
Conference Id=0x8B2D, Call Id1=50798, Call Id2=50797
Nov 21 21:22:06.487: //50796/C6DA8CB3B86D/FMSP/t30_rx_flag:
received flag of modulation: 0
Nov 21 21:22:06.487: //50796/C6DA8CB3B86D/FMSP/fax2_phaseB_receive:
fax2_configure_rx_data, DETECTED_COMMAND
Nov 21 21:22:06.487: //50796/C6DA8CB3B86D/FMSP/fax2_phaseB_receive:
fax2_command_receive, NO_COMMAND, T2 timer not expired
Nov 21 21:22:12.275: //50796/C6DA8CB3B86D/FMSP/t30_rx_flag:
received flag of modulation: 0
Nov 21 21:22:13.207: //50796/C6DA8CB3B86D/FMSP/fax2_phaseB_receive:
fax2_command_receive, PROCESSING
Nov 21 21:22:13.267: //50796/C6DA8CB3B86D/FMSP/fax2_command_receive:
msg dump (size=3):
FF C8 F4
Nov 21 21:22:13.267: //50796/C6DA8CB3B86D/FMSP/fax2_phaseB_receive:
fax2_command_receive, PROCESSING
Nov 21 21:22:13.287: //50796/C6DA8CB3B86D/FMSP/fax2_phaseB_receive:
fax2_command_receive, RECEIVED_COMMAND
Nov 21 21:22:13.287: //50796/C6DA8CB3B86D/FMSP/fax2_phaseD_receive:
received EOP
Nov 21 21:22:13.287: //50798/C6DA8CB3B86D/DMSP/docmsp_xmit:
srcCallId=50796, dstCallId=50798, direction=0
Nov 21 21:22:13.287: //50796/C6DA8CB3B86D/FMSP/fax2_phaseD_receive:
waiting for page acceptance by the application
Nov 21 21:22:13.287: //50797/C6DA8CB3B86D/MSPI_ON/mspi_xmit:
MMccb(State=CONFERENCED, Type=Onramp, Buffer Count=0),
Source Call Id=50798
Nov 21 21:22:13.287: //50797/C6DA8CB3B86D/MSPI_ON/mspi_onramp_xmit:
EOD Received
Nov 21 21:22:13.931: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_write:
return code=0
Nov 21 21:22:13.931: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_writeln:
(C)S: --yradnuoB=_7FCF2013162201695.faxgateway.company.com
Nov 21 21:22:13.931: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_write:
return code=0
Nov 21 21:22:13.931: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_writeln:
(C)S: Content-ID: <7FD12013162213931@faxgateway.company.com>
Nov 21 21:22:13.931: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_write:
return code=0
Nov 21 21:22:13.931: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_writeln:
(C)S: Content-Type: image/tiff; name="Cisco_fax.tif"; application=faxbw
Nov 21 21:22:13.931: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_write:
return code=0
Nov 21 21:22:13.931: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_writeln:
(C)S: Content-Disposition: attachment
Nov 21 21:22:13.931: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_write:
return code=0
Nov 21 21:22:13.931: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_writeln:
(C)S: Content-Transfer-Encoding: base64
Nov 21 21:22:13.931: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_write:
return code=0
Nov 21 21:22:13.931: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_write:
return code=0
Nov 21 21:22:13.931: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_send_data_cisco:exit@849
Nov 21 21:22:13.931: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_write:
return code=0
Nov 21 21:22:13.931: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_writeln:
(C)S: --yradnuoB=_7FCF2013162201695.faxgateway.company.com--
Nov 21 21:22:13.931: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_write:
return code=0
Nov 21 21:22:13.931: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_work_routine:
Sending terminating dot ...(socket=0)
Nov 21 21:22:13.931: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_writeln:
(C)S: .
Nov 21 21:22:13.931: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_write:
return code=0
Nov 21 21:22:13.959: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_getln:
(C)R: 550 Fax message contains 0 pages
Nov 21 21:22:13.959: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_work_routine:
error in SMTP server's response to terminating "."
Nov 21 21:22:13.959: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_work_routine:
ERROR, socket=0
Nov 21 21:22:13.959: //-1/C6DA8CB3B86D/SMTPC/esmtp_client_engine_work_routine:
Finishing, socket=-1, bytes send=1091
Nov 21 21:22:13.959: //50797/C6DA8CB3B86D/MSPI_ON/mspi_onramp_buff_finished_callback:
MMccb(Call State=CONFERENCED, Buffer Count=1)
Nov 21 21:22:13.959: //50797/C6DA8CB3B86D/MSPI_ON/mspi_onramp_buff_finished_callback:
EOD Received; Status=1
Nov 21 21:22:13.959: //50797/C6DA8CB3B86D/MSPI_ON/mspi_onramp_buff_finished_callback:
Message Id=7FD02013162201927@faxgateway.company.com
Nov 21 21:22:13.959: //50797/C6DA8CB3B86D/MSPI_ON/mspi_onramp_buff_finished_callback:
Status=1
Nov 21 21:22:13.959: //50797/C6DA8CB3B86D/MSPI/mspi_set_disconnect_text:
MMccb(Disconnect Cause=network out of order (38): SMTP client engine not completed)
Nov 21 21:22:13.959: //50797/C6DA8CB3B86D/CCAPI/cc_api_call_disconnected:
Cause Value=38, Interface=0x453B5564, Call Id=50797
Nov 21 21:22:13.959: //50797/C6DA8CB3B86D/CCAPI/cc_api_call_disconnected:
Call Entry(Responsed=TRUE, Cause Value=38, Retry Count=0)
Nov 21 21:22:13.959: //50797/C6DA8CB3B86D/FOIP_ON/lapp_on_application:
Event(Tag=11, Name=CC_EV_CALL_DISCONNECTED, Disposition=0)
Call Record(Call State=LAPP_ON_CS_FMSP_PAGE_ACCEPT_REQUESTED(4))
Nov 21 21:22:13.963: //50795/C6DA8CB3B86D/FOIP_ON/lapp_on_validate_context:exit@984
Nov 21 21:22:13.963: //50797/C6DA8CB3B86D/FOIP_ON/lapp_on_call_disconnected:
Cause Value=network out of order (38), Call Id=50797,
Call Record(Call State=LAPP_ON_CS_FMSP_PAGE_ACCEPT_REQUESTED(4),
Disconnect Cause=,
Call Id FMSP=50796, Call Id DMSP=50798, Call Id MSPI=50797, Call Id VTSP=50795)
Nov 21 21:22:13.963: //50797/C6DA8CB3B86D/FOIP_ON/lapp_on_call_disconnected:
Disconnecting MSPI
Nov 21 21:22:13.963: %LAPP_ON_MSGS-6-LAPP_ON_CAUSE_NO_ESMTP_CONNECT: ESMTP client did not connect or lost connection to remote server
Nov 21 21:22:13.963: //50795/C6DA8CB3B86D/FOIP_ON/lapp_on_change_state:
Old State=LAPP_ON_CS_FMSP_PAGE_ACCEPT_REQUESTED(4),
New State=LAPP_ON_CS_ERROR(10)
Nov 21 21:22:13.963: //50797/C6DA8CB3B86D/FOIP_ON/lapp_on_call_disconnected:
Call Record(Disconnect Cause=network out of order (38))
06-02-2014 06:53 AM
Hi,
Did you manage to solve this issue?
I started few debugs on the gateway and found some errors but still have no clue:
Call Record(Disconnect Cause=protocol error (111))
Cause Value=protocol error (111)
Call Record(Call State=LAPP_ON_CS_ERROR(10))
Thanks!
Tom.
06-09-2014 07:38 AM
Still not solved. Cisco support suggested adding the config command 'mta send success-fax-only' which is supposed to prevent sending empty emails or partial faxes, however there's a bug that means that has no effect IOS 12.4. We're looking at upgrading to 15.1(4)M8 which has the fix, but that will take some time.
Your problem sounds slightly different. See if you can get a network capture of the SMTP conversation with the target mailserver, to see if something's going wrong there.
Discover and save your favorite ideas. Come back to expert answers, step-by-step guides, recent topics, and more.
New here? Get started with these tips. How to use Community New member guide