[sr-dev] [kamailio] Database timeout over SSL? (#406)

Tobias Lindgren notifications at github.com
Fri Feb 5 10:15:18 CET 2016 

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
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.sip-router.org/pipermail/sr-dev/attachments/20160205/667199d7/attachment-0001.html>

More information about the sr-dev mailing list