4 Jun
2009
4 Jun
'09
8:19 a.m.
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(a)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
4 Jun
4 Jun
10:56 a.m.
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(a)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.
11:40 a.m.
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(a)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
12:03 p.m.
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(a)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(a)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(a)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
12:19 p.m.
On 04-06 13:03, Juha Heinanen wrote:
Jan Janak writes:
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.
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(a)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(a)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(a)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
12:32 p.m.
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
12:38 p.m.
El Jueves, 4 de Junio de 2009, Jan Janak escribió:
On 04-06 13:03, Juha Heinanen wrote:
If you are using xcal_client, remove it!
In OpenSIPS it caused this error due to a bad DB initialization.
--
Iñaki Baz Castillo <ibc(a)aliax.net>
Jan Janak writes:
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? 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(a)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(a)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(a)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
5:31 p.m.
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(a)test.fi and jh(a)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(a)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(a)localhost',950,0,0,'Twinkle/1.4.2',NULL,NULL,'',6111,'2009-06-04
18:22:05','test.fi')
6:05 p.m.
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(a)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>
5 Jun
5 Jun
10:44 a.m.
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(a)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>
11:03 a.m.
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(a)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(a)lists.sip-router.org
http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-dev
--
Daniel-Constantin Mierla
http://www.asipto.com/
11:12 a.m.
On Jun 05, 2009 at 11:44, Juha Heinanen <jh(a)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
8:04 p.m.
i'm just closing this thread and thank andrei for fixing a regex modfix
bug that caused my sr to become unresponsive.
-- juha
4 Jun
4 Jun
11:11 a.m.
On Jun 04, 2009 at 09:19, Juha Heinanen <jh(a)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
11:34 a.m.
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
11:57 a.m.
On Jun 04, 2009 at 12:34, Juha Heinanen <jh(a)tutpro.com> wrote:
Andrei Pelinescu-Onciul writes:
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
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.
5446
days inactive
5447
days old
16 comments
5 participants
participants (5)
-
Andrei Pelinescu-Onciul -
Daniel-Constantin Mierla -
Iñaki Baz Castillo -
Jan Janak -
jh＠tutpro.com