Hi, We are using Sofia SIP 1.12.11 as UA with Asterisk 1.8.7 using TLS. It registers OK but then keeps losing its connection and seems to keep registering every 30 seconds.
We have tried other clients such as Bria and these work fine with TLS to our Asterisk 1.8.7 server so its something to do with our Sofia client. The Sofia client works fine with TCP with same Asterisk 1.8.7 server. Trace is below, Sofia seems to get a HUP event which makes it lose its connection, anybody any ideas how to make Sofia keep the TLS connection open THanks ------------------------------------------------------------------------- nua: nua_stack_init: entering nua: nua_stack_set_params: entering nta_agent_create: initialized hash tables nta_agent_create: initialized transports nta_agent_create: initialized random identifiers nta_agent_create: initialized timer tport_tls_writevec: vec 0x4676c80 0xb6f200 581 (581) tport_vsend returned 581 tport(0x4687d80): reset timer nta: sent SUBSCRIBE (18216628) to TLS/178.76.132.10:5061 tport_pend(0x4687d80): pending 0x4665030 for tls/178.76.132.10:5061 (already 0) nua(0x4673cd0): removing subscribe usage with event message-summary nta_leg_destroy(0x468bc80) nta_leg_destroy(0x0) nua: nua_stack_shutdown: entering nta: outgoing_free(0x4664520) tport_release(0x4687d80): 0x4665030 by 0x4664520 with 0x0 tport(0x4687d80): set timer at 1799987 ms because idle since send sres_sofia_update(0x7998a0, -1, -1) sres_sofia_update(0x0, -1, -1) tport_destroy(0x4688af0) nta_agent_create: initialized resolver tport_create(): 0x465eb10 nta: master transport created tport_bind_server(0x465eb10) to */192.168.1.100:10131/sips tport_bind_server(0x465eb10): calling tport_listen for tls tport_alloc_primary(0x465eb10): new primary tport 0x465af70 tport_tls_init_master(0x465af70): tls context initialized for 192.168.1.100 tport_listen(0x465af70): listening at tls/192.168.1.100:10131/sips nta: bound to (192.168.1.100:10131;transport=*) nta: agent_init_via: SIP/2.0/tls 192.168.1.100:10131 (sips) nta: Via fields initialized nta: Contact header created nua_register: Adding contact URL '192.168.1.100' to list. nua: nua_set_params: entering nua(0x0): sent signal r_set_params nua: nh_create_handle: entering nua: nua_set_hparams: entering nua(0x7b5040): sent signal r_set_params nua: nh_create_handle: entering nua: nua_set_hparams: entering nua(0x46937b0): sent signal r_set_params nua: nua_register: entering nua(0x7b5040): sent signal r_register nua: nua_subscribe: entering nua(0x46937b0): sent signal r_subscribe nua: nua_application_event: entering nua: nua_destroy: entering nua: nua_stack_deinit: entering su_kqueue_port_deinit(0x4666c90) called nua: nua_stack_set_params: entering nua: nua_stack_set_params: entering nua: nua_stack_set_params: entering nua: nua_stack_set_params: entering nua(0x7b5040): adding register usage nta_leg_tcreate(0x4687030) nta: selecting scheme sips tport_tsend(0x465af70) tpn = tls/178.76.132.10:5061 tport_resolve addrinfo = 178.76.132.10:5061 tport_by_addrinfo(0x465af70): not found by name tls/178.76.132.10:5061 tport_alloc_secondary(0x465af70): new secondary tport 0x7dea60 tport_tls_connect(0x7dea60): connecting to tls/178.76.132.10:5061/sips tport(0x7dea60): reset timer tport_queue(0x7dea60): queueing 0x46930c0 for tls/178.76.132.10:5061 nta: sent REGISTER (18216632) to tls/178.76.132.10:5061 tport_pend(0x7dea60): pending 0x46930c0 for tls/178.76.132.10:5061 (already 0) nta: timer set to 32000 ms nua: nua_stack_set_params: entering nua(0x46937b0): adding subscribe usage with event message-summary nta_leg_tcreate(0x7e62e0) nta: selecting scheme sip tport_tsend(0x465af70) tpn = */178.76.132.10:5061 tport_resolve addrinfo = 178.76.132.10:5061 tport_by_addrinfo(0x465af70): found 0x7dea60 by name */178.76.132.10:5061 tport_queue(0x7dea60): queueing 0x4694db0 for tls/178.76.132.10:5061 nta: sent SUBSCRIBE (18216632) to */178.76.132.10:5061 tport_pend(0x7dea60): pending 0x4694db0 for tls/178.76.132.10:5061 (already 1) tls_connect(0x7dea60): events CONNECTING nua: nua_application_event: entering nua: nua_application_event: entering nua: nua_application_event: entering tls_connect(0x7dea60): events NEGOTIATING tls_connect(0x7dea60): events NEGOTIATING tport_send_event(0x7dea60) - ready to send to (tls/178.76.132.10:5061) tport_tls_writevec: vec 0x465ba60 0xb5ca00 485 (485) tport_vsend returned 485 tport_tls_writevec: vec 0x465ba60 0xb71200 545 (545) tport_vsend returned 545 tport_tls_set_events(0x7dea60): logical events IN real IN tport(0x7dea60): reset timer tport_wakeup(0x7dea60): events IN tport_recv_event(0x7dea60) tport_tls_recv(0x7dea60): tls_read() returned 527 tport_recv_iovec(0x7dea60) msg 0x4662050 from (tls/178.76.132.10:5061) has 527 bytes, veclen = 1 tport_deliver(0x7dea60): msg 0x4662050 (527 bytes) from tls/178.76.132.10:5061/sips next=0x0 nta: received 401 Unauthorized for REGISTER (18216632) nta: 401 Unauthorized is going to a transaction nta_outgoing: RTT is 272.915 ms tport_release(0x7dea60): 0x46930c0 by 0x4693d10 with 0x4662050 outbound(0x7b5040): detected NAT: 192.168.1.100 != 92.28.64.198 auth_digest_challenge_get(): got 4 nta: outgoing_free(0x4693d10) tport(0x7dea60): reset timer tport_wakeup(0x7dea60): events IN tport_recv_event(0x7dea60) tport_tls_recv(0x7dea60): tls_read() returned 528 tport_recv_iovec(0x7dea60) msg 0x46930c0 from (tls/178.76.132.10:5061) has 528 bytes, veclen = 1 tport_deliver(0x7dea60): msg 0x46930c0 (528 bytes) from tls/178.76.132.10:5061/sips next=0x0 nta: received 401 Unauthorized for SUBSCRIBE (18216632) nta: 401 Unauthorized is going to a transaction nta_outgoing: RTT is 276.353 ms tport_release(0x7dea60): 0x4694db0 by 0x4695450 with 0x46930c0 auth_digest_challenge_get(): got 4 nta: outgoing_free(0x4695450) tport(0x7dea60): reset timer tport(0x7dea60): set timer at 1799999 ms because idle since recv nua: nua_application_event: entering nua: nua_application_event: entering nua: nua_authenticate: entering nua(0x7b5040): sent signal r_authenticate nua: nua_application_event: entering nua: nua_authenticate: entering nua(0x46937b0): sent signal r_authenticate auth_digest_a1() has A1 = MD5(2000:asterisk:1234) = 3ef464e089ec15ab06967d09b2fa0c63 A2 = MD5(REGISTER:sips:178.76.132.10) auth_response: 1086fee7745e39171c8186211f955193 = MD5(3ef464e089ec15ab06967d09b2fa0c63:07997db9:22a2be38885d846b002befc573cf091e) (qop=NONE) nta: selecting scheme sips tport_tsend(0x465af70) tpn = tls/178.76.132.10:5061 tport_resolve addrinfo = 178.76.132.10:5061 tport_by_addrinfo(0x465af70): found 0x7dea60 by name tls/178.76.132.10:5061 tport_tls_writevec: vec 0x465ba60 0xb5ca00 644 (644) tport_vsend returned 644 tport(0x7dea60): set timer at 1799993 ms because idle since send nta: sent REGISTER (18216633) to tls/178.76.132.10:5061 tport_pend(0x7dea60): pending 0x46930c0 for tls/178.76.132.10:5061 (already 0) auth_digest_a1() has A1 = MD5(2000:asterisk:1234) = 3ef464e089ec15ab06967d09b2fa0c63 A2 = MD5(SUBSCRIBE:sip:2000@178.76.132.10) auth_response: 96a3063224c87f5c987a63fcdaee8087 = MD5(3ef464e089ec15ab06967d09b2fa0c63:213b8647:ce8d60dff9c29877f260c47204b89ce2) (qop=NONE) nta: selecting scheme sip tport_tsend(0x465af70) tpn = */178.76.132.10:5061 tport_resolve addrinfo = 178.76.132.10:5061 tport_by_addrinfo(0x465af70): found 0x7dea60 by name */178.76.132.10:5061 tport_tls_writevec: vec 0x465ba60 0xb6c600 710 (710) tport_vsend returned 710 tport(0x7dea60): reset timer nta: sent SUBSCRIBE (18216633) to */178.76.132.10:5061 tport_pend(0x7dea60): pending 0x4662050 for tls/178.76.132.10:5061 (already 1) tport_wakeup(0x7dea60): events IN tport_recv_event(0x7dea60) tport_tls_recv(0x7dea60): tls_read() returned 558 tport_recv_iovec(0x7dea60) msg 0x46952f0 from (tls/178.76.132.10:5061) has 558 bytes, veclen = 1 tport_deliver(0x7dea60): msg 0x46952f0 (558 bytes) from tls/178.76.132.10:5061/sips next=0x0 nta: received 200 OK for REGISTER (18216633) nta: 200 OK is going to a transaction nta_outgoing: RTT is 48.83 ms tport_release(0x7dea60): 0x46930c0 by 0x4666910 with 0x46952f0 nua(): refresh register after 569 seconds (in [540..570]) tport(0x7dea60): reset timer tport_pend(0x7dea60): pending 0x0 for tls/178.76.132.10:5061 (already 1) nta: outgoing_free(0x4666910) tport(0x7dea60): reset timer tport_wakeup(0x7dea60): events IN tport_recv_event(0x7dea60) tport_tls_recv(0x7dea60): tls_read() returned 522 tport_recv_iovec(0x7dea60) msg 0x4694db0 from (tls/178.76.132.10:5061) has 522 bytes, veclen = 1 tport_deliver(0x7dea60): msg 0x4694db0 (522 bytes) from tls/178.76.132.10:5061/sips next=0x0 nta: received 200 OK for SUBSCRIBE (18216633) nta: 200 OK is going to a transaction nta_outgoing: RTT is 76.148 ms tport_release(0x7dea60): 0x4662050 by 0x468aed0 with 0x4694db0 nua(): refresh subscribe after 570 seconds (in [540..570]) nta: outgoing_free(0x468aed0) tport(0x7dea60): reset timer tport_wakeup(0x7dea60): events IN tport_recv_event(0x7dea60) tport_tls_recv(0x7dea60): tls_read() returned 673 tport_recv_iovec(0x7dea60) msg 0x4662050 from (tls/178.76.132.10:5061) has 673 bytes, veclen = 1 tport_deliver(0x7dea60): msg 0x4662050 (673 bytes) from tls/178.76.132.10:5061/sips next=0x0 nta: received NOTIFY sips:2000@192.168.1.100:10131 SIP/2.0 (CSeq 102) nta: canonizing sips:2000@192.168.1.100:10131 with contact nta: NOTIFY (102) going to existing leg nua: nua_stack_process_request: entering nua(0x46937b0): nua_notify_server_preprocess: active () tport_tsend(0x7dea60) tpn = TLS/178.76.132.10:5061 tport_tls_writevec: vec 0x465ba60 0xb72400 462 (462) tport_vsend returned 462 tport(0x7dea60): reset timer nta: sent 200 OK for NOTIFY (102) nta: incoming_free(0x4664480) tport(0x7dea60): reset timer nua: nua_application_event: entering nua: nua_application_event: entering nua: nua_application_event: entering nua: nua_respond: entering nua(0x46937b0): sent signal r_respond nua: nua_application_event: entering tport_wakeup(0x7dea60): events IN HUP tport_shutdown0(0x7dea60, 2) tport_close(0x7dea60): tls/178.76.132.10:5061/sips tport_release(0x7dea60): 0x0 by 0x7df6b0 with 0x0 nua_register(0x7b5040): tport to tls/178.76.132.10:5061 closed nua(): refresh register after 0 seconds (in [0..0]) tport(0x7dea60): set timer at 0 ms because zap nta: selecting scheme sips tport_tsend(0x465af70) tpn = tls/178.76.132.10:5061 tport_resolve addrinfo = 178.76.132.10:5061 tport_by_addrinfo(0x465af70): not found by name tls/178.76.132.10:5061 tport_alloc_secondary(0x465af70): new secondary tport 0x4661080 tport_tls_connect(0x4661080): connecting to tls/178.76.132.10:5061/sips tport(0x4661080): reset timer tport_queue(0x4661080): queueing 0x46941b0 for tls/178.76.132.10:5061 nta: sent REGISTER (18216634) to tls/178.76.132.10:5061 tport_pend(0x4661080): pending 0x46941b0 for tls/178.76.132.10:5061 (already 0) tls_connect(0x4661080): events CONNECTING tls_connect(0x4661080): events NEGOTIATING tls_connect(0x4661080): events NEGOTIATING tport_send_event(0x4661080) - ready to send to (tls/178.76.132.10:5061) tport_tls_writevec: vec 0x465ba60 0xb5ca00 483 (483) tport_vsend returned 483 tport_tls_set_events(0x4661080): logical events IN real IN tport(0x4661080): reset timer tport_wakeup(0x4661080): events IN tport_recv_event(0x4661080) tport_tls_recv(0x4661080): tls_read() returned 526 tport_recv_iovec(0x4661080) msg 0x468e450 from (tls/178.76.132.10:5061) has 526 bytes, veclen = 1 tport_deliver(0x4661080): msg 0x468e450 (526 bytes) from tls/178.76.132.10:5061/sips next=0x0 nta: received 401 Unauthorized for REGISTER (18216634) nta: 401 Unauthorized is going to a transaction nta_outgoing: RTT is 242.641 ms tport_release(0x4661080): 0x46941b0 by 0x4693d10 with 0x468e450 auth_digest_challenge_get(): got 4 auth_digest_a1() has A1 = MD5(2000:asterisk:1234) = 3ef464e089ec15ab06967d09b2fa0c63 A2 = MD5(REGISTER:sips:178.76.132.10) auth_response: 730260601e6a8293775a34c645bb1d28 = MD5(3ef464e089ec15ab06967d09b2fa0c63:2f52e456:22a2be38885d846b002befc573cf091e) (qop=NONE) nta: selecting scheme sips tport_tsend(0x465af70) tpn = tls/178.76.132.10:5061 tport_resolve addrinfo = 178.76.132.10:5061 tport_by_addrinfo(0x465af70): found 0x4661080 by name tls/178.76.132.10:5061 tport_tls_writevec: vec 0x465ba60 0xb72000 644 (644) tport_vsend returned 644 tport(0x4661080): reset timer nta: sent REGISTER (18216635) to tls/178.76.132.10:5061 tport_pend(0x4661080): pending 0x4694420 for tls/178.76.132.10:5061 (already 0) nta: outgoing_free(0x4693d10) tport(0x4661080): reset timer tport_wakeup(0x4661080): events IN tport_recv_event(0x4661080) tport_tls_recv(0x4661080): tls_read() returned 558 tport_recv_iovec(0x4661080) msg 0x46941b0 from (tls/178.76.132.10:5061) has 558 bytes, veclen = 1 tport_deliver(0x4661080): msg 0x46941b0 (558 bytes) from tls/178.76.132.10:5061/sips next=0x0 nta: received 200 OK for REGISTER (18216635) nta: 200 OK is going to a transaction nta_outgoing: RTT is 47.138 ms tport_release(0x4661080): 0x4694420 by 0x4695450 with 0x46941b0 nua(): refresh register after 543 seconds (in [540..570]) tport(0x4661080): reset timer tport_pend(0x4661080): pending 0x0 for tls/178.76.132.10:5061 (already 0) nta: outgoing_free(0x4695450) tport(0x4661080): reset timer nua: nua_application_event: entering nua: nua_application_event: entering tport_wakeup(0x4661080): events IN HUP tport_shutdown0(0x4661080, 2) tport_close(0x4661080): tls/178.76.132.10:5061/sips tport_release(0x4661080): 0x0 by 0x7df6b0 with 0x0 nua_register(0x7b5040): tport to tls/178.76.132.10:5061 closed nua(): refresh register after 0 seconds (in [0..0]) tport(0x4661080): set timer at 0 ms because zap nta: selecting scheme sips tport_tsend(0x465af70) tpn = tls/178.76.132.10:5061 tport_resolve addrinfo = 178.76.132.10:5061 tport_by_addrinfo(0x465af70): not found by name tls/178.76.132.10:5061 tport_alloc_secondary(0x465af70): new secondary tport 0x46952f0 tport_tls_connect(0x46952f0): connecting to tls/178.76.132.10:5061/sips tport(0x46952f0): reset timer tport_queue(0x46952f0): queueing 0x46941b0 for tls/178.76.132.10:5061 nta: sent REGISTER (18216636) to tls/178.76.132.10:5061 178.76.132.10178.76.132.10178.76.132.10178.76.132.10178.76.132.10178.76.132.10 ------------------------------------------------------------------------------ All the data continuously generated in your IT infrastructure contains a definitive record of customers, application performance, security threats, fraudulent activity and more. Splunk takes this data and makes sense of it. Business sense. IT sense. Common sense. http://p.sf.net/sfu/splunk-d2dcopy1 _______________________________________________ Sofia-sip-devel mailing list Sofia-sip-devel@lists.sourceforge.net https://lists.sourceforge.net/lists/listinfo/sofia-sip-devel
