Ah, wait. I missed the fact that this only fails to work with multiple PIDs. You don't have your branch failover mode overridden, do you?

-- Sent from mobile. Apologies for brevity and errors.

-----Original Message----- From: Alex Balashov abalashov@evaristesys.com To: "David Escartín" descartin@sonoc.io, "Kamailio (SER) - Users Mailing List" sr-users@lists.kamailio.org Cc: Javi Gallart jgallart@bts.io Sent: Thu, 08 Nov 2018 11:46 AM Subject: Re: [SR-Users] variable $rb not updated on failure route after a 302 on the same PID

Hi,

Unlike onreply_routes, failure_routes do not directly correspond to a discrete SIP reply, because a SIP reply is only one of the things that can cause a failure_route to trigger. Other possibilities include a branch timeout, and possibly some other errors of an internal nature.

In other words, a failure_route is a bit more abstract than an onreply_route. So, in order to get the message attributes of a reply, you need to specify exactly which reply you want to access; this is usually the winning reply of the last branch attempted.

Or, to be more concrete and less pedagogic, try: $T_rpl($rb)

https://www.kamailio.org/wiki/cookbooks/5.1.x/pseudovariables#t_rpl_pv

-- Alex

On Thu, Nov 08, 2018 at 01:22:14PM +0100, David Escartín wrote:

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@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@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@10.100.10.67:5069] 11(8358) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body ["Javi" sip:34606147628@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@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@10.100.10.67:5069] 11(8358) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body ["Javi" sip:34606147628@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@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@10.100.10.67:5069] 13(8360) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body ["Javi" sip:34606147628@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@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@10.100.10.67:5069] 13(8360) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body ["Javi" sip:34606147628@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@10.100.10.67:5060 q=10 13(8360) DEBUG: uac_redirect [rd_funcs.c:295]: shmcontact2dset(): adding contact sip:34666988297@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@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@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@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@10.100.10.67:5069] 15(8362) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body ["Javi" sip:34606147628@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@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@10.100.10.67:5069] 15(8362) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body ["Javi" sip:34606147628@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@10.100.10.67:5069] 15(8362) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body ["Javi" sip:34606147628@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@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@10.100.10.67:5061;tag=9680SIPpTag001 To: "Javi" sip:34606147628@10.100.10.67:5069;tag=5 Call-ID: 1-9680@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@10.100.10.67:5069] 6(8353) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body ["Javi" sip:34606147628@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@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@10.100.10.67:5061;tag=9680SIPpTag001 To: "Javi" sip:34606147628@10.100.10.67:5069;tag=5 Call-ID: 1-9680@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@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@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@10.100.10.67:5069] 6(8353) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body ["Test" sip:34606147628@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@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@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@10.100.10.67:5061;tag=9680SIPpTag001 To: "Test" sip:34606147628@10.100.10.67:5069;tag=5 Call-ID: 1-9680@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@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@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@10.100.10.67:5069] 3(8350) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body ["Test" sip:34606147628@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@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@10.100.10.67:5069] 7(8354) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body ["Test" sip:34606147628@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@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@10.100.10.67:5061;tag=9680SIPpTag001 To: "Test" sip:34606147628@10.100.10.67:5069;tag=5 Call-ID: 1-9680@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@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@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@10.100.10.67:5069] 1(7698) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body ["Javi" sip:34606147628@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@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@10.100.10.67:5069] 1(7698) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body ["Javi" sip:34606147628@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@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@10.100.10.67:5069] 1(7698) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body ["Javi" sip:34606147628@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@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@10.100.10.67:5069] 1(7698) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body ["Javi" sip:34606147628@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@10.100.10.67:5060 q=10 1(7698) DEBUG: uac_redirect [rd_funcs.c:295]: shmcontact2dset(): adding contact sip:34666988297@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@10.100.10.67:5069] 1(7698) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body ["Javi" sip:34606147628@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@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@10.100.10.67:5069] 1(7698) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body ["Javi" sip:34606147628@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@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@10.100.10.67:5069] 1(7698) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body ["Javi" sip:34606147628@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@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@10.100.10.67:5061;tag=8173SIPpTag001 To: "Javi" sip:34606147628@10.100.10.67:5069;tag=3 Call-ID: 1-8173@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@10.100.10.67:5069] 1(7698) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body ["Javi" sip:34606147628@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@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@10.100.10.67:5061;tag=8173SIPpTag001 To: "Javi" sip:34606147628@10.100.10.67:5069;tag=3 Call-ID: 1-8173@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@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@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@10.100.10.67:5069] 1(7698) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body ["Test" sip:34606147628@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@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@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@10.100.10.67:5061;tag=8173SIPpTag001 To: "Test" sip:34606147628@10.100.10.67:5069;tag=3 Call-ID: 1-8173@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@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@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@10.100.10.67:5069] 1(7698) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body ["Test" sip:34606147628@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@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@10.100.10.67:5069] 1(7698) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body ["Test" sip:34606147628@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@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@10.100.10.67:5061;tag=8173SIPpTag001 To: "Test" sip:34606147628@10.100.10.67:5069;tag=3 Call-ID: 1-8173@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

---

Kamailio (SER) - Users Mailing List sr-users@lists.kamailio.org https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users

Hello

sorry for the delay

Yes Daniel we see the incorrect value using $T_rpl($rb) on the failure_route.

Alex we actually see the issue when using the same PID for processing all the responses of the different branches.

Let me test the patch and i will let you know Daniel

best regards

david

On 13/11/18 9:07, Daniel-Constantin Mierla wrote:

Hello,

for clarification, it is actually the $T_rpl($rb) not giving the expected value, right? Not the pure $rb...

If yes, then can you try with the patch from the next commit:

* https://github.com/kamailio/kamailio/commit/e2ca5516ae086cf33c61dbb9e653a548...

When all ok, I will backport.

Cheers, Daniel

On 08.11.18 13:22, David Escartín wrote:

...

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@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@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@10.100.10.67:5069] 11(8358) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body ["Javi" sip:34606147628@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@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@10.100.10.67:5069] 11(8358) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body ["Javi" sip:34606147628@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@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@10.100.10.67:5069] 13(8360) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body ["Javi" sip:34606147628@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@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@10.100.10.67:5069] 13(8360) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body ["Javi" sip:34606147628@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@10.100.10.67:5060 q=10 13(8360) DEBUG: uac_redirect [rd_funcs.c:295]: shmcontact2dset(): adding contact sip:34666988297@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@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@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@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@10.100.10.67:5069] 15(8362) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body ["Javi" sip:34606147628@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@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@10.100.10.67:5069] 15(8362) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body ["Javi" sip:34606147628@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@10.100.10.67:5069] 15(8362) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body ["Javi" sip:34606147628@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@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@10.100.10.67:5061;tag=9680SIPpTag001 To: "Javi" sip:34606147628@10.100.10.67:5069;tag=5 Call-ID: 1-9680@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@10.100.10.67:5069]  6(8353) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body ["Javi" sip:34606147628@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@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@10.100.10.67:5061;tag=9680SIPpTag001 To: "Javi" sip:34606147628@10.100.10.67:5069;tag=5 Call-ID: 1-9680@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@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@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@10.100.10.67:5069]  6(8353) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body ["Test" sip:34606147628@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@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@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@10.100.10.67:5061;tag=9680SIPpTag001 To: "Test" sip:34606147628@10.100.10.67:5069;tag=5 Call-ID: 1-9680@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@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@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@10.100.10.67:5069]  3(8350) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body ["Test" sip:34606147628@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@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@10.100.10.67:5069]  7(8354) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body ["Test" sip:34606147628@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@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@10.100.10.67:5061;tag=9680SIPpTag001 To: "Test" sip:34606147628@10.100.10.67:5069;tag=5 Call-ID: 1-9680@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@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@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@10.100.10.67:5069]  1(7698) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body ["Javi" sip:34606147628@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@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@10.100.10.67:5069]  1(7698) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body ["Javi" sip:34606147628@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@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@10.100.10.67:5069]  1(7698) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body ["Javi" sip:34606147628@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@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@10.100.10.67:5069]  1(7698) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body ["Javi" sip:34606147628@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@10.100.10.67:5060 q=10  1(7698) DEBUG: uac_redirect [rd_funcs.c:295]: shmcontact2dset(): adding contact sip:34666988297@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@10.100.10.67:5069]  1(7698) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body ["Javi" sip:34606147628@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@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@10.100.10.67:5069]  1(7698) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body ["Javi" sip:34606147628@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@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@10.100.10.67:5069]  1(7698) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body ["Javi" sip:34606147628@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@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@10.100.10.67:5061;tag=8173SIPpTag001 To: "Javi" sip:34606147628@10.100.10.67:5069;tag=3 Call-ID: 1-8173@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@10.100.10.67:5069]  1(7698) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body ["Javi" sip:34606147628@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@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@10.100.10.67:5061;tag=8173SIPpTag001 To: "Javi" sip:34606147628@10.100.10.67:5069;tag=3 Call-ID: 1-8173@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@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@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@10.100.10.67:5069]  1(7698) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body ["Test" sip:34606147628@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@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@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@10.100.10.67:5061;tag=8173SIPpTag001 To: "Test" sip:34606147628@10.100.10.67:5069;tag=3 Call-ID: 1-8173@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@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@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@10.100.10.67:5069]  1(7698) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body ["Test" sip:34606147628@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@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@10.100.10.67:5069]  1(7698) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body ["Test" sip:34606147628@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@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@10.100.10.67:5061;tag=8173SIPpTag001 To: "Test" sip:34606147628@10.100.10.67:5069;tag=3 Call-ID: 1-8173@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

---

Kamailio (SER) - Users Mailing List sr-users@lists.kamailio.org https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users