Hi Steve,
Ricardo found that TI-RPC rpc_pmap_rmtcall [1] tirpc_rpcb_rmtcall [2] tests are
failing when they use rpcbind *without* --enable-rmtcalls (the default since
2018, see 2e9c289 ("rpcbind: Disable remote calls by default") [3]).
TL;DR: Is there a way to detect missing support from rpcbind? Because we cannot
blindly expect that timeout means disabled remote calls (it could be also
caused by regression). Other option is just to disable these tests by default
(detection is preferred).
# export PATH="/opt/ltp/testcases/bin:$PATH"
# rpc_test.sh -s tirpc_svc_4 -c tirpc_rpcb_rmtcall
...
tirpc_rpcb_rmtcall 10.0.0.2 536875000
rpc_test 1 TFAIL: tirpc_rpcb_rmtcall 10.0.0.2 536875000 failed unexpectedly
As the name of the test suggests they are using pmap_rmtcall() and rpcb_rmtcall().
A bit debug info.
Modified rpc_test.sh to use strace:
+++ b/testcases/network/rpc/rpc-tirpc/rpc_test.sh
@@ -87,6 +87,8 @@ do_test()
done
fi
+ echo "$CLIENT $(tst_ipaddr) $PROGNUMNOSVC $CLIENT_EXTRA_OPTS" # FIXME: debug
+ EXPECT_RHOST_PASS strace -o /tmp/a $CLIENT $(tst_ipaddr) $PROGNUMNOSVC $CLIENT_EXTRA_OPTS
EXPECT_RHOST_PASS $CLIENT $(tst_ipaddr) $PROGNUMNOSVC $CLIENT_EXTRA_OPTS
}
I see the test timeouts (full strace output below):
# rpc_test.sh -s tirpc_svc_4 -c tirpc_rpcb_rmtcall
...
sendto(5, "h=\r}\0\0\0\0\0\0\0\2\0\1\206\240\0\0\0\4\0\0\0\5\0\0\0\0\0\0\0\0"..., 60, 0, {sa_family=AF_INET, sin_port=htons(111), sin_addr=inet_addr("10.0.0.2")}, 16) = 60
poll([{fd=5, events=POLLIN}], 1, 1000) = 0 (Timeout)
Using rpcbind 1.2.7-1.2 (from Tumbleweed), output when run with debug mode:
# /usr/sbin/rpcbind -w -f -d
rpcbind: PMAPPROC_DUMP
rpcbind: RPCB_UNSET request for (536875000, 1, ) :
rpcbind: RPCB_UNSET: succeeded
rpcbind: RPCB_SET request for (536875000, 1, udp, 0.0.0.0.223.168) :
rpcbind: RPCB_SET: succeeded
rpcbind: RPCB_GETADDR req for (100000, 2, tcp) from 127.0.0.1.3.98:
mergeaddr: contact uaddr = 127.0.0.1.0.111
addrmerge(caller, 0.0.0.0.0.111, 127.0.0.1.0.111, tcp
addrmerge: hint 127.0.0.1.0.111
addrmerge: returning 127.0.0.1.0.111
mergeaddr: uaddr = 0.0.0.0.0.111, merged uaddr = 127.0.0.1.0.111
rpcbind: getaddr: 127.0.0.1.0.111
rpcbind: PMAPPROC_DUMP
rpcbind: RPCB_GETADDR req for (536875000, 1, udp) from 10.0.0.1.3.105:
mergeaddr: contact uaddr = 10.0.0.2.0.111
addrmerge(caller, 0.0.0.0.223.168, 10.0.0.2.0.111, udp
addrmerge: hint 10.0.0.2.0.111
addrmerge: returning 10.0.0.2.223.168
mergeaddr: uaddr = 0.0.0.0.223.168, merged uaddr = 10.0.0.2.223.168
rpcbind: getaddr: 10.0.0.2.223.168
rpcbind: RPCBPROC_BCAST
rpcbind: rpcb_indirect callit req for (536875000, 1, 1, udp) from 10.0.0.1.3.105 :
rpcbind: found at uaddr 0.0.0.0.223.168
addrmerge(caller, 0.0.0.0.223.168, NULL, udp
addrmerge: hint 127.0.0.1.0.111
addrmerge: returning 127.0.0.1.223.168
addrmerge(caller, 0.0.0.0.223.168, NULL, udp
addrmerge: hint 10.0.0.1.3.105
addrmerge: returning 192.168.122.43.223.168
rpcbind: merged uaddr 192.168.122.43.223.168
rpcbind: RPCB_UNSET request for (536875000, 1, ) :
rpcbind: Suppression RPC_UNSET(map_unset)
rpcbind: rbl->rpcb_map.r_owner=superuser
rpcbind: owner=superuser
rpcbind: RPCB_UNSET: succeeded
Obviously, if I compile rpcbind with --enable-rmtcalls and run it, both tests work:
$ ./autogen.sh && ./configure --enable-debug --enable-warmstarts --enable-rmtcalls --with-rpcuser=rpc --with-nss-modules="files usrfiles"
$ make -j`nproc`
# ./rpcbind -w -d -f
# rpc_test.sh -s tirpc_svc_4 -c tirpc_rpcb_rmtcall
...
rpc_test 1 TINFO: using libtirpc: yes
tirpc_rpcb_rmtcall 10.0.0.2 536875000
rpc_test 1 TPASS: tirpc_rpcb_rmtcall 10.0.0.2 536875000 passed as expected
# rpc_test.sh -s rpc_svc_1 -c rpc_pmap_rmtcall
...
rpc_pmap_rmtcall 10.0.0.2 536875000
rpc_test 1 TPASS: rpc_pmap_rmtcall 10.0.0.2 536875000 passed as expected
And the rpcbind outpt contains also:
rpcbind: rpcbproc_callit_com: original XID 683f1705, new XID f68e200
rpcbind: my_svc_run: polled on forwarding fd 7, netid udp - calling handle_reply
Also, wouldn't it be worth mention --enable-rmtcalls in functions' man pages?
(Or have I overlooked that in man?)
Thanks for any hint.
Kind regards,
Petr
[1] https://github.com/linux-test-project/ltp/tree/master/testcases/network/rpc/rpc-tirpc/tests_pack/rpc_suite/rpc/rpc_addrmanagmt_pmap_rmtcall/rpc_pmap_rmtcall.c
[2] https://github.com/linux-test-project/ltp/tree/master/testcases/network/rpc/rpc-tirpc/tests_pack/rpc_suite/tirpc/tirpc_expertlevel_rpcb_rmtcall/tirpc_rpcb_rmtcall.c
[3] https://git.linux-nfs.org/?p=steved/rpcbind.git;a=commitdiff;h=2e9c289246c647e25649914bdb0d9400c66f486e
Full strace on rpcbind compiled without --enable-rmtcalls (the default, thus
how it's shipped to the new distros):
# rpc_test.sh -s tirpc_svc_4 -c tirpc_rpcb_rmtcall
execve("/opt/ltp/testcases/bin/tirpc_rpcb_rmtcall", ["tirpc_rpcb_rmtcall", "10.0.0.2", "536875000"], 0x7ffee8701b10 /* 228 vars */) = 0
...
openat(AT_FDCWD, "/etc/services", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 5
...
openat(AT_FDCWD, "/usr/etc/services", O_RDONLY|O_CLOEXEC) = 5
fstat(5, {st_mode=S_IFREG|0644, st_size=868338, ...}) = 0
read(5, "#\n# Network services, Internet s"..., 4096) = 4096
read(5, "[Jon_Postel]\ndaytime "..., 4096) = 4096
read(5, "gs 44/udp # MPM F"..., 4096) = 4096
read(5, "emote Job Service \nnetrjs-2 "..., 4096) = 4096
read(5, "Jon_Postel]\nhostname 1"..., 4096) = 4096
close(5) = 0
socket(AF_INET, SOCK_DGRAM, IPPROTO_UDP) = 5
getsockname(5, {sa_family=AF_INET, sin_port=htons(0), sin_addr=inet_addr("0.0.0.0")}, [128 => 16]) = 0
getsockopt(5, SOL_SOCKET, SO_TYPE, [2], [4]) = 0
openat(AT_FDCWD, "/etc/bindresvport.blacklist", O_RDONLY) = 6
fstat(6, {st_mode=S_IFREG|0644, st_size=415, ...}) = 0
read(6, "#\n# This file contains a list of"..., 4096) = 415
read(6, "", 4096) = 0
close(6) = 0
getsockname(5, {sa_family=AF_INET, sin_port=htons(0), sin_addr=inet_addr("0.0.0.0")}, [128 => 16]) = 0
getpid() = 28530
bind(5, {sa_family=AF_INET, sin_port=htons(722), sin_addr=inet_addr("0.0.0.0")}, 16) = 0
rt_sigprocmask(SIG_SETMASK, ~[RTMIN RT_1], [], 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
getsockname(5, {sa_family=AF_INET, sin_port=htons(722), sin_addr=inet_addr("0.0.0.0")}, [128 => 16]) = 0
getsockopt(5, SOL_SOCKET, SO_TYPE, [2], [4]) = 0
gettimeofday({tv_sec=1748867467, tv_usec=890549}, NULL) = 0
getpid() = 28530
setsockopt(5, SOL_IP, IP_RECVERR, [1], 4) = 0
ioctl(5, FIONBIO, [1]) = 0
...
rt_sigprocmask(SIG_SETMASK, ~[RTMIN RT_1], [], 8) = 0
sendto(5, "h0`M\0\0\0\0\0\0\0\2\0\1\206\240\0\0\0\4\0\0\0\3\0\0\0\0\0\0\0\0"..., 88, 0, {sa_family=AF_INET, sin_port=htons(111), sin_addr=inet_addr("10.0.0.2")}, 16) = 88
poll([{fd=5, events=POLLIN}], 1, 15000) = 1 ([{fd=5, revents=POLLIN}])
recvfrom(5, "h0`M\0\0\0\1\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\02010.0"..., 8800, 0, NULL, NULL) = 44
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_SETMASK, ~[RTMIN RT_1], [], 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_SETMASK, ~[RTMIN RT_1], [], 8) = 0
close(5) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
socket(AF_INET, SOCK_DGRAM, IPPROTO_UDP) = 5
getsockname(5, {sa_family=AF_INET, sin_port=htons(0), sin_addr=inet_addr("0.0.0.0")}, [128 => 16]) = 0
getsockopt(5, SOL_SOCKET, SO_TYPE, [2], [4]) = 0
getsockname(5, {sa_family=AF_INET, sin_port=htons(0), sin_addr=inet_addr("0.0.0.0")}, [128 => 16]) = 0
getpid() = 28530
bind(5, {sa_family=AF_INET, sin_port=htons(722), sin_addr=inet_addr("0.0.0.0")}, 16) = 0
rt_sigprocmask(SIG_SETMASK, ~[RTMIN RT_1], [], 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
getsockname(5, {sa_family=AF_INET, sin_port=htons(722), sin_addr=inet_addr("0.0.0.0")}, [128 => 16]) = 0
getsockopt(5, SOL_SOCKET, SO_TYPE, [2], [4]) = 0
gettimeofday({tv_sec=1748867467, tv_usec=892984}, NULL) = 0
getpid() = 28530
setsockopt(5, SOL_IP, IP_RECVERR, [1], 4) = 0
ioctl(5, FIONBIO, [1]) = 0
...
sendto(5, "h0V\302\0\0\0\0\0\0\0\2\0\1\206\240\0\0\0\4\0\0\0\5\0\0\0\0\0\0\0\0"..., 60, 0, {sa_family=AF_INET, sin_port=htons(111), sin_addr=inet_addr("10.0.0.2")}, 16) = 60
poll([{fd=5, events=POLLIN}], 1, 1000) = 0 (Timeout)
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_SETMASK, ~[RTMIN RT_1], [], 8) = 0
close(5) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
fstat(1, {st_mode=S_IFIFO|0600, st_size=0, ...}) = 0
write(1, "1\n", 2) = 2
exit_group(1) = ?
+++ exited with 1 +++
