[Home]

Summary:ASTERISK-07216: [patch] Realtime Voicemail (Re)Connection
Reporter:Douglas Garstang (dgarstang)Labels:
Date Opened:2006-06-21 14:35:23Date Closed:2006-07-10 00:14:29
Priority:MinorRegression?No
Status:Closed/CompleteComponents:Applications/General
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) 20060623__bug7410.diff.txt
( 1) 20060626__bug7410.diff.txt
Description:I'm using realtime for voicemail users, and for reasons that I don't yet understand, when it doesn't get used for a while (like overnight), the first connection attempt of the day will display this on the console.

Jun 21 07:54:00 ERROR[8112]: cdr_addon_mysql.c:159 mysql_log: cdr_mysql: Unknown connection error: (2006) MySQL server has gone away
Jun 21 07:54:01 NOTICE[8120]: rtp.c:564 ast_rtp_read: Unknown RTP codec 96 received
   -- Executing VoiceMail("SIP/xxx.187.142.186-b773c428", "u2944017@voicemail") in new stack
Jun 21 07:54:01 ERROR[8120]: res_config_mysql.c:623 mysql_reconnect: MySQL RealTime: Failed to reconnect. Check debug for more info.
Jun 21 07:54:01 WARNING[8120]: app_voicemail.c:2411 leave_voicemail: No entry in voicemail config file for '2944017'

The very next connection attempt will work. Happens like clockwork every morning. It would seem that Asterisk is not reconnecting the first time, even when it says it is.
Comments:By: Serge Vecher (serge-v) 2006-06-21 14:39:11

you have been asked before to read the BUG GUIDELINES and test the latest stable Asterisk release before reporting an issue. Is this an issue in 1.2.9.1?
By: Douglas Garstang (dgarstang) 2006-06-21 14:53:42

It's been ocurring for several releases. I will retest with 1.2.9.1, because I'd hate to see you burst a vein in your neck, or anything like that.


By: Serge Vecher (serge-v) 2006-06-21 15:00:13

don't worry, it already has, along with a couple of arteries
By: Douglas Garstang (dgarstang) 2006-06-22 09:15:48

This problem has been reproduced on 1.2.9.1
First realtime connection attempt of the morning...

   -- Nobody picked up in 36000 ms
   -- AGI Script Executing Application: (Dial) Options: (Local/u2944093@global_vmdeposit)
   -- Called u2944093@global_vmdeposit
   -- Executing Answer("Local/u2944093@global_vmdeposit-23e5,2", "") in new stack
   -- Local/u2944093@global_vmdeposit-23e5,1 answered SIP/2944093-3217
   -- Executing Wait("Local/u2944093@global_vmdeposit-23e5,2", "1") in new stack
 == Spawn extension (one_start, 2944093, 1) exited non-zero on 'Local/u2944093@global_vmdeposit-23e5,2<ZOMBIE>'
Jun 22 08:13:13 ERROR[18731]: cdr_addon_mysql.c:159 mysql_log: cdr_mysql: Unknown connection error: (2006) MySQL server has gone away
Jun 22 08:13:13 ERROR[18731]: cdr_addon_mysql.c:144 mysql_log: cdr_mysql: cannot connect to database server db1.ipt.twoeighty.com.
   -- Executing VoiceMail("SIP/2944093-3217", "u2944093@voicemail") in new stack
Jun 22 08:13:13 ERROR[18744]: res_config_mysql.c:623 mysql_reconnect: MySQL RealTime: Failed to reconnect. Check debug for more info.
Jun 22 08:13:13 WARNING[18744]: app_voicemail.c:2410 leave_voicemail: No entry in voicemail config file for '2944093'
 == Auto fallthrough, channel 'SIP/2944093-3217' status is 'NOANSWER'

Second realtime connection request of the morning...

   -- Nobody picked up in 36000 ms
   -- AGI Script Executing Application: (Dial) Options: (Local/u2944093@global_vmdeposit)
   -- Called u2944093@global_vmdeposit
   -- Executing Answer("Local/u2944093@global_vmdeposit-17f3,2", "") in new stack
   -- Local/u2944093@global_vmdeposit-17f3,1 answered SIP/2944093-f56f
   -- Executing Wait("Local/u2944093@global_vmdeposit-17f3,2", "1") in new stack
 == Spawn extension (one_start, 2944093, 1) exited non-zero on 'Local/u2944093@global_vmdeposit-17f3,2<ZOMBIE>'
   -- Executing VoiceMail("SIP/2944093-f56f", "u2944093@voicemail") in new stack
   -- Playing 'vm-theperson' (language 'en')
   -- Playing 'digits/2' (language 'en')
   -- Playing 'digits/9' (language 'en')
 == Spawn extension (global_vmdeposit, u2944093, 3) exited non-zero on 'SIP/2944093-f56f'


By: Tilghman Lesher (tilghman) 2006-06-22 09:58:30

As the error message suggests, please turn on debug logging in logger.conf.  We need to know exactly which mysql error is causing this.
By: Douglas Garstang (dgarstang) 2006-06-23 09:07:38

Here's my logger.conf:
console => notice,warning,error,verbose
messages => notice,warning,error,verbose,debug

and my console debug level is:
hera*CLI> set debug 999
Core debug was 99 and is now 999
(as you can see, it was already 99...)

The problem just ocurred. Here's what was appended to /var/log/asterisk/messages. There is no additional information that I can see.

Jun 23 07:59:07 DEBUG[8642] pbx.c: Launching 'VoiceMail'
Jun 23 07:59:07 VERBOSE[8642] logger.c:     -- Executing VoiceMail("SIP/xxx.187.142.186-b7200480", "u2944017@voicemail") in new stac
k
Jun 23 07:59:07 DEBUG[8642] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM ast_vm_users WHERE mailbox = '2944017' AND context = 'voicemail'
Jun 23 07:59:07 ERROR[8642] res_config_mysql.c: MySQL RealTime: Failed to reconnect. Check debug for more info.
Jun 23 07:59:07 DEBUG[8642] res_config_mysql.c: MySQL RealTime: Server Error: MySQL server has gone away
Jun 23 07:59:07 WARNING[8642] app_voicemail.c: No entry in voicemail config file for '2944017'
Jun 23 07:59:07 VERBOSE[8642] logger.c:   == Auto fallthrough, channel 'SIP/xxx.187.142.186-b7200480' status is 'CHANUNAVAIL'


By: Serge Vecher (serge-v) 2006-06-23 09:54:28

Well: there is this line ... Broken connection to the server?
Jun 23 07:59:07 DEBUG[8642] res_config_mysql.c: MySQL RealTime: Server Error: MySQL server has gone away
By: Douglas Garstang (dgarstang) 2006-06-23 09:58:57

I'm guessing here, but maybe this is happening. Does Asterisk open a socket to MySQL and attempt to keep it open? MySQL might be timing out and disconnecting the socket after some period of time due to no data on the socket. Asterisk then has a bug in it's logic where the first attempt to use a stale socket, does not result in it trying to reconnect until after the attempt has failed. When the next attempt comes in, the socket is already connected.

I think MySQL _should_ disconnect the stale socket. It's up to Asterisk to correctly re-establish the connection.


By: Tilghman Lesher (tilghman) 2006-06-23 12:41:41

Please test this patch, and give me feedback on whether it resolves your issue.
By: Douglas Garstang (dgarstang) 2006-06-23 12:58:33

I've patched all three of our Asterisk servers with this patch. Considering it's Friday, we may not know how well it works until Monday morning.
By: Douglas Garstang (dgarstang) 2006-06-26 09:31:44

The feedback is that this patch did not fix the problem. It happened again this morning.

Here's what was in /var/log/asterisk/messages

Jun 26 06:13:12 DEBUG[1816] chan_local.c: Not posting to queue since already masked on 'Local/u2944016@global_vmdeposit-0465,1'
Jun 26 06:13:12 DEBUG[1826] channel.c: Got clone lock for masquerade on 'SIP/xxx.187.142.190-08229600' at 0x816a394
Jun 26 06:13:12 DEBUG[1826] channel.c: Putting channel SIP/xxx.187.142.190-08229600 in 4/4 formats
Jun 26 06:13:12 DEBUG[1826] channel.c: Released clone lock on 'Local/u2944016@global_vmdeposit-0465,2<ZOMBIE>'
Jun 26 06:13:12 DEBUG[1826] channel.c: Done Masquerading SIP/xxx.187.142.190-08229600 (6)
Jun 26 06:13:12 DEBUG[1816] channel.c: Didn't get a frame from channel: Local/u2944016@global_vmdeposit-0465,2<ZOMBIE>
Jun 26 06:13:12 DEBUG[1816] channel.c: Bridge stops bridging channels Local/u2944016@global_vmdeposit-0465,2<ZOMBIE> and Local/u2944
016@global_vmdeposit-0465,1
Jun 26 06:13:12 DEBUG[1816] app_dial.c: Exiting with DIALSTATUS=ANSWER.
Jun 26 06:13:12 DEBUG[1816] res_agi.c: Local/u2944016@global_vmdeposit-0465,2<ZOMBIE> hungup
Jun 26 06:13:12 VERBOSE[1816] logger.c:   == Spawn extension (frompstn_start, 2944016, 2) exited non-zero on 'Local/u2944016@global_
vmdeposit-0465,2<ZOMBIE>'
Jun 26 06:13:12 ERROR[1816] cdr_addon_mysql.c: cdr_mysql: Unknown connection error: (2006) MySQL server has gone away
Jun 26 06:13:12 DEBUG[1816] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record.
Jun 26 06:13:12 DEBUG[1816] cdr_addon_mysql.c: cdr_mysql: SQL command as follows: INSERT INTO pbx_ast_cdr (calldate,clid,src,dst,dco
ntext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode) VALUES ('2006-06-26 06:12:48','50999939
06','5099993906','2944016','frompstn_start', 'SIP/xxx.187.142.190-08229600','Local/u2944016@global_vmdeposit-0465,1','Dial','Local/u
2944016@global_vmdeposit',24,0,'ANSWERED',3,'2944016')
Jun 26 06:13:12 DEBUG[1816] pbx.c: Function result is '5099993906'
Jun 26 06:13:12 DEBUG[1816] pbx.c: Function result is '5099993906'
Jun 26 06:13:12 DEBUG[1816] pbx.c: Function result is '2944016'
Jun 26 06:13:12 DEBUG[1816] pbx.c: Function result is 'frompstn_start'
Jun 26 06:13:12 DEBUG[1816] pbx.c: Function result is 'SIP/xxx.187.142.190-08229600'
Jun 26 06:13:12 DEBUG[1816] pbx.c: Function result is 'Local/u2944016@global_vmdeposit-0465,1'
Jun 26 06:13:12 DEBUG[1816] pbx.c: Function result is 'Dial'
Jun 26 06:13:12 DEBUG[1816] pbx.c: Function result is 'Local/u2944016@global_vmdeposit'
Jun 26 06:13:12 DEBUG[1816] pbx.c: Function result is '2006-06-26 06:12:48'
Jun 26 06:13:12 DEBUG[1816] pbx.c: Function result is '2006-06-26 06:13:12'
Jun 26 06:13:12 DEBUG[1816] pbx.c: Function result is '2006-06-26 06:13:12'
Jun 26 06:13:12 DEBUG[1816] pbx.c: Function result is '24'
Jun 26 06:13:12 DEBUG[1816] pbx.c: Function result is '0'
Jun 26 06:13:12 DEBUG[1816] pbx.c: Function result is 'ANSWERED'
Jun 26 06:13:12 DEBUG[1816] pbx.c: Function result is 'DOCUMENTATION'
Jun 26 06:13:12 DEBUG[1816] pbx.c: Function result is '2944016'
Jun 26 06:13:12 DEBUG[1816] pbx.c: Function result is '1151323968.24'
Jun 26 06:13:12 DEBUG[1816] pbx.c: Function result is '(null)'
Jun 26 06:13:13 VERBOSE[1826] logger.c:     -- Executing VoiceMail("SIP/xxx.187.142.190-08229600", "u2944016@voicemail") in new stac
k
Jun 26 06:13:13 DEBUG[1826] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM ast_vm_users WHERE mailbox = '2944016' A
ND context = 'voicemail'
Jun 26 06:13:13 ERROR[1826] res_config_mysql.c: MySQL RealTime: Failed to reconnect. Check debug for more info.
Jun 26 06:13:13 DEBUG[1826] res_config_mysql.c: MySQL RealTime: Server Error: MySQL server has gone away
Jun 26 06:13:13 WARNING[1826] app_voicemail.c: No entry in voicemail config file for '2944016'
By: Tilghman Lesher (tilghman) 2006-06-26 10:33:05

Okay, MySQL has apparently changed some semantics of what mysql_ping() does as of 5.0.3.  This code should now force a reconnect.
By: Douglas Garstang (dgarstang) 2006-06-26 10:41:12

I probably should have mentioned we are using MySQL 5.1.7. I'll give this new patch a try.

Is this new patch cumulative? Do I need to apply the old one first, or should I apply this one to a clean addons source tree?


By: mk (mklein) 2006-06-27 13:29:43

Yep, worked.
By: Douglas Garstang (dgarstang) 2006-06-27 13:40:34

Worked? You mean you where able to replicate this problem and the patch fixed it? I haven't had a chance to investigate if the patch worked yet.
By: Tilghman Lesher (tilghman) 2006-07-09 00:41:46

Any update?
By: mk (mklein) 2006-07-09 02:15:11

Hey Cory, been a while. Yes this patch (20060626) fixed the "MySQL has gone away" bug I was also experiencing. As of 5.0.3, mysql "smartly" decided to change some default variables, I beleieve this part of the patch explains everything:
+ /* The default is no longer to automatically reconnect on failure,
+ * (as of 5.0.3) so we have to set that option here. */
+ mysql_options(&mysql, MYSQL_OPT_RECONNECT, &trueval);

This should be applied to CVS and later releases, as it doesn't hurt to overrride an already true variable and fixes the problems with mysql 5.0.3+ with realtime.

-vile
By: Tilghman Lesher (tilghman) 2006-07-10 00:14:29

Fixed in 1.2, merged to trunk.