[Home]

Summary:ASTERISK-09948: Skinny to skinny calls one-way audio
Reporter:sbisker (sbisker)Labels:
Date Opened:2007-07-24 11:13:22Date Closed:2007-08-01 17:13:43
Priority:MajorRegression?No
Status:Closed/CompleteComponents:Channels/chan_skinny
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) 7920-7921.console.working.txt
( 1) 7920-7921.debug.working.txt
( 2) 7921-7920-back2backcalls.txt
( 3) 7921-7921.console.notworking.txt
( 4) 7921-7921.debug.notworking.txt
( 5) chan_skinny-callstate-fixes.txt
( 6) chan_skinny-callstate-fixes-v2.txt
( 7) chan_skinny-debug-enhancements.txt
( 8) chan_skinny-endcall-callstate.txt
( 9) new-debug-7921-7920.txt
Description:Version 76621 fixed the crashing of asterisk due to soft-key problems, but introduced another problem.  

7921 -> 7921 phones the remote party could not hear any audio.  In version 76784, the 7921 that initiates the call hears no audio.  If a 7920 phone calls a 7921/7920 phone, then both parties hear audio.
Comments:By: dea (dea) 2007-07-24 18:47:54

This may sound like an odd request, but can you power cycle the problem phone(s)?

There have been major improvements in communicating call states between
Asterisk and skinny phones, but more might need to be done.  I had a similar
one-way audio on my 7920 phone, and restarting Asterisk did not help it.
By random chance, I needed to reset the phone and afterwards it worked fine.

I suspect that the 7920/7921 are more sensitive to missing a call state
event, which can leave them in an odd state.
By: sbisker (sbisker) 2007-07-24 19:26:06

I tried that first, but it seems to only be Skinny to Skinny calls where the originating phone is a 7921.  7920 -> 7921 works fine.  7921 -> IAX to Second Server works fine.  7921 -> IAX Second Server -> IAX Original Server (via transfer) -> 7921/7920 works fine.

Like I mentioned in the report.  The initating caller is the one that hears no audio.  It was something that coincided around 1.4 SVN version 76621.  

Also, I need to correct the original post.  In both version 76621 and 76784, it was the originating phone that heard no audio.
By: dea (dea) 2007-07-24 21:07:02

Can you get a console log with skinny set debug and core verbose 3?

It could be that the 7921 needs special handling, but I'd like to
see the logs from a 7921 call.
By: sbisker (sbisker) 2007-07-25 07:54:30

I just re-ran the tests, and attached the appropriate files.  I attached both the console logs and the debug logs from /var/log/asterisk.
By: dea (dea) 2007-07-25 10:53:17

Nothing is jumping out of the logs at me.  In the failure case, what is
displayed on the 7921 screen?  Does it think it is connected?

Also the debug log has a lot of extra info.  I think we can track this
down easiest with these options and the output in the console:

core set verbose 3
core set debug 0 (way to much detail otherwise)
skinny set debug

If that does not help, I have a debug patch that adds details about
the line and call to the log.  We might be facing an issue that the
phone does not know what the call state is.
By: sbisker (sbisker) 2007-07-25 11:32:30

OK.  I did a total rebuild of 76708 and re-did my testing.  This time I reset the 7921 prior to testing.  The first call from 7921->7920 works fine. Both sides hear audio, however there is a slight delay on the 7921 hearing the remote party on the 7920.  After a hangup, I re-dial the 7920, and the audio is now one-way.  Only the 7920 can hear audio.  The 7921 can transmit, but not receive.  If I reset the 7921, it will work again, but only for the first call.  I must have missed this yesterday, because I was always originating the first call from the 7920.

One  more things to note.  When dialing from the 7921, it displays the Macro information, not the extension.  Looks something like this
             s
(Phone Icon) (s)


I uploaded the console log from the back-to-back phone calls.  They have separators to indicate working/not-working.
By: Jason Parker (jparker) 2007-07-25 11:39:55

Sounds like we're going to need to get some CCM dumps on this one.  It's pretty clear to me that we're doing something the 7921 doesn't like.
By: sbisker (sbisker) 2007-07-25 11:43:51

I don't have a CCM, but I'm sure very few people have 7921 phones.  Whoever has a CCM to debug with, I FedEx a 7921 for them to test with until this gets resolved.
By: dea (dea) 2007-07-25 12:02:10

CCM dumps may help, but not really needed.  The cause is incomplete
or incorrect packets for the callstate.

The phone is dumber than dumb and needs to be told by Asterisk what
the current callstate is.  We have to send the line and callreference
to the phone in the packet, and one area I found in the CCM dumps I
review that Asterisk gets wrong is the conferenceid.  In the CCM
dumps it is set to the callreference, but Asterisk sets it unconditionally
to 0:
req->data.startmedia.conferenceId = htolel(0);

I found that changing that line to:
req->data.startmedia.conferenceId = htolel(sub->callid);

Is part of the solution to communicate the correct callstate to the
phone.  I have a patch somewhere on here the modifies the debug logging
of stimulus and softkey events that makes this obvious, for example:
  ast_verbose("Received Stimulus: Redial(%d)\n", instance);
Becomes:
  ast_verbose("Received Stimulus: Redial(%d/%d)\n", instance,callreference);

The issue is that the phone can get it right on the first call completely
by chance, but after that it is hopelessly confused.  

sbisker-  Are you comfortable changing that one line to see if it fixes
the problem?
By: sbisker (sbisker) 2007-07-25 14:28:30

Making those changes had no effect.
callreference  is not a valid in chan_skinny.c  


I was testing with another person, and on the first call, there is about a 10 second period where the 7921 hears no audio.  After that period, the audio is clear.  Second call, no audio at all.
By: dea (dea) 2007-07-25 14:53:38

Sorry for the confusion.  The extra debugging requires more, but trivial,
changes.

The change I was asking about, which I think will help you is:
req->data.startmedia.conferenceId = htolel(0);
to:
req->data.startmedia.conferenceId = htolel(sub->callid);

There's only one instance of this in the code, so it is easy to find and
change.
By: sbisker (sbisker) 2007-07-25 14:59:38

I did change that portion, and it had no effect.
By: dea (dea) 2007-07-25 15:42:27

Is there anyway you can test Trunk instead of SVN-Branches-1.4?

I'm digging through both, and trunk happens to have more of my
fixes maintaining callstate.  If I can weed out what bits are missing,
I will post a patch for 1.4


** Edit  **
Nevermind.  Reading chan_skinny from my tree, trunk and branches-1.4 I can see
that the fix(es) needed never made it as far as a commit.

A quick test is to search for conferenceId.  If is is being set to 0 or htolel(0), it is wrong and needs to be htolel(callid) or htolel(sub->callid) depending on which is available in the function.  There are six instances in the code, so it would be a quick patch to fix, but I need to see what other changes got lost in the mix.


By: dea (dea) 2007-07-25 17:58:18

I started with a fresh Branches/1.4  checkout and ported what I think
were the key pieces to communicating the callstate to the phone.

Two functions needed their parameters updated to include line instance
and call reference number, which meant updating a dozen or so call locations.
We also needed changes to the start and stop_tone packet structures, and to
actually use the stop_tone packet structure.

The patch looks large, but it is fairly straight forward.  If this does not
make the 7921 happy, I will port my debug logging enhancements to a
standalone patch.  That will allow us to better follow the call flow and
see if we are not setting the callstate properly.
By: sbisker (sbisker) 2007-07-26 07:58:35

I applied your patch against  1.4 svn version 77112.  Same issues.  No audio at all on the originating 7921 phone after the first outbound call.  No ringing when the call is made, no nothing.  The receiving phone, hears all audio, every time.

I also tried trunk version 77265.  The 7921 phones register very quickly on trunk, but the behavior is a little worse.  Even though the phones are registered, calls go directly to voicemail. And after the first call out, the call still goes to voicemail, but there is no audio on the originating 7921 phone.
By: sbisker (sbisker) 2007-07-26 09:33:36

The plot thickens.  I went back to version 76708 without your latest patch.  

There are two distinct problems.

The first problem is callstate notification to the 7921.  When the 7921 is on a call and the call is terminated, the 7921 earpiece emits whitenoise for 5-10 seconds after the call is terminated.  If a call is made during that period, no audio is heard on the 7921.  After that period, calls can behave as you would normally expect.

The second problem is how the 7921 handles call Macros.  If the macro contains Answer() the 7921 has audio issues.  It hoses up audio for 10 seconds to indefinitely (depending on the technology of the phone being dialed) and really screws things up.  If you remove the Answer() portion of the macro below, everything is OK with one exception -- the 7921 phone doesn't indicate ringing on the line when making a call  -- the 7920 does indicate ringing when making a call.

exten => s,1,Set(TIMEOUT(absolute)=0)
exten => s,2,Answer()
exten => s,3,Wait(1)
exten => s,4,Dial(${ARG2}|20|tr)
exten => s,5,Voicemail(${ARG1},u)
exten => s,6,Hangup()
exten => s,105,Voicemail(${ARG1},b)
exten => s,106,Hangup()


I changed back to version 77112 with your patches.  And the removed Answer() and the 7921 now indicates ringing.  The only problem that still remains is the white noise period / no audio problem which lasts for 10 or so seconds, then goes away.


By: dea (dea) 2007-07-26 13:32:58

debug-enhancements includes:
Updates to stimulus_message and soft_key_event_message structures
Logging of the callreference number when skinny debug is on-
Old format
 Received Stimulus: Redial(1) /* Where 1 is the line # */
New format
 Received Stimulus: Redial(1/20) /* Line # / Call id */

I see a bug/quirk that I added a note about, but did not fix, since
this is a debug logging patch.  In handle_stimulus_message() we should
be looking up the sub based on the provided line/callreference not the
devices lastline/callreference.  While they should be in sync, I would
rather base decisions on which call the phone CLAIMS to be acting on.

With this patch applied, please place a call from a 7921 after powercycling
it.  Have skinny debug on, and verbose set to 3.  Place a 2nd call (which
we still expect to fail)

What we are looking for is that the phone sends consistent callreference
numbers for the lifetime of each call.  The callreference for the 2nd call
should NOT be the same as the 1st...
By: sbisker (sbisker) 2007-07-26 13:52:21

I made back to back calls on the 7921. And attached the console log per your instructions.  White noise was present when the second call was made, and it indicated that the remote end was ringing.


By: dea (dea) 2007-07-26 16:18:59

OK, the log looks pretty good, we have consistent callreferences throughout
the life of each call.

I see one issue, but I am not sure it explains this behaviour.  The first
line of the log:
chan_skinny.c:1293 find_subchannel_by_instance_reference:  Could not find subchannel with reference '0' on '5500'

The wireless phones cannot dial from an offhook state, so we have not
yet created a subchannel.  I would expect this message to happen EVERY
time a wireless phone places a call, or any time a wired phone places
a call from the onhook state (speeddial/vm/redial)

This hints at the possibility that we are not cleaning up sub channels
properly.  Looking at the code, I think this is very likely.

I have two more tests that may help narrow this down.

1.  Place a call-
   What is displayed after you press 'Send'?
   What is displayed when the far end answers?
   What is displayed after you hangup?

2.  Your logs show that you are hanging up the cal on the originating
   7921, what happens if the far end hangs up?  Can you then place a
   second call?
By: Damien Wedhorn (wedhorn) 2007-07-26 18:01:49

The find sub by reference is going to continue to be an issue. Some devices do not send this information. I have a CCM dump of a 30VIP to a 7960 which indicates the offhook message on a 7960 including some reference info and the offhook message of the 30VIP not indicating any reference info.

Skinny needs to be changed to track its own reference info. The general approach in the transfer patch is that chan_skinny tracks the reference info, and if no reference info is provided by the device, it uses its own reference info.

I have a feeling that the 7920/21 devices also don't send reference info, but find_sub_by_reference just returns the first sub on the first line. Not pretty, but for simple call structures (single line, single channel sort of stuff) it should work.
By: dea (dea) 2007-07-26 18:26:51

The 7920 and I am guessing the 7921 do send the call reference, but the
key is for an established connection.  Starting from the onhook state, there
is no active sub, so the phone send 0.

The back2backcalls log show the phones do send the call reference.

I continue to like the approach in the transfer patch and have already
thought about how it can help with additional feaures.  That said, if the
phone provides us with callreference information, we should use it.
If it does not provide us that detail, then we can fall back to the channels
view of the world.  Do you know if the 30VIP phones can support more than
one active call?  Having the callreference is going to be key to supporting
multiple calls per line.

I also agree that the code in trunk and 1.4 has problems with handling subs.
I do not see where we prune subs from the lines list, meaning that we are
wasting memory.  One of my tries at the transfer patch included an attempt
to remove a sub at hangup, and this is not a unique requirement for transfer.
It impacts phones that want to have multiple calls, with one or more on hold.

Wedhorn, I think we've swapped emails before.  Can you send me the CCM traces of the 30VIP in action?
By: Damien Wedhorn (wedhorn) 2007-07-26 18:43:17

What do you specifically mean by more than one active call? Do you mean to actually have more than one connected RTP stream to a device at a time? If so, I wouldn't have a clue because I don't think that chan_skinny actually does this at the moment. I'm pretty sure at the moment that chan_skinny stops an RTP stream before starting another (although i could be wrong).

If you mean multiple line instances only, then yes, the 30VIPs can handle multiple calls. However, there are line selection issues with the 30VIP in both 1.4 and trunk, but the transfer patch allows multiple lines on a 30VIP.

I'll send the dumps when I get home.
By: dea (dea) 2007-07-26 19:13:00

It varies by device, but a 7940 for example can have 16ish calls active.
That does not mean 16 RTP streams.  It means maintaining state for up to
sixteen calls per line, which would usually mean 1 active with RTP and
15 on hold.  The 79X1 (other than 7921 of which I have no idea) can maintain
state for many more than 16 per line.

Example-
  1.  I call the wife on my line 1
  2.  My boss calls me on my line 1

With the current code I can either ignore my boss, or quickly hangup on
my wife.  Not exactly win/win choices.  With the packet structure fixes
(mostly already in) and sub handling fixes that exist in on of the transfer
patches we have new options-

Put the wife on hold, use navigation keys to select the bosses call and
press 'Answer'.  Finish up with the boss, let him hangup, or hangup.  Now
we can press 'Resume' and pick up where we left off.

If the 30VIP only supports one call per line, then the above does not matter
much, except that the channel does not currently support/enforce the concept
of per line call limits.

We've gotten off track here and should take this to the dev mailing list to
work out the ToDo items.
By: Damien Wedhorn (wedhorn) 2007-07-26 19:28:51

We certainly have, but just to tie off the comments, the 30VIP can handle multiple calls (i've probably had 4 with the transfer patch). The issue is selecting calls, which I was going to work on at a later date, but basically changing hold to iterate through the subs on a line (think call waiting).
By: sbisker (sbisker) 2007-07-27 08:03:19

Not to beat a dead horse, but after reading through my comments, I may have been unclear regarding the 7921 after the callstate fixes were applied.

I can make unlimited working calls from the 7921 as long as 2 conditions are met.
(1) The dialplan macro doesn't contain Answer()
(2) I wait for the white/comfort noise to cease after each call.

I may have confused everyone regarding the comments on white noise.  After the call is hungup, the earpiece of the 7921 (regardless of if it made or received the call) continues generate comfort noise for a period of 10-15 seconds.  

Once the noise ceases, you can make another successful call.  If you attempt to make another call inside the 10-15 second window, the 7921 indicates ringing, but you can never hear the remote party.


By: dea (dea) 2007-07-27 11:08:12

Really cool to hear and good detective work.  One more bit of information
would be very helpful.  Do you get the white noise if either party initiates
the hangup, or only when the 7921 hangs up?
By: sbisker (sbisker) 2007-07-27 11:43:48

You get white noise no matter which side hangs up.  Also if the call is 7921->7921 both sides get the white noise for about the same period of time, regardless of who hungup.
By: pj (pj) 2007-07-27 12:37:17

maybe good thing to know is, that SIP for 7921 is on ci$co roadmap, so if will be too difficult and mainly time consuming to fully support this phones by chan_skinny, I hope, that SIP will be right way, how to reliably use this phones with asterisk.
same is true for all others never ci$co phones - 79x1, what are currently only partially supported by chan_skinny, possitive is, that SIP firmware for this desktop phones is available some months ago... :)


Q. Does the Cisco Unified Wireless IP Phone 7921G support SIP?
A. No, this phone supports only the SCCP protocol. Support for SIP protocol will come later.
By: dea (dea) 2007-07-27 12:39:35

Can you try this quick edit?

Comment out this line near line 2714:
transmit_tone(s, SKINNY_SILENCE);

It does not make much sense to tell the phone to play a tone in
an onhook state....
By: sbisker (sbisker) 2007-07-27 13:10:59

I commented out the occurrence from this block on line 2504

} else if ((l->type = TYPE_LINE) && (l->hookstate == SKINNY_ONHOOK)) {
       transmit_callstate(s, l->instance, SKINNY_ONHOOK, sub->callid);
       transmit_speaker_mode(s, SKINNY_SPEAKEROFF);
       transmit_ringer_mode(s, SKINNY_RING_OFF);
       //transmit_tone(s, SKINNY_SILENCE, l->instance, sub->callid);
       transmit_lamp_indication(s, STIMULUS_LINE, l->instance, SKINNY_LAMP_OFF);
       do_housekeeping(s);


It didn't make a difference.
By: dea (dea) 2007-07-27 15:46:18

Are you testing this on a production server?  I hate to ask you to test
ideas if that is the case.

The noise issue could be a couple of things-
  1.  The 7921 wants/needs a slightly different set of call state messages
      and the channel is not actually torn down at the end of the call.
      If this is the case, core show channels will still show an open
      channel to the 7921, and possibly a RTP stream
  2.  The phone is creating the noise, and it needs to be told to stop.

When the 7921 is making noise, does Asterisk still show an active channel?
What, if anything, is on the 7921 display?
By: sbisker (sbisker) 2007-07-29 14:29:52

"core show channels" doesn't show the call still being active.  It seems that it's just the phone generating the comfort noise.
By: dea (dea) 2007-07-31 17:47:56

I ran a set of tests against my 7940/7920/CIPC wondering if
the tone SKINNY_SILNCE might be the source of the 'comfort noise'
as you have described it.

I changed the tone on the line you commented out to SKINNY_NOTONE
and commented out the early return in transmit_tone(), line 1725 is.

My phones continued to work and no errors reported.  The CIPC softphone
complains early and often about packets/settings it does not like, so this
one seems to be a harmless test.  I would be interested if your 7921 continues
to make noise after ending the call.
By: dea (dea) 2007-07-31 20:28:31

Ignore my last message, it was a false trail.  I re-reviewed my CCM captures
and noted a handful of things that we do different in chan_skinny (maybe wrong).

In skinny_hangup() the transmit_tone() call needs to be before transmit_callstate()

In transmit_callstate() we should move the code to setup and send the
call state to after the if..else block.  The end call on CCM looks like this:

Transmit stop_tone
Transmit stop media
Transmit close receive channel
Transmit call state

Chan_skinny is doing this:
Transmit call state
Transmit stop media
Transmit close receive channel
Transmit stop tone

I can put together an incremental patch to apply on top of the callstate-fixs
patch if you are not comfortable making the edits directly.
By: sbisker (sbisker) 2007-08-01 07:59:45

OK.  I got the first part no problem.  

} else if ((l->type = TYPE_LINE) && (l->hookstate == SKINNY_ONHOOK)) {
       transmit_tone(s, SKINNY_SILENCE, l->instance, sub->callid);
       transmit_callstate(s, l->instance, SKINNY_ONHOOK, sub->callid);
       transmit_speaker_mode(s, SKINNY_SPEAKEROFF);
       ...

But you lost me on the second part.  Not really sure how to proceed on this one.  A patch would be appreciated.  I have both chan_skinny-callstate-fixes.txt and chan_skinny-debug-enhancements.txt applied.
By: dea (dea) 2007-08-01 10:55:34

The endcall-callstate patch changes the order that chan_skinny transmits
the stop_media/close_receive_channel/callstate packets.

It does not include the trivial changes you have already made inside
skinny_hangup(). If this patch on top of the previous patches and the
hand edits you've made help, I'll checkout a clean chan_skinny and make
a proper patch.

I also see that we have redundant calls to transmit_speaker_mode(), once
in skinny_hangup() and again in transmit_callstate().  One of these calls
could/should be removed, but it is not hurting us at this point.
By: sbisker (sbisker) 2007-08-01 12:13:45

Bingo... That fixed it.
By: dea (dea) 2007-08-01 13:06:07

Great!  I'll cleanup my tree, roll callstate-fixes and endcall-callstate into a single patch to make it easier for an administrator to merge.
By: dea (dea) 2007-08-01 13:17:06

As promised, chan_skinny-callstate-fixes-v2.txt is a roll up of the original callstate-fixes patch and the endcall-callstate patch.

The debug enhancements patch is not included, but a valuable addition.

These patches are candidates for Trunk and Branches/1.4:
chan_skinny-callstate-fixes-v2.txt
chan_skinny-debug-enhancements.txt

sbisker-  Can you confirm that your other Cisco phones continue to function
as expected?
By: sbisker (sbisker) 2007-08-01 13:32:00

The 7920 behaves as you would expect.  I don't have any other phones using chan_skinny.
By: Jason Parker (jparker) 2007-08-01 16:05:40

Committed chan_skinny-callstate-fixes-v2.txt in svn branch 1.4 and trunk in revisions 77883 and 77884.

Haven't yet gotten an answer on whether the debug-enhancements is okay to commit to 1.4.  I suspect it will be though.
By: Digium Subversion (svnbot) 2007-08-01 17:13:43

Repository: asterisk
Revision: 77891

------------------------------------------------------------------------
r77891 | qwell | 2007-08-01 17:13:43 -0500 (Wed, 01 Aug 2007) | 13 lines

Merged revisions 77890 via svnmerge from
https://origsvn.digium.com/svn/asterisk/branches/1.4

(closes issue ASTERISK-9948)
........
r77890 | qwell | 2007-08-01 17:28:56 -0500 (Wed, 01 Aug 2007) | 4 lines

Put in some additional debug information for softkey/stimulus messages.

Issue 10291, patch by DEA.

........

------------------------------------------------------------------------