Mar 19 12:04:37 [29292] DBG:core:tls_tcpconn_init: found socket based TLS server domain [0.0.0.0:0] Mar 19 12:04:37 [29292] DBG:core:tls_tcpconn_init: Setting in ACCEPT mode (server) Mar 19 12:04:37 [29292] DBG:core:tcpconn_add: hashes: 523, 2 Mar 19 12:04:37 [29292] DBG:core:handle_new_connect: new connection: 0xb6167d10 24 flags: 0002 Mar 19 12:04:37 [29292] DBG:core:send2child: to tcp child 0 0(29280), 0xb6167d10 Mar 19 12:04:37 [29280] DBG:core:handle_io: received n=4 con=0xb6167d10, fd=20 Mar 19 12:04:37 [29280] DBG:core:io_watch_add: io_watch_add(0x813d8c0, 20, 2, 0xb6167d10), fd_no=1 Mar 19 12:04:37 [29280] DBG:core:tls_update_fd: New fd is 20 Mar 19 12:04:41 [29280] DBG:core:tls_update_fd: New fd is 20 Mar 19 12:04:41 [29280] DBG:core:tls_accept: TLS handshake successful Mar 19 12:04:41 [29280] DBG:core:tls_accept: new connection from 193.xx.xx.xx6:5578 using TLSv1/SSLv3 AES256-SHA 256 Mar 19 12:04:41 [29280] DBG:core:tls_accept: local socket: xx.xx.xx13:443 Mar 19 12:04:41 [29280] INFO:core:tls_accept: client did not present a certificate Mar 19 12:04:41 [29280] DBG:core:tls_dump_cert_info: tls_accept: local (server) certificate subject:/C=IP/ST=SIP/O=OpenSER project/OU=OpenSER TLS tester/CN=OpenSER/emailAddress=team@openser.org Mar 19 12:04:41 [29280] DBG:core:tls_dump_cert_info: tls_accept: local (server) certificate issuer: /CN=OpenSER/ST=SIP/C=IP/emailAddress=team@openser.org/O=openser.org Mar 19 12:04:41 [29280] DBG:core:tls_update_fd: New fd is 20 Mar 19 12:04:42 [29280] DBG:core:tls_update_fd: New fd is 20 Mar 19 12:04:42 [29280] DBG:core:_tls_read: 447 bytes read Mar 19 12:04:42 [29280] DBG:core:tcp_read_req: content-length= 0 Mar 19 12:04:42 [29280] DBG:core:parse_msg: SIP Request: Mar 19 12:04:42 [29280] DBG:core:parse_msg: method: Mar 19 12:04:42 [29280] DBG:core:parse_msg: uri: Mar 19 12:04:42 [29280] DBG:core:parse_msg: version: Mar 19 12:04:42 [29280] DBG:core:parse_headers: flags=2 Mar 19 12:04:42 [29280] DBG:core:parse_via_param: found param type 235, = ; state=6 Mar 19 12:04:42 [29280] DBG:core:parse_via_param: found param type 232, = ; state=16 Mar 19 12:04:42 [29280] DBG:core:parse_via: end of header reached, state=5 Mar 19 12:04:42 [29280] DBG:core:parse_headers: via found, flags=2 Mar 19 12:04:42 [29280] DBG:core:parse_headers: this is the first via Mar 19 12:04:42 [29280] DBG:core:receive_msg: After parse_msg... Mar 19 12:04:42 [29280] DBG:core:receive_msg: preparing to run routing scripts... Mar 19 12:04:42 [29280] DBG:core:parse_headers: flags=100 Mar 19 12:04:42 [29280] DBG:core:parse_to: end of header reached, state=10 Mar 19 12:04:42 [29280] DBG:core:parse_to: display={9613041705}, ruri={sip:9613041705@xxxx.net} Mar 19 12:04:42 [29280] DBG:core:get_hdr_field: [39]; uri=[sip:9613041705@xxxx.net] Mar 19 12:04:42 [29280] DBG:core:get_hdr_field: to body [9613041705 ] Mar 19 12:04:42 [29280] DBG:core:get_hdr_field: cseq : <1> Mar 19 12:04:42 [29280] DBG:maxfwd:is_maxfwd_present: value = 70 Mar 19 12:04:42 [29280] DBG:core:check_via_address: params 193.xx.xx.xx6, 192.168.0.149, 0 Mar 19 12:04:42 [29280] DBG:core:parse_headers: flags=200 Mar 19 12:04:42 [29280] DBG:core:get_hdr_field: content_length=0 Mar 19 12:04:42 [29280] DBG:core:get_hdr_field: found end of header Mar 19 12:04:42 [29280] DBG:rr:find_first_route: No Route headers found Mar 19 12:04:42 [29280] DBG:rr:loose_route: There is no Route HF Mar 19 12:04:42 [29280] DBG:core:grep_sock_info: checking if host==us: 9==13 && [xxxx.net] == [xx.xx.xx13] Mar 19 12:04:42 [29280] DBG:core:grep_sock_info: checking if port 5060 matches port 5060 Mar 19 12:04:42 [29280] DBG:core:grep_sock_info: checking if host==us: 9==13 && [xxxx.net] == [xx.xx.xx13] Mar 19 12:04:42 [29280] DBG:core:grep_sock_info: checking if port 443 matches port 5060 Mar 19 12:04:42 [29280] DBG:core:check_self: host != me Mar 19 12:04:42 [29280] DBG:core:parse_headers: flags=ffffffffffffffff rewritehostport to Splendor_VOIP_GW:5065Mar 19 12:04:42 [29280] DBG:core:subst_run: running. r=1 Mar 19 12:04:42 [29280] DBG:core:subst_str: no match Mar 19 12:04:42 [29280] DBG:tm:t_newtran: transaction on entrance=0xffffffff Mar 19 12:04:42 [29280] DBG:core:parse_headers: flags=ffffffffffffffff Mar 19 12:04:42 [29280] DBG:core:parse_headers: flags=78 Mar 19 12:04:42 [29280] DBG:tm:t_lookup_request: start searching: hash=32878, isACK=0 Mar 19 12:04:42 [29280] DBG:tm:matching_3261: RFC3261 transaction matching failed Mar 19 12:04:42 [29280] DBG:tm:t_lookup_request: no transaction found Mar 19 12:04:42 [29280] DBG:tm:run_reqin_callbacks: trans=0xb618ab70, callback type 1, id 0 entered Mar 19 12:04:42 [29280] DBG:core:mk_proxy: doing DNS lookup... Mar 19 12:04:42 [29280] DBG:core:build_req_buf_from_sip_req: id added: <;i=2>, rcv proto=3 Mar 19 12:04:42 [29280] DBG:core:check_via_address: params 193.xx.xx.xx6, 192.168.0.149, 0 Mar 19 12:04:42 [29280] DBG:tm:set_timer: relative timeout is 500000 Mar 19 12:04:42 [29280] DBG:tm:insert_timer_unsafe: [4]: 0xb618acbc (790500000) Mar 19 12:04:42 [29280] DBG:tm:set_timer: relative timeout is 30 Mar 19 12:04:42 [29280] DBG:tm:insert_timer_unsafe: [0]: 0xb618acd8 (820) Mar 19 12:04:42 [29280] DBG:tm:t_relay_to: new transaction fwd'ed Mar 19 12:04:42 [29280] DBG:tm:t_unref: UNREF_UNSAFE: after is 0 Mar 19 12:04:42 [29280] DBG:core:destroy_avp_list: destroying list (nil) Mar 19 12:04:42 [29280] DBG:core:receive_msg: cleaning up Mar 19 12:04:42 [29267] DBG:core:parse_msg: SIP Reply (status): Mar 19 12:04:42 [29267] DBG:core:parse_msg: version: Mar 19 12:04:42 [29267] DBG:core:parse_msg: status: <503> Mar 19 12:04:42 [29267] DBG:core:parse_msg: reason: Mar 19 12:04:42 [29267] DBG:core:parse_headers: flags=2 Mar 19 12:04:42 [29267] DBG:core:parse_via_param: found param type 235, = ; state=6 Mar 19 12:04:42 [29267] DBG:core:parse_via_param: found param type 232, = ; state=6 Mar 19 12:04:42 [29267] DBG:core:parse_via_param: found param type 236, = <2>; state=16 Mar 19 12:04:42 [29267] DBG:core:parse_via: end of header reached, state=5 Mar 19 12:04:42 [29267] DBG:core:parse_headers: via found, flags=2 Mar 19 12:04:42 [29267] DBG:core:parse_headers: this is the first via Mar 19 12:04:42 [29267] DBG:core:receive_msg: After parse_msg... Mar 19 12:04:42 [29267] DBG:core:forward_reply: found module nathelper, passing reply to it Mar 19 12:04:42 [29267] DBG:core:parse_headers: flags=4 Mar 19 12:04:42 [29267] DBG:core:parse_via_param: found param type 234, = <193.xx.xx.xx6>; state=6 Mar 19 12:04:42 [29267] DBG:core:parse_via_param: found param type 235, = <5578>; state=6 Mar 19 12:04:42 [29267] DBG:core:parse_via_param: found param type 232, = ; state=16 Mar 19 12:04:42 [29267] DBG:core:parse_via: end of header reached, state=5 Mar 19 12:04:42 [29267] DBG:core:parse_headers: via found, flags=4 Mar 19 12:04:42 [29267] DBG:core:parse_headers: parse_headers: this is the second via Mar 19 12:04:42 [29267] DBG:core:forward_reply: found module tm, passing reply to it Mar 19 12:04:42 [29267] DBG:tm:t_check: start=0xffffffff Mar 19 12:04:42 [29267] DBG:core:parse_headers: flags=22 Mar 19 12:04:42 [29267] DBG:core:parse_to: end of header reached, state=10 Mar 19 12:04:42 [29267] DBG:core:parse_to: display={"9613041705"}, ruri={sip:9613041705@xxxx.net} Mar 19 12:04:42 [29267] DBG:core:get_hdr_field: [41]; uri=[sip:9613041705@xxxx.net] Mar 19 12:04:42 [29267] DBG:core:get_hdr_field: to body ["9613041705" ] Mar 19 12:04:42 [29267] DBG:core:get_hdr_field: cseq : <1> Mar 19 12:04:42 [29267] DBG:tm:t_reply_matching: hash 32878 label 684224561 branch 0 Mar 19 12:04:42 [29267] DBG:tm:t_reply_matching: REF_UNSAFE: after is 1 Mar 19 12:04:42 [29267] DBG:tm:t_reply_matching: reply matched (T=0xb618ab70)! Mar 19 12:04:42 [29267] DBG:tm:t_check: end=0xb618ab70 Mar 19 12:04:42 [29267] DBG:tm:reply_received: org. status uas=0, uac[0]=0 local=0 is_invite=0) Mar 19 12:04:42 [29267] DBG:core:parse_headers: flags=4000000000 Mar 19 12:04:42 [29267] DBG:core:get_hdr_field: content_length=0 Mar 19 12:04:42 [29267] DBG:core:get_hdr_field: found end of header Mar 19 12:04:42 [29267] DBG:tm:t_should_relay_response: T_code=0, new_code=503 Mar 19 12:04:42 [29267] DBG:tm:t_pick_branch: picked branch 0, code 503 Mar 19 12:04:42 [29267] DBG:tm:is_3263_failure: dns-failover test: branch=0, last_recv=503, flags=2 Mar 19 12:04:42 [29267] DBG:tm:t_should_relay_response: trying DNS-based failover Mar 19 12:04:42 [29267] DBG:tm:relay_reply: branch=0, save=0, relay=0 Mar 19 12:04:42 [29267] DBG:core:parse_headers: flags=2000 Mar 19 12:04:42 [29267] DBG:core:build_res_buf_from_sip_res: old size: 498, new size: 426 Mar 19 12:04:42 [29267] DBG:core:build_res_buf_from_sip_res: copied size: orig:105, new: 33, rest: 393 msg= SIP/2.0 500 SERVICE UNAVAILABLE Via: SIP/2.0/TLS 192.168.0.149:5578;received=193.xx.xx.xx6;rport=5578;branch=z9hG4bK18483009D7dL From: "9613041705" ;tag=18483009 To: "9613041705" Call-ID: FDD98DECC1B9XKnw@xx.xx.xx13 CSeq: 1 REGISTER Expires: 1800 User-Agent: Eyeball Softphone v7.1(Nov 19 2007,18:10:30) P-hint: outbound retry-after: 60 Content-Length: 0 Mar 19 12:04:42 [29267] DBG:core:_shm_resize: resize(0) called Mar 19 12:04:42 [29267] DBG:tm:insert_timer_unsafe: [2]: 0xb618abb8 (795) Mar 19 12:04:42 [29267] DBG:core:tcp_send: tcp connection found (0xb6167d10), acquiring fd Mar 19 12:04:42 [29267] DBG:core:tcp_send: c= 0xb6167d10, n=8 Mar 19 12:04:42 [29292] DBG:core:handle_ser_child: read response= b6167d10, 1, fd -1 from 3 (29267) Mar 19 12:04:42 [29267] DBG:core:tcp_send: after receive_fd: c= 0xb6167d10 n=4 fd=12 Mar 19 12:04:42 [29267] DBG:core:tcp_send: sending... Mar 19 12:04:42 [29267] DBG:core:tls_update_fd: New fd is 12 Mar 19 12:04:42 [29267] DBG:core:tls_write: write was successful (426 bytes) Mar 19 12:04:42 [29267] DBG:core:tcp_send: after write: c= 0xb6167d10 n=426 fd=12 Mar 19 12:04:42 [29267] DBG:core:tcp_send: buf= SIP/2.0 500 SERVICE UNAVAILABLE Via: SIP/2.0/TLS 192.168.0.149:5578;received=193.xx.xx.xx6;rport=5578;branch=z9hG4bK18483009D7dL From: "9613041705" ;tag=18483009 To: "9613041705" Call-ID: FDD98DECC1B9XKnw@xx.xx.xx13 CSeq: 1 REGISTER Expires: 1800 User-Agent: Eyeball Softphone v7.1(Nov 19 2007,18:10:30) P-hint: outbound retry-after: 60 Content-Length: 0 Mar 19 12:04:42 [29267] DBG:tm:relay_reply: sent buf=0x816af60: SIP/2.0 5..., shmem=0xb61784a0: SIP/2.0 5 Mar 19 12:04:42 [29267] DBG:tm:cleanup_uac_timers: RETR/FR timers reset Mar 19 12:04:42 [29267] DBG:tm:t_unref: UNREF_UNSAFE: after is 0 Mar 19 12:04:42 [29267] DBG:core:destroy_avp_list: destroying list (nil) Mar 19 12:04:42 [29267] DBG:core:receive_msg: cleaning up Mar 19 12:04:43 [29272] DBG:tm:utimer_routine: timer routine:4,tl=0xb618acbc next=(nil), timeout=790500000 Mar 19 12:04:43 [29280] DBG:core:tls_update_fd: New fd is 20 Mar 19 12:04:43 [29280] DBG:core:_tls_read: connection closed cleanly Mar 19 12:04:43 [29280] DBG:core:tcp_read_req: EOF Mar 19 12:04:43 [29280] DBG:core:io_watch_del: io_watch_del (0x813d8c0, 20, -1, 0x10) fd_no=2 called Mar 19 12:04:43 [29280] DBG:core:release_tcpconn: releasing con 0xb6167d10, state -1, fd=20, id=2 Mar 19 12:04:43 [29280] DBG:core:release_tcpconn: extra_data 0xb6177e28 Mar 19 12:04:43 [29292] DBG:core:handle_tcp_child: reader response= b6167d10, -1 from 0 Mar 19 12:04:43 [29292] DBG:core:tcpconn_destroy: destroying connection 0xb6167d10, flags 0002 Mar 19 12:04:43 [29292] DBG:core:tls_close: closing SSL connection Mar 19 12:04:43 [29292] DBG:core:tls_update_fd: New fd is 24 Mar 19 12:04:43 [29292] DBG:core:tls_shutdown: shutdown successful Mar 19 12:04:43 [29292] DBG:core:tls_tcpconn_clean: entered [root@localhost openser]# Mar 19 12:04:47 [29272] DBG:tm:timer_routine: timer routine:2,tl=0xb618abb8 next=(nil), timeout=795 Mar 19 12:04:47 [29272] DBG:tm:wait_handler: removing 0xb618ab70 from table Mar 19 12:04:47 [29272] DBG:tm:delete_cell: delete transaction 0xb618ab70 Mar 19 12:04:47 [29272] DBG:tm:wait_handler: done Mar 19 12:04:52 [29272] DBG:presence:msg_watchers_clean: cleaning pending subscriptions Mar 19 12:04:52 [29272] DBG:core:db_free_rows: freeing 0 rows Mar 19 12:04:52 [29272] DBG:presence:msg_presentity_clean: cleaning expired presentity information Mar 19 12:04:52 [29272] DBG:core:db_free_rows: freeing 0 rows Mar 19 12:06:32 [29272] DBG:presence:msg_watchers_clean: cleaning pending subscriptions Mar 19 12:06:32 [29272] DBG:core:db_free_rows: freeing 0 rows Mar 19 12:06:32 [29272] DBG:presence:msg_presentity_clean: cleaning expired presentity information Mar 19 12:06:32 [29272] DBG:core:db_free_rows: freeing 0 rows Mar 19 12:08:12 [29272] DBG:presence:msg_watchers_clean: cleaning pending subscriptions Mar 19 12:08:12 [29272] DBG:core:db_free_rows: freeing 0 rows Mar 19 12:08:12 [29272] DBG:presence:msg_presentity_clean: cleaning expired presentity information Mar 19 12:08:12 [29272] DBG:core:db_free_rows: freeing 0 rows