ARM, chan_mobile no audio

Asterisk Asterisk Support
1

Hi folks,

I installed asterisk from trunk (rev 169720) and addons from trunk (rev 732) on a CentOS server:
Linux XXXXXX 2.6.9-78.ELsmp #1 SMP Fri Jul 25 00:04:28 EDT 2008 i686 i686 i386 GNU/Linux
and bluez 2.10-3 and use bluetooth dongle (Integrated System Solution Corp. KY-BT100 Bluetooth Adapter) and the cellphone is a NOKIA 5310

It works very well.

Now I’m trying to reproduce this setup in a embedded system (ARM)
I installed asterisk 1.6.1.0, asterisk addons 1.6.1.0, bluez 4.32 and the OS is a Ubuntu 9.05:
Linux XXXXXX 2.6.22.18 #1 Thu Mar 19 14:46:22 IST 2009 armv5tejl GNU/Linux

Everything works perfect accept the audio. I can hear no sound on both directions.

I enabled the asterisk logs and saw that the mbl_write/read functions are not called (chan_mobile.c). Here is the output:

[May 19 17:41:33] VERBOSE[12276] asterisk.c:     -- Remote UNIX connection
[May 19 17:41:46] DEBUG[12294] chan_mobile.c: connect() failed (111).
[May 19 17:42:15] DEBUG[12303] chan_sip.c: Allocating new SIP dialog for 579ad3c451701c9408695e2b102caf16@192.168.0.121 - OPTIONS (No RTP)
[May 19 17:42:15] DEBUG[12303] chan_sip.c: Initializing initreq for method OPTIONS - callid 60528ba72534acb52a49bb9f0fac94b7@192.168.0.121
[May 19 17:42:15] DEBUG[12303] chan_sip.c: Trying to put 'OPTIONS si' onto UDP socket destined for 192.168.0.61:35240
[May 19 17:42:15] DEBUG[12303] chan_sip.c: Stopping retransmission on '60528ba72534acb52a49bb9f0fac94b7@192.168.0.121' of Request 102: Match Found
[May 19 17:42:21] VERBOSE[12294] chan_mobile.c:     -- Bluetooth Device Seste has connected.
[May 19 17:42:21] DEBUG[12317] chan_mobile.c: rfcomm_write() (Seste) [AT+BRSF=4]
[May 19 17:42:21] DEBUG[12318] chan_mobile.c: About to accept() socket.
[May 19 17:42:21] DEBUG[12317] chan_mobile.c: rfcomm_read() (Seste) [+BRSF: 495]
[May 19 17:42:21] DEBUG[12317] chan_mobile.c: rfcomm_read() (Seste) [OK]
[May 19 17:42:21] DEBUG[12317] chan_mobile.c: rfcomm_write() (Seste) [AT+CIND=?]
[May 19 17:42:22] DEBUG[12317] chan_mobile.c: rfcomm_read() (Seste) [+CIND: ("call",(0,1)),("service",(0,1)),("call_setup",(0-3)),("callsetup",(0-3)),("callheld",(0-2)),("battchg",(0-5)),("roam",(0,1)),("signal",(0-5))]
[May 19 17:42:22] DEBUG[12317] chan_mobile.c: CIEV_CALL=1 CIEV_CALLSETUP=4
[May 19 17:42:22] DEBUG[12317] chan_mobile.c: rfcomm_read() (Seste) [OK]
[May 19 17:42:22] DEBUG[12317] chan_mobile.c: rfcomm_write() (Seste) [AT+CIND?]
[May 19 17:42:22] DEBUG[12317] chan_mobile.c: rfcomm_read() (Seste) [+CIND: 0,1,0,0,0,1,0,5]
[May 19 17:42:22] DEBUG[12317] chan_mobile.c: rfcomm_read() (Seste) [OK]
[May 19 17:42:22] DEBUG[12317] chan_mobile.c: rfcomm_write() (Seste) [AT+CMER=3,0,0,1]
[May 19 17:42:22] DEBUG[12317] chan_mobile.c: rfcomm_read() (Seste) [OK]
[May 19 17:42:22] DEBUG[12317] chan_mobile.c: rfcomm_write() (Seste) [AT+CLIP=1]
[May 19 17:42:22] DEBUG[12317] chan_mobile.c: rfcomm_read() (Seste) [OK]
[May 19 17:42:22] DEBUG[12317] chan_mobile.c: rfcomm_write() (Seste) [AT+VGS=15]
[May 19 17:42:22] DEBUG[12317] chan_mobile.c: rfcomm_read() (Seste) [OK]
[May 19 17:42:22] DEBUG[12317] chan_mobile.c: rfcomm_write() (Seste) [AT+CMGF=1]
[May 19 17:42:22] DEBUG[12317] chan_mobile.c: rfcomm_read() (Seste) [OK]
[May 19 17:42:22] DEBUG[12317] chan_mobile.c: rfcomm_write() (Seste) [AT+CNMI=2,1,0,1,0]
[May 19 17:42:22] DEBUG[12317] chan_mobile.c: rfcomm_read() (Seste) [ERROR]
[May 19 17:42:23] VERBOSE[12317] chan_mobile.c:     -- Bluetooth Device Seste initialised and ready.
[May 19 17:42:30] DEBUG[12303] chan_sip.c: Allocating new SIP dialog for ZDBkZWNjN2E4NjllMzA2YzlhOWU0MTBmOTQxZDYyZTM. - SUBSCRIBE (No RTP)
[May 19 17:42:30] DEBUG[12303] chan_sip.c: Trying to put 'SIP/2.0 48' onto UDP socket destined for 192.168.0.61:35240
[May 19 17:42:35] DEBUG[12303] chan_sip.c: Allocating new SIP dialog for MDQ1OTEwOGU3NjI1MTVhYTA2ODNhODAxMmZiYmRiMDE. - SUBSCRIBE (No RTP)
[May 19 17:42:35] DEBUG[12303] chan_sip.c: Trying to put 'SIP/2.0 40' onto UDP socket destined for 192.168.0.61:35240
[May 19 17:42:35] DEBUG[12303] chan_sip.c: Trying to put 'SIP/2.0 20' onto UDP socket destined for 192.168.0.61:35240
[May 19 17:42:35] DEBUG[12303] chan_sip.c: Trying to put 'NOTIFY sip' onto UDP socket destined for 192.168.0.61:35240
[May 19 17:42:36] DEBUG[12303] chan_sip.c: Stopping retransmission on 'MDQ1OTEwOGU3NjI1MTVhYTA2ODNhODAxMmZiYmRiMDE.' of Request 102: Match Found
[May 19 17:43:16] DEBUG[12303] chan_sip.c: Allocating new SIP dialog for 5077205d448e35ca6baeb1220086f269@192.168.0.121 - OPTIONS (No RTP)
[May 19 17:43:16] DEBUG[12303] chan_sip.c: Initializing initreq for method OPTIONS - callid 48f0a8d56e1ceb0a135d77ae3435a9f5@192.168.0.121
[May 19 17:43:16] DEBUG[12303] chan_sip.c: Trying to put 'OPTIONS si' onto UDP socket destined for 192.168.0.61:35240
[May 19 17:43:16] DEBUG[12303] chan_sip.c: Stopping retransmission on '48f0a8d56e1ceb0a135d77ae3435a9f5@192.168.0.121' of Request 102: Match Found
[May 19 17:43:32] DEBUG[12317] chan_mobile.c: rfcomm_read() (Seste) [+CIEV: 3,1]
[May 19 17:43:32] DEBUG[12317] chan_mobile.c: Device Seste [+CIEV: 3,1]
[May 19 17:43:32] DEBUG[12317] chan_mobile.c: rfcomm_read() (Seste) [+CIEV: 4,1]
[May 19 17:43:32] DEBUG[12317] chan_mobile.c: Device Seste [+CIEV: 4,1]
[May 19 17:43:33] DEBUG[12317] chan_mobile.c: rfcomm_read() (Seste) [RING]
[May 19 17:43:33] DEBUG[12317] chan_mobile.c: Device Seste [RING]
[May 19 17:43:33] DEBUG[12317] chan_mobile.c: rfcomm_read() (Seste) [+CLIP: "01937079590",161]
[May 19 17:43:33] DEBUG[12322] pbx.c: Launching 'Set'
[May 19 17:43:33] VERBOSE[12322] pbx.c:     -- Executing [s@incoming-mobile:1] Set("Mobile/Seste-43c2", "CHANNEL(language)=br") in new stack
[May 19 17:43:33] DEBUG[12322] pbx.c: Launching 'Set'
[May 19 17:43:33] VERBOSE[12322] pbx.c:     -- Executing [s@incoming-mobile:2] Set("Mobile/Seste-43c2", "CALLERID(name)=unknown") in new stack
[May 19 17:43:33] DEBUG[12322] pbx.c: Launching 'Dial'
[May 19 17:43:33] VERBOSE[12322] pbx.c:     -- Executing [s@incoming-mobile:3] Dial("Mobile/Seste-43c2", "SIP/1000&SIP/2000,30") in new stack
[May 19 17:43:33] DEBUG[12322] chan_sip.c: Asked to create a SIP channel with formats: 0x40 (slin)
[May 19 17:43:33] VERBOSE[12322] netsock.c:   == Using SIP RTP CoS mark 5
[May 19 17:43:33] DEBUG[12322] chan_sip.c: Allocating new SIP dialog for 490721bf71088ec33a955b664efbda99@192.168.0.121 - INVITE (With RTP)
[May 19 17:43:33] DEBUG[12322] chan_sip.c: Setting NAT on RTP to Off
[May 19 17:43:33] WARNING[12322] chan_sip.c: No such host: 1000
[May 19 17:43:33] WARNING[12322] app_dial.c: Unable to create channel of type 'SIP' (cause 20 - Unknown)
[May 19 17:43:33] DEBUG[12322] chan_sip.c: Asked to create a SIP channel with formats: 0x40 (slin)
[May 19 17:43:33] VERBOSE[12322] netsock.c:   == Using SIP RTP CoS mark 5
[May 19 17:43:33] DEBUG[12322] chan_sip.c: Allocating new SIP dialog for 661b5a5911754f4d4fa04e5f04b0f9e1@192.168.0.121 - INVITE (With RTP)
[May 19 17:43:33] DEBUG[12322] chan_sip.c: Setting NAT on RTP to Off
[May 19 17:43:33] DEBUG[12322] rtp.c: Channel 'Mobile/Seste-43c2' has no RTP, not doing anything
[May 19 17:43:33] DEBUG[12322] channel.c: Not copying variable DIALEDTIME.
[May 19 17:43:33] DEBUG[12322] channel.c: Not copying variable ANSWEREDTIME.
[May 19 17:43:33] DEBUG[12322] channel.c: Not copying variable DIALEDPEERNAME.
[May 19 17:43:33] DEBUG[12322] channel.c: Not copying variable DIALEDPEERNUMBER.
[May 19 17:43:33] DEBUG[12322] channel.c: Not copying variable DIALSTATUS.
[May 19 17:43:33] DEBUG[12322] chan_sip.c: Outgoing Call for 2000
[May 19 17:43:33] DEBUG[12322] chan_sip.c: ** Our capability: 0xe (gsm|ulaw|alaw) Video flag: False Text flag: False
[May 19 17:43:33] DEBUG[12322] chan_sip.c: ** Our prefcodec: 0x40 (slin) 
[May 19 17:43:33] DEBUG[12322] chan_sip.c: Initializing initreq for method INVITE - callid 1e8eac432d52cf8a66388f5f2c1e4382@192.168.0.121
[May 19 17:43:33] DEBUG[12322] chan_sip.c: Trying to put 'INVITE sip' onto UDP socket destined for 192.168.0.61:35240
[May 19 17:43:33] VERBOSE[12322] app_dial.c:     -- Called 2000
[May 19 17:43:33] DEBUG[12303] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '1e8eac432d52cf8a66388f5f2c1e4382@192.168.0.121' Request 102: Found
[May 19 17:43:33] VERBOSE[12322] app_dial.c:     -- SIP/2000-00208840 is ringing
[May 19 17:43:33] DEBUG[12322] channel.c: Driver for channel 'Mobile/Seste-43c2' does not support indication 3, emulating it
[May 19 17:43:33] DEBUG[12322] channel.c: Prodding channel 'Mobile/Seste-43c2'
[May 19 17:43:33] DEBUG[12322] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[May 19 17:43:37] DEBUG[12317] chan_mobile.c: rfcomm_read() (Seste) [RING]
[May 19 17:43:37] DEBUG[12317] chan_mobile.c: rfcomm_read() (Seste) [+CLIP: "01937079590",161]
[May 19 17:43:42] DEBUG[12322] rtp.c: Got RTCP report of 132 bytes
[May 19 17:43:42] DEBUG[12322] chan_sip.c: Oooh, format changed to 4 ulaw
[May 19 17:43:42] DEBUG[12322] channel.c: Set channel SIP/2000-00208840 to read format slin
[May 19 17:43:42] DEBUG[12322] channel.c: Set channel SIP/2000-00208840 to write format slin
[May 19 17:43:42] DEBUG[12303] chan_sip.c: Acked pending invite 102
[May 19 17:43:42] DEBUG[12303] chan_sip.c: Stopping retransmission on '1e8eac432d52cf8a66388f5f2c1e4382@192.168.0.121' of Request 102: Match Found
[May 19 17:43:42] DEBUG[12303] chan_sip.c: Trying to put 'ACK sip:20' onto UDP socket destined for 192.168.0.61:35240
[May 19 17:43:42] DEBUG[12303] chan_sip.c: Trying to put 'SIP/2.0 50' onto UDP socket destined for 192.168.0.61:35240
[May 19 17:43:42] DEBUG[12303] chan_sip.c: Invalid SIP message - rejected , no callid, len 1028
[May 19 17:43:42] VERBOSE[12322] app_dial.c:     -- SIP/2000-00208840 answered Mobile/Seste-43c2
[May 19 17:43:42] DEBUG[12322] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[May 19 17:43:42] DEBUG[12322] chan_mobile.c: rfcomm_write() (Seste) [ATA]
[May 19 17:43:42] DEBUG[12278] chan_mobile.c: Checking device state for device Seste
[May 19 17:43:42] DEBUG[12317] chan_mobile.c: rfcomm_read() (Seste) [OK]
[May 19 17:43:42] DEBUG[12317] chan_mobile.c: rfcomm_read() (Seste) [+CIEV: 1,1]
[May 19 17:43:42] DEBUG[12317] chan_mobile.c: rfcomm_read() (Seste) [+CIEV: 3,0]
[May 19 17:43:42] DEBUG[12317] chan_mobile.c: rfcomm_read() (Seste) [+CIEV: 4,0]
[May 19 17:43:42] DEBUG[12318] chan_mobile.c: accept()ed socket.
[May 19 17:43:42] DEBUG[12318] chan_mobile.c: Incoming Audio Connection from device 00:1D:FD:E4:42:FF MTU is 64
[May 19 17:43:42] DEBUG[12318] chan_mobile.c: About to accept() socket.
[May 19 17:43:52] DEBUG[12317] chan_mobile.c: rfcomm_read() (Seste) [+CIEV: 8,4]
[May 19 17:44:01] DEBUG[12317] chan_mobile.c: rfcomm_read() (Seste) [+CIEV: 8,5]
[May 19 17:44:16] DEBUG[12303] chan_sip.c: Allocating new SIP dialog for 79ecbf0b7e04d89803d580d1518761df@192.168.0.121 - OPTIONS (No RTP)
[May 19 17:44:16] DEBUG[12303] chan_sip.c: Initializing initreq for method OPTIONS - callid 44aeb4be06cdcae05f0f758f7acfea90@192.168.0.121
[May 19 17:44:16] DEBUG[12303] chan_sip.c: Trying to put 'OPTIONS si' onto UDP socket destined for 192.168.0.61:35240
[May 19 17:44:16] DEBUG[12303] chan_sip.c: Stopping retransmission on '44aeb4be06cdcae05f0f758f7acfea90@192.168.0.121' of Request 102: Match Found
[May 19 17:44:17] DEBUG[12317] chan_mobile.c: rfcomm_read() (Seste) [+CIEV: 8,4]
[May 19 17:44:28] DEBUG[12317] chan_mobile.c: rfcomm_read() (Seste) [NO CARRIER]
[May 19 17:44:28] DEBUG[12317] chan_mobile.c: rfcomm_read() (Seste) [+CIEV: 1,0]
[May 19 17:44:33] DEBUG[12317] chan_mobile.c: rfcomm_read() (Seste) [+CIEV: 8,5]
[May 19 17:44:33] DEBUG[12303] chan_sip.c: Trying to put 'SIP/2.0 20' onto UDP socket destined for 192.168.0.61:35240
[May 19 17:44:33] DEBUG[12303] chan_sip.c: Trying to put 'SIP/2.0 50' onto UDP socket destined for 192.168.0.61:35240
[May 19 17:44:33] DEBUG[12303] chan_sip.c: Invalid SIP message - rejected , no callid, len 992
[May 19 17:44:33] DEBUG[12303] chan_sip.c: Trying to put 'SIP/2.0 20' onto UDP socket destined for 192.168.0.61:35240
[May 19 17:44:33] DEBUG[12303] chan_sip.c: Trying to put 'SIP/2.0 50' onto UDP socket destined for 192.168.0.61:35240
[May 19 17:44:33] DEBUG[12303] chan_sip.c: Invalid SIP message - rejected , no callid, len 992
[May 19 17:44:33] DEBUG[12303] chan_sip.c: Trying to put 'SIP/2.0 20' onto UDP socket destined for 192.168.0.61:35240
[May 19 17:44:33] DEBUG[12303] chan_sip.c: Trying to put 'SIP/2.0 50' onto UDP socket destined for 192.168.0.61:35240
[May 19 17:44:33] DEBUG[12303] chan_sip.c: Invalid SIP message - rejected , no callid, len 992
[May 19 17:44:33] DEBUG[12303] chan_sip.c: Trying to put 'SIP/2.0 20' onto UDP socket destined for 192.168.0.61:35240
[May 19 17:44:33] DEBUG[12303] chan_sip.c: Trying to put 'SIP/2.0 50' onto UDP socket destined for 192.168.0.61:35240
[May 19 17:44:33] DEBUG[12303] chan_sip.c: Invalid SIP message - rejected , no callid, len 992
[May 19 17:44:33] DEBUG[12322] channel.c: Didn't get a frame from channel: SIP/2000-00208840
[May 19 17:44:33] DEBUG[12322] channel.c: Bridge stops bridging channels Mobile/Seste-43c2 and SIP/2000-00208840
[May 19 17:44:33] DEBUG[12322] channel.c: Hanging up channel 'SIP/2000-00208840'
[May 19 17:44:33] DEBUG[12322] chan_sip.c: Hangup call SIP/2000-00208840, SIP callid 1e8eac432d52cf8a66388f5f2c1e4382@192.168.0.121
[May 19 17:44:33] DEBUG[12322] app_dial.c: Exiting with DIALSTATUS=ANSWER.
[May 19 17:44:33] DEBUG[12322] pbx.c: Spawn extension (incoming-mobile,s,3) exited non-zero on 'Mobile/Seste-43c2'
[May 19 17:44:33] VERBOSE[12322] pbx.c:   == Spawn extension (incoming-mobile, s, 3) exited non-zero on 'Mobile/Seste-43c2'
[May 19 17:44:33] DEBUG[12322] channel.c: Soft-Hanging up channel 'Mobile/Seste-43c2'
[May 19 17:44:33] DEBUG[12322] channel.c: Hanging up channel 'Mobile/Seste-43c2'
[May 19 17:44:33] DEBUG[12322] chan_mobile.c: Hanging up device Seste.
[May 19 17:44:33] DEBUG[12278] chan_mobile.c: Checking device state for device Seste
[May 19 17:44:33] DEBUG[12278] chan_mobile.c: Checking device state for device Seste
[May 19 17:45:16] DEBUG[12303] chan_sip.c: Allocating new SIP dialog for 0038ba4a1f9d6d875010e44e3eb07ddd@192.168.0.121 - OPTIONS (No RTP)
[May 19 17:45:16] DEBUG[12303] chan_sip.c: Initializing initreq for method OPTIONS - callid 2f310a92212bb7a54ae80f1b6fc0cf27@192.168.0.121
[May 19 17:45:16] DEBUG[12303] chan_sip.c: Trying to put 'OPTIONS si' onto UDP socket destined for 192.168.0.61:35240
[May 19 17:45:16] DEBUG[12303] chan_sip.c: Stopping retransmission on '2f310a92212bb7a54ae80f1b6fc0cf27@192.168.0.121' of Request 102: Match Found
[May 19 17:46:16] DEBUG[12303] chan_sip.c: Allocating new SIP dialog for 75547e4f219114db486f54800e333068@192.168.0.121 - OPTIONS (No RTP)
[May 19 17:46:16] DEBUG[12303] chan_sip.c: Initializing initreq for method OPTIONS - callid 1868d9ae2c7ea9872b40330f1af93a12@192.168.0.121
[May 19 17:46:16] DEBUG[12303] chan_sip.c: Trying to put 'OPTIONS si' onto UDP socket destined for 192.168.0.61:35240
[May 19 17:46:16] DEBUG[12303] chan_sip.c: Stopping retransmission on '1868d9ae2c7ea9872b40330f1af93a12@192.168.0.121' of Request 102: Match Found

I made a dump of the bluetooth package using hcidump:

root@debian:/etc/bluetooth# hcidump
HCI sniffer - Bluetooth packet analyzer ver 1.42
device: hci0 snap_len: 1028 filter: 0xffffffff
< ACL data: handle 42 flags 0x02 dlen 25
    L2CAP(d): cid 0x0040 len 21 [psm 0]
> HCI Event: Number of Completed Packets (0x13) plen 5
> ACL data: handle 42 flags 0x02 dlen 15
    L2CAP(d): cid 0x0040 len 11 [psm 0]
> ACL data: handle 42 flags 0x02 dlen 36
    L2CAP(d): cid 0x0040 len 32 [psm 0]
> HCI Event: Encrypt Change (0x08) plen 4
> HCI Event: Page Scan Repetition Mode Change (0x20) plen 7
> HCI Event: Role Change (0x12) plen 8
> HCI Event: Max Slots Change (0x1b) plen 3
> HCI Event: Encrypt Change (0x08) plen 4
> ACL data: handle 42 flags 0x02 dlen 36
    L2CAP(d): cid 0x0040 len 32 [psm 0]
> HCI Event: Connect Request (0x04) plen 10
< HCI Command: Accept Synchronous Connection (0x01|0x0029) plen 21
> HCI Event: Command Status (0x0f) plen 4
> HCI Event: Synchronous Connect Complete (0x2c) plen 17
< SCO data: handle 46 flags 0x00 dlen 48
> ACL data: handle 42 flags 0x02 dlen 22
    L2CAP(d): cid 0x0040 len 18 [psm 0]
> ACL data: handle 42 flags 0x02 dlen 22
    L2CAP(d): cid 0x0040 len 18 [psm 0]
> ACL data: handle 42 flags 0x02 dlen 22
    L2CAP(d): cid 0x0040 len 18 [psm 0]
> ACL data: handle 42 flags 0x02 dlen 22
    L2CAP(d): cid 0x0040 len 18 [psm 0]
> ACL data: handle 42 flags 0x02 dlen 36
    L2CAP(d): cid 0x0040 len 32 [psm 0]



> ACL data: handle 42 flags 0x02 dlen 22
    L2CAP(d): cid 0x0040 len 18 [psm 0]
> ACL data: handle 42 flags 0x02 dlen 22
    L2CAP(d): cid 0x0040 len 18 [psm 0]
> ACL data: handle 42 flags 0x02 dlen 22
    L2CAP(d): cid 0x0040 len 18 [psm 0]
> HCI Event: Disconn Complete (0x05) plen 4

Anybody knows what is happening??

tks
Rafael Seste

2

I made a mistake…the log level wasn’t good enough…

now i got the real logs…the function mbl_write was called but it wokrs only once. After that i got this errors:

[May 20 19:54:33] DEBUG[5625] chan_mobile.c: sco_read() error 104
[May 20 19:54:33] DEBUG[5625] chan_mobile.c: sco_write()
[May 20 19:54:33] DEBUG[5625] chan_mobile.c: sco write error 107
[May 20 19:54:33] DEBUG[5625] chan_mobile.c: sco_read()

error 104 - is connection reseted by peer
error 107 is not connected

some one knows why i got error 104???
it is a bluez error???

here is the full log:

[May 20 19:53:12] VERBOSE[5621] chan_mobile.c:     -- Bluetooth Device Seste initialised and ready.
[May 20 19:53:22] DEBUG[5619] chan_sip.c: Allocating new SIP dialog for 0cd58ffc5b68b98a76521ec71a807aff@192.168.0.121 - OPTIONS (No RTP)
[May 20 19:53:22] DEBUG[5619] chan_sip.c: Initializing initreq for method OPTIONS - callid 79e62b734054238a5fa7ebe32eeacfce@192.168.0.121
[May 20 19:53:22] DEBUG[5619] chan_sip.c: Trying to put 'OPTIONS si' onto UDP socket destined for 192.168.0.61:57694
[May 20 19:53:23] DEBUG[5619] chan_sip.c: Trying to put 'OPTIONS si' onto UDP socket destined for 192.168.0.61:57694
[May 20 19:53:24] DEBUG[5619] chan_sip.c: Trying to put 'OPTIONS si' onto UDP socket destined for 192.168.0.61:57694
[May 20 19:53:25] DEBUG[5619] chan_sip.c: Trying to put 'OPTIONS si' onto UDP socket destined for 192.168.0.61:57694
[May 20 19:53:26] DEBUG[5619] chan_sip.c: Trying to put 'OPTIONS si' onto UDP socket destined for 192.168.0.61:57694
[May 20 19:53:30] DEBUG[5619] acl.c: Found IP address for this socket
[May 20 19:53:30] DEBUG[5619] chan_sip.c: Allocating new SIP dialog for NzYzNTM2NTU3MmNjMGUwZGUwNDA3YTgwNTVjMTQ1ZGI. - REGISTER (No RTP)
[May 20 19:53:30] DEBUG[5619] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER
[May 20 19:53:30] DEBUG[5619] chan_sip.c: Trying to put 'SIP/2.0 40' onto UDP socket destined for 192.168.0.61:57695
[May 20 19:53:30] DEBUG[5619] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER
[May 20 19:53:30] VERBOSE[5619] chan_sip.c:     -- Registered SIP '2000' at 192.168.0.61 port 57695
[May 20 19:53:30] DEBUG[5619] chan_sip.c: Allocating new SIP dialog for 22efa98e7b89db1724ad59f0073c138b@192.168.0.121 - OPTIONS (No RTP)
[May 20 19:53:30] DEBUG[5619] acl.c: Found IP address for this socket
[May 20 19:53:30] DEBUG[5619] chan_sip.c: Initializing initreq for method OPTIONS - callid 0bdd3d664740a42c3b43dcbd131089cc@192.168.0.121
[May 20 19:53:30] DEBUG[5619] chan_sip.c: Trying to put 'OPTIONS si' onto UDP socket destined for 192.168.0.61:57695
[May 20 19:53:30] VERBOSE[5619] chan_sip.c:        > Saved useragent "X-Lite release 1103d stamp 53117" for peer 2000
[May 20 19:53:30] DEBUG[5619] chan_sip.c: Trying to put 'SIP/2.0 20' onto UDP socket destined for 192.168.0.61:57695
[May 20 19:53:30] DEBUG[5619] chan_sip.c: Stopping retransmission on '0bdd3d664740a42c3b43dcbd131089cc@192.168.0.121' of Request 102: Match Found
[May 20 19:53:30] NOTICE[5619] chan_sip.c: Peer '2000' is now Reachable. (1ms / 2000ms)
[May 20 19:53:30] DEBUG[5619] chan_sip.c: Destroying SIP dialog 0bdd3d664740a42c3b43dcbd131089cc@192.168.0.121
[May 20 19:53:30] DEBUG[5594] devicestate.c: No provider found, checking channel drivers for SIP - 2000
[May 20 19:53:30] DEBUG[5594] chan_sip.c: Checking device state for peer 2000
[May 20 19:53:30] DEBUG[5594] devicestate.c: Changing state for SIP/2000 - state 1 (Not in use)
[May 20 19:53:30] DEBUG[5594] devicestate.c: device 'SIP/2000' state '1'
[May 20 19:53:30] DEBUG[5594] devicestate.c: No provider found, checking channel drivers for SIP - 2000
[May 20 19:53:30] DEBUG[5594] chan_sip.c: Checking device state for peer 2000
[May 20 19:53:30] DEBUG[5594] devicestate.c: Changing state for SIP/2000 - state 1 (Not in use)
[May 20 19:53:30] DEBUG[5594] devicestate.c: device 'SIP/2000' state '1'
[May 20 19:53:30] DEBUG[5618] app_queue.c: Device 'SIP/2000' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[May 20 19:53:30] DEBUG[5618] app_queue.c: Device 'SIP/2000' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[May 20 19:53:31] DEBUG[5619] acl.c: Found IP address for this socket
[May 20 19:53:31] DEBUG[5619] chan_sip.c: Trying to put 'SIP/2.0 50' onto UDP socket destined for 192.168.0.61:57695
[May 20 19:53:31] DEBUG[5619] chan_sip.c: Got a request with unsupported SIP method.
[May 20 19:53:31] DEBUG[5619] chan_sip.c: Invalid SIP message - rejected , no callid, len 992
[May 20 19:53:52] DEBUG[5619] acl.c: Found IP address for this socket
[May 20 19:53:52] DEBUG[5619] chan_sip.c: Trying to put 'SIP/2.0 50' onto UDP socket destined for 192.168.0.61:57695
[May 20 19:53:52] DEBUG[5619] chan_sip.c: Got a request with unsupported SIP method.
[May 20 19:53:52] DEBUG[5619] chan_sip.c: Invalid SIP message - rejected , no callid, len 1028
[May 20 19:53:54] DEBUG[5619] acl.c: Found IP address for this socket
[May 20 19:53:54] VERBOSE[5619] netsock.c:   == Using SIP RTP CoS mark 5
[May 20 19:53:54] DEBUG[5619] chan_sip.c: Setting NAT on RTP to Off
[May 20 19:53:54] DEBUG[5619] chan_sip.c: Allocating new SIP dialog for OWFmMzM0Yzg1YzRiMWUwNzZlNmIyYzkxMTcwNTI0NzE. - INVITE (With RTP)
[May 20 19:53:54] DEBUG[5619] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE
[May 20 19:53:54] DEBUG[5619] chan_sip.c: Setting NAT on RTP to Off
[May 20 19:53:54] DEBUG[5619] chan_sip.c: Trying to put 'SIP/2.0 40' onto UDP socket destined for 192.168.0.61:57695
[May 20 19:53:54] DEBUG[5619] chan_sip.c: **** Received ACK (6) - Command in SIP ACK
[May 20 19:53:54] DEBUG[5619] chan_sip.c: Stopping retransmission on 'OWFmMzM0Yzg1YzRiMWUwNzZlNmIyYzkxMTcwNTI0NzE.' of Response 1: Match Found
[May 20 19:53:54] DEBUG[5619] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE
[May 20 19:53:54] DEBUG[5619] chan_sip.c: Setting NAT on RTP to Off
[May 20 19:53:54] DEBUG[5619] chan_sip.c: We're settling with these formats: 0xc (ulaw|alaw)
[May 20 19:53:54] DEBUG[5619] chan_sip.c: Checking SIP call limits for device 2000
[May 20 19:53:54] DEBUG[5619] chan_sip.c: Updating call counter for incoming call
[May 20 19:53:54] DEBUG[5619] chan_sip.c: *** Our native formats are 0x4 (ulaw) 
[May 20 19:53:54] DEBUG[5619] chan_sip.c: *** Joint capabilities are 0xc (ulaw|alaw) 
[May 20 19:53:54] DEBUG[5619] chan_sip.c: *** Our capabilities are 0xe (gsm|ulaw|alaw) 
[May 20 19:53:54] DEBUG[5619] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) 
[May 20 19:53:54] DEBUG[5619] chan_sip.c: This channel will not be able to handle video.
[May 20 19:53:54] DEBUG[5619] chan_sip.c: build_route: Contact hop: <sip:2000@192.168.0.61:57695>
[May 20 19:53:54] DEBUG[5619] chan_sip.c: SIP/2000-00208258: New call is still down.... Trying... 
[May 20 19:53:54] DEBUG[5619] chan_sip.c: Trying to put 'SIP/2.0 10' onto UDP socket destined for 192.168.0.61:57695
[May 20 19:53:54] DEBUG[5594] devicestate.c: No provider found, checking channel drivers for SIP - 2000
[May 20 19:53:54] DEBUG[5594] chan_sip.c: Checking device state for peer 2000
[May 20 19:53:54] DEBUG[5594] devicestate.c: Changing state for SIP/2000 - state 2 (In use)
[May 20 19:53:54] DEBUG[5594] devicestate.c: device 'SIP/2000' state '2'
[May 20 19:53:54] DEBUG[5594] devicestate.c: No provider found, checking channel drivers for SIP - 2000
[May 20 19:53:54] DEBUG[5594] chan_sip.c: Checking device state for peer 2000
[May 20 19:53:54] DEBUG[5594] devicestate.c: Changing state for SIP/2000 - state 2 (In use)
[May 20 19:53:54] DEBUG[5594] devicestate.c: device 'SIP/2000' state '2'
[May 20 19:53:54] DEBUG[5618] app_queue.c: Device 'SIP/2000' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[May 20 19:53:54] DEBUG[5618] app_queue.c: Device 'SIP/2000' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[May 20 19:53:54] DEBUG[5625] pbx.c: Launching 'Answer'
[May 20 19:53:54] VERBOSE[5625] pbx.c:     -- Executing [123@from-internal:1] Answer("SIP/2000-00208258", "") in new stack
[May 20 19:53:54] DEBUG[5594] devicestate.c: No provider found, checking channel drivers for SIP - 2000
[May 20 19:53:54] DEBUG[5594] chan_sip.c: Checking device state for peer 2000
[May 20 19:53:54] DEBUG[5594] devicestate.c: Changing state for SIP/2000 - state 2 (In use)
[May 20 19:53:54] DEBUG[5594] devicestate.c: device 'SIP/2000' state '2'
[May 20 19:53:54] DEBUG[5618] app_queue.c: Device 'SIP/2000' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[May 20 19:53:54] DEBUG[5625] chan_sip.c: SIP answering channel: SIP/2000-00208258
[May 20 19:53:54] DEBUG[5625] chan_sip.c: Setting framing from config on incoming call
[May 20 19:53:54] DEBUG[5625] chan_sip.c: ** Our capability: 0xc (ulaw|alaw) Video flag: True Text flag: True
[May 20 19:53:54] DEBUG[5625] chan_sip.c: ** Our prefcodec: 0x0 (nothing) 
[May 20 19:53:54] DEBUG[5625] chan_sip.c: -- Done with adding codecs to SDP
[May 20 19:53:54] DEBUG[5625] chan_sip.c: Done building SDP. Settling with this capability: 0xc (ulaw|alaw)
[May 20 19:53:54] DEBUG[5625] chan_sip.c: Trying to put 'SIP/2.0 20' onto UDP socket destined for 192.168.0.61:57695
[May 20 19:53:54] DEBUG[5625] rtp.c: Got RTCP report of 132 bytes
[May 20 19:53:54] DEBUG[5625] pbx.c: Launching 'Dial'
[May 20 19:53:54] VERBOSE[5625] pbx.c:     -- Executing [123@from-internal:2] Dial("SIP/2000-00208258", "Mobile/Seste/909037079681") in new stack
[May 20 19:53:54] DEBUG[5625] rtp.c: Channel 'Mobile/Seste-ef7b' has no RTP, not doing anything
[May 20 19:53:54] DEBUG[5625] channel.c: Not copying variable DIALEDTIME.
[May 20 19:53:54] DEBUG[5625] channel.c: Not copying variable ANSWEREDTIME.
[May 20 19:53:54] DEBUG[5625] channel.c: Not copying variable DIALEDPEERNAME.
[May 20 19:53:54] DEBUG[5625] channel.c: Not copying variable DIALEDPEERNUMBER.
[May 20 19:53:54] DEBUG[5625] channel.c: Not copying variable DIALSTATUS.
[May 20 19:53:54] DEBUG[5625] channel.c: Not copying variable SIPCALLID.
[May 20 19:53:54] DEBUG[5625] channel.c: Not copying variable SIPDOMAIN.
[May 20 19:53:54] DEBUG[5625] channel.c: Not copying variable SIPURI.
[May 20 19:53:54] DEBUG[5625] chan_mobile.c: Calling Seste/909037079681 on Mobile/Seste-ef7b
[May 20 19:53:54] VERBOSE[5625] app_dial.c:     -- Called Seste/909037079681
[May 20 19:53:54] DEBUG[5625] channel.c: Set channel Mobile/Seste-ef7b to read format ulaw
[May 20 19:53:54] DEBUG[5625] channel.c: Set channel SIP/2000-00208258 to read format slin
[May 20 19:53:54] DEBUG[5625] chan_mobile.c: *** mbl_write
[May 20 19:53:54] DEBUG[5625] chan_mobile.c: sco_write() not ready
[May 20 19:53:54] DEBUG[5625] chan_mobile.c: sco_read() not ready
[May 20 19:53:54] DEBUG[5625] chan_mobile.c: sco_write() not ready
[May 20 19:53:54] DEBUG[5625] chan_mobile.c: sco_read() not ready
[May 20 19:53:54] DEBUG[5625] chan_mobile.c: sco_write() not ready
[May 20 19:53:54] DEBUG[5625] chan_mobile.c: sco_read() not ready
[May 20 19:53:54] DEBUG[5625] chan_mobile.c: sco_write() not ready
[May 20 19:53:54] DEBUG[5625] chan_mobile.c: sco_read() not ready
[May 20 19:53:54] DEBUG[5625] chan_mobile.c: sco_write() not ready
[May 20 19:53:54] DEBUG[5625] chan_mobile.c: sco_read() not ready
[May 20 19:53:54] DEBUG[5625] chan_mobile.c: sco_write() not ready
[May 20 19:53:54] DEBUG[5625] chan_mobile.c: sco_read() not ready
[May 20 19:53:54] DEBUG[5619] chan_sip.c: **** Received ACK (6) - Command in SIP ACK
[May 20 19:53:54] DEBUG[5619] chan_sip.c: Stopping retransmission on 'OWFmMzM0Yzg1YzRiMWUwNzZlNmIyYzkxMTcwNTI0NzE.' of Response 2: Match Found
[May 20 19:53:54] DEBUG[5625] chan_mobile.c: *** mbl_write
[May 20 19:53:54] DEBUG[5625] chan_mobile.c: sco_write() not ready
[May 20 19:53:54] DEBUG[5625] chan_mobile.c: sco_read() not ready
[May 20 19:53:54] DEBUG[5625] chan_mobile.c: sco_write() not ready
[May 20 19:53:54] DEBUG[5625] chan_mobile.c: sco_read() not ready
[May 20 19:53:54] DEBUG[5625] chan_mobile.c: sco_write() not ready
[May 20 19:53:54] DEBUG[5625] chan_mobile.c: sco_read() not ready
[May 20 19:53:54] DEBUG[5625] chan_mobile.c: sco_write() not ready
[May 20 19:53:54] DEBUG[5625] chan_mobile.c: sco_read() not ready
[May 20 19:53:54] DEBUG[5625] chan_mobile.c: sco_write() not ready
[May 20 19:53:54] DEBUG[5625] chan_mobile.c: sco_read() not ready
[May 20 19:53:54] DEBUG[5625] chan_mobile.c: sco_write() not ready
[May 20 19:53:54] DEBUG[5625] chan_mobile.c: sco_read() not ready
[May 20 19:53:54] DEBUG[5621] chan_mobile.c: rfcomm_write() (Seste) [ATD909037079681;
]
[May 20 19:53:55] DEBUG[5625] chan_mobile.c: *** mbl_write
[May 20 19:53:55] DEBUG[5625] chan_mobile.c: sco_write() not ready
[May 20 19:53:55] DEBUG[5625] chan_mobile.c: sco_read() not ready
[May 20 19:53:55] DEBUG[5625] chan_mobile.c: sco_write() not ready
[May 20 19:53:55] DEBUG[5625] chan_mobile.c: sco_read() not ready
[May 20 19:53:55] DEBUG[5625] chan_mobile.c: sco_write() not ready
[May 20 19:53:55] DEBUG[5625] chan_mobile.c: sco_read() not ready
[May 20 19:53:55] DEBUG[5625] chan_mobile.c: sco_write() not ready
[May 20 19:53:55] DEBUG[5625] chan_mobile.c: sco_read() not ready
[May 20 19:53:55] DEBUG[5625] chan_mobile.c: sco_write() not ready
[May 20 19:53:55] DEBUG[5625] chan_mobile.c: sco_read() not ready
[May 20 19:53:55] DEBUG[5625] chan_mobile.c: sco_write() not ready
[May 20 19:53:55] DEBUG[5625] chan_mobile.c: sco_read() not ready
[May 20 19:53:55] DEBUG[5625] chan_mobile.c: sco_write() not ready
[May 20 19:53:55] DEBUG[5625] chan_mobile.c: sco_read() not ready
[May 20 19:53:55] DEBUG[5621] chan_mobile.c: rfcomm_read() (Seste) [OK]
[May 20 19:53:55] DEBUG[5594] devicestate.c: No provider found, checking channel drivers for Mobile - Seste
[May 20 19:53:55] DEBUG[5594] chan_mobile.c: Checking device state for device Seste
[May 20 19:53:55] DEBUG[5594] devicestate.c: Changing state for Mobile/Seste - state 2 (In use)
[May 20 19:53:55] DEBUG[5594] devicestate.c: device 'Mobile/Seste' state '2'
[May 20 19:53:55] DEBUG[5618] app_queue.c: Device 'Mobile/Seste' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[May 20 19:53:55] DEBUG[5625] chan_mobile.c: *** mbl_write
[May 20 19:53:55] DEBUG[5625] chan_mobile.c: sco_write() not ready
[May 20 19:53:55] DEBUG[5625] chan_mobile.c: sco_read() not ready
[May 20 19:53:55] DEBUG[5625] chan_mobile.c: sco_write() not ready
[May 20 19:53:55] DEBUG[5625] chan_mobile.c: sco_read() not ready
[May 20 19:53:55] DEBUG[5625] chan_mobile.c: sco_write() not ready
[May 20 19:53:55] DEBUG[5625] chan_mobile.c: sco_read() not ready
[May 20 19:53:55] DEBUG[5625] chan_mobile.c: sco_write() not ready
[May 20 19:53:55] DEBUG[5625] chan_mobile.c: sco_read() not ready
[May 20 19:53:55] DEBUG[5625] chan_mobile.c: sco_write() not ready
[May 20 19:53:55] DEBUG[5625] chan_mobile.c: sco_read() not ready
[May 20 19:53:55] DEBUG[5625] chan_mobile.c: sco_write() not ready
[May 20 19:53:55] DEBUG[5625] chan_mobile.c: sco_read() not ready
[May 20 19:53:55] DEBUG[5621] chan_mobile.c: rfcomm_read() (Seste) [+CIEV: 3,2]
[May 20 19:53:55] DEBUG[5621] chan_mobile.c: rfcomm_read() (Seste) [+CIEV: 4,2]
[May 20 19:53:57] DEBUG[5625] rtp.c: Got RTCP report of 152 bytes
[May 20 19:54:00] DEBUG[5625] chan_mobile.c: *** mbl_write
[May 20 19:54:00] DEBUG[5625] chan_mobile.c: sco_write() not ready
[May 20 19:54:00] DEBUG[5625] chan_mobile.c: sco_read() not ready
[May 20 19:54:00] DEBUG[5625] chan_mobile.c: sco_write() not ready
[May 20 19:54:00] DEBUG[5625] chan_mobile.c: sco_read() not ready
[May 20 19:54:00] DEBUG[5625] chan_mobile.c: sco_write() not ready
[May 20 19:54:00] DEBUG[5625] chan_mobile.c: sco_read() not ready
[May 20 19:54:00] DEBUG[5625] chan_mobile.c: sco_write() not ready
[May 20 19:54:00] DEBUG[5625] chan_mobile.c: sco_read() not ready
[May 20 19:54:00] DEBUG[5625] chan_mobile.c: sco_write() not ready
[May 20 19:54:00] DEBUG[5625] chan_mobile.c: sco_read() not ready
[May 20 19:54:00] DEBUG[5625] chan_mobile.c: sco_write() not ready
[May 20 19:54:00] DEBUG[5625] chan_mobile.c: sco_read() not ready
[May 20 19:54:00] DEBUG[5625] chan_mobile.c: sco_write() not ready
[May 20 19:54:00] DEBUG[5625] chan_mobile.c: sco_read() not ready
[May 20 19:54:00] DEBUG[5621] chan_mobile.c: rfcomm_read() (Seste) [+CIEV: 3,3]
[May 20 19:54:00] DEBUG[5621] chan_mobile.c: rfcomm_read() (Seste) [+CIEV: 4,3]
[May 20 19:54:00] VERBOSE[5625] app_dial.c:     -- Mobile/Seste-ef7b is ringing
[May 20 19:54:00] DEBUG[5625] channel.c: Driver for channel 'SIP/2000-00208258' does not support indication 3, emulating it
[May 20 19:54:00] DEBUG[5625] channel.c: Set channel SIP/2000-00208258 to write format slin
[May 20 19:54:00] DEBUG[5625] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[May 20 19:54:00] DEBUG[5625] channel.c: Generator got voice, switching to phase locked mode
[May 20 19:54:00] DEBUG[5625] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[May 20 19:54:00] DEBUG[5625] rtp.c: Ooh, format changed from unknown to ulaw
[May 20 19:54:00] DEBUG[5625] rtp.c: Created smoother: format: 4 ms: 20 len: 160
[May 20 19:54:00] DEBUG[5625] chan_mobile.c: *** mbl_write
[May 20 19:54:00] DEBUG[5625] chan_mobile.c: sco_write() not ready
[May 20 19:54:00] DEBUG[5625] chan_mobile.c: sco_read() not ready
[May 20 19:54:00] DEBUG[5625] chan_mobile.c: sco_write() not ready
[May 20 19:54:00] DEBUG[5625] chan_mobile.c: sco_read() not ready
[May 20 19:54:00] DEBUG[5625] chan_mobile.c: sco_write() not ready
[May 20 19:54:00] DEBUG[5625] chan_mobile.c: sco_read() not ready
[May 20 19:54:00] DEBUG[5625] chan_mobile.c: sco_write() not ready
[May 20 19:54:00] DEBUG[5625] chan_mobile.c: sco_read() not ready
[May 20 19:54:00] DEBUG[5625] chan_mobile.c: sco_write() not ready
[May 20 19:54:00] DEBUG[5625] chan_mobile.c: sco_read() not ready
[May 20 19:54:00] DEBUG[5625] chan_mobile.c: sco_write() not ready
[May 20 19:54:00] DEBUG[5625] chan_mobile.c: sco_read() not ready
[May 20 19:54:00] DEBUG[5625] chan_mobile.c: *** mbl_write
[May 20 19:54:00] DEBUG[5622] chan_mobile.c: accept()ed socket.
[May 20 19:54:00] DEBUG[5622] chan_mobile.c: Incoming Audio Connection from device 00:1D:FD:E4:42:FF MTU is 64
[May 20 19:54:00] DEBUG[5622] chan_mobile.c: About to accept() socket.
[May 20 19:54:00] DEBUG[5625] chan_mobile.c: *** mbl_write
[May 20 19:54:00] DEBUG[5625] chan_mobile.c: sco_write()
[May 20 19:54:00] DEBUG[5625] chan_mobile.c: sco_read()
[May 20 19:54:01] DEBUG[5621] chan_mobile.c: rfcomm_read() (Seste) [+CIEV: 8,4]
[May 20 19:54:02] DEBUG[5621] chan_mobile.c: rfcomm_read() (Seste) [+CIEV: 1,1]
[May 20 19:54:02] DEBUG[5619] chan_sip.c: Auto destroying SIP dialog 'NzYzNTM2NTU3MmNjMGUwZGUwNDA3YTgwNTVjMTQ1ZGI.'
[May 20 19:54:02] DEBUG[5619] chan_sip.c: Destroying SIP dialog NzYzNTM2NTU3MmNjMGUwZGUwNDA3YTgwNTVjMTQ1ZGI.
[May 20 19:54:13] DEBUG[5619] chan_sip.c: **** Received BYE (8) - Command in SIP BYE
[May 20 19:54:13] DEBUG[5619] chan_sip.c: Setting SIP_ALREADYGONE on dialog OWFmMzM0Yzg1YzRiMWUwNzZlNmIyYzkxMTcwNTI0NzE.
[May 20 19:54:13] DEBUG[5619] chan_sip.c: Received bye, issuing owner hangup
[May 20 19:54:13] DEBUG[5619] chan_sip.c: Trying to put 'SIP/2.0 20' onto UDP socket destined for 192.168.0.61:57695
[May 20 19:54:13] DEBUG[5619] acl.c: Found IP address for this socket
[May 20 19:54:13] DEBUG[5619] chan_sip.c: Trying to put 'SIP/2.0 50' onto UDP socket destined for 192.168.0.61:57695
[May 20 19:54:13] DEBUG[5619] chan_sip.c: Got a request with unsupported SIP method.
[May 20 19:54:13] DEBUG[5619] chan_sip.c: Invalid SIP message - rejected , no callid, len 992
[May 20 19:54:30] DEBUG[5619] chan_sip.c: Allocating new SIP dialog for 79a26ae07ff40cbf589e5a7a05650e0a@192.168.0.121 - OPTIONS (No RTP)
[May 20 19:54:30] DEBUG[5619] acl.c: Found IP address for this socket
[May 20 19:54:30] DEBUG[5619] chan_sip.c: Initializing initreq for method OPTIONS - callid 50ba358827c4a419372d57ae5e173f9e@192.168.0.121
[May 20 19:54:30] DEBUG[5619] chan_sip.c: Trying to put 'OPTIONS si' onto UDP socket destined for 192.168.0.61:57695
[May 20 19:54:30] DEBUG[5619] chan_sip.c: Stopping retransmission on '50ba358827c4a419372d57ae5e173f9e@192.168.0.121' of Request 102: Match Found
[May 20 19:54:30] DEBUG[5619] chan_sip.c: Destroying SIP dialog 50ba358827c4a419372d57ae5e173f9e@192.168.0.121
[May 20 19:54:33] DEBUG[5625] chan_mobile.c: sco_read() error 104
[May 20 19:54:33] DEBUG[5625] chan_mobile.c: sco_write()
[May 20 19:54:33] DEBUG[5625] chan_mobile.c: sco write error 107
[May 20 19:54:33] DEBUG[5625] chan_mobile.c: sco_read()
[May 20 19:54:33] DEBUG[5625] chan_mobile.c: sco_read() error 107
[May 20 19:54:33] DEBUG[5625] chan_mobile.c: sco_write()
[May 20 19:54:33] DEBUG[5625] chan_mobile.c: sco write error 107
[May 20 19:54:33] DEBUG[5625] chan_mobile.c: sco_read()
[May 20 19:54:33] DEBUG[5625] chan_mobile.c: sco_read() error 107
[May 20 19:54:33] DEBUG[5625] chan_mobile.c: sco_write()
[May 20 19:54:33] DEBUG[5625] chan_mobile.c: sco write error 107
[May 20 19:54:33] DEBUG[5625] chan_mobile.c: sco_read()
[May 20 19:54:33] DEBUG[5625] chan_mobile.c: sco_read() error 107
[May 20 19:54:33] DEBUG[5625] chan_mobile.c: sco_write()
[May 20 19:54:33] DEBUG[5625] chan_mobile.c: sco write error 107
[May 20 19:54:33] DEBUG[5625] chan_mobile.c: sco_read()
[May 20 19:54:33] DEBUG[5625] chan_mobile.c: sco_read() error 107
[May 20 19:54:33] DEBUG[5625] chan_mobile.c: sco_write()
[May 20 19:54:33] DEBUG[5625] chan_mobile.c: sco write error 107
[May 20 19:54:33] DEBUG[5625] chan_mobile.c: sco_read()
[May 20 19:54:33] DEBUG[5625] chan_mobile.c: sco_read() error 107
[May 20 19:54:33] DEBUG[5625] channel.c: Set channel SIP/2000-00208258 to write format ulaw
[May 20 19:54:33] DEBUG[5625] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[May 20 19:54:33] DEBUG[5625] rtp.c: Channel '<unspecified>' has no RTP, not doing anything
[May 20 19:54:33] DEBUG[5625] channel.c: Hanging up channel 'Mobile/Seste-ef7b'
[May 20 19:54:33] DEBUG[5625] chan_mobile.c: Hanging up device Seste.
[May 20 19:54:33] DEBUG[5625] chan_mobile.c: rfcomm_write() (Seste) [AT+CHUP
]
[May 20 19:54:33] DEBUG[5625] app_dial.c: Exiting with DIALSTATUS=CANCEL.
[May 20 19:54:33] DEBUG[5625] pbx.c: Spawn extension (from-internal,123,2) exited non-zero on 'SIP/2000-00208258'
[May 20 19:54:33] VERBOSE[5625] pbx.c:   == Spawn extension (from-internal, 123, 2) exited non-zero on 'SIP/2000-00208258'
[May 20 19:54:33] DEBUG[5625] channel.c: Soft-Hanging up channel 'SIP/2000-00208258'
[May 20 19:54:33] DEBUG[5625] channel.c: Hanging up channel 'SIP/2000-00208258'
[May 20 19:54:33] DEBUG[5625] chan_sip.c: Hangup call SIP/2000-00208258, SIP callid OWFmMzM0Yzg1YzRiMWUwNzZlNmIyYzkxMTcwNTI0NzE.
[May 20 19:54:33] DEBUG[5625] chan_sip.c: Updating call counter for incoming call
[May 20 19:54:33] DEBUG[5621] chan_mobile.c: rfcomm_read() (Seste) [+CIEV: 3,0]
[May 20 19:54:33] DEBUG[5621] chan_mobile.c: rfcomm_read() (Seste) [+CIEV: 4,0]
[May 20 19:54:33] DEBUG[5621] chan_mobile.c: rfcomm_read() (Seste) [+CIEV: 8,3]
[May 20 19:54:33] DEBUG[5621] chan_mobile.c: rfcomm_read() (Seste) [+CIEV: 8,5]
[May 20 19:54:33] DEBUG[5621] chan_mobile.c: rfcomm_read() (Seste) [NO CARRIER]
[May 20 19:54:33] DEBUG[5621] chan_mobile.c: rfcomm_read() (Seste) [+CIEV: 1,0]
[May 20 19:54:33] DEBUG[5621] chan_mobile.c: rfcomm_read() (Seste) [OK]
[May 20 19:54:33] DEBUG[5621] chan_mobile.c: Device Seste [OK]
[May 20 19:54:33] DEBUG[5594] devicestate.c: No provider found, checking channel drivers for Mobile - Seste
[May 20 19:54:33] DEBUG[5594] chan_mobile.c: Checking device state for device Seste
[May 20 19:54:33] DEBUG[5594] devicestate.c: Changing state for Mobile/Seste - state 1 (Not in use)
[May 20 19:54:33] DEBUG[5594] devicestate.c: device 'Mobile/Seste' state '1'
[May 20 19:54:33] DEBUG[5618] app_queue.c: Device 'Mobile/Seste' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[May 20 19:54:33] DEBUG[5594] devicestate.c: No provider found, checking channel drivers for Mobile - Seste
[May 20 19:54:33] DEBUG[5594] chan_mobile.c: Checking device state for device Seste
[May 20 19:54:33] DEBUG[5594] devicestate.c: Changing state for Mobile/Seste - state 1 (Not in use)
[May 20 19:54:33] DEBUG[5594] devicestate.c: device 'Mobile/Seste' state '1'
[May 20 19:54:33] DEBUG[5618] app_queue.c: Device 'Mobile/Seste' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[May 20 19:54:33] DEBUG[5594] devicestate.c: No provider found, checking channel drivers for SIP - 2000
[May 20 19:54:33] DEBUG[5594] chan_sip.c: Checking device state for peer 2000
[May 20 19:54:33] DEBUG[5594] devicestate.c: Changing state for SIP/2000 - state 1 (Not in use)
[May 20 19:54:33] DEBUG[5594] devicestate.c: device 'SIP/2000' state '1'
[May 20 19:54:33] DEBUG[5618] app_queue.c: Device 'SIP/2000' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[May 20 19:54:33] DEBUG[5594] devicestate.c: No provider found, checking channel drivers for SIP - 2000
[May 20 19:54:33] DEBUG[5594] chan_sip.c: Checking device state for peer 2000
[May 20 19:54:33] DEBUG[5594] devicestate.c: Changing state for SIP/2000 - state 1 (Not in use)
[May 20 19:54:33] DEBUG[5594] devicestate.c: device 'SIP/2000' state '1'
[May 20 19:54:33] DEBUG[5618] app_queue.c: Device 'SIP/2000' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[May 20 19:54:33] DEBUG[5619] chan_sip.c: Destroying SIP dialog OWFmMzM0Yzg1YzRiMWUwNzZlNmIyYzkxMTcwNTI0NzE.
[May 20 19:55:30] DEBUG[5619] chan_sip.c: Allocating new SIP dialog for 7874fa002a12807f338fc9f450b583db@192.168.0.121 - OPTIONS (No RTP)
[May 20 19:55:30] DEBUG[5619] acl.c: Found IP address for this socket
[May 20 19:55:30] DEBUG[5619] chan_sip.c: Initializing initreq for method OPTIONS - callid 7dab2ced31ae7b066ac8b189624eb208@192.168.0.121
[May 20 19:55:30] DEBUG[5619] chan_sip.c: Trying to put 'OPTIONS si' onto UDP socket destined for 192.168.0.61:57695
[May 20 19:55:30] DEBUG[5619] chan_sip.c: Stopping retransmission on '7dab2ced31ae7b066ac8b189624eb208@192.168.0.121' of Request 102: Match Found
[May 20 19:55:30] DEBUG[5619] chan_sip.c: Destroying SIP dialog 7dab2ced31ae7b066ac8b189624eb208@192.168.0.121
[May 20 19:56:01] DEBUG[5619] acl.c: Found IP address for this socket
[May 20 19:56:01] DEBUG[5619] chan_sip.c: Allocating new SIP dialog for MzAwMDA5NGUzMGJkODM0MjBiNWMzNmExYmFiOTM2NGM. - SUBSCRIBE (No RTP)
[May 20 19:56:01] DEBUG[5619] chan_sip.c: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE
[May 20 19:56:01] DEBUG[5619] chan_sip.c: Trying to put 'SIP/2.0 40' onto UDP socket destined for 192.168.0.61:57695
[May 20 19:56:01] DEBUG[5619] chan_sip.c: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE
[May 20 19:56:01] DEBUG[5619] chan_sip.c: Trying to put 'SIP/2.0 20' onto UDP socket destined for 192.168.0.61:57695
[May 20 19:56:01] DEBUG[5619] chan_sip.c: Trying to put 'NOTIFY sip' onto UDP socket destined for 192.168.0.61:57695
[May 20 19:56:01] DEBUG[5619] chan_sip.c: Stopping retransmission on 'MzAwMDA5NGUzMGJkODM0MjBiNWMzNmExYmFiOTM2NGM.' of Request 102: Match Found
[May 20 19:56:30] DEBUG[5619] chan_sip.c: Allocating new SIP dialog for 37d6bada79a1f6511d84b1267f36ea03@192.168.0.121 - OPTIONS (No RTP)
[May 20 19:56:30] DEBUG[5619] acl.c: Found IP address for this socket
[May 20 19:56:30] DEBUG[5619] chan_sip.c: Initializing initreq for method OPTIONS - callid 1cea1a352a016f9a118b7b0a051281b1@192.168.0.121
[May 20 19:56:31] DEBUG[5619] chan_sip.c: Trying to put 'OPTIONS si' onto UDP socket destined for 192.168.0.61:57695
[May 20 19:56:31] DEBUG[5619] chan_sip.c: Stopping retransmission on '1cea1a352a016f9a118b7b0a051281b1@192.168.0.121' of Request 102: Match Found
[May 20 19:56:31] DEBUG[5619] chan_sip.c: Destroying SIP dialog 1cea1a352a016f9a118b7b0a051281b1@192.168.0.121
[May 20 19:57:13] DEBUG[5619] acl.c: Found IP address for this socket
[May 20 19:57:13] DEBUG[5619] chan_sip.c: Trying to put 'SIP/2.0 50' onto UDP socket destined for 192.168.0.61:57695
[May 20 19:57:13] DEBUG[5619] chan_sip.c: Got a request with unsupported SIP method.
[May 20 19:57:13] DEBUG[5619] chan_sip.c: Invalid SIP message - rejected , no callid, len 992
[May 20 19:57:31] DEBUG[5619] chan_sip.c: Allocating new SIP dialog for 3156a9fe243fd4820fa947e71b92a68f@192.168.0.121 - OPTIONS (No RTP)
[May 20 19:57:31] DEBUG[5619] acl.c: Found IP address for this socket
[May 20 19:57:31] DEBUG[5619] chan_sip.c: Initializing initreq for method OPTIONS - callid 170cda9c76ea21716e780e6657a31ddc@192.168.0.121
[May 20 19:57:31] DEBUG[5619] chan_sip.c: Trying to put 'OPTIONS si' onto UDP socket destined for 192.168.0.61:57695
[May 20 19:57:31] DEBUG[5619] chan_sip.c: Stopping retransmission on '170cda9c76ea21716e780e6657a31ddc@192.168.0.121' of Request 102: Match Found
[May 20 19:57:31] DEBUG[5619] chan_sip.c: Destroying SIP dialog 170cda9c76ea21716e780e6657a31ddc@192.168.0.121
[May 20 19:58:31] DEBUG[5619] chan_sip.c: Allocating new SIP dialog for 082113242d9949d04f2d437a1320b143@192.168.0.121 - OPTIONS (No RTP)
[May 20 19:58:31] DEBUG[5619] acl.c: Found IP address for this socket
[May 20 19:58:31] DEBUG[5619] chan_sip.c: Initializing initreq for method OPTIONS - callid 0da17f3e2d6ce6530f526e8c0662cab3@192.168.0.121
[May 20 19:58:31] DEBUG[5619] chan_sip.c: Trying to put 'OPTIONS si' onto UDP socket destined for 192.168.0.61:57695
[May 20 19:58:31] DEBUG[5619] chan_sip.c: Stopping retransmission on '0da17f3e2d6ce6530f526e8c0662cab3@192.168.0.121' of Request 102: Match Found
[May 20 19:58:31] DEBUG[5619] chan_sip.c: Destroying SIP dialog 0da17f3e2d6ce6530f526e8c0662cab3@192.168.0.121
[May 20 19:59:31] DEBUG[5619] chan_sip.c: Allocating new SIP dialog for 1b458c5f7a6db57f53d2c55f67d432ac@192.168.0.121 - OPTIONS (No RTP)
[May 20 19:59:31] DEBUG[5619] acl.c: Found IP address for this socket
[May 20 19:59:31] DEBUG[5619] chan_sip.c: Initializing initreq for method OPTIONS - callid 2cbee30c34081ab02acee3cb42d61534@192.168.0.121
[May 20 19:59:31] DEBUG[5619] chan_sip.c: Trying to put 'OPTIONS si' onto UDP socket destined for 192.168.0.61:57695
[May 20 19:59:31] DEBUG[5619] chan_sip.c: Stopping retransmission on '2cbee30c34081ab02acee3cb42d61534@192.168.0.121' of Request 102: Match Found
[May 20 19:59:31] DEBUG[5619] chan_sip.c: Destroying SIP dialog 2cbee30c34081ab02acee3cb42d61534@192.168.0.121
[May 20 20:00:13] DEBUG[5619] acl.c: Found IP address for this socket
[May 20 20:00:13] DEBUG[5619] chan_sip.c: Trying to put 'SIP/2.0 50' onto UDP socket destined for 192.168.0.61:57695
[May 20 20:00:13] DEBUG[5619] chan_sip.c: Got a request with unsupported SIP method.
[May 20 20:00:13] DEBUG[5619] chan_sip.c: Invalid SIP message - rejected , no callid, len 992
[May 20 20:00:31] DEBUG[5619] chan_sip.c: Allocating new SIP dialog for 3dbe9189621226e97c49a03d53a60ce7@192.168.0.121 - OPTIONS (No RTP)
[May 20 20:00:31] DEBUG[5619] acl.c: Found IP address for this socket
[May 20 20:00:31] DEBUG[5619] chan_sip.c: Initializing initreq for method OPTIONS - callid 44d0a9607a0ace6c113730af63f6029e@192.168.0.121
[May 20 20:00:31] DEBUG[5619] chan_sip.c: Trying to put 'OPTIONS si' onto UDP socket destined for 192.168.0.61:57695
[May 20 20:00:31] DEBUG[5619] chan_sip.c: Stopping retransmission on '44d0a9607a0ace6c113730af63f6029e@192.168.0.121' of Request 102: Match Found
[May 20 20:00:31] DEBUG[5619] chan_sip.c: Destroying SIP dialog 44d0a9607a0ace6c113730af63f6029e@192.168.0.121
[May 20 20:00:32] DEBUG[5619] chan_sip.c: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE
[May 20 20:00:32] DEBUG[5619] chan_sip.c: Trying to put 'SIP/2.0 20' onto UDP socket destined for 192.168.0.61:57695
[May 20 20:00:32] DEBUG[5619] chan_sip.c: Trying to put 'NOTIFY sip' onto UDP socket destined for 192.168.0.61:57695
[May 20 20:00:32] DEBUG[5619] chan_sip.c: Stopping retransmission on 'MzAwMDA5NGUzMGJkODM0MjBiNWMzNmExYmFiOTM2NGM.' of Request 103: Match Found
3

I update the kernel to 2.6.30-rc6 and bluez to 4.40 and applied a chan_mobile patch:
issues.asterisk.org/view.php?id=15075

now I can hear the outgoing audio perfectly, but the incoming is truncated. I can´t understand almost anything.

I got the output from HCIDump and saw that some SCO packets are wrong.
Normally they have 4 bytes of header and 48 bytes of payload. The
packets sent to mobile are correct but the received ones are mostly
wrong. See the example below:

0000 03 ff ee ff ee ff ee ff ee ff ee ff 5c 00 30 ee … …0.
0010 ff ee ff ee ff ee ff ee ff ee ff ee ff ee ff ee … …
0020 ff ee ff ee ff ee ff ee ff ee ff ee ff ee ff ee … …
0030 ff ee ff ee ff ee ff ee ff ee ff ee ff ee ff 5c … …
0040 00 30 ee ff ee ff ee ff ee ff ee ff ee ff ee ff .0… …
0050 ee ff ee ff ee ff ee ff ee ff ee ff ee ff ee ff … …
0060 ee ff ee ff ee ff ee ff ee ff ee ff ee ff ee ff … …
0070 ee ff 5c 00 30 ee ff ee ff ee ff ee ff ee ff ee …0… …
0080 ff ee ff ee ff ee ff ee ff ee ff ee ff ee ff ee … …
0090 ff ee ff ee ff ee ff ee ff ee ff ee ff ee ff ee … …
00a0 ff ee ff ee ff 5c 00 30 ee ff ee ff ee ff ee ff …0 …
00b0 ee ff ee ff ee ff ee ff ee ff ee ff ee ff ee ff … …
00c0 ee ff ee ff ee ff ee ff ee ff ee ff ee ff ee ff … …
00d0 ee ff ee ff ee ff ee ff 5c 00 30 ee ff ee ff ee … .0…
00e0 ff ee ff ee ff ee ff ee ff ee ff ee ff ee ff ee … …
00f0 ff ee ff ee ff ee ff ee ff ee ff ee ff ee ff ee … …
0100 ff ee ff …

The first byte is correct (03) but the next header bytes are wrong.
They should be ‘5c 00 30’ that are 11 bytes after.

The correct packet should be similar to this one:

0000 03 5c 00 30 c7 ff 97 ff 77 ff e1 fe c3 fe cf fe …0… w…
0010 df fe 64 ff bb ff 36 00 bc 00 5e 01 11 02 6c 02 …d…6. …^…l.
0020 87 02 68 02 54 02 ba 01 b7 00 8b ff 69 fe a9 fd …h.T… …i…
0030 b6 fc 43 fc

from the dmesg i got this output

hci_scodata_packet: hci0 SCO packet for unknown connection handle 65516
hci_scodata_packet: hci0 SCO packet for unknown connection handle 65520
hci_scodata_packet: hci0 SCO packet for unknown connection handle 65520
btusb_isoc_complete: hci0 corrupted SCO packet
hci_scodata_packet: hci0 SCO packet for unknown connection handle 65510
hci_scodata_packet: hci0 SCO packet for unknown connection handle 61439
hci_scodata_packet: hci0 SCO packet for unknown connection handle 65517
hci_scodata_packet: hci0 SCO packet for unknown connection handle 57855
hci_scodata_packet: hci0 SCO packet for unknown connection handle 65527
hci_scodata_packet: hci0 SCO packet for unknown connection handle 61439
hci_scodata_packet: hci0 SCO packet for unknown connection handle 65519
hci_scodata_packet: hci0 SCO packet for unknown connection handle 61439
hci_scodata_packet: hci0 SCO packet for unknown connection handle 65522
hci_scodata_packet: hci0 SCO packet for unknown connection handle 65522

these error are related to the wrong header of the SCO packet.

Anybody knows how to solve this problem??

tks

Rafael