[asterisk-bugs] [JIRA] (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
Joshua Colp (JIRA)
noreply at issues.asterisk.org
Thu Jul 28 09:46:56 CDT 2016
[ https://issues.asterisk.org/jira/browse/ASTERISK-15596?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Joshua Colp closed 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
> -----------------------------------------------------------------------------------------------------------------------------
>
> Key: ASTERISK-15596
> URL: https://issues.asterisk.org/jira/browse/ASTERISK-15596
> Project: Asterisk
> Issue Type: Bug
> Components: Applications/app_fax
> Reporter: Roberto La Rosa
>
> 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 at 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 at 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 at 172.18.32.68' of Request 102: Match Found
> [Feb 9 16:03:34] DEBUG[14904] chan_sip.c: Destroying SIP dialog 4750706c4958eb7305db96b976a68660 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 172.18.32.68' of Request 102: Match Found
> [Feb 9 16:03:44] DEBUG[14904] chan_sip.c: Destroying SIP dialog 79ee3adc7a5f512b118774681ee0a1de at 172.18.32.68
> [Feb 9 16:03:44] DEBUG[14904] chan_sip.c: Allocating new SIP dialog for 1437426b549382bc739a7dc854bbbbcc at 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 at 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 at 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 at 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 at 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 at 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
--
This message was sent by Atlassian JIRA
(v6.2#6252)
More information about the asterisk-bugs
mailing list