ppp-over-tls tests: try to keep CentOS 6 CI working, and improve flaky startup of...

Even with EPEL, CentOS has an old version of socat which doesn't support the
'rawer' option, so let's use the older 'raw,echo=0' combination to keep it
limping along.

More carefully try to verify that socat and pppd start up and connect to each other:

- Wait for socat to create PTY in 1-second increments, and keep going until PTY
  actually exists (up to 15 seconds).
- Wait for ppp to connect to PTY in 1-second increments, and keep going until pppd
  creates a "UUCP-style lockfile" for the PTY.
- Log how long it takes for the above process to complete (socat and pppd combined
  startup) in the test output.

Signed-off-by: Daniel Lenski <dlenski@gmail.com>

diff --git a/tests/common.sh b/tests/common.sh
index f0de258cf613a00b2be2fe7ddd9a0386b26b873d..f125755d497690a559f428f5ac6efdc628486b8a 100644 (file)
--- a/tests/common.sh
+++ b/tests/common.sh
@@ -73,19 +73,37 @@ launch_simple_pppd() {
        CERT="$1"
        KEY="$2"
        shift 2
+       # The 'raw,echo=0' option is obsolete (http://www.dest-unreach.org/socat/doc/CHANGES), but its
+       # replacement 'rawer' isn't available until v1.7.3.0, which is newer than what we have available
+       # on our CentOS 6 CI image.
        LD_PRELOAD=libsocket_wrapper.so socat \
-                PTY,rawer,b9600,link="$SOCKDIR/pppd.$$.pty" \
+                PTY,raw,echo=0,b9600,link="$SOCKDIR/pppd.$$.pty" \
                 OPENSSL-LISTEN:443,verify=0,cert="$CERT",key="$KEY" 2>&1 &
        PID=$!
 
-       sleep 3 # Wait for socat to create the PTY link
+       # Wait for socat to create the PTY link
+       for ii in `seq 15`; do
+          PTY=`readlink "$SOCKDIR/pppd.$$.pty"`
+          test -n "$PTY" && break
+          sleep 1
+       done
 
        # It would be preferable to invoke `pppd notty` directly using socat, but it seemingly cannot handle
        # being wrapped by libsocket_wrapper.so.
        # pppd's option parsing is notably brittle: it must have the actual PTY device node, not a symlink
-       $SUDO $PPPD $(readlink "$SOCKDIR/pppd.$$.pty") noauth local debug nodetach nodefaultroute logfile "$LOGFILE" $* 2>&1 &
+       $SUDO $PPPD "$PTY" noauth lock local debug nodetach nodefaultroute logfile "$LOGFILE" $* 2>&1 &
        PID="$PID $!"
 
+       # Wait for pppd to create the "UUCP-style lockfile" indicating that it has started
+       # (https://refspecs.linuxfoundation.org/FHS_3.0/fhs/ch05s09.html)
+       for ii in `seq 15`; do
+          case "$PTY" in
+              /dev/pts/*) test -e "/var/lock/LCK..pts_`basename $PTY`" && break ;;
+              *) test -e "/var/lock/LCK..`basename $PTY`" && break ;;
+          esac
+          sleep 1
+       done
+
        # XX: Caller needs to use PID, rather than $!
 }
 

diff --git a/tests/ppp-over-tls b/tests/ppp-over-tls
index 2aa4ba5918efd54966a774392817591ea83e1a47..1b041d41e83038b109f489592a14bc449747a680 100755 (executable)
--- a/tests/ppp-over-tls
+++ b/tests/ppp-over-tls
@@ -43,77 +43,107 @@ TIMEOUT_3S_IDLE="idle 3"
 
 echo "Testing PPP ... "
 
-echo -n "Connecting to PPP peer (HDLC/RFC1662, IPv4+IPv6, DNS, extraneous VJ and CCP)... "
+echo -n "Starting PPP peer (HDLC/RFC1662, IPv4+IPv6, DNS, extraneous VJ and CCP)... "
+start=$(date +%s)
 launch_simple_pppd $CERT $KEY $HDLC_YES $IPV4_YES $OFFER_DNS $IPV6_YES 2>&1
+echo "started in $(( $(date +%s) - start )) seconds"
 wait_server "$PID"
+echo -n "Connecting to it with openconnect --protocol=nullppp... "
 start=$(date +%s)
 LD_PRELOAD=libsocket_wrapper.so $OPENCONNECT -q --protocol=nullppp $ADDRESS:443 -u test $FINGERPRINT --cookie "hdlc,term" -Ss '' >/dev/null 2>&1
 took=$(( $(date +%s) - start ))
 if grep -qF "$IPV4_SUCCESS_1" $LOGFILE && grep -qF "$IPV4_SUCCESS_2" $LOGFILE && grep -qF "$IPV6_SUCCESS_1" $LOGFILE && grep -qF "$IPV6_SUCCESS_2" $LOGFILE; then
     echo "ok (took $took seconds)"
 else
-    fail "$PID" "Did not negotiate IPCP and IP6CP successfully."
+    echo "failed (after $took seconds)"
+    echo "Log from pppd"; echo "===== START pppd log ====="
     cat $LOGFILE
+    echo "===== END pppd log ====="
+    fail "$PID" "Did not negotiate IPCP and IP6CP successfully."
 fi
 
 cleanup
 
-echo -n "Connecting to PPP peer (HDLC/RFC1662, IPv4+IPv6, DNS, extraneous VJ and CCP, no header compression)... "
+echo -n "Starting PPP peer (HDLC/RFC1662, IPv4+IPv6, DNS, extraneous VJ and CCP, no header compression)... "
+start=$(date +%s)
 launch_simple_pppd $CERT $KEY $HDLC_YES $IPV4_YES $OFFER_DNS $IPV6_YES $NO_HDR_COMP 2>&1
+echo "started in $(( $(date +%s) - start )) seconds"
 wait_server "$PID"
+echo -n "Connecting to it with openconnect --protocol=nullppp... "
 start=$(date +%s)
 LD_PRELOAD=libsocket_wrapper.so $OPENCONNECT -q --protocol=nullppp $ADDRESS:443 -u test $FINGERPRINT --cookie "hdlc,term" -Ss '' >/dev/null 2>&1
 took=$(( $(date +%s) - start ))
 if grep -qF "$IPV4_SUCCESS_1" $LOGFILE && grep -qF "$IPV4_SUCCESS_2" $LOGFILE && grep -qF "$IPV6_SUCCESS_1" $LOGFILE && grep -qF "$IPV6_SUCCESS_2" $LOGFILE; then
     echo "ok (took $took seconds)"
 else
-    fail "$PID" "Did not negotiate IPCP and IP6CP successfully."
+    echo "failed (after $took seconds)"
+    echo "Log from pppd"; echo "===== START pppd log ====="
     cat $LOGFILE
+    echo "===== END pppd log ====="
+    fail "$PID" "Did not negotiate IPCP and IP6CP successfully."
 fi
 
 cleanup
 
-echo -n "Connecting to PPP peer (sync/no-HDLC, IPv4+IPv6, DNS, extraneous VJ and CCP)... "
+echo -n "Starting PPP peer (sync/no-HDLC, IPv4+IPv6, DNS, extraneous VJ and CCP)... "
+start=$(date +%s)
 launch_simple_pppd $CERT $KEY $HDLC_NO $IPV4_YES $OFFER_DNS $IPV6_YES 2>&1
+echo "started in $(( $(date +%s) - start )) seconds"
 wait_server "$PID"
+echo -n "Connecting to it with openconnect --protocol=nullppp... "
 start=$(date +%s)
 LD_PRELOAD=libsocket_wrapper.so $OPENCONNECT -q --protocol=nullppp $ADDRESS:443 -u test $FINGERPRINT --cookie "term" -Ss '' >/dev/null 2>&1
 took=$(( $(date +%s) - start ))
 if grep -qF "$IPV4_SUCCESS_1" $LOGFILE && grep -qF "$IPV4_SUCCESS_2" $LOGFILE && grep -qF "$IPV6_SUCCESS_1" $LOGFILE && grep -qF "$IPV6_SUCCESS_2" $LOGFILE; then
     echo "ok (took $took seconds)"
 else
-    fail "$PID" "Did not negotiate IPCP and IP6CP successfully."
+    echo "failed (after $took seconds)"
+    echo "Log from pppd"; echo "===== START pppd log ====="
     cat $LOGFILE
+    echo "===== END pppd log ====="
+    fail "$PID" "Did not negotiate IPCP and IP6CP successfully."
 fi
 
 cleanup
 
-echo -n "Connecting to PPP peer (HDLC/RFC1662, IPv4 only)... "
+echo -n "Starting PPP peer (HDLC/RFC1662, IPv4 only)... "
+start=$(date +%s)
 launch_simple_pppd $CERT $KEY $HDLC_YES $NO_JUNK_COMP $IPV4_YES $IPV6_NO 2>&1
+echo "started in $(( $(date +%s) - start )) seconds"
 wait_server "$PID"
+echo -n "Connecting to it with openconnect --protocol=nullppp... "
 start=$(date +%s)
 LD_PRELOAD=libsocket_wrapper.so $OPENCONNECT -q --protocol=nullppp $ADDRESS:443 -u test $FINGERPRINT --cookie "hdlc,term" -Ss '' >/dev/null 2>&1
 took=$(( $(date +%s) - start ))
 if grep -qF "$IPV4_SUCCESS_1" $LOGFILE && grep -qF "$IPV4_SUCCESS_2" $LOGFILE; then
     echo "ok (took $took seconds)"
 else
-    fail "$PID" "Did not negotiate IPCP successfully."
+    echo "failed (after $took seconds)"
+    echo "Log from pppd"; echo "===== START pppd log ====="
     cat $LOGFILE
+    echo "===== END pppd log ====="
+    fail "$PID" "Did not negotiate IPCP successfully."
 fi
 
 cleanup
 
-echo -n "Connecting to PPP peer (HDLC/RFC1662, IPv6 only, 3s idle timeout)... "
+echo -n "Starting PPP peer (HDLC/RFC1662, IPv6 only, 3s idle timeout)... "
+start=$(date +%s)
 launch_simple_pppd $CERT $KEY $HDLC_YES $NO_JUNK_COMP $IPV4_NO $IPV6_YES $TIMEOUT_3S_IDLE 2>&1
+echo "started in $(( $(date +%s) - start )) seconds"
 wait_server "$PID"
+echo -n "Connecting to it with openconnect --protocol=nullppp... "
 start=$(date +%s)
 LD_PRELOAD=libsocket_wrapper.so $OPENCONNECT -q --protocol=nullppp $ADDRESS:443 -u test $FINGERPRINT --cookie "hdlc" -Ss '' >/dev/null 2>&1
 took=$(( $(date +%s) - start ))
 if grep -qF "$IPV6_SUCCESS_1" $LOGFILE && grep -qF "$IPV6_SUCCESS_2" $LOGFILE; then
     echo "ok (took $took seconds)"
 else
-    fail "$PID" "Did not negotiate IP6CP successfully."
+    echo "failed (after $took seconds)"
+    echo "Log from pppd"; echo "===== START pppd log ====="
     cat $LOGFILE
+    echo "===== END pppd log ====="
+    fail "$PID" "Did not negotiate IP6CP successfully."
 fi
 
 cleanup