20 Nov
2015
20 Nov
'15
4:11 p.m.
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
23 Nov
23 Nov
3:11 p.m.
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
3:27 p.m.
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
5:21 p.m.
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
5:32 p.m.
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
5:58 p.m.
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
6:22 p.m.
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
9 p.m.
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
9:31 p.m.
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
9:32 p.m.
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
24 Nov
24 Nov
1:48 p.m.
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
2:16 p.m.
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
26 Nov
26 Nov
9:49 a.m.
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…
---
Reply to this email directly or view it on GitHub:
https://github.com/kamailio/kamailio/issues/406#issuecomment-159849980
30 Nov
30 Nov
1:57 p.m.
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
7 Dec
7 Dec
10:27 p.m.
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
8 Dec
8 Dec
4:44 p.m.
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
9:20 p.m.
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
9:25 p.m.
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
10:54 p.m.
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
9 Dec
9 Dec
10:03 a.m.
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
14 Dec
14 Dec
10:26 a.m.
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
20 Jan
20 Jan
8:50 p.m.
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
24 Jan
24 Jan
9:50 p.m.
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
9:50 p.m.
Closed #406.
---
Reply to this email directly or view it on GitHub:
https://github.com/kamailio/kamailio/issues/406#event-524351563
29 Jan
29 Jan
1:46 p.m.
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
1 Feb
1 Feb
9:37 a.m.
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
4 Feb
4 Feb
1:47 p.m.
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
1:50 p.m.
@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
4:44 p.m.
Reopened #406.
---
Reply to this email directly or view it on GitHub:
https://github.com/kamailio/kamailio/issues/406#event-539348995
5 Feb
5 Feb
9:37 a.m.
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
10:15 a.m.
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
10:49 a.m.
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
10:54 a.m.
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
11:14 a.m.
There's a discussion here. Seems like "SELECT 1" is one way.
http://stackoverflow.com/questions/2546868/cheapest-way-to-to-determine-if-…
---
Reply to this email directly or view it on GitHub:
https://github.com/kamailio/kamailio/issues/406#issuecomment-180283755
11:19 a.m.
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
11:57 a.m.
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
12:14 p.m.
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
12:38 p.m.
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
2:36 p.m.
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
7:06 p.m.
From the web, maybe gives some good hints:
*
http://maxrohde.com/2015/04/26/mysql-error-2026-hy000-ssl-connection-error-…
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
7:45 p.m.
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
8:23 p.m.
@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
11:59 p.m.
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
9 Feb
9 Feb
11:45 a.m.
@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
10 Feb
10 Feb
1:39 p.m.
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
2:18 p.m.
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
2:58 p.m.
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
3:38 p.m.
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
3:58 p.m.
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
11 Feb
11 Feb
10:41 p.m.
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
15 Feb
15 Feb
12:51 p.m.
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
16 Feb
16 Feb
9:30 p.m.
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
18 Feb
18 Feb
3:22 p.m.
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
3:22 p.m.
Closed #406.
---
Reply to this email directly or view it on GitHub:
https://github.com/kamailio/kamailio/issues/406#event-555143728
2992
days inactive
3082
days old
53 comments
4 participants
participants (4)
-
Daniel-Constantin Mierla -
juha-h
-
Olle E. Johansson
-
Tobias Lindgren