Summary:	ASTERISK-07766: activating applicatoion feature cause 100% system load
Reporter:	Martin Vit (festr)	Labels:
Date Opened:	2006-09-18 13:46:49	Date Closed:	2006-09-27 11:59:34
Priority:	Blocker	Regression?	No
Status:	Closed/Complete	Components:	Resources/res_features
Versions:		Frequency of Occurrence
Related Issues:
Environment:		Attachments:
Description:	asterisk: 1.2-r43072M call SIP A -> SIP B. B press # and loop stop until hangup. features.conf testfeature => ASTERISK-5,callee,Playback,vm-intro ****** ADDITIONAL INFORMATION ****** debug: Sep 18 20:07:50 DEBUG[11592]: rtp.c:193 send_dtmf: Sending dtmf: 42 (*), at x.x.x.x Sep 18 20:07:50 DEBUG[11592]: channel.c:3405 ast_generic_bridge: Got DTMF on channel (SIP/festrntb-08162b78) Sep 18 20:07:50 DEBUG[11592]: channel.c:3661 ast_channel_bridge: Bridge stops bridging channels IAX2/festr-3 and SIP/festrntb-08162b78 Sep 18 20:07:50 DEBUG[11592]: res_features.c:999 ast_feature_interpret: Feature interpret: chan=IAX2/festr-3, peer=SIP/festrntb-08162b78, sense=2, features=2 Sep 18 20:07:50 DEBUG[11592]: res_features.c:1479 ast_bridge_call: Set time limit to 500 Sep 18 20:07:51 DEBUG[11592]: rtp.c:1267 ast_rtp_raw_write: Difference is 952, ms is 139 Sep 18 20:07:51 DEBUG[11592]: channel.c:3361 ast_generic_bridge: Nobody there, continuing... from this point loop start at: (attached gdb on running thread) 0xb7e6a871 in gettimeofday () from /lib/tls/libc.so.6 (gdb) bt #0  0xb7e6a871 in gettimeofday () from /lib/tls/libc.so.6 #1  0x08068c05 in ast_channel_bridge (c0=0x814e558, c1=0x817e8a0, config=0xb604cf60, fo=0xb604c418, rc=0xb604c41c) at time.h:99 #2  0xb7b49f86 in ast_bridge_call (chan=0x814e558, peer=0x817e8a0, config=0xb604cf60) at res_features.c:1330 #3  0xb61f6fe4 in dial_exec_full (chan=0x814e558, data=0x50, peerflags=0xb604d608) at app_dial.c:1607 #4  0xb61f994d in dial_exec (chan=0x0, data=0x1) at app_dial.c:1649 ASTERISK-1  0x08091f9d in pbx_extension_helper (c=0x814e558, con=0xb60580b0, context=0x814e6a8 "macro-dial_ext", exten=0x814e79c "ss", priority=11, label=0x0,    callerid=0xb60517d0 "SIP/festr|60|jtT", action=136603224) at pbx.c:553 ASTERISK-2  0x0809254c in ast_spawn_extension (c=0x0, context=0x1 <Address 0x1 out of bounds>, exten=0x1 <Address 0x1 out of bounds>, priority=1,    callerid=0x1 <Address 0x1 out of bounds>) at pbx.c:2230 ASTERISK-3  0xb63b58dc in macro_exec (chan=0x814e558, data=0x814e558) at app_macro.c:215 ASTERISK-4  0x08091f9d in pbx_extension_helper (c=0x814e558, con=0x0, context=0x814e6a8 "macro-dial_ext", exten=0x814e79c "ss", priority=1, label=0x0,    callerid=0xb60580b0 "dial_ext|60|jtT|Vit|exten|91|116|SIP/festr|0", action=0) at pbx.c:553 ASTERISK-5  0x08093266 in __ast_pbx_run (c=0x814e558) at pbx.c:2230 ASTERISK-6 0x08094dcc in pbx_thread (data=0x0) at pbx.c:2517 ASTERISK-7 0xb7fd0ccd in start_thread () from /lib/tls/libpthread.so.0 ASTERISK-8 0xb7eb9b0e in clone () from /lib/tls/libc.so.6 strace on this thread shows fast gettimeofday calls: ---cut--- gettimeofday({1158585691, 93397}, NULL) = 0 gettimeofday({1158585691, 93528}, NULL) = 0 gettimeofday({1158585691, 93675}, NULL) = 0 gettimeofday({1158585691, 93789}, NULL) = 0 gettimeofday({1158585691, 93848}, NULL) = 0 gettimeofday({1158585691, 93919}, NULL) = 0 ---cut---
Comments:	By: Martin Vit (festr) 2006-09-18 13:51:47 one more thing, the loop is at this line channel.c:3504 -  for (/* ever */;;) {... By: Serge Vecher (serge-v) 2006-09-18 14:35:33 what modifications have you done to the source? By: Martin Vit (festr) 2006-09-18 14:39:49 no modifications,  only some breakpoints in channel.c with DEBUG printing to figer out where the loop was By: Serge Vecher (serge-v) 2006-09-19 09:07:23 what's the output of 'ps ax' when this happens? By: Martin Vit (festr) 2006-09-19 09:44:49 output is the same as before this happens ps ax: -- cut -- 11362 ?        S<     0:00 /bin/sh /usr/sbin/safe_asterisk 11368 ?        S<l    5:42 /usr/sbin/asterisk -vvvg -c 11379 ?        S<     0:10 mpg123 -q -s --mono -r 8000 -b 2048 -f 8192 fpm-calm-river.mp3 le_wax_the_end.mp3 the_funky_lowlives.mp3 Flywheel.mp3 cloudy_this_morning.mp3 bana 11410 ?        S<     0:00 mpg123 -q -s --mono -r 8000 -b 2048 -f 8192 fpm-calm-river.mp3 le_wax_the_end.mp3 the_funky_lowlives.mp3 Flywheel.mp3 cloudy_this_morning.mp3 bana 21359 pts/4    S+     0:00 rasterisk r --- cut --- i've to cut some processes from output because of some public ip adresses By: Serge Vecher (serge-v) 2006-09-19 10:02:02 I bet it's is the mpg123 that causes the 100% cpu utilization, the question is why  is it related to ## dtmf ... By: Martin Vit (festr) 2006-09-19 11:14:03 i've stopped mpg123 (uncomment it in /etc/asterisk/musiconhold.conf and for sure ps ax if there is no mpg123) but the problem is the same. It is releted to any dtmf (tested * or number etc). If i do not set DYNAMIC_FEATURE for the channel, the problem does not occur. By: Russell Bryant (russell) 2006-09-27 11:59:34 This has been fixed in the 1.2 branch, 1.4 branch, and the trunk in revisions 43778, 43779, and 43780. If you exeperience any further problems, please file a new report and please make sure that I see it. Thanks!