Summary:	ASTERISK-01934: Current CVS Breaks GrandStream and possibly other SIP devices
Reporter:	cshaw59 (cshaw59)	Labels:
Date Opened:	2004-07-01 01:02:25	Date Closed:	2004-09-25 02:40:20
Priority:	Major	Regression?	No
Status:	Closed/Complete	Components:	Core/General
Versions:		Frequency of Occurrence
Related Issues:
Environment:		Attachments:	( 0) kujsipdebug.txt
Description:	CVS Since around 06/14/04 seems to not work with GrandStream Devices. I've tested this with 2 BT101s and a HT486, both exhibit the same behavior. When calls come in PSTN -> VoIP -> Asterisk -> Phone, the phone rings, but when answered it hangs up. Asterisk gives an error at line 1800 of chan_sip.c in function sip_write() "Asked to transmit frame type 64, while native format is 4 (read/write = 4/4) Which I assume means that everyone is talking ULAW but asterisk wants to talk SLINEAR? Dosen't make sense... especially since SLINEAR is explicitly disallowed... Calls originated on the GrandStream to PSTN work just fine...
Comments:	By: cshaw59 (cshaw59) 2004-07-01 01:13:02 I should have clarified, I meant to say signed linear is disallowed in MY sip.conf. By: teji (teji) 2004-07-01 08:51:50 For me, with cvs from 2004-06-09 & CVS from 2004-07-01 (today), it work fine. Heuu, Fine, in fact, no. After a certain time, GrandStrem phone seams to be free, but is sean like "busy" by *. I can place a call, i can surf on the phone, but if i dial to the phone, the "Busy" way of my extension.conf is runned ! Only solution : reset the phone ! Why ... I don't know (yes)... If somebody as an idea to help me... Thanks, teji By: Olle Johansson (oej) 2004-07-01 11:49:57 Thank you for your report. We need a SIP DEBUG output of the transaction, as well as the sip.conf entry for the grandstream. By: programmer_ted (programmer_ted) 2004-07-01 12:43:03 I also had this problem in the latest CVS dialing to a Sipura (PSTN -> BroadVoice -> Asterisk -> Sipura), and decided to try to fix the bug.  I have come up with a bugfix, but I may just be covering up a larger issue.  Should I post my bugfix here, or should I post it in a new bug report?  Notice: I still have to sign the disclaimer. I was planning on posting a full bug report later today with a SIP debug, the patch, my sip.conf entry, and SSH info (after, of course, signing the disclaimer).  What do you recommend?  Before posting my code, if I have free time and if I haven't heard back from a Bug Tracker, I may try to get a better grasp on the problem and its origination, to see if my bugfix really does cover it up or if it solves the problem. Just looking for advice, thanks! By: programmer_ted (programmer_ted) 2004-07-01 12:45:39 As a side note, both cshaw59 and I are using BroadVoice as our SIP provider.  I'm talking to a third person who has encountered the bug to see if he's also using BroadVoice; I'll update ASAP.  Either the bug's tied to BroadVoice, or it's tied to any SIP provider between PSTN and Asterisk. By: Olle Johansson (oej) 2004-07-01 15:20:29 Does this only happen with calls from PSTN, not with calls between two SIP devices connected to the same PSTN? Can you confirm that it is Broadvoice that is the PSTN connection? By: twisted (twisted) 2004-07-01 16:14:22 I am unable to duplicate the issue, with Grandstream BT102 and CVS-HEAD from 7/1/04.  Please verify your configuration, and update to latest cvs and test for issues at this point. By: programmer_ted (programmer_ted) 2004-07-01 18:12:38 oej: this only occurs PSTN -> BroadVoice (or another SIP provider?) -> Asterisk -> SIP, it appears.  PSTN -> Asterisk -> SIP works (obviously), and so does SIP -> Asterisk -> SIP.  As far as I know, this bug only occurs when using BroadVoice, but then again only myself and cshaw have confirmed that we're using BroadVoice (in a private email).  The third person to experience this issue is yet to reply on whether he is using BroadVoice or not. twisted: I'm currently updating to the 7/1 CVS-HEAD.  We reported this bug when using the 6/26 CVS-HEAD.  I sincerely do hope the bug is fixed (without my possible coverup fix) in this version.  I'll be able to confirm if 7/1 does indeed solve the issue within a few minutes. By: programmer_ted (programmer_ted) 2004-07-01 18:24:51 Just upgraded to the latest CVS, still no joy.  Here's some more info I was gonna include in my newer bug report that I was going to fill out tonight, but since I'm probably not going to include the source (it's fairly simplistic), I'll just tell you guys all I know here: After trying to track down the bug for a while, I found that the problem is in playtones being sent to the SIP phone as soon as it picks up, for whatever reason.  Because playtones_generator sends SLINEAR data regardless of formats supported by the channel it's sending to, the warning would appear and Asterisk would hang up the call.  My "bugfix" simply translated the SLINEAR data to the channel's current writeformat.  This is probably just covering up a more obscure bug - why is the generator even put on the line for the channel when the SIP phone picks up in the first place?  I don't know enough about the SIP protocol to be sure if this is a problem, but that's my hunch.  I'll post the SIP debug output from the moment the call is begun to the moment it's hung up later tonight. By: cshaw59 (cshaw59) 2004-07-01 20:13:21 Sip.conf Snippit [100] ; The Context for my BT101 type=friend user="Chris Shaw" <sip:100@server> username=100 auth=md5 secret=<SuperSecret Password> context=shawhome host=10.100.5.33 permit=10.100.5.0/255.255.255.0 canreinvite=no dtmfmode=inband mailbox=100 disallow=all allow=ulaw allow=alaw This configuration works for every version I've tried up to about CVS 6/14 or around there... then it breaks Please stay tuned for the DEBUG output, I have to rebuild a newer CVS and install, I have downgraded because I kinda need asterisk to work, it's my only phone right now :) By: Brian West (bkw918) 2004-07-01 21:52:14 Try nat=never By: kuj (kuj) 2004-07-01 22:22:37 Seeing similar things in a SIP only environment (no PSTN):   Sipura -> * -> NAT -> SIP Provider (FWD) Calling echotest (*393613 in my dialplan) at FWD results in Jul  1 20:49:19 WARNING[-1242506320]: Asked to transmit frame type 64, while native formats is 16 (read/write = 4/16) SIP debug attached as kujsipdebug.txt sip.conf: [general]                                                                       disallow=all allow=ulaw allow=g726 allow=gsm tos=lowdelay realm    = cojensen.net port     = 5060                 ; Port to bind to bindaddr = 192.168.254.250      ; Address to bind to externip = kuj.is-a-geek.net localnet = 192.168.254.0/255.255.255.0 srvlookup= no context  = from-sip             ; Default for incoming calls callerid = Asterisk [fwd] type=peer host=fwd.pulver.com secret=<password> username=256222 dtmfmode=rfc2833 fromuser=256222 fromdomain=fwd.pulver.com canreinvite=no                                                                   insecure=very [2001] type=friend secret=<anotherpassword> host=dynamic defaultip=192.168.254.251 port=5061 dtmfmode=info context=home mailbox=2001@home callerid="L1" <2001> nat=never canreinvite=no qualify=yes By: cshaw59 (cshaw59) 2004-07-02 00:25:20 I just did another cvs checkout at 7/1-21:42 and tried the nat=never as brian suggested, that seems to have done the trick... What is the difference between NAT=NO and NAT=NEVER? is it documented somewhere? I hope I didn't waste ppl's time with something I could have Wiki'd but I've never seen that one before? Tried it with 2 phones and it worked... edited on: 07-02-04 00:21 By: cshaw59 (cshaw59) 2004-07-02 00:33:18 Spoke too soon... it worked once, then I tried again and no joy... By: cshaw59 (cshaw59) 2004-07-02 00:45:44 == CDR updated on SIP/147.135.0.129-081423f0    -- Executing Playback("SIP/147.135.0.129-081423f0", "transfer|skip") in new stack    -- Playing 'transfer' (language 'en')    -- Executing Ringing("SIP/147.135.0.129-081423f0", "") in new stack    -- Executing Dial("SIP/147.135.0.129-081423f0", "sip/100|25|tT") in new stack We're at 10.100.5.99 port 45282 Answering/Requesting with root capability 4 Answering with preferred capability 0x8(ALAW) 12 headers, 9 lines Reliably Transmitting: INVITE sip:100@10.100.5.33 SIP/2.0 Via: SIP/2.0/UDP 10.100.5.99:5060;branch=z9hG4bK752d69e1 From: "5036617026" <sip:5036617026@10.100.5.99>;tag=as38e274fa To: <sip:100@10.100.5.33> Contact: <sip:5036617026@10.100.5.99> Call-ID: 78d336b528317931038c1018597afde8@10.100.5.99 CSeq: 102 INVITE User-Agent: Asterisk PBX Date: Fri, 02 Jul 2004 05:30:20 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER Content-Type: application/sdp Content-Length: 182 v=0 o=root 13433 13433 IN IP4 10.100.5.99 s=session c=IN IP4 10.100.5.99 t=0 0 m=audio 45282 RTP/AVP 0 8 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=silenceSupp:off - - - - (no NAT) to 10.100.5.33:5060    -- Called 100 server*CLI> Sip read: SIP/2.0 100 trying Via: SIP/2.0/UDP 10.100.5.99:5060;branch=z9hG4bK752d69e1 From: "5036617026" <sip:5036617026@10.100.5.99>;tag=as38e274fa To: <sip:100@10.100.5.33> Call-ID: 78d336b528317931038c1018597afde8@10.100.5.99 CSeq: 102 INVITE User-Agent: Grandstream BT100 1.0.5.3 Content-Length: 0 8 headers, 0 lines server*CLI> Sip read: SIP/2.0 180 ringing Via: SIP/2.0/UDP 10.100.5.99:5060;branch=z9hG4bK752d69e1 From: "5036617026" <sip:5036617026@10.100.5.99>;tag=as38e274fa To: <sip:100@10.100.5.33>;tag=89a3ff5c25036e5b Call-ID: 78d336b528317931038c1018597afde8@10.100.5.99 CSeq: 102 INVITE User-Agent: Grandstream BT100 1.0.5.3 Content-Length: 0 8 headers, 0 lines    -- SIP/100-eb80 is ringing server*CLI> Sip read: SIP/2.0 200 OK Via: SIP/2.0/UDP 10.100.5.99:5060;branch=z9hG4bK752d69e1 From: "5036617026" <sip:5036617026@10.100.5.99>;tag=as38e274fa To: <sip:100@10.100.5.33>;tag=89a3ff5c25036e5b Call-ID: 78d336b528317931038c1018597afde8@10.100.5.99 CSeq: 102 INVITE User-Agent: Grandstream BT100 1.0.5.3 Contact: <sip:100@10.100.5.33;user=phone> Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE Content-Type: application/sdp Content-Length: 140 v=0 o=100 8000 8000 IN IP4 10.100.5.33 s=SIP Call c=IN IP4 10.100.5.33 t=0 0 m=audio 5004 RTP/AVP 0 a=rtpmap:0 PCMU/8000 a=ptime:20 11 headers, 8 lines Found RTP audio format 0 Peer RTP is at port 10.100.5.33:0 Found description format PCMU Capabilities: us - 0xc(ULAW|ALAW), peer - audio=0x4(ULAW)/video=0x0(EMPTY), combined - 0x4(ULAW) Non-codec capabilities: us - 0x1(G723), peer - 0x0(EMPTY), combined - 0x0(EMPTY) list_route: hop: <sip:100@10.100.5.33;user=phone> set_destination: Parsing <sip:100@10.100.5.33;user=phone> for address/port to send to set_destination: set destination to 10.100.5.33, port 5060 Transmitting: ACK sip:100@10.100.5.33 SIP/2.0 Via: SIP/2.0/UDP 10.100.5.99:5060;branch=z9hG4bK573c31fa From: "5036617026" <sip:5036617026@10.100.5.99>;tag=as38e274fa To: <sip:100@10.100.5.33>;tag=89a3ff5c25036e5b Contact: <sip:5036617026@10.100.5.99> Call-ID: 78d336b528317931038c1018597afde8@10.100.5.99 CSeq: 102 ACK User-Agent: Asterisk PBX Content-Length: 0 (no NAT) to 10.100.5.33:5060    -- SIP/100-eb80 answered SIP/147.135.0.129-081423f0    -- Attempting native bridge of SIP/147.135.0.129-081423f0 and SIP/100-eb80    -- Attempting native bridge of SIP/147.135.0.129-081423f0 and SIP/100-eb80 Jul  1 22:30:21 WARNING[16400]: chan_sip.c:1800 sip_write: Asked to transmit frame type 64, while native formats is 4 (read/write = 4/4) set_destination: Parsing <sip:100@10.100.5.33;user=phone> for address/port to send to set_destination: set destination to 10.100.5.33, port 5060 Reliably Transmitting: BYE sip:100@10.100.5.33 SIP/2.0 Via: SIP/2.0/UDP 10.100.5.99:5060;branch=z9hG4bK14d9077f From: "5036617026" <sip:5036617026@10.100.5.99>;tag=as38e274fa To: <sip:100@10.100.5.33>;tag=89a3ff5c25036e5b Contact: <sip:5036617026@10.100.5.99> Call-ID: 78d336b528317931038c1018597afde8@10.100.5.99 CSeq: 103 BYE User-Agent: Asterisk PBX Content-Length: 0 (no NAT) to 10.100.5.33:5060  == Spawn extension (mainmenu, 2, 3) exited non-zero on 'SIP/147.135.0.129-081423f0' set_destination: Parsing <sip:147.135.0.128:5060;transport=udp> for address/port to send to set_destination: set destination to 147.135.0.128, port 5060 Reliably Transmitting: BYE sip:147.135.0.128:5060 SIP/2.0 Via: SIP/2.0/UDP 24.20.148.108:5060;branch=z9hG4bK04234c25;rport From: "Christopher Shaw"<sip:5039145839@sip.broadvoice.com;user=phone>;tag=as4f1b32f5 To: <sip:5036617026@147.135.0.129;user=phone>;tag=SD38bk801-1739408890-1088746209737 Contact: <sip:s@24.20.148.108> Call-ID: SD38bk801-6eba26ecd430afcb0d4dbe428b34c353-js11002 CSeq: 102 BYE User-Agent: Asterisk PBX Content-Length: 0 (no NAT) to 147.135.0.128:5060 server*CLI> Sip read: SIP/2.0 200 OK Via: SIP/2.0/UDP 10.100.5.99:5060;branch=z9hG4bK14d9077f From: "5036617026" <sip:5036617026@10.100.5.99>;tag=as38e274fa To: <sip:100@10.100.5.33>;tag=89a3ff5c25036e5b Call-ID: 78d336b528317931038c1018597afde8@10.100.5.99 CSeq: 103 BYE User-Agent: Grandstream BT100 1.0.5.3 Contact: <sip:100@10.100.5.33;user=phone> Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE Content-Length: 0 10 headers, 0 lines Destroying call '78d336b528317931038c1018597afde8@10.100.5.99' server*CLI> Sip read: SIP/2.0 200 OK Via: SIP/2.0/UDP 24.20.148.108:5060;received=24.20.148.108;branch=z9hG4bK04234c25;rport From: "Christopher Shaw"<sip:5039145839@sip.broadvoice.com;user=phone>;tag=as4f1b32f5 To: <sip:5036617026@147.135.0.129;user=phone>;tag=SD38bk801-1739408890-1088746209737 Call-ID: SD38bk801-6eba26ecd430afcb0d4dbe428b34c353-js11002 CSeq: 102 BYE Content-Length: 0 7 headers, 0 lines Message is BYE Destroying call 'SD38bk801-6eba26ecd430afcb0d4dbe428b34c353-js11002' 11 headers, 0 lines Reliably Transmitting: REGISTER sip:sip.broadvoice.com SIP/2.0 Via: SIP/2.0/UDP 24.20.148.108:5060;branch=z9hG4bK5d806c94 From: <sip:5039145839@sip.broadvoice.com>;tag=as76ae406b To: <sip:5039145839@sip.broadvoice.com> Call-ID: 79e2a9e37545e146515f007c5bd062c2@10.100.5.99 CSeq: 118 REGISTER User-Agent: Asterisk PBX Expires: 10 Contact: <sip:s@24.20.148.108> Event: registration Content-Length: 0 (no NAT) to 147.135.0.129:5060 11 headers, 0 lines Reliably Transmitting: OPTIONS sip:147.135.0.129 SIP/2.0 Via: SIP/2.0/UDP 24.20.148.108:5060;branch=z9hG4bK25a20fa9 From: "asterisk" <sip:asterisk@24.20.148.108>;tag=as5976fdb3 To: <sip:147.135.0.129> Contact: <sip:asterisk@24.20.148.108> Call-ID: 0e798916052492e91e13f03569fe913e@24.20.148.108 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Date: Fri, 02 Jul 2004 05:30:23 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER Content-Length: 0 (no NAT) to 147.135.0.129:5060 server*CLI> Sip read: SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 24.20.148.108:5060;branch=z9hG4bK5d806c94 From: <sip:5039145839@sip.broadvoice.com>;tag=as76ae406b To: <sip:5039145839@sip.broadvoice.com>;tag=SD3opu999- Call-ID: 79e2a9e37545e146515f007c5bd062c2@10.100.5.99 CSeq: 118 REGISTER WWW-Authenticate: DIGEST realm="BroadWorks",algorithm=MD5,nonce="1088746223663" Content-Length: 0 8 headers, 0 lines 12 headers, 0 lines Reliably Transmitting: REGISTER sip:sip.broadvoice.com SIP/2.0 Via: SIP/2.0/UDP 24.20.148.108:5060;branch=z9hG4bK2de93932 From: <sip:5039145839@sip.broadvoice.com>;tag=as76ae406b To: <sip:5039145839@sip.broadvoice.com> Call-ID: 79e2a9e37545e146515f007c5bd062c2@10.100.5.99 CSeq: 119 REGISTER User-Agent: Asterisk PBX Authorization: Digest username="5039145839", realm="BroadWorks", algorithm="MD5", uri="sip:sip.broadvoice.com", nonce="1088746223663", response="d4988f0afe76e56527a6455625e1ba19", opaque="" Expires: 10 Contact: <sip:s@24.20.148.108> Event: registration Content-Length: 0 (no NAT) to 147.135.0.129:5060 server*CLI> Sip read: SIP/2.0 200 OK Via: SIP/2.0/UDP 24.20.148.108:5060;branch=z9hG4bK25a20fa9 From: "asterisk" <sip:asterisk@24.20.148.108>;tag=as5976fdb3 To: <sip:147.135.0.129>;tag=SD3ol3799- Call-ID: 0e798916052492e91e13f03569fe913e@24.20.148.108 CSeq: 102 OPTIONS Accept: application/sdp,application/broadsoft,text/plain Allow: ACK,BYE,CANCEL,INFO,INVITE,MESSAGE,OPTIONS,PRACK,REFER,REGISTER,SUBSCRIBE,NOTIFY Supported: 100rel Content-Length: 0 10 headers, 0 lines Destroying call '0e798916052492e91e13f03569fe913e@24.20.148.108' server*CLI> Sip read: SIP/2.0 200 OK Via: SIP/2.0/UDP 24.20.148.108:5060;branch=z9hG4bK2de93932 From: <sip:5039145839@sip.broadvoice.com>;tag=as76ae406b To: <sip:5039145839@sip.broadvoice.com>;tag=SD3opu999- Call-ID: 79e2a9e37545e146515f007c5bd062c2@10.100.5.99 CSeq: 119 REGISTER Contact: <sip:s@24.20.148.108>;q=0.5;expires=9 Content-Length: 0 8 headers, 0 lines Destroying call '79e2a9e37545e146515f007c5bd062c2@10.100.5.99' By: cshaw59 (cshaw59) 2004-07-02 01:21:04 Tried twice more, it seemed that restarting * made it work, I had success 2 times, but then it stopped and no more... Very strange By: Alberto Fernandez (derkommissar) 2004-07-02 17:22:05 Im having the same Problem. bkw_ told me that there was a patch for this issue untill is fixed. I have the same problem and my calls are originated from PSTN to a CISCO as3800 then to asterisk. all ULAW, Including my grandstream phone witch is using ULAW. Can this patch be e-mailed to me: afernandez@xynergia.net Thanks Jul  2 17:51:21 WARNING[-1242326096]: chan_sip.c:1718 sip_write: &#65533;&#65533;Asked to transmit frame type 64, while native formats is 4 (read/write = 4/4) edited on: 07-02-04 17:10 By: Mark Spencer (markster) 2004-07-03 18:53:43 Sounds like a locking issue.  Perhaps when I have a realible net connection someone can find me on IRC so I can straighten it out. By: cshaw59 (cshaw59) 2004-07-06 11:52:11 What do you mean by locking? Like file locks? Should I try another kernel? Using 2.4.24 right now... By: cshaw59 (cshaw59) 2004-07-06 17:24:47 Also I should have mentioned this WAY earlier, as you can see from my debug output that the * server as well as the BT101 are behind a NAT. The reason I'm using NAT=no though is because I have UDP Port 5060 as well as my RTP Port range 40000-60000 DNATed to the * server. This really shouldn't make a difference but for a complete bugreport you should know my net topology err... netology.... whatever... By: cshaw59 (cshaw59) 2004-07-06 22:58:46 Duhhhh Nevermind, you're talking about the mutex lock, in the declaration right below where the error occours in chan_sip? ast_mutex_unlock(&p->lock); right? edited on: 07-06-04 22:45 By: cshaw59 (cshaw59) 2004-07-08 00:28:49 Dunno about anyone else but this seems to be resolved in today's CVS as of 8:00 PM PDT (GMT -7) Anyone else tried? By: Mark Spencer (markster) 2004-07-08 03:05:22 Yah definitely should be fixed.