[Home]

Summary:ASTERISK-24691: Asterisk tries to transcode between g722 & h264
Reporter:Mark Farmer (farmorg)Labels:
Date Opened:2015-01-15 06:07:10.000-0600Date Closed:2015-03-12 13:33:35
Priority:MajorRegression?
Status:Closed/CompleteComponents:Channels/chan_sip/CodecHandling
Versions:13.1.0 Frequency of
Occurrence		Constant
Related
Issues:
Environment:CentOS 6.6Attachments:( 0) myDebugLog.gz
( 1) sip.conf
Description:With the following codecs on SIP peers:

disallow = all
allow = g722,ulaw,alaw,h264

When we try to originate a call via AMI or transfer a call that was answered via a queue, Asterisk seems to try to use h264 and transcode between g722 & h264.

Console output:
{noformat}
 -- Called SIP/6059
   -- Local/6059@GageAgent-00000032;1 connected line has changed. Saving it until answer for SIP/ph-sip03-gn-lon1-0000008b
   -- SIP/6059-0000008c is ringing
   -- Local/6059@GageAgent-00000032;1 is ringing
   -- SIP/6059-0000008c answered Local/6059@GageAgent-00000032;2
   -- Local/6059@GageAgent-00000032;1 answered SIP/ph-sip03-gn-lon1-0000008b
   -- Channel Local/6059@GageAgent-00000032;2 joined 'simple_bridge' basic-bridge <2765d56b-fcb8-46b5-8d83-7866feea3196>
   -- Stopped music on hold on SIP/ph-sip03-gn-lon1-0000008b
   -- Channel SIP/6059-0000008c joined 'simple_bridge' basic-bridge <2765d56b-fcb8-46b5-8d83-7866feea3196>
   -- Channel SIP/ph-sip03-gn-lon1-0000008b joined 'simple_bridge' basic-bridge <70114587-b1d8-46a0-9f4e-ad77ed10da51>
   -- Channel Local/6059@GageAgent-00000032;1 joined 'simple_bridge' basic-bridge <70114587-b1d8-46a0-9f4e-ad77ed10da51>
   -- SIP/6032-0000008e is ringing
   -- SIP/6032-0000008e answered SIP/6059-0000008d
   -- Channel SIP/6059-0000008d joined 'simple_bridge' basic-bridge <92d9bf20-c496-4b6c-86bf-2919395a56bf>
   -- Channel SIP/6032-0000008e joined 'simple_bridge' basic-bridge <92d9bf20-c496-4b6c-86bf-2919395a56bf>
   -- Channel Local/6059@GageAgent-00000032;2 left 'simple_bridge' basic-bridge <2765d56b-fcb8-46b5-8d83-7866feea3196>
   -- Channel Local/6059@GageAgent-00000032;2 swapped with SIP/6059-0000008d into 'native_rtp' basic-bridge <92d9bf20-c496-4b6c-86bf-2919395a56bf>
   -- Stopped music on hold on Local/6059@GageAgent-00000032;2
   -- Channel SIP/6059-0000008d left 'native_rtp' basic-bridge <92d9bf20-c496-4b6c-86bf-2919395a56bf>
   -- Channel SIP/6059-0000008c left 'simple_bridge' basic-bridge <2765d56b-fcb8-46b5-8d83-7866feea3196>
 == Spawn extension (DLPN_All, 6032, 50006) exited non-zero on 'SIP/6059-0000008d'
[2015-01-15 09:29:05] WARNING[19055][C-0000007f]: channel.c:5070 ast_write: Codec mismatch on channel SIP/6032-0000008e setting write format to ulaw from slin16 native formats (g722|h264)
[2015-01-15 09:29:05] WARNING[19055][C-0000007f]: channel.c:5070 ast_write: Codec mismatch on channel SIP/6032-0000008e setting write format to slin16 from ulaw native formats (g722|h264)
   -- Registered SIP '6147' at xxx.xxx.xxx.xxx:61292
   -- Registered SIP '6147' at xxx.xxx.xxx.xxx:8029
   -- Channel SIP/ph-sip03-gn-lon1-0000008b left 'simple_bridge' basic-bridge <70114587-b1d8-46a0-9f4e-ad77ed10da51>
   -- Channel Local/6059@GageAgent-00000032;1 left 'simple_bridge' basic-bridge <70114587-b1d8-46a0-9f4e-ad77ed10da51>
 == Spawn extension (voicemenu-custom-19, s, 5) exited non-zero on 'SIP/ph-sip03-gn-lon1-0000008b'
   -- Channel Local/6059@GageAgent-00000032;2 left 'simple_bridge' basic-bridge <92d9bf20-c496-4b6c-86bf-2919395a56bf>
 == MixMonitor close filestream (mixed)
 == End MixMonitor Recording SIP/ph-sip03-gn-lon1-0000008b
{noformat}
Comments:By: Mark Farmer (farmorg) 2015-01-15 06:10:00.689-0600

Possibly related to ASTERISK-24380 and/or ASTERISK-21777 ?
By: Matt Jordan (mjordan) 2015-01-15 19:42:41.918-0600

We require a complete debug log to help triage the issue. This document will provide instructions on how to collect debugging logs from an Asterisk machine for the purpose of helping bug marshals troubleshoot an issue: https://wiki.asterisk.org/wiki/display/AST/Collecting+Debug+Information

Please provide your full 'sip.conf' as well.
By: Mark Farmer (farmorg) 2015-01-19 10:41:24.141-0600

Thanks for the info, we will get this info ASAP.
By: Mark Farmer (farmorg) 2015-01-22 10:56:01.111-0600

Please find attached debug log file.
One of our engineers has extracted the following from the debug log, hopefully it will help to identify & solve the problem.

{noformat}
[2015-01-21 15:08:10] DEBUG[12273][C-00000031] chan_sip.c: Processing session-level SDP b=AS:128... UNSUPPORTED OR FAILED.
[2015-01-21 15:08:10] DEBUG[12273][C-00000031] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED.
[2015-01-21 15:08:10] DEBUG[12273][C-00000031] chan_sip.c: Processing session-level SDP a=sendrecv... OK.
[2015-01-21 15:08:10] VERBOSE[12273][C-00000031] chan_sip.c: Found RTP audio format 9
[2015-01-21 15:08:10] DEBUG[12273][C-00000031] rtp_engine.c: Setting payload 9 (0x7fd1680a71e8) based on m type on 0x7fd11bed6840
[2015-01-21 15:08:10] VERBOSE[12273][C-00000031] chan_sip.c: Found RTP audio format 101
[2015-01-21 15:08:10] DEBUG[12273][C-00000031] rtp_engine.c: Setting payload 101 (0x7fd168513a48) based on m type on 0x7fd11bed6840
[2015-01-21 15:08:10] VERBOSE[12273][C-00000031] chan_sip.c: Found audio description format G722 for ID 9
[2015-01-21 15:08:10] DEBUG[12273][C-00000031] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:9 G722/8000... OK.
[2015-01-21 15:08:10] VERBOSE[12273][C-00000031] chan_sip.c: Found audio description format telephone-event for ID 101
[2015-01-21 15:08:10] DEBUG[12273][C-00000031] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK.
[2015-01-21 15:08:10] DEBUG[12273][C-00000031] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK.
[2015-01-21 15:08:10] VERBOSE[12273][C-00000031] chan_sip.c: Found RTP video format 99
[2015-01-21 15:08:10] DEBUG[12273][C-00000031] rtp_engine.c: Setting payload 99 (0x7fd168513a48) based on m type on 0x7fd11bed67d0
[2015-01-21 15:08:10] VERBOSE[12273][C-00000031] chan_sip.c: Found video description format H264 for ID 99
[2015-01-21 15:08:10] DEBUG[12273][C-00000031] chan_sip.c: Processing media-level (video) SDP a=rtpmap:99 H264/90000... OK.
[2015-01-21 15:08:10] DEBUG[12273][C-00000031] chan_sip.c: Processing media-level (video) SDP a=fmtp:99 profile-level-id=42800d... OK.
[2015-01-21 15:08:10] DEBUG[12273][C-00000031] chan_sip.c: Processing media-level (video) SDP a=sendrecv... UNSUPPORTED OR FAILED.
[2015-01-21 15:08:10] VERBOSE[12273][C-00000031] chan_sip.c: Capabilities: us - (g722|ulaw|alaw|h264), peer - audio=(g722)/video=(h264)/text=(nothing), combined - (g722|h264)
[2015-01-21 15:08:10] VERBOSE[12273][C-00000031] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|)
[2015-01-21 15:08:10] DEBUG[12273][C-00000031] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fd1b806fc98'
[2015-01-21 15:08:10] VERBOSE[12273][C-00000031] chan_sip.c: Peer audio RTP is at port 192.168.5.49:10028
[2015-01-21 15:08:10] DEBUG[12273][C-00000031] rtp_engine.c: Copying payload 9 (0x7fd168484d28) from 0x7fd11bed6840 to 0x7fd1b806fdd8
[2015-01-21 15:08:10] DEBUG[12273][C-00000031] rtp_engine.c: Copying payload 101 (0x7fd1680a71e8) from 0x7fd11bed6840 to 0x7fd1b806fdd8
[2015-01-21 15:08:10] DEBUG[12273][C-00000031] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7fd1b806fc98'
[2015-01-21 15:08:10] DEBUG[12273][C-00000031] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fd1b80d8ff8'
[2015-01-21 15:08:10] VERBOSE[12273][C-00000031] chan_sip.c: Peer video RTP is at port 192.168.5.49:10030
[2015-01-21 15:08:10] DEBUG[12273][C-00000031] rtp_engine.c: Copying payload 99 (0x7fd168279fe8) from 0x7fd11bed67d0 to 0x7fd1b80d9138
[2015-01-21 15:08:10] DEBUG[12273][C-00000031] chan_sip.c: We're settling with these formats: (g722|h264)
[2015-01-21 15:08:10] DEBUG[12273][C-00000031] chan_sip.c: We have an owner, now see if we need to change this call
[2015-01-21 15:08:10] DEBUG[12273][C-00000031] chan_sip.c: Setting native formats after processing SDP. peer joint formats (g722|h264), old nativeformats (g722|h264)
[2015-01-21 15:08:10] DEBUG[12273][C-00000031] chan_sip.c: Updating call counter for outgoing call
[2015-01-21 15:08:10] DEBUG[12211] devicestate.c: No provider found, checking channel drivers for SIP - 6046
[2015-01-21 15:08:10] DEBUG[12273][C-00000031] chan_sip.c: Strict routing enforced for session 674234be5bb2d30827882c3e4d53dcdb@213.216.146.208:5060
[2015-01-21 15:08:10] DEBUG[12211] chan_sip.c: Checking device state for peer 6046
[2015-01-21 15:08:10] DEBUG[12211] devicestate.c: Changing state for SIP/6046 - state 2 (In use)
[2015-01-21 15:08:10] VERBOSE[12273][C-00000031] chan_sip.c: Transmitting (NAT) to 195.59.152.66:20626:
{noformat}
By: Mark Farmer (farmorg) 2015-01-22 10:59:56.791-0600

Also attached sip.conf
Our SIP peers are in users.conf, please let me know if you need to see that too.
By: Rusty Newton (rnewton) 2015-01-30 17:53:28.305-0600

Why don't we see the following messages in your debug log

{noformat}
2015-01-15 09:29:05] WARNING[19055][C-0000007f]: channel.c:5070 ast_write: Codec mismatch on channel SIP/6032-0000008e setting write format to ulaw from slin16 native formats (g722|h264)
[2015-01-15 09:29:05] WARNING[19055][C-0000007f]: channel.c:5070 ast_write: Codec mismatch on channel SIP/6032-0000008e setting write format to slin16 from ulaw native formats (g722|h264)
{noformat}

Are you demonstrating two different scenarios, or did you exclude WARNING logger messages from your log?

Can you verify your debug log has all available log message types enabled (except dtmf,fax,security)?
By: Mark Farmer (farmorg) 2015-02-03 04:31:19.174-0600

Sadly I can't explain why those message are not in the debug log file, this was a single test with the following steps:

Put a call into a queue
Answer the call
Transfer the call to an extension with h264 enabled

I have spoken with the engineer who carried out the debugging and he did include the warning messages.
We will run the debug again ASAP just in case.

By: Rusty Newton (rnewton) 2015-02-03 17:38:23.335-0600

Thanks, remember to press "Send Back" or "Enter Feedback" when you get the new debug.
By: Rusty Newton (rnewton) 2015-02-24 09:01:25.199-0600

Mark, does the issue still occur? We haven't heard from you in a couple weeks.
By: Mark Farmer (farmorg) 2015-03-12 09:11:46.646-0500

Hi, apologies for the delay!
It actually seems to be working in 13.2 but I am not sure why as the change log didn't seem to make any reference to a fix for this.

I do have another issue that might be related though, should I open a new bug for this if we are unable to solve? The new issue is regarding sip video calls to a Polycom rmx2000 video bridge where video is not established between the end points. I downgraded the server to Asterisk 11 & it worked fine.
Are there any known issues around this?

Mark.

By: Rusty Newton (rnewton) 2015-03-12 13:33:26.162-0500

{quote}
Hi, apologies for the delay!
It actually seems to be working in 13.2 but I am not sure why as the change log didn't seem to make any reference to a fix for this.
{quote}

Good, and I'm not sure. Occasionally things slip through or a commit message is not worded well.

{quote}
I do have another issue that might be related though, should I open a new bug for this if we are unable to solve? The new issue is regarding sip video calls to a Polycom rmx2000 video bridge where video is not established between the end points. I downgraded the server to Asterisk 11 & it worked fine.
Are there any known issues around this?
Mark.
{quote}

There are a lot of differences between 11 and 13. Downgrading/upgrading between the two is not always a useful troubleshooting step. As always, if something appears to not be working correctly then you should first presume mis-configuration and pursue it on the asterisk-users mailing list or the Asterisk forums. If others can't help you resolve it and you still think it is a bug then at that point open a new issue on the tracker.