[SR-Users] cancel at first call after startup kamailio not relay

Hi, I have a problem with kamailio v 5.6.1 on mips architecture: version: kamailio 5.6.1 (mips/linux) flags: USE_TCP, USE_TLS, TLS_HOOKS, USE_RAW_SOCKS, DISABLE_NAGLE, USE_MCAST, DNS_IP_HACK, SHM_MMAP, PKG_MALLOC, Q_MALLOC, F_MALLOC, TLSF_MALLOC, DBG_SR_MEMORY, USE_FUTEX-NOSMP, USE_PTHREAD_MUTEX, USE_DNS_CACHE, USE_DNS_FAILOVER, USE_NAPTR, USE_DST_BLOCKLIST, HAVE_RESOLV_RES MAX_RECV_BUFFER_SIZE 262144, MAX_URI_SIZE 1024, BUF_SIZE 65535, DEFAULT PKG_SIZE 8MB poll method support: poll, epoll_lt, epoll_et, sigio_rt, select. id: unknown compiled on 14:22:18 Apr 27 2023 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/usr_avp.c:637]: destroy_avp_list(): destroying list (nil) 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/usr_avp.c:637]: destroy_avp_list(): destroying list (nil) 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/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/xavp.c:541]: xavp_destroy_list(): destroying xavp 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