-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1
Hi Bogdan,
Sry, didn't thought when I sent the logs. Here is the debug output
with an error 500.
chris...
Bogdan-Andrei Iancu schrieb:
Hi Christoph,
the log shows a working REGISTER. can you please provide a log with
failing INVITE (containing the error you were refereing at).
regards, bogdan
Christoph Fürstaller wrote:
Hi Bogdan,
Ok, if UDP is needed by this protocol then it shouldn't function
without it.
I attached the debuging output from openSER when the snom tries to
login.
What are the Contact entries? Are they because the phone didn't
unregistered correctly? I just pluged it off and an again to see
the login output. All this entries are in the location table in my
db.
chris...
Bogdan-Andrei Iancu wrote:
>> Hi Cris,
>
>> thanks for you info
>
>> Christoph Fürstaller wrote:
>
>
>>> -----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1
>
>
>>> Hi Bogdan, I still get
the same 'error' with another phone.
>>> A snom 190. If I connect it to an TLS only SER I get thd
>>> "500 I'm terribly sorry, server error occurred (7/TM)". If
>>> I open up UDP as well the phone registeres fine with SER.
>
>
>>> I read another posting
which sayes: " If I remember
>>> correctly
the RFC,
>>> UDP is mandatory for a SIP
server" Is this correct? I don't
>>>
know it.
>
>
>
>
>
>
>> yes, UDP is mandatory as protocol.
>
>
>>> I attached my cfg. It's the one coming with tls-openSER and
>>> i think you wrote it : )
>
>
>
>
>
>
>>
ok - I will take a look, but please give me also the RURI
>> sent
by the
>> SNOM (it is essential) - I will try to
locate the problem
>
>> regards, bogdan
>>
>
------------------------------------------------------------------------
>
11(26780) tcpconn_new: new tcp
connection to: 192.168.20.187
11(26780) tcpconn_new: on port 2049, type 3 11(26780)
tls_tcpconn_init: Entered: Creating a whole new ssl connection
11(26780) tls_tcpconn_init: Looking up tls domain
[192.168.20.156:5061] 11(26780) tls_tcpconn_init: Using default tls
server settings 11(26780) tls_tcpconn_init: Setting in ACCEPT mode
(server) 11(26780) tcpconn_add: hashes: 193, 209 11(26780)
handle_new_connect: new connection: 0x4060b6c8 25 flags: 0002
11(26780) send2child: to tcp child 0 7(26766), 0x4060b6c8 7(26766)
received n=4 con=0x4060b6c8, fd=20 7(26766) DBG:
io_watch_add(0x80f17c0, 20, 2, 0x4060b6c8), fd_no=1 7(26766)
tls_update_fd: New fd is 20 7(26766) tls_update_fd: New fd is 20
7(26766) tls_accept: TLS handshake successful 7(26766)
tls_update_fd: New fd is 20 7(26766) tls_update_fd: New fd is 20
7(26766) tls_update_fd: New fd is 20 7(26766) _tls_read: 866 bytes
read 7(26766) tcp_read_req: content-length= 0 7(26766) SIP Request:
7(26766) method: <REGISTER> 7(26766) uri:
<sip:192.168.20.156:5061;transport=tls> 7(26766) version:
<SIP/2.0> 7(26766) parse_headers: flags=2 7(26766) Found param type
232, <branch> = <z9hG4bK-xwuy1h54dryy>; state=6 7(26766) Found
param type 235, <rport> = <n/a>; state=17 7(26766) end of header
reached, state=5 7(26766) parse_headers: Via found, flags=2
7(26766) parse_headers: this is the first via 7(26766) After
parse_msg... 7(26766) preparing to run routing scripts... 7(26766)
parse_headers: flags=100 7(26766) DEBUG:parse_to:end of header
reached, state=9 7(26766) DEBUG: get_hdr_field: <To> [53];
uri=[sip:test@192.168.20.156:5061;transport=tls] 7(26766) DEBUG: to
body ["test" <sip:test@192.168.20.156:5061;transport=tls> ]
7(26766) get_hdr_field: cseq <CSeq>: <1> <REGISTER> 7(26766)
DEBUG:maxfwd:is_maxfwd_present: value = 70 7(26766) parse_headers:
flags=200 7(26766) DEBUG: get_hdr_body : content_length=0 7(26766)
found end of header 7(26766) find_first_route: No Route headers
found 7(26766) loose_route: There is no Route HF 7(26766)
grep_sock_info - checking if host==us: 14==14 && [192.168.20.156]
== [192.168.20.156] 7(26766) grep_sock_info - checking if port 5060
matches port 5061 7(26766) grep_sock_info - checking if host==us:
14==14 && [192.168.20.156] == [192.168.20.156] 7(26766)
grep_sock_info - checking if port 5061 matches port 5061 7(26766)
grep_sock_info - checking if host==us: 14==14 && [192.168.20.156]
== [192.168.20.156] 7(26766) grep_sock_info - checking if port 5060
matches port 5061 7(26766) grep_sock_info - checking if host==us:
14==14 && [192.168.20.156] == [192.168.20.156] 7(26766)
grep_sock_info - checking if port 5061 matches port 5061 7(26766)
parse_headers: flags=4000 7(26766) pre_auth(): Credentials with
given realm not found 7(26766) build_auth_hf(): 'WWW-Authenticate:
Digest realm="192.168.20.156",
nonce="4423cd4c884708795300456efae3cc8121e7155c" ' 7(26766)
parse_headers: flags=ffffffffffffffff 7(26766)
check_via_address(192.168.20.187, 192.168.20.187, 0) 7(26766)
tcp_send: tcp connection found (0x4060b6c8), acquiring fd 7(26766)
tcp_send, c= 0x4060b6c8, n=8 11(26780) handle_ser_child: read
response= 4060b6c8, 1, fd -1 from 7 (26766) 7(26766) tcp_send:
after receive_fd: c= 0x4060b6c8 n=4 fd=21 7(26766) tcp_send:
sending... 7(26766) tls_update_fd: New fd is 21 7(26766) tls_write:
Write was successful (722 bytes) 7(26766) tcp_send: after write: c=
0x4060b6c8 n=722 fd=21 7(26766) tcp_send: buf= SIP/2.0 401
Unauthorized Via: SIP/2.0/TLS
192.168.20.187:2049;branch=z9hG4bK-xwuy1h54dryy;rport=2049 From:
"test" <sip:test@192.168.20.156:5061;transport=tls>;tag=3ntprlhika
To: "test"
<sip:test@192.168.20.156:5061;transport=tls>;tag=010b4fa55c4d08d1039c6a916bb5ecdc.9c39
Call-ID: 3c26700a0c35-l9lq3hhij6ml@snom190 CSeq: 1 REGISTER
WWW-Authenticate: Digest realm="192.168.20.156",
nonce="4423cd4c884708795300456efae3cc8121e7155c" Server: OpenSer
(1.1.0-dev16 -tls (i386/linux)) Content-Length: 0 Warning: 392
192.168.20.156:5061 "Noisy feedback tells: pid=26766
req_src_ip=192.168.20.187 req_src_port=2049
in_uri=sip:192.168.20.156:5061;transport=tls
out_uri=sip:192.168.20.156:5061;transport=tls via_cnt==1"
>
>
7(26766) DEBUG:destroy_avp_list: destroying list (nil) 7(26766)
receive_msg: cleaning up 7(26766) tls_update_fd: New fd is 20
7(26766) tls_update_fd: New fd is 20 7(26766) tls_update_fd: New fd
is 20 7(26766) _tls_read: 1079 bytes read 7(26766) tcp_read_req:
content-length= 0 7(26766) SIP Request: 7(26766) method:
<REGISTER> 7(26766) uri:
<sip:192.168.20.156:5061;transport=tls> 7(26766) version:
<SIP/2.0> 7(26766) parse_headers: flags=2 7(26766) Found param type
232, <branch> = <z9hG4bK-6fjbha0qxrtw>; state=6 7(26766) Found
param type 235, <rport> = <n/a>; state=17 7(26766) end of header
reached, state=5 7(26766) parse_headers: Via found, flags=2
7(26766) parse_headers: this is the first via 7(26766) After
parse_msg... 7(26766) preparing to run routing scripts... 7(26766)
parse_headers: flags=100 7(26766) DEBUG:parse_to:end of header
reached, state=9 7(26766) DEBUG: get_hdr_field: <To> [53];
uri=[sip:test@192.168.20.156:5061;transport=tls] 7(26766) DEBUG: to
body ["test" <sip:test@192.168.20.156:5061;transport=tls> ]
7(26766) get_hdr_field: cseq <CSeq>: <2> <REGISTER> 7(26766)
DEBUG:maxfwd:is_maxfwd_present: value = 70 7(26766) parse_headers:
flags=200 7(26766) DEBUG: get_hdr_body : content_length=0 7(26766)
found end of header 7(26766) find_first_route: No Route headers
found 7(26766) loose_route: There is no Route HF 7(26766)
grep_sock_info - checking if host==us: 14==14 && [192.168.20.156]
== [192.168.20.156] 7(26766) grep_sock_info - checking if port 5060
matches port 5061 7(26766) grep_sock_info - checking if host==us:
14==14 && [192.168.20.156] == [192.168.20.156] 7(26766)
grep_sock_info - checking if port 5061 matches port 5061 7(26766)
grep_sock_info - checking if host==us: 14==14 && [192.168.20.156]
== [192.168.20.156] 7(26766) grep_sock_info - checking if port 5060
matches port 5061 7(26766) grep_sock_info - checking if host==us:
14==14 && [192.168.20.156] == [192.168.20.156] 7(26766)
grep_sock_info - checking if port 5061 matches port 5061 7(26766)
check_nonce(): comparing [4423cd4c884708795300456efae3cc8121e7155c]
and [4423cd4c884708795300456efae3cc8121e7155c] 7(26766) HA1 string
calculated: 53ee6c16b5102c59afa23cbd21a6d936 7(26766)
check_response(): Our result = '5eea837512ca0655ce1369c41b5185b6'
7(26766) check_response(): Authorization is OK 7(26766)
parse_headers: flags=ffffffffffffffff 7(26766) parse_headers:
flags=8000000 7(26766) build_contact(): Created Contact HF:
Contact:
<sip:test@192.168.20.187:2253;transport=tls;line=4f5o4cc1>;q=1;expires=246,
<sip:test@192.168.20.187:2254;transport=tls;line=4f5o4cc1>;q=1;expires=759,
<sip:test@192.168.20.187:2255;transport=tls;line=4f5o4cc1>;q=1;expires=1073,
<sip:test@192.168.20.187:2256;transport=tls;line=4f5o4cc1>;q=1;expires=1538,
<sip:test@192.168.20.187:2257;transport=tls;line=4f5o4cc1>;q=1;expires=1849,
<sip:test@192.168.20.187:2258;transport=tls;line=4f5o4cc1>;q=1;expires=2150,
<sip:test@192.168.20.187:2259;transport=tls;line=4f5o4cc1>;q=1;expires=2637,
<sip:test@192.168.20.187:2260;transport=tls;line=4f5o4cc1>;q=1;expires=3022,
<sip:test@192.168.20.187:2261;transport=tls;line=4f5o4cc1>;q=1;expires=3323,
<sip:test@192.168.20.187:2049;transport=tls;line=xxzpplzh>;q=1;expires=3442,
<sip:test@192.168.20.187:2049;transport=tls;line=kshlnn3b>;q=1;expires=3600
>
7(26766) parse_headers:
flags=ffffffffffffffff 7(26766)
check_via_address(192.168.20.187, 192.168.20.187, 0) 7(26766)
tcp_send: tcp connection found (0x4060b6c8), acquiring fd 7(26766)
tcp_send, c= 0x4060b6c8, n=8 11(26780) handle_ser_child: read
response= 4060b6c8, 1, fd -1 from 7 (26766) 7(26766) tcp_send:
after receive_fd: c= 0x4060b6c8 n=4 fd=21 7(26766) tcp_send:
sending... 7(26766) tls_update_fd: New fd is 21 7(26766) tls_write:
Write was successful (1467 bytes) 7(26766) tcp_send: after write:
c= 0x4060b6c8 n=1467 fd=21 7(26766) tcp_send: buf= SIP/2.0 200 OK
Via: SIP/2.0/TLS
192.168.20.187:2049;branch=z9hG4bK-6fjbha0qxrtw;rport=2049 From:
"test" <sip:test@192.168.20.156:5061;transport=tls>;tag=3ntprlhika
To: "test"
<sip:test@192.168.20.156:5061;transport=tls>;tag=010b4fa55c4d08d1039c6a916bb5ecdc.a59e
Call-ID: 3c26700a0c35-l9lq3hhij6ml@snom190 CSeq: 2 REGISTER
Contact:
<sip:test@192.168.20.187:2253;transport=tls;line=4f5o4cc1>;q=1;expires=246,
<sip:test@192.168.20.187:2254;transport=tls;line=4f5o4cc1>;q=1;expires=759,
<sip:test@192.168.20.187:2255;transport=tls;line=4f5o4cc1>;q=1;expires=1073,
<sip:test@192.168.20.187:2256;transport=tls;line=4f5o4cc1>;q=1;expires=1538,
<sip:test@192.168.20.187:2257;transport=tls;line=4f5o4cc1>;q=1;expires=1849,
<sip:test@192.168.20.187:2258;transport=tls;line=4f5o4cc1>;q=1;expires=2150,
<sip:test@192.168.20.187:2259;transport=tls;line=4f5o4cc1>;q=1;expires=2637,
<sip:test@192.168.20.187:2260;transport=tls;line=4f5o4cc1>;q=1;expires=3022,
<sip:test@192.168.20.187:2261;transport=tls;line=4f5o4cc1>;q=1;expires=3323,
<sip:test@192.168.20.187:2049;transport=tls;line=xxzpplzh>;q=1;expires=3442,
<sip:test@192.168.20.187:2049;transport=tls;line=kshlnn3b>;q=1;expires=3600
Server: OpenSer (1.1.0-dev16 -tls (i386/linux)) Content-Length: 0
Warning: 392 192.168.20.156:5061 "Noisy feedback tells: pid=26766
req_src_ip=192.168.20.187 req_src_port=2049
in_uri=sip:192.168.20.156:5061;transport=tls
out_uri=sip:192.168.20.156:5061;transport=tls via_cnt==1"
>
>
7(26766) DEBUG:destroy_avp_list: destroying list (nil) 7(26766)
receive_msg: cleaning up 7(26766) tcp_receive_loop: 0x4060b6c8
expired (81329, 81330) 7(26766) DBG: io_watch_del (0x80f17c0, 20,
-1, 0x10) fd_no=2 called 7(26766) releasing con 0x4060b6c8, state
0, fd=20, id=209 7(26766) extra_data 0x405dad88 11(26780)
handle_tcp_child: reader response= 4060b6c8, 0 from 0 11(26780)
DBG: io_watch_add(0x80f14a0, 25, 2, 0x4060b6c8), fd_no=15 11(26780)
handle_tcp_child: CONN_RELEASE 0x4060b6c8 refcnt= 0
>
------------------------------------------------------------------------
>
_______________________________________________ Users mailing list
Users(a)openser.org
http://openser.org/cgi-bin/mailman/listinfo/users
-----BEGIN
PGP SIGNATURE-----
Version: GnuPG v1.4.1 (MingW32)
Comment: Using GnuPG with Mozilla -
http://enigmail.mozdev.org
iD8DBQFEKDxbR0exH8dhr/YRAg4DAJ4+hLWSQf6K8bdl5ooXbR1713lC4wCg2gh9
TUCBM7BMg82DiNM25RhMuvg=
=yvu8
-----END PGP SIGNATURE-----
7(18696) tcpconn_new: new tcp connection to: 192.168.20.130
7(18696) tcpconn_new: on port 53605, type 3
7(18696) tls_tcpconn_init: Entered: Creating a whole new ssl connection
7(18696) tls_tcpconn_init: Looking up tls domain [192.168.20.156:5061]
7(18696) tls_tcpconn_init: Using default tls server settings
7(18696) tls_tcpconn_init: Setting in ACCEPT mode (server)
7(18696) tcpconn_add: hashes: 421, 1
7(18696) handle_new_connect: new connection: 0x405ca688 20 flags: 0002
7(18696) send2child: to tcp child 0 3(18691), 0x405ca688
3(18691) received n=4 con=0x405ca688, fd=15
3(18691) DBG: io_watch_add(0x80f17c0, 15, 2, 0x405ca688), fd_no=1
3(18691) tls_update_fd: New fd is 15
3(18691) tls_update_fd: New fd is 15
3(18691) tls_accept: TLS handshake successful
3(18691) tls_update_fd: New fd is 15
3(18691) tls_update_fd: New fd is 15
3(18691) _tls_read: 394 bytes read
3(18691) tcp_read_req: content-length= 0
3(18691) SIP Request:
3(18691) method: <REGISTER>
3(18691) uri: <sip:192.168.20.156>
3(18691) version: <SIP/2.0>
3(18691) parse_headers: flags=2
3(18691) DEBUG:parse_to:end of header reached, state=9
3(18691) DEBUG: get_hdr_field: <To> [25]; uri=[sip:10@192.168.20.156]
3(18691) DEBUG: to body [<sip:10@192.168.20.156>]
3(18691) get_hdr_field: cseq <CSeq>: <301> <REGISTER>
3(18691) Found param type 232, <branch> = <z9hG4bK1474748722>; state=16
3(18691) end of header reached, state=5
3(18691) parse_headers: Via found, flags=2
3(18691) parse_headers: this is the first via
3(18691) After parse_msg...
3(18691) preparing to run routing scripts...
3(18691) DEBUG:maxfwd:is_maxfwd_present: value = 70
3(18691) parse_headers: flags=200
3(18691) is_preloaded: Yes
3(18691) grep_sock_info - checking if host==us: 14==14 && [192.168.20.156] ==
[192.168.20.156]
3(18691) grep_sock_info - checking if port 5061 matches port 5061
3(18691) after_loose: Topmost route URI:
'sip:192.168.20.156:5061;transport=TLS;lr' is me
3(18691) parse_headers: flags=200
3(18691) DEBUG: get_hdr_body : content_length=0
3(18691) found end of header
3(18691) find_next_route: No next Route HF found
3(18691) after_loose: No next URI found
3(18691) grep_sock_info - checking if host==us: 14==14 && [192.168.20.156] ==
[192.168.20.156]
3(18691) grep_sock_info - checking if port 5061 matches port 5060
3(18691) check_self: host != me
3(18691) parse_headers: flags=ffffffffffffffff
3(18691) DEBUG: t_newtran: msg id=1 , global msg id=0 , T on entrance=0xffffffff
3(18691) parse_headers: flags=ffffffffffffffff
3(18691) parse_headers: flags=78
3(18691) t_lookup_request: start searching: hash=58053, isACK=0
3(18691) DEBUG: RFC3261 transaction matching failed
3(18691) DEBUG: t_lookup_request: no transaction found
3(18691) DEBUG: mk_proxy: doing DNS lookup...
3(18691) ERROR:tm:add_uac: can't fwd to af 2, proto 1 (no corresponding listening
socket)
3(18691) ERROR:tm:t_forward_nonack: failure to add branches
3(18691) ERROR:tm:t_relay_to: t_forward_nonack returned error
3(18691) parse_headers: flags=ffffffffffffffff
3(18691) check_via_address(192.168.20.130, 192.168.20.130, 0)
3(18691) WARNING:vqm_resize: resize(0) called
3(18691) DEBUG: cleanup_uac_timers: RETR/FR timers reset
3(18691) DEBUG: add_to_tail_of_timer[2]: 0x405ee610
3(18691) tcp_send: tcp connection found (0x405ca688), acquiring fd
3(18691) tcp_send, c= 0x405ca688, n=8
7(18696) handle_ser_child: read response= 405ca688, 1, fd -1 from 3 (18691)
3(18691) tcp_send: after receive_fd: c= 0x405ca688 n=4 fd=16
3(18691) tcp_send: sending...
3(18691) tls_update_fd: New fd is 16
3(18691) tls_write: Write was successful (531 bytes)
3(18691) tcp_send: after write: c= 0x405ca688 n=531 fd=16
3(18691) tcp_send: buf=
SIP/2.0 500 I'm terribly sorry, server error occurred (7/TM)
From: <sip:10@192.168.20.156>
To: <sip:10@192.168.20.156>;tag=ddf051b13744e2e8329237e95d7a9ade-5806
Call-ID: 532272529(a)192.168.20.130
CSeq: 301 REGISTER
Via: SIP/2.0/TLS 192.168.20.130:34820;branch=z9hG4bK1474748722
Server: OpenSer (1.1.0-dev16 -tls (i386/linux))
Content-Length: 0
Warning: 392 192.168.20.156:5061 "Noisy feedback tells: pid=18691 req_src_ip=19
2.168.20.130 req_src_port=53605 in_uri=sip:192.168.20.156 out_uri=sip:192.168.20.156
via_cnt==1"
3(18691) DEBUG:tm:_reply_light: reply sent out. buf=0x812e300: SIP/2.0 5..., sh
mem=0x405ef8c0: SIP/2.0 5
3(18691) DEBUG:tm:_reply_light: finished
3(18691) ERROR: generation of a stateful reply on error succeeded
3(18691) DEBUG:destroy_avp_list: destroying list (nil)
3(18691) receive_msg: cleaning up
2(18689) DEBUG: timer routine:2,tl=0x405ee610 next=(nil)
2(18689) DEBUG: wait_handler : removing 0x405ee5c8 from table
2(18689) DEBUG: delete transaction 0x405ee5c8
2(18689) DEBUG: wait_handler : done
3(18691) tcp_receive_loop: 0x405ca688 expired (22, 23)
3(18691) DBG: io_watch_del (0x80f17c0, 15, -1, 0x10) fd_no=2 called
3(18691) releasing con 0x405ca688, state 0, fd=15, id=1
3(18691) extra_data 0x405da7a0
7(18696) handle_tcp_child: reader response= 405ca688, 0 from 0
7(18696) DBG: io_watch_add(0x80f14a0, 20, 2, 0x405ca688), fd_no=11
7(18696) handle_tcp_child: CONN_RELEASE 0x405ca688 refcnt= 0
7(18696) handle_tcpconn_ev: data available on 0x405ca688 20
7(18696) DBG: io_watch_del (0x80f14a0, 20, -1, 0x0) fd_no=12 called
7(18696) send2child: to tcp child 0 3(18691), 0x405ca688
3(18691) received n=4 con=0x405ca688, fd=15
3(18691) DBG: io_watch_add(0x80f17c0, 15, 2, 0x405ca688), fd_no=1
3(18691) tls_update_fd: New fd is 15
3(18691) _tls_read: Error in SSL:
3(18691) ERROR: tcp_read_req: error reading
3(18691) DBG: io_watch_del (0x80f17c0, 15, -1, 0x10) fd_no=2 called
3(18691) releasing con 0x405ca688, state -2, fd=15, id=1
3(18691) extra_data 0x405da7a0
7(18696) handle_tcp_child: reader response= 405ca688, -2 from 0
7(18696) tcpconn_destroy: destroying connection 0x405ca688, flags 0002
7(18696) tls_close: Closing SSL connection
7(18696) tls_update_fd: New fd is 20
7(18696) tls_shutdown: First phase of 2-way handshake completed succesfuly
7(18696) tls_tcpconn_clean: Entered