Hi,
having some rare issues writing acc-data to a remote MySQL server. The connection is made using the MySQL SSL options. Most, 99,9%, of the writes work well.
The error is: ``` Nov 20 13:48:55 /usr/sbin/kamailio[28976]: WARNING: db_mysql [km_dbase.c:84]: db_mysql_submit_query(): driver error on ping: SSL connection error: socket layer receive error Nov 20 13:48:55 /usr/sbin/kamailio[28976]: ERROR: db_mysql [km_dbase.c:121]: db_mysql_submit_query(): driver error on query: SSL connection error: socket layer receive error Nov 20 13:48:55 /usr/sbin/kamailio[28976]: ERROR: <core> [db_query.c:235]: db_do_insert_cmd(): error while submitting query ```
Apart from the connection details (using [mysql-ssl-conf] for the SSL config block) I have this config: ``` modparam("db_mysql", "ping_interval", 30); modparam("db_mysql", "timeout_interval", 8); ```
The documentation suggests that "ping_interval" is the "Time interval in seconds to send ping messages to MySQL server in order to keep the connection open." However, looking at the code this seems a bit misleading because it looks like the ping is only done on an actual query (db_mysql_submit_query), i.e. not with a regular interval/on a timer as suggested by the documentation?
Also the "auto_reconnect" parameter is stated as default 1 (on), but in the code this is just used as a "retry" of the query itself and MYSQL_OPT_RECONNECT is never set on the connection (https://dev.mysql.com/doc/refman/5.5/en/auto-reconnect.html)? Maybe this is not necessary and it's enough to just re-try the query?
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/406
Does this happen under constant load of calls written to acc? Or you have sporadic calls that are written to acc?
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/406#issuecomment-158941724
This happens during constant load.
This morning I found a way to re-create this issue on a production system, but after restarting Kamailio I could not force this to happen again. My feeling, although not proven, is that the DB connection is dropped/timed out at some point and re-connecting is not working properly.
Looking at the connections on the database server it looks like some of the Kamailio childs have been sleeping for quite some time and others are used often: ``` | 22750784 | acc_user | 1.2.3.4:49102 | acc | Sleep | 0 | | NULL | | 22750785 | acc_user | 1.2.3.4:49101 | acc | Sleep | 1 | | NULL | | 22750786 | acc_user | 1.2.3.4:49103 | acc | Sleep | 6 | | NULL | | 22750787 | acc_user | 1.2.3.4:49105 | acc | Sleep | 0 | | NULL | | 22750789 | acc_user | 1.2.3.4:49107 | acc | Sleep | 2 | | NULL | | 22750790 | acc_user | 1.2.3.4:49108 | acc | Sleep | 3905 | | NULL | | 22750791 | acc_user | 1.2.3.4:49106 | acc | Sleep | 0 | | NULL | | 22750792 | acc_user | 1.2.3.4:49112 | acc | Sleep | 653 | | NULL | | 22750793 | acc_user | 1.2.3.4:49109 | acc | Sleep | 2 | | NULL | | 22750794 | acc_user | 1.2.3.4:49110 | acc | Sleep | 1551 | | NULL | | 22750795 | acc_user | 1.2.3.4:49114 | acc | Sleep | 6217 | | NULL | | 22750796 | acc_user | 1.2.3.4:49111 | acc | Sleep | 5110 | | NULL | | 22750797 | acc_user | 1.2.3.4:49113 | acc | Sleep | 8605 | | NULL | | 22750798 | acc_user | 1.2.3.4:49115 | acc | Sleep | 0 | | NULL | | 22750812 | kam_user | 1.2.3.4:49117 | routing_db | Sleep | 190 | | NULL | | 22750813 | kam_user | 1.2.3.4:49121 | routing_db | Sleep | 11665 | | NULL | | 22750814 | kam_user | 1.2.3.4:49119 | routing_db | Sleep | 0 | | NULL | | 22750816 | kam_user | 1.2.3.4:49123 | routing_db | Sleep | 2 | | NULL | | 22750818 | kam_user | 1.2.3.4:49127 | routing_db | Sleep | 0 | | NULL | | 22750819 | kam_user | 1.2.3.4:49125 | routing_db | Sleep | 10 | | NULL | | 22750820 | kam_user | 1.2.3.4:49129 | routing_db | Sleep | 30 | | NULL | | 22751056 | kam_user | 1.2.3.4:49205 | routing_db | Sleep | 0 | | NULL | | 22751057 | kam_user | 1.2.3.4:49206 | routing_db | Sleep | 1 | | NULL | | 22751058 | kam_user | 1.2.3.4:49208 | routing_db | Sleep | 0 | | NULL | | 22751059 | kam_user | 1.2.3.4:49207 | routing_db | Sleep | 11660 | | NULL | | 22751060 | kam_user | 1.2.3.4:49209 | routing_db | Sleep | 1 | | NULL | | 22751061 | kam_user | 1.2.3.4:49210 | routing_db | Sleep | 130 | | NULL | | 22751062 | kam_user | 1.2.3.4:49211 | routing_db | Sleep | 70 | | NULL | | 22751063 | kam_user | 1.2.3.4:49212 | routing_db | Sleep | 0 | | NULL | ```
What will actually happen in the MySQL API when a query is ran on a connection that has been closed?
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/406#issuecomment-158949340
It the code I see that the module attempts to reconnect only on errors CR_SERVER_GONE_ERROR and CR_SERVER_LOST.
It appears that in this case the error code is CR_SSL_CONNECTION_ERROR.
We can add this code to the condition to attempt to re-connect, but I wonder if other codes should be added, the list is at:
* https://dev.mysql.com/doc/refman/5.5/en/error-messages-client.html#error_cr_...
If you want to try yourself, see modules/db_mysql/km_dbase.c, line 116.
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/406#issuecomment-158985365
Aha, so it will not actually even re-try the query on the CR_SSL_CONNECTION_ERROR error?
Have seen these as well, again, very rare but still: ``` Nov 23 16:21:30 /usr/sbin/kamailio[31201]: WARNING: db_mysql [km_dbase.c:84]: db_mysql_submit_query(): driver error on ping: Can't connect to MySQL server on 'myDb' (4) Nov 23 16:21:30 /usr/sbin/kamailio[31201]: ERROR: db_mysql [km_dbase.c:121]: db_mysql_submit_query(): driver error on query: Can't connect to MySQL server on 'myDb' (4) Nov 23 16:21:30 /usr/sbin/kamailio[31201]: ERROR: <core> [db_query.c:235]: db_do_insert_cmd(): error while submitting query ```
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/406#issuecomment-158988359
Yes, it doesn't retry on CR_SSL_CONNECTION_ERROR.
I guess the next error codes can be added in the list to re-try:
``` CR_SSL_CONNECTION_ERROR CR_CONNECTION_ERROR CR_CONN_HOST_ERROR CR_SERVER_LOST_EXTENDED ```
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/406#issuecomment-158995592
I pushed to commits to add the extra error codes in the attempt to reconnect list and enforce the reconnect flag via mysql api (it was done via setting the field in mysql connection structure, which is still left, just in case older versions don't have the api).
Not sure if for the ssl connect will solve it or it will require more explicit connecting functions. Try the patches and if goes well, then I will backport.
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/406#issuecomment-159001695
Thanks, will try the nightly build tomorrow.
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/406#issuecomment-159047046
Unless @linuxmaniac has some updates, the debs nightly builds platform is not running.
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/406#issuecomment-159055221
Ok, will compile from master then. Thanks for the heads up.
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/406#issuecomment-159055719
Ended up checking out branch 4.3 and backporting your changes, however, I must be misunderstanding something because I'm having issues with the new db_mysql.so-file. When I use that one I get this error and I cannot connect to the DB anymore: ``` ERROR: db_mysql [km_my_con.c:114]: db_mysql_new_connection(): driver error: SSL connection error ``` Replacing with the debian package file works just fine again.
Isn't it enough just to re-compile the db_mysql module and replace the .so-file? Standard settings, make with "TLS_HOOKS=1 make include_modules="db_mysql tls" cfg"
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/406#issuecomment-159257771
Disregard that! Compiled using a very old libmysqlclient...
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/406#issuecomment-159263388
Ok, so I tested your code in a production system and just replacing the module didn't always seem to do the trick, I still ended up with messages like these: ``` Nov 25 15:35:26 /usr/sbin/kamailio[15053]: ERROR: db_mysql [km_dbase.c:128]: db_mysql_submit_query(): driver error on query: SSL connection error: socket layer receive error (2026) Nov 25 15:35:26 /usr/sbin/kamailio[15053]: ERROR: <core> [db_query.c:235]: db_do_insert_cmd(): error while submitting query ```
The error above lead me to the conclusion that "mysql_ping()" wasn't performed on these requests. Dug into the MySQL C API and from what I understand the MYSQL_OPT_RECONNECT=true is only used by and acted upon by mysql_ping(), no query functions. So I decreased the "ping_interval" setting to: ``` modparam("db_mysql", "ping_interval", 5); ``` to force mysql_ping to run more frequently. This code has now been running for almost 24h on a production system and it looks promising. Made a small addition to your code to get a warning if connection ID changed after mysql_ping (see attached diff). Now I'm getting a few of these messages: ``` Nov 26 08:55:27 /usr/sbin/kamailio[29363]: WARNING: db_mysql [km_dbase.c:91]: db_mysql_submit_query(): mysql thread id changed due to reconnect in mysql_ping ``` but from what I can see no more failed INSERTs.
I'm thinking MYSQL_OPT_RECONNECT together with frequent mysql_ping()'s seems to have done the trick.
[mysql_ping.diff.txt](https://github.com/kamailio/kamailio/files/44746/mysql_ping.diff.txt)
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/406#issuecomment-159849980
Update after a few more days in production.
This still seem to happen, but very seldom: ``` Nov 30 12:50:22 /usr/sbin/kamailio[25529]: WARNING: db_mysql [km_dbase.c:86]: db_mysql_submit_query(): driver error on ping: SSL connection error: socket layer receive error Nov 30 12:50:22 /usr/sbin/kamailio[25529]: ERROR: db_mysql [km_dbase.c:128]: db_mysql_submit_query(): driver error on query: SSL connection error: socket layer receive error (2026) Nov 30 12:50:22 /usr/sbin/kamailio[25529]: ERROR: <core> [db_query.c:235]: db_do_insert_cmd(): error while submitting query Nov 30 12:50:22 /usr/sbin/kamailio[25529]: WARNING: db_mysql [km_dbase.c:91]: db_mysql_submit_query(): mysql thread id changed due to reconnect in mysql_ping ```
Not sure if it would make sense to re-try the mysql_ping a few times?
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/406#issuecomment-160621074
I pushed commit 250c7125613fc0fc26b72f68a7d0bd63a4a1b430 to master that adds 3 attempts of mysql ping if autreconnect is set. Feedback about solving or not the issue is appreciated!
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/406#issuecomment-162668979
Patched in a production system, will get back.
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/406#issuecomment-162922330
Not sure if it's a good idea or not, but would it be possible to write some code that would periodically perform a mysql_ping on each kamailio child running? Maybe a better option is to lower the amount of childs to make sure the connection is used more frequently? Or if there's already a core setting to make the usage of the childs more round-robin?
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/406#issuecomment-163005295
From the logs after your most recent patch:
``` Dec 8 17:06:19 /usr/sbin/kamailio[31957]: WARNING: db_mysql [km_dbase.c:87]: db_mysql_submit_query(): driver error on ping: Lost connection to MySQL server during query Dec 8 17:06:19 /usr/sbin/kamailio[31957]: WARNING: db_mysql [km_dbase.c:87]: db_mysql_submit_query(): driver error on ping: Can't connect to MySQL server on 'xxxx' (4) Dec 8 17:06:19 /usr/sbin/kamailio[31957]: WARNING: db_mysql [km_dbase.c:87]: db_mysql_submit_query(): driver error on ping: SSL connection error: socket layer receive error Dec 8 17:06:19 /usr/sbin/kamailio[31957]: ERROR: db_mysql [km_dbase.c:131]: db_mysql_submit_query(): driver error on query: SSL connection error: socket layer receive error (2026) Dec 8 17:06:19 /usr/sbin/kamailio[31957]: ERROR: <core> [db_query.c:181]: db_do_raw_query(): error while submitting query Dec 8 17:06:19 /usr/sbin/kamailio[31957]: WARNING: db_mysql [km_dbase.c:92]: db_mysql_submit_query(): mysql thread id changed due to reconnect on mysql_ping ```
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/406#issuecomment-163006829
There are different types of kamailio processes (children), not easy to have a framework for doing mysql pings when is nothing else to do. Also, there could be executed code continuously but not involving mysql (e.g., receiving keepalive requests and replying to them).
What process gets to be selected for handing a sip udp packet is decided by kernel. For tcp, is an internal dispatcher of tcp connections based on least loaded worker.
If you know you have some constant traffic without mysql involvement, you can add a basic query that doesn't take resources with sqlops, like sql_query("describe table version") or "select now()...".
Worth looking at mysql server and client library setting for connections lifetime, maybe they have some settings there.
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/406#issuecomment-163030130
I understand. Been using SER>OpenSER>Kamailio but to be honest I've found it hard to understand what to monitor in order to understand when the amount of "children" should be increased and not.
Will continue to investigate this.
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/406#issuecomment-163155338
Hello,
Have been running your latest patch for some days now and this issue still occurs, but much more seldom than before. I also removed some TCP-childs as I don't handle much TCP traffic.
Found one time where it looks like all/most processes got their connections dropped: ``` Dec 13 15:37:45 /usr/sbin/kamailio[31904]: WARNING: db_mysql [km_dbase.c:87]: db_mysql_submit_query(): driver error on ping: SSL connection error: socket layer receive error Dec 13 15:37:45 /usr/sbin/kamailio[31904]: WARNING: db_mysql [km_dbase.c:87]: db_mysql_submit_query(): driver error on ping: SSL connection error: socket layer receive error Dec 13 15:37:45 /usr/sbin/kamailio[31904]: WARNING: db_mysql [km_dbase.c:87]: db_mysql_submit_query(): driver error on ping: SSL connection error: socket layer receive error Dec 13 15:37:50 /usr/sbin/kamailio[31904]: ERROR: db_mysql [km_dbase.c:131]: db_mysql_submit_query(): driver error on query: Can't connect to MySQL server on 'mysql' (4) (2003) Dec 13 15:37:50 /usr/sbin/kamailio[31904]: ERROR: <core> [db_query.c:235]: db_do_insert_cmd(): error while submitting query Dec 13 15:37:50 /usr/sbin/kamailio[31904]: WARNING: db_mysql [km_dbase.c:92]: db_mysql_submit_query(): mysql thread id changed due to reconnect on mysql_ping Dec 13 15:37:50 /usr/sbin/kamailio[31901]: WARNING: db_mysql [km_dbase.c:92]: db_mysql_submit_query(): mysql thread id changed due to reconnect on mysql_ping Dec 13 15:37:54 /usr/sbin/kamailio[31902]: WARNING: db_mysql [km_dbase.c:92]: db_mysql_submit_query(): mysql thread id changed due to reconnect on mysql_ping Dec 13 15:37:55 /usr/sbin/kamailio[31894]: WARNING: db_mysql [km_dbase.c:92]: db_mysql_submit_query(): mysql thread id changed due to reconnect on mysql_ping Dec 13 15:37:55 /usr/sbin/kamailio[31898]: WARNING: db_mysql [km_dbase.c:92]: db_mysql_submit_query(): mysql thread id changed due to reconnect on mysql_ping Dec 13 15:37:59 /usr/sbin/kamailio[31900]: WARNING: db_mysql [km_dbase.c:92]: db_mysql_submit_query(): mysql thread id changed due to reconnect on mysql_ping Dec 13 15:38:01 /usr/sbin/kamailio[31897]: WARNING: db_mysql [km_dbase.c:92]: db_mysql_submit_query(): mysql thread id changed due to reconnect on mysql_ping Dec 13 15:38:07 /usr/sbin/kamailio[31891]: WARNING: db_mysql [km_dbase.c:92]: db_mysql_submit_query(): mysql thread id changed due to reconnect on mysql_ping Dec 13 15:38:13 /usr/sbin/kamailio[31892]: WARNING: db_mysql [km_dbase.c:92]: db_mysql_submit_query(): mysql thread id changed due to reconnect on mysql_ping ```
``` Process:: ID=0 PID=31890 Type=attendant Process:: ID=1 PID=31891 Type=udp receiver child=0 sock=127.0.0.1:5060 Process:: ID=2 PID=31892 Type=udp receiver child=1 sock=127.0.0.1:5060 Process:: ID=3 PID=31894 Type=udp receiver child=2 sock=127.0.0.1:5060 Process:: ID=4 PID=31897 Type=udp receiver child=3 sock=127.0.0.1:5060 Process:: ID=5 PID=31898 Type=udp receiver child=4 sock=127.0.0.1:5060 Process:: ID=6 PID=31900 Type=udp receiver child=5 sock=127.0.0.1:5060 Process:: ID=7 PID=31901 Type=udp receiver child=6 sock=127.0.0.1:5060 Process:: ID=8 PID=31902 Type=udp receiver child=7 sock=127.0.0.1:5060 Process:: ID=9 PID=31903 Type=slow timer Process:: ID=10 PID=31904 Type=timer Process:: ID=11 PID=31907 Type=MI FIFO Process:: ID=12 PID=31909 Type=MI DATAGRAM Process:: ID=13 PID=31911 Type=tcp receiver (generic) child=0 Process:: ID=14 PID=31912 Type=tcp receiver (generic) child=1 Process:: ID=15 PID=31913 Type=tcp main process ```
The issue is obviously network related, and kamailio cannot recover after that.
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/406#issuecomment-164387493
Timer process can write acc for failed transactions.
Wondering if there are new observations in the past month. Couldn't find other tricks for adding in the c code...
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/406#issuecomment-173338971
Reopen where there is some new data. So far the c code was patched to be able to reconnect based on returned code.
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/406#issuecomment-174340166
Closed #406.
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/406#event-524351563
There's no new observations really, but the issue is still there. Had to turn off SSL for now as there's just to many inserts not being written correctly.
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/406#issuecomment-176733644
Just wanted to share an observation, and that is that we have multiple servers that are running Kamailio <> SSL <> MySQL, many servers have low load and there this issue is not common at all, but with the servers that have high traffic load this is very common.
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/406#issuecomment-177849835
There's been some new observations on this. When the `SSL connection error: socket layer receive error (2026)` error occurs, it's always the same Kamailio-process that encounters it, I've tried to restart Kamailio numerous times and it's always the same one (not the same pid obviously....): ``` Process:: ID=10 PID=27816 Type=timer ```
I can verify that this process can perform (at least) one db_insert/db_query before this error occurs.
I can also verify from debugs that other processes are able to use the SSL database connections while the `timer` process cannot.
From what I can see once this error happens, the `timer` process cannot recover/reconnect and the SSL error does not go away until Kamailio is restarted.
Any hints on how to debug further are appreciated.
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/406#issuecomment-179814253
@miconda doesn't look like I can reopen.
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/406#issuecomment-179815566
Reopened #406.
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/406#event-539348995
I looked at the docs for lib mysql client, haven't spotted any other hint for attempting to reconnect.
Is the next log message added by you?
``` Dec 8 17:06:19 /usr/sbin/kamailio[31957]: WARNING: db_mysql [km_dbase.c:92]: db_mysql_submit_query(): mysql thread id changed due to reconnect on mysql_ping ```
It doesn't match in the source code. If you did some changes to db_mysql module, post here the diff.
Also, what is the module that triggers the query in this case? It is done in timer process, so it could be acc, usrloc, sqlops... there should be eventuall some other error messages around those printed by db_mysql.
A solution would be to try to do queries more often on timer module. That can be achieved using rtimer, defining one that uses the main timer (mode=0) and execute a route block where you do a simple query.
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/406#issuecomment-180250223
Hi Daniel,
This is the debug output from yesterday when I was trying to find more details. This is the `timer` process and we're using the db_cluster module, as you can see there's one successful insert and after this there's the error thrown. Again, I've reverted back to the standard 4.3.4 db_mysql code, no local changes: ``` Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: DEBUG: tm [t_hooks.c:266]: run_trans_callbacks_internal(): DBG: trans=0x7f06c820a340, callback type 128, id 0 entered Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: DEBUG: acc [acc_logic.c:644]: tmcb_func(): acc callback called for t(0x7f06c820a340) event type 128, reply code 408 Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: DEBUG: db_cluster [dbcl_api.c:483]: db_cluster_use_table(): use table (missed_calls) - cluster [k2] Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: DEBUG: db_cluster [dbcl_api.c:492]: db_cluster_use_table(): set read table (missed_calls) - cluster [k2] (9/0) Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: DEBUG: db_cluster [dbcl_api.c:502]: db_cluster_use_table(): set write table (missed_calls) - cluster [k2] (9/0) Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: DEBUG: db_cluster [dbcl_api.c:492]: db_cluster_use_table(): set read table (missed_calls) - cluster [k2] (1/0) Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: DEBUG: db_cluster [dbcl_api.c:502]: db_cluster_use_table(): set write table (missed_calls) - cluster [k2] (1/0) Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: DEBUG: db_cluster [dbcl_api.c:378]: db_cluster_insert(): executing db cluster insert command Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: DEBUG: db_cluster [dbcl_api.c:379]: db_cluster_insert(): serial operation - cluster [k2] (9/0) Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: DEBUG: acc [acc_extra.h:81]: free_strar_mem(): Freeing memory, type is 2, message_index 7, index i 0 Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: DEBUG: acc [acc_extra.h:81]: free_strar_mem(): Freeing memory, type is 2, message_index 7, index i 1 Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: DEBUG: acc [acc_extra.h:81]: free_strar_mem(): Freeing memory, type is 2, message_index 7, index i 2 Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: DEBUG: acc [acc_extra.h:81]: free_strar_mem(): Freeing memory, type is 2, message_index 7, index i 3 Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: DEBUG: acc [acc_extra.h:81]: free_strar_mem(): Freeing memory, type is 2, message_index 7, index i 4 Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: DEBUG: acc [acc_extra.h:81]: free_strar_mem(): Freeing memory, type is 2, message_index 7, index i 5 Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: DEBUG: acc [acc_extra.h:81]: free_strar_mem(): Freeing memory, type is 1, message_index 7, index i 6 Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: DEBUG: acc [acc_extra.h:81]: free_strar_mem(): Freeing memory, type is 2, message_index 7, index i 7 Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: DEBUG: acc [acc_extra.h:81]: free_strar_mem(): Freeing memory, type is 2, message_index 7, index i 8 Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: DEBUG: acc [acc_extra.h:81]: free_strar_mem(): Freeing memory, type is 1, message_index 7, index i 9 Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: DEBUG: acc [acc_extra.h:81]: free_strar_mem(): Freeing memory, type is 1, message_index 7, index i 10 Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: DEBUG: acc [acc_extra.h:81]: free_strar_mem(): Freeing memory, type is 2, message_index 7, index i 13 Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: DEBUG: acc [acc_extra.h:81]: free_strar_mem(): Freeing memory, type is 1, message_index 7, index i 14 Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: DEBUG: acc [acc_extra.h:81]: free_strar_mem(): Freeing memory, type is 1, message_index 7, index i 15 Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: DEBUG: acc [acc_extra.h:81]: free_strar_mem(): Freeing memory, type is 1, message_index 7, index i 17 Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: DEBUG: acc [acc_extra.h:81]: free_strar_mem(): Freeing memory, type is 1, message_index 7, index i 18 Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: DEBUG: exec [exec_mod.c:178]: w_exec_msg(): executing [progress_call.sh 2 0 'data' 'data' '<null>'] Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: DEBUG: <core> [main.c:833]: sig_usr(): SIGCHLD received: we do not worry about grand-children Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: DEBUG: tm [t_lookup.c:1011]: t_check_msg(): DEBUG: t_check_msg: msg id=132 global id=132 T start=0x7f06c820a340 Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: DEBUG: tm [t_lookup.c:1083]: t_check_msg(): DEBUG: t_check_msg: T already found! Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: DEBUG: tm [t_lookup.c:1011]: t_check_msg(): DEBUG: t_check_msg: msg id=132 global id=132 T start=0x7f06c820a340 Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: DEBUG: tm [t_lookup.c:1083]: t_check_msg(): DEBUG: t_check_msg: T already found! Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: DEBUG: tm [tm.c:996]: t_check_status(): DEBUG:t_check_status: checked status is <408> Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: DEBUG: tm [t_lookup.c:1011]: t_check_msg(): DEBUG: t_check_msg: msg id=132 global id=132 T start=0x7f06c820a340 Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: DEBUG: tm [t_lookup.c:1083]: t_check_msg(): DEBUG: t_check_msg: T already found! Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: DEBUG: tm [tm.c:996]: t_check_status(): DEBUG:t_check_status: checked status is <408> Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: DEBUG: tm [t_lookup.c:1011]: t_check_msg(): DEBUG: t_check_msg: msg id=132 global id=132 T start=0x7f06c820a340 Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: DEBUG: tm [t_lookup.c:1083]: t_check_msg(): DEBUG: t_check_msg: T already found! Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: DEBUG: tm [tm.c:996]: t_check_status(): DEBUG:t_check_status: checked status is <408> Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: DEBUG: tm [t_lookup.c:1011]: t_check_msg(): DEBUG: t_check_msg: msg id=132 global id=132 T start=0x7f06c820a340 Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: DEBUG: tm [t_lookup.c:1083]: t_check_msg(): DEBUG: t_check_msg: T already found! Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: DEBUG: tm [tm.c:996]: t_check_status(): DEBUG:t_check_status: checked status is <408> Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: DEBUG: tm [t_reply.c:1750]: relay_reply(): DEBUG: relay_reply: branch=0, save=0, relay=0 icode=0 Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: DEBUG: <core> [msg_translator.c:158]: check_via_address(): (10.10.10.10, 10.10.10.10, 0) Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: DEBUG: tm [t_hooks.c:266]: run_trans_callbacks_internal(): DBG: trans=0x7f06c820a340, callback type 512, id 0 entered Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: DEBUG: acc [acc_logic.c:644]: tmcb_func(): acc callback called for t(0x7f06c820a340) event type 512, reply code 408 Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: DEBUG: tm [t_cancel.c:337]: cancel_branch(): DEBUG: cancel_branch: sending cancel... Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: DEBUG: tm [t_reply.c:1232]: t_should_relay_response(): ->>>>>>>>> T_code=180, new_code=408 Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: DEBUG: tm [t_lookup.c:1011]: t_check_msg(): DEBUG: t_check_msg: msg id=127 global id=127 T start=0x7f06c80e5af0 Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: DEBUG: tm [t_lookup.c:1083]: t_check_msg(): DEBUG: t_check_msg: T already found! Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: DEBUG: tm [t_lookup.c:1011]: t_check_msg(): DEBUG: t_check_msg: msg id=127 global id=127 T start=0x7f06c80e5af0 Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: DEBUG: tm [t_lookup.c:1083]: t_check_msg(): DEBUG: t_check_msg: T already found! Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: DEBUG: tm [t_hooks.c:266]: run_trans_callbacks_internal(): DBG: trans=0x7f06c80e5af0, callback type 128, id 0 entered Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: DEBUG: acc [acc_logic.c:644]: tmcb_func(): acc callback called for t(0x7f06c80e5af0) event type 128, reply code 408 Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: DEBUG: db_cluster [dbcl_api.c:483]: db_cluster_use_table(): use table (missed_calls) - cluster [k2] Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: DEBUG: db_cluster [dbcl_api.c:492]: db_cluster_use_table(): set read table (missed_calls) - cluster [k2] (9/0) Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: DEBUG: db_cluster [dbcl_api.c:502]: db_cluster_use_table(): set write table (missed_calls) - cluster [k2] (9/0) Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: DEBUG: db_cluster [dbcl_api.c:492]: db_cluster_use_table(): set read table (missed_calls) - cluster [k2] (1/0) Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: DEBUG: db_cluster [dbcl_api.c:502]: db_cluster_use_table(): set write table (missed_calls) - cluster [k2] (1/0) Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: DEBUG: db_cluster [dbcl_api.c:378]: db_cluster_insert(): executing db cluster insert command Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: DEBUG: db_cluster [dbcl_api.c:379]: db_cluster_insert(): serial operation - cluster [k2] (9/0) Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: ERROR: db_mysql [km_dbase.c:124]: db_mysql_submit_query(): driver error on query: SSL connection error: socket layer receive error (2026) Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: ERROR: <core> [db_query.c:235]: db_do_insert_cmd(): error while submitting query Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: DEBUG: db_cluster [dbcl_api.c:379]: db_cluster_insert(): serial operation - failure on cluster [k2] (9/0) Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: DEBUG: db_cluster [dbcl_api.c:379]: db_cluster_insert(): serial operation - cluster [k2] (1/0) Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: DEBUG: acc [acc_extra.h:81]: free_strar_mem(): Freeing memory, type is 2, message_index 7, index i 0 Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: DEBUG: acc [acc_extra.h:81]: free_strar_mem(): Freeing memory, type is 2, message_index 7, index i 1 Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: DEBUG: acc [acc_extra.h:81]: free_strar_mem(): Freeing memory, type is 2, message_index 7, index i 2 Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: DEBUG: acc [acc_extra.h:81]: free_strar_mem(): Freeing memory, type is 2, message_index 7, index i 3 Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: DEBUG: acc [acc_extra.h:81]: free_strar_mem(): Freeing memory, type is 2, message_index 7, index i 4 Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: DEBUG: acc [acc_extra.h:81]: free_strar_mem(): Freeing memory, type is 2, message_index 7, index i 5 Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: DEBUG: acc [acc_extra.h:81]: free_strar_mem(): Freeing memory, type is 2, message_index 7, index i 13 Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: DEBUG: acc [acc_extra.h:81]: free_strar_mem(): Freeing memory, type is 1, message_index 7, index i 14 Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: DEBUG: acc [acc_extra.h:81]: free_strar_mem(): Freeing memory, type is 1, message_index 7, index i 17 Feb 4 13:26:08 hostname /usr/sbin/kamailio[9845]: DEBUG: acc [acc_extra.h:81]: free_strar_mem(): Freeing memory, type is 1, message_index 7, index i 18 ```
Regarding the code change I did to output `mysql thread id changed due to reconnect on mysql_ping`, please see the diff attached in https://github.com/kamailio/kamailio/issues/406#issuecomment-159849980
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/406#issuecomment-180262563
So it is the acc module, which probably write a record on a retransmission timeout (case that doesn't seem to happen too often). Can you try the workaround with rtimer module I presented in a comment before?
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/406#issuecomment-180276224
Is it enough to make a simple SELECT or would I need to perform some bogus INSERT with the rtimer?
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/406#issuecomment-180278033
There's a discussion here. Seems like "SELECT 1" is one way. http://stackoverflow.com/questions/2546868/cheapest-way-to-to-determine-if-a...
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/406#issuecomment-180283755
Thanks, will give this a shoot!
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/406#issuecomment-180284633
Tried this: ``` modparam("rtimer", "timer", "name=test;interval=10;mode=1;"); # Tried both mode=1 and mode=0 modparam("rtimer", "exec", "timer=test;route=99"); route[99] { xlog("rtimer sql"); sql_query("common", "select 1", "ra_test"); sql_result_free("ra_test"); } ```
The rtimer SQL queries looks good from the debug output, still getting SSL errors on other queries on the same process though.
If I disable the SSL options (ssl-key, ssl-ca, ssl-cert, etc) in my.cnf (in the group), there are no sql warnings anymore and looks like all queries are fine.
As the `timer` process can successfully connect with the SQL using SSL when Kamailio starts up, can this be related somehow to that the API forgets the SSL settings along the way and cannot use them when trying to reconnect/re-establish the connection?
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/406#issuecomment-180295655
It has to be mode=0. Can you add also an xlog() in rtimer route to be sure it is executed by the same the same PID that throws errors?
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/406#issuecomment-180302932
Made another test with mode=0, xlog ends up on the `slow timer` process, not `timer`: ``` Process:: ID=9 PID=13311 Type=slow timer Feb 5 12:34:22 /usr/sbin/kamailio[13311]: ERROR: <script>: rtimer sql Feb 5 12:34:22 /usr/sbin/kamailio[13311]: DEBUG: db_cluster [dbcl_api.c:368]: db_cluster_raw_query(): executing db cluster raw query command Feb 5 12:34:22 /usr/sbin/kamailio[13311]: DEBUG: db_cluster [dbcl_api.c:369]: db_cluster_raw_query(): serial operation - cluster [k1] (9/0) ``` whereas the SSL error is seen on: ``` Process:: ID=10 PID=13312 Type=timer Feb 5 12:32:42 /usr/sbin/kamailio[13312]: ERROR: db_mysql [km_dbase.c:124]: db_mysql_submit_query(): driver error on query: SSL connection error: socket layer receive error (2026) Feb 5 12:32:42 /usr/sbin/kamailio[13312]: ERROR: <core> [db_query.c:181]: db_do_raw_query(): error while submitting query Feb 5 12:32:42 /usr/sbin/kamailio[13312]: DEBUG: db_cluster [dbcl_api.c:369]: db_cluster_raw_query(): serial operation - failre on cluster [k1] (9/0) Feb 5 12:32:42 /usr/sbin/kamailio[13312]: DEBUG: db_cluster [dbcl_api.c:369]: db_cluster_raw_query(): serial operation - cluster [k1] (1/0) ```
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/406#issuecomment-180310874
Hold on, Daniel. Your comment on timers and retransmission-timeout got me thinking, and we try to do some smart logic in our conf to re-route calls to different destinations using "t_set_fr()". If I remove this logic I'm no longer seeing these SSL errors from the timer-process.
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/406#issuecomment-180359978
From the web, maybe gives some good hints:
* http://maxrohde.com/2015/04/26/mysql-error-2026-hy000-ssl-connection-error-s...
Can you figure out how long it is in between the last successful query and the start of getting those errors?
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/406#issuecomment-180473816
I too have some time ago noticed db over ssl timeouts that happened in a timer process. I had two timer processes, one adding records to db and another that removed expired ones.
-- Juha
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/406#issuecomment-180494398
@juha-h but did they reconnect automatically?
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/406#issuecomment-180510356
Daniel-Constantin Mierla writes:
@juha-h but did they reconnect automatically?
I don't remember that, but the problem occurred only when SSL was used and the db was not unreachable at the time when errors occurred.
-- Juha
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/406#issuecomment-180612077
@miconda here's a log of Kamailio starting up vs. when the error occurs for three different timer processes (restarts): ``` Feb 5 12:36:36 /usr/sbin/kamailio[19627]: DEBUG: db_cluster [dbcl_api.c:269]: db_cluster_init(): initializing with cluster [cluster://k2] Feb 5 12:36:36 /usr/sbin/kamailio[19627]: DEBUG: db_cluster [dbcl_api.c:269]: db_cluster_init(): initializing with cluster [cluster://k1] Feb 5 12:37:42 /usr/sbin/kamailio[19627]: DEBUG: db_cluster [dbcl_api.c:483]: db_cluster_use_table(): use table (missed_calls) - cluster [k2] Feb 5 12:37:42 /usr/sbin/kamailio[19627]: DEBUG: db_cluster [dbcl_api.c:492]: db_cluster_use_table(): set read table (missed_calls) - cluster [k2] (9/0) Feb 5 12:37:42 /usr/sbin/kamailio[19627]: DEBUG: db_cluster [dbcl_api.c:502]: db_cluster_use_table(): set write table (missed_calls) - cluster [k2] (9/0) Feb 5 12:37:42 /usr/sbin/kamailio[19627]: DEBUG: db_cluster [dbcl_api.c:492]: db_cluster_use_table(): set read table (missed_calls) - cluster [k2] (1/0) Feb 5 12:37:42 /usr/sbin/kamailio[19627]: DEBUG: db_cluster [dbcl_api.c:502]: db_cluster_use_table(): set write table (missed_calls) - cluster [k2] (1/0) Feb 5 12:37:42 /usr/sbin/kamailio[19627]: DEBUG: db_cluster [dbcl_api.c:378]: db_cluster_insert(): executing db cluster insert command Feb 5 12:37:42 /usr/sbin/kamailio[19627]: DEBUG: db_cluster [dbcl_api.c:379]: db_cluster_insert(): serial operation - cluster [k2] (9/0) Feb 5 12:37:42 /usr/sbin/kamailio[19627]: DEBUG: db_cluster [dbcl_api.c:368]: db_cluster_raw_query(): executing db cluster raw query command Feb 5 12:37:42 /usr/sbin/kamailio[19627]: DEBUG: db_cluster [dbcl_api.c:369]: db_cluster_raw_query(): serial operation - cluster [k1] (9/0) Feb 5 12:37:42 /usr/sbin/kamailio[19627]: WARNING: db_mysql [km_dbase.c:84]: db_mysql_submit_query(): driver error on ping: Lost connection to MySQL server during query Feb 5 12:37:42 /usr/sbin/kamailio[19627]: ERROR: db_mysql [km_dbase.c:124]: db_mysql_submit_query(): driver error on query: SSL connection error: socket layer receive error (2026) Feb 5 12:37:42 /usr/sbin/kamailio[19627]: DEBUG: db_cluster [dbcl_api.c:369]: db_cluster_raw_query(): serial operation - failre on cluster [k1] (9/0) Feb 5 12:37:42 /usr/sbin/kamailio[19627]: DEBUG: db_cluster [dbcl_api.c:369]: db_cluster_raw_query(): serial operation - cluster [k1] (1/0)
Feb 5 12:31:42 /usr/sbin/kamailio[13312]: DEBUG: db_cluster [dbcl_api.c:269]: db_cluster_init(): initializing with cluster [cluster://k1] Feb 5 12:31:42 /usr/sbin/kamailio[13312]: DEBUG: db_cluster [dbcl_api.c:269]: db_cluster_init(): initializing with cluster [cluster://k2] Feb 5 12:32:42 /usr/sbin/kamailio[13312]: DEBUG: db_cluster [dbcl_api.c:483]: db_cluster_use_table(): use table (missed_calls) - cluster [k2] Feb 5 12:32:42 /usr/sbin/kamailio[13312]: DEBUG: db_cluster [dbcl_api.c:492]: db_cluster_use_table(): set read table (missed_calls) - cluster [k2] (9/0) Feb 5 12:32:42 /usr/sbin/kamailio[13312]: DEBUG: db_cluster [dbcl_api.c:502]: db_cluster_use_table(): set write table (missed_calls) - cluster [k2] (9/0) Feb 5 12:32:42 /usr/sbin/kamailio[13312]: DEBUG: db_cluster [dbcl_api.c:492]: db_cluster_use_table(): set read table (missed_calls) - cluster [k2] (1/0) Feb 5 12:32:42 /usr/sbin/kamailio[13312]: DEBUG: db_cluster [dbcl_api.c:502]: db_cluster_use_table(): set write table (missed_calls) - cluster [k2] (1/0) Feb 5 12:32:42 /usr/sbin/kamailio[13312]: DEBUG: db_cluster [dbcl_api.c:378]: db_cluster_insert(): executing db cluster insert command Feb 5 12:32:42 /usr/sbin/kamailio[13312]: DEBUG: db_cluster [dbcl_api.c:379]: db_cluster_insert(): serial operation - cluster [k2] (9/0) Feb 5 12:32:42 /usr/sbin/kamailio[13312]: DEBUG: db_cluster [dbcl_api.c:368]: db_cluster_raw_query(): executing db cluster raw query command Feb 5 12:32:42 /usr/sbin/kamailio[13312]: DEBUG: db_cluster [dbcl_api.c:369]: db_cluster_raw_query(): serial operation - cluster [k1] (9/0) Feb 5 12:32:42 /usr/sbin/kamailio[13312]: WARNING: db_mysql [km_dbase.c:84]: db_mysql_submit_query(): driver error on ping: Lost connection to MySQL server during query Feb 5 12:32:42 /usr/sbin/kamailio[13312]: ERROR: db_mysql [km_dbase.c:124]: db_mysql_submit_query(): driver error on query: SSL connection error: socket layer receive error (2026) Feb 5 12:32:42 /usr/sbin/kamailio[13312]: DEBUG: db_cluster [dbcl_api.c:369]: db_cluster_raw_query(): serial operation - failre on cluster [k1] (9/0) Feb 5 12:32:42 /usr/sbin/kamailio[13312]: DEBUG: db_cluster [dbcl_api.c:369]: db_cluster_raw_query(): serial operation - cluster [k1] (1/0)
Feb 5 11:39:03 /usr/sbin/kamailio[6663]: DEBUG: db_cluster [dbcl_api.c:269]: db_cluster_init(): initializing with cluster [cluster://k2] Feb 5 11:39:03 /usr/sbin/kamailio[6663]: DEBUG: db_cluster [dbcl_api.c:269]: db_cluster_init(): initializing with cluster [cluster://k1] Feb 5 11:40:14 /usr/sbin/kamailio[6663]: DEBUG: db_cluster [dbcl_api.c:483]: db_cluster_use_table(): use table (missed_calls) - cluster [k2] Feb 5 11:40:14 /usr/sbin/kamailio[6663]: DEBUG: db_cluster [dbcl_api.c:492]: db_cluster_use_table(): set read table (missed_calls) - cluster [k2] (9/0) Feb 5 11:40:14 /usr/sbin/kamailio[6663]: DEBUG: db_cluster [dbcl_api.c:502]: db_cluster_use_table(): set write table (missed_calls) - cluster [k2] (9/0) Feb 5 11:40:14 /usr/sbin/kamailio[6663]: DEBUG: db_cluster [dbcl_api.c:492]: db_cluster_use_table(): set read table (missed_calls) - cluster [k2] (1/0) Feb 5 11:40:14 /usr/sbin/kamailio[6663]: DEBUG: db_cluster [dbcl_api.c:502]: db_cluster_use_table(): set write table (missed_calls) - cluster [k2] (1/0) Feb 5 11:40:14 /usr/sbin/kamailio[6663]: DEBUG: db_cluster [dbcl_api.c:378]: db_cluster_insert(): executing db cluster insert command Feb 5 11:40:14 /usr/sbin/kamailio[6663]: DEBUG: db_cluster [dbcl_api.c:379]: db_cluster_insert(): serial operation - cluster [k2] (9/0) Feb 5 11:40:14 /usr/sbin/kamailio[6663]: DEBUG: db_cluster [dbcl_api.c:483]: db_cluster_use_table(): use table (acc) - cluster [k2] Feb 5 11:40:14 /usr/sbin/kamailio[6663]: DEBUG: db_cluster [dbcl_api.c:492]: db_cluster_use_table(): set read table (acc) - cluster [k2] (9/0) Feb 5 11:40:14 /usr/sbin/kamailio[6663]: DEBUG: db_cluster [dbcl_api.c:502]: db_cluster_use_table(): set write table (acc) - cluster [k2] (9/0) Feb 5 11:40:14 /usr/sbin/kamailio[6663]: DEBUG: db_cluster [dbcl_api.c:492]: db_cluster_use_table(): set read table (acc) - cluster [k2] (1/0) Feb 5 11:40:14 /usr/sbin/kamailio[6663]: DEBUG: db_cluster [dbcl_api.c:502]: db_cluster_use_table(): set write table (acc) - cluster [k2] (1/0) Feb 5 11:40:14 /usr/sbin/kamailio[6663]: DEBUG: db_cluster [dbcl_api.c:378]: db_cluster_insert(): executing db cluster insert command Feb 5 11:40:14 /usr/sbin/kamailio[6663]: DEBUG: db_cluster [dbcl_api.c:379]: db_cluster_insert(): serial operation - cluster [k2] (9/0) Feb 5 11:40:28 /usr/sbin/kamailio[6663]: DEBUG: db_cluster [dbcl_api.c:483]: db_cluster_use_table(): use table (missed_calls) - cluster [k2] Feb 5 11:40:28 /usr/sbin/kamailio[6663]: DEBUG: db_cluster [dbcl_api.c:492]: db_cluster_use_table(): set read table (missed_calls) - cluster [k2] (9/0) Feb 5 11:40:28 /usr/sbin/kamailio[6663]: DEBUG: db_cluster [dbcl_api.c:502]: db_cluster_use_table(): set write table (missed_calls) - cluster [k2] (9/0) Feb 5 11:40:28 /usr/sbin/kamailio[6663]: DEBUG: db_cluster [dbcl_api.c:492]: db_cluster_use_table(): set read table (missed_calls) - cluster [k2] (1/0) Feb 5 11:40:28 /usr/sbin/kamailio[6663]: DEBUG: db_cluster [dbcl_api.c:502]: db_cluster_use_table(): set write table (missed_calls) - cluster [k2] (1/0) Feb 5 11:40:28 /usr/sbin/kamailio[6663]: DEBUG: db_cluster [dbcl_api.c:378]: db_cluster_insert(): executing db cluster insert command Feb 5 11:40:28 /usr/sbin/kamailio[6663]: DEBUG: db_cluster [dbcl_api.c:379]: db_cluster_insert(): serial operation - cluster [k2] (9/0) Feb 5 11:40:28 /usr/sbin/kamailio[6663]: DEBUG: db_cluster [dbcl_api.c:368]: db_cluster_raw_query(): executing db cluster raw query command Feb 5 11:40:28 /usr/sbin/kamailio[6663]: DEBUG: db_cluster [dbcl_api.c:369]: db_cluster_raw_query(): serial operation - cluster [k1] (9/0) Feb 5 11:40:28 /usr/sbin/kamailio[6663]: WARNING: db_mysql [km_dbase.c:84]: db_mysql_submit_query(): driver error on ping: Lost connection to MySQL server during query Feb 5 11:40:28 /usr/sbin/kamailio[6663]: ERROR: db_mysql [km_dbase.c:124]: db_mysql_submit_query(): driver error on query: SSL connection error: socket layer receive error (2026) Feb 5 11:40:28 /usr/sbin/kamailio[6663]: DEBUG: db_cluster [dbcl_api.c:369]: db_cluster_raw_query(): serial operation - failre on cluster [k1] (9/0) Feb 5 11:40:28 /usr/sbin/kamailio[6663]: DEBUG: db_cluster [dbcl_api.c:369]: db_cluster_raw_query(): serial operation - cluster [k1] (1/0) ```
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/406#issuecomment-181811220
Instead of trying to use the re-connect built into the mysql_ping() command, would it be possible to do the mysql_real_connect again instead?
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/406#issuecomment-182353836
Everything should be possible, it one of the main benefits of open source ...
Can you change it in the source code and give it a try? If it works, we can add that in the repository, eventually with a config option.
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/406#issuecomment-182369633
Ok, I'll give that a try.
Just a short question on the log above, shouldn't there be a timeout/retry interval happening for failed queries? Looks like when the query is performed it fails immediately but I might be reading it wrong.
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/406#issuecomment-182386931
Yes, there should be a timeout, see the parameters for db_mysql module. But if the connection is down, I expect the libmysqlclient will not wait for timeout, just fails immediately. Time out can be tested when doing a query that takes too long.
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/406#issuecomment-182400827
I've been trying to search for a way to build db_mysql.so in a way that libmysqlclient will output debug information? Not sure if it will help though. Do you have any experience?
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/406#issuecomment-182408491
No, I haven't built libmysqlclient myself, used the packaged version in the OS.
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/406#issuecomment-183069130
Please see attached screenshots for tcpdump of the timer-process when the connections are dropped. `out.pcap` is from the mysql-acc-thread and `out2.pcap` is from a mysql-thread for selecting data in the kamailio.cfg.
In both cases it looks like the client is dropping the connection, even though the server is in the middle of working with the request. These are both decoded SSL connections.
 
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/406#issuecomment-184179011
Ok, so I believe I may have found the issue, or rather I think I know what's happening, just not where it all goes wrong.
In my kamailio config I have logic for some users to call through a list of numbers to find a number where they are able to take the call, pretty much like a hunt-group, trying the numbers one by one.
When none of the numbers are answered and one of these calls time out and Request Timeout occurs, it looks like the `timer` process would like to write a row for each call leg/branch to the `missed_calls` table and here's where the issue seems to occur (I've added some debug output to be able to trace back what's happening and 54110017 below is the mysql thread ID): ``` Feb 16 21:05:24 host /usr/sbin/kamailio[2731]: WARNING: db_mysql [km_dbase.c:80]: db_mysql_submit_query(): 54110017 entering db_mysql_submit_query Feb 16 21:05:24 host /usr/sbin/kamailio[2731]: WARNING: db_mysql [km_dbase.c:89]: db_mysql_submit_query(): 54110017 mysql ping done Feb 16 21:05:24 host /usr/sbin/kamailio[2731]: WARNING: db_mysql [km_dbase.c:101]: db_mysql_submit_query(): 54110017 submit_query(): insert into `missed_calls` (branch 1 data) Feb 16 21:05:24 host /usr/sbin/kamailio[2731]: WARNING: db_mysql [km_dbase.c:116]: db_mysql_submit_query(): 54110017 db_mysql_submit_query returned 0 Feb 16 21:05:24 host /usr/sbin/kamailio[2731]: WARNING: db_mysql [km_dbase.c:80]: db_mysql_submit_query(): 54110017 entering db_mysql_submit_query Feb 16 21:05:24 host /usr/sbin/kamailio[2731]: WARNING: db_mysql [km_dbase.c:101]: db_mysql_submit_query(): 54110017 submit_query(): insert into `missed_calls` (branch 2 data) Feb 16 21:05:24 host /usr/sbin/kamailio[2731]: ERROR: db_mysql [km_dbase.c:128]: db_mysql_submit_query(): 54110017 driver error on query: SSL connection error: socket layer receive error (2026) Feb 16 21:05:24 host /usr/sbin/kamailio[2731]: ERROR: <core> [db_query.c:235]: db_do_insert_cmd(): error while submitting query ```
I'm guessing that the two db_mysql_submit_query() calls run at almost the same time and that the first insert has not completed before the second insert wants to run, at which point something similar to what's described here occurs: http://dev.mysql.com/doc/refman/5.6/en/c-api-multiple-queries.html
This is only observed when the connection is running over SSL, so there's probably something related there.
OR.. my config is screwed up and I'm not working with branches in the correct way :)
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/406#issuecomment-184863893
After various adventures around this, I finally tried to upgrade libmysqlclient (or Connector/C) but that didn't do the work. Then I tried switching compiling libmysqclient with OpenSSL instead of the bundled yaSSL, and now it works just fine, no more SSL errors!
So, many hours down the drain, but not an issue in Kamailio. Closing this issue. Thanks all for your help!
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/406#issuecomment-185743396
Closed #406.
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/406#event-555143728
-
Daniel-Constantin Mierla -
juha-h
-
Olle E. Johansson
-
Tobias Lindgren