-----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@openser.org http://openser.org/cgi-bin/mailman/listinfo/users
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@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