rendered paste bodyMar 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, 2Mar 19 12:04:37 [29292] DBG:core:handle_new_connect: new connection: 0xb6167d10 24 flags: 0002Mar 19 12:04:37 [29292] DBG:core:send2child: to tcp child 0 0(29280), 0xb6167d10Mar 19 12:04:37 [29280] DBG:core:handle_io: received n=4 con=0xb6167d10, fd=20Mar 19 12:04:37 [29280] DBG:core:io_watch_add: io_watch_add(0x813d8c0, 20, 2, 0xb6167d10), fd_no=1Mar 19 12:04:37 [29280] DBG:core:tls_update_fd: New fd is 20Mar 19 12:04:41 [29280] DBG:core:tls_update_fd: New fd is 20Mar 19 12:04:41 [29280] DBG:core:tls_accept: TLS handshake successfulMar 19 12:04:41 [29280] DBG:core:tls_accept: new connection from 193.xx.xx.xx6:5578 using TLSv1/SSLv3 AES256-SHA 256Mar 19 12:04:41 [29280] DBG:core:tls_accept: local socket: xx.xx.xx13:443Mar 19 12:04:41 [29280] INFO:core:tls_accept: client did not present a certificateMar 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.orgMar 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.orgMar 19 12:04:41 [29280] DBG:core:tls_update_fd: New fd is 20Mar 19 12:04:42 [29280] DBG:core:tls_update_fd: New fd is 20Mar 19 12:04:42 [29280] DBG:core:_tls_read: 447 bytes readMar 19 12:04:42 [29280] DBG:core:tcp_read_req: content-length= 0Mar 19 12:04:42 [29280] DBG:core:parse_msg: SIP Request:Mar 19 12:04:42 [29280] DBG:core:parse_msg: method: <REGISTER>Mar 19 12:04:42 [29280] DBG:core:parse_msg: uri: <sip:xxxx.net>Mar 19 12:04:42 [29280] DBG:core:parse_msg: version: <SIP/2.0>Mar 19 12:04:42 [29280] DBG:core:parse_headers: flags=2Mar 19 12:04:42 [29280] DBG:core:parse_via_param: found param type 235, <rport> = <n/a>; state=6Mar 19 12:04:42 [29280] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK18483009D7dL>; state=16Mar 19 12:04:42 [29280] DBG:core:parse_via: end of header reached, state=5Mar 19 12:04:42 [29280] DBG:core:parse_headers: via found, flags=2Mar 19 12:04:42 [29280] DBG:core:parse_headers: this is the first viaMar 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=100Mar 19 12:04:42 [29280] DBG:core:parse_to: end of header reached, state=10Mar 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: <To> [39]; uri=[sip:9613041705@xxxx.net]Mar 19 12:04:42 [29280] DBG:core:get_hdr_field: to body [9613041705 <sip:9613041705@xxxx.net>]Mar 19 12:04:42 [29280] DBG:core:get_hdr_field: cseq <CSeq>: <1> <REGISTER>Mar 19 12:04:42 [29280] DBG:maxfwd:is_maxfwd_present: value = 70Mar 19 12:04:42 [29280] DBG:core:check_via_address: params 193.xx.xx.xx6, 192.168.0.149, 0Mar 19 12:04:42 [29280] DBG:core:parse_headers: flags=200Mar 19 12:04:42 [29280] DBG:core:get_hdr_field: content_length=0Mar 19 12:04:42 [29280] DBG:core:get_hdr_field: found end of headerMar 19 12:04:42 [29280] DBG:rr:find_first_route: No Route headers foundMar 19 12:04:42 [29280] DBG:rr:loose_route: There is no Route HFMar 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 5060Mar 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 5060Mar 19 12:04:42 [29280] DBG:core:check_self: host != meMar 19 12:04:42 [29280] DBG:core:parse_headers: flags=ffffffffffffffffrewritehostport to Splendor_VOIP_GW:5065Mar 19 12:04:42 [29280] DBG:core:subst_run: running. r=1Mar 19 12:04:42 [29280] DBG:core:subst_str: no matchMar 19 12:04:42 [29280] DBG:tm:t_newtran: transaction on entrance=0xffffffffMar 19 12:04:42 [29280] DBG:core:parse_headers: flags=ffffffffffffffffMar 19 12:04:42 [29280] DBG:core:parse_headers: flags=78Mar 19 12:04:42 [29280] DBG:tm:t_lookup_request: start searching: hash=32878, isACK=0Mar 19 12:04:42 [29280] DBG:tm:matching_3261: RFC3261 transaction matching failedMar 19 12:04:42 [29280] DBG:tm:t_lookup_request: no transaction foundMar 19 12:04:42 [29280] DBG:tm:run_reqin_callbacks: trans=0xb618ab70, callback type 1, id 0 enteredMar 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=3Mar 19 12:04:42 [29280] DBG:core:check_via_address: params 193.xx.xx.xx6, 192.168.0.149, 0Mar 19 12:04:42 [29280] DBG:tm:set_timer: relative timeout is 500000Mar 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 30Mar 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'edMar 19 12:04:42 [29280] DBG:tm:t_unref: UNREF_UNSAFE: after is 0Mar 19 12:04:42 [29280] DBG:core:destroy_avp_list: destroying list (nil)Mar 19 12:04:42 [29280] DBG:core:receive_msg: cleaning upMar 19 12:04:42 [29267] DBG:core:parse_msg: SIP Reply (status):Mar 19 12:04:42 [29267] DBG:core:parse_msg: version: <SIP/2.0>Mar 19 12:04:42 [29267] DBG:core:parse_msg: status: <503>Mar 19 12:04:42 [29267] DBG:core:parse_msg: reason: <SERVICE UNAVAILABLE>Mar 19 12:04:42 [29267] DBG:core:parse_headers: flags=2Mar 19 12:04:42 [29267] DBG:core:parse_via_param: found param type 235, <rport> = <n/a>; state=6Mar 19 12:04:42 [29267] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKe608.13078c82.0>; state=6Mar 19 12:04:42 [29267] DBG:core:parse_via_param: found param type 236, <i> = <2>; state=16Mar 19 12:04:42 [29267] DBG:core:parse_via: end of header reached, state=5Mar 19 12:04:42 [29267] DBG:core:parse_headers: via found, flags=2Mar 19 12:04:42 [29267] DBG:core:parse_headers: this is the first viaMar 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 itMar 19 12:04:42 [29267] DBG:core:parse_headers: flags=4Mar 19 12:04:42 [29267] DBG:core:parse_via_param: found param type 234, <received> = <193.xx.xx.xx6>; state=6Mar 19 12:04:42 [29267] DBG:core:parse_via_param: found param type 235, <rport> = <5578>; state=6Mar 19 12:04:42 [29267] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK18483009D7dL>; state=16Mar 19 12:04:42 [29267] DBG:core:parse_via: end of header reached, state=5Mar 19 12:04:42 [29267] DBG:core:parse_headers: via found, flags=4Mar 19 12:04:42 [29267] DBG:core:parse_headers: parse_headers: this is the second viaMar 19 12:04:42 [29267] DBG:core:forward_reply: found module tm, passing reply to itMar 19 12:04:42 [29267] DBG:tm:t_check: start=0xffffffffMar 19 12:04:42 [29267] DBG:core:parse_headers: flags=22Mar 19 12:04:42 [29267] DBG:core:parse_to: end of header reached, state=10Mar 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: <To> [41]; uri=[sip:9613041705@xxxx.net]Mar 19 12:04:42 [29267] DBG:core:get_hdr_field: to body ["9613041705" <sip:9613041705@xxxx.net>]Mar 19 12:04:42 [29267] DBG:core:get_hdr_field: cseq <CSeq>: <1> <REGISTER>Mar 19 12:04:42 [29267] DBG:tm:t_reply_matching: hash 32878 label 684224561 branch 0Mar 19 12:04:42 [29267] DBG:tm:t_reply_matching: REF_UNSAFE: after is 1Mar 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=0xb618ab70Mar 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=4000000000Mar 19 12:04:42 [29267] DBG:core:get_hdr_field: content_length=0Mar 19 12:04:42 [29267] DBG:core:get_hdr_field: found end of headerMar 19 12:04:42 [29267] DBG:tm:t_should_relay_response: T_code=0, new_code=503Mar 19 12:04:42 [29267] DBG:tm:t_pick_branch: picked branch 0, code 503Mar 19 12:04:42 [29267] DBG:tm:is_3263_failure: dns-failover test: branch=0, last_recv=503, flags=2Mar 19 12:04:42 [29267] DBG:tm:t_should_relay_response: trying DNS-based failoverMar 19 12:04:42 [29267] DBG:tm:relay_reply: branch=0, save=0, relay=0Mar 19 12:04:42 [29267] DBG:core:parse_headers: flags=2000Mar 19 12:04:42 [29267] DBG:core:build_res_buf_from_sip_res: old size: 498, new size: 426Mar 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 UNAVAILABLEVia: SIP/2.0/TLS 192.168.0.149:5578;received=193.xx.xx.xx6;rport=5578;branch=z9hG4bK18483009D7dLFrom: "9613041705" <sip:9613041705@xxxx.net>;tag=18483009To: "9613041705" <sip:9613041705@xxxx.net>Call-ID: FDD98DECC1B9XKnw@xx.xx.xx13CSeq: 1 REGISTERExpires: 1800User-Agent: Eyeball Softphone v7.1(Nov 19 2007,18:10:30)P-hint: outboundretry-after: 60Content-Length: 0Mar 19 12:04:42 [29267] DBG:core:_shm_resize: resize(0) calledMar 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 fdMar 19 12:04:42 [29267] DBG:core:tcp_send: c= 0xb6167d10, n=8Mar 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=12Mar 19 12:04:42 [29267] DBG:core:tcp_send: sending...Mar 19 12:04:42 [29267] DBG:core:tls_update_fd: New fd is 12Mar 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=12Mar 19 12:04:42 [29267] DBG:core:tcp_send: buf=SIP/2.0 500 SERVICE UNAVAILABLEVia: SIP/2.0/TLS 192.168.0.149:5578;received=193.xx.xx.xx6;rport=5578;branch=z9hG4bK18483009D7dLFrom: "9613041705" <sip:9613041705@xxxx.net>;tag=18483009To: "9613041705" <sip:9613041705@xxxx.net>Call-ID: FDD98DECC1B9XKnw@xx.xx.xx13CSeq: 1 REGISTERExpires: 1800User-Agent: Eyeball Softphone v7.1(Nov 19 2007,18:10:30)P-hint: outboundretry-after: 60Content-Length: 0Mar 19 12:04:42 [29267] DBG:tm:relay_reply: sent buf=0x816af60: SIP/2.0 5..., shmem=0xb61784a0: SIP/2.0 5Mar 19 12:04:42 [29267] DBG:tm:cleanup_uac_timers: RETR/FR timers resetMar 19 12:04:42 [29267] DBG:tm:t_unref: UNREF_UNSAFE: after is 0Mar 19 12:04:42 [29267] DBG:core:destroy_avp_list: destroying list (nil)Mar 19 12:04:42 [29267] DBG:core:receive_msg: cleaning upMar 19 12:04:43 [29272] DBG:tm:utimer_routine: timer routine:4,tl=0xb618acbc next=(nil), timeout=790500000Mar 19 12:04:43 [29280] DBG:core:tls_update_fd: New fd is 20Mar 19 12:04:43 [29280] DBG:core:_tls_read: connection closed cleanlyMar 19 12:04:43 [29280] DBG:core:tcp_read_req: EOFMar 19 12:04:43 [29280] DBG:core:io_watch_del: io_watch_del (0x813d8c0, 20, -1, 0x10) fd_no=2 calledMar 19 12:04:43 [29280] DBG:core:release_tcpconn: releasing con 0xb6167d10, state -1, fd=20, id=2Mar 19 12:04:43 [29280] DBG:core:release_tcpconn: extra_data 0xb6177e28Mar 19 12:04:43 [29292] DBG:core:handle_tcp_child: reader response= b6167d10, -1 from 0Mar 19 12:04:43 [29292] DBG:core:tcpconn_destroy: destroying connection 0xb6167d10, flags 0002Mar 19 12:04:43 [29292] DBG:core:tls_close: closing SSL connectionMar 19 12:04:43 [29292] DBG:core:tls_update_fd: New fd is 24Mar 19 12:04:43 [29292] DBG:core:tls_shutdown: shutdown successfulMar 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=795Mar 19 12:04:47 [29272] DBG:tm:wait_handler: removing 0xb618ab70 from tableMar 19 12:04:47 [29272] DBG:tm:delete_cell: delete transaction 0xb618ab70Mar 19 12:04:47 [29272] DBG:tm:wait_handler: doneMar 19 12:04:52 [29272] DBG:presence:msg_watchers_clean: cleaning pending subscriptionsMar 19 12:04:52 [29272] DBG:core:db_free_rows: freeing 0 rowsMar 19 12:04:52 [29272] DBG:presence:msg_presentity_clean: cleaning expired presentity informationMar 19 12:04:52 [29272] DBG:core:db_free_rows: freeing 0 rowsMar 19 12:06:32 [29272] DBG:presence:msg_watchers_clean: cleaning pending subscriptionsMar 19 12:06:32 [29272] DBG:core:db_free_rows: freeing 0 rowsMar 19 12:06:32 [29272] DBG:presence:msg_presentity_clean: cleaning expired presentity informationMar 19 12:06:32 [29272] DBG:core:db_free_rows: freeing 0 rowsMar 19 12:08:12 [29272] DBG:presence:msg_watchers_clean: cleaning pending subscriptionsMar 19 12:08:12 [29272] DBG:core:db_free_rows: freeing 0 rowsMar 19 12:08:12 [29272] DBG:presence:msg_presentity_clean: cleaning expired presentity informationMar 19 12:08:12 [29272] DBG:core:db_free_rows: freeing 0 rows