[asterisk-bugs] [Asterisk 0010479]: Registration/Un-Registration Problem with chan_skinny

[noreply at bugs.digium.com]

A NOTE has been added to this issue. 
====================================================================== 
http://bugs.digium.com/view.php?id=10479 
====================================================================== 
Reported By:                sbisker
Assigned To:                qwell
====================================================================== 
Project:                    Asterisk
Issue ID:                   10479
Category:                   Channels/chan_skinny
Reproducibility:            random
Severity:                   minor
Priority:                   normal
Status:                     assigned
Asterisk Version:            1.4.10  
SVN Branch (only for SVN checkouts, not tarball releases): N/A  
SVN Revision (number only!):  
Disclaimer on File?:        N/A 
Request Review:              
====================================================================== 
Date Submitted:             08-17-2007 06:54 CDT
Last Modified:              09-13-2007 10:05 CDT
====================================================================== 
Summary:                    Registration/Un-Registration Problem with
chan_skinny
Description: 
Having a problem with channels becoming partially unregistered.  This is
happening with 7920 and 7921 phones.  At some point during the day,
asterisk thinks that the  device becomes unregistered.  If you do a "skinny
show devices"  the device appears that it is registered, and the phone
screen indicates that it is registered.  However when making a call, the
following is in the log.


[Aug 16 09:46:14] VERBOSE[13870] logger.c:     -- Starting simple switch
on '5264 at 5264'
[Aug 16 09:46:15] DEBUG[12158] chan_skinny.c: Current sub
[Skinny/5264 at 5264-148] already has owner
[Aug 16 09:46:15] WARNING[13870] chan_skinny.c: Asked to transmit to a
non-existant session!
[Aug 16 09:46:15] NOTICE[13870] chan_skinny.c: Asked to indicate 'Stop
tone' condition on channel Skinny/5264 at 5264-148, but sessio
n does not exist.
[Aug 16 09:46:15] WARNING[13870] chan_skinny.c: Asked to transmit to a
non-existant session!
[Aug 16 09:46:15] NOTICE[13870] chan_skinny.c: Asked to indicate 'Stop
tone' condition on channel Skinny/5264 at 5264-148, but sessio
n does not exist.
[Aug 16 09:46:15] WARNING[13870] chan_skinny.c: Asked to transmit to a
non-existant session!
[Aug 16 09:46:15] NOTICE[13870] chan_skinny.c: Asked to indicate 'Stop
tone' condition on channel Skinny/5264 at 5264-148, but sessio
n does not exist.
[Aug 16 09:46:16] WARNING[13870] chan_skinny.c: Asked to transmit to a
non-existant session!
[Aug 16 09:46:16] VERBOSE[13870] logger.c:     -- Executing
[7848 at longdistance:1] Dial("Skinny/5264 at 5264-148",
"IAX2/isdpbx:password at isdpbx/7848||r") in new stack



If I do a "core show channels" no skinny sessions are shown, and no
channels are active for that device.  On a side note  can't do a "skinny
set debug" because asterisk crashes because the session doesn't exist, and
the debug code references session and not device.  I'll submit another bug
for this one too, if you want.
====================================================================== 

---------------------------------------------------------------------- 
 sbisker - 09-13-07 10:05  
---------------------------------------------------------------------- 
I've been watching this for quite some time now, and the phones seem to be
losing registration quite often, even with a good signal.

I was getting a lot of "Skinny Client was lost, unregistering" followed
immediately by a re-registration.  I tracked down all occurences of this,
and flagged them 001 - 004.  All of the registrations were being lost for a
002 90% of the time and a 003 the other 10%.

It seems that most of the unregisters are a result of 

res = poll(fds, 1, (keep_alive * 1100));

Where res == 0

Why would res = 0   so often.  The phone is still sending keepalives every
30 seconds, so it's beyond me.



Here's a snip of the code with my modified log messages for 002-004.

        fds[0].fd = s->fd;
        fds[0].events = POLLIN;
        fds[0].revents = 0;
        res = poll(fds, 1, (keep_alive * 1100)); /* If nothing has happen,
client is dead */
                                                 /* we add 10% to the
keep_alive to deal */
                                                 /* with network delays,
etc */
        if (res < 0) {
                if (errno != EINTR) {
                        ast_log(LOG_WARNING, "Select returned error:
%s\n", strerror(errno));
                        return res;
                }
        } else if (res == 0) {
                if (skinnydebug)
                        ast_verbose("Skinny Client was lost,
unregistering\n");
                ast_log(LOG_WARNING, "Skinny Client was lost,
unregistering: 002\n");
                skinny_unregister(NULL, s);
                return -1;
        }

        if (fds[0].revents) {
                ast_mutex_lock(&s->lock);
                memset(s->inbuf,0,sizeof(s->inbuf));
                res = read(s->fd, s->inbuf, 4);
                if (res < 0) {
                        ast_log(LOG_WARNING, "read() returned error:
%s\n", strerror(errno));

                        if (skinnydebug)
                                ast_verbose("Skinny Client was lost,
unregistering\n");
                        ast_log(LOG_WARNING, "Skinny Client was lost,
unregistering: 003\n");
                        skinny_unregister(NULL,s);
                        ast_mutex_unlock(&s->lock);
                        return res; 

Issue History 
Date Modified   Username       Field                    Change               
====================================================================== 
09-13-07 10:05  sbisker        Note Added: 0070484                          
======================================================================