[Home]

Summary:ASTERISK-08283: Asterisk crashes when updating state on a expired realtime peer (res_config_mysql)
Reporter:Dawid M (dmielnik)Labels:
Date Opened:2006-12-05 14:20:46.000-0600Date Closed:2007-06-19 14:21:09
Priority:CriticalRegression?No
Status:Closed/CompleteComponents:Channels/chan_iax2
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) 20070321_asterisk_crash.txt
( 1) bt_full_1.txt
( 2) bt_full_2.txt
( 3) full_1.txt
( 4) full_2.txt
( 5) thread_apply_all_bt_1.txt
( 6) thread_apply_all_bt_2.txt
( 7) verbose_2.txt
Description:I tried to test iax stability with the latest asterisk and asterisk-addons trunk version, but Asterisk only tuns for a few minutes and crashes - from gdb backtraces it seems that this may be connected with realtime and mysql.

Comments:By: Serge Vecher (serge-v) 2006-12-05 15:04:13.000-0600

was the "DONT OPTIMIZE" flag checked in menuselect under "Compiler Options"? If not, please recompile Asterisk and redo the bt's. Thanks.
By: Dawid M (dmielnik) 2006-12-05 15:52:43.000-0600

yes, DONT_OPTIMIZE option was checked
By: Matt O'Gorman (mogorman) 2006-12-07 10:27:52.000-0600

can you do a bt full plese
By: Joshua C. Colp (jcolp) 2006-12-18 20:54:41.000-0600

Please try the latest version of trunk. I changed some things in chan_iax2 that may have solved this.
By: Dawid M (dmielnik) 2006-12-19 05:13:13.000-0600

now it crashes after a couple of seconds..

   -- Seeding '5306332' at 83.8.65.105:1985 for 180
[Dec 19 12:03:44] ERROR[15217]: /usr/local/asterisk/include/asterisk/lock.h:310 __ast_pthread_mutex_trylock: chan_iax2.c line 6522 (socket_process): Error: '&iaxsl[f->callno]' was locked here.
   -- Registered IAX2 '5306332' (AUTHENTICATED) at 83.8.65.105:1985
[Dec 19 12:03:44] ERROR[15217]: /usr/local/asterisk/include/asterisk/lock.h:310 __ast_pthread_mutex_trylock: chan_iax2.c line 6522 (socket_process): Error: '&iaxsl[f->callno]' was locked here.
   -- Seeding '8480799' at 83.10.109.184:1410 for 180
   -- Registered IAX2 '8480799' (AUTHENTICATED) at 83.10.109.184:1410
[Dec 19 12:03:45] ERROR[15217]: /usr/local/asterisk/include/asterisk/lock.h:310 __ast_pthread_mutex_trylock: chan_iax2.c line 6522 (socket_process): Error: '&iaxsl[f->callno]' was locked here.
   -- Seeding '888925' at 83.23.77.143:2860 for 180
   -- Registered IAX2 '888925' (AUTHENTICATED) at 83.23.77.143:2860
[Dec 19 12:03:46] ERROR[15217]: /usr/local/asterisk/include/asterisk/lock.h:310 __ast_pthread_mutex_trylock: chan_iax2.c line 6522 (socket_process): Error: '&iaxsl[f->callno]' was locked here.
   -- Seeding '8857585' at 85.210.48.234:3530 for 180
   -- Registered IAX2 '8857585' (AUTHENTICATED) at 85.210.48.234:3530
[Dec 19 12:03:47] ERROR[15217]: /usr/local/asterisk/include/asterisk/lock.h:310 __ast_pthread_mutex_trylock: chan_iax2.c line 6522 (socket_process): Error: '&iaxsl[f->callno]' was locked here.
   -- Seeding '4913700' at 89.187.232.10:1143 for 180
   -- Registered IAX2 '4913700' (AUTHENTICATED) at 89.187.232.10:1143
[Dec 19 12:03:48] ERROR[15217]: /usr/local/asterisk/include/asterisk/lock.h:310 __ast_pthread_mutex_trylock: chan_iax2.c line 6522 (socket_process): Error: '&iaxsl[f->callno]' was locked here.
**** Received REGISTER (2) - Command in SIP REGISTER
**** Received REGISTER (2) - Command in SIP REGISTER
   -- Registered SIP '1360378' at 217.153.221.42 port 61020 expires 120
   -- Saved useragent "Linksys/PAP2T-3.1.15(LS)_IPFON" for peer 1360378
   -- SIP Seeding peer from astdb: '1360378' at 1360378@217.153.221.42:61020 for 120
[Dec 19 12:03:49] ERROR[15217]: /usr/local/asterisk/include/asterisk/lock.h:310 __ast_pthread_mutex_trylock: chan_iax2.c line 6855 (socket_process): Error: '&iaxsl[f->callno]' was locked here.
   -- Accepting AUTHENTICATED call from 89.187.232.10:
      > requested format = alaw,
      > requested prefs = (),
      > actual format = alaw,
      > host prefs = (gsm|alaw|ulaw|speex|ilbc),
      > priority = mine
[Dec 19 12:03:49] ERROR[15217]: /usr/local/asterisk/include/asterisk/lock.h:310 __ast_pthread_mutex_trylock: chan_iax2.c line 6522 (socket_process): Error: '&iaxsl[f->callno]' was locked here.
   -- Executing DeadAgi("IAX2/4913700-7", "agi://10.0.1.246/outbound_call_manager.php?1=4913700&2=0713769845&3=phoneast1")
   -- AGI Script Executing Application: (Dial) Options: (Local/0713769845@tel/n|120|CL(2100000:30000))
   -- Limit Data for this call:
      > timelimit      = 2100000
      > play_warning   = 30000
      > play_to_caller = yes
      > play_to_callee = no
      > warning_freq   = 0
      > start_sound    =
      > warning_sound  = phone-1-2
      > end_sound      =
[Dec 19 12:03:49] WARNING[15230]: pbx.c:1677 pbx_extension_helper: No application 'Random' for extension (tel, 0713769845, 1)
 == Spawn extension (tel, 0713769845, 1) exited non-zero on 'Local/0713769845@tel-1a2c,2'
   -- Called 0713769845@tel/n
[Dec 19 12:03:49] ERROR[15202]: /usr/local/asterisk/include/asterisk/lock.h:310 __ast_pthread_mutex_trylock: channel.c line 1537 (ast_hangup): Error: '&c->lock' was locked here.
 == Everyone is busy/congested at this time (1:0/0/1)
   -- AGI Script Executing Application: (Dial) Options: (SIP/etelko_ab/0713769845|120|CL(2100000:30000)CL(2100000:30000))
   -- Limit Data for this call:
      > timelimit      = 2100000
      > play_warning   = 30000
      > play_to_caller = yes
      > play_to_callee = no
      > warning_freq   = 0
      > start_sound    =
      > warning_sound  = phone-1-2
      > end_sound      =
   -- Called etelko_ab/0713769845
transmit_request ACK
   -- SIP/etelko_ab-0076c100 is making progress passing it to IAX2/4913700-7
**** Received REGISTER (2) - Command in SIP REGISTER
**** Received REGISTER (2) - Command in SIP REGISTER
**** Received REGISTER (2) - Command in SIP REGISTER
   -- Registered SIP '4126759' at 88.156.0.17 port 5061 expires 120
   -- Saved useragent "Linksys/PAP2-3.1.9(LSc)" for peer 4126759
   -- SIP Seeding peer from astdb: '4126759' at 4126759@88.156.0.17:5061 for 120
   -- Seeding '8665463' at 81.190.164.108:1670 for 180
   -- Registered IAX2 '8665463' (AUTHENTICATED) at 81.190.164.108:1670
[Dec 19 12:03:50] ERROR[15217]: /usr/local/asterisk/include/asterisk/lock.h:310 __ast_pthread_mutex_trylock: chan_iax2.c line 6522 (socket_process): Error: '&iaxsl[f->callno]' was locked here.
   -- Got SIP response 486 "Busy here" back from 10.254.254.1
transmit_request ACK
   -- SIP/etelko_ab-0076c100 is busy
chan_sip1 sip_hangup flags invitestate 5 0xc1a2005 data <INVITE>
chan_sip1 sip_hangup flags now 0xc1a2007
 == Everyone is busy/congested at this time (1:1/0/0)
   -- AGI Script Executing Application: (playtones) Options: (BUSY)
   -- AGI Script Executing Application: (wait) Options: (5)
**** Received INVITE (5) - Command in SIP INVITE
**** Received ACK (6) - Command in SIP ACK
setting state to INV_CONFIRMED
**** Received INVITE (5) - Command in SIP INVITE
   -- Executing [486276528@from_tel:1] Set("SIP/fromggtel-007726b0", "CALLERID(num)=Unknown") in new stack
   -- Executing [486276528@from_tel:2] Ringing("SIP/fromggtel-007726b0", "") in new stack
   -- Executing [486276528@from_tel:3] Wait("SIP/fromggtel-007726b0", "1") in new stack
**** Received CANCEL (14) - Command in SIP CANCEL
 == Spawn extension (from_tel, 486276528, 3) exited non-zero on 'SIP/fromggtel-007726b0'
chan_sip1 sip_hangup flags invitestate 7 0xc1a001d data <INVITE>
chan_sip1 sip_hangup flags now 0xc1a001f
**** Received ACK (6) - Command in SIP ACK
setting state to INV_CONFIRMED
   -- Seeding '8665203' at 212.87.229.18:1336 for 180
   -- Registered IAX2 '8665203' (AUTHENTICATED) at 212.87.229.18:1336
**** Received REGISTER (2) - Command in SIP REGISTER
**** Received REGISTER (2) - Command in SIP REGISTER
   -- Registered SIP '2656082' at 83.144.104.214 port 5061 expires 120
   -- Saved useragent "Linksys/PAP2-3.1.9(LSc)" for peer 2656082
   -- SIP Seeding peer from astdb: '2656082' at 2656082@83.144.104.214:5061 for 120
   -- AGI Script agi://10.0.1.246/outbound_call_manager.php?1=4913700&2=0713769845&3=phoneast1 completed, returning 0
   -- Executing Hangup("IAX2/4913700-7", "")
 == Spawn extension (from_gg, 0713769845, 2) exited non-zero on 'IAX2/4913700-7'
   -- Hungup 'IAX2/4913700-7'
   -- Seeding '3051473' at 80.48.35.51:1070 for 180
   -- Registered IAX2 '3051473' (AUTHENTICATED) at 80.48.35.51:1070
[Dec 19 12:04:00] ERROR[15217]: /usr/local/asterisk/include/asterisk/lock.h:310 __ast_pthread_mutex_trylock: chan_iax2.c line 6522 (socket_process): Error: '&iaxsl[f->callno]' was locked here.
**** Received INVITE (5) - Command in SIP INVITE
**** Received ACK (6) - Command in SIP ACK
setting state to INV_CONFIRMED
**** Received INVITE (5) - Command in SIP INVITE
   -- Executing [486276528@from_tel:1] Set("SIP/fromggtel-a3102eb0", "CALLERID(num)=Unknown") in new stack
   -- Executing [486276528@from_tel:2] Ringing("SIP/fromggtel-a3102eb0", "") in new stack
   -- Executing [486276528@from_tel:3] Wait("SIP/fromggtel-a3102eb0", "1") in new stack
   -- Executing [486276528@from_tel:4] DeadAGI("SIP/fromggtel-a3102eb0", "agi://10.0.1.246/inbound_call_manager.php?1=Unknown&2=486276528") in new stack
   -- AGI Script agi://10.0.1.246/inbound_call_manager.php?1=Unknown&2=486276528 completed, returning 0
   -- Executing [486276528@from_tel:5] Hangup("SIP/fromggtel-a3102eb0", "") in new stack
 == Spawn extension (from_tel, 486276528, 5) exited non-zero on 'SIP/fromggtel-a3102eb0'
chan_sip1 sip_hangup flags invitestate 3 0xc1a001c data <INVITE>
chan_sip1 sip_hangup flags now 0xc1a001c
**** Received ACK (6) - Command in SIP ACK
setting state to INV_CONFIRMED
**** Received REGISTER (2) - Command in SIP REGISTER
 == Parsing '/etc/asterisk/manager.conf': Found
**** Received REGISTER (2) - Command in SIP REGISTER
**** Received REGISTER (2) - Command in SIP REGISTER
   -- Registered SIP '3385989' at 87.207.113.18 port 59323 expires 600
Segmentation fault (core dumped)
By: Serge Vecher (serge-v) 2006-12-19 11:30:02.000-0600

dmielnik: please always attach backtraces as attachments to make notes in the bug more readable. Thanks.
By: Dawid M (dmielnik) 2007-01-02 05:56:36.000-0600

sure - ok
in the meantime - is there any progress with this issue ?
By: Dawid M (dmielnik) 2007-01-31 16:19:17.000-0600

?
By: Serge Vecher (serge-v) 2007-02-05 10:27:39.000-0600

While we are waiting for a developer to pick this up, what's the status with the latest trunk?
By: Dawid M (dmielnik) 2007-02-06 03:00:32.000-0600

I tested again with trunk two days ago - same result.
By: Serge Vecher (serge-v) 2007-02-26 14:02:49.000-0600

dmielnik, since there code changes, bt's need to be updated as well. Please upload the bt's from latest svn code -> also, include and svn revision rather than the time when you checked the branch out. Thanks.
By: Serge Vecher (serge-v) 2007-03-20 14:23:54

no response from reporter. If this is still an issue with 1.4.2, please upload new backtraces as requested.
By: Dawid M (dmielnik) 2007-03-21 11:48:16

I'm not sure if this is the same issue - but I have just tested the new release of Asterisk - asterisk-1.4.2 which crashed after a few minutes

I'm attaching the backlogs - yes, debug threads and don't optimize flags selected.
By: Dawid M (dmielnik) 2007-03-21 11:54:07

I dont mean to be rude - but could you actually look into this issue instead of waiting for it to resolve by itself with new releases ? quite sad we havent been able to use asterisk 1.4 yet because iax is unstable
By: Serge Vecher (serge-v) 2007-03-21 12:01:33

ok, did you save the console log as well? If so, please attach...
By: Dawid M (dmielnik) 2007-03-21 12:15:14

sorry - didn't save the console logs, will try again and provide backtraces along with verbose and debug logs as soon as I can
By: Dawid M (dmielnik) 2007-04-06 15:30:25

ok - some more back traces, and logs
(asterisk version 1.4.2, asterisk-addons version 1.4.0 - dont optimize and debug threads flags)
By: Serge Vecher (serge-v) 2007-04-09 09:08:43

I'm not knowledgeable enough to trace the problem by looking at bt's, but one thing I know is that one should never execute DeadAGI on a live call.
By: Dawid M (dmielnik) 2007-04-09 09:28:44

what exactly do you mean by 'executing DeadAGI on a live call' ? DeadAGI is used for call control in order to provide billing functions after the channel hangs up.

bt and verbose logs show that the crashes always occur on database queries (not on all database queries though) suggesting a problem on iax/realtime/mysql interfaces ?
By: Serge Vecher (serge-v) 2007-04-09 12:09:08

that is not what DeadAGI is designed to be used for, see note 0055483 in 8843 for example (or search bug-tracker for 'DeadAGI', others have explained it in a better way).
By: Dawid M (dmielnik) 2007-04-09 13:32:15

Im sorry but there doesent appear to be note 0055483 in bug 8843 :(

all AGI based prepaid applications use DeadAGI in this way, including Asterisk Calling Card Platform (ASTCC) written by Mark Spencer...

anyhow - this does not appear to be the problem here but rather the iax / realtime interface in the new iax architecture
By: Serge Vecher (serge-v) 2007-04-09 13:38:43

sorry, I meant 8443.
By: Dawid M (dmielnik) 2007-04-09 13:54:30

ok - will look into AGI and SIGHUP, like I said though this really doesent appear to be the issue here, so please investigate it further
By: Serge Vecher (serge-v) 2007-04-09 14:05:09

it looks like the crash is at the following line:

if(mysql_real_query(&mysql, sql, strlen(sql)))

this function is in the mysql library, I believe. Which version of libmysqlclient are you using?
By: Dawid M (dmielnik) 2007-04-09 15:19:52

it's 3.23.58

we are running Asterisk 1.2.9.1 and realtime with this version though without problems.
By: Dawid M (dmielnik) 2007-04-10 17:39:49

any ideas ??
By: Tilghman Lesher (tilghman) 2007-04-10 18:40:51

Some ideas:

1.  MySQL 3.23.58 is legacy software and is no longer supported by MySQL.  They recommend a library version of at least 4.1, if not 5.0.  You may want to consider upgrading your MySQL version.

2.  Not many developers are running 64-bit, so it is difficult to diagnose issues that may not appear on 32-bit x86.  You may want to consider attempting to reproduce the problem on 32-bit x86 to see if the problem goes away in that environment.

3.  The backtrace shows a clear memory corruption error.  These types of errors are very difficult to track down.  The developers are not ignoring your issue; we are generally stymied by these types of crashes.  We are unlikely to be able to track down this problem without access to the system on which you are having this issue (and even then, it's still difficult).
By: Wolfgang Liegel (wliegel) 2007-04-27 02:42:25

I have the same problem here.
I think the Asterisk crashes when it tries to notify an expired realtime peer.

While expired peers are removed from memory in chan_sip.c they obviously aren't removed from the callback list.
When a peer expires without having properly unregistered _and_ the subscription of any channel is still active, the callback pointer (struct ast_state_cb *cblist) in pbx.c seems to refer (cblist->next) to an invalid location.

To get a workaround for this issue I tried
   ignoreregexpire=yes
   rtautoclear=no
   rtcachefriends=yes
in sip.conf

I have no testing results, yet, but any comments and feedback would be appreciated.
By: Russell Bryant (russell) 2007-06-19 14:21:07

The backtrace here shows a crash within MySQL.  Unless you can update to an up to date version of MySQL, there is no reason for us to think the crash is the fault of Asterisk.  If you can upgrade MySQL, use the latest version of Asterisk, and still reproduce the crash, then feel free to reopen this issue with updated backtraces.  Thank you!