www.gsmopen.org ...low cost GSM for FreeSWITCH and Asterisk

I have similar problem like http://www.gsmopen.org/node/54
But patches that have been described there are did not help.

Channel always hangs, if i dialed incorrect number, and gsm-provider says:
"You have dialed the wrog number. Please check the number and try again".
Then i hanging up SIP-phone, SIP channel become free, but Celliax channel do not hanging up.

Log:

//============== HERE I BEGAN DIAL "incorrect" NUMBER =========================
[Jan 25 10:05:42] DEBUG[3211]: acl.c:490 ast_ouraddrfor: Found IP address for this socket
[Jan 25 10:05:42] DEBUG[3211]: chan_sip.c:2860 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 10.1.254.103:5060
== Using SIP RTP CoS mark 5
[Jan 25 10:05:42] DEBUG[3211]: chan_sip.c:4190 do_setnat: Setting NAT on RTP to Off
[Jan 25 10:05:42] DEBUG[3211]: chan_sip.c:6367 sip_alloc: Allocating new SIP dialog for 3322865512@10.1.244.174 - INVITE (With RTP)
[Jan 25 10:05:42] DEBUG[3211]: chan_sip.c:19451 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE
[Jan 25 10:05:42] DEBUG[3211]: chan_sip.c:4190 do_setnat: Setting NAT on RTP to Off
[Jan 25 10:05:42] DEBUG[3211]: chan_sip.c:2728 __sip_xmit: Trying to put 'SIP/2.0 401' onto UDP socket destined for 10.1.244.174:5060
[Jan 25 10:05:42] DEBUG[3211]: chan_sip.c:6433 find_call: = Found Their Call ID: 3322865512@10.1.244.174 Their Tag 1620856038 Our tag: as65089673
[Jan 25 10:05:42] DEBUG[3211]: chan_sip.c:19451 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE
[Jan 25 10:05:42] DEBUG[3211]: chan_sip.c:19470 handle_incoming: Ignoring SIP message because of retransmit (INVITE Seqno 1, ours 1)
[Jan 25 10:05:42] DEBUG[3211]: chan_sip.c:6433 find_call: = Found Their Call ID: 3322865512@10.1.244.174 Their Tag 1620856038 Our tag: as65089673
[Jan 25 10:05:42] DEBUG[3211]: chan_sip.c:19451 handle_incoming: **** Received ACK (6) - Command in SIP ACK
[Jan 25 10:05:42] DEBUG[3211]: chan_sip.c:3250 __sip_ack: Stopping retransmission on '3322865512@10.1.244.174' of Response 1: Match Found
[Jan 25 10:05:42] DEBUG[3211]: chan_sip.c:6433 find_call: = Found Their Call ID: 3322865512@10.1.244.174 Their Tag 1620856038 Our tag: as65089673
[Jan 25 10:05:42] DEBUG[3211]: chan_sip.c:19451 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE
[Jan 25 10:05:42] DEBUG[3211]: chan_sip.c:4190 do_setnat: Setting NAT on RTP to Off
[Jan 25 10:05:42] DEBUG[3211]: chan_sip.c:7057 process_sdp: Processing session-level SDP v=0... UNSUPPORTED.
[Jan 25 10:05:42] DEBUG[3211]: chan_sip.c:7057 process_sdp: Processing session-level SDP o=854 50054595 50054595 IN IP4 10.1.244.174... UNSUPPORTED.
[Jan 25 10:05:42] DEBUG[3211]: chan_sip.c:7057 process_sdp: Processing session-level SDP s=Cisco 7912 SIP Call... UNSUPPORTED.
[Jan 25 10:05:42] DEBUG[3211]: chan_sip.c:7057 process_sdp: Processing session-level SDP c=IN IP4 10.1.244.174... OK.
[Jan 25 10:05:42] DEBUG[3211]: chan_sip.c:7057 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED.
[Jan 25 10:05:42] DEBUG[3211]: chan_sip.c:7221 process_sdp: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000/1... OK.
[Jan 25 10:05:42] DEBUG[3211]: chan_sip.c:7221 process_sdp: Processing media-level (audio) SDP a=rtpmap:18 G729/8000/1... OK.
[Jan 25 10:05:42] DEBUG[3211]: chan_sip.c:7221 process_sdp: Processing media-level (audio) SDP a=fmtp:18 annexb=no... UNSUPPORTED.
[Jan 25 10:05:42] DEBUG[3211]: chan_sip.c:7221 process_sdp: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000/1... OK.
[Jan 25 10:05:42] DEBUG[3211]: chan_sip.c:7221 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK.
[Jan 25 10:05:42] DEBUG[3211]: chan_sip.c:7221 process_sdp: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED.
[Jan 25 10:05:42] DEBUG[3211]: chan_sip.c:7395 process_sdp: We're settling with these formats: 0xc (ulaw|alaw)
[Jan 25 10:05:42] DEBUG[3211]: chan_sip.c:17974 handle_request_invite: Checking SIP call limits for device 854
[Jan 25 10:05:42] DEBUG[3211]: chan_sip.c:4770 update_call_counter: Updating call counter for incoming call
[Jan 25 10:05:42] DEBUG[3211]: chan_sip.c:5747 sip_new: *** Our native formats are 0x4 (ulaw)
[Jan 25 10:05:42] DEBUG[3211]: chan_sip.c:5748 sip_new: *** Joint capabilities are 0xc (ulaw|alaw)
[Jan 25 10:05:42] DEBUG[3211]: chan_sip.c:5749 sip_new: *** Our capabilities are 0xe (gsm|ulaw|alaw)
[Jan 25 10:05:42] DEBUG[3211]: chan_sip.c:5750 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw)
[Jan 25 10:05:42] DEBUG[3211]: chan_sip.c:5778 sip_new: This channel will not be able to handle video.
[Jan 25 10:05:42] DEBUG[3211]: chan_sip.c:10958 build_route: build_route: Contact hop:
[Jan 25 10:05:42] DEBUG[3211]: chan_sip.c:18204 handle_request_invite: SIP/854-00000000: New call is still down.... Trying...
[Jan 25 10:05:42] DEBUG[3211]: chan_sip.c:2728 __sip_xmit: Trying to put 'SIP/2.0 100' onto UDP socket destined for 10.1.244.174:5060
[Jan 25 10:05:42] DEBUG[3211]: devicestate.c:452 ast_devstate_changed_literal: Notification of state change to be queued on device/channel SIP/854
[Jan 25 10:05:42] DEBUG[3201]: devicestate.c:325 _ast_device_state: No provider found, checking channel drivers for SIP - 854
[Jan 25 10:05:42] DEBUG[3201]: chan_sip.c:20720 sip_devicestate: Checking device state for peer 854
[Jan 25 10:05:42] DEBUG[3201]: devicestate.c:443 do_state_change: Changing state for SIP/854 - state 1 (Not in use)
[Jan 25 10:05:42] DEBUG[3212]: app_queue.c:772 handle_statechange: Device 'SIP/854' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jan 25 10:05:42] DEBUG[3251]: pbx.c:3119 pbx_extension_helper: Launching 'Macro'
-- Executing [8927480000@oao-all:1] Macro("SIP/854-00000000", "mobigat_tatar_megafon,8927480000") in new stack
[Jan 25 10:05:42] DEBUG[3251]: pbx.c:3119 pbx_extension_helper: Launching 'NoOp'
-- Executing [s@macro-mobigat_tatar_megafon:1] NoOp("SIP/854-00000000", ""Megafon Tatarstan - "8927480000") in new stack
[Jan 25 10:05:42] DEBUG[3251]: app_macro.c:355 _macro_exec: Executed application: NoOp
[Jan 25 10:05:42] DEBUG[3251]: pbx.c:3119 pbx_extension_helper: Launching 'Macro'
-- Executing [s@macro-mobigat_tatar_megafon:2] Macro("SIP/854-00000000", "mobigat,8927480000,silver,gold,ttk") in new stack
[Jan 25 10:05:42] DEBUG[3251]: pbx.c:3119 pbx_extension_helper: Launching 'Set'
-- Executing [s@macro-mobigat:1] Set("SIP/854-00000000", "numparam=1") in new stack
[Jan 25 10:05:42] DEBUG[3251]: app_macro.c:355 _macro_exec: Executed application: Set
[Jan 25 10:05:42] DEBUG[3251]: pbx.c:3020 pbx_substitute_variables_helper_full: Expression result is '2'
[Jan 25 10:05:42] DEBUG[3251]: pbx.c:3119 pbx_extension_helper: Launching 'Set'
-- Executing [s@macro-mobigat:2] Set("SIP/854-00000000", "numparam=2") in new stack
[Jan 25 10:05:42] DEBUG[3251]: app_macro.c:355 _macro_exec: Executed application: Set
[Jan 25 10:05:42] DEBUG[3251]: pbx.c:3119 pbx_extension_helper: Launching 'Goto'
-- Executing [s@macro-mobigat:3] Goto("SIP/854-00000000", "silver") in new stack
-- Goto (macro-mobigat,s,11)
[Jan 25 10:05:42] DEBUG[3251]: app_macro.c:355 _macro_exec: Executed application: Goto
[Jan 25 10:05:42] DEBUG[3251]: pbx.c:3119 pbx_extension_helper: Launching 'NoOp'
-- Executing [s@macro-mobigat:11] NoOp("SIP/854-00000000", ""Silver 2"") in new stack
[Jan 25 10:05:42] DEBUG[3251]: app_macro.c:355 _macro_exec: Executed application: NoOp
[Jan 25 10:05:42] DEBUG[3251]: pbx.c:3020 pbx_substitute_variables_helper_full: Expression result is '3'
[Jan 25 10:05:42] DEBUG[3251]: pbx.c:3119 pbx_extension_helper: Launching 'Set'
-- Executing [s@macro-mobigat:12] Set("SIP/854-00000000", "numparam=3") in new stack
[Jan 25 10:05:42] DEBUG[3251]: app_macro.c:355 _macro_exec: Executed application: Set
[Jan 25 10:05:42] DEBUG[3251]: pbx.c:3119 pbx_extension_helper: Launching 'Answer'
-- Executing [s@macro-mobigat:13] Answer("SIP/854-00000000", "") in new stack
[Jan 25 10:05:42] DEBUG[3251]: devicestate.c:452 ast_devstate_changed_literal: Notification of state change to be queued on device/channel SIP/854
[Jan 25 10:05:42] DEBUG[3201]: devicestate.c:325 _ast_device_state: No provider found, checking channel drivers for SIP - 854
[Jan 25 10:05:42] DEBUG[3201]: chan_sip.c:20720 sip_devicestate: Checking device state for peer 854
[Jan 25 10:05:42] DEBUG[3201]: devicestate.c:443 do_state_change: Changing state for SIP/854 - state 1 (Not in use)
[Jan 25 10:05:42] DEBUG[3212]: app_queue.c:772 handle_statechange: Device 'SIP/854' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jan 25 10:05:42] DEBUG[3251]: chan_sip.c:5305 sip_answer: SIP answering channel: SIP/854-00000000
[Jan 25 10:05:42] DEBUG[3251]: chan_sip.c:9199 transmit_response_with_sdp: Setting framing from config on incoming call
[Jan 25 10:05:42] DEBUG[3251]: chan_sip.c:8875 add_sdp: ** Our capability: 0xc (ulaw|alaw) Video flag: True Text flag: True
[Jan 25 10:05:42] DEBUG[3251]: chan_sip.c:8876 add_sdp: ** Our prefcodec: 0x0 (nothing)
[Jan 25 10:05:42] DEBUG[3251]: chan_sip.c:9008 add_sdp: -- Done with adding codecs to SDP
[Jan 25 10:05:42] DEBUG[3251]: channel.c:3043 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=43)
[Jan 25 10:05:42] DEBUG[3251]: chan_sip.c:9143 add_sdp: Done building SDP. Settling with this capability: 0xc (ulaw|alaw)
[Jan 25 10:05:42] DEBUG[3251]: chan_sip.c:2728 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.1.244.174:5060
[Jan 25 10:05:42] DEBUG[3211]: chan_sip.c:6433 find_call: = Found Their Call ID: 3322865512@10.1.244.174 Their Tag 1620856038 Our tag: as0c986154
[Jan 25 10:05:42] DEBUG[3211]: chan_sip.c:19451 handle_incoming: **** Received ACK (6) - Command in SIP ACK
[Jan 25 10:05:42] DEBUG[3211]: chan_sip.c:3250 __sip_ack: Stopping retransmission on '3322865512@10.1.244.174' of Response 2: Match Found
[Jan 25 10:05:43] DEBUG[3251]: app_macro.c:355 _macro_exec: Executed application: Answer
[Jan 25 10:05:43] DEBUG[3251]: pbx.c:3119 pbx_extension_helper: Launching 'Dial'
-- Executing [s@macro-mobigat:14] Dial("SIP/854-00000000", "Celliax/line1/8927480000,120") in new stack
[Jan 25 10:05:43] DEBUG[3251]: chan_celliax.c:564 celliax_request: rev [(nil)|b5d44bb0][DEBUG_PBX 564 ][none ][-1,-1,-1] ENTERING FUNC
[Jan 25 10:05:43] DEBUG[3251]: chan_celliax.c:568 celliax_request: rev [(nil)|b5d44bb0][DEBUG_PBX 568 ][none ][-1,-1,-1] Try to request type: Celliax, name: line1/8927480000, cause: 0, format: 64
[Jan 25 10:05:43] DEBUG[3251]: chan_celliax.c:593 celliax_request: rev [(nil)|b5d44bb0][DEBUG_PBX 593 ][line1 ][-1, 0, 0] Requesting: Celliax, name: line1/8927480000, format: 64
[Jan 25 10:05:43] DEBUG[3251]: chan_celliax.c:1138 celliax_new: rev [(nil)|b5d44bb0][DEBUG_PBX 1138 ][line1 ][-1, 0, 0] ENTERING FUNC
[Jan 25 10:05:43] DEBUG[3251]: celliax_additional.c:402 alsa_open_dev: rev [(nil)|b5d44bb0][DEBUG_SOUND 402 ][line1 ][-1, 0, 0] Acquired fd 46 from the poll descriptor
[Jan 25 10:05:43] DEBUG[3251]: celliax_additional.c:425 alsa_open_dev: rev [(nil)|b5d44bb0][DEBUG_SOUND 425 ][line1 ][-1, 0, 0] started!
[Jan 25 10:05:43] DEBUG[3251]: celliax_additional.c:437 alsa_open_dev: rev [(nil)|b5d44bb0][DEBUG_SOUND 437 ][line1 ][-1, 0, 0] ALSA handle = -1226685008
[Jan 25 10:05:43] DEBUG[3251]: celliax_additional.c:402 alsa_open_dev: rev [(nil)|b5d44bb0][DEBUG_SOUND 402 ][line1 ][-1, 0, 0] Acquired fd 47 from the poll descriptor
[Jan 25 10:05:43] DEBUG[3251]: celliax_additional.c:437 alsa_open_dev: rev [(nil)|b5d44bb0][DEBUG_SOUND 437 ][line1 ][-1, 0, 0] ALSA handle = -1226676904
[Jan 25 10:05:43] DEBUG[3251]: chan_celliax.c:1171 celliax_new: rev [(nil)|b5d44bb0][DEBUG_PBX 1171 ][line1 ][-1, 0, 0] new channel: name=Celliax/line1 requested_state=0
[Jan 25 10:05:43] DEBUG[3251]: chan_celliax.c:1255 celliax_new: rev [0xb6e36738|b5d44bb0][DEBUG_SERIAL 1255 ][line1 ][ 0, 0, 0] STARTED controldev_thread=3050318768 STOP=4294967294 NULL=4294967295
[Jan 25 10:05:43] DEBUG[3251]: chan_celliax.c:1267 celliax_new: rev [0xb6e36738|b5d44bb0][DEBUG_PBX 1267 ][line1 ][ 0, 0, 0] EXITING FUNC
[Jan 25 10:05:43] DEBUG[3251]: chan_celliax.c:625 celliax_request: rev [0xb6e36738|b5d44bb0][DEBUG_PBX 625 ][line1 ][ 0, 0, 0] EXITING FUNC
[Jan 25 10:05:43] DEBUG[3251]: rtp.c:1972 ast_rtp_make_compatible: Channel 'Celliax/line1' has no RTP, not doing anything
[Jan 25 10:05:43] DEBUG[3251]: channel.c:4280 ast_channel_inherit_variables: Not copying variable DIALEDTIME.
[Jan 25 10:05:43] DEBUG[3251]: channel.c:4280 ast_channel_inherit_variables: Not copying variable ANSWEREDTIME.
[Jan 25 10:05:43] DEBUG[3251]: channel.c:4280 ast_channel_inherit_variables: Not copying variable DIALEDPEERNAME.
[Jan 25 10:05:43] DEBUG[3251]: channel.c:4280 ast_channel_inherit_variables: Not copying variable DIALEDPEERNUMBER.
[Jan 25 10:05:43] DEBUG[3251]: channel.c:4280 ast_channel_inherit_variables: Not copying variable DIALSTATUS.
[Jan 25 10:05:43] DEBUG[3251]: channel.c:4280 ast_channel_inherit_variables: Not copying variable MACRO_DEPTH.
[Jan 25 10:05:43] DEBUG[3251]: channel.c:4280 ast_channel_inherit_variables: Not copying variable numparam.
[Jan 25 10:05:43] DEBUG[3251]: channel.c:4280 ast_channel_inherit_variables: Not copying variable ARG4.
[Jan 25 10:05:43] DEBUG[3251]: channel.c:4280 ast_channel_inherit_variables: Not copying variable ARG3.
[Jan 25 10:05:43] DEBUG[3251]: channel.c:4280 ast_channel_inherit_variables: Not copying variable ARG2.
[Jan 25 10:05:43] DEBUG[3251]: channel.c:4280 ast_channel_inherit_variables: Not copying variable ARG1.
[Jan 25 10:05:43] DEBUG[3251]: channel.c:4280 ast_channel_inherit_variables: Not copying variable MACRO_PRIORITY.
[Jan 25 10:05:43] DEBUG[3251]: channel.c:4280 ast_channel_inherit_variables: Not copying variable MACRO_CONTEXT.
[Jan 25 10:05:43] DEBUG[3251]: channel.c:4280 ast_channel_inherit_variables: Not copying variable MACRO_EXTEN.
[Jan 25 10:05:43] DEBUG[3251]: channel.c:4280 ast_channel_inherit_variables: Not copying variable SIPCALLID.
[Jan 25 10:05:43] DEBUG[3251]: channel.c:4280 ast_channel_inherit_variables: Not copying variable SIPDOMAIN.
[Jan 25 10:05:43] DEBUG[3251]: channel.c:4280 ast_channel_inherit_variables: Not copying variable SIPURI.
[Jan 25 10:05:43] DEBUG[3251]: chan_celliax.c:1006 celliax_call: rev [0xb6e36738|b5d44bb0][DEBUG_PBX 1006 ][line1 ][ 0, 0, 0] ENTERING FUNC
[Jan 25 10:05:43] DEBUG[3251]: chan_celliax.c:1020 celliax_call: rev [0xb6e36738|b5d44bb0][DEBUG_PBX 1020 ][line1 ][ 0, 0, 0] celliax_call to call idest: line1/8927480000, timeout: 0!
[Jan 25 10:05:43] DEBUG[3251]: chan_celliax.c:1041 celliax_call: rev [0xb6e36738|b5d44bb0][DEBUG_PBX 1041 ][line1 ][ 0, 0, 0] celliax_call dialing idest: line1/8927480000, timeout: 0, dstr: 8927480000!
[Jan 25 10:05:43] DEBUG[3251]: devicestate.c:452 ast_devstate_changed_literal: Notification of state change to be queued on device/channel Celliax/line1
[Jan 25 10:05:43] DEBUG[3201]: devicestate.c:325 _ast_device_state: No provider found, checking channel drivers for Celliax - line1
[Jan 25 10:05:43] DEBUG[3201]: chan_celliax.c:499 celliax_devicestate: rev [0xb6e36738|b71bbbb0][DEBUG_PBX 499 ][line1 ][ 3, 0, 0] Interface is OWNED by a channel
[Jan 25 10:05:43] DEBUG[3201]: devicestate.c:443 do_state_change: Changing state for Celliax/line1 - state 2 (In use)
[Jan 25 10:05:43] DEBUG[3212]: app_queue.c:772 handle_statechange: Device 'Celliax/line1' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Jan 25 10:05:43] DEBUG[3251]: celliax_additional.c:2947 celliax_serial_call_AT: rev [0xb6e36738|b5d44bb0][DEBUG_PBX 2947 ][line1 ][ 3, 0, 0] Dialing 8927480000
[Jan 25 10:05:43] DEBUG[3251]: celliax_additional.c:2549 celliax_serial_write_AT_expect1: rev [0xb6e36738|b5d44bb0][DEBUG_AT 2549 ][line1 ][ 3, 3, 3] sending: ATD8927480000;, expecting: OK
[Jan 25 10:05:43] DEBUG[3251]: celliax_additional.c:2398 celliax_serial_write_AT: rev [0xb6e36738|b5d44bb0][DEBUG_AT 2398 ][line1 ][ 3, 3, 3] sent data... (A)
[Jan 25 10:05:43] DEBUG[3254]: chan_celliax.c:2527 celliax_do_controldev_thread: rev [0xb6e36738|b5d02bb0][DEBUG_SERIAL 2527 ][line1 ][ 3, 3, 3] In celliax_do_controldev_thread: started, p=0xb6a78008
[Jan 25 10:05:43] DEBUG[3251]: celliax_additional.c:2398 celliax_serial_write_AT: rev [0xb6e36738|b5d44bb0][DEBUG_AT 2398 ][line1 ][ 3, 3, 3] sent data... (T)
[Jan 25 10:05:43] DEBUG[3251]: celliax_additional.c:2398 celliax_serial_write_AT: rev [0xb6e36738|b5d44bb0][DEBUG_AT 2398 ][line1 ][ 3, 3, 3] sent data... (D)
[Jan 25 10:05:43] DEBUG[3251]: celliax_additional.c:2398 celliax_serial_write_AT: rev [0xb6e36738|b5d44bb0][DEBUG_AT 2398 ][line1 ][ 3, 3, 3] sent data... (8)
[Jan 25 10:05:43] DEBUG[3251]: celliax_additional.c:2398 celliax_serial_write_AT: rev [0xb6e36738|b5d44bb0][DEBUG_AT 2398 ][line1 ][ 3, 3, 3] sent data... (9)
[Jan 25 10:05:43] DEBUG[3251]: celliax_additional.c:2398 celliax_serial_write_AT: rev [0xb6e36738|b5d44bb0][DEBUG_AT 2398 ][line1 ][ 3, 3, 3] sent data... (2)
[Jan 25 10:05:43] DEBUG[3251]: celliax_additional.c:2398 celliax_serial_write_AT: rev [0xb6e36738|b5d44bb0][DEBUG_AT 2398 ][line1 ][ 3, 3, 3] sent data... (7)
[Jan 25 10:05:43] DEBUG[3251]: celliax_additional.c:2398 celliax_serial_write_AT: rev [0xb6e36738|b5d44bb0][DEBUG_AT 2398 ][line1 ][ 3, 3, 3] sent data... (4)
[Jan 25 10:05:43] DEBUG[3251]: celliax_additional.c:2398 celliax_serial_write_AT: rev [0xb6e36738|b5d44bb0][DEBUG_AT 2398 ][line1 ][ 3, 3, 3] sent data... (8)
[Jan 25 10:05:43] DEBUG[3251]: celliax_additional.c:2398 celliax_serial_write_AT: rev [0xb6e36738|b5d44bb0][DEBUG_AT 2398 ][line1 ][ 3, 3, 3] sent data... (0)
[Jan 25 10:05:43] DEBUG[3251]: celliax_additional.c:2398 celliax_serial_write_AT: rev [0xb6e36738|b5d44bb0][DEBUG_AT 2398 ][line1 ][ 3, 3, 3] sent data... (0)
[Jan 25 10:05:43] DEBUG[3251]: celliax_additional.c:2398 celliax_serial_write_AT: rev [0xb6e36738|b5d44bb0][DEBUG_AT 2398 ][line1 ][ 3, 3, 3] sent data... (0)
[Jan 25 10:05:43] DEBUG[3251]: celliax_additional.c:2398 celliax_serial_write_AT: rev [0xb6e36738|b5d44bb0][DEBUG_AT 2398 ][line1 ][ 3, 3, 3] sent data... (0)
[Jan 25 10:05:43] DEBUG[3251]: celliax_additional.c:2398 celliax_serial_write_AT: rev [0xb6e36738|b5d44bb0][DEBUG_AT 2398 ][line1 ][ 3, 3, 3] sent data... (;)
[Jan 25 10:05:43] DEBUG[3251]: celliax_additional.c:2428 celliax_serial_write_AT: rev [0xb6e36738|b5d44bb0][DEBUG_AT 2428 ][line1 ][ 3, 3, 3] sent (carriage return)
[Jan 25 10:05:43] DEBUG[3251]: celliax_additional.c:1346 celliax_serial_read_AT: rev [0xb6e36738|b5d44bb0][DEBUG_AT 1346 ][line1 ][ 3, 3, 3] Read line 0: |OK|
[Jan 25 10:05:43] DEBUG[3251]: celliax_additional.c:2161 celliax_serial_read_AT: rev [0xb6e36738|b5d44bb0][DEBUG_AT 2161 ][line1 ][ 3, 3, 3] |OK| got what EXPECTED
[Jan 25 10:05:43] DEBUG[3251]: chan_celliax.c:1059 celliax_call: rev [0xb6e36738|b5d44bb0][DEBUG_PBX 1059 ][line1 ][ 3, 3, 3] call ongoing
[Jan 25 10:05:43] DEBUG[3251]: chan_celliax.c:1065 celliax_call: rev [0xb6e36738|b5d44bb0][DEBUG_PBX 1065 ][line1 ][ 3, 3, 3] celliax_call dialed idest: line1/8927480000, timeout: 0, dstr: 8927480000!
[Jan 25 10:05:43] DEBUG[3251]: chan_celliax.c:1068 celliax_call: rev [0xb6e36738|b5d44bb0][DEBUG_PBX 1068 ][line1 ][ 3, 3, 3] EXITING FUNC
-- Called line1/8927480000
[Jan 25 10:05:43] DEBUG[3251]: channel.c:3673 set_format: Set channel Celliax/line1 to read format ulaw
[Jan 25 10:05:43] DEBUG[3251]: channel.c:3673 set_format: Set channel SIP/854-00000000 to read format slin
[Jan 25 10:05:43] DEBUG[3251]: channel.c:3673 set_format: Set channel Celliax/line1 to write format slin
-- Celliax/line1 is ringing
[Jan 25 10:05:43] DEBUG[3251]: channel.c:3196 ast_indicate_data: Driver for channel 'SIP/854-00000000' does not support indication 3, emulating it
[Jan 25 10:05:43] DEBUG[3251]: channel.c:3673 set_format: Set channel SIP/854-00000000 to write format slin
[Jan 25 10:05:43] DEBUG[3251]: channel.c:2380 ast_settimeout: Scheduling timer at 160 sample intervals
[Jan 25 10:05:43] DEBUG[3251]: chan_celliax.c:903 celliax_read: rev [0xb6e36738|b5d44bb0][DEBUG_SOUND 903 ][line1 ][ 3, 3, 3] DTMF recognition inited
[Jan 25 10:05:43] DEBUG[3251]: channel.c:3673 set_format: Set channel SIP/854-00000000 to write format ulaw
[Jan 25 10:05:43] DEBUG[3251]: channel.c:2380 ast_settimeout: Scheduling timer at 0 sample intervals
[Jan 25 10:05:43] DEBUG[3251]: rtp.c:3296 ast_rtp_write: Ooh, format changed from unknown to ulaw
[Jan 25 10:05:43] DEBUG[3251]: rtp.c:3312 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160
[Jan 25 10:05:45] DEBUG[3254]: celliax_additional.c:1346 celliax_serial_read_AT: rev [0xb6e36738|b5d02bb0][DEBUG_AT 1346 ][line1 ][ 3, 3, 3] Read line 0: |+CSSI: 1|
[Jan 25 10:05:45] DEBUG[3254]: celliax_additional.c:1639 celliax_serial_read_AT: rev [0xb6e36738|b5d02bb0][DEBUG_AT 1639 ][line1 ][ 3, 3, 3] |+CSSI: 1| CALLFLOW_CALL_DIALING

//============== HERE I HEARD "You have dialed the wrog number", AND I HUNG UP SIP PHONE =========================
[Jan 25 10:05:55] DEBUG[3211]: chan_sip.c:6433 find_call: = Found Their Call ID: 3322865512@10.1.244.174 Their Tag 1620856038 Our tag: as0c986154
[Jan 25 10:05:55] DEBUG[3211]: chan_sip.c:19451 handle_incoming: **** Received BYE (8) - Command in SIP BYE
[Jan 25 10:05:55] DEBUG[3211]: chan_sip.c:2462 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 3322865512@10.1.244.174
[Jan 25 10:05:55] DEBUG[3211]: chan_sip.c:18973 handle_request_bye: Received bye, issuing owner hangup
[Jan 25 10:05:55] DEBUG[3211]: chan_sip.c:2728 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.1.244.174:5060
[Jan 25 10:05:55] DEBUG[3251]: rtp.c:1898 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything
[Jan 25 10:05:55] DEBUG[3251]: channel.c:1721 ast_hangup: Hanging up channel 'Celliax/line1'
[Jan 25 10:05:55] DEBUG[3251]: chan_celliax.c:648 celliax_hangup: rev [0xb6e36738|b5d44bb0][DEBUG_PBX 648 ][line1 ][ 3, 3, 3] ENTERING FUNC
[Jan 25 10:05:55] DEBUG[3254]: chan_celliax.c:441 celliax_unlocka_log: [b5d02bb0] I'm a dying thread, and I'm to go unlocking mutex 0xb6af9358 for the 0th time
[Jan 25 10:05:55] DEBUG[3254]: chan_celliax.c:441 celliax_unlocka_log: [b5d02bb0] I'm a dying thread, and I'm to go unlocking mutex 0xb6af9358 for the 1th time
[Jan 25 10:05:55] DEBUG[3254]: chan_celliax.c:441 celliax_unlocka_log: [b5d02bb0] I'm a dying thread, and I'm to go unlocking mutex 0xb6af9358 for the 2th time
[Jan 25 10:05:55] DEBUG[3254]: chan_celliax.c:441 celliax_unlocka_log: [b5d02bb0] I'm a dying thread, and I'm to go unlocking mutex 0xb6af9358 for the 3th time
[Jan 25 10:05:55] DEBUG[3254]: chan_celliax.c:441 celliax_unlocka_log: [b5d02bb0] I'm a dying thread, and I'm to go unlocking mutex 0xb6af9358 for the 4th time
[Jan 25 10:05:55] DEBUG[3254]: chan_celliax.c:448 celliax_unlocka_log: [b5d02bb0] I'm a dying thread, I've finished unlocking mutex 0xb6af9358
[Jan 25 10:05:55] DEBUG[3251]: celliax_additional.c:2549 celliax_serial_write_AT_expect1: rev [0xb6e36738|b5d44bb0][DEBUG_AT 2549 ][line1 ][ 3, 3, 3] sending: ATH, expecting: OK
[Jan 25 10:05:55] DEBUG[3251]: celliax_additional.c:2398 celliax_serial_write_AT: rev [0xb6e36738|b5d44bb0][DEBUG_AT 2398 ][line1 ][ 3, 3, 3] sent data... (A)
[Jan 25 10:05:55] DEBUG[3251]: celliax_additional.c:2398 celliax_serial_write_AT: rev [0xb6e36738|b5d44bb0][DEBUG_AT 2398 ][line1 ][ 3, 3, 3] sent data... (T)
[Jan 25 10:05:55] DEBUG[3251]: celliax_additional.c:2398 celliax_serial_write_AT: rev [0xb6e36738|b5d44bb0][DEBUG_AT 2398 ][line1 ][ 3, 3, 3] sent data... (H)
[Jan 25 10:05:55] DEBUG[3251]: celliax_additional.c:2428 celliax_serial_write_AT: rev [0xb6e36738|b5d44bb0][DEBUG_AT 2428 ][line1 ][ 3, 3, 3] sent (carriage return)
[Jan 25 10:05:55] DEBUG[3251]: celliax_additional.c:1346 celliax_serial_read_AT: rev [0xb6e36738|b5d44bb0][DEBUG_AT 1346 ][line1 ][ 3, 3, 3] Read line 0: |NO CARRIER|
[Jan 25 10:05:55] DEBUG[3251]: celliax_additional.c:1489 celliax_serial_read_AT: rev [0xb6e36738|b5d44bb0][DEBUG_AT 1489 ][line1 ][ 3, 3,102] |NO CARRIER| CALLFLOW_CALL_NOCARRIER
[Jan 25 10:05:55] DEBUG[3251]: chan_celliax.c:463 celliax_queue_control: rev [0xb6e36738|b5d44bb0][DEBUG_PBX 463 ][line1 ][ 3, 3,102] Queued CONTROL FRAME 1