pseudovar $ru not in sync with $rz,$rU,$rp, etc #3762

gaaf · 2024-02-22T17:40:29Z

Description

The uri parser seems to fail in multiple ways on username-parameters. The ways it fails depends on the presence of user-params in the incoming request and on adjustments to $ru, $rd and $rU in the script.

My expectation is that the whole username, including user-params is always visible in $rU. In reality, the user-params are absent or present depending on manipulations to the uri in the script.

When setting $rU to a value with a user-param, that user-param is represented when reading $ru, but not in $rU.

Troubleshooting

Reproduction

I used below config script to test various scenario's.

debug=2
memlog=4
#fork=no    # This option should not be present to enable forking but disable daemonize, also -D commandline parameter is needed
log_stderror=yes
log_name="kamailio-test"
log_facility=LOG_LOCAL5

sip_warning=no

children=2
shm_mem_size=128

check_via=no    # (cmd. line: -v)
dns=no          # (cmd. line: -r)
rev_dns=no      # (cmd. line: -R)
dns_use_search_list=no
use_dns_failover=yes
dns_srv_lb=yes
disable_tcp=yes

auto_aliases=no
listen=172.16.1.19:7060


loadmodule "sl.so"
loadmodule "pv.so"
loadmodule "xlog.so"

modparam("xlog", "prefix", "")


route {
	xnotice("Incoming $rm to $rU\n");
	xinfo("$$ru = $ru\n");
	switch ($rU) {
		case "100":
			xnotice("Set $$rU = \"1234;first=yes\"\n");
			$rU = "1234;first=yes";
			xinfo("$$ru: $ru\n");
			xinfo("$$rU: $rU\n");
			if ($rU != "1234;first=yes") {
				xerr("Fail!\n");
			} else {
				xinfo("Success!\n");
			}
			break;
			
		case "200":
			xnotice("Set $$rd = \"example.com;transport=udp\"\n");
			$rd = "example.com;transport=udp";
			xinfo("$$ru: $ru\n");
			xinfo("$$rU: $rU\n");
			xnotice("Set $$rU = \"1234;first=yes\"\n");
			$rU = "1234;first=yes";
			xinfo("$$ru: $ru\n");
			xinfo("$$rU: $rU\n");
			if ($rU != "1234;first=yes") {
				xerr("Fail!\n");
			} else {
				xinfo("Success!\n");
			}
			break;
			
		case "300":
			xnotice("Set $$ru = \"sip:1234@example.com;transport=udp\"\n");
			$ru = "sip:1234@example.com;transport=udp";
			xinfo("$$ru: $ru\n");
			xinfo("$$rU: $rU\n");
			xnotice("Set $$rU = \"1234;first=yes\"\n");
			$rU = "1234;first=yes";
			xinfo("$$ru: $ru\n");
			xinfo("$$rU: $rU\n");
			if ($rU != "1234;first=yes") {
				xerr("Fail!\n");
			} else {
				xinfo("Success!\n");
			}
			break;

		case "400":
			xnotice("Set $$ru = \"sip:1234;first=yes@example.com;transport=udp\"\n");
			$ru = "sip:1234;first=yes@example.com;transport=udp";
			xinfo("$$ru: $ru\n");
			xinfo("$$rU: $rU\n");
			if ($rU != "1234;first=yes") {
				xerr("Fail!\n");
			} else {
				xinfo("Success!\n");
			}
			xnotice("Set $$rU = \"1234;second=yes\"\n");
			$rU = "1234;second=yes";
			xinfo("$$ru: $ru\n");
			xinfo("$$rU: $rU\n");
			if ($rU != "1234;second=yes") {
				xerr("Fail!\n");
			} else {
				xinfo("Success!\n");
			}
			break;
	}
 
	sl_send_reply(500, "Done");
	exit;
}

Outputs:

 1(2206122) NOTICE: Incoming INVITE to 100
 1(2206122) INFO: $ru = sip:100@172.16.1.19:7060;user=phone
 1(2206122) NOTICE: Set $rU = "1234;first=yes"
 1(2206122) INFO: $ru: sip:1234;first=yes@172.16.1.19:7060;user=phone
 1(2206122) INFO: $rU: 1234
 1(2206122) ERROR: Fail!

Setting $rU with a user-param sets it correctly in $ru, but reading $rU back fails.

 1(2206122) NOTICE: Incoming INVITE to 200
 1(2206122) INFO: $ru = sip:200@172.16.1.19:7060;user=phone
 1(2206122) NOTICE: Set $rd = "example.com;transport=udp"
 1(2206122) INFO: $ru: sip:200@example.com;transport=udp:7060;user=phone
 1(2206122) INFO: $rU: 200
 1(2206122) NOTICE: Set $rU = "1234;first=yes"
 1(2206122) INFO: $ru: sip:1234;first=yes@example.com;transport=udp:7060;user=phone
 1(2206122) INFO: $rU: 1234
 1(2206122) ERROR: Fail!

Same when setting $rd in advance.

 1(2206122) NOTICE: Incoming INVITE to 300
 1(2206122) INFO: $ru = sip:300@172.16.1.19:7060;user=phone
 1(2206122) NOTICE: Set $ru = "sip:1234@example.com;transport=udp"
 1(2206122) INFO: $ru: sip:1234@example.com;transport=udp
 1(2206122) INFO: $rU: 1234
 1(2206122) NOTICE: Set $rU = "1234;first=yes"
 1(2206122) INFO: $ru: sip:1234;first=yes@example.com;transport=udp
 1(2206122) INFO: $rU: 1234;first=yes
 1(2206122) INFO: Success!

When setting $ru first with no user-param lets a later asssignment to $rU with user-param succeed.

 1(2206122) NOTICE: Incoming INVITE to 400
 1(2206122) INFO: $ru = sip:400@172.16.1.19:7060;user=phone
 1(2206122) NOTICE: Set $ru = "sip:1234;first=yes@example.com;transport=udp"
 1(2206122) INFO: $ru: sip:1234;first=yes@example.com;transport=udp
 1(2206122) INFO: $rU: 1234;first=yes
 1(2206122) INFO: Success!
 1(2206122) NOTICE: Set $rU = "1234;second=yes"
 1(2206122) INFO: $ru: sip:1234;second=yes@example.com;transport=udp
 1(2206122) INFO: $rU: 1234;second=yes
 1(2206122) INFO: Success!

Setting $ru with a user-params succeeds. Subsequently overwriting the user part with $rU with a user-param also succeeds.

 1(2206122) NOTICE: Incoming INVITE to 400
 1(2206122) INFO: $ru = sip:400;existing=yes@172.16.1.19:7060;user=phone
 1(2206122) NOTICE: Set $ru = "sip:1234;first=yes@example.com;transport=udp"
 1(2206122) INFO: $ru: sip:1234;first=yes@example.com;transport=udp
 1(2206122) INFO: $rU: 1234;first=yes
 1(2206122) INFO: Success!
 1(2206122) NOTICE: Set $rU = "1234;second=yes"
 1(2206122) INFO: $ru: sip:1234;second=yes@example.com;transport=udp
 1(2206122) INFO: $rU: 1234;second=yes
 1(2206122) INFO: Success!

Same as previous, but with incoming user-param.

 1(2206122) NOTICE: Incoming INVITE to 100
 1(2206122) INFO: $ru = sip:100;existing=yes@172.16.1.19:7060;user=phone
 1(2206122) NOTICE: Set $rU = "1234;first=yes"
 1(2206122) INFO: $ru: sip:1234;first=yes;existing=yes@172.16.1.19:7060;user=phone
 1(2206122) INFO: $rU: 1234
 1(2206122) ERROR: Fail!

This one fails in an interesting way. The incoming uri has a user-param. When overwriting $rU with a user-param, the user-param from the incoming request is kept in addition to the new one instead of being overwritten. $rU still misses (both) user-params.

Debugging Data

I have no build (yet) with EXTRA_DEBUG enabled.

The text was updated successfully, but these errors were encountered:

gaaf · 2024-02-22T18:10:18Z

Debug log with EXTRA_DEBUG enabled for call scenario 100:

 1(2262224) DEBUG: <core> [core/udp_server.c:494]: udp_rcv_loop(): received on udp socket: (106/100/493) [[INVITE sip:100@172.16.1.19:7060;user=phone SIP/2.0 0D  0A Via: SIP/2.0/UDP 172.16.1.19:7001;branch=z9hG4bK]]
 1(2262224) DEBUG: <core> [core/parser/parse_fline.c:249]: parse_first_line(): first line type 1 (request) flags 1
 1(2262224) DEBUG: <core> [core/parser/msg_parser.c:677]: parse_msg(): SIP Request:
 1(2262224) DEBUG: <core> [core/parser/msg_parser.c:678]: parse_msg():  method:  <INVITE>
 1(2262224) DEBUG: <core> [core/parser/msg_parser.c:680]: parse_msg():  uri:     <sip:100@172.16.1.19:7060;user=phone>
 1(2262224) DEBUG: <core> [core/parser/msg_parser.c:682]: parse_msg():  version: <SIP/2.0>
 1(2262224) DEBUG: <core> [core/parser/msg_parser.c:324]: parse_headers(): flags=2
 1(2262224) DEBUG: <core> [core/parser/parse_hname2.c:301]: parse_sip_header_name(): parsed header name [Via] type 1
 1(2262224) DEBUG: <core> [core/parser/parse_via.c:1300]: parse_via_param(): Found param type 232, <branch> = <z9hG4bKa1-1>; state=16
 1(2262224) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
 1(2262224) DEBUG: <core> [core/parser/msg_parser.c:555]: parse_headers(): Via found, flags=2
 1(2262224) DEBUG: <core> [core/parser/msg_parser.c:557]: parse_headers(): this is the first via
 1(2262224) DEBUG: <core> [core/parser/msg_parser.c:618]: parse_headers(): header field type 1, name=<Via>, body=<SIP/2.0/UDP 172.16.1.19:7001;branch=z9hG4bKa1-1>
 1(2262224) DEBUG: <core> [core/parser/msg_parser.c:709]: parse_msg(): first via: <SIP/2.0/UDP> <172.16.1.19:7001(7001)> 1(2262224) DEBUG: <core> [core/parser/msg_parser.c:717]: parse_msg(): ;<> 1(2262224) DEBUG: <core> [core/parser/msg_parser.c:720]: parse_msg(): 
 1(2262224) DEBUG: <core> [core/parser/msg_parser.c:740]: parse_msg(): exiting parse_msg
 1(2262224) DEBUG: <core> [core/parser/msg_parser.c:324]: parse_headers(): flags=78
 1(2262224) DEBUG: <core> [core/parser/parse_hname2.c:301]: parse_sip_header_name(): parsed header name [From] type 4
 1(2262224) DEBUG: <core> [core/parser/msg_parser.c:618]: parse_headers(): header field type 4, name=<From>, body=<"test" <sip:+12345678@172.16.1.19:7001>;tag=1>
 1(2262224) DEBUG: <core> [core/parser/parse_hname2.c:301]: parse_sip_header_name(): parsed header name [To] type 3
 1(2262224) DEBUG: <core> [core/parser/parse_addr_spec.c:884]: parse_addr_spec(): end of header reached, state=10
 1(2262224) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): <To> [39]; uri=[sip:100@172.16.1.19:7060;user=phone]
 1(2262224) DEBUG: <core> [core/parser/msg_parser.c:174]: get_hdr_field(): to body (39)[<sip:100@172.16.1.19:7060;user=phone>
], to tag (0)[]
 1(2262224) DEBUG: <core> [core/parser/msg_parser.c:618]: parse_headers(): header field type 3, name=<To>, body=<<sip:100@172.16.1.19:7060;user=phone>>
 1(2262224) DEBUG: <core> [core/parser/parse_hname2.c:301]: parse_sip_header_name(): parsed header name [Call-ID] type 6
 1(2262224) DEBUG: <core> [core/parser/msg_parser.c:618]: parse_headers(): header field type 6, name=<Call-ID>, body=<1-2262234@172.16.1.19>
 1(2262224) DEBUG: <core> [core/parser/parse_hname2.c:301]: parse_sip_header_name(): parsed header name [CSeq] type 5
 1(2262224) DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>: <1> <INVITE>
 1(2262224) DEBUG: <core> [core/parser/msg_parser.c:618]: parse_headers(): header field type 5, name=<CSeq>, body=<1 INVITE>
 1(2262224) DEBUG: <core> [core/receive.c:389]: receive_msg(): --- received sip message - request - call-id: [1-2262234@172.16.1.19] - cseq: [1 INVITE]
 1(2262224) DEBUG: <core> [core/receive.c:261]: ksr_evrt_pre_routing(): event route core:pre-routing not defined
 1(2262224) DEBUG: <core> [core/receive.c:471]: receive_msg(): preparing to run routing scripts...
 1(2262224) DEBUG: <core> [core/parser/parse_uri.c:1252]: parse_uri(): state=11
 1(2262224) DEBUG: <core> [core/parser/parse_uri.c:1253]: parse_uri(): parsed uri:
 type=3 user=<100>(3)
 passwd=<>(0)
 host=<172.16.1.19>(11)
 port=<7060>(4): 7060
 params=<>(0)
 headers=<>(0)
 1(2262224) DEBUG: <core> [core/parser/parse_uri.c:1264]: parse_uri():  uri flags :  1(2262224) DEBUG: <core> [core/parser/parse_uri.c:1266]: parse_uri(): sip_user_phone  1(2262224) DEBUG: <core> [core/parser/parse_uri.c:1267]: parse_uri():    value=2
 1(2262224) DEBUG: <core> [core/parser/parse_uri.c:1268]: parse_uri():  uri params:
   transport=<>, val=<>, proto=0
 1(2262224) DEBUG: <core> [core/parser/parse_uri.c:1271]: parse_uri():    user-param=<user=phone>, val=<phone>
 1(2262224) DEBUG: <core> [core/parser/parse_uri.c:1274]: parse_uri():    method=<>, val=<>
 1(2262224) DEBUG: <core> [core/parser/parse_uri.c:1277]: parse_uri():    ttl=<>, val=<>
 1(2262224) DEBUG: <core> [core/parser/parse_uri.c:1280]: parse_uri():    maddr=<>, val=<>
 1(2262224) DEBUG: <core> [core/parser/parse_uri.c:1283]: parse_uri():    lr=<>
 1(2262224) DEBUG: <core> [core/parser/parse_uri.c:1284]: parse_uri():    r2=<>
 1(2262224) DEBUG: <core> [core/pvapi.c:1509]: pv_printf_mode(): final buffer length 23
 1(2262224) NOTICE: Incoming INVITE to 100
 1(2262224) DEBUG: <core> [core/pvapi.c:1509]: pv_printf_mode(): final buffer length 42
 1(2262224) INFO: $ru = sip:100@172.16.1.19:7060;user=phone
 1(2262224) DEBUG: <core> [core/pvapi.c:1509]: pv_printf_mode(): final buffer length 27
 1(2262224) NOTICE: Set $rU = "1234;first=yes"
 1(2262224) DEBUG: <core> [core/parser/parse_uri.c:1252]: parse_uri(): state=11
 1(2262224) DEBUG: <core> [core/parser/parse_uri.c:1253]: parse_uri(): parsed uri:
 type=3 user=<1234>(4)
 passwd=<>(0)
 host=<172.16.1.19>(11)
 port=<7060>(4): 7060
 params=<first=yes>(9)
 headers=<>(0)
 1(2262224) DEBUG: <core> [core/parser/parse_uri.c:1264]: parse_uri():  uri flags :  1(2262224) DEBUG: <core> [core/parser/parse_uri.c:1266]: parse_uri(): sip_user_phone  1(2262224) DEBUG: <core> [core/parser/parse_uri.c:1267]: parse_uri():    value=2
 1(2262224) DEBUG: <core> [core/parser/parse_uri.c:1268]: parse_uri():  uri params:
   transport=<>, val=<>, proto=0
 1(2262224) DEBUG: <core> [core/parser/parse_uri.c:1271]: parse_uri():    user-param=<user=phone>, val=<phone>
 1(2262224) DEBUG: <core> [core/parser/parse_uri.c:1274]: parse_uri():    method=<>, val=<>
 1(2262224) DEBUG: <core> [core/parser/parse_uri.c:1277]: parse_uri():    ttl=<>, val=<>
 1(2262224) DEBUG: <core> [core/parser/parse_uri.c:1280]: parse_uri():    maddr=<>, val=<>
 1(2262224) DEBUG: <core> [core/parser/parse_uri.c:1283]: parse_uri():    lr=<>
 1(2262224) DEBUG: <core> [core/parser/parse_uri.c:1284]: parse_uri():    r2=<>
 1(2262224) DEBUG: <core> [core/pvapi.c:1509]: pv_printf_mode(): final buffer length 52
 1(2262224) INFO: $ru: sip:1234;first=yes@172.16.1.19:7060;user=phone
 1(2262224) DEBUG: <core> [core/pvapi.c:1509]: pv_printf_mode(): final buffer length 10
 1(2262224) INFO: $rU: 1234
 1(2262224) DEBUG: <core> [core/pvapi.c:1509]: pv_printf_mode(): final buffer length 6
 1(2262224) ERROR: Fail!

gaaf · 2024-03-05T15:14:14Z

Well this all is caused by the phone2tel parameter defaulting to "on" and the fact that the pseudovars $rU/$rp/$rz/etc are NOT in sync with what is in $ru.

github-actions · 2024-04-17T02:39:26Z

This issue is stale because it has been open 6 weeks with no activity. Remove stale label or comment or this will be closed in 2 weeks.

gaaf changed the title ~~User-params parsing fails in multiple ways~~ pseudovar $ru not in sync with $rz,$rU,$rp, etc Mar 5, 2024

github-actions bot added the Stale label Apr 17, 2024

github-actions bot added the expired label May 1, 2024

github-actions bot closed this as not planned Won't fix, can't repro, duplicate, stale May 1, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

pseudovar $ru not in sync with $rz,$rU,$rp, etc #3762

pseudovar $ru not in sync with $rz,$rU,$rp, etc #3762

gaaf commented Feb 22, 2024

gaaf commented Feb 22, 2024

gaaf commented Mar 5, 2024 •

edited

github-actions bot commented Apr 17, 2024

pseudovar $ru not in sync with $rz,$rU,$rp, etc #3762

pseudovar $ru not in sync with $rz,$rU,$rp, etc #3762

Comments

gaaf commented Feb 22, 2024

Description

Troubleshooting

Reproduction

Outputs:

Debugging Data

gaaf commented Feb 22, 2024

gaaf commented Mar 5, 2024 • edited

github-actions bot commented Apr 17, 2024

gaaf commented Mar 5, 2024 •

edited