Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18847]: DBG:core:tcpconn_timeout: timeout for hash=1 - 0x7f21d5e53168 (157 > 152)
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18847]: DBG:core:io_watch_del: io_watch_del (0x762c20, 25, -1, 0x10) fd_no=18 called
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18847]: DBG:core:print_ip: tcpconn_new: new tcp connection to: 82.76.196.2
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18847]: DBG:core:tcpconn_new: on port 41889, type 2
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18847]: DBG:core:tcpconn_add: hashes: 1011, 2
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18847]: DBG:core:handle_new_connect: new connection: 0x7f21d5e53168 25 flags: 0002
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18847]: DBG:core:send2child: to tcp child 0 0(18842), 0x7f21d5e53168
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:core:handle_io: received n=8 con=0x7f21d5e53168, fd=21
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:core:io_watch_add: io_watch_add(0x762d80, 21, 2, 0x7f21d5e53168), fd_no=1
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:core:tcp_read_req: content-length= 0
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:core:parse_msg: SIP Request:
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:core:parse_msg:  method:  <BYE>
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:core:parse_msg:  uri:     <sip:*43@193.0.0.21>
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:core:parse_msg:  version: <SIP/2.0>
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:core:parse_headers: flags=2
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK5msquoq8i5hc7sbg0raeuu7>; state=6
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:core:parse_via_param: found param type 235, <rport> = <n/a>; state=17
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:core:parse_via: end of header reached, state=5
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:core:parse_headers: via found, flags=2
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:core:parse_headers: this is the first via
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:core:receive_msg: After parse_msg...
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:core:receive_msg: preparing to run routing scripts...
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:core:parse_headers: flags=100
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:core:parse_to_param: tag=as62acd0d2
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:core:parse_to: end of header reached, state=29
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:core:parse_to: display={}, ruri={sip:*43@proxy.local.ro}
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:core:get_hdr_field: <To> [46]; uri=[sip:*43@proxy.local.ro]
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:core:get_hdr_field: to body [<sip:*43@proxy.local.ro>]
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:core:get_hdr_field: cseq <CSeq>: <1221> <BYE>
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:maxfwd:is_maxfwd_present: value = 70
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:core:parse_headers: flags=78
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:tm:t_lookup_request: start searching: hash=56091, isACK=0
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:tm:matching_3261: RFC3261 transaction matching failed
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:tm:t_lookup_request: no transaction found
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:core:parse_to_param: tag=hopauop0fhhc6ipv06ic
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:core:parse_to: end of header reached, state=29
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:core:parse_to: display={}, ruri={sip:50102@proxy.local.ro}
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:core:parse_headers: flags=200
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:rr:is_preloaded: is_preloaded: No
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:core:grep_sock_info: checking if host==us: 14==14 &&  [193.0.0.21] == [193.0.0.30]
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:core:grep_sock_info: checking if host==us: 14==14 &&  [193.0.0.21] == [193.0.0.30]
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:core:check_self: host != me
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:core:grep_sock_info: checking if host==us: 14==14 &&  [193.0.0.30] == [193.0.0.30]
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:rr:after_loose: Topmost route URI: 'sip:193.0.0.30;transport=TCP;r2=on;lr=on;ftag=hopauop0fhhc6ipv06ic' is me
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:core:grep_sock_info: checking if host==us: 14==14 &&  [193.0.0.30] == [193.0.0.30]
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:core:parse_headers: flags=200
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:core:get_hdr_field: content_length=0
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:core:get_hdr_field: found end of header
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:rr:find_next_route: No next Route HF found
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:rr:after_loose: no next URI found
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:rr:run_rr_callbacks: callback id 2 entered with <transport=TCP;r2=on;lr=on;ftag=hopauop0fhhc6ipv06ic>
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:uac:restore_uri: getting 'vsf' Route param
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:uac:restore_uri: route param 'vsf' not found
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:uac:restore_uri: getting 'vst' Route param
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:uac:restore_uri: route param 'vst' not found
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:core:parse_headers: flags=ffffffffffffffff
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:tm:t_newtran: transaction on entrance=(nil)
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:core:parse_headers: flags=ffffffffffffffff
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:core:parse_headers: flags=78
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:tm:t_lookup_request: start searching: hash=56091, isACK=0
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:tm:matching_3261: RFC3261 transaction matching failed
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:tm:t_lookup_request: no transaction found
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:tm:run_reqin_callbacks: trans=0x7f21d5e63308, callback type 1, id 1 entered
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:tm:run_reqin_callbacks: trans=0x7f21d5e63308, callback type 1, id 0 entered
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:siptrace:trace_onreq_in: nothing to trace...
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:core:mk_proxy: doing DNS lookup...
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:core:build_req_buf_from_sip_req: id added: <;i=2>, rcv proto=2
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:tm:set_timer: relative timeout is 500000
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:tm:insert_timer_unsafe: [4]: 0x7f21d5e63528 (158200000)
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:tm:set_timer: relative timeout is 30
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:tm:insert_timer_unsafe: [0]: 0x7f21d5e63558 (187)
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:tm:t_relay_to: new transaction fwd'ed
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: ROUTE 1 ENDING BYE sip:50102@proxy.local.ro sip:*43@193.0.0.21
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:tm:t_unref: UNREF_UNSAFE: [0x7f21d5e63308] after is 0
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:core:destroy_avp_list: destroying list (nil)
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:core:receive_msg: cleaning up
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18838]: DBG:core:parse_msg: SIP Reply  (status):
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18838]: DBG:core:parse_msg:  version: <SIP/2.0>
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18838]: DBG:core:parse_msg:  status:  <200>
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18838]: DBG:core:parse_msg:  reason:  <OK>
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18838]: DBG:core:parse_headers: flags=2
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18838]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKb1bd.cb19f86.0>; state=6
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18838]: DBG:core:parse_via_param: found param type 236, <i> = <2>; state=6
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18838]: DBG:core:parse_via_param: found param type 234, <received> = <193.0.0.30>; state=16
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18838]: DBG:core:parse_via: end of header reached, state=5
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18838]: DBG:core:parse_headers: via found, flags=2
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18838]: DBG:core:parse_headers: this is the first via
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18838]: DBG:core:receive_msg: After parse_msg...
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18838]: DBG:core:forward_reply: found module nathelper, passing reply to it
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18838]: DBG:core:parse_headers: flags=4
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18838]: DBG:core:parse_via_param: found param type 234, <received> = <82.76.196.2>; state=6
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18838]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK5msquoq8i5hc7sbg0raeuu7>; state=6
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18838]: DBG:core:parse_via_param: found param type 235, <rport> = <41889>; state=16
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18838]: DBG:core:parse_via: end of header reached, state=5
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18838]: DBG:core:parse_headers: via found, flags=4
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18838]: DBG:core:parse_headers: parse_headers: this is the second via
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18838]: DBG:core:forward_reply: found module tm, passing reply to it
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18838]: DBG:tm:t_check: start=0xffffffffffffffff
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18838]: DBG:core:parse_headers: flags=22
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18838]: DBG:core:parse_to_param: tag=as62acd0d2
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18838]: DBG:core:parse_to: end of header reached, state=29
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18838]: DBG:core:parse_to: display={}, ruri={sip:*43@proxy.local.ro}
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18838]: DBG:core:get_hdr_field: <To> [46]; uri=[sip:*43@proxy.local.ro]
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18838]: DBG:core:get_hdr_field: to body [<sip:*43@proxy.local.ro>]
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18838]: DBG:core:get_hdr_field: cseq <CSeq>: <1221> <BYE>
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18838]: DBG:tm:t_reply_matching: hash 56091 label 110072252 branch 0
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18838]: DBG:tm:t_reply_matching: REF_UNSAFE:[0x7f21d5e63308] after is 1
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18838]: DBG:tm:t_reply_matching: reply matched (T=0x7f21d5e63308)!
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18838]: DBG:tm:t_check: end=0x7f21d5e63308
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18838]: DBG:tm:reply_received: org. status uas=0, uac[0]=0 local=0 is_invite=0)
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18838]: DBG:tm:t_should_relay_response: T_code=0, new_code=200
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18838]: DBG:tm:relay_reply: branch=0, save=0, relay=0
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18838]: DBG:core:parse_headers: flags=2000
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18838]: DBG:core:get_hdr_field: content_length=0
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18838]: DBG:core:build_res_buf_from_sip_res:  old size: 713, new size: 623
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18838]: DBG:core:build_res_buf_from_sip_res: copied size: orig:106, new: 16, rest: 607 msg=#012SIP/2.0 200 OK#015#012Via: SIP/2.0/TCP 192.168.253.235:5060;received=82.76.196.2;branch=z9hG4bK5msquoq8i5hc7sbg0raeuu7;rport=41889#015#012Record-Route: <sip:193.0.0.30;r2=on;lr=on;ftag=hopauop0fhhc6ipv06ic>#015#012Record-Route: <sip:193.0.0.30;transport=tcp;r2=on;lr=on;ftag=hopauop0fhhc6ipv06ic>#015#012From: <sip:50102@proxy.local.ro>;tag=hopauop0fhhc6ipv06ic#015#012To: <sip:*43@proxy.local.ro>;tag=as62acd0d2#015#012Call-ID: BY6LoZT5oIefuw6APm2AEyDHQuczUC#015#012CSeq: 1221 BYE#015#012User-Agent: "PBX"#015#012Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY#015#012Supported: replaces#015#012Contact: <sip:*43@193.0.0.21>#015#012Content-Length: 0#015#012#015#012
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18838]: DBG:core:_shm_resize: resize(0) called
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18838]: DBG:tm:insert_timer_unsafe: [2]: 0x7f21d5e63388 (162)
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18838]: DBG:core:tcp_send: tcp connection found (0x7f21d5e53168), acquiring fd
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18838]: DBG:core:tcp_send: c= 0x7f21d5e53168, n=16
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18847]: DBG:core:handle_ser_child: read response= 7f21d5e53168, 1, fd -1 from 5 (18838)
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18838]: DBG:core:tcp_send: after receive_fd: c= 0x7f21d5e53168 n=8 fd=14
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18838]: DBG:core:tcp_send: sending...
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18838]: DBG:core:tcp_send: after write: c= 0x7f21d5e53168 n=623 fd=14
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18838]: DBG:core:tcp_send: buf=#012SIP/2.0 200 OK#015#012Via: SIP/2.0/TCP 192.168.253.235:5060;received=82.76.196.2;branch=z9hG4bK5msquoq8i5hc7sbg0raeuu7;rport=41889#015#012Record-Route: <sip:193.0.0.30;r2=on;lr=on;ftag=hopauop0fhhc6ipv06ic>#015#012Record-Route: <sip:193.0.0.30;transport=tcp;r2=on;lr=on;ftag=hopauop0fhhc6ipv06ic>#015#012From: <sip:50102@proxy.local.ro>;tag=hopauop0fhhc6ipv06ic#015#012To: <sip:*43@proxy.local.ro>;tag=as62acd0d2#015#012Call-ID: BY6LoZT5oIefuw6APm2AEyDHQuczUC#015#012CSeq: 1221 BYE#015#012User-Agent: "PBX"#015#012Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY#015#012Supported: replaces#015#012Contact: <sip:*43@193.0.0.21>#015#012Content-Length: 0#015#012#015#012
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18838]: DBG:tm:relay_reply: sent buf=0x7b2998: SIP/2.0 2..., shmem=0x7f21d5e667a0: SIP/2.0 2
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18838]: DBG:tm:cleanup_uac_timers: RETR/FR timers reset
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18838]: DBG:tm:t_unref: UNREF_UNSAFE: [0x7f21d5e63308] after is 0
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18838]: DBG:core:destroy_avp_list: destroying list (nil)
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18838]: DBG:core:receive_msg: cleaning up
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:core:tcp_read: EOF on 0x7f21d5e53168, FD 21
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:core:tcp_read_req: EOF
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:core:io_watch_del: io_watch_del (0x762d80, 21, -1, 0x10) fd_no=2 called
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:core:release_tcpconn:  releasing con 0x7f21d5e53168, state -1, fd=21, id=2
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18842]: DBG:core:release_tcpconn:  extra_data (nil)
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18847]: DBG:core:handle_tcp_child: reader response= 7f21d5e53168, -1 from 0
Jan  7 20:26:39 proxy /usr/local/sbin/opensips[18847]: DBG:core:tcpconn_destroy: destroying connection 0x7f21d5e53168, flags 0002