Using default script for make a call from sip ua to PSTN system (#!define WITH_PSTN), the cancel sent for the first call after start kamailio doesn't relay to PSTN system and I have the trace error beelow:

2(3203) BUG: {1 27018 CANCEL 0tBgb95Z.0eE5VVrAkoP06nvunIknKNz} tm [t_cancel.c:318]: cancel_branch(): local_cancel buffer=(nil) != BUSY_BUFFER (trying to continue)
12(3203) ERROR: {1 27018 CANCEL 0tBgb95Z.0eE5VVrAkoP06nvunIknKNz} tm [t_fwd.c:1434]: e2e_cancel(): cancel error

the next calls works fine. Does anyone have any suggestions?

Beelow trace at debug level:

37(3695) INFO: <core> [core/cfg/cfg_ctx.c:602]: cfg_set_now(): core.debug has been changed to 3

37(3695) DEBUG: ctl [io_listener.c:518]: handle_stream_read(): bytes processed: 23

12(3670) DEBUG: <core> [core/parser/parse_fline.c:250]: parse_first_line(): first line type 1 (request) flags 1

12(3670) DEBUG: <core> [core/parser/msg_parser.c:677]: parse_msg(): SIP Request:

12(3670) DEBUG: <core> [core/parser/msg_parser.c:679]: parse_msg(): method: <CANCEL>

12(3670) DEBUG: <core> [core/parser/msg_parser.c:681]: parse_msg(): uri: <sip:100@192.168.2.238:5060>

12(3670) DEBUG: <core> [core/parser/msg_parser.c:683]: parse_msg(): version: <SIP/2.0>

12(3670) DEBUG: <core> [core/parser/parse_hname2.c:302]: parse_sip_header_name(): parsed header name [Via] type 1

12(3670) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 235, <rport> = <n/a>; state=6

12(3670) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bKPjLBcUXshEKW2s9T0en9czTYAsciW1vV-W>; state=16

12(3670) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5

12(3670) DEBUG: <core> [core/parser/msg_parser.c:555]: parse_headers(): Via found, flags=2

12(3670) DEBUG: <core> [core/parser/msg_parser.c:557]: parse_headers(): this is the first via

12(3670) DEBUG: <core> [core/parser/parse_hname2.c:302]: parse_sip_header_name(): parsed header name [Max-Forwards] type 8

12(3670) DEBUG: <core> [core/parser/parse_hname2.c:302]: parse_sip_header_name(): parsed header name [From] type 4

12(3670) DEBUG: <core> [core/parser/parse_hname2.c:302]: parse_sip_header_name(): parsed header name [To] type 3

12(3670) DEBUG: <core> [core/parser/parse_addr_spec.c:884]: parse_addr_spec(): end of header reached, state=9

12(3670) DEBUG: <core> [core/parser/msg_parser.c:173]: get_hdr_field(): <To> [23]; uri=[sip:100@192.168.2.238]

12(3670) DEBUG: <core> [core/parser/msg_parser.c:176]: get_hdr_field(): to body (23)[sip:100@192.168.2.238

], to tag (0)[]

12(3670) DEBUG: <core> [core/parser/parse_hname2.c:302]: parse_sip_header_name(): parsed header name [Call-ID] type 6

12(3670) DEBUG: <core> [core/parser/parse_hname2.c:302]: parse_sip_header_name(): parsed header name [CSeq] type 5

12(3670) DEBUG: <core> [core/parser/msg_parser.c:154]: get_hdr_field(): cseq <CSeq>: <17038> <CANCEL>

12(3670) DEBUG: <core> [core/receive.c:394]: receive_msg(): --- received sip message - request - call-id: [CYxrNJtcCFZKS.PJN29LlEBd0aejPQUU] - cseq: [17038 CANCEL]

12(3670) DEBUG: <core> [core/parser/parse_hname2.c:302]: parse_sip_header_name(): parsed header name [User-Agent] type 28

12(3670) DEBUG: <core> [core/parser/parse_hname2.c:302]: parse_sip_header_name(): parsed header name [Content-Length] type 12

12(3670) DEBUG: <core> [core/parser/msg_parser.c:187]: get_hdr_field(): content_length=0

12(3670) DEBUG: <core> [core/parser/msg_parser.c:91]: get_hdr_field(): found end of header

12(3670) DEBUG: {1 17038 CANCEL CYxrNJtcCFZKS.PJN29LlEBd0aejPQUU} <core> [core/receive.c:261]: ksr_evrt_pre_routing(): event route core:pre-routing not defined

12(3670) DEBUG: {1 17038 CANCEL CYxrNJtcCFZKS.PJN29LlEBd0aejPQUU} <core> [core/receive.c:471]: receive_msg(): preparing to run routing scripts...

12(3670) DEBUG: {1 17038 CANCEL CYxrNJtcCFZKS.PJN29LlEBd0aejPQUU} maxfwd [mf_funcs.c:74]: is_maxfwd_present(): value = 70

12(3670) DEBUG: {1 17038 CANCEL CYxrNJtcCFZKS.PJN29LlEBd0aejPQUU} sanity [sanity.c:247]: check_ruri_sip_version(): check_ruri_sip_version entered

12(3670) DEBUG: {1 17038 CANCEL CYxrNJtcCFZKS.PJN29LlEBd0aejPQUU} sanity [sanity.c:270]: check_ruri_sip_version(): check_ruri_sip_version passed

12(3670) DEBUG: {1 17038 CANCEL CYxrNJtcCFZKS.PJN29LlEBd0aejPQUU} sanity [sanity.c:277]: check_ruri_scheme(): check_ruri_scheme entered

12(3670) DEBUG: {1 17038 CANCEL CYxrNJtcCFZKS.PJN29LlEBd0aejPQUU} sanity [sanity.c:297]: check_ruri_scheme(): check_ruri_scheme passed

12(3670) DEBUG: {1 17038 CANCEL CYxrNJtcCFZKS.PJN29LlEBd0aejPQUU} sanity [sanity.c:318]: check_required_headers(): check_required_headers entered

12(3670) DEBUG: {1 17038 CANCEL CYxrNJtcCFZKS.PJN29LlEBd0aejPQUU} sanity [sanity.c:340]: check_required_headers(): check_required_headers passed

12(3670) DEBUG: {1 17038 CANCEL CYxrNJtcCFZKS.PJN29LlEBd0aejPQUU} sanity [sanity.c:348]: check_via1_header(): check via1 header

12(3670) DEBUG: {1 17038 CANCEL CYxrNJtcCFZKS.PJN29LlEBd0aejPQUU} sanity [sanity.c:506]: check_cseq_method(): check_cseq_method entered

12(3670) DEBUG: {1 17038 CANCEL CYxrNJtcCFZKS.PJN29LlEBd0aejPQUU} sanity [sanity.c:539]: check_cseq_method(): check_cseq_method passed

12(3670) DEBUG: {1 17038 CANCEL CYxrNJtcCFZKS.PJN29LlEBd0aejPQUU} sanity [sanity.c:548]: check_cseq_value(): check_cseq_value entered

12(3670) DEBUG: {1 17038 CANCEL CYxrNJtcCFZKS.PJN29LlEBd0aejPQUU} sanity [sanity.c:576]: check_cseq_value(): check_cseq_value passed

12(3670) DEBUG: {1 17038 CANCEL CYxrNJtcCFZKS.PJN29LlEBd0aejPQUU} sanity [sanity.c:585]: check_cl(): check_cl entered

12(3670) DEBUG: {1 17038 CANCEL CYxrNJtcCFZKS.PJN29LlEBd0aejPQUU} sanity [sanity.c:610]: check_cl(): check_cl passed

12(3670) DEBUG: {1 17038 CANCEL CYxrNJtcCFZKS.PJN29LlEBd0aejPQUU} sanity [sanity.c:622]: check_expires_value(): check_expires_value entered

12(3670) DEBUG: {1 17038 CANCEL CYxrNJtcCFZKS.PJN29LlEBd0aejPQUU} sanity [sanity.c:659]: check_expires_value(): no expires header found

12(3670) DEBUG: {1 17038 CANCEL CYxrNJtcCFZKS.PJN29LlEBd0aejPQUU} sanity [sanity.c:758]: check_parse_uris(): check_parse_uris entered

12(3670) DEBUG: {1 17038 CANCEL CYxrNJtcCFZKS.PJN29LlEBd0aejPQUU} sanity [sanity.c:762]: check_parse_uris(): parsing ruri

12(3670) DEBUG: {1 17038 CANCEL CYxrNJtcCFZKS.PJN29LlEBd0aejPQUU} sanity [sanity.c:776]: check_parse_uris(): looking up From header

12(3670) DEBUG: {1 17038 CANCEL CYxrNJtcCFZKS.PJN29LlEBd0aejPQUU} <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=Jjj1QBeRxydZ5rq.-xKCfcJZhlPANj9N

12(3670) DEBUG: {1 17038 CANCEL CYxrNJtcCFZKS.PJN29LlEBd0aejPQUU} <core> [core/parser/parse_addr_spec.c:884]: parse_addr_spec(): end of header reached, state=29

12(3670) DEBUG: {1 17038 CANCEL CYxrNJtcCFZKS.PJN29LlEBd0aejPQUU} sanity [sanity.c:791]: check_parse_uris(): looking up To header

12(3670) DEBUG: {1 17038 CANCEL CYxrNJtcCFZKS.PJN29LlEBd0aejPQUU} sanity [sanity.c:837]: check_parse_uris(): check_parse_uris passed

12(3670) DEBUG: {1 17038 CANCEL CYxrNJtcCFZKS.PJN29LlEBd0aejPQUU} sanity [sanity_mod.c:254]: w_sanity_check(): sanity checks result: 1

12(3670) DEBUG: {1 17038 CANCEL CYxrNJtcCFZKS.PJN29LlEBd0aejPQUU} tm [t_lookup.c:727]: t_lookupOriginalT(): searching on hash entry 10182

12(3670) DEBUG: {1 17038 CANCEL CYxrNJtcCFZKS.PJN29LlEBd0aejPQUU} tm [t_lookup.c:440]: matching_3261(): RFC3261 transaction matched, tid=PjLBcUXshEKW2s9T0en9czTYAsciW1vV-W

12(3670) DEBUG: {1 17038 CANCEL CYxrNJtcCFZKS.PJN29LlEBd0aejPQUU} tm [t_lookup.c:823]: t_lookupOriginalT(): canceled transaction found (0x729bff78)!

12(3670) DEBUG: {1 17038 CANCEL CYxrNJtcCFZKS.PJN29LlEBd0aejPQUU} tm [t_lookup.c:826]: t_lookupOriginalT(): found - lookup completed

12(3670) DEBUG: {1 17038 CANCEL CYxrNJtcCFZKS.PJN29LlEBd0aejPQUU} tm [tm.c:1232]: ki_t_lookup_cancel_flags(): lookup_original: t_lookupOriginalT returned: 0x729bff78

12(3670) DEBUG: {1 17038 CANCEL CYxrNJtcCFZKS.PJN29LlEBd0aejPQUU} tm [t_lookup.c:1348]: t_newtran(): msg (0x771181ec) id=1/3670 global id=0/0 T start=0xffffffff

12(3670) DEBUG: {1 17038 CANCEL CYxrNJtcCFZKS.PJN29LlEBd0aejPQUU} tm [t_lookup.c:498]: t_lookup_request(): start searching: hash=10182, isACK=0

12(3670) DEBUG: {1 17038 CANCEL CYxrNJtcCFZKS.PJN29LlEBd0aejPQUU} tm [t_lookup.c:456]: matching_3261(): RFC3261 transaction matching failed - via branch [z9hG4bKPjLBcUXshEKW2s9T0en9czTYAsciW1vV-W]

12(3670) DEBUG: {1 17038 CANCEL CYxrNJtcCFZKS.PJN29LlEBd0aejPQUU} tm [t_lookup.c:675]: t_lookup_request(): no transaction found

12(3670) DEBUG: {1 17038 CANCEL CYxrNJtcCFZKS.PJN29LlEBd0aejPQUU} <core> [core/crypto/md5utils.c:67]: MD5StringArray(): MD5 calculated: dd71ad9d7511b02a5fc83c3c70ce307f

12(3670) DEBUG: {1 17038 CANCEL CYxrNJtcCFZKS.PJN29LlEBd0aejPQUU} tm [t_lookup.c:727]: t_lookupOriginalT(): searching on hash entry 10182

12(3670) DEBUG: {1 17038 CANCEL CYxrNJtcCFZKS.PJN29LlEBd0aejPQUU} tm [t_lookup.c:432]: matching_3261(): matched skip method - s:0x2 t:0x2 m:0x2 - continue searching

12(3670) DEBUG: {1 17038 CANCEL CYxrNJtcCFZKS.PJN29LlEBd0aejPQUU} tm [t_lookup.c:440]: matching_3261(): RFC3261 transaction matched, tid=PjLBcUXshEKW2s9T0en9czTYAsciW1vV-W

12(3670) DEBUG: {1 17038 CANCEL CYxrNJtcCFZKS.PJN29LlEBd0aejPQUU} tm [t_lookup.c:823]: t_lookupOriginalT(): canceled transaction found (0x729bff78)!

12(3670) DEBUG: {1 17038 CANCEL CYxrNJtcCFZKS.PJN29LlEBd0aejPQUU} tm [t_lookup.c:826]: t_lookupOriginalT(): found - lookup completed

12(3670) BUG: {1 17038 CANCEL CYxrNJtcCFZKS.PJN29LlEBd0aejPQUU} tm [t_cancel.c:318]: cancel_branch(): local_cancel buffer=(nil) != BUSY_BUFFER (trying to continue)

12(3670) ERROR: {1 17038 CANCEL CYxrNJtcCFZKS.PJN29LlEBd0aejPQUU} tm [t_fwd.c:1434]: e2e_cancel(): cancel error

12(3670) DEBUG: {1 17038 CANCEL CYxrNJtcCFZKS.PJN29LlEBd0aejPQUU} tm [t_reply.c:1763]: cleanup_uac_timers(): RETR/FR timers reset

12(3670) DEBUG: {1 17038 CANCEL CYxrNJtcCFZKS.PJN29LlEBd0aejPQUU} tm [t_reply.c:638]: _reply_light(): reply sent out - buf=0x77101e68: SIP/2.0 500 cancel e... shmem=0x729c5b60: SIP/2.0 500 cancel e

12(3670) DEBUG: {1 17038 CANCEL CYxrNJtcCFZKS.PJN29LlEBd0aejPQUU} tm [t_funcs.c:120]: put_on_wait(): put T [0x729c36d8] on wait

12(3670) DEBUG: {1 17038 CANCEL CYxrNJtcCFZKS.PJN29LlEBd0aejPQUU} tm [t_reply.c:648]: _reply_light(): finished

12(3670) DEBUG: {1 17038 CANCEL CYxrNJtcCFZKS.PJN29LlEBd0aejPQUU} tm [t_funcs.c:373]: t_relay_to(): new transaction forwarded

12(3670) DEBUG: {1 17038 CANCEL CYxrNJtcCFZKS.PJN29LlEBd0aejPQUU} <core> [core/receive.c:529]: receive_msg(): request-route executed in: 9868 usec

12(3670) DEBUG: {1 17038 CANCEL CYxrNJtcCFZKS.PJN29LlEBd0aejPQUU} <core> [core/usr_avp.c:637]: destroy_avp_list(): destroying list (nil)

12(3670) DEBUG: {1 17038 CANCEL CYxrNJtcCFZKS.PJN29LlEBd0aejPQUU} <core> [core/xavp.c:541]: xavp_destroy_list(): destroying xavp list (nil)

12(3670) DEBUG: {1 17038 CANCEL CYxrNJtcCFZKS.PJN29LlEBd0aejPQUU} <core> [core/receive.c:628]: receive_msg(): cleaning up

34(3692) DEBUG: tm [timer.c:642]: wait_handler(): finished transaction: 0x729c36d8 (p:0x72866768/n:0x729bff78)

34(3692) DEBUG: tm [h_table.c:132]: free_cell_helper(): freeing transaction 0x729c36d8 from timer.c:650