[OpenSIPS-Users] Opensips 1.6.3, presence, NAT&TCP - NOTIFY problem
mika.saari at wipsl.com
mika.saari at wipsl.com
Fri Oct 29 11:11:40 CEST 2010
Hi,
I am having problem with opensips 1.6.3 (release) and presence module
(openxcap used as xcap server). When using unNAT:ed network with UDP or
TCP, everything works nicely. When using NAT:ed network with UDP
everything works nicely. But when using NAT:ed network with TCP the last
(after the logout is requested) NOTIFY for SUBSCRIBE(Expires=0) is not
sent by the server, but instead the server informs that is can not find
the ready opened connection and is trying to open new one. The TCP
connection is open and all other responses comes to the client without
problems. Below is debug=6 strip from the logs. I would appreciate any
tips to help to find out possible problem in my configuration file.
Thanks a lot for help,
-Mika
---- Debug ----
First we register:
Oct 29 08:52:23 myserver opensips[15150]: DBG:core:tcp_read_req:
headers:#012REGISTER sip:domain.domain.com;transport=TCP
SIP/2.0#015#012Route: <sip:domain.domain.com;lr;transport=TCP>#015#012Via:
SIP/2.0/TCP
localhost;branch=z9hG4bKtstro6grtlhc6v0m0g7gck2;rport#015#012From:
<sip:test at domain.domain.com>;tag=pdhbo6lfjdhc61hf0g7g#015#012To:
<sip:test at domain.domain.com>#015#012Contact:
<sip:3mk3X8t3i9uYifL8c8c6 at 192.168.35.163:5060;transport=TCP>;expires=3600#015#012CSeq:
4925001 REGISTER#015#012Call-ID:
Y0WY6ItSoIdypggf1A9hKAvor2YqRk#015#012Supported:
sec-agree#015#012User-Agent: S60 RM-596 013.003#015#012Max-Forwards:
70#015#012Content-Length: 0#015#012#015#012.
.
.
.
No go because no authetication is done:
Oct 29 08:52:23 myserver opensips[15150]: DBG:core:tcp_send:
buf=#012SIP/2.0 401 Unauthorized#015#012Via: SIP/2.0/TCP
localhost;branch=z9hG4bKtstro6grtlhc6v0m0g7gck2;rport=57217;received=193.65.183.217#015#012From:
<sip:test at domain.domain.com>;tag=pdhbo6lfjdhc61hf0g7g#015#012To:
<sip:test at domain.domain.com>;tag=c97b4d1cb1f3d0da549e06a8d482ef63.db64#015#012CSeq:
4925001 REGISTER#015#012Call-ID:
Y0WY6ItSoIdypggf1A9hKAvor2YqRk#015#012WWW-Authenticate: Digest
realm="domain.domain.com",
nonce="4cca613500000004ea9ad4b2a093b7bb66e7519a54aa234a"#015#012Server:
OpenSIPS (1.6.3-tls (x86_64/linux))#015#012Content-Length:
0#015#012#015#012
.
.
We register again:
Oct 29 08:52:23 myserver opensips[15150]: DBG:core:tcp_read_req:
headers:#012REGISTER sip:domain.domain.com;transport=TCP
SIP/2.0#015#012Route: <sip:domain.domain.com;lr;transport=TCP>#015#012Via:
SIP/2.0/TCP
192.168.35.163:5060;branch=z9hG4bKgf8b4e5i72tngsspngd5p2b;rport#015#012From:
<sip:test at domain.domain.com>;tag=pdhbo6lfjdhc61hf0g7g#015#012To:
<sip:test at domain.domain.com>#015#012Contact:
<sip:3mk3X8t3i9uYifL8c8c6 at 192.168.35.163:5060;transport=TCP>;expires=3600#015#012CSeq:
4925002 REGISTER#015#012Call-ID:
Y0WY6ItSoIdypggf1A9hKAvor2YqRk#015#012Supported:
sec-agree#015#012User-Agent: S60 RM-596 013.003#015#012Max-Forwards:
70#015#012Authorization: Digest
realm="domain.domain.com",nonce="4cca613500000004ea9ad4b2a093b7bb66e7519a54aa234a",algorithm=MD5,username="test",uri="sip:domain.domain.com;transport=TCP",response="f730112d6a13178b9465a85aad2fb7ec"#015#012Content-Length:
0#015#012#015#012.
.
.
.
This time we are happy:
Oct 29 08:52:23 myserver opensips[15150]: DBG:core:tcp_send:
buf=#012SIP/2.0 200 OK#015#012Via: SIP/2.0/TCP
192.168.35.163:5060;branch=z9hG4bKgf8b4e5i72tngsspngd5p2b;rport=57217;received=193.65.183.217#015#012From:
<sip:test at domain.domain.com>;tag=pdhbo6lfjdhc61hf0g7g#015#012To:
<sip:test at domain.domain.com>;tag=c97b4d1cb1f3d0da549e06a8d482ef63.8ffd#015#012CSeq:
4925002 REGISTER#015#012Call-ID:
Y0WY6ItSoIdypggf1A9hKAvor2YqRk#015#012Contact:
<sip:3mk3X8t3i9uYifL8c8c6 at 192.168.35.163:5060;transport=TCP>;expires=3600;received="sip:193.65.183.217:57217;transport=TCP"#015#012Server:
OpenSIPS (1.6.3-tls (x86_64/linux))#015#012Content-Length:
0#015#012#015#012
.
.
Time flies and we can do our SIP calls.
.
.
Time to unregister from the server and send SUBSCRIBE with Expires:0:
Oct 29 08:52:53 myserver opensips[15150]: DBG:core:tcp_read: read 514
bytes:#012SUBSCRIBE sip:193.65.183.21;transport=TCP SIP/2.0#015#012Via:
SIP/2.0/TCP
192.168.35.163:5060;branch=z9hG4bKp57ro6jhr1hc7m2btmo7o7u;rport#015#012To:
<sip:test at domain.domain.com>;tag=155c340f586c28d0300cf5a6ccf90d99-9787#015#012From:
<sip:test at domain.domain.com>;tag=pe0bo6m5lphc6prk0mp5#015#012Contact:
<sip:3mk3X8t3i9uYifL8c8c6 at 192.168.35.163:5060;transport=TCP>#015#012Call-ID:
toWY6GR3oIfMo0mOnkQdVO3qgbQAg2#015#012CSeq: 4925004
SUBSCRIBE#015#012Expires: 0#015#012Max-Forwards: 70#015#012Accept:
application/watcherinfo+xml#015#012Event:
presence.winfo#015#012Content-Length: 0#015#012#015#012
Oct 29 08:52:53 myserver opensips[15150]: DBG:core:tcp_read_req: read= 514
bytes, parsed=514, state=4, error=1
Oct 29 08:52:53 myserver opensips[15150]: DBG:core:tcp_read_req: last
char=0x0A, parsed msg=#012SUBSCRIBE sip:193.65.183.21;transport=TCP
SIP/2.0#015#012Via: SIP/2.0/TCP
192.168.35.163:5060;branch=z9hG4bKp57ro6jhr1hc7m2btmo7o7u;rport#015#012To:
<sip:test at domain.domain.com>;tag=155c340f586c28d0300cf5a6ccf90d99-9787#015#012From:
<sip:test at domain.domain.com>;tag=pe0bo6m5lphc6prk0mp5#015#012Contact:
<sip:3mk3X8t3i9uYifL8c8c6 at 192.168.35.163:5060;transport=TCP>#015#012Call-ID:
toWY6GR3oIfMo0mOnkQdVO3qgbQAg2#015#012CSeq: 4925004
SUBSCRIBE#015#012Expires: 0#015#012Max-Forwards: 70#015#012Accept:
application/watcherinfo+xml#015#012Event:
presence.winfo#015#012Content-Length: 0#015#012#015#012
Oct 29 08:52:53 myserver opensips[15150]: DBG:core:tcp_read_req: end of
header part
Oct 29 08:52:53 myserver opensips[15150]: DBG:core:tcp_read_req: -
received from: port 57217
Oct 29 08:52:53 myserver opensips[15150]: DBG:core:print_ip: - received
from: ip 193.65.183.217
Oct 29 08:52:53 myserver opensips[15150]: DBG:core:tcp_read_req:
headers:#012SUBSCRIBE sip:193.65.183.21;transport=TCP SIP/2.0#015#012Via:
SIP/2.0/TCP
192.168.35.163:5060;branch=z9hG4bKp57ro6jhr1hc7m2btmo7o7u;rport#015#012To:
<sip:test at domain.domain.com>;tag=155c340f586c28d0300cf5a6ccf90d99-9787#015#012From:
<sip:test at domain.domain.com>;tag=pe0bo6m5lphc6prk0mp5#015#012Contact:
<sip:3mk3X8t3i9uYifL8c8c6 at 192.168.35.163:5060;transport=TCP>#015#012Call-ID:
toWY6GR3oIfMo0mOnkQdVO3qgbQAg2#015#012CSeq: 4925004
SUBSCRIBE#015#012Expires: 0#015#012Max-Forwards: 70#015#012Accept:
application/watcherinfo+xml#015#012Event:
presence.winfo#015#012Content-Length: 0#015#012#015#012.
Oct 29 08:52:53 myserver opensips[15150]: DBG:core:tcp_read_req:
content-length= 0
Oct 29 08:52:53 myserver opensips[15150]: DBG:core:tcp_send:
buf=#012SIP/2.0 200 OK#015#012Via: SIP/2.0/TCP
192.168.35.163:5060;branch=z9hG4bKp57ro6jhr1hc7m2btmo7o7u;rport=57217;received=193.65.183.217#015#012To:
<sip:test at domain.domain.com>;tag=155c340f586c28d0300cf5a6ccf90d99-9787#015#012From:
<sip:test at domain.domain.com>;tag=pe0bo6m5lphc6prk0mp5#015#012Call-ID:
toWY6GR3oIfMo0mOnkQdVO3qgbQAg2#015#012CSeq: 4925004
SUBSCRIBE#015#012Expires: 0#015#012Contact:
<sip:193.65.183.21;transport=tcp>#015#012Server: OpenSIPS (1.6.3-tls
(x86_64/linux))#015#012Content-Length: 0#015#012#015#012
Oct 29 08:52:53 myserver opensips[15150]: DBG:tm:_reply_light: reply sent
out. buf=0x7b7fa8: SIP/2.0 2..., shmem=0x7ffedcf4b5a8: SIP/2.0 2
Oct 29 08:52:53 myserver opensips[15150]: DBG:tm:_reply_light: finished
Oct 29 08:52:53 myserver opensips[15150]:
DBG:presence:send_notify_request: dialog info:
Oct 29 08:52:53 myserver opensips[15150]: DBG:presence:printf_subs:
#012#011[pres_uri]= sip:test at domain.domain.com#012#011[to_user]=
test#011[to_domain]= domain.domain.com#012#011[w_user]=
test#011[w_domain]= domain.domain.com#012#011[event]=
presence.winfo#012#011[status]= active#012#011[expires]=
0#012#011[callid]=
toWY6GR3oIfMo0mOnkQdVO3qgbQAg2#011[local_cseq]=1#012#011[to_tag]=
155c340f586c28d0300cf5a6ccf90d99-9787#011[from_tag]=
pe0bo6m5lphc6prk0mp5#012#011[contact]=
sip:3mk3X8t3i9uYifL8c8c6 at 192.168.35.163:5060;transport=TCP#011[record_route]=
Oct 29 08:52:53 myserver opensips[15150]: DBG:core:db_new_result: allocate
48 bytes for result set at 0x7b3948
Oct 29 08:52:53 myserver opensips[15150]:
DBG:db_mysql:db_mysql_get_columns: 2 columns returned from the query
Oct 29 08:52:53 myserver opensips[15150]: DBG:core:db_allocate_columns:
allocate 56 bytes for result columns at 0x7b4910
Oct 29 08:52:53 myserver opensips[15150]:
DBG:db_mysql:db_mysql_get_columns:
RES_NAMES(0x7b4920)[0]=[watcher_username]
Oct 29 08:52:53 myserver opensips[15150]:
DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
Oct 29 08:52:53 myserver opensips[15150]:
DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x7b4930)[1]=[watcher_domain]
Oct 29 08:52:53 myserver opensips[15150]:
DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
Oct 29 08:52:53 myserver opensips[15150]:
DBG:db_mysql:db_mysql_convert_rows: no rows returned from the query
Oct 29 08:52:53 myserver opensips[15150]:
DBG:presence:add_waiting_watchers: The query returned no result
Oct 29 08:52:53 myserver opensips[15150]: DBG:core:db_free_columns:
freeing result columns at 0x7b4910
Oct 29 08:52:53 myserver opensips[15150]: DBG:core:db_free_rows: freeing 0
rows
Oct 29 08:52:53 myserver opensips[15150]: DBG:core:db_free_result: freeing
result set at 0x7b3948
Oct 29 08:52:53 myserver opensips[15150]: DBG:presence:build_str_hdr:
state = terminated
Oct 29 08:52:53 myserver opensips[15150]:
DBG:presence:send_notify_request: headers:#012Max-Forwards:
70#015#012Event: presence.winfo#015#012Contact:
<sip:193.65.183.21;transport=tcp>#015#012Subscription-State:
terminated;reason=timeout#015#012Content-Type:
application/watcherinfo+xml#015#012
Oct 29 08:52:53 myserver opensips[15150]: DBG:presence:build_dlg_t:
CONTACT = sip:3mk3X8t3i9uYifL8c8c6 at 192.168.35.163:5060;transport=TCP
Oct 29 08:52:53 myserver opensips[15150]: DBG:tm:t_uac:
next_hop=<sip:3mk3X8t3i9uYifL8c8c6 at 192.168.35.163:5060;transport=TCP>
Oct 29 08:52:53 myserver opensips[15150]: DBG:core:parse_uri: parsed
uri:#012 type=1 user=<3mk3X8t3i9uYifL8c8c6>(20)#012 passwd=<>(0)#012
host=<192.168.35.163>(14)#012 port=<5060>(4): 5060#012
params=<transport=TCP>(13)#012 headers=<>(0)
Oct 29 08:52:53 myserver opensips[15150]: DBG:core:parse_uri: uri
params:#012 transport=<transport=TCP>, val=<TCP>, proto=2
Oct 29 08:52:53 myserver opensips[15150]: DBG:core:parse_uri:
user-param=<>, val=<>
Oct 29 08:52:53 myserver opensips[15150]: DBG:core:parse_uri:
method=<>, val=<>
Oct 29 08:52:53 myserver opensips[15150]: DBG:core:parse_uri: ttl=<>,
val=<>
Oct 29 08:52:53 myserver opensips[15150]: DBG:core:parse_uri: maddr=<>,
val=<>
Oct 29 08:52:53 myserver opensips[15150]: DBG:core:parse_uri: lr=<>
Oct 29 08:52:53 myserver opensips[15150]: DBG:core:mk_proxy: doing DNS
lookup...
Oct 29 08:52:53 myserver opensips[15150]: DBG:tm:dlg2hash: 13406
Oct 29 08:52:53 myserver opensips[15150]: DBG:tm:print_request_uri:
sip:3mk3X8t3i9uYifL8c8c6 at 192.168.35.163:5060;transport=TCP
Oct 29 08:52:53 myserver opensips[15150]: DBG:core:_tcpconn_find: 0 port
5060
Oct 29 08:52:53 myserver opensips[15150]: DBG:core:print_ip: tcpconn_find:
ip 192.168.35.163
=== Here comes the problem. The Contact in REGISTER is same as in the
NOTIFY the server is trying to send
(sip:3mk3X8t3i9uYifL8c8c6 at 192.168.35.163:5060;transport=TCP) but no open
tcp connection found. ====
Oct 29 08:52:53 myserver opensips[15150]: DBG:core:tcp_send: no open tcp
connection found, opening new one
Oct 29 08:52:53 myserver opensips[15150]: ERROR:core:tcp_blocking_connect:
poll error: flags 18
Oct 29 08:52:53 myserver opensips[15150]: ERROR:core:tcp_blocking_connect:
failed to retrieve SO_ERROR (111) Connection refused
Oct 29 08:52:53 myserver opensips[15150]: ERROR:core:tcpconn_connect:
tcp_blocking_connect failed
Oct 29 08:52:53 myserver opensips[15150]: ERROR:core:tcp_send: connect failed
Oct 29 08:52:53 myserver opensips[15150]: ERROR:tm:msg_send: tcp_send failed
Oct 29 08:52:53 myserver opensips[15150]: ERROR:tm:t_uac: attempt to send
to 'sip:3mk3X8t3i9uYifL8c8c6 at 192.168.35.163:5060;transport=TCP' failed
Oct 29 08:52:53 myserver opensips[15150]: DBG:tm:set_timer: relative
timeout is 30
Oct 29 08:52:53 myserver opensips[15150]: DBG:tm:insert_timer_unsafe: [0]:
0x7ffedcf499f0 (69426)
Oct 29 08:52:53 myserver opensips[15150]:
INFO:presence:send_notify_request: NOTIFY sip:test at domain.domain.com via
sip:3mk3X8t3i9uYifL8c8c6 at 192.168.35.163:5060;transport=TCP on behalf of
sip:test at domain.domain.com for event presence.winfo
Oct 29 08:52:53 myserver opensips[15150]: DBG:tm:t_unref: UNREF_UNSAFE:
after is 0
Oct 29 08:52:53 myserver opensips[15150]: DBG:core:destroy_avp_list:
destroying list (nil)
More information about the Users
mailing list