From 767389c8dd55f8d97aa9ec2ce4165c26dea31fdd Mon Sep 17 00:00:00 2001 From: Paolo Abeni Date: Fri, 12 Feb 2021 15:20:27 -0800 Subject: [PATCH 1/4] selftests: mptcp: dump more info on errors Even if that may sound completely unlikely, the mptcp implementation is not perfect, yet. When the self-tests report an error we usually need more information of what the scripts currently report. iproute allow provides some additional goodies since a few releases, let's dump them. Signed-off-by: Paolo Abeni Signed-off-by: Mat Martineau Signed-off-by: David S. Miller --- .../testing/selftests/net/mptcp/mptcp_connect.sh | 15 ++++++++++++--- 1 file changed, 12 insertions(+), 3 deletions(-) diff --git a/tools/testing/selftests/net/mptcp/mptcp_connect.sh b/tools/testing/selftests/net/mptcp/mptcp_connect.sh index 2cfd87d94db89..0c6b9d3c03c0a 100755 --- a/tools/testing/selftests/net/mptcp/mptcp_connect.sh +++ b/tools/testing/selftests/net/mptcp/mptcp_connect.sh @@ -128,6 +128,7 @@ cleanup() local netns for netns in "$ns1" "$ns2" "$ns3" "$ns4";do ip netns del $netns + rm -f /tmp/$netns.{nstat,out} done } @@ -438,16 +439,24 @@ do_transfer() kill ${cappid_connector} fi + NSTAT_HISTORY=/tmp/${listener_ns}.nstat ip netns exec ${listener_ns} \ + nstat | grep Tcp > /tmp/${listener_ns}.out + if [ ${listener_ns} != ${connector_ns} ]; then + NSTAT_HISTORY=/tmp/${connector_ns}.nstat ip netns exec ${connector_ns} \ + nstat | grep Tcp > /tmp/${connector_ns}.out + fi + local duration duration=$((stop-start)) duration=$(printf "(duration %05sms)" $duration) if [ ${rets} -ne 0 ] || [ ${retc} -ne 0 ]; then echo "$duration [ FAIL ] client exit code $retc, server $rets" 1>&2 echo -e "\nnetns ${listener_ns} socket stat for ${port}:" 1>&2 - ip netns exec ${listener_ns} ss -nita 1>&2 -o "sport = :$port" + ip netns exec ${listener_ns} ss -Menita 1>&2 -o "sport = :$port" + cat /tmp/${listener_ns}.out echo -e "\nnetns ${connector_ns} socket stat for ${port}:" 1>&2 - ip netns exec ${connector_ns} ss -nita 1>&2 -o "dport = :$port" - + ip netns exec ${connector_ns} ss -Menita 1>&2 -o "dport = :$port" + [ ${listener_ns} != ${connector_ns} ] && cat /tmp/${connector_ns}.out cat "$capout" return 1 fi From f384221a381751508f390b36d0e51bd5a7beb627 Mon Sep 17 00:00:00 2001 From: Matthieu Baerts Date: Fri, 12 Feb 2021 15:20:28 -0800 Subject: [PATCH 2/4] selftests: mptcp: fix ACKRX debug message Info from received MPCapable SYN were printed instead of the ones from received MPCapable 3rd ACK. Fixes: fed61c4b584c ("selftests: mptcp: make 2nd net namespace use tcp syn cookies unconditionally") Signed-off-by: Matthieu Baerts Signed-off-by: Mat Martineau Signed-off-by: David S. Miller --- tools/testing/selftests/net/mptcp/mptcp_connect.sh | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tools/testing/selftests/net/mptcp/mptcp_connect.sh b/tools/testing/selftests/net/mptcp/mptcp_connect.sh index 0c6b9d3c03c0a..9ab35ae416289 100755 --- a/tools/testing/selftests/net/mptcp/mptcp_connect.sh +++ b/tools/testing/selftests/net/mptcp/mptcp_connect.sh @@ -502,7 +502,7 @@ do_transfer() echo "${listener_ns} SYNRX: ${cl_proto} -> ${srv_proto}: expect ${expect_synrx}, got ${stat_synrx_now_l}" fi if [ $expect_ackrx -ne $stat_ackrx_now_l ] ;then - echo "${listener_ns} ACKRX: ${cl_proto} -> ${srv_proto}: expect ${expect_synrx}, got ${stat_synrx_now_l}" + echo "${listener_ns} ACKRX: ${cl_proto} -> ${srv_proto}: expect ${expect_ackrx}, got ${stat_ackrx_now_l} " fi if [ $retc -eq 0 ] && [ $rets -eq 0 ];then From 45759a871593ea726f44a107c05a345609ad0754 Mon Sep 17 00:00:00 2001 From: Matthieu Baerts Date: Fri, 12 Feb 2021 15:20:29 -0800 Subject: [PATCH 3/4] selftests: mptcp: display warnings on one line Before we had this in case of SYN retransmissions: (...) # ns4 MPTCP -> ns2 (10.0.1.2:10034 ) MPTCP (duration 1201ms) [ OK ] # ns4 MPTCP -> ns2 (dead:beef:1::2:10035) MPTCP (duration 1242ms) [ OK ] # ns4 MPTCP -> ns2 (10.0.2.1:10036 ) MPTCP ns2-60143c00-cDZWo4 SYNRX: MPTCP -> MPTCP: expect 11, got # 13 # (duration 6221ms) [ OK ] # ns4 MPTCP -> ns2 (dead:beef:2::1:10037) MPTCP (duration 1427ms) [ OK ] # ns4 MPTCP -> ns3 (10.0.2.2:10038 ) MPTCP (duration 881ms) [ OK ] (...) Now we have: (...) # ns4 MPTCP -> ns2 (10.0.1.2:10034 ) MPTCP (duration 1201ms) [ OK ] # ns4 MPTCP -> ns2 (dead:beef:1::2:10035) MPTCP (duration 1242ms) [ OK ] # ns4 MPTCP -> ns2 (10.0.2.1:10036 ) MPTCP (duration 6221ms) [ OK ] WARN: SYNRX: expect 11, got 13 # ns4 MPTCP -> ns2 (dead:beef:2::1:10037) MPTCP (duration 1427ms) [ OK ] # ns4 MPTCP -> ns3 (10.0.2.2:10038 ) MPTCP (duration 881ms) [ OK ] (...) So we put everything on one line, keep the durations and "OK" aligned and removed duplicated info to short the warning. Signed-off-by: Matthieu Baerts Signed-off-by: Mat Martineau Signed-off-by: David S. Miller --- .../selftests/net/mptcp/mptcp_connect.sh | 63 ++++++++++++------- 1 file changed, 40 insertions(+), 23 deletions(-) diff --git a/tools/testing/selftests/net/mptcp/mptcp_connect.sh b/tools/testing/selftests/net/mptcp/mptcp_connect.sh index 9ab35ae416289..362e891f89cfe 100755 --- a/tools/testing/selftests/net/mptcp/mptcp_connect.sh +++ b/tools/testing/selftests/net/mptcp/mptcp_connect.sh @@ -334,6 +334,21 @@ do_ping() return 0 } +# $1: ns, $2: MIB counter +get_mib_counter() +{ + local listener_ns="${1}" + local mib="${2}" + + # strip the header + ip netns exec "${listener_ns}" \ + nstat -z -a "${mib}" | \ + tail -n+2 | \ + while read a count c rest; do + echo $count + done +} + # $1: ns, $2: port wait_local_port_listen() { @@ -410,10 +425,10 @@ do_transfer() sleep 1 fi - local stat_synrx_last_l=$(ip netns exec ${listener_ns} nstat -z -a MPTcpExtMPCapableSYNRX | while read a count c rest ;do echo $count;done) - local stat_ackrx_last_l=$(ip netns exec ${listener_ns} nstat -z -a MPTcpExtMPCapableACKRX | while read a count c rest ;do echo $count;done) - local stat_cookietx_last=$(ip netns exec ${listener_ns} nstat -z -a TcpExtSyncookiesSent | while read a count c rest ;do echo $count;done) - local stat_cookierx_last=$(ip netns exec ${listener_ns} nstat -z -a TcpExtSyncookiesRecv | while read a count c rest ;do echo $count;done) + local stat_synrx_last_l=$(get_mib_counter "${listener_ns}" "MPTcpExtMPCapableSYNRX") + local stat_ackrx_last_l=$(get_mib_counter "${listener_ns}" "MPTcpExtMPCapableACKRX") + local stat_cookietx_last=$(get_mib_counter "${listener_ns}" "TcpExtSyncookiesSent") + local stat_cookierx_last=$(get_mib_counter "${listener_ns}" "TcpExtSyncookiesRecv") ip netns exec ${listener_ns} ./mptcp_connect -t $timeout -l -p $port -s ${srv_proto} $extra_args $local_addr < "$sin" > "$sout" & local spid=$! @@ -448,15 +463,17 @@ do_transfer() local duration duration=$((stop-start)) - duration=$(printf "(duration %05sms)" $duration) + printf "(duration %05sms) " "${duration}" if [ ${rets} -ne 0 ] || [ ${retc} -ne 0 ]; then - echo "$duration [ FAIL ] client exit code $retc, server $rets" 1>&2 + echo "[ FAIL ] client exit code $retc, server $rets" 1>&2 echo -e "\nnetns ${listener_ns} socket stat for ${port}:" 1>&2 ip netns exec ${listener_ns} ss -Menita 1>&2 -o "sport = :$port" cat /tmp/${listener_ns}.out echo -e "\nnetns ${connector_ns} socket stat for ${port}:" 1>&2 ip netns exec ${connector_ns} ss -Menita 1>&2 -o "dport = :$port" [ ${listener_ns} != ${connector_ns} ] && cat /tmp/${connector_ns}.out + + echo cat "$capout" return 1 fi @@ -466,11 +483,14 @@ do_transfer() check_transfer $cin $sout "file received by server" rets=$? - local stat_synrx_now_l=$(ip netns exec ${listener_ns} nstat -z -a MPTcpExtMPCapableSYNRX | while read a count c rest ;do echo $count;done) - local stat_ackrx_now_l=$(ip netns exec ${listener_ns} nstat -z -a MPTcpExtMPCapableACKRX | while read a count c rest ;do echo $count;done) + if [ $retc -eq 0 ] && [ $rets -eq 0 ]; then + printf "[ OK ]" + fi - local stat_cookietx_now=$(ip netns exec ${listener_ns} nstat -z -a TcpExtSyncookiesSent | while read a count c rest ;do echo $count;done) - local stat_cookierx_now=$(ip netns exec ${listener_ns} nstat -z -a TcpExtSyncookiesRecv | while read a count c rest ;do echo $count;done) + local stat_synrx_now_l=$(get_mib_counter "${listener_ns}" "MPTcpExtMPCapableSYNRX") + local stat_ackrx_now_l=$(get_mib_counter "${listener_ns}" "MPTcpExtMPCapableACKRX") + local stat_cookietx_now=$(get_mib_counter "${listener_ns}" "TcpExtSyncookiesSent") + local stat_cookierx_now=$(get_mib_counter "${listener_ns}" "TcpExtSyncookiesRecv") expect_synrx=$((stat_synrx_last_l)) expect_ackrx=$((stat_ackrx_last_l)) @@ -484,35 +504,32 @@ do_transfer() fi if [ $cookies -eq 2 ];then if [ $stat_cookietx_last -ge $stat_cookietx_now ] ;then - echo "${listener_ns} CookieSent: ${cl_proto} -> ${srv_proto}: did not advance" + printf " WARN: CookieSent: did not advance" fi if [ $stat_cookierx_last -ge $stat_cookierx_now ] ;then - echo "${listener_ns} CookieRecv: ${cl_proto} -> ${srv_proto}: did not advance" + printf " WARN: CookieRecv: did not advance" fi else if [ $stat_cookietx_last -ne $stat_cookietx_now ] ;then - echo "${listener_ns} CookieSent: ${cl_proto} -> ${srv_proto}: changed" + printf " WARN: CookieSent: changed" fi if [ $stat_cookierx_last -ne $stat_cookierx_now ] ;then - echo "${listener_ns} CookieRecv: ${cl_proto} -> ${srv_proto}: changed" + printf " WARN: CookieRecv: changed" fi fi if [ $expect_synrx -ne $stat_synrx_now_l ] ;then - echo "${listener_ns} SYNRX: ${cl_proto} -> ${srv_proto}: expect ${expect_synrx}, got ${stat_synrx_now_l}" + printf " WARN: SYNRX: expect %d, got %d" \ + "${expect_synrx}" "${stat_synrx_now_l}" fi if [ $expect_ackrx -ne $stat_ackrx_now_l ] ;then - echo "${listener_ns} ACKRX: ${cl_proto} -> ${srv_proto}: expect ${expect_ackrx}, got ${stat_ackrx_now_l} " - fi - - if [ $retc -eq 0 ] && [ $rets -eq 0 ];then - echo "$duration [ OK ]" - cat "$capout" - return 0 + printf " WARN: ACKRX: expect %d, got %d" \ + "${expect_ackrx}" "${stat_ackrx_now_l}" fi + echo cat "$capout" - return 1 + [ $retc -eq 0 ] && [ $rets -eq 0 ] } make_file() From 5f88117f256507fc2d146627a3e39bb0cc282a11 Mon Sep 17 00:00:00 2001 From: Matthieu Baerts Date: Fri, 12 Feb 2021 15:20:30 -0800 Subject: [PATCH 4/4] selftests: mptcp: fail if not enough SYN/3rd ACK If we receive less MPCapable SYN or 3rd ACK than expected, we now mark the test as failed. On the other hand, if we receive more, we keep the warning but we add a hint that it is probably due to retransmissions and that's why we don't mark the test as failed. Closes: https://github.com/multipath-tcp/mptcp_net-next/issues/148 Signed-off-by: Matthieu Baerts Signed-off-by: Mat Martineau Signed-off-by: David S. Miller --- .../selftests/net/mptcp/mptcp_connect.sh | 28 +++++++++++++------ 1 file changed, 20 insertions(+), 8 deletions(-) diff --git a/tools/testing/selftests/net/mptcp/mptcp_connect.sh b/tools/testing/selftests/net/mptcp/mptcp_connect.sh index 362e891f89cfe..10a030b53b23e 100755 --- a/tools/testing/selftests/net/mptcp/mptcp_connect.sh +++ b/tools/testing/selftests/net/mptcp/mptcp_connect.sh @@ -483,10 +483,6 @@ do_transfer() check_transfer $cin $sout "file received by server" rets=$? - if [ $retc -eq 0 ] && [ $rets -eq 0 ]; then - printf "[ OK ]" - fi - local stat_synrx_now_l=$(get_mib_counter "${listener_ns}" "MPTcpExtMPCapableSYNRX") local stat_ackrx_now_l=$(get_mib_counter "${listener_ns}" "MPTcpExtMPCapableACKRX") local stat_cookietx_now=$(get_mib_counter "${listener_ns}" "TcpExtSyncookiesSent") @@ -502,6 +498,22 @@ do_transfer() expect_synrx=$((stat_synrx_last_l+1)) expect_ackrx=$((stat_ackrx_last_l+1)) fi + + if [ ${stat_synrx_now_l} -lt ${expect_synrx} ]; then + printf "[ FAIL ] lower MPC SYN rx (%d) than expected (%d)\n" \ + "${stat_synrx_now_l}" "${expect_synrx}" 1>&2 + retc=1 + fi + if [ ${stat_ackrx_now_l} -lt ${expect_ackrx} ]; then + printf "[ FAIL ] lower MPC ACK rx (%d) than expected (%d)\n" \ + "${stat_ackrx_now_l}" "${expect_ackrx}" 1>&2 + rets=1 + fi + + if [ $retc -eq 0 ] && [ $rets -eq 0 ]; then + printf "[ OK ]" + fi + if [ $cookies -eq 2 ];then if [ $stat_cookietx_last -ge $stat_cookietx_now ] ;then printf " WARN: CookieSent: did not advance" @@ -518,12 +530,12 @@ do_transfer() fi fi - if [ $expect_synrx -ne $stat_synrx_now_l ] ;then - printf " WARN: SYNRX: expect %d, got %d" \ + if [ ${stat_synrx_now_l} -gt ${expect_synrx} ]; then + printf " WARN: SYNRX: expect %d, got %d (probably retransmissions)" \ "${expect_synrx}" "${stat_synrx_now_l}" fi - if [ $expect_ackrx -ne $stat_ackrx_now_l ] ;then - printf " WARN: ACKRX: expect %d, got %d" \ + if [ ${stat_ackrx_now_l} -gt ${expect_ackrx} ]; then + printf " WARN: ACKRX: expect %d, got %d (probably retransmissions)" \ "${expect_ackrx}" "${stat_ackrx_now_l}" fi