[Home]

Summary:ASTERISK-15278: Error in ulaw
Reporter:Scott Johnson (globalnetinc)Labels:
Date Opened:2009-12-04 22:50:56.000-0600Date Closed:2011-06-07 14:01:08
Priority:MajorRegression?No
Status:Closed/CompleteComponents:Codecs/codec_ulaw
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:
Description:Every since upgrade from prior version 1.6.1.X we see these errors in the debug log:
chan_sip.c: Bogus frame of format 'ulaw' received from 'SIP/4065877430-0000036d'!

These are Linksys ATAs 2102 running 5.2.10 of code
Comments:By: Scott Johnson (globalnetinc) 2009-12-04 23:04:49.000-0600

[Dec  4 20:49:42] DEBUG[31449] chan_sip.c: Acked pending invite 102
[Dec  4 20:49:42] DEBUG[31449] chan_sip.c: Stopping retransmission on '52be476b6a335d06472f3ff13b398387@216.166.168.4' of Request 102: Match Found
[Dec  4 20:49:42] DEBUG[31449] chan_sip.c: We're settling with these formats: 0x4 (ulaw)
[Dec  4 20:49:42] DEBUG[31449] chan_sip.c: build_route: Contact hop: <sip:18663637172@66.62.196.101:5060;transport=udp>
[Dec  4 20:49:42] DEBUG[31449] chan_sip.c: Session-Expires: 1800
[Dec  4 20:49:42] DEBUG[31449] chan_sip.c: Refresher: UAC
[Dec  4 20:49:42] DEBUG[31449] chan_sip.c: Session timer started: 48863 - 52be476b6a335d06472f3ff13b398387@216.166.168.4
[Dec  4 20:49:42] DEBUG[31449] chan_sip.c: Trying to put 'ACK sip:186' onto UDP socket destined for 66.62.196.101:5060
[Dec  4 20:49:42] DEBUG[6545] chan_sip.c: SIP answering channel: SIP/4063881619-00000352
[Dec  4 20:49:42] DEBUG[6545] chan_sip.c: ** Our capability: 0x900 (g726|g729) Video flag: True Text flag: True
[Dec  4 20:49:42] DEBUG[6545] chan_sip.c: ** Our prefcodec: 0x0 (nothing)
[Dec  4 20:49:42] DEBUG[6545] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 172.16.0.72:5060
[Dec  4 20:49:42] DEBUG[31449] chan_sip.c: Stopping retransmission on '2cb37ef-4211a5ad@192.168.255.2' of Response 102: Match Found
[Dec  4 20:49:48] DEBUG[6545] chan_sip.c: Bogus frame of format 'ulaw' received from 'SIP/4063881619-00000352'!
[Dec  4 20:49:48] DEBUG[31449] chan_sip.c: Setting framing for 4 to 20
[Dec  4 20:49:48] DEBUG[31449] chan_sip.c: Setting framing for 2 to 20
[Dec  4 20:49:48] DEBUG[31449] chan_sip.c: Setting framing for 1 to 20
[Dec  4 20:49:48] DEBUG[31449] chan_sip.c: Setting framing for 32 to 20
[Dec  4 20:49:48] DEBUG[31449] chan_sip.c: Setting framing for 32 to 20
[Dec  4 20:49:48] DEBUG[31449] chan_sip.c: Setting framing for 128 to 20
[Dec  4 20:49:48] DEBUG[31449] chan_sip.c: Setting framing for 8 to 20
[Dec  4 20:49:48] DEBUG[31449] chan_sip.c: Setting framing for 4096 to 20
[Dec  4 20:49:48] DEBUG[31449] chan_sip.c: Setting framing for 64 to 20
[Dec  4 20:49:48] DEBUG[31449] chan_sip.c: Setting framing for 64 to 20
[Dec  4 20:49:48] DEBUG[31449] chan_sip.c: Setting framing for 32 to 20
[Dec  4 20:49:48] DEBUG[31449] chan_sip.c: Setting framing for 32 to 20
[Dec  4 20:49:48] DEBUG[31449] chan_sip.c: Setting framing for 256 to 20
[Dec  4 20:49:48] DEBUG[31449] chan_sip.c: Setting framing for 65536 to 20
[Dec  4 20:49:48] DEBUG[31449] chan_sip.c: Setting framing for 262144 to 20
[Dec  4 20:49:48] DEBUG[31449] chan_sip.c: Setting framing for 524288 to 20
[Dec  4 20:49:48] DEBUG[31449] chan_sip.c: Setting framing for 1024 to 20
[Dec  4 20:49:48] DEBUG[31449] chan_sip.c: Setting framing for 1048576 to 20
[Dec  4 20:49:48] DEBUG[31449] chan_sip.c: Setting framing for 2097152 to 20
[Dec  4 20:49:48] DEBUG[31449] chan_sip.c: Setting framing for 1048576 to 20
[Dec  4 20:49:48] DEBUG[31449] chan_sip.c: Setting framing for 4194304 to 20
[Dec  4 20:49:48] DEBUG[31449] chan_sip.c: Setting framing for 67108864 to 20
[Dec  4 20:49:48] DEBUG[31449] chan_sip.c: Setting framing for 134217728 to 20
[Dec  4 20:49:48] DEBUG[31449] chan_sip.c: Setting framing for 512 to 20
[Dec  4 20:49:48] DEBUG[31449] chan_sip.c: Setting framing for 2048 to 20
[Dec  4 20:49:48] DEBUG[31449] chan_sip.c: Setting framing for 16 to 20
[Dec  4 20:49:48] DEBUG[31449] chan_sip.c: Trying to put 'SIP/2.0 488' onto UDP socket destined for 172.16.0.72:5060
[Dec  4 20:49:48] DEBUG[31449] chan_sip.c: SIP message could not be handled, bad request: 2cb37ef-4211a5ad@192.168.255.2
[Dec  4 20:49:49] DEBUG[6545] chan_sip.c: Bogus frame of format 'ulaw' received from 'SIP/4063881619-00000352'!
[Dec  4 20:49:49] DEBUG[31449] chan_sip.c: Stopping retransmission on '2cb37ef-4211a5ad@192.168.255.2' of Response 103: Match Found
[Dec  4 20:49:49] DEBUG[6545] chan_sip.c: Bogus frame of format 'ulaw' received from 'SIP/4063881619-00000352'!
[Dec  4 20:49:49] DEBUG[6545] chan_sip.c: Bogus frame of format 'ulaw' received from 'SIP/4063881619-00000352'!
[Dec  4 20:49:49] DEBUG[6545] chan_sip.c: Bogus frame of format 'ulaw' received from 'SIP/4063881619-00000352'!
[Dec  4 20:49:49] DEBUG[6545] chan_sip.c: Bogus frame of format 'ulaw' received from 'SIP/4063881619-00000352'!
[Dec  4 20:49:49] DEBUG[6545] chan_sip.c: Bogus frame of format 'ulaw' received from 'SIP/4063881619-00000352'!
[Dec  4 20:49:49] DEBUG[6545] chan_sip.c: Bogus frame of format 'ulaw' received from 'SIP/4063881619-00000352'!
[Dec  4 20:49:49] DEBUG[6545] chan_sip.c: Bogus frame of format 'ulaw' received from 'SIP/4063881619-00000352'!
[Dec  4 20:49:49] DEBUG[6545] chan_sip.c: Bogus frame of format 'ulaw' received from 'SIP/4063881619-00000352'!
[Dec  4 20:49:49] DEBUG[6545] chan_sip.c: Bogus frame of format 'ulaw' received from 'SIP/4063881619-00000352'!
[Dec  4 20:49:49] DEBUG[6545] chan_sip.c: Bogus frame of format 'ulaw' received from 'SIP/4063881619-00000352'!
[Dec  4 20:49:49] DEBUG[6545] chan_sip.c: Bogus frame of format 'ulaw' received from 'SIP/4063881619-00000352'!
[Dec  4 20:49:49] DEBUG[6545] chan_sip.c: Bogus frame of format 'ulaw' received from 'SIP/4063881619-00000352'!
[Dec  4 20:49:49] DEBUG[6545] chan_sip.c: Bogus frame of format 'ulaw' received from 'SIP/4063881619-00000352'!
[Dec  4 20:49:49] DEBUG[6545] chan_sip.c: Bogus frame of format 'ulaw' received from 'SIP/4063881619-00000352'!
..........
..........
[Dec  4 20:49:52] DEBUG[6545] chan_sip.c: Bogus frame of format 'ulaw' received from 'SIP/4063881619-00000352'!
[Dec  4 20:49:52] DEBUG[6545] chan_sip.c: Bogus frame of format 'ulaw' received from 'SIP/4063881619-00000352'!
[Dec  4 20:49:52] DEBUG[6545] chan_sip.c: Bogus frame of format 'ulaw' received from 'SIP/4063881619-00000352'!
[Dec  4 20:49:52] DEBUG[6545] chan_sip.c: Bogus frame of format 'ulaw' received from 'SIP/4063881619-00000352'!
[Dec  4 20:49:52] DEBUG[31449] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 172.16.0.72:5060
[Dec  4 20:49:52] DEBUG[6545] channel.c: Didn't get a frame from channel: SIP/4063881619-00000352
[Dec  4 20:49:52] DEBUG[6545] channel.c: Bridge stops bridging channels SIP/4063881619-00000352 and SIP/VoIP360Residential-00000353
[Dec  4 20:49:52] DEBUG[6545] cdr_addon_mysql.c: Inserting a CDR record.
[Dec  4 20:49:52] DEBUG[6545] cdr_addon_mysql.c: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposit
ion,amaflags,accountcode,uniqueid) VALUES ('2009-12-04 20:49:32','"Robert Weiman" <4063881619>','4063881619','18663637172','from-inside-redir','SIP/4063881619-00000352','SIP/VoIP360R
esidential-00000353','Dial','SIP/18663637172@VoIP360Residential,60','20','10','ANSWERED','2','172.16.0.72','1259984972.898')
[Dec  4 20:49:52] DEBUG[6545] channel.c: Hanging up channel 'SIP/VoIP360Residential-00000353'
[Dec  4 20:49:52] DEBUG[6545] chan_sip.c: Hangup call SIP/VoIP360Residential-00000353, SIP callid 52be476b6a335d06472f3ff13b398387@216.166.168.4
[Dec  4 20:49:52] DEBUG[6545] chan_sip.c: Session timer stopped: -1 - 52be476b6a335d06472f3ff13b398387@216.166.168.4
[Dec  4 20:49:52] DEBUG[6545] chan_sip.c: Trying to put 'BYE sip:186' onto UDP socket destined for 66.62.196.101:5060
[Dec  4 20:49:52] DEBUG[6545] rtp.c: Channel '<unspecified>' has no RTP, not doing anything
[Dec  4 20:49:52] DEBUG[6545] app_dial.c: Exiting with DIALSTATUS=ANSWER.
[Dec  4 20:49:52] DEBUG[6545] app_macro.c: Spawn extension (macro-tl-dialout-base,dial-SIP,11) exited non-zero on 'SIP/4063881619-00000352' in macro 'tl-dialout-base'
[Dec  4 20:49:52] DEBUG[6545] app_macro.c: Spawn extension (macro-tl-dialout-1-trunk,s,3) exited non-zero on 'SIP/4063881619-00000352' in macro 'tl-dialout-1-trunk'
[Dec  4 20:49:52] DEBUG[6545] pbx.c: Spawn extension (from-inside-redir,18663637172,1) exited non-zero on 'SIP/4063881619-00000352'
[Dec  4 20:49:52] DEBUG[6545] channel.c: Soft-Hanging up channel 'SIP/4063881619-00000352'
[Dec  4 20:49:52] DEBUG[6545] pbx.c: Launching 'Hangup'
[Dec  4 20:49:52] DEBUG[6545] pbx.c: Spawn extension (from-inside-redir,h,1) exited non-zero on 'SIP/4063881619-00000352'
[Dec  4 20:49:52] DEBUG[6545] channel.c: Hanging up channel 'SIP/4063881619-00000352'
[Dec  4 20:49:52] DEBUG[6545] chan_sip.c: Hangup call SIP/4063881619-00000352, SIP callid 2cb37ef-4211a5ad@192.168.255.2
[Dec  4 20:49:52] DEBUG[31449] chan_sip.c: Stopping retransmission on '52be476b6a335d06472f3ff13b398387@216.166.168.4' of Request 103: Match Found
[Dec  4 20:49:52] DEBUG[31449] chan_sip.c:
---------- SIP HISTORY for '2cb37ef-4211a5ad@192.168.255.2'
[Dec  4 20:49:52] DEBUG[31449] chan_sip.c:   * SIP Call
[Dec  4 20:49:52] DEBUG[31449] chan_sip.c:   001. Rx              INVITE / 101 INVITE / sip:18663637172@172.16.0.4
[Dec  4 20:49:52] DEBUG[31449] chan_sip.c:   002. AuthChal        Auth challenge sent for  - nc 0
[Dec  4 20:49:52] DEBUG[31449] chan_sip.c:   003. TxRespRel       SIP/2.0 / 101 INVITE - 401 Unauthorized
[Dec  4 20:49:52] DEBUG[31449] chan_sip.c:   004. SchedDestroy    6400 ms
[Dec  4 20:49:52] DEBUG[31449] chan_sip.c:   005. Rx              INVITE / 101 INVITE / sip:18663637172@172.16.0.4
[Dec  4 20:49:52] DEBUG[31449] chan_sip.c:   006. Rx              INVITE / 101 INVITE / sip:18663637172@172.16.0.4
[Dec  4 20:49:52] DEBUG[31449] chan_sip.c:   007. Rx              ACK / 101 ACK / sip:18663637172@172.16.0.4
[Dec  4 20:49:52] DEBUG[31449] chan_sip.c:   008. Rx              INVITE / 102 INVITE / sip:18663637172@172.16.0.4
[Dec  4 20:49:52] DEBUG[31449] chan_sip.c:   009. CancelDestroy
[Dec  4 20:49:52] DEBUG[31449] chan_sip.c:   010. Invite          New call: 2cb37ef-4211a5ad@192.168.255.2
[Dec  4 20:49:52] DEBUG[31449] chan_sip.c:   011. AuthOK          Auth challenge succesful for 4063881619
[Dec  4 20:49:52] DEBUG[31449] chan_sip.c:   012. NewChan         Channel SIP/4063881619-00000352 - from 2cb37ef-4211a5ad@192.168
[Dec  4 20:49:52] DEBUG[31449] chan_sip.c:   013. TxResp          SIP/2.0 / 102 INVITE - 100 Trying
[Dec  4 20:49:52] DEBUG[31449] chan_sip.c:   014. TxResp          SIP/2.0 / 102 INVITE - 183 Session Progress
[Dec  4 20:49:52] DEBUG[31449] chan_sip.c:   015. TxRespRel       SIP/2.0 / 102 INVITE - 200 OK
[Dec  4 20:49:52] DEBUG[31449] chan_sip.c:   016. Rx              ACK / 102 ACK / sip:18663637172@172.16.0.4
[Dec  4 20:49:52] DEBUG[31449] chan_sip.c:   017. Rx              INVITE / 103 INVITE / sip:18663637172@172.16.0.4
[Dec  4 20:49:52] DEBUG[31449] chan_sip.c:   018. TxRespRel       SIP/2.0 / 103 INVITE - 488 Not acceptable here
[Dec  4 20:49:52] DEBUG[31449] chan_sip.c:   019. Rx              ACK / 103 ACK / sip:18663637172@172.16.0.4
[Dec  4 20:49:52] DEBUG[31449] chan_sip.c:   020. Rx              BYE / 104 BYE / sip:18663637172@172.16.0.4
[Dec  4 20:49:52] DEBUG[31449] chan_sip.c:   021. RTCPaudio       Quality:ssrc=1499011858;themssrc=4255752317;rxjitter=0.010603;r
[Dec  4 20:49:52] DEBUG[31449] chan_sip.c:   022. RTCPaudioJitter Quality:rxjitter=0.010603;
[Dec  4 20:49:52] DEBUG[31449] chan_sip.c:   023. RTCPaudioLoss   Quality:lost=0;expected=880;
[Dec  4 20:49:52] DEBUG[31449] chan_sip.c:   024. RTCPaudioRTT    Quality:Not available
[Dec  4 20:49:52] DEBUG[31449] chan_sip.c:   025. TxResp          SIP/2.0 / 104 BYE - 200 OK
[Dec  4 20:49:52] DEBUG[31449] chan_sip.c:   026. Hangup          Cause Normal Clearing
[Dec  4 20:49:52] DEBUG[31449] chan_sip.c:
---------- END SIP HISTORY for '2cb37ef-4211a5ad@192.168.255.2'
By: David Woolley (davidw) 2009-12-06 04:42:04.000-0600

This is a SIP issue, not a codec issue.  Please follow the SIP problem reporting procedures (including sip set debug output).

The message is not saying that there is any error in the handling of ulaw.  It is actually saying that it has received an RTP frame, containing ulaw encoded data, when it hasn't actually agreed that ulaw is an acceptable format for the session.

What is actually going wrong, as issues should not be reported purely on the basis of  messages output when debug logging is turned on.  Why did you turn on debug logging?
By: Elazar Broad (ebroad) 2009-12-07 10:50:29.000-0600

Thanks David!
By: Leif Madsen (lmadsen) 2010-01-07 11:08:34.000-0600

Closed due to lack of feedback. Please reopen when you have the requested information to attach.