[Spce-user] [km_dbase.c:122]

Crexpedio Support Team jesse at crexpedio.com
Fri Jun 12 21:21:44 EDT 2015





Thank you for the quick response.

This is a Amazon hosted server with 4Gb Ram, 8 Gb SSD HDD.


Normal usage of the server shows CPU under 5% and memory usage about 1.5Gb.




root at secure:/# df -h
Filesystem      Size  Used Avail Use% Mounted on
rootfs          7.8G  2.4G  5.1G  32% /
udev             10M     0   10M   0% /dev
tmpfs           377M  112K  376M   1% /run
/dev/xvda       7.8G  2.4G  5.1G  32% /
tmpfs           5.0M     0  5.0M   0% /run/lock
tmpfs           753M     0  753M   0% /run/shm

root at secure:/# iostat
Linux 3.16-0.bpo.3-amd64 (secure) 	06/12/2015 	_x86_64_	(1 CPU)

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
           1.94    0.00    3.08   90.79    4.01    0.18

Device:            tps    kB_read/s    kB_wrtn/s    kB_read    kB_wrtn
xvda             23.75         1.94       147.66     342009   26071492



I’ve read through the lists and found some that you have assisted on, but they all seem to be fixes that should not be present in this release. Server appears to be running smoothly and SQL is running as it should. There are also some duplicate errors in the debug below that make me think that there is a data issue:  ERROR: db_mysql [km_dbase.c:122]: db_mysql_submit_query(): driver error on query: Duplicate entry 'uloc-55786194-11a7-b02' for key ‘ruid_idx'

I have googled for all these errors and have come up inconclusive. I contacted SIPWISE directly for a 10 ticket (incident) package to see if these can get resolved. I’m just very concerned as this is basically a fresh install with 20 accounts and I’m having lots of problems.

/var/log/mysql/mysqld.err
Shows no relevant information regarding problems

/var/log/mysql.slow-queries.log (this shows continuously throughout the log file)
# Time: 150612  1:39:04
# User at Host: kamailio[kamailio] @ localhost []
# Query_time: 6.225502  Lock_time: 0.000034 Rows_sent: 0  Rows_examined: 1
SET timestamp=1434094744;
delete from location where username='88340757' AND contact='sip:88340757 at 192.168.4.112:37144;transport=TLS;ob' <sip:88340757 at 192.168.4.112:37144;transport=TLS;ob'> AND domain='secure.crexpedio.com <http://secure.crexpedio.com/>';
# Time: 150612  1:42:00
# User at Host: kamailio[kamailio] @ localhost []
# Query_time: 6.034056  Lock_time: 0.000061 Rows_sent: 0  Rows_examined: 2
SET timestamp=1434094920;
update location set callid='C0Adq.nYdqcare67Gi4O6JHWHPx.AtJ1',path='<sip:lb at 127.0.0.1;lr;socket=sip:10.237.162.56:5061 <sip:lb at 127.0.0.1;lr;socket=sip:10.237.162.56:5061>>',expires='2015-06-12 01:56:54',q=-1.00     ,cseq=33483,flags=0,cflags=0,user_agent='Bria Stretto Android 3.2.1',received=NULL,socket='udp:127.0.0.1:5062',methods=8159,last_modified='2015-06-12 01:41:54',ruid='uloc-55786194-11ad-d22',instance=NULL,reg_id=0,contact='sip:5010100101 at 201.191.199.69:41658;transport=TLS;ob' <sip:5010100101 at 201.191.199.69:41658;transport=TLS;ob'> where username='5010100101' AND contact='sip:5010100101 at 201.191.199.69:41658;transport=TLS;ob' <sip:5010100101 at 201.191.199.69:41658;transport=TLS;ob'> AND domain='secure-voip10.ncryptmedia.com <http://secure-voip10.ncryptmedia.com/>';
# Time: 150612  1:42:12
# User at Host: kamailio[kamailio] @ localhost []
# Query_time: 5.919136  Lock_time: 0.000054 Rows_sent: 0  Rows_examined: 0
SET timestamp=1434094932;
insert into location (username,contact,expires,q,callid,cseq,flags,cflags,user_agent,received,path,socket,methods,last_modified,ruid,instance,reg_id,domain ) values ('5010100101','sip:5010100101 at 10.133.168.146:41658;transport=TLS;ob','2015-06-12 <sip:5010100101 at 10.133.168.146:41658;transport=TLS;ob','2015-06-12> 01:57:07',-1.00     ,'AsCI4bAHub-O2slCsuWLP003SWsVFiJz',36751,0,192,'Bria Stretto Android 3.2.1','sip:201.191.199.69:41658;transport=tls' <sip:201.191.199.69:41658;transport=tls'>,'<sip:lb at 127.0.0.1;lr;received=sip:201.191.199.69:41658%3Btransport%3Dtls;socket=sip:10.237.162.56:5061 <sip:lb at 127.0.0.1;lr;received=sip:201.191.199.69:41658%3Btransport%3Dtls;socket=sip:10.237.162.56:5061>>','udp:127.0.0.1:5062',8159,'2015-06-12 01:42:07','uloc-55786194-11b3-162','<urn:uuid:bb051b37-84a6-3e06-986a-9d895ee4dea7>',1,'secure-voip10.ncryptmedia.com <http://secure-voip10.ncryptmedia.com/>');
# Time: 150612  1:42:25
# User at Host: kamailio[kamailio] @ localhost []
# Query_time: 6.512000  Lock_time: 0.000055 Rows_sent: 0  Rows_examined: 6
SET timestamp=1434094945;
update location set expires='2015-06-12 01:57:19',q=-1.00     ,cseq=48717,flags=0,cflags=192,user_agent='Bria Stretto Android 3.2.1',received='sip:201.191.199.69:41658;transport=tls',path='<sip:lb at 127.0.0.1;lr;received=sip:201.191.199.69:41658%3Btransport%3Dtls;socket=sip:10.237.162.56:5061>',socket='udp:127.0.0.1:5062',methods=8159,last_modified='2015-06-12 <sip:201.191.199.69:41658;transport=tls',path='<sip:lb at 127.0.0.1;lr;received=sip:201.191.199.69:41658%3Btransport%3Dtls;socket=sip:10.237.162.56:5061>',socket='udp:127.0.0.1:5062',methods=8159,last_modified='2015-06-12> 01:42:19',callid='MqV7TKeYQ77X4VTulYWoMGQApIoaJ2A5',contact='sip:5010100101 at 10.133.168.146:41658;transport=TLS;ob' <sip:5010100101 at 10.133.168.146:41658;transport=TLS;ob'> where username='5010100101' AND instance='<urn:uuid:bb051b37-84a6-3e06-986a-9d895ee4dea7>' AND reg_id=1 AND domain='secure-voip10.ncryptmedia.com <http://secure-voip10.ncryptmedia.com/>';




> On Jun 12, 2015, at 10:35 AM, Daniel Grotti <dgrotti at sipwise.com <mailto:dgrotti at sipwise.com>> wrote:
> 
> Hello guys,
> well I saw your message in the mailing list and also saw a couple of asnwer there.
> Actually is not so easy to say what can cause this problem.
> The issue is the DB disconnection:
> 
> Jun 11 21:02:26 secure proxy[4525]: ERROR: db_mysql [km_dbase.c:122]: db_mysql_submit_query(): driver error on query: Lost connection to MySQL server during query
> 
> 
> All the suggestion you got already are good to check
> I would check mysql logs in /var/log/mysql and also:
> 
> - what kind of HDD/RAID does that machine have ? 
> - Do you see high %wa percentage (IO wait) in 'top' ? 
> - What is the disk utilization reported in 'iostat -dx1' during that ?
> - is it happening only to this customer ?
> 
> It looks related to the system resources though.
> I would start to dig in this direction.
> 
> 
> Daniel
> 
> 
> From: "Crexpedio Support Team" <jesse at crexpedio.com <mailto:jesse at crexpedio.com>>
> To: "Daniel Grotti" <dgrotti at sipwise.com <mailto:dgrotti at sipwise.com>>
> Sent: Friday, June 12, 2015 6:16:30 PM
> Subject: [km_dbase.c:122]
> 
> Daniel,
> 
> I’m sorry to write to you directly but I was hoping you had a minute to look over this problem. I am struggling with this platform which is already in a production stage with 20 customers.
> 
> 
> I’ve had some issues which I believe are all related to a database issue but haven’t found a fix. Server is installed following documentation and config files have not been manually edited.
> 
> For example:
> - subscriber gets failed registration multiple times prior to extension logging in.
> - no data in Call Distribution report on GUI
> - CDR’s are empty
> 
> Enviornment
> mr3.8.1-1433635162
> 
> Logs from Kamailio-proxy.log (subscriber number, domain and IP are bogus but logs are real)
> 
> Jun 11 21:02:20 secure proxy[4537]: NOTICE: <script>: New request on proxy - M=REGISTER R=sip:secure.domain.com F=sip:88888888 at secure.domain.com <mailto:88888888 at secure.domain.com> T=sip:88888888 at secure.domain.com <mailto:88888888 at secure.domain.com> IP=200.200.200.200:39999 (127.0.0.1:5060) ID=w1vwnvtiLSC4oMtd3cb0NUZN2CrhqcWO
> Jun 11 21:02:20 secure proxy[4537]: NOTICE: <script>: Authentication failed, no credentials - R=sip:secure.domain.com ID=w1vwnvtiLSC4oMtd3cb0NUZN2CrhqcWO
> Jun 11 21:02:20 secure proxy[4525]: NOTICE: <script>: New request on proxy - M=REGISTER R=sip:secure.domain.com F=sip:88888888 at secure.domain.com <mailto:88888888 at secure.domain.com> T=sip:88888888 at secure.domain.com <mailto:88888888 at secure.domain.com> IP=200.200.200.200:39999 (127.0.0.1:5060) ID=w1vwnvtiLSC4oMtd3cb0NUZN2CrhqcWO
> Jun 11 21:02:26 secure proxy[4525]: ERROR: db_mysql [km_dbase.c:122]: db_mysql_submit_query(): driver error on query: Lost connection to MySQL server during query
> Jun 11 21:02:26 secure proxy[4525]: ERROR: <core> [db_query.c:235]: db_do_insert_cmd(): error while submitting query
> Jun 11 21:02:26 secure proxy[4525]: ERROR: usrloc [ucontact.c:629]: db_insert_ucontact(): inserting contact in db failed
> Jun 11 21:02:26 secure proxy[4525]: ERROR: usrloc [urecord.c:548]: insert_ucontact(): failed to insert in database
> Jun 11 21:02:26 secure proxy[4525]: ERROR: registrar [save.c:521]: insert_contacts(): failed to insert contact
> Jun 11 21:02:31 secure proxy[4531]: NOTICE: <script>: New request on proxy - M=REGISTER R=sip:secure.domain.com F=sip:88888888 at secure.domain.com <mailto:88888888 at secure.domain.com> T=sip:88888888 at secure.domain.com <mailto:88888888 at secure.domain.com> IP=200.200.200.200:39999 (127.0.0.1:5060) ID=FeMkULbvDUDm6B29o92VtjpCpAuD.UXq
> Jun 11 21:02:31 secure proxy[4531]: NOTICE: <script>: Authentication failed, no credentials - R=sip:secure.domain.com ID=FeMkULbvDUDm6B29o92VtjpCpAuD.UXq
> Jun 11 21:02:31 secure proxy[4534]: NOTICE: <script>: New request on proxy - M=REGISTER R=sip:secure.domain.com F=sip:88888888 at secure.domain.com <mailto:88888888 at secure.domain.com> T=sip:88888888 at secure.domain.com <mailto:88888888 at secure.domain.com> IP=200.200.200.200:39999 (127.0.0.1:5060) ID=FeMkULbvDUDm6B29o92VtjpCpAuD.UXq
> Jun 11 21:02:37 secure proxy[4534]: ERROR: db_mysql [km_dbase.c:122]: db_mysql_submit_query(): driver error on query: Lost connection to MySQL server during query
> Jun 11 21:02:37 secure proxy[4534]: ERROR: <core> [db_query.c:235]: db_do_insert_cmd(): error while submitting query
> Jun 11 21:02:37 secure proxy[4534]: ERROR: usrloc [ucontact.c:629]: db_insert_ucontact(): inserting contact in db failed
> Jun 11 21:02:37 secure proxy[4534]: ERROR: usrloc [urecord.c:548]: insert_ucontact(): failed to insert in database
> Jun 11 21:02:37 secure proxy[4534]: ERROR: registrar [save.c:521]: insert_contacts(): failed to insert contact
> Jun 11 21:02:44 secure proxy[4520]: NOTICE: <script>: New request on proxy - M=REGISTER R=sip:secure.domain.com F=sip:88888888 at secure.domain.com <mailto:88888888 at secure.domain.com> T=sip:88888888 at secure.domain.com <mailto:88888888 at secure.domain.com> IP=200.200.200.200:39999 (127.0.0.1:5060) ID=eBGfI1JFE.oUd.vPpswiXsv8KEtxnlpn
> Jun 11 21:02:44 secure proxy[4520]: NOTICE: <script>: Authentication failed, no credentials - R=sip:secure.domain.com ID=eBGfI1JFE.oUd.vPpswiXsv8KEtxnlpn
> Jun 11 21:02:44 secure proxy[4537]: NOTICE: <script>: New request on proxy - M=REGISTER R=sip:secure.domain.com F=sip:88888888 at secure.domain.com <mailto:88888888 at secure.domain.com> T=sip:88888888 at secure.domain.com <mailto:88888888 at secure.domain.com> IP=200.200.200.200:39999 (127.0.0.1:5060) ID=eBGfI1JFE.oUd.vPpswiXsv8KEtxnlpn
> Jun 11 21:02:45 secure proxy[4537]: NOTICE: <script>: Contacts successfully saved, expires in 900s - R=sip:secure.domain.com ID=eBGfI1JFE.oUd.vPpswiXsv8KEtxnlpn
> Jun 11 21:02:45 secure proxy[4519]: NOTICE: <script>: New request on proxy - M=REGISTER R=sip:secure.domain.com F=sip:88888888 at secure.domain.com <mailto:88888888 at secure.domain.com> T=sip:88888888 at secure.domain.com <mailto:88888888 at secure.domain.com> IP=200.200.200.200:39999 (127.0.0.1:5060) ID=eBGfI1JFE.oUd.vPpswiXsv8KEtxnlpn
> Jun 11 21:02:45 secure proxy[4525]: NOTICE: <script>: New request on proxy - M=REGISTER R=sip:secure.domain.com F=sip:88888888 at secure.domain.com <mailto:88888888 at secure.domain.com> T=sip:88888888 at secure.domain.com <mailto:88888888 at secure.domain.com> IP=200.200.200.200:39999 (127.0.0.1:5060) ID=b.Ibsie7kDB0pcL20jjqvTJDLVqpbLgg
> Jun 11 21:02:45 secure proxy[4525]: NOTICE: <script>: Authentication failed, no credentials - R=sip:secure.domain.com ID=b.Ibsie7kDB0pcL20jjqvTJDLVqpbLgg
> Jun 11 21:02:45 secure proxy[4522]: NOTICE: <script>: New request on proxy - M=REGISTER R=sip:secure.domain.com F=sip:88888888 at secure.domain.com <mailto:88888888 at secure.domain.com> T=sip:88888888 at secure.domain.com <mailto:88888888 at secure.domain.com> IP=200.200.200.200:39999 (127.0.0.1:5060) ID=b.Ibsie7kDB0pcL20jjqvTJDLVqpbLgg
> Jun 11 21:02:48 secure proxy[4519]: NOTICE: <script>: Contacts successfully deleted - R=sip:secure.domain.com ID=eBGfI1JFE.oUd.vPpswiXsv8KEtxnlpn
> Jun 11 21:02:54 secure proxy[4522]: ERROR: db_mysql [km_dbase.c:122]: db_mysql_submit_query(): driver error on query: Lost connection to MySQL server during query
> Jun 11 21:02:54 secure proxy[4522]: ERROR: <core> [db_query.c:235]: db_do_insert_cmd(): error while submitting query
> Jun 11 21:02:54 secure proxy[4522]: ERROR: usrloc [ucontact.c:629]: db_insert_ucontact(): inserting contact in db failed
> Jun 11 21:02:54 secure proxy[4522]: ERROR: usrloc [urecord.c:548]: insert_ucontact(): failed to insert in database
> Jun 11 21:02:54 secure proxy[4522]: ERROR: registrar [save.c:521]: insert_contacts(): failed to insert contact
> Jun 11 21:03:01 secure proxy[4534]: NOTICE: <script>: New request on proxy - M=REGISTER R=sip:secure.domain.com F=sip:88888888 at secure.domain.com <mailto:88888888 at secure.domain.com> T=sip:88888888 at secure.domain.com <mailto:88888888 at secure.domain.com> IP=200.200.200.200:39999 (127.0.0.1:5060) ID=3tipgKc0nT2Bdw3rxOrFzcikpgcanQKN
> Jun 11 21:03:01 secure proxy[4534]: NOTICE: <script>: Authentication failed, no credentials - R=sip:secure.domain.com ID=3tipgKc0nT2Bdw3rxOrFzcikpgcanQKN
> Jun 11 21:03:01 secure proxy[4520]: NOTICE: <script>: New request on proxy - M=REGISTER R=sip:secure.domain.com F=sip:88888888 at secure.domain.com <mailto:88888888 at secure.domain.com> T=sip:88888888 at secure.domain.com <mailto:88888888 at secure.domain.com> IP=200.200.200.200:39999 (127.0.0.1:5060) ID=3tipgKc0nT2Bdw3rxOrFzcikpgcanQKN
> Jun 11 21:03:02 secure proxy[4520]: NOTICE: <script>: Contacts successfully saved, expires in 900s - R=sip:secure.domain.com ID=3tipgKc0nT2Bdw3rxOrFzcikpgcanQKN
> Jun 11 21:03:02 secure proxy[4537]: NOTICE: <script>: New request on proxy - M=REGISTER R=sip:secure.domain.com F=sip:88888888 at secure.domain.com <mailto:88888888 at secure.domain.com> T=sip:88888888 at secure.domain.com <mailto:88888888 at secure.domain.com> IP=200.200.200.200:39999 (127.0.0.1:5060) ID=3tipgKc0nT2Bdw3rxOrFzcikpgcanQKN
> Jun 11 21:03:02 secure proxy[4525]: NOTICE: <script>: New request on proxy - M=REGISTER R=sip:secure.domain.com F=sip:88888888 at secure.domain.com <mailto:88888888 at secure.domain.com> T=sip:88888888 at secure.domain.com <mailto:88888888 at secure.domain.com> IP=200.200.200.200:39999 (127.0.0.1:5060) ID=ySN6jCakYHYrnWtj6eJbJ5COHpbOp9Fe
> Jun 11 21:03:02 secure proxy[4525]: NOTICE: <script>: Authentication failed, no credentials - R=sip:secure.domain.com ID=ySN6jCakYHYrnWtj6eJbJ5COHpbOp9Fe
> Jun 11 21:03:02 secure proxy[4519]: NOTICE: <script>: New request on proxy - M=REGISTER R=sip:secure.domain.com F=sip:88888888 at secure.domain.com <mailto:88888888 at secure.domain.com> T=sip:88888888 at secure.domain.com <mailto:88888888 at secure.domain.com> IP=200.200.200.200:39999 (127.0.0.1:5060) ID=ySN6jCakYHYrnWtj6eJbJ5COHpbOp9Fe
> Jun 11 21:03:04 secure proxy[4537]: NOTICE: <script>: Contacts successfully deleted - R=sip:secure.domain.com ID=3tipgKc0nT2Bdw3rxOrFzcikpgcanQKN
> Jun 11 21:03:07 secure proxy[4519]: ERROR: db_mysql [km_dbase.c:122]: db_mysql_submit_query(): driver error on query: Duplicate entry 'uloc-55786194-11a7-b02' for key 'ruid_idx'
> Jun 11 21:03:07 secure proxy[4519]: ERROR: <core> [db_query.c:235]: db_do_insert_cmd(): error while submitting query
> Jun 11 21:03:07 secure proxy[4519]: ERROR: usrloc [ucontact.c:629]: db_insert_ucontact(): inserting contact in db failed
> Jun 11 21:03:07 secure proxy[4519]: ERROR: usrloc [urecord.c:548]: insert_ucontact(): failed to insert in database
> Jun 11 21:03:07 secure proxy[4519]: ERROR: registrar [save.c:521]: insert_contacts(): failed to insert contact
> Jun 11 21:03:12 secure proxy[4522]: NOTICE: <script>: New request on proxy - M=REGISTER R=sip:secure.domain.com F=sip:88888888 at secure.domain.com <mailto:88888888 at secure.domain.com> T=sip:88888888 at secure.domain.com <mailto:88888888 at secure.domain.com> IP=200.200.200.200:39999 (127.0.0.1:5060) ID=objP.SyrDoQJOdyQzCSsutv-PrglhR37
> Jun 11 21:03:12 secure proxy[4522]: NOTICE: <script>: Authentication failed, no credentials - R=sip:secure.domain.com ID=objP.SyrDoQJOdyQzCSsutv-PrglhR37
> Jun 11 21:03:12 secure proxy[4528]: NOTICE: <script>: New request on proxy - M=REGISTER R=sip:secure.domain.com F=sip:88888888 at secure.domain.com <mailto:88888888 at secure.domain.com> T=sip:88888888 at secure.domain.com <mailto:88888888 at secure.domain.com> IP=200.200.200.200:39999 (127.0.0.1:5060) ID=objP.SyrDoQJOdyQzCSsutv-PrglhR37
> ^C
> 
> Mysql is running:
> 
> root at secure:/home/admin# ps aux | grep mysql
> root      2229  0.0  0.0   4192  1548 ?        S    Jun10   0:00 /bin/sh /usr/bin/mysqld_safe
> mysql     3312  0.1  3.7 658404 144204 ?       Sl   Jun10   2:45 /usr/sbin/mysqld --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib/mysql/plugin --user=mysql --log-error=/var/log/mysql/mysqld.err --pid-file=/var/run/mysqld/mysqld.pid --socket=/var/run/mysqld/mysqld.sock --port=3306
> 
> 
> 
> root at secure:/home/admin# mysql -u root -p
> Enter password:
> Welcome to the MySQL monitor.  Commands end with ; or \g.
> Your MySQL connection id is 71051
> Server version: 5.5.43-0+deb7u1-log (Debian)
> 
> Copyright (c) 2000, 2015, Oracle and/or its affiliates. All rights reserved.
> 
> Oracle is a registered trademark of Oracle Corporation and/or its
> affiliates. Other names may be trademarks of their respective
> owners.
> 
> Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.
> 
> mysql> show databases;
> +--------------------+
> | Database           |
> +--------------------+
> | information_schema |
> | accounting         |
> | billing            |
> | carrier            |
> | kamailio           |
> | mysql              |
> | ngcp               |
> | performance_schema |
> | prosody            |
> | provisioning       |
> | sipstats           |
> | stats              |
> | syslog             |
> +--------------------+
> 13 rows in set (1.20 sec)
> 
> 
> Please advise.
> 
> 
> 
> 
> 
> 
> 
> 
> 

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.sipwise.com/mailman/private/spce-user_lists.sipwise.com/attachments/20150612/8c4adde0/attachment.html>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: Screen Shot 2015-06-12 at 10.44.39 AM.png
Type: image/png
Size: 31231 bytes
Desc: not available
URL: <http://lists.sipwise.com/mailman/private/spce-user_lists.sipwise.com/attachments/20150612/8c4adde0/attachment.png>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: smime.p7s
Type: application/pkcs7-signature
Size: 2547 bytes
Desc: not available
URL: <http://lists.sipwise.com/mailman/private/spce-user_lists.sipwise.com/attachments/20150612/8c4adde0/attachment.p7s>


More information about the Spce-user mailing list