[OpenSIPS-Devel] [ opensips-Bugs-3488471 ] usrloc:db_insert_ucontact: inserting contact in db failed

SourceForge.net noreply at sourceforge.net
Wed Apr 25 11:11:39 CEST 2012 

Bugs item #3488471, was opened at 2012-02-16 23:32
Message generated for change (Comment added) made by vladut-paiu
You can respond by visiting: 
https://sourceforge.net/tracker/?func=detail&atid=1086410&aid=3488471&group_id=232389

Please note that this message will contain a full copy of the comment thread,
including the initial issue submission, for this request,
not just the latest update.
Category: modules
Group: 1.7.x
>Status: Closed
>Resolution: Fixed
Priority: 8
Private: Yes
Submitted By: Nobody/Anonymous (nobody)
Assigned to: Vladut-Stefan Paiu (vladut-paiu)
Summary: usrloc:db_insert_ucontact: inserting contact in db failed

Initial Comment:
Usrloc strange stuck on this record:
mysql> select * from location order by expires asc;
+-------+----------+--------+---------------------------------+----------+------+---------------------+-------+---------------------------------------------------+-------+---------------------+-------+--------+---------------------------------------+------------------------+---------+
| id    | username | domain | contact                         | received | path | expires             | q     | callid                                            | cseq  | last_modified       | flags | cflags | user_agent                            | socket                 | methods |
+-------+----------+--------+---------------------------------+----------+------+---------------------+-------+---------------------------------------------------+-------+---------------------+-------+--------+---------------------------------------+------------------------+---------+
| 16638 |          |        | sip:81.211.5.210:5060           | NULL     | NULL | 2012-02-16 18:48:53 | -1.00 | abf2344f-ff1c-ff04-8000-0002a4055cd0 at 81.211.5.210 | 26963 | 2012-02-16 18:38:53 |     0 |      0 | AddPac SIP Gateway                    | udp:87.249.26.210:5061 |    NULL |

Logs:
Feb 17 11:07:12 SimpleOffice-1 /usr/local/sbin/opensips[79108]: ERROR:usrloc:db_insert_ucontact: inserting contact in db failed
Feb 17 11:07:12 SimpleOffice-1 /usr/local/sbin/opensips[79108]: ERROR:usrloc:wb_timer: inserting contact into database failed
Feb 17 11:07:42 SimpleOffice-1 /usr/local/sbin/opensips[79108]: CRITICAL:db_mysql:wrapper_single_mysql_stmt_execute: driver error (1062): Duplicate entry 'sip:81.211.5.210:5060' for key 'account_contact_idx'
Feb 17 11:07:42 SimpleOffice-1 /usr/local/sbin/opensips[79108]: ERROR:usrloc:db_insert_ucontact: inserting contact in db failed
Feb 17 11:07:42 SimpleOffice-1 /usr/local/sbin/opensips[79108]: ERROR:usrloc:wb_timer: inserting contact into database failed
Feb 17 11:08:13 SimpleOffice-1 /usr/local/sbin/opensips[79108]: CRITICAL:db_mysql:wrapper_single_mysql_stmt_execute: driver error (1062): Duplicate entry 'sip:81.211.5.210:5060' for key 'account_contact_idx'
... 
Fixed by removing this record from database.
FreeBSD 7.1-RC2 i386
OpenSIPS v1.7.1
Mysql 5.1.58

----------------------------------------------------------------------

>Comment By: Vladut-Stefan Paiu (vladut-paiu)
Date: 2012-04-25 02:11

Message:
Hello,

Seems there was a bug, where if your DB does not respond while OpenSIPS
tries to delete it, the record would get deleted from OpenSIPS mem, so the
DB entry would stay there forever ( or until next restart :) ).

Committed a fix for this in the trunk, 1.8 and 1.7 branches.

Regards,
Vlad

----------------------------------------------------------------------

Comment By: Nobody/Anonymous (nobody)
Date: 2012-02-29 03:14

Message:
Made some bruteforce with register packets.
I think the problem with buggy contact in database, like:
"x101--sip:419x101 at 10.192.116.142:5060"
or 
"sip:81.211.5.210:5060" - empty contact
or from something like 
"555--sip::::::::::::::::::::::::::::::::::::::::::::::::::::::::"
from this debug:
########### DEBUG ##############
Feb 29 14:58:44 [99773] DBG:core:parse_via_param: found param type 232,
<branch> = <z9hG4bK7f89.ee746af.0>; state=6
Feb 29 14:58:44 [99773] DBG:core:parse_via_param: found param type 234,
<received> = <10.192.118.98>; state=16
Feb 29 14:58:44 [99773] DBG:core:parse_via: end of header reached, state=5
Feb 29 14:58:44 [99776]
CRITICAL:db_mysql:wrapper_single_mysql_stmt_execute: driver error (1062):
Duplicate entry
'555--sip::::::::::::::::::::::::::::::::::::::::::::::::::::::::' for key
'account_contact_idx'
Feb 29 14:58:44 [99773] DBG:core:parse_headers: via found, flags=2
Feb 29 14:58:44 [99773] DBG:core:parse_headers: this is the first via
Feb 29 14:58:44 [99776] ERROR:usrloc:db_insert_ucontact: inserting contact
in db failed
Feb 29 14:58:44 [99773] DBG:core:receive_msg: After parse_msg...
Feb 29 14:58:44 [99776] ERROR:usrloc:wb_timer: inserting contact into
database failed
Feb 29 14:58:44 [99773] DBG:core:forward_reply: found module tm, passing
reply to it
Feb 29 14:58:44 [99776] DBG:db_mysql:has_stmt_ctx: ctx found for location
Feb 29 14:58:44 [99773] DBG:tm:t_check: start=0xffffffff
Feb 29 14:58:44 [99776] DBG:db_mysql:db_mysql_do_prepared_query:
conn=0x821d290 (tail=136434504) MC=0x821d37c
Feb 29 14:58:44 [99773] DBG:core:parse_headers: flags=22
Feb 29 14:58:44 [99776] DBG:db_mysql:db_mysql_do_prepared_query: set values
for the statement run
Feb 29 14:58:44 [99773] DBG:core:parse_to_param: tag=as5305e166
Feb 29 14:58:44 [99776] DBG:db_mysql:db_mysql_val2bind: added val (0):
len=3; type=254; is_null=0
Feb 29 14:58:44 [99773] DBG:core:parse_to: end of header reached, state=29
Feb 29 14:58:44 [99776] DBG:db_mysql:db_mysql_val2bind: added val (1):
len=1021; type=254; is_null=0
Feb 29 14:58:44 [99773] DBG:core:parse_to: display={},
ruri={sip:10.192.118.99:5060}
Feb 29 14:58:44 [99776] DBG:db_mysql:db_mysql_val2bind: added val (2):
len=36; type=12; is_null=0
Feb 29 14:58:44 [99773] DBG:core:get_hdr_field: <To> [39];
uri=[sip:10.192.118.99:5060]
Feb 29 14:58:44 [99776] DBG:db_mysql:db_mysql_val2bind: added val (3):
len=8; type=5; is_null=0
Feb 29 14:58:44 [99773] DBG:core:get_hdr_field: to body
[sip:10.192.118.99:5060]
Feb 29 14:58:44 [99776] DBG:db_mysql:db_mysql_val2bind: added val (4):
len=31; type=254; is_null=0
Feb 29 14:58:44 [99773] DBG:core:get_hdr_field: cseq <CSeq>: <14> <OPTIONS>
Feb 29 14:58:44 [99776] DBG:db_mysql:db_mysql_val2bind: added val (5):
len=4; type=3; is_null=0
Feb 29 14:58:44 [99773] DBG:tm:t_reply_matching: hash 39159 label 262555630
branch 0
Feb 29 14:58:44 [99776] DBG:db_mysql:db_mysql_val2bind: added val (6):
len=4; type=3; is_null=0
Feb 29 14:58:44 [99773] DBG:tm:t_reply_matching: REF_UNSAFE:[0x28c29f40]
after is 1
Feb 29 14:58:44 [99776] DBG:db_mysql:db_mysql_val2bind: added val (7):
len=4; type=3; is_null=0
Feb 29 14:58:44 [99773] DBG:tm:t_reply_matching: reply matched
(T=0x28c29f40)!
Feb 29 14:58:44 [99776] DBG:db_mysql:db_mysql_val2bind: added val (8):
len=3; type=254; is_null=0
Feb 29 14:58:44 [99773] DBG:tm:t_check: end=0x28c29f40
Feb 29 14:58:44 [99776] DBG:db_mysql:db_mysql_val2bind: added val (11):
len=22; type=254; is_null=0
Feb 29 14:58:44 [99773] DBG:tm:reply_received: org. status uas=0, uac[0]=0
local=2 is_invite=0)
Feb 29 14:58:44 [99776] DBG:db_mysql:db_mysql_val2bind: added val (13):
len=36; type=12; is_null=0
Feb 29 14:58:44 [99773] DBG:tm:t_should_relay_response: T_code=0,
new_code=200
Feb 29 14:58:44 [99776] DBG:db_mysql:db_mysql_do_prepared_query: doing
BIND_PARAM in...
Feb 29 14:58:44 [99773] DBG:tm:local_reply: branch=0, save=0, winner=0
Feb 29 14:58:44 [99773] DBG:tm:local_reply: local transaction completed
Feb 29 14:58:44 [99773] DBG:tm:run_trans_callbacks: trans=0x28c29f40,
callback type 256, id 0 entered
Feb 29 14:58:44 [99773] DBG:dispatcher:ds_options_callback: OPTIONS-Request
was finished with code 200 (to sip:10.192.118.99:5060, group 1)
Feb 29 14:58:44 [99773] DBG:dispatcher:ds_set_state: no event sent
Feb 29 14:58:44 [99773] DBG:tm:cleanup_uac_timers: RETR/FR timers reset
Feb 29 14:58:44 [99773] DBG:tm:insert_timer_unsafe: [2]: 0x28c29f88 (1385)
Feb 29 14:58:44 [99773] DBG:tm:t_unref: UNREF_UNSAFE: [0x28c29f40] after is
0
Feb 29 14:58:44 [99773] DBG:core:destroy_avp_list: destroying list 0x0
Feb 29 14:58:44 [99773] DBG:core:receive_msg: cleaning up
Feb 29 14:58:44 [99776]
CRITICAL:db_mysql:wrapper_single_mysql_stmt_execute: driver error (1062):
Duplicate entry
'555--sip::::::::::::::::::::::::::::::::::::::::::::::::::::::::' for key
'account_contact_idx'
Feb 29 14:58:44 [99776] ERROR:usrloc:db_insert_ucontact: inserting contact
in db failed
Feb 29 14:58:44 [99776] ERROR:usrloc:wb_timer: inserting contact into
database failed
Feb 29 14:58:44 [99776] DBG:db_mysql:has_stmt_ctx: ctx found for location
Feb 29 14:58:44 [99776] DBG:db_mysql:db_mysql_do_prepared_query:
conn=0x821d290 (tail=136434504) MC=0x821d37c
Feb 29 14:58:44 [99776] DBG:db_mysql:db_mysql_do_prepared_query: set values
for the statement run
Feb 29 14:58:44 [99776] DBG:db_mysql:db_mysql_val2bind: added val (0):
len=3; type=254; is_null=0
Feb 29 14:58:44 [99776] DBG:db_mysql:db_mysql_val2bind: added val (1):
len=521; type=254; is_null=0
Feb 29 14:58:44 [99776] DBG:db_mysql:db_mysql_val2bind: added val (2):
len=36; type=12; is_null=0
Feb 29 14:58:44 [99776] DBG:db_mysql:db_mysql_val2bind: added val (3):
len=8; type=5; is_null=0
Feb 29 14:58:44 [99776] DBG:db_mysql:db_mysql_val2bind: added val (4):
len=31; type=254; is_null=0
Feb 29 14:58:44 [99776] DBG:db_mysql:db_mysql_val2bind: added val (5):
len=4; type=3; is_null=0
Feb 29 14:58:44 [99776] DBG:db_mysql:db_mysql_val2bind: added val (6):
len=4; type=3; is_null=0
Feb 29 14:58:44 [99776] DBG:db_mysql:db_mysql_val2bind: added val (7):
len=4; type=3; is_null=0
Feb 29 14:58:44 [99776] DBG:db_mysql:db_mysql_val2bind: added val (8):
len=3; type=254; is_null=0
Feb 29 14:58:44 [99776] DBG:db_mysql:db_mysql_val2bind: added val (11):
len=22; type=254; is_null=0
Feb 29 14:58:44 [99776] DBG:db_mysql:db_mysql_val2bind: added val (13):
len=36; type=12; is_null=0
Feb 29 14:58:44 [99776] DBG:db_mysql:db_mysql_do_prepared_query: doing
BIND_PARAM in...
Feb 29 14:58:44 [99776]
CRITICAL:db_mysql:wrapper_single_mysql_stmt_execute: driver error (1062):
Duplicate entry
'555--sip:7875609@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@' for key
'account_contact_idx'
Feb 29 14:58:44 [99776] ERROR:usrloc:db_insert_ucontact: inserting contact
in db failed
Feb 29 14:58:44 [99776] ERROR:usrloc:wb_timer: inserting contact into
database failed
Feb 29 14:58:44 [99776] DBG:db_mysql:has_stmt_ctx: ctx found for location
Feb 29 14:58:44 [99776] DBG:db_mysql:db_mysql_do_prepared_query:
conn=0x821d290 (tail=136434504) MC=0x821d37c
Feb 29 14:58:44 [99776] DBG:db_mysql:db_mysql_do_prepared_query: set values
for the statement run
Feb 29 14:58:44 [99776] DBG:db_mysql:db_mysql_val2bind: added val (0):
len=3; type=254; is_null=0
Feb 29 14:58:44 [99776] DBG:db_mysql:db_mysql_val2bind: added val (1):
len=1021; type=254; is_null=0
Feb 29 14:58:44 [99776] DBG:db_mysql:db_mysql_val2bind: added val (2):
len=36; type=12; is_null=0
Feb 29 14:58:44 [99776] DBG:db_mysql:db_mysql_val2bind: added val (3):
len=8; type=5; is_null=0
Feb 29 14:58:44 [99776] DBG:db_mysql:db_mysql_val2bind: added val (4):
len=31; type=254; is_null=0
Feb 29 14:58:44 [99776] DBG:db_mysql:db_mysql_val2bind: added val (5):
len=4; type=3; is_null=0
Feb 29 14:58:44 [99776] DBG:db_mysql:db_mysql_val2bind: added val (6):
len=4; type=3; is_null=0
Feb 29 14:58:44 [99776] DBG:db_mysql:db_mysql_val2bind: added val (7):
len=4; type=3; is_null=0
Feb 29 14:58:44 [99776] DBG:db_mysql:db_mysql_val2bind: added val (8):
len=3; type=254; is_null=0
Feb 29 14:58:44 [99776] DBG:db_mysql:db_mysql_val2bind: added val (11):
len=22; type=254; is_null=0
Feb 29 14:58:44 [99776] DBG:db_mysql:db_mysql_val2bind: added val (13):
len=36; type=12; is_null=0
Feb 29 14:58:44 [99776] DBG:db_mysql:db_mysql_do_prepared_query: doing
BIND_PARAM in...
Feb 29 14:58:44 [99776]
CRITICAL:db_mysql:wrapper_single_mysql_stmt_execute: driver error (1062):
Duplicate entry
'555--sip:7875609@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@' for key
'account_contact_idx'
Feb 29 14:58:44 [99776] ERROR:usrloc:db_insert_ucontact: inserting contact
in db failed
Feb 29 14:58:44 [99776] ERROR:usrloc:wb_timer: inserting contact into
database failed
Feb 29 14:58:44 [99776] DBG:usrloc:mem_timer_udomain: usrloc timer
attempting to flush rows to DB
Feb 29 14:58:45 [99776] DBG:tm:utimer_routine: timer
routine:4,tl=0x28bfde44 next=0x28c2a08c, timeout=1380800000
Feb 29 14:58:45 [99776] DBG:tm:utimer_routine: timer
routine:4,tl=0x28c2a08c next=0x0, timeout=1380800000
Feb 29 14:58:50 [99776] DBG:tm:timer_routine: timer routine:2,tl=0x28bfdd40
next=0x28c29f88, timeout=1385
Feb 29 14:58:50 [99776] DBG:tm:wait_handler: removing 0x28bfdcf8 from table
Feb 29 14:58:50 [99776] DBG:tm:delete_cell: delete transaction 0x28bfdcf8
Feb 29 14:58:50 [99776] DBG:tm:wait_handler: done
Feb 29 14:58:50 [99776] DBG:tm:timer_routine: timer routine:2,tl=0x28c29f88
next=0x0, timeout=1385
Feb 29 14:58:50 [99776] DBG:tm:wait_handler: removing 0x28c29f40 from table
Feb 29 14:58:50 [99776] DBG:tm:delete_cell: delete transaction 0x28c29f40
Feb 29 14:58:50 [99776] DBG:tm:wait_handler: done
Feb 29 14:59:15 [99776] DBG:dispatcher:ds_check_timer: probing set #1, URI
sip:10.192.118.99:5060
Feb 29 14:59:15 [99776] DBG:tm:t_uac: next_hop=<sip:10.192.118.99:5060>
Feb 29 14:59:15 [99776] DBG:core:mk_proxy: doing DNS lookup...
Feb 29 14:59:15 [99776] DBG:tm:dlg2hash: 39156
Feb 29 14:59:15 [99776] DBG:tm:print_request_uri: sip:10.192.118.99:5060
Feb 29 14:59:15 [99776] DBG:tm:set_timer: relative timeout is 500000
Feb 29 14:59:15 [99776] DBG:tm:insert_timer_unsafe: [4]: 0x28c2a08c
(1410800000)
Feb 29 14:59:15 [99776] DBG:tm:set_timer: relative timeout is 10
Feb 29 14:59:15 [99776] DBG:tm:insert_timer_unsafe: [0]: 0x28c2a0a8 (1420)
Feb 29 14:59:15 [99776] DBG:dispatcher:ds_check_timer: probing set #1, URI
sip:10.192.118.99:5060
Feb 29 14:59:15 [99776] DBG:tm:t_uac: next_hop=<sip:10.192.118.99:5060>
Feb 29 14:59:15 [99776] DBG:core:mk_proxy: doing DNS lookup...
Feb 29 14:59:15 [99776] DBG:tm:dlg2hash: 39157
Feb 29 14:59:15 [99776] DBG:tm:print_request_uri: sip:10.192.118.99:5060
Feb 29 14:59:15 [99776] DBG:tm:set_timer: relative timeout is 500000
Feb 29 14:59:15 [99776] DBG:tm:insert_timer_unsafe: [4]: 0x28bfde44
(1410800000)
Feb 29 14:59:15 [99776] DBG:tm:set_timer: relative timeout is 10
Feb 29 14:59:15 [99776] DBG:tm:insert_timer_unsafe: [0]: 0x28bfde60 (1420)
Feb 29 14:59:15 [99776] DBG:db_mysql:has_stmt_ctx: ctx found for location
Feb 29 14:59:15 [99776] DBG:db_mysql:db_mysql_do_prepared_query:
conn=0x821d290 (tail=136434504) MC=0x821d37c
Feb 29 14:59:15 [99776] DBG:db_mysql:db_mysql_do_prepared_query: set values
for the statement run
Feb 29 14:59:15 [99776] DBG:db_mysql:db_mysql_val2bind: added val (0):
len=3; type=254; is_null=0
Feb 29 14:59:15 [99776] DBG:db_mysql:db_mysql_val2bind: added val (1):
len=521; type=254; is_null=0
Feb 29 14:59:15 [99776] DBG:db_mysql:db_mysql_val2bind: added val (2):
len=36; type=12; is_null=0
Feb 29 14:59:15 [99776] DBG:db_mysql:db_mysql_val2bind: added val (3):
len=8; type=5; is_null=0
Feb 29 14:59:15 [99776] DBG:db_mysql:db_mysql_val2bind: added val (4):
len=31; type=254; is_null=0
Feb 29 14:59:15 [99776] DBG:db_mysql:db_mysql_val2bind: added val (5):
len=4; type=3; is_null=0
Feb 29 14:59:15 [99776] DBG:db_mysql:db_mysql_val2bind: added val (6):
len=4; type=3; is_null=0
Feb 29 14:59:15 [99776] DBG:db_mysql:db_mysql_val2bind: added val (7):
len=4; type=3; is_null=0
Feb 29 14:59:15 [99776] DBG:db_mysql:db_mysql_val2bind: added val (8):
len=3; type=254; is_null=0
Feb 29 14:59:15 [99773] DBG:core:parse_msg: SIP Reply  (status):
Feb 29 14:59:15 [99776] DBG:db_mysql:db_mysql_val2bind: added val (11):
len=22; type=254; is_null=0
Feb 29 14:59:15 [99773] DBG:core:parse_msg:  version: <SIP/2.0>
Feb 29 14:59:15 [99776] DBG:db_mysql:db_mysql_val2bind: added val (13):
len=36; type=12; is_null=0
Feb 29 14:59:15 [99773] DBG:core:parse_msg:  status:  <200>
Feb 29 14:59:15 [99776] DBG:db_mysql:db_mysql_do_prepared_query: doing
BIND_PARAM in...
Feb 29 14:59:15 [99773] DBG:core:parse_msg:  reason:  <OK>
Feb 29 14:59:15 [99773] DBG:core:parse_headers: flags=2
Feb 29 14:59:15 [99773] DBG:core:parse_via_param: found param type 232,
<branch> = <z9hG4bK4f89.590307c.0>; state=6
Feb 29 14:59:15 [99773] DBG:core:parse_via_param: found param type 234,
<received> = <10.192.118.98>; state=16
Feb 29 14:59:15 [99773] DBG:core:parse_via: end of header reached, state=5
Feb 29 14:59:15 [99773] DBG:core:parse_headers: via found, flags=2
Feb 29 14:59:15 [99773] DBG:core:parse_headers: this is the first via
Feb 29 14:59:15 [99773] DBG:core:receive_msg: After parse_msg...
Feb 29 14:59:15 [99773] DBG:core:forward_reply: found module tm, passing
reply to it
Feb 29 14:59:15 [99773] DBG:tm:t_check: start=0xffffffff
Feb 29 14:59:15 [99773] DBG:core:parse_headers: flags=22
Feb 29 14:59:15 [99773] DBG:core:parse_to_param: tag=as099dd62c
Feb 29 14:59:15 [99773] DBG:core:parse_to: end of header reached, state=29
Feb 29 14:59:15 [99773] DBG:core:parse_to: display={},
ruri={sip:10.192.118.99:5060}
Feb 29 14:59:15 [99773] DBG:core:get_hdr_field: <To> [39];
uri=[sip:10.192.118.99:5060]
Feb 29 14:59:15 [99773] DBG:core:get_hdr_field: to body
[sip:10.192.118.99:5060]
Feb 29 14:59:15 [99773] DBG:core:get_hdr_field: cseq <CSeq>: <14> <OPTIONS>
Feb 29 14:59:15 [99773] DBG:tm:t_reply_matching: hash 39156 label 208679061
branch 0
Feb 29 14:59:15 [99773] DBG:tm:t_reply_matching: REF_UNSAFE:[0x28c29f40]
after is 1
Feb 29 14:59:15 [99773] DBG:tm:t_reply_matching: reply matched
(T=0x28c29f40)!
Feb 29 14:59:15 [99773] DBG:tm:t_check: end=0x28c29f40
Feb 29 14:59:15 [99773] DBG:tm:reply_received: org. status uas=0, uac[0]=0
local=2 is_invite=0)
Feb 29 14:59:15 [99773] DBG:tm:t_should_relay_response: T_code=0,
new_code=200
Feb 29 14:59:15 [99773] DBG:tm:local_reply: branch=0, save=0, winner=0
Feb 29 14:59:15 [99773] DBG:tm:local_reply: local transaction completed
Feb 29 14:59:15 [99773] DBG:tm:run_trans_callbacks: trans=0x28c29f40,
callback type 256, id 0 entered
Feb 29 14:59:15 [99773] DBG:dispatcher:ds_options_callback: OPTIONS-Request
was finished with code 200 (to sip:10.192.118.99:5060, group 1)
Feb 29 14:59:15 [99773] DBG:dispatcher:ds_set_state: no event sent
Feb 29 14:59:15 [99773] DBG:tm:cleanup_uac_timers: RETR/FR timers reset
Feb 29 14:59:15 [99773] DBG:tm:insert_timer_unsafe: [2]: 0x28c29f88 (1415)
Feb 29 14:59:15 [99773] DBG:tm:t_unref: UNREF_UNSAFE: [0x28c29f40] after is
0
Feb 29 14:59:15 [99773] DBG:core:destroy_avp_list: destroying list 0x0
Feb 29 14:59:15 [99773] DBG:core:receive_msg: cleaning up
Feb 29 14:59:15 [99773] DBG:core:parse_msg: SIP Reply  (status):
Feb 29 14:59:15 [99776]
CRITICAL:db_mysql:wrapper_single_mysql_stmt_execute: driver error (1062):
Duplicate entry
'555--sip::::::::::::::::::::::::::::::::::::::::::::::::::::::::' for key
'account_contact_idx'
Feb 29 14:59:15 [99773] DBG:core:parse_msg:  version: <SIP/2.0>
Feb 29 14:59:15 [99776] ERROR:usrloc:db_insert_ucontact: inserting contact
in db failed
Feb 29 14:59:15 [99773] DBG:core:parse_msg:  status:  <200>
Feb 29 14:59:15 [99776] ERROR:usrloc:wb_timer: inserting contact into
database failed
Feb 29 14:59:15 [99773] DBG:core:parse_msg:  reason:  <OK>
Feb 29 14:59:15 [99776] DBG:db_mysql:has_stmt_ctx: ctx found for location
Feb 29 14:59:15 [99773] DBG:core:parse_headers: flags=2
Feb 29 14:59:15 [99776] DBG:db_mysql:db_mysql_do_prepared_query:
conn=0x821d290 (tail=136434504) MC=0x821d37c
Feb 29 14:59:15 [99773] DBG:core:parse_via_param: found param type 232,
<branch> = <z9hG4bK5f89.49c85891.0>; state=6
Feb 29 14:59:15 [99776] DBG:db_mysql:db_mysql_do_prepared_query: set values
for the statement run
Feb 29 14:59:15 [99773] DBG:core:parse_via_param: found param type 234,
<received> = <10.192.118.98>; state=16
Feb 29 14:59:15 [99776] DBG:db_mysql:db_mysql_val2bind: added val (0):
len=3; type=254; is_null=0
Feb 29 14:59:15 [99773] DBG:core:parse_via: end of header reached, state=5
Feb 29 14:59:15 [99776] DBG:db_mysql:db_mysql_val2bind: added val (1):
len=1021; type=254; is_null=0
Feb 29 14:59:15 [99773] DBG:core:parse_headers: via found, flags=2
Feb 29 14:59:15 [99776] DBG:db_mysql:db_mysql_val2bind: added val (2):
len=36; type=12; is_null=0
Feb 29 14:59:15 [99773] DBG:core:parse_headers: this is the first via
Feb 29 14:59:15 [99776] DBG:db_mysql:db_mysql_val2bind: added val (3):
len=8; type=5; is_null=0
Feb 29 14:59:15 [99773] DBG:core:receive_msg: After parse_msg...
Feb 29 14:59:15 [99776] DBG:db_mysql:db_mysql_val2bind: added val (4):
len=31; type=254; is_null=0
Feb 29 14:59:15 [99773] DBG:core:forward_reply: found module tm, passing
reply to it
Feb 29 14:59:15 [99776] DBG:db_mysql:db_mysql_val2bind: added val (5):
len=4; type=3; is_null=0
Feb 29 14:59:15 [99773] DBG:tm:t_check: start=0xffffffff
Feb 29 14:59:15 [99776] DBG:db_mysql:db_mysql_val2bind: added val (6):
len=4; type=3; is_null=0
Feb 29 14:59:15 [99773] DBG:core:parse_headers: flags=22
Feb 29 14:59:15 [99776] DBG:db_mysql:db_mysql_val2bind: added val (7):
len=4; type=3; is_null=0
Feb 29 14:59:15 [99773] DBG:core:parse_to_param: tag=as475aa36d
Feb 29 14:59:15 [99776] DBG:db_mysql:db_mysql_val2bind: added val (8):
len=3; type=254; is_null=0
Feb 29 14:59:15 [99773] DBG:core:parse_to: end of header reached, state=29
Feb 29 14:59:15 [99776] DBG:db_mysql:db_mysql_val2bind: added val (11):
len=22; type=254; is_null=0
Feb 29 14:59:15 [99773] DBG:core:parse_to: display={},
ruri={sip:10.192.118.99:5060}
Feb 29 14:59:15 [99776] DBG:db_mysql:db_mysql_val2bind: added val (13):
len=36; type=12; is_null=0
Feb 29 14:59:15 [99773] DBG:core:get_hdr_field: <To> [39];
uri=[sip:10.192.118.99:5060]
Feb 29 14:59:15 [99776] DBG:db_mysql:db_mysql_do_prepared_query: doing
BIND_PARAM in...
Feb 29 14:59:15 [99773] DBG:core:get_hdr_field: to body
[sip:10.192.118.99:5060]
Feb 29 14:59:15 [99773] DBG:core:get_hdr_field: cseq <CSeq>: <14> <OPTIONS>
Feb 29 14:59:15 [99773] DBG:tm:t_reply_matching: hash 39157 label 428182676
branch 0
Feb 29 14:59:15 [99773] DBG:tm:t_reply_matching: REF_UNSAFE:[0x28bfdcf8]
after is 1
Feb 29 14:59:15 [99773] DBG:tm:t_reply_matching: reply matched
(T=0x28bfdcf8)!
Feb 29 14:59:15 [99773] DBG:tm:t_check: end=0x28bfdcf8
Feb 29 14:59:15 [99773] DBG:tm:reply_received: org. status uas=0, uac[0]=0
local=2 is_invite=0)
Feb 29 14:59:15 [99773] DBG:tm:t_should_relay_response: T_code=0,
new_code=200
Feb 29 14:59:15 [99773] DBG:tm:local_reply: branch=0, save=0, winner=0
Feb 29 14:59:15 [99773] DBG:tm:local_reply: local transaction completed
Feb 29 14:59:15 [99773] DBG:tm:run_trans_callbacks: trans=0x28bfdcf8,
callback type 256, id 0 entered
Feb 29 14:59:15 [99773] DBG:dispatcher:ds_options_callback: OPTIONS-Request
was finished with code 200 (to sip:10.192.118.99:5060, group 1)
Feb 29 14:59:15 [99773] DBG:dispatcher:ds_set_state: no event sent
Feb 29 14:59:15 [99773] DBG:tm:cleanup_uac_timers: RETR/FR timers reset
Feb 29 14:59:15 [99773] DBG:tm:insert_timer_unsafe: [2]: 0x28bfdd40 (1415)
Feb 29 14:59:15 [99773] DBG:tm:t_unref: UNREF_UNSAFE: [0x28bfdcf8] after is
0
Feb 29 14:59:15 [99773] DBG:core:destroy_avp_list: destroying list 0x0
Feb 29 14:59:15 [99773] DBG:core:receive_msg: cleaning up
Feb 29 14:59:15 [99776]
CRITICAL:db_mysql:wrapper_single_mysql_stmt_execute: driver error (1062):
Duplicate entry
'555--sip::::::::::::::::::::::::::::::::::::::::::::::::::::::::' for key
'account_contact_idx'
Feb 29 14:59:15 [99776] ERROR:usrloc:db_insert_ucontact: inserting contact
in db failed
Feb 29 14:59:15 [99776] ERROR:usrloc:wb_timer: inserting contact into
database failed
Feb 29 14:59:15 [99776] DBG:db_mysql:has_stmt_ctx: ctx found for location
Feb 29 14:59:15 [99776] DBG:db_mysql:db_mysql_do_prepared_query:
conn=0x821d290 (tail=136434504) MC=0x821d37c
Feb 29 14:59:15 [99776] DBG:db_mysql:db_mysql_do_prepared_query: set values
for the statement run
Feb 29 14:59:15 [99776] DBG:db_mysql:db_mysql_val2bind: added val (0):
len=3; type=254; is_null=0
Feb 29 14:59:15 [99776] DBG:db_mysql:db_mysql_val2bind: added val (1):
len=521; type=254; is_null=0
Feb 29 14:59:15 [99776] DBG:db_mysql:db_mysql_val2bind: added val (2):
len=36; type=12; is_null=0
Feb 29 14:59:15 [99776] DBG:db_mysql:db_mysql_val2bind: added val (3):
len=8; type=5; is_null=0
Feb 29 14:59:15 [99776] DBG:db_mysql:db_mysql_val2bind: added val (4):
len=31; type=254; is_null=0
Feb 29 14:59:15 [99776] DBG:db_mysql:db_mysql_val2bind: added val (5):
len=4; type=3; is_null=0
Feb 29 14:59:15 [99776] DBG:db_mysql:db_mysql_val2bind: added val (6):
len=4; type=3; is_null=0
Feb 29 14:59:15 [99776] DBG:db_mysql:db_mysql_val2bind: added val (7):
len=4; type=3; is_null=0
Feb 29 14:59:15 [99776] DBG:db_mysql:db_mysql_val2bind: added val (8):
len=3; type=254; is_null=0
Feb 29 14:59:15 [99776] DBG:db_mysql:db_mysql_val2bind: added val (11):
len=22; type=254; is_null=0
Feb 29 14:59:15 [99776] DBG:db_mysql:db_mysql_val2bind: added val (13):
len=36; type=12; is_null=0
Feb 29 14:59:15 [99776] DBG:db_mysql:db_mysql_do_prepared_query: doing
BIND_PARAM in...
Feb 29 14:59:15 [99776]
CRITICAL:db_mysql:wrapper_single_mysql_stmt_execute: driver error (1062):
Duplicate entry
'555--sip:7875609@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@' for key
'account_contact_idx'
Feb 29 14:59:15 [99776] ERROR:usrloc:db_insert_ucontact: inserting contact
in db failed
Feb 29 14:59:15 [99776] ERROR:usrloc:wb_timer: inserting contact into
database failed
Feb 29 14:59:15 [99776] DBG:db_mysql:has_stmt_ctx: ctx found for location
Feb 29 14:59:15 [99776] DBG:db_mysql:db_mysql_do_prepared_query:
conn=0x821d290 (tail=136434504) MC=0x821d37c
Feb 29 14:59:15 [99776] DBG:db_mysql:db_mysql_do_prepared_query: set values
for the statement run
Feb 29 14:59:15 [99776] DBG:db_mysql:db_mysql_val2bind: added val (0):
len=3; type=254; is_null=0
Feb 29 14:59:15 [99776] DBG:db_mysql:db_mysql_val2bind: added val (1):
len=1021; type=254; is_null=0
Feb 29 14:59:15 [99776] DBG:db_mysql:db_mysql_val2bind: added val (2):
len=36; type=12; is_null=0
Feb 29 14:59:15 [99776] DBG:db_mysql:db_mysql_val2bind: added val (3):
len=8; type=5; is_null=0
Feb 29 14:59:15 [99776] DBG:db_mysql:db_mysql_val2bind: added val (4):
len=31; type=254; is_null=0
Feb 29 14:59:15 [99776] DBG:db_mysql:db_mysql_val2bind: added val (5):
len=4; type=3; is_null=0
Feb 29 14:59:15 [99776] DBG:db_mysql:db_mysql_val2bind: added val (6):
len=4; type=3; is_null=0
Feb 29 14:59:15 [99776] DBG:db_mysql:db_mysql_val2bind: added val (7):
len=4; type=3; is_null=0
Feb 29 14:59:15 [99776] DBG:db_mysql:db_mysql_val2bind: added val (8):
len=3; type=254; is_null=0
Feb 29 14:59:15 [99776] DBG:db_mysql:db_mysql_val2bind: added val (11):
len=22; type=254; is_null=0
Feb 29 14:59:15 [99776] DBG:db_mysql:db_mysql_val2bind: added val (13):
len=36; type=12; is_null=0
Feb 29 14:59:15 [99776] DBG:db_mysql:db_mysql_do_prepared_query: doing
BIND_PARAM in...
Feb 29 14:59:15 [99776]
CRITICAL:db_mysql:wrapper_single_mysql_stmt_execute: driver error (1062):
Duplicate entry
'555--sip:7875609@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@' for key
'account_contact_idx'
Feb 29 14:59:15 [99776] ERROR:usrloc:db_insert_ucontact: inserting contact
in db failed
Feb 29 14:59:15 [99776] ERROR:usrloc:wb_timer: inserting contact into
database failed
Feb 29 14:59:15 [99776] DBG:usrloc:mem_timer_udomain: usrloc timer
attempting to flush rows to DB
Feb 29 14:59:15 [99776] DBG:tm:utimer_routine: timer
routine:4,tl=0x28c2a08c next=0x28bfde44, timeout=1410800000
Feb 29 14:59:15 [99776] DBG:tm:utimer_routine: timer
routine:4,tl=0x28bfde44 next=0x0, timeout=1410800000
Feb 29 14:59:20 [99776] DBG:tm:timer_routine: timer routine:2,tl=0x28c29f88
next=0x28bfdd40, timeout=1415
Feb 29 14:59:20 [99776] DBG:tm:wait_handler: removing 0x28c29f40 from table
Feb 29 14:59:20 [99776] DBG:tm:delete_cell: delete transaction 0x28c29f40
Feb 29 14:59:20 [99776] DBG:tm:wait_handler: done
Feb 29 14:59:20 [99776] DBG:tm:timer_routine: timer routine:2,tl=0x28bfdd40
next=0x0, timeout=1415
Feb 29 14:59:20 [99776] DBG:tm:wait_handler: removing 0x28bfdcf8 from table
Feb 29 14:59:20 [99776] DBG:tm:delete_cell: delete transaction 0x28bfdcf8
Feb 29 14:59:20 [99776] DBG:tm:wait_handler: done
Feb 29 14:59:38 [99773] DBG:core:parse_msg: SIP Request:
Feb 29 14:59:38 [99773] DBG:core:parse_msg:  method:  <OPTIONS>
Feb 29 14:59:38 [99773] DBG:core:parse_msg:  uri:    
<sip:373 at 10.192.100.89:5060>
Feb 29 14:59:38 [99773] DBG:core:parse_msg:  version: <SIP/2.0>
Feb 29 14:59:38 [99773] DBG:core:parse_headers: flags=2
Feb 29 14:59:38 [99773] DBG:core:parse_via_param: found param type 232,
<branch> = <z9hG4bK74012d0d>; state=6
Feb 29 14:59:38 [99773] DBG:core:parse_via_param: found param type 235,
<rport> = <n/a>; state=17
Feb 29 14:59:38 [99773] DBG:core:parse_via: end of header reached, state=5
Feb 29 14:59:38 [99773] DBG:core:parse_headers: via found, flags=2
Feb 29 14:59:38 [99773] DBG:core:parse_headers: this is the first via
Feb 29 14:59:38 [99773] DBG:core:receive_msg: After parse_msg...
Feb 29 14:59:38 [99773] DBG:core:receive_msg: preparing to run routing
scripts...
Feb 29 14:59:38 [99773] DBG:pike:mark_node: search on branch 87 (top=0x0)
Feb 29 14:59:38 [99773] DBG:pike:mark_node: only first 0 were matched!
Feb 29 14:59:38 [99773] DBG:pike:pike_check_req: src IP
[87.249.10.60],node=0x28b8b0b4; hits=[0,1],[0,0] node_flags=0 func_flags=1
Feb 29 14:59:38 [99773] DBG:pike:append_to_timer: 0x28b8b0c4 in
0x28b5efe4(0x28b5efe4,0x28b5efe4)
Feb 29 14:59:38 [99773] DBG:core:check_ip_address: params 87.249.10.60,
87.249.10.60, 0
Feb 29 14:59:38 [99773] DBG:core:parse_headers: flags=ffffffffffffffff
Feb 29 14:59:38 [99773] DBG:core:parse_to: end of header reached, state=10
Feb 29 14:59:38 [99773] DBG:core:parse_to: display={},
ruri={sip:373 at 10.192.100.89:5060}
Feb 29 14:59:38 [99773] DBG:core:get_hdr_field: <To> [30];
uri=[sip:373 at 10.192.100.89:5060]
Feb 29 14:59:38 [99773] DBG:core:get_hdr_field: to body
[<sip:373 at 10.192.100.89:5060>
]
Feb 29 14:59:38 [99773] DBG:core:get_hdr_field: cseq <CSeq>: <102>
<OPTIONS>
Feb 29 14:59:38 [99773] DBG:core:get_hdr_field: content_length=0
Feb 29 14:59:38 [99773] DBG:core:get_hdr_field: found end of header
Feb 29 14:59:38 [99773] DBG:maxfwd:is_maxfwd_present: value = 70
Feb 29 14:59:38 [99773] DBG:core:parse_to_param: tag=as27c19fc7
Feb 29 14:59:38 [99773] DBG:core:parse_to: end of header reached, state=29
Feb 29 14:59:38 [99773] DBG:core:parse_to: display={"Unknown"},
ruri={sip:Unknown at 87.249.10.60}
Feb 29 14:59:38 [99773] DBG:core:parse_headers: flags=ffffffffffffffff
Feb 29 14:59:38 [99773] DBG:core:destroy_avp_list: destroying list 0x0
Feb 29 14:59:38 [99773] DBG:core:receive_msg: cleaning up
Feb 29 14:59:45 [99776] DBG:dispatcher:ds_check_timer: probing set #1, URI
sip:10.192.118.99:5060
Feb 29 14:59:45 [99776] DBG:tm:t_uac: next_hop=<sip:10.192.118.99:5060>
Feb 29 14:59:45 [99776] DBG:core:mk_proxy: doing DNS lookup...
Feb 29 14:59:45 [99776] DBG:tm:dlg2hash: 39154
Feb 29 14:59:45 [99776] DBG:tm:print_request_uri: sip:10.192.118.99:5060
Feb 29 14:59:45 [99776] DBG:tm:set_timer: relative timeout is 500000
Feb 29 14:59:45 [99776] DBG:tm:insert_timer_unsafe: [4]: 0x28bfde44
(1440800000)
Feb 29 14:59:45 [99776] DBG:tm:set_timer: relative timeout is 10
Feb 29 14:59:45 [99776] DBG:tm:insert_timer_unsafe: [0]: 0x28bfde60 (1450)
Feb 29 14:59:45 [99776] DBG:dispatcher:ds_check_timer: probing set #1, URI
sip:10.192.118.99:5060
Feb 29 14:59:45 [99776] DBG:tm:t_uac: next_hop=<sip:10.192.118.99:5060>
Feb 29 14:59:45 [99776] DBG:core:mk_proxy: doing DNS lookup...
Feb 29 14:59:45 [99776] DBG:tm:dlg2hash: 39155
Feb 29 14:59:45 [99776] DBG:tm:print_request_uri: sip:10.192.118.99:5060
Feb 29 14:59:45 [99776] DBG:tm:set_timer: relative timeout is 500000
Feb 29 14:59:45 [99776] DBG:tm:insert_timer_unsafe: [4]: 0x28c2a08c
(1440800000)
Feb 29 14:59:45 [99776] DBG:tm:set_timer: relative timeout is 10
Feb 29 14:59:45 [99776] DBG:tm:insert_timer_unsafe: [0]: 0x28c2a0a8 (1450)
Feb 29 14:59:45 [99776] DBG:db_mysql:has_stmt_ctx: ctx found for location
Feb 29 14:59:45 [99776] DBG:db_mysql:db_mysql_do_prepared_query:
conn=0x821d290 (tail=136434504) MC=0x821d37c
Feb 29 14:59:45 [99776] DBG:db_mysql:db_mysql_do_prepared_query: set values
for the statement run
Feb 29 14:59:45 [99776] DBG:db_mysql:db_mysql_val2bind: added val (0):
len=3; type=254; is_null=0
Feb 29 14:59:45 [99776] DBG:db_mysql:db_mysql_val2bind: added val (1):
len=521; type=254; is_null=0
Feb 29 14:59:45 [99776] DBG:db_mysql:db_mysql_val2bind: added val (2):
len=36; type=12; is_null=0
Feb 29 14:59:45 [99776] DBG:db_mysql:db_mysql_val2bind: added val (3):
len=8; type=5; is_null=0
Feb 29 14:59:45 [99776] DBG:db_mysql:db_mysql_val2bind: added val (4):
len=31; type=254; is_null=0
Feb 29 14:59:45 [99776] DBG:db_mysql:db_mysql_val2bind: added val (5):
len=4; type=3; is_null=0
Feb 29 14:59:45 [99776] DBG:db_mysql:db_mysql_val2bind: added val (6):
len=4; type=3; is_null=0
Feb 29 14:59:45 [99776] DBG:db_mysql:db_mysql_val2bind: added val (7):
len=4; type=3; is_null=0
Feb 29 14:59:45 [99776] DBG:db_mysql:db_mysql_val2bind: added val (8):
len=3; type=254; is_null=0
Feb 29 14:59:45 [99776] DBG:db_mysql:db_mysql_val2bind: added val (11):
len=22; type=254; is_null=0
Feb 29 14:59:45 [99776] DBG:db_mysql:db_mysql_val2bind: added val (13):
len=36; type=12; is_null=0
Feb 29 14:59:45 [99776] DBG:db_mysql:db_mysql_do_prepared_query: doing
BIND_PARAM in...
Feb 29 14:59:45 [99773] DBG:core:parse_msg: SIP Reply  (status):
Feb 29 14:59:45 [99773] DBG:core:parse_msg:  version: <SIP/2.0>
Feb 29 14:59:45 [99773] DBG:core:parse_msg:  status:  <200>
Feb 29 14:59:45 [99773] DBG:core:parse_msg:  reason:  <OK>
Feb 29 14:59:45 [99773] DBG:core:parse_headers: flags=2
Feb 29 14:59:45 [99773] DBG:core:parse_via_param: found param type 232,
<branch> = <z9hG4bK2f89.bca1d147.0>; state=6
Feb 29 14:59:45 [99773] DBG:core:parse_via_param: found param type 234,
<received> = <10.192.118.98>; state=16
Feb 29 14:59:45 [99773] DBG:core:parse_via: end of header reached, state=5
Feb 29 14:59:45 [99773] DBG:core:parse_headers: via found, flags=2
Feb 29 14:59:45 [99773] DBG:core:parse_headers: this is the first via
Feb 29 14:59:45 [99773] DBG:core:receive_msg: After parse_msg...
Feb 29 14:59:45 [99773] DBG:core:forward_reply: found module tm, passing
reply to it
Feb 29 14:59:45 [99773] DBG:tm:t_check: start=0xffffffff
Feb 29 14:59:45 [99773] DBG:core:parse_headers: flags=22
Feb 29 14:59:45 [99773] DBG:core:parse_to_param: tag=as68688d69
Feb 29 14:59:45 [99773] DBG:core:parse_to: end of header reached, state=29
Feb 29 14:59:45 [99773] DBG:core:parse_to: display={},
ruri={sip:10.192.118.99:5060}
Feb 29 14:59:45 [99773] DBG:core:get_hdr_field: <To> [39];
uri=[sip:10.192.118.99:5060]
Feb 29 14:59:45 [99773] DBG:core:get_hdr_field: to body
[sip:10.192.118.99:5060]
Feb 29 14:59:45 [99773] DBG:core:get_hdr_field: cseq <CSeq>: <14> <OPTIONS>
Feb 29 14:59:45 [99773] DBG:tm:t_reply_matching: hash 39154 label
1948064459 branch 0
Feb 29 14:59:45 [99773] DBG:tm:t_reply_matching: REF_UNSAFE:[0x28bfdcf8]
after is 1
Feb 29 14:59:45 [99773] DBG:tm:t_reply_matching: reply matched
(T=0x28bfdcf8)!
Feb 29 14:59:45 [99773] DBG:tm:t_check: end=0x28bfdcf8
Feb 29 14:59:45 [99773] DBG:tm:reply_received: org. status uas=0, uac[0]=0
local=2 is_invite=0)
Feb 29 14:59:45 [99773] DBG:tm:t_should_relay_response: T_code=0,
new_code=200
Feb 29 14:59:45 [99773] DBG:tm:local_reply: branch=0, save=0, winner=0
Feb 29 14:59:45 [99773] DBG:tm:local_reply: local transaction completed
Feb 29 14:59:45 [99773] DBG:tm:run_trans_callbacks: trans=0x28bfdcf8,
callback type 256, id 0 entered
Feb 29 14:59:45 [99773] DBG:dispatcher:ds_options_callback: OPTIONS-Request
was finished with code 200 (to sip:10.192.118.99:5060, group 1)
Feb 29 14:59:45 [99773] DBG:dispatcher:ds_set_state: no event sent
Feb 29 14:59:45 [99773] DBG:tm:cleanup_uac_timers: RETR/FR timers reset
Feb 29 14:59:45 [99773] DBG:tm:insert_timer_unsafe: [2]: 0x28bfdd40 (1445)
Feb 29 14:59:45 [99773] DBG:tm:t_unref: UNREF_UNSAFE: [0x28bfdcf8] after is
0
Feb 29 14:59:45 [99773] DBG:core:destroy_avp_list: destroying list 0x0
Feb 29 14:59:45 [99773] DBG:core:receive_msg: cleaning up
Feb 29 14:59:45 [99773] DBG:core:parse_msg: SIP Reply  (status):
Feb 29 14:59:45 [99773] DBG:core:parse_msg:  version: <SIP/2.0>
Feb 29 14:59:45 [99776]
CRITICAL:db_mysql:wrapper_single_mysql_stmt_execute: driver error (1062):
Duplicate entry
'555--sip::::::::::::::::::::::::::::::::::::::::::::::::::::::::' for key
'account_contact_idx'
Feb 29 14:59:45 [99773] DBG:core:parse_msg:  status:  <200>
Feb 29 14:59:45 [99776] ERROR:usrloc:db_insert_ucontact: inserting contact
in db failed
Feb 29 14:59:45 [99773] DBG:core:parse_msg:  reason:  <OK>
Feb 29 14:59:45 [99776] ERROR:usrloc:wb_timer: inserting contact into
database failed
Feb 29 14:59:45 [99773] DBG:core:parse_headers: flags=2
Feb 29 14:59:45 [99776] DBG:db_mysql:has_stmt_ctx: ctx found for location
Feb 29 14:59:45 [99773] DBG:core:parse_via_param: found param type 232,
<branch> = <z9hG4bK3f89.bf04ac22.0>; state=6
Feb 29 14:59:45 [99776] DBG:db_mysql:db_mysql_do_prepared_query:
conn=0x821d290 (tail=136434504) MC=0x821d37c
Feb 29 14:59:45 [99773] DBG:core:parse_via_param: found param type 234,
<received> = <10.192.118.98>; state=16
Feb 29 14:59:45 [99776] DBG:db_mysql:db_mysql_do_prepared_query: set values
for the statement run
Feb 29 14:59:45 [99773] DBG:core:parse_via: end of header reached, state=5
Feb 29 14:59:45 [99776] DBG:db_mysql:db_mysql_val2bind: added val (0):
len=3; type=254; is_null=0
Feb 29 14:59:45 [99773] DBG:core:parse_headers: via found, flags=2
Feb 29 14:59:45 [99776] DBG:db_mysql:db_mysql_val2bind: added val (1):
len=1021; type=254; is_null=0
Feb 29 14:59:45 [99773] DBG:core:parse_headers: this is the first via
Feb 29 14:59:45 [99776] DBG:db_mysql:db_mysql_val2bind: added val (2):
len=36; type=12; is_null=0
Feb 29 14:59:45 [99773] DBG:core:receive_msg: After parse_msg...
Feb 29 14:59:45 [99776] DBG:db_mysql:db_mysql_val2bind: added val (3):
len=8; type=5; is_null=0
Feb 29 14:59:45 [99773] DBG:core:forward_reply: found module tm, passing
reply to it
Feb 29 14:59:45 [99776] DBG:db_mysql:db_mysql_val2bind: added val (4):
len=31; type=254; is_null=0
Feb 29 14:59:45 [99773] DBG:tm:t_check: start=0xffffffff
Feb 29 14:59:45 [99776] DBG:db_mysql:db_mysql_val2bind: added val (5):
len=4; type=3; is_null=0
Feb 29 14:59:45 [99773] DBG:core:parse_headers: flags=22
Feb 29 14:59:45 [99776] DBG:db_mysql:db_mysql_val2bind: added val (6):
len=4; type=3; is_null=0
Feb 29 14:59:45 [99773] DBG:core:parse_to_param: tag=as5b225918
Feb 29 14:59:45 [99776] DBG:db_mysql:db_mysql_val2bind: added val (7):
len=4; type=3; is_null=0
Feb 29 14:59:45 [99773] DBG:core:parse_to: end of header reached, state=29
Feb 29 14:59:45 [99776] DBG:db_mysql:db_mysql_val2bind: added val (8):
len=3; type=254; is_null=0
Feb 29 14:59:45 [99773] DBG:core:parse_to: display={},
ruri={sip:10.192.118.99:5060}
Feb 29 14:59:45 [99776] DBG:db_mysql:db_mysql_val2bind: added val (11):
len=22; type=254; is_null=0
Feb 29 14:59:45 [99773] DBG:core:get_hdr_field: <To> [39];
uri=[sip:10.192.118.99:5060]
Feb 29 14:59:45 [99776] DBG:db_mysql:db_mysql_val2bind: added val (13):
len=36; type=12; is_null=0
Feb 29 14:59:45 [99773] DBG:core:get_hdr_field: to body
[sip:10.192.118.99:5060]
Feb 29 14:59:45 [99776] DBG:db_mysql:db_mysql_do_prepared_query: doing
BIND_PARAM in...
Feb 29 14:59:45 [99773] DBG:core:get_hdr_field: cseq <CSeq>: <14> <OPTIONS>
Feb 29 14:59:45 [99773] DBG:tm:t_reply_matching: hash 39155 label 583680251
branch 0
Feb 29 14:59:45 [99773] DBG:tm:t_reply_matching: REF_UNSAFE:[0x28c29f40]
after is 1
Feb 29 14:59:45 [99773] DBG:tm:t_reply_matching: reply matched
(T=0x28c29f40)!
Feb 29 14:59:45 [99773] DBG:tm:t_check: end=0x28c29f40
Feb 29 14:59:45 [99773] DBG:tm:reply_received: org. status uas=0, uac[0]=0
local=2 is_invite=0)
Feb 29 14:59:45 [99773] DBG:tm:t_should_relay_response: T_code=0,
new_code=200
Feb 29 14:59:45 [99773] DBG:tm:local_reply: branch=0, save=0, winner=0
Feb 29 14:59:45 [99773] DBG:tm:local_reply: local transaction completed
Feb 29 14:59:45 [99773] DBG:tm:run_trans_callbacks: trans=0x28c29f40,
callback type 256, id 0 entered
Feb 29 14:59:45 [99773] DBG:dispatcher:ds_options_callback: OPTIONS-Request
was finished with code 200 (to sip:10.192.118.99:5060, group 1)
Feb 29 14:59:45 [99773] DBG:dispatcher:ds_set_state: no event sent
Feb 29 14:59:45 [99773] DBG:tm:cleanup_uac_timers: RETR/FR timers reset
Feb 29 14:59:45 [99773] DBG:tm:insert_timer_unsafe: [2]: 0x28c29f88 (1445)
Feb 29 14:59:45 [99773] DBG:tm:t_unref: UNREF_UNSAFE: [0x28c29f40] after is
0
Feb 29 14:59:45 [99773] DBG:core:destroy_avp_list: destroying list 0x0
Feb 29 14:59:45 [99773] DBG:core:receive_msg: cleaning up
Feb 29 14:59:45 [99776]
CRITICAL:db_mysql:wrapper_single_mysql_stmt_execute: driver error (1062):
Duplicate entry
'555--sip::::::::::::::::::::::::::::::::::::::::::::::::::::::::' for key
'account_contact_idx'
Feb 29 14:59:45 [99776] ERROR:usrloc:db_insert_ucontact: inserting contact
in db failed
Feb 29 14:59:45 [99776] ERROR:usrloc:wb_timer: inserting contact into
database failed
Feb 29 14:59:45 [99776] DBG:db_mysql:has_stmt_ctx: ctx found for location
Feb 29 14:59:45 [99776] DBG:db_mysql:db_mysql_do_prepared_query:
conn=0x821d290 (tail=136434504) MC=0x821d37c
Feb 29 14:59:45 [99776] DBG:db_mysql:db_mysql_do_prepared_query: set values
for the statement run
Feb 29 14:59:45 [99776] DBG:db_mysql:db_mysql_val2bind: added val (0):
len=3; type=254; is_null=0
Feb 29 14:59:45 [99776] DBG:db_mysql:db_mysql_val2bind: added val (1):
len=521; type=254; is_null=0
Feb 29 14:59:45 [99776] DBG:db_mysql:db_mysql_val2bind: added val (2):
len=36; type=12; is_null=0
Feb 29 14:59:45 [99776] DBG:db_mysql:db_mysql_val2bind: added val (3):
len=8; type=5; is_null=0
Feb 29 14:59:45 [99776] DBG:db_mysql:db_mysql_val2bind: added val (4):
len=31; type=254; is_null=0
Feb 29 14:59:45 [99776] DBG:db_mysql:db_mysql_val2bind: added val (5):
len=4; type=3; is_null=0
Feb 29 14:59:45 [99776] DBG:db_mysql:db_mysql_val2bind: added val (6):
len=4; type=3; is_null=0
Feb 29 14:59:45 [99776] DBG:db_mysql:db_mysql_val2bind: added val (7):
len=4; type=3; is_null=0
Feb 29 14:59:45 [99776] DBG:db_mysql:db_mysql_val2bind: added val (8):
len=3; type=254; is_null=0
Feb 29 14:59:45 [99776] DBG:db_mysql:db_mysql_val2bind: added val (11):
len=22; type=254; is_null=0
Feb 29 14:59:45 [99776] DBG:db_mysql:db_mysql_val2bind: added val (13):
len=36; type=12; is_null=0
Feb 29 14:59:45 [99776] DBG:db_mysql:db_mysql_do_prepared_query: doing
BIND_PARAM in...
Feb 29 14:59:45 [99776]
CRITICAL:db_mysql:wrapper_single_mysql_stmt_execute: driver error (1062):
Duplicate entry
'555--sip:7875609@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@' for key
'account_contact_idx'
Feb 29 14:59:45 [99776] ERROR:usrloc:db_insert_ucontact: inserting contact
in db failed
Feb 29 14:59:45 [99776] ERROR:usrloc:wb_timer: inserting contact into
database failed
Feb 29 14:59:45 [99776] DBG:db_mysql:has_stmt_ctx: ctx found for location
Feb 29 14:59:45 [99776] DBG:db_mysql:db_mysql_do_prepared_query:
conn=0x821d290 (tail=136434504) MC=0x821d37c
Feb 29 14:59:45 [99776] DBG:db_mysql:db_mysql_do_prepared_query: set values
for the statement run
Feb 29 14:59:45 [99776] DBG:db_mysql:db_mysql_val2bind: added val (0):
len=3; type=254; is_null=0
Feb 29 14:59:45 [99776] DBG:db_mysql:db_mysql_val2bind: added val (1):
len=1021; type=254; is_null=0
Feb 29 14:59:45 [99776] DBG:db_mysql:db_mysql_val2bind: added val (2):
len=36; type=12; is_null=0
Feb 29 14:59:45 [99776] DBG:db_mysql:db_mysql_val2bind: added val (3):
len=8; type=5; is_null=0
Feb 29 14:59:45 [99776] DBG:db_mysql:db_mysql_val2bind: added val (4):
len=31; type=254; is_null=0
Feb 29 14:59:45 [99776] DBG:db_mysql:db_mysql_val2bind: added val (5):
len=4; type=3; is_null=0
Feb 29 14:59:45 [99776] DBG:db_mysql:db_mysql_val2bind: added val (6):
len=4; type=3; is_null=0
Feb 29 14:59:45 [99776] DBG:db_mysql:db_mysql_val2bind: added val (7):
len=4; type=3; is_null=0
Feb 29 14:59:45 [99776] DBG:db_mysql:db_mysql_val2bind: added val (8):
len=3; type=254; is_null=0
Feb 29 14:59:45 [99776] DBG:db_mysql:db_mysql_val2bind: added val (11):
len=22; type=254; is_null=0
Feb 29 14:59:45 [99776] DBG:db_mysql:db_mysql_val2bind: added val (13):
len=36; type=12; is_null=0
Feb 29 14:59:45 [99776] DBG:db_mysql:db_mysql_do_prepared_query: doing
BIND_PARAM in...
Feb 29 14:59:45 [99776]
CRITICAL:db_mysql:wrapper_single_mysql_stmt_execute: driver error (1062):
Duplicate entry
'555--sip:7875609@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@' for key
'account_contact_idx'
Feb 29 14:59:45 [99776] ERROR:usrloc:db_insert_ucontact: inserting contact
in db failed
Feb 29 14:59:45 [99776] ERROR:usrloc:wb_timer: inserting contact into
database failed
Feb 29 14:59:45 [99776] DBG:usrloc:mem_timer_udomain: usrloc timer
attempting to flush rows to DB
Feb 29 14:59:46 [99776] DBG:tm:utimer_routine: timer
routine:4,tl=0x28bfde44 next=0x28c2a08c, timeout=1440800000
Feb 29 14:59:46 [99776] DBG:tm:utimer_routine: timer
routine:4,tl=0x28c2a08c next=0x0, timeout=1440800000
Feb 29 14:59:50 [99776] DBG:tm:timer_routine: timer routine:2,tl=0x28bfdd40
next=0x28c29f88, timeout=1445
Feb 29 14:59:50 [99776] DBG:tm:wait_handler: removing 0x28bfdcf8 from table
Feb 29 14:59:50 [99776] DBG:tm:delete_cell: delete transaction 0x28bfdcf8
Feb 29 14:59:50 [99776] DBG:tm:wait_handler: done
Feb 29 14:59:50 [99776] DBG:tm:timer_routine: timer routine:2,tl=0x28c29f88
next=0x0, timeout=1445
Feb 29 14:59:50 [99776] DBG:tm:wait_handler: removing 0x28c29f40 from table
Feb 29 14:59:50 [99776] DBG:tm:delete_cell: delete transaction 0x28c29f40
Feb 29 14:59:50 [99776] DBG:tm:wait_handler: done

simpletest# Feb 29 15:00:15 [99776] DBG:dispatcher:ds_check_timer: probing
set #1, URI sip:10.192.118.99:5060
Feb 29 15:00:15 [99776] DBG:tm:t_uac: next_hop=<sip:10.192.118.99:5060>
Feb 29 15:00:15 [99776] DBG:core:mk_proxy: doing DNS lookup...
Feb 29 15:00:15 [99776] DBG:tm:dlg2hash: 39169
Feb 29 15:00:15 [99776] DBG:tm:print_request_uri: sip:10.192.118.99:5060
Feb 29 15:00:15 [99776] DBG:tm:set_timer: relative timeout is 500000
Feb 29 15:00:15 [99776] DBG:tm:insert_timer_unsafe: [4]: 0x28c2a08c
(1470800000)
Feb 29 15:00:15 [99776] DBG:tm:set_timer: relative timeout is 10
Feb 29 15:00:15 [99776] DBG:tm:insert_timer_unsafe: [0]: 0x28c2a0a8 (1480)
Feb 29 15:00:15 [99776] DBG:dispatcher:ds_check_timer: probing set #1, URI
sip:10.192.118.99:5060
Feb 29 15:00:15 [99776] DBG:tm:t_uac: next_hop=<sip:10.192.118.99:5060>
Feb 29 15:00:15 [99776] DBG:core:mk_proxy: doing DNS lookup...
Feb 29 15:00:15 [99776] DBG:tm:dlg2hash: 39168
Feb 29 15:00:15 [99776] DBG:tm:print_request_uri: sip:10.192.118.99:5060
Feb 29 15:00:15 [99776] DBG:tm:set_timer: relative timeout is 500000
Feb 29 15:00:15 [99776] DBG:tm:insert_timer_unsafe: [4]: 0x28bfde44
(1470800000)
Feb 29 15:00:15 [99776] DBG:tm:set_timer: relative timeout is 10
Feb 29 15:00:15 [99776] DBG:tm:insert_timer_unsafe: [0]: 0x28bfde60 (1480)
Feb 29 15:00:15 [99776] DBG:db_mysql:has_stmt_ctx: ctx found for location
Feb 29 15:00:15 [99776] DBG:db_mysql:db_mysql_do_prepared_query:
conn=0x821d290 (tail=136434504) MC=0x821d37c
Feb 29 15:00:15 [99776] DBG:db_mysql:db_mysql_do_prepared_query: set values
for the statement run
Feb 29 15:00:15 [99776] DBG:db_mysql:db_mysql_val2bind: added val (0):
len=3; type=254; is_null=0
Feb 29 15:00:15 [99776] DBG:db_mysql:db_mysql_val2bind: added val (1):
len=521; type=254; is_null=0
Feb 29 15:00:15 [99776] DBG:db_mysql:db_mysql_val2bind: added val (2):
len=36; type=12; is_null=0
Feb 29 15:00:15 [99776] DBG:db_mysql:db_mysql_val2bind: added val (3):
len=8; type=5; is_null=0
Feb 29 15:00:15 [99776] DBG:db_mysql:db_mysql_val2bind: added val (4):
len=31; type=254; is_null=0
Feb 29 15:00:15 [99776] DBG:db_mysql:db_mysql_val2bind: added val (5):
len=4; type=3; is_null=0
Feb 29 15:00:15 [99776] DBG:db_mysql:db_mysql_val2bind: added val (6):
len=4; type=3; is_null=0
Feb 29 15:00:15 [99776] DBG:db_mysql:db_mysql_val2bind: added val (7):
len=4; type=3; is_null=0
Feb 29 15:00:15 [99776] DBG:db_mysql:db_mysql_val2bind: added val (8):
len=3; type=254; is_null=0
Feb 29 15:00:15 [99776] DBG:db_mysql:db_mysql_val2bind: added val (11):
len=22; type=254; is_null=0
Feb 29 15:00:15 [99776] DBG:db_mysql:db_mysql_val2bind: added val (13):
len=36; type=12; is_null=0
Feb 29 15:00:15 [99776] DBG:db_mysql:db_mysql_do_prepared_query: doing
BIND_PARAM in...
Feb 29 15:00:15 [99773] DBG:core:parse_msg: SIP Reply  (status):
Feb 29 15:00:15 [99773] DBG:core:parse_msg:  version: <SIP/2.0>
Feb 29 15:00:15 [99773] DBG:core:parse_msg:  status:  <200>
Feb 29 15:00:15 [99773] DBG:core:parse_msg:  reason:  <OK>
Feb 29 15:00:15 [99773] DBG:core:parse_headers: flags=2
Feb 29 15:00:15 [99773] DBG:core:parse_via_param: found param type 232,
<branch> = <z9hG4bK1099.80ffb331.0>; state=6
Feb 29 15:00:15 [99773] DBG:core:parse_via_param: found param type 234,
<received> = <10.192.118.98>; state=16
Feb 29 15:00:15 [99773] DBG:core:parse_via: end of header reached, state=5
Feb 29 15:00:15 [99773] DBG:core:parse_headers: via found, flags=2
Feb 29 15:00:15 [99773] DBG:core:parse_headers: this is the first via
Feb 29 15:00:15 [99773] DBG:core:receive_msg: After parse_msg...
Feb 29 15:00:15 [99773] DBG:core:forward_reply: found module tm, passing
reply to it
Feb 29 15:00:15 [99773] DBG:tm:t_check: start=0xffffffff
Feb 29 15:00:15 [99773] DBG:core:parse_headers: flags=22
Feb 29 15:00:15 [99773] DBG:core:parse_to_param: tag=as184fb609
Feb 29 15:00:15 [99773] DBG:core:parse_to: end of header reached, state=29
Feb 29 15:00:15 [99773] DBG:core:parse_to: display={},
ruri={sip:10.192.118.99:5060}
Feb 29 15:00:15 [99773] DBG:core:get_hdr_field: <To> [39];
uri=[sip:10.192.118.99:5060]
Feb 29 15:00:15 [99773] DBG:core:get_hdr_field: to body
[sip:10.192.118.99:5060]
Feb 29 15:00:15 [99773] DBG:core:get_hdr_field: cseq <CSeq>: <14> <OPTIONS>
Feb 29 15:00:15 [99773] DBG:tm:t_reply_matching: hash 39169 label 322699016
branch 0
Feb 29 15:00:15 [99773] DBG:tm:t_reply_matching: REF_UNSAFE:[0x28c29f40]
after is 1
Feb 29 15:00:15 [99773] DBG:tm:t_reply_matching: reply matched
(T=0x28c29f40)!
Feb 29 15:00:15 [99773] DBG:tm:t_check: end=0x28c29f40
Feb 29 15:00:15 [99773] DBG:tm:reply_received: org. status uas=0, uac[0]=0
local=2 is_invite=0)
Feb 29 15:00:15 [99773] DBG:tm:t_should_relay_response: T_code=0,
new_code=200
Feb 29 15:00:15 [99773] DBG:tm:local_reply: branch=0, save=0, winner=0
Feb 29 15:00:15 [99773] DBG:tm:local_reply: local transaction completed
Feb 29 15:00:15 [99773] DBG:tm:run_trans_callbacks: trans=0x28c29f40,
callback type 256, id 0 entered
Feb 29 15:00:15 [99773] DBG:dispatcher:ds_options_callback: OPTIONS-Request
was finished with code 200 (to sip:10.192.118.99:5060, group 1)
Feb 29 15:00:15 [99776]
CRITICAL:db_mysql:wrapper_single_mysql_stmt_execute: driver error (1062):
Duplicate entry
'555--sip::::::::::::::::::::::::::::::::::::::::::::::::::::::::' for key
'account_contact_idx'
################################
Maybe add some more checks before inserting contact into database.
You can reproduce this errors with bruteforcing OpenSIPS with SiVuS Voip
Vulnerability scanner or by sending incomplete/broken(or using some buggy
hardware/software) register packets and then restarting proxy server.

P.S. Also you can find a lot of interesting information by using this tool,
like proxy passing this packet to my dispatched asterisk:
<--- SIP read from 10.192.118.98:5060 --->
INVITE sip:7875609 at simpletest.tel.ru
SIP/2....................................................................................................0
Record-Route: <sip:10.192.118.98;lr;ftag=1928301774>
Via: SIP/2.0/UDP 10.192.118.98;branch=z9hG4bK2ef6.ab667965.0
Via: SIP/2.0/UDP
10.1.1.100;rport=50537;received=87.249.10.61;branch=GkeKfeIlyi85jcn
To: 7875609 <SIP:7875609 at simpletest.tel.ru>
From: 555 <SIP:555 at 10.1.1.200>;tag=1928301774
CSeq: 99094 INVITE
Call-ID: 5kBnqlY63KONJRPqIIVf at simpletest.tel.ru
Max-Forwards: 69
Date: Wed Feb 29 14:51:32 GMT+04:00 2012
Contact: <sip:555 at 87.249.10.61:50537>
Subject: 10114.1
Content-Type: application/sdp
Content-Length: 0
Source-IP: 87.249.10.61

<------------->
Asterisk warn:
[Feb 29 13:40:58] WARNING[19482]: chan_sip.c:7442
determine_firstline_parts: Bad request protocol
SIP/2....................................................................................................0
Maybe add some additional checks?

----------------------------------------------------------------------

Comment By: Vladut-Stefan Paiu (vladut-paiu)
Date: 2012-02-23 03:13

Message:
Hi,

Please open another bug report for the dialog issue, and please also attach
there the SIP trace and the full OpenSIPS log for a call that gets stuck.

For the current bug, please upload the full debug OpenSIPS logs for a
restart that caused the stuck location entry.

Regards,
Vlad

----------------------------------------------------------------------

Comment By: Nobody/Anonymous (nobody)
Date: 2012-02-23 01:51

Message:
We restart the proxy because of another bug with hanged dialogs in state
3...
http://lists.opensips.org/pipermail/users/2011-February/016721.html
Limiting concurrent calls but dialogs stuck so users can't make calls.. so
it is another story)
Bug over the bug :)

----------------------------------------------------------------------

Comment By: Nobody/Anonymous (nobody)
Date: 2012-02-23 01:49

Message:
Yes, after restart. I'll try to upgrade to version 1.7.2 and see what's
changed.

----------------------------------------------------------------------

Comment By: Vladut-Stefan Paiu (vladut-paiu)
Date: 2012-02-21 04:22

Message:
Hi,

So you are saying that the stuck location entries only happen when you do a
restart on the proxy ?
Is it possible to get the full debug OpenSIPS logs for a restart that
caused the stuck location entry ?

Regards,
Vlad

----------------------------------------------------------------------

Comment By: Nobody/Anonymous (nobody)
Date: 2012-02-21 03:57

Message:
Yes, this is proxy restart problem.
One more stuck record:
Feb 21 15:51:43 SimpleOffice-1 /usr/local/sbin/opensips[21827]:
CRITICAL:db_mysql:wrapper_single_mysql_stmt_execute: driver error (1062): D
                  x101--sip:419x101 at 10.192.116.142:5060' for key
'account_contact_idx'
Feb 21 15:51:43 SimpleOffice-1 /usr/local/sbin/opensips[21827]:
ERROR:usrloc:db_insert_ucontact: inserting contact in db failed
Feb 21 15:51:43 SimpleOffice-1 /usr/local/sbin/opensips[21827]:
ERROR:usrloc:wb_timer: inserting contact into database failed

+-------+----------+--------+---------------------------------+----------+------+---------------------+-------+--------------------------------------------+-------+---------------------+-------+--------+----------------------------------+------------------------+---------+
| id    | username | domain | contact                         | received |
path | expires             | q     | callid                                
    | cseq  | last_modified       | flags | cflags | user_agent            
          | socket                 | methods |
+-------+----------+--------+---------------------------------+----------+------+---------------------+-------+--------------------------------------------+-------+---------------------+-------+--------+----------------------------------+------------------------+---------+
| 44822 | 419x101  |        | sip:419x101 at 10.192.116.142:5060 | NULL     |
NULL | 2012-02-21 16:13:58 | -1.00 |
1BD1-859F-47539598E1C3E56C1892-705 at SipHost | 40722 | 2012-02-21 15:55:38 | 
   0 |      0 | dlink 12-37-61928258-0.9.5.1.735 | udp:87.249.26.210:5060 |
   NULL |
+-------+----------+--------+---------------------------------+----------+------+---------------------+-------+--------------------------------------------+-------+---------------------+-------+--------+----------------------------------+------------------------+---------+

Seems that some hardware sending register packets in wrong format and proxy
can't parse them correctly. After restart.

----------------------------------------------------------------------

Comment By: Nobody/Anonymous (nobody)
Date: 2012-02-20 02:50

Message:
Logs are clear...
2012-02-16 18:48:53 we restarted opensips... then this began to appear in
the logfile.
Another restart, again error in the logfile:
Feb 17 16:05:28 SimpleOffice-1 /usr/local/sbin/opensips[38705]:
CRITICAL:db_mysql:wrapper_single_mysql_stmt_execute: driver error (1062):
Duplicate entry 'sip:81.211.5.210:5060' for key 'account_contact_idx'

mysql> select count(*) from location;
+----------+
| count(*) |
+----------+
|     1429 |
+----------+

And only one record is buggy.. i think problem with importing data from
table location on proxy startup.

Tcpdump'ed packet from addpack:
REGISTER sip:87.249.26.210:5061 SIP/2.0
Via: SIP/2.0/UDP 81.211.5.210:5060;branch=z9hG4bKb54ffd01a443419
From: <sip:87.249.26.210>;tag=b54ffd01a4
To: <sip:87.249.26.210>
Call-ID: b5fb344f-efe7-fd41-8001-0002a4055cd0 at 81.211.5.210
CSeq: 43419 REGISTER
Date: Mon, 20 Feb 2012 14:12:58 GMT
User-Agent: AddPac SIP Gateway
Contact: <sip:81.211.5.210:5060>;expires=600
Expires: 600
Content-Length: 0
Max-Forwards: 70


----------------------------------------------------------------------

Comment By: Vladut-Stefan Paiu (vladut-paiu)
Date: 2012-02-20 01:19

Message:
Hello,

Do you, by any chance, still have any logs from the OpenSIPS and/or Mysql
side from 2012-02-16 18:48:53, the date when that specific contact should
have gotten expired & removed from DB ? I'm curious to see if there were
any relevant errors around that time.

Regards,
Vlad

----------------------------------------------------------------------

You can respond by visiting: 
https://sourceforge.net/tracker/?func=detail&atid=1086410&aid=3488471&group_id=232389

More information about the Devel mailing list