Hello and thanks for the reply!
Den fre 11 aug. 2023 kl 21:46 skrev Henning Westerholt <[email protected]>: > 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 <http://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:[email protected] <sip%[email protected]>;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:[email protected] <sip%[email protected]>;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:[email protected] <sip%[email protected]>;transport=tcp;transport=tcp>;tag=275047#015#012From: <sip:[email protected] <sip%[email protected]>>;tag=408469#015#012Call-ID: 2571561691999559409#015#012CSeq: 26880 INVITE#015#012Content-Type: application/sdp#015#012Contact: <sip:[email protected]: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: 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_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:[email protected] <sip%[email protected]>;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:[email protected] <sip%[email protected]>;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:[email protected] <sip%[email protected]>;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:[email protected] <sip%[email protected]>;transport=tcp SIP/2.0#015#012To: <sip:[email protected] <sip%[email protected]>;transport=tcp;transport=tcp>;tag=275047#015#012From: <sip:[email protected] <sip%[email protected]>>;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:[email protected] <sip%[email protected]>;transport=tcp;transport=tcp>;tag=275047#015#012From: <sip:[email protected] <sip%[email protected]>>;tag=408469#015#012Call-ID: 2571561691999559409#015#012CSeq: 26880 INVITE#015#012Content-Type: application/sdp#015#012Contact: <sip:[email protected]: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: 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 <http://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 <http://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 <http://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 <http://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 <http://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 <http://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:[email protected] <sip%[email protected]>;transport=tcp SIP/2.0#015#012To: <sip:[email protected] <sip%[email protected]>;transport=tcp;transport=tcp>#015#012From: <sip:[email protected] <sip%[email protected]>>;tag=408469#015#012Call-ID: 2571561691999559409#015#012CSeq: 26880 INVITE#015#012Contact: <sip:[email protected]: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:[email protected] <sip%[email protected]>;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:[email protected] <sip%[email protected]>;transport=tcp;transport=tcp>#015#012From: <sip:[email protected] <sip%[email protected]>>;tag=408469#015#012Call-ID: 2571561691999559409#015#012CSeq: 26880 INVITE#015#012Contact: <sip:[email protected]: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/usr_avp.c:637]: destroy_avp_list(): destroying list (nil)* *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/usr_avp.c:637]: destroy_avp_list(): destroying list (nil)* *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/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/xavp.c:541]: xavp_destroy_list(): destroying xavp 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 <[email protected]> > *Sent:* Donnerstag, 10. August 2023 15:02 > *To:* [email protected] > *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 >
__________________________________________________________ Kamailio - Users Mailing List - Non Commercial Discussions To unsubscribe send an email to [email protected] Important: keep the mailing list in the recipients, do not reply only to the sender! Edit mailing list options or unsubscribe:
