| Summary: | ASTERISK-13288: Asterisk revision 166901 segfault during park using Aastra SPRE function to park extension | ||
| Reporter: | David Brillert (aragon) | Labels: | |
| Date Opened: | 2008-12-31 16:32:22.000-0600 | Date Closed: | 2009-01-17 20:00:48.000-0600 |
| Priority: | Critical | Regression? | No |
| Status: | Closed/Complete | Components: | Features/Parking |
| Versions: | Frequency of Occurrence | ||
| Related Issues: | |||
| Environment: | Attachments: | ( 0) 14157.experiment ( 1) aastra_spre_segfault.pcap ( 2) jan12spresegfault.txt | |
| Description: | features.conf parkext=700 Aastra programmable key configured as spre:700 Aastra phone answers incoming call from another SIP extension. Aastra user presses PFK to send caller to park orbit. Aastra phone automatically grabs line 2 key puts line 1 on hold and plays back park extension 701 on line 2. Asterisk segfaults Line 1 remains on hold and blinking on Aastra phone for a short time. Asterisk segfaults ****** ADDITIONAL INFORMATION ****** Extension 229 dials 225 and 225 is Aastra 480i which issues spre code. As soon as spre 700 is complete Asterisk CLI gets busy... == Parked SIP/225-b7c09340 on 701@parkedcalls. Will timeout back to extension [commzilla-super] s, 1 in 45 seconds -- Added extension '701' priority 1 to parkedcalls -- <SIP/225-b7c09340> Playing 'digits/7' (language 'en') Extension Changed 701[commzilla-local] new state InUse for Notify User 225 Extension Changed 701[commzilla-local] new state InUse for Notify User 230 Extension Changed 701[commzilla-local] new state InUse for Notify User 233 -- <SIP/225-b7c09340> Playing 'digits/0' (language 'en') -- <SIP/225-b7c09340> Playing 'digits/1' (language 'en') -- Started music on hold, class 'default', on SIP/225-b7c09340 == Spawn extension (commzilla-super, s, 1) exited non-zero on 'SIP/225-b7c09340' -- Stopped music on hold on SIP/225-b7c09340 == SIP/225-b7c09340 got tired of being parked [Dec 31 17:17:29] NOTICE[16809]: cdr.c:431 check_post: CDR on channel 'SIP/225-b7c09340' already posted [Dec 31 17:17:29] NOTICE[16809]: cdr.c:431 check_post: CDR on channel 'SIP/225-b7c09340' already posted [Dec 31 17:17:29] ERROR[16809]: channel.c:1229 ast_channel_free: Unable to find channel in list to free. Assuming it has already been done. [Dec 31 17:17:29] ERROR[16809]: /dar/build/asterisk-1.4.23/include/asterisk/lock.h:428 __ast_pthread_mutex_lock: channel.c line 1233 (ast_channel_free): Error obtaining mutex: Invalid argument [Dec 31 17:17:29] ERROR[16809]: /dar/build/asterisk-1.4.23/include/asterisk/lock.h:511 __ast_pthread_mutex_unlock: channel.c line 1234 (ast_channel_free): mutex '&chan->lock' freed more times than we've locked! [Dec 31 17:17:29] ERROR[16809]: /dar/build/asterisk-1.4.23/include/asterisk/lock.h:528 __ast_pthread_mutex_unlock: channel.c line 1234 (ast_channel_free): Error releasing mutex: Invalid argument [Dec 31 17:17:29] ERROR[16809]: /dar/build/asterisk-1.4.23/include/asterisk/lock.h:428 __ast_pthread_mutex_lock: channel.c line 1243 (ast_channel_free): Error obtaining mutex: Invalid argument [Dec 31 17:17:29] ERROR[16809]: /dar/build/asterisk-1.4.23/include/asterisk/lock.h:511 __ast_pthread_mutex_unlock: channel.c line 1244 (ast_channel_free): mutex '&chan->lock' freed more times than we've locked! [Dec 31 17:17:29] ERROR[16809]: /dar/build/asterisk-1.4.23/include/asterisk/lock.h:528 __ast_pthread_mutex_unlock: channel.c line 1244 (ast_channel_free): Error releasing mutex: Invalid argument [Dec 31 17:17:29] ERROR[16809]: /dar/build/asterisk-1.4.23/include/asterisk/lock.h:316 __ast_pthread_mutex_destroy: channel.c line 1301 (ast_channel_free): Error: attempt to destroy invalid mutex '&chan->lock'. [Dec 31 17:17:29] ERROR[16809]: /dar/build/asterisk-1.4.23/include/asterisk/lock.h:511 __ast_pthread_mutex_unlock: channel.c line 1305 (ast_channel_free): mutex '&(&channels)->lock' freed more times than we've locked! [Dec 31 17:17:29] ERROR[16809]: /dar/build/asterisk-1.4.23/include/asterisk/lock.h:528 __ast_pthread_mutex_unlock: channel.c line 1305 (ast_channel_free): Error releasing mutex: Operation not permitted Extension Changed 701[commzilla-local] new state Idle for Notify User 225 Extension Changed 701[commzilla-local] new state Idle for Notify User 230 Extension Changed 701[commzilla-local] new state Idle for Notify User 233 -- Stopped music on hold on SIP/229-b7c16330 Here is the backtrace Core was generated by `/usr/sbin/asterisk -f -U scopserv -G scopserv -vvvg -c'. Program terminated with signal 11, Segmentation fault. #0 0x0808aba9 in ast_channel_free () (gdb) bt #0 0x0808aba9 in ast_channel_free () #1 0x0808bae2 in ast_hangup () #2 0x00e3a1c9 in do_parking_thread (ignore=0x0) at res_features.c:1992 #3 0x0811f807 in dummy_start () #4 0x008fe45b in start_thread () from /lib/libpthread.so.0 ASTERISK-1 0x00855e5e in clone () from /lib/libc.so.6 (gdb) bt full #0 0x0808aba9 in ast_channel_free () No symbol table info available. #1 0x0808bae2 in ast_hangup () No symbol table info available. #2 0x00e3a1c9 in do_parking_thread (ignore=0x0) at res_features.c:1992 f = (struct ast_frame *) 0x0 chan = (struct ast_channel *) 0x9536eb8 tms = 2284 x = 7 con = (struct ast_context *) 0x93da458 pl = (struct parkeduser *) 0x0 pt = (struct parkeduser *) 0x0 ms = -1 nrfds = {fds_bits = {0 <repeats 32 times>}} pu = (struct parkeduser *) 0x95357f8 max = -1 nefds = {fds_bits = {0 <repeats 32 times>}} rfds = {fds_bits = {0, 4194304, 0 <repeats 30 times>}} efds = {fds_bits = {0 <repeats 32 times>}} __PRETTY_FUNCTION__ = "do_parking_thread" #3 0x0811f807 in dummy_start () No symbol table info available. #4 0x008fe45b in start_thread () from /lib/libpthread.so.0 No symbol table info available. ASTERISK-1 0x00855e5e in clone () from /lib/libc.so.6 | ||
| Comments: | By: David Brillert (aragon) 2008-12-31 17:15:11.000-0600 Also Aastra SIP transfer to park extension fails but does not produce segfault like spre transfer By: Leif Madsen (lmadsen) 2009-01-06 08:30:56.000-0600 Just a quick question; did you generate that backtrace with 'DONT_OPTIMIZE' enabled in menuselect under the Compiler Flags? That backtrace looks a bit light to me, so I just thought I'd double check. Thanks! By: David Brillert (aragon) 2009-01-08 14:51:04.000-0600 yes By: Leif Madsen (lmadsen) 2009-01-09 12:56:19.000-0600 I hate to assign any more issues to murf, but he may be the best one to look at this as it is in his favourite part of Asterisk... PARKING! :) Please reassign should this not be the case. By: Steve Murphy (murf) 2009-01-09 14:34:05.000-0600 I've attached a small patch to see what 'f' (a frame ptr) is set to... please download it (14157.experiment), use it to patch your asterisk source, make, make install, and see what console messages you get. In general, it looks very much like the channel has already been freed. Trying to free it a second time seems to prove fatal. What kind of Aastra phone do you have? I have a 53i... I don't remember that feature, but it's been a long time since I played with it. One more thing; If you could do a "sip debug" or better yet, a wireshark type capture of the traffic between asterisk and the phone up to the point of the crash, that would be most invaluable. By: David Brillert (aragon) 2009-01-09 15:00:37.000-0600 It does not matter if 53i or 480i or 57i. Various firmware versions of Aastra firmware also have no effect on problem. I will test the patch next week. Thanks Murf By: Joel Vandal (jvandal) 2009-01-09 15:07:14.000-0600 This is not a patch to fix the problem but to help find why it crash. By: David Brillert (aragon) 2009-01-09 15:14:52.000-0600 Yes I understand. The sooner we can test insert the patch and reproduce the sooner Murf can provide a working patch or at least find root cause. By: Steve Murphy (murf) 2009-01-09 16:34:15.000-0600 Oho! I pulled out the userguide for the 53i and lo and behold, there it is, you can program the softkeys... The 53i manual seems to want you to use the web interface to program the phone... and has very specific instructions for Asterisk (or Aasterisk in one place!) On page 32 of the Model 53i IP Phone User Guide, it suggests using sprecode. But on pages 33 and 34, "Setting Park/Pickup Keys", they advise for asterisk you'd use the Hard Key value of "Park", and/or "Pickup" (one key for Park, another key for Pickup), with Value field set to 700 for either case. As to "Line", they say "select the lines for which to apply the Park and pickup configuration". So, here's what I'm thinking. You say it puts line 1 on hold, and then pumps the precode out to line 2. This sounds... not good. I'd play with the "line" entry for the programmable softkey and see if another setting works better. And, I'd check to make sure the phone has hardkey options of Park or Pickup, and use those instead of the precode stuff. And if all you have is the precode stuff, then set up in features.conf, a one-touch code for parking (like *3 or something), and see if that works better with the precode option. By: Steve Murphy (murf) 2009-01-09 16:40:54.000-0600 Oh, and on page 35, they say that to park a call, you press the "park" softkey. The server should announce the exten number of the parking stall. Then you press the "handset with down arrow" key to complete parking. And to pickup a parked exten, they say, pick up the handset; enter the exten num of the parked exten (701?) and hit the "Pickup" softkey. Hmmm. I wonder what the key does that is so special. Seems like just dialing ext 701 like normal would give you that. Oh, well! By: David Brillert (aragon) 2009-01-09 21:12:55.000-0600 Hi Murf I have tried the following methods before opening bug report: -dedicated SIP transfer key (transfer fails) -Aastra park key (transfer fails) -Asterisk blind transfer (works) -Asterisk one touch park (works) -spre code (transfer fails and segfaults asterisk about 80% of the time) Normally the spre behaves as SIP one touch transfer the spre attempts to transfer to Asterisk park extension by completing the transfer on a single line. Whereas the SIP transfer would normally invoke a second line. spre code transfers used to work perfectly in Asterisk for me. I also did some additional reading and some new settings in Aastra 1.4 firmware are required to complete a blind SIP transfer that does not attempt to use a second line. This setting had no effect. Aastra SIP transfers to park and spre transfers to park just don't seem to work. We'll patch to help with the segfault analysis. And I will wireshark capture the SIP events leading to park failure. Funny thing in manual is that park key is programmed and then some default values are mentioned for certain SIP PBX's. Park is referred to as 700. I don't see what is so special about this either... By: David Brillert (aragon) 2009-01-12 14:42:13.000-0600 Hi Murf Updated to Asterisk revision 168494 Reproduced segfault with SIP transfer or spre SIP transfer Here is Asterisk CLI during spre transfer (I had to park a few calls to segfault Asterisk) Extension Changed 6002[default-local] new state InUse for Notify User 6001 Extension Changed 6002[default-local] new state InUse for Notify User 6010 Extension Changed 6002[default-local] new state InUse for Notify User 6002 -- Executing [6001@default-super:1] GotoIf("SIP/6002-b7d28240", "0?3") in new stack -- Executing [6001@default-super:2] Set("SIP/6002-b7d28240", "GROUP(OUTGOING)=6002") in new stack -- Executing [6001@default-super:3] Set("SIP/6002-b7d28240", "OUTBOUND_GROUP_ONCE=6001@INCOMING") in new stack -- Executing [6001@default-super:4] Set("SIP/6002-b7d28240", "GROUPCOUNT=0") in new stack -- Executing [6001@default-super:5] Set("SIP/6002-b7d28240", "GROUPCOUNT2=0") in new stack -- Executing [6001@default-super:6] Set("SIP/6002-b7d28240", "DB(default/wrapup/6001/lastcall)=1231792614.11") in new stack -- Executing [6001@default-super:7] Macro("SIP/6002-b7d28240", "default-dial|SIP/6001|6001|default|20|en|b6001@default|twWkKM(all-tapi^1231792614.11)||default||Local/0@default-local-devices|vm") in new stack -- Executing [s@macro-default-dial:1] NoOp("SIP/6002-b7d28240", ""CALL TO LOCAL EXTENSION FROM 6002(Reception 6002)"") in new stack -- Executing [s@macro-default-dial:2] UserEvent("SIP/6002-b7d28240", "TAPI|TAPIEVENT: LINE_NEWCALL default") in new stack -- Executing [s@macro-default-dial:3] UserEvent("SIP/6002-b7d28240", "TAPI|TAPIEVENT: LINE_CALLSTATE LINECALLSTATE_OFFERING") in new stack -- Executing [s@macro-default-dial:4] UserEvent("SIP/6002-b7d28240", "TAPI|TAPIEVENT: SET CALLERID ") in new stack -- Executing [s@macro-default-dial:5] UserEvent("SIP/6002-b7d28240", "TAPI|TAPIEVENT: LINE_CALLINFO LINECALLINFOSTATE_CALLERID") in new stack -- Executing [s@macro-default-dial:6] AGI("SIP/6002-b7d28240", "/var/www/scopserv/telephony/scripts/agi/dial.php") in new stack -- Launched AGI Script /var/www/scopserv/telephony/scripts/agi/dial.php == /var/www/scopserv/telephony/scripts/agi/dial.php: Added extension '6001' to extension map. -- AGI Script Executing Application: (SetMusicOnHold) Options: (default) -- AGI Script Executing Application: (MixMonitor) Options: (6002:_1231792614.11.WAV|b) == Begin MixMonitor Recording SIP/6002-b7d28240 == Parsing '/etc/asterisk/manager.conf': Found == /var/www/scopserv/telephony/scripts/agi/dial.php: Extension State for '6001' is '0'. -- AGI Script Executing Application: (NoOp) Options: (STATUS:) == /var/www/scopserv/telephony/scripts/agi/dial.php: ------------------------------------------------------------------------------- == /var/www/scopserv/telephony/scripts/agi/dial.php: Doing the action dial == /var/www/scopserv/telephony/scripts/agi/dial.php: Caller ID number is '6002' == /var/www/scopserv/telephony/scripts/agi/dial.php: DbSet default/6001/CallTrace to 6002 == /var/www/scopserv/telephony/scripts/agi/dial.php: Dial string is SIP/6001|20|twWkKM(all-tapi^1231792614.11)T|. -- AGI Script Executing Application: (Dial) Options: (SIP/6001|20|twWkKM(all-tapi^1231792614.11)T|) Extension Changed 6001[default-local] new state Ringing for Notify User 6001 Extension Changed 6001[default-local] new state Ringing for Notify User 6002 Extension Changed 6001[default-local] new state Ringing for Notify User 6010 -- Called 6001 -- SIP/6001-08d5dfa0 is ringing -- SIP/6001-08d5dfa0 answered SIP/6002-b7d28240 Extension Changed 6001[default-local] new state InUse for Notify User 6001 Extension Changed 6001[default-local] new state InUse for Notify User 6002 Extension Changed 6001[default-local] new state InUse for Notify User 6010 -- Executing [s@macro-all-tapi:1] UserEvent("SIP/6001-08d5dfa0", "TAPI|TAPIEVENT [~1231792614.11] LINE_CALLSTATE LINECALLSTATE_CONNECTED") in new stack Extension Changed 6001[default-local] new state Hold for Notify User 6001 Extension Changed 6001[default-local] new state Hold for Notify User 6002 Extension Changed 6001[default-local] new state Hold for Notify User 6010 -- Started music on hold, class 'default', on SIP/6002-b7d28240 -- Executing [7000@default-super:1] Park("SIP/6001-b7d6d090", "") in new stack == Parked SIP/6001-b7d6d090 on 7001@parkedcalls. Will timeout back to extension [default-super] s, 1 in 45 seconds -- Added extension '7001' priority 1 to parkedcalls -- <SIP/6001-b7d6d090> Playing 'digits/7' (language 'en') -- <SIP/6001-b7d6d090> Playing 'digits/0' (language 'en') -- <SIP/6001-b7d6d090> Playing 'digits/0' (language 'en') -- <SIP/6001-b7d6d090> Playing 'digits/1' (language 'en') -- Started music on hold, class 'default', on SIP/6001-b7d6d090 == Spawn extension (default-super, s, 1) exited non-zero on 'SIP/6001-b7d6d090' -- Stopped music on hold on SIP/6001-b7d6d090 == Parking: f=(nil) and type=-100 == SIP/6001-b7d6d090 got tired of being parked [Jan 12 15:37:03] NOTICE[8572]: cdr.c:431 check_post: CDR on channel 'SIP/6001-b7d6d090' already posted [Jan 12 15:37:03] NOTICE[8572]: cdr.c:431 check_post: CDR on channel 'SIP/6001-b7d6d090' already posted [Jan 12 15:37:03] ERROR[8572]: channel.c:1229 ast_channel_free: Unable to find channel in list to free. Assuming it has already been done. [Jan 12 15:37:03] ERROR[8572]: /dar/build/asterisk-1.4.23/include/asterisk/lock.h:428 __ast_pthread_mutex_lock: channel.c line 1233 (ast_channel_free): Error obtaining mutex: Invalid argument [Jan 12 15:37:03] ERROR[8572]: /dar/build/asterisk-1.4.23/include/asterisk/lock.h:511 __ast_pthread_mutex_unlock: channel.c line 1234 (ast_channel_free): mutex '&chan->lock' freed more times than we've locked! [Jan 12 15:37:03] ERROR[8572]: /dar/build/asterisk-1.4.23/include/asterisk/lock.h:528 __ast_pthread_mutex_unlock: channel.c line 1234 (ast_channel_free): Error releasing mutex: Invalid argument [Jan 12 15:37:03] ERROR[8572]: /dar/build/asterisk-1.4.23/include/asterisk/lock.h:428 __ast_pthread_mutex_lock: channel.c line 1243 (ast_channel_free): Error obtaining mutex: Invalid argument [Jan 12 15:37:03] ERROR[8572]: /dar/build/asterisk-1.4.23/include/asterisk/lock.h:511 __ast_pthread_mutex_unlock: channel.c line 1244 (ast_channel_free): mutex '&chan->lock' freed more times than we've locked! [Jan 12 15:37:03] ERROR[8572]: /dar/build/asterisk-1.4.23/include/asterisk/lock.h:528 __ast_pthread_mutex_unlock: channel.c line 1244 (ast_channel_free): Error releasing mutex: Invalid argument [Jan 12 15:37:03] ERROR[8572]: /dar/build/asterisk-1.4.23/include/asterisk/lock.h:316 __ast_pthread_mutex_destroy: channel.c line 1301 (ast_channel_free): Error: attempt to destroy invalid mutex '&chan->lock'. [Jan 12 15:37:03] ERROR[8572]: /dar/build/asterisk-1.4.23/include/asterisk/lock.h:511 __ast_pthread_mutex_unlock: channel.c line 1305 (ast_channel_free): mutex '&(&channels)->lock' freed more times than we've locked! [Jan 12 15:37:03] ERROR[8572]: /dar/build/asterisk-1.4.23/include/asterisk/lock.h:528 __ast_pthread_mutex_unlock: channel.c line 1305 (ast_channel_free): Error releasing mutex: Operation not permitted == Parsing '/etc/asterisk/manager.conf': Found == Parsing '/etc/asterisk/manager.conf': Found == Parsing '/etc/asterisk/manager.conf': Found Extension Changed 6001[default-local] new state InUse for Notify User 6001 -- Stopped music on hold on SIP/6002-b7d28240 Extension Changed 6001[default-local] new state InUse for Notify User 6002 Extension Changed 6001[default-local] new state InUse for Notify User 6010 -- Executing [h@macro-default-dial:1] ResetCDR("SIP/6002-b7d28240", "w") in new stack -- Executing [h@macro-default-dial:2] NoCDR("SIP/6002-b7d28240", "") in new stack -- Executing [h@macro-default-dial:3] UserEvent("SIP/6002-b7d28240", "TAPI|TAPIEVENT: LINE_CALLSTATE LINECALLSTATE_IDLE") in new stack -- Executing [h@macro-default-dial:4] System("SIP/6002-b7d28240", "/var/www/scopserv/telephony/scripts/billing/cdr.sh 1231792614.11") in new stack Extension Changed 6001[default-local] new state Idle for Notify User 6001 Extension Changed 6001[default-local] new state Idle for Notify User 6002 Extension Changed 6001[default-local] new state Idle for Notify User 6010 -- AGI Script /var/www/scopserv/telephony/scripts/agi/dial.php completed, returning 0 -- Executing [6001@default-super:8] GotoIf("SIP/6002-b7d28240", "1?9:10") in new stack -- Goto (default-super,6001,9) -- Executing [6001@default-super:9] Hangup("SIP/6002-b7d28240", "") in new stack == Spawn extension (default-super, 6001, 9) exited non-zero on 'SIP/6002-b7d28240' Extension Changed 6002[default-local] new state Idle for Notify User 6001 Extension Changed 6002[default-local] new state Idle for Notify User 6010 Extension Changed 6002[default-local] new state Idle for Notify User 6002 == End MixMonitor Recording SIP/6002-b7d28240 -- Saved useragent "SipSpkr v2.01" for peer 2001 Extension Changed 6002[default-local] new state InUse for Notify User 6001 Extension Changed 6002[default-local] new state InUse for Notify User 6010 Extension Changed 6002[default-local] new state InUse for Notify User 6002 -- Executing [6001@default-super:1] GotoIf("SIP/6002-b7d2c928", "0?3") in new stack -- Executing [6001@default-super:2] Set("SIP/6002-b7d2c928", "GROUP(OUTGOING)=6002") in new stack -- Executing [6001@default-super:3] Set("SIP/6002-b7d2c928", "OUTBOUND_GROUP_ONCE=6001@INCOMING") in new stack -- Executing [6001@default-super:4] Set("SIP/6002-b7d2c928", "GROUPCOUNT=0") in new stack -- Executing [6001@default-super:5] Set("SIP/6002-b7d2c928", "GROUPCOUNT2=0") in new stack -- Executing [6001@default-super:6] Set("SIP/6002-b7d2c928", "DB(default/wrapup/6001/lastcall)=1231792651.14") in new stack -- Executing [6001@default-super:7] Macro("SIP/6002-b7d2c928", "default-dial|SIP/6001|6001|default|20|en|b6001@default|twWkKM(all-tapi^1231792651.14)||default||Local/0@default-local-devices|vm") in new stack -- Executing [s@macro-default-dial:1] NoOp("SIP/6002-b7d2c928", ""CALL TO LOCAL EXTENSION FROM 6002(Reception 6002)"") in new stack -- Executing [s@macro-default-dial:2] UserEvent("SIP/6002-b7d2c928", "TAPI|TAPIEVENT: LINE_NEWCALL default") in new stack -- Executing [s@macro-default-dial:3] UserEvent("SIP/6002-b7d2c928", "TAPI|TAPIEVENT: LINE_CALLSTATE LINECALLSTATE_OFFERING") in new stack -- Executing [s@macro-default-dial:4] UserEvent("SIP/6002-b7d2c928", "TAPI|TAPIEVENT: SET CALLERID ") in new stack -- Executing [s@macro-default-dial:5] UserEvent("SIP/6002-b7d2c928", "TAPI|TAPIEVENT: LINE_CALLINFO LINECALLINFOSTATE_CALLERID") in new stack -- Executing [s@macro-default-dial:6] AGI("SIP/6002-b7d2c928", "/var/www/scopserv/telephony/scripts/agi/dial.php") in new stack -- Launched AGI Script /var/www/scopserv/telephony/scripts/agi/dial.php == /var/www/scopserv/telephony/scripts/agi/dial.php: Added extension '6001' to extension map. -- AGI Script Executing Application: (SetMusicOnHold) Options: (default) -- AGI Script Executing Application: (MixMonitor) Options: (6002:_1231792651.14.WAV|b) == Begin MixMonitor Recording SIP/6002-b7d2c928 == Parsing '/etc/asterisk/manager.conf': Found == /var/www/scopserv/telephony/scripts/agi/dial.php: Extension State for '6001' is '0'. -- AGI Script Executing Application: (NoOp) Options: (STATUS:) == /var/www/scopserv/telephony/scripts/agi/dial.php: ------------------------------------------------------------------------------- == /var/www/scopserv/telephony/scripts/agi/dial.php: Doing the action dial == /var/www/scopserv/telephony/scripts/agi/dial.php: Caller ID number is '6002' == /var/www/scopserv/telephony/scripts/agi/dial.php: DbSet default/6001/CallTrace to 6002 == /var/www/scopserv/telephony/scripts/agi/dial.php: Dial string is SIP/6001|20|twWkKM(all-tapi^1231792651.14)T|. -- AGI Script Executing Application: (Dial) Options: (SIP/6001|20|twWkKM(all-tapi^1231792651.14)T|) Extension Changed 6001[default-local] new state Ringing for Notify User 6001 Extension Changed 6001[default-local] new state Ringing for Notify User 6002 Extension Changed 6001[default-local] new state Ringing for Notify User 6010 -- Called 6001 -- SIP/6001-08d5dfa0 is ringing [Jan 12 15:37:32] NOTICE[8590]: chan_iax2.c:8974 __iax2_poke_noanswer: Peer 'iaxmodem0' is now UNREACHABLE! Time: 1 Extension Changed 6001[default-local] new state InUse for Notify User 6001 Extension Changed 6001[default-local] new state InUse for Notify User 6002 Extension Changed 6001[default-local] new state InUse for Notify User 6010 -- SIP/6001-08d5dfa0 answered SIP/6002-b7d2c928 -- Executing [s@macro-all-tapi:1] UserEvent("SIP/6001-08d5dfa0", "TAPI|TAPIEVENT [~1231792651.14] LINE_CALLSTATE LINECALLSTATE_CONNECTED") in new stack Extension Changed 6001[default-local] new state Hold for Notify User 6001 Extension Changed 6001[default-local] new state Hold for Notify User 6002 Extension Changed 6001[default-local] new state Hold for Notify User 6010 -- Started music on hold, class 'default', on SIP/6002-b7d2c928 -- Executing [7000@default-super:1] Park("SIP/6001-b7d3c9a8", "") in new stack == Parked SIP/6001-b7d3c9a8 on 7001@parkedcalls. Will timeout back to extension [default-super] s, 1 in 45 seconds -- Added extension '7001' priority 1 to parkedcalls -- <SIP/6001-b7d3c9a8> Playing 'digits/7' (language 'en') -- <SIP/6001-b7d3c9a8> Playing 'digits/0' (language 'en') -- <SIP/6001-b7d3c9a8> Playing 'digits/0' (language 'en') -- <SIP/6001-b7d3c9a8> Playing 'digits/1' (language 'en') -- Started music on hold, class 'default', on SIP/6001-b7d3c9a8 == Spawn extension (default-super, s, 1) exited non-zero on 'SIP/6001-b7d3c9a8' -- Stopped music on hold on SIP/6001-b7d3c9a8 [Jan 12 15:37:39] ERROR[8572]: /dar/build/asterisk-1.4.23/include/asterisk/lock.h:428 __ast_pthread_mutex_lock: channel.c line 2489 (ast_indicate_data): Error obtaining mutex: Invalid argument [Jan 12 15:37:39] ERROR[8572]: /dar/build/asterisk-1.4.23/include/asterisk/lock.h:511 __ast_pthread_mutex_unlock: channel.c line 2493 (ast_indicate_data): mutex '&chan->lock' freed more times than we've locked! [Jan 12 15:37:39] ERROR[8572]: /dar/build/asterisk-1.4.23/include/asterisk/lock.h:528 __ast_pthread_mutex_unlock: channel.c line 2493 (ast_indicate_data): Error releasing mutex: Invalid argument [Jan 12 15:37:39] ERROR[8572]: /dar/build/asterisk-1.4.23/include/asterisk/lock.h:428 __ast_pthread_mutex_lock: channel.c line 2489 (ast_indicate_data): Error obtaining mutex: Invalid argument [Jan 12 15:37:39] ERROR[8572]: /dar/build/asterisk-1.4.23/include/asterisk/lock.h:511 __ast_pthread_mutex_unlock: channel.c line 2493 (ast_indicate_data): mutex '&chan->lock' freed more times than we've locked! [Jan 12 15:37:39] ERROR[8572]: /dar/build/asterisk-1.4.23/include/asterisk/lock.h:528 __ast_pthread_mutex_unlock: channel.c line 2493 (ast_indicate_data): Error releasing mutex: Invalid argument [Jan 12 15:37:39] ERROR[8572]: /dar/build/asterisk-1.4.23/include/asterisk/lock.h:428 __ast_pthread_mutex_lock: channel.c line 2489 (ast_indicate_data): Error obtaining mutex: Invalid argument [Jan 12 15:37:39] ERROR[8572]: /dar/build/asterisk-1.4.23/include/asterisk/lock.h:511 __ast_pthread_mutex_unlock: channel.c line 2493 (ast_indicate_data): mutex '&chan->lock' freed more times than we've locked! [Jan 12 15:37:39] ERROR[8572]: /dar/build/asterisk-1.4.23/include/asterisk/lock.h:528 __ast_pthread_mutex_unlock: channel.c line 2493 (ast_indicate_data): Error releasing mutex: Invalid argument [Jan 12 15:37:42] NOTICE[8586]: chan_iax2.c:8053 socket_process: Peer 'iaxmodem0' is now REACHABLE! Time: 3 -- Stopped music on hold on SIP/6002-b7d2c928 -- Executing [h@macro-default-dial:1] ResetCDR("SIP/6002-b7d2c928", "w") in new stack -- Executing [h@macro-default-dial:2] NoCDR("SIP/6002-b7d2c928", "") in new stack -- Executing [h@macro-default-dial:3] UserEvent("SIP/6002-b7d2c928", "TAPI|TAPIEVENT: LINE_CALLSTATE LINECALLSTATE_IDLE") in new stack -- Executing [h@macro-default-dial:4] System("SIP/6002-b7d2c928", "/var/www/scopserv/telephony/scripts/billing/cdr.sh 1231792651.14") in new stack == Spawn extension (macro-default-dial, s, 6) exited non-zero on 'SIP/6002-b7d2c928' in macro 'default-dial' == Spawn extension (default-super, 6001, 7) exited non-zero on 'SIP/6002-b7d2c928' == End MixMonitor Recording SIP/6002-b7d2c928 Extension Changed 6001[default-local] new state Idle for Notify User 6001 Extension Changed 6001[default-local] new state Idle for Notify User 6002 Extension Changed 6001[default-local] new state Idle for Notify User 6010 Extension Changed 6002[default-local] new state Idle for Notify User 6001 Extension Changed 6002[default-local] new state Idle for Notify User 6010 Extension Changed 6002[default-local] new state Idle for Notify User 6002 Disconnected from Asterisk server Executing last minute cleanups Backtraces and Wireshare pcap attached By: David Brillert (aragon) 2009-01-13 13:13:19.000-0600 I should mention that these logs are based on Asterisk revision 168494 and patched with 14157.experiment 'f' (a frame ptr) is set to... == Parking: f=(nil) and type=-100 Hey Murf What next? Cheers By: Leif Madsen (lmadsen) 2009-01-14 17:30:23.000-0600 Terry has mentioned an issue with Parking at commit 166093 that could very well be causing your crashing problems. Could you try with a revision prior to 166093 (i.e. 166092) and see if that solves the crashing problem? It may not have anything to do with the SPRE stuff on your phone. Just a thought. By: David Brillert (aragon) 2009-01-14 17:37:13.000-0600 Hi Leif SPRE or SIP xfer either will crash Asterisk Tested with Polycom phones with same results. By: Leif Madsen (lmadsen) 2009-01-14 17:41:45.000-0600 I know, that's what I'm saying :) It doesn't matter that you're using SPRE. I wanted you to try Asterisk prior to the revision I mentioned above to see if your issue goes away or not. By: David Brillert (aragon) 2009-01-14 18:22:18.000-0600 I downgraded to 1.4.21 and tested again SIP transfer and SPRE work without segfaulting blind transfer to park and one touch segfault 1.4.21 with little effort By: David Brillert (aragon) 2009-01-15 18:18:04.000-0600 I have upgraded to 168494 again. I prefer to use this version because it fixes many other service affecting issues for me. So I prefer to help murf fix in any way I can assist I hope we can get park fixed once and for all in all of it's potential configurations :) blind transfer attended transfer one touch park SIP transfer to parkexten Parking is extremely important for my PRI users and I hate to see it crash Asterisk... Also I hope someone will take this out of feedback status ;) By: David Brillert (aragon) 2009-01-16 13:36:51.000-0600 I just tested Revision: 168761 To include Repository: asterisk Revision: 168716 U branches/1.4/res/res_features.c ------------------------------------------------------------------------ r168716 | twilson | 2009-01-15 12:22:50 -0600 (Thu, 15 Jan 2009) | 12 lines Convert call to park_call_full to masq_park_call_announce Since we removed the AST_PBX_KEEPALIVE return value, we need to use masqueraded parking, otherwise we will try to call ast_hangup() in __pbx_run() and in do_parking_thread() and then promptly crash. (closes issue 0014215) Reported by: waverly360 Tested by: otherwiseguy (closes issue 0014228) Reported by: kobaz Tested by: otherwiseguy This resulted in segfault during SIP transfer to park ext Core was generated by `/usr/sbin/asterisk -f -U scopserv -G scopserv -vvvg -c'. Program terminated with signal 11, Segmentation fault. #0 0x0808aba9 in ast_channel_free () (gdb) bt #0 0x0808aba9 in ast_channel_free () #1 0x0808bae2 in ast_hangup () #2 0x00f82212 in do_parking_thread (ignore=0x0) at res_features.c:1994 #3 0x0811f7d7 in dummy_start () #4 0x008fd45b in start_thread () from /lib/libpthread.so.0 ASTERISK-1 0x00854e5e in clone () from /lib/libc.so.6 (gdb) bt full #0 0x0808aba9 in ast_channel_free () No symbol table info available. #1 0x0808bae2 in ast_hangup () No symbol table info available. #2 0x00f82212 in do_parking_thread (ignore=0x0) at res_features.c:1994 f = (struct ast_frame *) 0x0 chan = (struct ast_channel *) 0x8d54a28 tms = 3145 x = 7 con = (struct ast_context *) 0x8075704 pl = (struct parkeduser *) 0x0 pt = (struct parkeduser *) 0x0 ms = -1 nrfds = {fds_bits = {0 <repeats 32 times>}} pu = (struct parkeduser *) 0x8d66c68 max = -1 nefds = {fds_bits = {0 <repeats 32 times>}} rfds = {fds_bits = {0, 0, 0, 0, 1048576, 0 <repeats 27 times>}} efds = {fds_bits = {0 <repeats 32 times>}} __PRETTY_FUNCTION__ = "do_parking_thread" #3 0x0811f7d7 in dummy_start () No symbol table info available. #4 0x008fd45b in start_thread () from /lib/libpthread.so.0 No symbol table info available. ASTERISK-1 0x00854e5e in clone () from /lib/libc.so.6 No symbol table info available. By: Terry Wilson (twilson) 2009-01-16 17:17:18.000-0600 aragon: is there any chance I could get you to try with a completely fresh checkout of 1.4 just to make sure? This looks like exactly the same crash that the patch fixed for me. By: Terry Wilson (twilson) 2009-01-16 17:27:15.000-0600 I've tried: A calls B, B parks A, timeout B picks up A calls B, B parks A, B calls parking exten A calls B, A parks B, timeout A picks up A calls B, A parks B, A calls parking exten All of the above are with native SIP transfers like you are using. I tried with Attended, Blind, and Attended completed during the extension read back and I can't reproduce. By: David Brillert (aragon) 2009-01-17 16:26:34.000-0600 Otherwiseguy I did a fresh checkout of today's SVN I was not able to crash Asterisk Yippeee You can close this bug report Nice commit; cheers By: David Brillert (aragon) 2009-01-17 16:38:06.000-0600 I also tested to confirm park would return to extension after callback duration. This worked too. I tested with two scenarios. 1. A calls B and B parks A - callback returns to B after timeout (also possible to park caller again) 2. A calls B and B parks A - B picks up parked call and transfers to C - C answers transferred A and parks A - Call is successfully returned by callback to C after timeout I think this revision also can close bug 14066 My test revision is 169154 By: Terry Wilson (twilson) 2009-01-17 20:00:47.000-0600 Closing at request of reporter | ||