[Home]

Summary:ASTERISK-07852: [patch] crash when calling skinny phone, that is unregistered
Reporter:pj (pj)Labels:
Date Opened:2006-10-02 05:36:27Date Closed:2006-10-09 11:15:43
Priority:CriticalRegression?No
Status:Closed/CompleteComponents:Channels/chan_skinny
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) patch.diff
Description:asterisk crashes when calling phone, that is not available/unregistered
asterisk probably doesn't correctly handle phone unregistering
look below at column R, where is still "Y", even if phone is off

Asterisk SVN-branch-1.4-r43997

ipbx*CLI> skinny list devices
Name                 DeviceId         IP              Type            R NL
-------------------- ---------------- --------------- --------------- - --
PJ                   SEP000D288E664B  0.0.0.0         7920            Y  1


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

debug traces:

(gdb) bt full
#0  0xbfffe410 in __kernel_vsyscall ()
No symbol table info available.
#1  0xb7d17fc0 in raise () from /lib/i686/libc.so.6
No symbol table info available.
#2  0xb7d19851 in abort () from /lib/i686/libc.so.6
No symbol table info available.
#3  0xb7d4d41b in __fsetlocking () from /lib/i686/libc.so.6
No symbol table info available.
#4  0xb7d54dad in mallopt () from /lib/i686/libc.so.6
No symbol table info available.
ASTERISK-1  0xb7d54f33 in free () from /lib/i686/libc.so.6
No symbol table info available.
ASTERISK-2  0xb78f21b8 in iax2_destroy (callno=28) at chan_iax2.c:1771
      frame = {data = 0xb793ad00, ts = -1224847976, ms = -1215410237, type = 3079908608, next = 0x2a, prev = 0xb78f1eeb}
      pvt = Variable "pvt" is not available.


(gdb) bt
#0  0xbfffe410 in __kernel_vsyscall ()
#1  0xb7d17fc0 in raise () from /lib/i686/libc.so.6
#2  0xb7d19851 in abort () from /lib/i686/libc.so.6
#3  0xb7d4d41b in __fsetlocking () from /lib/i686/libc.so.6
#4  0xb7d54dad in mallopt () from /lib/i686/libc.so.6
ASTERISK-1  0xb7d54f33 in free () from /lib/i686/libc.so.6
ASTERISK-2  0xb78f21b8 in iax2_destroy (callno=28) at chan_iax2.c:1771
ASTERISK-3  0xb78fb523 in iax2_hangup (c=0x81d5b40) at chan_iax2.c:2925
ASTERISK-4  0x0807f5ce in ast_hangup (chan=0x81d5b40) at channel.c:1560
ASTERISK-5  0x080bff0d in __ast_pbx_run (c=0x81d5b40) at pbx.c:2496
ASTERISK-6 0x080c093e in pbx_thread (data=0x81d5b40) at pbx.c:2556
ASTERISK-7 0x080ead1b in dummy_start (data=0x81c4a60) at utils.c:538
ASTERISK-8 0xb7f4d540 in start_thread () from /lib/i686/libpthread.so.0
ASTERISK-9 0xb7dba55e in clone () from /lib/i686/libc.so.6



console log:


[Sep 29 22:42:44]     -- Executing [s@macro-call_local_lines:2] Dial("IAX2/bill-gw-28", "Skinny/324@PJ") in new stack
[Sep 29 22:42:44]     -- skinny_request(324@PJ)
[Sep 29 22:42:44] WARNING[22305]: chan_skinny.c:1354 transmit_response: Transmit: write only sent -1 out of 24 bytes: Bad file descriptor
[Sep 29 22:42:44] WARNING[22305]: chan_skinny.c:1354 transmit_response: Transmit: write only sent -1 out of 24 bytes: Bad file descriptor
[Sep 29 22:42:44] WARNING[22305]: chan_skinny.c:1354 transmit_response: Transmit: write only sent -1 out of 16 bytes: Bad file descriptor
[Sep 29 22:42:44] WARNING[22305]: chan_skinny.c:1354 transmit_response: Transmit: write only sent -1 out of 216 bytes: Bad file descriptor
[Sep 29 22:42:44] WARNING[22305]: chan_skinny.c:1354 transmit_response: Transmit: write only sent -1 out of 24 bytes: Bad file descriptor
[Sep 29 22:42:44] WARNING[22305]: chan_skinny.c:1354 transmit_response: Transmit: write only sent -1 out of 56 bytes: Bad file descriptor
[Sep 29 22:42:44] WARNING[22305]: chan_skinny.c:1354 transmit_response: Transmit: write only sent -1 out of 28 bytes: Bad file descriptor
[Sep 29 22:42:44]     -- Called 324@PJ
[Sep 29 22:42:44]     -- Skinny/324@PJ-4 is ringing
[Sep 29 22:42:44] NOTICE[21557]: sched.c:283 ast_sched_del: Attempted to delete nonexistent schedule entry 0!
ipbx*CLI> *** glibc detected *** asterisk: double free or corruption (!prev): 0x081c0ec0 ***
======= Backtrace: =========
/lib/i686/libc.so.6[0xb7d54dad]
/lib/i686/libc.so.6(__libc_free+0x83)[0xb7d54f33]
/usr/lib/asterisk/modules/chan_iax2.so[0xb78f21b8]
/usr/lib/asterisk/modules/chan_iax2.so[0xb78fb523]
asterisk(ast_hangup+0x31e)[0x807f5ce]
asterisk[0x80bff0d]
asterisk[0x80c093e]
asterisk[0x80ead1b]
/lib/i686/libpthread.so.0[0xb7f4d540]
/lib/i686/libc.so.6(__clone+0x5e)[0xb7dba55e]
======= Memory map: ========
08048000-08139000 r-xp 00000000 03:02 326366     /usr/sbin/asterisk
08139000-08146000 rwxp 000f1000 03:02 326366     /usr/sbin/asterisk
08146000-081df000 rwxp 08146000 00:00 0          [heap]
b6f64000-b6f65000 ---p b6f64000 00:00 0
b6f65000-b6fa5000 rwxp b6f65000 00:00 0
b6fa5000-b6fa6000 ---p b6fa5000 00:00 0
b6fa6000-b6fe6000 rwxp b6fa6000 00:00 0
b6fe6000-b6fe7000 ---p b6fe6000 00:00 0
b6fe7000-b7027000 rwxp b6fe7000 00:00 0
b7027000-b7028000 ---p b7027000 00:00 0
b7028000-b7068000 rwxp b7028000 00:00 0
b7068000-b7069000 ---p b7068000 00:00 0
b7069000-b70a9000 rwxp b7069000 00:00 0
b70a9000-b70aa000 ---p b70a9000 00:00 0
b70aa000-b70ea000 rwxp b70aa000 00:00 0
b70ea000-b70eb000 ---p b70ea000 00:00 0
b70eb000-b712b000 rwxp b70eb000 00:00 0
b712b000-b712c000 r-xp 00000000 03:02 263246     /usr/lib/asterisk/modules/func_uri.so
b712c000-b712d000 rwxp 00001000 03:02 263246     /usr/lib/asterisk/modules/func_uri.so
b712d000-b712f000 r-xp 00000000 03:02 263245     /usr/lib/asterisk/modules/func_timeout.so
b712f000-b7130000 rwxp 00001000 03:02 263245     /usr/lib/asterisk/modules/func_timeout.so
b7130000-b7134000 r-xp 00000000 03:02 263244     /usr/lib/asterisk/modules/func_strings.so
b7134000-b7135000 rwxp 00003000 03:02 263244     /usr/lib/asterisk/modules/func_strings.so
b7135000-b7136000 r-xp 00000000 03:02 263243     /usr/lib/asterisk/modules/func_sha1.so
b7136000-b7137000 rwxp 00000000 03:02 263243     /usr/lib/asterisk/modules/func_sha1.so
b7137000-b7139000 r-xp 00000000 03:02 263242     /usr/lib/asterisk/modules/func_realtime.so
b7139000-b713a000 rwxp 00001000 03:02 263242     /usr/lib/asterisk/modules/func_realtime.so
b713a000-b713c000 r-xp 00000000 03:02 263241     /usr/lib/asterisk/modules/func_rand.so
b713c000-b713d000 rwxp 00001000 03:02 263241     /usr/lib/asterisk/modules/func_rand.so
b713d000-b713e000 r-xp 00000000 03:02 263240     /usr/lib/asterisk/modules/func_moh.so
b713e000-b713f000 rwxp 00001000 03:02 263240     /usr/lib/asterisk/modules/func_moh.so
b713f000-b7141000 r-xp 00000000 03:02 263239     /usr/lib/asterisk/modules/func_md5.so
b7141000-b7142000 rwxp 00001000 03:02 263239     /usr/lib/asterisk/modules/func_md5.so
b7142000-b7144000 r-xp 00000000 03:02 263238     /usr/lib/asterisk/modules/func_math.so
b7144000-b7145000 rwxp 00001000 03:02 263238     /usr/lib/asterisk/modules/func_math.so
b7145000-b7147000 r-xp 00000000 03:02 263237     /usr/lib/asterisk/modules/func_logic.so
b7147000-b7148000 rwxp 00001000 03:02 263237     /usr/lib/asterisk/modules/func_logic.so
b7148000-b7149000 r-xp 00000000 03:02 263236     /usr/lib/asterisk/modules/func_language.so
b7149000-b714a000 rwxp 00001000 03:02 263236     /usr/lib/asterisk/modules/func_language.so
b714a000-b714c000 r-xp 00000000 03:02 263235     /usr/lib/asterisk/modules/func_groupcount.so
b714c000-b714d000 rwxp 00001000 03:02 263235     /usr/lib/asterisk/modules/func_groupcount.so
b714d000-b714e000 r-xp 00000000 03:02 263234     /usr/lib/asterisk/modules/func_global.so
b714e000-b714f000 rwxp 00000000 03:02 263234     /usr/lib/asterisk/modules/func_global.so
b714f000-b7151000 r-xp 00000000 03:02 263233     /usr/lib/asterisk/modules/func_env.so
b7151000-b7152000 rwxp 00001000 03:02 263233     /usr/lib/asterisk/modules/func_env.so
b7152000-b7154000 r-xp 00000000 03:02 263232     /usr/lib/asterisk/modules/func_enum.so
b7154000-b7155000 rwxp 00001000 03:02 263232     /usr/lib/asterisk/modules/func_enum.so
[Sep 29 22:42:54] NOTICE[21551]: sched.c:283 ast_sched_del: Attempted to delete nonexistent schedule entry 0!
[Sep 29 22:42:54] NOTICE[21551]: sched.c:283 ast_sched_del: Attempted to delete nonexistent schedule entry 0!
[Sep 29 22:42:54] NOTICE[21551]: sched.c:283 ast_sched_del: Attempted to delete nonexistent schedule entry 0!
[Sep 29 22:42:54] NOTICE[21551]: sched.c:283 ast_sched_del: Attempted to delete nonexistent schedule entry 0!
ipbx*CLI>
Disconnected from Asterisk server
[Sep 29 22:42:54] Executing last minute cleanups
Comments:By: pj (pj) 2006-10-02 15:03:37

additional info:
asterisk crashes, when issue command "skinny reset" to device, what is unregistered (unavailable):

ipbx*CLI> skinny show devices
Name                 DeviceId         IP              Type            R NL
-------------------- ---------------- --------------- --------------- - --
PJ                   SEP000D288E664B  0.0.0.0         7920            Y  1

ipbx*CLI> skinny reset SEP000D288E664B
ipbx*CLI>
Disconnected from Asterisk server
[Oct  2 21:50:29] Executing last minute cleanups




(gdb) bt
#0  0xb7d8c4c7 in free () from /lib/i686/libc.so.6
#1  0xb7d8da84 in calloc () from /lib/i686/libc.so.6
#2  0xb7922a26 in find_callno (callno=21, dcallno=0, sin=0xb788933c, new=1, lockpeer=1, sockfd=9) at ../include/asterisk/utils.h:327
#3  0xb792cd9e in socket_process (thread=0x818acc8) at chan_iax2.c:6447
#4  0xb793739f in iax2_process_thread (data=0x818acc8) at chan_iax2.c:7637
ASTERISK-1  0x080ead1b in dummy_start (data=0x81899a8) at utils.c:538
ASTERISK-2  0xb7f84540 in start_thread () from /lib/i686/libpthread.so.0
ASTERISK-3  0xb7df155e in clone () from /lib/i686/libc.so.6



(gdb) bt full
#0  0xb7d8c4c7 in free () from /lib/i686/libc.so.6
No symbol table info available.
#1  0xb7d8da84 in calloc () from /lib/i686/libc.so.6
No symbol table info available.
#2  0xb7922a26 in find_callno (callno=21, dcallno=0, sin=0xb788933c, new=1, lockpeer=1, sockfd=9) at ../include/asterisk/utils.h:327
       res = 0
       x = 62
       now = {tv_sec = 1159819308, tv_usec = 778061}
       host = "prec\000\004\016\b??\027\b\223\035\000\0009l&ASTERISK-342;&ASTERISK-705;$W\224&ASTERISK-705;\000\000\000\000\030\021\034\b(m\210&ASTERISK-705;$W\224&ASTERISK-705;\030\021\034\b\030\021\034\b\bm\210&ASTERISK-705;'\036\221&ASTERISK-705;??\027\b?\n\000\000`z\224&ASTERISK-705;\221b&ASTERISK-342;&ASTERISK-705;6\000\000\000\223\035\000"
       __PRETTY_FUNCTION__ = "find_callno"
#3  0xb792cd9e in socket_process (thread=0x818acc8) at chan_iax2.c:6447
       callno = Variable "callno" is not available.
By: Anthony LaMantia (alamantia) 2006-10-02 15:42:18

was this backtrace generated from an asterisk build compiled  with dont-optimize selected via menuselect?
By: Anthony LaMantia (alamantia) 2006-10-02 16:43:05

also, do you have any information on how the skinnny phone is being unregistered via asterisk,  skinny_unregister() should set the register flag to 0 as well and null-out the skinny session variable  ( d->session  in it's use in skinny_reset_device) which would prevent it calling transmit_response which is the only place i can see this cli handler causing a segfault.. as for when dialing the phone i still need to test this out. but if you have more information it would be great.
By: Jason Parker (jparker) 2006-10-02 21:23:19

Without having too much (or any, as it were) time to look into this, I do believe I know what the cause is.

Basically, when a phone is unplugged (or anything like that), the session isn't destroyed (struct skinnysession *s).  The problem probably lies within the poll (or whatever call it uses) in the main session loop (skinny_session()?).

Anthony, if you want to give me a call on my cell tomorrow (you know where to find the number - 256 areacode), I can give you a brief overview of how it all works.

pj, were you the one who sent a similar message to the asterisk-dev mailing list the other day?
By: pj (pj) 2006-10-03 02:31:02

hello, this backtrace is probably from asterisk compiled without "dont-optimize" flag, so sorry if it useless
phone is unregistered by simply power off (I have wifi 7920, with fw2.0)
and yes, I was reported this issue to -dev list, some days ago...
I can help with testing/debugging, but I'm not developer, so can't help with making patch for this ;-(
PJ


here is console log, when power off
ipbx*CLI> skinny show devices
Name                 DeviceId         IP              Type            R NL
-------------------- ---------------- --------------- --------------- - --
PJ                   SEP000D288E664B  193.179.xx.xx  7920            Y  1
ipbx*CLI>


[Oct  3 09:23:13] WARNING[12024]: chan_skinny.c:4175 get_input: read() returned error: Connection reset by peer
[Oct  3 09:23:13] NOTICE[12024]: chan_skinny.c:4259 skinny_session: Skinny Session returned: Connection reset by peer
ipbx*CLI>
ipbx*CLI> skinny show devices
Name                 DeviceId         IP              Type            R NL
-------------------- ---------------- --------------- --------------- - --
PJ                   SEP000D288E664B  0.0.0.0         7920            Y  1

and power on again:
[Oct  3 09:23:40]     -- Starting Skinny session from 193.179.xx.xx
[Oct  3 09:23:40]     -- Device 'SEP000D288E664B' successfully registered
[Oct  3 09:23:40] Device capability set to '8'
[Oct  3 09:23:40] Adding button: 9, 1
ipbx*CLI>
ipbx*CLI> skinny show devices
Name                 DeviceId         IP              Type            R NL
-------------------- ---------------- --------------- --------------- - --
PJ                   SEP000D288E664B  193.179.xx.xx  7920            Y  1
By: Anthony LaMantia (alamantia) 2006-10-04 16:06:11

pj: can you test the uploaded patch and report back your experiance with it?
By: nguyencongtriet (nguyencongtriet) 2006-10-04 22:30:16

I got the same problem on SVN r44392:
The system crash after try to delete:
ast_sched_del: Attempted to delete nonexistent schedule entry 19784!
*** glibc detected *** asterisk: double free or corruption (!prev): 0x081c0ec0 ***
By: pj (pj) 2006-10-05 04:37:19

sad to say, this patch doesn't help, still exactly same problem, phone seems to be still registered (even if off) and when I call to this phone asterisk crashes (tried with todays 1.4 branch)
By: Anthony LaMantia (alamantia) 2006-10-05 14:04:37

I have written a new patch that i would like you to test and report back on, just so you know qwell will be back in soon and can assist us a bit with this bug.. right now i'm preforming most of my tests using a skinny softphone i have to hack up to test the channel out and i'm not sure if it's 100% compilant with the cisco phones that you are using..

please test the patch and inform us if the crash is still happening.
By: pj (pj) 2006-10-05 16:56:37

I can say, that chan_skinny is currently unregistering phone corectly.
If I call to unregistered phone it does NOT crash asterisk.
I will be happy, if this patch will be soon in 1.4branch :-)
tested: Asterisk SVN-branch-1.4-r44502M
By: Jason Parker (jparker) 2006-10-09 11:15:42

Fixed in branch 1.4 in revision 44764, and trunk in revision 44765.