From descartin@bts.io Thu Nov  8 13:22:35 2018
From: David =?utf-8?q?Escart=C3=ADn?= <descartin@bts.io>
To: sr-users@lists.kamailio.org
Subject: [SR-Users] variable $rb not updated on failure route after a 302 on
	the same PID
Date: Thu, 08 Nov 2018 13:22:14 +0100
Message-ID: <b82e0ea4-8614-0bdc-8e5d-acc16bf6ce61@bts.io>
MIME-Version: 1.0
Content-Type: multipart/mixed; boundary="===============1349260945=="

--===============1349260945==
Content-Type: text/plain; charset="utf-8"
Content-Transfer-Encoding: 8bit

Hello all
we are seeing what we think is quite strange behaviour

We have expecienced this on 5.0 and 5.1 version.

this is the call flow
INV-->
<-- 302 (SDP)
INV-->

<-- 503 (SDP) (or another 302)


When we receive a 302 and we load contacts and create a new branch, when 
we receive the second error response, and we receive it on the same udp 
receiver process, if we read the content of $rb on the the 
onreply_route, we get the proper value of the response SDP, but when we 
read $T_rpl($rb) on the failure_route, we get the value of the first 
error transaction.

If the response (second) is received in another PID, it's ok.


I'm not sure if i'm explaining myself, but we would think that the value 
should be updated, no matter which PID is used to process the response


for example, running the kamailio with only 1 child. For the first 302 
we have


onreply route checking $rb
1(7698) INFO: <script>: LAL 
{"sdp_data":"3466666666","sdp_data_2":null,"nrn":null}
failure_route checking $T_rpl($rb)
  1(7698) INFO: <script>: LOOOOOOOOL 
{"sdp_data":"3466666666","sdp_data_2":null,"nrn":null}
and for the next error
  1(7698) INFO: <script>: LAL 
{"sdp_data":"34619796636","sdp_data_2":null,"nrn":null}
  1(7698) INFO: <script>: LOOOOOOOOL 
{"sdp_data":"3466666666","sdp_data_2":null,"nrn":null}

If we run it with 16 children and the PID don't match. For the first 302 
we have

onreply route checking $rb
13(8360) INFO: <script>: LAL 
{"sdp_data":"3466666666","sdp_data_2":null,"nrn":null}
failure_route checking $T_rpl($rb)
13(8360) INFO: <script>: LOOOOOOOOL 
{"sdp_data":"3466666666","sdp_data_2":null,"nrn":null}
and for the next error after loading the contacts
15(8362) INFO: <script>: LAL 
{"sdp_data":"34619796636","sdp_data_2":null,"nrn":null}

15(8362) INFO: <script>: LOOOOOOOOL 
{"sdp_data":"34619796636","sdp_data_2":null,"nrn":null}


i attach you the logs in both cases

could you please check if you see anything wrong?

best regards

david


16_children.log

11(8358) DEBUG: <core> [core/udp_server.c:492]: udp_rcv_loop(): received 
on udp socket: (106/100/634) [[INVITE sip:34606147628(a)10.100.10.67:5069 
SIP/2.0 0D  0A Via: SIP/2.0/UDP 10.100.10.67:5061;branch=z9hG4bK-]]
11(8358) DEBUG: <core> [core/parser/msg_parser.c:604]: parse_msg(): SIP 
Request:
11(8358) DEBUG: <core> [core/parser/msg_parser.c:606]: parse_msg():  
method:  <INVITE>
11(8358) DEBUG: <core> [core/parser/msg_parser.c:608]: parse_msg():  
uri:     <sip:34606147628(a)10.100.10.67:5069>
11(8358) DEBUG: <core> [core/parser/msg_parser.c:610]: parse_msg():  
version: <SIP/2.0>
11(8358) DEBUG: <core> [core/parser/parse_via.c:1303]: 
parse_via_param(): Found param type 232, <branch> = <z9hG4bK-9680-1-0>; 
state=16
11(8358) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end 
of header reached, state=5
11(8358) DEBUG: <core> [core/parser/msg_parser.c:492]: parse_headers(): 
Via found, flags=2
11(8358) DEBUG: <core> [core/parser/msg_parser.c:494]: parse_headers(): 
this is the first via
11(8358) DEBUG: <core> [core/parser/parse_addr_spec.c:864]: 
parse_addr_spec(): end of header reached, state=10
11(8358) DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): 
<To> [44]; uri=[sip:34606147628(a)10.100.10.67:5069]
11(8358) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): 
to body ["Javi" <sip:34606147628(a)10.100.10.67:5069>
]
11(8358) DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): 
cseq <CSeq>: <1> <INVITE>
11(8358) DEBUG: <core> [core/receive.c:205]: receive_msg(): --- received 
sip message - request - call-id: [1-9680(a)10.100.10.67] - cseq: [1 INVITE]
11(8358) DEBUG: <core> [core/receive.c:248]: receive_msg(): preparing to 
run routing scripts...
11(8358) INFO: <script>: hereeeeeeeeeee
11(8358) DEBUG: tm [t_lookup.c:1320]: t_newtran(): msg id=1 , global msg 
id=0 , T on entrance=0xffffffffffffffff
11(8358) DEBUG: <core> [core/parser/msg_parser.c:183]: get_hdr_field(): 
content_length=217
11(8358) DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): 
found end of header
11(8358) DEBUG: tm [t_lookup.c:477]: t_lookup_request(): start 
searching: hash=13774, isACK=0
11(8358) DEBUG: tm [t_lookup.c:435]: matching_3261(): RFC3261 
transaction matching failed
11(8358) DEBUG: tm [t_lookup.c:659]: t_lookup_request(): no transaction 
found
11(8358) DEBUG: <core> [core/parser/parse_addr_spec.c:185]: 
parse_to_param(): add param: tag=9680SIPpTag001
11(8358) DEBUG: <core> [core/parser/parse_addr_spec.c:864]: 
parse_addr_spec(): end of header reached, state=29
11(8358) DEBUG: <core> [core/md5utils.c:67]: MD5StringArray(): MD5 
calculated: 56115a2d09f62d466f1d45a5f5ff7cc2
11(8358) DEBUG: tm [t_funcs.c:324]: t_relay_to(): new INVITE
11(8358) DEBUG: <core> [core/msg_translator.c:159]: check_via_address(): 
(10.100.10.67, 10.100.10.67, 0)
11(8358) DEBUG: tm [t_reply.c:596]: _reply_light(): reply sent out. 
buf=0x7f334b5f4ea0: SIP/2.0 100 trying -..., shmem=0x7f3346638240: 
SIP/2.0 100 trying -
11(8358) DEBUG: tm [t_reply.c:606]: _reply_light(): finished
11(8358) INFO: <script>: LEL
11(8358) DEBUG: <core> [core/msg_translator.c:159]: check_via_address(): 
(10.100.10.67, 10.100.10.67, 0)
11(8358) INFO: <script>: hereeeeeeeeeee
11(8358) DEBUG: tm [t_funcs.c:372]: t_relay_to(): new transaction forwarded
11(8358) DEBUG: <core> [core/receive.c:289]: receive_msg(): 
request-route executed in: 550 usec
11(8358) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
11(8358) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
11(8358) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
11(8358) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
11(8358) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
11(8358) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
11(8358) DEBUG: <core> [core/xavp.c:446]: xavp_destroy_list(): 
destroying xavp list (nil)
11(8358) DEBUG: <core> [core/receive.c:378]: receive_msg(): cleaning up
11(8358) DEBUG: <core> [core/udp_server.c:492]: udp_rcv_loop(): received 
on udp socket: (106/100/397) [[SIP/2.0 100 Trying 0D  0A Via: 
SIP/2.0/UDP 
52.88.180.226:5069;branch=z9hG4bKec53.56115a2d09f62d466f1d45a5f]]
11(8358) DEBUG: <core> [core/parser/msg_parser.c:614]: parse_msg(): SIP 
Reply  (status):
11(8358) DEBUG: <core> [core/parser/msg_parser.c:616]: parse_msg():  
version: <SIP/2.0>
11(8358) DEBUG: <core> [core/parser/msg_parser.c:618]: parse_msg():  
status:  <100>
11(8358) DEBUG: <core> [core/parser/msg_parser.c:620]: parse_msg():  
reason:  <Trying>
11(8358) DEBUG: <core> [core/parser/parse_via.c:1303]: 
parse_via_param(): Found param type 232, <branch> = 
<z9hG4bKec53.56115a2d09f62d466f1d45a5f5ff7cc2.0>; state=9
11(8358) DEBUG: <core> [core/parser/parse_via.c:2681]: parse_via(): 
parsing via: next via
11(8358) DEBUG: <core> [core/parser/parse_via.c:1303]: 
parse_via_param(): Found param type 232, <branch> = <z9hG4bK-9680-1-0>; 
state=16
11(8358) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end 
of header reached, state=5
11(8358) DEBUG: <core> [core/parser/msg_parser.c:492]: parse_headers(): 
Via found, flags=2
11(8358) DEBUG: <core> [core/parser/msg_parser.c:494]: parse_headers(): 
this is the first via
11(8358) DEBUG: <core> [core/parser/parse_addr_spec.c:864]: 
parse_addr_spec(): end of header reached, state=10
11(8358) DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): 
<To> [44]; uri=[sip:34606147628(a)10.100.10.67:5069]
11(8358) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): 
to body ["Javi" <sip:34606147628(a)10.100.10.67:5069>
]
11(8358) DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): 
cseq <CSeq>: <1> <INVITE>
11(8358) DEBUG: <core> [core/receive.c:205]: receive_msg(): --- received 
sip message - reply - call-id: [1-9680(a)10.100.10.67] - cseq: [1 INVITE]
11(8358) DEBUG: tm [t_lookup.c:1019]: t_check_msg(): msg 
(0x7f334b5f3768) id=2 global id=1 T start=0xffffffffffffffff
13(8360) DEBUG: <core> [core/udp_server.c:492]: udp_rcv_loop(): received 
on udp socket: (106/100/479) [[SIP/2.0 302 Moved Temporarily 0D  0A Via: 
SIP/2.0/UDP 52.88.180.226:5069;branch=z9hG4bKec53.56115a2d09f62d]]
11(8358) DEBUG: tm [t_lookup.c:897]: t_reply_matching(): 
t_reply_matching: hash 13774 label 0 branch 0
11(8358) DEBUG: tm [t_lookup.c:951]: t_reply_matching(): reply 
(0x7f334b5f3768) matched an active transaction (T=0x7f334663b040)!
11(8358) DEBUG: tm [t_lookup.c:1088]: t_check_msg(): msg 
(0x7f334b5f3768) id=2 global id=2 T end=0x7f334663b040
11(8358) DEBUG: tm [t_reply.c:2209]: reply_received(): org. status 
uas=100, uac[0]=0 local=0 is_invite=1)
11(8358) DEBUG: <core> [core/parser/msg_parser.c:183]: get_hdr_field(): 
content_length=0
11(8358) DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): 
found end of header
11(8358) INFO: <script>: LAL
11(8358) DEBUG: tm [t_reply.c:1265]: t_should_relay_response(): 
->>>>>>>>> T_code=100, new_code=100
11(8358) DEBUG: tm [t_reply.c:1788]: relay_reply(): branch=0, save=0, 
relay=-1 icode=0
11(8358) DEBUG: <core> [core/receive.c:362]: receive_msg(): reply-route 
executed in: 149 usec
11(8358) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
11(8358) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
11(8358) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
11(8358) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
11(8358) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
11(8358) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
11(8358) DEBUG: <core> [core/xavp.c:446]: xavp_destroy_list(): 
destroying xavp list (nil)
11(8358) DEBUG: <core> [core/receive.c:378]: receive_msg(): cleaning up
13(8360) DEBUG: <core> [core/parser/msg_parser.c:614]: parse_msg(): SIP 
Reply  (status):
13(8360) DEBUG: <core> [core/parser/msg_parser.c:616]: parse_msg():  
version: <SIP/2.0>
13(8360) DEBUG: <core> [core/parser/msg_parser.c:618]: parse_msg():  
status:  <302>
13(8360) DEBUG: <core> [core/parser/msg_parser.c:620]: parse_msg():  
reason:  <Moved Temporarily>
13(8360) DEBUG: <core> [core/parser/parse_via.c:1303]: 
parse_via_param(): Found param type 232, <branch> = 
<z9hG4bKec53.56115a2d09f62d466f1d45a5f5ff7cc2.0>; state=9
13(8360) DEBUG: <core> [core/parser/parse_via.c:2681]: parse_via(): 
parsing via: next via
13(8360) DEBUG: <core> [core/parser/parse_via.c:1303]: 
parse_via_param(): Found param type 232, <branch> = <z9hG4bK-9680-1-0>; 
state=16
13(8360) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end 
of header reached, state=5
13(8360) DEBUG: <core> [core/parser/msg_parser.c:492]: parse_headers(): 
Via found, flags=2
13(8360) DEBUG: <core> [core/parser/msg_parser.c:494]: parse_headers(): 
this is the first via
13(8360) DEBUG: <core> [core/parser/parse_addr_spec.c:185]: 
parse_to_param(): add param: tag=5
13(8360) DEBUG: <core> [core/parser/parse_addr_spec.c:864]: 
parse_addr_spec(): end of header reached, state=29
13(8360) DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): 
<To> [50]; uri=[sip:34606147628(a)10.100.10.67:5069]
13(8360) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): 
to body ["Javi" <sip:34606147628(a)10.100.10.67:5069>]
13(8360) DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): 
cseq <CSeq>: <1> <INVITE>
13(8360) DEBUG: <core> [core/receive.c:205]: receive_msg(): --- received 
sip message - reply - call-id: [1-9680(a)10.100.10.67] - cseq: [1 INVITE]
13(8360) DEBUG: tm [t_lookup.c:1019]: t_check_msg(): msg 
(0x7f334b5f3768) id=1 global id=0 T start=0xffffffffffffffff
13(8360) DEBUG: tm [t_lookup.c:897]: t_reply_matching(): 
t_reply_matching: hash 13774 label 0 branch 0
13(8360) DEBUG: tm [t_lookup.c:951]: t_reply_matching(): reply 
(0x7f334b5f3768) matched an active transaction (T=0x7f334663b040)!
13(8360) DEBUG: tm [t_lookup.c:1088]: t_check_msg(): msg 
(0x7f334b5f3768) id=1 global id=1 T end=0x7f334663b040
13(8360) DEBUG: tm [t_reply.c:2209]: reply_received(): org. status 
uas=100, uac[0]=100 local=0 is_invite=1)
13(8360) DEBUG: <core> [core/parser/msg_parser.c:183]: get_hdr_field(): 
content_length=63
13(8360) DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): 
found end of header
13(8360) INFO: <script>: LAL 
{"sdp_data":"3466666666","sdp_data_2":null,"nrn":null}

13(8360) DEBUG: tm [t_reply.c:1265]: t_should_relay_response(): 
->>>>>>>>> T_code=100, new_code=302
13(8360) DEBUG: <core> [core/parser/msg_parser.c:614]: parse_msg(): SIP 
Reply  (status):
13(8360) DEBUG: <core> [core/parser/msg_parser.c:616]: parse_msg():  
version: <SIP/2.0>
13(8360) DEBUG: <core> [core/parser/msg_parser.c:618]: parse_msg():  
status:  <302>
13(8360) DEBUG: <core> [core/parser/msg_parser.c:620]: parse_msg():  
reason:  <Moved Temporarily>
13(8360) DEBUG: <core> [core/parser/parse_via.c:1303]: 
parse_via_param(): Found param type 232, <branch> = 
<z9hG4bKec53.56115a2d09f62d466f1d45a5f5ff7cc2.0>; state=9
13(8360) DEBUG: <core> [core/parser/parse_via.c:2681]: parse_via(): 
parsing via: next via
13(8360) DEBUG: <core> [core/parser/parse_via.c:1303]: 
parse_via_param(): Found param type 232, <branch> = <z9hG4bK-9680-1-0>; 
state=16
13(8360) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end 
of header reached, state=5
13(8360) DEBUG: <core> [core/parser/msg_parser.c:492]: parse_headers(): 
Via found, flags=2
13(8360) DEBUG: <core> [core/parser/msg_parser.c:494]: parse_headers(): 
this is the first via
13(8360) DEBUG: <core> [core/parser/parse_addr_spec.c:185]: 
parse_to_param(): add param: tag=5
13(8360) DEBUG: <core> [core/parser/parse_addr_spec.c:864]: 
parse_addr_spec(): end of header reached, state=29
13(8360) DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): 
<To> [50]; uri=[sip:34606147628(a)10.100.10.67:5069]
13(8360) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): 
to body ["Javi" <sip:34606147628(a)10.100.10.67:5069>]
13(8360) DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): 
cseq <CSeq>: <1> <INVITE>
13(8360) DEBUG: <core> [core/parser/msg_parser.c:183]: get_hdr_field(): 
content_length=63
13(8360) DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): 
found end of header
13(8360) INFO: <script>: LOOOOOOOOL 
{"sdp_data":"3466666666","sdp_data_2":null,"nrn":null}

13(8360) DEBUG: tm [t_lookup.c:1019]: t_check_msg(): msg 
(0x7f3346637088) id=0 global id=0 T start=0x7f334663b040
13(8360) DEBUG: tm [t_lookup.c:1091]: t_check_msg(): T (0x7f334663b040) 
already found for msg (0x7f3346637088)!
13(8360) DEBUG: tmx [t_var.c:534]: pv_get_tm_reply_code(): reply code is 
<302>
13(8360) INFO: <script>: Call: 302 received, trying to load contacts
13(8360) DEBUG: uac_redirect [rd_funcs.c:72]: get_redirect(): resume 
branch=0
13(8360) DEBUG: uac_redirect [rd_funcs.c:79]: get_redirect(): checking 
branch=0 (added=0)
13(8360) DEBUG: uac_redirect [rd_funcs.c:83]: get_redirect(): branch=0 
is a redirect (added=0)
13(8360) DEBUG: uac_redirect [rd_funcs.c:159]: sort_contacts(): 
sort_contacts: <sip:34666988297(a)10.100.10.67:5060> q=10
13(8360) DEBUG: uac_redirect [rd_funcs.c:295]: shmcontact2dset(): adding 
contact <sip:34666988297(a)10.100.10.67:5060>
13(8360) DEBUG: <core> [sruid.c:183]: sruid_next(): new sruid is 
[rdir-5be4236b-20a8-1] (1 / 20)
13(8360) DEBUG: tm [t_serial.c:191]: ki_t_load_contacts(): nr_branches is 1
13(8360) DEBUG: tm [t_serial.c:194]: ki_t_load_contacts(): nothing to do 
- only one contact!
13(8360) INFO: <script>: LEL
13(8360) DEBUG: <core> [core/msg_translator.c:159]: check_via_address(): 
(10.100.10.67, 10.100.10.67, 0)
13(8360) INFO: <script>: hereeeeeeeeeee
13(8360) DEBUG: tm [t_reply.c:1788]: relay_reply(): branch=0, save=0, 
relay=-1 icode=0
13(8360) DEBUG: <core> [core/receive.c:362]: receive_msg(): reply-route 
executed in: 783 usec
13(8360) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
13(8360) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
13(8360) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
13(8360) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
13(8360) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
13(8360) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
13(8360) DEBUG: <core> [core/xavp.c:446]: xavp_destroy_list(): 
destroying xavp list (nil)
13(8360) DEBUG: <core> [core/receive.c:378]: receive_msg(): cleaning up
14(8361) DEBUG: <core> [core/udp_server.c:492]: udp_rcv_loop(): received 
on udp socket: (106/100/397) [[SIP/2.0 100 Trying 0D  0A Via: 
SIP/2.0/UDP 
52.88.180.226:5069;branch=z9hG4bKec53.56115a2d09f62d466f1d45a5f]]
15(8362) DEBUG: <core> [core/udp_server.c:492]: udp_rcv_loop(): received 
on udp socket: (106/100/482) [[SIP/2.0 503 Service Unavailable 0D  0A 
Via: SIP/2.0/UDP 52.88.180.226:5069;branch=z9hG4bKec53.56115a2d09f6]]
14(8361) DEBUG: <core> [core/parser/msg_parser.c:614]: parse_msg(): SIP 
Reply  (status):
14(8361) DEBUG: <core> [core/parser/msg_parser.c:616]: parse_msg():  
version: <SIP/2.0>
14(8361) DEBUG: <core> [core/parser/msg_parser.c:618]: parse_msg():  
status:  <100>
14(8361) DEBUG: <core> [core/parser/msg_parser.c:620]: parse_msg():  
reason:  <Trying>
15(8362) DEBUG: <core> [core/parser/msg_parser.c:614]: parse_msg(): SIP 
Reply  (status):
15(8362) DEBUG: <core> [core/parser/msg_parser.c:616]: parse_msg():  
version: <SIP/2.0>
15(8362) DEBUG: <core> [core/parser/msg_parser.c:618]: parse_msg():  
status:  <503>
15(8362) DEBUG: <core> [core/parser/msg_parser.c:620]: parse_msg():  
reason:  <Service Unavailable>
14(8361) DEBUG: <core> [core/parser/parse_via.c:1303]: 
parse_via_param(): Found param type 232, <branch> = 
<z9hG4bKec53.56115a2d09f62d466f1d45a5f5ff7cc2.1>; state=9
14(8361) DEBUG: <core> [core/parser/parse_via.c:2681]: parse_via(): 
parsing via: next via
14(8361) DEBUG: <core> [core/parser/parse_via.c:1303]: 
parse_via_param(): Found param type 232, <branch> = <z9hG4bK-9680-1-0>; 
state=16
14(8361) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end 
of header reached, state=5
14(8361) DEBUG: <core> [core/parser/msg_parser.c:492]: parse_headers(): 
Via found, flags=2
14(8361) DEBUG: <core> [core/parser/msg_parser.c:494]: parse_headers(): 
this is the first via
15(8362) DEBUG: <core> [core/parser/parse_via.c:1303]: 
parse_via_param(): Found param type 232, <branch> = 
<z9hG4bKec53.56115a2d09f62d466f1d45a5f5ff7cc2.1>; state=9
15(8362) DEBUG: <core> [core/parser/parse_via.c:2681]: parse_via(): 
parsing via: next via
15(8362) DEBUG: <core> [core/parser/parse_via.c:1303]: 
parse_via_param(): Found param type 232, <branch> = <z9hG4bK-9680-1-0>; 
state=16
15(8362) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end 
of header reached, state=5
14(8361) DEBUG: <core> [core/parser/parse_addr_spec.c:864]: 
parse_addr_spec(): end of header reached, state=10
15(8362) DEBUG: <core> [core/parser/msg_parser.c:492]: parse_headers(): 
Via found, flags=2
14(8361) DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): 
<To> [44]; uri=[sip:34606147628(a)10.100.10.67:5069]
15(8362) DEBUG: <core> [core/parser/msg_parser.c:494]: parse_headers(): 
this is the first via
14(8361) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): 
to body ["Javi" <sip:34606147628(a)10.100.10.67:5069>
]
14(8361) DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): 
cseq <CSeq>: <1> <INVITE>
14(8361) DEBUG: <core> [core/receive.c:205]: receive_msg(): --- received 
sip message - reply - call-id: [1-9680(a)10.100.10.67] - cseq: [1 INVITE]
15(8362) DEBUG: <core> [core/parser/parse_addr_spec.c:185]: 
parse_to_param(): add param: tag=5
15(8362) DEBUG: <core> [core/parser/parse_addr_spec.c:864]: 
parse_addr_spec(): end of header reached, state=29
15(8362) DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): 
<To> [50]; uri=[sip:34606147628(a)10.100.10.67:5069]
15(8362) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): 
to body ["Javi" <sip:34606147628(a)10.100.10.67:5069>]
14(8361) DEBUG: tm [t_lookup.c:1019]: t_check_msg(): msg 
(0x7f334b5f3768) id=1 global id=0 T start=0xffffffffffffffff
14(8361) DEBUG: tm [t_lookup.c:897]: t_reply_matching(): 
t_reply_matching: hash 13774 label 0 branch 1
14(8361) DEBUG: tm [t_lookup.c:951]: t_reply_matching(): reply 
(0x7f334b5f3768) matched an active transaction (T=0x7f334663b040)!
14(8361) DEBUG: tm [t_lookup.c:1088]: t_check_msg(): msg 
(0x7f334b5f3768) id=1 global id=1 T end=0x7f334663b040
15(8362) DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): 
cseq <CSeq>: <1> <INVITE>
14(8361) DEBUG: tm [t_reply.c:2209]: reply_received(): org. status 
uas=100, uac[1]=0 local=0 is_invite=1)
15(8362) DEBUG: <core> [core/receive.c:205]: receive_msg(): --- received 
sip message - reply - call-id: [1-9680(a)10.100.10.67] - cseq: [1 INVITE]
15(8362) DEBUG: tm [t_lookup.c:1019]: t_check_msg(): msg 
(0x7f334b5f3768) id=1 global id=0 T start=0xffffffffffffffff
15(8362) DEBUG: tm [t_lookup.c:897]: t_reply_matching(): 
t_reply_matching: hash 13774 label 0 branch 1
15(8362) DEBUG: tm [t_lookup.c:951]: t_reply_matching(): reply 
(0x7f334b5f3768) matched an active transaction (T=0x7f334663b040)!
14(8361) DEBUG: <core> [core/parser/msg_parser.c:183]: get_hdr_field(): 
content_length=0
15(8362) DEBUG: tm [t_lookup.c:1088]: t_check_msg(): msg 
(0x7f334b5f3768) id=1 global id=1 T end=0x7f334663b040
15(8362) DEBUG: tm [t_reply.c:2209]: reply_received(): org. status 
uas=100, uac[1]=100 local=0 is_invite=1)
14(8361) DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): 
found end of header
14(8361) INFO: <script>: LAL
14(8361) DEBUG: tm [t_reply.c:1265]: t_should_relay_response(): 
->>>>>>>>> T_code=100, new_code=100
14(8361) DEBUG: tm [t_reply.c:1788]: relay_reply(): branch=1, save=0, 
relay=-1 icode=0
14(8361) DEBUG: <core> [core/receive.c:362]: receive_msg(): reply-route 
executed in: 199 usec
14(8361) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
14(8361) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
14(8361) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
14(8361) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
14(8361) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
14(8361) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
14(8361) DEBUG: <core> [core/xavp.c:446]: xavp_destroy_list(): 
destroying xavp list (nil)
14(8361) DEBUG: <core> [core/receive.c:378]: receive_msg(): cleaning up
15(8362) DEBUG: <core> [core/parser/msg_parser.c:183]: get_hdr_field(): 
content_length=64
15(8362) DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): 
found end of header
15(8362) INFO: <script>: LAL 
{"sdp_data":"34619796636","sdp_data_2":null,"nrn":null}

15(8362) DEBUG: tm [t_reply.c:1265]: t_should_relay_response(): 
->>>>>>>>> T_code=100, new_code=503
15(8362) DEBUG: <core> [core/parser/msg_parser.c:614]: parse_msg(): SIP 
Reply  (status):
15(8362) DEBUG: <core> [core/parser/msg_parser.c:616]: parse_msg():  
version: <SIP/2.0>
15(8362) DEBUG: <core> [core/parser/msg_parser.c:618]: parse_msg():  
status:  <503>
15(8362) DEBUG: <core> [core/parser/msg_parser.c:620]: parse_msg():  
reason:  <Service Unavailable>
15(8362) DEBUG: <core> [core/parser/parse_via.c:1303]: 
parse_via_param(): Found param type 232, <branch> = 
<z9hG4bKec53.56115a2d09f62d466f1d45a5f5ff7cc2.1>; state=9
15(8362) DEBUG: <core> [core/parser/parse_via.c:2681]: parse_via(): 
parsing via: next via
15(8362) DEBUG: <core> [core/parser/parse_via.c:1303]: 
parse_via_param(): Found param type 232, <branch> = <z9hG4bK-9680-1-0>; 
state=16
15(8362) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end 
of header reached, state=5
15(8362) DEBUG: <core> [core/parser/msg_parser.c:492]: parse_headers(): 
Via found, flags=2
15(8362) DEBUG: <core> [core/parser/msg_parser.c:494]: parse_headers(): 
this is the first via
15(8362) DEBUG: <core> [core/parser/parse_addr_spec.c:185]: 
parse_to_param(): add param: tag=5
15(8362) DEBUG: <core> [core/parser/parse_addr_spec.c:864]: 
parse_addr_spec(): end of header reached, state=29
15(8362) DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): 
<To> [50]; uri=[sip:34606147628(a)10.100.10.67:5069]
15(8362) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): 
to body ["Javi" <sip:34606147628(a)10.100.10.67:5069>]
15(8362) DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): 
cseq <CSeq>: <1> <INVITE>
15(8362) DEBUG: <core> [core/parser/msg_parser.c:183]: get_hdr_field(): 
content_length=64
15(8362) DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): 
found end of header
15(8362) INFO: <script>: LOOOOOOOOL 
{"sdp_data":"34619796636","sdp_data_2":null,"nrn":null}

15(8362) DEBUG: tm [t_lookup.c:1019]: t_check_msg(): msg 
(0x7f3346637088) id=0 global id=0 T start=0x7f334663b040
15(8362) DEBUG: tm [t_lookup.c:1091]: t_check_msg(): T (0x7f334663b040) 
already found for msg (0x7f3346637088)!
15(8362) DEBUG: tmx [t_var.c:534]: pv_get_tm_reply_code(): reply code is 
<503>
15(8362) DEBUG: tm [t_lookup.c:1019]: t_check_msg(): msg 
(0x7f3346637088) id=0 global id=0 T start=0x7f334663b040
15(8362) DEBUG: tm [t_lookup.c:1091]: t_check_msg(): T (0x7f334663b040) 
already found for msg (0x7f3346637088)!
15(8362) DEBUG: tmx [t_var.c:534]: pv_get_tm_reply_code(): reply code is 
<503>
15(8362) INFO: <script>: LEL
15(8362) DEBUG: <core> [core/msg_translator.c:159]: check_via_address(): 
(10.100.10.67, 10.100.10.67, 0)
15(8362) INFO: <script>: hereeeeeeeeeee
15(8362) DEBUG: tm [t_reply.c:1788]: relay_reply(): branch=1, save=0, 
relay=-1 icode=0
15(8362) DEBUG: <core> [core/receive.c:362]: receive_msg(): reply-route 
executed in: 676 usec
15(8362) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
15(8362) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
15(8362) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
15(8362) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
15(8362) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
15(8362) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
15(8362) DEBUG: <core> [core/xavp.c:446]: xavp_destroy_list(): 
destroying xavp list (nil)
15(8362) DEBUG: <core> [core/receive.c:378]: receive_msg(): cleaning up
15(8362) DEBUG: <core> [core/udp_server.c:492]: udp_rcv_loop(): received 
on udp socket: (106/100/404) [[SIP/2.0 180 Ringing 0D  0A Via: 
SIP/2.0/UDP 52.88.180.226:5069;branch=z9hG4bKec53.56115a2d09f62d466f1d45a5]]
15(8362) DEBUG: <core> [core/parser/msg_parser.c:614]: parse_msg(): SIP 
Reply  (status):
15(8362) DEBUG: <core> [core/parser/msg_parser.c:616]: parse_msg():  
version: <SIP/2.0>
15(8362) DEBUG: <core> [core/parser/msg_parser.c:618]: parse_msg():  
status:  <180>
15(8362) DEBUG: <core> [core/parser/msg_parser.c:620]: parse_msg():  
reason:  <Ringing>
15(8362) DEBUG: <core> [core/parser/parse_via.c:1303]: 
parse_via_param(): Found param type 232, <branch> = 
<z9hG4bKec53.56115a2d09f62d466f1d45a5f5ff7cc2.2>; state=9
15(8362) DEBUG: <core> [core/parser/parse_via.c:2681]: parse_via(): 
parsing via: next via
15(8362) DEBUG: <core> [core/parser/parse_via.c:1303]: 
parse_via_param(): Found param type 232, <branch> = <z9hG4bK-9680-1-0>; 
state=16
15(8362) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end 
of header reached, state=5
15(8362) DEBUG: <core> [core/parser/msg_parser.c:492]: parse_headers(): 
Via found, flags=2
15(8362) DEBUG: <core> [core/parser/msg_parser.c:494]: parse_headers(): 
this is the first via
15(8362) DEBUG: <core> [core/parser/parse_addr_spec.c:185]: 
parse_to_param(): add param: tag=5
15(8362) DEBUG: <core> [core/parser/parse_addr_spec.c:864]: 
parse_addr_spec(): end of header reached, state=29
15(8362) DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): 
<To> [50]; uri=[sip:34606147628(a)10.100.10.67:5069]
15(8362) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): 
to body ["Javi" <sip:34606147628(a)10.100.10.67:5069>]
15(8362) DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): 
cseq <CSeq>: <1> <INVITE>
15(8362) DEBUG: <core> [core/receive.c:205]: receive_msg(): --- received 
sip message - reply - call-id: [1-9680(a)10.100.10.67] - cseq: [1 INVITE]
15(8362) DEBUG: tm [t_lookup.c:1019]: t_check_msg(): msg 
(0x7f334b5f3768) id=2 global id=1 T start=0xffffffffffffffff
  6(8353) DEBUG: <core> [core/udp_server.c:492]: udp_rcv_loop(): 
received on udp socket: (106/100/595) [[SIP/2.0 200 OK 0D  0A Via: 
SIP/2.0/UDP 
52.88.180.226:5069;branch=z9hG4bKec53.56115a2d09f62d466f1d45a5f5ff7]]
15(8362) DEBUG: tm [t_lookup.c:897]: t_reply_matching(): 
t_reply_matching: hash 13774 label 0 branch 2
15(8362) DEBUG: tm [t_lookup.c:951]: t_reply_matching(): reply 
(0x7f334b5f3768) matched an active transaction (T=0x7f334663b040)!
15(8362) DEBUG: tm [t_lookup.c:1088]: t_check_msg(): msg 
(0x7f334b5f3768) id=2 global id=2 T end=0x7f334663b040
15(8362) DEBUG: tm [t_reply.c:2209]: reply_received(): org. status 
uas=100, uac[2]=0 local=0 is_invite=1)
15(8362) DEBUG: <core> [core/parser/msg_parser.c:183]: get_hdr_field(): 
content_length=0
15(8362) DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): 
found end of header
15(8362) INFO: <script>: LAL
15(8362) DEBUG: tm [t_reply.c:1265]: t_should_relay_response(): 
->>>>>>>>> T_code=100, new_code=180
15(8362) DEBUG: tm [t_reply.c:1788]: relay_reply(): branch=2, save=0, 
relay=2 icode=0
15(8362) DEBUG: <core> [core/msg_translator.c:2270]: 
generate_res_buf_from_sip_res(): old size: 404, new size: 318
15(8362) DEBUG: <core> [core/msg_translator.c:2288]: 
generate_res_buf_from_sip_res(): copied size: orig:112, new: 26, rest: 
292 msg=
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 10.100.10.67:5061;branch=z9hG4bK-9680-1-0
From: "BTS" <sip:34917019888(a)10.100.10.67:5061>;tag=9680SIPpTag001
To: "Javi" <sip:34606147628(a)10.100.10.67:5069>;tag=5
Call-ID: 1-9680(a)10.100.10.67
CSeq: 1 INVITE
Contact: <sip:10.100.10.67:5060;transport=UDP>
Content-Length: 0


15(8362) DEBUG: <core> [core/receive.c:362]: receive_msg(): reply-route 
executed in: 71 usec
15(8362) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
15(8362) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
15(8362) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
15(8362) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
15(8362) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
15(8362) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
15(8362) DEBUG: <core> [core/xavp.c:446]: xavp_destroy_list(): 
destroying xavp list (nil)
15(8362) DEBUG: <core> [core/receive.c:378]: receive_msg(): cleaning up
  6(8353) DEBUG: <core> [core/parser/msg_parser.c:614]: parse_msg(): SIP 
Reply  (status):
  6(8353) DEBUG: <core> [core/parser/msg_parser.c:616]: parse_msg():  
version: <SIP/2.0>
  6(8353) DEBUG: <core> [core/parser/msg_parser.c:618]: parse_msg():  
status:  <200>
  6(8353) DEBUG: <core> [core/parser/msg_parser.c:620]: parse_msg():  
reason:  <OK>
  6(8353) DEBUG: <core> [core/parser/parse_via.c:1303]: 
parse_via_param(): Found param type 232, <branch> = 
<z9hG4bKec53.56115a2d09f62d466f1d45a5f5ff7cc2.2>; state=9
  6(8353) DEBUG: <core> [core/parser/parse_via.c:2681]: parse_via(): 
parsing via: next via
  6(8353) DEBUG: <core> [core/parser/parse_via.c:1303]: 
parse_via_param(): Found param type 232, <branch> = <z9hG4bK-9680-1-0>; 
state=16
  6(8353) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end 
of header reached, state=5
  6(8353) DEBUG: <core> [core/parser/msg_parser.c:492]: parse_headers(): 
Via found, flags=2
  6(8353) DEBUG: <core> [core/parser/msg_parser.c:494]: parse_headers(): 
this is the first via
  6(8353) DEBUG: <core> [core/parser/parse_addr_spec.c:185]: 
parse_to_param(): add param: tag=5
  6(8353) DEBUG: <core> [core/parser/parse_addr_spec.c:864]: 
parse_addr_spec(): end of header reached, state=29
  6(8353) DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): 
<To> [50]; uri=[sip:34606147628(a)10.100.10.67:5069]
  6(8353) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): 
to body ["Javi" <sip:34606147628(a)10.100.10.67:5069>]
  6(8353) DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): 
cseq <CSeq>: <1> <INVITE>
  6(8353) DEBUG: <core> [core/receive.c:205]: receive_msg(): --- 
received sip message - reply - call-id: [1-9680(a)10.100.10.67] - cseq: [1 
INVITE]
  6(8353) DEBUG: tm [t_lookup.c:1019]: t_check_msg(): msg 
(0x7f334b5f3768) id=1 global id=0 T start=0xffffffffffffffff
  6(8353) DEBUG: tm [t_lookup.c:897]: t_reply_matching(): 
t_reply_matching: hash 13774 label 0 branch 2
  6(8353) DEBUG: tm [t_lookup.c:951]: t_reply_matching(): reply 
(0x7f334b5f3768) matched an active transaction (T=0x7f334663b040)!
  6(8353) DEBUG: tm [t_lookup.c:1088]: t_check_msg(): msg 
(0x7f334b5f3768) id=1 global id=1 T end=0x7f334663b040
  6(8353) DEBUG: tm [t_reply.c:2209]: reply_received(): org. status 
uas=180, uac[2]=180 local=0 is_invite=1)
  6(8353) DEBUG: <core> [core/parser/msg_parser.c:183]: get_hdr_field(): 
content_length=161
  6(8353) DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): 
found end of header
  6(8353) INFO: <script>: LAL v=0
o=user1 53655765 2353687637 IN IP4 10.100.10.67
s=-
c=IN IP4 10.100.10.67
t=0 0
m=audio 6000 RTP/AVP 0 18
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000

  6(8353) DEBUG: tm [t_reply.c:1265]: t_should_relay_response(): 
->>>>>>>>> T_code=180, new_code=200
  6(8353) DEBUG: tm [t_reply.c:1788]: relay_reply(): branch=2, save=0, 
relay=2 icode=0
  6(8353) DEBUG: <core> [core/msg_translator.c:2270]: 
generate_res_buf_from_sip_res(): old size: 595, new size: 509
  6(8353) DEBUG: <core> [core/msg_translator.c:2288]: 
generate_res_buf_from_sip_res(): copied size: orig:107, new: 21, rest: 
488 msg=
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.100.10.67:5061;branch=z9hG4bK-9680-1-0
From: "BTS" <sip:34917019888(a)10.100.10.67:5061>;tag=9680SIPpTag001
To: "Javi" <sip:34606147628(a)10.100.10.67:5069>;tag=5
Call-ID: 1-9680(a)10.100.10.67
CSeq: 1 INVITE
Contact: <sip:10.100.10.67:5060;transport=UDP>
Content-Type: application/sdp
Content-Length:   161

v=0
o=user1 53655765 2353687637 IN IP4 10.100.10.67
s=-
c=IN IP4 10.100.10.67
t=0 0
m=audio 6000 RTP/AVP 0 18
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000

  6(8353) DEBUG: tm [t_reply.c:1631]: cleanup_uac_timers(): RETR/FR 
timers reset
  6(8353) DEBUG: <core> [core/receive.c:362]: receive_msg(): reply-route 
executed in: 283 usec
  6(8353) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  6(8353) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  6(8353) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  6(8353) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  6(8353) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  6(8353) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  6(8353) DEBUG: <core> [core/xavp.c:446]: xavp_destroy_list(): 
destroying xavp list (nil)
  6(8353) DEBUG: <core> [core/receive.c:378]: receive_msg(): cleaning up
  6(8353) DEBUG: <core> [core/udp_server.c:492]: udp_rcv_loop(): 
received on udp socket: (106/100/323) [[ACK 
sip:34606147628(a)10.100.10.67:5060 SIP/2.0 0D  0A Via: SIP/2.0/UDP 
10.100.10.67:5061;branch=z9hG4bK-968]]
  6(8353) DEBUG: <core> [core/parser/msg_parser.c:604]: parse_msg(): SIP 
Request:
  6(8353) DEBUG: <core> [core/parser/msg_parser.c:606]: parse_msg():  
method:  <ACK>
  6(8353) DEBUG: <core> [core/parser/msg_parser.c:608]: parse_msg():  
uri:     <sip:34606147628(a)10.100.10.67:5060>
  6(8353) DEBUG: <core> [core/parser/msg_parser.c:610]: parse_msg():  
version: <SIP/2.0>
  6(8353) DEBUG: <core> [core/parser/parse_via.c:1303]: 
parse_via_param(): Found param type 232, <branch> = <z9hG4bK-9680-1-0>; 
state=16
  6(8353) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end 
of header reached, state=5
  6(8353) DEBUG: <core> [core/parser/msg_parser.c:492]: parse_headers(): 
Via found, flags=2
  6(8353) DEBUG: <core> [core/parser/msg_parser.c:494]: parse_headers(): 
this is the first via
  6(8353) DEBUG: <core> [core/parser/parse_addr_spec.c:185]: 
parse_to_param(): add param: tag=5
  6(8353) DEBUG: <core> [core/parser/parse_addr_spec.c:864]: 
parse_addr_spec(): end of header reached, state=29
  6(8353) DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): 
<To> [50]; uri=[sip:34606147628(a)10.100.10.67:5069]
  6(8353) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): 
to body ["Test" <sip:34606147628(a)10.100.10.67:5069>]
  6(8353) DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): 
cseq <CSeq>: <1> <ACK>
  6(8353) DEBUG: <core> [core/receive.c:205]: receive_msg(): --- 
received sip message - request - call-id: [1-9680(a)10.100.10.67] - cseq: 
[1 ACK]
  6(8353) DEBUG: <core> [core/receive.c:248]: receive_msg(): preparing 
to run routing scripts...
  6(8353) DEBUG: sl [sl_funcs.c:387]: sl_filter_ACK(): too late to be a 
local ACK!
  6(8353) INFO: <script>: hereeeeeeeeeee
  6(8353) DEBUG: tm [t_lookup.c:1320]: t_newtran(): msg id=2 , global 
msg id=1 , T on entrance=0xffffffffffffffff
  6(8353) DEBUG: <core> [core/parser/msg_parser.c:183]: get_hdr_field(): 
content_length=0
  6(8353) DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): 
found end of header
  6(8353) DEBUG: tm [t_lookup.c:477]: t_lookup_request(): start 
searching: hash=13774, isACK=1
  6(8353) DEBUG: tm [t_lookup.c:435]: matching_3261(): RFC3261 
transaction matching failed
  6(8353) DEBUG: tm [t_lookup.c:659]: t_lookup_request(): no transaction 
found
  6(8353) DEBUG: tm [t_funcs.c:284]: t_relay_to(): forwarding ACK 
statelessly
  6(8353) DEBUG: <core> [core/md5utils.c:67]: MD5StringArray(): MD5 
calculated: 56115a2d09f62d466f1d45a5f5ff7cc2
  6(8353) DEBUG: <core> [core/msg_translator.c:159]: 
check_via_address(): (10.100.10.67, 10.100.10.67, 0)
  6(8353) DEBUG: <core> [core/forward.c:557]: forward_request(): Sending:
ACK sip:34606147628(a)10.100.10.67:5060 SIP/2.0
Via: SIP/2.0/UDP 
52.88.180.226:5069;branch=z9hG4bKec53.56115a2d09f62d466f1d45a5f5ff7cc2.0
Via: SIP/2.0/UDP 10.100.10.67:5061;branch=z9hG4bK-9680-1-0
From: "BTS" <sip:34917019888(a)10.100.10.67:5061>;tag=9680SIPpTag001
To: "Test" <sip:34606147628(a)10.100.10.67:5069>;tag=5
Call-ID: 1-9680(a)10.100.10.67
CSeq: 1 ACK
Max-Forwards: 70
Subject: 1
Content-Length: 0

.
  6(8353) DEBUG: <core> [core/forward.c:559]: forward_request(): orig. 
len=323, new_len=414, proto=1
  6(8353) INFO: <script>: hereeeeeeeeeee
  6(8353) DEBUG: <core> [core/receive.c:289]: receive_msg(): 
request-route executed in: 232 usec
  6(8353) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  6(8353) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  6(8353) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  6(8353) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  6(8353) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  6(8353) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  6(8353) DEBUG: <core> [core/xavp.c:446]: xavp_destroy_list(): 
destroying xavp list (nil)
  6(8353) DEBUG: <core> [core/receive.c:378]: receive_msg(): cleaning up
  3(8350) DEBUG: <core> [core/udp_server.c:492]: udp_rcv_loop(): 
received on udp socket: (106/100/338) [[BYE 
sip:34606147628(a)10.100.10.67:5060 SIP/2.0 0D  0A Via: SIP/2.0/UDP 
10.100.10.67:5061;branch=z9hG4bK-968]]
  3(8350) DEBUG: <core> [core/parser/msg_parser.c:604]: parse_msg(): SIP 
Request:
  3(8350) DEBUG: <core> [core/parser/msg_parser.c:606]: parse_msg():  
method:  <BYE>
  3(8350) DEBUG: <core> [core/parser/msg_parser.c:608]: parse_msg():  
uri:     <sip:34606147628(a)10.100.10.67:5060>
  3(8350) DEBUG: <core> [core/parser/msg_parser.c:610]: parse_msg():  
version: <SIP/2.0>
  3(8350) DEBUG: <core> [core/parser/parse_via.c:1303]: 
parse_via_param(): Found param type 232, <branch> = <z9hG4bK-9680-1-8>; 
state=16
  3(8350) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end 
of header reached, state=5
  3(8350) DEBUG: <core> [core/parser/msg_parser.c:492]: parse_headers(): 
Via found, flags=2
  3(8350) DEBUG: <core> [core/parser/msg_parser.c:494]: parse_headers(): 
this is the first via
  3(8350) DEBUG: <core> [core/parser/parse_addr_spec.c:185]: 
parse_to_param(): add param: tag=5
  3(8350) DEBUG: <core> [core/parser/parse_addr_spec.c:864]: 
parse_addr_spec(): end of header reached, state=29
  3(8350) DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): 
<To> [50]; uri=[sip:34606147628(a)10.100.10.67:5069]
  3(8350) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): 
to body ["Test" <sip:34606147628(a)10.100.10.67:5069>]
  3(8350) DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): 
cseq <CSeq>: <2> <BYE>
  3(8350) DEBUG: <core> [core/receive.c:205]: receive_msg(): --- 
received sip message - request - call-id: [1-9680(a)10.100.10.67] - cseq: 
[2 BYE]
  3(8350) DEBUG: <core> [core/receive.c:248]: receive_msg(): preparing 
to run routing scripts...
  3(8350) INFO: <script>: hereeeeeeeeeee
  3(8350) DEBUG: tm [t_lookup.c:1320]: t_newtran(): msg id=2 , global 
msg id=1 , T on entrance=0xffffffffffffffff
  3(8350) DEBUG: <core> [core/parser/msg_parser.c:183]: get_hdr_field(): 
content_length=0
  3(8350) DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): 
found end of header
  3(8350) DEBUG: tm [t_lookup.c:477]: t_lookup_request(): start 
searching: hash=13771, isACK=0
  3(8350) DEBUG: tm [t_lookup.c:435]: matching_3261(): RFC3261 
transaction matching failed
  3(8350) DEBUG: tm [t_lookup.c:659]: t_lookup_request(): no transaction 
found
  3(8350) DEBUG: <core> [core/md5utils.c:67]: MD5StringArray(): MD5 
calculated: 5b69d64cadac24fd6fc477c074a9b4c9
  3(8350) INFO: <script>: LEL
  3(8350) DEBUG: <core> [core/msg_translator.c:159]: 
check_via_address(): (10.100.10.67, 10.100.10.67, 0)
  3(8350) INFO: <script>: hereeeeeeeeeee
  3(8350) DEBUG: tm [t_funcs.c:372]: t_relay_to(): new transaction forwarded
  3(8350) DEBUG: <core> [core/receive.c:289]: receive_msg(): 
request-route executed in: 265 usec
  3(8350) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  3(8350) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  3(8350) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  3(8350) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  3(8350) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  3(8350) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  3(8350) DEBUG: <core> [core/xavp.c:446]: xavp_destroy_list(): 
destroying xavp list (nil)
  3(8350) DEBUG: <core> [core/receive.c:378]: receive_msg(): cleaning up
  7(8354) DEBUG: <core> [core/udp_server.c:492]: udp_rcv_loop(): 
received on udp socket: (106/100/396) [[SIP/2.0 200 OK 0D  0A Via: 
SIP/2.0/UDP 
52.88.180.226:5069;branch=z9hG4bKbc53.5b69d64cadac24fd6fc477c074a9b]]
  7(8354) DEBUG: <core> [core/parser/msg_parser.c:614]: parse_msg(): SIP 
Reply  (status):
  7(8354) DEBUG: <core> [core/parser/msg_parser.c:616]: parse_msg():  
version: <SIP/2.0>
  7(8354) DEBUG: <core> [core/parser/msg_parser.c:618]: parse_msg():  
status:  <200>
  7(8354) DEBUG: <core> [core/parser/msg_parser.c:620]: parse_msg():  
reason:  <OK>
  7(8354) DEBUG: <core> [core/parser/parse_via.c:1303]: 
parse_via_param(): Found param type 232, <branch> = 
<z9hG4bKbc53.5b69d64cadac24fd6fc477c074a9b4c9.0>; state=9
  7(8354) DEBUG: <core> [core/parser/parse_via.c:2681]: parse_via(): 
parsing via: next via
  7(8354) DEBUG: <core> [core/parser/parse_via.c:1303]: 
parse_via_param(): Found param type 232, <branch> = <z9hG4bK-9680-1-8>; 
state=16
  7(8354) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end 
of header reached, state=5
  7(8354) DEBUG: <core> [core/parser/msg_parser.c:492]: parse_headers(): 
Via found, flags=2
  7(8354) DEBUG: <core> [core/parser/msg_parser.c:494]: parse_headers(): 
this is the first via
  7(8354) DEBUG: <core> [core/parser/parse_addr_spec.c:185]: 
parse_to_param(): add param: tag=5
  7(8354) DEBUG: <core> [core/parser/parse_addr_spec.c:864]: 
parse_addr_spec(): end of header reached, state=29
  7(8354) DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): 
<To> [50]; uri=[sip:34606147628(a)10.100.10.67:5069]
  7(8354) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): 
to body ["Test" <sip:34606147628(a)10.100.10.67:5069>]
  7(8354) DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): 
cseq <CSeq>: <2> <BYE>
  7(8354) DEBUG: <core> [core/receive.c:205]: receive_msg(): --- 
received sip message - reply - call-id: [1-9680(a)10.100.10.67] - cseq: [2 
BYE]
  7(8354) DEBUG: tm [t_lookup.c:1019]: t_check_msg(): msg 
(0x7f334b5f3768) id=2 global id=1 T start=0xffffffffffffffff
  7(8354) DEBUG: tm [t_lookup.c:897]: t_reply_matching(): 
t_reply_matching: hash 13771 label 0 branch 0
  7(8354) DEBUG: tm [t_lookup.c:951]: t_reply_matching(): reply 
(0x7f334b5f3768) matched an active transaction (T=0x7f33466359d8)!
  7(8354) DEBUG: tm [t_lookup.c:1088]: t_check_msg(): msg 
(0x7f334b5f3768) id=2 global id=2 T end=0x7f33466359d8
  7(8354) DEBUG: tm [t_reply.c:2209]: reply_received(): org. status 
uas=0, uac[0]=0 local=0 is_invite=0)
  7(8354) DEBUG: tm [t_reply.c:1265]: t_should_relay_response(): 
->>>>>>>>> T_code=0, new_code=200
  7(8354) DEBUG: tm [t_reply.c:1788]: relay_reply(): branch=0, save=0, 
relay=0 icode=0
  7(8354) DEBUG: <core> [core/msg_translator.c:2270]: 
generate_res_buf_from_sip_res(): old size: 396, new size: 310
  7(8354) DEBUG: <core> [core/msg_translator.c:2288]: 
generate_res_buf_from_sip_res(): copied size: orig:107, new: 21, rest: 
289 msg=
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.100.10.67:5061;branch=z9hG4bK-9680-1-8
From: "BTS" <sip:34917019888(a)10.100.10.67:5061>;tag=9680SIPpTag001
To: "Test" <sip:34606147628(a)10.100.10.67:5069>;tag=5
Call-ID: 1-9680(a)10.100.10.67
CSeq: 2 BYE
Contact: <sip:10.100.10.67:5060;transport=UDP>
Content-Length: 0


  7(8354) DEBUG: tm [t_reply.c:1631]: cleanup_uac_timers(): RETR/FR 
timers reset
  7(8354) DEBUG: <core> [core/receive.c:362]: receive_msg(): reply-route 
executed in: 137 usec
  7(8354) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  7(8354) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  7(8354) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  7(8354) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  7(8354) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  7(8354) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  7(8354) DEBUG: <core> [core/xavp.c:446]: xavp_destroy_list(): 
destroying xavp list (nil)
  7(8354) DEBUG: <core> [core/receive.c:378]: receive_msg(): cleaning up
18(8365) DEBUG: tm [h_table.c:129]: free_cell_helper(): freeing 
transaction 0x7f334663b040 from timer.c:654
18(8365) DEBUG: tm [h_table.c:129]: free_cell_helper(): freeing 
transaction 0x7f33466359d8 from timer.c:654



1_children.log

1(7698) DEBUG: <core> [core/udp_server.c:492]: udp_rcv_loop(): received 
on udp socket: (106/100/634) [[INVITE sip:34606147628(a)10.100.10.67:5069 
SIP/2.0 0D  0A Via: SIP/2.0/UDP 10.100.10.67:5061;branch=z9hG4bK-]]
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:604]: parse_msg(): SIP 
Request:
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:606]: parse_msg():  
method:  <INVITE>
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:608]: parse_msg():  
uri:     <sip:34606147628(a)10.100.10.67:5069>
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:610]: parse_msg():  
version: <SIP/2.0>
  1(7698) DEBUG: <core> [core/parser/parse_via.c:1303]: 
parse_via_param(): Found param type 232, <branch> = <z9hG4bK-8173-1-0>; 
state=16
  1(7698) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end 
of header reached, state=5
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:492]: parse_headers(): 
Via found, flags=2
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:494]: parse_headers(): 
this is the first via
  1(7698) DEBUG: <core> [core/parser/parse_addr_spec.c:864]: 
parse_addr_spec(): end of header reached, state=10
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): 
<To> [44]; uri=[sip:34606147628(a)10.100.10.67:5069]
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): 
to body ["Javi" <sip:34606147628(a)10.100.10.67:5069>
]
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): 
cseq <CSeq>: <1> <INVITE>
  1(7698) DEBUG: <core> [core/receive.c:205]: receive_msg(): --- 
received sip message - request - call-id: [1-8173(a)10.100.10.67] - cseq: 
[1 INVITE]
  1(7698) DEBUG: <core> [core/receive.c:248]: receive_msg(): preparing 
to run routing scripts...
  1(7698) INFO: <script>: hereeeeeeeeeee
  1(7698) DEBUG: tm [t_lookup.c:1320]: t_newtran(): msg id=1 , global 
msg id=0 , T on entrance=0xffffffffffffffff
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:183]: get_hdr_field(): 
content_length=217
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): 
found end of header
  1(7698) DEBUG: tm [t_lookup.c:477]: t_lookup_request(): start 
searching: hash=65453, isACK=0
  1(7698) DEBUG: tm [t_lookup.c:435]: matching_3261(): RFC3261 
transaction matching failed
  1(7698) DEBUG: tm [t_lookup.c:659]: t_lookup_request(): no transaction 
found
  1(7698) DEBUG: <core> [core/parser/parse_addr_spec.c:185]: 
parse_to_param(): add param: tag=8173SIPpTag001
  1(7698) DEBUG: <core> [core/parser/parse_addr_spec.c:864]: 
parse_addr_spec(): end of header reached, state=29
  1(7698) DEBUG: <core> [core/md5utils.c:67]: MD5StringArray(): MD5 
calculated: 8f25665e8c867e73b07da3cb1f702171
  1(7698) DEBUG: tm [t_funcs.c:324]: t_relay_to(): new INVITE
  1(7698) DEBUG: <core> [core/msg_translator.c:159]: 
check_via_address(): (10.100.10.67, 10.100.10.67, 0)
  1(7698) DEBUG: tm [t_reply.c:596]: _reply_light(): reply sent out. 
buf=0x7fe2c208bea0: SIP/2.0 100 trying -..., shmem=0x7fe2bd0c9f40: 
SIP/2.0 100 trying -
  1(7698) DEBUG: tm [t_reply.c:606]: _reply_light(): finished
  1(7698) INFO: <script>: LEL
  1(7698) DEBUG: <core> [core/msg_translator.c:159]: 
check_via_address(): (10.100.10.67, 10.100.10.67, 0)
  1(7698) INFO: <script>: hereeeeeeeeeee
  1(7698) DEBUG: tm [t_funcs.c:372]: t_relay_to(): new transaction forwarded
  1(7698) DEBUG: <core> [core/receive.c:289]: receive_msg(): 
request-route executed in: 607 usec
  1(7698) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  1(7698) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  1(7698) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  1(7698) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  1(7698) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  1(7698) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  1(7698) DEBUG: <core> [core/xavp.c:446]: xavp_destroy_list(): 
destroying xavp list (nil)
  1(7698) DEBUG: <core> [core/receive.c:378]: receive_msg(): cleaning up
  1(7698) DEBUG: <core> [core/udp_server.c:492]: udp_rcv_loop(): 
received on udp socket: (106/100/397) [[SIP/2.0 100 Trying 0D  0A Via: 
SIP/2.0/UDP 
52.88.180.226:5069;branch=z9hG4bKdaff.8f25665e8c867e73b07da3cb1]]
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:614]: parse_msg(): SIP 
Reply  (status):
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:616]: parse_msg():  
version: <SIP/2.0>
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:618]: parse_msg():  
status:  <100>
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:620]: parse_msg():  
reason:  <Trying>
  1(7698) DEBUG: <core> [core/parser/parse_via.c:1303]: 
parse_via_param(): Found param type 232, <branch> = 
<z9hG4bKdaff.8f25665e8c867e73b07da3cb1f702171.0>; state=9
  1(7698) DEBUG: <core> [core/parser/parse_via.c:2681]: parse_via(): 
parsing via: next via
  1(7698) DEBUG: <core> [core/parser/parse_via.c:1303]: 
parse_via_param(): Found param type 232, <branch> = <z9hG4bK-8173-1-0>; 
state=16
  1(7698) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end 
of header reached, state=5
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:492]: parse_headers(): 
Via found, flags=2
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:494]: parse_headers(): 
this is the first via
  1(7698) DEBUG: <core> [core/parser/parse_addr_spec.c:864]: 
parse_addr_spec(): end of header reached, state=10
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): 
<To> [44]; uri=[sip:34606147628(a)10.100.10.67:5069]
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): 
to body ["Javi" <sip:34606147628(a)10.100.10.67:5069>
]
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): 
cseq <CSeq>: <1> <INVITE>
  1(7698) DEBUG: <core> [core/receive.c:205]: receive_msg(): --- 
received sip message - reply - call-id: [1-8173(a)10.100.10.67] - cseq: [1 
INVITE]
  1(7698) DEBUG: tm [t_lookup.c:1019]: t_check_msg(): msg 
(0x7fe2c208a768) id=2 global id=1 T start=0xffffffffffffffff
  1(7698) DEBUG: tm [t_lookup.c:897]: t_reply_matching(): 
t_reply_matching: hash 65453 label 0 branch 0
  1(7698) DEBUG: tm [t_lookup.c:951]: t_reply_matching(): reply 
(0x7fe2c208a768) matched an active transaction (T=0x7fe2bd0c76d8)!
  1(7698) DEBUG: tm [t_lookup.c:1088]: t_check_msg(): msg 
(0x7fe2c208a768) id=2 global id=2 T end=0x7fe2bd0c76d8
  1(7698) DEBUG: tm [t_reply.c:2209]: reply_received(): org. status 
uas=100, uac[0]=0 local=0 is_invite=1)
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:183]: get_hdr_field(): 
content_length=0
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): 
found end of header
  1(7698) INFO: <script>: LAL
  1(7698) DEBUG: tm [t_reply.c:1265]: t_should_relay_response(): 
->>>>>>>>> T_code=100, new_code=100
  1(7698) DEBUG: tm [t_reply.c:1788]: relay_reply(): branch=0, save=0, 
relay=-1 icode=0
  1(7698) DEBUG: <core> [core/receive.c:362]: receive_msg(): reply-route 
executed in: 118 usec
  1(7698) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  1(7698) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  1(7698) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  1(7698) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  1(7698) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  1(7698) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  1(7698) DEBUG: <core> [core/xavp.c:446]: xavp_destroy_list(): 
destroying xavp list (nil)
  1(7698) DEBUG: <core> [core/receive.c:378]: receive_msg(): cleaning up
  1(7698) DEBUG: <core> [core/udp_server.c:492]: udp_rcv_loop(): 
received on udp socket: (106/100/479) [[SIP/2.0 302 Moved Temporarily 
0D  0A Via: SIP/2.0/UDP 
52.88.180.226:5069;branch=z9hG4bKdaff.8f25665e8c867e]]
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:614]: parse_msg(): SIP 
Reply  (status):
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:616]: parse_msg():  
version: <SIP/2.0>
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:618]: parse_msg():  
status:  <302>
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:620]: parse_msg():  
reason:  <Moved Temporarily>
  1(7698) DEBUG: <core> [core/parser/parse_via.c:1303]: 
parse_via_param(): Found param type 232, <branch> = 
<z9hG4bKdaff.8f25665e8c867e73b07da3cb1f702171.0>; state=9
  1(7698) DEBUG: <core> [core/parser/parse_via.c:2681]: parse_via(): 
parsing via: next via
  1(7698) DEBUG: <core> [core/parser/parse_via.c:1303]: 
parse_via_param(): Found param type 232, <branch> = <z9hG4bK-8173-1-0>; 
state=16
  1(7698) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end 
of header reached, state=5
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:492]: parse_headers(): 
Via found, flags=2
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:494]: parse_headers(): 
this is the first via
  1(7698) DEBUG: <core> [core/parser/parse_addr_spec.c:185]: 
parse_to_param(): add param: tag=3
  1(7698) DEBUG: <core> [core/parser/parse_addr_spec.c:864]: 
parse_addr_spec(): end of header reached, state=29
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): 
<To> [50]; uri=[sip:34606147628(a)10.100.10.67:5069]
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): 
to body ["Javi" <sip:34606147628(a)10.100.10.67:5069>]
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): 
cseq <CSeq>: <1> <INVITE>
  1(7698) DEBUG: <core> [core/receive.c:205]: receive_msg(): --- 
received sip message - reply - call-id: [1-8173(a)10.100.10.67] - cseq: [1 
INVITE]
  1(7698) DEBUG: tm [t_lookup.c:1019]: t_check_msg(): msg 
(0x7fe2c208a768) id=3 global id=2 T start=0xffffffffffffffff
  1(7698) DEBUG: tm [t_lookup.c:897]: t_reply_matching(): 
t_reply_matching: hash 65453 label 0 branch 0
  1(7698) DEBUG: tm [t_lookup.c:951]: t_reply_matching(): reply 
(0x7fe2c208a768) matched an active transaction (T=0x7fe2bd0c76d8)!
  1(7698) DEBUG: tm [t_lookup.c:1088]: t_check_msg(): msg 
(0x7fe2c208a768) id=3 global id=3 T end=0x7fe2bd0c76d8
  1(7698) DEBUG: tm [t_reply.c:2209]: reply_received(): org. status 
uas=100, uac[0]=100 local=0 is_invite=1)
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:183]: get_hdr_field(): 
content_length=63
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): 
found end of header
  1(7698) INFO: <script>: LAL 
{"sdp_data":"3466666666","sdp_data_2":null,"nrn":null}

  1(7698) DEBUG: tm [t_reply.c:1265]: t_should_relay_response(): 
->>>>>>>>> T_code=100, new_code=302
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:614]: parse_msg(): SIP 
Reply  (status):
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:616]: parse_msg():  
version: <SIP/2.0>
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:618]: parse_msg():  
status:  <302>
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:620]: parse_msg():  
reason:  <Moved Temporarily>
  1(7698) DEBUG: <core> [core/parser/parse_via.c:1303]: 
parse_via_param(): Found param type 232, <branch> = 
<z9hG4bKdaff.8f25665e8c867e73b07da3cb1f702171.0>; state=9
  1(7698) DEBUG: <core> [core/parser/parse_via.c:2681]: parse_via(): 
parsing via: next via
  1(7698) DEBUG: <core> [core/parser/parse_via.c:1303]: 
parse_via_param(): Found param type 232, <branch> = <z9hG4bK-8173-1-0>; 
state=16
  1(7698) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end 
of header reached, state=5
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:492]: parse_headers(): 
Via found, flags=2
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:494]: parse_headers(): 
this is the first via
  1(7698) DEBUG: <core> [core/parser/parse_addr_spec.c:185]: 
parse_to_param(): add param: tag=3
  1(7698) DEBUG: <core> [core/parser/parse_addr_spec.c:864]: 
parse_addr_spec(): end of header reached, state=29
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): 
<To> [50]; uri=[sip:34606147628(a)10.100.10.67:5069]
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): 
to body ["Javi" <sip:34606147628(a)10.100.10.67:5069>]
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): 
cseq <CSeq>: <1> <INVITE>
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:183]: get_hdr_field(): 
content_length=63
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): 
found end of header
  1(7698) INFO: <script>: LOOOOOOOOL 
{"sdp_data":"3466666666","sdp_data_2":null,"nrn":null}

  1(7698) DEBUG: tm [t_lookup.c:1019]: t_check_msg(): msg 
(0x7fe2bd0ca850) id=0 global id=0 T start=0x7fe2bd0c76d8
  1(7698) DEBUG: tm [t_lookup.c:1091]: t_check_msg(): T (0x7fe2bd0c76d8) 
already found for msg (0x7fe2bd0ca850)!
  1(7698) DEBUG: tmx [t_var.c:534]: pv_get_tm_reply_code(): reply code 
is <302>
  1(7698) INFO: <script>: Call: 302 received, trying to load contacts
  1(7698) DEBUG: uac_redirect [rd_funcs.c:72]: get_redirect(): resume 
branch=0
  1(7698) DEBUG: uac_redirect [rd_funcs.c:79]: get_redirect(): checking 
branch=0 (added=0)
  1(7698) DEBUG: uac_redirect [rd_funcs.c:83]: get_redirect(): branch=0 
is a redirect (added=0)
  1(7698) DEBUG: uac_redirect [rd_funcs.c:159]: sort_contacts(): 
sort_contacts: <sip:34666988297(a)10.100.10.67:5060> q=10
  1(7698) DEBUG: uac_redirect [rd_funcs.c:295]: shmcontact2dset(): 
adding contact <sip:34666988297(a)10.100.10.67:5060>
  1(7698) DEBUG: <core> [sruid.c:183]: sruid_next(): new sruid is 
[rdir-5be42212-1e12-1] (1 / 20)
  1(7698) DEBUG: tm [t_serial.c:191]: ki_t_load_contacts(): nr_branches is 1
  1(7698) DEBUG: tm [t_serial.c:194]: ki_t_load_contacts(): nothing to 
do - only one contact!
  1(7698) INFO: <script>: LEL
  1(7698) DEBUG: <core> [core/msg_translator.c:159]: 
check_via_address(): (10.100.10.67, 10.100.10.67, 0)
  1(7698) INFO: <script>: hereeeeeeeeeee
  1(7698) DEBUG: tm [t_reply.c:1788]: relay_reply(): branch=0, save=0, 
relay=-1 icode=0
  1(7698) DEBUG: <core> [core/receive.c:362]: receive_msg(): reply-route 
executed in: 581 usec
  1(7698) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  1(7698) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  1(7698) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  1(7698) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  1(7698) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  1(7698) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  1(7698) DEBUG: <core> [core/xavp.c:446]: xavp_destroy_list(): 
destroying xavp list (nil)
  1(7698) DEBUG: <core> [core/receive.c:378]: receive_msg(): cleaning up
  1(7698) DEBUG: <core> [core/udp_server.c:492]: udp_rcv_loop(): 
received on udp socket: (106/100/397) [[SIP/2.0 100 Trying 0D  0A Via: 
SIP/2.0/UDP 
52.88.180.226:5069;branch=z9hG4bKdaff.8f25665e8c867e73b07da3cb1]]
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:614]: parse_msg(): SIP 
Reply  (status):
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:616]: parse_msg():  
version: <SIP/2.0>
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:618]: parse_msg():  
status:  <100>
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:620]: parse_msg():  
reason:  <Trying>
  1(7698) DEBUG: <core> [core/parser/parse_via.c:1303]: 
parse_via_param(): Found param type 232, <branch> = 
<z9hG4bKdaff.8f25665e8c867e73b07da3cb1f702171.1>; state=9
  1(7698) DEBUG: <core> [core/parser/parse_via.c:2681]: parse_via(): 
parsing via: next via
  1(7698) DEBUG: <core> [core/parser/parse_via.c:1303]: 
parse_via_param(): Found param type 232, <branch> = <z9hG4bK-8173-1-0>; 
state=16
  1(7698) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end 
of header reached, state=5
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:492]: parse_headers(): 
Via found, flags=2
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:494]: parse_headers(): 
this is the first via
  1(7698) DEBUG: <core> [core/parser/parse_addr_spec.c:864]: 
parse_addr_spec(): end of header reached, state=10
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): 
<To> [44]; uri=[sip:34606147628(a)10.100.10.67:5069]
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): 
to body ["Javi" <sip:34606147628(a)10.100.10.67:5069>
]
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): 
cseq <CSeq>: <1> <INVITE>
  1(7698) DEBUG: <core> [core/receive.c:205]: receive_msg(): --- 
received sip message - reply - call-id: [1-8173(a)10.100.10.67] - cseq: [1 
INVITE]
  1(7698) DEBUG: tm [t_lookup.c:1019]: t_check_msg(): msg 
(0x7fe2c208a768) id=4 global id=3 T start=0xffffffffffffffff
  1(7698) DEBUG: tm [t_lookup.c:897]: t_reply_matching(): 
t_reply_matching: hash 65453 label 0 branch 1
  1(7698) DEBUG: tm [t_lookup.c:951]: t_reply_matching(): reply 
(0x7fe2c208a768) matched an active transaction (T=0x7fe2bd0c76d8)!
  1(7698) DEBUG: tm [t_lookup.c:1088]: t_check_msg(): msg 
(0x7fe2c208a768) id=4 global id=4 T end=0x7fe2bd0c76d8
  1(7698) DEBUG: tm [t_reply.c:2209]: reply_received(): org. status 
uas=100, uac[1]=0 local=0 is_invite=1)
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:183]: get_hdr_field(): 
content_length=0
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): 
found end of header
  1(7698) INFO: <script>: LAL
  1(7698) DEBUG: tm [t_reply.c:1265]: t_should_relay_response(): 
->>>>>>>>> T_code=100, new_code=100
  1(7698) DEBUG: tm [t_reply.c:1788]: relay_reply(): branch=1, save=0, 
relay=-1 icode=0
  1(7698) DEBUG: <core> [core/receive.c:362]: receive_msg(): reply-route 
executed in: 38 usec
  1(7698) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  1(7698) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  1(7698) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  1(7698) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  1(7698) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  1(7698) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  1(7698) DEBUG: <core> [core/xavp.c:446]: xavp_destroy_list(): 
destroying xavp list (nil)
  1(7698) DEBUG: <core> [core/receive.c:378]: receive_msg(): cleaning up
  1(7698) DEBUG: <core> [core/udp_server.c:492]: udp_rcv_loop(): 
received on udp socket: (106/100/482) [[SIP/2.0 503 Service Unavailable 
0D  0A Via: SIP/2.0/UDP 52.88.180.226:5069;branch=z9hG4bKdaff.8f25665e8c86]]
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:614]: parse_msg(): SIP 
Reply  (status):
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:616]: parse_msg():  
version: <SIP/2.0>
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:618]: parse_msg():  
status:  <503>
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:620]: parse_msg():  
reason:  <Service Unavailable>
  1(7698) DEBUG: <core> [core/parser/parse_via.c:1303]: 
parse_via_param(): Found param type 232, <branch> = 
<z9hG4bKdaff.8f25665e8c867e73b07da3cb1f702171.1>; state=9
  1(7698) DEBUG: <core> [core/parser/parse_via.c:2681]: parse_via(): 
parsing via: next via
  1(7698) DEBUG: <core> [core/parser/parse_via.c:1303]: 
parse_via_param(): Found param type 232, <branch> = <z9hG4bK-8173-1-0>; 
state=16
  1(7698) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end 
of header reached, state=5
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:492]: parse_headers(): 
Via found, flags=2
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:494]: parse_headers(): 
this is the first via
  1(7698) DEBUG: <core> [core/parser/parse_addr_spec.c:185]: 
parse_to_param(): add param: tag=3
  1(7698) DEBUG: <core> [core/parser/parse_addr_spec.c:864]: 
parse_addr_spec(): end of header reached, state=29
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): 
<To> [50]; uri=[sip:34606147628(a)10.100.10.67:5069]
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): 
to body ["Javi" <sip:34606147628(a)10.100.10.67:5069>]
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): 
cseq <CSeq>: <1> <INVITE>
  1(7698) DEBUG: <core> [core/receive.c:205]: receive_msg(): --- 
received sip message - reply - call-id: [1-8173(a)10.100.10.67] - cseq: [1 
INVITE]
  1(7698) DEBUG: tm [t_lookup.c:1019]: t_check_msg(): msg 
(0x7fe2c208a768) id=5 global id=4 T start=0xffffffffffffffff
  1(7698) DEBUG: tm [t_lookup.c:897]: t_reply_matching(): 
t_reply_matching: hash 65453 label 0 branch 1
  1(7698) DEBUG: tm [t_lookup.c:951]: t_reply_matching(): reply 
(0x7fe2c208a768) matched an active transaction (T=0x7fe2bd0c76d8)!
  1(7698) DEBUG: tm [t_lookup.c:1088]: t_check_msg(): msg 
(0x7fe2c208a768) id=5 global id=5 T end=0x7fe2bd0c76d8
  1(7698) DEBUG: tm [t_reply.c:2209]: reply_received(): org. status 
uas=100, uac[1]=100 local=0 is_invite=1)
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:183]: get_hdr_field(): 
content_length=64
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): 
found end of header
  1(7698) INFO: <script>: LAL 
{"sdp_data":"34619796636","sdp_data_2":null,"nrn":null}

  1(7698) DEBUG: tm [t_reply.c:1265]: t_should_relay_response(): 
->>>>>>>>> T_code=100, new_code=503
  1(7698) INFO: <script>: LOOOOOOOOL 
{"sdp_data":"3466666666","sdp_data_2":null,"nrn":null}

  1(7698) DEBUG: tm [t_lookup.c:1019]: t_check_msg(): msg 
(0x7fe2bd0cbb88) id=0 global id=0 T start=0x7fe2bd0c76d8
  1(7698) DEBUG: tm [t_lookup.c:1091]: t_check_msg(): T (0x7fe2bd0c76d8) 
already found for msg (0x7fe2bd0cbb88)!
  1(7698) DEBUG: tmx [t_var.c:534]: pv_get_tm_reply_code(): reply code 
is <503>
  1(7698) DEBUG: tm [t_lookup.c:1019]: t_check_msg(): msg 
(0x7fe2bd0cbb88) id=0 global id=0 T start=0x7fe2bd0c76d8
  1(7698) DEBUG: tm [t_lookup.c:1091]: t_check_msg(): T (0x7fe2bd0c76d8) 
already found for msg (0x7fe2bd0cbb88)!
  1(7698) DEBUG: tmx [t_var.c:534]: pv_get_tm_reply_code(): reply code 
is <503>
  1(7698) INFO: <script>: LEL
  1(7698) DEBUG: <core> [core/msg_translator.c:159]: 
check_via_address(): (10.100.10.67, 10.100.10.67, 0)
  1(7698) INFO: <script>: hereeeeeeeeeee
  1(7698) DEBUG: tm [t_reply.c:1788]: relay_reply(): branch=1, save=0, 
relay=-1 icode=0
  1(7698) DEBUG: <core> [core/receive.c:362]: receive_msg(): reply-route 
executed in: 188 usec
  1(7698) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  1(7698) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  1(7698) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  1(7698) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  1(7698) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  1(7698) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  1(7698) DEBUG: <core> [core/xavp.c:446]: xavp_destroy_list(): 
destroying xavp list (nil)
  1(7698) DEBUG: <core> [core/receive.c:378]: receive_msg(): cleaning up
  1(7698) DEBUG: <core> [core/udp_server.c:492]: udp_rcv_loop(): 
received on udp socket: (106/100/404) [[SIP/2.0 180 Ringing 0D  0A Via: 
SIP/2.0/UDP 52.88.180.226:5069;branch=z9hG4bKdaff.8f25665e8c867e73b07da3cb]]
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:614]: parse_msg(): SIP 
Reply  (status):
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:616]: parse_msg():  
version: <SIP/2.0>
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:618]: parse_msg():  
status:  <180>
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:620]: parse_msg():  
reason:  <Ringing>
  1(7698) DEBUG: <core> [core/parser/parse_via.c:1303]: 
parse_via_param(): Found param type 232, <branch> = 
<z9hG4bKdaff.8f25665e8c867e73b07da3cb1f702171.2>; state=9
  1(7698) DEBUG: <core> [core/parser/parse_via.c:2681]: parse_via(): 
parsing via: next via
  1(7698) DEBUG: <core> [core/parser/parse_via.c:1303]: 
parse_via_param(): Found param type 232, <branch> = <z9hG4bK-8173-1-0>; 
state=16
  1(7698) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end 
of header reached, state=5
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:492]: parse_headers(): 
Via found, flags=2
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:494]: parse_headers(): 
this is the first via
  1(7698) DEBUG: <core> [core/parser/parse_addr_spec.c:185]: 
parse_to_param(): add param: tag=3
  1(7698) DEBUG: <core> [core/parser/parse_addr_spec.c:864]: 
parse_addr_spec(): end of header reached, state=29
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): 
<To> [50]; uri=[sip:34606147628(a)10.100.10.67:5069]
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): 
to body ["Javi" <sip:34606147628(a)10.100.10.67:5069>]
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): 
cseq <CSeq>: <1> <INVITE>
  1(7698) DEBUG: <core> [core/receive.c:205]: receive_msg(): --- 
received sip message - reply - call-id: [1-8173(a)10.100.10.67] - cseq: [1 
INVITE]
  1(7698) DEBUG: tm [t_lookup.c:1019]: t_check_msg(): msg 
(0x7fe2c208a768) id=6 global id=5 T start=0xffffffffffffffff
  1(7698) DEBUG: tm [t_lookup.c:897]: t_reply_matching(): 
t_reply_matching: hash 65453 label 0 branch 2
  1(7698) DEBUG: tm [t_lookup.c:951]: t_reply_matching(): reply 
(0x7fe2c208a768) matched an active transaction (T=0x7fe2bd0c76d8)!
  1(7698) DEBUG: tm [t_lookup.c:1088]: t_check_msg(): msg 
(0x7fe2c208a768) id=6 global id=6 T end=0x7fe2bd0c76d8
  1(7698) DEBUG: tm [t_reply.c:2209]: reply_received(): org. status 
uas=100, uac[2]=0 local=0 is_invite=1)
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:183]: get_hdr_field(): 
content_length=0
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): 
found end of header
  1(7698) INFO: <script>: LAL
  1(7698) DEBUG: tm [t_reply.c:1265]: t_should_relay_response(): 
->>>>>>>>> T_code=100, new_code=180
  1(7698) DEBUG: tm [t_reply.c:1788]: relay_reply(): branch=2, save=0, 
relay=2 icode=0
  1(7698) DEBUG: <core> [core/msg_translator.c:2270]: 
generate_res_buf_from_sip_res(): old size: 404, new size: 318
  1(7698) DEBUG: <core> [core/msg_translator.c:2288]: 
generate_res_buf_from_sip_res(): copied size: orig:112, new: 26, rest: 
292 msg=
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 10.100.10.67:5061;branch=z9hG4bK-8173-1-0
From: "BTS" <sip:34917019888(a)10.100.10.67:5061>;tag=8173SIPpTag001
To: "Javi" <sip:34606147628(a)10.100.10.67:5069>;tag=3
Call-ID: 1-8173(a)10.100.10.67
CSeq: 1 INVITE
Contact: <sip:10.100.10.67:5060;transport=UDP>
Content-Length: 0


  1(7698) DEBUG: <core> [core/receive.c:362]: receive_msg(): reply-route 
executed in: 93 usec
  1(7698) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  1(7698) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  1(7698) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  1(7698) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  1(7698) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  1(7698) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  1(7698) DEBUG: <core> [core/xavp.c:446]: xavp_destroy_list(): 
destroying xavp list (nil)
  1(7698) DEBUG: <core> [core/receive.c:378]: receive_msg(): cleaning up
  1(7698) DEBUG: <core> [core/udp_server.c:492]: udp_rcv_loop(): 
received on udp socket: (106/100/595) [[SIP/2.0 200 OK 0D  0A Via: 
SIP/2.0/UDP 
52.88.180.226:5069;branch=z9hG4bKdaff.8f25665e8c867e73b07da3cb1f702]]
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:614]: parse_msg(): SIP 
Reply  (status):
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:616]: parse_msg():  
version: <SIP/2.0>
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:618]: parse_msg():  
status:  <200>
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:620]: parse_msg():  
reason:  <OK>
  1(7698) DEBUG: <core> [core/parser/parse_via.c:1303]: 
parse_via_param(): Found param type 232, <branch> = 
<z9hG4bKdaff.8f25665e8c867e73b07da3cb1f702171.2>; state=9
  1(7698) DEBUG: <core> [core/parser/parse_via.c:2681]: parse_via(): 
parsing via: next via
  1(7698) DEBUG: <core> [core/parser/parse_via.c:1303]: 
parse_via_param(): Found param type 232, <branch> = <z9hG4bK-8173-1-0>; 
state=16
  1(7698) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end 
of header reached, state=5
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:492]: parse_headers(): 
Via found, flags=2
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:494]: parse_headers(): 
this is the first via
  1(7698) DEBUG: <core> [core/parser/parse_addr_spec.c:185]: 
parse_to_param(): add param: tag=3
  1(7698) DEBUG: <core> [core/parser/parse_addr_spec.c:864]: 
parse_addr_spec(): end of header reached, state=29
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): 
<To> [50]; uri=[sip:34606147628(a)10.100.10.67:5069]
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): 
to body ["Javi" <sip:34606147628(a)10.100.10.67:5069>]
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): 
cseq <CSeq>: <1> <INVITE>
  1(7698) DEBUG: <core> [core/receive.c:205]: receive_msg(): --- 
received sip message - reply - call-id: [1-8173(a)10.100.10.67] - cseq: [1 
INVITE]
  1(7698) DEBUG: tm [t_lookup.c:1019]: t_check_msg(): msg 
(0x7fe2c208a768) id=7 global id=6 T start=0xffffffffffffffff
  1(7698) DEBUG: tm [t_lookup.c:897]: t_reply_matching(): 
t_reply_matching: hash 65453 label 0 branch 2
  1(7698) DEBUG: tm [t_lookup.c:951]: t_reply_matching(): reply 
(0x7fe2c208a768) matched an active transaction (T=0x7fe2bd0c76d8)!
  1(7698) DEBUG: tm [t_lookup.c:1088]: t_check_msg(): msg 
(0x7fe2c208a768) id=7 global id=7 T end=0x7fe2bd0c76d8
  1(7698) DEBUG: tm [t_reply.c:2209]: reply_received(): org. status 
uas=180, uac[2]=180 local=0 is_invite=1)
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:183]: get_hdr_field(): 
content_length=161
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): 
found end of header
  1(7698) INFO: <script>: LAL v=0
o=user1 53655765 2353687637 IN IP4 10.100.10.67
s=-
c=IN IP4 10.100.10.67
t=0 0
m=audio 6000 RTP/AVP 0 18
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000

  1(7698) DEBUG: tm [t_reply.c:1265]: t_should_relay_response(): 
->>>>>>>>> T_code=180, new_code=200
  1(7698) DEBUG: tm [t_reply.c:1788]: relay_reply(): branch=2, save=0, 
relay=2 icode=0
  1(7698) DEBUG: <core> [core/msg_translator.c:2270]: 
generate_res_buf_from_sip_res(): old size: 595, new size: 509
  1(7698) DEBUG: <core> [core/msg_translator.c:2288]: 
generate_res_buf_from_sip_res(): copied size: orig:107, new: 21, rest: 
488 msg=
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.100.10.67:5061;branch=z9hG4bK-8173-1-0
From: "BTS" <sip:34917019888(a)10.100.10.67:5061>;tag=8173SIPpTag001
To: "Javi" <sip:34606147628(a)10.100.10.67:5069>;tag=3
Call-ID: 1-8173(a)10.100.10.67
CSeq: 1 INVITE
Contact: <sip:10.100.10.67:5060;transport=UDP>
Content-Type: application/sdp
Content-Length:   161

v=0
o=user1 53655765 2353687637 IN IP4 10.100.10.67
s=-
c=IN IP4 10.100.10.67
t=0 0
m=audio 6000 RTP/AVP 0 18
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000

  1(7698) DEBUG: tm [t_reply.c:1631]: cleanup_uac_timers(): RETR/FR 
timers reset
  1(7698) DEBUG: <core> [core/receive.c:362]: receive_msg(): reply-route 
executed in: 185 usec
  1(7698) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  1(7698) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  1(7698) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  1(7698) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  1(7698) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  1(7698) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  1(7698) DEBUG: <core> [core/xavp.c:446]: xavp_destroy_list(): 
destroying xavp list (nil)
  1(7698) DEBUG: <core> [core/receive.c:378]: receive_msg(): cleaning up
  1(7698) DEBUG: <core> [core/udp_server.c:492]: udp_rcv_loop(): 
received on udp socket: (106/100/323) [[ACK 
sip:34606147628(a)10.100.10.67:5060 SIP/2.0 0D  0A Via: SIP/2.0/UDP 
10.100.10.67:5061;branch=z9hG4bK-817]]
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:604]: parse_msg(): SIP 
Request:
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:606]: parse_msg():  
method:  <ACK>
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:608]: parse_msg():  
uri:     <sip:34606147628(a)10.100.10.67:5060>
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:610]: parse_msg():  
version: <SIP/2.0>
  1(7698) DEBUG: <core> [core/parser/parse_via.c:1303]: 
parse_via_param(): Found param type 232, <branch> = <z9hG4bK-8173-1-0>; 
state=16
  1(7698) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end 
of header reached, state=5
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:492]: parse_headers(): 
Via found, flags=2
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:494]: parse_headers(): 
this is the first via
  1(7698) DEBUG: <core> [core/parser/parse_addr_spec.c:185]: 
parse_to_param(): add param: tag=3
  1(7698) DEBUG: <core> [core/parser/parse_addr_spec.c:864]: 
parse_addr_spec(): end of header reached, state=29
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): 
<To> [50]; uri=[sip:34606147628(a)10.100.10.67:5069]
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): 
to body ["Test" <sip:34606147628(a)10.100.10.67:5069>]
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): 
cseq <CSeq>: <1> <ACK>
  1(7698) DEBUG: <core> [core/receive.c:205]: receive_msg(): --- 
received sip message - request - call-id: [1-8173(a)10.100.10.67] - cseq: 
[1 ACK]
  1(7698) DEBUG: <core> [core/receive.c:248]: receive_msg(): preparing 
to run routing scripts...
  1(7698) DEBUG: sl [sl_funcs.c:387]: sl_filter_ACK(): too late to be a 
local ACK!
  1(7698) INFO: <script>: hereeeeeeeeeee
  1(7698) DEBUG: tm [t_lookup.c:1320]: t_newtran(): msg id=8 , global 
msg id=7 , T on entrance=0xffffffffffffffff
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:183]: get_hdr_field(): 
content_length=0
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): 
found end of header
  1(7698) DEBUG: tm [t_lookup.c:477]: t_lookup_request(): start 
searching: hash=65453, isACK=1
  1(7698) DEBUG: tm [t_lookup.c:435]: matching_3261(): RFC3261 
transaction matching failed
  1(7698) DEBUG: tm [t_lookup.c:659]: t_lookup_request(): no transaction 
found
  1(7698) DEBUG: tm [t_funcs.c:284]: t_relay_to(): forwarding ACK 
statelessly
  1(7698) DEBUG: <core> [core/md5utils.c:67]: MD5StringArray(): MD5 
calculated: 8f25665e8c867e73b07da3cb1f702171
  1(7698) DEBUG: <core> [core/msg_translator.c:159]: 
check_via_address(): (10.100.10.67, 10.100.10.67, 0)
  1(7698) DEBUG: <core> [core/forward.c:557]: forward_request(): Sending:
ACK sip:34606147628(a)10.100.10.67:5060 SIP/2.0
Via: SIP/2.0/UDP 
52.88.180.226:5069;branch=z9hG4bKdaff.8f25665e8c867e73b07da3cb1f702171.0
Via: SIP/2.0/UDP 10.100.10.67:5061;branch=z9hG4bK-8173-1-0
From: "BTS" <sip:34917019888(a)10.100.10.67:5061>;tag=8173SIPpTag001
To: "Test" <sip:34606147628(a)10.100.10.67:5069>;tag=3
Call-ID: 1-8173(a)10.100.10.67
CSeq: 1 ACK
Max-Forwards: 70
Subject: 1
Content-Length: 0

.
  1(7698) DEBUG: <core> [core/forward.c:559]: forward_request(): orig. 
len=323, new_len=414, proto=1
  1(7698) INFO: <script>: hereeeeeeeeeee
  1(7698) DEBUG: <core> [core/receive.c:289]: receive_msg(): 
request-route executed in: 109 usec
  1(7698) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  1(7698) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  1(7698) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  1(7698) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  1(7698) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  1(7698) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  1(7698) DEBUG: <core> [core/xavp.c:446]: xavp_destroy_list(): 
destroying xavp list (nil)
  1(7698) DEBUG: <core> [core/receive.c:378]: receive_msg(): cleaning up
  1(7698) DEBUG: <core> [core/udp_server.c:492]: udp_rcv_loop(): 
received on udp socket: (106/100/338) [[BYE 
sip:34606147628(a)10.100.10.67:5060 SIP/2.0 0D  0A Via: SIP/2.0/UDP 
10.100.10.67:5061;branch=z9hG4bK-817]]
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:604]: parse_msg(): SIP 
Request:
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:606]: parse_msg():  
method:  <BYE>
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:608]: parse_msg():  
uri:     <sip:34606147628(a)10.100.10.67:5060>
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:610]: parse_msg():  
version: <SIP/2.0>
  1(7698) DEBUG: <core> [core/parser/parse_via.c:1303]: 
parse_via_param(): Found param type 232, <branch> = <z9hG4bK-8173-1-8>; 
state=16
  1(7698) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end 
of header reached, state=5
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:492]: parse_headers(): 
Via found, flags=2
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:494]: parse_headers(): 
this is the first via
  1(7698) DEBUG: <core> [core/parser/parse_addr_spec.c:185]: 
parse_to_param(): add param: tag=3
  1(7698) DEBUG: <core> [core/parser/parse_addr_spec.c:864]: 
parse_addr_spec(): end of header reached, state=29
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): 
<To> [50]; uri=[sip:34606147628(a)10.100.10.67:5069]
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): 
to body ["Test" <sip:34606147628(a)10.100.10.67:5069>]
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): 
cseq <CSeq>: <2> <BYE>
  1(7698) DEBUG: <core> [core/receive.c:205]: receive_msg(): --- 
received sip message - request - call-id: [1-8173(a)10.100.10.67] - cseq: 
[2 BYE]
  1(7698) DEBUG: <core> [core/receive.c:248]: receive_msg(): preparing 
to run routing scripts...
  1(7698) INFO: <script>: hereeeeeeeeeee
  1(7698) DEBUG: tm [t_lookup.c:1320]: t_newtran(): msg id=9 , global 
msg id=8 , T on entrance=(nil)
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:183]: get_hdr_field(): 
content_length=0
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): 
found end of header
  1(7698) DEBUG: tm [t_lookup.c:477]: t_lookup_request(): start 
searching: hash=65450, isACK=0
  1(7698) DEBUG: tm [t_lookup.c:435]: matching_3261(): RFC3261 
transaction matching failed
  1(7698) DEBUG: tm [t_lookup.c:659]: t_lookup_request(): no transaction 
found
  1(7698) DEBUG: <core> [core/md5utils.c:67]: MD5StringArray(): MD5 
calculated: 72541dabc2c0991bc1a987a58afe468a
  1(7698) INFO: <script>: LEL
  1(7698) DEBUG: <core> [core/msg_translator.c:159]: 
check_via_address(): (10.100.10.67, 10.100.10.67, 0)
  1(7698) INFO: <script>: hereeeeeeeeeee
  1(7698) DEBUG: tm [t_funcs.c:372]: t_relay_to(): new transaction forwarded
  1(7698) DEBUG: <core> [core/receive.c:289]: receive_msg(): 
request-route executed in: 223 usec
  1(7698) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  1(7698) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  1(7698) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  1(7698) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  1(7698) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  1(7698) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  1(7698) DEBUG: <core> [core/xavp.c:446]: xavp_destroy_list(): 
destroying xavp list (nil)
  1(7698) DEBUG: <core> [core/receive.c:378]: receive_msg(): cleaning up
  1(7698) DEBUG: <core> [core/udp_server.c:492]: udp_rcv_loop(): 
received on udp socket: (106/100/396) [[SIP/2.0 200 OK 0D  0A Via: 
SIP/2.0/UDP 
52.88.180.226:5069;branch=z9hG4bKaaff.72541dabc2c0991bc1a987a58afe4]]
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:614]: parse_msg(): SIP 
Reply  (status):
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:616]: parse_msg():  
version: <SIP/2.0>
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:618]: parse_msg():  
status:  <200>
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:620]: parse_msg():  
reason:  <OK>
  1(7698) DEBUG: <core> [core/parser/parse_via.c:1303]: 
parse_via_param(): Found param type 232, <branch> = 
<z9hG4bKaaff.72541dabc2c0991bc1a987a58afe468a.0>; state=9
  1(7698) DEBUG: <core> [core/parser/parse_via.c:2681]: parse_via(): 
parsing via: next via
  1(7698) DEBUG: <core> [core/parser/parse_via.c:1303]: 
parse_via_param(): Found param type 232, <branch> = <z9hG4bK-8173-1-8>; 
state=16
  1(7698) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end 
of header reached, state=5
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:492]: parse_headers(): 
Via found, flags=2
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:494]: parse_headers(): 
this is the first via
  1(7698) DEBUG: <core> [core/parser/parse_addr_spec.c:185]: 
parse_to_param(): add param: tag=3
  1(7698) DEBUG: <core> [core/parser/parse_addr_spec.c:864]: 
parse_addr_spec(): end of header reached, state=29
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): 
<To> [50]; uri=[sip:34606147628(a)10.100.10.67:5069]
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): 
to body ["Test" <sip:34606147628(a)10.100.10.67:5069>]
  1(7698) DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): 
cseq <CSeq>: <2> <BYE>
  1(7698) DEBUG: <core> [core/receive.c:205]: receive_msg(): --- 
received sip message - reply - call-id: [1-8173(a)10.100.10.67] - cseq: [2 
BYE]
  1(7698) DEBUG: tm [t_lookup.c:1019]: t_check_msg(): msg 
(0x7fe2c208a768) id=10 global id=9 T start=0xffffffffffffffff
  1(7698) DEBUG: tm [t_lookup.c:897]: t_reply_matching(): 
t_reply_matching: hash 65450 label 0 branch 0
  1(7698) DEBUG: tm [t_lookup.c:951]: t_reply_matching(): reply 
(0x7fe2c208a768) matched an active transaction (T=0x7fe2bd0ccd40)!
  1(7698) DEBUG: tm [t_lookup.c:1088]: t_check_msg(): msg 
(0x7fe2c208a768) id=10 global id=10 T end=0x7fe2bd0ccd40
  1(7698) DEBUG: tm [t_reply.c:2209]: reply_received(): org. status 
uas=0, uac[0]=0 local=0 is_invite=0)
  1(7698) DEBUG: tm [t_reply.c:1265]: t_should_relay_response(): 
->>>>>>>>> T_code=0, new_code=200
  1(7698) DEBUG: tm [t_reply.c:1788]: relay_reply(): branch=0, save=0, 
relay=0 icode=0
  1(7698) DEBUG: <core> [core/msg_translator.c:2270]: 
generate_res_buf_from_sip_res(): old size: 396, new size: 310
  1(7698) DEBUG: <core> [core/msg_translator.c:2288]: 
generate_res_buf_from_sip_res(): copied size: orig:107, new: 21, rest: 
289 msg=
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.100.10.67:5061;branch=z9hG4bK-8173-1-8
From: "BTS" <sip:34917019888(a)10.100.10.67:5061>;tag=8173SIPpTag001
To: "Test" <sip:34606147628(a)10.100.10.67:5069>;tag=3
Call-ID: 1-8173(a)10.100.10.67
CSeq: 2 BYE
Contact: <sip:10.100.10.67:5060;transport=UDP>
Content-Length: 0


  1(7698) DEBUG: tm [t_reply.c:1631]: cleanup_uac_timers(): RETR/FR 
timers reset
  1(7698) DEBUG: <core> [core/receive.c:362]: receive_msg(): reply-route 
executed in: 74 usec
  1(7698) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  1(7698) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  1(7698) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  1(7698) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  1(7698) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  1(7698) DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): 
destroying list (nil)
  1(7698) DEBUG: <core> [core/xavp.c:446]: xavp_destroy_list(): 
destroying xavp list (nil)
  1(7698) DEBUG: <core> [core/receive.c:378]: receive_msg(): cleaning up
  3(7700) DEBUG: tm [h_table.c:129]: free_cell_helper(): freeing 
transaction 0x7fe2bd0c76d8 from timer.c:654
  3(7700) DEBUG: tm [h_table.c:129]: free_cell_helper(): freeing 
transaction 0x7fe2bd0ccd40 from timer.c:654




--===============1349260945==--