I have problems with Asterisk 1.4.14 with Mobigaters S4.
All works good, but after some time the sound does not reaches the dial-up user. And after that this problem persist to all outgoing calls.
SIP client of Asterisk hears the cellphone subscriber. But the cellphone subscriber can't hear the SIP client of Asterisk.
This trouble may appear after some working hours of Asterisk, or even after serveral days.
Problem disapears after restarting the Asterisk (restart of chan_celliax.so crashes Asterisk).
After some time the problem appears again.
I use Linux debian 2.6.18-4-686.
This problem was was found out on an "ordinary" PC, and on the HP Proliant DL160G5 server too.
And the same was also on Asterisk 1.4.14 and on 1.6.0.20 too.
On Mobigater S4 I use only 2 lines.
Dialplan in extentions.conf:
exten => _8XXX.,1,dial(Celliax/line0/${EXTEN},120,t)
celliax.conf:
; The first interface (named line0)
[line0]
language=en
context=default2
extension=59006
debug_serial=yes
debug_pbx=yes
debug_sound=yes
debug_call=yes
sms_receiving_program=/usr/local/sbin/ciapalo
control_device_protocol=AT
control_device_speed=115200
control_device_name=/dev/ttyACM0 ; this is a Celliax Official Device, recognized as a modem by Linux
portaudio_capture_device_id=0
need_acoustic_ring=0
dsp_silence_threshold=1024
playback_boost=0 ;
capture_boost=0 ;
alsa_capture_device_name=plughw:0
alsa_playback_device_name=plughw:0
alsa_period_size=160
alsa_periods_in_buffer=4
at_dial_pre_number=ATD
at_dial_expect=OK
at_hangup=ATH
at_hangup_expect=OK
at_answer=ATA
at_answer_expect=OK
at_initial_pause=500000
at_preinit_1=atciapa ; nonsense entry, just to show the preinit
at_preinit_1_expect=OK
at_preinit_2=
at_preinit_2_expect=
at_preinit_3=
at_preinit_3_expect=
at_preinit_4=
at_preinit_4_expect=
at_preinit_5=
at_preinit_5_expect=
at_after_preinit_pause=500000
at_postinit_1=at+cmic=0,9 ; modem's microphone sensitivity (our spk)
at_postinit_1_expect=OK
at_postinit_2=AT+CKPD="EEE" ;send three "end" buttonpress, to have the phone in a sane state, ready to dialing with furter CKPDs ***THIS IS IMPORTANT, needed on c650***
at_postinit_2_expect=OK
at_postinit_3=AT+CSSN=1,0
at_postinit_3_expect=OK
at_postinit_4=at+sidet=0 ; no sidetone in modem, please
at_postinit_4_expect=OK
at_postinit_5=at+clvl=99 ; modem's speaker level, out mic
at_postinit_5_expect=OK
at_query_battchg=AT+CBC
at_query_battchg_expect=OK
at_query_signal=AT+CSQ
at_query_signal_expect=OK
at_send_dtmf=AT+VTS
at_indicator_noservice_string=+CIEV: 2,0
at_indicator_nosignal_string=+CIEV: 5,0
at_indicator_lowsignal_string=+CIEV: 5,1
at_indicator_lowbattchg_string=+CIEV: 0,1
at_indicator_nobattchg_string=+CIEV: 0,0
at_indicator_callactive_string=+CIEV: 3,1
at_indicator_nocallactive_string=+CIEV: 3,0
at_indicator_nocallsetup_string=+CIEV: 6,0
at_indicator_callsetupincoming_string=+CIEV: 6,1
at_indicator_callsetupoutgoing_string=+CIEV: 6,2
at_indicator_callsetupremoteringing_string=+CIEV: 6,3
at_call_idle=+MCST: 1
at_call_incoming=+MCST: 2
at_call_active=+CSSI: 7
at_call_failed=+MCST: 65
at_call_calling=+CSSI: 1
[line1]
language=en
context=default2
extension=59006
sms_receiving_program=/usr/local/sbin/ciapalo
control_device_protocol=AT
control_device_speed=115200
control_device_name=/dev/ttyACM1 ; this is a Celliax Official Device, recognized as a modem by Linux
portaudio_capture_device_id=1
need_acoustic_ring=0
dsp_silence_threshold=1024
playback_boost=0 ;
capture_boost=0 ;
alsa_capture_device_name=plughw:1
alsa_playback_device_name=plughw:1
alsa_period_size=160
alsa_periods_in_buffer=4
at_dial_pre_number=ATD
at_dial_expect=OK
at_hangup=ATH
at_hangup_expect=OK
at_answer=ATA
at_answer_expect=OK
at_initial_pause=500000
at_preinit_1=atciapa ; nonsense entry, just to show the preinit
at_preinit_1_expect=OK
at_preinit_2=
at_preinit_2_expect=
at_preinit_3=
at_preinit_3_expect=
at_preinit_4=
at_preinit_4_expect=
at_preinit_5=
at_preinit_5_expect=
at_after_preinit_pause=500000
at_postinit_1=at+cmic=0,9 ; modem's microphone sensitivity (our spk)
at_postinit_1_expect=OK
at_postinit_2=AT+CKPD="EEE" ;send three "end" buttonpress, to have the phone in a sane state, ready to dialing with furter CKPDs ***THIS IS IMPORTANT, needed on c650***
at_postinit_2_expect=OK
at_postinit_3=AT+CSSN=1,0
at_postinit_3_expect=OK
at_postinit_4=at+sidet=0 ; no sidetone in modem, please
at_postinit_4_expect=OK
at_postinit_5=at+clvl=99 ; modem's speaker level, out mic
at_postinit_5_expect=OK
at_query_battchg=AT+CBC
at_query_battchg_expect=OK
at_query_signal=AT+CSQ
at_query_signal_expect=OK
at_send_dtmf=AT+VTS
at_indicator_noservice_string=+CIEV: 2,0
at_indicator_nosignal_string=+CIEV: 5,0
at_indicator_lowsignal_string=+CIEV: 5,1
at_indicator_lowbattchg_string=+CIEV: 0,1
at_indicator_nobattchg_string=+CIEV: 0,0
at_indicator_callactive_string=+CIEV: 3,1
at_indicator_nocallactive_string=+CIEV: 3,0
at_indicator_nocallsetup_string=+CIEV: 6,0
at_indicator_callsetupincoming_string=+CIEV: 6,1
at_indicator_callsetupoutgoing_string=+CIEV: 6,2
at_indicator_callsetupremoteringing_string=+CIEV: 6,3
at_call_idle=+MCST: 1
at_call_incoming=+MCST: 2
at_call_active=+CSSI: 7
at_call_failed=+MCST: 65
at_call_calling=+CSSI: 1
--------
Line2 and Line3 discribed similary, but SIM-cards are absent.
Results of some Linux commands:
debian:~# ls -l /dev/ttyA*
crw-rw---- 1 root dialout 166, 0 2010-04-02 10:27 /dev/ttyACM0
crw-rw---- 1 root dialout 166, 1 2010-04-02 10:23 /dev/ttyACM1
crw-rw---- 1 root dialout 166, 2 2010-04-02 10:23 /dev/ttyACM2
crw-rw---- 1 root dialout 166, 3 2010-04-02 10:23 /dev/ttyACM3
debian:~# ls -l /dev/ttyU*
ls: /dev/ttyU*: No such file or directory
debian:~# ls -l /dev/snd*
lrwxrwxrwx 1 root root 24 2010-03-25 11:51 /dev/sndstat -> /proc/asound/oss/sndstat
/dev/snd:
total 0
crw-rw---- 1 root audio 116, 0 2010-03-25 11:54 controlC0
crw-rw---- 1 root audio 116, 32 2010-03-25 11:54 controlC1
crw-rw---- 1 root audio 116, 64 2010-03-25 11:54 controlC2
crw-rw---- 1 root audio 116, 96 2010-03-25 11:54 controlC3
crw-rw---- 1 root audio 116, 24 2010-03-25 11:54 pcmC0D0c
crw-rw---- 1 root audio 116, 16 2010-03-25 11:54 pcmC0D0p
crw-rw---- 1 root audio 116, 56 2010-03-25 11:54 pcmC1D0c
crw-rw---- 1 root audio 116, 48 2010-03-25 11:54 pcmC1D0p
crw-rw---- 1 root audio 116, 88 2010-03-25 11:54 pcmC2D0c
crw-rw---- 1 root audio 116, 80 2010-03-25 11:54 pcmC2D0p
crw-rw---- 1 root audio 116, 120 2010-03-25 11:54 pcmC3D0c
crw-rw---- 1 root audio 116, 112 2010-03-25 11:54 pcmC3D0p
crw-rw---- 1 root audio 116, 33 2010-03-25 11:54 timer
debian:~# svn info
Path: .
URL: http://svn.freeswitch.org:81/svn/freeswitch/branches/gmaruzz/mod_gsmopen...
Repository Root: http://svn.freeswitch.org:81/svn
Repository UUID: d0543943-73ff-0310-b7d9-9358b9ac24b2
Revision: 16515
Node Kind: directory
Schedule: normal
Last Changed Author: gmaruzz
Last Changed Rev: 16511
Last Changed Date: 2010-01-25 17:48:11 +0300 (Mon, 25 Jan 2010)
debian:~# lsmod |grep snd
snd_usb_audio 69024 4
snd_pcm 68676 5 snd_usb_audio
snd_timer 20996 1 snd_pcm
snd_page_alloc 9640 1 snd_pcm
snd_usb_lib 14976 1 snd_usb_audio
snd_rawmidi 22560 1 snd_usb_lib
snd_seq_device 7820 1 snd_rawmidi
snd_hwdep 8836 1 snd_usb_audio
snd 47012 10 snd_usb_audio,snd_pcm,snd_timer,snd_rawmidi,snd_seq_device,snd_hwdep
soundcore 9248 1 snd
usbcore 112644 6 snd_usb_audio,snd_usb_lib,usbhid,cdc_acm,ohci_hcd
one way sound 2
Hi Farfor,
can you post, or pastebin somewhere, the debug info from a run that gives you problems?
You can obtain debug info following the instruction at the bottom of this page:
http://www.gsmopen.org/howtobug
I have been waited for the
I have been waited for the "problem" moment.
This is my log:
[Apr 8 09:03:11] DEBUG[15646]: chan_sip.c:4190 do_setnat: Setting NAT on RTP to Off
[Apr 8 09:03:11] DEBUG[15646]: chan_sip.c:6367 sip_alloc: Allocating new SIP dialog for 1dc5d99e203beebe5620c1a325b24720@10.1.254.100 - INVITE (With RTP)
[Apr 8 09:03:11] DEBUG[15646]: chan_sip.c:19451 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE
[Apr 8 09:03:11] DEBUG[15646]: chan_sip.c:4190 do_setnat: Setting NAT on RTP to Off
[Apr 8 09:03:11] DEBUG[15646]: chan_sip.c:2728 __sip_xmit: Trying to put 'SIP/2.0 401' onto UDP socket destined for 10.1.254.100:5060
[Apr 8 09:03:11] DEBUG[15646]: chan_sip.c:6433 find_call: = Found Their Call ID: 1dc5d99e203beebe5620c1a325b24720@10.1.254.100 Their Tag as433e0e98 Our tag: as3d410eca
[Apr 8 09:03:11] DEBUG[15646]: chan_sip.c:19451 handle_incoming: **** Received ACK (6) - Command in SIP ACK
[Apr 8 09:03:11] DEBUG[15646]: chan_sip.c:3250 __sip_ack: Stopping retransmission on '1dc5d99e203beebe5620c1a325b24720@10.1.254.100' of Response 102: Match Found
[Apr 8 09:03:11] DEBUG[15646]: chan_sip.c:6433 find_call: = Found Their Call ID: 1dc5d99e203beebe5620c1a325b24720@10.1.254.100 Their Tag as433e0e98 Our tag: as3d410eca
[Apr 8 09:03:11] DEBUG[15646]: chan_sip.c:19451 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE
[Apr 8 09:03:11] DEBUG[15646]: chan_sip.c:4190 do_setnat: Setting NAT on RTP to Off
[Apr 8 09:03:11] DEBUG[15646]: chan_sip.c:7057 process_sdp: Processing session-level SDP v=0... UNSUPPORTED.
[Apr 8 09:03:11] DEBUG[15646]: chan_sip.c:7057 process_sdp: Processing session-level SDP o=root 20828 20829 IN IP4 10.1.254.100... UNSUPPORTED.
[Apr 8 09:03:11] DEBUG[15646]: chan_sip.c:7057 process_sdp: Processing session-level SDP s=session... UNSUPPORTED.
[Apr 8 09:03:11] DEBUG[15646]: chan_sip.c:7057 process_sdp: Processing session-level SDP c=IN IP4 10.1.254.100... OK.
[Apr 8 09:03:11] DEBUG[15646]: chan_sip.c:7057 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED.
[Apr 8 09:03:11] DEBUG[15646]: chan_sip.c:7221 process_sdp: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK.
[Apr 8 09:03:11] DEBUG[15646]: chan_sip.c:7221 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK.
[Apr 8 09:03:11] DEBUG[15646]: chan_sip.c:7221 process_sdp: Processing media-level (audio) SDP a=fmtp:101 0-16... UNSUPPORTED.
[Apr 8 09:03:11] DEBUG[15646]: chan_sip.c:7221 process_sdp: Processing media-level (audio) SDP a=silenceSupp:off - - - -... UNSUPPORTED.
[Apr 8 09:03:11] DEBUG[15646]: chan_sip.c:7221 process_sdp: Processing media-level (audio) SDP a=ptime:20... OK.
[Apr 8 09:03:11] DEBUG[15646]: chan_sip.c:7221 process_sdp: Processing media-level (audio) SDP a=sendrecv... OK.
[Apr 8 09:03:11] DEBUG[15646]: chan_sip.c:7395 process_sdp: We're settling with these formats: 0x4 (ulaw)
[Apr 8 09:03:11] DEBUG[15646]: chan_sip.c:17974 handle_request_invite: Checking SIP call limits for device silver
[Apr 8 09:03:11] DEBUG[15646]: chan_sip.c:4770 update_call_counter: Updating call counter for incoming call
[Apr 8 09:03:11] DEBUG[15646]: chan_sip.c:5747 sip_new: *** Our native formats are 0x4 (ulaw)
[Apr 8 09:03:11] DEBUG[15646]: chan_sip.c:5748 sip_new: *** Joint capabilities are 0x4 (ulaw)
[Apr 8 09:03:11] DEBUG[15646]: chan_sip.c:5749 sip_new: *** Our capabilities are 0xc (ulaw|alaw)
[Apr 8 09:03:11] DEBUG[15646]: chan_sip.c:5750 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw)
[Apr 8 09:03:11] DEBUG[15646]: chan_sip.c:5778 sip_new: This channel will not be able to handle video.
[Apr 8 09:03:11] DEBUG[15646]: chan_sip.c:10958 build_route: build_route: Contact hop:
[Apr 8 09:03:11] DEBUG[15646]: chan_sip.c:18204 handle_request_invite: SIP/silver-0000009b: New call is still down.... Trying...
[Apr 8 09:03:11] DEBUG[15646]: chan_sip.c:2728 __sip_xmit: Trying to put 'SIP/2.0 100' onto UDP socket destined for 10.1.254.100:5060
[Apr 8 09:03:11] DEBUG[15646]: devicestate.c:452 ast_devstate_changed_literal: Notification of state change to be queued on device/channel SIP/silver
[Apr 8 09:03:11] DEBUG[15640]: devicestate.c:325 _ast_device_state: No provider found, checking channel drivers for SIP - silver
[Apr 8 09:03:11] DEBUG[15640]: chan_sip.c:20720 sip_devicestate: Checking device state for peer silver
[Apr 8 09:03:11] DEBUG[15640]: devicestate.c:443 do_state_change: Changing state for SIP/silver - state 1 (Not in use)
[Apr 8 09:03:11] DEBUG[15647]: app_queue.c:772 handle_statechange: Device 'SIP/silver' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Apr 8 09:03:11] DEBUG[16676]: pbx.c:3119 pbx_extension_helper: Launching 'Dial'
-- Executing [89274800281@mobigatersilver:1] Dial("SIP/silver-0000009b", "Celliax/line1/89274800281,120,t") in new stack
[Apr 8 09:03:11] DEBUG[16676]: chan_celliax.c:572 celliax_request: rev [(nil)|b7024bb0][DEBUG_PBX 572 ][none ][-1,-1,-1] ENTERING FUNC
[Apr 8 09:03:11] DEBUG[16676]: chan_celliax.c:576 celliax_request: rev [(nil)|b7024bb0][DEBUG_PBX 576 ][none ][-1,-1,-1] Try to request type: Celliax, name: line1/89274800281, cause: 0, format: 64
[Apr 8 09:03:11] DEBUG[16676]: chan_celliax.c:601 celliax_request: rev [(nil)|b7024bb0][DEBUG_PBX 601 ][line1 ][-1, 0,110] Requesting: Celliax, name: line1/89274800281, format: 64
[Apr 8 09:03:11] DEBUG[16676]: chan_celliax.c:1147 celliax_new: rev [(nil)|b7024bb0][DEBUG_PBX 1147 ][line1 ][-1, 0,110] ENTERING FUNC
[Apr 8 09:03:11] DEBUG[16676]: celliax_additional.c:402 alsa_open_dev: rev [(nil)|b7024bb0][DEBUG_SOUND 402 ][line1 ][-1, 0,110] Acquired fd 31 from the poll descriptor
[Apr 8 09:03:11] DEBUG[16676]: celliax_additional.c:425 alsa_open_dev: rev [(nil)|b7024bb0][DEBUG_SOUND 425 ][line1 ][-1, 0,110] started!
[Apr 8 09:03:11] DEBUG[16676]: celliax_additional.c:437 alsa_open_dev: rev [(nil)|b7024bb0][DEBUG_SOUND 437 ][line1 ][-1, 0,110] ALSA handle = 138554088
[Apr 8 09:03:11] DEBUG[16676]: celliax_additional.c:402 alsa_open_dev: rev [(nil)|b7024bb0][DEBUG_SOUND 402 ][line1 ][-1, 0,110] Acquired fd 32 from the poll descriptor
[Apr 8 09:03:11] DEBUG[16676]: celliax_additional.c:437 alsa_open_dev: rev [(nil)|b7024bb0][DEBUG_SOUND 437 ][line1 ][-1, 0,110] ALSA handle = 138531696
[Apr 8 09:03:11] DEBUG[16676]: chan_celliax.c:1180 celliax_new: rev [(nil)|b7024bb0][DEBUG_PBX 1180 ][line1 ][-1, 0,110] new channel: name=Celliax/line1 requested_state=0
[Apr 8 09:03:11] DEBUG[16676]: chan_celliax.c:1264 celliax_new: rev [0x8413590|b7024bb0][DEBUG_SERIAL 1264 ][line1 ][ 0, 0,110] STARTED controldev_thread=3070651312 STOP=4294967294 NULL=4294967295
[Apr 8 09:03:11] DEBUG[16676]: chan_celliax.c:1276 celliax_new: rev [0x8413590|b7024bb0][DEBUG_PBX 1276 ][line1 ][ 0, 0,110] EXITING FUNC
[Apr 8 09:03:11] DEBUG[16676]: chan_celliax.c:633 celliax_request: rev [0x8413590|b7024bb0][DEBUG_PBX 633 ][line1 ][ 0, 0,110] EXITING FUNC
[Apr 8 09:03:11] DEBUG[16676]: rtp.c:1972 ast_rtp_make_compatible: Channel 'Celliax/line1' has no RTP, not doing anything
[Apr 8 09:03:11] DEBUG[16676]: channel.c:4280 ast_channel_inherit_variables: Not copying variable DIALEDTIME.
[Apr 8 09:03:11] DEBUG[16676]: channel.c:4280 ast_channel_inherit_variables: Not copying variable ANSWEREDTIME.
[Apr 8 09:03:11] DEBUG[16676]: channel.c:4280 ast_channel_inherit_variables: Not copying variable DIALEDPEERNAME.
[Apr 8 09:03:11] DEBUG[16676]: channel.c:4280 ast_channel_inherit_variables: Not copying variable DIALEDPEERNUMBER.
[Apr 8 09:03:11] DEBUG[16676]: channel.c:4280 ast_channel_inherit_variables: Not copying variable DIALSTATUS.
[Apr 8 09:03:11] DEBUG[16676]: channel.c:4280 ast_channel_inherit_variables: Not copying variable SIPCALLID.
[Apr 8 09:03:11] DEBUG[16676]: channel.c:4280 ast_channel_inherit_variables: Not copying variable SIPDOMAIN.
[Apr 8 09:03:11] DEBUG[16676]: channel.c:4280 ast_channel_inherit_variables: Not copying variable SIPURI.
[Apr 8 09:03:11] DEBUG[16676]: chan_celliax.c:1015 celliax_call: rev [0x8413590|b7024bb0][DEBUG_PBX 1015 ][line1 ][ 0, 0,110] ENTERING FUNC
[Apr 8 09:03:11] DEBUG[16676]: chan_celliax.c:1029 celliax_call: rev [0x8413590|b7024bb0][DEBUG_PBX 1029 ][line1 ][ 0, 0,110] celliax_call to call idest: line1/89274800281, timeout: 0!
[Apr 8 09:03:11] DEBUG[16676]: chan_celliax.c:1050 celliax_call: rev [0x8413590|b7024bb0][DEBUG_PBX 1050 ][line1 ][ 0, 0,110] celliax_call dialing idest: line1/89274800281, timeout: 0, dstr: 89274800281!
[Apr 8 09:03:11] DEBUG[16676]: devicestate.c:452 ast_devstate_changed_literal: Notification of state change to be queued on device/channel Celliax/line1
[Apr 8 09:03:11] DEBUG[15640]: devicestate.c:325 _ast_device_state: No provider found, checking channel drivers for Celliax - line1
[Apr 8 09:03:11] DEBUG[15640]: chan_celliax.c:507 celliax_devicestate: rev [0x8413590|b7cfabb0][DEBUG_PBX 507 ][line1 ][ 3, 0,110] Interface is OWNED by a channel
[Apr 8 09:03:11] DEBUG[15640]: devicestate.c:443 do_state_change: Changing state for Celliax/line1 - state 2 (In use)
[Apr 8 09:03:11] DEBUG[15647]: app_queue.c:772 handle_statechange: Device 'Celliax/line1' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Apr 8 09:03:11] DEBUG[16676]: celliax_additional.c:2950 celliax_serial_call_AT: rev [0x8413590|b7024bb0][DEBUG_PBX 2950 ][line1 ][ 3, 0,110] Dialing 89274800281
[Apr 8 09:03:11] DEBUG[16679]: chan_celliax.c:2536 celliax_do_controldev_thread: rev [0x8413590|b7066bb0][DEBUG_SERIAL 2536 ][line1 ][ 3, 3, 3] In celliax_do_controldev_thread: started, p=0xb721b008
[Apr 8 09:03:11] DEBUG[16676]: chan_celliax.c:1068 celliax_call: rev [0x8413590|b7024bb0][DEBUG_PBX 1068 ][line1 ][ 3, 3, 3] call ongoing
[Apr 8 09:03:11] DEBUG[16676]: chan_celliax.c:1074 celliax_call: rev [0x8413590|b7024bb0][DEBUG_PBX 1074 ][line1 ][ 3, 3, 3] celliax_call dialed idest: line1/89274800281, timeout: 0, dstr: 89274800281!
[Apr 8 09:03:11] DEBUG[16676]: chan_celliax.c:1077 celliax_call: rev [0x8413590|b7024bb0][DEBUG_PBX 1077 ][line1 ][ 3, 3, 3] EXITING FUNC
-- Called line1/89274800281
[Apr 8 09:03:11] DEBUG[16676]: channel.c:3673 set_format: Set channel Celliax/line1 to read format ulaw
[Apr 8 09:03:11] DEBUG[16676]: channel.c:3673 set_format: Set channel SIP/silver-0000009b to read format slin
[Apr 8 09:03:11] DEBUG[16676]: channel.c:3673 set_format: Set channel Celliax/line1 to write format slin
-- Celliax/line1 is ringing
[Apr 8 09:03:11] DEBUG[16676]: chan_sip.c:2728 __sip_xmit: Trying to put 'SIP/2.0 180' onto UDP socket destined for 10.1.254.100:5060
[Apr 8 09:03:11] DEBUG[16676]: chan_sip.c:9199 transmit_response_with_sdp: Setting framing from config on incoming call
[Apr 8 09:03:11] DEBUG[16676]: chan_sip.c:8875 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True Text flag: True
[Apr 8 09:03:11] DEBUG[16676]: chan_sip.c:8876 add_sdp: ** Our prefcodec: 0x0 (nothing)
[Apr 8 09:03:11] DEBUG[16676]: chan_sip.c:9008 add_sdp: -- Done with adding codecs to SDP
[Apr 8 09:03:11] DEBUG[16676]: channel.c:3043 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Apr 8 09:03:11] DEBUG[16676]: chan_sip.c:9143 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw)
[Apr 8 09:03:11] DEBUG[16676]: chan_sip.c:2728 __sip_xmit: Trying to put 'SIP/2.0 183' onto UDP socket destined for 10.1.254.100:5060
[Apr 8 09:03:11] DEBUG[16676]: rtp.c:3296 ast_rtp_write: Ooh, format changed from unknown to ulaw
[Apr 8 09:03:11] DEBUG[16676]: rtp.c:3312 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160
[Apr 8 09:03:16] DEBUG[16676]: rtp.c:1148 ast_rtcp_read: Got RTCP report of 64 bytes
[Apr 8 09:03:21] DEBUG[16676]: rtp.c:1148 ast_rtcp_read: Got RTCP report of 64 bytes
[Apr 8 09:03:26] DEBUG[16676]: rtp.c:1148 ast_rtcp_read: Got RTCP report of 64 bytes
; ===== talk still continuing. 9274800281 can't hear me. =====
P.S.: Now I use Asterisk 1.6.0.20. This is it's log.
I have been waiting 2
maybe is a problem with alsa.
SIP can hear GSM, GSM cannot hear SIP? Or the other way around?
have you downloaded the chan_celliax code from the svn as detailed in the "download" section of this website? (I don't see the revision number)
can you please enable debug_sound in the celliax config file and have another round of debugging (in the file you sent me there is no the audio debugging)? (remember to "set debug=100" on the asterisk command line)
-giovanni
Yes! SIP can hear GSM, but
Yes! SIP can hear GSM, but GSM hear only silence.
debian:~# svn info
Path: .
URL: http://svn.freeswitch.org:81/svn/freeswitch/branches/gmaruzz/mod_gsmopen...
Repository Root: http://svn.freeswitch.org:81/svn
Repository UUID: d0543943-73ff-0310-b7d9-9358b9ac24b2
Revision: 16515
Node Kind: directory
Schedule: normal
Last Changed Author: gmaruzz
Last Changed Rev: 16511
Last Changed Date: 2010-01-25 17:48:11 +0300 (Mon, 25 Jan 2010)
Ok. I'll try new version too. When the problem will appear again, then I'll will get new debug log with debug_sound. I remember about "set debug=100".
New log with the problem.
-- Executing [89274800232@mobigatersilver:1] Dial("SIP/silver-00000110", "Celliax/line1/89274800232,120,t") in new stack
[Apr 14 14:13:26] DEBUG[4350]: chan_celliax.c:572 celliax_request: rev [(nil)|b7094bb0][DEBUG_PBX 572 ][none ][-1,-1,-1] ENTERING FUNC
[Apr 14 14:13:26] DEBUG[4350]: chan_celliax.c:576 celliax_request: rev [(nil)|b7094bb0][DEBUG_PBX 576 ][none ][-1,-1,-1] Try to request type: Celliax, name: line1/89274800232, cause: 0, format: 64
[Apr 14 14:13:26] DEBUG[4350]: chan_celliax.c:601 celliax_request: rev [(nil)|b7094bb0][DEBUG_PBX 601 ][line1 ][-1, 0,110] Requesting: Celliax, name: line1/89274800232, format: 64
[Apr 14 14:13:26] DEBUG[4350]: chan_celliax.c:1147 celliax_new: rev [(nil)|b7094bb0][DEBUG_PBX 1147 ][line1 ][-1, 0,110] ENTERING FUNC
[Apr 14 14:13:26] DEBUG[4350]: celliax_additional.c:402 alsa_open_dev: rev [(nil)|b7094bb0][DEBUG_SOUND 402 ][line1 ][-1, 0,110] Acquired fd 28 from the poll descriptor
[Apr 14 14:13:26] DEBUG[4350]: celliax_additional.c:425 alsa_open_dev: rev [(nil)|b7094bb0][DEBUG_SOUND 425 ][line1 ][-1, 0,110] started!
[Apr 14 14:13:26] DEBUG[4350]: celliax_additional.c:437 alsa_open_dev: rev [(nil)|b7094bb0][DEBUG_SOUND 437 ][line1 ][-1, 0,110] ALSA handle = 138571264
[Apr 14 14:13:26] DEBUG[4350]: celliax_additional.c:402 alsa_open_dev: rev [(nil)|b7094bb0][DEBUG_SOUND 402 ][line1 ][-1, 0,110] Acquired fd 29 from the poll descriptor
[Apr 14 14:13:26] DEBUG[4350]: celliax_additional.c:437 alsa_open_dev: rev [(nil)|b7094bb0][DEBUG_SOUND 437 ][line1 ][-1, 0,110] ALSA handle = 138572992
[Apr 14 14:13:26] DEBUG[4350]: chan_celliax.c:1180 celliax_new: rev [(nil)|b7094bb0][DEBUG_PBX 1180 ][line1 ][-1, 0,110] new channel: name=Celliax/line1 requested_state=0
[Apr 14 14:13:26] DEBUG[4350]: chan_celliax.c:1264 celliax_new: rev [0x8416748|b7094bb0][DEBUG_SERIAL 1264 ][line1 ][ 0, 0,110] STARTED controldev_thread=3071163312 STOP=4294967294 NULL=4294967295
[Apr 14 14:13:26] DEBUG[4350]: chan_celliax.c:1276 celliax_new: rev [0x8416748|b7094bb0][DEBUG_PBX 1276 ][line1 ][ 0, 0,110] EXITING FUNC
[Apr 14 14:13:26] DEBUG[4350]: chan_celliax.c:633 celliax_request: rev [0x8416748|b7094bb0][DEBUG_PBX 633 ][line1 ][ 0, 0,110] EXITING FUNC
[Apr 14 14:13:26] DEBUG[4350]: rtp.c:1972 ast_rtp_make_compatible: Channel 'Celliax/line1' has no RTP, not doing anything
[Apr 14 14:13:26] DEBUG[4350]: channel.c:4280 ast_channel_inherit_variables: Not copying variable DIALEDTIME.
[Apr 14 14:13:26] DEBUG[4350]: channel.c:4280 ast_channel_inherit_variables: Not copying variable ANSWEREDTIME.
[Apr 14 14:13:26] DEBUG[4350]: channel.c:4280 ast_channel_inherit_variables: Not copying variable DIALEDPEERNAME.
[Apr 14 14:13:26] DEBUG[4350]: channel.c:4280 ast_channel_inherit_variables: Not copying variable DIALEDPEERNUMBER.
[Apr 14 14:13:26] DEBUG[4350]: channel.c:4280 ast_channel_inherit_variables: Not copying variable DIALSTATUS.
[Apr 14 14:13:26] DEBUG[4350]: channel.c:4280 ast_channel_inherit_variables: Not copying variable SIPCALLID.
[Apr 14 14:13:26] DEBUG[4350]: channel.c:4280 ast_channel_inherit_variables: Not copying variable SIPDOMAIN.
[Apr 14 14:13:26] DEBUG[4350]: channel.c:4280 ast_channel_inherit_variables: Not copying variable SIPURI.
[Apr 14 14:13:26] DEBUG[4350]: chan_celliax.c:1015 celliax_call: rev [0x8416748|b7094bb0][DEBUG_PBX 1015 ][line1 ][ 0, 0,110] ENTERING FUNC
[Apr 14 14:13:26] DEBUG[4350]: chan_celliax.c:1029 celliax_call: rev [0x8416748|b7094bb0][DEBUG_PBX 1029 ][line1 ][ 0, 0,110] celliax_call to call idest: line1/89274800232, timeout: 0!
[Apr 14 14:13:26] DEBUG[4350]: chan_celliax.c:1050 celliax_call: rev [0x8416748|b7094bb0][DEBUG_PBX 1050 ][line1 ][ 0, 0,110] celliax_call dialing idest: line1/89274800232, timeout: 0, dstr: 89274800232!
[Apr 14 14:13:26] DEBUG[4350]: devicestate.c:452 ast_devstate_changed_literal: Notification of state change to be queued on device/channel Celliax/line1
[Apr 14 14:13:26] DEBUG[2615]: devicestate.c:325 _ast_device_state: No provider found, checking channel drivers for Celliax - line1
[Apr 14 14:13:26] DEBUG[2615]: chan_celliax.c:507 celliax_devicestate: rev [0x8416748|b7cf0bb0][DEBUG_PBX 507 ][line1 ][ 3, 0,110] Interface is OWNED by a channel
[Apr 14 14:13:26] DEBUG[2615]: devicestate.c:443 do_state_change: Changing state for Celliax/line1 - state 2 (In use)
[Apr 14 14:13:26] DEBUG[2622]: app_queue.c:772 handle_statechange: Device 'Celliax/line1' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Apr 14 14:13:26] DEBUG[4350]: celliax_additional.c:2950 celliax_serial_call_AT: rev [0x8416748|b7094bb0][DEBUG_PBX 2950 ][line1 ][ 3, 0,110] Dialing 89274800232
[Apr 14 14:13:26] DEBUG[4353]: chan_celliax.c:2536 celliax_do_controldev_thread: rev [0x8416748|b70e3bb0][DEBUG_SERIAL 2536 ][line1 ][ 3, 3, 3] In celliax_do_controldev_thread: started, p=0xb7211008
[Apr 14 14:13:26] DEBUG[4350]: chan_celliax.c:1068 celliax_call: rev [0x8416748|b7094bb0][DEBUG_PBX 1068 ][line1 ][ 3, 3, 3] call ongoing
[Apr 14 14:13:26] DEBUG[4350]: chan_celliax.c:1074 celliax_call: rev [0x8416748|b7094bb0][DEBUG_PBX 1074 ][line1 ][ 3, 3, 3] celliax_call dialed idest: line1/89274800232, timeout: 0, dstr: 89274800232!
[Apr 14 14:13:26] DEBUG[4350]: chan_celliax.c:1077 celliax_call: rev [0x8416748|b7094bb0][DEBUG_PBX 1077 ][line1 ][ 3, 3, 3] EXITING FUNC
-- Called line1/89274800232
[Apr 14 14:13:26] DEBUG[4350]: channel.c:3673 set_format: Set channel Celliax/line1 to read format ulaw
[Apr 14 14:13:26] DEBUG[4350]: channel.c:3673 set_format: Set channel SIP/silver-00000110 to read format slin
[Apr 14 14:13:26] DEBUG[4350]: channel.c:3673 set_format: Set channel Celliax/line1 to write format slin
-- Celliax/line1 is ringing
[Apr 14 14:13:26] DEBUG[4350]: chan_sip.c:2728 __sip_xmit: Trying to put 'SIP/2.0 180' onto UDP socket destined for 10.1.254.100:5060
[Apr 14 14:13:26] DEBUG[4350]: chan_sip.c:9199 transmit_response_with_sdp: Setting framing from config on incoming call
[Apr 14 14:13:26] DEBUG[4350]: chan_sip.c:8875 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True Text flag: True
[Apr 14 14:13:26] DEBUG[4350]: chan_sip.c:8876 add_sdp: ** Our prefcodec: 0x0 (nothing)
[Apr 14 14:13:26] DEBUG[4350]: chan_sip.c:9008 add_sdp: -- Done with adding codecs to SDP
[Apr 14 14:13:26] DEBUG[4350]: channel.c:3043 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Apr 14 14:13:26] DEBUG[4350]: chan_sip.c:9143 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw)
[Apr 14 14:13:26] DEBUG[4350]: chan_sip.c:2728 __sip_xmit: Trying to put 'SIP/2.0 183' onto UDP socket destined for 10.1.254.100:5060
[Apr 14 14:13:26] DEBUG[4350]: rtp.c:3296 ast_rtp_write: Ooh, format changed from unknown to ulaw
[Apr 14 14:13:26] DEBUG[4350]: rtp.c:3312 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160
[Apr 14 14:13:31] DEBUG[4350]: rtp.c:1148 ast_rtcp_read: Got RTCP report of 64 bytes
; ========= DIALING..... =========
[Apr 14 14:13:36] DEBUG[4350]: rtp.c:1148 ast_rtcp_read: Got RTCP report of 64 bytes
; ========= 9274800232 ANSWERED, BUT DON'T HEAR ME ==========
[Apr 14 14:13:41] DEBUG[4350]: rtp.c:1148 ast_rtcp_read: Got RTCP report of 64 bytes
; ========= 9274800232 IS HANGING UP ============
[Apr 14 14:13:45] DEBUG[4353]: chan_celliax.c:464 celliax_queue_control: rev [0x8416748|b70e3bb0][DEBUG_PBX 464 ][line1 ][ 3, 3,102] Queued CONTROL FRAME 1
[Apr 14 14:13:45] DEBUG[4350]: chan_celliax.c:919 celliax_read: rev [0x8416748|b7094bb0][DEBUG_PBX 919 ][line1 ][ 3, 3,102] Sent CONTROL FRAME 1
[Apr 14 14:13:45] DEBUG[4350]: channel.c:1721 ast_hangup: Hanging up channel 'Celliax/line1'
[Apr 14 14:13:45] DEBUG[4350]: chan_celliax.c:656 celliax_hangup: rev [0x8416748|b7094bb0][DEBUG_PBX 656 ][line1 ][ 3, 3,102] ENTERING FUNC
[Apr 14 14:13:45] DEBUG[4353]: chan_celliax.c:441 celliax_unlocka_log: [b70e3bb0] I'm a dying thread, and I'm to go unlocking mutex 0xb7292358 for the 0th time
[Apr 14 14:13:45] DEBUG[4353]: chan_celliax.c:441 celliax_unlocka_log: [b70e3bb0] I'm a dying thread, and I'm to go unlocking mutex 0xb7292358 for the 1th time
[Apr 14 14:13:45] DEBUG[4353]: chan_celliax.c:441 celliax_unlocka_log: [b70e3bb0] I'm a dying thread, and I'm to go unlocking mutex 0xb7292358 for the 2th time
[Apr 14 14:13:45] DEBUG[4353]: chan_celliax.c:441 celliax_unlocka_log: [b70e3bb0] I'm a dying thread, and I'm to go unlocking mutex 0xb7292358 for the 3th time
[Apr 14 14:13:45] DEBUG[4353]: chan_celliax.c:441 celliax_unlocka_log: [b70e3bb0] I'm a dying thread, and I'm to go unlocking mutex 0xb7292358 for the 4th time
[Apr 14 14:13:45] DEBUG[4353]: chan_celliax.c:448 celliax_unlocka_log: [b70e3bb0] I'm a dying thread, I've finished unlocking mutex 0xb7292358
[Apr 14 14:13:45] DEBUG[4350]: chan_celliax.c:704 celliax_hangup: rev [0x8416748|b7094bb0][DEBUG_SERIAL 704 ][line1 ][ 3, 0, 0] call hungup
[Apr 14 14:13:45] DEBUG[4350]: chan_celliax.c:726 celliax_hangup: rev [0x8416748|b7094bb0][DEBUG_SOUND 726 ][line1 ][ 3, 0, 0] shutting down sound
[Apr 14 14:13:45] DEBUG[4350]: chan_celliax.c:2686 celliax_serial_init: rev [0x8416748|b7094bb0][DEBUG_SERIAL 2686 ][line1 ][ 3, 0, 0] Syncing Serial
[Apr 14 14:13:45] DEBUG[4350]: devicestate.c:452 ast_devstate_changed_literal: Notification of state change to be queued on device/channel Celliax/line1
[Apr 14 14:13:45] DEBUG[4350]: chan_celliax.c:777 celliax_hangup: rev [(nil)|b7094bb0][DEBUG_PBX 777 ][line1 ][-1, 0, 0] Hanged Up
[Apr 14 14:13:45] DEBUG[4350]: chan_celliax.c:788 celliax_hangup: rev [(nil)|b7094bb0][DEBUG_PBX 788 ][line1 ][-1, 0, 0] EXITING FUNC
[Apr 14 14:13:45] DEBUG[4350]: devicestate.c:452 ast_devstate_changed_literal: Notification of state change to be queued on device/channel Celliax/line1
== Everyone is busy/congested at this time (1:0/0/1)
[Apr 14 14:13:45] DEBUG[4350]: rtp.c:1898 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything
[Apr 14 14:13:45] DEBUG[4350]: app_dial.c:2060 dial_exec_full: Exiting with DIALSTATUS=CHANUNAVAIL.
-- Auto fallthrough, channel 'SIP/silver-00000110' status is 'CHANUNAVAIL'
[Apr 14 14:13:45] DEBUG[4350]: chan_sip.c:2728 __sip_xmit: Trying to put 'SIP/2.0 503' onto UDP socket destined for 10.1.254.100:5060
[Apr 14 14:13:45] DEBUG[4350]: chan_sip.c:2462 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 70ac81e80f51376379f6ab694a4824fe@10.1.254.100
[Apr 14 14:13:45] DEBUG[4350]: channel.c:1618 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/silver-00000110'
[Apr 14 14:13:45] DEBUG[4350]: devicestate.c:452 ast_devstate_changed_literal: Notification of state change to be queued on device/channel SIP/silver
[Apr 14 14:13:45] DEBUG[4350]: channel.c:1618 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/silver-00000110'
[Apr 14 14:13:45] DEBUG[4350]: channel.c:1721 ast_hangup: Hanging up channel 'SIP/silver-00000110'
[Apr 14 14:13:45] DEBUG[4350]: chan_sip.c:5139 sip_hangup: Hangup call SIP/silver-00000110, SIP callid 70ac81e80f51376379f6ab694a4824fe@10.1.254.100
[Apr 14 14:13:45] DEBUG[4350]: devicestate.c:452 ast_devstate_changed_literal: Notification of state change to be queued on device/channel SIP/silver
[Apr 14 14:13:45] DEBUG[2615]: devicestate.c:325 _ast_device_state: No provider found, checking channel drivers for Celliax - line1
[Apr 14 14:13:45] DEBUG[2615]: chan_celliax.c:503 celliax_devicestate: rev [(nil)|b7cf0bb0][DEBUG_PBX 503 ][line1 ][-1, 0, 0] Interface is NOT OWNED by a channel
[Apr 14 14:13:45] DEBUG[2615]: devicestate.c:443 do_state_change: Changing state for Celliax/line1 - state 1 (Not in use)
[Apr 14 14:13:45] DEBUG[2615]: devicestate.c:325 _ast_device_state: No provider found, checking channel drivers for Celliax - line1
[Apr 14 14:13:45] DEBUG[2615]: chan_celliax.c:503 celliax_devicestate: rev [(nil)|b7cf0bb0][DEBUG_PBX 503 ][line1 ][-1, 0, 0] Interface is NOT OWNED by a channel
[Apr 14 14:13:45] DEBUG[2615]: devicestate.c:443 do_state_change: Changing state for Celliax/line1 - state 1 (Not in use)
[Apr 14 14:13:45] DEBUG[2615]: devicestate.c:325 _ast_device_state: No provider found, checking channel drivers for SIP - silver
[Apr 14 14:13:45] DEBUG[2615]: chan_sip.c:20720 sip_devicestate: Checking device state for peer silver
[Apr 14 14:13:45] DEBUG[2615]: devicestate.c:443 do_state_change: Changing state for SIP/silver - state 1 (Not in use)
[Apr 14 14:13:45] DEBUG[2615]: devicestate.c:325 _ast_device_state: No provider found, checking channel drivers for SIP - silver
[Apr 14 14:13:45] DEBUG[2615]: chan_sip.c:20720 sip_devicestate: Checking device state for peer silver
[Apr 14 14:13:45] DEBUG[2615]: devicestate.c:443 do_state_change: Changing state for SIP/silver - state 1 (Not in use)
[Apr 14 14:13:45] DEBUG[2621]: chan_sip.c:6433 find_call: = Found Their Call ID: 70ac81e80f51376379f6ab694a4824fe@10.1.254.100 Their Tag as29395615 Our tag: as10f258fe
[Apr 14 14:13:45] DEBUG[2621]: chan_sip.c:19451 handle_incoming: **** Received ACK (6) - Command in SIP ACK
[Apr 14 14:13:45] DEBUG[2621]: chan_sip.c:3250 __sip_ack: Stopping retransmission on '70ac81e80f51376379f6ab694a4824fe@10.1.254.100' of Response 103: Match Found
[Apr 14 14:13:45] DEBUG[2621]: chan_sip.c:4927 sip_destroy: Destroying SIP dialog 70ac81e80f51376379f6ab694a4824fe@10.1.254.100
[Apr 14 14:13:45] DEBUG[2622]: app_queue.c:772 handle_statechange: Device 'Celliax/line1' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Apr 14 14:13:45] DEBUG[2622]: app_queue.c:772 handle_statechange: Device 'Celliax/line1' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Apr 14 14:13:45] DEBUG[2622]: app_queue.c:772 handle_statechange: Device 'SIP/silver' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Apr 14 14:13:45] DEBUG[2622]: app_queue.c:772 handle_statechange: Device 'SIP/silver' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
new log 2
Ciao farfor,
sorry to answer so late, it's slipped by.
The log you pasted here does not contains the info for debugging.
Please follow the instruction at http://www.gsmopen.org/howtobug , particularly:
"
Edit logger.conf and modify the last lines to be (without quotation marks): "console => notice,warning,error,debug" "full => notice,warning,error,debug,verbose" Start Asterisk, and from the CLI (without quotation marks): "set debug 100" "load chan_celliax.so" then replicate your problem. Please include all the output
"
Also, be sure that you have activated debug for audio, at_commands, pbx, etc in the celliax config file (celliax.conf). Please do not activate debug for locks or the "debug all".
-giovanni
Another try
logger.conf - is correct. In celliax.conf I was added debug for AT commands. Other "debugs" in celliax.conf already was activated.
But result is the same: in debug log nothing appears during answer.
And when the problem not persist, there are many lines in debug log during answer moment.
another try 2
Please, post somewhere a much longer debug log, from another run. Best would be a couple of minutes before and after.
Also, writing me at what time the problem shows up.
Unfortunately from the little you sent I cannot understand where the problem is.
Maybe an hardware problem?
How you recover from it? (I mean: you have to reboot, or you just restart asterisk?)