i was again hit by the problem of non-expiring location table entries. this time it happened without any mi commands when pjsua crashed right after registration. 15 minutes after expiring, that registration is still in location table, but not in memory cash.
related to this location entry, i also got to syslog:
Apr 23 09:32:30 siika /usr/sbin/sip-proxy[14304]: ERROR: db_mysql [km_dbase.c:122]: driver error on query: Duplicate entry 'uloc-51761da3-37fb-e' for key 'ruid_idx' Apr 23 09:32:30 siika /usr/sbin/sip-proxy[14304]: ERROR: <core> [db_query.c:235]: error while submitting query Apr 23 09:32:30 siika /usr/sbin/sip-proxy[14304]: ERROR: usrloc [ucontact.c:615]: inserting contact in db failed Apr 23 09:32:30 siika /usr/sbin/sip-proxy[14304]: ERROR: usrloc [urecord.c:363]: updating contact in db failed
that update was triggered by some timer, because it was not related to any sip request. i haven't checked from the code what update is in question, but unless ruid field itself is updated, i don't see how it can result in duplicate entry.
-- juha
Hello,
it is on my to-do for later today to review this issue, following the report before.
Cheers, Daniel
On 4/23/13 8:55 AM, Juha Heinanen wrote:
i was again hit by the problem of non-expiring location table entries. this time it happened without any mi commands when pjsua crashed right after registration. 15 minutes after expiring, that registration is still in location table, but not in memory cash.
related to this location entry, i also got to syslog:
Apr 23 09:32:30 siika /usr/sbin/sip-proxy[14304]: ERROR: db_mysql [km_dbase.c:122]: driver error on query: Duplicate entry 'uloc-51761da3-37fb-e' for key 'ruid_idx' Apr 23 09:32:30 siika /usr/sbin/sip-proxy[14304]: ERROR: <core> [db_query.c:235]: error while submitting query Apr 23 09:32:30 siika /usr/sbin/sip-proxy[14304]: ERROR: usrloc [ucontact.c:615]: inserting contact in db failed Apr 23 09:32:30 siika /usr/sbin/sip-proxy[14304]: ERROR: usrloc [urecord.c:363]: updating contact in db failed
that update was triggered by some timer, because it was not related to any sip request. i haven't checked from the code what update is in question, but unless ruid field itself is updated, i don't see how it can result in duplicate entry.
-- juha
sr-dev mailing list sr-dev@lists.sip-router.org http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-dev
daniel,
i can now repeat the ruid conflict issue at will:
1) start sip proxy with empty location table
2) start pjsua that registers itself causing location entry to appear both in memory and location table:
# sip-proxy_ctl mi ul_dump | grep -E -i -w 'AOR|Ruid' AOR:: jh@test.fi Ruid:: uloc-5176382e-3ed4-1
3) kill pjsua (if you are lucky and it does not crash on its own) with killall -KILL pjsua
4) restart pjsua, which again registers itself and causes the error:
Apr 23 10:31:14 siika /usr/sbin/sip-proxy[16084]: INFO: REGISTER sip:jh@test.fi by jh@test.fi from <192.98.102.10> is authorized ## Apr 23 10:31:14 siika /usr/sbin/sip-proxy[16084]: ERROR: db_mysql [km_dbase.c:122]: driver error on query: Duplicate entry 'uloc-5176382e-3ed4-1' for key 'ruid_idx' Apr 23 10:31:14 siika /usr/sbin/sip-proxy[16084]: ERROR: <core> [db_query.c:235]: error while submitting query Apr 23 10:31:14 siika /usr/sbin/sip-proxy[16084]: ERROR: usrloc [ucontact.c:615]: inserting contact in db failed Apr 23 10:31:14 siika /usr/sbin/sip-proxy[16084]: ERROR: usrloc [ucontact.c:998]: failed to update database Apr 23 10:31:14 siika /usr/sbin/sip-proxy[16084]: ERROR: registrar [save.c:739]: failed to update contact
-- juha
Hello,
can you capture (ngrep) the REGISTER requests for the two cases and send them over? I don't have a pjsua with me right now, but I can re-inject them with protoshot and reproduce, that will help to troubleshoot properly.
Cheers, Daniel
On 4/23/13 9:34 AM, Juha Heinanen wrote:
daniel,
i can now repeat the ruid conflict issue at will:
start sip proxy with empty location table
start pjsua that registers itself causing location entry to appear
both in memory and location table:
# sip-proxy_ctl mi ul_dump | grep -E -i -w 'AOR|Ruid' AOR:: jh@test.fi Ruid:: uloc-5176382e-3ed4-1
- kill pjsua (if you are lucky and it does not crash on its own) with
killall -KILL pjsua
- restart pjsua, which again registers itself and causes the error:
Apr 23 10:31:14 siika /usr/sbin/sip-proxy[16084]: INFO: REGISTER sip:jh@test.fi by jh@test.fi from <192.98.102.10> is authorized ## Apr 23 10:31:14 siika /usr/sbin/sip-proxy[16084]: ERROR: db_mysql [km_dbase.c:122]: driver error on query: Duplicate entry 'uloc-5176382e-3ed4-1' for key 'ruid_idx' Apr 23 10:31:14 siika /usr/sbin/sip-proxy[16084]: ERROR: <core> [db_query.c:235]: error while submitting query Apr 23 10:31:14 siika /usr/sbin/sip-proxy[16084]: ERROR: usrloc [ucontact.c:615]: inserting contact in db failed Apr 23 10:31:14 siika /usr/sbin/sip-proxy[16084]: ERROR: usrloc [ucontact.c:998]: failed to update database Apr 23 10:31:14 siika /usr/sbin/sip-proxy[16084]: ERROR: registrar [save.c:739]: failed to update contact
-- juha
sr-dev mailing list sr-dev@lists.sip-router.org http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-dev
Daniel-Constantin Mierla writes:
can you capture (ngrep) the REGISTER requests for the two cases and send them over? I don't have a pjsua with me right now, but I can re-inject them with protoshot and reproduce, that will help to troubleshoot properly.
daniel,
the requests along with some syslog entries and comments are below. i removed Authorization: headers from register requests.
-- juha
T 2013/04/23 22:01:22.372754 192.98.102.10:57892 -> 192.98.102.10:5060 [AP] REGISTER sip:192.98.102.10 SIP/2.0. Via: SIP/2.0/TCP 192.98.102.10:57892;rport;branch=z9hG4bKPj9e911277-3bc5-4184-807f-6fa5534b1f21. Route: sip:192.98.102.10;transport=tcp;lr. Max-Forwards: 70. From: sip:jh@test.fi;tag=68259460-b3cc-49e7-81f4-3e6138d5eec9. To: sip:jh@test.fi. Call-ID: 9f971272-fcf4-4312-874f-d390a448e88a. CSeq: 28125 REGISTER. User-Agent: PJSUA v2.1 Linux-3.2.0.4/x86_64/glibc-2.13. Supported: outbound, path. Contact: sip:jh@192.98.102.10:5068;transport=TCP;ob;reg-id=1;+sip.instance="urn:uuid:00000000-0000-0000-0000-000091625c08". Expires: 300. Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS. Content-Length: 0.
Apr 23 22:01:22 siika /usr/sbin/sip-proxy[6393]: INFO: REGISTER sip:jh@test.fi by jh@test.fi from <192.98.102.10> is authorized
## T 2013/04/23 22:01:22.501737 192.98.102.10:5060 -> 192.98.102.10:57892 [AP] SIP/2.0 200 OK. Via: SIP/2.0/TCP 192.98.102.10:57892;rport=57892;branch=z9hG4bKPj9e911277-3bc5-4184-807f-6fa5534b1f21. From: sip:jh@test.fi;tag=68259460-b3cc-49e7-81f4-3e6138d5eec9. To: sip:jh@test.fi;tag=c02670ad1171fe45d9ff9a27d6c2cb82-a4e7. Call-ID: 9f971272-fcf4-4312-874f-d390a448e88a. CSeq: 28125 REGISTER. Contact: sip:jh@192.98.102.10:5068;transport=TCP;ob;q=0.5;expires=300;received="sip:192.98.102.10:57892;transport=TCP";+sip.instance="urn:uuid:00000000-0000-0000-0000-000091625c08";reg-id=1. Supported: outbound. Require: outbound. Server: OpenXg SIP Proxy (4.1.0-dev3 (x86_64/linux)). Content-Length: 0. .
at this point i -KILLed pjsua and started it again.
## T 2013/04/23 22:01:51.333822 192.98.102.10:52559 -> 192.98.102.10:5060 [AP] REGISTER sip:192.98.102.10 SIP/2.0. Via: SIP/2.0/TCP 192.98.102.10:52559;rport;branch=z9hG4bKPj5dc30bbd-73e3-483d-8ff8-7401cd8c49c7. Route: sip:192.98.102.10;transport=tcp;lr. Max-Forwards: 70. From: sip:jh@test.fi;tag=c9c332e4-24cb-461e-a978-efb48200cf7f. To: sip:jh@test.fi. Call-ID: 0f3f745f-1846-4a3b-a1fd-b900ad896c3c. CSeq: 2625 REGISTER. User-Agent: PJSUA v2.1 Linux-3.2.0.4/x86_64/glibc-2.13. Supported: outbound, path. Contact: sip:jh@192.98.102.10:5068;transport=TCP;ob;reg-id=1;+sip.instance="urn:uuid:00000000-0000-0000-0000-000091625c08". Expires: 300. Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS. Content-Length: 0. .
Apr 23 22:01:51 siika /usr/sbin/sip-proxy[6399]: INFO: REGISTER sip:jh@test.fi by jh@test.fi from <192.98.102.10> is authorized #Apr 23 22:01:51 siika /usr/sbin/sip-proxy[6399]: ERROR: db_mysql [km_dbase.c:122]: driver error on query: Duplicate entry 'uloc-5176d955-18f9-1' for key 'ruid_idx' Apr 23 22:01:51 siika /usr/sbin/sip-proxy[6399]: ERROR: <core> [db_query.c:235]: error while submitting query Apr 23 22:01:51 siika /usr/sbin/sip-proxy[6399]: ERROR: usrloc [ucontact.c:615]: inserting contact in db failed Apr 23 22:01:51 siika /usr/sbin/sip-proxy[6399]: ERROR: usrloc [ucontact.c:998]: failed to update database Apr 23 22:01:51 siika /usr/sbin/sip-proxy[6399]: ERROR: registrar [save.c:739]: failed to update contact # T 2013/04/23 22:01:51.441256 192.98.102.10:5060 -> 192.98.102.10:52559 [AP] SIP/2.0 500 Server Internal Error. Via: SIP/2.0/TCP 192.98.102.10:52559;rport=52559;branch=z9hG4bKPj5dc30bbd-73e3-483d-8ff8-7401cd8c49c7. From: sip:jh@test.fi;tag=c9c332e4-24cb-461e-a978-efb48200cf7f. To: sip:jh@test.fi;tag=c02670ad1171fe45d9ff9a27d6c2cb82-d6cb. Call-ID: 0f3f745f-1846-4a3b-a1fd-b900ad896c3c. CSeq: 2625 REGISTER. Contact: sip:jh@192.98.102.10:5068;transport=TCP;ob;q=0.5;expires=300;received="sip:192.98.102.10:52559;transport=TCP";+sip.instance="urn:uuid:00000000-0000-0000-0000-000091625c08";reg-id=1. P-Registrar-Error: usrloc_contact_update failed. Server: OpenXg SIP Proxy (4.1.0-dev3 (x86_64/linux)). Content-Length: 0.
Hello,
I tried to reproduce, but didn't get it. Can you give the parameters you set for registrar and usrloc modules? Maybe is specific for some matching mode or other parameter value. I tried with default config file, over udp as well as over tcp, with and without gruu enabled.
Cheers, Daniel
On 4/23/13 9:06 PM, Juha Heinanen wrote:
Daniel-Constantin Mierla writes:
can you capture (ngrep) the REGISTER requests for the two cases and send them over? I don't have a pjsua with me right now, but I can re-inject them with protoshot and reproduce, that will help to troubleshoot properly.
daniel,
the requests along with some syslog entries and comments are below. i removed Authorization: headers from register requests.
-- juha
T 2013/04/23 22:01:22.372754 192.98.102.10:57892 -> 192.98.102.10:5060 [AP] REGISTER sip:192.98.102.10 SIP/2.0. Via: SIP/2.0/TCP 192.98.102.10:57892;rport;branch=z9hG4bKPj9e911277-3bc5-4184-807f-6fa5534b1f21. Route: sip:192.98.102.10;transport=tcp;lr. Max-Forwards: 70. From: sip:jh@test.fi;tag=68259460-b3cc-49e7-81f4-3e6138d5eec9. To: sip:jh@test.fi. Call-ID: 9f971272-fcf4-4312-874f-d390a448e88a. CSeq: 28125 REGISTER. User-Agent: PJSUA v2.1 Linux-3.2.0.4/x86_64/glibc-2.13. Supported: outbound, path. Contact: sip:jh@192.98.102.10:5068;transport=TCP;ob;reg-id=1;+sip.instance="urn:uuid:00000000-0000-0000-0000-000091625c08". Expires: 300. Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS. Content-Length: 0.
Apr 23 22:01:22 siika /usr/sbin/sip-proxy[6393]: INFO: REGISTER sip:jh@test.fi by jh@test.fi from <192.98.102.10> is authorized
## T 2013/04/23 22:01:22.501737 192.98.102.10:5060 -> 192.98.102.10:57892 [AP] SIP/2.0 200 OK. Via: SIP/2.0/TCP 192.98.102.10:57892;rport=57892;branch=z9hG4bKPj9e911277-3bc5-4184-807f-6fa5534b1f21. From: sip:jh@test.fi;tag=68259460-b3cc-49e7-81f4-3e6138d5eec9. To: sip:jh@test.fi;tag=c02670ad1171fe45d9ff9a27d6c2cb82-a4e7. Call-ID: 9f971272-fcf4-4312-874f-d390a448e88a. CSeq: 28125 REGISTER. Contact: sip:jh@192.98.102.10:5068;transport=TCP;ob;q=0.5;expires=300;received="sip:192.98.102.10:57892;transport=TCP";+sip.instance="urn:uuid:00000000-0000-0000-0000-000091625c08";reg-id=1. Supported: outbound. Require: outbound. Server: OpenXg SIP Proxy (4.1.0-dev3 (x86_64/linux)). Content-Length: 0. .
at this point i -KILLed pjsua and started it again.
## T 2013/04/23 22:01:51.333822 192.98.102.10:52559 -> 192.98.102.10:5060 [AP] REGISTER sip:192.98.102.10 SIP/2.0. Via: SIP/2.0/TCP 192.98.102.10:52559;rport;branch=z9hG4bKPj5dc30bbd-73e3-483d-8ff8-7401cd8c49c7. Route: sip:192.98.102.10;transport=tcp;lr. Max-Forwards: 70. From: sip:jh@test.fi;tag=c9c332e4-24cb-461e-a978-efb48200cf7f. To: sip:jh@test.fi. Call-ID: 0f3f745f-1846-4a3b-a1fd-b900ad896c3c. CSeq: 2625 REGISTER. User-Agent: PJSUA v2.1 Linux-3.2.0.4/x86_64/glibc-2.13. Supported: outbound, path. Contact: sip:jh@192.98.102.10:5068;transport=TCP;ob;reg-id=1;+sip.instance="urn:uuid:00000000-0000-0000-0000-000091625c08". Expires: 300. Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS. Content-Length: 0. .
Apr 23 22:01:51 siika /usr/sbin/sip-proxy[6399]: INFO: REGISTER sip:jh@test.fi by jh@test.fi from <192.98.102.10> is authorized #Apr 23 22:01:51 siika /usr/sbin/sip-proxy[6399]: ERROR: db_mysql [km_dbase.c:122]: driver error on query: Duplicate entry 'uloc-5176d955-18f9-1' for key 'ruid_idx' Apr 23 22:01:51 siika /usr/sbin/sip-proxy[6399]: ERROR: <core> [db_query.c:235]: error while submitting query Apr 23 22:01:51 siika /usr/sbin/sip-proxy[6399]: ERROR: usrloc [ucontact.c:615]: inserting contact in db failed Apr 23 22:01:51 siika /usr/sbin/sip-proxy[6399]: ERROR: usrloc [ucontact.c:998]: failed to update database Apr 23 22:01:51 siika /usr/sbin/sip-proxy[6399]: ERROR: registrar [save.c:739]: failed to update contact # T 2013/04/23 22:01:51.441256 192.98.102.10:5060 -> 192.98.102.10:52559 [AP] SIP/2.0 500 Server Internal Error. Via: SIP/2.0/TCP 192.98.102.10:52559;rport=52559;branch=z9hG4bKPj5dc30bbd-73e3-483d-8ff8-7401cd8c49c7. From: sip:jh@test.fi;tag=c9c332e4-24cb-461e-a978-efb48200cf7f. To: sip:jh@test.fi;tag=c02670ad1171fe45d9ff9a27d6c2cb82-d6cb. Call-ID: 0f3f745f-1846-4a3b-a1fd-b900ad896c3c. CSeq: 2625 REGISTER. Contact: sip:jh@192.98.102.10:5068;transport=TCP;ob;q=0.5;expires=300;received="sip:192.98.102.10:52559;transport=TCP";+sip.instance="urn:uuid:00000000-0000-0000-0000-000091625c08";reg-id=1. P-Registrar-Error: usrloc_contact_update failed. Server: OpenXg SIP Proxy (4.1.0-dev3 (x86_64/linux)). Content-Length: 0.
Daniel-Constantin Mierla writes:
I tried to reproduce, but didn't get it. Can you give the parameters you set for registrar and usrloc modules? Maybe is specific for some matching mode or other parameter value. I tried with default config file, over udp as well as over tcp, with and without gruu enabled.
here are my module params:
# -- common params modparam("registrar|nathelper", "received_avp", "$avp(received_uri)")
# -- registrar params modparam("registrar", "default_q", 500) modparam("registrar", "default_expires", 1200) modparam("registrar", "max_expires", 3600) modparam("registrar", "max_contacts", 6) modparam("registrar", "method_filtering", 1) modparam("registrar", "gruu_enabled", 1) modparam("registrar", "outbound_mode", 1) modparam("registrar", "use_path", 1) modparam("registrar", "path_mode", 1)
# -- usrloc params modparam("usrloc", "db_url", "mysql://foo:bar@127.0.0.1/sip_proxy_cache") modparam("usrloc", "use_domain", 1) modparam("usrloc", "db_mode", 1) modparam("usrloc", "db_check_update", 1) modparam("usrloc", "nat_bflag", 7) modparam("usrloc", "timer_procs", 2)
-- juha
Daniel-Constantin Mierla writes:
I tried to reproduce, but didn't get it. Can you give the parameters you set for registrar and usrloc modules? Maybe is specific for some matching mode or other parameter value. I tried with default config file, over udp as well as over tcp, with and without gruu enabled.
forgot to mention that i have loaded outbound module before path module and that path module has params:
# -- path params modparam("path", "use_received", 1)
-- juha
Hello,
I think it is related to the issue reported also in the tracker, triggering error log message in your case by setting db_check_update parameter.
- http://sip-router.org/tracker/index.php?do=details&task_id=278&proje...
Practically, the contact address and aor are the same, only the call-id is different. In memory matching is done ok, but database operations always involved call-id. So the update failed due to different call-id, then it tried to insert, but failed due to same ruid.
I made a patch which is now in master. Give it a try and let me know if works fine now. You have to set db_ops_ruid parameter of usrloc module to 1.
It just popped up in my head, proabably I have to extend it a bit to update call-id value, for now is just doing the old query using ruid in WHERE clause instead of values for aor, contact address and call-id.
Cheers, Daniel
On 4/24/13 7:12 AM, Juha Heinanen wrote:
Daniel-Constantin Mierla writes:
I tried to reproduce, but didn't get it. Can you give the parameters you set for registrar and usrloc modules? Maybe is specific for some matching mode or other parameter value. I tried with default config file, over udp as well as over tcp, with and without gruu enabled.
forgot to mention that i have loaded outbound module before path module and that path module has params:
# -- path params modparam("path", "use_received", 1)
-- juha
-
Daniel-Constantin Mierla -
Juha Heinanen