Hello and thanks for the reply!

Den fre 11 aug. 2023 kl 21:46 skrev Henning Westerholt <hw@gilawa.com>:

Hello,

this sounds odd. Are you maybe using a failure route to intercept the 503 and send the INVITE to a new destination?

I have checked the failure_routes and the only one it should be able to take only prints some logging. To be on the safe side I added logging to every failure_route and I cannot see it takes any of those failure_routes actually.

When the implicit 408 is processed I can see that it goes through event_route[tm:branch-failure:xyz] but that route also has only log printouts. No action is taken here either. While processing the 503 it doesn't seem to go through the event_route[tm:branch-failure:xyz], though.

I have enabled extra level of debug prints for tm , tmx and core. Is there any other module I should enable as well?

I have tried to understand the log but had a hard time to figure out why this is happening. What I can see is that the processing of the 503 differs a lot from how the "implicit" 408 was processed. For example in the log for 503 it is possible to see the (as I understand it) DNS failover (dns_a_resolve())in action while no such thing can be seen when the "implicit" 408 is processed.

Sorry for appending this lengthy log file produced but it is what I am now trying to understand. BTW. I am using Kamailio 5.5.3. Perhaps I should try a later version but I am under the impression that it is my configuration that is at fault unless otherwise proven.

/Mattis

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[334]: DEBUG: <core> [core/io_wait.h:600]: io_watch_del(): DBG: io_watch_del (0x561d25d75420, 78, -1, 0x0) fd_no=61 called

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[334]: DEBUG: <core> [core/tcp_main.c:4471]: handle_tcpconn_ev(): sending to child, events 1

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[334]: DEBUG: <core> [core/tcp_main.c:4141]: send2child(): selected tcp worker idx:4 proc:40 pid:330 for activity on [tcp:127.0.0.1:5080], 0x7ff6d547d848

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/tcp_read.c:1737]: handle_io(): received n=8 con=0x7ff6d547d848, fd=14

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/parser/parse_fline.c:249]: parse_first_line(): first line type 2 (reply(status)) flags 1

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/tcp_read.c:1536]: tcp_read_req(): content-length=212

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/receive.c:126]: sip_check_fline(): first line indicates a SIP reply

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/proxy.c:264]: mk_proxy(): doing DNS lookup...

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/forward.c:175]: get_out_socket(): socket determined: 0x7ff6deb793b0

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/parser/parse_fline.c:249]: parse_first_line(): first line type 2 (reply(status)) flags 1

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/parser/msg_parser.c:687]: parse_msg(): SIP Reply (status):

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/parser/msg_parser.c:689]: parse_msg(): version: <SIP/2.0>

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/parser/msg_parser.c:691]: parse_msg(): status: <503>

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/parser/msg_parser.c:693]: parse_msg(): reason: <Failure>

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name [Via] type 1

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bKc71d.683e467296bf493c4deb34680f739eb2.0>; state=6

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 236, <i> = <2>; state=6

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 234, <received> = <127.0.0.1>; state=16

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/parser/msg_parser.c:555]: parse_headers(): Via found, flags=2

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/parser/msg_parser.c:557]: parse_headers(): this is the first via

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name [Via] type 1

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 235, <rport> = <52292>; state=6

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 234, <received> = <172.17.0.2>; state=6

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK301728>; state=16

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/parser/msg_parser.c:555]: parse_headers(): Via found, flags=78

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/parser/msg_parser.c:568]: parse_headers(): this is the second via

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name [To] type 3

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=275047

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/parser/parse_addr_spec.c:884]: parse_addr_spec(): end of header reached, state=29

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/parser/msg_parser.c:173]: get_hdr_field(): <To> [73]; uri=[sip:siprec@sip.dev.abc.com;transport=tcp;transport=tcp]

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/parser/msg_parser.c:176]: get_hdr_field(): to body (60)[<sip:siprec@sip.dev.abc.com;transport=tcp;transport=tcp>], to tag (6)[275047]

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name [From] type 4

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name [Call-ID] type 6

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name [CSeq] type 5

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/parser/msg_parser.c:154]: get_hdr_field(): cseq <CSeq>: <26880> <INVITE>

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/receive.c:387]: receive_msg(): --- received sip message - reply - call-id: [2571561691999559409] - cseq: [26880 INVITE]

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/receive.c:259]: ksr_evrt_pre_routing(): event route core:pre-routing not defined

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: INFO: <script>: In reply_route 503 INVITE 2571561691999559409 SIP/2.0 503 Failure#015#012Via: SIP/2.0/TCP 172.17.0.2:5060;branch=z9hG4bKc71d.683e467296bf493c4deb34680f739eb2.0;i=2;received=127.0.0.1#015#012Via: SIP/2.0/TCP 127.0.0.1:35090;rport=52292;received=172.17.0.2;branch=z9hG4bK301728#015#012To: <sip:siprec@sip.dev.abc.com;transport=tcp;transport=tcp>;tag=275047#015#012From: <sip:systemtest@sip.dev.abc.com>;tag=408469#015#012Call-ID: 2571561691999559409#015#012CSeq: 26880 INVITE#015#012Content-Type: application/sdp#015#012Contact: <sip:siprec@127.0.0.1:35091;transport=tcp>#015#012Record-Route: <sip:172.17.0.2;r2=on;transport=tcp;lr>, <sip:172.17.0.2:5060;r2=on;transport=tcp;lr>#015#012Content-Length: 212#015#012#015#012v=0#015#012o=- 132273 930181 IN IP4 127.0.0.1#015#012s=-#015#012c=IN IP4 127.0.0.1#015#012t=0 0#015#012m=audio 30002 RTP/AVP 8 101#015#012a=rtpmap:8 PCMA/8000#015#012a=ptime:20#015#012a=rtpmap:101 telephone-event/8000#015#012a=fmtp:101 0-15#015#012a=ptime:20#015#012a=sendrecv#015

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: tmx [t_var.c:561]: pv_get_tm_reply_code(): reply code is <503>

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name [Content-Type] type 11

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name [Contact] type 7

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name [Record-Route] type 10

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name [Content-Length] type 12

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/parser/msg_parser.c:187]: get_hdr_field(): content_length=212

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/parser/msg_parser.c:91]: get_hdr_field(): found end of header

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: tm [t_lookup.c:1034]: t_check_msg(): msg (0x7ff6df4cbf68) id=1/330 global id=0/0 T start=0xffffffffffffffff

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: tm [t_lookup.c:912]: t_reply_matching(): t_reply_matching: hash 53628 label 0 branch 0

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: tm [t_lookup.c:967]: t_reply_matching(): reply (0x7ff6df4cbf68) matched an active transaction (T=0x7ff6d5477fc0)!

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: tm [t_hooks.c:256]: run_trans_callbacks_internal(): DBG: trans=0x7ff6d5477fc0, callback type 2, id 0 entered

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: tm [t_lookup.c:1103]: t_check_msg(): msg (0x7ff6df4cbf68) id=1/330 global id=1/330 T end=0x7ff6d5477fc0

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/parser/parse_fline.c:249]: parse_first_line(): first line type 1 (request) flags 1

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/parser/msg_parser.c:677]: parse_msg(): SIP Request:

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/parser/msg_parser.c:679]: parse_msg(): method: <INVITE>

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/parser/msg_parser.c:681]: parse_msg(): uri: <sip:siprec@sip.dev.abc.com;transport=tcp>

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/parser/msg_parser.c:683]: parse_msg(): version: <SIP/2.0>

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name [To] type 3

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/parser/parse_addr_spec.c:884]: parse_addr_spec(): end of header reached, state=10

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/parser/msg_parser.c:173]: get_hdr_field(): <To> [62]; uri=[sip:siprec@sip.dev.abc.com;transport=tcp;transport=tcp]

debug: Data: {"event":"stopped","params":{"dialogId":"2571561691999559409"}}

debug: Line: {"event":"stopped","params":{"dialogId":"2571561691999559409"}}

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/parser/msg_parser.c:176]: get_hdr_field(): to body (62)[<sip:siprec@sip.dev.abc.com;transport=tcp;transport=tcp>#015#012], to tag (0)[]

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name [From] type 4

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name [Call-ID] type 6

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name [CSeq] type 5

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/parser/msg_parser.c:154]: get_hdr_field(): cseq <CSeq>: <26880> <INVITE>

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name [Contact] type 7

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name [Max-Forwards] type 8

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name [Route] type 9

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name [Content-Type] type 11

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name [Via] type 1

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK301728>; state=16

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/parser/msg_parser.c:555]: parse_headers(): Via found, flags=2

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/parser/msg_parser.c:557]: parse_headers(): this is the first via

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: INFO: <script>: reply_route - Received reply - in if for 503 for <null> 503 with callid 2571561691999559409 INVITE

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: tm [t_lookup.c:1034]: t_check_msg(): msg (0x7ff6df4cbf68) id=1/330 global id=1/330 T start=0x7ff6d5477fc0

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: tm [t_lookup.c:1108]: t_check_msg(): T (0x7ff6d5477fc0) already found for msg (0x7ff6df4cbf68)!

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: tm [t_reply.c:2363]: reply_received(): transaction found - T:0x7ff6d5477fc0 branch:0

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: tm [t_reply.c:2376]: reply_received(): original status uas=200, uac[0]=408 local=0 is_invite=1)

verbose: Got event for dialog: 2571561691999559409 stopped

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/tcp_main.c:1623]: _tcpconn_find(): found connection by peer address (id: 3)

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/tcp_main.c:2485]: tcpconn_send_put(): send from reader (330 (40)), reusing fd

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/tcp_main.c:2720]: tcpconn_do_send(): sending...

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/tcp_main.c:2753]: tcpconn_do_send(): after real write: c= 0x7ff6d547d848 n=423 fd=14

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/tcp_main.c:2754]: tcpconn_do_send(): buf=#012ACK sip:siprec@sip.dev.abc.com;transport=tcp SIP/2.0#015#012To: <sip:siprec@sip.dev.abc.com;transport=tcp;transport=tcp>;tag=275047#015#012From: <sip:systemtest@sip.dev.abc.com>;tag=408469#015#012Call-ID: 2571561691999559409#015#012CSeq: 26880 ACK#015#012Max-Forwards: 70#015#012Route: <sip:172.17.0.2:5060;transport=tcp;lr=true>#015#012Via: SIP/2.0/TCP 172.17.0.2:5060;branch=z9hG4bKc71d.683e467296bf493c4deb34680f739eb2.0;i=2#015#012Content-Length: 0#015#012#015#012

debug: emitting event=stopped, dialogId=2571561691999559409

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/proxy.c:264]: mk_proxy(): doing DNS lookup...

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/forward.c:175]: get_out_socket(): socket determined: 0x7ff6deb793b0

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: tmx [t_var.c:561]: pv_get_tm_reply_code(): reply code is <503>

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: INFO: <script>: Received reply for siprec 503 with callid 2571561691999559409 INVITE SIP/2.0 503 Failure#015#012Via: SIP/2.0/TCP 172.17.0.2:5060;branch=z9hG4bKc71d.683e467296bf493c4deb34680f739eb2.0;i=2;received=127.0.0.1#015#012Via: SIP/2.0/TCP 127.0.0.1:35090;rport=52292;received=172.17.0.2;branch=z9hG4bK301728#015#012To: <sip:siprec@sip.dev.abc.com;transport=tcp;transport=tcp>;tag=275047#015#012From: <sip:systemtest@sip.dev.abc.com>;tag=408469#015#012Call-ID: 2571561691999559409#015#012CSeq: 26880 INVITE#015#012Content-Type: application/sdp#015#012Contact: <sip:siprec@127.0.0.1:35091;transport=tcp>#015#012Record-Route: <sip:172.17.0.2;r2=on;transport=tcp;lr>, <sip:172.17.0.2:5060;r2=on;transport=tcp;lr>#015#012Content-Length: 212#015#012#015#012v=0#015#012o=- 132273 930181 IN IP4 127.0.0.1#015#012s=-#015#012c=IN IP4 127.0.0.1#015#012t=0 0#015#012m=audio 30002 RTP/AVP 8 101#015#012a=rtpmap:8 PCMA/8000#015#012a=ptime:20#015#012a=rtpmap:101 telephone-event/8000#015#012a=fmtp:101 0-15#015#012a=ptime:20#015#012a=sendrecv#015

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: tmx [t_var.c:561]: pv_get_tm_reply_code(): reply code is <503>

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: INFO: <script>: Received reply - in if for 503 for siprec 503 with callid 2571561691999559409 INVITE

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: tm [t_lookup.c:1034]: t_check_msg(): msg (0x7ff6df4cbf68) id=1/330 global id=1/330 T start=0x7ff6d5477fc0

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: tm [t_lookup.c:1108]: t_check_msg(): T (0x7ff6d5477fc0) already found for msg (0x7ff6df4cbf68)!

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: tmx [t_var.c:561]: pv_get_tm_reply_code(): reply code is <503>

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: INFO: <script>: Received reply t_any_timeout siprec 503 with callid 2571561691999559409 INVITE

verbose: dtmfclient mediatool client stopped {"dialogId":"2571561691999559409"}

debug: Line:

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: tm [t_lookup.c:1034]: t_check_msg(): msg (0x7ff6df4cbf68) id=1/330 global id=1/330 T start=0x7ff6d5477fc0

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: tm [t_lookup.c:1108]: t_check_msg(): T (0x7ff6d5477fc0) already found for msg (0x7ff6df4cbf68)!

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: tmx [t_var.c:561]: pv_get_tm_reply_code(): reply code is <503>

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: INFO: <script>: Received reply t_any_replied() siprec 503 with callid 2571561691999559409 INVITE

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: tm [t_lookup.c:1034]: t_check_msg(): msg (0x7ff6df4cbf68) id=1/330 global id=1/330 T start=0x7ff6d5477fc0

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: tm [t_lookup.c:1108]: t_check_msg(): T (0x7ff6d5477fc0) already found for msg (0x7ff6df4cbf68)!

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: tm [t_lookup.c:1034]: t_check_msg(): msg (0x7ff6df4cbf68) id=1/330 global id=1/330 T start=0x7ff6d5477fc0

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: tm [t_lookup.c:1108]: t_check_msg(): T (0x7ff6d5477fc0) already found for msg (0x7ff6df4cbf68)!

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: tmx [t_var.c:561]: pv_get_tm_reply_code(): reply code is <503>

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: INFO: <script>: Received reply t_check_trans() siprec 503 with callid 2571561691999559409 INVITE

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: tmx [t_var.c:561]: pv_get_tm_reply_code(): reply code is <503>

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: tm [t_lookup.c:1034]: t_check_msg(): msg (0x7ff6df4cbf68) id=1/330 global id=1/330 T start=0x7ff6d5477fc0

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: tm [t_lookup.c:1108]: t_check_msg(): T (0x7ff6d5477fc0) already found for msg (0x7ff6df4cbf68)!

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: tmx [t_var.c:616]: pv_get_tm_reply_reason(): reply reason is [Failure]

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/dns_cache.c:527]: _dns_hash_find(): (sip.dev.abc.com(19), 35), h=780

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/dns_cache.c:2807]: dns_a_resolve(): (i-00940045868948771.siprec.discovery.dev.abc.com, 1) returning -1

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/dns_cache.c:2222]: dns_srv_get_nxt_rr(): (0x7ff6d547d098, 0, 0, 1354222632): selected 0/1 in grp. 1 (rand_w=0, rr=0x7ff6d547d160 rd=0x7ff6d547d178 p=10 w=100 rsum=100)

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/dns_cache.c:527]: _dns_hash_find(): (i-00940045868948772.siprec.discovery.dev.abc.com(52), 1), h=876

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/dns_cache.c:2807]: dns_a_resolve(): (i-00940045868948772.siprec.discovery.dev.abc.com, 0) returning 0

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/dns_cache.c:3050]: dns_srv_resolve_ip(): ("_sip._tcp.siprec.discovery.dev.abc.com", 1, 0), ret=0, ip=127.0.0.1

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/dns_cache.c:3163]: dns_srv_sip_resolve(): (sip.dev.abc.com, 1, 0), srv, ret=0

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/msg_translator.c:2985]: create_via_hf(): id added: <;i=2>, rcv proto=2

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: INFO: <script>: onsend_route INVITE sip:siprec@sip.dev.abc.com;transport=tcp SIP/2.0#015#012To: <sip:siprec@sip.dev.abc.com;transport=tcp;transport=tcp>#015#012From: <sip:systemtest@sip.dev.abc.com>;tag=408469#015#012Call-ID: 2571561691999559409#015#012CSeq: 26880 INVITE#015#012Contact: <sip:systemtest@127.0.0.1:35090;transport=tcp>#015#012Max-Forwards: 70#015#012Route: <sip:172.17.0.2:5060;transport=tcp;lr=true>#015#012Content-Type: application/sdp#015#012Via: SIP/2.0/TCP 127.0.0.1:35090;branch=z9hG4bK301728#015#012Content-Length: 224#015#012#015#012v=0#015#012o=- 728318 394366 IN IP4 127.0.0.1#015#012s=-#015#012c=IN IP4 127.0.0.1#015#012t=0 0#015#012m=audio 30000 RTP/AVP 8 101#015#012a=rtpmap:8 PCMA/8000#015#012a=ptime:20#015#012a=sendrecv#015#012a=rtpmap:101 telephone-event/8000#015#012a=fmtp:101 0-15#015#012a=ptime:20#015#012a=sendrecv#015#012

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/tcp_main.c:1623]: _tcpconn_find(): found connection by peer address (id: 5)

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/tcp_main.c:2501]: tcpconn_send_put(): tcp connection found (0x7ff6d5487600), acquiring fd

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/tcp_main.c:2511]: tcpconn_send_put(): c=0x7ff6d5487600, n=16

>>>>>> Here a ACK is received by the recording client.

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[334]: DEBUG: <core> [core/tcp_main.c:3806]: handle_ser_child(): read response= 7ff6d5487600, 2, fd -1 from 40 (330)

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/tcp_main.c:2541]: tcpconn_send_put(): after receive_fd: c= 0x7ff6d5487600 n=8 fd=16

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/tcp_main.c:2720]: tcpconn_do_send(): sending...

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/tcp_main.c:2753]: tcpconn_do_send(): after real write: c= 0x7ff6d5487600 n=958 fd=16

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/tcp_main.c:2754]: tcpconn_do_send(): buf=#012INVITE sip:siprec@sip.dev.abc.com;transport=tcp SIP/2.0#015#012Record-Route: <sip:172.17.0.2;r2=on;transport=tcp;lr>#015#012Record-Route: <sip:172.17.0.2:5060;r2=on;transport=tcp;lr>#015#012To: <sip:siprec@sip.dev.abc.com;transport=tcp;transport=tcp>#015#012From: <sip:systemtest@sip.dev.abc.com>;tag=408469#015#012Call-ID: 2571561691999559409#015#012CSeq: 26880 INVITE#015#012Contact: <sip:systemtest@127.0.0.1:35090;transport=tcp>#015#012Max-Forwards: 70#015#012Route: <sip:172.17.0.2:5060;transport=tcp;lr=true>#015#012Content-Type: application/sdp#015#012Via: SIP/2.0/TCP 172.17.0.2:5060;branch=z9hG4bKc71d.683e467296bf493c4deb34680f739eb2.2;i=2#015#012Via: SIP/2.0/TCP 127.0.0.1:35090;rport=52292;received=172.17.0.2;branch=z9hG4bK301728#015#012Content-Length: 224#015#012X-auth-domain: <null>#015#012#015#012v=0#015#012o=- 728318 394366 IN IP4 127.0.0.1#015#012s=-#015#012c=IN IP4 127.0.0.1#015#012t=0 0#015#012m=audio 30000 RTP/AVP 8 101#015#012a=rtpmap:8 PCMA/8000#015#012a=ptime:20#015#012a=sendrecv#015#012a=rtpmap:101 telephone-event/8000#015#012a=fmtp:101 0-15#015#012a=ptime:20#015#012a=sendrecv#015#012

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/proxy.c:264]: mk_proxy(): doing DNS lookup...

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/forward.c:175]: get_out_socket(): socket determined: 0x7ff6deb793b0

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: tm [t_reply.c:1363]: t_should_relay_response(): ->>>>>>>>> T_code=200, new_code=503

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: tm [t_reply.c:1374]: t_should_relay_response(): final reply already sent

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: tm [t_reply.c:1625]: t_should_relay_response(): finished with rps discarded - uas status: 200

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: tm [t_reply.c:1924]: relay_reply(): reply status=2 branch=0, save=0, relay=-1 icode=0 msg status=503

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/receive.c:596]: receive_msg(): reply-route executed in: 9148 usec

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/usr_avp.c:637]: destroy_avp_list(): destroying list (nil)

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/xavp.c:541]: xavp_destroy_list(): destroying xavp list (nil)

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/receive.c:606]: receive_msg(): cleaning up

Aug 14 07:52:44 4e8d794e0e40 /usr/sbin/kamailio[330]: DEBUG: <core> [core/io_wait.h:375]: io_watch_add(): processing io_watch_add(0x561d25d08260, 14, 2, 0x7ff6d547d848) - fd_no=1

Cheers,

Henning

--

Henning Westerholt – https://skalatan.de/blog/

Kamailio services – https://gilawa.com

From: Mattis Lind <mattislind@gmail.com>
Sent: Donnerstag, 10. August 2023 15:02
To: sr-users@lists.kamailio.org
Subject: [SR-Users] Kamailio dns-failover / dns-loadbalancing with slow responding client.

Hello!

I am looking into a problem where we have Kamailio forwarding calls to two or more "recording-clients". I will try my best to describe the problem and would appreciate it if someone has an idea what to do. Please feel free to ask if you think I have forgotten to describe something that might be important or something is unclear in what I have written.

We use use_dns_failover=yes and dns_srv_lb=yes so calls get load balancing to the "recording-clients". There is also the t_set_fr(60000,1000) parameter set so that if there is no response within 1 second it would try the next recording-client. The SRV record points to two or more recording clients.

It now happens that the recording-clients sometimes have some kind of temporary problem so it will respond with a 503 after 5 seconds.

What happens is that after the 1 second timeout trying to get the INVITE through to the first recording-client Kamailio will internally generate a 408. This will cause it to failover to another recording-client which happily takes care of the INVITE and responds properly with a 200 OK.

Everything would have been just fine except for the fact that the first recording-client is just slow and finally responds with a 503. This 503 is not relayed backwards since a 200 has already been forwarded back to the caller. But when receiving the 503 Kamailio will initiate a new INVITE which is trying to set up a new call to a recording client. It looks like it is doing a new failover regardless if it already has done a failover for this failed transaction.

I don't want Kamailio to send that last INVITE when receiving the 503. How can I configure Kamailio to disregard the last 503 (except for responding with an ACK) and not initiate a new INVITE?

I have tried a lot of different changes to the configuration but failed to achieve this, unfortunately. Do I need to use the dispatcher module to achieve this?

/Mattis