i tried again to start twinkle and this time got:
Jun 4 09:15:12 localhost /usr/sbin/sip-router[7304]: INFO: xlog [xlog.c:186]: INFO: REGISTER sip:test@test.fi by test@test.fi from <192.98.101.10> is authorized Jun 4 09:15:12 localhost /usr/sbin/sip-router[7269]: ERROR: db_mysql [km_dbase.c:117]: driver error on query: Commands out of sync; you can't run this command now Jun 4 09:15:12 localhost /usr/sbin/sip-router[7269]: ERROR: <core> [db_query.c:101]: error while submitting query
by the way, how to get rid of
"xlog [xlog.c:186]:"
in xlog INFO output?
-- juha
On 04-06 09:19, Juha Heinanen wrote:
i tried again to start twinkle and this time got:
Jun 4 09:15:12 localhost /usr/sbin/sip-router[7304]: INFO: xlog [xlog.c:186]: INFO: REGISTER sip:test@test.fi by test@test.fi from <192.98.101.10> is authorized Jun 4 09:15:12 localhost /usr/sbin/sip-router[7269]: ERROR: db_mysql [km_dbase.c:117]: driver error on query: Commands out of sync; you can't run this command now Jun 4 09:15:12 localhost /usr/sbin/sip-router[7269]: ERROR: <core> [db_query.c:101]: error while submitting query
Could you try to figure out which query is generating this error? There is a debug statement commented out on line 95 of km_dbase.c in db_mysql module, please, uncomment it and try again, it should print the query that generates this error in syslog.
Jan.
Jan Janak writes:
Jun 4 09:15:12 localhost /usr/sbin/sip-router[7304]: INFO: xlog [xlog.c:186]: INFO: REGISTER sip:test@test.fi by test@test.fi from <192.98.101.10> is authorized
actually there is also improvement in the above, i.e., log level INFO is printed automatically i could get rid of it in the bodies of my xlog messages. it just remains to get rid of "xlog [xlog.c:186]:" without making the xlog message more complicated.
-- juha
Jan Janak writes:
Could you try to figure out which query is generating this error? There is a debug statement commented out on line 95 of km_dbase.c in db_mysql module, please, uncomment it and try again, it should print the query that generates this error in syslog.
jan,
i uncommented the dbg message and changed it to info. looks like the problem may have something to do with msilo module. when ua registers, it is checked from db if there are some pending messages for it.
-- juha
Jun 4 12:57:45 localhost /usr/sbin/sip-router[20251]: INFO: xlog [xlog.c:186]: INFO: REGISTER sip:jh@test.fi by jh@test.fi from <192.98.101.10> is authorized Jun 4 12:57:45 localhost /usr/sbin/sip-router[20251]: INFO: db_mysql [km_dbase.c:98]: submit_query(): update location set expires='2009-06-04 13:57:45',q=0.50 ,cseq=441,flags=0,cflags=0,user_agent='Twinkle/1.4.2',received=NULL,path=NULL,socket='',methods=6111,last_modified='2009-06-04 12:57:45' where username='jh' AND contact='sip:jh_test_fi@192.98.101.10:5074;transport=udp' AND callid='ysunsysgskxufqy@localhost' AND domain='test.fi' Jun 4 12:57:45 localhost /usr/sbin/sip-router[20283]: INFO: xlog [xlog.c:186]: INFO: REGISTER sip:test@test.fi by test@test.fi from <192.98.101.10> is authorized Jun 4 12:57:45 localhost /usr/sbin/sip-router[20283]: INFO: db_mysql [km_dbase.c:98]: submit_query(): insert into location (username,contact,expires,q,callid,cseq,flags,cflags,user_agent,received,path,socket,methods,last_modified,domain ) values ('test','sip:test@192.98.101.10:5074;transport=tcp','2009-06-04 13:57:45',0.50 ,'xtbkpufsizzylnl@localhost',116,0,0,'Twinkle/1.4.2',NULL,NULL,'',6111,'2009-06-04 12:57:45','test.fi') Jun 4 12:57:45 localhost /usr/sbin/sip-router[20251]: INFO: db_mysql [km_dbase.c:98]: submit_query(): select id,src_addr,dst_addr,body,ctype,inc_time from silo where username='jh' AND domain='test.fi' AND snd_time=0 order by id Jun 4 12:57:45 localhost /usr/sbin/sip-router[20283]: INFO: db_mysql [km_dbase.c:98]: submit_query(): select id,src_addr,dst_addr,body,ctype,inc_time from silo where username='test' AND domain='test.fi' AND snd_time=0 order by id Jun 4 12:57:45 localhost /usr/sbin/sip-router[20283]: ERROR: db_mysql [km_dbase.c:119]: driver error on query: Commands out of sync; you can't run this command now Jun 4 12:57:45 localhost /usr/sbin/sip-router[20283]: ERROR: <core> [db_query.c:101]: error while submitting query
On 04-06 13:03, Juha Heinanen wrote:
Jan Janak writes:
Could you try to figure out which query is generating this error? There is a debug statement commented out on line 95 of km_dbase.c in db_mysql module, please, uncomment it and try again, it should print the query that generates this error in syslog.
jan,
i uncommented the dbg message and changed it to info. looks like the problem may have something to do with msilo module. when ua registers, it is checked from db if there are some pending messages for it.
-- juha
Jun 4 12:57:45 localhost /usr/sbin/sip-router[20251]: INFO: xlog [xlog.c:186]: INFO: REGISTER sip:jh@test.fi by jh@test.fi from <192.98.101.10> is authorized Jun 4 12:57:45 localhost /usr/sbin/sip-router[20251]: INFO: db_mysql [km_dbase.c:98]: submit_query(): update location set expires='2009-06-04 13:57:45',q=0.50 ,cseq=441,flags=0,cflags=0,user_agent='Twinkle/1.4.2',received=NULL,path=NULL,socket='',methods=6111,last_modified='2009-06-04 12:57:45' where username='jh' AND contact='sip:jh_test_fi@192.98.101.10:5074;transport=udp' AND callid='ysunsysgskxufqy@localhost' AND domain='test.fi' Jun 4 12:57:45 localhost /usr/sbin/sip-router[20283]: INFO: xlog [xlog.c:186]: INFO: REGISTER sip:test@test.fi by test@test.fi from <192.98.101.10> is authorized Jun 4 12:57:45 localhost /usr/sbin/sip-router[20283]: INFO: db_mysql [km_dbase.c:98]: submit_query(): insert into location (username,contact,expires,q,callid,cseq,flags,cflags,user_agent,received,path,socket,methods,last_modified,domain ) values ('test','sip:test@192.98.101.10:5074;transport=tcp','2009-06-04 13:57:45',0.50 ,'xtbkpufsizzylnl@localhost',116,0,0,'Twinkle/1.4.2',NULL,NULL,'',6111,'2009-06-04 12:57:45','test.fi') Jun 4 12:57:45 localhost /usr/sbin/sip-router[20251]: INFO: db_mysql [km_dbase.c:98]: submit_query(): select id,src_addr,dst_addr,body,ctype,inc_time from silo where username='jh' AND domain='test.fi' AND snd_time=0 order by id Jun 4 12:57:45 localhost /usr/sbin/sip-router[20283]: INFO: db_mysql [km_dbase.c:98]: submit_query(): select id,src_addr,dst_addr,body,ctype,inc_time from silo where username='test' AND domain='test.fi' AND snd_time=0 order by id Jun 4 12:57:45 localhost /usr/sbin/sip-router[20283]: ERROR: db_mysql [km_dbase.c:119]: driver error on query: Commands out of sync; you can't run this command now Jun 4 12:57:45 localhost /usr/sbin/sip-router[20283]: ERROR: <core> [db_query.c:101]: error while submitting query
Juha,
Is this all the output? The problem occurs in process 20283, this error is returned by the mysql library when the caller does not free the result returned by a previous command correctly. I am especially interested in previous databasa queries submitted within process 20283.
I could also happen that one of the modules does not initialize database properly in mod_init or child_init, could you send me the list of modules you are using?
Jan.
Jan Janak writes:
Is this all the output? The problem occurs in process 20283, this error is returned by the mysql library when the caller does not free the result returned by a previous command correctly. I am especially interested in previous databasa queries submitted within process 20283.
jan,
that was all the output after sr started. before that there was db access by module initializations, nothing by 20283. i'll investigate.
-- juha
El Jueves, 4 de Junio de 2009, Jan Janak escribió:
On 04-06 13:03, Juha Heinanen wrote:
Jan Janak writes:
Could you try to figure out which query is generating this error? There is a debug statement commented out on line 95 of km_dbase.c in db_mysql module, please, uncomment it and try again, it should print the query that generates this error in syslog.
jan,
i uncommented the dbg message and changed it to info. looks like the problem may have something to do with msilo module. when ua registers, it is checked from db if there are some pending messages for it.
-- juha
Jun 4 12:57:45 localhost /usr/sbin/sip-router[20251]: INFO: xlog [xlog.c:186]: INFO: REGISTER sip:jh@test.fi by jh@test.fi from <192.98.101.10> is authorized Jun 4 12:57:45 localhost /usr/sbin/sip-router[20251]: INFO: db_mysql [km_dbase.c:98]: submit_query(): update location set expires='2009-06-04 13:57:45',q=0.50
,cseq=441,flags=0,cflags=0,user_agent='Twinkle/1.4.2',received=NULL,path= NULL,socket='',methods=6111,last_modified='2009-06-04 12:57:45' where username='jh' AND contact='sip:jh_test_fi@192.98.101.10:5074;transport=udp' AND callid='ysunsysgskxufqy@localhost' AND domain='test.fi' Jun 4 12:57:45 localhost /usr/sbin/sip-router[20283]: INFO: xlog [xlog.c:186]: INFO: REGISTER sip:test@test.fi by test@test.fi from <192.98.101.10> is authorized Jun 4 12:57:45 localhost /usr/sbin/sip-router[20283]: INFO: db_mysql [km_dbase.c:98]: submit_query(): insert into location (username,contact,expires,q,callid,cseq,flags,cflags,user_agent,received, path,socket,methods,last_modified,domain ) values ('test','sip:test@192.98.101.10:5074;transport=tcp','2009-06-04 13:57:45',0.50 ,'xtbkpufsizzylnl@localhost',116,0,0,'Twinkle/1.4.2',NULL,NULL,'',6111,'2 009-06-04 12:57:45','test.fi') Jun 4 12:57:45 localhost /usr/sbin/sip-router[20251]: INFO: db_mysql [km_dbase.c:98]: submit_query(): select id,src_addr,dst_addr,body,ctype,inc_time from silo where username='jh' AND domain='test.fi' AND snd_time=0 order by id Jun 4 12:57:45 localhost /usr/sbin/sip-router[20283]: INFO: db_mysql [km_dbase.c:98]: submit_query(): select id,src_addr,dst_addr,body,ctype,inc_time from silo where username='test' AND domain='test.fi' AND snd_time=0 order by id Jun 4 12:57:45 localhost /usr/sbin/sip-router[20283]: ERROR: db_mysql [km_dbase.c:119]: driver error on query: Commands out of sync; you can't run this command now Jun 4 12:57:45 localhost /usr/sbin/sip-router[20283]: ERROR: <core> [db_query.c:101]: error while submitting query
Juha,
Is this all the output? The problem occurs in process 20283, this error is returned by the mysql library when the caller does not free the result returned by a previous command correctly. I am especially interested in previous databasa queries submitted within process 20283.
I could also happen that one of the modules does not initialize database properly in mod_init or child_init, could you send me the list of modules you are using?
If you are using xcal_client, remove it! In OpenSIPS it caused this error due to a bad DB initialization.
jan,
i'm starting to get desperate. i removed most of functionality from my config. i start proxy and then twinkle that has two accounts: test@test.fi and jh@test.fi. twinkle manages to register test, but does not anymore get any response when it tries to register jh.
with this test, no error messages comes to syslog, but proxy becomes totally unresponsive after handling the first register. proxy processes seem to be alive.
below is all that sip proxy prints to syslog.
- juha
Jun 4 18:21:49 localhost sip-router: WARNING: <core> [cfg.y:2898]: warning in config file, line 1834, column 12: constant value in while(...) Jun 4 18:21:49 localhost sip-router: INFO: <core> [tcp_main.c:4088]: init_tcp: using epoll_lt as the io watch method (auto detected) Jun 4 18:21:49 localhost /usr/sbin/sip-router[6360]: INFO: db_mysql [km_dbase.c:98]: submit_query(): select table_version from version where table_name='gw' Jun 4 18:21:49 localhost /usr/sbin/sip-router[6360]: INFO: db_mysql [km_dbase.c:98]: submit_query(): select table_version from version where table_name='lcr' Jun 4 18:21:49 localhost /usr/sbin/sip-router[6360]: INFO: db_mysql [km_dbase.c:98]: submit_query(): select ip_addr,port,uri_scheme,transport,strip,tag,grp_id,flags,weight,hostname,ping from gw Jun 4 18:21:49 localhost /usr/sbin/sip-router[6360]: INFO: db_mysql [km_dbase.c:98]: submit_query(): select prefix,from_uri,grp_id,priority from lcr Jun 4 18:21:49 localhost /usr/sbin/sip-router[6360]: INFO: db_mysql [km_dbase.c:98]: submit_query(): select table_version from version where table_name='dialplan' Jun 4 18:21:49 localhost /usr/sbin/sip-router[6360]: INFO: db_mysql [km_dbase.c:98]: submit_query(): select dpid,pr,match_op,match_exp,match_len,subst_exp,repl_exp,attrs from dialplan order by pr Jun 4 18:21:49 localhost /usr/sbin/sip-router[6360]: NOTICE: mediaproxy [mediaproxy.c:1734]: engage_media_proxy() will not work because the dialog module is not loaded Jun 4 18:21:49 localhost /usr/sbin/sip-router[6360]: INFO: misc_radius [misc_radius.c:162]: initializing... Jun 4 18:21:49 localhost /usr/sbin/sip-router[6360]: WARNING: tls [tls_mod.c:308]: WARNING: tls: mod_init: tls support is disabled (set enable_tls=1 in the config to enable it) Jun 4 18:21:49 localhost /usr/sbin/sip-router[6360]: INFO: utils [utils.c:263]: forward functionality disabled Jun 4 18:21:49 localhost /usr/sbin/sip-router[6360]: INFO: utils [utils.c:176]: xcap_auth_status function is disabled Jun 4 18:21:49 localhost /usr/sbin/sip-router[6360]: INFO: cfgutils [cfgutils.c:703]: no hash_file given, disable hash functionality Jun 4 18:21:49 localhost /usr/sbin/sip-router[6360]: INFO: pv [pv_shv.c:57]: locks array size 16 Jun 4 18:21:49 localhost /usr/sbin/sip-router[6360]: INFO: usrloc [hslot.c:53]: locks array size 512 Jun 4 18:21:49 localhost /usr/sbin/sip-router[6360]: INFO: db_mysql [km_dbase.c:98]: submit_query(): select table_version from version where table_name='domain' Jun 4 18:21:49 localhost /usr/sbin/sip-router[6360]: INFO: db_mysql [km_dbase.c:98]: submit_query(): select domain from domain Jun 4 18:21:49 localhost /usr/sbin/sip-router[6360]: WARNING: permissions [parse_config.c:251]: file not found: /etc/sip-router/permissions.allow Jun 4 18:21:49 localhost /usr/sbin/sip-router[6360]: WARNING: permissions [permissions.c:604]: default allow file (/etc/sip-router/permissions.allow) not found => empty rule set Jun 4 18:21:49 localhost /usr/sbin/sip-router[6360]: INFO: db_mysql [km_dbase.c:98]: submit_query(): select table_version from version where table_name='trusted' Jun 4 18:21:49 localhost /usr/sbin/sip-router[6360]: INFO: db_mysql [km_dbase.c:98]: submit_query(): select src_ip,proto,from_pattern,tag from trusted Jun 4 18:21:49 localhost /usr/sbin/sip-router[6360]: INFO: db_mysql [km_dbase.c:98]: submit_query(): select table_version from version where table_name='address' Jun 4 18:21:49 localhost /usr/sbin/sip-router[6360]: INFO: db_mysql [km_dbase.c:98]: submit_query(): select grp,ip_addr,mask,port from address Jun 4 18:21:49 localhost /usr/sbin/sip-router[6360]: INFO: pike [ip_tree.c:88]: probing 256 set size Jun 4 18:21:49 localhost /usr/sbin/sip-router[6360]: INFO: local [local.c:290]: initializing Jun 4 18:21:49 localhost /usr/sbin/sip-router[6360]: INFO: db_mysql [km_dbase.c:98]: submit_query(): select table_version from version where table_name='location' Jun 4 18:21:49 localhost /usr/sbin/sip-router[6360]: INFO: db_mysql [km_dbase.c:98]: submit_query(): select username from location where username='dummy_user' Jun 4 18:21:49 localhost /usr/sbin/sip-router[6360]: INFO: utils [utils.c:317]: leaving fixup_http_query Jun 4 18:21:49 localhost /usr/sbin/sip-router[6360]: INFO: <core> [udp_server.c:166]: INFO: udp_init: SO_RCVBUF is initially 111616 Jun 4 18:21:49 localhost /usr/sbin/sip-router[6360]: INFO: <core> [udp_server.c:217]: INFO: udp_init: SO_RCVBUF is finally 262142 Jun 4 18:21:49 localhost /usr/sbin/sip-router[6360]: INFO: <core> [udp_server.c:166]: INFO: udp_init: SO_RCVBUF is initially 111616 Jun 4 18:21:49 localhost /usr/sbin/sip-router[6360]: INFO: <core> [udp_server.c:217]: INFO: udp_init: SO_RCVBUF is finally 262142 Jun 4 18:21:49 localhost /usr/sbin/sip-router[6360]: INFO: <core> [udp_server.c:166]: INFO: udp_init: SO_RCVBUF is initially 111616 Jun 4 18:21:49 localhost /usr/sbin/sip-router[6360]: INFO: <core> [udp_server.c:217]: INFO: udp_init: SO_RCVBUF is finally 262142 Jun 4 18:21:49 localhost /usr/sbin/sip-router[6360]: INFO: <core> [sctp_server.c:426]: sctp: socket 8 initialized (0x8226ff8) Jun 4 18:21:49 localhost /usr/sbin/sip-router[6361]: INFO: db_mysql [km_dbase.c:98]: submit_query(): select username,contact,expires,q,callid,cseq,flags,cflags,user_agent,received,path,socket,methods,last_modified,domain from location Jun 4 18:21:49 localhost /usr/sbin/sip-router[6381]: INFO: mi_xmlrpc [mi_xmlrpc.c:252]: starting xmlrpc server Jun 4 18:22:05 localhost /usr/sbin/sip-router[6382]: INFO: xlog [xlog.c:186]: INFO: REGISTER sip:test@test.fi by test@test.fi from <192.98.101.10> is authorized Jun 4 18:22:05 localhost /usr/sbin/sip-router[6382]: INFO: db_mysql [km_dbase.c:98]: submit_query(): insert into location (username,contact,expires,q,callid,cseq,flags,cflags,user_agent,received,path,socket,methods,last_modified,domain ) values ('test','sip:test@192.98.101.10:5074;transport=tcp','2009-06-04 19:22:05',0.50 ,'rhmhnveyfyqyaue@localhost',950,0,0,'Twinkle/1.4.2',NULL,NULL,'',6111,'2009-06-04 18:22:05','test.fi')
i turned on debug and here are the last words (after successful radius authorization) from the proxy before it becomes unresponsive while handling the register request. looks to me that it happens while proxy is executing save("location") call. after save there is just exit. 200 ok never leaves the proxy.
-- juha
Jun 4 18:51:11 localhost /usr/sbin/sip-router[8249]: INFO: xlog [xlog.c:186]: INFO: REGISTER sip:test@test.fi by test@test.fi from <192.98.101.10> is authorized Jun 4 18:51:11 localhost /usr/sbin/sip-router[8249]: DEBUG: htable [ht_api.c:112]: htable found [auth] Jun 4 18:51:11 localhost /usr/sbin/sip-router[8249]: DEBUG: permissions [address.c:383]: looking for <2, a6562c0, 5074> Jun 4 18:51:11 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/msg_parser.c:318]: parse_headers: flags=88 Jun 4 18:51:11 localhost /usr/sbin/sip-router[8249]: DEBUG: permissions [permissions.c:784]: looking for To: sip:test@test.fi Contact: sip:test@192.98.101.10 Jun 4 18:51:11 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/msg_parser.c:318]: parse_headers: flags=80 Jun 4 18:51:11 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/msg_parser.c:89]: found end of header Jun 4 18:51:11 localhost /usr/sbin/sip-router[8249]: DEBUG: permissions [permissions.c:803]: no contact denied => Allowed Jun 4 18:51:11 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/msg_parser.c:318]: parse_headers: flags=ffffffffffffffff Jun 4 18:51:11 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/msg_parser.c:318]: parse_headers: flags=8000000 Jun 4 18:51:11 localhost /usr/sbin/sip-router[8249]: DEBUG: registrar [save.c:489]: 2 valid contacts Jun 4 18:51:11 localhost /usr/sbin/sip-router[8249]: DEBUG: registrar [save.c:511]: 1 contacts after commit Jun 4 18:51:11 localhost /usr/sbin/sip-router[8249]: INFO: db_mysql [km_dbase.c:98]: submit_query(): delete from location where username='test' AND contact='sip:test@192.98.101.10:5074;transport=udp' AND callid='fvatirvfbqfpevk@localhost' AND domain='test.fi' Jun 4 18:51:11 localhost /usr/sbin/sip-router[8249]: DEBUG: registrar [reply.c:192]: created Contact HF: Contact: sip:test@192.98.101.10:5074;transport=tcp;q=0.5;expires=3359#015#012 Jun 4 18:51:11 localhost /usr/sbin/sip-router[8249]: DEBUG: sl [sl.c:314]: reply in stateless mode (sl) Jun 4 18:51:11 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/msg_parser.c:318]: parse_headers: flags=ffffffffffffffff Jun 4 18:51:11 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [msg_translator.c:200]: check_via_address(192.98.101.10, 192.98.101.10, 0) Jun 4 18:51:11 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list 0xb338dfb0 Jun 4 18:51:11 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil) Jun 4 18:51:11 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil) Jun 4 18:51:11 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil) Jun 4 18:51:11 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil) Jun 4 18:51:11 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil) Jun 4 18:51:11 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [receive.c:244]: receive_msg: cleaning up Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [parser/msg_parser.c:594]: SIP Request: Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [parser/msg_parser.c:596]: method: <NOTIFY> Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [parser/msg_parser.c:598]: uri: sip:test@192.98.101.10:5074;transport=udp Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [parser/msg_parser.c:600]: version: <SIP/2.0> Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [parser/msg_parser.c:318]: parse_headers: flags=2 Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [parser/parse_via.c:1283]: Found param type 232, <branch> = <z9hG4bKce8f.7aa61b05.0>; state=16 Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [parser/parse_via.c:2296]: end of header reached, state=5 Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [parser/msg_parser.c:493]: parse_headers: Via found, flags=2 Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [parser/msg_parser.c:495]: parse_headers: this is the first via Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [receive.c:120]: After parse_msg... Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [receive.c:156]: preparing to run routing scripts... Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [msg_translator.c:200]: check_via_address(192.98.101.10, 192.98.101.10, 0) Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [parser/msg_parser.c:318]: parse_headers: flags=100 Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [parser/parse_to.c:174]: DEBUG: add_param: tag=oggsp Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [parser/parse_to.c:753]: end of header reached, state=29 Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [parser/msg_parser.c:173]: DEBUG: get_hdr_field: <To> [30]; uri=[sip:test@test.fi] Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [parser/msg_parser.c:175]: DEBUG: to body [sip:test@test.fi] Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [parser/msg_parser.c:153]: get_hdr_field: cseq <CSeq>: <1> <NOTIFY> Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [parser/msg_parser.c:187]: DEBUG: get_hdr_body : content_length=0 Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: maxfwd [mf_funcs.c:85]: value = 70 Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: lcr [lcr_mod.c:2227]: request did not come from gw Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: siputils [checks.c:68]: totag found Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [parser/msg_parser.c:318]: parse_headers: flags=200 Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: rr [loose.c:85]: is_preloaded: No Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 13==13 && [192.98.101.10] == [192.98.101.10] Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5074 Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 13==9 && [192.98.101.10] == [127.0.0.1] Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5070 matches port 5074 Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 13==9 && [192.98.101.10] == [127.0.0.1] Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5080 matches port 5074 Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 13==13 && [192.98.101.10] == [192.98.101.10] Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5074 Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 13==13 && [192.98.101.10] == [192.98.101.10] Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5074 Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [forward.c:298]: check_self: host != me Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 13==13 && [192.98.101.10] == [192.98.101.10] Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060 Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: rr [loose.c:781]: Topmost route URI: 'sip:192.98.101.10;lr;ftag=oggsp' is me Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [parser/msg_parser.c:318]: parse_headers: flags=200 Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [parser/msg_parser.c:89]: found end of header Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: rr [loose.c:257]: No next Route HF found Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: rr [loose.c:800]: No next URI found Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: rr [rr_cb.c:97]: callback id 0 entered with <lr;ftag=oggsp> Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: uac [from.c:421]: getting 'vsf' Route param Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: uac [from.c:425]: route param 'vsf' not found Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: rr [loose.c:968]: params are <;lr;ftag=oggsp> Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [parser/msg_parser.c:594]: SIP Request: Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [parser/msg_parser.c:596]: method: <NOTIFY> Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [parser/msg_parser.c:598]: uri: sip:test@192.98.101.10:5074;transport=udp Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [parser/msg_parser.c:600]: version: <SIP/2.0> Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [parser/msg_parser.c:318]: parse_headers: flags=2 Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [parser/parse_via.c:1283]: Found param type 232, <branch> = <z9hG4bKce8f.7aa61b05.0>; state=16 Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [parser/parse_via.c:2296]: end of header reached, state=5 Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [parser/msg_parser.c:493]: parse_headers: Via found, flags=2 Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [parser/msg_parser.c:495]: parse_headers: this is the first via Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [receive.c:120]: After parse_msg... Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [receive.c:156]: preparing to run routing scripts... Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [msg_translator.c:200]: check_via_address(192.98.101.10, 192.98.101.10, 0) Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [parser/msg_parser.c:318]: parse_headers: flags=100 Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [parser/parse_to.c:174]: DEBUG: add_param: tag=oggsp Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [parser/parse_to.c:753]: end of header reached, state=29 Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [parser/msg_parser.c:173]: DEBUG: get_hdr_field: <To> [30]; uri=[sip:test@test.fi] Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [parser/msg_parser.c:175]: DEBUG: to body [sip:test@test.fi] Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [parser/msg_parser.c:153]: get_hdr_field: cseq <CSeq>: <1> <NOTIFY> Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [parser/msg_parser.c:187]: DEBUG: get_hdr_body : content_length=0 Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: maxfwd [mf_funcs.c:85]: value = 70 Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: lcr [lcr_mod.c:2227]: request did not come from gw Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: siputils [checks.c:68]: totag found Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [parser/msg_parser.c:318]: parse_headers: flags=200 Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: rr [loose.c:85]: is_preloaded: No Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 13==13 && [192.98.101.10] == [192.98.101.10] Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5074 Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 13==9 && [192.98.101.10] == [127.0.0.1] Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5070 matches port 5074 Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 13==9 && [192.98.101.10] == [127.0.0.1] Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5080 matches port 5074 Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 13==13 && [192.98.101.10] == [192.98.101.10] Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5074 Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 13==13 && [192.98.101.10] == [192.98.101.10] Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5074 Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [forward.c:298]: check_self: host != me Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 13==13 && [192.98.101.10] == [192.98.101.10] Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060 Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: rr [loose.c:781]: Topmost route URI: 'sip:192.98.101.10;lr;ftag=oggsp' is me Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [parser/msg_parser.c:318]: parse_headers: flags=200 Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [parser/msg_parser.c:89]: found end of header Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: rr [loose.c:257]: No next Route HF found Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: rr [loose.c:800]: No next URI found Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: rr [rr_cb.c:97]: callback id 0 entered with <lr;ftag=oggsp> Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: uac [from.c:421]: getting 'vsf' Route param Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: uac [from.c:425]: route param 'vsf' not found Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: rr [loose.c:968]: params are <;lr;ftag=oggsp> Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/msg_parser.c:594]: SIP Request: Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/msg_parser.c:596]: method: <NOTIFY> Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/msg_parser.c:598]: uri: sip:test@192.98.101.10:5074;transport=udp Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/msg_parser.c:600]: version: <SIP/2.0> Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/msg_parser.c:318]: parse_headers: flags=2 Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/parse_via.c:1283]: Found param type 232, <branch> = <z9hG4bKce8f.7aa61b05.0>; state=16 Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/parse_via.c:2296]: end of header reached, state=5 Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/msg_parser.c:493]: parse_headers: Via found, flags=2 Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/msg_parser.c:495]: parse_headers: this is the first via Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [receive.c:120]: After parse_msg... Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [receive.c:156]: preparing to run routing scripts... Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [msg_translator.c:200]: check_via_address(192.98.101.10, 192.98.101.10, 0) Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/msg_parser.c:318]: parse_headers: flags=100 Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/parse_to.c:174]: DEBUG: add_param: tag=oggsp Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/parse_to.c:753]: end of header reached, state=29 Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/msg_parser.c:173]: DEBUG: get_hdr_field: <To> [30]; uri=[sip:test@test.fi] Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/msg_parser.c:175]: DEBUG: to body [sip:test@test.fi] Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/msg_parser.c:153]: get_hdr_field: cseq <CSeq>: <1> <NOTIFY> Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/msg_parser.c:187]: DEBUG: get_hdr_body : content_length=0 Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: maxfwd [mf_funcs.c:85]: value = 70 Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: lcr [lcr_mod.c:2227]: request did not come from gw Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: siputils [checks.c:68]: totag found Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/msg_parser.c:318]: parse_headers: flags=200 Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: rr [loose.c:85]: is_preloaded: No Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 13==13 && [192.98.101.10] == [192.98.101.10] Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5074 Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 13==9 && [192.98.101.10] == [127.0.0.1] Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5070 matches port 5074 Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 13==9 && [192.98.101.10] == [127.0.0.1] Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5080 matches port 5074 Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 13==13 && [192.98.101.10] == [192.98.101.10] Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5074 Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 13==13 && [192.98.101.10] == [192.98.101.10] Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5074 Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [forward.c:298]: check_self: host != me Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 13==13 && [192.98.101.10] == [192.98.101.10] Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060 Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: rr [loose.c:781]: Topmost route URI: 'sip:192.98.101.10;lr;ftag=oggsp' is me Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/msg_parser.c:318]: parse_headers: flags=200 Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/msg_parser.c:89]: found end of header Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: rr [loose.c:257]: No next Route HF found Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: rr [loose.c:800]: No next URI found Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: rr [rr_cb.c:97]: callback id 0 entered with <lr;ftag=oggsp> Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: uac [from.c:421]: getting 'vsf' Route param Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: uac [from.c:425]: route param 'vsf' not found Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: rr [loose.c:968]: params are <;lr;ftag=oggsp>
when i read the "last words" debug more closely, it appears that the proxy handling three requests at the time when it goes into coma: it is executing save function from one register request, getting another register request, and getting a notify from presence server.
any pointers on how to find out why sr becomes unresponsive are greatly appreciated. how can it happen that the proxy stops doing anything even though its processes (or at least some of them) are still alive?
-- juha
---------------------------------------
Jun 4 18:51:11 localhost /usr/sbin/sip-router[8249]: INFO: xlog [xlog.c:186]: INFO: REGISTER sip:test@test.fi by test@test.fi from <192.98.101.10> is authorized Jun 4 18:51:11 localhost /usr/sbin/sip-router[8249]: DEBUG: htable [ht_api.c:112]: htable found [auth] Jun 4 18:51:11 localhost /usr/sbin/sip-router[8249]: DEBUG: permissions [address.c:383]: looking for <2, a6562c0, 5074> Jun 4 18:51:11 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/msg_parser.c:318]: parse_headers: flags=88 Jun 4 18:51:11 localhost /usr/sbin/sip-router[8249]: DEBUG: permissions [permissions.c:784]: looking for To: sip:test@test.fi Contact: sip:test@192.98.101.10 Jun 4 18:51:11 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/msg_parser.c:318]: parse_headers: flags=80 Jun 4 18:51:11 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/msg_parser.c:89]: found end of header Jun 4 18:51:11 localhost /usr/sbin/sip-router[8249]: DEBUG: permissions [permissions.c:803]: no contact denied => Allowed Jun 4 18:51:11 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/msg_parser.c:318]: parse_headers: flags=ffffffffffffffff Jun 4 18:51:11 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/msg_parser.c:318]: parse_headers: flags=8000000 Jun 4 18:51:11 localhost /usr/sbin/sip-router[8249]: DEBUG: registrar [save.c:489]: 2 valid contacts Jun 4 18:51:11 localhost /usr/sbin/sip-router[8249]: DEBUG: registrar [save.c:511]: 1 contacts after commit Jun 4 18:51:11 localhost /usr/sbin/sip-router[8249]: INFO: db_mysql [km_dbase.c:98]: submit_query(): delete from location where username='test' AND contact='sip:test@192.98.101.10:5074;transport=udp' AND callid='fvatirvfbqfpevk@localhost' AND domain='test.fi' Jun 4 18:51:11 localhost /usr/sbin/sip-router[8249]: DEBUG: registrar [reply.c:192]: created Contact HF: Contact: sip:test@192.98.101.10:5074;transport=tcp;q=0.5;expires=3359#015#012 Jun 4 18:51:11 localhost /usr/sbin/sip-router[8249]: DEBUG: sl [sl.c:314]: reply in stateless mode (sl) Jun 4 18:51:11 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/msg_parser.c:318]: parse_headers: flags=ffffffffffffffff Jun 4 18:51:11 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [msg_translator.c:200]: check_via_address(192.98.101.10, 192.98.101.10, 0) Jun 4 18:51:11 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list 0xb338dfb0 Jun 4 18:51:11 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil) Jun 4 18:51:11 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil) Jun 4 18:51:11 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil) Jun 4 18:51:11 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil) Jun 4 18:51:11 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil) Jun 4 18:51:11 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [receive.c:244]: receive_msg: cleaning up Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [parser/msg_parser.c:594]: SIP Request: Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [parser/msg_parser.c:596]: method: <NOTIFY> Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [parser/msg_parser.c:598]: uri: sip:test@192.98.101.10:5074;transport=udp Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [parser/msg_parser.c:600]: version: <SIP/2.0> Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [parser/msg_parser.c:318]: parse_headers: flags=2 Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [parser/parse_via.c:1283]: Found param type 232, <branch> = <z9hG4bKce8f.7aa61b05.0>; state=16 Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [parser/parse_via.c:2296]: end of header reached, state=5 Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [parser/msg_parser.c:493]: parse_headers: Via found, flags=2 Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [parser/msg_parser.c:495]: parse_headers: this is the first via Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [receive.c:120]: After parse_msg... Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [receive.c:156]: preparing to run routing scripts... Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [msg_translator.c:200]: check_via_address(192.98.101.10, 192.98.101.10, 0) Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [parser/msg_parser.c:318]: parse_headers: flags=100 Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [parser/parse_to.c:174]: DEBUG: add_param: tag=oggsp Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [parser/parse_to.c:753]: end of header reached, state=29 Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [parser/msg_parser.c:173]: DEBUG: get_hdr_field: <To> [30]; uri=[sip:test@test.fi] Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [parser/msg_parser.c:175]: DEBUG: to body [sip:test@test.fi] Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [parser/msg_parser.c:153]: get_hdr_field: cseq <CSeq>: <1> <NOTIFY> Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [parser/msg_parser.c:187]: DEBUG: get_hdr_body : content_length=0 Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: maxfwd [mf_funcs.c:85]: value = 70 Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: lcr [lcr_mod.c:2227]: request did not come from gw Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: siputils [checks.c:68]: totag found Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [parser/msg_parser.c:318]: parse_headers: flags=200 Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: rr [loose.c:85]: is_preloaded: No Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 13==13 && [192.98.101.10] == [192.98.101.10] Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5074 Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 13==9 && [192.98.101.10] == [127.0.0.1] Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5070 matches port 5074 Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 13==9 && [192.98.101.10] == [127.0.0.1] Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5080 matches port 5074 Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 13==13 && [192.98.101.10] == [192.98.101.10] Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5074 Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 13==13 && [192.98.101.10] == [192.98.101.10] Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5074 Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [forward.c:298]: check_self: host != me Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 13==13 && [192.98.101.10] == [192.98.101.10] Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060 Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: rr [loose.c:781]: Topmost route URI: 'sip:192.98.101.10;lr;ftag=oggsp' is me Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [parser/msg_parser.c:318]: parse_headers: flags=200 Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [parser/msg_parser.c:89]: found end of header Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: rr [loose.c:257]: No next Route HF found Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: rr [loose.c:800]: No next URI found Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: rr [rr_cb.c:97]: callback id 0 entered with <lr;ftag=oggsp> Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: uac [from.c:421]: getting 'vsf' Route param Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: uac [from.c:425]: route param 'vsf' not found Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: rr [loose.c:968]: params are <;lr;ftag=oggsp> Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [parser/msg_parser.c:594]: SIP Request: Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [parser/msg_parser.c:596]: method: <NOTIFY> Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [parser/msg_parser.c:598]: uri: sip:test@192.98.101.10:5074;transport=udp Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [parser/msg_parser.c:600]: version: <SIP/2.0> Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [parser/msg_parser.c:318]: parse_headers: flags=2 Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [parser/parse_via.c:1283]: Found param type 232, <branch> = <z9hG4bKce8f.7aa61b05.0>; state=16 Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [parser/parse_via.c:2296]: end of header reached, state=5 Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [parser/msg_parser.c:493]: parse_headers: Via found, flags=2 Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [parser/msg_parser.c:495]: parse_headers: this is the first via Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [receive.c:120]: After parse_msg... Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [receive.c:156]: preparing to run routing scripts... Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [msg_translator.c:200]: check_via_address(192.98.101.10, 192.98.101.10, 0) Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [parser/msg_parser.c:318]: parse_headers: flags=100 Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [parser/parse_to.c:174]: DEBUG: add_param: tag=oggsp Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [parser/parse_to.c:753]: end of header reached, state=29 Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [parser/msg_parser.c:173]: DEBUG: get_hdr_field: <To> [30]; uri=[sip:test@test.fi] Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [parser/msg_parser.c:175]: DEBUG: to body [sip:test@test.fi] Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [parser/msg_parser.c:153]: get_hdr_field: cseq <CSeq>: <1> <NOTIFY> Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [parser/msg_parser.c:187]: DEBUG: get_hdr_body : content_length=0 Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: maxfwd [mf_funcs.c:85]: value = 70 Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: lcr [lcr_mod.c:2227]: request did not come from gw Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: siputils [checks.c:68]: totag found Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [parser/msg_parser.c:318]: parse_headers: flags=200 Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: rr [loose.c:85]: is_preloaded: No Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 13==13 && [192.98.101.10] == [192.98.101.10] Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5074 Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 13==9 && [192.98.101.10] == [127.0.0.1] Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5070 matches port 5074 Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 13==9 && [192.98.101.10] == [127.0.0.1] Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5080 matches port 5074 Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 13==13 && [192.98.101.10] == [192.98.101.10] Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5074 Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 13==13 && [192.98.101.10] == [192.98.101.10] Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5074 Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [forward.c:298]: check_self: host != me Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 13==13 && [192.98.101.10] == [192.98.101.10] Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060 Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: rr [loose.c:781]: Topmost route URI: 'sip:192.98.101.10;lr;ftag=oggsp' is me Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [parser/msg_parser.c:318]: parse_headers: flags=200 Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [parser/msg_parser.c:89]: found end of header Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: rr [loose.c:257]: No next Route HF found Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: rr [loose.c:800]: No next URI found Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: rr [rr_cb.c:97]: callback id 0 entered with <lr;ftag=oggsp> Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: uac [from.c:421]: getting 'vsf' Route param Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: uac [from.c:425]: route param 'vsf' not found Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: rr [loose.c:968]: params are <;lr;ftag=oggsp> Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/msg_parser.c:594]: SIP Request: Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/msg_parser.c:596]: method: <NOTIFY> Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/msg_parser.c:598]: uri: sip:test@192.98.101.10:5074;transport=udp Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/msg_parser.c:600]: version: <SIP/2.0> Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/msg_parser.c:318]: parse_headers: flags=2 Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/parse_via.c:1283]: Found param type 232, <branch> = <z9hG4bKce8f.7aa61b05.0>; state=16 Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/parse_via.c:2296]: end of header reached, state=5 Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/msg_parser.c:493]: parse_headers: Via found, flags=2 Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/msg_parser.c:495]: parse_headers: this is the first via Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [receive.c:120]: After parse_msg... Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [receive.c:156]: preparing to run routing scripts... Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [msg_translator.c:200]: check_via_address(192.98.101.10, 192.98.101.10, 0) Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/msg_parser.c:318]: parse_headers: flags=100 Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/parse_to.c:174]: DEBUG: add_param: tag=oggsp Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/parse_to.c:753]: end of header reached, state=29 Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/msg_parser.c:173]: DEBUG: get_hdr_field: <To> [30]; uri=[sip:test@test.fi] Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/msg_parser.c:175]: DEBUG: to body [sip:test@test.fi] Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/msg_parser.c:153]: get_hdr_field: cseq <CSeq>: <1> <NOTIFY> Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/msg_parser.c:187]: DEBUG: get_hdr_body : content_length=0 Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: maxfwd [mf_funcs.c:85]: value = 70 Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: lcr [lcr_mod.c:2227]: request did not come from gw Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: siputils [checks.c:68]: totag found Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/msg_parser.c:318]: parse_headers: flags=200 Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: rr [loose.c:85]: is_preloaded: No Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 13==13 && [192.98.101.10] == [192.98.101.10] Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5074 Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 13==9 && [192.98.101.10] == [127.0.0.1] Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5070 matches port 5074 Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 13==9 && [192.98.101.10] == [127.0.0.1] Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5080 matches port 5074 Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 13==13 && [192.98.101.10] == [192.98.101.10] Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5074 Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 13==13 && [192.98.101.10] == [192.98.101.10] Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5074 Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [forward.c:298]: check_self: host != me Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 13==13 && [192.98.101.10] == [192.98.101.10] Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060 Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: rr [loose.c:781]: Topmost route URI: 'sip:192.98.101.10;lr;ftag=oggsp' is me Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/msg_parser.c:318]: parse_headers: flags=200 Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/msg_parser.c:89]: found end of header Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: rr [loose.c:257]: No next Route HF found Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: rr [loose.c:800]: No next URI found Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: rr [rr_cb.c:97]: callback id 0 entered with <lr;ftag=oggsp> Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: uac [from.c:421]: getting 'vsf' Route param Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: uac [from.c:425]: route param 'vsf' not found Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: rr [loose.c:968]: params are <;lr;ftag=oggsp>
On 06/05/2009 11:44 AM, Juha Heinanen wrote:
when i read the "last words" debug more closely, it appears that the proxy handling three requests at the time when it goes into coma: it is executing save function from one register request, getting another register request, and getting a notify from presence server.
any pointers on how to find out why sr becomes unresponsive are greatly appreciated. how can it happen that the proxy stops doing anything even though its processes (or at least some of them) are still alive?
can you attach with gdb to the processes and see where they are stuck?
Is the cpu high? Are all processes still alive?
Cheers, Daniel
-- juha
Jun 4 18:51:11 localhost /usr/sbin/sip-router[8249]: INFO: xlog [xlog.c:186]: INFO: REGISTER sip:test@test.fi by test@test.fi from <192.98.101.10> is authorized Jun 4 18:51:11 localhost /usr/sbin/sip-router[8249]: DEBUG: htable [ht_api.c:112]: htable found [auth] Jun 4 18:51:11 localhost /usr/sbin/sip-router[8249]: DEBUG: permissions [address.c:383]: looking for <2, a6562c0, 5074> Jun 4 18:51:11 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/msg_parser.c:318]: parse_headers: flags=88 Jun 4 18:51:11 localhost /usr/sbin/sip-router[8249]: DEBUG: permissions [permissions.c:784]: looking for To: sip:test@test.fi Contact: sip:test@192.98.101.10 Jun 4 18:51:11 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/msg_parser.c:318]: parse_headers: flags=80 Jun 4 18:51:11 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/msg_parser.c:89]: found end of header Jun 4 18:51:11 localhost /usr/sbin/sip-router[8249]: DEBUG: permissions [permissions.c:803]: no contact denied => Allowed Jun 4 18:51:11 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/msg_parser.c:318]: parse_headers: flags=ffffffffffffffff Jun 4 18:51:11 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/msg_parser.c:318]: parse_headers: flags=8000000 Jun 4 18:51:11 localhost /usr/sbin/sip-router[8249]: DEBUG: registrar [save.c:489]: 2 valid contacts Jun 4 18:51:11 localhost /usr/sbin/sip-router[8249]: DEBUG: registrar [save.c:511]: 1 contacts after commit Jun 4 18:51:11 localhost /usr/sbin/sip-router[8249]: INFO: db_mysql [km_dbase.c:98]: submit_query(): delete from location where username='test' AND contact='sip:test@192.98.101.10:5074;transport=udp' AND callid='fvatirvfbqfpevk@localhost' AND domain='test.fi' Jun 4 18:51:11 localhost /usr/sbin/sip-router[8249]: DEBUG: registrar [reply.c:192]: created Contact HF: Contact: sip:test@192.98.101.10:5074;transport=tcp;q=0.5;expires=3359#015#012 Jun 4 18:51:11 localhost /usr/sbin/sip-router[8249]: DEBUG: sl [sl.c:314]: reply in stateless mode (sl) Jun 4 18:51:11 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/msg_parser.c:318]: parse_headers: flags=ffffffffffffffff Jun 4 18:51:11 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [msg_translator.c:200]: check_via_address(192.98.101.10, 192.98.101.10, 0) Jun 4 18:51:11 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list 0xb338dfb0 Jun 4 18:51:11 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil) Jun 4 18:51:11 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil) Jun 4 18:51:11 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil) Jun 4 18:51:11 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil) Jun 4 18:51:11 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil) Jun 4 18:51:11 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [receive.c:244]: receive_msg: cleaning up Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [parser/msg_parser.c:594]: SIP Request: Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [parser/msg_parser.c:596]: method: <NOTIFY> Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [parser/msg_parser.c:598]: uri: sip:test@192.98.101.10:5074;transport=udp Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [parser/msg_parser.c:600]: version: <SIP/2.0> Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [parser/msg_parser.c:318]: parse_headers: flags=2 Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [parser/parse_via.c:1283]: Found param type 232, <branch> = <z9hG4bKce8f.7aa61b05.0>; state=16 Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [parser/parse_via.c:2296]: end of header reached, state=5 Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [parser/msg_parser.c:493]: parse_headers: Via found, flags=2 Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [parser/msg_parser.c:495]: parse_headers: this is the first via Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [receive.c:120]: After parse_msg... Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [receive.c:156]: preparing to run routing scripts... Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [msg_translator.c:200]: check_via_address(192.98.101.10, 192.98.101.10, 0) Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [parser/msg_parser.c:318]: parse_headers: flags=100 Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [parser/parse_to.c:174]: DEBUG: add_param: tag=oggsp Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [parser/parse_to.c:753]: end of header reached, state=29 Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [parser/msg_parser.c:173]: DEBUG: get_hdr_field: <To> [30]; uri=[sip:test@test.fi] Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [parser/msg_parser.c:175]: DEBUG: to body [sip:test@test.fi] Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [parser/msg_parser.c:153]: get_hdr_field: cseq <CSeq>: <1> <NOTIFY> Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [parser/msg_parser.c:187]: DEBUG: get_hdr_body : content_length=0 Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: maxfwd [mf_funcs.c:85]: value = 70 Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: lcr [lcr_mod.c:2227]: request did not come from gw Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: siputils [checks.c:68]: totag found Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [parser/msg_parser.c:318]: parse_headers: flags=200 Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: rr [loose.c:85]: is_preloaded: No Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 13==13 && [192.98.101.10] == [192.98.101.10] Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5074 Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 13==9 && [192.98.101.10] == [127.0.0.1] Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5070 matches port 5074 Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 13==9 && [192.98.101.10] == [127.0.0.1] Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5080 matches port 5074 Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 13==13 && [192.98.101.10] == [192.98.101.10] Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5074 Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 13==13 && [192.98.101.10] == [192.98.101.10] Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5074 Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [forward.c:298]: check_self: host != me Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 13==13 && [192.98.101.10] == [192.98.101.10] Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060 Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: rr [loose.c:781]: Topmost route URI: 'sip:192.98.101.10;lr;ftag=oggsp' is me Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [parser/msg_parser.c:318]: parse_headers: flags=200 Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: <core> [parser/msg_parser.c:89]: found end of header Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: rr [loose.c:257]: No next Route HF found Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: rr [loose.c:800]: No next URI found Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: rr [rr_cb.c:97]: callback id 0 entered with <lr;ftag=oggsp> Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: uac [from.c:421]: getting 'vsf' Route param Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: uac [from.c:425]: route param 'vsf' not found Jun 4 18:51:11 localhost /usr/sbin/sip-router[8252]: DEBUG: rr [loose.c:968]: params are <;lr;ftag=oggsp> Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [parser/msg_parser.c:594]: SIP Request: Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [parser/msg_parser.c:596]: method: <NOTIFY> Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [parser/msg_parser.c:598]: uri: sip:test@192.98.101.10:5074;transport=udp Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [parser/msg_parser.c:600]: version: <SIP/2.0> Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [parser/msg_parser.c:318]: parse_headers: flags=2 Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [parser/parse_via.c:1283]: Found param type 232, <branch> = <z9hG4bKce8f.7aa61b05.0>; state=16 Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [parser/parse_via.c:2296]: end of header reached, state=5 Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [parser/msg_parser.c:493]: parse_headers: Via found, flags=2 Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [parser/msg_parser.c:495]: parse_headers: this is the first via Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [receive.c:120]: After parse_msg... Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [receive.c:156]: preparing to run routing scripts... Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [msg_translator.c:200]: check_via_address(192.98.101.10, 192.98.101.10, 0) Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [parser/msg_parser.c:318]: parse_headers: flags=100 Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [parser/parse_to.c:174]: DEBUG: add_param: tag=oggsp Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [parser/parse_to.c:753]: end of header reached, state=29 Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [parser/msg_parser.c:173]: DEBUG: get_hdr_field: <To> [30]; uri=[sip:test@test.fi] Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [parser/msg_parser.c:175]: DEBUG: to body [sip:test@test.fi] Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [parser/msg_parser.c:153]: get_hdr_field: cseq <CSeq>: <1> <NOTIFY> Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [parser/msg_parser.c:187]: DEBUG: get_hdr_body : content_length=0 Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: maxfwd [mf_funcs.c:85]: value = 70 Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: lcr [lcr_mod.c:2227]: request did not come from gw Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: siputils [checks.c:68]: totag found Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [parser/msg_parser.c:318]: parse_headers: flags=200 Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: rr [loose.c:85]: is_preloaded: No Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 13==13 && [192.98.101.10] == [192.98.101.10] Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5074 Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 13==9 && [192.98.101.10] == [127.0.0.1] Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5070 matches port 5074 Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 13==9 && [192.98.101.10] == [127.0.0.1] Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5080 matches port 5074 Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 13==13 && [192.98.101.10] == [192.98.101.10] Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5074 Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 13==13 && [192.98.101.10] == [192.98.101.10] Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5074 Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [forward.c:298]: check_self: host != me Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 13==13 && [192.98.101.10] == [192.98.101.10] Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060 Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: rr [loose.c:781]: Topmost route URI: 'sip:192.98.101.10;lr;ftag=oggsp' is me Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [parser/msg_parser.c:318]: parse_headers: flags=200 Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: <core> [parser/msg_parser.c:89]: found end of header Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: rr [loose.c:257]: No next Route HF found Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: rr [loose.c:800]: No next URI found Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: rr [rr_cb.c:97]: callback id 0 entered with <lr;ftag=oggsp> Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: uac [from.c:421]: getting 'vsf' Route param Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: uac [from.c:425]: route param 'vsf' not found Jun 4 18:51:12 localhost /usr/sbin/sip-router[8251]: DEBUG: rr [loose.c:968]: params are <;lr;ftag=oggsp> Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/msg_parser.c:594]: SIP Request: Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/msg_parser.c:596]: method: <NOTIFY> Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/msg_parser.c:598]: uri: sip:test@192.98.101.10:5074;transport=udp Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/msg_parser.c:600]: version: <SIP/2.0> Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/msg_parser.c:318]: parse_headers: flags=2 Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/parse_via.c:1283]: Found param type 232, <branch> = <z9hG4bKce8f.7aa61b05.0>; state=16 Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/parse_via.c:2296]: end of header reached, state=5 Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/msg_parser.c:493]: parse_headers: Via found, flags=2 Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/msg_parser.c:495]: parse_headers: this is the first via Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [receive.c:120]: After parse_msg... Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [receive.c:156]: preparing to run routing scripts... Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [msg_translator.c:200]: check_via_address(192.98.101.10, 192.98.101.10, 0) Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/msg_parser.c:318]: parse_headers: flags=100 Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/parse_to.c:174]: DEBUG: add_param: tag=oggsp Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/parse_to.c:753]: end of header reached, state=29 Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/msg_parser.c:173]: DEBUG: get_hdr_field: <To> [30]; uri=[sip:test@test.fi] Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/msg_parser.c:175]: DEBUG: to body [sip:test@test.fi] Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/msg_parser.c:153]: get_hdr_field: cseq <CSeq>: <1> <NOTIFY> Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/msg_parser.c:187]: DEBUG: get_hdr_body : content_length=0 Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: maxfwd [mf_funcs.c:85]: value = 70 Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: lcr [lcr_mod.c:2227]: request did not come from gw Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: siputils [checks.c:68]: totag found Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/msg_parser.c:318]: parse_headers: flags=200 Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: rr [loose.c:85]: is_preloaded: No Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 13==13 && [192.98.101.10] == [192.98.101.10] Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5074 Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 13==9 && [192.98.101.10] == [127.0.0.1] Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5070 matches port 5074 Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 13==9 && [192.98.101.10] == [127.0.0.1] Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5080 matches port 5074 Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 13==13 && [192.98.101.10] == [192.98.101.10] Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5074 Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 13==13 && [192.98.101.10] == [192.98.101.10] Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5074 Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [forward.c:298]: check_self: host != me Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 13==13 && [192.98.101.10] == [192.98.101.10] Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060 Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: rr [loose.c:781]: Topmost route URI: 'sip:192.98.101.10;lr;ftag=oggsp' is me Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/msg_parser.c:318]: parse_headers: flags=200 Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: <core> [parser/msg_parser.c:89]: found end of header Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: rr [loose.c:257]: No next Route HF found Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: rr [loose.c:800]: No next URI found Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: rr [rr_cb.c:97]: callback id 0 entered with <lr;ftag=oggsp> Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: uac [from.c:421]: getting 'vsf' Route param Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: uac [from.c:425]: route param 'vsf' not found Jun 4 18:51:14 localhost /usr/sbin/sip-router[8249]: DEBUG: rr [loose.c:968]: params are <;lr;ftag=oggsp>
sr-dev mailing list sr-dev@lists.sip-router.org http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-dev
On Jun 05, 2009 at 11:44, Juha Heinanen jh@tutpro.com wrote:
when i read the "last words" debug more closely, it appears that the proxy handling three requests at the time when it goes into coma: it is executing save function from one register request, getting another register request, and getting a notify from presence server.
any pointers on how to find out why sr becomes unresponsive are greatly appreciated. how can it happen that the proxy stops doing anything even though its processes (or at least some of them) are still alive?
Could you attach with gdb to some processes and send us a backtrace? (gdb ser <pid_of_process> ; bt ) You could start sr with a small number of processes (e.g. -l eth0 -n 2) and then dump the backtrace from all of them using:
for r in `pidof ser`; do echo PID $r >>/tmp/bt.log; gdb -batch -ex bt ser $r >>/tmp/bt.log ; done Please send also the new log (with maximum debugging) so that we can try to correlate and the config (you could send only to me and Jan if) or at least the list of the modules loaded.
Thanks, Andrei
i'm just closing this thread and thank andrei for fixing a regex modfix bug that caused my sr to become unresponsive.
-- juha
On Jun 04, 2009 at 09:19, Juha Heinanen jh@tutpro.com wrote: [...]
by the way, how to get rid of
"xlog [xlog.c:186]:"
in xlog INFO output?
Replace the corresponding LOG line with: LOG_(DEFAULT_FACILITY, L_INFO, "<script>: ", ...(old LOG content)...)
We use "<script>: " as prefix for the script xlog() (modules_s/xlog) and log() (core).
Andrei
Andrei Pelinescu-Onciul writes:
Replace the corresponding LOG line with: LOG_(DEFAULT_FACILITY, L_INFO, "<script>: ", ...(old LOG content)...)
andrei,
are you suggesting that if i now have xlog
xlog("L_INFO", "INFO: Routing in-dialog $rm from <$fu> to <$ru>\n")
i should replace it with
LOG_(DEFAULT_FACILITY, L_INFO, "<script>: ", "INFO: Routing in-dialog $rm from <$fu> to <$ru>\n" )
if yes, it is far too long and complicated.
there must be a way to make the original xlog to produce the message without line number.
-- juha
On Jun 04, 2009 at 12:34, Juha Heinanen jh@tutpro.com wrote:
Andrei Pelinescu-Onciul writes:
Replace the corresponding LOG line with: LOG_(DEFAULT_FACILITY, L_INFO, "<script>: ", ...(old LOG content)...)
andrei,
are you suggesting that if i now have xlog
xlog("L_INFO", "INFO: Routing in-dialog $rm from <$fu> to <$ru>\n")
i should replace it with
LOG_(DEFAULT_FACILITY, L_INFO, "<script>: ", "INFO: Routing in-dialog $rm from <$fu> to <$ru>\n" )
if yes, it is far too long and complicated.
No, you should replace the LOG/LM_* call inside the xlog module code, corresponding to the script xlog() command. The script xlog() doesn't have to change, only its implementation.
Andrei
-
Andrei Pelinescu-Onciul -
Daniel-Constantin Mierla -
Iñaki Baz Castillo -
Jan Janak -
jh＠tutpro.com