[Home]

Summary:ASTERISK-03182: channel format set wrong on manager redirect
Reporter:k3v (k3v)Labels:
Date Opened:2005-01-04 18:53:25.000-0600Date Closed:2011-06-07 14:10:17
Priority:MinorRegression?No
Status:Closed/CompleteComponents:Channels/chan_sip/CodecHandling
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) sip-debug-cisco-to-polycom.txt
( 1) sip-debug-polycom-to-polycom.txt
Description:This is a strange one.  I'm working on an operator panel that uses Action: redirect to toss calls.  Receptionist is SIP/100.  If I call from another SIP channel (Zap works fine), formats are set to strange values.  I have disallow=all, allow=ulaw (in that order) as the only codecs in my [general] of sip.conf (also tried in each registration's context).  

I do not experience a problem redirecting to another SIP channel, only to Playback() and MusicOnHold().

Here's some goods from debug log.  The first section is a redirect with no ExtraChannel, sending to a Playback().

Jan  4 17:46:25 DEBUG[9502]: Allocating new SIP call for 3ad3667e-974a44c-d42d533b@199.104.120.151
Jan  4 17:46:25 DEBUG[9502]: Setting NAT on RTP to 0
Jan  4 17:46:25 DEBUG[9502]: Check for res for 104
Jan  4 17:46:25 DEBUG[9502]: Call from user '104' is 1 out of 0
Jan  4 17:46:25 DEBUG[9502]: build_route: Record-Route hop: <sip:100@199.104.120.160;ftag=2B11FFEA-74FB6481;lr=on>
Jan  4 17:46:25 DEBUG[9502]: build_route: Contact hop: <sip:104@199.104.120.151>
Jan  4 17:46:25 DEBUG[9502]: Device 'SIP/104' changed to state '2'
Jan  4 17:46:25 DEBUG[9502]: Device 'SIP/104' changed to state '2'
Jan  4 17:46:25 DEBUG[9502]: Launching 'Macro'
Jan  4 17:46:25 DEBUG[9502]: Launching 'Dial'
Jan  4 17:46:25 DEBUG[9502]: Allocating new SIP call for (null)
Jan  4 17:46:25 DEBUG[9502]: Setting NAT on RTP to 0
Jan  4 17:46:25 DEBUG[9502]: Not copying variable STACK-macro-stdexten-s-3.
Jan  4 17:46:25 DEBUG[9502]: Copying soft-transferable variable ALERT_INFO.
Jan  4 17:46:25 DEBUG[9502]: Not copying variable STACK-macro-stdexten-s-2.
Jan  4 17:46:25 DEBUG[9502]: Not copying variable chan.
Jan  4 17:46:25 DEBUG[9502]: Not copying variable STACK-macro-stdexten-s-1.
Jan  4 17:46:25 DEBUG[9502]: Not copying variable ARG3.
Jan  4 17:46:25 DEBUG[9502]: Not copying variable ARG2.
Jan  4 17:46:25 DEBUG[9502]: Not copying variable ARG1.
Jan  4 17:46:25 DEBUG[9502]: Not copying variable MACRO_PRIORITY.
Jan  4 17:46:25 DEBUG[9502]: Not copying variable MACRO_CONTEXT.
Jan  4 17:46:25 DEBUG[9502]: Not copying variable MACRO_EXTEN.
Jan  4 17:46:25 DEBUG[9502]: Not copying variable STACK-office-100-3.
Jan  4 17:46:25 DEBUG[9502]: Not copying variable STACK-office-100-2.
Jan  4 17:46:25 DEBUG[9502]: Not copying variable STACK-office-100-1.
Jan  4 17:46:25 DEBUG[9502]: Not copying variable SIPCALLID.
Jan  4 17:46:25 DEBUG[9502]: Not copying variable SIPUSERAGENT.
Jan  4 17:46:25 DEBUG[9502]: Not copying variable SIPDOMAIN.
Jan  4 17:46:25 DEBUG[9502]: Not copying variable SIPURI.
Jan  4 17:46:25 DEBUG[9502]: Outgoing Call for 100
Jan  4 17:46:25 DEBUG[9502]: Call from user '100' is 1 out of 0
Jan  4 17:46:25 DEBUG[9502]: Set channel SIP/100-5d0d to read format ulaw
Jan  4 17:46:25 DEBUG[9502]: Set channel SIP/104-6875 to write format ulaw
Jan  4 17:46:25 DEBUG[9502]: Set channel SIP/100-5d0d to write format ulaw
Jan  4 17:46:25 DEBUG[9502]: Set channel SIP/104-6875 to read format ulaw
Jan  4 17:46:25 DEBUG[9502]: (Provisional) Stopping retransmission (but retaining packet) on '73fec0181ef6a7c4765fff410257393a@199.104.120.160' Request 102: Found
Jan  4 17:46:25 DEBUG[9502]: (Provisional) Stopping retransmission (but retaining packet) on '73fec0181ef6a7c4765fff410257393a@199.104.120.160' Request 102: Found
Jan  4 17:46:25 DEBUG[9502]: Device 'SIP/100' changed to state '2'
Jan  4 17:46:25 DEBUG[9502]: Device 'SIP/100' changed to state '2'
Jan  4 17:46:27 DEBUG[9502]: Acked pending invite 102
Jan  4 17:46:27 DEBUG[9502]: Stopping retransmission on '73fec0181ef6a7c4765fff410257393a@199.104.120.160' of Request 102: Found
Jan  4 17:46:27 DEBUG[9502]: build_route: Contact hop: <sip:100@199.104.120.154:5060>
Jan  4 17:46:27 DEBUG[9502]: Set channel SIP/104-6875 to read format ulaw
Jan  4 17:46:27 DEBUG[9502]: Set channel SIP/100-5d0d to write format ulaw
Jan  4 17:46:27 DEBUG[9502]: Set channel SIP/104-6875 to write format ulaw
Jan  4 17:46:27 DEBUG[9502]: Set channel SIP/100-5d0d to read format ulaw
Jan  4 17:46:27 DEBUG[9502]: sip_answer(SIP/104-6875)
Jan  4 17:46:27 DEBUG[9502]: Deferring reinvite on '3ad3667e-974a44c-d42d533b@199.104.120.151'
Jan  4 17:46:27 DEBUG[9502]: Stopping retransmission on '3ad3667e-974a44c-d42d533b@199.104.120.151' of Response 1: Found
Jan  4 17:46:27 DEBUG[9502]: Sending pending reinvite on '3ad3667e-974a44c-d42d533b@199.104.120.151'
Jan  4 17:46:27 DEBUG[9502]: (Provisional) Stopping retransmission (but retaining packet) on '3ad3667e-974a44c-d42d533b@199.104.120.151' Request 102: Found
Jan  4 17:46:27 DEBUG[9502]: Ooh, format changed from unknown to ulaw
Jan  4 17:46:27 DEBUG[9502]: Ooh, format changed from unknown to ulaw
Jan  4 17:46:27 DEBUG[9502]: Acked pending invite 103
Jan  4 17:46:27 DEBUG[9502]: Stopping retransmission on '73fec0181ef6a7c4765fff410257393a@199.104.120.160' of Request 103: Found
Jan  4 17:46:27 DEBUG[9502]: build_route: Retaining previous route: <sip:100@199.104.120.154:5060>
Jan  4 17:46:27 DEBUG[9502]: Acked pending invite 102
Jan  4 17:46:27 DEBUG[9502]: Stopping retransmission on '3ad3667e-974a44c-d42d533b@199.104.120.151' of Request 102: Found
Jan  4 17:46:27 DEBUG[9502]: build_route: Record-Route hop: <sip:104@199.104.120.160;ftag=as772a4e4a;lr=on>
Jan  4 17:46:27 DEBUG[9502]: build_route: Contact hop: <sip:104@199.104.120.151>
-----------at this point 104 and 100 can speak----------
Jan  4 17:46:39 DEBUG[9502]: Manager received command 'Redirect'
Jan  4 17:46:39 DEBUG[9502]: Soft-Hanging up channel 'SIP/104-6875'
Jan  4 17:46:39 DEBUG[9502]: Oooh, got a hangup
Jan  4 17:46:39 DEBUG[9502]: Returning from native bridge, channels: SIP/104-6875, SIP/100-5d0d
Jan  4 17:46:39 DEBUG[9502]: Hanging up channel 'SIP/100-5d0d'
Jan  4 17:46:39 DEBUG[9502]: sip_hangup(SIP/100-5d0d)
Jan  4 17:46:39 DEBUG[9502]: update_user_counter(100) - decrement outUse counter
Jan  4 17:46:39 DEBUG[9502]: Exiting with DIALSTATUS=ANSWER.
Jan  4 17:46:39 DEBUG[9502]: Spawn extension (office,8669,0) exited non-zero on 'SIP/104-6875' in macro 'stdexten'
Jan  4 17:46:39 DEBUG[9502]: Spawn extension (office,8669,0) exited non-zero on 'SIP/104-6875'
Jan  4 17:46:39 DEBUG[9502]: Launching 'Playback'  <<-- playing lyrics-louie-louie.gsm
Jan  4 17:46:39 DEBUG[9502]: Device 'SIP/100' changed to state '0'
Jan  4 17:46:39 DEBUG[9502]: Device 'SIP/100' changed to state '0'
Jan  4 17:46:39 DEBUG[9502]: Set channel SIP/104-6875 to write format gsm           <<--- there be demons here
Jan  4 17:46:39 DEBUG[9502]: Difference is 94696, ms is 11857
Jan  4 17:46:39 DEBUG[9502]: Scheduling timer at 160 sample intervals
Jan  4 17:46:39 DEBUG[9502]: Acked pending invite 104
Jan  4 17:46:39 DEBUG[9502]: Stopping retransmission on '73fec0181ef6a7c4765fff410257393a@199.104.120.160' of Request 104: Found
Jan  4 17:46:39 DEBUG[9502]: build_route: Retaining previous route: <sip:100@199.104.120.154:5060>
Jan  4 17:46:39 DEBUG[9502]: Stopping retransmission on '73fec0181ef6a7c4765fff410257393a@199.104.120.160' of Request 105: Found

The behavior is different when using an ExtraChannel to send both legs to MusicOnHold():

Jan  4 17:37:21 DEBUG[9502]: Set channel SIP/104-8e55 to write format slin
Jan  4 17:37:21 DEBUG[9502]: Set channel SIP/100-253f to write format gsm

I can include more if needed, but I figured this is already long enough.







****** ADDITIONAL INFORMATION ******

Disclaimer on... oh wait, I can't fix this one. :)
Comments:By: k3v (k3v) 2005-01-04 19:00:01.000-0600

I thought I'd give it a spin trying some other applications.  This happens with Record():

Jan  4 17:56:21 DEBUG[9502]: Launching 'Record'
Jan  4 17:56:21 DEBUG[9502]: Device 'SIP/100' changed to state '0'
Jan  4 17:56:21 DEBUG[9502]: Device 'SIP/100' changed to state '0'
Jan  4 17:56:21 DEBUG[9502]: Set channel SIP/104-26af to write format gsm
Jan  4 17:56:21 DEBUG[9502]: Difference is 47504, ms is 5958
Jan  4 17:56:21 DEBUG[9502]: Scheduling timer at 160 sample intervals
Jan  4 17:56:21 DEBUG[9502]: Acked pending invite 104
Jan  4 17:56:21 DEBUG[9502]: Scheduling timer at 0 sample intervals
Jan  4 17:56:21 DEBUG[9502]: Scheduling timer at 0 sample intervals
Jan  4 17:56:21 DEBUG[9502]: Set channel SIP/104-26af to write format ulaw
Jan  4 17:56:21 DEBUG[9502]: Set channel SIP/104-26af to read format slin

I hear nothing, it records nothing.
By: k3v (k3v) 2005-01-19 02:17:26.000-0600

Apparently this is not just a SIP problem.  A call from a remote IAX2 user to a Zap channel, where both ends have 'disallow=all; allow=ulaw; allow=gsm':

Jan 19 00:59:38 DEBUG[1134]: Set channel Zap/49-1 to read format gsm
Jan 19 00:59:38 DEBUG[1134]: Set channel IAX2/kevin@kevin/1 to write format gsm
Jan 19 00:59:38 DEBUG[1134]: Set channel Zap/49-1 to write format slin
Jan 19 00:59:38 DEBUG[1134]: Set channel IAX2/kevin@kevin/1 to read format slin

When both ends are set to 'disallow=all; allow=ulaw;':

Jan 19 01:17:56 DEBUG[1134]: Set channel Zap/49-1 to read format ulaw
Jan 19 01:17:56 DEBUG[1134]: Set channel IAX2/kevin@kevin/1 to write format ulaw
Jan 19 01:17:56 DEBUG[1134]: Set channel Zap/49-1 to write format ulaw
Jan 19 01:17:56 DEBUG[1134]: Set channel IAX2/kevin@kevin/1 to read format ulaw

How can a Zap channel be slin or gsm?  Isn't that terribly broken?
By: k3v (k3v) 2005-01-27 01:51:39.000-0600

update:

Basically this problem occurs when I redirect to something that requires transcoding.  If I were to do Playback(foo) then Dial(SIP/bar), the caller would hear nothing until SIP/bar answers, and the translator path becomes native again.

Could we discuss in IRC perhaps?  This is the only remaining issue preventing this system from going live.
By: Mark Spencer (markster) 2005-01-27 10:59:56.000-0600

Is the call being answered before being transferred?
By: k3v (k3v) 2005-01-27 13:02:08.000-0600

mark, yes.
By: k3v (k3v) 2005-01-27 13:40:03.000-0600

..and I only have the problem when redirecting the originator of the call.  Redirect of destination works just great.  I'm trying to dig up a SIP UA that does something other than ULAW and G.729, to see how a call that was never natively bridged will perform.
By: k3v (k3v) 2005-01-27 14:46:56.000-0600

This actually seems to be a Polycom<->Asterisk interoperability issue.  When a Polycom UA leg of the call is redirected (origin or destination, doesn't matter), something goes wrong.  I'm attaching some sip debugs per Olle's request.  

sip-debug-polycom-to-polycom.txt:
 * A call from polycom(139@199.104.120.153) to polycom(104@199.104.120.151)
 Action: redirect
 Channel: SIP/139-8369
 Context: office
 Exten: 8669 (Playback(lyrics-louie-louie); Hangup)
 Priority: 1

sip-debug-cisco-to-polycom.txt: (somehow works ok)
 * A call from cisco(100@199.104.120.154) to polycom(104@199.104.120.151)
 Action: redirect
 Channel: SIP/100-6d96
 Context: office
 Exten: 8669 (same)
 Priority: 1
By: k3v (k3v) 2005-01-29 14:42:03.000-0600

This is not codec related.  I assumed that.  

It seems canreinvite=no fixes my issue.  With canreinvite=yes, Aa Cisco 7960 UA handles the redirect/transfer ok, but the Polycom does not.

Shall we change the bug title, reopen, or just let this die?
By: Mark Spencer (markster) 2005-02-08 01:52:41.000-0600

Does that mean the polycom doesn't like reinvites?
By: k3v (k3v) 2005-02-09 00:53:13.000-0600

I don't know what to think about it.  I am not a sip master like olle or anything either.  The weirdest part is that once the polycom was rejoined to another sip ua, the two-way audio resumed.  I'm satisfied with canreinvite=no, but there is some issue here.  If you'd like to clean up, I can open again when I find more time to spend on it.
By: Mark Spencer (markster) 2005-02-27 21:19:01.000-0600

To the best of my reading, this appears to be a bug in the polycom.  I see no problems with the exchange posted (clearly it is nearly identical to the Cisco version).  I suggest using ethereal to look and confirm that the Polycom is not sending RTP audio back to Asterisk.  If you see that the polycom *is* sending audio (and non-silent audio) back to Asterisk, please feel free to reopen.