Summary: | ASTERISK-03182: channel format set wrong on manager redirect | ||
Reporter: | k3v (k3v) | Labels: | |
Date Opened: | 2005-01-04 18:53:25.000-0600 | Date Closed: | 2011-06-07 14:10:17 |
Priority: | Minor | Regression? | No |
Status: | Closed/Complete | Components: | 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. |