[Home]

Summary:ASTERISK-13922: [patch] Regular segfault with chan_unistim
Reporter:Barry Flanagan (barryf)Labels:
Date Opened:2009-04-08 07:44:44Date Closed:2009-05-07 12:15:42
Priority:CriticalRegression?No
Status:Closed/CompleteComponents:Channels/chan_unistim
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) 20090421__bug14858.diff.txt
( 1) 20090507__bug14858.diff.txt
( 2) gdb.output
( 3) unistim.log
Description:Running Asterisk 1.6.0.8 on Ubuntu 8.10 Server. This same crash also happens on 1.2.26 and 1.4.2x with the chan_unistim drivers. We have approx. 40 unistim handsets, in a callcenter environment. At least once a day, Asterisk segfaults with the same gdb output.

It appears to happen during attended transfers, using the res_features atxfer.

gdb output below.

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

#0  0xb7c629f0 in pthread_mutex_lock () from /lib/tls/i686/cmov/libpthread.so.0                                                                            
(gdb) bt full                                                                                                                                              
#0  0xb7c629f0 in pthread_mutex_lock () from /lib/tls/i686/cmov/libpthread.so.0                                                                            
No symbol table info available.                                                                                                                            
#1  0xb7d67d86 in pthread_mutex_lock () from /lib/tls/i686/cmov/libc.so.6                                                                                  
No symbol table info available.                                                                                                                            
#2  0x0808e00c in ast_mutex_lock (pmutex=0x80) at /usr/src/asterisk-1.6/asterisk-1.6.0.9/include/asterisk/lock.h:770                                        
No locals.                                                                                                                                                  
#3  0x0808f698 in __ast_queue_frame (chan=0x0, fin=0xb6a85f24, head=0) at channel.c:972                                                                    
       f = (struct ast_frame *) 0xb508b3d8                                                                                                                
       cur = (struct ast_frame *) 0x0                                                                                                                      
       blah = 1                                                                                                                                            
       qlen = 0                                                                                                                                            
       __PRETTY_FUNCTION__ = "__ast_queue_frame"                                                                                                          
#4  0x0808f9ce in ast_queue_frame (chan=0x0, fin=0xb6a85f24) at channel.c:1025                                                                              
No locals.                                                                                                                                                  
ASTERISK-1  0xb6a91614 in unistim_do_senddigit (pte=0xb700b900, digit=48 '0') at chan_unistim.c:2534                                                                
       f = {frametype = AST_FRAME_DTMF_END, subclass = 48, datalen = 0, samples = 0, mallocd = 0, mallocd_hdr_len = 0, offset = 0,                        
 src = 0xb6a9eff8 "unistim", data = 0x0, delivery = {tv_sec = 0, tv_usec = 0}, frame_list = {next = 0x0}, flags = 0, ts = 0, len = 0, seqno = 0}          
       sub = (struct unistim_subchannel *) 0xb6fa4dc0                                                                                                      
       __PRETTY_FUNCTION__ = "unistim_do_senddigit"                                                                                                        
ASTERISK-2  0xb6a9167e in key_call (pte=0xb700b900, keycode=48 '0') at chan_unistim.c:2547                                                                          
       __PRETTY_FUNCTION__ = "key_call"                                                                                                                    
ASTERISK-3  0xb6a94709 in process_request (size=14, buf=0xb6fd7dd8 "", pte=0xb700b900) at chan_unistim.c:3397                                                      
       keycode = 64 '@'                                                                                                                                    
       tmpbuf = "10.?\037??`??\001\000\000\000\030`??;\035?`???l??k\220?\001\000\000\000?`???\217?k\220??`??\n\000\000\000P\000\000\000<\000\000\000#", '\0' <repeats 34 times>, "PX\035WT\224?\001@\000\000\000\000\000\000\000\000?`???/???`????\v\000\000\000@\235??\v\000\000\000?`??\000\000\000\000%_??/??\v\000\000\000(?\000??b???}??\036x\024\b\000\000\000\000?b??\020\000\000\000?`??\001\000\000\000?`??\030\000\000\000\000\000\000\000?}??\006\000\000\000?"...        
       __PRETTY_FUNCTION__ = "process_request"                                                                                                            
ASTERISK-4  0xb6a95479 in parsing (size=14, buf=0xb6fd7dd8 "", pte=0xb700b900, addr_from=0xb6a862ac) at chan_unistim.c:3572                                        
       sbuf = (short unsigned int *) 0xb6fd7dd8                                                                                                            
       seq = 1195                                                                                                                                          
       tmpbuf = "10.80.60.35", '\0' <repeats 76 times>, "8b???/??8b????\220}\002?@\235??\v\000\000\000?a??\000\000\000\000\bb??(b??\000\000\000\000\220}\002?\200}\002?t\177\002?\000\000\000\000\000\000\000\000\200}\002??)?\bb??\001\000\000\000\000\000\000\000\001", '\0' <repeats 11 times>, "?\037?,@?\200}\002??y\000\000\000\000\000\000\001\000\000\000?/??8b???\037?\v\000\000\000\001\000\000\000Hb???}?2???/??Xb??c\237??"
---Type <return> to continue, or q <return> to quit---
       __PRETTY_FUNCTION__ = "parsing"
ASTERISK-5  0xb6a968af in unistimsock_read (id=0xb6fa0ad0, fd=11, events=1, ignore=0x0) at chan_unistim.c:3894
       addr_from = {sin_family = 2, sin_port = 34835, sin_addr = {s_addr = 591155210}, sin_zero = "\000\000\000\000\000\000\000"}
       cur = (struct unistimsession *) 0xb700b900
       found = 1
       tmp = 31
       dw_num_bytes_rcvd = 14
       __PRETTY_FUNCTION__ = "unistimsock_read"
ASTERISK-6 0x080d7b43 in ast_io_wait (ioc=0xb6fd8de0, howlong=1000) at io.c:288
       res = 1
       x = 0
       origcnt = 1
ASTERISK-7 0xb6a98c96 in do_monitor (data=0x0) at chan_unistim.c:4562
       cur = (struct unistimsession *) 0x0
       dw_timeout = 31069
       tick = 2240212150
       res = 1000
       reloading = 0
ASTERISK-8 0x081480d9 in dummy_start (data=0x8726f08) at utils.c:861
       __cancel_buf = {__cancel_jmp_buf = {{__cancel_jmp_buf = {-1211691020, 0, 0, -1230478392, 1864810679, 383865802}, __mask_was_saved = 0}}, __pad = {
   0xb6a86490, 0x0, 0x0, 0x0}}
       __cancel_routine = (void (*)(void *)) 0x807539e <ast_unregister_thread>
       __cancel_arg = (void *) 0xb6a86b90
       not_first_call = 0
       ret = (void *) 0x0
       a = {start_routine = 0xb6a98a60 <do_monitor>, data = 0x0,
 name = 0x875dcc8 "do_monitor", ' ' <repeats 11 times>, "started at [ 4601] chan_unistim.c restart_monitor()"}
ASTERISK-9 0xb7c6150f in start_thread () from /lib/tls/i686/cmov/libpthread.so.0
No symbol table info available.
ASTERISK-10 0xb7d59a0e in clone () from /lib/tls/i686/cmov/libc.so.6
No symbol table info available.
Comments:By: Barry Flanagan (barryf) 2009-04-08 09:10:32

Here is the Asterisk log from the time of the crash, with unistim debugging turned on:

[Apr  8 13:56:51] VERBOSE[30803] logger.c: Request received
[Apr  8 13:56:51] VERBOSE[30803] logger.c: Key pressed : keycode = 0x43 - current state : 6
[Apr  8 13:56:51] VERBOSE[30803] logger.c: Send Digit 3
[Apr  8 13:56:51] VERBOSE[30803] logger.c: Sending Stream Based Tone Frequency Component List Download 697 1477
[Apr  8 13:56:51] VERBOSE[30803] logger.c: Sending Stream Based Tone On
[Apr  8 13:56:51] VERBOSE[1747] logger.c:     -- Executing [s@macro-custom-agentlogin:24]  [1;36;40mSet [0;37;40m(" [1;35;40mUSTM/3503@3503-0 [0;37;40m", " [1;35;40mGLOBAL(AGENTBYCALLERID_3503)=3503 [0;37;40m") in new stack
[Apr  8 13:56:51] VERBOSE[1747] logger.c:   == Setting global variable 'AGENTBYCALLERID_3503' to '3503'
[Apr  8 13:56:51] VERBOSE[1747] logger.c:     -- Executing [s@macro-custom-agentlogin:25]  [1;36;40mQueueLog [0;37;40m(" [1;35;40mUSTM/3503@3503-0 [0;37;40m", " [1;35;40mNONE,NONE,Agent/3503,AGENTCALLBACKLOGIN,3503@from-internal [0;37;40m") in new stack
[Apr  8 13:56:51] VERBOSE[1747] logger.c:     -- Executing [s@macro-custom-agentlogin:26]  [1;36;40mExecIf [0;37;40m(" [1;35;40mUSTM/3503@3503-0 [0;37;40m", " [1;35;40m1?SendText(@4@37@Lgoff 3503@121) [0;37;40m") in new stack
[Apr  8 13:56:51] VERBOSE[1747] logger.c: unistim_sendtext called
[Apr  8 13:56:51] VERBOSE[1747] logger.c: Sending favorite pos 4 with status 0x25
[Apr  8 13:56:51] VERBOSE[1747] logger.c:     -- Executing [s@macro-custom-agentlogin:27]  [1;36;40mExecIf [0;37;40m(" [1;35;40mUSTM/3503@3503-0 [0;37;40m", " [1;35;40m1?SendText(Agent 3503 Logged in) [0;37;40m") in new stack
[Apr  8 13:56:51] VERBOSE[1747] logger.c: unistim_sendtext called
[Apr  8 13:56:51] VERBOSE[1747] logger.c: Sending text at pos 0, inverse flag 5
[Apr  8 13:56:51] VERBOSE[1747] logger.c: Sending text at pos 32, inverse flag 5
[Apr  8 13:56:51] VERBOSE[1747] logger.c: Sending text at pos 64, inverse flag 5
[Apr  8 13:56:51] VERBOSE[1747] logger.c:     -- Executing [s@macro-custom-agentlogin:28]  [1;36;40mSet [0;37;40m(" [1;35;40mUSTM/3503@3503-0 [0;37;40m", " [1;35;40m__AGENTID=3503 [0;37;40m") in new stack
[Apr  8 13:56:51] VERBOSE[1747] logger.c:     -- Executing [s@macro-custom-agentlogin:29]  [1;36;40mGotoIf [0;37;40m(" [1;35;40mUSTM/3503@3503-0 [0;37;40m", " [1;35;40m0?start [0;37;40m") in new stack
[Apr  8 13:56:51] VERBOSE[1747] logger.c:     -- Executing [120@from-internal-callcentre-imbiz:3]  [1;36;40mHangup [0;37;40m(" [1;35;40mUSTM/3503@3503-0 [0;37;40m", " [1;35;40m [0;37;40m") in new stack
[Apr  8 13:56:51] VERBOSE[1747] logger.c:   == Spawn extension (from-internal-callcentre-imbiz, 120, 3) exited non-zero on 'USTM/3503@3503-0'
[Apr  8 13:56:51] VERBOSE[1747] logger.c:     -- Executing [h@from-internal-callcentre-imbiz:1]  [1;36;40mMacro [0;37;40m(" [1;35;40mUSTM/3503@3503-0 [0;37;40m", " [1;35;40mhangupcall [0;37;40m") in new stack
[Apr  8 13:56:51] VERBOSE[1747] logger.c:     -- Executing [s@macro-hangupcall:1]  [1;36;40mResetCDR [0;37;40m(" [1;35;40mUSTM/3503@3503-0 [0;37;40m", " [1;35;40mvw [0;37;40m") in new stack
[Apr  8 13:56:51] VERBOSE[1747] logger.c:     -- Executing [s@macro-hangupcall:2]  [1;36;40mNoCDR [0;37;40m(" [1;35;40mUSTM/3503@3503-0 [0;37;40m", " [1;35;40m [0;37;40m") in new stack
[Apr  8 13:56:51] VERBOSE[1747] logger.c:     -- Executing [s@macro-hangupcall:3]  [1;36;40mGotoIf [0;37;40m(" [1;35;40mUSTM/3503@3503-0 [0;37;40m", " [1;35;40m1?skiprg [0;37;40m") in new stack
[Apr  8 13:56:51] VERBOSE[1747] logger.c:     -- Goto (macro-hangupcall,s,6)
[Apr  8 13:56:51] VERBOSE[1747] logger.c:     -- Executing [s@macro-hangupcall:6]  [1;36;40mGotoIf [0;37;40m(" [1;35;40mUSTM/3503@3503-0 [0;37;40m", " [1;35;40m1?skipblkvm [0;37;40m") in new stack
[Apr  8 13:56:51] VERBOSE[1747] logger.c:     -- Goto (macro-hangupcall,s,9)
[Apr  8 13:56:51] VERBOSE[1747] logger.c:     -- Executing [s@macro-hangupcall:9]  [1;36;40mGotoIf [0;37;40m(" [1;35;40mUSTM/3503@3503-0 [0;37;40m", " [1;35;40m1?theend [0;37;40m") in new stack
[Apr  8 13:56:51] VERBOSE[1747] logger.c:     -- Goto (macro-hangupcall,s,11)
[Apr  8 13:56:51] VERBOSE[1747] logger.c:     -- Executing [s@macro-hangupcall:11]  [1;36;40mHangup [0;37;40m(" [1;35;40mUSTM/3503@3503-0 [0;37;40m", " [1;35;40m [0;37;40m") in new stack
[Apr  8 13:56:51] VERBOSE[1747] logger.c:   == Spawn extension (macro-hangupcall, s, 11) exited non-zero on 'USTM/3503@3503-0' in macro 'hangupcall'
[Apr  8 13:56:51] VERBOSE[1747] logger.c:   == Spawn extension (from-internal-callcentre-imbiz, h, 1) exited non-zero on 'USTM/3503@3503-0'
[Apr  8 13:56:51] VERBOSE[1747] logger.c: unistim_hangup(USTM/3503@3503-0) on 3503@3503
[Apr  8 13:56:51] VERBOSE[1747] logger.c: Sending no ring packet
[Apr  8 13:56:51] VERBOSE[1747] logger.c: Sending end call
[Apr  8 13:56:51] VERBOSE[1747] logger.c: Destroying RTP session
[Apr  8 13:56:51] VERBOSE[1747] logger.c: Sending stop timer
[Apr  8 13:56:51] VERBOSE[1747] logger.c: USTM(3503@3503-0) channel already destroyed
[Apr  8 13:56:51] VERBOSE[1747] logger.c: Sending Stream Based Tone Off
[Apr  8 13:56:51] VERBOSE[1747] logger.c: Sending select output packet output=c0 volume=1 mute=ce
[Apr  8 13:56:51] VERBOSE[1747] logger.c: Sending favorite pos 0 with status 0x24
[Apr  8 13:56:51] VERBOSE[1747] logger.c: Sending led_update (8)
[Apr  8 13:56:51] VERBOSE[1747] logger.c: Sending led_update (10)
[Apr  8 13:56:51] VERBOSE[1747] logger.c: Sending favorite pos 0 with status 0x20
[Apr  8 13:56:51] VERBOSE[1747] logger.c: Sending status text
[Apr  8 13:56:51] VERBOSE[1747] logger.c: Sending text at pos 32, inverse flag 5
[Apr  8 13:56:51] VERBOSE[1747] logger.c: Sending text at pos 0, inverse flag 5
[Apr  8 13:56:51] VERBOSE[1747] logger.c: Sending text at pos 64, inverse flag 5
[Apr  8 13:56:51] VERBOSE[1747] logger.c: Sending title text
[Apr  8 13:56:51] VERBOSE[1747] logger.c: Sending favorite pos 0 with status 0x20
[Apr  8 13:56:51] VERBOSE[30803] logger.c: Sending Stream Based Tone Off
By: Barry Flanagan (barryf) 2009-04-21 04:08:31

Bump.

Does anyone know where I should be looking for a cause for this consistent crash?

It appears that a null channel is being returned for some reason (chan=0x0):

#3 0x0808f698 in __ast_queue_frame (chan=0x0, fin=0xb6a85f24, head=0) at channel.c:972

What could cause this? chan_unistim always seems to be involved when the crasdh occurs, but it looks like the error is in Asterisk core...

Any help much appreciated.

-Barry
By: Tilghman Lesher (tilghman) 2009-04-21 12:30:35

chan_unistim is extremely unsupported, mainly because the protocol was built on reverse-engineering and has no documentation.  We may have accepted it into the codebase, but it is unlikely to ever be fully functional.
By: Tilghman Lesher (tilghman) 2009-04-21 12:36:27

This patch may or may not help, but as stated before, this channel driver is unsupported.  If it works, I'll commit it; if not, there's not much we can do.
By: Barry Flanagan (barryf) 2009-04-22 03:34:32

Thanks, I will test today and let you know how it goes.
By: Barry Flanagan (barryf) 2009-04-22 05:27:00

Unfortunately, rather than a crash, this time the log filled (up to 2Gb limit) with:

ERROR[30968] channel.c: ast_read() called with no recorded file descriptor.

See the attached unistim.log file.

-Barry
By: Tilghman Lesher (tilghman) 2009-04-22 10:41:06

That problem is another issue already in progress.  Please see ASTERISK-13565.
By: Digium Subversion (svnbot) 2009-04-22 11:01:31

Repository: asterisk
Revision: 189911

U   trunk/channels/chan_unistim.c

------------------------------------------------------------------------
r189911 | tilghman | 2009-04-22 11:01:30 -0500 (Wed, 22 Apr 2009) | 7 lines

Do not continue to receive DTMF, when the channel is hungup and about to be destroyed.
(closes issue ASTERISK-13922)
Reported by: barryf
Patches:
      20090421__bug14858.diff.txt uploaded by tilghman (license 14)
Tested by: barryf

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

http://svn.digium.com/view/asterisk?view=rev&revision=189911
By: Digium Subversion (svnbot) 2009-04-22 11:02:30

Repository: asterisk
Revision: 189912

_U  branches/1.6.0/
U   branches/1.6.0/channels/chan_unistim.c

------------------------------------------------------------------------
r189912 | tilghman | 2009-04-22 11:02:29 -0500 (Wed, 22 Apr 2009) | 14 lines

Merged revisions 189911 via svnmerge from
https://origsvn.digium.com/svn/asterisk/trunk

........
 r189911 | tilghman | 2009-04-22 11:01:30 -0500 (Wed, 22 Apr 2009) | 7 lines
 
 Do not continue to receive DTMF, when the channel is hungup and about to be destroyed.
 (closes issue ASTERISK-13922)
  Reported by: barryf
  Patches:
        20090421__bug14858.diff.txt uploaded by tilghman (license 14)
  Tested by: barryf
........

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

http://svn.digium.com/view/asterisk?view=rev&revision=189912
By: Digium Subversion (svnbot) 2009-04-22 11:03:08

Repository: asterisk
Revision: 189913

_U  branches/1.6.1/
U   branches/1.6.1/channels/chan_unistim.c

------------------------------------------------------------------------
r189913 | tilghman | 2009-04-22 11:03:08 -0500 (Wed, 22 Apr 2009) | 14 lines

Merged revisions 189911 via svnmerge from
https://origsvn.digium.com/svn/asterisk/trunk

........
 r189911 | tilghman | 2009-04-22 11:01:30 -0500 (Wed, 22 Apr 2009) | 7 lines
 
 Do not continue to receive DTMF, when the channel is hungup and about to be destroyed.
 (closes issue ASTERISK-13922)
  Reported by: barryf
  Patches:
        20090421__bug14858.diff.txt uploaded by tilghman (license 14)
  Tested by: barryf
........

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

http://svn.digium.com/view/asterisk?view=rev&revision=189913
By: Digium Subversion (svnbot) 2009-04-22 11:04:09

Repository: asterisk
Revision: 189914

_U  branches/1.6.2/
U   branches/1.6.2/channels/chan_unistim.c

------------------------------------------------------------------------
r189914 | tilghman | 2009-04-22 11:04:08 -0500 (Wed, 22 Apr 2009) | 14 lines

Merged revisions 189911 via svnmerge from
https://origsvn.digium.com/svn/asterisk/trunk

........
 r189911 | tilghman | 2009-04-22 11:01:30 -0500 (Wed, 22 Apr 2009) | 7 lines
 
 Do not continue to receive DTMF, when the channel is hungup and about to be destroyed.
 (closes issue ASTERISK-13922)
  Reported by: barryf
  Patches:
        20090421__bug14858.diff.txt uploaded by tilghman (license 14)
  Tested by: barryf
........

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

http://svn.digium.com/view/asterisk?view=rev&revision=189914
By: Barry Flanagan (barryf) 2009-05-07 05:01:31

I am still having the crash with chan_unistim on the 1.6-svn code. Happens much more rarely but still happening.

Attached gdb.output
By: Tilghman Lesher (tilghman) 2009-05-07 12:12:34

In the future, when we've committed a fix in an issue, please open a new issue instead of reopening an old one.  New patch uploaded.
By: Digium Subversion (svnbot) 2009-05-07 12:13:37

Repository: asterisk
Revision: 192938

U   trunk/channels/chan_unistim.c

------------------------------------------------------------------------
r192938 | tilghman | 2009-05-07 12:13:37 -0500 (Thu, 07 May 2009) | 6 lines

Send DTMF frame before playing back audio.
(closes issue ASTERISK-13922)
Reported by: barryf
Patches:
      20090507__bug14858.diff.txt uploaded by tilghman (license 14)

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

http://svn.digium.com/view/asterisk?view=rev&revision=192938
By: Digium Subversion (svnbot) 2009-05-07 12:14:26

Repository: asterisk
Revision: 192939

_U  branches/1.6.0/
U   branches/1.6.0/channels/chan_unistim.c

------------------------------------------------------------------------
r192939 | tilghman | 2009-05-07 12:14:26 -0500 (Thu, 07 May 2009) | 13 lines

Merged revisions 192938 via svnmerge from
https://origsvn.digium.com/svn/asterisk/trunk

........
 r192938 | tilghman | 2009-05-07 12:13:36 -0500 (Thu, 07 May 2009) | 6 lines
 
 Send DTMF frame before playing back audio.
 (closes issue ASTERISK-13922)
  Reported by: barryf
  Patches:
        20090507__bug14858.diff.txt uploaded by tilghman (license 14)
........

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

http://svn.digium.com/view/asterisk?view=rev&revision=192939
By: Digium Subversion (svnbot) 2009-05-07 12:15:01

Repository: asterisk
Revision: 192941

_U  branches/1.6.1/
U   branches/1.6.1/channels/chan_unistim.c

------------------------------------------------------------------------
r192941 | tilghman | 2009-05-07 12:15:01 -0500 (Thu, 07 May 2009) | 13 lines

Merged revisions 192938 via svnmerge from
https://origsvn.digium.com/svn/asterisk/trunk

........
 r192938 | tilghman | 2009-05-07 12:13:36 -0500 (Thu, 07 May 2009) | 6 lines
 
 Send DTMF frame before playing back audio.
 (closes issue ASTERISK-13922)
  Reported by: barryf
  Patches:
        20090507__bug14858.diff.txt uploaded by tilghman (license 14)
........

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

http://svn.digium.com/view/asterisk?view=rev&revision=192941
By: Digium Subversion (svnbot) 2009-05-07 12:15:41

Repository: asterisk
Revision: 192942

_U  branches/1.6.2/
U   branches/1.6.2/channels/chan_unistim.c

------------------------------------------------------------------------
r192942 | tilghman | 2009-05-07 12:15:41 -0500 (Thu, 07 May 2009) | 13 lines

Merged revisions 192938 via svnmerge from
https://origsvn.digium.com/svn/asterisk/trunk

........
 r192938 | tilghman | 2009-05-07 12:13:36 -0500 (Thu, 07 May 2009) | 6 lines
 
 Send DTMF frame before playing back audio.
 (closes issue ASTERISK-13922)
  Reported by: barryf
  Patches:
        20090507__bug14858.diff.txt uploaded by tilghman (license 14)
........

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

http://svn.digium.com/view/asterisk?view=rev&revision=192942