12(3061) DEBUG: ims_registrar_pcscf [async_reginfo.c:200]: new_reginfo_event(): pres_uri [sip:alice@fast-ims.in]
12(3061) DEBUG: htable [ht_var.c:90]: pv_set_ht_cell(): set value for $sht(a=>675ac234f6756d2ba25f8471f6b9ebc9@0:0:0:0:0:0:0:0::start_time)
12(3061) ERROR: <script>: REGISTER SUCCESS[675ac234f6756d2ba25f8471f6b9ebc9@0:0:0:0:0:0:0:0] took +500ms
12(3061) DEBUG: tm [t_reply.c:1265]: t_should_relay_response(): ->>>>>>>>> T_code=0, new_code=200
12(3061) DEBUG: tm [t_reply.c:1786]: relay_reply(): branch=0, save=0, relay=0 icode=0
12(3061) DEBUG: <core> [core/msg_translator.c:2265]: generate_res_buf_from_sip_res(): old size: 675, new size: 588
12(3061) DEBUG: <core> [core/msg_translator.c:2283]: generate_res_buf_from_sip_res(): copied size: orig:311, new: 224, rest: 364 msg=
SIP/2.0 200 OK
Call-ID: 675ac234f6756d2ba25f8471f6b9ebc9@0:0:0:0:0:0:0:0
CSeq: 2 REGISTER
From: "alice" <sip:alice@fast-ims.in>;tag=4d0e1d5e
To: "alice" <sip:alice@fast-ims.in>;tag=6c91412686794797a7cb8248a452c726-0fd5
Via: SIP/2.0/UDP 192.168.99.52:5060;rport=5060;branch=z9hG4bK-333432-e247309917757c2dd26aaeaf5256fd44
Contact: <sip:alice@192.168.99.52:5060;transport=udp;registering_acc=fast-ims_in>;expires=540
Path: <sip:term@pcscf.fast-ims.in;lr>
P-Associated-URI: <sip:alice@fast-ims.in>
Service-Route: <sip:orig@scscf.fast-ims.in;lr>
Server:scscf1
Content-Length: 0


12(3061) DEBUG: tm [t_reply.c:1629]: cleanup_uac_timers(): RETR/FR timers reset
12(3061) DEBUG: <core> [core/receive.c:348]: receive_msg(): reply-route executed in: 19083 usec
12(3061) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
12(3061) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
12(3061) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
12(3061) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
12(3061) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
12(3061) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
12(3061) DEBUG: <core> [core/xavp.c:446]: xavp_destroy_list(): destroying xavp list (nil)
12(3061) DEBUG: <core> [core/receive.c:364]: receive_msg(): cleaning up
23(3132) DEBUG: ims_registrar_pcscf [async_reginfo.c:289]: reginfo_event_process(): PROCESSING REGINFO EVENT with event [0]
23(3132) DEBUG: ims_registrar_pcscf [async_reginfo.c:341]: reginfo_event_process(): Sending out-of-band subscribe with remote_target [sip:alice@fast-ims.in] pres_uri [sip:alice@fast-ims.in] subs_watcher_uri [sip:pcscf.fast-ims.in] subs_contact [sip:pcscf.fast-ims.in] extra_headers [P-Asserted-Identity: <sip:pcscf.fast-ims.in>
] expires [3600] event [64] flag [4] source_flag [8192]
23(3132) DEBUG: pua [send_subscribe.c:54]: print_subs(): pres_uri= sip:alice@fast-ims.in - len: 21
23(3132) DEBUG: pua [send_subscribe.c:57]: print_subs(): watcher_uri= sip:pcscf.fast-ims.in - len: 21
23(3132) DEBUG: pua [hash.c:132]: search_htable(): core_hash= 344
23(3132) DEBUG: pua [hash.c:185]: search_htable(): record not found
23(3132) DEBUG: pua [send_subscribe.c:1042]: send_subscribe(): request for a subscription with update type and no record found
13(3062) DEBUG: <core> [core/parser/msg_parser.c:600]: parse_msg(): SIP Request:
13(3062) DEBUG: <core> [core/parser/msg_parser.c:602]: parse_msg():  method:  <SUBSCRIBE>
13(3062) DEBUG: <core> [core/parser/msg_parser.c:604]: parse_msg():  uri:     <sip:alice@fast-ims.in>
13(3062) DEBUG: <core> [core/parser/msg_parser.c:606]: parse_msg():  version: <SIP/2.0>
13(3062) DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>: <1> <SUBSCRIBE>
13(3062) DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=10
13(3062) DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): <To> [33]; uri=[sip:alice@fast-ims.in]
13(3062) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body ["alice" <sip:alice@fast-ims.in>
]
13(3062) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK-333432-9ea487d4f060041e8c7c3306e1774ccc>; state=16
13(3062) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
13(3062) DEBUG: <core> [core/parser/msg_parser.c:491]: parse_headers(): Via found, flags=2
13(3062) DEBUG: <core> [core/parser/msg_parser.c:493]: parse_headers(): this is the first via
13(3062) DEBUG: <core> [core/receive.c:191]: receive_msg(): --- received sip message - request - call-id: [91944db2af82758bf7b6f064588816ad@0:0:0:0:0:0:0:0] - cseq: [1 SUBSCRIBE]
13(3062) DEBUG: <core> [core/receive.c:234]: receive_msg(): preparing to run routing scripts...
13(3062) DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=440c8bdd
13(3062) DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29
13(3062) ERROR: <script>: SUBSCRIBE (sip:alice@fast-ims.in (192.168.99.52:5060) to sip:alice@fast-ims.in, 91944db2af82758bf7b6f064588816ad@0:0:0:0:0:0:0:0)
13(3062) DEBUG: <script>: Mem: Total 67108864, Free 63927672 [1% used]
13(3062) DEBUG: maxfwd [mf_funcs.c:76]: is_maxfwd_present(): value = 70 
13(3062) DEBUG: <core> [core/parser/msg_parser.c:183]: get_hdr_field(): content_length=0
13(3062) DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): found end of header
13(3062) DEBUG: sanity [sanity_mod.c:256]: w_sanity_check(): sanity checks result: 1
13(3062) DEBUG: siputils [checks.c:120]: has_totag(): no totag
13(3062) DEBUG: <core> [core/select.c:412]: run_select(): Calling SELECT 0x7fa73a5148e8
13(3062) DEBUG: tm [t_lookup.c:1019]: t_check_msg(): msg (0x7fa73a61b4c0) id=1 global id=0 T start=0xffffffffffffffff
13(3062) DEBUG: tm [t_lookup.c:477]: t_lookup_request(): start searching: hash=549, isACK=0
13(3062) DEBUG: tm [t_lookup.c:435]: matching_3261(): RFC3261 transaction matching failed
13(3062) DEBUG: tm [t_lookup.c:659]: t_lookup_request(): no transaction found
13(3062) DEBUG: tm [t_lookup.c:1088]: t_check_msg(): msg (0x7fa73a61b4c0) id=1 global id=1 T end=(nil)
13(3062) DEBUG: siputils [checks.c:120]: has_totag(): no totag
13(3062) DEBUG: tm [t_lookup.c:1019]: t_check_msg(): msg (0x7fa73a61b4c0) id=1 global id=1 T start=(nil)
13(3062) DEBUG: tm [t_lookup.c:1094]: t_check_msg(): T previously sought and not found for msg (0x7fa73a61b4c0)
13(3062) DEBUG: tm [t_lookup.c:1019]: t_check_msg(): msg (0x7fa73a61b4c0) id=1 global id=1 T start=(nil)
13(3062) DEBUG: tm [t_lookup.c:1094]: t_check_msg(): T previously sought and not found for msg (0x7fa73a61b4c0)
13(3062) DEBUG: rr [loose.c:112]: find_first_route(): No Route headers found
13(3062) DEBUG: rr [loose.c:944]: loose_route(): There is no Route HF
13(3062) INFO: rr [rr_mod.c:443]: pv_get_route_uri_f(): No route header present.
13(3062) DEBUG: nathelper [nathelper.c:805]: add_contact_alias_0(): no need to add alias param
13(3062) DEBUG: <core> [core/re.c:436]: subst_run(): running. r=1
13(3062) DEBUG: <core> [core/re.c:504]: subst_str(): no match
13(3062) DEBUG: textops [txt_var.c:92]: tr_txt_eval_re(): no match for subst expression
13(3062) DEBUG: rr [loose.c:112]: find_first_route(): No Route headers found
13(3062) DEBUG: rr [loose.c:944]: loose_route(): There is no Route HF
13(3062) DEBUG: ims_registrar_pcscf [service_routes.c:186]: getContactP(): number of service routes to look for is 0
13(3062) DEBUG: ims_registrar_pcscf [service_routes.c:210]: getContactP(): This is a request - using first via to find contact
13(3062) DEBUG: ims_registrar_pcscf [service_routes.c:218]: getContactP(): searching for contact with host:port:proto contact [1://192.168.99.52:5060]
13(3062) DEBUG: ims_usrloc_pcscf [udomain.c:459]: get_pcontact(): Searching for contact with AOR [sip:alice@192.168.99.52:5060;transport=udp;registering_acc=fast-ims_in] in P-CSCF usrloc based on VIA [1://192.168.99.52:5060] Received [1://192.168.99.52:5060], Search flag is 0
13(3062) DEBUG: ims_usrloc_pcscf [udomain.c:463]: get_pcontact(): Have an AOR to search for
13(3062) DEBUG: ims_usrloc_pcscf [udomain.c:468]: get_pcontact(): checking for rinstance13(3062) DEBUG: ims_usrloc_pcscf [udomain.c:480]: get_pcontact(): no rinstance param
13(3062) DEBUG: ims_usrloc_pcscf [usrloc.c:148]: get_aor_hash(): Returning hash: [2892500256]
13(3062) DEBUG: ims_usrloc_pcscf [udomain.c:503]: get_pcontact(): get_pcontact slot is [288]
13(3062) DEBUG: ims_usrloc_pcscf [udomain.c:507]: get_pcontact(): comparing contact with aorhash [2892500256], aor [sip:alice@192.168.99.52:5060;transport=udp;registering_acc=fast-ims_in]
13(3062) DEBUG: ims_usrloc_pcscf [udomain.c:508]: get_pcontact():   contact host [192.168.99.52:5060]
13(3062) DEBUG: ims_usrloc_pcscf [udomain.c:509]: get_pcontact(): contact received [1:192.168.99.52:5060]
13(3062) DEBUG: ims_usrloc_pcscf [udomain.c:519]: get_pcontact(): found contact with URI [sip:alice@192.168.99.52:5060;transport=udp;registering_acc=fast-ims_in]
13(3062) DEBUG: ims_registrar_pcscf [service_routes.c:121]: checkcontact(): Port 5060 (search 5060), Proto 1 (search 1), reg_state registered (search registered)
13(3062) DEBUG: ims_registrar_pcscf [service_routes.c:149]: checkcontact(): Received host len 13 (search 13)
13(3062) DEBUG: ims_registrar_pcscf [service_routes.c:154]: checkcontact(): Received host 192.168.99.52 (search 192.168.99.52)
13(3062) DEBUG: ims_registrar_pcscf [service_routes.c:158]: checkcontact(): check contact passed
13(3062) DEBUG: ims_registrar_pcscf [service_routes.c:304]: getContactP(): Trying to set asserted identity field13(3062) DEBUG: ims_registrar_pcscf [service_routes.c:308]: getContactP(): Checking through contact users13(3062) DEBUG: ims_registrar_pcscf [service_routes.c:310]: getContactP(): Found default contact user so setting asserted identity13(3062) DEBUG: ims_registrar_pcscf [service_routes.c:317]: getContactP(): Have set the asserted_identity param to [sip:alice@fast-ims.in]
13(3062) DEBUG: siputils [chargingvector.c:293]: sip_get_charging_vector(): No valid P-Charging-Vector header found.
13(3062) DEBUG: siputils [chargingvector.c:133]: sip_generate_charging_vector(): PCV generate
13(3062) DEBUG: siputils [chargingvector.c:163]: sip_parse_charging_vector(): parsing PCV header [icid-value=4956537F000101F60B00000900000000; icid-generated-at=192.168.99.237
]
13(3062) DEBUG: siputils [chargingvector.c:173]: sip_parse_charging_vector(): parsed P-Charging-Vector icid-value=4956537F000101F60B00000900000000
13(3062) DEBUG: siputils [chargingvector.c:188]: sip_parse_charging_vector(): parsed P-Charging-Vector icid-generated-at=192.168.99.237
13(3062) INFO: siputils [chargingvector.c:432]: sip_handle_pcv(): Generated PCV header P-Charging-Vector: icid-value=4956537F000101F60B00000900000000; icid-generated-at=192.168.99.237
13(3062) DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=9
13(3062) DEBUG: ims_registrar_pcscf [service_routes.c:673]: assert_identity(): Identity to assert: sip:alice@fast-ims.in
13(3062) DEBUG: ims_registrar_pcscf [service_routes.c:186]: getContactP(): number of service routes to look for is 0
13(3062) DEBUG: ims_registrar_pcscf [service_routes.c:210]: getContactP(): This is a request - using first via to find contact
13(3062) DEBUG: ims_registrar_pcscf [service_routes.c:218]: getContactP(): searching for contact with host:port:proto contact [1://192.168.99.52:5060]
13(3062) DEBUG: ims_usrloc_pcscf [udomain.c:459]: get_pcontact(): Searching for contact with AOR [sip:alice@192.168.99.52:5060;transport=udp;registering_acc=fast-ims_in] in P-CSCF usrloc based on VIA [1://192.168.99.52:5060] Received [1://192.168.99.52:5060], Search flag is 0
13(3062) DEBUG: ims_usrloc_pcscf [udomain.c:463]: get_pcontact(): Have an AOR to search for
13(3062) DEBUG: ims_usrloc_pcscf [udomain.c:468]: get_pcontact(): checking for rinstance13(3062) DEBUG: ims_usrloc_pcscf [udomain.c:480]: get_pcontact(): no rinstance param
13(3062) DEBUG: ims_usrloc_pcscf [usrloc.c:148]: get_aor_hash(): Returning hash: [2892500256]
13(3062) DEBUG: ims_usrloc_pcscf [udomain.c:503]: get_pcontact(): get_pcontact slot is [288]
13(3062) DEBUG: ims_usrloc_pcscf [udomain.c:507]: get_pcontact(): comparing contact with aorhash [2892500256], aor [sip:alice@192.168.99.52:5060;transport=udp;registering_acc=fast-ims_in]
13(3062) DEBUG: ims_usrloc_pcscf [udomain.c:508]: get_pcontact():   contact host [192.168.99.52:5060]
13(3062) DEBUG: ims_usrloc_pcscf [udomain.c:509]: get_pcontact(): contact received [1:192.168.99.52:5060]
13(3062) DEBUG: ims_usrloc_pcscf [udomain.c:519]: get_pcontact(): found contact with URI [sip:alice@192.168.99.52:5060;transport=udp;registering_acc=fast-ims_in]
13(3062) DEBUG: ims_registrar_pcscf [service_routes.c:121]: checkcontact(): Port 5060 (search 5060), Proto 1 (search 1), reg_state registered (search registered)
13(3062) DEBUG: ims_registrar_pcscf [service_routes.c:149]: checkcontact(): Received host len 13 (search 13)
13(3062) DEBUG: ims_registrar_pcscf [service_routes.c:154]: checkcontact(): Received host 192.168.99.52 (search 192.168.99.52)
13(3062) DEBUG: ims_registrar_pcscf [service_routes.c:158]: checkcontact(): check contact passed
13(3062) DEBUG: ims_registrar_pcscf [service_routes.c:304]: getContactP(): Trying to set asserted identity field13(3062) DEBUG: ims_registrar_pcscf [service_routes.c:308]: getContactP(): Checking through contact users13(3062) DEBUG: ims_registrar_pcscf [service_routes.c:310]: getContactP(): Found default contact user so setting asserted identity13(3062) DEBUG: ims_registrar_pcscf [service_routes.c:317]: getContactP(): Have set the asserted_identity param to [sip:alice@fast-ims.in]
13(3062) DEBUG: ims_registrar_pcscf [service_routes.c:677]: assert_identity(): Public identity: sip:alice@fast-ims.in
13(3062) DEBUG: ims_registrar_pcscf [service_routes.c:682]: assert_identity(): Match!
13(3062) DEBUG: ims_registrar_pcscf [service_routes.c:63]: find_first_route(): No Route headers found
13(3062) DEBUG: ims_usrloc_pcscf [usrloc.c:148]: get_aor_hash(): Returning hash: [2892500256]
13(3062) DEBUG: ims_usrloc_pcscf [usrloc.c:139]: get_hash_slot(): Returning hash slot: [288]
13(3062) DEBUG: ims_registrar_pcscf [service_routes.c:430]: check_service_routes(): Request doesn't have any route headers to check service-route...ignoring
13(3062) DEBUG: ims_usrloc_pcscf [usrloc.c:148]: get_aor_hash(): Returning hash: [2892500256]
13(3062) DEBUG: ims_usrloc_pcscf [usrloc.c:139]: get_hash_slot(): Returning hash slot: [288]
13(3062) DEBUG: ims_registrar_pcscf [service_routes.c:186]: getContactP(): number of service routes to look for is 0
13(3062) DEBUG: ims_registrar_pcscf [service_routes.c:210]: getContactP(): This is a request - using first via to find contact
13(3062) DEBUG: ims_registrar_pcscf [service_routes.c:218]: getContactP(): searching for contact with host:port:proto contact [1://192.168.99.52:5060]
13(3062) DEBUG: ims_usrloc_pcscf [udomain.c:459]: get_pcontact(): Searching for contact with AOR [sip:alice@192.168.99.52:5060;transport=udp;registering_acc=fast-ims_in] in P-CSCF usrloc based on VIA [1://192.168.99.52:5060] Received [1://192.168.99.52:5060], Search flag is 0
13(3062) DEBUG: ims_usrloc_pcscf [udomain.c:463]: get_pcontact(): Have an AOR to search for
13(3062) DEBUG: ims_usrloc_pcscf [udomain.c:468]: get_pcontact(): checking for rinstance13(3062) DEBUG: ims_usrloc_pcscf [udomain.c:480]: get_pcontact(): no rinstance param
13(3062) DEBUG: ims_usrloc_pcscf [usrloc.c:148]: get_aor_hash(): Returning hash: [2892500256]
13(3062) DEBUG: ims_usrloc_pcscf [udomain.c:503]: get_pcontact(): get_pcontact slot is [288]
13(3062) DEBUG: ims_usrloc_pcscf [udomain.c:507]: get_pcontact(): comparing contact with aorhash [2892500256], aor [sip:alice@192.168.99.52:5060;transport=udp;registering_acc=fast-ims_in]
13(3062) DEBUG: ims_usrloc_pcscf [udomain.c:508]: get_pcontact():   contact host [192.168.99.52:5060]
13(3062) DEBUG: ims_usrloc_pcscf [udomain.c:509]: get_pcontact(): contact received [1:192.168.99.52:5060]
13(3062) DEBUG: ims_usrloc_pcscf [udomain.c:519]: get_pcontact(): found contact with URI [sip:alice@192.168.99.52:5060;transport=udp;registering_acc=fast-ims_in]
13(3062) DEBUG: ims_registrar_pcscf [service_routes.c:121]: checkcontact(): Port 5060 (search 5060), Proto 1 (search 1), reg_state registered (search registered)
13(3062) DEBUG: ims_registrar_pcscf [service_routes.c:149]: checkcontact(): Received host len 13 (search 13)
13(3062) DEBUG: ims_registrar_pcscf [service_routes.c:154]: checkcontact(): Received host 192.168.99.52 (search 192.168.99.52)
13(3062) DEBUG: ims_registrar_pcscf [service_routes.c:158]: checkcontact(): check contact passed
13(3062) DEBUG: ims_registrar_pcscf [service_routes.c:304]: getContactP(): Trying to set asserted identity field13(3062) DEBUG: ims_registrar_pcscf [service_routes.c:308]: getContactP(): Checking through contact users13(3062) DEBUG: ims_registrar_pcscf [service_routes.c:310]: getContactP(): Found default contact user so setting asserted identity13(3062) DEBUG: ims_registrar_pcscf [service_routes.c:317]: getContactP(): Have set the asserted_identity param to [sip:alice@fast-ims.in]
13(3062) DEBUG: ims_usrloc_pcscf [usrloc.c:148]: get_aor_hash(): Returning hash: [2892500256]
13(3062) DEBUG: ims_usrloc_pcscf [usrloc.c:139]: get_hash_slot(): Returning hash slot: [288]
13(3062) DEBUG: ims_registrar_pcscf [service_routes.c:605]: force_service_routes(): Setting route header to <Route: <sip:orig@scscf.fast-ims.in;lr>
> 
13(3062) DEBUG: ims_registrar_pcscf [service_routes.c:614]: force_service_routes(): Setting dst_uri to <sip:orig@scscf.fast-ims.in;lr> 
13(3062) DEBUG: ims_usrloc_pcscf [usrloc.c:148]: get_aor_hash(): Returning hash: [2892500256]
13(3062) DEBUG: ims_usrloc_pcscf [usrloc.c:139]: get_hash_slot(): Returning hash slot: [288]
13(3062) DEBUG: rr [loose.c:1209]: is_direction(): param ftag not found
13(3062) DEBUG: tm [t_lookup.c:1320]: t_newtran(): msg id=1 , global msg id=1 , T on entrance=(nil)
13(3062) DEBUG: tm [t_lookup.c:477]: t_lookup_request(): start searching: hash=549, isACK=0
13(3062) DEBUG: tm [t_lookup.c:435]: matching_3261(): RFC3261 transaction matching failed
13(3062) DEBUG: tm [t_lookup.c:659]: t_lookup_request(): no transaction found
13(3062) DEBUG: tm [t_hooks.c:349]: run_reqin_callbacks_internal(): trans=0x7fa72fbc5a78, callback type 1, id 0 entered
 3(3052) DEBUG: <core> [core/parser/msg_parser.c:600]: parse_msg(): SIP Request:
 3(3052) DEBUG: <core> [core/parser/msg_parser.c:602]: parse_msg():  method:  <SUBSCRIBE>
 3(3052) DEBUG: <core> [core/parser/msg_parser.c:604]: parse_msg():  uri:     <sip:alice@fast-ims.in>
 3(3052) DEBUG: <core> [core/parser/msg_parser.c:606]: parse_msg():  version: <SIP/2.0>
 3(3052) DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>: <1> <SUBSCRIBE>
 3(3052) DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=10
 3(3052) DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): <To> [33]; uri=[sip:alice@fast-ims.in]
 3(3052) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body ["alice" <sip:alice@fast-ims.in>
]
 3(3052) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK-333432-c82e2cf2d2bde0eb837987a7874b3f97>; state=16
 3(3052) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
 3(3052) DEBUG: <core> [core/parser/msg_parser.c:491]: parse_headers(): Via found, flags=2
 3(3052) DEBUG: <core> [core/parser/msg_parser.c:493]: parse_headers(): this is the first via
 3(3052) DEBUG: <core> [core/receive.c:191]: receive_msg(): --- received sip message - request - call-id: [601cf210acace0fa83c4aaca1a366395@0:0:0:0:0:0:0:0] - cseq: [1 SUBSCRIBE]
 3(3052) DEBUG: <core> [core/receive.c:234]: receive_msg(): preparing to run routing scripts...
 3(3052) DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=2dd300f1
 3(3052) DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29
 3(3052) ERROR: <script>: SUBSCRIBE (sip:alice@fast-ims.in (192.168.99.52:5060) to sip:alice@fast-ims.in, 601cf210acace0fa83c4aaca1a366395@0:0:0:0:0:0:0:0)
 3(3052) DEBUG: <script>: Mem: Total 67108864, Free 63921160 [1% used]
 3(3052) DEBUG: maxfwd [mf_funcs.c:76]: is_maxfwd_present(): value = 70 
 3(3052) DEBUG: <core> [core/parser/msg_parser.c:183]: get_hdr_field(): content_length=0
 3(3052) DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): found end of header
 3(3052) DEBUG: sanity [sanity_mod.c:256]: w_sanity_check(): sanity checks result: 1
 3(3052) DEBUG: siputils [checks.c:120]: has_totag(): no totag
 3(3052) DEBUG: <core> [core/select.c:412]: run_select(): Calling SELECT 0x7fa73a5148e8
 3(3052) DEBUG: tm [t_lookup.c:1019]: t_check_msg(): msg (0x7fa73a61b4c0) id=1 global id=0 T start=0xffffffffffffffff
 3(3052) DEBUG: tm [t_lookup.c:477]: t_lookup_request(): start searching: hash=13934, isACK=0
 3(3052) DEBUG: tm [t_lookup.c:435]: matching_3261(): RFC3261 transaction matching failed
 3(3052) DEBUG: tm [t_lookup.c:659]: t_lookup_request(): no transaction found
 3(3052) DEBUG: tm [t_lookup.c:1088]: t_check_msg(): msg (0x7fa73a61b4c0) id=1 global id=1 T end=(nil)
 3(3052) DEBUG: siputils [checks.c:120]: has_totag(): no totag
 3(3052) DEBUG: tm [t_lookup.c:1019]: t_check_msg(): msg (0x7fa73a61b4c0) id=1 global id=1 T start=(nil)
 3(3052) DEBUG: tm [t_lookup.c:1094]: t_check_msg(): T previously sought and not found for msg (0x7fa73a61b4c0)
 3(3052) DEBUG: tm [t_lookup.c:1019]: t_check_msg(): msg (0x7fa73a61b4c0) id=1 global id=1 T start=(nil)
 3(3052) DEBUG: tm [t_lookup.c:1094]: t_check_msg(): T previously sought and not found for msg (0x7fa73a61b4c0)
 3(3052) DEBUG: rr [loose.c:112]: find_first_route(): No Route headers found
 3(3052) DEBUG: rr [loose.c:944]: loose_route(): There is no Route HF
 3(3052) INFO: rr [rr_mod.c:443]: pv_get_route_uri_f(): No route header present.
 3(3052) DEBUG: nathelper [nathelper.c:805]: add_contact_alias_0(): no need to add alias param
 3(3052) DEBUG: <core> [core/re.c:436]: subst_run(): running. r=1
 3(3052) DEBUG: <core> [core/re.c:504]: subst_str(): no match
 3(3052) DEBUG: textops [txt_var.c:92]: tr_txt_eval_re(): no match for subst expression
 3(3052) DEBUG: rr [loose.c:112]: find_first_route(): No Route headers found
 3(3052) DEBUG: rr [loose.c:944]: loose_route(): There is no Route HF
 3(3052) DEBUG: ims_registrar_pcscf [service_routes.c:186]: getContactP(): number of service routes to look for is 0
 3(3052) DEBUG: ims_registrar_pcscf [service_routes.c:210]: getContactP(): This is a request - using first via to find contact
 3(3052) DEBUG: ims_registrar_pcscf [service_routes.c:218]: getContactP(): searching for contact with host:port:proto contact [1://192.168.99.52:5060]
 3(3052) DEBUG: ims_usrloc_pcscf [udomain.c:459]: get_pcontact(): Searching for contact with AOR [sip:alice@192.168.99.52:5060;transport=udp;registering_acc=fast-ims_in] in P-CSCF usrloc based on VIA [1://192.168.99.52:5060] Received [1://192.168.99.52:5060], Search flag is 0
 3(3052) DEBUG: ims_usrloc_pcscf [udomain.c:463]: get_pcontact(): Have an AOR to search for
 3(3052) DEBUG: ims_usrloc_pcscf [udomain.c:468]: get_pcontact(): checking for rinstance 3(3052) DEBUG: ims_usrloc_pcscf [udomain.c:480]: get_pcontact(): no rinstance param
 3(3052) DEBUG: ims_usrloc_pcscf [usrloc.c:148]: get_aor_hash(): Returning hash: [2892500256]
 3(3052) DEBUG: ims_usrloc_pcscf [udomain.c:503]: get_pcontact(): get_pcontact slot is [288]
 3(3052) DEBUG: ims_usrloc_pcscf [udomain.c:507]: get_pcontact(): comparing contact with aorhash [2892500256], aor [sip:alice@192.168.99.52:5060;transport=udp;registering_acc=fast-ims_in]
 3(3052) DEBUG: ims_usrloc_pcscf [udomain.c:508]: get_pcontact():   contact host [192.168.99.52:5060]
 3(3052) DEBUG: ims_usrloc_pcscf [udomain.c:509]: get_pcontact(): contact received [1:192.168.99.52:5060]
 3(3052) DEBUG: ims_usrloc_pcscf [udomain.c:519]: get_pcontact(): found contact with URI [sip:alice@192.168.99.52:5060;transport=udp;registering_acc=fast-ims_in]
 3(3052) DEBUG: ims_registrar_pcscf [service_routes.c:121]: checkcontact(): Port 5060 (search 5060), Proto 1 (search 1), reg_state registered (search registered)
 3(3052) DEBUG: ims_registrar_pcscf [service_routes.c:149]: checkcontact(): Received host len 13 (search 13)
 3(3052) DEBUG: ims_registrar_pcscf [service_routes.c:154]: checkcontact(): Received host 192.168.99.52 (search 192.168.99.52)
 3(3052) DEBUG: ims_registrar_pcscf [service_routes.c:158]: checkcontact(): check contact passed
 3(3052) DEBUG: ims_registrar_pcscf [service_routes.c:304]: getContactP(): Trying to set asserted identity field 3(3052) DEBUG: ims_registrar_pcscf [service_routes.c:308]: getContactP(): Checking through contact users 3(3052) DEBUG: ims_registrar_pcscf [service_routes.c:310]: getContactP(): Found default contact user so setting asserted identity 3(3052) DEBUG: ims_registrar_pcscf [service_routes.c:317]: getContactP(): Have set the asserted_identity param to [sip:alice@fast-ims.in]
 3(3052) DEBUG: siputils [chargingvector.c:293]: sip_get_charging_vector(): No valid P-Charging-Vector header found.
 3(3052) DEBUG: siputils [chargingvector.c:133]: sip_generate_charging_vector(): PCV generate
 3(3052) DEBUG: siputils [chargingvector.c:163]: sip_parse_charging_vector(): parsing PCV header [icid-value=4956537F000101EC0B00000900000000; icid-generated-at=192.168.99.237
]
 3(3052) DEBUG: siputils [chargingvector.c:173]: sip_parse_charging_vector(): parsed P-Charging-Vector icid-value=4956537F000101EC0B00000900000000
 3(3052) DEBUG: siputils [chargingvector.c:188]: sip_parse_charging_vector(): parsed P-Charging-Vector icid-generated-at=192.168.99.237
 3(3052) INFO: siputils [chargingvector.c:432]: sip_handle_pcv(): Generated PCV header P-Charging-Vector: icid-value=4956537F000101EC0B00000900000000; icid-generated-at=192.168.99.237
 3(3052) DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=9
 3(3052) DEBUG: ims_registrar_pcscf [service_routes.c:673]: assert_identity(): Identity to assert: sip:alice@fast-ims.in
 3(3052) DEBUG: ims_registrar_pcscf [service_routes.c:186]: getContactP(): number of service routes to look for is 0
 3(3052) DEBUG: ims_registrar_pcscf [service_routes.c:210]: getContactP(): This is a request - using first via to find contact
 3(3052) DEBUG: ims_registrar_pcscf [service_routes.c:218]: getContactP(): searching for contact with host:port:proto contact [1://192.168.99.52:5060]
 3(3052) DEBUG: ims_usrloc_pcscf [udomain.c:459]: get_pcontact(): Searching for contact with AOR [sip:alice@192.168.99.52:5060;transport=udp;registering_acc=fast-ims_in] in P-CSCF usrloc based on VIA [1://192.168.99.52:5060] Received [1://192.168.99.52:5060], Search flag is 0
 3(3052) DEBUG: ims_usrloc_pcscf [udomain.c:463]: get_pcontact(): Have an AOR to search for
 3(3052) DEBUG: ims_usrloc_pcscf [udomain.c:468]: get_pcontact(): checking for rinstance 3(3052) DEBUG: ims_usrloc_pcscf [udomain.c:480]: get_pcontact(): no rinstance param
 3(3052) DEBUG: ims_usrloc_pcscf [usrloc.c:148]: get_aor_hash(): Returning hash: [2892500256]
 3(3052) DEBUG: ims_usrloc_pcscf [udomain.c:503]: get_pcontact(): get_pcontact slot is [288]
 3(3052) DEBUG: ims_usrloc_pcscf [udomain.c:507]: get_pcontact(): comparing contact with aorhash [2892500256], aor [sip:alice@192.168.99.52:5060;transport=udp;registering_acc=fast-ims_in]
 3(3052) DEBUG: ims_usrloc_pcscf [udomain.c:508]: get_pcontact():   contact host [192.168.99.52:5060]
 3(3052) DEBUG: ims_usrloc_pcscf [udomain.c:509]: get_pcontact(): contact received [1:192.168.99.52:5060]
 3(3052) DEBUG: ims_usrloc_pcscf [udomain.c:519]: get_pcontact(): found contact with URI [sip:alice@192.168.99.52:5060;transport=udp;registering_acc=fast-ims_in]
 3(3052) DEBUG: ims_registrar_pcscf [service_routes.c:121]: checkcontact(): Port 5060 (search 5060), Proto 1 (search 1), reg_state registered (search registered)
 3(3052) DEBUG: ims_registrar_pcscf [service_routes.c:149]: checkcontact(): Received host len 13 (search 13)
 3(3052) DEBUG: ims_registrar_pcscf [service_routes.c:154]: checkcontact(): Received host 192.168.99.52 (search 192.168.99.52)
 3(3052) DEBUG: ims_registrar_pcscf [service_routes.c:158]: checkcontact(): check contact passed
 3(3052) DEBUG: ims_registrar_pcscf [service_routes.c:304]: getContactP(): Trying to set asserted identity field 3(3052) DEBUG: ims_registrar_pcscf [service_routes.c:308]: getContactP(): Checking through contact users 3(3052) DEBUG: ims_registrar_pcscf [service_routes.c:310]: getContactP(): Found default contact user so setting asserted identity 3(3052) DEBUG: ims_registrar_pcscf [service_routes.c:317]: getContactP(): Have set the asserted_identity param to [sip:alice@fast-ims.in]
 3(3052) DEBUG: ims_registrar_pcscf [service_routes.c:677]: assert_identity(): Public identity: sip:alice@fast-ims.in
 3(3052) DEBUG: ims_registrar_pcscf [service_routes.c:682]: assert_identity(): Match!
 3(3052) DEBUG: ims_registrar_pcscf [service_routes.c:63]: find_first_route(): No Route headers found
 3(3052) DEBUG: ims_usrloc_pcscf [usrloc.c:148]: get_aor_hash(): Returning hash: [2892500256]
 3(3052) DEBUG: ims_usrloc_pcscf [usrloc.c:139]: get_hash_slot(): Returning hash slot: [288]
 3(3052) DEBUG: ims_registrar_pcscf [service_routes.c:430]: check_service_routes(): Request doesn't have any route headers to check service-route...ignoring
 3(3052) DEBUG: ims_usrloc_pcscf [usrloc.c:148]: get_aor_hash(): Returning hash: [2892500256]
 3(3052) DEBUG: ims_usrloc_pcscf [usrloc.c:139]: get_hash_slot(): Returning hash slot: [288]
 3(3052) DEBUG: ims_registrar_pcscf [service_routes.c:186]: getContactP(): number of service routes to look for is 0
 3(3052) DEBUG: ims_registrar_pcscf [service_routes.c:210]: getContactP(): This is a request - using first via to find contact
 3(3052) DEBUG: ims_registrar_pcscf [service_routes.c:218]: getContactP(): searching for contact with host:port:proto contact [1://192.168.99.52:5060]
 3(3052) DEBUG: ims_usrloc_pcscf [udomain.c:459]: get_pcontact(): Searching for contact with AOR [sip:alice@192.168.99.52:5060;transport=udp;registering_acc=fast-ims_in] in P-CSCF usrloc based on VIA [1://192.168.99.52:5060] Received [1://192.168.99.52:5060], Search flag is 0
 3(3052) DEBUG: ims_usrloc_pcscf [udomain.c:463]: get_pcontact(): Have an AOR to search for
 3(3052) DEBUG: ims_usrloc_pcscf [udomain.c:468]: get_pcontact(): checking for rinstance 3(3052) DEBUG: ims_usrloc_pcscf [udomain.c:480]: get_pcontact(): no rinstance param
 3(3052) DEBUG: ims_usrloc_pcscf [usrloc.c:148]: get_aor_hash(): Returning hash: [2892500256]
 3(3052) DEBUG: ims_usrloc_pcscf [udomain.c:503]: get_pcontact(): get_pcontact slot is [288]
 3(3052) DEBUG: ims_usrloc_pcscf [udomain.c:507]: get_pcontact(): comparing contact with aorhash [2892500256], aor [sip:alice@192.168.99.52:5060;transport=udp;registering_acc=fast-ims_in]
 3(3052) DEBUG: ims_usrloc_pcscf [udomain.c:508]: get_pcontact():   contact host [192.168.99.52:5060]
 3(3052) DEBUG: ims_usrloc_pcscf [udomain.c:509]: get_pcontact(): contact received [1:192.168.99.52:5060]
 3(3052) DEBUG: ims_usrloc_pcscf [udomain.c:519]: get_pcontact(): found contact with URI [sip:alice@192.168.99.52:5060;transport=udp;registering_acc=fast-ims_in]
 3(3052) DEBUG: ims_registrar_pcscf [service_routes.c:121]: checkcontact(): Port 5060 (search 5060), Proto 1 (search 1), reg_state registered (search registered)
 3(3052) DEBUG: ims_registrar_pcscf [service_routes.c:149]: checkcontact(): Received host len 13 (search 13)
 3(3052) DEBUG: ims_registrar_pcscf [service_routes.c:154]: checkcontact(): Received host 192.168.99.52 (search 192.168.99.52)
 3(3052) DEBUG: ims_registrar_pcscf [service_routes.c:158]: checkcontact(): check contact passed
 3(3052) DEBUG: ims_registrar_pcscf [service_routes.c:304]: getContactP(): Trying to set asserted identity field 3(3052) DEBUG: ims_registrar_pcscf [service_routes.c:308]: getContactP(): Checking through contact users 3(3052) DEBUG: ims_registrar_pcscf [service_routes.c:310]: getContactP(): Found default contact user so setting asserted identity 3(3052) DEBUG: ims_registrar_pcscf [service_routes.c:317]: getContactP(): Have set the asserted_identity param to [sip:alice@fast-ims.in]
 3(3052) DEBUG: ims_usrloc_pcscf [usrloc.c:148]: get_aor_hash(): Returning hash: [2892500256]
 3(3052) DEBUG: ims_usrloc_pcscf [usrloc.c:139]: get_hash_slot(): Returning hash slot: [288]
 3(3052) DEBUG: ims_registrar_pcscf [service_routes.c:605]: force_service_routes(): Setting route header to <Route: <sip:orig@scscf.fast-ims.in;lr>
> 
 3(3052) DEBUG: ims_registrar_pcscf [service_routes.c:614]: force_service_routes(): Setting dst_uri to <sip:orig@scscf.fast-ims.in;lr> 
 3(3052) DEBUG: ims_usrloc_pcscf [usrloc.c:148]: get_aor_hash(): Returning hash: [2892500256]
 3(3052) DEBUG: ims_usrloc_pcscf [usrloc.c:139]: get_hash_slot(): Returning hash slot: [288]
 3(3052) DEBUG: rr [loose.c:1209]: is_direction(): param ftag not found
 3(3052) DEBUG: tm [t_lookup.c:1320]: t_newtran(): msg id=1 , global msg id=1 , T on entrance=(nil)
 3(3052) DEBUG: tm [t_lookup.c:477]: t_lookup_request(): start searching: hash=13934, isACK=0
 3(3052) DEBUG: tm [t_lookup.c:435]: matching_3261(): RFC3261 transaction matching failed
 3(3052) DEBUG: tm [t_lookup.c:659]: t_lookup_request(): no transaction found
 3(3052) DEBUG: tm [t_hooks.c:349]: run_reqin_callbacks_internal(): trans=0x7fa72fbc7128, callback type 1, id 0 entered
 3(3052) DEBUG: <core> [core/md5utils.c:67]: MD5StringArray(): MD5 calculated: 6d06870104cdb13c2099675f9e0da93a
 3(3052) DEBUG: <core> [core/dns_cache.c:542]: _dns_hash_find(): (_sip._udp.scscf.fast-ims.in(27), 33), h=146
13(3062) DEBUG: <core> [core/md5utils.c:67]: MD5StringArray(): MD5 calculated: c02b9c13a7aef7d3558eb11d60fd362f
13(3062) DEBUG: <core> [core/dns_cache.c:542]: _dns_hash_find(): (_sip._udp.scscf.fast-ims.in(27), 33), h=146
 3(3052) DEBUG: <core> [core/resolve.c:937]: get_record(): skipping 1 NS (p=0xa8b2d2, end=0xa8b303)
13(3062) DEBUG: <core> [core/resolve.c:937]: get_record(): skipping 1 NS (p=0xa8b2d2, end=0xa8b303)
 6(3055) DEBUG: <core> [core/parser/msg_parser.c:600]: parse_msg(): SIP Request:
 6(3055) DEBUG: <core> [core/parser/msg_parser.c:602]: parse_msg():  method:  <OPTIONS>
 6(3055) DEBUG: <core> [core/parser/msg_parser.c:604]: parse_msg():  uri:     <sip:fast-ims.in>
 6(3055) DEBUG: <core> [core/parser/msg_parser.c:606]: parse_msg():  version: <SIP/2.0>
 6(3055) DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>: <1> <OPTIONS>
 6(3055) DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=10
 6(3055) DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): <To> [33]; uri=[sip:alice@fast-ims.in]
 6(3055) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body ["alice" <sip:alice@fast-ims.in>
]
 6(3055) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK-333432-f245c7db1dc636dc29dfffd2b56e55ea>; state=16
 6(3055) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
 6(3055) DEBUG: <core> [core/parser/msg_parser.c:491]: parse_headers(): Via found, flags=2
 6(3055) DEBUG: <core> [core/parser/msg_parser.c:493]: parse_headers(): this is the first via
 6(3055) DEBUG: <core> [core/receive.c:191]: receive_msg(): --- received sip message - request - call-id: [f69127cf4a25ac7a2c5cac8f53e6c750@0:0:0:0:0:0:0:0] - cseq: [1 OPTIONS]
 6(3055) DEBUG: <core> [core/receive.c:234]: receive_msg(): preparing to run routing scripts...
 6(3055) DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=48ca0ce
 6(3055) DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29
 6(3055) ERROR: <script>: OPTIONS (sip:alice@fast-ims.in (192.168.99.52:5060) to sip:alice@fast-ims.in, f69127cf4a25ac7a2c5cac8f53e6c750@0:0:0:0:0:0:0:0)
 6(3055) DEBUG: <core> [core/socket_info.c:564]: grep_sock_info(): checking if host==us: 11==14 && [fast-ims.in] == [192.168.99.237]
 6(3055) DEBUG: <core> [core/socket_info.c:567]: grep_sock_info(): checking if port 5060 (advertise 0) matches port 5060
 6(3055) DEBUG: <core> [core/forward.c:412]: check_self(): host != me
 6(3055) DEBUG: <script>: Mem: Total 67108864, Free 63901040 [1% used]
 6(3055) DEBUG: maxfwd [mf_funcs.c:76]: is_maxfwd_present(): value = 70 
 6(3055) DEBUG: <core> [core/parser/msg_parser.c:183]: get_hdr_field(): content_length=0
 6(3055) DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): found end of header
 6(3055) DEBUG: sanity [sanity_mod.c:256]: w_sanity_check(): sanity checks result: 1
 6(3055) DEBUG: siputils [checks.c:120]: has_totag(): no totag
 6(3055) DEBUG: <core> [core/select.c:412]: run_select(): Calling SELECT 0x7fa73a5148e8
 6(3055) DEBUG: tm [t_lookup.c:1019]: t_check_msg(): msg (0x7fa73a61b4c0) id=1 global id=0 T start=0xffffffffffffffff
 6(3055) DEBUG: tm [t_lookup.c:477]: t_lookup_request(): start searching: hash=13106, isACK=0
 6(3055) DEBUG: tm [t_lookup.c:435]: matching_3261(): RFC3261 transaction matching failed
 6(3055) DEBUG: tm [t_lookup.c:659]: t_lookup_request(): no transaction found
 6(3055) DEBUG: tm [t_lookup.c:1088]: t_check_msg(): msg (0x7fa73a61b4c0) id=1 global id=1 T end=(nil)
 6(3055) DEBUG: siputils [checks.c:120]: has_totag(): no totag
 6(3055) DEBUG: tm [t_lookup.c:1019]: t_check_msg(): msg (0x7fa73a61b4c0) id=1 global id=1 T start=(nil)
 6(3055) DEBUG: tm [t_lookup.c:1094]: t_check_msg(): T previously sought and not found for msg (0x7fa73a61b4c0)
 6(3055) DEBUG: tm [t_lookup.c:1019]: t_check_msg(): msg (0x7fa73a61b4c0) id=1 global id=1 T start=(nil)
 6(3055) DEBUG: tm [t_lookup.c:1094]: t_check_msg(): T previously sought and not found for msg (0x7fa73a61b4c0)
 6(3055) DEBUG: rr [loose.c:112]: find_first_route(): No Route headers found
 6(3055) DEBUG: rr [loose.c:944]: loose_route(): There is no Route HF
 6(3055) INFO: rr [rr_mod.c:443]: pv_get_route_uri_f(): No route header present.
 6(3055) DEBUG: <core> [core/re.c:436]: subst_run(): running. r=1
 6(3055) DEBUG: <core> [core/re.c:504]: subst_str(): no match
 6(3055) DEBUG: textops [txt_var.c:92]: tr_txt_eval_re(): no match for subst expression
 6(3055) DEBUG: rr [loose.c:112]: find_first_route(): No Route headers found
 6(3055) DEBUG: rr [loose.c:944]: loose_route(): There is no Route HF
 6(3055) DEBUG: ims_registrar_pcscf [service_routes.c:186]: getContactP(): number of service routes to look for is 0
 6(3055) DEBUG: ims_registrar_pcscf [service_routes.c:210]: getContactP(): This is a request - using first via to find contact
 6(3055) DEBUG: ims_registrar_pcscf [service_routes.c:218]: getContactP(): searching for contact with host:port:proto contact [1://192.168.99.52:5060]
 6(3055) DEBUG: ims_usrloc_pcscf [udomain.c:459]: get_pcontact(): Searching for contact with AOR [sip:alice@192.168.99.52:5060;transport=udp;registering_acc=fast-ims_in] in P-CSCF usrloc based on VIA [1://192.168.99.52:5060] Received [1://192.168.99.52:5060], Search flag is 0
 6(3055) DEBUG: ims_usrloc_pcscf [udomain.c:463]: get_pcontact(): Have an AOR to search for
 6(3055) DEBUG: ims_usrloc_pcscf [udomain.c:468]: get_pcontact(): checking for rinstance 6(3055) DEBUG: ims_usrloc_pcscf [udomain.c:480]: get_pcontact(): no rinstance param
 6(3055) DEBUG: ims_usrloc_pcscf [usrloc.c:148]: get_aor_hash(): Returning hash: [2892500256]
 6(3055) DEBUG: ims_usrloc_pcscf [udomain.c:503]: get_pcontact(): get_pcontact slot is [288]
 6(3055) DEBUG: ims_usrloc_pcscf [udomain.c:507]: get_pcontact(): comparing contact with aorhash [2892500256], aor [sip:alice@192.168.99.52:5060;transport=udp;registering_acc=fast-ims_in]
 6(3055) DEBUG: ims_usrloc_pcscf [udomain.c:508]: get_pcontact():   contact host [192.168.99.52:5060]
 6(3055) DEBUG: ims_usrloc_pcscf [udomain.c:509]: get_pcontact(): contact received [1:192.168.99.52:5060]
 6(3055) DEBUG: ims_usrloc_pcscf [udomain.c:519]: get_pcontact(): found contact with URI [sip:alice@192.168.99.52:5060;transport=udp;registering_acc=fast-ims_in]
 6(3055) DEBUG: ims_registrar_pcscf [service_routes.c:121]: checkcontact(): Port 5060 (search 5060), Proto 1 (search 1), reg_state registered (search registered)
 6(3055) DEBUG: ims_registrar_pcscf [service_routes.c:149]: checkcontact(): Received host len 13 (search 13)
 6(3055) DEBUG: ims_registrar_pcscf [service_routes.c:154]: checkcontact(): Received host 192.168.99.52 (search 192.168.99.52)
 6(3055) DEBUG: ims_registrar_pcscf [service_routes.c:158]: checkcontact(): check contact passed
 6(3055) DEBUG: ims_registrar_pcscf [service_routes.c:304]: getContactP(): Trying to set asserted identity field 6(3055) DEBUG: ims_registrar_pcscf [service_routes.c:308]: getContactP(): Checking through contact users 6(3055) DEBUG: ims_registrar_pcscf [service_routes.c:310]: getContactP(): Found default contact user so setting asserted identity 6(3055) DEBUG: ims_registrar_pcscf [service_routes.c:317]: getContactP(): Have set the asserted_identity param to [sip:alice@fast-ims.in]
 6(3055) DEBUG: siputils [chargingvector.c:293]: sip_get_charging_vector(): No valid P-Charging-Vector header found.
 6(3055) DEBUG: siputils [chargingvector.c:133]: sip_generate_charging_vector(): PCV generate
 6(3055) DEBUG: siputils [chargingvector.c:163]: sip_parse_charging_vector(): parsing PCV header [icid-value=4956537F000101EF0B00000900000000; icid-generated-at=192.168.99.237
]
 6(3055) DEBUG: siputils [chargingvector.c:173]: sip_parse_charging_vector(): parsed P-Charging-Vector icid-value=4956537F000101EF0B00000900000000
 6(3055) DEBUG: siputils [chargingvector.c:188]: sip_parse_charging_vector(): parsed P-Charging-Vector icid-generated-at=192.168.99.237
 6(3055) INFO: siputils [chargingvector.c:432]: sip_handle_pcv(): Generated PCV header P-Charging-Vector: icid-value=4956537F000101EF0B00000900000000; icid-generated-at=192.168.99.237
 6(3055) DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=9
 6(3055) DEBUG: ims_registrar_pcscf [service_routes.c:673]: assert_identity(): Identity to assert: sip:alice@fast-ims.in
 6(3055) DEBUG: ims_registrar_pcscf [service_routes.c:186]: getContactP(): number of service routes to look for is 0
 6(3055) DEBUG: ims_registrar_pcscf [service_routes.c:210]: getContactP(): This is a request - using first via to find contact
 6(3055) DEBUG: ims_registrar_pcscf [service_routes.c:218]: getContactP(): searching for contact with host:port:proto contact [1://192.168.99.52:5060]
 6(3055) DEBUG: ims_usrloc_pcscf [udomain.c:459]: get_pcontact(): Searching for contact with AOR [sip:alice@192.168.99.52:5060;transport=udp;registering_acc=fast-ims_in] in P-CSCF usrloc based on VIA [1://192.168.99.52:5060] Received [1://192.168.99.52:5060], Search flag is 0
 6(3055) DEBUG: ims_usrloc_pcscf [udomain.c:463]: get_pcontact(): Have an AOR to search for
 6(3055) DEBUG: ims_usrloc_pcscf [udomain.c:468]: get_pcontact(): checking for rinstance 6(3055) DEBUG: ims_usrloc_pcscf [udomain.c:480]: get_pcontact(): no rinstance param
 6(3055) DEBUG: ims_usrloc_pcscf [usrloc.c:148]: get_aor_hash(): Returning hash: [2892500256]
 6(3055) DEBUG: ims_usrloc_pcscf [udomain.c:503]: get_pcontact(): get_pcontact slot is [288]
 6(3055) DEBUG: ims_usrloc_pcscf [udomain.c:507]: get_pcontact(): comparing contact with aorhash [2892500256], aor [sip:alice@192.168.99.52:5060;transport=udp;registering_acc=fast-ims_in]
 6(3055) DEBUG: ims_usrloc_pcscf [udomain.c:508]: get_pcontact():   contact host [192.168.99.52:5060]
 6(3055) DEBUG: ims_usrloc_pcscf [udomain.c:509]: get_pcontact(): contact received [1:192.168.99.52:5060]
 6(3055) DEBUG: ims_usrloc_pcscf [udomain.c:519]: get_pcontact(): found contact with URI [sip:alice@192.168.99.52:5060;transport=udp;registering_acc=fast-ims_in]
 6(3055) DEBUG: ims_registrar_pcscf [service_routes.c:121]: checkcontact(): Port 5060 (search 5060), Proto 1 (search 1), reg_state registered (search registered)
 6(3055) DEBUG: ims_registrar_pcscf [service_routes.c:149]: checkcontact(): Received host len 13 (search 13)
 6(3055) DEBUG: ims_registrar_pcscf [service_routes.c:154]: checkcontact(): Received host 192.168.99.52 (search 192.168.99.52)
 6(3055) DEBUG: ims_registrar_pcscf [service_routes.c:158]: checkcontact(): check contact passed
 6(3055) DEBUG: ims_registrar_pcscf [service_routes.c:304]: getContactP(): Trying to set asserted identity field 6(3055) DEBUG: ims_registrar_pcscf [service_routes.c:308]: getContactP(): Checking through contact users 6(3055) DEBUG: ims_registrar_pcscf [service_routes.c:310]: getContactP(): Found default contact user so setting asserted identity 6(3055) DEBUG: ims_registrar_pcscf [service_routes.c:317]: getContactP(): Have set the asserted_identity param to [sip:alice@fast-ims.in]
 6(3055) DEBUG: ims_registrar_pcscf [service_routes.c:677]: assert_identity(): Public identity: sip:alice@fast-ims.in
 6(3055) DEBUG: ims_registrar_pcscf [service_routes.c:682]: assert_identity(): Match!
 6(3055) DEBUG: ims_registrar_pcscf [service_routes.c:63]: find_first_route(): No Route headers found
 6(3055) DEBUG: ims_usrloc_pcscf [usrloc.c:148]: get_aor_hash(): Returning hash: [2892500256]
 6(3055) DEBUG: ims_usrloc_pcscf [usrloc.c:139]: get_hash_slot(): Returning hash slot: [288]
 6(3055) DEBUG: ims_registrar_pcscf [service_routes.c:430]: check_service_routes(): Request doesn't have any route headers to check service-route...ignoring
 6(3055) DEBUG: ims_usrloc_pcscf [usrloc.c:148]: get_aor_hash(): Returning hash: [2892500256]
 6(3055) DEBUG: ims_usrloc_pcscf [usrloc.c:139]: get_hash_slot(): Returning hash slot: [288]
 6(3055) DEBUG: ims_registrar_pcscf [service_routes.c:186]: getContactP(): number of service routes to look for is 0
 6(3055) DEBUG: ims_registrar_pcscf [service_routes.c:210]: getContactP(): This is a request - using first via to find contact
 6(3055) DEBUG: ims_registrar_pcscf [service_routes.c:218]: getContactP(): searching for contact with host:port:proto contact [1://192.168.99.52:5060]
 6(3055) DEBUG: ims_usrloc_pcscf [udomain.c:459]: get_pcontact(): Searching for contact with AOR [sip:alice@192.168.99.52:5060;transport=udp;registering_acc=fast-ims_in] in P-CSCF usrloc based on VIA [1://192.168.99.52:5060] Received [1://192.168.99.52:5060], Search flag is 0
 6(3055) DEBUG: ims_usrloc_pcscf [udomain.c:463]: get_pcontact(): Have an AOR to search for
 6(3055) DEBUG: ims_usrloc_pcscf [udomain.c:468]: get_pcontact(): checking for rinstance 6(3055) DEBUG: ims_usrloc_pcscf [udomain.c:480]: get_pcontact(): no rinstance param
 6(3055) DEBUG: ims_usrloc_pcscf [usrloc.c:148]: get_aor_hash(): Returning hash: [2892500256]
 6(3055) DEBUG: ims_usrloc_pcscf [udomain.c:503]: get_pcontact(): get_pcontact slot is [288]
 6(3055) DEBUG: ims_usrloc_pcscf [udomain.c:507]: get_pcontact(): comparing contact with aorhash [2892500256], aor [sip:alice@192.168.99.52:5060;transport=udp;registering_acc=fast-ims_in]
 6(3055) DEBUG: ims_usrloc_pcscf [udomain.c:508]: get_pcontact():   contact host [192.168.99.52:5060]
 6(3055) DEBUG: ims_usrloc_pcscf [udomain.c:509]: get_pcontact(): contact received [1:192.168.99.52:5060]
 6(3055) DEBUG: ims_usrloc_pcscf [udomain.c:519]: get_pcontact(): found contact with URI [sip:alice@192.168.99.52:5060;transport=udp;registering_acc=fast-ims_in]
 6(3055) DEBUG: ims_registrar_pcscf [service_routes.c:121]: checkcontact(): Port 5060 (search 5060), Proto 1 (search 1), reg_state registered (search registered)
 6(3055) DEBUG: ims_registrar_pcscf [service_routes.c:149]: checkcontact(): Received host len 13 (search 13)
 6(3055) DEBUG: ims_registrar_pcscf [service_routes.c:154]: checkcontact(): Received host 192.168.99.52 (search 192.168.99.52)
 6(3055) DEBUG: ims_registrar_pcscf [service_routes.c:158]: checkcontact(): check contact passed
 6(3055) DEBUG: ims_registrar_pcscf [service_routes.c:304]: getContactP(): Trying to set asserted identity field 6(3055) DEBUG: ims_registrar_pcscf [service_routes.c:308]: getContactP(): Checking through contact users 6(3055) DEBUG: ims_registrar_pcscf [service_routes.c:310]: getContactP(): Found default contact user so setting asserted identity 6(3055) DEBUG: ims_registrar_pcscf [service_routes.c:317]: getContactP(): Have set the asserted_identity param to [sip:alice@fast-ims.in]
 6(3055) DEBUG: ims_usrloc_pcscf [usrloc.c:148]: get_aor_hash(): Returning hash: [2892500256]
 6(3055) DEBUG: ims_usrloc_pcscf [usrloc.c:139]: get_hash_slot(): Returning hash slot: [288]
 6(3055) DEBUG: ims_registrar_pcscf [service_routes.c:605]: force_service_routes(): Setting route header to <Route: <sip:orig@scscf.fast-ims.in;lr>
> 
 6(3055) DEBUG: ims_registrar_pcscf [service_routes.c:614]: force_service_routes(): Setting dst_uri to <sip:orig@scscf.fast-ims.in;lr> 
 6(3055) DEBUG: ims_usrloc_pcscf [usrloc.c:148]: get_aor_hash(): Returning hash: [2892500256]
 6(3055) DEBUG: ims_usrloc_pcscf [usrloc.c:139]: get_hash_slot(): Returning hash slot: [288]
 6(3055) DEBUG: tm [t_lookup.c:1320]: t_newtran(): msg id=1 , global msg id=1 , T on entrance=(nil)
 6(3055) DEBUG: tm [t_lookup.c:477]: t_lookup_request(): start searching: hash=13106, isACK=0
 6(3055) DEBUG: tm [t_lookup.c:435]: matching_3261(): RFC3261 transaction matching failed
 6(3055) DEBUG: tm [t_lookup.c:659]: t_lookup_request(): no transaction found
 6(3055) DEBUG: tm [t_hooks.c:349]: run_reqin_callbacks_internal(): trans=0x7fa72fbcb638, callback type 1, id 0 entered
 6(3055) DEBUG: <core> [core/md5utils.c:67]: MD5StringArray(): MD5 calculated: d0f38d354d4474f0c0e6018840d50851
 6(3055) DEBUG: <core> [core/dns_cache.c:542]: _dns_hash_find(): (_sip._udp.scscf.fast-ims.in(27), 33), h=146
 6(3055) DEBUG: <core> [core/resolve.c:937]: get_record(): skipping 1 NS (p=0xa8b2d2, end=0xa8b303)
 6(3055) DEBUG: <core> [core/resolve.c:952]: get_record(): parsing 2 ARs (p=0xa8b2e3, end=0xa8b303)
 6(3055) DEBUG: <core> [core/dns_cache.c:1748]: dns_get_related(): (0x7fa72fbce1f0 (_sip._udp.scscf.fast-ims.in, 33), 33, *0x7fa73a5e7000) (0)
 6(3055) DEBUG: <core> [core/dns_cache.c:847]: dns_cache_add_unsafe(): adding _sip._udp.scscf.fast-ims.in(27) 33 (flags=0) at 146
 6(3055) DEBUG: <core> [core/dns_cache.c:847]: dns_cache_add_unsafe(): adding scscf.fast-ims.in(17) 1 (flags=0) at 1022
 6(3055) DEBUG: <core> [core/dns_cache.c:2348]: dns_srv_get_nxt_rr(): (0x7fa72fbce1f0, 0, 0, 595539622): selected 0/1 in grp. 0 (rand_w=0, rr=0x7fa72fbce250 rd=0x7fa72fbce268 p=0 w=0 rsum=0)
 6(3055) DEBUG: <core> [core/dns_cache.c:542]: _dns_hash_find(): (scscf.fast-ims.in(17), 1), h=1022
 6(3055) DEBUG: <core> [core/dns_cache.c:2957]: dns_a_resolve(): (scscf.fast-ims.in, 0) returning 0
 6(3055) DEBUG: <core> [core/dns_cache.c:3200]: dns_srv_resolve_ip(): ("_sip._udp.scscf.fast-ims.in", 0, 0), ret=0, ip=192.168.99.237
 6(3055) DEBUG: <core> [core/dns_cache.c:3296]: dns_srv_sip_resolve(): (scscf.fast-ims.in, 0, 0), srv0, ret=0
 6(3055) DEBUG: <core> [core/msg_translator.c:159]: check_via_address(): (192.168.99.52, 192.168.99.52, 0)
 1(3050) DEBUG: <core> [core/parser/msg_parser.c:610]: parse_msg(): SIP Reply  (status):
 1(3050) DEBUG: <core> [core/parser/msg_parser.c:612]: parse_msg():  version: <SIP/2.0>
 1(3050) DEBUG: <core> [core/parser/msg_parser.c:614]: parse_msg():  status:  <200>
 1(3050) DEBUG: <core> [core/parser/msg_parser.c:616]: parse_msg():  reason:  <OK>
 1(3050) DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>: <1> <OPTIONS>
 1(3050) DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=1540cd406f0926f14f2218028ad14659.0310
 1(3050) DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29
 1(3050) DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): <To> [75]; uri=[sip:alice@fast-ims.in]
 1(3050) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body ["alice" <sip:alice@fast-ims.in>]
 1(3050) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK2333.d0f38d354d4474f0c0e6018840d50851.0>; state=16
 1(3050) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
 1(3050) DEBUG: <core> [core/parser/msg_parser.c:491]: parse_headers(): Via found, flags=2
 1(3050) DEBUG: <core> [core/parser/msg_parser.c:493]: parse_headers(): this is the first via
 1(3050) DEBUG: <core> [core/receive.c:191]: receive_msg(): --- received sip message - reply - call-id: [f69127cf4a25ac7a2c5cac8f53e6c750@0:0:0:0:0:0:0:0] - cseq: [1 OPTIONS]
 1(3050) DEBUG: tm [t_lookup.c:1019]: t_check_msg(): msg (0x7fa73a61b4c0) id=1 global id=0 T start=0xffffffffffffffff
 1(3050) DEBUG: tm [t_lookup.c:897]: t_reply_matching(): t_reply_matching: hash 13106 label 0 branch 0
 1(3050) DEBUG: tm [t_lookup.c:951]: t_reply_matching(): reply (0x7fa73a61b4c0) matched an active transaction (T=0x7fa72fbcb638)!
 1(3050) DEBUG: tm [t_lookup.c:1088]: t_check_msg(): msg (0x7fa73a61b4c0) id=1 global id=1 T end=0x7fa72fbcb638
 1(3050) DEBUG: tm [t_reply.c:2200]: reply_received(): org. status uas=0, uac[0]=0 local=0 is_invite=0)
 1(3050) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 235, <rport> = <5060>; state=6
 1(3050) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK-333432-f245c7db1dc636dc29dfffd2b56e55ea>; state=16
 1(3050) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
 1(3050) DEBUG: <core> [core/parser/msg_parser.c:491]: parse_headers(): Via found, flags=ffffffffffffffff
 1(3050) DEBUG: <core> [core/parser/msg_parser.c:504]: parse_headers(): this is the second via
 1(3050) DEBUG: <core> [core/parser/msg_parser.c:183]: get_hdr_field(): content_length=0
 1(3050) DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): found end of header
 1(3050) DEBUG: <core> [core/parser/msg_parser.c:600]: parse_msg(): SIP Request:
 1(3050) DEBUG: <core> [core/parser/msg_parser.c:602]: parse_msg():  method:  <OPTIONS>
 1(3050) DEBUG: <core> [core/parser/msg_parser.c:604]: parse_msg():  uri:     <sip:fast-ims.in>
 1(3050) DEBUG: <core> [core/parser/msg_parser.c:606]: parse_msg():  version: <SIP/2.0>
 1(3050) DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>: <1> <OPTIONS>
 1(3050) DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=10
 1(3050) DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): <To> [33]; uri=[sip:alice@fast-ims.in]
 1(3050) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body ["alice" <sip:alice@fast-ims.in>
]
 1(3050) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK-333432-f245c7db1dc636dc29dfffd2b56e55ea>; state=16
 1(3050) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
 1(3050) DEBUG: <core> [core/parser/msg_parser.c:491]: parse_headers(): Via found, flags=2
 1(3050) DEBUG: <core> [core/parser/msg_parser.c:493]: parse_headers(): this is the first via
 1(3050) DEBUG: pv [pv_core.c:388]: pv_get_xto_attr(): no Tag parameter
 1(3050) DEBUG: textops [textops.c:2626]: has_body_f(): content length is zero
 1(3050) DEBUG: tm [t_reply.c:1265]: t_should_relay_response(): ->>>>>>>>> T_code=0, new_code=200
 1(3050) DEBUG: tm [t_reply.c:1786]: relay_reply(): branch=0, save=0, relay=0 icode=0
 1(3050) DEBUG: <core> [core/msg_translator.c:2265]: generate_res_buf_from_sip_res(): old size: 514, new size: 427
 1(3050) DEBUG: <core> [core/msg_translator.c:2283]: generate_res_buf_from_sip_res(): copied size: orig:309, new: 222, rest: 205 msg=
SIP/2.0 200 OK
Call-ID: f69127cf4a25ac7a2c5cac8f53e6c750@0:0:0:0:0:0:0:0
CSeq: 1 OPTIONS
From: "alice" <sip:alice@fast-ims.in>;tag=48ca0ce
To: "alice" <sip:alice@fast-ims.in>;tag=1540cd406f0926f14f2218028ad14659.0310
Via: SIP/2.0/UDP 192.168.99.52:5060;rport=5060;branch=z9hG4bK-333432-f245c7db1dc636dc29dfffd2b56e55ea
Accept: */*
Accept-Encoding: 
Accept-Language: en
Supported: 
Server:scscf1
Content-Length: 0


 1(3050) DEBUG: tm [t_reply.c:1629]: cleanup_uac_timers(): RETR/FR timers reset
 1(3050) DEBUG: <core> [core/receive.c:348]: receive_msg(): reply-route executed in: 681 usec
 1(3050) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
 1(3050) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
 1(3050) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
 1(3050) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
 1(3050) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
 1(3050) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
 1(3050) DEBUG: <core> [core/xavp.c:446]: xavp_destroy_list(): destroying xavp list (nil)
 1(3050) DEBUG: <core> [core/receive.c:364]: receive_msg(): cleaning up
 6(3055) DEBUG: tm [timer.h:214]: _set_fr_retr(): too late, timer already marked for deletion
 6(3055) DEBUG: tm [t_funcs.c:368]: t_relay_to(): SER: new transaction fwd'ed
 6(3055) DEBUG: <core> [core/receive.c:275]: receive_msg(): request-route executed in: 2573 usec
 6(3055) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
 6(3055) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
 6(3055) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
 6(3055) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
 6(3055) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
 6(3055) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
 6(3055) DEBUG: <core> [core/xavp.c:446]: xavp_destroy_list(): destroying xavp list (nil)
 6(3055) DEBUG: <core> [core/receive.c:364]: receive_msg(): cleaning up
13(3062) DEBUG: <core> [core/resolve.c:952]: get_record(): parsing 2 ARs (p=0xa8b2e3, end=0xa8b303)
13(3062) DEBUG: <core> [core/dns_cache.c:1748]: dns_get_related(): (0x7fa72fbceb48 (_sip._udp.scscf.fast-ims.in, 33), 33, *0x7fa73a5d8df0) (0)
 3(3052) DEBUG: <core> [core/resolve.c:952]: get_record(): parsing 2 ARs (p=0xa8b2e3, end=0xa8b303)
 3(3052) DEBUG: <core> [core/dns_cache.c:1748]: dns_get_related(): (0x7fa72fbcec48 (_sip._udp.scscf.fast-ims.in, 33), 33, *0x7fa73a5d8df0) (0)
 3(3052) DEBUG: <core> [core/dns_cache.c:847]: dns_cache_add_unsafe(): adding _sip._udp.scscf.fast-ims.in(27) 33 (flags=0) at 146
 3(3052) DEBUG: <core> [core/dns_cache.c:847]: dns_cache_add_unsafe(): adding scscf.fast-ims.in(17) 1 (flags=0) at 1022
 3(3052) DEBUG: <core> [core/dns_cache.c:2348]: dns_srv_get_nxt_rr(): (0x7fa72fbcec48, 0, 0, 595539622): selected 0/1 in grp. 0 (rand_w=0, rr=0x7fa72fbceca8 rd=0x7fa72fbcecc0 p=0 w=0 rsum=0)
13(3062) DEBUG: <core> [core/dns_cache.c:847]: dns_cache_add_unsafe(): adding _sip._udp.scscf.fast-ims.in(27) 33 (flags=0) at 146
13(3062) DEBUG: <core> [core/dns_cache.c:847]: dns_cache_add_unsafe(): adding scscf.fast-ims.in(17) 1 (flags=0) at 1022
13(3062) DEBUG: <core> [core/dns_cache.c:2348]: dns_srv_get_nxt_rr(): (0x7fa72fbceb48, 0, 0, 595539622): selected 0/1 in grp. 0 (rand_w=0, rr=0x7fa72fbceba8 rd=0x7fa72fbcebc0 p=0 w=0 rsum=0)
 3(3052) DEBUG: <core> [core/dns_cache.c:542]: _dns_hash_find(): (scscf.fast-ims.in(17), 1), h=1022
 3(3052) DEBUG: <core> [core/dns_cache.c:2957]: dns_a_resolve(): (scscf.fast-ims.in, 0) returning 0
 3(3052) DEBUG: <core> [core/dns_cache.c:3200]: dns_srv_resolve_ip(): ("_sip._udp.scscf.fast-ims.in", 0, 0), ret=0, ip=192.168.99.237
 3(3052) DEBUG: <core> [core/dns_cache.c:3296]: dns_srv_sip_resolve(): (scscf.fast-ims.in, 0, 0), srv0, ret=0
13(3062) DEBUG: <core> [core/dns_cache.c:542]: _dns_hash_find(): (scscf.fast-ims.in(17), 1), h=1022
 3(3052) DEBUG: <core> [core/msg_translator.c:159]: check_via_address(): (192.168.99.52, 192.168.99.52, 0)
13(3062) DEBUG: <core> [core/dns_cache.c:2957]: dns_a_resolve(): (scscf.fast-ims.in, 0) returning 0
13(3062) DEBUG: <core> [core/dns_cache.c:3200]: dns_srv_resolve_ip(): ("_sip._udp.scscf.fast-ims.in", 0, 0), ret=0, ip=192.168.99.237
13(3062) DEBUG: <core> [core/dns_cache.c:3296]: dns_srv_sip_resolve(): (scscf.fast-ims.in, 0, 0), srv0, ret=0
13(3062) DEBUG: <core> [core/msg_translator.c:159]: check_via_address(): (192.168.99.52, 192.168.99.52, 0)
 2(3051) DEBUG: <core> [core/parser/msg_parser.c:600]: parse_msg(): SIP Request:
 2(3051) DEBUG: <core> [core/parser/msg_parser.c:602]: parse_msg():  method:  <PUBLISH>
 2(3051) DEBUG: <core> [core/parser/msg_parser.c:604]: parse_msg():  uri:     <sip:alice@fast-ims.in>
 2(3051) DEBUG: <core> [core/parser/msg_parser.c:606]: parse_msg():  version: <SIP/2.0>
 2(3051) DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>: <1> <PUBLISH>
 2(3051) DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=10
 2(3051) DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): <To> [33]; uri=[sip:alice@fast-ims.in]
 2(3051) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body ["alice" <sip:alice@fast-ims.in>
]
 2(3051) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK-333432-0bf01678a40903ef6aa498c6f497909e>; state=16
 2(3051) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
 2(3051) DEBUG: <core> [core/parser/msg_parser.c:491]: parse_headers(): Via found, flags=2
 2(3051) DEBUG: <core> [core/parser/msg_parser.c:493]: parse_headers(): this is the first via
 2(3051) DEBUG: <core> [core/receive.c:191]: receive_msg(): --- received sip message - request - call-id: [6312689dc372ef9f6c3ae4697187479b@0:0:0:0:0:0:0:0] - cseq: [1 PUBLISH]
 2(3051) DEBUG: <core> [core/receive.c:234]: receive_msg(): preparing to run routing scripts...
 2(3051) DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=95539ec8
 2(3051) DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29
 2(3051) ERROR: <script>: PUBLISH (sip:alice@fast-ims.in (192.168.99.52:5060) to sip:alice@fast-ims.in, 6312689dc372ef9f6c3ae4697187479b@0:0:0:0:0:0:0:0)
 2(3051) DEBUG: <script>: Mem: Total 67108864, Free 63884688 [1% used]
 2(3051) DEBUG: maxfwd [mf_funcs.c:76]: is_maxfwd_present(): value = 70 
 2(3051) DEBUG: <core> [core/parser/msg_parser.c:183]: get_hdr_field(): content_length=411
 2(3051) DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): found end of header
 2(3051) DEBUG: sanity [sanity_mod.c:256]: w_sanity_check(): sanity checks result: 1
 2(3051) DEBUG: siputils [checks.c:120]: has_totag(): no totag
 2(3051) DEBUG: <core> [core/select.c:412]: run_select(): Calling SELECT 0x7fa73a5148e8
 2(3051) DEBUG: tm [t_lookup.c:1019]: t_check_msg(): msg (0x7fa73a61b4c0) id=1 global id=0 T start=0xffffffffffffffff
 2(3051) DEBUG: tm [t_lookup.c:477]: t_lookup_request(): start searching: hash=616, isACK=0
 2(3051) DEBUG: tm [t_lookup.c:435]: matching_3261(): RFC3261 transaction matching failed
 2(3051) DEBUG: tm [t_lookup.c:659]: t_lookup_request(): no transaction found
 2(3051) DEBUG: tm [t_lookup.c:1088]: t_check_msg(): msg (0x7fa73a61b4c0) id=1 global id=1 T end=(nil)
 2(3051) DEBUG: siputils [checks.c:120]: has_totag(): no totag
 2(3051) DEBUG: tm [t_lookup.c:1019]: t_check_msg(): msg (0x7fa73a61b4c0) id=1 global id=1 T start=(nil)
 2(3051) DEBUG: tm [t_lookup.c:1094]: t_check_msg(): T previously sought and not found for msg (0x7fa73a61b4c0)
 2(3051) DEBUG: tm [t_lookup.c:1019]: t_check_msg(): msg (0x7fa73a61b4c0) id=1 global id=1 T start=(nil)
 2(3051) DEBUG: tm [t_lookup.c:1094]: t_check_msg(): T previously sought and not found for msg (0x7fa73a61b4c0)
 2(3051) DEBUG: rr [loose.c:112]: find_first_route(): No Route headers found
 2(3051) DEBUG: rr [loose.c:944]: loose_route(): There is no Route HF
 2(3051) INFO: rr [rr_mod.c:443]: pv_get_route_uri_f(): No route header present.
 2(3051) DEBUG: <core> [core/re.c:436]: subst_run(): running. r=1
 2(3051) DEBUG: <core> [core/re.c:504]: subst_str(): no match
 2(3051) DEBUG: textops [txt_var.c:92]: tr_txt_eval_re(): no match for subst expression
 2(3051) DEBUG: rr [loose.c:112]: find_first_route(): No Route headers found
 2(3051) DEBUG: rr [loose.c:944]: loose_route(): There is no Route HF
 2(3051) DEBUG: ims_registrar_pcscf [service_routes.c:186]: getContactP(): number of service routes to look for is 0
 2(3051) DEBUG: ims_registrar_pcscf [service_routes.c:210]: getContactP(): This is a request - using first via to find contact
 2(3051) DEBUG: ims_registrar_pcscf [service_routes.c:218]: getContactP(): searching for contact with host:port:proto contact [1://192.168.99.52:5060]
 2(3051) DEBUG: ims_usrloc_pcscf [udomain.c:459]: get_pcontact(): Searching for contact with AOR [sip:alice@192.168.99.52:5060;transport=udp;registering_acc=fast-ims_in] in P-CSCF usrloc based on VIA [1://192.168.99.52:5060] Received [1://192.168.99.52:5060], Search flag is 0
 2(3051) DEBUG: ims_usrloc_pcscf [udomain.c:463]: get_pcontact(): Have an AOR to search for
 2(3051) DEBUG: ims_usrloc_pcscf [udomain.c:468]: get_pcontact(): checking for rinstance 2(3051) DEBUG: ims_usrloc_pcscf [udomain.c:480]: get_pcontact(): no rinstance param
 2(3051) DEBUG: ims_usrloc_pcscf [usrloc.c:148]: get_aor_hash(): Returning hash: [2892500256]
 2(3051) DEBUG: ims_usrloc_pcscf [udomain.c:503]: get_pcontact(): get_pcontact slot is [288]
 2(3051) DEBUG: ims_usrloc_pcscf [udomain.c:507]: get_pcontact(): comparing contact with aorhash [2892500256], aor [sip:alice@192.168.99.52:5060;transport=udp;registering_acc=fast-ims_in]
 2(3051) DEBUG: ims_usrloc_pcscf [udomain.c:508]: get_pcontact():   contact host [192.168.99.52:5060]
 2(3051) DEBUG: ims_usrloc_pcscf [udomain.c:509]: get_pcontact(): contact received [1:192.168.99.52:5060]
 2(3051) DEBUG: ims_usrloc_pcscf [udomain.c:519]: get_pcontact(): found contact with URI [sip:alice@192.168.99.52:5060;transport=udp;registering_acc=fast-ims_in]
 2(3051) DEBUG: ims_registrar_pcscf [service_routes.c:121]: checkcontact(): Port 5060 (search 5060), Proto 1 (search 1), reg_state registered (search registered)
 2(3051) DEBUG: ims_registrar_pcscf [service_routes.c:149]: checkcontact(): Received host len 13 (search 13)
 2(3051) DEBUG: ims_registrar_pcscf [service_routes.c:154]: checkcontact(): Received host 192.168.99.52 (search 192.168.99.52)
 2(3051) DEBUG: ims_registrar_pcscf [service_routes.c:158]: checkcontact(): check contact passed
 2(3051) DEBUG: ims_registrar_pcscf [service_routes.c:304]: getContactP(): Trying to set asserted identity field 2(3051) DEBUG: ims_registrar_pcscf [service_routes.c:308]: getContactP(): Checking through contact users 2(3051) DEBUG: ims_registrar_pcscf [service_routes.c:310]: getContactP(): Found default contact user so setting asserted identity 2(3051) DEBUG: ims_registrar_pcscf [service_routes.c:317]: getContactP(): Have set the asserted_identity param to [sip:alice@fast-ims.in]
 2(3051) DEBUG: siputils [chargingvector.c:293]: sip_get_charging_vector(): No valid P-Charging-Vector header found.
 2(3051) DEBUG: siputils [chargingvector.c:133]: sip_generate_charging_vector(): PCV generate
 2(3051) DEBUG: siputils [chargingvector.c:163]: sip_parse_charging_vector(): parsing PCV header [icid-value=4956537F000101EB0B00000900000000; icid-generated-at=192.168.99.237
]
 2(3051) DEBUG: siputils [chargingvector.c:173]: sip_parse_charging_vector(): parsed P-Charging-Vector icid-value=4956537F000101EB0B00000900000000
 2(3051) DEBUG: siputils [chargingvector.c:188]: sip_parse_charging_vector(): parsed P-Charging-Vector icid-generated-at=192.168.99.237
 2(3051) INFO: siputils [chargingvector.c:432]: sip_handle_pcv(): Generated PCV header P-Charging-Vector: icid-value=4956537F000101EB0B00000900000000; icid-generated-at=192.168.99.237
 2(3051) DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=9
 2(3051) DEBUG: ims_registrar_pcscf [service_routes.c:673]: assert_identity(): Identity to assert: sip:alice@fast-ims.in
 2(3051) DEBUG: ims_registrar_pcscf [service_routes.c:186]: getContactP(): number of service routes to look for is 0
 2(3051) DEBUG: ims_registrar_pcscf [service_routes.c:210]: getContactP(): This is a request - using first via to find contact
 2(3051) DEBUG: ims_registrar_pcscf [service_routes.c:218]: getContactP(): searching for contact with host:port:proto contact [1://192.168.99.52:5060]
 2(3051) DEBUG: ims_usrloc_pcscf [udomain.c:459]: get_pcontact(): Searching for contact with AOR [sip:alice@192.168.99.52:5060;transport=udp;registering_acc=fast-ims_in] in P-CSCF usrloc based on VIA [1://192.168.99.52:5060] Received [1://192.168.99.52:5060], Search flag is 0
 2(3051) DEBUG: ims_usrloc_pcscf [udomain.c:463]: get_pcontact(): Have an AOR to search for
 2(3051) DEBUG: ims_usrloc_pcscf [udomain.c:468]: get_pcontact(): checking for rinstance 2(3051) DEBUG: ims_usrloc_pcscf [udomain.c:480]: get_pcontact(): no rinstance param
 2(3051) DEBUG: ims_usrloc_pcscf [usrloc.c:148]: get_aor_hash(): Returning hash: [2892500256]
 2(3051) DEBUG: ims_usrloc_pcscf [udomain.c:503]: get_pcontact(): get_pcontact slot is [288]
 2(3051) DEBUG: ims_usrloc_pcscf [udomain.c:507]: get_pcontact(): comparing contact with aorhash [2892500256], aor [sip:alice@192.168.99.52:5060;transport=udp;registering_acc=fast-ims_in]
 2(3051) DEBUG: ims_usrloc_pcscf [udomain.c:508]: get_pcontact():   contact host [192.168.99.52:5060]
 2(3051) DEBUG: ims_usrloc_pcscf [udomain.c:509]: get_pcontact(): contact received [1:192.168.99.52:5060]
 2(3051) DEBUG: ims_usrloc_pcscf [udomain.c:519]: get_pcontact(): found contact with URI [sip:alice@192.168.99.52:5060;transport=udp;registering_acc=fast-ims_in]
 2(3051) DEBUG: ims_registrar_pcscf [service_routes.c:121]: checkcontact(): Port 5060 (search 5060), Proto 1 (search 1), reg_state registered (search registered)
 2(3051) DEBUG: ims_registrar_pcscf [service_routes.c:149]: checkcontact(): Received host len 13 (search 13)
 2(3051) DEBUG: ims_registrar_pcscf [service_routes.c:154]: checkcontact(): Received host 192.168.99.52 (search 192.168.99.52)
 2(3051) DEBUG: ims_registrar_pcscf [service_routes.c:158]: checkcontact(): check contact passed
 2(3051) DEBUG: ims_registrar_pcscf [service_routes.c:304]: getContactP(): Trying to set asserted identity field 2(3051) DEBUG: ims_registrar_pcscf [service_routes.c:308]: getContactP(): Checking through contact users 2(3051) DEBUG: ims_registrar_pcscf [service_routes.c:310]: getContactP(): Found default contact user so setting asserted identity 2(3051) DEBUG: ims_registrar_pcscf [service_routes.c:317]: getContactP(): Have set the asserted_identity param to [sip:alice@fast-ims.in]
 2(3051) DEBUG: ims_registrar_pcscf [service_routes.c:677]: assert_identity(): Public identity: sip:alice@fast-ims.in
 2(3051) DEBUG: ims_registrar_pcscf [service_routes.c:682]: assert_identity(): Match!
 2(3051) DEBUG: ims_registrar_pcscf [service_routes.c:63]: find_first_route(): No Route headers found
 2(3051) DEBUG: ims_usrloc_pcscf [usrloc.c:148]: get_aor_hash(): Returning hash: [2892500256]
 2(3051) DEBUG: ims_usrloc_pcscf [usrloc.c:139]: get_hash_slot(): Returning hash slot: [288]
 2(3051) DEBUG: ims_registrar_pcscf [service_routes.c:430]: check_service_routes(): Request doesn't have any route headers to check service-route...ignoring
 2(3051) DEBUG: ims_usrloc_pcscf [usrloc.c:148]: get_aor_hash(): Returning hash: [2892500256]
 2(3051) DEBUG: ims_usrloc_pcscf [usrloc.c:139]: get_hash_slot(): Returning hash slot: [288]
 2(3051) DEBUG: ims_registrar_pcscf [service_routes.c:186]: getContactP(): number of service routes to look for is 0
 2(3051) DEBUG: ims_registrar_pcscf [service_routes.c:210]: getContactP(): This is a request - using first via to find contact
 2(3051) DEBUG: ims_registrar_pcscf [service_routes.c:218]: getContactP(): searching for contact with host:port:proto contact [1://192.168.99.52:5060]
 2(3051) DEBUG: ims_usrloc_pcscf [udomain.c:459]: get_pcontact(): Searching for contact with AOR [sip:alice@192.168.99.52:5060;transport=udp;registering_acc=fast-ims_in] in P-CSCF usrloc based on VIA [1://192.168.99.52:5060] Received [1://192.168.99.52:5060], Search flag is 0
 2(3051) DEBUG: ims_usrloc_pcscf [udomain.c:463]: get_pcontact(): Have an AOR to search for
 2(3051) DEBUG: ims_usrloc_pcscf [udomain.c:468]: get_pcontact(): checking for rinstance 2(3051) DEBUG: ims_usrloc_pcscf [udomain.c:480]: get_pcontact(): no rinstance param
 2(3051) DEBUG: ims_usrloc_pcscf [usrloc.c:148]: get_aor_hash(): Returning hash: [2892500256]
 2(3051) DEBUG: ims_usrloc_pcscf [udomain.c:503]: get_pcontact(): get_pcontact slot is [288]
 2(3051) DEBUG: ims_usrloc_pcscf [udomain.c:507]: get_pcontact(): comparing contact with aorhash [2892500256], aor [sip:alice@192.168.99.52:5060;transport=udp;registering_acc=fast-ims_in]
 2(3051) DEBUG: ims_usrloc_pcscf [udomain.c:508]: get_pcontact():   contact host [192.168.99.52:5060]
 2(3051) DEBUG: ims_usrloc_pcscf [udomain.c:509]: get_pcontact(): contact received [1:192.168.99.52:5060]
 2(3051) DEBUG: ims_usrloc_pcscf [udomain.c:519]: get_pcontact(): found contact with URI [sip:alice@192.168.99.52:5060;transport=udp;registering_acc=fast-ims_in]
 2(3051) DEBUG: ims_registrar_pcscf [service_routes.c:121]: checkcontact(): Port 5060 (search 5060), Proto 1 (search 1), reg_state registered (search registered)
 2(3051) DEBUG: ims_registrar_pcscf [service_routes.c:149]: checkcontact(): Received host len 13 (search 13)
 2(3051) DEBUG: ims_registrar_pcscf [service_routes.c:154]: checkcontact(): Received host 192.168.99.52 (search 192.168.99.52)
 2(3051) DEBUG: ims_registrar_pcscf [service_routes.c:158]: checkcontact(): check contact passed
 2(3051) DEBUG: ims_registrar_pcscf [service_routes.c:304]: getContactP(): Trying to set asserted identity field 2(3051) DEBUG: ims_registrar_pcscf [service_routes.c:308]: getContactP(): Checking through contact users 2(3051) DEBUG: ims_registrar_pcscf [service_routes.c:310]: getContactP(): Found default contact user so setting asserted identity 2(3051) DEBUG: ims_registrar_pcscf [service_routes.c:317]: getContactP(): Have set the asserted_identity param to [sip:alice@fast-ims.in]
 2(3051) DEBUG: ims_usrloc_pcscf [usrloc.c:148]: get_aor_hash(): Returning hash: [2892500256]
 2(3051) DEBUG: ims_usrloc_pcscf [usrloc.c:139]: get_hash_slot(): Returning hash slot: [288]
 2(3051) DEBUG: ims_registrar_pcscf [service_routes.c:605]: force_service_routes(): Setting route header to <Route: <sip:orig@scscf.fast-ims.in;lr>
> 
 2(3051) DEBUG: ims_registrar_pcscf [service_routes.c:614]: force_service_routes(): Setting dst_uri to <sip:orig@scscf.fast-ims.in;lr> 
 2(3051) DEBUG: ims_usrloc_pcscf [usrloc.c:148]: get_aor_hash(): Returning hash: [2892500256]
 2(3051) DEBUG: ims_usrloc_pcscf [usrloc.c:139]: get_hash_slot(): Returning hash slot: [288]
 2(3051) DEBUG: tm [t_lookup.c:1320]: t_newtran(): msg id=1 , global msg id=1 , T on entrance=(nil)
 2(3051) DEBUG: tm [t_lookup.c:477]: t_lookup_request(): start searching: hash=616, isACK=0
 2(3051) DEBUG: tm [t_lookup.c:435]: matching_3261(): RFC3261 transaction matching failed
 2(3051) DEBUG: tm [t_lookup.c:659]: t_lookup_request(): no transaction found
 2(3051) DEBUG: tm [t_hooks.c:349]: run_reqin_callbacks_internal(): trans=0x7fa72fbcf618, callback type 1, id 0 entered
 2(3051) DEBUG: <core> [core/md5utils.c:67]: MD5StringArray(): MD5 calculated: 63af2e9256525ccfb8c0bba93e9d39d8
 2(3051) DEBUG: <core> [core/dns_cache.c:542]: _dns_hash_find(): (_sip._udp.scscf.fast-ims.in(27), 33), h=146
 2(3051) DEBUG: <core> [core/dns_cache.c:2348]: dns_srv_get_nxt_rr(): (0x7fa72fbce1f0, 0, 0, 595539622): selected 0/1 in grp. 0 (rand_w=0, rr=0x7fa72fbce250 rd=0x7fa72fbce268 p=0 w=0 rsum=0)
 2(3051) DEBUG: <core> [core/dns_cache.c:542]: _dns_hash_find(): (scscf.fast-ims.in(17), 1), h=1022
 2(3051) DEBUG: <core> [core/dns_cache.c:2957]: dns_a_resolve(): (scscf.fast-ims.in, 0) returning 0
 2(3051) DEBUG: <core> [core/dns_cache.c:3200]: dns_srv_resolve_ip(): ("_sip._udp.scscf.fast-ims.in", 0, 0), ret=0, ip=192.168.99.237
 2(3051) DEBUG: <core> [core/dns_cache.c:3296]: dns_srv_sip_resolve(): (scscf.fast-ims.in, 0, 0), srv0, ret=0
 2(3051) DEBUG: <core> [core/msg_translator.c:159]: check_via_address(): (192.168.99.52, 192.168.99.52, 0)
 2(3051) DEBUG: tm [t_funcs.c:368]: t_relay_to(): SER: new transaction fwd'ed
 2(3051) DEBUG: <core> [core/receive.c:275]: receive_msg(): request-route executed in: 2085 usec
 2(3051) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
 2(3051) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
 2(3051) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
 2(3051) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
 2(3051) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
 2(3051) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
 2(3051) DEBUG: <core> [core/xavp.c:446]: xavp_destroy_list(): destroying xavp list (nil)
 2(3051) DEBUG: <core> [core/receive.c:364]: receive_msg(): cleaning up
 3(3052) DEBUG: tm [t_funcs.c:368]: t_relay_to(): SER: new transaction fwd'ed
 3(3052) DEBUG: <core> [core/receive.c:275]: receive_msg(): request-route executed in: 29401 usec
 3(3052) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
 3(3052) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
 3(3052) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
 3(3052) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
 3(3052) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
 3(3052) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
 3(3052) DEBUG: <core> [core/xavp.c:446]: xavp_destroy_list(): destroying xavp list (nil)
 3(3052) DEBUG: <core> [core/receive.c:364]: receive_msg(): cleaning up
13(3062) DEBUG: tm [t_funcs.c:368]: t_relay_to(): SER: new transaction fwd'ed
13(3062) DEBUG: <core> [core/receive.c:275]: receive_msg(): request-route executed in: 31098 usec
13(3062) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
13(3062) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
13(3062) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
13(3062) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
13(3062) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
13(3062) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
13(3062) DEBUG: <core> [core/xavp.c:446]: xavp_destroy_list(): destroying xavp list (nil)
13(3062) DEBUG: <core> [core/receive.c:364]: receive_msg(): cleaning up
10(3059) DEBUG: <core> [core/parser/msg_parser.c:600]: parse_msg(): SIP Request:
10(3059) DEBUG: <core> [core/parser/msg_parser.c:602]: parse_msg():  method:  <SUBSCRIBE>
10(3059) DEBUG: <core> [core/parser/msg_parser.c:604]: parse_msg():  uri:     <sip:alice@192.168.99.52:5060;transport=udp;registering_acc=fast-ims_in>
10(3059) DEBUG: <core> [core/parser/msg_parser.c:606]: parse_msg():  version: <SIP/2.0>
10(3059) DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>: <1> <SUBSCRIBE>
10(3059) DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=10
10(3059) DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): <To> [33]; uri=[sip:alice@fast-ims.in]
10(3059) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body ["alice" <sip:alice@fast-ims.in>
]
10(3059) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bKe663.6065c34e803cae955cb8869e94daa0a0.0>; state=16
10(3059) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
10(3059) DEBUG: <core> [core/parser/msg_parser.c:491]: parse_headers(): Via found, flags=2
10(3059) DEBUG: <core> [core/parser/msg_parser.c:493]: parse_headers(): this is the first via
10(3059) DEBUG: <core> [core/receive.c:191]: receive_msg(): --- received sip message - request - call-id: [601cf210acace0fa83c4aaca1a366395@0:0:0:0:0:0:0:0] - cseq: [1 SUBSCRIBE]
10(3059) DEBUG: <core> [core/receive.c:234]: receive_msg(): preparing to run routing scripts...
10(3059) DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=2dd300f1
10(3059) DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29
10(3059) ERROR: <script>: SUBSCRIBE (sip:alice@fast-ims.in (192.168.99.237:6060) to sip:alice@fast-ims.in, 601cf210acace0fa83c4aaca1a366395@0:0:0:0:0:0:0:0)
10(3059) DEBUG: <script>: Mem: Total 67108864, Free 63869944 [1% used]
10(3059) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bKe663.0cee18db131f3591c8aed8f48d232fab.1>; state=16
10(3059) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
10(3059) DEBUG: <core> [core/parser/msg_parser.c:491]: parse_headers(): Via found, flags=100
10(3059) DEBUG: <core> [core/parser/msg_parser.c:504]: parse_headers(): this is the second via
10(3059) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bKe663.55b27c250c20ce701e19ab3f35edb216.0>; state=16
10(3059) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
10(3059) DEBUG: <core> [core/parser/msg_parser.c:491]: parse_headers(): Via found, flags=100
10(3059) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bKe663.6d06870104cdb13c2099675f9e0da93a.0>; state=16
10(3059) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
10(3059) DEBUG: <core> [core/parser/msg_parser.c:491]: parse_headers(): Via found, flags=100
10(3059) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 235, <rport> = <5060>; state=6
10(3059) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK-333432-c82e2cf2d2bde0eb837987a7874b3f97>; state=16
10(3059) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
10(3059) DEBUG: <core> [core/parser/msg_parser.c:491]: parse_headers(): Via found, flags=100
10(3059) DEBUG: maxfwd [mf_funcs.c:76]: is_maxfwd_present(): value = 66 
10(3059) DEBUG: <core> [core/parser/msg_parser.c:183]: get_hdr_field(): content_length=0
10(3059) DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): found end of header
10(3059) DEBUG: sanity [sanity_mod.c:256]: w_sanity_check(): sanity checks result: 1
10(3059) DEBUG: siputils [checks.c:120]: has_totag(): no totag
10(3059) DEBUG: <core> [core/select.c:412]: run_select(): Calling SELECT 0x7fa73a5148e8
10(3059) DEBUG: tm [t_lookup.c:1019]: t_check_msg(): msg (0x7fa73a61b4c0) id=1 global id=0 T start=0xffffffffffffffff
10(3059) DEBUG: tm [t_lookup.c:477]: t_lookup_request(): start searching: hash=13934, isACK=0
10(3059) DEBUG: tm [t_lookup.c:435]: matching_3261(): RFC3261 transaction matching failed
10(3059) DEBUG: tm [t_lookup.c:659]: t_lookup_request(): no transaction found
10(3059) DEBUG: tm [t_lookup.c:1088]: t_check_msg(): msg (0x7fa73a61b4c0) id=1 global id=1 T end=(nil)
10(3059) DEBUG: siputils [checks.c:120]: has_totag(): no totag
10(3059) DEBUG: tm [t_lookup.c:1019]: t_check_msg(): msg (0x7fa73a61b4c0) id=1 global id=1 T start=(nil)
10(3059) DEBUG: tm [t_lookup.c:1094]: t_check_msg(): T previously sought and not found for msg (0x7fa73a61b4c0)
10(3059) DEBUG: tm [t_lookup.c:1019]: t_check_msg(): msg (0x7fa73a61b4c0) id=1 global id=1 T start=(nil)
10(3059) DEBUG: tm [t_lookup.c:1094]: t_check_msg(): T previously sought and not found for msg (0x7fa73a61b4c0)
10(3059) DEBUG: rr [loose.c:85]: is_preloaded(): is_preloaded: Yes
10(3059) DEBUG: <core> [core/socket_info.c:564]: grep_sock_info(): checking if host==us: 17==14 && [pcscf.fast-ims.in] == [192.168.99.237]
10(3059) DEBUG: <core> [core/socket_info.c:567]: grep_sock_info(): checking if port 5060 (advertise 0) matches port 5060
10(3059) DEBUG: rr [loose.c:788]: after_loose(): Topmost route URI: 'sip:term@pcscf.fast-ims.in;lr' is me
10(3059) DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): found end of header
10(3059) DEBUG: rr [loose.c:180]: find_next_route(): No next Route HF found
10(3059) DEBUG: rr [loose.c:813]: after_loose(): No next URI found
10(3059) DEBUG: rr [rr_cb.c:95]: run_rr_callbacks(): callback id 1 entered with <lr>
10(3059) DEBUG: ims_dialog [dlg_handlers.c:826]: dlg_onroute(): No to tag header found --- ignoring... MESSAGE [SUBSCRIBE
10(3059) DEBUG: rr [rr_cb.c:95]: run_rr_callbacks(): callback id 0 entered with <lr>
10(3059) DEBUG: nathelper [nathelper.c:1096]: handle_ruri_alias(): no alias param
10(3059) DEBUG: pv [pv_core.c:1138]: pv_get_dsturi_attr(): no destination URI
10(3059) DEBUG: pv [pv_core.c:1138]: pv_get_dsturi_attr(): no destination URI
10(3059) DEBUG: pv [pv_core.c:1138]: pv_get_dsturi_attr(): no destination URI
10(3059) DEBUG: rr [record.c:918]: add_rr_param(): rr_param_buf=<;rm=7>
10(3059) DEBUG: siputils [checks.c:120]: has_totag(): no totag
10(3059) DEBUG: textops [textops.c:2626]: has_body_f(): content length is zero
10(3059) DEBUG: rr [loose.c:1209]: is_direction(): param ftag not found
10(3059) DEBUG: tm [t_lookup.c:1320]: t_newtran(): msg id=1 , global msg id=1 , T on entrance=(nil)
10(3059) DEBUG: tm [t_lookup.c:477]: t_lookup_request(): start searching: hash=13934, isACK=0
10(3059) DEBUG: tm [t_lookup.c:435]: matching_3261(): RFC3261 transaction matching failed
10(3059) DEBUG: tm [t_lookup.c:659]: t_lookup_request(): no transaction found
10(3059) DEBUG: tm [t_hooks.c:349]: run_reqin_callbacks_internal(): trans=0x7fa72fbd32d0, callback type 1, id 0 entered
10(3059) DEBUG: <core> [core/md5utils.c:67]: MD5StringArray(): MD5 calculated: fd52276d5bd9ab1945ec2ff6fc0e691c
10(3059) DEBUG: <core> [core/dns_cache.c:3329]: dns_srv_sip_resolve(): (192.168.99.52, 0, 0), ip, ret=0
10(3059) DEBUG: <core> [core/msg_translator.c:159]: check_via_address(): (192.168.99.237, 192.168.99.237, 0)
10(3059) DEBUG: tm [t_funcs.c:368]: t_relay_to(): SER: new transaction fwd'ed
10(3059) DEBUG: <core> [core/receive.c:275]: receive_msg(): request-route executed in: 841 usec
10(3059) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
10(3059) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
10(3059) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
10(3059) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
10(3059) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
10(3059) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
10(3059) DEBUG: <core> [core/xavp.c:446]: xavp_destroy_list(): destroying xavp list (nil)
10(3059) DEBUG: <core> [core/receive.c:364]: receive_msg(): cleaning up
14(3063) DEBUG: <core> [core/parser/msg_parser.c:610]: parse_msg(): SIP Reply  (status):
14(3063) DEBUG: <core> [core/parser/msg_parser.c:612]: parse_msg():  version: <SIP/2.0>
14(3063) DEBUG: <core> [core/parser/msg_parser.c:614]: parse_msg():  status:  <501>
14(3063) DEBUG: <core> [core/parser/msg_parser.c:616]: parse_msg():  reason:  <Not implemented>
14(3063) DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=10
14(3063) DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): <To> [33]; uri=[sip:alice@fast-ims.in]
14(3063) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body ["alice" <sip:alice@fast-ims.in>
]
14(3063) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bKe663.fd52276d5bd9ab1945ec2ff6fc0e691c.0>; state=9
14(3063) DEBUG: <core> [core/parser/parse_via.c:2681]: parse_via(): parsing via: next via
14(3063) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bKe663.6065c34e803cae955cb8869e94daa0a0.0>; state=9
14(3063) DEBUG: <core> [core/parser/parse_via.c:2681]: parse_via(): parsing via: next via
14(3063) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bKe663.0cee18db131f3591c8aed8f48d232fab.1>; state=9
14(3063) DEBUG: <core> [core/parser/parse_via.c:2681]: parse_via(): parsing via: next via
14(3063) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bKe663.55b27c250c20ce701e19ab3f35edb216.0>; state=9
14(3063) DEBUG: <core> [core/parser/parse_via.c:2681]: parse_via(): parsing via: next via
14(3063) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bKe663.6d06870104cdb13c2099675f9e0da93a.0>; state=9
14(3063) DEBUG: <core> [core/parser/parse_via.c:2681]: parse_via(): parsing via: next via
14(3063) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 235, <rport> = <5060>; state=6
14(3063) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK-333432-c82e2cf2d2bde0eb837987a7874b3f97>; state=16
14(3063) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
14(3063) DEBUG: <core> [core/parser/msg_parser.c:491]: parse_headers(): Via found, flags=2
14(3063) DEBUG: <core> [core/parser/msg_parser.c:493]: parse_headers(): this is the first via
14(3063) DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>: <1> <SUBSCRIBE>
14(3063) DEBUG: <core> [core/receive.c:191]: receive_msg(): --- received sip message - reply - call-id: [601cf210acace0fa83c4aaca1a366395@0:0:0:0:0:0:0:0] - cseq: [1 SUBSCRIBE]
14(3063) DEBUG: tm [t_lookup.c:1019]: t_check_msg(): msg (0x7fa73a61b4c0) id=1 global id=0 T start=0xffffffffffffffff
14(3063) DEBUG: tm [t_lookup.c:897]: t_reply_matching(): t_reply_matching: hash 13934 label 0 branch 0
14(3063) DEBUG: tm [t_lookup.c:951]: t_reply_matching(): reply (0x7fa73a61b4c0) matched an active transaction (T=0x7fa72fbd32d0)!
14(3063) DEBUG: tm [t_lookup.c:1088]: t_check_msg(): msg (0x7fa73a61b4c0) id=1 global id=1 T end=0x7fa72fbd32d0
14(3063) DEBUG: tm [t_reply.c:2200]: reply_received(): org. status uas=0, uac[0]=0 local=0 is_invite=0)
14(3063) DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=10
14(3063) DEBUG: tm [t_reply.c:1265]: t_should_relay_response(): ->>>>>>>>> T_code=0, new_code=501
14(3063) DEBUG: <core> [core/action.c:1541]: run_actions(): null action list (rec_level=1)
14(3063) DEBUG: tm [t_reply.c:1786]: relay_reply(): branch=0, save=0, relay=0 icode=0
14(3063) DEBUG: <core> [core/msg_translator.c:2265]: generate_res_buf_from_sip_res(): old size: 864, new size: 783
14(3063) DEBUG: <core> [core/msg_translator.c:2283]: generate_res_buf_from_sip_res(): copied size: orig:152, new: 71, rest: 712 msg=
SIP/2.0 501 Not implemented
To: "alice" <sip:alice@fast-ims.in>
Via: SIP/2.0/UDP 192.168.99.237:6060;branch=z9hG4bKe663.6065c34e803cae955cb8869e94daa0a0.0,SIP/2.0/UDP 192.168.99.237:4060;branch=z9hG4bKe663.0cee18db131f3591c8aed8f48d232fab.1,SIP/2.0/UDP 192.168.99.237:6060;branch=z9hG4bKe663.55b27c250c20ce701e19ab3f35edb216.0,SIP/2.0/UDP 192.168.99.237;branch=z9hG4bKe663.6d06870104cdb13c2099675f9e0da93a.0,SIP/2.0/UDP 192.168.99.52:5060;rport=5060;branch=z9hG4bK-333432-c82e2cf2d2bde0eb837987a7874b3f97
CSeq: 1 SUBSCRIBE
Call-ID: 601cf210acace0fa83c4aaca1a366395@0:0:0:0:0:0:0:0
From: "alice" <sip:alice@fast-ims.in>;tag=2dd300f1
Contact: "alice" <sip:alice@192.168.99.52:5060;transport=udp;registering_acc=fast-ims_in>
User-Agent: Jitsi2.11.5602Linux
Content-Length: 0


14(3063) DEBUG: tm [t_reply.c:1629]: cleanup_uac_timers(): RETR/FR timers reset
14(3063) DEBUG: <core> [core/receive.c:348]: receive_msg(): reply-route executed in: 256 usec
14(3063) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
14(3063) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
14(3063) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
14(3063) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
14(3063) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
14(3063) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
14(3063) DEBUG: <core> [core/xavp.c:446]: xavp_destroy_list(): destroying xavp list (nil)
14(3063) DEBUG: <core> [core/receive.c:364]: receive_msg(): cleaning up
16(3065) DEBUG: <core> [core/parser/msg_parser.c:610]: parse_msg(): SIP Reply  (status):
16(3065) DEBUG: <core> [core/parser/msg_parser.c:612]: parse_msg():  version: <SIP/2.0>
16(3065) DEBUG: <core> [core/parser/msg_parser.c:614]: parse_msg():  status:  <501>
16(3065) DEBUG: <core> [core/parser/msg_parser.c:616]: parse_msg():  reason:  <Not implemented>
16(3065) DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=10
16(3065) DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): <To> [33]; uri=[sip:alice@fast-ims.in]
16(3065) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body ["alice" <sip:alice@fast-ims.in>
]
16(3065) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bKe663.6d06870104cdb13c2099675f9e0da93a.0>; state=9
16(3065) DEBUG: <core> [core/parser/parse_via.c:2681]: parse_via(): parsing via: next via
16(3065) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 235, <rport> = <5060>; state=6
16(3065) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK-333432-c82e2cf2d2bde0eb837987a7874b3f97>; state=16
16(3065) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
16(3065) DEBUG: <core> [core/parser/msg_parser.c:491]: parse_headers(): Via found, flags=2
16(3065) DEBUG: <core> [core/parser/msg_parser.c:493]: parse_headers(): this is the first via
16(3065) DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>: <1> <SUBSCRIBE>
16(3065) DEBUG: <core> [core/receive.c:191]: receive_msg(): --- received sip message - reply - call-id: [601cf210acace0fa83c4aaca1a366395@0:0:0:0:0:0:0:0] - cseq: [1 SUBSCRIBE]
16(3065) DEBUG: tm [t_lookup.c:1019]: t_check_msg(): msg (0x7fa73a61b4c0) id=1 global id=0 T start=0xffffffffffffffff
16(3065) DEBUG: tm [t_lookup.c:897]: t_reply_matching(): t_reply_matching: hash 13934 label 0 branch 0
16(3065) DEBUG: tm [t_lookup.c:951]: t_reply_matching(): reply (0x7fa73a61b4c0) matched an active transaction (T=0x7fa72fbc7128)!
16(3065) DEBUG: tm [t_lookup.c:1088]: t_check_msg(): msg (0x7fa73a61b4c0) id=1 global id=1 T end=0x7fa72fbc7128
16(3065) DEBUG: tm [t_reply.c:2200]: reply_received(): org. status uas=0, uac[0]=0 local=0 is_invite=0)
16(3065) DEBUG: <core> [core/parser/msg_parser.c:183]: get_hdr_field(): content_length=0
16(3065) DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): found end of header
16(3065) DEBUG: tm [t_reply.c:1265]: t_should_relay_response(): ->>>>>>>>> T_code=0, new_code=501
16(3065) DEBUG: tm [t_reply.c:1786]: relay_reply(): branch=0, save=0, relay=0 icode=0
16(3065) DEBUG: <core> [core/msg_translator.c:2265]: generate_res_buf_from_sip_res(): old size: 525, new size: 444
16(3065) DEBUG: <core> [core/msg_translator.c:2283]: generate_res_buf_from_sip_res(): copied size: orig:152, new: 71, rest: 373 msg=
SIP/2.0 501 Not implemented
To: "alice" <sip:alice@fast-ims.in>
Via: SIP/2.0/UDP 192.168.99.52:5060;rport=5060;branch=z9hG4bK-333432-c82e2cf2d2bde0eb837987a7874b3f97
CSeq: 1 SUBSCRIBE
Call-ID: 601cf210acace0fa83c4aaca1a366395@0:0:0:0:0:0:0:0
From: "alice" <sip:alice@fast-ims.in>;tag=2dd300f1
Contact: "alice" <sip:alice@192.168.99.52:5060;transport=udp;registering_acc=fast-ims_in>
User-Agent: Jitsi2.11.5602Linux
Content-Length: 0


16(3065) DEBUG: tm [t_reply.c:1629]: cleanup_uac_timers(): RETR/FR timers reset
16(3065) DEBUG: <core> [core/receive.c:348]: receive_msg(): reply-route executed in: 257 usec
16(3065) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
16(3065) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
16(3065) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
16(3065) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
16(3065) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
16(3065) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
16(3065) DEBUG: <core> [core/xavp.c:446]: xavp_destroy_list(): destroying xavp list (nil)
16(3065) DEBUG: <core> [core/receive.c:364]: receive_msg(): cleaning up
 0(3046) ALERT: <core> [main.c:743]: handle_sigs(): child process 3132 exited by a signal 11
 0(3046) ALERT: <core> [main.c:746]: handle_sigs(): core was generated
 0(3046) INFO: <core> [main.c:768]: handle_sigs(): terminating due to SIGCHLD
 0(3046) DEBUG: <core> [main.c:770]: handle_sigs(): terminating due to SIGCHLD
24(3133) INFO: <core> [main.c:823]: sig_usr(): signal 15 received
22(3110) INFO: <core> [main.c:823]: sig_usr(): signal 15 received
21(3109) INFO: <core> [main.c:823]: sig_usr(): signal 15 received
20(3088) INFO: <core> [main.c:823]: sig_usr(): signal 15 received
19(3068) INFO: <core> [main.c:823]: sig_usr(): signal 15 received
18(3067) INFO: <core> [main.c:823]: sig_usr(): signal 15 received
17(3066) INFO: <core> [main.c:823]: sig_usr(): signal 15 received
16(3065) INFO: <core> [main.c:823]: sig_usr(): signal 15 received
15(3064) INFO: <core> [main.c:823]: sig_usr(): signal 15 received
14(3063) INFO: <core> [main.c:823]: sig_usr(): signal 15 received
13(3062) INFO: <core> [main.c:823]: sig_usr(): signal 15 received
12(3061) INFO: <core> [main.c:823]: sig_usr(): signal 15 received
11(3060) INFO: <core> [main.c:823]: sig_usr(): signal 15 received
10(3059) INFO: <core> [main.c:823]: sig_usr(): signal 15 received
 9(3058) INFO: <core> [main.c:823]: sig_usr(): signal 15 received
 8(3057) INFO: <core> [main.c:823]: sig_usr(): signal 15 received
 7(3056) INFO: <core> [main.c:823]: sig_usr(): signal 15 received
 6(3055) INFO: <core> [main.c:823]: sig_usr(): signal 15 received
 5(3054) INFO: <core> [main.c:823]: sig_usr(): signal 15 received
 4(3053) INFO: <core> [main.c:823]: sig_usr(): signal 15 received
 3(3052) INFO: <core> [main.c:823]: sig_usr(): signal 15 received
 2(3051) INFO: <core> [main.c:823]: sig_usr(): signal 15 received
 1(3050) INFO: <core> [main.c:823]: sig_usr(): signal 15 received
 0(3046) DEBUG: rtpengine [rtpengine.c:1682]: mod_destroy(): rtpengine_hash_table_destroy() success!
 0(3046) DEBUG: ims_usrloc_pcscf [pcontact.c:259]: free_pcontact(): freeing pcontact: <sip:alice@192.168.99.52:5060;transport=udp;registering_acc=fast-ims_in>
 0(3046) DEBUG: ims_usrloc_pcscf [pcontact.c:263]: free_pcontact(): freeing linked IMPI: <sip:alice@fast-ims.in>
 0(3046) DEBUG: ims_usrloc_pcscf [pcontact.c:259]: free_pcontact(): freeing pcontact: <sip:alice@192.168.99.52:5060;transport=udp;registering_acc=fast-ims_in>
 0(3046) DEBUG: ims_usrloc_pcscf [pcontact.c:263]: free_pcontact(): freeing linked IMPI: <sip:alice@fast-ims.in>
 0(3046) DEBUG: <core> [db_pool.c:100]: pool_remove(): removing connection from the pool
 0(3046) DEBUG: tm [t_funcs.c:86]: tm_shutdown(): DEBUG: tm_shutdown : start
 0(3046) DEBUG: tm [t_funcs.c:89]: tm_shutdown(): DEBUG: tm_shutdown : emptying hash table
 0(3046) DEBUG: tm [h_table.c:129]: free_cell_helper(): freeing transaction 0x7fa72fbc5a78 from h_table.c:448
 0(3046) DEBUG: tm [h_table.c:204]: free_cell_helper(): branch 0 -> dns_h.srv (_sip._udp.scscf.fast-ims.in) ref=2, dns_h.a (scscf.fast-ims.in) ref=5
 0(3046) DEBUG: tm [h_table.c:129]: free_cell_helper(): freeing transaction 0x7fa72fbcf618 from h_table.c:448
 0(3046) DEBUG: tm [h_table.c:204]: free_cell_helper(): branch 0 -> dns_h.srv (_sip._udp.scscf.fast-ims.in) ref=3, dns_h.a (scscf.fast-ims.in) ref=4
 0(3046) DEBUG: tm [h_table.c:129]: free_cell_helper(): freeing transaction 0x7fa72fbcb638 from h_table.c:448
 0(3046) DEBUG: tm [h_table.c:204]: free_cell_helper(): branch 0 -> dns_h.srv (_sip._udp.scscf.fast-ims.in) ref=2, dns_h.a (scscf.fast-ims.in) ref=3
 0(3046) DEBUG: tm [h_table.c:129]: free_cell_helper(): freeing transaction 0x7fa72fbd32d0 from h_table.c:448
 0(3046) DEBUG: tm [h_table.c:129]: free_cell_helper(): freeing transaction 0x7fa72fbc7128 from h_table.c:448
 0(3046) DEBUG: tm [h_table.c:204]: free_cell_helper(): branch 0 -> dns_h.srv (_sip._udp.scscf.fast-ims.in) ref=2, dns_h.a (scscf.fast-ims.in) ref=2
 0(3046) DEBUG: tm [h_table.c:129]: free_cell_helper(): freeing transaction 0x7fa72fbc0650 from h_table.c:448
 0(3046) DEBUG: tm [h_table.c:204]: free_cell_helper(): branch 0 -> dns_h.srv (_sip._udp.fast-ims.in) ref=3, dns_h.a (icscf.fast-ims.in) ref=3
 0(3046) DEBUG: tm [h_table.c:129]: free_cell_helper(): freeing transaction 0x7fa72fbc2438 from h_table.c:448
 0(3046) DEBUG: tm [h_table.c:204]: free_cell_helper(): branch 0 -> dns_h.srv (_sip._udp.fast-ims.in) ref=2, dns_h.a (icscf.fast-ims.in) ref=2
 0(3046) DEBUG: tm [t_funcs.c:91]: tm_shutdown(): DEBUG: tm_shutdown : removing semaphores
 0(3046) DEBUG: tm [t_funcs.c:93]: tm_shutdown(): DEBUG: tm_shutdown : destroying tmcb lists
 0(3046) DEBUG: tm [t_funcs.c:96]: tm_shutdown(): DEBUG: tm_shutdown : done
 0(3046) INFO: <core> [core/sctp_core.c:53]: sctp_core_destroy(): SCTP API not initialized
 0(3046) DEBUG: <core> [core/mem/shm.c:174]: shm_core_lock_destroy(): destroying the shared memory lock
 0(3046) DEBUG: <core> [core/mem/shm.c:266]: shm_destroy_manager(): destroying memory manager: q_malloc
 0(3046) DEBUG: <core> [core/mem/pkg.c:89]: pkg_destroy_manager(): destroying memory manager: q_malloc