2016-06-21 12:18:57.008  {1 CANCEL VqT_vW5XY2B6A0xuYa7mmQ} DEBUG: <core> [receive.c:221]: receive_msg(): preparing to run routing scripts...
2016-06-21 12:18:57.008  {1 CANCEL VqT_vW5XY2B6A0xuYa7mmQ} DEBUG: <core> [parser/msg_parser.c:153]: get_hdr_field(): get_hdr_field: cseq <CSeq>: <750311> <CANCEL>
2016-06-21 12:18:57.008  {1 CANCEL VqT_vW5XY2B6A0xuYa7mmQ} DEBUG: <core> [parser/msg_parser.c:187]: get_hdr_field(): DEBUG: get_hdr_body : content_length=0
2016-06-21 12:18:57.008  {1 CANCEL VqT_vW5XY2B6A0xuYa7mmQ} DEBUG: <core> [parser/msg_parser.c:89]: get_hdr_field(): found end of header
2016-06-21 12:18:57.008  {1 CANCEL VqT_vW5XY2B6A0xuYa7mmQ} DEBUG: <core> [parser/parse_addr_spec.c:172]: parse_to_param(): DEBUG: add_param: tag=9PV_tw
2016-06-21 12:18:57.008  {1 CANCEL VqT_vW5XY2B6A0xuYa7mmQ} DEBUG: <core> [parser/parse_addr_spec.c:894]: parse_addr_spec(): end of header reached, state=29
2016-06-21 12:18:57.008  {1 CANCEL VqT_vW5XY2B6A0xuYa7mmQ} DEBUG: sanity [mod_sanity.c:248]: w_sanity_check(): sanity checks result: 1
2016-06-21 12:18:57.008  {1 CANCEL VqT_vW5XY2B6A0xuYa7mmQ} DEBUG: maxfwd [mf_funcs.c:85]: is_maxfwd_present(): value = 49 
2016-06-21 12:18:57.008  {1 CANCEL VqT_vW5XY2B6A0xuYa7mmQ} DEBUG: tmx [tmx_pretran.c:219]: tmx_check_pretran(): no pre-transaction management for ACK or CANCEL
2016-06-21 12:18:57.008  {1 CANCEL VqT_vW5XY2B6A0xuYa7mmQ} WARNING: <script>: ABC SOURCE -  10.112.185.128:5060 ID=VqT_vW5XY2B6A0xuYa7mmQ
2016-06-21 12:18:57.008  {1 CANCEL VqT_vW5XY2B6A0xuYa7mmQ} INFO: <script>: New request - M=CANCEL R=sip:sec.abcsoft.503@example.local F=sip:502@example.local T=sip:sec.abcsoft.503@example.local IP=udp:10.112.185.128:5060 ID=VqT_vW5XY2B6A0xuYa7mmQ
2016-06-21 12:18:57.008  {1 CANCEL VqT_vW5XY2B6A0xuYa7mmQ} DEBUG: siputils [checks.c:97]: has_totag(): no totag
2016-06-21 12:18:57.008  {1 CANCEL VqT_vW5XY2B6A0xuYa7mmQ} DEBUG: tm [t_lookup.c:701]: t_lookupOriginalT(): DEBUG: t_lookupOriginalT: searching on hash entry 20684
2016-06-21 12:18:57.008  {1 CANCEL VqT_vW5XY2B6A0xuYa7mmQ} DEBUG: tm [t_lookup.c:409]: matching_3261(): DEBUG: RFC3261 transaction matched, tid=iz-kuh802broqT9YKBLjHg
2016-06-21 12:18:57.008  {1 CANCEL VqT_vW5XY2B6A0xuYa7mmQ} DEBUG: tm [t_lookup.c:798]: t_lookupOriginalT(): DEBUG: t_lookupOriginalT: canceled transaction found (0x7f744dfd09a8)! 
2016-06-21 12:18:57.008  {1 CANCEL VqT_vW5XY2B6A0xuYa7mmQ} DEBUG: tm [t_lookup.c:801]: t_lookupOriginalT(): DEBUG: t_lookupOriginalT completed
2016-06-21 12:18:57.008  {1 CANCEL VqT_vW5XY2B6A0xuYa7mmQ} DEBUG: tm [tm.c:992]: w_t_lookup_cancel(): lookup_original: t_lookupOriginalT returned: 0x7f744dfd09a8
2016-06-21 12:18:57.008  {1 CANCEL VqT_vW5XY2B6A0xuYa7mmQ} DEBUG: tm [t_lookup.c:1312]: t_newtran(): DEBUG: t_newtran: msg id=9 , global msg id=8 , T on entrance=0xffffffffffffffff
2016-06-21 12:18:57.008  {1 CANCEL VqT_vW5XY2B6A0xuYa7mmQ} DEBUG: tm [t_lookup.c:466]: t_lookup_request(): t_lookup_request: start searching: hash=20684, isACK=0
2016-06-21 12:18:57.008  {1 CANCEL VqT_vW5XY2B6A0xuYa7mmQ} DEBUG: tm [t_lookup.c:424]: matching_3261(): DEBUG: RFC3261 transaction matching failed
2016-06-21 12:18:57.008  {1 CANCEL VqT_vW5XY2B6A0xuYa7mmQ} DEBUG: tm [t_lookup.c:648]: t_lookup_request(): DEBUG: t_lookup_request: no transaction found
2016-06-21 12:18:57.008  {1 CANCEL VqT_vW5XY2B6A0xuYa7mmQ} DEBUG: tm [t_hooks.c:358]: run_reqin_callbacks_internal(): DBG: trans=0x7f744dfed4b8, callback type 1, id 0 entered
2016-06-21 12:18:57.008  {1 CANCEL VqT_vW5XY2B6A0xuYa7mmQ} DEBUG: <core> [md5utils.c:67]: MD5StringArray(): MD5 calculated: 29f9b25910de6b835aee5e8cb41de048
2016-06-21 12:18:57.008  {1 CANCEL VqT_vW5XY2B6A0xuYa7mmQ} DEBUG: tm [t_lookup.c:701]: t_lookupOriginalT(): DEBUG: t_lookupOriginalT: searching on hash entry 20684
2016-06-21 12:18:57.008  {1 CANCEL VqT_vW5XY2B6A0xuYa7mmQ} DEBUG: tm [t_lookup.c:409]: matching_3261(): DEBUG: RFC3261 transaction matched, tid=iz-kuh802broqT9YKBLjHg
2016-06-21 12:18:57.008  {1 CANCEL VqT_vW5XY2B6A0xuYa7mmQ} DEBUG: tm [t_lookup.c:798]: t_lookupOriginalT(): DEBUG: t_lookupOriginalT: canceled transaction found (0x7f744dfd09a8)! 
2016-06-21 12:18:57.008  {1 CANCEL VqT_vW5XY2B6A0xuYa7mmQ} DEBUG: tm [t_lookup.c:801]: t_lookupOriginalT(): DEBUG: t_lookupOriginalT completed
2016-06-21 12:18:57.008  {1 CANCEL VqT_vW5XY2B6A0xuYa7mmQ} DEBUG: tm [t_reply.c:1592]: cleanup_uac_timers(): DEBUG: cleanup_uac_timers: RETR/FR timers reset
2016-06-21 12:18:57.008  {1 CANCEL VqT_vW5XY2B6A0xuYa7mmQ} DEBUG: tm [t_reply.c:648]: _reply_light(): DEBUG: reply sent out. buf=0x7f7451b93610: SIP/2.0 487 Request ..., shmem=0x7f744dfd9b18: SIP/2.0 487 Request 
2016-06-21 12:18:57.008  {1 CANCEL VqT_vW5XY2B6A0xuYa7mmQ} DEBUG: tm [t_reply.c:658]: _reply_light(): DEBUG: _reply_light: finished
2016-06-21 12:18:57.008  {1 CANCEL VqT_vW5XY2B6A0xuYa7mmQ} DEBUG: tm [t_fwd.c:1279]: e2e_cancel(): DEBUG: e2e_cancel: e2e cancel -- no active branches
2016-06-21 12:18:57.008  {1 CANCEL VqT_vW5XY2B6A0xuYa7mmQ} DEBUG: tm [t_reply.c:1592]: cleanup_uac_timers(): DEBUG: cleanup_uac_timers: RETR/FR timers reset
2016-06-21 12:18:57.008  {1 CANCEL VqT_vW5XY2B6A0xuYa7mmQ} DEBUG: tm [t_reply.c:648]: _reply_light(): DEBUG: reply sent out. buf=0x7f7451b93610: SIP/2.0 200 ok -- no..., shmem=0x7f744dfe19c0: SIP/2.0 200 ok -- no
2016-06-21 12:18:57.008  {1 CANCEL VqT_vW5XY2B6A0xuYa7mmQ} DEBUG: tm [t_reply.c:658]: _reply_light(): DEBUG: _reply_light: finished
2016-06-21 12:18:57.008  {1 CANCEL VqT_vW5XY2B6A0xuYa7mmQ} DEBUG: tm [t_funcs.c:368]: t_relay_to(): SER: new transaction fwd'ed
2016-06-21 12:18:57.008  {1 CANCEL VqT_vW5XY2B6A0xuYa7mmQ} DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
2016-06-21 12:18:57.008  {1 CANCEL VqT_vW5XY2B6A0xuYa7mmQ} DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
2016-06-21 12:18:57.008  {1 CANCEL VqT_vW5XY2B6A0xuYa7mmQ} DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
2016-06-21 12:18:57.008  {1 CANCEL VqT_vW5XY2B6A0xuYa7mmQ} DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
2016-06-21 12:18:57.008  {1 CANCEL VqT_vW5XY2B6A0xuYa7mmQ} DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
2016-06-21 12:18:57.008  {1 CANCEL VqT_vW5XY2B6A0xuYa7mmQ} DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
2016-06-21 12:18:57.008  {1 CANCEL VqT_vW5XY2B6A0xuYa7mmQ} DEBUG: <core> [xavp.c:446]: xavp_destroy_list(): destroying xavp list (nil)
2016-06-21 12:18:57.008  {1 CANCEL VqT_vW5XY2B6A0xuYa7mmQ} DEBUG: <core> [receive.c:322]: receive_msg(): cleaning up
2016-06-21 12:18:57.013  {1 ACK VqT_vW5XY2B6A0xuYa7mmQ} DEBUG: tmx [tmx_pretran.c:219]: tmx_check_pretran(): no pre-transaction management for ACK or CANCEL