[Home]

Summary:ASTERISK-11763: null pointer in chan_skinny when 'regcontext' used
Reporter:Brian Candler (candlerb)Labels:
Date Opened:2008-04-01 03:57:17Date Closed:2008-04-22 17:05:38
Priority:CriticalRegression?No
Status:Closed/CompleteComponents:Core/PBX
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) thread-apply-all-bt.txt
Description:Uncomment the 'regcontext' example line from skinny.conf, wait for a Cisco phone to connect, and Asterisk dumps core.

GDB output:

...
[New Thread -1215501408 (LWP 12516)]
   -- Starting Skinny session from 10.69.255.249
   -- Added extension '110' priority 1 to skinnyregistrations

Program received signal SIGSEGV, Segmentation fault.
[Switching to Thread -1215501408 (LWP 12516)]
ast_add_extension2 (con=0x86d1a88, replace=1, extension=0xb78ce1c0 "110",
   priority=Variable "priority" is not available.
) at pbx.c:6056
6056                            if (x->exten) { /* this test for safety purposes */
(gdb) bt
#0  ast_add_extension2 (con=0x86d1a88, replace=1, extension=0xb78ce1c0 "110",
   priority=Variable "priority" is not available.
) at pbx.c:6056
#1  0x080e4f71 in ast_add_extension (context=0x363840 "skinnyregistrations",
   replace=141620640, extension=0x870f5a0 "??p\b", priority=141620640,
   label=0x870f5a0 "??p\b", callerid=0x870f5a0 "??p\b",
   application=0x870f5a0 "??p\b", data=0x870f5a0, datad=0x870f5a0,
   registrar=0x870f5a0 "??p\b") at pbx.c:5859
#2  0x00359a6f in handle_message (req=0x870f180, s=0x870e600)
   at /home/candlerb/svn/asterisk/branches/1.6.0/include/asterisk/utils.h:502
#3  0x0035b88f in skinny_session (data=0x870e600) at chan_skinny.c:5585
#4  0x08122445 in dummy_start (data=0x86d1a88) at utils.c:870
ASTERISK-1  0x005793cc in start_thread () from /lib/tls/libpthread.so.0
ASTERISK-2  0x004d21ae in clone () from /lib/tls/libc.so.6
(gdb) print x
$1 = (struct match_char *) 0x0

I wondered if this was perhaps because I had no [skinnyregistrations] section in extensions.conf, but I added one and it made no difference.


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

$ cat /etc/asterisk/skinny.conf
[general]
bindaddr=0.0.0.0        ; Address to bind to
bindport=2000           ; Port to bind to, default tcp/2000
dateformat=D-M-Y        ; M,D,Y in any order (6 chars max)
                       ; "A" may also be used, but it must be at the end.
                       ; Use M for month, D for day, Y for year, A for 12-hour time.
keepalive=120

; *** ADDING THIS LINE CAUSES THE CRASH ***
regcontext=skinnyregistrations

[brian]
device=SEPXXXXXXXXXXXX
;nat=yes
callerid="Brian Candler" <XXX XXXX XXXX>
;mailbox=110
;vmexten=8500                   ; Device level voicemailmain pilot number
regexten=110
context=from-skinny

linelabel="Foo"
line => 111
callerid="John Chambers" <408-526-4000>
context=did
;regexten=111

linelabel="Bar"
;mailbox=110
line => 112
speeddial => 101,Jack Smith         ; Adds a speeddial button to a device.
speeddial => 102,Bob Peterson ; When a context is specified, the speeddial watches a dialplan hint.

Comments:By: Michiel van Baak (mvanbaak) 2008-04-01 13:44:48

I cannot reproduce this on my trunk setup, and the changes between trunk and 1.6 are none in this area.

My skinny.conf:

[general]
bindaddr=0.0.0.0
bindport=2000
dateformat=D-M-Y
keepalive=120
vmexten=1233
regcontext = skinnyregistrations

[office]
device = SEP0015626A4B99
nat=yes
callerid="VanBaak" <6000>
mailbox=13
context = internal
regexten = 6000
callwaiting=yes
transfer=yes
threewaycalling=yes
linelabel=VanBaak
setvar=name=vanbaak
line => 6000
callerid="3d" <6001>
context=internal
regexten=6001
linelabel=3d
setvar=name=3d
line => 6001
speeddial => 6002@hints,Livingroom

[livingroom]
device = SEP0012D9166A2C
nat=yes
callerid="Livingroom" <6002>
mailbox=13
callwaiting=yes
transfer=yes
threewaycalling=yes
context=internal
regexten=6002
linelabel=Livingroom
line => 6002
By: Michiel van Baak (mvanbaak) 2008-04-01 17:55:58

Can you recompile asterisk with the DONT_OPTIMIZE flag set and post a backtrace of a crash after that ?
run the following commands on the source tree:
make distclean
./configure --enable-dev-mode
make menuselect
make
make install

in the 'make menuselect' section make sure to visit '11. Compiler Flags - Development' and check the box next to '1. DONT_OPTIMIZE'

By: Brian Candler (candlerb) 2008-04-02 04:53:32

I stopped Asterisk, rebuilt with DONT_OPTIMIZE as described and restarted Asterisk under gdb. Initially when the phone reconnected by itself it was successful. However I then unplugged and replugged the phone into its PoE switch to power cycle it, and then Asterisk crashed as before.

*CLI> [New Thread -1215399008 (LWP 30597)]
   -- Starting Skinny session from 10.69.255.249
   -- Added extension '111' priority 1 to skinnyregistrations
   -- Device 'SEP00195659657A' successfully registered
Adding button: 9, 1
Device capability set to '12'
[New Thread -1215644768 (LWP 30606)]
   -- Starting Skinny session from 10.69.255.249

Program received signal SIGSEGV, Segmentation fault.
[Switching to Thread -1215644768 (LWP 30606)]
0x080e7f81 in add_pri (con=0x92bfed0, tmp=0x9300db8, el=0x0, e=0x92fe8a0,
   replace=1) at pbx.c:6056
6056                            if (x->exten) { /* this test for safety purposes */
(gdb) bt
#0  0x080e7f81 in add_pri (con=0x92bfed0, tmp=0x9300db8, el=0x0, e=0x92fe8a0,
   replace=1) at pbx.c:6056
#1  0x080e850c in ast_add_extension2 (con=0x92bfed0, replace=1,
   extension=0xb78ab110 "111", priority=1, label=0x0, callerid=0x0,
   application=0x2e9d16 "Noop", data=0x9300da8, datad=0x805a970,
   registrar=0x2e99b8 "Skinny") at pbx.c:6225
#2  0x080e7766 in ast_add_extension (context=0x2ef2e0 "skinnyregistrations",
   replace=1, extension=0xb78ab110 "111", priority=1, label=0x0,
   callerid=0x0, application=0x2e9d16 "Noop", data=0x9300da8,
   datad=0x805a970, registrar=0x2e99b8 "Skinny") at pbx.c:5859
#3  0x002d83c3 in register_exten (l=0x92c11b8) at chan_skinny.c:1697
#4  0x002d879b in skinny_register (req=0x92fd470, s=0x92fcc60)
   at chan_skinny.c:1757
ASTERISK-1  0x002e0966 in handle_register_message (req=0x92fd470, s=0x92fcc60)
   at chan_skinny.c:3852
ASTERISK-2  0x002e6a36 in handle_message (req=0x92fd470, s=0x92fcc60)
   at chan_skinny.c:5291
ASTERISK-3  0x002e7c78 in skinny_session (data=0x92fcc60) at chan_skinny.c:5585
ASTERISK-4  0x08126286 in dummy_start (data=0x92ff6a0) at utils.c:870
ASTERISK-5  0x005793cc in start_thread () from /lib/tls/libpthread.so.0
ASTERISK-6 0x004d21ae in clone () from /lib/tls/libc.so.6
(gdb) info threads
* 30 Thread -1215644768 (LWP 30606)  0x080e7f81 in add_pri (con=0x92bfed0,
   tmp=0x9300db8, el=0x0, e=0x92fe8a0, replace=1) at pbx.c:6056
 29 Thread -1215399008 (LWP 30597)  0x003ef7a2 in _dl_sysinfo_int80 ()
  from /lib/ld-linux.so.2
 28 Thread -1215153248 (LWP 30596)  0x003ef7a2 in _dl_sysinfo_int80 ()
  from /lib/ld-linux.so.2
 27 Thread -1214907488 (LWP 30595)  0x003ef7a2 in _dl_sysinfo_int80 ()
  from /lib/ld-linux.so.2
 26 Thread -1214661728 (LWP 30594)  0x003ef7a2 in _dl_sysinfo_int80 ()
  from /lib/ld-linux.so.2
 25 Thread -1214375008 (LWP 30593)  0x003ef7a2 in _dl_sysinfo_int80 ()
  from /lib/ld-linux.so.2
 24 Thread -1214129248 (LWP 30592)  0x003ef7a2 in _dl_sysinfo_int80 ()
  from /lib/ld-linux.so.2
 23 Thread -1213883488 (LWP 30591)  0x003ef7a2 in _dl_sysinfo_int80 ()
  from /lib/ld-linux.so.2
 22 Thread -1213637728 (LWP 30590)  0x003ef7a2 in _dl_sysinfo_int80 ()
  from /lib/ld-linux.so.2
 21 Thread -1213391968 (LWP 30589)  0x003ef7a2 in _dl_sysinfo_int80 ()
  from /lib/ld-linux.so.2
 20 Thread -1213146208 (LWP 30588)  0x003ef7a2 in _dl_sysinfo_int80 ()
  from /lib/ld-linux.so.2
 19 Thread -1212900448 (LWP 30587)  0x003ef7a2 in _dl_sysinfo_int80 ()
  from /lib/ld-linux.so.2
 18 Thread -1212654688 (LWP 30586)  0x003ef7a2 in _dl_sysinfo_int80 ()
  from /lib/ld-linux.so.2
 17 Thread -1212408928 (LWP 30585)  0x003ef7a2 in _dl_sysinfo_int80 ()
  from /lib/ld-linux.so.2
 16 Thread -1212163168 (LWP 30584)  0x003ef7a2 in _dl_sysinfo_int80 ()
  from /lib/ld-linux.so.2
 15 Thread -1211917408 (LWP 30583)  0x003ef7a2 in _dl_sysinfo_int80 ()
  from /lib/ld-linux.so.2
 14 Thread -1211671648 (LWP 30582)  0x003ef7a2 in _dl_sysinfo_int80 ()
  from /lib/ld-linux.so.2
 13 Thread -1211425888 (LWP 30581)  0x003ef7a2 in _dl_sysinfo_int80 ()
  from /lib/ld-linux.so.2
 12 Thread -1211180128 (LWP 30580)  0x003ef7a2 in _dl_sysinfo_int80 ()
  from /lib/ld-linux.so.2
 11 Thread -1210934368 (LWP 30579)  0x003ef7a2 in _dl_sysinfo_int80 ()
  from /lib/ld-linux.so.2
 10 Thread -1210688608 (LWP 30578)  0x003ef7a2 in _dl_sysinfo_int80 ()
  from /lib/ld-linux.so.2
 9 Thread -1210442848 (LWP 30577)  0x003ef7a2 in _dl_sysinfo_int80 ()
  from /lib/ld-linux.so.2
 8 Thread -1210197088 (LWP 30576)  0x003ef7a2 in _dl_sysinfo_int80 ()
  from /lib/ld-linux.so.2
 7 Thread -1209951328 (LWP 30575)  0x003ef7a2 in _dl_sysinfo_int80 ()
  from /lib/ld-linux.so.2
 6 Thread -1209705568 (LWP 30574)  0x003ef7a2 in _dl_sysinfo_int80 ()
  from /lib/ld-linux.so.2
 5 Thread -1209447520 (LWP 30573)  0x003ef7a2 in _dl_sysinfo_int80 ()
---Type <return> to continue, or q <return> to quit---
  from /lib/ld-linux.so.2
 4 Thread -1209201760 (LWP 30572)  0x003ef7a2 in _dl_sysinfo_int80 ()
  from /lib/ld-linux.so.2
 3 Thread -1208956000 (LWP 30571)  0x003ef7a2 in _dl_sysinfo_int80 ()
  from /lib/ld-linux.so.2
 1 Thread -1208952608 (LWP 30567)  0x003ef7a2 in _dl_sysinfo_int80 ()
  from /lib/ld-linux.so.2
(gdb) print x
$1 = (struct match_char *) 0x0
(gdb)

FWIW, platform is CentOS 4.6 (kernel 2.6.9-67.0.7.EL), and the steps I'm running to start Asterisk are:

# gdb /usr/sbin/asterisk
run -cnvvv

Just to be sure, I repeated the whole process as follows:

- unplug phone and stop asterisk
- start asterisk as shown above; wait for asterisk to give CLI> prompt
- plug in phone

It was successful this time:

*CLI> [New Thread -1215263840 (LWP 30675)]
   -- Starting Skinny session from 10.69.255.249
   -- Added extension '111' priority 1 to skinnyregistrations
   -- Device 'SEP00195659657A' successfully registered
Adding button: 9, 1
Device capability set to '12'

I then unplugged the phone and plugged it back in:

   -- ast_get_srv: SRV lookup for '_sip._UDP.sipgate.co.uk' mapped to host sipgate.co.uk, port 5060
   -- ast_get_srv: SRV lookup for '_sip._UDP.sipgate.co.uk' mapped to host sipgate.co.uk, port 5060
[New Thread -1215509600 (LWP 30681)]
   -- Starting Skinny session from 10.69.255.249

Program received signal SIGSEGV, Segmentation fault.
[Switching to Thread -1215509600 (LWP 30681)]
0x080e7f81 in add_pri (con=0x8c9e878, tmp=0x8cdca30, el=0x0, e=0x8cdd6d8,
   replace=1) at pbx.c:6056
6056                            if (x->exten) { /* this test for safety purposes */
(gdb)

So it's pretty repeatable, if not on the very first connection.
By: Joshua C. Colp (jcolp) 2008-04-02 11:30:21

I think I have an idea... can you grab a dialplan show before you cause it to crash, and a thread apply all bt when you do?
By: Brian Candler (candlerb) 2008-04-03 02:44:00

Uploaded as thread-apply-all-bt.txt


By: Brian Candler (candlerb) 2008-04-04 03:34:30

Ah, I forgot to give 'dialplan show' from immediately before the crash. Here it is:

*CLI> dialplan show
[ Context 'app_dial_gosub_virtual_context' created by 'app_dial' ]
 's' =>            1. KeepAlive()                                [app_dial]

[ Context 'default' created by 'pbx_config' ]
 Include =>        'extensions'                                  [pbx_config]
 Include =>        'invalid'                                     [pbx_config]

[ Context 'from-skinny' created by 'pbx_config' ]
 Include =>        'extensions'                                  [pbx_config]
 Include =>        'testing'                                     [pbx_config]
 Include =>        'outbound'                                    [pbx_config]

[ Context 'from-sip' created by 'pbx_config' ]
 Include =>        'extensions'                                  [pbx_config]
 Include =>        'testing'                                     [pbx_config]
 Include =>        'outbound'                                    [pbx_config]

[ Context 'internal' created by 'pbx_config' ]
 Include =>        'extensions'                                  [pbx_config]
 Include =>        'testing'                                     [pbx_config]
 Include =>        'outbound'                                    [pbx_config]

[ Context 'incoming' created by 'pbx_config' ]
 '8000' =>         1. Answer()                                   [pbx_config]
                   2. Wait(1)                                    [pbx_config]
                   3. Background(enter-ext-of-person)            [pbx_config]
 '8836' =>         1. Macro(ext,SIP/1836@cme-london)             [pbx_config]
 '8888' =>         1. Answer()                                   [pbx_config]
                   2. Wait(1)                                    [pbx_config]
                   3. Playback(office-iguanas)                   [pbx_config]
                   4. Hangup()                                   [pbx_config]
 '8998' =>         1. Macro(ext,SIP/907XXXXXXXXX@cme-london)     [pbx_config]
 'i' =>            1. Background(pbx-invalid)                    [pbx_config]
 't' =>            1. Playback(vm-goodbye)                       [pbx_config]
                   2. Hangup()                                   [pbx_config]
 Include =>        'extensions'                                  [pbx_config]

[ Context 'testing' created by 'pbx_config' ]
 '611' =>          1. Answer()                                   [pbx_config]
                   2. Playback(your-call-is-not-important)       [pbx_config]
                   3. Playback(office-iguanas)                   [pbx_config]
                   4. Playback(that-tickles)                     [pbx_config]
                   5. Hangup()                                   [pbx_config]
 '612' =>          1. Answer()                                   [pbx_config]
                   2. AGI(agi-testing.agi)                       [pbx_config]
 '_7X.' =>         1. AGI(agi://10.69.255.251)                   [pbx_config]

[ Context 'invalid' created by 'pbx_config' ]
 '_X!' =>          1. Answer()                                   [pbx_config]
                   2. Background(pbx-invalid)                    [pbx_config]

[ Context 'outbound' created by 'pbx_config' ]
 '_9.' =>          1. Dial(Zap/4/${EXTEN:1})                     [pbx_config]
                   2. Congestion()                               [pbx_config]
                   102. Congestion()                             [pbx_config]
 '_X.' =>          1. Dial(SIP/${EXTEN}@sipgate-out,15,r)        [pbx_config]
                   2. Congestion()                               [pbx_config]
                   102. Congestion()                             [pbx_config]

[ Context 'extensions' created by 'pbx_config' ]
 '101' =>          1. Macro(ext,Zap/1)                           [pbx_config]
 '102' =>          1. Macro(ext,Zap/2)                           [pbx_config]
 '111' =>          1. Macro(ext,Skinny/111@brian)                [pbx_config]
 '301' =>          1. Macro(ext,SIP/testing301)                  [pbx_config]
 '302' =>          1. Macro(ext,SIP/testing302)                  [pbx_config]
 '401' =>          1. Macro(ext,SIP/tulip1)                      [pbx_config]
 '402' =>          1. Macro(ext,SIP/tulip2)                      [pbx_config]
 '403' =>          1. Macro(ext,SIP/tulip3)                      [pbx_config]
 '404' =>          1. Macro(ext,SIP/tulip4)                      [pbx_config]
 '501' =>          1. Macro(ext,BLT/320Plantronics)              [pbx_config]
 '502' =>          1. Macro(ext,BLT/BrianC/07XXXXXXXXX)          [pbx_config]
 '601' =>          1. Macro(ext,SIP/1836@cme-london)             [pbx_config]
 '_2XX' =>         1. Macro(ext,iax2/asterisk2/${EXTEN}@incoming) [pbx_config]

[ Context 'macro-ext' created by 'pbx_config' ]
 's' =>            1. Dial(${ARG1},15)                           [pbx_config]
                   2. Playback(vm-nobodyavail)                   [pbx_config]
                   3. Hangup()                                   [pbx_config]
                   102. Wait(1)                                  [pbx_config]
                   103. Playback(tt-allbusy)                     [pbx_config]
                   104. Hangup()                                 [pbx_config]

[ Context 'skinnyregistrations' created by 'Skinny' ]
 '111' =>          1. Noop(111)                                  [Skinny]

-= 28 extensions (49 priorities) in 12 contexts. =-

Notice that the phone *did* successfully add an entry under skinnyregistrations.
But power-cycling the phone, so it tries to register again, causes the crash.
By: Brian Candler (candlerb) 2008-04-04 07:25:13

I have seen another symptom, which may or may not be related so I'll report it here. This is with regcontext commented out in skinny.conf.

What happens is that I pick up the phone and get dialtone, but the characters I dial seem to be ignored on the phone (I continue to hear dialtone). However looking at Asterisk's console, it clearly has received the button presses, but is failing to send the responses back to the phone.

Here, I pick up the phone, then dial 611.

*CLI>
*CLI> [New Thread -1216664672 (LWP 9995)]
   -- Starting simple switch on '111@brian'
[Apr  4 13:16:15] WARNING[9800]: chan_skinny.c:1800 transmit_response: Asked to transmit to a non-existant session!
[Apr  4 13:16:15] NOTICE[9800]: chan_skinny.c:3593 skinny_indicate: Asked to indicate 'Stop tone' condition on channel Skinny/111@brian-8, but session does not exist.
[Apr  4 13:16:16] WARNING[9800]: chan_skinny.c:1800 transmit_response: Asked to transmit to a non-existant session!
[Apr  4 13:16:16] NOTICE[9800]: chan_skinny.c:3593 skinny_indicate: Asked to indicate 'Stop tone' condition on channel Skinny/111@brian-8, but session does not exist.
[Apr  4 13:16:16] WARNING[9800]: chan_skinny.c:1800 transmit_response: Asked to transmit to a non-existant session!
[Apr  4 13:16:16] NOTICE[9800]: chan_skinny.c:3593 skinny_indicate: Asked to indicate 'Stop tone' condition on channel Skinny/111@brian-8, but session does not exist.
[Apr  4 13:16:18] WARNING[9800]: chan_skinny.c:1800 transmit_response: Asked to transmit to a non-existant session!
   -- Executing [611@from-skinny:1] Answer("Skinny/111@brian-8", "") in new stack
[Apr  4 13:16:18] WARNING[9800]: chan_skinny.c:1800 transmit_response: Asked to transmit to a non-existant session!
[Apr  4 13:16:18] WARNING[9800]: chan_skinny.c:1800 transmit_response: Asked to transmit to a non-existant session!
[Apr  4 13:16:18] WARNING[9800]: chan_skinny.c:1800 transmit_response: Asked to transmit to a non-existant session!
[Apr  4 13:16:18] WARNING[9800]: chan_skinny.c:1800 transmit_response: Asked to transmit to a non-existant session!
[Apr  4 13:16:18] WARNING[9800]: chan_skinny.c:1800 transmit_response: Asked to transmit to a non-existant session!
[Apr  4 13:16:18] WARNING[9800]: chan_skinny.c:1800 transmit_response: Asked to transmit to a non-existant session!
[Apr  4 13:16:18] WARNING[9800]: chan_skinny.c:1800 transmit_response: Asked to transmit to a non-existant session!
   -- Executing [611@from-skinny:2] Playback("Skinny/111@brian-8", "your-call-is-not-important") in new stack
   -- <Skinny/111@brian-8> Playing 'your-call-is-not-important.gsm' (language 'en')
   -- Executing [611@from-skinny:3] Playback("Skinny/111@brian-8", "office-iguanas") in new stack
   -- <Skinny/111@brian-8> Playing 'office-iguanas.alaw' (language 'en')
   -- Executing [611@from-skinny:4] Playback("Skinny/111@brian-8", "that-tickles") in new stack
   -- <Skinny/111@brian-8> Playing 'that-tickles.alaw' (language 'en')
   -- Executing [611@from-skinny:5] Hangup("Skinny/111@brian-8", "") in new stack
 == Spawn extension (from-skinny, 611, 5) exited non-zero on 'Skinny/111@brian-8'
[Thread -1216664672 (LWP 9995) exited]
[Apr  4 13:16:34] WARNING[9800]: chan_skinny.c:4458 handle_onhook_message: Skinny(111@brian-8) channel already destroyed

You can see that Asterisk is handling extension 611 according to the dialplan. However no audio arrives at the phone.

*CLI> help skinny
                 skinny reset Reset Skinny device(s)
    skinny set debug {on|off} Enable/Disable Skinny debugging
          skinny show devices List defined Skinny devices
           skinny show device List Skinny device information
            skinny show lines List defined Skinny lines per device
             skinny show line List Skinny line information
         skinny show settings List global Skinny settings
*CLI> skinny show devices
Name                 DeviceId         IP              Type            R NL
-------------------- ---------------- --------------- --------------- - --
brian                SEP00195659657A                  7941            N  1
*CLI> skinny show device brian
Name:        brian
Id:          SEP00195659657A
version:     P002F202
Ip address:  Unknown
Port:        0
Device Type: 7941
Registered:  No
Lines:       1
 111 (Brian Candler)
Addons:      0
Speeddials:  0
*CLI> skinny show lines
Device Name          Instance Name                 Label
-------------------- -------- -------------------- --------------------
brian                       1 111                  Brian Candler
*CLI> skinny show line brian
*CLI> skinny show line 111
Line:             111
On Device:        brian
Line Label:       Brian Candler
Extension:        <not set>
Context:          from-skinny
CallGroup:
PickupGroup:
Language:         <not set>
Accountcode:      <not set>
AmaFlag:          Unknown
CallerId Number:  020XXXXXXXX
CallerId Name:    Brian Candler
Hide CallerId:    No
CFwdAll:          <not set>
CFwdBusy:         <not set>
CFwdNoAnswer:     <not set>
VoicemailBox:     <not set>
VoicemailNumber:  <not set>
MWIblink:         0
Regextension:     <not set>
Regcontext:       <not set>
MoHInterpret:     default
MoHSuggest:       <not set>
Last dialed nr:   611
Last CallerID:    <not set>
Transfer enabled: No
Callwaiting:      No
3Way Calling:     No
Can forward:      No
Do Not Disturb:   No
NAT:              No
immediate:        No
Group:            0
Codecs:           0xc (ulaw|alaw)
Codec Order:      (none)

*CLI>

I tried "skinny reset brian" (without unplugging the phone), but nothing changes.

If I unplug and reconnect the phone, and wait for it to reboot, it seems OK after that.

I *think* the problem arises if the phone is left unused for a while, and therefore decides to re-register.

Oh, and I should have said before: this is a Cisco CP-7941G phone, firmware is TERM41.7-0-3-0S


By: Michiel van Baak (mvanbaak) 2008-04-06 10:06:02

What troubles me in your latest comment is this line under skinny show device:
Registered: No

Can you set your keepalive to a smaller value and see if this fixes the problem?
mine is set to 30
By: Brian Candler (candlerb) 2008-04-10 05:09:31

Sorry, I have been away for a few days.

To ensure I'm up to date, I have cleanly rebuilt asterisk/branches/1.6.0 (svn update; make distclean; ./configure --enable-dev-mode; make menuselect; make; sudo make install)

PROBLEM 1: crash in pbx.c:6209

With keepalive=120, and regcontext enabled in skinny.conf, I can cause a crash as before (by starting asterisk, waiting for the phone to register, unplugging and replugging the phone)

With keepalive=30, I cannot crash it in this way. It takes 48 seconds from plugging in the phone until it re-registers. A possibility, therefore, is that the crash occurs when a phone re-registers while it is already registered.

PROBLEM 2: "transmit to a non-existant [sic] session"

This was more difficult to replicate anyway, as it involved leaving the phone for an extended period of time and then trying to make a call later.

A quick attempt to replicate with keepalive=30 and regcontext enabled failed (I left the phone for about half an hour, and it made a call successfully)

I have tried setting keepalive back to 120, commenting out regcontext to prevent the crash, and will let you know if I can replicate it this way again.

Note that the initially reported crash (problem 1) remains entirely reproducible.
By: Michiel van Baak (mvanbaak) 2008-04-10 05:25:59

Ok, thanks.
This makes it clear there's not a bug in chan_skinny, but in the code to create/update the extensions.
By: Brian Candler (candlerb) 2008-04-10 07:56:07

FYI I can now repeat problem 2 reliably, which appears to be related in some way. What you do is (with keepalive=120):

1. restart asterisk
2. wait for phone to register itself (it starts a thread)
3. unplug and replug the phone (it starts another thread)
4. wait for the thread started in step (2) to terminate

The phone is now considered 'unregistered' by Asterisk, but as far as the phone is concerned it is talking happily. Hell breaks loose when you start pressing buttons on it, as Asterisk processes the button presses but doesn't know where to send the replies.

[Apr 10 13:44:59] Asterisk Ready.
[New Thread -1214932064 (LWP 17584)]
*CLI> [New Thread -1215177824 (LWP 17585)]   << INITIAL REGISTRATION
[Apr 10 13:45:10]     -- Starting Skinny session from 10.69.255.249
[Apr 10 13:45:10]     -- Device 'SEP00195659657A' successfully registered
[Apr 10 13:45:10] Adding button: 9, 1
[Apr 10 13:45:10] Device capability set to '12'

*CLI> skinny show device brian
Name:        brian
Id:          SEP00195659657A
version:     P002F202
Ip address:  10.69.255.249
Port:        52528
Device Type: 7941
Registered:  Yes         <<<<<<<<< NOTE
Lines:       1
 111 (Brian Candler)
Addons:      0
Speeddials:  0
*CLI> [New Thread -1215423584 (LWP 17594)]    << SECOND REGISTRATION
[Apr 10 13:46:06]     -- Starting Skinny session from 10.69.255.249
[Apr 10 13:46:06]     -- Device 'SEP00195659657A' successfully registered
[Apr 10 13:46:06] Adding button: 9, 1
[Apr 10 13:46:06] Device capability set to '12'
skinny show device brian
Name:        brian
Id:          SEP00195659657A
version:     P002F202
Ip address:  10.69.255.249
Port:        49954
Device Type: 7941
Registered:  Yes          <<<<<<<<< NOTE
Lines:       1
 111 (Brian Candler)
Addons:      0
Speeddials:  0
*CLI> [Apr 10 13:46:44]     -- ast_get_srv: SRV lookup for '_sip._UDP.sipgate.co.uk' mapped to host sipgate.co.uk, port 5060
[Apr 10 13:46:44]     -- ast_get_srv: SRV lookup for '_sip._UDP.sipgate.co.uk' mapped to host sipgate.co.uk, port 5060
[Thread -1215177824 (LWP 17585) exited]   << INITIAL REGISTRATION EXPIRED!
[Apr 10 13:48:29]     -- ast_get_srv: SRV lookup for '_sip._UDP.sipgate.co.uk' mapped to host sipgate.co.uk, port 5060
[Apr 10 13:48:29]     -- ast_get_srv: SRV lookup for '_sip._UDP.sipgate.co.uk' mapped to host sipgate.co.uk, port 5060
skinny show device brian
Name:        brian
Id:          SEP00195659657A
version:     P002F202
Ip address:  Unknown
Port:        0
Device Type: 7941
Registered:  No            <<<<<<< NOTE!!!
Lines:       1
 111 (Brian Candler)
Addons:      0
Speeddials:  0
*CLI> [Apr 10 13:50:07] WARNING[17560]: chan_skinny.c:1557  find_subchannel_by_instance_reference: Could not find subchannel with reference '0' on 'brian'  << PICKED UP HERE
[New Thread -1215177824 (LWP 17595)]
[Apr 10 13:50:07]     -- Starting simple switch on '111@brian'
[Apr 10 13:50:09] WARNING[17560]: chan_skinny.c:1827 transmit_response: Asked to transmit to a non-existant session!
[Apr 10 13:50:09] NOTICE[17560]: chan_skinny.c:3644 skinny_indicate: Asked to indicate 'Stop tone' condition on channel Skinny/111@brian-1, but session does not exist.
[Apr 10 13:50:10] WARNING[17560]: chan_skinny.c:1827 transmit_response: Asked to transmit to a non-existant session!
[Apr 10 13:50:10] NOTICE[17560]: chan_skinny.c:3644 skinny_indicate: Asked to indicate 'Stop tone' condition on channel Skinny/111@brian-1, but session does not exist.
[Apr 10 13:50:10] WARNING[17560]: chan_skinny.c:1827 transmit_response: Asked to transmit to a non-existant session!
[Apr 10 13:50:10] NOTICE[17560]: chan_skinny.c:3644 skinny_indicate: Asked to indicate 'Stop tone' condition on channel Skinny/111@brian-1, but session does not exist.
[Apr 10 13:50:12] WARNING[17560]: chan_skinny.c:1827 transmit_response: Asked to transmit to a non-existant session!
[Apr 10 13:50:12] WARNING[17560]: chan_skinny.c:1827 transmit_response: Asked to transmit to a non-existant session!
[Apr 10 13:50:12]     -- Executing [611@from-skinny:1] Answer("Skinny/111@brian-1", "") in new stack
[Apr 10 13:50:12] WARNING[17560]: chan_skinny.c:1827 transmit_response: Asked to transmit to a non-existant session!
[Apr 10 13:50:12] WARNING[17560]: chan_skinny.c:1827 transmit_response: Asked to transmit to a non-existant session!
[Apr 10 13:50:12] WARNING[17560]: chan_skinny.c:1827 transmit_response: Asked to transmit to a non-existant session!
[Apr 10 13:50:12] WARNING[17560]: chan_skinny.c:1827 transmit_response: Asked to transmit to a non-existant session!
[Apr 10 13:50:12] WARNING[17560]: chan_skinny.c:1827 transmit_response: Asked to transmit to a non-existant session!
[Apr 10 13:50:12] WARNING[17560]: chan_skinny.c:1827 transmit_response: Asked to transmit to a non-existant session!
[Apr 10 13:50:12]     -- Executing [611@from-skinny:2] Playback("Skinny/111@brian-1", "your-call-is-not-important") in new stack
[Apr 10 13:50:12]     -- <Skinny/111@brian-1> Playing 'your-call-is-not-important.gsm' (language 'en')

The problem goes away if you set keepalive=30, because the original connection thread terminates itself before the phone reboots:

*CLI> [New Thread -1215685728 (LWP 17630)]     << INITIAL REGISTRATION
[Apr 10 13:52:32]     -- Starting Skinny session from 10.69.255.249
[Apr 10 13:52:32]     -- Device 'SEP00195659657A' successfully registered
[Apr 10 13:52:32] Adding button: 9, 1
[Apr 10 13:52:32] Device capability set to '12'
[Thread -1215685728 (LWP 17630) exited]     << INITIAL REGISTRATION EXPIRED
[New Thread -1215685728 (LWP 17637)]        << NEW REGISTRATION
[Apr 10 13:53:22]     -- Starting Skinny session from 10.69.255.249
[Apr 10 13:53:22]     -- Device 'SEP00195659657A' successfully registered
[Apr 10 13:53:22] Adding button: 9, 1
[Apr 10 13:53:22] Device capability set to '12'

So the problem seems to be that when a session expires the phone is forcibly unregistered, even if the phone has in the mean time re-registered via another session. Whether the responsibility for detecting this condition lies with chan_skinny or core, though, I don't know. If it's chan_skinny I'll open a new ticket.

Aside: I'm using a timeout of 120 because that's what configs/skinny.conf.sample shows.
By: Jason Parker (jparker) 2008-04-22 17:05:38

I am quite confident that the fix for ASTERISK-11872 fixed this issue as well.

Please see the referenced issue for details.