[Spce-user] Fwd: [km_dbase.c:122]
Daniel Grotti
dgrotti at sipwise.com
Fri Jun 12 13:23:41 EDT 2015
for the list interest
----- Original Message -----
From: "Crexpedio Support Team" <jesse at crexpedio.com>
To: "Daniel Grotti" <dgrotti at sipwise.com>
Cc: "Crexpedio" <info at crexpedio.com>, "Jorge Quesada" <jquesada at incom.co.cr>
Sent: Friday, June 12, 2015 7:09:01 PM
Subject: Re: [km_dbase.c:122]
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' AND domain=' 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 >',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' where username='5010100101' AND contact=' sip:5010100101 at 201.191.199.69:41658;transport=TLS;ob' AND domain=' 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 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: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 ');
# 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 01:42:19',callid='MqV7TKeYQ77X4VTulYWoMGQApIoaJ2A5',contact=' 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 ';
On Jun 12, 2015, at 10:35 AM, Daniel Grotti < 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:
- w hat 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
----- Original Message -----
From: "Crexpedio Support Team" < jesse at crexpedio.com >
To: "Daniel Grotti" < 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.
<blockquote>
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 T=sip: 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 T=sip: 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 T=sip: 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 T=sip: 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 T=sip: 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 T=sip: 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 T=sip: 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 T=sip: 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 T=sip: 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 T=sip: 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 T=sip: 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 T=sip: 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 T=sip: 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 T=sip: 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 T=sip: 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 T=sip: 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.
</blockquote>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.sipwise.com/mailman/private/spce-user_lists.sipwise.com/attachments/20150612/e98c69b8/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/e98c69b8/attachment.png>
More information about the Spce-user
mailing list