[OpenSER-Devel] db_mysql commands out of sync, presence

[Anca Vamanu]

hi,

It is strange that this error appears when a 'delete' is being executed. 
Not expected from the description of the error.
What version of libmysql-client are you using?

regards,
Anca

Juha Heinanen wrote:
> anca,
>
> this morning i noticed that during the night "out of sync" error had
> reappeared.  the first error was this:
>
> Mar 30 23:07:10 tutpro /usr/sbin/openser[11733]: ERROR:db_mysql:db_mysql_submit_query: driver error on query: Commands out of sync; you can't run this command now 
> Mar 30 23:07:10 tutpro /usr/sbin/openser[11733]: ERROR:core:db_do_delete: error while submitting query 
> Mar 30 23:07:10 tutpro /usr/sbin/openser[11733]: ERROR:pua:db_update: while deleting from db table pua 
>
> and after that it kept repeating itself until now.  i increased debug
> level and got the following around the error.  i don't know if it shows
> info by the new debug messages.
>
> -- juha
>
> Mar 31 07:47:46 test /usr/sbin/openser[11734]: DBG:core:db_new_result: allocate 28 bytes for result set at 0x81f1718 
> Mar 31 07:47:46 test /usr/sbin/openser[11734]: DBG:db_mysql:db_mysql_get_columns: 5 columns returned from the query 
> Mar 31 07:47:46 test /usr/sbin/openser[11734]: DBG:core:db_allocate_columns: allocate 20 bytes for result names at 0x81f0ee0 
> Mar 31 07:47:46 test /usr/sbin/openser[11734]: DBG:core:db_allocate_columns: allocate 20 bytes for result types at 0x81f0ec0 
> Mar 31 07:47:46 test /usr/sbin/openser[11734]: DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[0] at 0x81f0b70 
> Mar 31 07:47:46 test /usr/sbin/openser[11734]: DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81f0b70)[0]=[received] 
> Mar 31 07:47:46 test /usr/sbin/openser[11734]: DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[1] at 0x81f0b90 
> Mar 31 07:47:46 test /usr/sbin/openser[11734]: DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81f0b90)[1]=[contact] 
> Mar 31 07:47:46 test /usr/sbin/openser[11734]: DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[2] at 0x81f0f20 
> Mar 31 07:47:46 test /usr/sbin/openser[11734]: DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81f0f20)[2]=[socket] 
> Mar 31 07:47:46 test /usr/sbin/openser[11734]: DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[3] at 0x81f0f10 
> Mar 31 07:47:46 test /usr/sbin/openser[11734]: DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81f0f10)[3]=[cflags] 
> Mar 31 07:47:46 test /usr/sbin/openser[11734]: DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[4] at 0x81f0f00 
> Mar 31 07:47:46 test /usr/sbin/openser[11734]: DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81f0f00)[4]=[path] 
> Mar 31 07:47:46 test /usr/sbin/openser[11734]: DBG:core:db_free_columns: freeing 5 columns 
> Mar 31 07:47:46 test /usr/sbin/openser[11734]: DBG:core:db_free_columns: freeing RES_NAMES[0] at 0x81f0b70 
> Mar 31 07:47:46 test /usr/sbin/openser[11734]: DBG:core:db_free_columns: freeing RES_NAMES[1] at 0x81f0b90 
> Mar 31 07:47:46 test /usr/sbin/openser[11734]: DBG:core:db_free_columns: freeing RES_NAMES[2] at 0x81f0f20 
> Mar 31 07:47:46 test /usr/sbin/openser[11734]: DBG:core:db_free_columns: freeing RES_NAMES[3] at 0x81f0f10 
> Mar 31 07:47:46 test /usr/sbin/openser[11734]: DBG:core:db_free_columns: freeing RES_NAMES[4] at 0x81f0f00 
> Mar 31 07:47:46 test /usr/sbin/openser[11734]: DBG:core:db_free_columns: freeing result names at 0x81f0ee0 
> Mar 31 07:47:46 test /usr/sbin/openser[11734]: DBG:core:db_free_columns: freeing result types at 0x81f0ec0 
> Mar 31 07:47:46 test /usr/sbin/openser[11734]: DBG:core:db_free_rows: freeing 0 rows 
> Mar 31 07:47:46 test /usr/sbin/openser[11734]: DBG:core:db_free_result: freeing result set at 0x81f1718 
> Mar 31 07:47:47 test /usr/sbin/openser[11733]: DBG:pua:db_update: NO_UPDATEDB_FLAG 
> Mar 31 07:47:47 test /usr/sbin/openser[11733]: ERROR:db_mysql:db_mysql_submit_query: driver error on query: Commands out of sync; you can't run this command now 
> Mar 31 07:47:47 test /usr/sbin/openser[11733]: ERROR:core:db_do_delete: error while submitting query 
> Mar 31 07:47:47 test /usr/sbin/openser[11733]: ERROR:pua:db_update: while deleting from db table pua 
> Mar 31 07:47:47 test /usr/sbin/openser[11733]: DBG:pua:print_ua_pres: ^Ipres_uri= sip:jh at vm.test.com   len= 20 
> Mar 31 07:47:47 test /usr/sbin/openser[11733]: DBG:pua:print_ua_pres: ^Ietag= a.1206800939.2338.1.10 - len= 22 
> Mar 31 07:47:47 test /usr/sbin/openser[11733]: DBG:pua:print_ua_pres: ^Iid=  
> Mar 31 07:47:47 test /usr/sbin/openser[11733]: DBG:pua:print_ua_pres: ^Iexpires= 7704567 
> Mar 31 07:47:47 test /usr/sbin/openser[11733]: DBG:presence:printf_subs:  ^I[pres_uri]= sip:foo.bar at test.com ^I[to_user]= foo.bar^I[to_domain]= test.com ^I[w_user]= jh^I[w_domain]= test.com ^I[event]= presence ^I[status]= active ^I[expires]= 1206942027 ^I[callid]= lectmjubipnzkxk at fish.test.com^I[local_cseq]=1 ^I[to_tag]= 25.11737.1206938427.10^I[from_tag]= rahuw ^I[contact]= sip:jh at 192.98.100.3:5066;transport=tcp^I[record_route]=  
> Mar 31 07:47:47 test /usr/sbin/openser[11733]: DBG:presence:update_db_subs: INSERTDB_FLAG 
> Mar 31 07:47:47 test /usr/sbin/openser[11733]: ERROR:db_mysql:db_mysql_submit_query: driver error on query: Commands out of sync; you can't run this command now 
> Mar 31 07:47:47 test /usr/sbin/openser[11733]: ERROR:core:db_do_insert: error while submitting query 
> Mar 31 07:47:47 test /usr/sbin/openser[11733]: ERROR:presence:update_db_subs: unsuccessful sql insert 
> Mar 31 07:47:47 test /usr/sbin/openser[11733]: DBG:presence:msg_watchers_clean: cleaning pending subscriptions 
> Mar 31 07:47:47 test /usr/sbin/openser[11733]: ERROR:db_mysql:db_mysql_submit_query: driver error on query: Commands out of sync; you can't run this command now 
> Mar 31 07:47:47 test /usr/sbin/openser[11733]: ERROR:core:db_do_query: error while submitting query 
> Mar 31 07:47:47 test /usr/sbin/openser[11733]: ERROR:presence:msg_watchers_clean: querying database for expired messages 
> Mar 31 07:47:47 test /usr/sbin/openser[11733]: DBG:presence:msg_presentity_clean: cleaning expired presentity information 
> Mar 31 07:47:47 test /usr/sbin/openser[11733]: ERROR:db_mysql:db_mysql_submit_query: driver error on query: Commands out of sync; you can't run this command now 
> Mar 31 07:47:47 test /usr/sbin/openser[11733]: ERROR:core:db_do_query: error while submitting query 
> Mar 31 07:47:47 test /usr/sbin/openser[11733]: ERROR:presence:msg_presentity_clean: querying database for expired messages 
> Mar 31 07:47:47 test /usr/sbin/openser[11733]: DBG:msilo:m_clean_silo: cleaning stored messages - 36600 
> Mar 31 07:47:47 test /usr/sbin/openser[11733]: DBG:msilo:m_clean_silo: cleaning expired messages 
> Mar 31 07:47:47 test /usr/sbin/openser[11733]: ERROR:db_mysql:db_mysql_submit_query: driver error on query: Commands out of sync; you can't run this command now 
> Mar 31 07:47:47 test /usr/sbin/openser[11733]: ERROR:core:db_do_delete: error while submitting query 
> Mar 31 07:47:47 test /usr/sbin/openser[11733]: DBG:msilo:m_clean_silo: ERROR cleaning expired messages 
> Mar 31 07:47:47 test /usr/sbin/openser[11733]: ERROR:db_mysql:db_mysql_submit_query: driver error on query: Commands out of sync; you can't run this command now 
> Mar 31 07:47:47 test /usr/sbin/openser[11733]: ERROR:core:db_do_raw_query: error while submitting query 
> Mar 31 07:47:47 test /usr/sbin/openser[11733]: ERROR:usrloc:get_all_db_ucontacts: raw_query failed 
> Mar 31 07:47:47 test /usr/sbin/openser[11733]: ERROR:mediaproxy:pingClients: failed to fetch contacts 
> Mar 31 07:47:47 test /usr/sbin/openser[11733]: ERROR:db_mysql:db_mysql_submit_query: driver error on query: Commands out of sync; you can't run this command now 
> Mar 31 07:47:47 test /usr/sbin/openser[11733]: ERROR:core:db_do_delete: error while submitting query 
> Mar 31 07:47:47 test /usr/sbin/openser[11733]: ERROR:usrloc:db_timer_udomain: failed to delete from table location 
> Mar 31 07:47:47 test /usr/sbin/openser[11733]: ERROR:usrloc:timer: synchronizing cache failed 
> Mar 31 07:47:47 test /usr/sbin/openser[11734]: DBG:core:db_new_result: allocate 28 bytes for result set at 0x81f1718 
> Mar 31 07:47:47 test /usr/sbin/openser[11734]: DBG:db_mysql:db_mysql_get_columns: 5 columns returned from the query 
> Mar 31 07:47:47 test /usr/sbin/openser[11734]: DBG:core:db_allocate_columns: allocate 20 bytes for result names at 0x81f0ec0 
> Mar 31 07:47:47 test /usr/sbin/openser[11734]: DBG:core:db_allocate_columns: allocate 20 bytes for result types at 0x81f0ee0 
> Mar 31 07:47:47 test /usr/sbin/openser[11734]: DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[0] at 0x81f0f00 
> Mar 31 07:47:47 test /usr/sbin/openser[11734]: DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81f0f00)[0]=[received] 
> Mar 31 07:47:47 test /usr/sbin/openser[11734]: DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[1] at 0x81f0f10 
> Mar 31 07:47:47 test /usr/sbin/openser[11734]: DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81f0f10)[1]=[contact] 
> Mar 31 07:47:47 test /usr/sbin/openser[11734]: DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[2] at 0x81f0f20 
> Mar 31 07:47:47 test /usr/sbin/openser[11734]: DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81f0f20)[2]=[socket] 
> Mar 31 07:47:47 test /usr/sbin/openser[11734]: DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[3] at 0x81f0b90 
> Mar 31 07:47:47 test /usr/sbin/openser[11734]: DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81f0b90)[3]=[cflags] 
> Mar 31 07:47:47 test /usr/sbin/openser[11734]: DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[4] at 0x81f0b70 
> Mar 31 07:47:47 test /usr/sbin/openser[11734]: DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81f0b70)[4]=[path] 
> Mar 31 07:47:47 test /usr/sbin/openser[11734]: DBG:core:db_free_columns: freeing 5 columns 
> Mar 31 07:47:47 test /usr/sbin/openser[11734]: DBG:core:db_free_columns: freeing RES_NAMES[0] at 0x81f0f00 
> Mar 31 07:47:47 test /usr/sbin/openser[11734]: DBG:core:db_free_columns: freeing RES_NAMES[1] at 0x81f0f10 
> Mar 31 07:47:47 test /usr/sbin/openser[11734]: DBG:core:db_free_columns: freeing RES_NAMES[2] at 0x81f0f20 
> Mar 31 07:47:47 test /usr/sbin/openser[11734]: DBG:core:db_free_columns: freeing RES_NAMES[3] at 0x81f0b90 
>