[Home]

Summary:ASTERISK-17572: Skinny to Skinny transfer crash
Reporter:Mark Murawski (kobaz)Labels:
Date Opened:2011-03-17 16:42:53Date Closed:2013-03-08 02:01:19.000-0600
Priority:CriticalRegression?No
Status:Closed/CompleteComponents:Channels/chan_skinny
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) skinny.conf
( 1) skinny-crash
Description:Transferring from a skinny phone to another skinny phone will seg fault.


Sip phone calls skinny phone
skinny phone attended transfers to another skinny phone

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

2011-03-17 17:41:52] NOTICE[14117]: pbx.c:4921 __ast_pbx_run: pbx_run finished for SIP/6288-00000005, (nil) -100
[2011-03-17 17:41:52] NOTICE[14117]: channel.c:608 ast_channel_run_registered_hangup_handlers: No hangup handlers for channel: SIP/6288-00000005
 == Using SIP RTP CoS mark 5
   -- Executing [1000@cos_internal+local+ld:1] Goto("SIP/6288-00000006", "_cos_internal+local+ld,1000,1") in new stack
   -- Goto (_cos_internal+local+ld,1000,1)
   -- Executing [1000@_cos_internal+local+ld:1] Dial("SIP/6288-00000006", "SCCP/1000") in new stack
[2011-03-17 17:41:52] WARNING[14121]: channel.c:5647 ast_request: No channel type registered for 'SCCP'
[2011-03-17 17:41:52] WARNING[14121]: app_dial.c:2045 dial_exec_full: Unable to create channel of type 'SCCP' (cause 66 - Channel not implemented)
 == Everyone is busy/congested at this time (1:0/0/1)
   -- Executing [1000@_cos_internal+local+ld:2] Dial("SIP/6288-00000006", "Skinny/1000") in new stack
   -- skinny_request(1000)
   -- Called 1000
   -- SIP/6288-00000006 calling Skinny/1000@SEP0014A9239820-3 (callee is ringing)
   -- Skinny/1000@SEP0014A9239820-3 answered SIP/6288-00000006
   -- Starting simple switch on '1000@SEP0014A9239820'
   -- Started music on hold, class 'default', on channel 'SIP/6288-00000006'
   -- Executing [1001@cos_internal+local+ld+intl:1] Goto("Skinny/1000@SEP0014A9239820-4", "_cos_internal+local+ld+intl,1001,1") in new stack
   -- Goto (_cos_internal+local+ld+intl,1001,1)
   -- Executing [1001@_cos_internal+local+ld+intl:1] Dial("Skinny/1000@SEP0014A9239820-4", "SCCP/1001") in new stack
[2011-03-17 17:41:58] WARNING[14123]: channel.c:5647 ast_request: No channel type registered for 'SCCP'
[2011-03-17 17:41:58] WARNING[14123]: app_dial.c:2045 dial_exec_full: Unable to create channel of type 'SCCP' (cause 66 - Channel not implemented)
 == Everyone is busy/congested at this time (1:0/0/1)
   -- Executing [1001@_cos_internal+local+ld+intl:2] Dial("Skinny/1000@SEP0014A9239820-4", "Skinny/1001") in new stack
   -- skinny_request(1001)
   -- Called 1001
   -- Skinny/1000@SEP0014A9239820-4 calling Skinny/1001@SEP001121D89A42-5 (callee is ringing)
   -- Skinny/1001@SEP001121D89A42-5 answered Skinny/1000@SEP0014A9239820-4
   -- Locally bridging Skinny/1000@SEP0014A9239820-4 and Skinny/1001@SEP001121D89A42-5
   -- Stopped music on hold on SIP/6288-00000006
[2011-03-17 17:42:02] NOTICE[14121]: chan_skinny.c:4195 skinny_fixup: skinny_fixup(Skinny/1001@SEP001121D89A42-5, Skinny/1001@SEP001121D89A42-5<MASQ>)
      > Killing inactive sub 3
Comments:By: Mark Murawski (kobaz) 2011-03-17 16:43:49

uploaded console output
uploaded backtrace
By: David Woolley (davidw) 2011-03-18 07:02:57

Which thread crashed?  I believe the reporting protocol requires bt on the current thread before the thread apply all bt's.
By: Mark Murawski (kobaz) 2011-03-18 11:39:09

Thread 3
By: Damien Wedhorn (wedhorn) 2011-03-18 15:44:26

Kobaz, how are you doing the transfer? I can't align your console output to a normal device or features transfer.

Also, can you "skinny set debug on" for the console output.
By: Mark Murawski (kobaz) 2011-03-21 09:50:10

Heres without debug

########### 2609 calls 2610, 2610 answers
*CLI>   == Using SIP RTP CoS mark 5
   -- Executing [2610@cos_internal+local+ld+intl:1] Goto("SIP/2609-00000001", "_cos_internal+local+ld+intl,2610,1") in new stack
   -- Goto (_cos_internal+local+ld+intl,2610,1)
   -- Executing [2610@_cos_internal+local+ld+intl:1] Dial("SIP/2609-00000001", "Skinny/2610") in new stack
   -- skinny_request(2610)
   -- Called 2610
   -- SIP/2609-00000001 calling Skinny/2610@SEP0014A9239820-3 (callee is ringing)
   -- Skinny/2610@SEP0014A9239820-3 answered SIP/2609-00000001

*CLI>
*CLI>
*CLI>
########### 2610 calls 2611
*CLI>     -- Started music on hold, class 'default', on channel 'SIP/2609-00000001'
   -- Starting simple switch on '2610@SEP0014A9239820'
   -- Executing [2611@cos_internal+local+ld+intl:1] Goto("Skinny/2610@SEP0014A9239820-4", "_cos_internal+local+ld+intl,2611,1") in new stack
   -- Goto (_cos_internal+local+ld+intl,2611,1)
   -- Executing [2611@_cos_internal+local+ld+intl:1] Dial("Skinny/2610@SEP0014A9239820-4", "Skinny/2611") in new stack
   -- skinny_request(2611)
   -- Called 2611
   -- Skinny/2610@SEP0014A9239820-4 calling Skinny/2611@SEP001121D89A42-5 (callee is ringing)

*CLI>
*CLI>
*CLI>
########### 2611 answers
*CLI>
*CLI>
*CLI>     -- Skinny/2611@SEP001121D89A42-5 answered Skinny/2610@SEP0014A9239820-4
   -- Locally bridging Skinny/2610@SEP0014A9239820-4 and Skinny/2611@SEP001121D89A42-5

*CLI>

########### complete transfer from 2610 to 2610
*CLI>
*CLI>
*CLI> [2011-03-21 10:43:27] NOTICE[6932]: chan_skinny.c:4195 skinny_fixup: skinny_fixup(Skinny/2611@SEP001121D89A42-5, Skinny/2611@SEP001121D89A42-5<MASQ>)
      > Killing inactive sub 3

Segmentation fault (core dumped)
demo2 {/apps} root#
By: Mark Murawski (kobaz) 2011-03-21 09:54:21

################# 2609 calls 2610
*CLI>   == Using SIP RTP CoS mark 5
   -- Executing [2610@cos_internal+local+ld+intl:1] Goto("SIP/2609-00000000", "_cos_internal+local+ld+intl,2610,1") in new stack
   -- Goto (_cos_internal+local+ld+intl,2610,1)
   -- Executing [2610@_cos_internal+local+ld+intl:1] Dial("SIP/2609-00000000", "Skinny/2610") in new stack
   -- skinny_request(2610)
skinny_new: tmp->nativeformats=0xc (ulaw|alaw) fmt=ulaw
skinny_get_rtp_peer() Channel = Skinny/2610@SEP0014A9239820-1
   -- skinny_call(Skinny/2610@SEP0014A9239820-1)
Displaying Prompt Status 'Ring-In'
Setting Callinfo to 2609(2609) from Cisco 2610(2610) on SEP0014A9239820(1)
Setting ringer mode to '2'.
 == Found device: SEP0014A9239820
   -- Called 2610
   -- SIP/2609-00000000 calling Skinny/2610@SEP0014A9239820-1 (callee is ringing)

*CLI>
*CLI>
*CLI>
*CLI>
*CLI>
*CLI>
*CLI>
################# 2610 answers
*CLI>  Received Softkey Event: Answer(1/1)
Setting ringer mode to '1'.
 == Found device: SEP0014A9239820
   -- Skinny/2610@SEP0014A9239820-1 answered SIP/2609-00000000
   -- Asked to indicate 'Media Source Update' condition on channel Skinny/2610@SEP0014A9239820-1
skinny_get_rtp_peer() Channel = Skinny/2610@SEP0014A9239820-1
skinny_get_rtp_peer() Using AST_RTP_GLUE_RESULT_LOCAL
RECEIVED UNKNOWN MESSAGE TYPE:  49
Received Open Receive Channel Ack
device ipaddr = 192.168.50.105:17494
asterisk ipaddr = 192.168.50.1:16594
Setting payloadType to 'ulaw' (20 ms)
skinny_get_rtp_peer() Channel = Skinny/2610@SEP0014A9239820-1
skinny_get_rtp_peer() Using AST_RTP_GLUE_RESULT_LOCAL

*CLI>
*CLI>
*CLI>
*CLI>
*CLI>
*CLI>
################# 2610 transfer to 2611, 2611 answers
*CLI>  Received Softkey Event: Transfer(1/1)
Putting on Hold(1)
skinny_new: tmp->nativeformats=0xc (ulaw|alaw) fmt=ulaw
Clearing Display
   -- Started music on hold, class 'default', on channel 'SIP/2609-00000000'
   -- Starting simple switch on '2610@SEP0014A9239820'
Collected digit: [2]
   -- Asked to indicate 'Stop tone' condition on channel Skinny/2610@SEP0014A9239820-2
Collected digit: [6]
   -- Asked to indicate 'Stop tone' condition on channel Skinny/2610@SEP0014A9239820-2
Collected digit: [1]
   -- Asked to indicate 'Stop tone' condition on channel Skinny/2610@SEP0014A9239820-2
Collected digit: [1]
   -- Asked to indicate 'Stop tone' condition on channel Skinny/2610@SEP0014A9239820-2
 == Found device: SEP0014A9239820
   -- Executing [2611@cos_internal+local+ld+intl:1] Goto("Skinny/2610@SEP0014A9239820-2", "_cos_internal+local+ld+intl,2611,1") in new stack
   -- Goto (_cos_internal+local+ld+intl,2611,1)
   -- Executing [2611@_cos_internal+local+ld+intl:1] Dial("Skinny/2610@SEP0014A9239820-2", "Skinny/2611") in new stack
   -- skinny_request(2611)
skinny_new: tmp->nativeformats=0xc (ulaw|alaw) fmt=ulaw
skinny_get_rtp_peer() Channel = Skinny/2611@SEP001121D89A42-3
skinny_get_rtp_peer() Channel = Skinny/2610@SEP0014A9239820-2
skinny_get_rtp_peer() Using AST_RTP_GLUE_RESULT_LOCAL
   -- skinny_call(Skinny/2611@SEP001121D89A42-3)
Displaying Prompt Status 'Ring-In'
Setting Callinfo to Cisco 2610(2610) from Cisco 2611(2611) on SEP001121D89A42(1)
Setting ringer mode to '2'.
 == Found device: SEP001121D89A42
   -- Called 2611
   -- Skinny/2610@SEP0014A9239820-2 calling Skinny/2611@SEP001121D89A42-3 (callee is ringing)
   -- Asked to indicate 'Remote end is ringing' condition on channel Skinny/2610@SEP0014A9239820-2
Received Open Receive Channel Ack
device ipaddr = 192.168.50.105:19040
asterisk ipaddr = 192.168.50.1:16630
Displaying Prompt Status 'Ring Out'
Setting payloadType to 'ulaw' (20 ms)
Setting Callinfo to Cisco 2610(2610) from 2611(2611) on SEP0014A9239820(1)
Received Softkey Event: Answer(1/3)
Setting ringer mode to '1'.
 == Found device: SEP001121D89A42
   -- Skinny/2611@SEP001121D89A42-3 answered Skinny/2610@SEP0014A9239820-2
skinny_answer(Skinny/2610@SEP0014A9239820-2) on 2610@SEP0014A9239820-2
 == Found device: SEP0014A9239820
Setting Callinfo to (2611) from 2611(2611) on SEP0014A9239820(1)
Displaying Prompt Status 'Connected'
   -- Asked to indicate 'Stop tone' condition on channel Skinny/2610@SEP0014A9239820-2
   -- Asked to indicate 'Media Source Update' condition on channel Skinny/2610@SEP0014A9239820-2
   -- Asked to indicate 'Media Source Update' condition on channel Skinny/2611@SEP001121D89A42-3
skinny_get_rtp_peer() Channel = Skinny/2610@SEP0014A9239820-2
skinny_get_rtp_peer() Using AST_RTP_GLUE_RESULT_LOCAL
skinny_get_rtp_peer() Channel = Skinny/2611@SEP001121D89A42-3
skinny_get_rtp_peer() Using AST_RTP_GLUE_RESULT_LOCAL
   -- Locally bridging Skinny/2610@SEP0014A9239820-2 and Skinny/2611@SEP001121D89A42-3
RECEIVED UNKNOWN MESSAGE TYPE:  49
Received Open Receive Channel Ack
device ipaddr = 192.168.50.106:32542
asterisk ipaddr = 192.168.50.1:16818
Setting payloadType to 'ulaw' (20 ms)

*CLI>
*CLI>
*CLI>
*CLI>
################# 2610 completes transfer
*CLI>
*CLI>  Received Softkey Event: Transfer(1/2)
   -- Stopped music on hold on SIP/2609-00000000
   -- Asked to indicate 'Stop tone' condition on channel Skinny/2610@SEP0014A9239820-1
[2011-03-21 10:51:31] NOTICE[9026]: chan_skinny.c:4195 skinny_fixup: skinny_fixup(Skinny/2611@SEP001121D89A42-3, Skinny/2611@SEP001121D89A42-3<MAS                                                  >)
   -- Hanging up SEP0014A9239820/1
      > Killing inactive sub 1
Segmentation fault (core dumped)
By: Mark Murawski (kobaz) 2011-03-21 09:56:15

If you want access to the box that exhibits the problem, I can set that up.
By: Mark Murawski (kobaz) 2011-03-21 09:58:26

Crashed thread

#0  0x081e0c2d in ?? ()
#1  0x080bcfa9 in ast_waitfor_nandfds (c=0xb27f9ee0, n=2, fds=0x0, nfds=0, exception=0x0, outfd=0x0, ms=0xb27f9efc) at channel.c:3224
#2  0x080c5381 in ast_waitfor_n (c0=0xb2ae1250, c1=0xb2ae8f68, config=0xb27facc0, fo=0xb27fa21c, rc=0xb27fa218) at channel.c:3543
#3  ast_generic_bridge (c0=0xb2ae1250, c1=0xb2ae8f68, config=0xb27facc0, fo=0xb27fa21c, rc=0xb27fa218) at channel.c:7035
#4  ast_channel_bridge (c0=0xb2ae1250, c1=0xb2ae8f68, config=0xb27facc0, fo=0xb27fa21c, rc=0xb27fa218) at channel.c:7483
ASTERISK-1  0x080f8229 in ast_bridge_call (chan=0xb2ae1250, peer=0xb2ae8f68, config=0xb27facc0) at features.c:3564
ASTERISK-2  0xb68c4ae1 in dial_exec_full (chan=<value optimized out>, data=<value optimized out>, peerflags=0xb27fade8, continue_exec=0x0) at app_dial.c:2682
ASTERISK-3  0xb68c66ad in dial_exec (chan=0xb2ae1250, data=0xb27fcea8 "Skinny/2610") at app_dial.c:2782
ASTERISK-4  0x08147f1b in pbx_exec (c=0xb2ae1250, app=0xb609480, data=0xb27fcea8 "Skinny/2610") at pbx.c:1407
ASTERISK-5  0x08156810 in pbx_extension_helper (c=<value optimized out>, con=<value optimized out>, context=<value optimized out>, exten=0xb2ae160c "2610", priority=1, label=0x0,
   callerid=0xb287ce70 "2609", action=E_SPAWN, found=0xb27ff2ec, combined_find_spawn=1) at pbx.c:4086
ASTERISK-6 0x0815a785 in ast_spawn_extension (c=0xb2ae1250, args=<value optimized out>) at pbx.c:4605
ASTERISK-7 __ast_pbx_run (c=0xb2ae1250, args=<value optimized out>) at pbx.c:4703
ASTERISK-8 0x0815c07e in pbx_thread (data=0xb2ae1250) at pbx.c:5021
ASTERISK-9 0x0819ccad in dummy_start (data=0xb2ae3708) at utils.c:971
ASTERISK-10 0xb72db955 in start_thread () from /lib/i686/cmov/libpthread.so.0
ASTERISK-11 0xb74e7e7e in clone () from /lib/i686/cmov/libc.so.6
By: Damien Wedhorn (wedhorn) 2013-03-08 02:01:19.416-0600

I can't see this type of issue with recent versions of skinny, so I'll suspend this issue.