Linux 2.6.18-6-686
Asterisk 1.4.27
Mobigater S4
----------------
Schema:
http://yfrog.com/5cmobigaterj
RUSSIAN:
После того, как первый пользователь позвонил на мобильный телефон, создается два канала - канал между Астерисками и канал celliax. После завершения звонка модуль celliax посылает команду ATH, ожидая услышать в ответ OK. Но Mobigater почему то вместо ОК иногда отвечает NO CARRIER. В следствии чего канал подвисает и убить его можно только перезагрузкой Asterisk. Другие пользователи уже позвонить не могут. Случается так не каждый раз, а как-то бессистемно.
----------------
ENGLISH:
First user call to number: 80295566066
Second user call to number: 80296603885
Quote:gsm*CLI> core show channels
Channel Location State Application(Data)
Celliax/line0 80296603885@incoming Dialing AppDial((Outgoing Line))
SIP/sta-pbx-2-000000 80296603885@outbound Ring Dial(Celliax/line0/80296603885
Celliax/line2 (None) Up AppDial((Outgoing Line))
SIP/sta-pbx-2-000000 80295566066@outbound Up Dial(Celliax/line2/80295566066
4 active channels
2 active calls
First user end call:
Quote:gsm*CLI> core show channels
Channel Location State Application(Data)
Celliax/line0 (None) Up AppDial((Outgoing Line))
SIP/sta-pbx-2-000000 80296603885@outbound Up Dial(Celliax/line0/80296603885
2 active channels
1 active call
Second user end call:
Quote:gsm*CLI> core show channels
Channel Location State Application(Data)
SIP/sta-pbx-2-000000 80296603885@outbound Up Dial(Celliax/line0/80296603885
1 active channel
1 active call
But channel still alive!
Debug log:
[Jan 20 12:32:15] DEBUG[19063] chan_sip.c: Allocating new SIP dialog for 21b9936c0ed247e85266cd610c08023d@192.168.5.253 - INVITE (With RTP)
[Jan 20 12:32:15] DEBUG[19063] chan_sip.c: Setting NAT on RTP to Off
[Jan 20 12:32:15] DEBUG[19063] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED.
[Jan 20 12:32:15] DEBUG[19063] chan_sip.c: Processing session-level SDP o=root 2280 2280 IN IP4 192.168.5.253... UNSUPPORTED.
[Jan 20 12:32:15] DEBUG[19063] chan_sip.c: Processing session-level SDP s=session... UNSUPPORTED.
[Jan 20 12:32:15] DEBUG[19063] chan_sip.c: Processing session-level SDP c=IN IP4 192.168.5.253... OK.
[Jan 20 12:32:15] DEBUG[19063] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED.
[Jan 20 12:32:15] DEBUG[19063] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK.
[Jan 20 12:32:15] DEBUG[19063] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK.
[Jan 20 12:32:15] DEBUG[19063] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK.
[Jan 20 12:32:15] DEBUG[19063] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-16... UNSUPPORTED.
[Jan 20 12:32:15] DEBUG[19063] chan_sip.c: Processing media-level (audio) SDP a=silenceSupp:off - - - -... UNSUPPORTED.
[Jan 20 12:32:15] DEBUG[19063] chan_sip.c: Processing media-level (audio) SDP a=ptime:20... OK.
[Jan 20 12:32:15] DEBUG[19063] chan_sip.c: T38 state changed to 0 on channel
[Jan 20 12:32:15] DEBUG[19063] chan_sip.c: We're settling with these formats: 0x4 (ulaw)
[Jan 20 12:32:15] DEBUG[19063] chan_sip.c: Checking SIP call limits for device gsm-1
[Jan 20 12:32:15] DEBUG[19063] chan_sip.c: Updating call counter for incoming call
[Jan 20 12:32:15] DEBUG[19063] chan_sip.c: *** Our native formats are 0x4 (ulaw)
[Jan 20 12:32:15] DEBUG[19063] chan_sip.c: *** Joint capabilities are 0x4 (ulaw)
[Jan 20 12:32:15] DEBUG[19063] chan_sip.c: *** Our capabilities are 0x4 (ulaw)
[Jan 20 12:32:15] DEBUG[19063] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw)
[Jan 20 12:32:15] DEBUG[19063] chan_sip.c: This channel will not be able to handle video.
[Jan 20 12:32:15] DEBUG[19063] chan_sip.c: build_route: Contact hop:
[Jan 20 12:32:15] DEBUG[19063] chan_sip.c: SIP/sta-pbx-2-00000002: New call is still down.... Trying...
[Jan 20 12:32:15] DEBUG[19063] devicestate.c: Notification of state change to be queued on device/channel SIP/sta-pbx-2
[Jan 20 12:32:15] DEBUG[19135] pbx.c: Launching 'Goto'
[Jan 20 12:32:15] VERBOSE[19135] logger.c: -- Executing [80295566066@interoffice:1] Goto("SIP/sta-pbx-2-00000002", "outbound|80295566066|1") in new stack
[Jan 20 12:32:15] VERBOSE[19135] logger.c: -- Goto (outbound,80295566066,1)
[Jan 20 12:32:15] DEBUG[19135] pbx.c: Launching 'Dial'
[Jan 20 12:32:15] VERBOSE[19135] logger.c: -- Executing [80295566066@outbound:1] Dial("SIP/sta-pbx-2-00000002", "Celliax/line2/80295566066") in new stack
[Jan 20 12:32:15] DEBUG[19135] chan_celliax.c: rev exported[(nil)|b64d1bb0][DEBUG_PBX 564 ][none ][-1,-1,-1] ENTERING FUNC
[Jan 20 12:32:15] DEBUG[19135] chan_celliax.c: rev exported[(nil)|b64d1bb0][DEBUG_PBX 568 ][none ][-1,-1,-1] Try to request type: Celliax, name: line2/80295566066, cause: 0, format: 64
[Jan 20 12:32:15] DEBUG[19135] chan_celliax.c: rev exported[(nil)|b64d1bb0][DEBUG_PBX 593 ][line2 ][-1, 0, 0] Requesting: Celliax, name: line2/80295566066, format: 64
[Jan 20 12:32:15] DEBUG[19135] chan_celliax.c: rev exported[(nil)|b64d1bb0][DEBUG_PBX 1138 ][line2 ][-1, 0, 0] ENTERING FUNC
[Jan 20 12:32:15] DEBUG[19045] chan_sip.c: Checking device state for peer sta-pbx-2
[Jan 20 12:32:15] DEBUG[19045] devicestate.c: Changing state for SIP/sta-pbx-2 - state 1 (Not in use)
[Jan 20 12:32:15] DEBUG[19048] app_queue.c: Device 'SIP/sta-pbx-2' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jan 20 12:32:15] DEBUG[19135] celliax_additional.c: rev exported[(nil)|b64d1bb0][DEBUG_SOUND 402 ][line2 ][-1, 0, 0] Acquired fd 42 from the poll descriptor
[Jan 20 12:32:15] DEBUG[19135] celliax_additional.c: rev exported[(nil)|b64d1bb0][DEBUG_SOUND 425 ][line2 ][-1, 0, 0] started!
[Jan 20 12:32:15] DEBUG[19135] celliax_additional.c: rev exported[(nil)|b64d1bb0][DEBUG_SOUND 437 ][line2 ][-1, 0, 0] ALSA handle = 138621784
[Jan 20 12:32:15] DEBUG[19135] celliax_additional.c: rev exported[(nil)|b64d1bb0][DEBUG_SOUND 402 ][line2 ][-1, 0, 0] Acquired fd 43 from the poll descriptor
[Jan 20 12:32:15] DEBUG[19135] celliax_additional.c: rev exported[(nil)|b64d1bb0][DEBUG_SOUND 437 ][line2 ][-1, 0, 0] ALSA handle = 138629392
[Jan 20 12:32:15] DEBUG[19135] chan_celliax.c: rev exported[(nil)|b64d1bb0][DEBUG_PBX 1171 ][line2 ][-1, 0, 0] new channel: name=Celliax/line2 requested_state=0
[Jan 20 12:32:15] DEBUG[19135] chan_celliax.c: rev exported[0x842b010|b64d1bb0][DEBUG_SERIAL 1255 ][line2 ][ 0, 0, 0] STARTED controldev_thread=3058228144 STOP=4294967294 NULL=4294967295
[Jan 20 12:32:15] DEBUG[19135] chan_celliax.c: rev exported[0x842b010|b64d1bb0][DEBUG_PBX 1267 ][line2 ][ 0, 0, 0] EXITING FUNC
[Jan 20 12:32:15] DEBUG[19135] chan_celliax.c: rev exported[0x842b010|b64d1bb0][DEBUG_PBX 625 ][line2 ][ 0, 0, 0] EXITING FUNC
[Jan 20 12:32:16] DEBUG[19135] rtp.c: Channel 'Celliax/line2' has no RTP, not doing anything
[Jan 20 12:32:16] DEBUG[19135] channel.c: Not copying variable DIALEDTIME.
[Jan 20 12:32:16] DEBUG[19135] channel.c: Not copying variable ANSWEREDTIME.
[Jan 20 12:32:16] DEBUG[19135] channel.c: Not copying variable DIALEDPEERNAME.
[Jan 20 12:32:16] DEBUG[19135] channel.c: Not copying variable DIALEDPEERNUMBER.
[Jan 20 12:32:16] DEBUG[19135] channel.c: Not copying variable DIALSTATUS.
[Jan 20 12:32:16] DEBUG[19135] channel.c: Not copying variable SIPCALLID.
[Jan 20 12:32:16] DEBUG[19135] channel.c: Not copying variable SIPUSERAGENT.
[Jan 20 12:32:16] DEBUG[19135] channel.c: Not copying variable SIPDOMAIN.
[Jan 20 12:32:16] DEBUG[19135] channel.c: Not copying variable SIPURI.
[Jan 20 12:32:16] DEBUG[19135] chan_celliax.c: rev exported[0x842b010|b64d1bb0][DEBUG_PBX 1006 ][line2 ][ 0, 0, 0] ENTERING FUNC
[Jan 20 12:32:16] DEBUG[19135] chan_celliax.c: rev exported[0x842b010|b64d1bb0][DEBUG_PBX 1020 ][line2 ][ 0, 0, 0] celliax_call to call idest: line2/80295566066, timeout: 0!
[Jan 20 12:32:16] DEBUG[19135] chan_celliax.c: rev exported[0x842b010|b64d1bb0][DEBUG_PBX 1041 ][line2 ][ 0, 0, 0] celliax_call dialing idest: line2/80295566066, timeout: 0, dstr: 80295566066!
[Jan 20 12:32:16] DEBUG[19135] devicestate.c: Notification of state change to be queued on device/channel Celliax/line2
[Jan 20 12:32:16] DEBUG[19045] chan_celliax.c: rev exported[0x842b010|b7dc7bb0][DEBUG_PBX 499 ][line2 ][ 3, 0, 0] Interface is OWNED by a channel
[Jan 20 12:32:16] DEBUG[19045] devicestate.c: Changing state for Celliax/line2 - state 2 (In use)
[Jan 20 12:32:16] DEBUG[19048] app_queue.c: Device 'Celliax/line2' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Jan 20 12:32:16] DEBUG[19135] celliax_additional.c: rev exported[0x842b010|b64d1bb0][DEBUG_PBX 2945 ][line2 ][ 3, 0, 0] Dialing 80295566066
[Jan 20 12:32:16] DEBUG[19135] celliax_additional.c: rev exported[0x842b010|b64d1bb0][DEBUG_AT 2547 ][line2 ][ 3, 3, 3] sending: ATD80295566066;, expecting: OK
[Jan 20 12:32:16] DEBUG[19135] celliax_additional.c: rev exported[0x842b010|b64d1bb0][DEBUG_AT 2396 ][line2 ][ 3, 3, 3] sent data... (A)
[Jan 20 12:32:16] DEBUG[19138] chan_celliax.c: rev exported[0x842b010|b648dbb0][DEBUG_SERIAL 2527 ][line2 ][ 0, 0, 0] In celliax_do_controldev_thread: started, p=0xb77df008
[Jan 20 12:32:16] DEBUG[19135] celliax_additional.c: rev exported[0x842b010|b64d1bb0][DEBUG_AT 2396 ][line2 ][ 3, 3, 3] sent data... (T)
[Jan 20 12:32:16] DEBUG[19135] celliax_additional.c: rev exported[0x842b010|b64d1bb0][DEBUG_AT 2396 ][line2 ][ 3, 3, 3] sent data... (D)
[Jan 20 12:32:16] DEBUG[19135] celliax_additional.c: rev exported[0x842b010|b64d1bb0][DEBUG_AT 2396 ][line2 ][ 3, 3, 3] sent data... (8)
[Jan 20 12:32:16] DEBUG[19135] celliax_additional.c: rev exported[0x842b010|b64d1bb0][DEBUG_AT 2396 ][line2 ][ 3, 3, 3] sent data... (0)
[Jan 20 12:32:16] DEBUG[19135] celliax_additional.c: rev exported[0x842b010|b64d1bb0][DEBUG_AT 2396 ][line2 ][ 3, 3, 3] sent data... (2)
[Jan 20 12:32:16] DEBUG[19135] celliax_additional.c: rev exported[0x842b010|b64d1bb0][DEBUG_AT 2396 ][line2 ][ 3, 3, 3] sent data... (9)
[Jan 20 12:32:16] DEBUG[19135] celliax_additional.c: rev exported[0x842b010|b64d1bb0][DEBUG_AT 2396 ][line2 ][ 3, 3, 3] sent data... (5)
[Jan 20 12:32:16] DEBUG[19135] celliax_additional.c: rev exported[0x842b010|b64d1bb0][DEBUG_AT 2396 ][line2 ][ 3, 3, 3] sent data... (5)
[Jan 20 12:32:16] DEBUG[19135] celliax_additional.c: rev exported[0x842b010|b64d1bb0][DEBUG_AT 2396 ][line2 ][ 3, 3, 3] sent data... (6)
[Jan 20 12:32:16] DEBUG[19135] celliax_additional.c: rev exported[0x842b010|b64d1bb0][DEBUG_AT 2396 ][line2 ][ 3, 3, 3] sent data... (6)
[Jan 20 12:32:16] DEBUG[19135] celliax_additional.c: rev exported[0x842b010|b64d1bb0][DEBUG_AT 2396 ][line2 ][ 3, 3, 3] sent data... (0)
[Jan 20 12:32:16] DEBUG[19135] celliax_additional.c: rev exported[0x842b010|b64d1bb0][DEBUG_AT 2396 ][line2 ][ 3, 3, 3] sent data... (6)
[Jan 20 12:32:16] DEBUG[19135] celliax_additional.c: rev exported[0x842b010|b64d1bb0][DEBUG_AT 2396 ][line2 ][ 3, 3, 3] sent data... (6)
[Jan 20 12:32:16] DEBUG[19135] celliax_additional.c: rev exported[0x842b010|b64d1bb0][DEBUG_AT 2396 ][line2 ][ 3, 3, 3] sent data... (;)
[Jan 20 12:32:16] DEBUG[19135] celliax_additional.c: rev exported[0x842b010|b64d1bb0][DEBUG_AT 2426 ][line2 ][ 3, 3, 3] sent (carriage return)
[Jan 20 12:32:16] DEBUG[19135] celliax_additional.c: rev exported[0x842b010|b64d1bb0][DEBUG_AT 1346 ][line2 ][ 3, 3, 3] Read line 0: |OK|
[Jan 20 12:32:16] DEBUG[19135] celliax_additional.c: rev exported[0x842b010|b64d1bb0][DEBUG_AT 2159 ][line2 ][ 3, 3, 3] |OK| got what EXPECTED
[Jan 20 12:32:16] DEBUG[19135] chan_celliax.c: rev exported[0x842b010|b64d1bb0][DEBUG_PBX 1059 ][line2 ][ 3, 3, 3] call ongoing
[Jan 20 12:32:16] DEBUG[19135] chan_celliax.c: rev exported[0x842b010|b64d1bb0][DEBUG_PBX 1065 ][line2 ][ 3, 3, 3] celliax_call dialed idest: line2/80295566066, timeout: 0, dstr: 80295566066!
[Jan 20 12:32:16] DEBUG[19135] chan_celliax.c: rev exported[0x842b010|b64d1bb0][DEBUG_PBX 1068 ][line2 ][ 3, 3, 3] EXITING FUNC
[Jan 20 12:32:16] VERBOSE[19135] logger.c: -- Called line2/80295566066
[Jan 20 12:32:16] DEBUG[19135] channel.c: Set channel Celliax/line2 to read format ulaw
[Jan 20 12:32:16] DEBUG[19135] channel.c: Set channel SIP/sta-pbx-2-00000002 to read format slin
[Jan 20 12:32:16] DEBUG[19135] channel.c: Set channel Celliax/line2 to write format slin
[Jan 20 12:32:16] VERBOSE[19135] logger.c: -- Celliax/line2 is ringing
[Jan 20 12:32:16] DEBUG[19135] rtp.c: Channel 'Celliax/line2' has no RTP, not doing anything
[Jan 20 12:32:16] DEBUG[19135] chan_celliax.c: rev exported[0x842b010|b64d1bb0][DEBUG_SOUND 903 ][line2 ][ 3, 3, 3] DTMF recognition inited
[Jan 20 12:32:16] DEBUG[19135] chan_sip.c: Setting framing from config on incoming call
[Jan 20 12:32:16] DEBUG[19135] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: True
[Jan 20 12:32:16] DEBUG[19135] chan_sip.c: ** Our prefcodec: 0x0 (nothing)
[Jan 20 12:32:16] DEBUG[19135] chan_sip.c: -- Done with adding codecs to SDP
[Jan 20 12:32:16] DEBUG[19135] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw)
[Jan 20 12:32:16] DEBUG[19135] rtp.c: Ooh, format changed from unknown to ulaw
[Jan 20 12:32:16] DEBUG[19135] rtp.c: Created smoother: format: 4 ms: 20 len: 160
[Jan 20 12:32:16] DEBUG[19063] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jan 20 12:32:16] DEBUG[19063] chan_sip.c: Destroying SIP dialog 1380377101d3fa4b28e3a91e7446261b@192.168.5.186
[Jan 20 12:32:16] VERBOSE[19063] logger.c: Really destroying SIP dialog '1380377101d3fa4b28e3a91e7446261b@192.168.5.186' Method: OPTIONS
[Jan 20 12:32:16] DEBUG[19063] devicestate.c: Notification of state change to be queued on device/channel SIP/sta-pbx-7
[Jan 20 12:32:16] DEBUG[19045] chan_sip.c: Checking device state for peer sta-pbx-7
[Jan 20 12:32:16] DEBUG[19045] devicestate.c: Changing state for SIP/sta-pbx-7 - state 5 (Unavailable)
[Jan 20 12:32:16] DEBUG[19048] app_queue.c: Device 'SIP/sta-pbx-7' changed to state '5' (Unavailable) but we don't care because they're not a member of any queue.
[Jan 20 12:32:18] DEBUG[19063] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jan 20 12:32:18] DEBUG[19063] chan_sip.c: Stopping retransmission on '058bea3d3cd8476b5d3d238d31d1bacf@192.168.5.186' of Request 102: Match Found
[Jan 20 12:32:18] NOTICE[19063] chan_sip.c: Peer 'sta-pbx-3' is now Reachable. (82ms / 180ms)
[Jan 20 12:32:18] DEBUG[19063] devicestate.c: Notification of state change to be queued on device/channel SIP/sta-pbx-3
[Jan 20 12:32:18] VERBOSE[19063] logger.c: Really destroying SIP dialog '058bea3d3cd8476b5d3d238d31d1bacf@192.168.5.186' Method: OPTIONS
[Jan 20 12:32:18] DEBUG[19045] chan_sip.c: Checking device state for peer sta-pbx-3
[Jan 20 12:32:18] DEBUG[19045] devicestate.c: Changing state for SIP/sta-pbx-3 - state 1 (Not in use)
[Jan 20 12:32:18] DEBUG[19048] app_queue.c: Device 'SIP/sta-pbx-3' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jan 20 12:32:21] DEBUG[19135] rtp.c: Got RTCP report of 64 bytes
[Jan 20 12:32:26] DEBUG[19135] rtp.c: Got RTCP report of 64 bytes
[Jan 20 12:32:26] DEBUG[19063] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jan 20 12:32:26] DEBUG[19063] chan_sip.c: Destroying SIP dialog 1797f3233c8c5ac03731d18f4d678716@192.168.5.186
[Jan 20 12:32:26] VERBOSE[19063] logger.c: Really destroying SIP dialog '1797f3233c8c5ac03731d18f4d678716@192.168.5.186' Method: OPTIONS
[Jan 20 12:32:26] DEBUG[19063] devicestate.c: Notification of state change to be queued on device/channel SIP/sta-pbx-7
[Jan 20 12:32:26] DEBUG[19045] chan_sip.c: Checking device state for peer sta-pbx-7
[Jan 20 12:32:26] DEBUG[19045] devicestate.c: Changing state for SIP/sta-pbx-7 - state 5 (Unavailable)
[Jan 20 12:32:26] DEBUG[19048] app_queue.c: Device 'SIP/sta-pbx-7' changed to state '5' (Unavailable) but we don't care because they're not a member of any queue.
[Jan 20 12:32:27] DEBUG[19063] chan_sip.c: Auto destroying SIP dialog '05e9da893a18ae8f388753f24a0ec5dc@192.168.5.253'
[Jan 20 12:32:27] DEBUG[19063] chan_sip.c: Destroying SIP dialog 05e9da893a18ae8f388753f24a0ec5dc@192.168.5.253
[Jan 20 12:32:27] VERBOSE[19063] logger.c: Really destroying SIP dialog '05e9da893a18ae8f388753f24a0ec5dc@192.168.5.253' Method: OPTIONS
[Jan 20 12:32:27] DEBUG[19138] celliax_additional.c: rev exported[0x842b010|b648dbb0][DEBUG_AT 1346 ][line2 ][ 3, 3, 3] Read line 0: |+CSSI: 7|
[Jan 20 12:32:27] DEBUG[19138] celliax_additional.c: rev exported[0x842b010|b648dbb0][DEBUG_AT 1616 ][line2 ][ 3, 3,300] |+CSSI: 7| CALLFLOW_CALL_ACTIVE
[Jan 20 12:32:27] DEBUG[19138] celliax_additional.c: rev exported[0x842b010|b648dbb0][DEBUG_PBX 1619 ][line2 ][ 3, 3,300] just received a remote ANSWER
[Jan 20 12:32:27] DEBUG[19138] chan_celliax.c: rev exported[0x842b010|b648dbb0][DEBUG_PBX 463 ][line2 ][ 3, 3,300] Queued CONTROL FRAME 3
[Jan 20 12:32:27] DEBUG[19135] chan_celliax.c: rev exported[0x842b010|b64d1bb0][DEBUG_PBX 910 ][line2 ][ 3, 3,300] Sent CONTROL FRAME 3
[Jan 20 12:32:27] VERBOSE[19135] logger.c: -- Celliax/line2 is ringing
[Jan 20 12:32:27] DEBUG[19135] rtp.c: Channel 'Celliax/line2' has no RTP, not doing anything
[Jan 20 12:32:27] DEBUG[19138] celliax_additional.c: rev exported[0x842b010|b648dbb0][DEBUG_PBX 1622 ][line2 ][ 3, 3,300] just sent AST_CONTROL_RINGING
[Jan 20 12:32:27] DEBUG[19138] celliax_additional.c: rev exported[0x842b010|b648dbb0][DEBUG_PBX 1623 ][line2 ][ 3, 3,300] going to send AST_CONTROL_ANSWER
[Jan 20 12:32:27] DEBUG[19138] chan_celliax.c: rev exported[0x842b010|b648dbb0][DEBUG_PBX 463 ][line2 ][ 3, 3,300] Queued CONTROL FRAME 4
[Jan 20 12:32:27] DEBUG[19135] chan_celliax.c: rev exported[0x842b010|b64d1bb0][DEBUG_PBX 910 ][line2 ][ 3, 3,300] Sent CONTROL FRAME 4
[Jan 20 12:32:27] DEBUG[19135] devicestate.c: Notification of state change to be queued on device/channel Celliax/line2
[Jan 20 12:32:27] VERBOSE[19135] logger.c: -- Celliax/line2 answered SIP/sta-pbx-2-00000002
[Jan 20 12:32:27] DEBUG[19135] rtp.c: Channel 'Celliax/line2' has no RTP, not doing anything
[Jan 20 12:32:27] DEBUG[19135] devicestate.c: Notification of state change to be queued on device/channel SIP/sta-pbx-2
[Jan 20 12:32:27] DEBUG[19135] chan_sip.c: SIP answering channel: SIP/sta-pbx-2-00000002
[Jan 20 12:32:27] DEBUG[19135] chan_sip.c: Setting framing from config on incoming call
[Jan 20 12:32:27] DEBUG[19135] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: True
[Jan 20 12:32:27] DEBUG[19135] chan_sip.c: ** Our prefcodec: 0x0 (nothing)
[Jan 20 12:32:27] DEBUG[19135] chan_sip.c: -- Done with adding codecs to SDP
[Jan 20 12:32:27] DEBUG[19135] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw)
[Jan 20 12:32:27] WARNING[19135] chan_celliax.c: rev exported[0x842b010|b64d1bb0][WARNING 547 ][line2 ][ 6, 3,300] Don't know how to display condition 20 on Celliax/line2
[Jan 20 12:32:27] DEBUG[19063] chan_sip.c: Stopping retransmission on '21b9936c0ed247e85266cd610c08023d@192.168.5.253' of Response 102: Match Found
[Jan 20 12:32:27] DEBUG[19138] celliax_additional.c: rev exported[0x842b010|b648dbb0][DEBUG_PBX 1625 ][line2 ][ 6, 3,300] just sent AST_CONTROL_ANSWER
[Jan 20 12:32:27] DEBUG[19138] celliax_additional.c: rev exported[0x842b010|b648dbb0][DEBUG_PBX 1630 ][line2 ][ 6, 6,300] just interface_state UP
[Jan 20 12:32:27] DEBUG[19135] celliax_additional.c: rev exported[0x842b010|b64d1bb0][DEBUG_SOUND 682 ][line2 ][ 6, 6,300] PREVENTING an ALSA write XRUN (celliax can't fill the soundcard buffer fast enough). If this happens often (not after silence or after a pause in the speech, that's OK), and appear to damage the sound quality, first check if you have some IRQ problem, maybe sharing the soundcard IRQ with a broken or heavy loaded ethernet or graphic card. Then consider to increase the alsa_periods_in_buffer (now is set to 5) for this interface in the config file. delayp1=0, delayp2=800
[Jan 20 12:32:28] DEBUG[19045] chan_celliax.c: rev exported[0x842b010|b7dc7bb0][DEBUG_PBX 499 ][line2 ][ 6, 6,300] Interface is OWNED by a channel
[Jan 20 12:32:28] DEBUG[19045] devicestate.c: Changing state for Celliax/line2 - state 2 (In use)
[Jan 20 12:32:28] DEBUG[19045] chan_sip.c: Checking device state for peer sta-pbx-2
[Jan 20 12:32:28] DEBUG[19045] devicestate.c: Changing state for SIP/sta-pbx-2 - state 1 (Not in use)
[Jan 20 12:32:28] DEBUG[19048] app_queue.c: Device 'Celliax/line2' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Jan 20 12:32:28] DEBUG[19048] app_queue.c: Device 'SIP/sta-pbx-2' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jan 20 12:32:31] DEBUG[19135] rtp.c: Got RTCP report of 64 bytes
[Jan 20 12:32:32] DEBUG[19063] chan_sip.c: Auto destroying SIP dialog '560aae5a3d5f9b6a59873a665ff6eb2e@10.255.101.101'
[Jan 20 12:32:32] DEBUG[19063] chan_sip.c: Destroying SIP dialog 560aae5a3d5f9b6a59873a665ff6eb2e@10.255.101.101
[Jan 20 12:32:32] VERBOSE[19063] logger.c: Really destroying SIP dialog '560aae5a3d5f9b6a59873a665ff6eb2e@10.255.101.101' Method: OPTIONS
[Jan 20 12:32:36] DEBUG[19135] rtp.c: Got RTCP report of 64 bytes
[Jan 20 12:32:36] DEBUG[19063] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jan 20 12:32:36] DEBUG[19063] chan_sip.c: Destroying SIP dialog 4f2f179f4a3d879c13e73120212dfad7@192.168.5.186
[Jan 20 12:32:36] VERBOSE[19063] logger.c: Really destroying SIP dialog '4f2f179f4a3d879c13e73120212dfad7@192.168.5.186' Method: OPTIONS
[Jan 20 12:32:36] DEBUG[19063] devicestate.c: Notification of state change to be queued on device/channel SIP/sta-pbx-7
[Jan 20 12:32:36] DEBUG[19045] chan_sip.c: Checking device state for peer sta-pbx-7
[Jan 20 12:32:36] DEBUG[19045] devicestate.c: Changing state for SIP/sta-pbx-7 - state 5 (Unavailable)
[Jan 20 12:32:36] DEBUG[19048] app_queue.c: Device 'SIP/sta-pbx-7' changed to state '5' (Unavailable) but we don't care because they're not a member of any queue.
[Jan 20 12:32:41] DEBUG[19135] rtp.c: Got RTCP report of 64 bytes
[Jan 20 12:32:43] DEBUG[19063] chan_sip.c: Auto destroying SIP dialog '2926347502ba00e8484524e1518dd076@10.255.101.101'
[Jan 20 12:32:43] DEBUG[19063] chan_sip.c: Destroying SIP dialog 2926347502ba00e8484524e1518dd076@10.255.101.101
[Jan 20 12:32:43] VERBOSE[19063] logger.c: Really destroying SIP dialog '2926347502ba00e8484524e1518dd076@10.255.101.101' Method: OPTIONS
[Jan 20 12:32:46] DEBUG[19063] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jan 20 12:32:46] DEBUG[19063] chan_sip.c: Stopping retransmission on '546907b71bb8b5f35f0e0cdf202e3551@192.168.5.186' of Request 102: Match Found
[Jan 20 12:32:46] VERBOSE[19063] logger.c: Really destroying SIP dialog '546907b71bb8b5f35f0e0cdf202e3551@192.168.5.186' Method: OPTIONS
[Jan 20 12:32:46] DEBUG[19063] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jan 20 12:32:46] DEBUG[19063] chan_sip.c: Stopping retransmission on '5cb2cd10341983b203d4256d56045e29@192.168.5.186' of Request 102: Match Found
[Jan 20 12:32:46] VERBOSE[19063] logger.c: Really destroying SIP dialog '5cb2cd10341983b203d4256d56045e29@192.168.5.186' Method: OPTIONS
[Jan 20 12:32:46] DEBUG[19135] rtp.c: Got RTCP report of 64 bytes
[Jan 20 12:32:46] DEBUG[19063] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jan 20 12:32:47] DEBUG[19063] chan_sip.c: Destroying SIP dialog 1dbdd0923c68f9db71cde2c45bd0f35f@192.168.5.186
[Jan 20 12:32:47] VERBOSE[19063] logger.c: Really destroying SIP dialog '1dbdd0923c68f9db71cde2c45bd0f35f@192.168.5.186' Method: OPTIONS
[Jan 20 12:32:47] DEBUG[19063] devicestate.c: Notification of state change to be queued on device/channel SIP/sta-pbx-7
[Jan 20 12:32:47] DEBUG[19045] chan_sip.c: Checking device state for peer sta-pbx-7
[Jan 20 12:32:47] DEBUG[19045] devicestate.c: Changing state for SIP/sta-pbx-7 - state 5 (Unavailable)
[Jan 20 12:32:47] DEBUG[19048] app_queue.c: Device 'SIP/sta-pbx-7' changed to state '5' (Unavailable) but we don't care because they're not a member of any queue.
[Jan 20 12:32:51] DEBUG[19135] rtp.c: Got RTCP report of 64 bytes
[Jan 20 12:32:51] DEBUG[19138] celliax_additional.c: rev exported[0x842b010|b648dbb0][DEBUG_AT 1346 ][line2 ][ 6, 6,300] Read line 0: |NO CARRIER|
[Jan 20 12:32:51] DEBUG[19138] celliax_additional.c: rev exported[0x842b010|b648dbb0][DEBUG_AT 1489 ][line2 ][ 6, 6,102] |NO CARRIER| CALLFLOW_CALL_NOCARRIER
[Jan 20 12:32:51] DEBUG[19138] chan_celliax.c: rev exported[0x842b010|b648dbb0][DEBUG_PBX 463 ][line2 ][ 6, 6,102] Queued CONTROL FRAME 1
[Jan 20 12:32:51] DEBUG[19135] chan_celliax.c: rev exported[0x842b010|b64d1bb0][DEBUG_PBX 910 ][line2 ][ 6, 6,102] Sent CONTROL FRAME 1
[Jan 20 12:32:51] DEBUG[19135] channel.c: Didn't get a frame from channel: Celliax/line2
[Jan 20 12:32:51] DEBUG[19135] channel.c: Bridge stops bridging channels SIP/sta-pbx-2-00000002 and Celliax/line2
[Jan 20 12:32:51] DEBUG[19135] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record.
[Jan 20 12:32:51] DEBUG[19135] cdr_addon_mysql.c: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,userfield) VALUES ('2010-01-20 12:32:15','\"Sergei Pahamovich\" <1304>','1304','80295566066','outbound', 'SIP/sta-pbx-2-00000002','Celliax/line2','Dial','Celliax/line2/80295566066',36,24,'ANSWERED',3,'','')
[Jan 20 12:32:51] DEBUG[19135] channel.c: Hanging up channel 'Celliax/line2'
[Jan 20 12:32:51] DEBUG[19135] chan_celliax.c: rev exported[0x842b010|b64d1bb0][DEBUG_PBX 648 ][line2 ][ 6, 6,102] ENTERING FUNC
[Jan 20 12:32:51] DEBUG[19138] chan_celliax.c: exported[b648dbb0] I'm a dying thread, and I'm to go unlocking mutex 0xb7860358 for the 0th time
[Jan 20 12:32:51] DEBUG[19138] chan_celliax.c: exported[b648dbb0] I'm a dying thread, and I'm to go unlocking mutex 0xb7860358 for the 1th time
[Jan 20 12:32:51] DEBUG[19138] chan_celliax.c: exported[b648dbb0] I'm a dying thread, and I'm to go unlocking mutex 0xb7860358 for the 2th time
[Jan 20 12:32:51] DEBUG[19138] chan_celliax.c: exported[b648dbb0] I'm a dying thread, and I'm to go unlocking mutex 0xb7860358 for the 3th time
[Jan 20 12:32:51] DEBUG[19138] chan_celliax.c: exported[b648dbb0] I'm a dying thread, and I'm to go unlocking mutex 0xb7860358 for the 4th time
[Jan 20 12:32:51] DEBUG[19138] chan_celliax.c: exported[b648dbb0] I'm a dying thread, I've finished unlocking mutex 0xb7860358
[Jan 20 12:32:51] DEBUG[19135] celliax_additional.c: rev exported[0x842b010|b64d1bb0][DEBUG_AT 2547 ][line2 ][ 6, 6,102] sending: ATH, expecting: OK
[Jan 20 12:32:51] DEBUG[19135] celliax_additional.c: rev exported[0x842b010|b64d1bb0][DEBUG_AT 2396 ][line2 ][ 6, 6,102] sent data... (A)
[Jan 20 12:32:51] DEBUG[19135] celliax_additional.c: rev exported[0x842b010|b64d1bb0][DEBUG_AT 2396 ][line2 ][ 6, 6,102] sent data... (T)
[Jan 20 12:32:51] DEBUG[19135] celliax_additional.c: rev exported[0x842b010|b64d1bb0][DEBUG_AT 2396 ][line2 ][ 6, 6,102] sent data... (H)
[Jan 20 12:32:51] DEBUG[19135] celliax_additional.c: rev exported[0x842b010|b64d1bb0][DEBUG_AT 2426 ][line2 ][ 6, 6,102] sent (carriage return)
[Jan 20 12:32:51] DEBUG[19135] celliax_additional.c: rev exported[0x842b010|b64d1bb0][DEBUG_AT 1346 ][line2 ][ 6, 6,102] Read line 0: |OK|
[Jan 20 12:32:51] DEBUG[19135] celliax_additional.c: rev exported[0x842b010|b64d1bb0][DEBUG_AT 2159 ][line2 ][ 6, 6,102] |OK| got what EXPECTED
[Jan 20 12:32:51] DEBUG[19135] chan_celliax.c: rev exported[0x842b010|b64d1bb0][DEBUG_SERIAL 695 ][line2 ][ 6, 0, 0] call hungup
[Jan 20 12:32:51] DEBUG[19135] chan_celliax.c: rev exported[0x842b010|b64d1bb0][DEBUG_SOUND 717 ][line2 ][ 6, 0, 0] shutting down sound
[Jan 20 12:32:51] DEBUG[19135] chan_celliax.c: rev exported[0x842b010|b64d1bb0][DEBUG_SERIAL 2677 ][line2 ][ 6, 0, 0] Syncing Serial
[Jan 20 12:32:51] DEBUG[19135] devicestate.c: Notification of state change to be queued on device/channel Celliax/line2
[Jan 20 12:32:51] DEBUG[19135] chan_celliax.c: rev exported[(nil)|b64d1bb0][DEBUG_PBX 768 ][line2 ][-1, 0, 0] Hanged Up
[Jan 20 12:32:51] DEBUG[19135] chan_celliax.c: rev exported[(nil)|b64d1bb0][DEBUG_PBX 779 ][line2 ][-1, 0, 0] EXITING FUNC
[Jan 20 12:32:51] DEBUG[19135] devicestate.c: Notification of state change to be queued on device/channel Celliax/line2
[Jan 20 12:32:51] DEBUG[19135] rtp.c: Channel '' has no RTP, not doing anything
[Jan 20 12:32:51] DEBUG[19135] app_dial.c: Exiting with DIALSTATUS=ANSWER.
[Jan 20 12:32:51] DEBUG[19135] pbx.c: Spawn extension (outbound,80295566066,1) exited non-zero on 'SIP/sta-pbx-2-00000002'
[Jan 20 12:32:51] VERBOSE[19135] logger.c: == Spawn extension (outbound, 80295566066, 1) exited non-zero on 'SIP/sta-pbx-2-00000002'
[Jan 20 12:32:51] DEBUG[19135] channel.c: Soft-Hanging up channel 'SIP/sta-pbx-2-00000002'
[Jan 20 12:32:51] DEBUG[19135] channel.c: Hanging up channel 'SIP/sta-pbx-2-00000002'
[Jan 20 12:32:51] DEBUG[19135] chan_sip.c: Hangup call SIP/sta-pbx-2-00000002, SIP callid 21b9936c0ed247e85266cd610c08023d@192.168.5.253)
[Jan 20 12:32:51] DEBUG[19135] devicestate.c: Notification of state change to be queued on device/channel SIP/sta-pbx-2
[Jan 20 12:32:51] DEBUG[19045] chan_celliax.c: rev exported[(nil)|b7dc7bb0][DEBUG_PBX 495 ][line2 ][-1, 0, 0] Interface is NOT OWNED by a channel
[Jan 20 12:32:51] DEBUG[19045] devicestate.c: Changing state for Celliax/line2 - state 1 (Not in use)
[Jan 20 12:32:51] DEBUG[19045] chan_celliax.c: rev exported[(nil)|b7dc7bb0][DEBUG_PBX 495 ][line2 ][-1, 0, 0] Interface is NOT OWNED by a channel
[Jan 20 12:32:51] DEBUG[19045] devicestate.c: Changing state for Celliax/line2 - state 1 (Not in use)
[Jan 20 12:32:51] DEBUG[19045] chan_sip.c: Checking device state for peer sta-pbx-2
[Jan 20 12:32:51] DEBUG[19045] devicestate.c: Changing state for SIP/sta-pbx-2 - state 1 (Not in use)
[Jan 20 12:32:51] DEBUG[19063] chan_sip.c: Stopping retransmission on '21b9936c0ed247e85266cd610c08023d@192.168.5.253' of Request 102: Match Found
[Jan 20 12:32:51] VERBOSE[19063] logger.c: Really destroying SIP dialog '21b9936c0ed247e85266cd610c08023d@192.168.5.253' Method: ACK
[Jan 20 12:32:51] DEBUG[19048] app_queue.c: Device 'Celliax/line2' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jan 20 12:32:51] DEBUG[19048] app_queue.c: Device 'Celliax/line2' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jan 20 12:32:51] DEBUG[19048] app_queue.c: Device 'SIP/sta-pbx-2' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jan 20 12:32:55] DEBUG[19063] chan_sip.c: Allocating new SIP dialog for 62708eb6736f0a444c64f42406ea538b@192.168.5.253 - OPTIONS (No RTP)
[Jan 20 12:32:55] DEBUG[19063] chan_sip.c: SIP message could not be handled, bad request: 62708eb6736f0a444c64f42406ea538b@192.168.5.253
[Jan 20 12:32:57] DEBUG[19063] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jan 20 12:32:57] DEBUG[19063] chan_sip.c: Destroying SIP dialog 6487e05360597a71646b4e167c03413a@192.168.5.186
[Jan 20 12:32:57] VERBOSE[19063] logger.c: Really destroying SIP dialog '6487e05360597a71646b4e167c03413a@192.168.5.186' Method: OPTIONS
[Jan 20 12:32:57] DEBUG[19063] devicestate.c: Notification of state change to be queued on device/channel SIP/sta-pbx-7
[Jan 20 12:32:57] DEBUG[19045] chan_sip.c: Checking device state for peer sta-pbx-7
[Jan 20 12:32:57] DEBUG[19045] devicestate.c: Changing state for SIP/sta-pbx-7 - state 5 (Unavailable)
[Jan 20 12:32:57] DEBUG[19048] app_queue.c: Device 'SIP/sta-pbx-7' changed to state '5' (Unavailable) but we don't care because they're not a member of any queue.
[Jan 20 12:32:57] DEBUG[19063] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jan 20 12:32:57] DEBUG[19063] chan_sip.c: Stopping retransmission on '0df9564e3a31b27b41eeb90d77f68922@192.168.5.186' of Request 102: Match Found
[Jan 20 12:32:57] VERBOSE[19063] logger.c: Really destroying SIP dialog '0df9564e3a31b27b41eeb90d77f68922@192.168.5.186' Method: OPTIONS
[Jan 20 12:32:57] DEBUG[19063] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jan 20 12:32:57] DEBUG[19063] chan_sip.c: Stopping retransmission on '647cbbbe6a2088400ebd87d47319ce83@192.168.5.186' of Request 102: Match Found
[Jan 20 12:32:57] VERBOSE[19063] logger.c: Really destroying SIP dialog '647cbbbe6a2088400ebd87d47319ce83@192.168.5.186' Method: OPTIONS
[Jan 20 12:32:59] DEBUG[19063] chan_sip.c: Setting NAT on RTP to Off
[Jan 20 12:32:59] DEBUG[19063] chan_sip.c: Allocating new SIP dialog for 3444fe41030561f6222671ff7fca1f69@192.168.5.253 - INVITE (With RTP)
[Jan 20 12:32:59] DEBUG[19063] chan_sip.c: Setting NAT on RTP to Off
[Jan 20 12:32:59] DEBUG[19063] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED.
[Jan 20 12:32:59] DEBUG[19063] chan_sip.c: Processing session-level SDP o=root 2280 2280 IN IP4 192.168.5.253... UNSUPPORTED.
[Jan 20 12:32:59] DEBUG[19063] chan_sip.c: Processing session-level SDP s=session... UNSUPPORTED.
[Jan 20 12:32:59] DEBUG[19063] chan_sip.c: Processing session-level SDP c=IN IP4 192.168.5.253... OK.
[Jan 20 12:32:59] DEBUG[19063] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED.
[Jan 20 12:32:59] DEBUG[19063] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK.
[Jan 20 12:32:59] DEBUG[19063] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK.
[Jan 20 12:32:59] DEBUG[19063] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK.
[Jan 20 12:32:59] DEBUG[19063] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-16... UNSUPPORTED.
[Jan 20 12:32:59] DEBUG[19063] chan_sip.c: Processing media-level (audio) SDP a=silenceSupp:off - - - -... UNSUPPORTED.
[Jan 20 12:32:59] DEBUG[19063] chan_sip.c: Processing media-level (audio) SDP a=ptime:20... OK.
[Jan 20 12:32:59] DEBUG[19063] chan_sip.c: T38 state changed to 0 on channel
[Jan 20 12:32:59] DEBUG[19063] chan_sip.c: We're settling with these formats: 0x4 (ulaw)
[Jan 20 12:32:59] DEBUG[19063] chan_sip.c: Checking SIP call limits for device gsm-1
[Jan 20 12:32:59] DEBUG[19063] chan_sip.c: Updating call counter for incoming call
[Jan 20 12:32:59] DEBUG[19063] chan_sip.c: *** Our native formats are 0x4 (ulaw)
[Jan 20 12:32:59] DEBUG[19063] chan_sip.c: *** Joint capabilities are 0x4 (ulaw)
[Jan 20 12:32:59] DEBUG[19063] chan_sip.c: *** Our capabilities are 0x4 (ulaw)
[Jan 20 12:32:59] DEBUG[19063] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw)
[Jan 20 12:32:59] DEBUG[19063] chan_sip.c: This channel will not be able to handle video.
[Jan 20 12:32:59] DEBUG[19063] chan_sip.c: build_route: Contact hop:
[Jan 20 12:32:59] DEBUG[19063] chan_sip.c: SIP/sta-pbx-2-00000003: New call is still down.... Trying...
[Jan 20 12:32:59] DEBUG[19063] devicestate.c: Notification of state change to be queued on device/channel SIP/sta-pbx-2
[Jan 20 12:32:59] DEBUG[19045] chan_sip.c: Checking device state for peer sta-pbx-2
[Jan 20 12:32:59] DEBUG[19045] devicestate.c: Changing state for SIP/sta-pbx-2 - state 1 (Not in use)
[Jan 20 12:32:59] DEBUG[19048] app_queue.c: Device 'SIP/sta-pbx-2' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jan 20 12:32:59] DEBUG[19142] pbx.c: Launching 'Goto'
[Jan 20 12:32:59] VERBOSE[19142] logger.c: -- Executing [80295566066@interoffice:1] Goto("SIP/sta-pbx-2-00000003", "outbound|80295566066|1") in new stack
[Jan 20 12:32:59] VERBOSE[19142] logger.c: -- Goto (outbound,80295566066,1)
[Jan 20 12:32:59] DEBUG[19142] pbx.c: Launching 'Dial'
[Jan 20 12:32:59] VERBOSE[19142] logger.c: -- Executing [80295566066@outbound:1] Dial("SIP/sta-pbx-2-00000003", "Celliax/line2/80295566066") in new stack
[Jan 20 12:32:59] DEBUG[19142] chan_celliax.c: rev exported[(nil)|b64d1bb0][DEBUG_PBX 564 ][none ][-1,-1,-1] ENTERING FUNC
[Jan 20 12:32:59] DEBUG[19142] chan_celliax.c: rev exported[(nil)|b64d1bb0][DEBUG_PBX 568 ][none ][-1,-1,-1] Try to request type: Celliax, name: line2/80295566066, cause: 0, format: 64
[Jan 20 12:32:59] DEBUG[19142] chan_celliax.c: rev exported[(nil)|b64d1bb0][DEBUG_PBX 593 ][line2 ][-1, 0, 0] Requesting: Celliax, name: line2/80295566066, format: 64
[Jan 20 12:32:59] DEBUG[19142] chan_celliax.c: rev exported[(nil)|b64d1bb0][DEBUG_PBX 1138 ][line2 ][-1, 0, 0] ENTERING FUNC
[Jan 20 12:32:59] DEBUG[19142] celliax_additional.c: rev exported[(nil)|b64d1bb0][DEBUG_SOUND 402 ][line2 ][-1, 0, 0] Acquired fd 42 from the poll descriptor
[Jan 20 12:32:59] DEBUG[19142] celliax_additional.c: rev exported[(nil)|b64d1bb0][DEBUG_SOUND 425 ][line2 ][-1, 0, 0] started!
[Jan 20 12:32:59] DEBUG[19142] celliax_additional.c: rev exported[(nil)|b64d1bb0][DEBUG_SOUND 437 ][line2 ][-1, 0, 0] ALSA handle = 138573160
[Jan 20 12:32:59] DEBUG[19142] celliax_additional.c: rev exported[(nil)|b64d1bb0][DEBUG_SOUND 402 ][line2 ][-1, 0, 0] Acquired fd 43 from the poll descriptor
[Jan 20 12:32:59] DEBUG[19142] celliax_additional.c: rev exported[(nil)|b64d1bb0][DEBUG_SOUND 437 ][line2 ][-1, 0, 0] ALSA handle = 138616624
[Jan 20 12:32:59] DEBUG[19142] chan_celliax.c: rev exported[(nil)|b64d1bb0][DEBUG_PBX 1171 ][line2 ][-1, 0, 0] new channel: name=Celliax/line2 requested_state=0
[Jan 20 12:32:59] DEBUG[19142] chan_celliax.c: rev exported[0x8419f90|b64d1bb0][DEBUG_SERIAL 1255 ][line2 ][ 0, 0, 0] STARTED controldev_thread=3058228144 STOP=4294967294 NULL=4294967295
[Jan 20 12:32:59] DEBUG[19142] chan_celliax.c: rev exported[0x8419f90|b64d1bb0][DEBUG_PBX 1267 ][line2 ][ 0, 0, 0] EXITING FUNC
[Jan 20 12:32:59] DEBUG[19142] chan_celliax.c: rev exported[0x8419f90|b64d1bb0][DEBUG_PBX 625 ][line2 ][ 0, 0, 0] EXITING FUNC
[Jan 20 12:32:59] DEBUG[19142] rtp.c: Channel 'Celliax/line2' has no RTP, not doing anything
[Jan 20 12:32:59] DEBUG[19142] channel.c: Not copying variable DIALEDTIME.
[Jan 20 12:32:59] DEBUG[19142] channel.c: Not copying variable ANSWEREDTIME.
[Jan 20 12:32:59] DEBUG[19142] channel.c: Not copying variable DIALEDPEERNAME.
[Jan 20 12:32:59] DEBUG[19142] channel.c: Not copying variable DIALEDPEERNUMBER.
[Jan 20 12:32:59] DEBUG[19142] channel.c: Not copying variable DIALSTATUS.
[Jan 20 12:32:59] DEBUG[19142] channel.c: Not copying variable SIPCALLID.
[Jan 20 12:32:59] DEBUG[19142] channel.c: Not copying variable SIPUSERAGENT.
[Jan 20 12:32:59] DEBUG[19142] channel.c: Not copying variable SIPDOMAIN.
[Jan 20 12:32:59] DEBUG[19142] channel.c: Not copying variable SIPURI.
[Jan 20 12:32:59] DEBUG[19142] chan_celliax.c: rev exported[0x8419f90|b64d1bb0][DEBUG_PBX 1006 ][line2 ][ 0, 0, 0] ENTERING FUNC
[Jan 20 12:32:59] DEBUG[19142] chan_celliax.c: rev exported[0x8419f90|b64d1bb0][DEBUG_PBX 1020 ][line2 ][ 0, 0, 0] celliax_call to call idest: line2/80295566066, timeout: 0!
[Jan 20 12:32:59] DEBUG[19142] chan_celliax.c: rev exported[0x8419f90|b64d1bb0][DEBUG_PBX 1041 ][line2 ][ 0, 0, 0] celliax_call dialing idest: line2/80295566066, timeout: 0, dstr: 80295566066!
[Jan 20 12:32:59] DEBUG[19142] devicestate.c: Notification of state change to be queued on device/channel Celliax/line2
[Jan 20 12:32:59] DEBUG[19045] chan_celliax.c: rev exported[0x8419f90|b7dc7bb0][DEBUG_PBX 499 ][line2 ][ 3, 0, 0] Interface is OWNED by a channel
[Jan 20 12:32:59] DEBUG[19045] devicestate.c: Changing state for Celliax/line2 - state 2 (In use)
[Jan 20 12:32:59] DEBUG[19048] app_queue.c: Device 'Celliax/line2' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Jan 20 12:32:59] DEBUG[19142] celliax_additional.c: rev exported[0x8419f90|b64d1bb0][DEBUG_PBX 2945 ][line2 ][ 3, 0, 0] Dialing 80295566066
[Jan 20 12:32:59] DEBUG[19142] celliax_additional.c: rev exported[0x8419f90|b64d1bb0][DEBUG_AT 2547 ][line2 ][ 3, 3, 3] sending: ATD80295566066;, expecting: OK
[Jan 20 12:32:59] DEBUG[19142] celliax_additional.c: rev exported[0x8419f90|b64d1bb0][DEBUG_AT 2396 ][line2 ][ 3, 3, 3] sent data... (A)
[Jan 20 12:32:59] DEBUG[19145] chan_celliax.c: rev exported[0x8419f90|b648dbb0][DEBUG_SERIAL 2527 ][line2 ][ 3, 3, 3] In celliax_do_controldev_thread: started, p=0xb77df008
[Jan 20 12:32:59] DEBUG[19142] celliax_additional.c: rev exported[0x8419f90|b64d1bb0][DEBUG_AT 2396 ][line2 ][ 3, 3, 3] sent data... (T)
[Jan 20 12:32:59] DEBUG[19142] celliax_additional.c: rev exported[0x8419f90|b64d1bb0][DEBUG_AT 2396 ][line2 ][ 3, 3, 3] sent data... (D)
[Jan 20 12:32:59] DEBUG[19142] celliax_additional.c: rev exported[0x8419f90|b64d1bb0][DEBUG_AT 2396 ][line2 ][ 3, 3, 3] sent data... (8)
[Jan 20 12:32:59] DEBUG[19142] celliax_additional.c: rev exported[0x8419f90|b64d1bb0][DEBUG_AT 2396 ][line2 ][ 3, 3, 3] sent data... (0)
[Jan 20 12:32:59] DEBUG[19142] celliax_additional.c: rev exported[0x8419f90|b64d1bb0][DEBUG_AT 2396 ][line2 ][ 3, 3, 3] sent data... (2)
[Jan 20 12:32:59] DEBUG[19142] celliax_additional.c: rev exported[0x8419f90|b64d1bb0][DEBUG_AT 2396 ][line2 ][ 3, 3, 3] sent data... (9)
[Jan 20 12:32:59] DEBUG[19142] celliax_additional.c: rev exported[0x8419f90|b64d1bb0][DEBUG_AT 2396 ][line2 ][ 3, 3, 3] sent data... (5)
[Jan 20 12:32:59] DEBUG[19142] celliax_additional.c: rev exported[0x8419f90|b64d1bb0][DEBUG_AT 2396 ][line2 ][ 3, 3, 3] sent data... (5)
[Jan 20 12:32:59] DEBUG[19142] celliax_additional.c: rev exported[0x8419f90|b64d1bb0][DEBUG_AT 2396 ][line2 ][ 3, 3, 3] sent data... (6)
[Jan 20 12:32:59] DEBUG[19142] celliax_additional.c: rev exported[0x8419f90|b64d1bb0][DEBUG_AT 2396 ][line2 ][ 3, 3, 3] sent data... (6)
[Jan 20 12:32:59] DEBUG[19142] celliax_additional.c: rev exported[0x8419f90|b64d1bb0][DEBUG_AT 2396 ][line2 ][ 3, 3, 3] sent data... (0)
[Jan 20 12:32:59] DEBUG[19142] celliax_additional.c: rev exported[0x8419f90|b64d1bb0][DEBUG_AT 2396 ][line2 ][ 3, 3, 3] sent data... (6)
[Jan 20 12:32:59] DEBUG[19142] celliax_additional.c: rev exported[0x8419f90|b64d1bb0][DEBUG_AT 2396 ][line2 ][ 3, 3, 3] sent data... (6)
[Jan 20 12:32:59] DEBUG[19142] celliax_additional.c: rev exported[0x8419f90|b64d1bb0][DEBUG_AT 2396 ][line2 ][ 3, 3, 3] sent data... (;)
[Jan 20 12:32:59] DEBUG[19142] celliax_additional.c: rev exported[0x8419f90|b64d1bb0][DEBUG_AT 2426 ][line2 ][ 3, 3, 3] sent (carriage return)
[Jan 20 12:32:59] DEBUG[19142] celliax_additional.c: rev exported[0x8419f90|b64d1bb0][DEBUG_AT 1346 ][line2 ][ 3, 3, 3] Read line 0: |OK|
[Jan 20 12:32:59] DEBUG[19142] celliax_additional.c: rev exported[0x8419f90|b64d1bb0][DEBUG_AT 2159 ][line2 ][ 3, 3, 3] |OK| got what EXPECTED
[Jan 20 12:32:59] DEBUG[19142] chan_celliax.c: rev exported[0x8419f90|b64d1bb0][DEBUG_PBX 1059 ][line2 ][ 3, 3, 3] call ongoing
[Jan 20 12:32:59] DEBUG[19142] chan_celliax.c: rev exported[0x8419f90|b64d1bb0][DEBUG_PBX 1065 ][line2 ][ 3, 3, 3] celliax_call dialed idest: line2/80295566066, timeout: 0, dstr: 80295566066!
[Jan 20 12:32:59] DEBUG[19142] chan_celliax.c: rev exported[0x8419f90|b64d1bb0][DEBUG_PBX 1068 ][line2 ][ 3, 3, 3] EXITING FUNC
[Jan 20 12:32:59] VERBOSE[19142] logger.c: -- Called line2/80295566066
[Jan 20 12:32:59] DEBUG[19142] channel.c: Set channel Celliax/line2 to read format ulaw
[Jan 20 12:32:59] DEBUG[19142] channel.c: Set channel SIP/sta-pbx-2-00000003 to read format slin
[Jan 20 12:32:59] DEBUG[19142] channel.c: Set channel Celliax/line2 to write format slin
[Jan 20 12:32:59] VERBOSE[19142] logger.c: -- Celliax/line2 is ringing
[Jan 20 12:32:59] DEBUG[19142] rtp.c: Channel 'Celliax/line2' has no RTP, not doing anything
[Jan 20 12:32:59] DEBUG[19142] chan_sip.c: Setting framing from config on incoming call
[Jan 20 12:32:59] DEBUG[19142] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: True
[Jan 20 12:32:59] DEBUG[19142] chan_sip.c: ** Our prefcodec: 0x0 (nothing)
[Jan 20 12:32:59] DEBUG[19142] chan_sip.c: -- Done with adding codecs to SDP
[Jan 20 12:32:59] DEBUG[19142] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw)
[Jan 20 12:32:59] DEBUG[19142] rtp.c: Ooh, format changed from unknown to ulaw
[Jan 20 12:32:59] DEBUG[19142] rtp.c: Created smoother: format: 4 ms: 20 len: 160
[Jan 20 12:33:04] DEBUG[19142] rtp.c: Got RTCP report of 64 bytes
[Jan 20 12:33:07] DEBUG[19063] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jan 20 12:33:07] DEBUG[19063] chan_sip.c: Destroying SIP dialog 1971fe8643b609d416ddbe405e4b98c8@192.168.5.186
[Jan 20 12:33:07] VERBOSE[19063] logger.c: Really destroying SIP dialog '1971fe8643b609d416ddbe405e4b98c8@192.168.5.186' Method: OPTIONS
[Jan 20 12:33:07] DEBUG[19063] devicestate.c: Notification of state change to be queued on device/channel SIP/sta-pbx-7
[Jan 20 12:33:07] DEBUG[19045] chan_sip.c: Checking device state for peer sta-pbx-7
[Jan 20 12:33:07] DEBUG[19045] devicestate.c: Changing state for SIP/sta-pbx-7 - state 5 (Unavailable)
[Jan 20 12:33:07] DEBUG[19048] app_queue.c: Device 'SIP/sta-pbx-7' changed to state '5' (Unavailable) but we don't care because they're not a member of any queue.
[Jan 20 12:33:08] DEBUG[19145] celliax_additional.c: rev exported[0x8419f90|b648dbb0][DEBUG_AT 1346 ][line2 ][ 3, 3, 3] Read line 0: |+CSSI: 7|
[Jan 20 12:33:08] DEBUG[19145] celliax_additional.c: rev exported[0x8419f90|b648dbb0][DEBUG_AT 1616 ][line2 ][ 3, 3,300] |+CSSI: 7| CALLFLOW_CALL_ACTIVE
[Jan 20 12:33:08] DEBUG[19145] celliax_additional.c: rev exported[0x8419f90|b648dbb0][DEBUG_PBX 1619 ][line2 ][ 3, 3,300] just received a remote ANSWER
[Jan 20 12:33:08] DEBUG[19145] chan_celliax.c: rev exported[0x8419f90|b648dbb0][DEBUG_PBX 463 ][line2 ][ 3, 3,300] Queued CONTROL FRAME 3
[Jan 20 12:33:08] DEBUG[19142] chan_celliax.c: rev exported[0x8419f90|b64d1bb0][DEBUG_PBX 910 ][line2 ][ 3, 3,300] Sent CONTROL FRAME 3
[Jan 20 12:33:08] VERBOSE[19142] logger.c: -- Celliax/line2 is ringing
[Jan 20 12:33:08] DEBUG[19142] rtp.c: Channel 'Celliax/line2' has no RTP, not doing anything
[Jan 20 12:33:08] DEBUG[19145] celliax_additional.c: rev exported[0x8419f90|b648dbb0][DEBUG_PBX 1622 ][line2 ][ 3, 3,300] just sent AST_CONTROL_RINGING
[Jan 20 12:33:08] DEBUG[19145] celliax_additional.c: rev exported[0x8419f90|b648dbb0][DEBUG_PBX 1623 ][line2 ][ 3, 3,300] going to send AST_CONTROL_ANSWER
[Jan 20 12:33:08] DEBUG[19145] chan_celliax.c: rev exported[0x8419f90|b648dbb0][DEBUG_PBX 463 ][line2 ][ 3, 3,300] Queued CONTROL FRAME 4
[Jan 20 12:33:08] DEBUG[19142] chan_celliax.c: rev exported[0x8419f90|b64d1bb0][DEBUG_PBX 910 ][line2 ][ 3, 3,300] Sent CONTROL FRAME 4
[Jan 20 12:33:08] DEBUG[19142] devicestate.c: Notification of state change to be queued on device/channel Celliax/line2
[Jan 20 12:33:08] VERBOSE[19142] logger.c: -- Celliax/line2 answered SIP/sta-pbx-2-00000003
[Jan 20 12:33:08] DEBUG[19142] rtp.c: Channel 'Celliax/line2' has no RTP, not doing anything
[Jan 20 12:33:08] DEBUG[19142] devicestate.c: Notification of state change to be queued on device/channel SIP/sta-pbx-2
[Jan 20 12:33:08] DEBUG[19142] chan_sip.c: SIP answering channel: SIP/sta-pbx-2-00000003
[Jan 20 12:33:08] DEBUG[19142] chan_sip.c: Setting framing from config on incoming call
[Jan 20 12:33:08] DEBUG[19142] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: True
[Jan 20 12:33:08] DEBUG[19142] chan_sip.c: ** Our prefcodec: 0x0 (nothing)
[Jan 20 12:33:08] DEBUG[19142] chan_sip.c: -- Done with adding codecs to SDP
[Jan 20 12:33:08] DEBUG[19142] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw)
[Jan 20 12:33:08] WARNING[19142] chan_celliax.c: rev exported[0x8419f90|b64d1bb0][WARNING 547 ][line2 ][ 6, 3,300] Don't know how to display condition 20 on Celliax/line2
[Jan 20 12:33:08] DEBUG[19145] celliax_additional.c: rev exported[0x8419f90|b648dbb0][DEBUG_PBX 1625 ][line2 ][ 6, 3,300] just sent AST_CONTROL_ANSWER
[Jan 20 12:33:08] DEBUG[19145] celliax_additional.c: rev exported[0x8419f90|b648dbb0][DEBUG_PBX 1630 ][line2 ][ 6, 6,300] just interface_state UP
[Jan 20 12:33:08] DEBUG[19063] chan_sip.c: Stopping retransmission on '3444fe41030561f6222671ff7fca1f69@192.168.5.253' of Response 102: Match Found
[Jan 20 12:33:08] DEBUG[19142] celliax_additional.c: rev exported[0x8419f90|b64d1bb0][DEBUG_SOUND 682 ][line2 ][ 6, 6,300] PREVENTING an ALSA write XRUN (celliax can't fill the soundcard buffer fast enough). If this happens often (not after silence or after a pause in the speech, that's OK), and appear to damage the sound quality, first check if you have some IRQ problem, maybe sharing the soundcard IRQ with a broken or heavy loaded ethernet or graphic card. Then consider to increase the alsa_periods_in_buffer (now is set to 5) for this interface in the config file. delayp1=0, delayp2=800
[Jan 20 12:33:09] DEBUG[19045] chan_celliax.c: rev exported[0x8419f90|b7dc7bb0][DEBUG_PBX 499 ][line2 ][ 6, 6,300] Interface is OWNED by a channel
[Jan 20 12:33:09] DEBUG[19045] devicestate.c: Changing state for Celliax/line2 - state 2 (In use)
[Jan 20 12:33:09] DEBUG[19045] chan_sip.c: Checking device state for peer sta-pbx-2
[Jan 20 12:33:09] DEBUG[19045] devicestate.c: Changing state for SIP/sta-pbx-2 - state 1 (Not in use)
[Jan 20 12:33:09] DEBUG[19048] app_queue.c: Device 'Celliax/line2' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Jan 20 12:33:09] DEBUG[19048] app_queue.c: Device 'SIP/sta-pbx-2' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jan 20 12:33:09] DEBUG[19142] rtp.c: Got RTCP report of 64 bytes
[Jan 20 12:33:11] DEBUG[19063] chan_sip.c: Allocating new SIP dialog for 2ca48ac20bbb2bf02d4e18ad2a1402b6@10.255.101.101 - OPTIONS (No RTP)
[Jan 20 12:33:11] DEBUG[19063] chan_sip.c: SIP message could not be handled, bad request: 2ca48ac20bbb2bf02d4e18ad2a1402b6@10.255.101.101
[Jan 20 12:33:14] DEBUG[19142] rtp.c: Got RTCP report of 64 bytes
[Jan 20 12:33:17] DEBUG[19063] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jan 20 12:33:17] DEBUG[19063] chan_sip.c: Destroying SIP dialog 71ace0c820d0c58960080a4f5654dd8b@192.168.5.186
[Jan 20 12:33:17] VERBOSE[19063] logger.c: Really destroying SIP dialog '71ace0c820d0c58960080a4f5654dd8b@192.168.5.186' Method: OPTIONS
[Jan 20 12:33:17] DEBUG[19063] devicestate.c: Notification of state change to be queued on device/channel SIP/sta-pbx-7
[Jan 20 12:33:17] DEBUG[19045] chan_sip.c: Checking device state for peer sta-pbx-7
[Jan 20 12:33:17] DEBUG[19045] devicestate.c: Changing state for SIP/sta-pbx-7 - state 5 (Unavailable)
[Jan 20 12:33:17] DEBUG[19048] app_queue.c: Device 'SIP/sta-pbx-7' changed to state '5' (Unavailable) but we don't care because they're not a member of any queue.
[Jan 20 12:33:18] DEBUG[19063] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jan 20 12:33:18] DEBUG[19063] chan_sip.c: Stopping retransmission on '14ab58cb20b43d191a36569d3f525f71@192.168.5.186' of Request 102: Match Found
[Jan 20 12:33:18] VERBOSE[19063] logger.c: Really destroying SIP dialog '14ab58cb20b43d191a36569d3f525f71@192.168.5.186' Method: OPTIONS
[Jan 20 12:33:19] DEBUG[19142] rtp.c: Got RTCP report of 64 bytes
[Jan 20 12:33:24] DEBUG[19142] rtp.c: Got RTCP report of 64 bytes
[Jan 20 12:33:26] DEBUG[19063] chan_sip.c: Setting NAT on RTP to Off
[Jan 20 12:33:26] DEBUG[19063] chan_sip.c: Allocating new SIP dialog for 49e93b10452167f153ee591560679e92@192.168.5.253 - INVITE (With RTP)
[Jan 20 12:33:26] DEBUG[19063] chan_sip.c: Setting NAT on RTP to Off
[Jan 20 12:33:26] DEBUG[19063] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED.
[Jan 20 12:33:26] DEBUG[19063] chan_sip.c: Processing session-level SDP o=root 2280 2280 IN IP4 192.168.5.253... UNSUPPORTED.
[Jan 20 12:33:26] DEBUG[19063] chan_sip.c: Processing session-level SDP s=session... UNSUPPORTED.
[Jan 20 12:33:26] DEBUG[19063] chan_sip.c: Processing session-level SDP c=IN IP4 192.168.5.253... OK.
[Jan 20 12:33:26] DEBUG[19063] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED.
[Jan 20 12:33:26] DEBUG[19063] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK.
[Jan 20 12:33:26] DEBUG[19063] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK.
[Jan 20 12:33:26] DEBUG[19063] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK.
[Jan 20 12:33:26] DEBUG[19063] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-16... UNSUPPORTED.
[Jan 20 12:33:26] DEBUG[19063] chan_sip.c: Processing media-level (audio) SDP a=silenceSupp:off - - - -... UNSUPPORTED.
[Jan 20 12:33:26] DEBUG[19063] chan_sip.c: Processing media-level (audio) SDP a=ptime:20... OK.
[Jan 20 12:33:26] DEBUG[19063] chan_sip.c: T38 state changed to 0 on channel
[Jan 20 12:33:26] DEBUG[19063] chan_sip.c: We're settling with these formats: 0x4 (ulaw)
[Jan 20 12:33:26] DEBUG[19063] chan_sip.c: Checking SIP call limits for device gsm-1
[Jan 20 12:33:26] DEBUG[19063] chan_sip.c: Updating call counter for incoming call
[Jan 20 12:33:26] DEBUG[19063] chan_sip.c: *** Our native formats are 0x4 (ulaw)
[Jan 20 12:33:26] DEBUG[19063] chan_sip.c: *** Joint capabilities are 0x4 (ulaw)
[Jan 20 12:33:26] DEBUG[19063] chan_sip.c: *** Our capabilities are 0x4 (ulaw)
[Jan 20 12:33:26] DEBUG[19063] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw)
[Jan 20 12:33:26] DEBUG[19063] chan_sip.c: This channel will not be able to handle video.
[Jan 20 12:33:26] DEBUG[19063] chan_sip.c: build_route: Contact hop:
[Jan 20 12:33:26] DEBUG[19063] chan_sip.c: SIP/sta-pbx-2-00000004: New call is still down.... Trying...
[Jan 20 12:33:26] DEBUG[19063] devicestate.c: Notification of state change to be queued on device/channel SIP/sta-pbx-2
[Jan 20 12:33:26] DEBUG[19146] pbx.c: Launching 'Goto'
[Jan 20 12:33:26] VERBOSE[19146] logger.c: -- Executing [80296603885@interoffice:1] Goto("SIP/sta-pbx-2-00000004", "outbound|80296603885|1") in new stack
[Jan 20 12:33:26] VERBOSE[19146] logger.c: -- Goto (outbound,80296603885,1)
[Jan 20 12:33:26] DEBUG[19146] pbx.c: Launching 'Dial'
[Jan 20 12:33:26] VERBOSE[19146] logger.c: -- Executing [80296603885@outbound:1] Dial("SIP/sta-pbx-2-00000004", "Celliax/line0/80296603885") in new stack
[Jan 20 12:33:26] DEBUG[19146] chan_celliax.c: rev exported[(nil)|b6403bb0][DEBUG_PBX 564 ][none ][-1,-1,-1] ENTERING FUNC
[Jan 20 12:33:26] DEBUG[19146] chan_celliax.c: rev exported[(nil)|b6403bb0][DEBUG_PBX 568 ][none ][-1,-1,-1] Try to request type: Celliax, name: line0/80296603885, cause: 0, format: 64
[Jan 20 12:33:26] DEBUG[19146] chan_celliax.c: rev exported[(nil)|b6403bb0][DEBUG_PBX 593 ][line0 ][-1, 0, 0] Requesting: Celliax, name: line0/80296603885, format: 64
[Jan 20 12:33:26] DEBUG[19146] chan_celliax.c: rev exported[(nil)|b6403bb0][DEBUG_PBX 1138 ][line0 ][-1, 0, 0] ENTERING FUNC
[Jan 20 12:33:26] DEBUG[19045] chan_sip.c: Checking device state for peer sta-pbx-2
[Jan 20 12:33:26] DEBUG[19045] devicestate.c: Changing state for SIP/sta-pbx-2 - state 1 (Not in use)
[Jan 20 12:33:26] DEBUG[19146] celliax_additional.c: rev exported[(nil)|b6403bb0][DEBUG_SOUND 402 ][line0 ][-1, 0, 0] Acquired fd 50 from the poll descriptor
[Jan 20 12:33:26] DEBUG[19146] celliax_additional.c: rev exported[(nil)|b6403bb0][DEBUG_SOUND 425 ][line0 ][-1, 0, 0] started!
[Jan 20 12:33:26] DEBUG[19146] celliax_additional.c: rev exported[(nil)|b6403bb0][DEBUG_SOUND 437 ][line0 ][-1, 0, 0] ALSA handle = 138712528
[Jan 20 12:33:26] DEBUG[19048] app_queue.c: Device 'SIP/sta-pbx-2' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jan 20 12:33:26] DEBUG[19146] celliax_additional.c: rev exported[(nil)|b6403bb0][DEBUG_SOUND 402 ][line0 ][-1, 0, 0] Acquired fd 51 from the poll descriptor
[Jan 20 12:33:26] DEBUG[19146] celliax_additional.c: rev exported[(nil)|b6403bb0][DEBUG_SOUND 437 ][line0 ][-1, 0, 0] ALSA handle = 138720136
[Jan 20 12:33:26] DEBUG[19146] chan_celliax.c: rev exported[(nil)|b6403bb0][DEBUG_PBX 1171 ][line0 ][-1, 0, 0] new channel: name=Celliax/line0 requested_state=0
[Jan 20 12:33:26] DEBUG[19146] chan_celliax.c: rev exported[0x841a7e0|b6403bb0][DEBUG_SERIAL 1255 ][line0 ][ 0, 0, 0] STARTED controldev_thread=3057396656 STOP=4294967294 NULL=4294967295
[Jan 20 12:33:26] DEBUG[19146] chan_celliax.c: rev exported[0x841a7e0|b6403bb0][DEBUG_PBX 1267 ][line0 ][ 0, 0, 0] EXITING FUNC
[Jan 20 12:33:26] DEBUG[19146] chan_celliax.c: rev exported[0x841a7e0|b6403bb0][DEBUG_PBX 625 ][line0 ][ 0, 0, 0] EXITING FUNC
[Jan 20 12:33:26] DEBUG[19146] rtp.c: Channel 'Celliax/line0' has no RTP, not doing anything
[Jan 20 12:33:26] DEBUG[19146] channel.c: Not copying variable DIALEDTIME.
[Jan 20 12:33:26] DEBUG[19146] channel.c: Not copying variable ANSWEREDTIME.
[Jan 20 12:33:26] DEBUG[19146] channel.c: Not copying variable DIALEDPEERNAME.
[Jan 20 12:33:26] DEBUG[19146] channel.c: Not copying variable DIALEDPEERNUMBER.
[Jan 20 12:33:26] DEBUG[19146] channel.c: Not copying variable DIALSTATUS.
[Jan 20 12:33:26] DEBUG[19146] channel.c: Not copying variable SIPCALLID.
[Jan 20 12:33:26] DEBUG[19146] channel.c: Not copying variable SIPUSERAGENT.
[Jan 20 12:33:26] DEBUG[19146] channel.c: Not copying variable SIPDOMAIN.
[Jan 20 12:33:26] DEBUG[19146] channel.c: Not copying variable SIPURI.
[Jan 20 12:33:26] DEBUG[19146] chan_celliax.c: rev exported[0x841a7e0|b6403bb0][DEBUG_PBX 1006 ][line0 ][ 0, 0, 0] ENTERING FUNC
[Jan 20 12:33:26] DEBUG[19146] chan_celliax.c: rev exported[0x841a7e0|b6403bb0][DEBUG_PBX 1020 ][line0 ][ 0, 0, 0] celliax_call to call idest: line0/80296603885, timeout: 0!
[Jan 20 12:33:26] DEBUG[19146] chan_celliax.c: rev exported[0x841a7e0|b6403bb0][DEBUG_PBX 1041 ][line0 ][ 0, 0, 0] celliax_call dialing idest: line0/80296603885, timeout: 0, dstr: 80296603885!
[Jan 20 12:33:26] DEBUG[19146] devicestate.c: Notification of state change to be queued on device/channel Celliax/line0
[Jan 20 12:33:26] DEBUG[19146] celliax_additional.c: rev exported[0x841a7e0|b6403bb0][DEBUG_PBX 2945 ][line0 ][ 3, 0, 0] Dialing 80296603885
[Jan 20 12:33:26] DEBUG[19146] celliax_additional.c: rev exported[0x841a7e0|b6403bb0][DEBUG_AT 2547 ][line0 ][ 3, 3, 3] sending: ATD80296603885;, expecting: OK
[Jan 20 12:33:26] DEBUG[19146] celliax_additional.c: rev exported[0x841a7e0|b6403bb0][DEBUG_AT 2396 ][line0 ][ 3, 3, 3] sent data... (A)
[Jan 20 12:33:26] DEBUG[19149] chan_celliax.c: rev exported[0x841a7e0|b63c2bb0][DEBUG_SERIAL 2527 ][line0 ][ 3, 3, 3] In celliax_do_controldev_thread: started, p=0xb7921008
[Jan 20 12:33:26] DEBUG[19045] chan_celliax.c: rev exported[0x841a7e0|b7dc7bb0][DEBUG_PBX 499 ][line0 ][ 3, 3, 3] Interface is OWNED by a channel
[Jan 20 12:33:26] DEBUG[19045] devicestate.c: Changing state for Celliax/line0 - state 2 (In use)
[Jan 20 12:33:26] DEBUG[19048] app_queue.c: Device 'Celliax/line0' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Jan 20 12:33:26] DEBUG[19146] celliax_additional.c: rev exported[0x841a7e0|b6403bb0][DEBUG_AT 2396 ][line0 ][ 3, 3, 3] sent data... (T)
[Jan 20 12:33:26] DEBUG[19146] celliax_additional.c: rev exported[0x841a7e0|b6403bb0][DEBUG_AT 2396 ][line0 ][ 3, 3, 3] sent data... (D)
[Jan 20 12:33:26] DEBUG[19146] celliax_additional.c: rev exported[0x841a7e0|b6403bb0][DEBUG_AT 2396 ][line0 ][ 3, 3, 3] sent data... (8)
[Jan 20 12:33:26] DEBUG[19146] celliax_additional.c: rev exported[0x841a7e0|b6403bb0][DEBUG_AT 2396 ][line0 ][ 3, 3, 3] sent data... (0)
[Jan 20 12:33:26] DEBUG[19146] celliax_additional.c: rev exported[0x841a7e0|b6403bb0][DEBUG_AT 2396 ][line0 ][ 3, 3, 3] sent data... (2)
[Jan 20 12:33:26] DEBUG[19146] celliax_additional.c: rev exported[0x841a7e0|b6403bb0][DEBUG_AT 2396 ][line0 ][ 3, 3, 3] sent data... (9)
[Jan 20 12:33:26] DEBUG[19146] celliax_additional.c: rev exported[0x841a7e0|b6403bb0][DEBUG_AT 2396 ][line0 ][ 3, 3, 3] sent data... (6)
[Jan 20 12:33:26] DEBUG[19146] celliax_additional.c: rev exported[0x841a7e0|b6403bb0][DEBUG_AT 2396 ][line0 ][ 3, 3, 3] sent data... (6)
[Jan 20 12:33:26] DEBUG[19146] celliax_additional.c: rev exported[0x841a7e0|b6403bb0][DEBUG_AT 2396 ][line0 ][ 3, 3, 3] sent data... (0)
[Jan 20 12:33:26] DEBUG[19146] celliax_additional.c: rev exported[0x841a7e0|b6403bb0][DEBUG_AT 2396 ][line0 ][ 3, 3, 3] sent data... (3)
[Jan 20 12:33:26] DEBUG[19146] celliax_additional.c: rev exported[0x841a7e0|b6403bb0][DEBUG_AT 2396 ][line0 ][ 3, 3, 3] sent data... (8)
[Jan 20 12:33:26] DEBUG[19146] celliax_additional.c: rev exported[0x841a7e0|b6403bb0][DEBUG_AT 2396 ][line0 ][ 3, 3, 3] sent data... (8)
[Jan 20 12:33:26] DEBUG[19146] celliax_additional.c: rev exported[0x841a7e0|b6403bb0][DEBUG_AT 2396 ][line0 ][ 3, 3, 3] sent data... (5)
[Jan 20 12:33:26] DEBUG[19146] celliax_additional.c: rev exported[0x841a7e0|b6403bb0][DEBUG_AT 2396 ][line0 ][ 3, 3, 3] sent data... (;)
[Jan 20 12:33:26] DEBUG[19146] celliax_additional.c: rev exported[0x841a7e0|b6403bb0][DEBUG_AT 2426 ][line0 ][ 3, 3, 3] sent (carriage return)
[Jan 20 12:33:26] DEBUG[19146] celliax_additional.c: rev exported[0x841a7e0|b6403bb0][DEBUG_AT 1346 ][line0 ][ 3, 3, 3] Read line 0: |OK|
[Jan 20 12:33:26] DEBUG[19146] celliax_additional.c: rev exported[0x841a7e0|b6403bb0][DEBUG_AT 2159 ][line0 ][ 3, 3, 3] |OK| got what EXPECTED
[Jan 20 12:33:26] DEBUG[19146] chan_celliax.c: rev exported[0x841a7e0|b6403bb0][DEBUG_PBX 1059 ][line0 ][ 3, 3, 3] call ongoing
[Jan 20 12:33:26] DEBUG[19146] chan_celliax.c: rev exported[0x841a7e0|b6403bb0][DEBUG_PBX 1065 ][line0 ][ 3, 3, 3] celliax_call dialed idest: line0/80296603885, timeout: 0, dstr: 80296603885!
[Jan 20 12:33:26] DEBUG[19146] chan_celliax.c: rev exported[0x841a7e0|b6403bb0][DEBUG_PBX 1068 ][line0 ][ 3, 3, 3] EXITING FUNC
[Jan 20 12:33:26] VERBOSE[19146] logger.c: -- Called line0/80296603885
[Jan 20 12:33:26] DEBUG[19146] channel.c: Set channel Celliax/line0 to read format ulaw
[Jan 20 12:33:26] DEBUG[19146] channel.c: Set channel SIP/sta-pbx-2-00000004 to read format slin
[Jan 20 12:33:26] DEBUG[19146] channel.c: Set channel Celliax/line0 to write format slin
[Jan 20 12:33:26] VERBOSE[19146] logger.c: -- Celliax/line0 is ringing
[Jan 20 12:33:26] DEBUG[19146] rtp.c: Channel 'Celliax/line0' has no RTP, not doing anything
[Jan 20 12:33:26] DEBUG[19146] chan_sip.c: Setting framing from config on incoming call
[Jan 20 12:33:26] DEBUG[19146] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: True
[Jan 20 12:33:26] DEBUG[19146] chan_sip.c: ** Our prefcodec: 0x0 (nothing)
[Jan 20 12:33:26] DEBUG[19146] chan_sip.c: -- Done with adding codecs to SDP
[Jan 20 12:33:26] DEBUG[19146] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw)
[Jan 20 12:33:26] DEBUG[19146] rtp.c: Ooh, format changed from unknown to ulaw
[Jan 20 12:33:26] DEBUG[19146] rtp.c: Created smoother: format: 4 ms: 20 len: 160
[Jan 20 12:33:27] DEBUG[19063] chan_sip.c: Auto destroying SIP dialog '62708eb6736f0a444c64f42406ea538b@192.168.5.253'
[Jan 20 12:33:27] DEBUG[19063] chan_sip.c: Destroying SIP dialog 62708eb6736f0a444c64f42406ea538b@192.168.5.253
[Jan 20 12:33:27] VERBOSE[19063] logger.c: Really destroying SIP dialog '62708eb6736f0a444c64f42406ea538b@192.168.5.253' Method: OPTIONS
[Jan 20 12:33:27] DEBUG[19063] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jan 20 12:33:27] DEBUG[19063] chan_sip.c: Destroying SIP dialog 1af6c9b57d6e98144aa4e54f30317983@192.168.5.186
[Jan 20 12:33:27] VERBOSE[19063] logger.c: Really destroying SIP dialog '1af6c9b57d6e98144aa4e54f30317983@192.168.5.186' Method: OPTIONS
[Jan 20 12:33:27] DEBUG[19063] devicestate.c: Notification of state change to be queued on device/channel SIP/sta-pbx-7
[Jan 20 12:33:27] DEBUG[19045] chan_sip.c: Checking device state for peer sta-pbx-7
[Jan 20 12:33:27] DEBUG[19045] devicestate.c: Changing state for SIP/sta-pbx-7 - state 5 (Unavailable)
[Jan 20 12:33:27] DEBUG[19048] app_queue.c: Device 'SIP/sta-pbx-7' changed to state '5' (Unavailable) but we don't care because they're not a member of any queue.
[Jan 20 12:33:28] DEBUG[19149] celliax_additional.c: rev exported[0x841a7e0|b63c2bb0][DEBUG_AT 1346 ][line0 ][ 3, 3, 3] Read line 0: |+CSSI: 1|
[Jan 20 12:33:28] DEBUG[19149] celliax_additional.c: rev exported[0x841a7e0|b63c2bb0][DEBUG_AT 1637 ][line0 ][ 3, 3, 3] |+CSSI: 1| CALLFLOW_CALL_DIALING
[Jan 20 12:33:29] DEBUG[19142] rtp.c: Got RTCP report of 64 bytes
[Jan 20 12:33:31] DEBUG[19146] rtp.c: Got RTCP report of 64 bytes
[Jan 20 12:33:34] DEBUG[19142] rtp.c: Got RTCP report of 64 bytes
[Jan 20 12:33:36] DEBUG[19146] rtp.c: Got RTCP report of 64 bytes
[Jan 20 12:33:37] DEBUG[19063] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jan 20 12:33:38] DEBUG[19063] chan_sip.c: Destroying SIP dialog 103dad4a232cd0bd63d5cf833fe7e376@192.168.5.186
[Jan 20 12:33:38] VERBOSE[19063] logger.c: Really destroying SIP dialog '103dad4a232cd0bd63d5cf833fe7e376@192.168.5.186' Method: OPTIONS
[Jan 20 12:33:38] DEBUG[19063] devicestate.c: Notification of state change to be queued on device/channel SIP/sta-pbx-7
[Jan 20 12:33:38] DEBUG[19045] chan_sip.c: Checking device state for peer sta-pbx-7
[Jan 20 12:33:38] DEBUG[19045] devicestate.c: Changing state for SIP/sta-pbx-7 - state 5 (Unavailable)
[Jan 20 12:33:38] DEBUG[19048] app_queue.c: Device 'SIP/sta-pbx-7' changed to state '5' (Unavailable) but we don't care because they're not a member of any queue.
[Jan 20 12:33:39] DEBUG[19142] rtp.c: Got RTCP report of 64 bytes
[Jan 20 12:33:41] DEBUG[19146] rtp.c: Got RTCP report of 64 bytes
[Jan 20 12:33:43] DEBUG[19063] chan_sip.c: Auto destroying SIP dialog '2ca48ac20bbb2bf02d4e18ad2a1402b6@10.255.101.101'
[Jan 20 12:33:43] DEBUG[19063] chan_sip.c: Destroying SIP dialog 2ca48ac20bbb2bf02d4e18ad2a1402b6@10.255.101.101
[Jan 20 12:33:43] VERBOSE[19063] logger.c: Really destroying SIP dialog '2ca48ac20bbb2bf02d4e18ad2a1402b6@10.255.101.101' Method: OPTIONS
[Jan 20 12:33:44] DEBUG[19142] rtp.c: Got RTCP report of 64 bytes
[Jan 20 12:33:46] DEBUG[19063] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jan 20 12:33:46] DEBUG[19063] chan_sip.c: Stopping retransmission on '61f742e768087c4067c7eb0405d15960@192.168.5.186' of Request 102: Match Found
[Jan 20 12:33:46] VERBOSE[19063] logger.c: Really destroying SIP dialog '61f742e768087c4067c7eb0405d15960@192.168.5.186' Method: OPTIONS
[Jan 20 12:33:46] DEBUG[19063] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jan 20 12:33:46] DEBUG[19063] chan_sip.c: Stopping retransmission on '311cfad13afe6b642967bc4b782a87a2@192.168.5.186' of Request 102: Match Found
[Jan 20 12:33:46] VERBOSE[19063] logger.c: Really destroying SIP dialog '311cfad13afe6b642967bc4b782a87a2@192.168.5.186' Method: OPTIONS
[Jan 20 12:33:46] DEBUG[19146] rtp.c: Got RTCP report of 64 bytes
[Jan 20 12:33:46] DEBUG[19063] chan_sip.c: Setting SIP_ALREADYGONE on dialog 3444fe41030561f6222671ff7fca1f69@192.168.5.253
[Jan 20 12:33:46] DEBUG[19063] chan_sip.c: Received bye, issuing owner hangup
[Jan 20 12:33:46] DEBUG[19142] channel.c: Didn't get a frame from channel: SIP/sta-pbx-2-00000003
[Jan 20 12:33:46] WARNING[19142] chan_celliax.c: rev exported[0x8419f90|b64d1bb0][WARNING 547 ][line2 ][ 6, 6,300] Don't know how to display condition 20 on Celliax/line2
[Jan 20 12:33:46] DEBUG[19142] channel.c: Bridge stops bridging channels SIP/sta-pbx-2-00000003 and Celliax/line2
[Jan 20 12:33:46] DEBUG[19142] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record.
[Jan 20 12:33:46] DEBUG[19142] cdr_addon_mysql.c: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,userfield) VALUES ('2010-01-20 12:32:59','\"Sergei Pahamovich\" <1304>','1304','80295566066','outbound', 'SIP/sta-pbx-2-00000003','Celliax/line2','Dial','Celliax/line2/80295566066',47,38,'ANSWERED',3,'','')
[Jan 20 12:33:46] DEBUG[19142] channel.c: Hanging up channel 'Celliax/line2'
[Jan 20 12:33:46] DEBUG[19142] chan_celliax.c: rev exported[0x8419f90|b64d1bb0][DEBUG_PBX 648 ][line2 ][ 6, 6,300] ENTERING FUNC
[Jan 20 12:33:46] DEBUG[19145] chan_celliax.c: exported[b648dbb0] I'm a dying thread, and I'm to go unlocking mutex 0xb7860358 for the 0th time
[Jan 20 12:33:46] DEBUG[19145] chan_celliax.c: exported[b648dbb0] I'm a dying thread, and I'm to go unlocking mutex 0xb7860358 for the 1th time
[Jan 20 12:33:46] DEBUG[19145] chan_celliax.c: exported[b648dbb0] I'm a dying thread, and I'm to go unlocking mutex 0xb7860358 for the 2th time
[Jan 20 12:33:46] DEBUG[19145] chan_celliax.c: exported[b648dbb0] I'm a dying thread, and I'm to go unlocking mutex 0xb7860358 for the 3th time
[Jan 20 12:33:46] DEBUG[19145] chan_celliax.c: exported[b648dbb0] I'm a dying thread, and I'm to go unlocking mutex 0xb7860358 for the 4th time
[Jan 20 12:33:46] DEBUG[19145] chan_celliax.c: exported[b648dbb0] I'm a dying thread, I've finished unlocking mutex 0xb7860358
[Jan 20 12:33:46] DEBUG[19142] celliax_additional.c: rev exported[0x8419f90|b64d1bb0][DEBUG_AT 2547 ][line2 ][ 6, 6,300] sending: ATH, expecting: OK
[Jan 20 12:33:46] DEBUG[19142] celliax_additional.c: rev exported[0x8419f90|b64d1bb0][DEBUG_AT 2396 ][line2 ][ 6, 6,300] sent data... (A)
[Jan 20 12:33:46] DEBUG[19142] celliax_additional.c: rev exported[0x8419f90|b64d1bb0][DEBUG_AT 2396 ][line2 ][ 6, 6,300] sent data... (T)
[Jan 20 12:33:46] DEBUG[19142] celliax_additional.c: rev exported[0x8419f90|b64d1bb0][DEBUG_AT 2396 ][line2 ][ 6, 6,300] sent data... (H)
[Jan 20 12:33:46] DEBUG[19142] celliax_additional.c: rev exported[0x8419f90|b64d1bb0][DEBUG_AT 2426 ][line2 ][ 6, 6,300] sent (carriage return)
[Jan 20 12:33:46] DEBUG[19142] celliax_additional.c: rev exported[0x8419f90|b64d1bb0][DEBUG_AT 1346 ][line2 ][ 6, 6,300] Read line 0: |OK|
[Jan 20 12:33:46] DEBUG[19142] celliax_additional.c: rev exported[0x8419f90|b64d1bb0][DEBUG_AT 2159 ][line2 ][ 6, 6,300] |OK| got what EXPECTED
[Jan 20 12:33:46] DEBUG[19142] chan_celliax.c: rev exported[0x8419f90|b64d1bb0][DEBUG_SERIAL 695 ][line2 ][ 6, 0, 0] call hungup
[Jan 20 12:33:46] DEBUG[19142] chan_celliax.c: rev exported[0x8419f90|b64d1bb0][DEBUG_SOUND 717 ][line2 ][ 6, 0, 0] shutting down sound
[Jan 20 12:33:46] DEBUG[19142] chan_celliax.c: rev exported[0x8419f90|b64d1bb0][DEBUG_SERIAL 2677 ][line2 ][ 6, 0, 0] Syncing Serial
[Jan 20 12:33:46] DEBUG[19142] devicestate.c: Notification of state change to be queued on device/channel Celliax/line2
[Jan 20 12:33:46] DEBUG[19142] chan_celliax.c: rev exported[(nil)|b64d1bb0][DEBUG_PBX 768 ][line2 ][-1, 0, 0] Hanged Up
[Jan 20 12:33:47] DEBUG[19142] chan_celliax.c: rev exported[(nil)|b64d1bb0][DEBUG_PBX 779 ][line2 ][-1, 0, 0] EXITING FUNC
[Jan 20 12:33:47] DEBUG[19142] devicestate.c: Notification of state change to be queued on device/channel Celliax/line2
[Jan 20 12:33:47] DEBUG[19142] rtp.c: Channel '' has no RTP, not doing anything
[Jan 20 12:33:47] DEBUG[19142] app_dial.c: Exiting with DIALSTATUS=ANSWER.
[Jan 20 12:33:47] DEBUG[19142] pbx.c: Spawn extension (outbound,80295566066,1) exited non-zero on 'SIP/sta-pbx-2-00000003'
[Jan 20 12:33:47] VERBOSE[19142] logger.c: == Spawn extension (outbound, 80295566066, 1) exited non-zero on 'SIP/sta-pbx-2-00000003'
[Jan 20 12:33:47] DEBUG[19142] channel.c: Soft-Hanging up channel 'SIP/sta-pbx-2-00000003'
[Jan 20 12:33:47] DEBUG[19142] channel.c: Hanging up channel 'SIP/sta-pbx-2-00000003'
[Jan 20 12:33:47] DEBUG[19142] chan_sip.c: Hangup call SIP/sta-pbx-2-00000003, SIP callid 3444fe41030561f6222671ff7fca1f69@192.168.5.253)
[Jan 20 12:33:47] DEBUG[19142] devicestate.c: Notification of state change to be queued on device/channel SIP/sta-pbx-2
[Jan 20 12:33:47] DEBUG[19045] chan_celliax.c: rev exported[(nil)|b7dc7bb0][DEBUG_PBX 495 ][line2 ][-1, 0, 0] Interface is NOT OWNED by a channel
[Jan 20 12:33:47] DEBUG[19045] devicestate.c: Changing state for Celliax/line2 - state 1 (Not in use)
[Jan 20 12:33:47] DEBUG[19045] chan_celliax.c: rev exported[(nil)|b7dc7bb0][DEBUG_PBX 495 ][line2 ][-1, 0, 0] Interface is NOT OWNED by a channel
[Jan 20 12:33:47] DEBUG[19045] devicestate.c: Changing state for Celliax/line2 - state 1 (Not in use)
[Jan 20 12:33:47] DEBUG[19045] chan_sip.c: Checking device state for peer sta-pbx-2
[Jan 20 12:33:47] DEBUG[19045] devicestate.c: Changing state for SIP/sta-pbx-2 - state 1 (Not in use)
[Jan 20 12:33:47] DEBUG[19048] app_queue.c: Device 'Celliax/line2' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jan 20 12:33:47] DEBUG[19048] app_queue.c: Device 'Celliax/line2' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jan 20 12:33:47] DEBUG[19048] app_queue.c: Device 'SIP/sta-pbx-2' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jan 20 12:33:47] VERBOSE[19063] logger.c: Really destroying SIP dialog '3444fe41030561f6222671ff7fca1f69@192.168.5.253' Method: BYE
[Jan 20 12:33:48] DEBUG[19063] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jan 20 12:33:48] DEBUG[19063] chan_sip.c: Destroying SIP dialog 28b5a27971941ef0486bf1b5597576f5@192.168.5.186
[Jan 20 12:33:48] VERBOSE[19063] logger.c: Really destroying SIP dialog '28b5a27971941ef0486bf1b5597576f5@192.168.5.186' Method: OPTIONS
[Jan 20 12:33:48] DEBUG[19063] devicestate.c: Notification of state change to be queued on device/channel SIP/sta-pbx-7
[Jan 20 12:33:48] DEBUG[19045] chan_sip.c: Checking device state for peer sta-pbx-7
[Jan 20 12:33:48] DEBUG[19045] devicestate.c: Changing state for SIP/sta-pbx-7 - state 5 (Unavailable)
[Jan 20 12:33:48] DEBUG[19048] app_queue.c: Device 'SIP/sta-pbx-7' changed to state '5' (Unavailable) but we don't care because they're not a member of any queue.
[Jan 20 12:33:49] DEBUG[19149] celliax_additional.c: rev exported[0x841a7e0|b63c2bb0][DEBUG_AT 1346 ][line0 ][ 3, 3, 3] Read line 0: |+CSSI: 7|
[Jan 20 12:33:49] DEBUG[19149] celliax_additional.c: rev exported[0x841a7e0|b63c2bb0][DEBUG_AT 1616 ][line0 ][ 3, 3,300] |+CSSI: 7| CALLFLOW_CALL_ACTIVE
[Jan 20 12:33:49] DEBUG[19149] celliax_additional.c: rev exported[0x841a7e0|b63c2bb0][DEBUG_PBX 1619 ][line0 ][ 3, 3,300] just received a remote ANSWER
[Jan 20 12:33:49] DEBUG[19149] chan_celliax.c: rev exported[0x841a7e0|b63c2bb0][DEBUG_PBX 463 ][line0 ][ 3, 3,300] Queued CONTROL FRAME 3
[Jan 20 12:33:49] DEBUG[19146] chan_celliax.c: rev exported[0x841a7e0|b6403bb0][DEBUG_PBX 910 ][line0 ][ 3, 3,300] Sent CONTROL FRAME 3
[Jan 20 12:33:49] VERBOSE[19146] logger.c: -- Celliax/line0 is ringing
[Jan 20 12:33:49] DEBUG[19146] rtp.c: Channel 'Celliax/line0' has no RTP, not doing anything
[Jan 20 12:33:49] DEBUG[19149] celliax_additional.c: rev exported[0x841a7e0|b63c2bb0][DEBUG_PBX 1622 ][line0 ][ 3, 3,300] just sent AST_CONTROL_RINGING
[Jan 20 12:33:49] DEBUG[19149] celliax_additional.c: rev exported[0x841a7e0|b63c2bb0][DEBUG_PBX 1623 ][line0 ][ 3, 3,300] going to send AST_CONTROL_ANSWER
[Jan 20 12:33:49] DEBUG[19149] chan_celliax.c: rev exported[0x841a7e0|b63c2bb0][DEBUG_PBX 463 ][line0 ][ 3, 3,300] Queued CONTROL FRAME 4
[Jan 20 12:33:49] DEBUG[19146] chan_celliax.c: rev exported[0x841a7e0|b6403bb0][DEBUG_PBX 910 ][line0 ][ 3, 3,300] Sent CONTROL FRAME 4
[Jan 20 12:33:49] DEBUG[19146] devicestate.c: Notification of state change to be queued on device/channel Celliax/line0
[Jan 20 12:33:49] VERBOSE[19146] logger.c: -- Celliax/line0 answered SIP/sta-pbx-2-00000004
[Jan 20 12:33:49] DEBUG[19146] rtp.c: Channel 'Celliax/line0' has no RTP, not doing anything
[Jan 20 12:33:49] DEBUG[19146] devicestate.c: Notification of state change to be queued on device/channel SIP/sta-pbx-2
[Jan 20 12:33:49] DEBUG[19146] chan_sip.c: SIP answering channel: SIP/sta-pbx-2-00000004
[Jan 20 12:33:49] DEBUG[19146] chan_sip.c: Setting framing from config on incoming call
[Jan 20 12:33:49] DEBUG[19146] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: True
[Jan 20 12:33:49] DEBUG[19146] chan_sip.c: ** Our prefcodec: 0x0 (nothing)
[Jan 20 12:33:49] DEBUG[19146] chan_sip.c: -- Done with adding codecs to SDP
[Jan 20 12:33:49] DEBUG[19146] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw)
[Jan 20 12:33:49] WARNING[19146] chan_celliax.c: rev exported[0x841a7e0|b6403bb0][WARNING 547 ][line0 ][ 6, 3,300] Don't know how to display condition 20 on Celliax/line0
[Jan 20 12:33:49] DEBUG[19045] chan_celliax.c: rev exported[0x841a7e0|b7dc7bb0][DEBUG_PBX 499 ][line0 ][ 6, 3,300] Interface is OWNED by a channel
[Jan 20 12:33:49] DEBUG[19045] devicestate.c: Changing state for Celliax/line0 - state 2 (In use)
[Jan 20 12:33:49] DEBUG[19045] chan_sip.c: Checking device state for peer sta-pbx-2
[Jan 20 12:33:49] DEBUG[19045] devicestate.c: Changing state for SIP/sta-pbx-2 - state 1 (Not in use)
[Jan 20 12:33:49] DEBUG[19063] chan_sip.c: Stopping retransmission on '49e93b10452167f153ee591560679e92@192.168.5.253' of Response 102: Match Found
[Jan 20 12:33:49] DEBUG[19048] app_queue.c: Device 'Celliax/line0' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Jan 20 12:33:50] DEBUG[19048] app_queue.c: Device 'SIP/sta-pbx-2' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jan 20 12:33:50] DEBUG[19149] celliax_additional.c: rev exported[0x841a7e0|b63c2bb0][DEBUG_PBX 1625 ][line0 ][ 6, 3,300] just sent AST_CONTROL_ANSWER
[Jan 20 12:33:50] DEBUG[19149] celliax_additional.c: rev exported[0x841a7e0|b63c2bb0][DEBUG_PBX 1630 ][line0 ][ 6, 6,300] just interface_state UP
[Jan 20 12:33:50] DEBUG[19146] celliax_additional.c: rev exported[0x841a7e0|b6403bb0][DEBUG_SOUND 682 ][line0 ][ 6, 6,300] PREVENTING an ALSA write XRUN (celliax can't fill the soundcard buffer fast enough). If this happens often (not after silence or after a pause in the speech, that's OK), and appear to damage the sound quality, first check if you have some IRQ problem, maybe sharing the soundcard IRQ with a broken or heavy loaded ethernet or graphic card. Then consider to increase the alsa_periods_in_buffer (now is set to 5) for this interface in the config file. delayp1=0, delayp2=800
[Jan 20 12:33:50] DEBUG[19146] celliax_additional.c: rev exported[0x841a7e0|b6403bb0][DEBUG_SOUND 606 ][line0 ][ 6, 6,300] You've got an ALSA write XRUN in the past (celliax can't fill the soundcard buffer fast enough). If this happens often (not after silence or after a pause in the speech, that's OK), and appear to damage the sound quality, first check if you have some IRQ problem, maybe sharing the soundcard IRQ with a broken or heavy loaded ethernet or graphic card. Then consider to increase the alsa_periods_in_buffer (now is set to 5) for this interface in the config file
[Jan 20 12:33:51] DEBUG[19146] rtp.c: Got RTCP report of 64 bytes
[Jan 20 12:33:55] DEBUG[19063] chan_sip.c: Allocating new SIP dialog for 3f56239341aa80994d5b860543302e0a@192.168.5.253 - OPTIONS (No RTP)
[Jan 20 12:33:55] DEBUG[19063] chan_sip.c: SIP message could not be handled, bad request: 3f56239341aa80994d5b860543302e0a@192.168.5.253
[Jan 20 12:33:56] DEBUG[19146] rtp.c: Got RTCP report of 64 bytes
[Jan 20 12:33:57] DEBUG[19063] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jan 20 12:33:57] DEBUG[19063] chan_sip.c: Stopping retransmission on '3aa7ece9757ceca5236bbae518dd5f60@192.168.5.186' of Request 102: Match Found
[Jan 20 12:33:57] VERBOSE[19063] logger.c: Really destroying SIP dialog '3aa7ece9757ceca5236bbae518dd5f60@192.168.5.186' Method: OPTIONS
[Jan 20 12:33:57] DEBUG[19063] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jan 20 12:33:57] DEBUG[19063] chan_sip.c: Stopping retransmission on '27a0acc21495899e29d4b5944410fdb6@192.168.5.186' of Request 102: Match Found
[Jan 20 12:33:57] VERBOSE[19063] logger.c: Really destroying SIP dialog '27a0acc21495899e29d4b5944410fdb6@192.168.5.186' Method: OPTIONS
[Jan 20 12:33:58] DEBUG[19063] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jan 20 12:33:58] DEBUG[19063] chan_sip.c: Destroying SIP dialog 77e390861cd3281c200e58791f52f231@192.168.5.186
[Jan 20 12:33:58] VERBOSE[19063] logger.c: Really destroying SIP dialog '77e390861cd3281c200e58791f52f231@192.168.5.186' Method: OPTIONS
[Jan 20 12:33:58] DEBUG[19063] devicestate.c: Notification of state change to be queued on device/channel SIP/sta-pbx-7
[Jan 20 12:33:58] DEBUG[19045] chan_sip.c: Checking device state for peer sta-pbx-7
[Jan 20 12:33:58] DEBUG[19045] devicestate.c: Changing state for SIP/sta-pbx-7 - state 5 (Unavailable)
[Jan 20 12:33:58] DEBUG[19048] app_queue.c: Device 'SIP/sta-pbx-7' changed to state '5' (Unavailable) but we don't care because they're not a member of any queue.
[Jan 20 12:34:01] DEBUG[19146] rtp.c: Got RTCP report of 64 bytes
[Jan 20 12:34:06] DEBUG[19146] rtp.c: Got RTCP report of 64 bytes
[Jan 20 12:34:08] DEBUG[19063] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jan 20 12:34:08] DEBUG[19063] chan_sip.c: Destroying SIP dialog 5c9567e844d7d48d1ec721fa198734f0@192.168.5.186
[Jan 20 12:34:08] VERBOSE[19063] logger.c: Really destroying SIP dialog '5c9567e844d7d48d1ec721fa198734f0@192.168.5.186' Method: OPTIONS
[Jan 20 12:34:08] DEBUG[19063] devicestate.c: Notification of state change to be queued on device/channel SIP/sta-pbx-7
[Jan 20 12:34:08] DEBUG[19045] chan_sip.c: Checking device state for peer sta-pbx-7
[Jan 20 12:34:08] DEBUG[19045] devicestate.c: Changing state for SIP/sta-pbx-7 - state 5 (Unavailable)
[Jan 20 12:34:08] DEBUG[19048] app_queue.c: Device 'SIP/sta-pbx-7' changed to state '5' (Unavailable) but we don't care because they're not a member of any queue.
[Jan 20 12:34:11] DEBUG[19063] chan_sip.c: Allocating new SIP dialog for 7f4396743f766358509c218d11add6d3@10.255.101.101 - OPTIONS (No RTP)
[Jan 20 12:34:11] DEBUG[19063] chan_sip.c: SIP message could not be handled, bad request: 7f4396743f766358509c218d11add6d3@10.255.101.101
[Jan 20 12:34:11] DEBUG[19146] rtp.c: Got RTCP report of 64 bytes
[Jan 20 12:34:16] DEBUG[19146] rtp.c: Got RTCP report of 64 bytes
[Jan 20 12:34:18] DEBUG[19063] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jan 20 12:34:18] DEBUG[19063] chan_sip.c: Stopping retransmission on '12709155619d7dbf4b00c0c773b66341@192.168.5.186' of Request 102: Match Found
[Jan 20 12:34:18] VERBOSE[19063] logger.c: Really destroying SIP dialog '12709155619d7dbf4b00c0c773b66341@192.168.5.186' Method: OPTIONS
[Jan 20 12:34:18] DEBUG[19063] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jan 20 12:34:18] DEBUG[19063] chan_sip.c: Destroying SIP dialog 56f9d69b5bde747516ed9b74060cece3@192.168.5.186
[Jan 20 12:34:18] VERBOSE[19063] logger.c: Really destroying SIP dialog '56f9d69b5bde747516ed9b74060cece3@192.168.5.186' Method: OPTIONS
[Jan 20 12:34:18] DEBUG[19063] devicestate.c: Notification of state change to be queued on device/channel SIP/sta-pbx-7
[Jan 20 12:34:18] DEBUG[19045] chan_sip.c: Checking device state for peer sta-pbx-7
[Jan 20 12:34:18] DEBUG[19045] devicestate.c: Changing state for SIP/sta-pbx-7 - state 5 (Unavailable)
[Jan 20 12:34:18] DEBUG[19048] app_queue.c: Device 'SIP/sta-pbx-7' changed to state '5' (Unavailable) but we don't care because they're not a member of any queue.
[Jan 20 12:34:19] DEBUG[19146] celliax_additional.c: rev exported[0x841a7e0|b6403bb0][DEBUG_SOUND 606 ][line0 ][ 6, 6,300] You've got an ALSA write XRUN in the past (celliax can't fill the soundcard buffer fast enough). If this happens often (not after silence or after a pause in the speech, that's OK), and appear to damage the sound quality, first check if you have some IRQ problem, maybe sharing the soundcard IRQ with a broken or heavy loaded ethernet or graphic card. Then consider to increase the alsa_periods_in_buffer (now is set to 5) for this interface in the config file
[Jan 20 12:34:21] DEBUG[19146] rtp.c: Got RTCP report of 64 bytes
[Jan 20 12:34:26] DEBUG[19146] rtp.c: Got RTCP report of 64 bytes
[Jan 20 12:34:27] DEBUG[19063] chan_sip.c: Auto destroying SIP dialog '3f56239341aa80994d5b860543302e0a@192.168.5.253'
[Jan 20 12:34:27] DEBUG[19063] chan_sip.c: Destroying SIP dialog 3f56239341aa80994d5b860543302e0a@192.168.5.253
[Jan 20 12:34:27] VERBOSE[19063] logger.c: Really destroying SIP dialog '3f56239341aa80994d5b860543302e0a@192.168.5.253' Method: OPTIONS
[Jan 20 12:34:28] DEBUG[19063] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jan 20 12:34:29] DEBUG[19063] chan_sip.c: Destroying SIP dialog 4bb0c4d655a0b6a82a358dca2efbde6e@192.168.5.186
[Jan 20 12:34:29] VERBOSE[19063] logger.c: Really destroying SIP dialog '4bb0c4d655a0b6a82a358dca2efbde6e@192.168.5.186' Method: OPTIONS
[Jan 20 12:34:29] DEBUG[19063] devicestate.c: Notification of state change to be queued on device/channel SIP/sta-pbx-7
[Jan 20 12:34:29] DEBUG[19045] chan_sip.c: Checking device state for peer sta-pbx-7
[Jan 20 12:34:29] DEBUG[19045] devicestate.c: Changing state for SIP/sta-pbx-7 - state 5 (Unavailable)
[Jan 20 12:34:29] DEBUG[19048] app_queue.c: Device 'SIP/sta-pbx-7' changed to state '5' (Unavailable) but we don't care because they're not a member of any queue.
[Jan 20 12:34:30] DEBUG[19146] celliax_additional.c: rev exported[0x841a7e0|b6403bb0][DEBUG_SOUND 606 ][line0 ][ 6, 6,300] You've got an ALSA write XRUN in the past (celliax can't fill the soundcard buffer fast enough). If this happens often (not after silence or after a pause in the speech, that's OK), and appear to damage the sound quality, first check if you have some IRQ problem, maybe sharing the soundcard IRQ with a broken or heavy loaded ethernet or graphic card. Then consider to increase the alsa_periods_in_buffer (now is set to 5) for this interface in the config file
[Jan 20 12:34:31] DEBUG[19146] rtp.c: Got RTCP report of 64 bytes
[Jan 20 12:34:32] DEBUG[19060] chan_celliax.c: rev exported[(nil)|b775bbb0][DEBUG_SERIAL 2102 ][line1 ][-1, 0, 0] Syncing Serial
[Jan 20 12:34:32] DEBUG[19060] celliax_additional.c: rev exported[(nil)|b775bbb0][DEBUG_AT 2501 ][line1 ][-1, 0, 0] sending: AT
[Jan 20 12:34:32] DEBUG[19060] celliax_additional.c: rev exported[(nil)|b775bbb0][DEBUG_AT 2396 ][line1 ][-1, 0, 0] sent data... (A)
[Jan 20 12:34:32] DEBUG[19060] celliax_additional.c: rev exported[(nil)|b775bbb0][DEBUG_AT 2396 ][line1 ][-1, 0, 0] sent data... (T)
[Jan 20 12:34:32] DEBUG[19060] celliax_additional.c: rev exported[(nil)|b775bbb0][DEBUG_AT 2426 ][line1 ][-1, 0, 0] sent (carriage return)
[Jan 20 12:34:32] DEBUG[19060] celliax_additional.c: rev exported[(nil)|b775bbb0][DEBUG_AT 1346 ][line1 ][-1, 0, 0] Read line 0: |OK|
[Jan 20 12:34:32] DEBUG[19060] celliax_additional.c: rev exported[(nil)|b775bbb0][DEBUG_AT 2165 ][line1 ][-1, 0, 0] got OK
[Jan 20 12:34:32] DEBUG[19060] celliax_additional.c: rev exported[(nil)|b775bbb0][DEBUG_AT 2547 ][line1 ][-1, 0, 0] sending: AT+CBC, expecting: OK
[Jan 20 12:34:32] DEBUG[19060] celliax_additional.c: rev exported[(nil)|b775bbb0][DEBUG_AT 2396 ][line1 ][-1, 0, 0] sent data... (A)
[Jan 20 12:34:32] DEBUG[19060] celliax_additional.c: rev exported[(nil)|b775bbb0][DEBUG_AT 2396 ][line1 ][-1, 0, 0] sent data... (T)
[Jan 20 12:34:32] DEBUG[19060] celliax_additional.c: rev exported[(nil)|b775bbb0][DEBUG_AT 2396 ][line1 ][-1, 0, 0] sent data... (+)
[Jan 20 12:34:32] DEBUG[19060] celliax_additional.c: rev exported[(nil)|b775bbb0][DEBUG_AT 2396 ][line1 ][-1, 0, 0] sent data... (C)
[Jan 20 12:34:32] DEBUG[19060] celliax_additional.c: rev exported[(nil)|b775bbb0][DEBUG_AT 2396 ][line1 ][-1, 0, 0] sent data... (B)
[Jan 20 12:34:32] DEBUG[19060] celliax_additional.c: rev exported[(nil)|b775bbb0][DEBUG_AT 2396 ][line1 ][-1, 0, 0] sent data... (C)
[Jan 20 12:34:32] DEBUG[19060] celliax_additional.c: rev exported[(nil)|b775bbb0][DEBUG_AT 2426 ][line1 ][-1, 0, 0] sent (carriage return)
[Jan 20 12:34:32] DEBUG[19060] celliax_additional.c: rev exported[(nil)|b775bbb0][DEBUG_AT 1346 ][line1 ][-1, 0, 0] Read line 0: |+CBC: 0,80,3919|
[Jan 20 12:34:32] DEBUG[19060] celliax_additional.c: rev exported[(nil)|b775bbb0][DEBUG_AT 1527 ][line1 ][-1, 0, 0] |+CBC: 0,80,3919| +CBC: Powered by battery, battery strenght=80
[Jan 20 12:34:32] DEBUG[19060] celliax_additional.c: rev exported[(nil)|b775bbb0][DEBUG_AT 1346 ][line1 ][-1, 0, 0] Read line 1: |OK|
[Jan 20 12:34:32] DEBUG[19060] celliax_additional.c: rev exported[(nil)|b775bbb0][DEBUG_AT 2159 ][line1 ][-1, 0, 0] |OK| got what EXPECTED
[Jan 20 12:34:32] DEBUG[19060] celliax_additional.c: rev exported[(nil)|b775bbb0][DEBUG_AT 2547 ][line1 ][-1, 0, 0] sending: AT+CSQ, expecting: OK
[Jan 20 12:34:32] DEBUG[19060] celliax_additional.c: rev exported[(nil)|b775bbb0][DEBUG_AT 2396 ][line1 ][-1, 0, 0] sent data... (A)
[Jan 20 12:34:32] DEBUG[19060] celliax_additional.c: rev exported[(nil)|b775bbb0][DEBUG_AT 2396 ][line1 ][-1, 0, 0] sent data... (T)
[Jan 20 12:34:32] DEBUG[19060] celliax_additional.c: rev exported[(nil)|b775bbb0][DEBUG_AT 2396 ][line1 ][-1, 0, 0] sent data... (+)
[Jan 20 12:34:32] DEBUG[19060] celliax_additional.c: rev exported[(nil)|b775bbb0][DEBUG_AT 2396 ][line1 ][-1, 0, 0] sent data... (C)
[Jan 20 12:34:33] DEBUG[19060] celliax_additional.c: rev exported[(nil)|b775bbb0][DEBUG_AT 2396 ][line1 ][-1, 0, 0] sent data... (S)
[Jan 20 12:34:33] DEBUG[19060] celliax_additional.c: rev exported[(nil)|b775bbb0][DEBUG_AT 2396 ][line1 ][-1, 0, 0] sent data... (Q)
[Jan 20 12:34:33] DEBUG[19060] celliax_additional.c: rev exported[(nil)|b775bbb0][DEBUG_AT 2426 ][line1 ][-1, 0, 0] sent (carriage return)
[Jan 20 12:34:33] DEBUG[19060] celliax_additional.c: rev exported[(nil)|b775bbb0][DEBUG_AT 1346 ][line1 ][-1, 0, 0] Read line 0: |+CSQ: 25,0|
[Jan 20 12:34:33] DEBUG[19060] celliax_additional.c: rev exported[(nil)|b775bbb0][DEBUG_AT 1550 ][line1 ][-1, 0, 0] |+CSQ: 25,0| +CSQ: Signal Quality: 25, Error Rate=0
[Jan 20 12:34:33] DEBUG[19060] celliax_additional.c: rev exported[(nil)|b775bbb0][DEBUG_AT 1346 ][line1 ][-1, 0, 0] Read line 1: |OK|
[Jan 20 12:34:33] DEBUG[19060] celliax_additional.c: rev exported[(nil)|b775bbb0][DEBUG_AT 2159 ][line1 ][-1, 0, 0] |OK| got what EXPECTED
[Jan 20 12:34:36] DEBUG[19146] rtp.c: Got RTCP report of 64 bytes
[Jan 20 12:34:39] DEBUG[19063] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jan 20 12:34:39] DEBUG[19063] chan_sip.c: Destroying SIP dialog 50f3b7ba1bc21b774a664eb838f2656f@192.168.5.186
[Jan 20 12:34:39] VERBOSE[19063] logger.c: Really destroying SIP dialog '50f3b7ba1bc21b774a664eb838f2656f@192.168.5.186' Method: OPTIONS
[Jan 20 12:34:39] DEBUG[19063] devicestate.c: Notification of state change to be queued on device/channel SIP/sta-pbx-7
[Jan 20 12:34:39] DEBUG[19045] chan_sip.c: Checking device state for peer sta-pbx-7
[Jan 20 12:34:39] DEBUG[19045] devicestate.c: Changing state for SIP/sta-pbx-7 - state 5 (Unavailable)
[Jan 20 12:34:39] DEBUG[19048] app_queue.c: Device 'SIP/sta-pbx-7' changed to state '5' (Unavailable) but we don't care because they're not a member of any queue.
[Jan 20 12:34:41] DEBUG[19146] rtp.c: Got RTCP report of 64 bytes
[Jan 20 12:34:43] DEBUG[19063] chan_sip.c: Auto destroying SIP dialog '7f4396743f766358509c218d11add6d3@10.255.101.101'
[Jan 20 12:34:43] DEBUG[19063] chan_sip.c: Destroying SIP dialog 7f4396743f766358509c218d11add6d3@10.255.101.101
[Jan 20 12:34:43] VERBOSE[19063] logger.c: Really destroying SIP dialog '7f4396743f766358509c218d11add6d3@10.255.101.101' Method: OPTIONS
[Jan 20 12:34:43] DEBUG[19060] chan_celliax.c: rev exported[(nil)|b775bbb0][DEBUG_SERIAL 2102 ][line3 ][-1, 0, 0] Syncing Serial
[Jan 20 12:34:43] DEBUG[19060] celliax_additional.c: rev exported[(nil)|b775bbb0][DEBUG_AT 2501 ][line3 ][-1, 0, 0] sending: AT
[Jan 20 12:34:43] DEBUG[19060] celliax_additional.c: rev exported[(nil)|b775bbb0][DEBUG_AT 2396 ][line3 ][-1, 0, 0] sent data... (A)
[Jan 20 12:34:43] DEBUG[19060] celliax_additional.c: rev exported[(nil)|b775bbb0][DEBUG_AT 2396 ][line3 ][-1, 0, 0] sent data... (T)
[Jan 20 12:34:43] DEBUG[19060] celliax_additional.c: rev exported[(nil)|b775bbb0][DEBUG_AT 2426 ][line3 ][-1, 0, 0] sent (carriage return)
[Jan 20 12:34:43] DEBUG[19060] celliax_additional.c: rev exported[(nil)|b775bbb0][DEBUG_AT 1346 ][line3 ][-1, 0, 0] Read line 0: |OK|
[Jan 20 12:34:43] DEBUG[19060] celliax_additional.c: rev exported[(nil)|b775bbb0][DEBUG_AT 2165 ][line3 ][-1, 0, 0] got OK
[Jan 20 12:34:43] DEBUG[19060] celliax_additional.c: rev exported[(nil)|b775bbb0][DEBUG_AT 2547 ][line3 ][-1, 0, 0] sending: AT+CBC, expecting: OK
[Jan 20 12:34:43] DEBUG[19060] celliax_additional.c: rev exported[(nil)|b775bbb0][DEBUG_AT 2396 ][line3 ][-1, 0, 0] sent data... (A)
[Jan 20 12:34:43] DEBUG[19060] celliax_additional.c: rev exported[(nil)|b775bbb0][DEBUG_AT 2396 ][line3 ][-1, 0, 0] sent data... (T)
[Jan 20 12:34:43] DEBUG[19060] celliax_additional.c: rev exported[(nil)|b775bbb0][DEBUG_AT 2396 ][line3 ][-1, 0, 0] sent data... (+)
[Jan 20 12:34:43] DEBUG[19060] celliax_additional.c: rev exported[(nil)|b775bbb0][DEBUG_AT 2396 ][line3 ][-1, 0, 0] sent data... (C)
[Jan 20 12:34:43] DEBUG[19060] celliax_additional.c: rev exported[(nil)|b775bbb0][DEBUG_AT 2396 ][line3 ][-1, 0, 0] sent data... (B)
[Jan 20 12:34:43] DEBUG[19060] celliax_additional.c: rev exported[(nil)|b775bbb0][DEBUG_AT 2396 ][line3 ][-1, 0, 0] sent data... (C)
[Jan 20 12:34:43] DEBUG[19060] celliax_additional.c: rev exported[(nil)|b775bbb0][DEBUG_AT 2426 ][line3 ][-1, 0, 0] sent (carriage return)
[Jan 20 12:34:43] DEBUG[19060] celliax_additional.c: rev exported[(nil)|b775bbb0][DEBUG_AT 1346 ][line3 ][-1, 0, 0] Read line 0: |+CBC: 0,82,3944|
[Jan 20 12:34:43] DEBUG[19060] celliax_additional.c: rev exported[(nil)|b775bbb0][DEBUG_AT 1527 ][line3 ][-1, 0, 0] |+CBC: 0,82,3944| +CBC: Powered by battery, battery strenght=82
[Jan 20 12:34:43] DEBUG[19060] celliax_additional.c: rev exported[(nil)|b775bbb0][DEBUG_AT 1346 ][line3 ][-1, 0, 0] Read line 1: |OK|
[Jan 20 12:34:43] DEBUG[19060] celliax_additional.c: rev exported[(nil)|b775bbb0][DEBUG_AT 2159 ][line3 ][-1, 0, 0] |OK| got what EXPECTED
[Jan 20 12:34:43] DEBUG[19060] celliax_additional.c: rev exported[(nil)|b775bbb0][DEBUG_AT 2547 ][line3 ][-1, 0, 0] sending: AT+CSQ, expecting: OK
[Jan 20 12:34:43] DEBUG[19060] celliax_additional.c: rev exported[(nil)|b775bbb0][DEBUG_AT 2396 ][line3 ][-1, 0, 0] sent data... (A)
[Jan 20 12:34:43] DEBUG[19060] celliax_additional.c: rev exported[(nil)|b775bbb0][DEBUG_AT 2396 ][line3 ][-1, 0, 0] sent data... (T)
[Jan 20 12:34:43] DEBUG[19060] celliax_additional.c: rev exported[(nil)|b775bbb0][DEBUG_AT 2396 ][line3 ][-1, 0, 0] sent data... (+)
[Jan 20 12:34:43] DEBUG[19060] celliax_additional.c: rev exported[(nil)|b775bbb0][DEBUG_AT 2396 ][line3 ][-1, 0, 0] sent data... (C)
[Jan 20 12:34:43] DEBUG[19060] celliax_additional.c: rev exported[(nil)|b775bbb0][DEBUG_AT 2396 ][line3 ][-1, 0, 0] sent data... (S)
[Jan 20 12:34:43] DEBUG[19060] celliax_additional.c: rev exported[(nil)|b775bbb0][DEBUG_AT 2396 ][line3 ][-1, 0, 0] sent data... (Q)
[Jan 20 12:34:43] DEBUG[19060] celliax_additional.c: rev exported[(nil)|b775bbb0][DEBUG_AT 2426 ][line3 ][-1, 0, 0] sent (carriage return)
[Jan 20 12:34:43] DEBUG[19060] celliax_additional.c: rev exported[(nil)|b775bbb0][DEBUG_AT 1346 ][line3 ][-1, 0, 0] Read line 0: |+CSQ: 17,0|
[Jan 20 12:34:43] DEBUG[19060] celliax_additional.c: rev exported[(nil)|b775bbb0][DEBUG_AT 1346 ][line3 ][-1, 0, 0] Read line 1: |OK|
[Jan 20 12:34:43] DEBUG[19060] celliax_additional.c: rev exported[(nil)|b775bbb0][DEBUG_AT 1550 ][line3 ][-1, 0, 0] |+CSQ: 17,0| +CSQ: Signal Quality: 17, Error Rate=0
[Jan 20 12:34:43] DEBUG[19060] celliax_additional.c: rev exported[(nil)|b775bbb0][DEBUG_AT 2159 ][line3 ][-1, 0, 0] |OK| got what EXPECTED
[Jan 20 12:34:45] DEBUG[19063] chan_sip.c: Setting SIP_ALREADYGONE on dialog 49e93b10452167f153ee591560679e92@192.168.5.253
[Jan 20 12:34:45] DEBUG[19063] chan_sip.c: Received bye, issuing owner hangup
[Jan 20 12:34:45] DEBUG[19146] channel.c: Didn't get a frame from channel: SIP/sta-pbx-2-00000004
[Jan 20 12:34:45] WARNING[19146] chan_celliax.c: rev exported[0x841a7e0|b6403bb0][WARNING 547 ][line0 ][ 6, 6,300] Don't know how to display condition 20 on Celliax/line0
[Jan 20 12:34:45] DEBUG[19146] channel.c: Bridge stops bridging channels SIP/sta-pbx-2-00000004 and Celliax/line0
[Jan 20 12:34:45] DEBUG[19146] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record.
[Jan 20 12:34:45] DEBUG[19146] cdr_addon_mysql.c: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,userfield) VALUES ('2010-01-20 12:33:26','\"Evgeniya Spiridonova\" <2139>','2139','80296603885','outbound', 'SIP/sta-pbx-2-00000004','Celliax/line0','Dial','Celliax/line0/80296603885',79,56,'ANSWERED',3,'','')
[Jan 20 12:34:45] DEBUG[19146] channel.c: Hanging up channel 'Celliax/line0'
[Jan 20 12:34:45] DEBUG[19146] chan_celliax.c: rev exported[0x841a7e0|b6403bb0][DEBUG_PBX 648 ][line0 ][ 6, 6,300] ENTERING FUNC
[Jan 20 12:34:45] DEBUG[19149] chan_celliax.c: exported[b63c2bb0] I'm a dying thread, and I'm to go unlocking mutex 0xb79a2358 for the 0th time
[Jan 20 12:34:45] DEBUG[19149] chan_celliax.c: exported[b63c2bb0] I'm a dying thread, and I'm to go unlocking mutex 0xb79a2358 for the 1th time
[Jan 20 12:34:45] DEBUG[19149] chan_celliax.c: exported[b63c2bb0] I'm a dying thread, and I'm to go unlocking mutex 0xb79a2358 for the 2th time
[Jan 20 12:34:45] DEBUG[19149] chan_celliax.c: exported[b63c2bb0] I'm a dying thread, and I'm to go unlocking mutex 0xb79a2358 for the 3th time
[Jan 20 12:34:45] DEBUG[19149] chan_celliax.c: exported[b63c2bb0] I'm a dying thread, and I'm to go unlocking mutex 0xb79a2358 for the 4th time
[Jan 20 12:34:45] DEBUG[19149] chan_celliax.c: exported[b63c2bb0] I'm a dying thread, I've finished unlocking mutex 0xb79a2358
[Jan 20 12:34:45] DEBUG[19146] celliax_additional.c: rev exported[0x841a7e0|b6403bb0][DEBUG_AT 2547 ][line0 ][ 6, 6,300] sending: ATH, expecting: OK
[Jan 20 12:34:45] DEBUG[19146] celliax_additional.c: rev exported[0x841a7e0|b6403bb0][DEBUG_AT 2396 ][line0 ][ 6, 6,300] sent data... (A)
[Jan 20 12:34:45] DEBUG[19146] celliax_additional.c: rev exported[0x841a7e0|b6403bb0][DEBUG_AT 2396 ][line0 ][ 6, 6,300] sent data... (T)
[Jan 20 12:34:45] DEBUG[19146] celliax_additional.c: rev exported[0x841a7e0|b6403bb0][DEBUG_AT 2396 ][line0 ][ 6, 6,300] sent data... (H)
[Jan 20 12:34:45] DEBUG[19146] celliax_additional.c: rev exported[0x841a7e0|b6403bb0][DEBUG_AT 2426 ][line0 ][ 6, 6,300] sent (carriage return)
[Jan 20 12:34:45] DEBUG[19146] celliax_additional.c: rev exported[0x841a7e0|b6403bb0][DEBUG_AT 1346 ][line0 ][ 6, 6,300] Read line 0: |NO CARRIER|
[Jan 20 12:34:45] DEBUG[19146] celliax_additional.c: rev exported[0x841a7e0|b6403bb0][DEBUG_AT 1489 ][line0 ][ 6, 6,102] |NO CARRIER| CALLFLOW_CALL_NOCARRIER
[Jan 20 12:34:45] DEBUG[19146] chan_celliax.c: rev exported[0x841a7e0|b6403bb0][DEBUG_PBX 463 ][line0 ][ 6, 6,102] Queued CONTROL FRAME 1
[Jan 20 12:34:46] DEBUG[19063] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jan 20 12:34:46] DEBUG[19063] chan_sip.c: Stopping retransmission on '265d28c54766d70c503870575edb6303@192.168.5.186' of Request 102: Match Found
[Jan 20 12:34:46] VERBOSE[19063] logger.c: Really destroying SIP dialog '265d28c54766d70c503870575edb6303@192.168.5.186' Method: OPTIONS
[Jan 20 12:34:46] DEBUG[19063] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jan 20 12:34:46] DEBUG[19063] chan_sip.c: Stopping retransmission on '195d1c0f79c7d47c039a49330597458d@192.168.5.186' of Request 102: Match Found
[Jan 20 12:34:46] VERBOSE[19063] logger.c: Really destroying SIP dialog '195d1c0f79c7d47c039a49330597458d@192.168.5.186' Method: OPTIONS
[Jan 20 12:34:47] DEBUG[19063] chan_sip.c: Setting NAT on RTP to Off
[Jan 20 12:34:47] DEBUG[19063] chan_sip.c: Allocating new SIP dialog for 797a97571233726e6f562a8532e0294c@192.168.5.253 - INVITE (With RTP)
[Jan 20 12:34:47] DEBUG[19063] chan_sip.c: Setting NAT on RTP to Off
[Jan 20 12:34:47] DEBUG[19063] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED.
[Jan 20 12:34:47] DEBUG[19063] chan_sip.c: Processing session-level SDP o=root 2280 2280 IN IP4 192.168.5.253... UNSUPPORTED.
[Jan 20 12:34:47] DEBUG[19063] chan_sip.c: Processing session-level SDP s=session... UNSUPPORTED.
[Jan 20 12:34:47] DEBUG[19063] chan_sip.c: Processing session-level SDP c=IN IP4 192.168.5.253... OK.
[Jan 20 12:34:47] DEBUG[19063] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED.
[Jan 20 12:34:47] DEBUG[19063] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK.
[Jan 20 12:34:47] DEBUG[19063] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK.
[Jan 20 12:34:47] DEBUG[19063] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK.
[Jan 20 12:34:47] DEBUG[19063] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-16... UNSUPPORTED.
[Jan 20 12:34:47] DEBUG[19063] chan_sip.c: Processing media-level (audio) SDP a=silenceSupp:off - - - -... UNSUPPORTED.
[Jan 20 12:34:47] DEBUG[19063] chan_sip.c: Processing media-level (audio) SDP a=ptime:20... OK.
[Jan 20 12:34:47] DEBUG[19063] chan_sip.c: T38 state changed to 0 on channel
[Jan 20 12:34:47] DEBUG[19063] chan_sip.c: We're settling with these formats: 0x4 (ulaw)
[Jan 20 12:34:47] DEBUG[19063] chan_sip.c: Checking SIP call limits for device gsm-1
[Jan 20 12:34:47] DEBUG[19063] chan_sip.c: Updating call counter for incoming call
[Jan 20 12:34:47] DEBUG[19063] chan_sip.c: *** Our native formats are 0x4 (ulaw)
[Jan 20 12:34:47] DEBUG[19063] chan_sip.c: *** Joint capabilities are 0x4 (ulaw)
[Jan 20 12:34:47] DEBUG[19063] chan_sip.c: *** Our capabilities are 0x4 (ulaw)
[Jan 20 12:34:47] DEBUG[19063] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw)
[Jan 20 12:34:47] DEBUG[19063] chan_sip.c: This channel will not be able to handle video.
[Jan 20 12:34:47] DEBUG[19063] chan_sip.c: build_route: Contact hop:
[Jan 20 12:34:47] DEBUG[19063] chan_sip.c: SIP/sta-pbx-2-00000005: New call is still down.... Trying...
[Jan 20 12:34:47] DEBUG[19063] devicestate.c: Notification of state change to be queued on device/channel SIP/sta-pbx-2
[Jan 20 12:34:47] DEBUG[19152] pbx.c: Launching 'Goto'
[Jan 20 12:34:47] VERBOSE[19152] logger.c: -- Executing [80447688816@interoffice:1] Goto("SIP/sta-pbx-2-00000005", "outbound|80447688816|1") in new stack
[Jan 20 12:34:47] VERBOSE[19152] logger.c: -- Goto (outbound,80447688816,1)
[Jan 20 12:34:47] DEBUG[19152] pbx.c: Launching 'Dial'
[Jan 20 12:34:47] VERBOSE[19152] logger.c: -- Executing [80447688816@outbound:1] Dial("SIP/sta-pbx-2-00000005", "Celliax/line0/80447688816") in new stack
[Jan 20 12:34:47] DEBUG[19152] chan_celliax.c: rev exported[(nil)|b63c2bb0][DEBUG_PBX 564 ][none ][-1,-1,-1] ENTERING FUNC
[Jan 20 12:34:47] DEBUG[19152] chan_celliax.c: rev exported[(nil)|b63c2bb0][DEBUG_PBX 568 ][none ][-1,-1,-1] Try to request type: Celliax, name: line0/80447688816, cause: 0, format: 64
[Jan 20 12:34:47] WARNING[19152] chan_celliax.c: rev exported[0x841a7e0|b63c2bb0][WARNING 602 ][line0 ][ 6, 6,102] owned by another channel
[Jan 20 12:34:47] WARNING[19152] chan_celliax.c: rev exported[0x841a7e0|b63c2bb0][WARNING 622 ][line0 ][ 6, 6,102] Unable to create new Celliax channel line0/80447688816
[Jan 20 12:34:47] DEBUG[19152] chan_celliax.c: rev exported[0x841a7e0|b63c2bb0][DEBUG_PBX 625 ][line0 ][ 6, 6,102] EXITING FUNC
[Jan 20 12:34:47] WARNING[19152] app_dial.c: Unable to create channel of type 'Celliax' (cause 44 - Requested channel not available)
[Jan 20 12:34:47] VERBOSE[19152] logger.c: == Everyone is busy/congested at this time (1:0/0/1)
[Jan 20 12:34:47] DEBUG[19152] rtp.c: Channel '' has no RTP, not doing anything
[Jan 20 12:34:47] DEBUG[19152] app_dial.c: Exiting with DIALSTATUS=CHANUNAVAIL.
[Jan 20 12:34:47] DEBUG[19152] pbx.c: Launching 'Dial'
[Jan 20 12:34:47] VERBOSE[19152] logger.c: -- Executing [80447688816@outbound:2] Dial("SIP/sta-pbx-2-00000005", "Celliax/line1/80447688816") in new stack
[Jan 20 12:34:47] DEBUG[19152] chan_celliax.c: rev exported[(nil)|b63c2bb0][DEBUG_PBX 564 ][none ][-1,-1,-1] ENTERING FUNC
[Jan 20 12:34:47] DEBUG[19152] chan_celliax.c: rev exported[(nil)|b63c2bb0][DEBUG_PBX 568 ][none ][-1,-1,-1] Try to request type: Celliax, name: line1/80447688816, cause: 0, format: 64
[Jan 20 12:34:47] DEBUG[19152] chan_celliax.c: rev exported[(nil)|b63c2bb0][DEBUG_PBX 593 ][line1 ][-1, 0, 0] Requesting: Celliax, name: line1/80447688816, format: 64
[Jan 20 12:34:47] DEBUG[19152] chan_celliax.c: rev exported[(nil)|b63c2bb0][DEBUG_PBX 1138 ][line1 ][-1, 0, 0] ENTERING FUNC
[Jan 20 12:34:47] DEBUG[19045] chan_sip.c: Checking device state for peer sta-pbx-2
[Jan 20 12:34:47] DEBUG[19152] celliax_additional.c: rev exported[(nil)|b63c2bb0][DEBUG_SOUND 402 ][line1 ][-1, 0, 0] Acquired fd 43 from the poll descriptor
[Jan 20 12:34:47] DEBUG[19152] celliax_additional.c: rev exported[(nil)|b63c2bb0][DEBUG_SOUND 425 ][line1 ][-1, 0, 0] started!
[Jan 20 12:34:47] DEBUG[19152] celliax_additional.c: rev exported[(nil)|b63c2bb0][DEBUG_SOUND 437 ][line1 ][-1, 0, 0] ALSA handle = 138594264
[Jan 20 12:34:47] DEBUG[19045] devicestate.c: Changing state for SIP/sta-pbx-2 - state 1 (Not in use)
[Jan 20 12:34:47] DEBUG[19152] celliax_additional.c: rev exported[(nil)|b63c2bb0][DEBUG_SOUND 402 ][line1 ][-1, 0, 0] Acquired fd 49 from the poll descriptor
[Jan 20 12:34:47] DEBUG[19152] celliax_additional.c: rev exported[(nil)|b63c2bb0][DEBUG_SOUND 437 ][line1 ][-1, 0, 0] ALSA handle = 138579800
[Jan 20 12:34:47] DEBUG[19152] chan_celliax.c: rev exported[(nil)|b63c2bb0][DEBUG_PBX 1171 ][line1 ][-1, 0, 0] new channel: name=Celliax/line1 requested_state=0
[Jan 20 12:34:47] DEBUG[19152] chan_celliax.c: rev exported[0x841e108|b63c2bb0][DEBUG_SERIAL 1255 ][line1 ][ 0, 0, 0] STARTED controldev_thread=3058506672 STOP=4294967294 NULL=4294967295
[Jan 20 12:34:47] DEBUG[19152] chan_celliax.c: rev exported[0x841e108|b63c2bb0][DEBUG_PBX 1267 ][line1 ][ 0, 0, 0] EXITING FUNC
[Jan 20 12:34:47] DEBUG[19152] chan_celliax.c: rev exported[0x841e108|b63c2bb0][DEBUG_PBX 625 ][line1 ][ 0, 0, 0] EXITING FUNC
[Jan 20 12:34:47] DEBUG[19152] rtp.c: Channel 'Celliax/line1' has no RTP, not doing anything
[Jan 20 12:34:47] DEBUG[19152] channel.c: Not copying variable DIALEDTIME.
[Jan 20 12:34:47] DEBUG[19152] channel.c: Not copying variable ANSWEREDTIME.
[Jan 20 12:34:47] DEBUG[19152] channel.c: Not copying variable DIALEDPEERNAME.
[Jan 20 12:34:47] DEBUG[19152] channel.c: Not copying variable DIALEDPEERNUMBER.
[Jan 20 12:34:47] DEBUG[19152] channel.c: Not copying variable DIALSTATUS.
[Jan 20 12:34:47] DEBUG[19152] channel.c: Not copying variable SIPCALLID.
[Jan 20 12:34:47] DEBUG[19152] channel.c: Not copying variable SIPUSERAGENT.
[Jan 20 12:34:47] DEBUG[19152] channel.c: Not copying variable SIPDOMAIN.
[Jan 20 12:34:47] DEBUG[19152] channel.c: Not copying variable SIPURI.
[Jan 20 12:34:47] DEBUG[19152] chan_celliax.c: rev exported[0x841e108|b63c2bb0][DEBUG_PBX 1006 ][line1 ][ 0, 0, 0] ENTERING FUNC
[Jan 20 12:34:47] DEBUG[19152] chan_celliax.c: rev exported[0x841e108|b63c2bb0][DEBUG_PBX 1020 ][line1 ][ 0, 0, 0] celliax_call to call idest: line1/80447688816, timeout: 0!
[Jan 20 12:34:47] DEBUG[19152] chan_celliax.c: rev exported[0x841e108|b63c2bb0][DEBUG_PBX 1041 ][line1 ][ 0, 0, 0] celliax_call dialing idest: line1/80447688816, timeout: 0, dstr: 80447688816!
[Jan 20 12:34:47] DEBUG[19152] devicestate.c: Notification of state change to be queued on device/channel Celliax/line1
[Jan 20 12:34:47] DEBUG[19152] celliax_additional.c: rev exported[0x841e108|b63c2bb0][DEBUG_PBX 2945 ][line1 ][ 3, 0, 0] Dialing 80447688816
[Jan 20 12:34:47] DEBUG[19152] celliax_additional.c: rev exported[0x841e108|b63c2bb0][DEBUG_AT 2547 ][line1 ][ 3, 3, 3] sending: ATD80447688816;, expecting: OK
[Jan 20 12:34:47] DEBUG[19152] celliax_additional.c: rev exported[0x841e108|b63c2bb0][DEBUG_AT 2396 ][line1 ][ 3, 3, 3] sent data... (A)
[Jan 20 12:34:47] DEBUG[19155] chan_celliax.c: rev exported[0x841e108|b64d1bb0][DEBUG_SERIAL 2527 ][line1 ][ 3, 3, 3] In celliax_do_controldev_thread: started, p=0xb7862008
[Jan 20 12:34:47] DEBUG[19045] chan_celliax.c: rev exported[0x841e108|b7dc7bb0][DEBUG_PBX 499 ][line1 ][ 3, 3, 3] Interface is OWNED by a channel
[Jan 20 12:34:47] DEBUG[19045] devicestate.c: Changing state for Celliax/line1 - state 2 (In use)
[Jan 20 12:34:47] DEBUG[19152] celliax_additional.c: rev exported[0x841e108|b63c2bb0][DEBUG_AT 2396 ][line1 ][ 3, 3, 3] sent data... (T)
[Jan 20 12:34:47] DEBUG[19048] app_queue.c: Device 'SIP/sta-pbx-2' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jan 20 12:34:47] DEBUG[19048] app_queue.c: Device 'Celliax/line1' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Jan 20 12:34:47] DEBUG[19152] celliax_additional.c: rev exported[0x841e108|b63c2bb0][DEBUG_AT 2396 ][line1 ][ 3, 3, 3] sent data... (D)
[Jan 20 12:34:47] DEBUG[19152] celliax_additional.c: rev exported[0x841e108|b63c2bb0][DEBUG_AT 2396 ][line1 ][ 3, 3, 3] sent data... (8)
[Jan 20 12:34:47] DEBUG[19152] celliax_additional.c: rev exported[0x841e108|b63c2bb0][DEBUG_AT 2396 ][line1 ][ 3, 3, 3] sent data... (0)
[Jan 20 12:34:47] DEBUG[19152] celliax_additional.c: rev exported[0x841e108|b63c2bb0][DEBUG_AT 2396 ][line1 ][ 3, 3, 3] sent data... (4)
[Jan 20 12:34:47] DEBUG[19152] celliax_additional.c: rev exported[0x841e108|b63c2bb0][DEBUG_AT 2396 ][line1 ][ 3, 3, 3] sent data... (4)
[Jan 20 12:34:47] DEBUG[19152] celliax_additional.c: rev exported[0x841e108|b63c2bb0][DEBUG_AT 2396 ][line1 ][ 3, 3, 3] sent data... (7)
[Jan 20 12:34:47] DEBUG[19152] celliax_additional.c: rev exported[0x841e108|b63c2bb0][DEBUG_AT 2396 ][line1 ][ 3, 3, 3] sent data... (6)
[Jan 20 12:34:47] DEBUG[19152] celliax_additional.c: rev exported[0x841e108|b63c2bb0][DEBUG_AT 2396 ][line1 ][ 3, 3, 3] sent data... (8)
[Jan 20 12:34:47] DEBUG[19152] celliax_additional.c: rev exported[0x841e108|b63c2bb0][DEBUG_AT 2396 ][line1 ][ 3, 3, 3] sent data... (8)
[Jan 20 12:34:47] DEBUG[19152] celliax_additional.c: rev exported[0x841e108|b63c2bb0][DEBUG_AT 2396 ][line1 ][ 3, 3, 3] sent data... (8)
[Jan 20 12:34:47] DEBUG[19152] celliax_additional.c: rev exported[0x841e108|b63c2bb0][DEBUG_AT 2396 ][line1 ][ 3, 3, 3] sent data... (1)
[Jan 20 12:34:47] DEBUG[19152] celliax_additional.c: rev exported[0x841e108|b63c2bb0][DEBUG_AT 2396 ][line1 ][ 3, 3, 3] sent data... (6)
[Jan 20 12:34:47] DEBUG[19152] celliax_additional.c: rev exported[0x841e108|b63c2bb0][DEBUG_AT 2396 ][line1 ][ 3, 3, 3] sent data... (;)
[Jan 20 12:34:47] DEBUG[19152] celliax_additional.c: rev exported[0x841e108|b63c2bb0][DEBUG_AT 2426 ][line1 ][ 3, 3, 3] sent (carriage return)
[Jan 20 12:34:47] DEBUG[19152] celliax_additional.c: rev exported[0x841e108|b63c2bb0][DEBUG_AT 1346 ][line1 ][ 3, 3, 3] Read line 0: |OK|
[Jan 20 12:34:47] DEBUG[19152] celliax_additional.c: rev exported[0x841e108|b63c2bb0][DEBUG_AT 2159 ][line1 ][ 3, 3, 3] |OK| got what EXPECTED
[Jan 20 12:34:47] DEBUG[19152] chan_celliax.c: rev exported[0x841e108|b63c2bb0][DEBUG_PBX 1059 ][line1 ][ 3, 3, 3] call ongoing
[Jan 20 12:34:47] DEBUG[19152] chan_celliax.c: rev exported[0x841e108|b63c2bb0][DEBUG_PBX 1065 ][line1 ][ 3, 3, 3] celliax_call dialed idest: line1/80447688816, timeout: 0, dstr: 80447688816!
[Jan 20 12:34:47] DEBUG[19152] chan_celliax.c: rev exported[0x841e108|b63c2bb0][DEBUG_PBX 1068 ][line1 ][ 3, 3, 3] EXITING FUNC
[Jan 20 12:34:47] VERBOSE[19152] logger.c: -- Called line1/80447688816
[Jan 20 12:34:47] DEBUG[19152] channel.c: Set channel Celliax/line1 to read format ulaw
[Jan 20 12:34:47] DEBUG[19152] channel.c: Set channel SIP/sta-pbx-2-00000005 to read format slin
[Jan 20 12:34:47] DEBUG[19152] channel.c: Set channel Celliax/line1 to write format slin
[Jan 20 12:34:47] VERBOSE[19152] logger.c: -- Celliax/line1 is ringing
[Jan 20 12:34:47] DEBUG[19152] rtp.c: Channel 'Celliax/line1' has no RTP, not doing anything
[Jan 20 12:34:47] DEBUG[19152] chan_celliax.c: rev exported[0x841e108|b63c2bb0][DEBUG_SOUND 903 ][line1 ][ 3, 3, 3] DTMF recognition inited
[Jan 20 12:34:47] DEBUG[19152] chan_sip.c: Setting framing from config on incoming call
[Jan 20 12:34:47] DEBUG[19152] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: True
[Jan 20 12:34:47] DEBUG[19152] chan_sip.c: ** Our prefcodec: 0x0 (nothing)
[Jan 20 12:34:47] DEBUG[19152] chan_sip.c: -- Done with adding codecs to SDP
[Jan 20 12:34:47] DEBUG[19152] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw)
[Jan 20 12:34:47] DEBUG[19152] rtp.c: Ooh, format changed from unknown to ulaw
[Jan 20 12:34:47] DEBUG[19152] rtp.c: Created smoother: format: 4 ms: 20 len: 160
[Jan 20 12:34:49] DEBUG[19063] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jan 20 12:34:49] DEBUG[19155] celliax_additional.c: rev exported[0x841e108|b64d1bb0][DEBUG_AT 1346 ][line1 ][ 3, 3, 3] Read line 0: |+CSSI: 1|
[Jan 20 12:34:49] DEBUG[19155] celliax_additional.c: rev exported[0x841e108|b64d1bb0][DEBUG_AT 1637 ][line1 ][ 3, 3, 3] |+CSSI: 1| CALLFLOW_CALL_DIALING
[Jan 20 12:34:49] DEBUG[19063] chan_sip.c: Destroying SIP dialog 79fa06d74ca079132dd7604f49b63474@192.168.5.186
[Jan 20 12:34:49] VERBOSE[19063] logger.c: Really destroying SIP dialog '79fa06d74ca079132dd7604f49b63474@192.168.5.186' Method: OPTIONS
[Jan 20 12:34:49] DEBUG[19063] devicestate.c: Notification of state change to be queued on device/channel SIP/sta-pbx-7
[Jan 20 12:34:49] DEBUG[19045] chan_sip.c: Checking device state for peer sta-pbx-7
[Jan 20 12:34:49] DEBUG[19045] devicestate.c: Changing state for SIP/sta-pbx-7 - state 5 (Unavailable)
[Jan 20 12:34:49] DEBUG[19048] app_queue.c: Device 'SIP/sta-pbx-7' changed to state '5' (Unavailable) but we don't care because they're not a member of any queue.
[Jan 20 12:34:52] DEBUG[19152] rtp.c: Got RTCP report of 64 bytes
[Jan 20 12:34:55] DEBUG[19063] chan_sip.c: Allocating new SIP dialog for 5b3a149a62d417220f1e0abc61bf840a@192.168.5.253 - OPTIONS (No RTP)
[Jan 20 12:34:55] DEBUG[19063] chan_sip.c: SIP message could not be handled, bad request: 5b3a149a62d417220f1e0abc61bf840a@192.168.5.253
[Jan 20 12:34:57] DEBUG[19063] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jan 20 12:34:57] DEBUG[19063] chan_sip.c: Stopping retransmission on '34568a3043c98c4b67d2180435af5952@192.168.5.186' of Request 102: Match Found
[Jan 20 12:34:57] VERBOSE[19063] logger.c: Really destroying SIP dialog '34568a3043c98c4b67d2180435af5952@192.168.5.186' Method: OPTIONS
[Jan 20 12:34:57] DEBUG[19063] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jan 20 12:34:57] DEBUG[19152] rtp.c: Got RTCP report of 64 bytes
[Jan 20 12:34:57] DEBUG[19063] chan_sip.c: Stopping retransmission on '7ba095dc35be2ab40caee7a903adfd17@192.168.5.186' of Request 102: Match Found
[Jan 20 12:34:57] VERBOSE[19063] logger.c: Really destroying SIP dialog '7ba095dc35be2ab40caee7a903adfd17@192.168.5.186' Method: OPTIONS
[Jan 20 12:34:59] DEBUG[19155] celliax_additional.c: rev exported[0x841e108|b64d1bb0][DEBUG_AT 1346 ][line1 ][ 3, 3, 3] Read line 0: |+CSSI: 7|
[Jan 20 12:34:59] DEBUG[19155] celliax_additional.c: rev exported[0x841e108|b64d1bb0][DEBUG_AT 1616 ][line1 ][ 3, 3,300] |+CSSI: 7| CALLFLOW_CALL_ACTIVE
[Jan 20 12:34:59] DEBUG[19155] celliax_additional.c: rev exported[0x841e108|b64d1bb0][DEBUG_PBX 1619 ][line1 ][ 3, 3,300] just received a remote ANSWER
[Jan 20 12:34:59] DEBUG[19155] chan_celliax.c: rev exported[0x841e108|b64d1bb0][DEBUG_PBX 463 ][line1 ][ 3, 3,300] Queued CONTROL FRAME 3
[Jan 20 12:34:59] DEBUG[19152] chan_celliax.c: rev exported[0x841e108|b63c2bb0][DEBUG_PBX 910 ][line1 ][ 3, 3,300] Sent CONTROL FRAME 3
[Jan 20 12:34:59] VERBOSE[19152] logger.c: -- Celliax/line1 is ringing
[Jan 20 12:34:59] DEBUG[19152] rtp.c: Channel 'Celliax/line1' has no RTP, not doing anything
[Jan 20 12:34:59] DEBUG[19155] celliax_additional.c: rev exported[0x841e108|b64d1bb0][DEBUG_PBX 1622 ][line1 ][ 3, 3,300] just sent AST_CONTROL_RINGING
[Jan 20 12:34:59] DEBUG[19155] celliax_additional.c: rev exported[0x841e108|b64d1bb0][DEBUG_PBX 1623 ][line1 ][ 3, 3,300] going to send AST_CONTROL_ANSWER
[Jan 20 12:34:59] DEBUG[19155] chan_celliax.c: rev exported[0x841e108|b64d1bb0][DEBUG_PBX 463 ][line1 ][ 3, 3,300] Queued CONTROL FRAME 4
[Jan 20 12:34:59] DEBUG[19152] chan_celliax.c: rev exported[0x841e108|b63c2bb0][DEBUG_PBX 910 ][line1 ][ 3, 3,300] Sent CONTROL FRAME 4
[Jan 20 12:34:59] DEBUG[19152] devicestate.c: Notification of state change to be queued on device/channel Celliax/line1
[Jan 20 12:34:59] VERBOSE[19152] logger.c: -- Celliax/line1 answered SIP/sta-pbx-2-00000005
[Jan 20 12:34:59] DEBUG[19152] rtp.c: Channel 'Celliax/line1' has no RTP, not doing anything
[Jan 20 12:34:59] DEBUG[19152] devicestate.c: Notification of state change to be queued on device/channel SIP/sta-pbx-2
[Jan 20 12:34:59] DEBUG[19152] chan_sip.c: SIP answering channel: SIP/sta-pbx-2-00000005
[Jan 20 12:34:59] DEBUG[19152] chan_sip.c: Setting framing from config on incoming call
[Jan 20 12:34:59] DEBUG[19152] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: True
[Jan 20 12:34:59] DEBUG[19152] chan_sip.c: ** Our prefcodec: 0x0 (nothing)
[Jan 20 12:34:59] DEBUG[19152] chan_sip.c: -- Done with adding codecs to SDP
[Jan 20 12:34:59] DEBUG[19152] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw)
[Jan 20 12:34:59] WARNING[19152] chan_celliax.c: rev exported[0x841e108|b63c2bb0][WARNING 547 ][line1 ][ 6, 3,300] Don't know how to display condition 20 on Celliax/line1
[Jan 20 12:34:59] DEBUG[19155] celliax_additional.c: rev exported[0x841e108|b64d1bb0][DEBUG_PBX 1625 ][line1 ][ 6, 3,300] just sent AST_CONTROL_ANSWER
[Jan 20 12:34:59] DEBUG[19155] celliax_additional.c: rev exported[0x841e108|b64d1bb0][DEBUG_PBX 1630 ][line1 ][ 6, 6,300] just interface_state UP
[Jan 20 12:34:59] DEBUG[19063] chan_sip.c: Stopping retransmission on '797a97571233726e6f562a8532e0294c@192.168.5.253' of Response 102: Match Found
[Jan 20 12:34:59] DEBUG[19152] celliax_additional.c: rev exported[0x841e108|b63c2bb0][DEBUG_SOUND 682 ][line1 ][ 6, 6,300] PREVENTING an ALSA write XRUN (celliax can't fill the soundcard buffer fast enough). If this happens often (not after silence or after a pause in the speech, that's OK), and appear to damage the sound quality, first check if you have some IRQ problem, maybe sharing the soundcard IRQ with a broken or heavy loaded ethernet or graphic card. Then consider to increase the alsa_periods_in_buffer (now is set to 5) for this interface in the config file. delayp1=0, delayp2=800
[Jan 20 12:34:59] DEBUG[19045] chan_celliax.c: rev exported[0x841e108|b7dc7bb0][DEBUG_PBX 499 ][line1 ][ 6, 6,300] Interface is OWNED by a channel
[Jan 20 12:34:59] DEBUG[19045] devicestate.c: Changing state for Celliax/line1 - state 2 (In use)
[Jan 20 12:34:59] DEBUG[19045] chan_sip.c: Checking device state for peer sta-pbx-2
[Jan 20 12:34:59] DEBUG[19045] devicestate.c: Changing state for SIP/sta-pbx-2 - state 1 (Not in use)
[Jan 20 12:34:59] DEBUG[19048] app_queue.c: Device 'Celliax/line1' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Jan 20 12:34:59] DEBUG[19048] app_queue.c: Device 'SIP/sta-pbx-2' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jan 20 12:34:59] DEBUG[19063] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jan 20 12:34:59] DEBUG[19063] chan_sip.c: Destroying SIP dialog 49a78a4a10fab0317714f81176b674e2@192.168.5.186
[Jan 20 12:34:59] VERBOSE[19063] logger.c: Really destroying SIP dialog '49a78a4a10fab0317714f81176b674e2@192.168.5.186' Method: OPTIONS
[Jan 20 12:34:59] DEBUG[19063] devicestate.c: Notification of state change to be queued on device/channel SIP/sta-pbx-7
[Jan 20 12:34:59] DEBUG[19045] chan_sip.c: Checking device state for peer sta-pbx-7
[Jan 20 12:34:59] DEBUG[19045] devicestate.c: Changing state for SIP/sta-pbx-7 - state 5 (Unavailable)
[Jan 20 12:34:59] DEBUG[19048] app_queue.c: Device 'SIP/sta-pbx-7' changed to state '5' (Unavailable) but we don't care because they're not a member of any queue.
[Jan 20 12:35:02] DEBUG[19063] chan_sip.c: Setting SIP_ALREADYGONE on dialog 797a97571233726e6f562a8532e0294c@192.168.5.253
[Jan 20 12:35:02] DEBUG[19063] chan_sip.c: Received bye, issuing owner hangup
[Jan 20 12:35:02] DEBUG[19152] channel.c: Didn't get a frame from channel: SIP/sta-pbx-2-00000005
[Jan 20 12:35:02] WARNING[19152] chan_celliax.c: rev exported[0x841e108|b63c2bb0][WARNING 547 ][line1 ][ 6, 6,300] Don't know how to display condition 20 on Celliax/line1
[Jan 20 12:35:02] DEBUG[19152] channel.c: Bridge stops bridging channels SIP/sta-pbx-2-00000005 and Celliax/line1
[Jan 20 12:35:02] DEBUG[19152] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record.
[Jan 20 12:35:02] DEBUG[19152] cdr_addon_mysql.c: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,userfield) VALUES ('2010-01-20 12:34:47','\"Romanycheva Olga\" <2143>','2143','80447688816','outbound', 'SIP/sta-pbx-2-00000005','Celliax/line1','Dial','Celliax/line1/80447688816',15,3,'ANSWERED',3,'','')
[Jan 20 12:35:02] DEBUG[19152] channel.c: Hanging up channel 'Celliax/line1'
[Jan 20 12:35:02] DEBUG[19152] chan_celliax.c: rev exported[0x841e108|b63c2bb0][DEBUG_PBX 648 ][line1 ][ 6, 6,300] ENTERING FUNC
[Jan 20 12:35:02] DEBUG[19155] chan_celliax.c: exported[b64d1bb0] I'm a dying thread, and I'm to go unlocking mutex 0xb78e3358 for the 0th time
[Jan 20 12:35:02] DEBUG[19155] chan_celliax.c: exported[b64d1bb0] I'm a dying thread, and I'm to go unlocking mutex 0xb78e3358 for the 1th time
[Jan 20 12:35:02] DEBUG[19155] chan_celliax.c: exported[b64d1bb0] I'm a dying thread, and I'm to go unlocking mutex 0xb78e3358 for the 2th time
[Jan 20 12:35:02] DEBUG[19155] chan_celliax.c: exported[b64d1bb0] I'm a dying thread, and I'm to go unlocking mutex 0xb78e3358 for the 3th time
[Jan 20 12:35:02] DEBUG[19155] chan_celliax.c: exported[b64d1bb0] I'm a dying thread, and I'm to go unlocking mutex 0xb78e3358 for the 4th time
[Jan 20 12:35:02] DEBUG[19155] chan_celliax.c: exported[b64d1bb0] I'm a dying thread, I've finished unlocking mutex 0xb78e3358
[Jan 20 12:35:02] DEBUG[19152] celliax_additional.c: rev exported[0x841e108|b63c2bb0][DEBUG_AT 2547 ][line1 ][ 6, 6,300] sending: ATH, expecting: OK
[Jan 20 12:35:02] DEBUG[19152] celliax_additional.c: rev exported[0x841e108|b63c2bb0][DEBUG_AT 2396 ][line1 ][ 6, 6,300] sent data... (A)
[Jan 20 12:35:02] DEBUG[19152] celliax_additional.c: rev exported[0x841e108|b63c2bb0][DEBUG_AT 2396 ][line1 ][ 6, 6,300] sent data... (T)
[Jan 20 12:35:02] DEBUG[19152] celliax_additional.c: rev exported[0x841e108|b63c2bb0][DEBUG_AT 2396 ][line1 ][ 6, 6,300] sent data... (H)
[Jan 20 12:35:02] DEBUG[19152] celliax_additional.c: rev exported[0x841e108|b63c2bb0][DEBUG_AT 2426 ][line1 ][ 6, 6,300] sent (carriage return)
[Jan 20 12:35:02] DEBUG[19152] celliax_additional.c: rev exported[0x841e108|b63c2bb0][DEBUG_AT 1346 ][line1 ][ 6, 6,300] Read line 0: |OK|
[Jan 20 12:35:02] DEBUG[19152] celliax_additional.c: rev exported[0x841e108|b63c2bb0][DEBUG_AT 2159 ][line1 ][ 6, 6,300] |OK| got what EXPECTED
[Jan 20 12:35:02] DEBUG[19152] chan_celliax.c: rev exported[0x841e108|b63c2bb0][DEBUG_SERIAL 695 ][line1 ][ 6, 0, 0] call hungup
[Jan 20 12:35:02] DEBUG[19152] chan_celliax.c: rev exported[0x841e108|b63c2bb0][DEBUG_SOUND 717 ][line1 ][ 6, 0, 0] shutting down sound
[Jan 20 12:35:02] DEBUG[19152] chan_celliax.c: rev exported[0x841e108|b63c2bb0][DEBUG_SERIAL 2677 ][line1 ][ 6, 0, 0] Syncing Serial
[Jan 20 12:35:02] DEBUG[19152] devicestate.c: Notification of state change to be queued on device/channel Celliax/line1
[Jan 20 12:35:02] DEBUG[19152] chan_celliax.c: rev exported[(nil)|b63c2bb0][DEBUG_PBX 768 ][line1 ][-1, 0, 0] Hanged Up
[Jan 20 12:35:02] DEBUG[19152] chan_celliax.c: rev exported[(nil)|b63c2bb0][DEBUG_PBX 779 ][line1 ][-1, 0, 0] EXITING FUNC
[Jan 20 12:35:02] DEBUG[19152] devicestate.c: Notification of state change to be queued on device/channel Celliax/line1
[Jan 20 12:35:02] DEBUG[19152] rtp.c: Channel '' has no RTP, not doing anything
[Jan 20 12:35:02] DEBUG[19152] app_dial.c: Exiting with DIALSTATUS=ANSWER.
[Jan 20 12:35:02] DEBUG[19152] pbx.c: Spawn extension (outbound,80447688816,2) exited non-zero on 'SIP/sta-pbx-2-00000005'
[Jan 20 12:35:02] VERBOSE[19152] logger.c: == Spawn extension (outbound, 80447688816, 2) exited non-zero on 'SIP/sta-pbx-2-00000005'
[Jan 20 12:35:02] DEBUG[19152] channel.c: Soft-Hanging up channel 'SIP/sta-pbx-2-00000005'
[Jan 20 12:35:02] DEBUG[19152] channel.c: Hanging up channel 'SIP/sta-pbx-2-00000005'
[Jan 20 12:35:02] DEBUG[19152] chan_sip.c: Hangup call SIP/sta-pbx-2-00000005, SIP callid 797a97571233726e6f562a8532e0294c@192.168.5.253)
[Jan 20 12:35:02] DEBUG[19152] devicestate.c: Notification of state change to be queued on device/channel SIP/sta-pbx-2
[Jan 20 12:35:02] DEBUG[19045] chan_celliax.c: rev exported[(nil)|b7dc7bb0][DEBUG_PBX 495 ][line1 ][-1, 0, 0] Interface is NOT OWNED by a channel
[Jan 20 12:35:02] DEBUG[19045] devicestate.c: Changing state for Celliax/line1 - state 1 (Not in use)
[Jan 20 12:35:02] DEBUG[19045] chan_celliax.c: rev exported[(nil)|b7dc7bb0][DEBUG_PBX 495 ][line1 ][-1, 0, 0] Interface is NOT OWNED by a channel
[Jan 20 12:35:02] DEBUG[19045] devicestate.c: Changing state for Celliax/line1 - state 1 (Not in use)
[Jan 20 12:35:02] DEBUG[19045] chan_sip.c: Checking device state for peer sta-pbx-2
[Jan 20 12:35:02] DEBUG[19045] devicestate.c: Changing state for SIP/sta-pbx-2 - state 1 (Not in use)
[Jan 20 12:35:02] DEBUG[19048] app_queue.c: Device 'Celliax/line1' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jan 20 12:35:02] DEBUG[19048] app_queue.c: Device 'Celliax/line1' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jan 20 12:35:02] DEBUG[19048] app_queue.c: Device 'SIP/sta-pbx-2' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jan 20 12:35:03] VERBOSE[19063] logger.c: Really destroying SIP dialog '797a97571233726e6f562a8532e0294c@192.168.5.253' Method: BYE
[Jan 20 12:35:09] DEBUG[19063] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jan 20 12:35:09] DEBUG[19063] chan_sip.c: Destroying SIP dialog 79ae29e2629d137e5dfc8e6f3af9871f@192.168.5.186
[Jan 20 12:35:09] VERBOSE[19063] logger.c: Really destroying SIP dialog '79ae29e2629d137e5dfc8e6f3af9871f@192.168.5.186' Method: OPTIONS
[Jan 20 12:35:09] DEBUG[19063] devicestate.c: Notification of state change to be queued on device/channel SIP/sta-pbx-7
[Jan 20 12:35:09] DEBUG[19045] chan_sip.c: Checking device state for peer sta-pbx-7
[Jan 20 12:35:09] DEBUG[19045] devicestate.c: Changing state for SIP/sta-pbx-7 - state 5 (Unavailable)
[Jan 20 12:35:09] DEBUG[19048] app_queue.c: Device 'SIP/sta-pbx-7' changed to state '5' (Unavailable) but we don't care because they're not a member of any queue.
[Jan 20 12:35:11] DEBUG[19063] chan_sip.c: Allocating new SIP dialog for 1894e85c16483a165a082f11703ceaa2@10.255.101.101 - OPTIONS (No RTP)
[Jan 20 12:35:11] DEBUG[19063] chan_sip.c: SIP message could not be handled, bad request: 1894e85c16483a165a082f11703ceaa2@10.255.101.101
[Jan 20 12:35:18] DEBUG[19063] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jan 20 12:35:18] DEBUG[19063] chan_sip.c: Stopping retransmission on '564b5ef0334add712737f7652131fe3d@192.168.5.186' of Request 102: Match Found
[Jan 20 12:35:18] VERBOSE[19063] logger.c: Really destroying SIP dialog '564b5ef0334add712737f7652131fe3d@192.168.5.186' Method: OPTIONS
[Jan 20 12:35:19] DEBUG[19063] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jan 20 12:35:20] DEBUG[19063] chan_sip.c: Destroying SIP dialog 32d5f14370d523d95909e439703a8307@192.168.5.186
[Jan 20 12:35:20] VERBOSE[19063] logger.c: Really destroying SIP dialog '32d5f14370d523d95909e439703a8307@192.168.5.186' Method: OPTIONS
[Jan 20 12:35:20] DEBUG[19063] devicestate.c: Notification of state change to be queued on device/channel SIP/sta-pbx-7
[Jan 20 12:35:20] DEBUG[19045] chan_sip.c: Checking device state for peer sta-pbx-7
[Jan 20 12:35:20] DEBUG[19045] devicestate.c: Changing state for SIP/sta-pbx-7 - state 5 (Unavailable)
[Jan 20 12:35:20] DEBUG[19048] app_queue.c: Device 'SIP/sta-pbx-7' changed to state '5' (Unavailable) but we don't care because they're not a member of any queue.
[Jan 20 12:35:20] VERBOSE[19134] logger.c: -- Remote UNIX connection disconnected
[Jan 20 12:35:27] DEBUG[19063] chan_sip.c: Auto destroying SIP dialog '5b3a149a62d417220f1e0abc61bf840a@192.168.5.253'
[Jan 20 12:35:27] DEBUG[19063] chan_sip.c: Destroying SIP dialog 5b3a149a62d417220f1e0abc61bf840a@192.168.5.253
[Jan 20 12:35:27] VERBOSE[19063] logger.c: Really destroying SIP dialog '5b3a149a62d417220f1e0abc61bf840a@192.168.5.253' Method: OPTIONS
[Jan 20 12:35:30] DEBUG[19063] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jan 20 12:35:30] DEBUG[19063] chan_sip.c: Destroying SIP dialog 4cd109e22a769a235282791d3380bd87@192.168.5.186
[Jan 20 12:35:30] VERBOSE[19063] logger.c: Really destroying SIP dialog '4cd109e22a769a235282791d3380bd87@192.168.5.186' Method: OPTIONS
[Jan 20 12:35:30] DEBUG[19063] devicestate.c: Notification of state change to be queued on device/channel SIP/sta-pbx-7
[Jan 20 12:35:30] DEBUG[19045] chan_sip.c: Checking device state for peer sta-pbx-7
[Jan 20 12:35:30] DEBUG[19045] devicestate.c: Changing state for SIP/sta-pbx-7 - state 5 (Unavailable)
[Jan 20 12:35:30] DEBUG[19048] app_queue.c: Device 'SIP/sta-pbx-7' changed to state '5' (Unavailable) but we don't care because they're not a member of any queue.
IT_prof what is problem?
S4 mobigater is not supported and is known to make problems at the level of USB bus, disconnections, etc etc... but this seems not yet happened to you.
What is the problem?
additional
additional information.
Sometimes (not always, but very often) when asterisk send ATH command to the gsm-interface to hangup, interface answers NO CARRIER.
Then I can't hangup channel between pbx and gsm-interface with "soft hangup" and "celliax_hangup" commands.
Asterisk's reboot only help me and it_prof.
What do you think about?
Why sometime can gsm-interface return NO CARRIER after ATH (hangup) command?
NO CARRIER after ATH
Mmmmmh, seems that the USB is not reporting the OK that is sent after the ATH.
The correct "dialog" would be (as you know):
--->ATH
<---OK
<---NO CARRIER
BTW the S4 is unreliable at the level of USB (overload bus bandwidth), but maybe this is not the case.
Can you post here some more debug log, in addition of the log you posted before?
I'll try to made a workaround during next week (and please, if you have suggestion, write it here)
Additional debug log
Thank you for your help, gmaruzz!
You can download log here
additional infos on NO CARRIER after ATH
You think that the problem comes *always* in the form of an ATH followed by a NO_CARRIER instead of the expected OK? (if this is the case, the solution would be simple for me to implement)
Can you check if the problem persists using only three lines? (eg: commenting out one interface from the celliax.conf file)
Also, can you please comment the debug output, I mean, describing what you do at what moment?
When you launch a call, when you answer, when you hangup, when there is the problem, etc...
That would help me a lot in reading the debug.
" You think that the problem
" You think that the problem comes *always* in the form of an ATH followed by a NO_CARRIER instead of the expected OK? (if this is the case, the solution would be simple for me to implement)"
Yes, I do.
This problem is appear only when we received NO_CARRIER after ATH.
Today we tried insert in celliax.conf at_hangup_expect=NO CARRIER. Unfortunately it helped us is not in all cases.
I'll try to make a patch for you to test
I'll try to make a patch for you to test, let's say in a couple hours, maybe before
patch for NO CARRIER after ATH
Dear surium and IT_prof,
would you like to test this quick and dirty hack?
Please edit the sources of chan_celliax module, file celliax_additional.c, line 2163, now is:
if ((strcmp(p->line_array.result[i], "OK") == 0)) {
make it:
//if ((strcmp(p->line_array.result[i], "OK") == 0)) {
if ((strcmp(p->line_array.result[i], "OK") == 0) || (strcmp(p->line_array.result[i], "NO CARRIER") == 0) ) {
the line that is not preceded by // is one only line, is just the browser dimension that maybe breaks it. Enlarge your browser and you'll see it all in one line.
Then recompile chan_celliax.so module and re-copy it at its place.
Let me know if this solves your problem
Unfortunately this patch
Unfortunately this patch didn't solve our problem.
Normal call termination
[Jan 22 12:55:16] DEBUG[4966] celliax_additional.c: rev exported[0x8441b40|b643cbb0][DEBUG_AT 1346 ][line0 ][ 6, 6,300] Read line 0: |NO CARRIER|
[Jan 22 12:55:16] DEBUG[4966] celliax_additional.c: rev exported[0x8441b40|b643cbb0][DEBUG_AT 1489 ][line0 ][ 6, 6,102] |NO CARRIER| CALLFLOW_CALL_NOCARRIER
[Jan 22 12:55:16] DEBUG[4966] chan_celliax.c: rev exported[0x8441b40|b643cbb0][DEBUG_PBX 463 ][line0 ][ 6, 6,102] Queued CONTROL FRAME 1
[Jan 22 12:55:16] DEBUG[4963] chan_celliax.c: rev exported[0x8441b40|b63eebb0][DEBUG_PBX 910 ][line0 ][ 6, 6,102] Sent CONTROL FRAME 1
[Jan 22 12:55:16] DEBUG[4963] channel.c: Bridge stops bridging channels SIP/sta-pbx-2-00000010 and Celliax/line0
[Jan 22 12:55:16] DEBUG[4966] celliax_additional.c: rev exported[0x8441b40|b643cbb0][DEBUG_AT 2166 ][line0 ][ 6, 6,102] got OK
[Jan 22 12:55:16] DEBUG[4963] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record.
[Jan 22 12:55:16] DEBUG[4963]: cdr_addon_mysql.c:246 mysql_log: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid,userfield) VALUES ('2010-01-22 12:54:56','\"Sergey Makushinsky\" <1300>','1300','80291872337','outbound', 'SIP/sta-pbx-2-00000010','Celliax/line0','Dial','Celliax/line0/80291872337',20,10,'ANSWERED',3,'','1264157696.34','')
[Jan 22 12:55:16] DEBUG[4963]: channel.c:1564 ast_hangup: Hanging up channel 'Celliax/line0'
[Jan 22 12:55:16] DEBUG[4963]: chan_celliax.c:648 celliax_hangup: rev exported[0x8441b40|b63eebb0][DEBUG_PBX 648 ][line0 ][ 6, 6,102] ENTERING FUNC
[Jan 22 12:55:16] DEBUG[4966]: chan_celliax.c:441 celliax_unlocka_log: exported[b643cbb0] I'm a dying thread, and I'm to go unlocking mutex 0xb7999358 for the 0th time
[Jan 22 12:55:16] DEBUG[4966]: chan_celliax.c:441 celliax_unlocka_log: exported[b643cbb0] I'm a dying thread, and I'm to go unlocking mutex 0xb7999358 for the 1th time
[Jan 22 12:55:16] DEBUG[4966]: chan_celliax.c:441 celliax_unlocka_log: exported[b643cbb0] I'm a dying thread, and I'm to go unlocking mutex 0xb7999358 for the 2th time
[Jan 22 12:55:16] DEBUG[4966]: chan_celliax.c:441 celliax_unlocka_log: exported[b643cbb0] I'm a dying thread, and I'm to go unlocking mutex 0xb7999358 for the 3th time
[Jan 22 12:55:16] DEBUG[4966]: chan_celliax.c:441 celliax_unlocka_log: exported[b643cbb0] I'm a dying thread, and I'm to go unlocking mutex 0xb7999358 for the 4th time
[Jan 22 12:55:16] DEBUG[4966]: chan_celliax.c:448 celliax_unlocka_log: exported[b643cbb0] I'm a dying thread, I've finished unlocking mutex 0xb7999358
[Jan 22 12:55:16] DEBUG[4963]: celliax_additional.c:2548 celliax_serial_write_AT_expect1: rev exported[0x8441b40|b63eebb0][DEBUG_AT 2548 ][line0 ][ 6, 6,102] sending: ATH, expecting: OK
[Jan 22 12:55:16] DEBUG[4963]: celliax_additional.c:2397 celliax_serial_write_AT: rev exported[0x8441b40|b63eebb0][DEBUG_AT 2397 ][line0 ][ 6, 6,102] sent data... (A)
[Jan 22 12:55:16] DEBUG[4963]: celliax_additional.c:2397 celliax_serial_write_AT: rev exported[0x8441b40|b63eebb0][DEBUG_AT 2397 ][line0 ][ 6, 6,102] sent data... (T)
[Jan 22 12:55:16] DEBUG[4963]: celliax_additional.c:2397 celliax_serial_write_AT: rev exported[0x8441b40|b63eebb0][DEBUG_AT 2397 ][line0 ][ 6, 6,102] sent data... (H)
[Jan 22 12:55:16] DEBUG[4963]: celliax_additional.c:2427 celliax_serial_write_AT: rev exported[0x8441b40|b63eebb0][DEBUG_AT 2427 ][line0 ][ 6, 6,102] sent (carriage return)
[Jan 22 12:55:16] DEBUG[4963]: celliax_additional.c:1346 celliax_serial_read_AT: rev exported[0x8441b40|b63eebb0][DEBUG_AT 1346 ][line0 ][ 6, 6,102] Read line 0: |OK|
[Jan 22 12:55:16] DEBUG[4963]: celliax_additional.c:2159 celliax_serial_read_AT: rev exported[0x8441b40|b63eebb0][DEBUG_AT 2159 ][line0 ][ 6, 6,102] |OK| got what EXPECTED
[Jan 22 12:55:16] DEBUG[4963]: chan_celliax.c:695 celliax_hangup: rev exported[0x8441b40|b63eebb0][DEBUG_SERIAL 695 ][line0 ][ 6, 0, 0] call hungup
[Jan 22 12:55:16] DEBUG[4963]: chan_celliax.c:717 celliax_hangup: rev exported[0x8441b40|b63eebb0][DEBUG_SOUND 717 ][line0 ][ 6, 0, 0] shutting down sound
[Jan 22 12:55:16] DEBUG[4963]: chan_celliax.c:2677 celliax_serial_init: rev exported[0x8441b40|b63eebb0][DEBUG_SERIAL 2677 ][line0 ][ 6, 0, 0] Syncing Serial
[Jan 22 12:55:16] DEBUG[4963]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel Celliax/line0
[Jan 22 12:55:16] DEBUG[4963]: chan_celliax.c:768 celliax_hangup: rev exported[(nil)|b63eebb0][DEBUG_PBX 768 ][line0 ][-1, 0, 0] Hanged Up
[Jan 22 12:55:16] DEBUG[4610]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Celliax - line0
[Jan 22 12:55:16] DEBUG[4963]: chan_celliax.c:779 celliax_hangup: rev exported[(nil)|b63eebb0][DEBUG_PBX 779 ][line0 ][-1, 0, 0] EXITING FUNC
[Jan 22 12:55:16] DEBUG[4963]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel Celliax/line0
[Jan 22 12:55:16] DEBUG[4963]: rtp.c:1573 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything
[Jan 22 12:55:16] DEBUG[4963]: app_dial.c:1901 dial_exec_full: Exiting with DIALSTATUS=ANSWER.
[Jan 22 12:55:16] DEBUG[4963]: pbx.c:2411 __ast_pbx_run: Spawn extension (outbound,80291872337,1) exited non-zero on 'SIP/sta-pbx-2-00000010'
== Spawn extension (outbound, 80291872337, 1) exited non-zero on 'SIP/sta-pbx-2-00000010'
[Jan 22 12:55:16] DEBUG[4963]: channel.c:1461 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/sta-pbx-2-00000010'
[Jan 22 12:55:16] DEBUG[4963]: channel.c:1564 ast_hangup: Hanging up channel 'SIP/sta-pbx-2-00000010'
[Jan 22 12:55:16] DEBUG[4963]: chan_sip.c:3706 sip_hangup: Hangup call SIP/sta-pbx-2-00000010, SIP callid 5d0d18433224d83031bd83f84f4ef8b5@192.168.5.253)
[Jan 22 12:55:16] DEBUG[4963]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/sta-pbx-2
[Jan 22 12:55:16] DEBUG[4610]: chan_celliax.c:495 celliax_devicestate: rev exported[(nil)|b7dbebb0][DEBUG_PBX 495 ][line0 ][-1, 0, 0] Interface is NOT OWNED by a channel
[Jan 22 12:55:16] DEBUG[4610]: devicestate.c:287 do_state_change: Changing state for Celliax/line0 - state 1 (Not in use)
[Jan 22 12:55:16] DEBUG[4610]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Celliax - line0
[Jan 22 12:55:16] DEBUG[4610]: chan_celliax.c:495 celliax_devicestate: rev exported[(nil)|b7dbebb0][DEBUG_PBX 495 ][line0 ][-1, 0, 0] Interface is NOT OWNED by a channel
[Jan 22 12:55:16] DEBUG[4610]: devicestate.c:287 do_state_change: Changing state for Celliax/line0 - state 1 (Not in use)
[Jan 22 12:55:16] DEBUG[4610]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - sta-pbx-2
[Jan 22 12:55:16] DEBUG[4610]: chan_sip.c:17206 sip_devicestate: Checking device state for peer sta-pbx-2
[Jan 22 12:55:16] DEBUG[4610]: devicestate.c:287 do_state_change: Changing state for SIP/sta-pbx-2 - state 1 (Not in use)
After ATH asterisk works with 0x8441b40|b63eebb0 for hangup celliax and sip channel
Failed call termination
[Jan 22 12:27:29] DEBUG[4620] chan_sip.c: = Found Their Call ID: 1c7f05a30134f16c5e76680b65ba687b@192.168.5.253 Their Tag as3579c1f1 Our tag: as3d38e2fa
[Jan 22 12:27:29] DEBUG[4620] chan_sip.c: **** Received BYE (8) - Command in SIP BYE
[Jan 22 12:27:29] DEBUG[4620] chan_sip.c: Setting SIP_ALREADYGONE on dialog 1c7f05a30134f16c5e76680b65ba687b@192.168.5.253
[Jan 22 12:27:29] DEBUG[4620] chan_sip.c: Received bye, issuing owner hangup
[Jan 22 12:27:29] DEBUG[4826] channel.c: Didn't get a frame from channel: SIP/sta-pbx-2-0000000d
[Jan 22 12:27:29] WARNING[4826] chan_celliax.c: rev exported[0x8424c60|b6690bb0][WARNING 547 ][line1 ][ 6, 6,300] Don't know how to display condition 20 on Celliax/line1
[Jan 22 12:27:29] DEBUG[4826] channel.c: Bridge stops bridging channels SIP/sta-pbx-2-0000000d and Celliax/line1
[Jan 22 12:27:29] DEBUG[4826] cdr_addon_mysql.c: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid,userfield) VALUES ('2010-01-22 12:25:45','\"Evgeniya Spiridonova\" <2139>','2139','80447221788','outbound', 'SIP/sta-pbx-2-0000000d','Celliax/line1','Dial','Celliax/line1/80447221788',104,61,'ANSWERED',3,'','1264155945.27','')
[Jan 22 12:27:29] DEBUG[4826] channel.c: Hanging up channel 'Celliax/line1'
[Jan 22 12:27:29] DEBUG[4826] chan_celliax.c: rev exported[0x8424c60|b6690bb0][DEBUG_PBX 648 ][line1 ][ 6, 6,300] ENTERING FUNC
[Jan 22 12:27:29] DEBUG[4835] chan_celliax.c: exported[b6480bb0] I'm a dying thread, and I'm to go unlocking mutex 0xb78da358 for the 0th time
[Jan 22 12:27:29] DEBUG[4835] chan_celliax.c: exported[b6480bb0] I'm a dying thread, and I'm to go unlocking mutex 0xb78da358 for the 1th time
[Jan 22 12:27:29] DEBUG[4835] chan_celliax.c: exported[b6480bb0] I'm a dying thread, and I'm to go unlocking mutex 0xb78da358 for the 2th time
[Jan 22 12:27:29] DEBUG[4835] chan_celliax.c: exported[b6480bb0] I'm a dying thread, and I'm to go unlocking mutex 0xb78da358 for the 3th time
[Jan 22 12:27:29] DEBUG[4835] chan_celliax.c: exported[b6480bb0] I'm a dying thread, and I'm to go unlocking mutex 0xb78da358 for the 4th time
[Jan 22 12:27:29] DEBUG[4835] chan_celliax.c: exported[b6480bb0] I'm a dying thread, I've finished unlocking mutex 0xb78da358
[Jan 22 12:27:29] DEBUG[4826] celliax_additional.c: rev exported[0x8424c60|b6690bb0][DEBUG_AT 2548 ][line1 ][ 6, 6,300] sending: ATH, expecting: OK
[Jan 22 12:27:29] DEBUG[4826] celliax_additional.c: rev exported[0x8424c60|b6690bb0][DEBUG_AT 2397 ][line1 ][ 6, 6,300] sent data... (A)
[Jan 22 12:27:29] DEBUG[4826] celliax_additional.c: rev exported[0x8424c60|b6690bb0][DEBUG_AT 2397 ][line1 ][ 6, 6,300] sent data... (T)
[Jan 22 12:27:29] DEBUG[4826] celliax_additional.c: rev exported[0x8424c60|b6690bb0][DEBUG_AT 2397 ][line1 ][ 6, 6,300] sent data... (H)
[Jan 22 12:27:29] DEBUG[4826] celliax_additional.c: rev exported[0x8424c60|b6690bb0][DEBUG_AT 2427 ][line1 ][ 6, 6,300] sent (carriage return)
[Jan 22 12:27:30] DEBUG[4826] celliax_additional.c: rev exported[0x8424c60|b6690bb0][DEBUG_AT 1346 ][line1 ][ 6, 6,300] Read line 0: |NO CARRIER|
[Jan 22 12:27:30] DEBUG[4826] celliax_additional.c: rev exported[0x8424c60|b6690bb0][DEBUG_AT 1489 ][line1 ][ 6, 6,102] |NO CARRIER| CALLFLOW_CALL_NOCARRIER
[Jan 22 12:27:30] DEBUG[4826] chan_celliax.c: rev exported[0x8424c60|b6690bb0][DEBUG_PBX 463 ][line1 ][ 6, 6,102] Queued CONTROL FRAME 1
and after nothing about [0x8424c60|b6690bb0]
post some more debug
:(
can you post some more from this last file, from ATH on?
I need to understand what happens lo [line1] after NO CARRIER
also, if you're in IRC (irc.freenode.net) we can chat more easily on the #gsmopen channel
ATH NO CARRIER new patch
try this patch:
celliax_additional.c, line 1485, is now:
if ((strcmp(p->line_array.result[i], "NO CARRIER") == 0)) {
p->phone_callflow = CALLFLOW_CALL_NOCARRIER;
if (option_debug > 1)
DEBUGA_AT("|%s| CALLFLOW_CALL_NOCARRIER\n", CELLIAX_P_LOG,
p->line_array.result[i]);
if (p->interface_state != AST_STATE_DOWN && p->owner) {
p->owner->hangupcause = AST_CAUSE_FAILURE;
celliax_queue_control(p->owner, AST_CONTROL_HANGUP);
} else {
ERRORA("Why NO CARRIER now?\n", CELLIAX_P_LOG);
}
}
make it:
if ((strcmp(p->line_array.result[i], "NO CARRIER") == 0)) {
p->phone_callflow = CALLFLOW_CALL_NOCARRIER;
if (option_debug > 1)
DEBUGA_AT("|%s| CALLFLOW_CALL_NOCARRIER\n", CELLIAX_P_LOG,
p->line_array.result[i]);
p->control_to_send = 0; //ADDED LINE!!!
usleep(20000); //ADDED LINE!!!
if (p->interface_state != AST_STATE_DOWN && p->owner) {
p->owner->hangupcause = AST_CAUSE_FAILURE;
celliax_queue_control(p->owner, AST_CONTROL_HANGUP);
} else {
ERRORA("Why NO CARRIER now?\n", CELLIAX_P_LOG);
}
}
then recompile, re-copy chan_celliax.so at its place, shutdown and restart asterisk, and see if it work. You can leave the previous patch there, will not hurt (I hope ;) )
Thank you
The patch works, the channels are no longer hangs
Thank you very much, gmaruzz!