[OpenSIPS-Users] opensips 1.7+tls problems

yufei.tao yufei.tao at redembedded.com
Wed Aug 17 12:15:35 CEST 2011


Hi Vlad

Thanks very much for your response to my problems 2 and 3 - and they're
solved :)

About my problem 1: Registrations over TLS doesn't work on opensips 1.7:
so far it seems the server can only successfully send one message back
to the client and fail on sending the second:

1. In my route[register] that processes registrations, if I use
sl_send_reply("100", "Trying"), then the process is:
   initial REGISTER ---->
   <--------- 100 -------
Then server will then fail to send 401.

2. If I remove sl_send_reply("100", "Trying"), the process is:
 --- initial REGISTER ---->
 <---- 401 challenge -----
 --- REGISTER+auth ------->
Then server thinks the registration was successful and put it in the
location table fine, but failed to send OK back to client. I've got a
log with debug=6 that shows things since the success of authorization:

Aug 17 10:21:07 server2 /usr/sbin/opensips[27699]:
DBG:auth:check_response: authorization is OK
Aug 17 10:21:07 server2 /usr/sbin/opensips[27699]:
DBG:core:db_free_columns: freeing result columns at 0x8241630
Aug 17 10:21:07 server2 /usr/sbin/opensips[27699]:
DBG:core:db_free_rows: freeing 1 rows
Aug 17 10:21:07 server2 /usr/sbin/opensips[27699]: DBG:core:db_free_row:
freeing row values at 0x82403cc
Aug 17 10:21:07 server2 /usr/sbin/opensips[27699]:
DBG:core:db_free_rows: freeing rows at 0x82403c4
Aug 17 10:21:07 server2 /usr/sbin/opensips[27699]:
DBG:core:db_free_result: freeing result set at 0x824034c
Aug 17 10:21:07 server2 /usr/sbin/opensips[27699]:
MY-DBUG:REGISTER:REGISTERED: user at myserver.com, cseq=2
Aug 17 10:21:07 server2 /usr/sbin/opensips[27699]:
DBG:core:parse_headers: flags=ffffffffffffffff
Aug 17 10:21:07 server2 /usr/sbin/opensips[27699]:
DBG:core:parse_headers: flags=8000000
Aug 17 10:21:07 server2 /usr/sbin/opensips[27699]:
DBG:core:parse_headers: flags=ffffffffffffffff
Aug 17 10:21:07 server2 /usr/sbin/opensips[27699]:
DBG:registrar:build_contact: created Contact HF: Contact:
<sip:user at 127.0.1.1:5060>;expires=60;received="sip:10.82.131.132:16689;transport=TLS"^M
 
Aug 17 10:21:07 server2 /usr/sbin/opensips[27699]:
DBG:core:parse_headers: flags=ffffffffffffffff
Aug 17 10:21:07 server2 /usr/sbin/opensips[27699]:
DBG:core:check_ip_address: params 10.82.131.132, 127.0.1.1, 0
Aug 17 10:21:07 server2 /usr/sbin/opensips[27699]:
DBG:sl:run_sl_callbacks: callback id 1 entered
Aug 17 10:21:07 server2 /usr/sbin/opensips[27699]:
DBG:siptrace:trace_sl_onreply_out: trace off...
Aug 17 10:21:07 server2 /usr/sbin/opensips[27699]:
DBG:sl:run_sl_callbacks: callback id 0 entered
Aug 17 10:21:07 server2 /usr/sbin/opensips[27699]: DBG:core:tcp_send:
tcp connection found (0xa79246f8), acquiring fd
Aug 17 10:21:07 server2 /usr/sbin/opensips[27762]:
DBG:core:handle_ser_child: read response= a79246f8, 1, fd -1 from 39
(27699)
Aug 17 10:21:07 server2 /usr/sbin/opensips[27699]: DBG:core:tcp_send: c=
0xa79246f8, n=8
Aug 17 10:21:07 server2 /usr/sbin/opensips[27699]: DBG:core:tcp_send:
after receive_fd: c= 0xa79246f8 n=4 fd=52
Aug 17 10:21:07 server2 /usr/sbin/opensips[27699]: DBG:core:tcp_send:
sending...
Aug 17 10:21:07 server2 /usr/sbin/opensips[27699]:
DBG:core:tls_update_fd: New fd is 52
Aug 17 10:21:07 server2 /usr/sbin/opensips[27699]: ERROR:core:tls_write:
something wrong in SSL:
Aug 17 10:21:07 server2 /usr/sbin/opensips[27699]:
ERROR:core:tls_blocking_write: failed to send data
Aug 17 10:21:07 server2 /usr/sbin/opensips[27699]:
ERROR:core:tsend_stream: tsend_stream: failed to send: (32) Broken pipe
Aug 17 10:21:07 server2 /usr/sbin/opensips[27699]: DBG:core:tcp_send:
after write: c= 0xa79246f8 n=-1 fd=52
Aug 17 10:21:07 server2 /usr/sbin/opensips[27699]: DBG:core:tcp_send:
buf= SIP/2.0 200 OK^M Via: SIP/2.0/TLS
127.0.1.1:5060;branch=z9hG4bK-13722-1-3;rport=16689;received=10.82.131.132^M
From: user <sip:user at myserver.com:5060>;tag=1^M To: user
<sip:user at myserver.com>;tag=4d01edab9105ba9cff8de765aa181a6e.e2bb^M
Call-ID: 1-13722 at 127.0.1.1^M CSeq: 2 REGISTER^M Contact:
<sip:user at 127.0.1.1:5060>;expires=60;received="sip:10.82.131.132:16689;transport=TLS"^M
Server: OpenSIPS (1.7.0-beta-tls (i386/linux))^M Content-Length: 0^M ^M  
Aug 17 10:21:07 server2 /usr/sbin/opensips[27699]: ERROR:core:tcp_send:
failed to send
Aug 17 10:21:07 server2 /usr/sbin/opensips[27762]:
DBG:core:handle_ser_child: read response= a79246f8, -2, fd -1 from 39
(27699)
Aug 17 10:21:07 server2 /usr/sbin/opensips[27762]:
DBG:core:tcpconn_destroy: delaying (0xa79246f8, flags 0002) ...
Aug 17 10:21:07 server2 /usr/sbin/opensips[27699]: ERROR:sl:msg_send:
tcp_send failed
Aug 17 10:21:07 server2 /usr/sbin/opensips[27699]:
ERROR:signaling:sig_send_reply_mod: failed to send reply with sl module
Aug 17 10:21:07 server2 /usr/sbin/opensips[27699]:
ERROR:registrar:send_reply: failed to send 200 OK
Aug 17 10:21:07 server2 /usr/sbin/opensips[27699]:
DBG:core:destroy_avp_list: destroying list 0xa794a198
Aug 17 10:21:07 server2 /usr/sbin/opensips[27699]: DBG:core:receive_msg:
cleaning up
Aug 17 10:21:07 server2 /usr/sbin/opensips[27699]:
DBG:core:io_watch_del: io_watch_del (0x8168f20, 51, -1, 0x10) fd_no=2
called
Aug 17 10:21:07 server2 /usr/sbin/opensips[27699]:
DBG:core:release_tcpconn:  releasing con 0xa79246f8, state -2, fd=51, id=19
Aug 17 10:21:07 server2 /usr/sbin/opensips[27699]:
DBG:core:release_tcpconn:  extra_data 0xa7934814
Aug 17 10:21:07 server2 /usr/sbin/opensips[27762]:
DBG:core:handle_tcp_child: reader response= a79246f8, -2 from 0  
Aug 17 10:21:07 server2 /usr/sbin/opensips[27762]:
DBG:core:tcpconn_destroy: destroying connection 0xa79246f8, flags 0002
Aug 17 10:21:07 server2 /usr/sbin/opensips[27762]: DBG:core:tls_close:
closing SSL connection
Aug 17 10:21:07 server2 /usr/sbin/opensips[27762]:
DBG:core:tls_update_fd: New fd is 112
Aug 17 10:21:07 server2 /usr/sbin/opensips[27762]:
DBG:core:tls_shutdown: first phase of 2-way handshake completed succesfuly
Aug 17 10:21:07 server2 /usr/sbin/opensips[27762]:
DBG:core:tls_tcpconn_clean: entered
Aug 17 10:21:19 server2 /usr/sbin/opensips[27681]:
DBG:core:udp_rcv_loop: probing packet received len = 2

Any suggestions where I should look? Thanks very much!

Yufei



More information about the Users mailing list