# 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 +++