[Home]

Summary:ASTERISK-15341: ReceiveFAX always end with "Transmission error" but Fax transmitted successfully
Reporter:Kristijan Vrban (vrban)Labels:
Date Opened:2009-12-21 04:02:21.000-0600Date Closed:2009-12-21 12:13:35.000-0600
Priority:MinorRegression?No
Status:Closed/CompleteComponents:Applications/app_fax
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:
Description:I successfully receive a fax via t.38 (spandsp-0.0.6pre12) but app_fax always end with "WARNING[12627]: app_fax.c:811 transmit: Transmission error" and then jump to the hangup extension.

****** ADDITIONAL INFORMATION ******

[Dec 21 10:36:53] DEBUG[12627]: app_fax.c:175 span_message: FLOW T.30 Send complete in phase T30_PHASE_E, state 2
[Dec 21 10:36:53] DEBUG[12627]: app_fax.c:211 phase_e_handler: Fax phase E handler. result=0
[Dec 21 10:36:53] DEBUG[12627]: app_fax.c:247 phase_e_handler: Fax transmitted successfully.
[Dec 21 10:36:53] DEBUG[12627]: app_fax.c:248 phase_e_handler:   Remote station ID: testfax
[Dec 21 10:36:53] DEBUG[12627]: app_fax.c:249 phase_e_handler:   Pages transferred: 1
[Dec 21 10:36:53] DEBUG[12627]: app_fax.c:250 phase_e_handler:   Image resolution:  8031 x 7700
[Dec 21 10:36:53] DEBUG[12627]: app_fax.c:251 phase_e_handler:   Transfer Rate:     9600
[Dec 21 10:36:53] DEBUG[12627]: app_fax.c:175 span_message: FLOW T.30 Changing from state 2 to 32
[Dec 21 10:36:53] DEBUG[12627]: app_fax.c:175 span_message: FLOW T.30 Changing from phase T30_PHASE_E to T30_PHASE_CALL_FINISHED
[Dec 21 10:36:53] DEBUG[12627]: app_fax.c:175 span_message: FLOW T.38T Set rx type 8
[Dec 21 10:36:53] DEBUG[12627]: app_fax.c:175 span_message: FLOW T.38T Set tx type 8
[Dec 21 10:36:53] DEBUG[12627]: app_fax.c:175 span_message: FLOW T.38T FAX exchange complete
[Dec 21 10:36:53] DEBUG[12627]: app_fax.c:698 transmit_t38: Loop finished, res=0
[Dec 21 10:36:53] DEBUG[12627]: chan_sip.c:10068 add_sdp: ** Our capability: 0x80e (gsm|ulaw|alaw|g726) Video flag: True Text flag: True
[Dec 21 10:36:53] DEBUG[12627]: chan_sip.c:10069 add_sdp: ** Our prefcodec: 0x0 (nothing)
[Dec 21 10:36:53] DEBUG[12627]: chan_sip.c:10193 add_sdp: -- Done with adding codecs to SDP
[Dec 21 10:36:53] DEBUG[12627]: chan_sip.c:10331 add_sdp: Done building SDP. Settling with this capability: 0x80e (gsm|ulaw|alaw|g726)
[Dec 21 10:36:53] DEBUG[12627]: chan_sip.c:3271 initialize_initreq: Initializing already initialized SIP dialog 5afd76f20084569f1399fce470664678@ip.ip.ip.ip (presumably reinvite)
[Dec 21 10:36:53] DEBUG[12627]: chan_sip.c:3559 __sip_xmit: Trying to put 'INVITE sip:' onto UDP socket destined for ip.ip.ip.ip:5060
[Dec 21 10:36:53] DEBUG[12627]: app_fax.c:719 transmit_t38: Shutting down T.38 on SIP/K9905039A7-00000003
[Dec 21 10:36:53] DEBUG[12346]: chan_sip.c:4136 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '5afd76f20084569f1399fce470664678@ip.ip.ip.ip' Request 103: Found
[Dec 21 10:36:53] DEBUG[12346]: chan_sip.c:4058 __sip_ack: Acked pending invite 103
[Dec 21 10:36:53] DEBUG[12346]: chan_sip.c:4095 __sip_ack: Stopping retransmission on '5afd76f20084569f1399fce470664678@ip.ip.ip.ip' of Request 103: Match Found
[Dec 21 10:36:53] DEBUG[12346]: chan_sip.c:3559 __sip_xmit: Trying to put 'ACK sip:008' onto UDP socket destined for ip.ip.ip.ip:5060
[Dec 21 10:36:54] DEBUG[12346]: chan_sip.c:3284 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 5afd76f20084569f1399fce470664678@ip.ip.ip.ip
[Dec 21 10:36:54] DEBUG[12346]: chan_sip.c:21071 handle_request_bye: Received bye, issuing owner hangup
[Dec 21 10:36:54] DEBUG[12346]: chan_sip.c:3559 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for ip.ip.ip.ip:5060
[Dec 21 10:36:54] WARNING[12627]: app_fax.c:811 transmit: Transmission error
[Dec 21 10:36:54] DEBUG[12627]: pbx.c:4299 __ast_pbx_run: Spawn extension (fax-in,s,1) exited non-zero on 'SIP/K9905039A7-00000003'
 == Spawn extension (fax-in, s, 1) exited non-zero on 'SIP/K9905039A7-00000003'
[Dec 21 10:36:54] DEBUG[12627]: channel.c:1634 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/K9905039A7-00000003'
[Dec 21 10:36:54] DEBUG[12627]: pbx.c:3689 pbx_extension_helper: Launching 'NoOp'
   -- Executing [h@fax-in:1] NoOp("SIP/K9905039A7-00000003", "###       FAXSTATUS: SUCCESS") in new stack
[Dec 21 10:36:54] DEBUG[12627]: pbx.c:3689 pbx_extension_helper: Launching 'NoOp'
   -- Executing [h@fax-in:2] NoOp("SIP/K9905039A7-00000003", "###        FAXERROR: ") in new stack
[Dec 21 10:36:54] DEBUG[12627]: pbx.c:3689 pbx_extension_helper: Launching 'NoOp'
   -- Executing [h@fax-in:3] NoOp("SIP/K9905039A7-00000003", "###         FAXMODE: T38") in new stack
[Dec 21 10:36:54] DEBUG[12627]: pbx.c:3689 pbx_extension_helper: Launching 'NoOp'
   -- Executing [h@fax-in:4] NoOp("SIP/K9905039A7-00000003", "###        FAXPAGES: 1") in new stack
[Dec 21 10:36:54] DEBUG[12627]: pbx.c:3689 pbx_extension_helper: Launching 'NoOp'
   -- Executing [h@fax-in:5] NoOp("SIP/K9905039A7-00000003", "###      FAXBITRATE: 9600") in new stack
[Dec 21 10:36:54] DEBUG[12627]: pbx.c:3689 pbx_extension_helper: Launching 'NoOp'
   -- Executing [h@fax-in:6] NoOp("SIP/K9905039A7-00000003", "###   FAXRESOLUTION: 7700") in new stack
[Dec 21 10:36:54] DEBUG[12627]: pbx.c:3689 pbx_extension_helper: Launching 'NoOp'
   -- Executing [h@fax-in:7] NoOp("SIP/K9905039A7-00000003", "### REMOTESTATIONID: testfax") in new stack
[Dec 21 10:36:54] DEBUG[12627]: channel.c:1739 ast_hangup: Hanging up channel 'SIP/K9905039A7-00000003'
[Dec 21 10:36:54] DEBUG[12627]: chan_sip.c:5991 sip_hangup: Hangup call SIP/K9905039A7-00000003, SIP callid 5afd76f20084569f1399fce470664678@ip.ip.ip.ip
[Dec 21 10:36:54] DEBUG[12627]: cdr.c:1243 ast_cdr_detach: Dropping CDR !
[Dec 21 10:36:54] DEBUG[12347]: chan_sip.c:22917 sip_devicestate: Checking device state for peer K9905039A7
[Dec 21 10:36:54] DEBUG[12347]: devicestate.c:460 do_state_change: Changing state for SIP/K9905039A7 - state 1 (Not in use)
[Dec 21 10:36:54] DEBUG[12347]: devicestate.c:440 devstate_event: device 'SIP/K9905039A7' state '1'
[Dec 21 10:36:54] DEBUG[12352]: app_queue.c:1084 handle_statechange: Device 'SIP/K9905039A7' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Dec 21 10:36:55] DEBUG[12346]: chan_sip.c:5774 sip_destroy: Destroying SIP dialog 5afd76f20084569f1399fce470664678@ip.ip.ip.ip
Comments:By: Kristijan Vrban (vrban) 2009-12-21 08:45:54.000-0600

ok, the main reason for that issue is, the old 1.4.20 asterisk that does the T.38 pass-through, because of:

chan_sip.c:14271 handle_request_invite: RTP re-invite after T38 session not handled yet !
By: Leif Madsen (lmadsen) 2009-12-21 08:50:59.000-0600

I'm not sure I understand your comment... ?
By: Kristijan Vrban (vrban) 2009-12-21 09:19:07.000-0600

the old 1.4.20 does not handle the RTP re-invite after the t.38 transmission between the T.38 gateway and the 1.6.2 asterisk with app_fax. my settings is:

T.38 gateway (some bigger siemens box) -> asterisk 1.4.20 (t.38 pass-through) ->
asterisk 1.6.2 with app_fax. and the app_fax error only happen with older 1.4 asterisk version because of the "chan_sip.c:14271 handle_request_invite: RTP re-invite after T38 session not handled yet ! " but since asterisk 1.4 can handle the RTP re-invite after T38 session, this issues is solved a can be closed.

More important is the t.38 pass-through issue ASTERISK-15209
By: Leif Madsen (lmadsen) 2009-12-21 12:13:35.000-0600

Closed per the reporter.