2016-06-20 15:28:06.825  {1 CANCEL 4mi9eNbuolumfFpoy0b0jw} 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=4mi9eNbuolumfFpoy0b0jw
2016-06-20 15:28:06.825  {1 CANCEL 4mi9eNbuolumfFpoy0b0jw} DEBUG: siputils [checks.c:97]: has_totag(): no totag
2016-06-20 15:28:06.825  {1 CANCEL 4mi9eNbuolumfFpoy0b0jw} DEBUG: tm [t_lookup.c:701]: t_lookupOriginalT(): DEBUG: t_lookupOriginalT: searching on hash entry 54310
2016-06-20 15:28:06.825  {1 CANCEL 4mi9eNbuolumfFpoy0b0jw} DEBUG: tm [t_lookup.c:409]: matching_3261(): DEBUG: RFC3261 transaction matched, tid=yP9-Om7uwsXsEVKU1ArX0Q
2016-06-20 15:28:06.825  {1 CANCEL 4mi9eNbuolumfFpoy0b0jw} DEBUG: tm [t_lookup.c:798]: t_lookupOriginalT(): DEBUG: t_lookupOriginalT: canceled transaction found (0x7f476dd67c38)! 
2016-06-20 15:28:06.825  {1 CANCEL 4mi9eNbuolumfFpoy0b0jw} DEBUG: tm [t_lookup.c:801]: t_lookupOriginalT(): DEBUG: t_lookupOriginalT completed
2016-06-20 15:28:06.825  {1 CANCEL 4mi9eNbuolumfFpoy0b0jw} DEBUG: tm [tm.c:992]: w_t_lookup_cancel(): lookup_original: t_lookupOriginalT returned: 0x7f476dd67c38
2016-06-20 15:28:06.825  {1 CANCEL 4mi9eNbuolumfFpoy0b0jw} DEBUG: tm [t_lookup.c:1312]: t_newtran(): DEBUG: t_newtran: msg id=7 , global msg id=6 , T on entrance=0xffffffffffffffff
2016-06-20 15:28:06.825  {1 CANCEL 4mi9eNbuolumfFpoy0b0jw} DEBUG: tm [t_lookup.c:466]: t_lookup_request(): t_lookup_request: start searching: hash=54310, isACK=0
2016-06-20 15:28:06.825  {1 CANCEL 4mi9eNbuolumfFpoy0b0jw} DEBUG: tm [t_lookup.c:424]: matching_3261(): DEBUG: RFC3261 transaction matching failed
2016-06-20 15:28:06.825  {1 CANCEL 4mi9eNbuolumfFpoy0b0jw} DEBUG: tm [t_lookup.c:648]: t_lookup_request(): DEBUG: t_lookup_request: no transaction found
2016-06-20 15:28:06.825  {1 CANCEL 4mi9eNbuolumfFpoy0b0jw} DEBUG: tm [t_hooks.c:358]: run_reqin_callbacks_internal(): DBG: trans=0x7f476dd73078, callback type 1, id 0 entered
2016-06-20 15:28:06.825  {1 CANCEL 4mi9eNbuolumfFpoy0b0jw} DEBUG: <core> [md5utils.c:67]: MD5StringArray(): MD5 calculated: dcf75426037c4eae918870c6c53e4cd0
2016-06-20 15:28:06.825  {1 CANCEL 4mi9eNbuolumfFpoy0b0jw} DEBUG: tm [t_lookup.c:701]: t_lookupOriginalT(): DEBUG: t_lookupOriginalT: searching on hash entry 54310
2016-06-20 15:28:06.825  {1 CANCEL 4mi9eNbuolumfFpoy0b0jw} DEBUG: tm [t_lookup.c:409]: matching_3261(): DEBUG: RFC3261 transaction matched, tid=yP9-Om7uwsXsEVKU1ArX0Q
2016-06-20 15:28:06.825  {1 CANCEL 4mi9eNbuolumfFpoy0b0jw} DEBUG: tm [t_lookup.c:798]: t_lookupOriginalT(): DEBUG: t_lookupOriginalT: canceled transaction found (0x7f476dd67c38)! 
2016-06-20 15:28:06.825  {1 CANCEL 4mi9eNbuolumfFpoy0b0jw} DEBUG: tm [t_lookup.c:801]: t_lookupOriginalT(): DEBUG: t_lookupOriginalT completed
2016-06-20 15:28:06.825  {1 CANCEL 4mi9eNbuolumfFpoy0b0jw} ERROR: tm [t_msgbuilder.c:287]: build_local_reparse(): ERROR: build_local_reparse: INVITE is missing
2016-06-20 15:28:06.826  {1 CANCEL 4mi9eNbuolumfFpoy0b0jw} ERROR: tm [t_msgbuilder.c:494]: build_local_reparse(): ERROR: build_local_reparse: cannot build CANCEL request
2016-06-20 15:28:06.826  {1 CANCEL 4mi9eNbuolumfFpoy0b0jw} ERROR: tm [t_cancel.c:310]: cancel_branch(): ERROR: attempt to build a CANCEL failed
2016-06-20 15:28:06.826  {1 CANCEL 4mi9eNbuolumfFpoy0b0jw} ERROR: tm [t_fwd.c:1389]: e2e_cancel(): ERROR: cancel error
2016-06-20 15:28:06.826  {1 CANCEL 4mi9eNbuolumfFpoy0b0jw} DEBUG: tm [t_reply.c:1592]: cleanup_uac_timers(): DEBUG: cleanup_uac_timers: RETR/FR timers reset
2016-06-20 15:28:06.826  {1 CANCEL 4mi9eNbuolumfFpoy0b0jw} DEBUG: tm [t_reply.c:648]: _reply_light(): DEBUG: reply sent out. buf=0x7f477191e2d0: SIP/2.0 500 cancel e..., shmem=0x7f476dd72d08: SIP/2.0 500 cancel e
2016-06-20 15:28:06.826  {1 CANCEL 4mi9eNbuolumfFpoy0b0jw} DEBUG: tm [t_reply.c:658]: _reply_light(): DEBUG: _reply_light: finished
2016-06-20 15:28:06.826  {1 CANCEL 4mi9eNbuolumfFpoy0b0jw} DEBUG: tm [t_funcs.c:368]: t_relay_to(): SER: new transaction fwd'ed
2016-06-20 15:28:06.826  {1 CANCEL 4mi9eNbuolumfFpoy0b0jw} DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
2016-06-20 15:28:06.826  {1 CANCEL 4mi9eNbuolumfFpoy0b0jw} DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
2016-06-20 15:28:06.826  {1 CANCEL 4mi9eNbuolumfFpoy0b0jw} DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
2016-06-20 15:28:06.826  {1 CANCEL 4mi9eNbuolumfFpoy0b0jw} DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
2016-06-20 15:28:06.826  {1 CANCEL 4mi9eNbuolumfFpoy0b0jw} DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
2016-06-20 15:28:06.826  {1 CANCEL 4mi9eNbuolumfFpoy0b0jw} DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
2016-06-20 15:28:06.826  {1 CANCEL 4mi9eNbuolumfFpoy0b0jw} DEBUG: <core> [xavp.c:446]: xavp_destroy_list(): destroying xavp list (nil)
2016-06-20 15:28:06.826  {1 CANCEL 4mi9eNbuolumfFpoy0b0jw} DEBUG: <core> [receive.c:322]: receive_msg(): cleaning up