[SR-Users] variable $rb not updated on failure route after a 302 on the same PID
David Escartín
descartin at bts.io
Tue Nov 13 13:36:12 CET 2018
hello Daniel
patch seems to be working ok, at least for the test i was making to
duplicate the issue, works OK!
best regards
david
On 13/11/18 13:06, David Escartín wrote:
> 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/e2ca5516ae086cf33c61dbb9e653a5484cca2074
>>
>>
>> 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 at 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 at 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 at 10.100.10.67:5069]
>>> 11(8358) DEBUG: <core> [core/parser/msg_parser.c:172]:
>>> get_hdr_field(): to body ["Javi" <sip:34606147628 at 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 at 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 at 10.100.10.67:5069]
>>> 11(8358) DEBUG: <core> [core/parser/msg_parser.c:172]:
>>> get_hdr_field(): to body ["Javi" <sip:34606147628 at 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 at 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 at 10.100.10.67:5069]
>>> 13(8360) DEBUG: <core> [core/parser/msg_parser.c:172]:
>>> get_hdr_field(): to body ["Javi" <sip:34606147628 at 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 at 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 at 10.100.10.67:5069]
>>> 13(8360) DEBUG: <core> [core/parser/msg_parser.c:172]:
>>> get_hdr_field(): to body ["Javi" <sip:34606147628 at 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 at 10.100.10.67:5060> q=10
>>> 13(8360) DEBUG: uac_redirect [rd_funcs.c:295]: shmcontact2dset():
>>> adding contact <sip:34666988297 at 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 at 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 at 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 at 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 at 10.100.10.67:5069]
>>> 15(8362) DEBUG: <core> [core/parser/msg_parser.c:172]:
>>> get_hdr_field(): to body ["Javi" <sip:34606147628 at 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 at 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 at 10.100.10.67:5069]
>>> 15(8362) DEBUG: <core> [core/parser/msg_parser.c:172]:
>>> get_hdr_field(): to body ["Javi" <sip:34606147628 at 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 at 10.100.10.67:5069]
>>> 15(8362) DEBUG: <core> [core/parser/msg_parser.c:172]:
>>> get_hdr_field(): to body ["Javi" <sip:34606147628 at 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 at 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 at 10.100.10.67:5061>;tag=9680SIPpTag001
>>> To: "Javi" <sip:34606147628 at 10.100.10.67:5069>;tag=5
>>> Call-ID: 1-9680 at 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 at 10.100.10.67:5069]
>>> 6(8353) DEBUG: <core> [core/parser/msg_parser.c:172]:
>>> get_hdr_field(): to body ["Javi" <sip:34606147628 at 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 at 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 at 10.100.10.67:5061>;tag=9680SIPpTag001
>>> To: "Javi" <sip:34606147628 at 10.100.10.67:5069>;tag=5
>>> Call-ID: 1-9680 at 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 at 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 at 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 at 10.100.10.67:5069]
>>> 6(8353) DEBUG: <core> [core/parser/msg_parser.c:172]:
>>> get_hdr_field(): to body ["Test" <sip:34606147628 at 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 at 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 at 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 at 10.100.10.67:5061>;tag=9680SIPpTag001
>>> To: "Test" <sip:34606147628 at 10.100.10.67:5069>;tag=5
>>> Call-ID: 1-9680 at 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 at 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 at 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 at 10.100.10.67:5069]
>>> 3(8350) DEBUG: <core> [core/parser/msg_parser.c:172]:
>>> get_hdr_field(): to body ["Test" <sip:34606147628 at 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 at 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 at 10.100.10.67:5069]
>>> 7(8354) DEBUG: <core> [core/parser/msg_parser.c:172]:
>>> get_hdr_field(): to body ["Test" <sip:34606147628 at 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 at 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 at 10.100.10.67:5061>;tag=9680SIPpTag001
>>> To: "Test" <sip:34606147628 at 10.100.10.67:5069>;tag=5
>>> Call-ID: 1-9680 at 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 at 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 at 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 at 10.100.10.67:5069]
>>> 1(7698) DEBUG: <core> [core/parser/msg_parser.c:172]:
>>> get_hdr_field(): to body ["Javi" <sip:34606147628 at 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 at 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 at 10.100.10.67:5069]
>>> 1(7698) DEBUG: <core> [core/parser/msg_parser.c:172]:
>>> get_hdr_field(): to body ["Javi" <sip:34606147628 at 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 at 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 at 10.100.10.67:5069]
>>> 1(7698) DEBUG: <core> [core/parser/msg_parser.c:172]:
>>> get_hdr_field(): to body ["Javi" <sip:34606147628 at 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 at 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 at 10.100.10.67:5069]
>>> 1(7698) DEBUG: <core> [core/parser/msg_parser.c:172]:
>>> get_hdr_field(): to body ["Javi" <sip:34606147628 at 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 at 10.100.10.67:5060> q=10
>>> 1(7698) DEBUG: uac_redirect [rd_funcs.c:295]: shmcontact2dset():
>>> adding contact <sip:34666988297 at 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 at 10.100.10.67:5069]
>>> 1(7698) DEBUG: <core> [core/parser/msg_parser.c:172]:
>>> get_hdr_field(): to body ["Javi" <sip:34606147628 at 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 at 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 at 10.100.10.67:5069]
>>> 1(7698) DEBUG: <core> [core/parser/msg_parser.c:172]:
>>> get_hdr_field(): to body ["Javi" <sip:34606147628 at 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 at 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 at 10.100.10.67:5069]
>>> 1(7698) DEBUG: <core> [core/parser/msg_parser.c:172]:
>>> get_hdr_field(): to body ["Javi" <sip:34606147628 at 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 at 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 at 10.100.10.67:5061>;tag=8173SIPpTag001
>>> To: "Javi" <sip:34606147628 at 10.100.10.67:5069>;tag=3
>>> Call-ID: 1-8173 at 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 at 10.100.10.67:5069]
>>> 1(7698) DEBUG: <core> [core/parser/msg_parser.c:172]:
>>> get_hdr_field(): to body ["Javi" <sip:34606147628 at 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 at 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 at 10.100.10.67:5061>;tag=8173SIPpTag001
>>> To: "Javi" <sip:34606147628 at 10.100.10.67:5069>;tag=3
>>> Call-ID: 1-8173 at 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 at 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 at 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 at 10.100.10.67:5069]
>>> 1(7698) DEBUG: <core> [core/parser/msg_parser.c:172]:
>>> get_hdr_field(): to body ["Test" <sip:34606147628 at 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 at 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 at 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 at 10.100.10.67:5061>;tag=8173SIPpTag001
>>> To: "Test" <sip:34606147628 at 10.100.10.67:5069>;tag=3
>>> Call-ID: 1-8173 at 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 at 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 at 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 at 10.100.10.67:5069]
>>> 1(7698) DEBUG: <core> [core/parser/msg_parser.c:172]:
>>> get_hdr_field(): to body ["Test" <sip:34606147628 at 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 at 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 at 10.100.10.67:5069]
>>> 1(7698) DEBUG: <core> [core/parser/msg_parser.c:172]:
>>> get_hdr_field(): to body ["Test" <sip:34606147628 at 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 at 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 at 10.100.10.67:5061>;tag=8173SIPpTag001
>>> To: "Test" <sip:34606147628 at 10.100.10.67:5069>;tag=3
>>> Call-ID: 1-8173 at 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 at lists.kamailio.org
>>> https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users
More information about the sr-users
mailing list