ASTERISK-15596: T.38 session fails with '488 Not acceptable here' if within 5 seconds there is no "SIP 100 Trying" REINVITE reply from remote

[Home]

Summary: ASTERISK-15596: T.38 session fails with '488 Not acceptable here' if within 5 seconds there is no "SIP 100 Trying" REINVITE reply from remote

Reporter: Roberto La Rosa (rlr2maverick) Labels:

Date Opened: 2010-02-09 09:10:22.000-0600 Date Closed: 2011-07-27 13:42:02

Priority: Major Regression? No

Status: Closed/Complete Components: Applications/app_fax

Versions: Frequency of
Occurrence

Related
Issues:
is related to ASTERISK-21955 [patch] Asterisk responds 488 to session timers re-Invite in an active T.38 dialog after exactly 5 seconds

Environment: Attachments:

Description: Good morning,

our setup is based on asterisk 1.6.1.14 & spandsp 0.0.6-pre17. We're always receiving fax with no error.

When sending we're experiencing a quite strange chan_sip codecs negotiation, selecting ulaw (8kbit??? with fax @14400 ???) even if slin is preferred and available.

At the first write (TSI) from asterisk to the channel remote side (fax) we're encountering HDLC carrier down and the transmission never takes place.

T38 nego can't proceed and fax is never sent.

Is there any experience to share ?

Indeed,
RLR

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

---
chan_sip debug

[Feb 9 16:03:34] DEBUG[14904] chan_sip.c: Allocating new SIP dialog for 2335425c1fcd17740681c1f034a13cb2@172.18.32.68 - OPTIONS (No RTP)
[Feb 9 16:03:34] DEBUG[14904] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 172.18.32.68:5060
[Feb 9 16:03:34] DEBUG[14904] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sipbuddies WHERE name = '' AND host = 'dynamic'
[Feb 9 16:03:34] DEBUG[14904] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sipbuddies WHERE name = ''
[Feb 9 16:03:34] DEBUG[14904] chan_sip.c: Initializing initreq for method OPTIONS - callid 4750706c4958eb7305db96b976a68660@172.18.32.68
[Feb 9 16:03:34] DEBUG[14904] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 172.18.68.56:7084
[Feb 9 16:03:34] DEBUG[14904] chan_sip.c: Stopping retransmission on '4750706c4958eb7305db96b976a68660@172.18.32.68' of Request 102: Match Found
[Feb 9 16:03:34] DEBUG[14904] chan_sip.c: Destroying SIP dialog 4750706c4958eb7305db96b976a68660@172.18.32.68
[Feb 9 16:03:34] DEBUG[14904] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 172.18.68.73:5060
[Feb 9 16:03:34] DEBUG[14904] chan_sip.c: Destroying SIP dialog 006eb7f630a8e90c1857aafe7abb76bc@172.18.32.68
[Feb 9 16:03:34] DEBUG[14871] chan_sip.c: Checking device state for peer 1399
[Feb 9 16:03:37] DEBUG[14904] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER
[Feb 9 16:03:37] DEBUG[14904] chan_sip.c: Ignoring SIP message because of retransmit (REGISTER Seqno 48659, ours 48659)
[Feb 9 16:03:37] DEBUG[14904] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 172.18.68.40:49529
[Feb 9 16:03:41] DEBUG[14904] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER
[Feb 9 16:03:41] DEBUG[14904] chan_sip.c: Ignoring SIP message because of retransmit (REGISTER Seqno 48659, ours 48659)
[Feb 9 16:03:41] DEBUG[14904] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 172.18.68.40:49529
[Feb 9 16:03:44] DEBUG[15134] chan_sip.c: Asked to create a SIP channel with formats: 0x40 (slin)
[Feb 9 16:03:44] DEBUG[15134] chan_sip.c: Allocating new SIP dialog for 61935e611b3b0e1e5a58ee346ba525f9@172.18.32.68 - INVITE (With RTP)
[Feb 9 16:03:44] DEBUG[15134] chan_sip.c: Setting NAT on RTP to Off
[Feb 9 16:03:44] DEBUG[15134] chan_sip.c: Setting NAT on VRTP to Off
[Feb 9 16:03:44] DEBUG[15134] chan_sip.c: Setting NAT on UDPTL to Off
[Feb 9 16:03:44] DEBUG[15134] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 172.18.32.68:5060
[Feb 9 16:03:44] DEBUG[15134] chan_sip.c: *** Our native formats are 0x40 (slin)
[Feb 9 16:03:44] DEBUG[15134] chan_sip.c: *** Joint capabilities are 0x40 (slin)
[Feb 9 16:03:44] DEBUG[15134] chan_sip.c: *** Our capabilities are 0x3c014e (gsm|ulaw|alaw|slin|g729|h261|h263|h263p|h264)
[Feb 9 16:03:44] DEBUG[15134] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x40 (slin)
[Feb 9 16:03:44] DEBUG[15134] chan_sip.c: *** Our preferred formats from the incoming channel are 0x40 (slin)
[Feb 9 16:03:44] DEBUG[15134] chan_sip.c: This channel can handle video! HOLLYWOOD next!
[Feb 9 16:03:44] DEBUG[15134] chan_sip.c: Outgoing Call for 00243828913
[Feb 9 16:03:44] DEBUG[15134] chan_sip.c: Updating call counter for outgoing call
[Feb 9 16:03:44] DEBUG[15134] chan_sip.c: This call needs video offers!
[Feb 9 16:03:44] DEBUG[15134] chan_sip.c: ** Our capability: 0x3c004e (gsm|ulaw|alaw|slin|h261|h263|h263p|h264) Video flag: False Text flag: False
[Feb 9 16:03:44] DEBUG[15134] chan_sip.c: ** Our prefcodec: 0x40 (slin)
[Feb 9 16:03:44] DEBUG[15134] chan_sip.c: -- Done with adding codecs to SDP
[Feb 9 16:03:44] DEBUG[15134] chan_sip.c: Done building SDP. Settling with this capability: 0x3c004e (gsm|ulaw|alaw|slin|h261|h263|h263p|h264)
[Feb 9 16:03:44] DEBUG[15134] chan_sip.c: Initializing initreq for method INVITE - callid 1e682c5a0a2fa19408bf969a3bb16101@172.18.32.68
[Feb 9 16:03:44] DEBUG[15134] chan_sip.c: Trying to put 'INVITE sip:' onto UDP socket destined for 172.18.76.12:5060
[Feb 9 16:03:44] DEBUG[14904] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '1e682c5a0a2fa19408bf969a3bb16101@172.18.32.68' Request 102: Found
[Feb 9 16:03:44] DEBUG[14904] chan_sip.c: SIP response 100 to standard invite
[Feb 9 16:03:44] DEBUG[14904] chan_sip.c: Allocating new SIP dialog for 21277ea9396e07892436a25a36d3bae3@172.18.32.68 - OPTIONS (No RTP)
[Feb 9 16:03:44] DEBUG[14904] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 172.18.32.68:5060
[Feb 9 16:03:44] DEBUG[14904] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sipbuddies WHERE name = '' AND host = 'dynamic'
[Feb 9 16:03:44] DEBUG[14904] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sipbuddies WHERE name = ''
[Feb 9 16:03:44] DEBUG[14904] chan_sip.c: Initializing initreq for method OPTIONS - callid 79ee3adc7a5f512b118774681ee0a1de@172.18.32.68
[Feb 9 16:03:44] DEBUG[14904] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 172.18.68.56:5060
[Feb 9 16:03:44] DEBUG[14904] chan_sip.c: Stopping retransmission on '79ee3adc7a5f512b118774681ee0a1de@172.18.32.68' of Request 102: Match Found
[Feb 9 16:03:44] DEBUG[14904] chan_sip.c: Destroying SIP dialog 79ee3adc7a5f512b118774681ee0a1de@172.18.32.68
[Feb 9 16:03:44] DEBUG[14904] chan_sip.c: Allocating new SIP dialog for 1437426b549382bc739a7dc854bbbbcc@172.18.32.68 - OPTIONS (No RTP)
[Feb 9 16:03:44] DEBUG[14904] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 172.18.32.68:5060
[Feb 9 16:03:44] DEBUG[14904] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sipbuddies WHERE name = '' AND host = 'dynamic'
[Feb 9 16:03:44] DEBUG[14904] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sipbuddies WHERE name = ''
[Feb 9 16:03:44] DEBUG[14904] chan_sip.c: Initializing initreq for method OPTIONS - callid 419f0833529dfaea24a9177b2e9179a4@172.18.32.68
[Feb 9 16:03:44] DEBUG[14904] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 172.18.68.73:5060
[Feb 9 16:03:45] DEBUG[14904] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '1e682c5a0a2fa19408bf969a3bb16101@172.18.32.68' Request 102: Found
[Feb 9 16:03:45] DEBUG[14904] chan_sip.c: SIP response 180 to standard invite
[Feb 9 16:03:45] DEBUG[14871] chan_sip.c: Checking device state for peer to-pstn-trunk1
[Feb 9 16:03:45] DEBUG[14904] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER
[Feb 9 16:03:45] DEBUG[14904] chan_sip.c: Ignoring SIP message because of retransmit (REGISTER Seqno 48659, ours 48659)
[Feb 9 16:03:45] DEBUG[14904] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 172.18.68.40:49529
[Feb 9 16:03:45] DEBUG[15134] chan_sip.c: Oooh, format changed to 4 ulaw
[Feb 9 16:03:45] DEBUG[14904] chan_sip.c: Acked pending invite 102
[Feb 9 16:03:45] DEBUG[14904] chan_sip.c: Stopping retransmission on '1e682c5a0a2fa19408bf969a3bb16101@172.18.32.68' of Request 102: Match Found
[Feb 9 16:03:45] DEBUG[14904] chan_sip.c: SIP response 200 to standard invite
[Feb 9 16:03:45] DEBUG[14904] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED.
[Feb 9 16:03:45] DEBUG[14904] chan_sip.c: Processing session-level SDP o=CiscoSystemsSIP-GW-UserAgent 5249 1338 IN IP4 172.18.76.12... UNSUPPORTED.
[Feb 9 16:03:45] DEBUG[14904] chan_sip.c: Processing session-level SDP s=SIP Call... UNSUPPORTED.
[Feb 9 16:03:45] DEBUG[14904] chan_sip.c: Processing session-level SDP c=IN IP4 172.18.76.12... OK.
[Feb 9 16:03:45] DEBUG[14904] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED.
[Feb 9 16:03:45] DEBUG[14904] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK.
[Feb 9 16:03:45] WARNING[14904] chan_sip.c: Unsupported SDP media type in offer: video 0
[Feb 9 16:03:45] DEBUG[14904] chan_sip.c: We're settling with these formats: 0x4 (ulaw)
[Feb 9 16:03:45] DEBUG[14904] chan_sip.c: We have an owner, now see if we need to change this call
[Feb 9 16:03:45] DEBUG[14904] chan_sip.c: Updating call counter for outgoing call
[Feb 9 16:03:45] DEBUG[14904] chan_sip.c: build_route: Contact hop: <sip:00243828913@172.18.76.12:5060;user=phone>
[Feb 9 16:03:45] DEBUG[14904] chan_sip.c: Trying to put 'ACK sip:002' onto UDP socket destined for 172.18.76.12:5060
[Feb 9 16:03:45] DEBUG[14871] chan_sip.c: Checking device state for peer to-pstn-trunk1
[Feb 9 16:03:45] DEBUG[14904] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 172.18.68.73:5060
[Feb 9 16:03:46] DEBUG[14904] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 172.18.68.73:5060
[Feb 9 16:03:47] DEBUG[14904] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 172.18.68.73:5060
[Feb 9 16:03:48] DEBUG[14904] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE
[Feb 9 16:03:48] DEBUG[14904] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED.
[Feb 9 16:03:48] DEBUG[14904] chan_sip.c: Processing session-level SDP o=CiscoSystemsSIP-GW-UserAgent 5249 1339 IN IP4 172.18.76.12... UNSUPPORTED.
[Feb 9 16:03:48] DEBUG[14904] chan_sip.c: Processing session-level SDP s=SIP Call... UNSUPPORTED.
[Feb 9 16:03:48] DEBUG[14904] chan_sip.c: Processing session-level SDP c=IN IP4 172.18.76.12... OK.
[Feb 9 16:03:48] DEBUG[14904] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED.
[Feb 9 16:03:48] DEBUG[14904] chan_sip.c: FaxVersion: 0
[Feb 9 16:03:48] DEBUG[14904] chan_sip.c: Processing media-level (image) SDP a=T38FaxVersion:0... OK.
[Feb 9 16:03:48] DEBUG[14904] chan_sip.c: T38MaxBitRate: 14400
[Feb 9 16:03:48] DEBUG[14904] chan_sip.c: Processing media-level (image) SDP a=T38MaxBitRate:14400... OK.
[Feb 9 16:03:48] DEBUG[14904] chan_sip.c: FillBitRemoval: 0
[Feb 9 16:03:48] DEBUG[14904] chan_sip.c: Processing media-level (image) SDP a=T38FaxFillBitRemoval:0... OK.
[Feb 9 16:03:48] DEBUG[14904] chan_sip.c: Transcoding MMR: 0
[Feb 9 16:03:48] DEBUG[14904] chan_sip.c: Processing media-level (image) SDP a=T38FaxTranscodingMMR:0... OK.
[Feb 9 16:03:48] DEBUG[14904] chan_sip.c: Transcoding JBIG: 0
[Feb 9 16:03:48] DEBUG[14904] chan_sip.c: Processing media-level (image) SDP a=T38FaxTranscodingJBIG:0... OK.
[Feb 9 16:03:48] DEBUG[14904] chan_sip.c: RateManagement: transferredTCF
[Feb 9 16:03:48] DEBUG[14904] chan_sip.c: Processing media-level (image) SDP a=T38FaxRateManagement:transferredTCF... OK.
[Feb 9 16:03:48] DEBUG[14904] chan_sip.c: MaxBufferSize:200
[Feb 9 16:03:48] DEBUG[14904] chan_sip.c: Processing media-level (image) SDP a=T38FaxMaxBuffer:200... OK.
[Feb 9 16:03:48] DEBUG[14904] chan_sip.c: Overriding T38FaxMaxDatagram '72' with '-1'
[Feb 9 16:03:48] DEBUG[14904] chan_sip.c: FaxMaxDatagram: 4294967295
[Feb 9 16:03:48] DEBUG[14904] chan_sip.c: Processing media-level (image) SDP a=T38FaxMaxDatagram:72... OK.
[Feb 9 16:03:48] DEBUG[14904] chan_sip.c: UDP EC: t38UDPRedundancy
[Feb 9 16:03:48] DEBUG[14904] chan_sip.c: Processing media-level (image) SDP a=T38FaxUdpEC:t38UDPRedundancy... OK.
[Feb 9 16:03:48] DEBUG[14904] chan_sip.c: T38 state changed to 2 on channel SIP/to-pstn-trunk1-00000008
[Feb 9 16:03:48] DEBUG[14904] chan_sip.c: Have T.38 but no audio, accepting offer anyway
[Feb 9 16:03:48] DEBUG[14904] chan_sip.c: SIP/to-pstn-trunk1-00000008: This call is UP....
[Feb 9 16:03:48] DEBUG[14904] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 172.18.76.12:5060
[Feb 9 16:03:48] DEBUG[14904] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 172.18.68.73:5060
[Feb 9 16:03:48] DEBUG[14904] chan_sip.c: Destroying SIP dialog 419f0833529dfaea24a9177b2e9179a4@172.18.32.68
[Feb 9 16:03:48] DEBUG[14871] chan_sip.c: Checking device state for peer 1399
[Feb 9 16:03:49] DEBUG[14904] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER
[Feb 9 16:03:49] DEBUG[14904] chan_sip.c: Ignoring SIP message because of retransmit (REGISTER Seqno 48659, ours 48659)
[Feb 9 16:03:49] DEBUG[14904] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 172.18.68.40:49529
[Feb 9 16:03:49] DEBUG[14904] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER
[Feb 9 16:03:49] DEBUG[14904] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 172.18.68.40:49529
[Feb 9 16:03:50] DEBUG[14904] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER
[Feb 9 16:03:50] DEBUG[14904] chan_sip.c: Ignoring SIP message because of retransmit (REGISTER Seqno 48660, ours 48660)
[Feb 9 16:03:50] DEBUG[14904] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 172.18.68.40:49529
[Feb 9 16:03:51] DEBUG[14904] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER
[Feb 9 16:03:51] DEBUG[14904] chan_sip.c: Ignoring SIP message because of retransmit (REGISTER Seqno 48660, ours 48660)
[Feb 9 16:03:51] DEBUG[14904] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 172.18.68.40:49529
[Feb 9 16:03:53] DEBUG[14904] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER
[Feb 9 16:03:53] DEBUG[14904] chan_sip.c: Ignoring SIP message because of retransmit (REGISTER Seqno 48660, ours 48660)
[Feb 9 16:03:53] DEBUG[14904] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 172.18.68.40:49529
[Feb 9 16:03:53] DEBUG[14904] chan_sip.c: T38 state changed to 0 on channel SIP/to-pstn-trunk1-00000008

---
app_fax debug

[Feb 9 15:57:45] DEBUG[15103] app_fax.c: FLOW T.30 HDLC signal status is Carrier up (-2) in state 18
[Feb 9 15:57:45] DEBUG[15103] app_fax.c: FLOW T.30 HDLC signal status is Framing OK (-6) in state 18
[Feb 9 15:57:45] DEBUG[15103] app_fax.c: FLOW T.30 Changing from phase T30_PHASE_A_CNG to T30_PHASE_B_RX
[Feb 9 15:57:45] DEBUG[15103] app_fax.c: FLOW FAX Set rx type 4
[Feb 9 15:57:45] DEBUG[15103] app_fax.c: FLOW FAX Set tx type 0
[Feb 9 15:57:47] DEBUG[15103] app_fax.c: FLOW T.30 Stop none (0 remaining)
[Feb 9 15:57:47] DEBUG[15103] app_fax.c: FLOW T.30 Rx: CSI without final frame tag
[Feb 9 15:57:47] DEBUG[15103] app_fax.c: FLOW T.30 Rx: ff 03 40 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20
[Feb 9 15:57:47] DEBUG[15103] app_fax.c: FLOW T.30 Remote gave CSI as: ""
[Feb 9 15:57:47] DEBUG[15103] app_fax.c: FLOW T.30 Stop none (0 remaining)
[Feb 9 15:57:47] DEBUG[15103] app_fax.c: FLOW T.30 Rx: DIS with final frame tag
[Feb 9 15:57:47] DEBUG[15103] app_fax.c: FLOW T.30 Rx: ff 13 80 00 ee f8 80 80 10
[Feb 9 15:57:47] DEBUG[15103] app_fax.c: FLOW T.30 In state 18
[Feb 9 15:57:47] DEBUG[15103] app_fax.c: FLOW T.30 DIS:
[Feb 9 15:57:47] DEBUG[15103] app_fax.c: FLOW T.30 .... ...0= Store and forward Internet fax (T.37): Not set
[Feb 9 15:57:47] DEBUG[15103] app_fax.c: FLOW T.30 .... .0..= Real-time Internet fax (T.38): Not set
[Feb 9 15:57:47] DEBUG[15103] app_fax.c: FLOW T.30 .... 0...= 3G mobile network: Not set
[Feb 9 15:57:47] DEBUG[15103] app_fax.c: FLOW T.30 ..0. ....= V.8 capabilities: Not set
[Feb 9 15:57:47] DEBUG[15103] app_fax.c: FLOW T.30 .0.. ....= Preferred octets: 256 octets
[Feb 9 15:57:47] DEBUG[15103] app_fax.c: FLOW T.30 .... ...0= Ready to transmit a fax document (polling): Not set
[Feb 9 15:57:47] DEBUG[15103] app_fax.c: FLOW T.30 .... ..1.= Can receive fax: Set
[Feb 9 15:57:47] DEBUG[15103] app_fax.c: FLOW T.30 ..10 11..= Supported data signalling rates: V.27 ter, V.29, and V.17
[Feb 9 15:57:47] DEBUG[15103] app_fax.c: FLOW T.30 .1.. ....= R8x7.7lines/mm and/or 200x200pels/25.4mm: Set
[Feb 9 15:57:47] DEBUG[15103] app_fax.c: FLOW T.30 1... ....= 2-D coding: Set
[Feb 9 15:57:47] DEBUG[15103] app_fax.c: FLOW T.30 .... ..00= Recording width: 215mm +- 1%
[Feb 9 15:57:47] DEBUG[15103] app_fax.c: FLOW T.30 .... 10..= Recording length: Unlimited
[Feb 9 15:57:47] DEBUG[15103] app_fax.c: FLOW T.30 .111 ....= Receiver's minimum scan line time: 0ms at 3.85 l/mm; T7.7 = T3.85
[Feb 9 15:57:47] DEBUG[15103] app_fax.c: FLOW T.30 1... ....= Extension indicator: Set
[Feb 9 15:57:47] DEBUG[15103] app_fax.c: FLOW T.30 .... ..0.= Compressed/uncompressed mode: Compressed
[Feb 9 15:57:47] DEBUG[15103] app_fax.c: FLOW T.30 .... .0..= Error correction mode (ECM): Non-ECM
[Feb 9 15:57:47] DEBUG[15103] app_fax.c: FLOW T.30 .0.. ....= T.6 coding: Not set
[Feb 9 15:57:47] DEBUG[15103] app_fax.c: FLOW T.30 1... ....= Extension indicator: Set
[Feb 9 15:57:47] DEBUG[15103] app_fax.c: FLOW T.30 .... ...0= "Field not valid" supported: Not set
[Feb 9 15:57:47] DEBUG[15103] app_fax.c: FLOW T.30 .... ..0.= Multiple selective polling: Not set
[Feb 9 15:57:47] DEBUG[15103] app_fax.c: FLOW T.30 .... .0..= Polled sub-address: Not set
[Feb 9 15:57:47] DEBUG[15103] app_fax.c: FLOW T.30 .... 0...= T.43 coding: Not set
[Feb 9 15:57:47] DEBUG[15103] app_fax.c: FLOW T.30 ...0 ....= Plane interleave: Not set
[Feb 9 15:57:47] DEBUG[15103] app_fax.c: FLOW T.30 ..0. ....= Voice coding with 32kbit/s ADPCM (Rec. G.726): Not set
[Feb 9 15:57:47] DEBUG[15103] app_fax.c: FLOW T.30 .0.. ....= Reserved for the use of extended voice coding set: Not set
[Feb 9 15:57:47] DEBUG[15103] app_fax.c: FLOW T.30 1... ....= Extension indicator: Set
[Feb 9 15:57:47] DEBUG[15103] app_fax.c: FLOW T.30 .... ...0= R8x15.4lines/mm: Not set
[Feb 9 15:57:47] DEBUG[15103] app_fax.c: FLOW T.30 .... ..0.= 300x300pels/25.4mm: Not set
[Feb 9 15:57:47] DEBUG[15103] app_fax.c: FLOW T.30 .... .0..= R16x15.4lines/mm and/or 400x400pels/25.4mm: Not set
[Feb 9 15:57:47] DEBUG[15103] app_fax.c: FLOW T.30 .... 0...= Inch-based resolution preferred: Not set
[Feb 9 15:57:47] DEBUG[15103] app_fax.c: FLOW T.30 ...1 ....= Metric-based resolution preferred: Set
[Feb 9 15:57:47] DEBUG[15103] app_fax.c: FLOW T.30 ..0. ....= Minimum scan line time for higher resolutions: T15.4 = T7.7
[Feb 9 15:57:47] DEBUG[15103] app_fax.c: FLOW T.30 .0.. ....= Selective polling: Not set
[Feb 9 15:57:47] DEBUG[15103] app_fax.c: FLOW T.30 0... ....= Extension indicator: Not set
[Feb 9 15:57:47] DEBUG[15103] app_fax.c: FLOW T.30 Selected compression T.4 2-D (2)
[Feb 9 15:57:47] DEBUG[15103] app_fax.c: FLOW T.30 Trying to send file '/var/spool/asterisk/fax/510.OUTGOING.1265620266.11.tif'
[Feb 9 15:57:47] DEBUG[15103] app_fax.c: FLOW T.30 Start sending document
[Feb 9 15:57:47] DEBUG[15103] app_fax.c: FLOW T.30 Minimum bits per row will be 0
[Feb 9 15:57:47] DEBUG[15103] app_fax.c: FLOW T.30 Starting page 1 of transfer
[Feb 9 15:57:47] DEBUG[15103] app_fax.c: FLOW T.30 DCS:
[Feb 9 15:57:47] DEBUG[15103] app_fax.c: FLOW T.30 .... ...0= Store and forward Internet fax (T.37): Not set
[Feb 9 15:57:47] DEBUG[15103] app_fax.c: FLOW T.30 .... .0..= Real-time Internet fax (T.38): Not set
[Feb 9 15:57:47] DEBUG[15103] app_fax.c: FLOW T.30 .... 0...= 3G mobile network: Not set
[Feb 9 15:57:47] DEBUG[15103] app_fax.c: FLOW T.30 .... ..1.= Receive fax: Set
[Feb 9 15:57:47] DEBUG[15103] app_fax.c: FLOW T.30 ..10 00..= Selected data signalling rate: V.17 14400bps
[Feb 9 15:57:47] DEBUG[15103] app_fax.c: FLOW T.30 .1.. ....= R8x7.7lines/mm and/or 200x200pels/25.4mm: Set
[Feb 9 15:57:47] DEBUG[15103] app_fax.c: FLOW T.30 1... ....= 2-D coding: Set
[Feb 9 15:57:47] DEBUG[15103] app_fax.c: FLOW T.30 .... ..00= Recording width: 215mm +- 1%
[Feb 9 15:57:47] DEBUG[15103] app_fax.c: FLOW T.30 .... 10..= Recording length: Unlimited
[Feb 9 15:57:47] DEBUG[15103] app_fax.c: FLOW T.30 .111 ....= Minimum scan line time: 0ms
[Feb 9 15:57:47] DEBUG[15103] app_fax.c: FLOW T.30 0... ....= Extension indicator: Not set
[Feb 9 15:57:47] DEBUG[15103] app_fax.c: FLOW T.30 Changing from state 18 to 4
[Feb 9 15:57:47] DEBUG[15103] app_fax.c: FLOW T.30 Sending ident '510'
[Feb 9 15:57:47] DEBUG[15103] app_fax.c: FLOW T.30 Tx: TSI without final frame tag
[Feb 9 15:57:47] DEBUG[15103] app_fax.c: FLOW T.30 Tx: ff 03 43 30 31 35 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20
[Feb 9 15:57:47] DEBUG[15103] app_fax.c: FLOW T.30 HDLC signal status is Carrier down (-1) in state 4
[Feb 9 15:57:47] DEBUG[15103] app_fax.c: FLOW T.30 Changing from phase T30_PHASE_B_RX to T30_PHASE_B_TX
[Feb 9 15:57:47] DEBUG[15103] app_fax.c: FLOW FAX Set rx type 0
[Feb 9 15:57:47] DEBUG[15103] app_fax.c: FLOW FAX Set tx type 4
[Feb 9 15:57:49] DEBUG[15103] app_fax.c: FLOW T.30 Send complete in phase T30_PHASE_B_TX, state 4
[Feb 9 15:57:49] DEBUG[15103] app_fax.c: FLOW T.30 DCS:
[Feb 9 15:57:49] DEBUG[15103] app_fax.c: FLOW T.30 .... ...0= Store and forward Internet fax (T.37): Not set
[Feb 9 15:57:49] DEBUG[15103] app_fax.c: FLOW T.30 .... .0..= Real-time Internet fax (T.38): Not set
[Feb 9 15:57:49] DEBUG[15103] app_fax.c: FLOW T.30 .... 0...= 3G mobile network: Not set
[Feb 9 15:57:49] DEBUG[15103] app_fax.c: FLOW T.30 .... ..1.= Receive fax: Set
[Feb 9 15:57:49] DEBUG[15103] app_fax.c: FLOW T.30 ..10 00..= Selected data signalling rate: V.17 14400bps
[Feb 9 15:57:49] DEBUG[15103] app_fax.c: FLOW T.30 .1.. ....= R8x7.7lines/mm and/or 200x200pels/25.4mm: Set
[Feb 9 15:57:49] DEBUG[15103] app_fax.c: FLOW T.30 1... ....= 2-D coding: Set
[Feb 9 15:57:49] DEBUG[15103] app_fax.c: FLOW T.30 .... ..00= Recording width: 215mm +- 1%
[Feb 9 15:57:49] DEBUG[15103] app_fax.c: FLOW T.30 .... 10..= Recording length: Unlimited
[Feb 9 15:57:49] DEBUG[15103] app_fax.c: FLOW T.30 .111 ....= Minimum scan line time: 0ms
[Feb 9 15:57:49] DEBUG[15103] app_fax.c: FLOW T.30 0... ....= Extension indicator: Not set
[Feb 9 15:57:49] DEBUG[15103] app_fax.c: FLOW T.30 Tx: DCS with final frame tag
[Feb 9 15:57:49] DEBUG[15103] app_fax.c: FLOW T.30 Tx: ff 13 83 00 e2 78
[Feb 9 15:57:50] DEBUG[15103] app_fax.c: FLOW T.30 Send complete in phase T30_PHASE_B_TX, state 4
[Feb 9 15:57:50] DEBUG[15103] app_fax.c: FLOW T.30 Send complete in phase T30_PHASE_B_TX, state 4
[Feb 9 15:57:50] DEBUG[15103] app_fax.c: FLOW T.30 Changing from state 4 to 5
[Feb 9 15:57:50] DEBUG[15103] app_fax.c: FLOW T.30 Changing from phase T30_PHASE_B_TX to T30_PHASE_C_NON_ECM_TX
[Feb 9 15:57:50] DEBUG[15103] app_fax.c: FLOW FAX Set rx type 0
[Feb 9 15:57:50] DEBUG[15103] app_fax.c: FLOW FAX Set rx type 0
[Feb 9 15:57:50] DEBUG[15103] app_fax.c: FLOW FAX Set tx type 7
[Feb 9 15:58:02] DEBUG[15103] app_fax.c: FLOW T.30 Send complete in phase T30_PHASE_C_NON_ECM_TX, state 5
[Feb 9 15:58:02] DEBUG[15103] app_fax.c: FLOW T.30 Changing from phase T30_PHASE_C_NON_ECM_TX to T30_PHASE_B_RX
[Feb 9 15:58:02] DEBUG[15103] app_fax.c: FLOW FAX Set rx type 4
[Feb 9 15:58:02] DEBUG[15103] app_fax.c: FLOW FAX Set tx type 0
[Feb 9 15:58:02] DEBUG[15103] app_fax.c: FLOW T.30 Start T4
[Feb 9 15:58:02] DEBUG[15103] app_fax.c: FLOW T.30 Changing from state 5 to 6
[Feb 9 15:58:02] DEBUG[15103] app_fax.c: FLOW T.30 HDLC signal status is Carrier up (-2) in state 6
[Feb 9 15:58:02] DEBUG[15103] app_fax.c: FLOW T.30 HDLC signal status is Framing OK (-6) in state 6
[Feb 9 15:58:02] DEBUG[15103] app_fax.c: FLOW T.30 Start T4A
[Feb 9 15:58:04] DEBUG[15103] app_fax.c: FLOW T.30 Stop T4A (12640 remaining)
[Feb 9 15:58:04] DEBUG[15103] app_fax.c: FLOW T.30 Rx: CSI without final frame tag
[Feb 9 15:58:04] DEBUG[15103] app_fax.c: FLOW T.30 Rx: ff 03 40 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20
[Feb 9 15:58:04] DEBUG[15103] app_fax.c: FLOW T.30 Remote gave CSI as: ""
[Feb 9 15:58:04] DEBUG[15103] app_fax.c: FLOW T.30 Stop none (0 remaining)
[Feb 9 15:58:04] DEBUG[15103] app_fax.c: FLOW T.30 Rx: DIS with final frame tag
[Feb 9 15:58:04] DEBUG[15103] app_fax.c: FLOW T.30 Rx: ff 13 80 00 ee 78
[Feb 9 15:58:04] DEBUG[15103] app_fax.c: FLOW T.30 In state 6
[Feb 9 15:58:04] DEBUG[15103] app_fax.c: FLOW T.30 Retry number 1
[Feb 9 15:58:04] DEBUG[15103] app_fax.c: FLOW T.30 DCS:
[Feb 9 15:58:04] DEBUG[15103] app_fax.c: FLOW T.30 .... ...0= Store and forward Internet fax (T.37): Not set
[Feb 9 15:58:04] DEBUG[15103] app_fax.c: FLOW T.30 .... .0..= Real-time Internet fax (T.38): Not set
[Feb 9 15:58:04] DEBUG[15103] app_fax.c: FLOW T.30 .... 0...= 3G mobile network: Not set
[Feb 9 15:58:04] DEBUG[15103] app_fax.c: FLOW T.30 .... ..1.= Receive fax: Set
[Feb 9 15:58:04] DEBUG[15103] app_fax.c: FLOW T.30 ..10 00..= Selected data signalling rate: V.17 14400bps
[Feb 9 15:58:04] DEBUG[15103] app_fax.c: FLOW T.30 .1.. ....= R8x7.7lines/mm and/or 200x200pels/25.4mm: Set
[Feb 9 15:58:04] DEBUG[15103] app_fax.c: FLOW T.30 1... ....= 2-D coding: Set
[Feb 9 15:58:04] DEBUG[15103] app_fax.c: FLOW T.30 .... ..00= Recording width: 215mm +- 1%
[Feb 9 15:58:04] DEBUG[15103] app_fax.c: FLOW T.30 .... 10..= Recording length: Unlimited
[Feb 9 15:58:04] DEBUG[15103] app_fax.c: FLOW T.30 .111 ....= Minimum scan line time: 0ms
[Feb 9 15:58:04] DEBUG[15103] app_fax.c: FLOW T.30 0... ....= Extension indicator: Not set
[Feb 9 15:58:04] DEBUG[15103] app_fax.c: FLOW T.30 Changing from state 6 to 4
[Feb 9 15:58:04] DEBUG[15103] app_fax.c: FLOW T.30 Sending ident '510'
[Feb 9 15:58:04] DEBUG[15103] app_fax.c: FLOW T.30 Tx: TSI without final frame tag
[Feb 9 15:58:04] DEBUG[15103] app_fax.c: FLOW T.30 Tx: ff 03 43 30 31 35 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20
[Feb 9 15:58:04] DEBUG[15103] app_fax.c: FLOW T.30 HDLC signal status is Carrier down (-1) in state 4
[Feb 9 15:58:04] DEBUG[15103] app_fax.c: FLOW T.30 Changing from phase T30_PHASE_B_RX to T30_PHASE_B_TX
[Feb 9 15:58:04] DEBUG[15103] app_fax.c: FLOW FAX Set rx type 0
[Feb 9 15:58:04] DEBUG[15103] app_fax.c: FLOW FAX Set tx type 4
[Feb 9 15:58:10] DEBUG[15103] app_fax.c: FLOW T.30 Send complete in phase T30_PHASE_B_TX, state 4
[Feb 9 15:58:10] DEBUG[15103] app_fax.c: FLOW T.30 DCS:
[Feb 9 15:58:10] DEBUG[15103] app_fax.c: FLOW T.30 .... ...0= Store and forward Internet fax (T.37): Not set
[Feb 9 15:58:10] DEBUG[15103] app_fax.c: FLOW T.30 .... .0..= Real-time Internet fax (T.38): Not set
[Feb 9 15:58:10] DEBUG[15103] app_fax.c: FLOW T.30 .... 0...= 3G mobile network: Not set
[Feb 9 15:58:10] DEBUG[15103] app_fax.c: FLOW T.30 .... ..1.= Receive fax: Set
[Feb 9 15:58:10] DEBUG[15103] app_fax.c: FLOW T.30 ..10 00..= Selected data signalling rate: V.17 14400bps
[Feb 9 15:58:10] DEBUG[15103] app_fax.c: FLOW T.30 .1.. ....= R8x7.7lines/mm and/or 200x200pels/25.4mm: Set
[Feb 9 15:58:10] DEBUG[15103] app_fax.c: FLOW T.30 1... ....= 2-D coding: Set
[Feb 9 15:58:10] DEBUG[15103] app_fax.c: FLOW T.30 .... ..00= Recording width: 215mm +- 1%
[Feb 9 15:58:10] DEBUG[15103] app_fax.c: FLOW T.30 .... 10..= Recording length: Unlimited
[Feb 9 15:58:10] DEBUG[15103] app_fax.c: FLOW T.30 .111 ....= Minimum scan line time: 0ms
[Feb 9 15:58:10] DEBUG[15103] app_fax.c: FLOW T.30 0... ....= Extension indicator: Not set
[Feb 9 15:58:10] DEBUG[15103] app_fax.c: FLOW T.30 Tx: DCS with final frame tag
[Feb 9 15:58:10] DEBUG[15103] app_fax.c: FLOW T.30 Tx: ff 13 83 00 e2 78
[Feb 9 15:58:10] DEBUG[15103] app_fax.c: FLOW T.30 Send complete in phase T30_PHASE_B_TX, state 4
[Feb 9 15:58:10] DEBUG[15103] app_fax.c: FLOW T.30 Send complete in phase T30_PHASE_B_TX, state 4
[Feb 9 15:58:10] DEBUG[15103] app_fax.c: FLOW T.30 Changing from state 4 to 5
[Feb 9 15:58:10] DEBUG[15103] app_fax.c: FLOW T.30 Changing from phase T30_PHASE_B_TX to T30_PHASE_C_NON_ECM_TX
[Feb 9 15:58:10] DEBUG[15103] app_fax.c: FLOW FAX Set rx type 0
[Feb 9 15:58:10] DEBUG[15103] app_fax.c: FLOW FAX Set rx type 0
[Feb 9 15:58:10] DEBUG[15103] app_fax.c: FLOW FAX Set tx type 7
[Feb 9 15:58:18] DEBUG[15103] app_fax.c: FLOW T.30 Changing from state 5 to 32
[Feb 9 15:58:18] DEBUG[15103] app_fax.c: FLOW T.30 Changing from phase T30_PHASE_C_NON_ECM_TX to T30_PHASE_CALL_FINISHED
[Feb 9 15:58:18] DEBUG[15103] app_fax.c: FLOW FAX Set rx type 8
[Feb 9 15:58:18] DEBUG[15103] app_fax.c: FLOW FAX FAX exchange complete
[Feb 9 15:58:18] DEBUG[15103] app_fax.c: FLOW FAX Set tx type 8
[Feb 9 15:58:18] DEBUG[15103] app_fax.c: FLOW FAX FAX exchange complete

Comments: By: Roberto La Rosa (rlr2maverick) 2010-02-10 07:04:32.000-0600

some further investigations lead us to te well known sequence

Got T.38 Re-invite without audio. Keeping RTP active during T.38 session.
SIP/2.0 488 Not acceptable here

by the way our dump stays under this common situation.

Our ATA model is audiocodes mp202
By: Leif Madsen (lmadsen) 2010-02-10 14:38:48.000-0600

You may also want to check the 1.6.1.15-rc2 that was just released to determine if the couple of T.38 changes that went in there may resolve this for you.

You'll need to provide a SIP trace and SIP history of this happening as well in order for a developer to review the issue.
By: Roberto La Rosa (rlr2maverick) 2010-02-10 15:09:39.000-0600

nice to meet you lmadsen,

the bug we're experiencing was submitted to further investigation these days.

We found it is bound to

488 Not acceptable here

error message in reply to a T.38 reinvite provided by either fax/ata with no audio codec (and no other codec), during initial channel mode switchover from audio to T.38 only transmitting a fax file with SendFAX application (app_fax.c).

We're using 1.6.1.14 brabnch with spandsp 0.0.6-pre17

In effects it sounds to be a chan_sip.c related problem during coded matching evaluation not considering T.38 proto just and already engaged. Logs will follow.
By: Roberto La Rosa (rlr2maverick) 2010-02-11 10:23:02.000-0600

dear lmadsen,

I'm considering a more specific case title as

"T.38 session fails with '488 Not acceptable here' if within 5 seconds there is no no "SIP 100 Trying" REINVITE reply from remote"

The code aborting the T.38 sip session is in chan_sip.c

19391 case AST_STATE_UP:
19392 ast_debug(2, "%s: This call is UP.... \n", c->name);
19393
19394 transmit_response(p, "100 Trying", req);
19395
19396 if (p->t38.state == T38_PEER_REINVITE) {
19397 --------------> p->t38id = ast_sched_add(sched, 5000, sip_t38_abort, dialog_ref(p, "passing dialog ptr into sched structure based on t38id for sip_t38_abort."));

Nothing comes from the fax/ATA and the session is terminated (while already sending out fax data).

Am I wrong when considering a patch where this delay is greater than 120 seconds ? (I'll try)
By: Roberto La Rosa (rlr2maverick) 2010-02-12 03:34:14.000-0600

good morning there

no chance to send fax altering in chan_sip.c from

19397 --------------> p->t38id = ast_sched_add(sched, 5000, sip_t38_abort, dialog_ref(p, "passing dialog ptr into sched structure based on t38id for sip_t38_abort."));

to

19397 --------------> p->t38id = ast_sched_add(sched, 185000, sip_t38_abort, dialog_ref(p, "passing dialog ptr into sched structure based on t38id for sip_t38_abort."));

waiting for the fax data to flow, while p->t38.state == T38_PEER_REINVITE only null frame format 5/0 len 0 goes from asterisk to the fax.

I'm not sure the reinvite reply to 'SIP/2.0 100 Trying' has to come directly from ATA/Fax or, missing it I would promote T.38 state from T38_PEER_REINVITE to T38_ENABLED waiting for eventual further errors from the peer if any.
By: Leif Madsen (lmadsen) 2010-02-22 15:42:44.000-0600

Updated subject per reporter.
By: Leif Madsen (lmadsen) 2010-02-22 15:43:52.000-0600

Thanks for the information. I think that should be enough for now. I have no other feedback for you as we'll need to wait for a developer to review this. Thanks for updating!
By: haggard (haggard) 2010-03-02 05:39:14.000-0600

hello,

I ran into a similar problem when I got a Session-Timer based reinvite with no audio parameters from a Fritz!Box after 15 mins. while receiving a fax over T.38. Asterisk answers the reinvite with 488 and the Fritz!Box drops the call. Could this also be based on this problem ?

[Mar 1 17:46:00] VERBOSE[2629] udptl.c: UDPTL (SIP/): packet from 192.168.10.70:7078 (type 0, seq 0, len 16)
[Mar 1 17:46:00] VERBOSE[2629] udptl.c: UDPTL (SIP/): packet from 192.168.10.70:7078 (type 0, seq 0, len 10)
[Mar 1 17:46:00] VERBOSE[2629] udptl.c: UDPTL (SIP/): packet from 192.168.10.70:7078 (type 0, seq 0, len 8)
[Mar 1 17:46:00] VERBOSE[1723] chan_sip.c:
<--- SIP read from UDP://192.168.10.17:5060 --->
INVITE sip:<hiddenusername>@192.168.10.251 SIP/2.0
Record-Route: <sip:192.168.10.17;lr=on;ftag=1DC6ABCA53CA5DFE>
Via: SIP/2.0/UDP 192.168.10.17;branch=z9hG4bKddcc.f9f07bc6.0
Via: SIP/2.0/UDP 192.168.10.70:5060;branch=z9hG4bK00F4D62CD74DEC94
From: <sip:<hiddenusername>@192.168.10.17>;tag=1DC6ABCA53CA5DFE
To: <sip:<hiddenusername>@192.168.10.17>;tag=as179c2945
Call-ID: 0D0ED0C1801A8404@192.168.10.70
CSeq: 3412 INVITE
Contact: <sip:<hiddenusername>@192.168.10.70;uniq=7C753EB6F51196D06B341D62CE1C7>
Max-Forwards: 69
Session-Expires: 1800;refresher=uac
Min-SE: 1800
X-Designated-Service: fax/t38
User-Agent: AVM FRITZ!Box Fon WLAN 7170 29.04.76 (Jul 13 2009)
Supported: 100rel,replaces,timer
Allow-Events: telephone-event,refer
Allow: INVITE,ACK,OPTIONS,CANCEL,BYE,UPDATE,PRACK,INFO,SUBSCRIBE,NOTIFY,REFER,MESSAGE,PUBLISH
Content-Type: application/sdp
Accept: application/sdp, multipart/mixed
Accept-Encoding: identity
Content-Length: 350

v=0
o=user 6496966 6496968 IN IP4 192.168.10.70
s=call
c=IN IP4 192.168.10.70
t=0 0
m=image 7078 udptl t38
a=T38FaxVersion:1
a=T38MaxBitRate:14400
a=T38FaxTranscodingMMR
a=T38FaxTranscodingJBIG
a=T38FaxRateManagement:transferredTCF
a=T38FaxUdpEC:t38UDPRedundancy
a=T38FaxUdpEC:t38UDPFEC
a=T38FaxMaxBuffer:512
a=T38FaxMaxDatagram:500

<------------->
[Mar 1 17:46:00] VERBOSE[1723] chan_sip.c: --- (24 headers 15 lines) ---

<------------->
[Mar 1 17:46:00] VERBOSE[1723] chan_sip.c: --- (24 headers 15 lines) ---
[Mar 1 17:46:00] VERBOSE[1723] chan_sip.c: Sending to 192.168.10.17 : 5060 (no NAT)
[Mar 1 17:46:00] VERBOSE[1723] chan_sip.c: Got T.38 offer in SDP in dialog 0D0ED0C1801A8404@192.168.10.70
[Mar 1 17:46:00] VERBOSE[1723] chan_sip.c: Capabilities: us - 0xc (ulaw|alaw), peer - audio=0x0 (nothing)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x0 (nothing)
[Mar 1 17:46:00] VERBOSE[1723] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x0 (nothing), combined - 0x0 (nothing)
[Mar 1 17:46:00] VERBOSE[1723] chan_sip.c: Got T.38 Re-invite without audio. Keeping RTP active during T.38 session.
[Mar 1 17:46:00] VERBOSE[1723] chan_sip.c:
<--- Transmitting (no NAT) to 192.168.10.17:5060 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 192.168.10.17;branch=z9hG4bKddcc.f9f07bc6.0;received=192.168.10.17
Via: SIP/2.0/UDP 192.168.10.70:5060;branch=z9hG4bK00F4D62CD74DEC94
Record-Route: <sip:192.168.10.17;lr=on;ftag=1DC6ABCA53CA5DFE>
From: <sip:<hiddenusername>@192.168.10.17>;tag=1DC6ABCA53CA5DFE
To: <sip:<hiddenusername>@192.168.10.17>;tag=as179c2945
Call-ID: 0D0ED0C1801A8404@192.168.10.70
CSeq: 3412 INVITE
Server: Fax2Mail1
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces, timer
Contact: <sip:<hiddenusername>@192.168.10.251>
Content-Length: 0

<------------>
[Mar 1 17:46:00] VERBOSE[2629] udptl.c: UDPTL (SIP/): packet from 192.168.10.70:7078 (type 0, seq 0, len 8)
[Mar 1 17:46:01] VERBOSE[2629] udptl.c: UDPTL (SIP/): packet from 192.168.10.70:7078 (type 0, seq 0, len 13)
[Mar 1 17:46:01] VERBOSE[2629] udptl.c: UDPTL (SIP/): packet from 192.168.10.70:7078 (type 0, seq 0, len 13)
[Mar 1 17:46:01] VERBOSE[2629] udptl.c: UDPTL (SIP/): packet from 192.168.10.70:7078 (type 0, seq 0, len 13)
[Mar 1 17:46:01] VERBOSE[2629] udptl.c: UDPTL (SIP/): packet from 192.168.10.70:7078 (type 0, seq 0, len 13)
[Mar 1 17:46:01] VERBOSE[2629] udptl.c: UDPTL (SIP/): packet from 192.168.10.70:7078 (type 0, seq 0, len 13)
[Mar 1 17:46:01] VERBOSE[2629] udptl.c: UDPTL (SIP/): packet from 192.168.10.70:7078 (type 0, seq 0, len 13)
[Mar 1 17:46:01] VERBOSE[2629] udptl.c: UDPTL (SIP/): packet from 192.168.10.70:7078 (type 0, seq 0, len 13)
[Mar 1 17:46:01] VERBOSE[2629] udptl.c: UDPTL (SIP/): packet from 192.168.10.70:7078 (type 0, seq 0, len 10)
[Mar 1 17:46:05] VERBOSE[1723] chan_sip.c:
<--- Reliably Transmitting (no NAT) to 192.168.10.17:5060 --->
SIP/2.0 488 Not acceptable here
Via: SIP/2.0/UDP 192.168.10.17;branch=z9hG4bKddcc.f9f07bc6.0;received=192.168.10.17
Via: SIP/2.0/UDP 192.168.10.70:5060;branch=z9hG4bK00F4D62CD74DEC94
From: <sip:<hiddenusername>@192.168.10.17>;tag=1DC6ABCA53CA5DFE
To: <sip:<hiddenusername>@192.168.10.17>;tag=as179c2945
Call-ID: 0D0ED0C1801A8404@192.168.10.70
CSeq: 3412 INVITE
Server: Fax2Mail1
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces, timer
Content-Length: 0
X-Asterisk-HangupCause: Normal Clearing
X-Asterisk-HangupCauseCode: 16

<------------>
[Mar 1 17:46:05] VERBOSE[1723] chan_sip.c:
<--- SIP read from UDP://192.168.10.17:5060 --->
ACK sip:<hiddenusername>@192.168.10.251 SIP/2.0
Via: SIP/2.0/UDP 192.168.10.17;branch=z9hG4bKddcc.f9f07bc6.0
From: <sip:<hiddenusername>@192.168.10.17>;tag=1DC6ABCA53CA5DFE
Call-ID: 0D0ED0C1801A8404@192.168.10.70
To: <sip:<hiddenusername>@192.168.10.17>;tag=as179c2945
CSeq: 3412 ACK
Max-Forwards: 70
User-Agent: openSER
Content-Length: 0

<------------->
[Mar 1 17:46:05] VERBOSE[1723] chan_sip.c: --- (9 headers 0 lines) ---
[Mar 1 17:46:07] VERBOSE[2629] udptl.c: UDPTL (SIP/): packet from 192.168.10.70:7078 (type 0, seq 0, len 8)
[Mar 1 17:46:07] VERBOSE[2629] udptl.c: UDPTL (SIP/): packet from 192.168.10.70:7078 (type 0, seq 0, len 13)
[Mar 1 17:46:07] VERBOSE[2629] udptl.c: UDPTL (SIP/): packet from 192.168.10.70:7078 (type 0, seq 0, len 13)
[Mar 1 17:46:07] VERBOSE[2629] udptl.c: UDPTL (SIP/): packet from 192.168.10.70:7078 (type 0, seq 0, len 13)
[Mar 1 17:46:08] VERBOSE[2629] udptl.c: UDPTL (SIP/): packet from 192.168.10.70:7078 (type 0, seq 0, len 13)
[Mar 1 17:46:08] VERBOSE[2629] udptl.c: UDPTL (SIP/): packet from 192.168.10.70:7078 (type 0, seq 0, len 13)
[Mar 1 17:46:08] VERBOSE[2629] udptl.c: UDPTL (SIP/): packet from 192.168.10.70:7078 (type 0, seq 0, len 13)
[Mar 1 17:46:08] VERBOSE[2629] udptl.c: UDPTL (SIP/): packet from 192.168.10.70:7078 (type 0, seq 0, len 13)
[Mar 1 17:46:08] VERBOSE[2629] udptl.c: UDPTL (SIP/): packet from 192.168.10.70:7078 (type 0, seq 0, len 10)
[Mar 1 17:46:13] VERBOSE[2629] udptl.c: UDPTL (SIP/): packet from 192.168.10.70:7078 (type 0, seq 0, len 8)
[Mar 1 17:46:14] VERBOSE[2629] udptl.c: UDPTL (SIP/): packet from 192.168.10.70:7078 (type 0, seq 0, len 13)
[Mar 1 17:46:14] VERBOSE[2629] udptl.c: UDPTL (SIP/): packet from 192.168.10.70:7078 (type 0, seq 0, len 13)
[Mar 1 17:46:14] VERBOSE[2629] udptl.c: UDPTL (SIP/): packet from 192.168.10.70:7078 (type 0, seq 0, len 13)
[Mar 1 17:46:14] VERBOSE[2629] udptl.c: UDPTL (SIP/): packet from 192.168.10.70:7078 (type 0, seq 0, len 13)
[Mar 1 17:46:14] VERBOSE[2629] udptl.c: UDPTL (SIP/): packet from 192.168.10.70:7078 (type 0, seq 0, len 13)
[Mar 1 17:46:14] VERBOSE[2629] udptl.c: UDPTL (SIP/): packet from 192.168.10.70:7078 (type 0, seq 0, len 13)
[Mar 1 17:46:14] VERBOSE[2629] udptl.c: UDPTL (SIP/): packet from 192.168.10.70:7078 (type 0, seq 0, len 13)
[Mar 1 17:46:14] VERBOSE[2629] udptl.c: UDPTL (SIP/): packet from 192.168.10.70:7078 (type 0, seq 0, len 10)
[Mar 1 17:46:19] VERBOSE[2629] udptl.c: UDPTL (SIP/): packet from 192.168.10.70:7078 (type 0, seq 0, len 8)
[Mar 1 17:46:20] VERBOSE[2629] udptl.c: UDPTL (SIP/): packet from 192.168.10.70:7078 (type 0, seq 0, len 13)
[Mar 1 17:46:20] VERBOSE[2629] udptl.c: UDPTL (SIP/): packet from 192.168.10.70:7078 (type 0, seq 0, len 13)
[Mar 1 17:46:20] VERBOSE[2629] udptl.c: UDPTL (SIP/): packet from 192.168.10.70:7078 (type 0, seq 0, len 13)
[Mar 1 17:46:20] VERBOSE[2629] udptl.c: UDPTL (SIP/): packet from 192.168.10.70:7078 (type 0, seq 0, len 10)
[Mar 1 17:46:21] VERBOSE[1723] chan_sip.c:
<--- SIP read from UDP://192.168.10.17:5060 --->
BYE sip:<hiddenusername>@192.168.10.251 SIP/2.0
Record-Route: <sip:192.168.10.17;lr=on;ftag=1DC6ABCA53CA5DFE>
Via: SIP/2.0/UDP 192.168.10.17;branch=z9hG4bKedcc.6c141d05.0
Via: SIP/2.0/UDP 192.168.10.70:5060;branch=z9hG4bK17AA5CEB003B3B81
From: <sip:<hiddenusername>@192.168.10.17>;tag=1DC6ABCA53CA5DFE
To: <sip:<hiddenusername>@192.168.10.17>;tag=as179c2945
Call-ID: 0D0ED0C1801A8404@192.168.10.70
CSeq: 3413 BYE
X-RTP-Stat: CS=1360;PS=5666;ES=0;OS=8400;SP=0/0;SO=0;QS=-;PR=305;ER=0;OR=0;CR=0;SR=0;QR=-;PL=0,0;BL=0;LS=0;RB=0/0;SB=0/0;EN=PCMA,FAX;DE=;JI=0,0;DL=0,0,0;IP=192.168.10.70,192.168.10.251:4483
Reason: Q.850; cause=16
Max-Forwards: 69
User-Agent: AVM FRITZ!Box Fon WLAN 7170 29.04.76 (Jul 13 2009)
Supported: 100rel,replaces,timer
Allow-Events: telephone-event,refer
Content-Length: 0
By: Russell Bryant (russell) 2011-07-27 13:41:37.954-0500

Per the Asterisk maintenance timeline page at http://www.asterisk.org/asterisk-versions maintenance (bug) support for the 1.4 and 1.6.x branches has ended. For continued maintenance support please move to the 1.8 branch which is a long term support (LTS) branch. For more information about branch support, please see https://wiki.asterisk.org/wiki/display/AST/Asterisk+Versions

If this is still an issue, please open a new issue so it can be re-triaged appropriately. Thanks!