From 57b497fe47408c0ca933a262f94aa2bff87d8dc9 Mon Sep 17 00:00:00 2001 From: gkc Date: Mon, 25 Mar 2024 11:42:05 +0000 Subject: [PATCH 01/34] chore: added some cleanup into e2e_all.yaml --- .github/workflows/e2e_all.yaml | 2 ++ 1 file changed, 2 insertions(+) diff --git a/.github/workflows/e2e_all.yaml b/.github/workflows/e2e_all.yaml index ef9237525..ce9a018aa 100644 --- a/.github/workflows/e2e_all.yaml +++ b/.github/workflows/e2e_all.yaml @@ -32,6 +32,8 @@ jobs: envs: SHA script: | cd noports + rm -rf tests/e2e_all/runtime + mkdir -p tests/e2e_all/runtime echo "Running git fetch" git fetch echo "Running git checkout -f $SHA" From aad177efe611c8d71781114bf05be11e9db5a4e5 Mon Sep 17 00:00:00 2001 From: gkc Date: Mon, 25 Mar 2024 11:43:55 +0000 Subject: [PATCH 02/34] test: Added some scaffolding to capture daemon log file fragments for reporting in the event of a test failure --- tests/e2e_all/scripts/common/run_tests.sh | 27 ++++++++++++++-------- tests/e2e_all/scripts/tests/minus_s_flag | 26 +++++++++++++++++++++ tests/e2e_all/scripts/tests/minus_u_flag | 27 ++++++++++++++++++++++ tests/e2e_all/scripts/tests/npt_to_port_22 | 15 +++++++++--- 4 files changed, 83 insertions(+), 12 deletions(-) diff --git a/tests/e2e_all/scripts/common/run_tests.sh b/tests/e2e_all/scripts/common/run_tests.sh index cc61fcbd7..a84a75445 100755 --- a/tests/e2e_all/scripts/common/run_tests.sh +++ b/tests/e2e_all/scripts/common/run_tests.sh @@ -25,6 +25,7 @@ echo "### " >> "$reportFile" outputDir=$(getOutputDir) mkdir -p "${outputDir}/clients" +mkdir -p "${outputDir}/tests" numDaemons=$(wc -w <<< "$daemonVersions") numClients=$(wc -w <<< "$clientVersions") @@ -46,6 +47,8 @@ do baseFileName="${outputDir}/clients/${testToRun}.daemon.${daemonVersion}.client.${clientVersion}" stdoutFileName="${baseFileName}.out" stderrFileName="${baseFileName}.err" + DAEMON_LOG_FRAGMENT_NAME="${baseFileName}.daemonLogFragment.log" + export DAEMON_LOG_FRAGMENT_NAME exitStatus=1 maxAttempts=3 @@ -56,6 +59,8 @@ do while (( exitStatus != 0 && exitStatus != 50 && attempts < maxAttempts )); do + rm -f "$DAEMON_LOG_FRAGMENT_NAME" + touch "$DAEMON_LOG_FRAGMENT_NAME" if (( attempts > 0 )); then logWarning " Exit status was $exitStatus; will retry in 3 seconds"; sleep 3; fi @@ -66,6 +71,19 @@ do > "$stdoutFileName" 2> "$stderrFileName" exitStatus=$? + if (( exitStatus != 0 )); then + # shellcheck disable=SC2129 + echo " test execution's stdout: " | tee -a "$reportFile" + sed 's/^/ /' "$stdoutFileName" | tee -a "$reportFile" + + echo " test execution's stderr: " | tee -a "$reportFile" + sed 's/^/ /' "$stderrFileName" | tee -a "$reportFile" + + echo " daemon log fragment: " | tee -a "$reportFile" + sed 's/^/ /' "$DAEMON_LOG_FRAGMENT_NAME" | tee -a "$reportFile" + + echo; echo >> "$reportFile" + fi attempts=$((attempts+1)) done @@ -120,15 +138,6 @@ do case $testResult in FAILED) logInfoAndReport " ${logColour}Test ${testResult}${NC} : exit code $exitStatus $additionalInfo" - - # shellcheck disable=SC2129 - echo " test execution's stdout: " >> "$reportFile" - sed 's/^/ /' "$stdoutFileName" >> "$reportFile" - - echo " test execution's stderr: " >> "$reportFile" - sed 's/^/ /' "$stderrFileName" >> "$reportFile" - - echo >> "$reportFile" ;; "N/A") logInfoAndReport " ${logColour}Test ${testResult}${NC}" diff --git a/tests/e2e_all/scripts/tests/minus_s_flag b/tests/e2e_all/scripts/tests/minus_s_flag index 39955fb6d..c9f012544 100755 --- a/tests/e2e_all/scripts/tests/minus_s_flag +++ b/tests/e2e_all/scripts/tests/minus_s_flag @@ -45,6 +45,15 @@ fi # 2a. Run sshnp against a daemon without the -s flag, with that new key # 2b. Verify it fails deviceName=$(getDeviceNameNoFlags "$commitId" "$daemonVersion" ) + +# We will capture daemon log from now until end of test +outputDir=$(getOutputDir) +daemonLogFile="${outputDir}/daemons/${deviceName}.log" +echo "First daemon (without flags) $deviceName" >> "$DAEMON_LOG_FRAGMENT_NAME" +echo "" >> "$DAEMON_LOG_FRAGMENT_NAME" +tail -f "$daemonLogFile" >> "$DAEMON_LOG_FRAGMENT_NAME" & +tailPid=$! # We'll kill this later + l1="$clientBinaryPath/sshnp -f $clientAtSign -d $deviceName -i $identityFilename" l2=" -t $daemonAtSign -h $srvAtSign -u $remoteUsername" l4=" --root-domain $atDirectoryHost" @@ -72,6 +81,7 @@ else if (( exitStatus == 0 )); then # It should have failed logError "$scriptName: sshnp with new key did not fail as expected" + kill $tailPid exit 1 else logInfo "$scriptName: sshnp with new key failed as expected" | tee -a "$(getReportFile)" @@ -82,6 +92,16 @@ fi # 3a. Run against a daemon with the -s flag # 3b. Verify it succeeds deviceName=$(getDeviceNameWithFlags "$commitId" "$daemonVersion" ) + +# We will capture daemon log from now until end of test +outputDir=$(getOutputDir) +daemonLogFile="${outputDir}/daemons/${deviceName}.log" +echo "" >> "$DAEMON_LOG_FRAGMENT_NAME" +echo "Second daemon (with flags) : $deviceName" >> "$DAEMON_LOG_FRAGMENT_NAME" +echo "" >> "$DAEMON_LOG_FRAGMENT_NAME" +tail -f "$daemonLogFile" >> "$DAEMON_LOG_FRAGMENT_NAME" & +tailPid=$! # We'll kill this later + l1="$clientBinaryPath/sshnp -f $clientAtSign -d $deviceName -i $identityFilename" l2=" -t $daemonAtSign -h $srvAtSign -u $remoteUsername" l4=" --root-domain $atDirectoryHost" @@ -92,6 +112,8 @@ echo "$(iso8601Date) | Executing $sshnpCommand" sshCommand=$($sshnpCommand) sshnpExitStatus=$? if (( sshnpExitStatus != 0 )); then + # Kill the daemon log tail, and exit with the exit status of the sshnp command + kill $tailPid exit $sshnpExitStatus fi @@ -99,4 +121,8 @@ echo "$(iso8601Date) | Executing $sshCommand" # shellcheck disable=SC2091 $(getTestSshCommand "$sshCommand") +sshExitStatus=$? +# Kill the daemon log tail, and exit with the exit status of the ssh command +kill "$tailPid" +exit $sshExitStatus diff --git a/tests/e2e_all/scripts/tests/minus_u_flag b/tests/e2e_all/scripts/tests/minus_u_flag index 60d64c33d..c44bfb5af 100755 --- a/tests/e2e_all/scripts/tests/minus_u_flag +++ b/tests/e2e_all/scripts/tests/minus_u_flag @@ -45,6 +45,16 @@ fi # does not have the -u flag enabled. # 1b. Verify it fails deviceName=$(getDeviceNameNoFlags "$commitId" "$daemonVersion" ) + +# We will capture daemon log from now until end of test +outputDir=$(getOutputDir) +daemonLogFile="${outputDir}/daemons/${deviceName}.log" +echo "" >> "$DAEMON_LOG_FRAGMENT_NAME" +echo "First daemon (without flags) $deviceName" >> "$DAEMON_LOG_FRAGMENT_NAME" +echo "" >> "$DAEMON_LOG_FRAGMENT_NAME" +tail -f "$daemonLogFile" >> "$DAEMON_LOG_FRAGMENT_NAME" & +tailPid=$! # We'll kill this later + l1="$clientBinaryPath/sshnp -f $clientAtSign -d $deviceName -i $identityFilename" l2=" -t $daemonAtSign -h $srvAtSign " l4=" --root-domain $atDirectoryHost" @@ -58,6 +68,7 @@ sshnpExitStatus=$? if (( sshnpExitStatus == 0 )); then # It should have failed logError "$scriptName: sshnp to ${deviceName} without '-u ' did not fail as expected" + kill $tailPid exit 1 fi @@ -65,6 +76,14 @@ fi # DOES have the -u flag enabled. # 2b. Verify it succeeds, and that the subsequent ssh succeeds deviceName=$(getDeviceNameWithFlags "$commitId" "$daemonVersion" ) +kill $tailPid +daemonLogFile="${outputDir}/daemons/${deviceName}.log" +echo "" >> "$DAEMON_LOG_FRAGMENT_NAME" +echo "Second daemon (with flags) : $deviceName" >> "$DAEMON_LOG_FRAGMENT_NAME" +echo "" >> "$DAEMON_LOG_FRAGMENT_NAME" +tail -f "$daemonLogFile" >> "$DAEMON_LOG_FRAGMENT_NAME" & +tailPid=$! # We'll kill this later + l1="$clientBinaryPath/sshnp -f $clientAtSign -d $deviceName -i $identityFilename" l2=" -t $daemonAtSign -h $srvAtSign" l4=" --root-domain $atDirectoryHost" @@ -75,6 +94,8 @@ echo "$(iso8601Date) | Executing $sshnpCommand" sshCommand=$($sshnpCommand) sshnpExitStatus=$? if (( sshnpExitStatus != 0 )); then + logError "$scriptName: sshnp to ${deviceName} without '-u ' should have succeeded but did not" + kill $tailPid exit $sshnpExitStatus fi @@ -82,3 +103,9 @@ echo "$(iso8601Date) | Executing $sshCommand" # shellcheck disable=SC2091 $(getTestSshCommand "$sshCommand") +sshExitStatus=$? +if (( sshExitStatus != 0 )); then + logError "$scriptName: ssh to ${deviceName} without '-u ' should have succeeded but did not" +fi +kill $tailPid +exit $sshExitStatus diff --git a/tests/e2e_all/scripts/tests/npt_to_port_22 b/tests/e2e_all/scripts/tests/npt_to_port_22 index ac72614fb..3edf6d64d 100755 --- a/tests/e2e_all/scripts/tests/npt_to_port_22 +++ b/tests/e2e_all/scripts/tests/npt_to_port_22 @@ -33,6 +33,12 @@ fi deviceName=$(getDeviceNameWithFlags "$commitId" "$daemonVersion" ) +# We will capture daemon log from now until end of test +outputDir=$(getOutputDir) +daemonLogFile="${outputDir}/daemons/${deviceName}.log" +tail -f -n 0 "$daemonLogFile" >> "$DAEMON_LOG_FRAGMENT_NAME" & +tailPid=$! # We'll kill this later + clientBinaryPath=$(getPathToBinariesForTypeAndVersion "$clientVersion") baseNptCommand=$(getBaseNptCommand "$clientBinaryPath") @@ -47,6 +53,8 @@ nptPort=$($nptCommand) # 2. Check the exit status nptExitStatus=$? if (( nptExitStatus != 0 )); then + # Kill the daemon log tail, and exit with the exit status of the npt command + kill "$tailPid" exit $nptExitStatus fi @@ -58,6 +66,7 @@ echo "$(iso8601Date) | Executing $sshCommand" | tee -a "$(getReportFile)" # shellcheck disable=SC2091 $(getTestSshCommand "$sshCommand") - -# 4. Exit with the exit status of the ssh command -exit $? +sshExitStatus=$? +# 4. Kill the daemon log tail, and exit with the exit status of the ssh command +kill "$tailPid" +exit $sshExitStatus From 63c5905998246b7a0fa0b76717a754212c39ac90 Mon Sep 17 00:00:00 2001 From: gkc Date: Mon, 25 Mar 2024 11:44:25 +0000 Subject: [PATCH 03/34] fix: tests: added cleanup of test-generated ssh keys --- tests/e2e_all/scripts/main.sh | 3 +++ 1 file changed, 3 insertions(+) diff --git a/tests/e2e_all/scripts/main.sh b/tests/e2e_all/scripts/main.sh index 6c649a1b7..e3152b0eb 100755 --- a/tests/e2e_all/scripts/main.sh +++ b/tests/e2e_all/scripts/main.sh @@ -221,6 +221,9 @@ echo logInfo "Restoring authorized_keys from backup" restoreAuthorizedKeys +logInfo "Removing $identityFilename and $identityFilename.pub" +rm -f "${identityFilename}" "${identityFilename}.pub" + reportFile=$(getReportFile) echo From 29d8e7d79843571b217cca3f1cb9b81c22b0d646 Mon Sep 17 00:00:00 2001 From: gkc Date: Mon, 25 Mar 2024 12:18:59 +0000 Subject: [PATCH 04/34] test: npt_to_port_22: Log info about the spawned srv process --- tests/e2e_all/scripts/tests/npt_to_port_22 | 8 ++++++++ 1 file changed, 8 insertions(+) diff --git a/tests/e2e_all/scripts/tests/npt_to_port_22 b/tests/e2e_all/scripts/tests/npt_to_port_22 index 3edf6d64d..a38c11195 100755 --- a/tests/e2e_all/scripts/tests/npt_to_port_22 +++ b/tests/e2e_all/scripts/tests/npt_to_port_22 @@ -58,6 +58,10 @@ if (( nptExitStatus != 0 )); then exit $nptExitStatus fi + +echo "$(iso8601Date) | Running ps for the spawned srv process BEFORE running ssh" | tee -a "$(getReportFile)" +ps -ef | grep "srv " | grep "$nptPort" | tee -a "$(getReportFile)" + # 3. Execute an ssh sshCommand="ssh -p $nptPort -o StrictHostKeyChecking=accept-new -o IdentitiesOnly=yes" sshCommand="${sshCommand} ${remoteUsername}@localhost -i $identityFilename" @@ -67,6 +71,10 @@ echo "$(iso8601Date) | Executing $sshCommand" | tee -a "$(getReportFile)" # shellcheck disable=SC2091 $(getTestSshCommand "$sshCommand") sshExitStatus=$? + +echo "$(iso8601Date) | Running ps for the spawned srv process AFTER running ssh" | tee -a "$(getReportFile)" +ps -ef | grep "srv " | grep "$nptPort" | tee -a "$(getReportFile)" + # 4. Kill the daemon log tail, and exit with the exit status of the ssh command kill "$tailPid" exit $sshExitStatus From 6b0127fd7f9ed153f30846b8f82b35a9293ed7ae Mon Sep 17 00:00:00 2001 From: gkc Date: Mon, 25 Mar 2024 12:30:04 +0000 Subject: [PATCH 05/34] test: fix: add missing kill for the daemon log fragment tail --- tests/e2e_all/scripts/tests/minus_s_flag | 1 + 1 file changed, 1 insertion(+) diff --git a/tests/e2e_all/scripts/tests/minus_s_flag b/tests/e2e_all/scripts/tests/minus_s_flag index c9f012544..b26bd6e58 100755 --- a/tests/e2e_all/scripts/tests/minus_s_flag +++ b/tests/e2e_all/scripts/tests/minus_s_flag @@ -94,6 +94,7 @@ fi deviceName=$(getDeviceNameWithFlags "$commitId" "$daemonVersion" ) # We will capture daemon log from now until end of test +kill $tailPid outputDir=$(getOutputDir) daemonLogFile="${outputDir}/daemons/${deviceName}.log" echo "" >> "$DAEMON_LOG_FRAGMENT_NAME" From 12b5d0bf1f11c37fc0c9252a1e96b61e807cee26 Mon Sep 17 00:00:00 2001 From: gkc Date: Mon, 25 Mar 2024 12:47:57 +0000 Subject: [PATCH 06/34] test: npt_to_port_22: we know that the srv process is not running even though npt printed the port and (apparently) started the srv process; add the --verbose flag to see if anything pops from the npt process's log --- tests/e2e_all/scripts/tests/npt_to_port_22 | 11 ++++++----- 1 file changed, 6 insertions(+), 5 deletions(-) diff --git a/tests/e2e_all/scripts/tests/npt_to_port_22 b/tests/e2e_all/scripts/tests/npt_to_port_22 index a38c11195..1a09905aa 100755 --- a/tests/e2e_all/scripts/tests/npt_to_port_22 +++ b/tests/e2e_all/scripts/tests/npt_to_port_22 @@ -44,7 +44,7 @@ clientBinaryPath=$(getPathToBinariesForTypeAndVersion "$clientVersion") baseNptCommand=$(getBaseNptCommand "$clientBinaryPath") # Let's put together the npt command we will execute -nptCommand="$baseNptCommand $additionalFlags" +nptCommand="$baseNptCommand $additionalFlags --verbose" # 1. Execute the npt command - its output is the port that npt is using echo "$(iso8601Date) | Executing $nptCommand" | tee -a "$(getReportFile)" @@ -59,8 +59,9 @@ if (( nptExitStatus != 0 )); then fi -echo "$(iso8601Date) | Running ps for the spawned srv process BEFORE running ssh" | tee -a "$(getReportFile)" -ps -ef | grep "srv " | grep "$nptPort" | tee -a "$(getReportFile)" +echo "$(iso8601Date) | npt OK, local port is $nptPort" >> "$(getReportFile)" +echo "$(iso8601Date) | Running ps for the spawned srv process with port $nptPort BEFORE running ssh" >> "$(getReportFile)" +ps -ef | grep "srv " | grep "$nptPort" >> "$(getReportFile)" # 3. Execute an ssh sshCommand="ssh -p $nptPort -o StrictHostKeyChecking=accept-new -o IdentitiesOnly=yes" @@ -72,8 +73,8 @@ echo "$(iso8601Date) | Executing $sshCommand" | tee -a "$(getReportFile)" $(getTestSshCommand "$sshCommand") sshExitStatus=$? -echo "$(iso8601Date) | Running ps for the spawned srv process AFTER running ssh" | tee -a "$(getReportFile)" -ps -ef | grep "srv " | grep "$nptPort" | tee -a "$(getReportFile)" +echo "$(iso8601Date) | Running ps for the spawned srv process with port $nptPort AFTER running ssh" >> "$(getReportFile)" +ps -ef | grep "srv " | grep "$nptPort" >> "$(getReportFile)" # 4. Kill the daemon log tail, and exit with the exit status of the ssh command kill "$tailPid" From 2df47db7bb065588e5ff3f2d5fa75ebebb7c185a Mon Sep 17 00:00:00 2001 From: gkc Date: Mon, 25 Mar 2024 14:05:51 +0000 Subject: [PATCH 07/34] test: tweak logging for forked srv process --- .../noports_core/lib/src/srv/srv_impl.dart | 12 ++++---- packages/dart/sshnoports/bin/srv.dart | 28 +++++++++++++++++-- packages/dart/sshnoports/pubspec.lock | 2 +- packages/dart/sshnoports/pubspec.yaml | 1 + 4 files changed, 33 insertions(+), 10 deletions(-) diff --git a/packages/dart/noports_core/lib/src/srv/srv_impl.dart b/packages/dart/noports_core/lib/src/srv/srv_impl.dart index c265fc1e7..f666f72b4 100644 --- a/packages/dart/noports_core/lib/src/srv/srv_impl.dart +++ b/packages/dart/noports_core/lib/src/srv/srv_impl.dart @@ -231,7 +231,7 @@ class SrvImplInline implements Srv { // Authenticate if we have an rvdAuthString if (rvdAuthString != null) { - logger.info('authenticating'); + logger.info('run() authenticating to rvd'); socket.writeln(rvdAuthString); await socket.flush(); } @@ -351,7 +351,7 @@ class SrvImplDart implements Srv { DataTransformer createEncrypter(String aesKeyBase64, String ivBase64) { final DartAesCtr algorithm = DartAesCtr.with256bits( - macAlgorithm: Hmac.sha256(), + macAlgorithm: MacAlgorithm.empty, ); final SecretKey sessionAESKey = SecretKey(base64Decode(aesKeyBase64)); final List sessionIV = base64Decode(ivBase64); @@ -368,7 +368,7 @@ class SrvImplDart implements Srv { DataTransformer createDecrypter(String aesKeyBase64, String ivBase64) { final DartAesCtr algorithm = DartAesCtr.with256bits( - macAlgorithm: Hmac.sha256(), + macAlgorithm: MacAlgorithm.empty, ); final SecretKey sessionAESKey = SecretKey(base64Decode(aesKeyBase64)); final List sessionIV = base64Decode(ivBase64); @@ -579,7 +579,7 @@ class SrvImplDart implements Srv { logger.severe('Unknown request to control socket: [$request]'); return; } - logger.info('Control socket received ${args.first} request - ' + logger.info('_runDaemonSideMulti Control socket received ${args.first} request - ' ' creating new socketToSocket connection'); await SocketConnector.socketToSocket( connector: sc, @@ -592,7 +592,7 @@ class SrvImplDart implements Srv { transformAtoB: createEncrypter(args[1], args[2]), transformBtoA: createDecrypter(args[1], args[2])); if (rvdAuthString != null) { - stderr.writeln('authenticating new socket connection to rvd'); + logger.info('_runDaemonSideMulti authenticating new socket connection to rvd'); sc.connections.last.sideB.socket.writeln(rvdAuthString); } @@ -634,7 +634,7 @@ class SrvImplDart implements Srv { transformAtoB: encrypter, transformBtoA: decrypter); if (rvdAuthString != null) { - stderr.writeln('authenticating socketB'); + logger.info('_runDaemonSideSingle authenticating socketB to rvd'); socketConnector.connections.first.sideB.socket.writeln(rvdAuthString); } diff --git a/packages/dart/sshnoports/bin/srv.dart b/packages/dart/sshnoports/bin/srv.dart index e1eb8ff3e..ae90b23bb 100644 --- a/packages/dart/sshnoports/bin/srv.dart +++ b/packages/dart/sshnoports/bin/srv.dart @@ -2,16 +2,38 @@ import 'dart:io'; import 'package:args/args.dart'; import 'package:at_utils/at_logger.dart'; +import 'package:logging/logging.dart'; import 'package:noports_core/srv.dart'; import 'package:socket_connector/socket_connector.dart'; import 'package:sshnoports/src/print_version.dart'; +class TmpFileLoggingHandler implements LoggingHandler { + File f = File('/tmp/noports/srv.$pid.log'); + + TmpFileLoggingHandler() { + f.createSync(recursive: true); + } + + @override + void call(LogRecord record) { + f.writeAsStringSync('${record.level.name}' + '|${record.time}' + '|${record.loggerName}' + '|${record.message} \n', + mode: FileMode.writeOnlyAppend); + } +} + Future main(List args) async { - // Do not change this to anything below WARNING. If you do, then the - // onConnect callback in SrvImplDart._runClientSideMulti will crash the - // program + // For production usage, do not change this to anything below SHOUT or this + // programme will crash when emitting log messages, as this process's parent + // will have exited and closed its stderr. + // However you can set this log level to whatever you wish if you also change + // the default logging handler (see below) AtSignLogger.root_level = 'SHOUT'; AtSignLogger.defaultLoggingHandler = AtSignLogger.stdErrLoggingHandler; + // Uncomment this next line if you need to debug and see all output. + // AtSignLogger.defaultLoggingHandler = TmpFileLoggingHandler(); final ArgParser parser = ArgParser(showAliasesInUsage: true) ..addOption('host', abbr: 'h', mandatory: true, help: 'rvd host') diff --git a/packages/dart/sshnoports/pubspec.lock b/packages/dart/sshnoports/pubspec.lock index 75fbcb817..85a471577 100644 --- a/packages/dart/sshnoports/pubspec.lock +++ b/packages/dart/sshnoports/pubspec.lock @@ -515,7 +515,7 @@ packages: source: hosted version: "3.0.0" logging: - dependency: transitive + dependency: "direct main" description: name: logging sha256: "623a88c9594aa774443aa3eb2d41807a48486b5613e67599fb4c41c0ad47c340" diff --git a/packages/dart/sshnoports/pubspec.yaml b/packages/dart/sshnoports/pubspec.yaml index e34c93a8f..d47f19f8c 100644 --- a/packages/dart/sshnoports/pubspec.yaml +++ b/packages/dart/sshnoports/pubspec.yaml @@ -15,6 +15,7 @@ dependencies: socket_connector: ^2.2.0 dartssh2: 2.8.2 at_utils: 3.0.16 + logging: ^1.2.0 dependency_overrides: args: From 289b192f61786c22779fb3d48858304ce30ce83a Mon Sep 17 00:00:00 2001 From: gkc Date: Mon, 25 Mar 2024 14:12:24 +0000 Subject: [PATCH 08/34] test: tweak logging for for debugging --- packages/dart/sshnoports/bin/srv.dart | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/packages/dart/sshnoports/bin/srv.dart b/packages/dart/sshnoports/bin/srv.dart index ae90b23bb..6c4023c41 100644 --- a/packages/dart/sshnoports/bin/srv.dart +++ b/packages/dart/sshnoports/bin/srv.dart @@ -30,10 +30,10 @@ Future main(List args) async { // will have exited and closed its stderr. // However you can set this log level to whatever you wish if you also change // the default logging handler (see below) - AtSignLogger.root_level = 'SHOUT'; + AtSignLogger.root_level = 'FINEST'; AtSignLogger.defaultLoggingHandler = AtSignLogger.stdErrLoggingHandler; // Uncomment this next line if you need to debug and see all output. - // AtSignLogger.defaultLoggingHandler = TmpFileLoggingHandler(); + AtSignLogger.defaultLoggingHandler = TmpFileLoggingHandler(); final ArgParser parser = ArgParser(showAliasesInUsage: true) ..addOption('host', abbr: 'h', mandatory: true, help: 'rvd host') From 7e39ce2e550eced9b01e2935aef7ef3e08033e38 Mon Sep 17 00:00:00 2001 From: gkc Date: Mon, 25 Mar 2024 14:41:43 +0000 Subject: [PATCH 09/34] test: methinks we have an unhandled exception somewhere in srv --- packages/dart/sshnoports/bin/srv.dart | 6 ++++++ 1 file changed, 6 insertions(+) diff --git a/packages/dart/sshnoports/bin/srv.dart b/packages/dart/sshnoports/bin/srv.dart index 6c4023c41..852a06836 100644 --- a/packages/dart/sshnoports/bin/srv.dart +++ b/packages/dart/sshnoports/bin/srv.dart @@ -1,3 +1,4 @@ +import 'dart:async'; import 'dart:io'; import 'package:args/args.dart'; @@ -35,6 +36,7 @@ Future main(List args) async { // Uncomment this next line if you need to debug and see all output. AtSignLogger.defaultLoggingHandler = TmpFileLoggingHandler(); + AtSignLogger logger = AtSignLogger(' srv.main '); final ArgParser parser = ArgParser(showAliasesInUsage: true) ..addOption('host', abbr: 'h', mandatory: true, help: 'rvd host') ..addOption('port', abbr: 'p', mandatory: true, help: 'rvd port') @@ -60,6 +62,7 @@ Future main(List args) async { negatable: false, help: 'Set this flag when we want multiple connections via the rvd'); + await runZonedGuarded(() async { try { final ArgResults parsed; try { @@ -129,4 +132,7 @@ Future main(List args) async { stderr.writeln('\n$e'); exit(1); } + }, (Object error, StackTrace stackTrace) async { + logger.severe('Unhandled exception $error; stackTrace follows\n$stackTrace'); + }); } From c7f977a5e7b9a7bb56a58fc07c0f4ce1443b67db Mon Sep 17 00:00:00 2001 From: gkc Date: Mon, 25 Mar 2024 14:59:48 +0000 Subject: [PATCH 10/34] test: reduce number of tests so can focus on re-running npt test until it flakes so we can see logs --- .github/workflows/e2e_all.yaml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/.github/workflows/e2e_all.yaml b/.github/workflows/e2e_all.yaml index ce9a018aa..f61b01be6 100644 --- a/.github/workflows/e2e_all.yaml +++ b/.github/workflows/e2e_all.yaml @@ -39,4 +39,4 @@ jobs: echo "Running git checkout -f $SHA" git checkout -f "$SHA" echo "Running tests" - tests/e2e_all/scripts/main.sh @apricoteventual @combinedbelgian @rv_am + tests/e2e_all/scripts/main.sh @apricoteventual @combinedbelgian @rv_am -t 'minus_s_flag npt_to_port_22' From c976571656c26ed183b306946fb1b903f22cdf8a Mon Sep 17 00:00:00 2001 From: gkc Date: Tue, 26 Mar 2024 12:20:57 +0000 Subject: [PATCH 11/34] test: tweak logging in bin/srv.dart --- packages/dart/sshnoports/bin/srv.dart | 8 +++++++- 1 file changed, 7 insertions(+), 1 deletion(-) diff --git a/packages/dart/sshnoports/bin/srv.dart b/packages/dart/sshnoports/bin/srv.dart index 852a06836..9365c3e6b 100644 --- a/packages/dart/sshnoports/bin/srv.dart +++ b/packages/dart/sshnoports/bin/srv.dart @@ -113,18 +113,24 @@ Future main(List args) async { ).run(); /// Shut myself down once the socket connector closes + logger.shout('About to write "waiting for Srv to close" message to stderr'); stderr.writeln('Waiting for Srv to close'); + logger.shout('Wrote waiting message to stderr'); await sc.done; } on ArgumentError { rethrow; } catch (e) { // Do not remove this output; it is specifically looked for in // [SrvImplExec.run]. + logger.shout('About to write "${Srv.completedWithExceptionString}" message to stderr'); stderr.writeln('${Srv.completedWithExceptionString} : $e'); + logger.shout('Wrote "${Srv.completedWithExceptionString}" message to stderr'); exit(1); } + logger.shout('About to write "Closed - exiting" message to stderr'); stderr.writeln('Closed - exiting'); + logger.shout('Wrote "Closed - exiting" message to stderr'); exit(0); } on ArgumentError catch (e) { printVersion(); @@ -133,6 +139,6 @@ Future main(List args) async { exit(1); } }, (Object error, StackTrace stackTrace) async { - logger.severe('Unhandled exception $error; stackTrace follows\n$stackTrace'); + logger.shout('Unhandled exception $error; stackTrace follows\n$stackTrace'); }); } From eba99484cd020c1ba359a0f6e79e620573a17f0a Mon Sep 17 00:00:00 2001 From: gkc Date: Tue, 26 Mar 2024 12:44:38 +0000 Subject: [PATCH 12/34] test: more log tweaking in srv --- .github/workflows/e2e_all.yaml | 2 + .../noports_core/lib/src/srv/srv_impl.dart | 26 +-- packages/dart/sshnoports/bin/srv.dart | 162 ++++++++++-------- packages/dart/sshnoports/bin/sshnp.dart | 8 +- 4 files changed, 109 insertions(+), 89 deletions(-) diff --git a/.github/workflows/e2e_all.yaml b/.github/workflows/e2e_all.yaml index f61b01be6..e8a413b0a 100644 --- a/.github/workflows/e2e_all.yaml +++ b/.github/workflows/e2e_all.yaml @@ -39,4 +39,6 @@ jobs: echo "Running git checkout -f $SHA" git checkout -f "$SHA" echo "Running tests" + SRV_LOG_TO_TMP="true" + export SRV_LOG_TO_TMP tests/e2e_all/scripts/main.sh @apricoteventual @combinedbelgian @rv_am -t 'minus_s_flag npt_to_port_22' diff --git a/packages/dart/noports_core/lib/src/srv/srv_impl.dart b/packages/dart/noports_core/lib/src/srv/srv_impl.dart index f666f72b4..04fb170e3 100644 --- a/packages/dart/noports_core/lib/src/srv/srv_impl.dart +++ b/packages/dart/noports_core/lib/src/srv/srv_impl.dart @@ -225,8 +225,8 @@ class SrvImplInline implements Srv { } try { - logger.info( - 'Creating socket connection to rvd at $streamingHost:$streamingPort'); + logger.info('Creating socket connection to rvd' + ' at $streamingHost:$streamingPort'); Socket socket = await Socket.connect(streamingHost, streamingPort); // Authenticate if we have an rvdAuthString @@ -448,8 +448,8 @@ class SrvImplDart implements Srv { beforeJoining: (Side sideA, Side sideB) async { // Authenticate the sideB socket (to the rvd) if (rvdAuthString != null) { - logger.info( - '_runClientSideSingle authenticating new connection to rvd'); + logger.info('_runClientSideSingle authenticating' + ' new connection to rvd'); sideB.socket.writeln(rvdAuthString); } }, @@ -469,8 +469,8 @@ class SrvImplDart implements Srv { timeout: Duration(seconds: 1)); // Authenticate the control socket if (rvdAuthString != null) { - logger.info( - '_runClientSideMulti authenticating control socket connection to rvd'); + logger.info('_runClientSideMulti authenticating' + ' control socket connection to rvd'); sessionControlSocket.writeln(rvdAuthString); } DataTransformer controlEncrypter = @@ -486,8 +486,8 @@ class SrvImplDart implements Srv { controlStream.listen((event) { String response = String.fromCharCodes(event).trim(); - logger.info( - '_runClientSideMulti Received control socket response: [$response]'); + logger.info('_runClientSideMulti' + ' Received control socket response: [$response]'); }, onError: (e) { logger.severe('_runClientSideMulti controlSocket error: $e'); socketConnector?.close(); @@ -547,8 +547,8 @@ class SrvImplDart implements Srv { timeout: Duration(seconds: 1)); // Authenticate the control socket if (rvdAuthString != null) { - logger.info( - '_runDaemonSideMulti authenticating control socket connection to rvd'); + logger.info('_runDaemonSideMulti authenticating' + ' control socket connection to rvd'); sessionControlSocket.writeln(rvdAuthString); } DataTransformer controlEncrypter = @@ -579,7 +579,8 @@ class SrvImplDart implements Srv { logger.severe('Unknown request to control socket: [$request]'); return; } - logger.info('_runDaemonSideMulti Control socket received ${args.first} request - ' + logger.info('_runDaemonSideMulti' + ' Control socket received ${args.first} request - ' ' creating new socketToSocket connection'); await SocketConnector.socketToSocket( connector: sc, @@ -592,7 +593,8 @@ class SrvImplDart implements Srv { transformAtoB: createEncrypter(args[1], args[2]), transformBtoA: createDecrypter(args[1], args[2])); if (rvdAuthString != null) { - logger.info('_runDaemonSideMulti authenticating new socket connection to rvd'); + logger.info('_runDaemonSideMulti authenticating' + ' new socket connection to rvd'); sc.connections.last.sideB.socket.writeln(rvdAuthString); } diff --git a/packages/dart/sshnoports/bin/srv.dart b/packages/dart/sshnoports/bin/srv.dart index 9365c3e6b..a59fed0e7 100644 --- a/packages/dart/sshnoports/bin/srv.dart +++ b/packages/dart/sshnoports/bin/srv.dart @@ -17,11 +17,17 @@ class TmpFileLoggingHandler implements LoggingHandler { @override void call(LogRecord record) { - f.writeAsStringSync('${record.level.name}' + f.writeAsStringSync( + '${record.level.name}' '|${record.time}' '|${record.loggerName}' '|${record.message} \n', - mode: FileMode.writeOnlyAppend); + mode: FileMode.writeOnlyAppend); + try { + AtSignLogger.stdErrLoggingHandler.call(record); + } catch (e) { + f.writeAsStringSync('********** Failed to log to stderr: $e'); + } } } @@ -29,14 +35,17 @@ Future main(List args) async { // For production usage, do not change this to anything below SHOUT or this // programme will crash when emitting log messages, as this process's parent // will have exited and closed its stderr. - // However you can set this log level to whatever you wish if you also change - // the default logging handler (see below) - AtSignLogger.root_level = 'FINEST'; + AtSignLogger.root_level = 'SHOUT'; AtSignLogger.defaultLoggingHandler = AtSignLogger.stdErrLoggingHandler; - // Uncomment this next line if you need to debug and see all output. - AtSignLogger.defaultLoggingHandler = TmpFileLoggingHandler(); - AtSignLogger logger = AtSignLogger(' srv.main '); + // However if environment has SRV_LOG_TO_TMP == "true" then we will log to a + // file in /tmp and we might as well log everything + if ((Platform.environment['SRV_LOG_TO_TMP'] ?? "false").toLowerCase() == + 'true') { + AtSignLogger.defaultLoggingHandler = TmpFileLoggingHandler(); + AtSignLogger.root_level = 'FINEST'; + } + final ArgParser parser = ArgParser(showAliasesInUsage: true) ..addOption('host', abbr: 'h', mandatory: true, help: 'rvd host') ..addOption('port', abbr: 'p', mandatory: true, help: 'rvd port') @@ -63,81 +72,84 @@ Future main(List args) async { help: 'Set this flag when we want multiple connections via the rvd'); await runZonedGuarded(() async { - try { - final ArgResults parsed; try { - parsed = parser.parse(args); - } on FormatException catch (e) { - throw ArgumentError(e.message); - } + final ArgResults parsed; + try { + parsed = parser.parse(args); + } on FormatException catch (e) { + throw ArgumentError(e.message); + } - final String streamingHost = parsed['host']; - final int streamingPort = int.parse(parsed['port']); - final int localPort = int.parse(parsed['local-port']); - final bool bindLocalPort = parsed['bind-local-port']; - final String localHost = parsed['local-host']; - final bool rvAuth = parsed['rv-auth']; - final bool rvE2ee = parsed['rv-e2ee']; - final bool multi = parsed['multi']; + final String streamingHost = parsed['host']; + final int streamingPort = int.parse(parsed['port']); + final int localPort = int.parse(parsed['local-port']); + final bool bindLocalPort = parsed['bind-local-port']; + final String localHost = parsed['local-host']; + final bool rvAuth = parsed['rv-auth']; + final bool rvE2ee = parsed['rv-e2ee']; + final bool multi = parsed['multi']; - String? rvdAuthString = rvAuth ? Platform.environment['RV_AUTH'] : null; - String? sessionAESKeyString = - rvE2ee ? Platform.environment['RV_AES'] : null; - String? sessionIVString = rvE2ee ? Platform.environment['RV_IV'] : null; + String? rvdAuthString = rvAuth ? Platform.environment['RV_AUTH'] : null; + String? sessionAESKeyString = + rvE2ee ? Platform.environment['RV_AES'] : null; + String? sessionIVString = rvE2ee ? Platform.environment['RV_IV'] : null; - if (rvAuth && (rvdAuthString ?? '').isEmpty) { - throw ArgumentError( - '--rv-auth required, but RV_AUTH is not in environment'); - } - if (rvE2ee && (sessionAESKeyString ?? '').isEmpty) { - throw ArgumentError( - '--rv-e2ee required, but RV_AES is not in environment'); - } - if (rvE2ee && (sessionIVString ?? '').isEmpty) { - throw ArgumentError( - '--rv-e2ee required, but RV_IV is not in environment'); - } + if (rvAuth && (rvdAuthString ?? '').isEmpty) { + throw ArgumentError( + '--rv-auth required, but RV_AUTH is not in environment'); + } + if (rvE2ee && (sessionAESKeyString ?? '').isEmpty) { + throw ArgumentError( + '--rv-e2ee required, but RV_AES is not in environment'); + } + if (rvE2ee && (sessionIVString ?? '').isEmpty) { + throw ArgumentError( + '--rv-e2ee required, but RV_IV is not in environment'); + } - try { - SocketConnector sc = await Srv.dart( - streamingHost, - streamingPort, - localPort: localPort, - localHost: localHost, - bindLocalPort: bindLocalPort, - rvdAuthString: rvdAuthString, - sessionAESKeyString: sessionAESKeyString, - sessionIVString: sessionIVString, - multi: multi, - detached: true, // by definition - this is the srv binary - ).run(); + try { + SocketConnector sc = await Srv.dart( + streamingHost, + streamingPort, + localPort: localPort, + localHost: localHost, + bindLocalPort: bindLocalPort, + rvdAuthString: rvdAuthString, + sessionAESKeyString: sessionAESKeyString, + sessionIVString: sessionIVString, + multi: multi, + detached: true, // by definition - this is the srv binary + ).run(); - /// Shut myself down once the socket connector closes - logger.shout('About to write "waiting for Srv to close" message to stderr'); - stderr.writeln('Waiting for Srv to close'); - logger.shout('Wrote waiting message to stderr'); - await sc.done; - } on ArgumentError { - rethrow; - } catch (e) { - // Do not remove this output; it is specifically looked for in - // [SrvImplExec.run]. - logger.shout('About to write "${Srv.completedWithExceptionString}" message to stderr'); - stderr.writeln('${Srv.completedWithExceptionString} : $e'); - logger.shout('Wrote "${Srv.completedWithExceptionString}" message to stderr'); + /// Shut myself down once the socket connector closes + logger.shout( + 'About to write "waiting for Srv to close" message to stderr'); + stderr.writeln('Waiting for Srv to close'); + logger.shout('Wrote waiting message to stderr'); + await sc.done; + } on ArgumentError { + rethrow; + } catch (e) { + // Do not remove this output; it is specifically looked for in + // [SrvImplExec.run]. + logger.shout( + 'About to write "${Srv.completedWithExceptionString}" message to stderr'); + stderr.writeln('${Srv.completedWithExceptionString} : $e'); + logger.shout( + 'Wrote "${Srv.completedWithExceptionString}" message to stderr'); + exit(1); + } + + logger.shout('About to write "Closed - exiting" message to stderr'); + stderr.writeln('Closed - exiting'); + logger.shout('Wrote "Closed - exiting" message to stderr'); + exit(0); + } on ArgumentError catch (e) { + printVersion(); + stderr.writeln(parser.usage); + stderr.writeln('\n$e'); exit(1); } - - logger.shout('About to write "Closed - exiting" message to stderr'); - stderr.writeln('Closed - exiting'); - logger.shout('Wrote "Closed - exiting" message to stderr'); - exit(0); - } on ArgumentError catch (e) { - printVersion(); - stderr.writeln(parser.usage); - stderr.writeln('\n$e'); - exit(1); - } }, (Object error, StackTrace stackTrace) async { logger.shout('Unhandled exception $error; stackTrace follows\n$stackTrace'); }); diff --git a/packages/dart/sshnoports/bin/sshnp.dart b/packages/dart/sshnoports/bin/sshnp.dart index 391eadef8..d2c3d0d5b 100644 --- a/packages/dart/sshnoports/bin/sshnp.dart +++ b/packages/dart/sshnoports/bin/sshnp.dart @@ -40,11 +40,15 @@ void main(List args) async { bool originalLineMode = true; try { originalLineMode = stdin.lineMode; - } catch (e) {terminalError = e;} + } catch (e) { + terminalError = e; + } bool originalEchoMode = true; try { originalEchoMode = stdin.echoMode; - } catch (e) {terminalError ??= e;} + } catch (e) { + terminalError ??= e; + } bool shouldResetTerminal = false; From 17a9ee50359d66b1f49d6a433f861747785cc182 Mon Sep 17 00:00:00 2001 From: gkc Date: Tue, 26 Mar 2024 12:46:52 +0000 Subject: [PATCH 13/34] test: more log tweaking in srv --- packages/dart/sshnoports/bin/srv.dart | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/packages/dart/sshnoports/bin/srv.dart b/packages/dart/sshnoports/bin/srv.dart index a59fed0e7..813a7267b 100644 --- a/packages/dart/sshnoports/bin/srv.dart +++ b/packages/dart/sshnoports/bin/srv.dart @@ -26,7 +26,8 @@ class TmpFileLoggingHandler implements LoggingHandler { try { AtSignLogger.stdErrLoggingHandler.call(record); } catch (e) { - f.writeAsStringSync('********** Failed to log to stderr: $e'); + f.writeAsStringSync('********** Failed to log to stderr: $e', + mode: FileMode.writeOnlyAppend); } } } From c8edcedb4a8c76cf36b4ad14b1f1d3b6a1c5a45c Mon Sep 17 00:00:00 2001 From: gkc Date: Tue, 26 Mar 2024 12:52:18 +0000 Subject: [PATCH 14/34] test: e2e_all.yaml : run all tests --- .github/workflows/e2e_all.yaml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/.github/workflows/e2e_all.yaml b/.github/workflows/e2e_all.yaml index e8a413b0a..062c0209f 100644 --- a/.github/workflows/e2e_all.yaml +++ b/.github/workflows/e2e_all.yaml @@ -41,4 +41,4 @@ jobs: echo "Running tests" SRV_LOG_TO_TMP="true" export SRV_LOG_TO_TMP - tests/e2e_all/scripts/main.sh @apricoteventual @combinedbelgian @rv_am -t 'minus_s_flag npt_to_port_22' + tests/e2e_all/scripts/main.sh @apricoteventual @combinedbelgian @rv_am From 57876ee97b56a7b04a149a83e79d92c4d2ada38b Mon Sep 17 00:00:00 2001 From: gkc Date: Tue, 26 Mar 2024 15:00:10 +0000 Subject: [PATCH 15/34] test: e2e_all: if any daemon does not start successfully, then output its log file and abandon the test run --- tests/e2e_all/scripts/common/start_daemons.sh | 44 +++++++++++++++---- tests/e2e_all/scripts/main.sh | 3 -- 2 files changed, 35 insertions(+), 12 deletions(-) diff --git a/tests/e2e_all/scripts/common/start_daemons.sh b/tests/e2e_all/scripts/common/start_daemons.sh index 912a1356b..163b0cef8 100755 --- a/tests/e2e_all/scripts/common/start_daemons.sh +++ b/tests/e2e_all/scripts/common/start_daemons.sh @@ -10,6 +10,31 @@ source "$testScriptsDir/common/check_env.include.sh" || exit $? outputDir=$(getOutputDir) mkdir -p "${outputDir}/daemons" +waitUntilStarted() { + logInfo "Waiting for daemon $2 to start" + # $1 is pid, $2 is deviceName, $3 is logFile + totalSleepTime=0 + + while ! grep "Monitor .*monitor started" "$3"; + do + if ! ps -p "$1" > /dev/null + then + logError "Daemon $2 has exited. Log file follows: " + cat "$3" + # Do something knowing the pid exists, i.e. the process with $PID is running + exit 1 + fi + sleep 1 + totalSleepTime=$(( totalSleepTime + 1 )) + if (( totalSleepTime > daemonStartWait)); + then + logError "Daemon $2 has failed to start. Log file follows: " + cat "$3" + exit 1 + fi + done +} + # For each daemonVersion # Start two daemons for each typeAndVersion # 1) with the -u and -s flags set @@ -18,28 +43,29 @@ for typeAndVersion in $daemonVersions do logInfo " Starting daemons for commitId $commitId and version $typeAndVersion" - deviceName=$(getDeviceNameNoFlags "$commitId" "$typeAndVersion" ) - logInfo " Got deviceName $deviceName" - pathToBinaries=$(getPathToBinariesForTypeAndVersion "$typeAndVersion") cBinary="$pathToBinaries/sshnpd" fRoot="--root-domain $atDirectoryHost" fAtSigns="-m $clientAtSign -a $daemonAtSign" + deviceName=$(getDeviceNameNoFlags "$commitId" "$typeAndVersion" ) + logFile="${outputDir}/daemons/${deviceName}.log" logInfo " Starting daemon version $typeAndVersion with neither the -u nor -s flags" commandLine="$cBinary $fRoot $fAtSigns -d ${deviceName} --storage-path ${outputDir}/daemons/${deviceName}.storage -v" - echo " --> $commandLine >& ${outputDir}/daemons/${deviceName}.log 2>&1 &" - $commandLine > "${outputDir}/daemons/${deviceName}.log" 2>&1 & - sleep 0.2 + echo " --> $commandLine >& $logFile 2>&1 &" + $commandLine > "$logFile" 2>&1 & + + waitUntilStarted $! "$deviceName" "$logFile" echo deviceName=$(getDeviceNameWithFlags "$commitId" "$typeAndVersion" ) + logFile="${outputDir}/daemons/${deviceName}.log" logInfo " Starting daemon version $typeAndVersion with the -u and -s flags" commandLine="$cBinary $fRoot $fAtSigns -d ${deviceName} --storage-path ${outputDir}/daemons/${deviceName}.storage -v -u -s" - echo " --> $commandLine >& ${outputDir}/daemons/${deviceName}.log 2>&1 &" - $commandLine > "${outputDir}/daemons/${deviceName}.log" 2>&1 & - sleep 0.2 + echo " --> $commandLine >& $logFile 2>&1 &" + $commandLine > "$logFile" 2>&1 & + waitUntilStarted $! "$deviceName" "$logFile" echo echo diff --git a/tests/e2e_all/scripts/main.sh b/tests/e2e_all/scripts/main.sh index e3152b0eb..c2544ed70 100755 --- a/tests/e2e_all/scripts/main.sh +++ b/tests/e2e_all/scripts/main.sh @@ -202,9 +202,6 @@ if test "$retCode" != 0; then logError "Failed to start daemons; will not run tests" exit $retCode else - echo - logInfo "Sleeping for $daemonStartWait seconds to allow daemons to start" - sleep "$daemonStartWait" logInfo "Calling common/run_tests.sh" "$testScriptsDir/common/run_tests.sh" testExitStatus=$? From 8433eec7ef2c3b866c1de6cd96661f029b5aa12d Mon Sep 17 00:00:00 2001 From: gkc Date: Tue, 26 Mar 2024 15:10:18 +0000 Subject: [PATCH 16/34] test: logging tweak to srv.dart --- packages/dart/sshnoports/bin/srv.dart | 1 + 1 file changed, 1 insertion(+) diff --git a/packages/dart/sshnoports/bin/srv.dart b/packages/dart/sshnoports/bin/srv.dart index 813a7267b..dac75bbce 100644 --- a/packages/dart/sshnoports/bin/srv.dart +++ b/packages/dart/sshnoports/bin/srv.dart @@ -108,6 +108,7 @@ Future main(List args) async { '--rv-e2ee required, but RV_IV is not in environment'); } + logger.shout('About to call Srv.dart(...).run()'); try { SocketConnector sc = await Srv.dart( streamingHost, From 8c10a3aea6dc4e9efccf411b08ab9b425414aa91 Mon Sep 17 00:00:00 2001 From: gkc Date: Tue, 26 Mar 2024 15:11:36 +0000 Subject: [PATCH 17/34] test: logging tweak to srv.dart --- packages/dart/sshnoports/bin/srv.dart | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/packages/dart/sshnoports/bin/srv.dart b/packages/dart/sshnoports/bin/srv.dart index dac75bbce..d74060edf 100644 --- a/packages/dart/sshnoports/bin/srv.dart +++ b/packages/dart/sshnoports/bin/srv.dart @@ -38,7 +38,6 @@ Future main(List args) async { // will have exited and closed its stderr. AtSignLogger.root_level = 'SHOUT'; AtSignLogger.defaultLoggingHandler = AtSignLogger.stdErrLoggingHandler; - AtSignLogger logger = AtSignLogger(' srv.main '); // However if environment has SRV_LOG_TO_TMP == "true" then we will log to a // file in /tmp and we might as well log everything if ((Platform.environment['SRV_LOG_TO_TMP'] ?? "false").toLowerCase() == @@ -46,6 +45,7 @@ Future main(List args) async { AtSignLogger.defaultLoggingHandler = TmpFileLoggingHandler(); AtSignLogger.root_level = 'FINEST'; } + AtSignLogger logger = AtSignLogger(' srv.main '); final ArgParser parser = ArgParser(showAliasesInUsage: true) ..addOption('host', abbr: 'h', mandatory: true, help: 'rvd host') From bb7c76c18870023d72dedf37a5d462dbe618cb97 Mon Sep 17 00:00:00 2001 From: gkc Date: Tue, 26 Mar 2024 15:31:39 +0000 Subject: [PATCH 18/34] test: logging tweak to srv.dart --- packages/dart/sshnoports/bin/srv.dart | 1 + 1 file changed, 1 insertion(+) diff --git a/packages/dart/sshnoports/bin/srv.dart b/packages/dart/sshnoports/bin/srv.dart index d74060edf..9acd29ce6 100644 --- a/packages/dart/sshnoports/bin/srv.dart +++ b/packages/dart/sshnoports/bin/srv.dart @@ -129,6 +129,7 @@ Future main(List args) async { stderr.writeln('Waiting for Srv to close'); logger.shout('Wrote waiting message to stderr'); await sc.done; + logger.shout('sc is done'); } on ArgumentError { rethrow; } catch (e) { From 92d1afc2664ed5d430d9b42a2fde01538ae09bc1 Mon Sep 17 00:00:00 2001 From: gkc Date: Tue, 26 Mar 2024 15:38:06 +0000 Subject: [PATCH 19/34] test: logging tweak to Srv --- packages/dart/noports_core/lib/src/srv/srv_impl.dart | 2 ++ 1 file changed, 2 insertions(+) diff --git a/packages/dart/noports_core/lib/src/srv/srv_impl.dart b/packages/dart/noports_core/lib/src/srv/srv_impl.dart index 04fb170e3..b9b6f1944 100644 --- a/packages/dart/noports_core/lib/src/srv/srv_impl.dart +++ b/packages/dart/noports_core/lib/src/srv/srv_impl.dart @@ -496,6 +496,7 @@ class SrvImplDart implements Srv { socketConnector?.close(); }); + logger.info('_runClientSideMulti calling SocketConnector.serverToSocket'); socketConnector = await SocketConnector.serverToSocket( portA: localPort, addressB: hosts[0], @@ -525,6 +526,7 @@ class SrvImplDart implements Srv { sideB.transformer = createDecrypter(socketAESKey, socketIV); }, ); + logger.info('_runClientSideMulti serverToSocket is ready'); // upon socketConnector.done, destroy the control socket, and complete unawaited(socketConnector.done.whenComplete(() { From b3065baa702f199c8d712c49893878b468fff667 Mon Sep 17 00:00:00 2001 From: gkc Date: Tue, 26 Mar 2024 19:45:49 +0000 Subject: [PATCH 20/34] test: more logging tweaks --- packages/dart/noports_core/lib/src/srv/srv_impl.dart | 6 ++++++ tests/e2e_all/scripts/common/common_functions.include.sh | 2 ++ tests/e2e_all/scripts/srv.sh | 9 +++++++++ 3 files changed, 17 insertions(+) create mode 100755 tests/e2e_all/scripts/srv.sh diff --git a/packages/dart/noports_core/lib/src/srv/srv_impl.dart b/packages/dart/noports_core/lib/src/srv/srv_impl.dart index b9b6f1944..6a23038d7 100644 --- a/packages/dart/noports_core/lib/src/srv/srv_impl.dart +++ b/packages/dart/noports_core/lib/src/srv/srv_impl.dart @@ -67,6 +67,12 @@ class SrvImplExec implements Srv { @override Future run() async { String? command = await Srv.getLocalBinaryPath(); + // + // + // TODO Revert this + // + // + command='$command.sh'; String postfix = Platform.isWindows ? '.exe' : ''; if (command == null) { throw SshnpError( diff --git a/tests/e2e_all/scripts/common/common_functions.include.sh b/tests/e2e_all/scripts/common/common_functions.include.sh index 82b202821..da66ff89a 100644 --- a/tests/e2e_all/scripts/common/common_functions.include.sh +++ b/tests/e2e_all/scripts/common/common_functions.include.sh @@ -390,6 +390,8 @@ buildCurrentDartBinaries() { logInfo " Compiling npt" dart compile exe --verbosity "$compileVerbosity" bin/npt.dart -o "$binaryOutputDir/npt" fi + + cp "$testScriptsDir/srv.sh" "$binaryOutputDir/srv.sh" } downloadDartBinaries() { diff --git a/tests/e2e_all/scripts/srv.sh b/tests/e2e_all/scripts/srv.sh new file mode 100755 index 000000000..3ffc6f3ae --- /dev/null +++ b/tests/e2e_all/scripts/srv.sh @@ -0,0 +1,9 @@ +#!/bin/bash + +# Sometimes while testing it's handy to execute this script rather than executing the srv directly + +binDir="$(dirname -- "$0")" + +mkdir -p /tmp/noports + +"${binDir}/srv" "$@" 2>&1 | tee -a /tmp/noports/srv.sh.$$.log From d06df9e5d5d1d8ad0fc4eb1e4ffb8cb114f954cc Mon Sep 17 00:00:00 2001 From: gkc Date: Tue, 26 Mar 2024 19:52:43 +0000 Subject: [PATCH 21/34] test: more logging tweaks --- packages/dart/noports_core/lib/src/srv/srv_impl.dart | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/packages/dart/noports_core/lib/src/srv/srv_impl.dart b/packages/dart/noports_core/lib/src/srv/srv_impl.dart index 6a23038d7..529234fa9 100644 --- a/packages/dart/noports_core/lib/src/srv/srv_impl.dart +++ b/packages/dart/noports_core/lib/src/srv/srv_impl.dart @@ -72,7 +72,9 @@ class SrvImplExec implements Srv { // TODO Revert this // // - command='$command.sh'; + if (command != null) { + command = '$command.sh'; + } String postfix = Platform.isWindows ? '.exe' : ''; if (command == null) { throw SshnpError( @@ -602,7 +604,7 @@ class SrvImplDart implements Srv { transformBtoA: createDecrypter(args[1], args[2])); if (rvdAuthString != null) { logger.info('_runDaemonSideMulti authenticating' - ' new socket connection to rvd'); + ' new socket connection to rvd'); sc.connections.last.sideB.socket.writeln(rvdAuthString); } From ebb77db71fd4c00f7ee564cc72eeb94b6bf9dabf Mon Sep 17 00:00:00 2001 From: gkc Date: Wed, 27 Mar 2024 10:57:14 +0000 Subject: [PATCH 22/34] test: more logging tweaks --- tests/e2e_all/scripts/srv.sh | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/tests/e2e_all/scripts/srv.sh b/tests/e2e_all/scripts/srv.sh index 3ffc6f3ae..88b9cbd5e 100755 --- a/tests/e2e_all/scripts/srv.sh +++ b/tests/e2e_all/scripts/srv.sh @@ -6,4 +6,6 @@ binDir="$(dirname -- "$0")" mkdir -p /tmp/noports -"${binDir}/srv" "$@" 2>&1 | tee -a /tmp/noports/srv.sh.$$.log +# "${binDir}/srv" "$@" 2>&1 | tee -a /tmp/noports/srv.sh.$$.log +"${binDir}/srv" "$@" +echo "Exit code was $? " >> /tmp/noports/srv.sh.$$.log From caf6d2a4e241a68e758c265cfacd9f9248216988 Mon Sep 17 00:00:00 2001 From: gkc Date: Wed, 27 Mar 2024 11:16:42 +0000 Subject: [PATCH 23/34] test: more logging tweaks --- packages/dart/sshnoports/bin/srv.dart | 12 ++++++++++-- 1 file changed, 10 insertions(+), 2 deletions(-) diff --git a/packages/dart/sshnoports/bin/srv.dart b/packages/dart/sshnoports/bin/srv.dart index 9acd29ce6..605a7b694 100644 --- a/packages/dart/sshnoports/bin/srv.dart +++ b/packages/dart/sshnoports/bin/srv.dart @@ -40,9 +40,10 @@ Future main(List args) async { AtSignLogger.defaultLoggingHandler = AtSignLogger.stdErrLoggingHandler; // However if environment has SRV_LOG_TO_TMP == "true" then we will log to a // file in /tmp and we might as well log everything + var fileLogger=TmpFileLoggingHandler(); if ((Platform.environment['SRV_LOG_TO_TMP'] ?? "false").toLowerCase() == 'true') { - AtSignLogger.defaultLoggingHandler = TmpFileLoggingHandler(); + AtSignLogger.defaultLoggingHandler = fileLogger; AtSignLogger.root_level = 'FINEST'; } AtSignLogger logger = AtSignLogger(' srv.main '); @@ -153,7 +154,14 @@ Future main(List args) async { stderr.writeln('\n$e'); exit(1); } - }, (Object error, StackTrace stackTrace) async { + }, (error, stackTrace) async { + fileLogger.f.writeAsStringSync( + 'direct to log file:' + ' Unhandled exception $error;' + ' stackTrace follows:' + '\n' + '$stackTrace', + mode: FileMode.writeOnlyAppend); logger.shout('Unhandled exception $error; stackTrace follows\n$stackTrace'); }); } From 017f924688f17f2e427fbec8f6ac6821f274bd34 Mon Sep 17 00:00:00 2001 From: gkc Date: Wed, 27 Mar 2024 14:31:47 +0000 Subject: [PATCH 24/34] test: Tweaked test rig a little --- tests/e2e_all/scripts/common/run_tests.sh | 15 ++++++++++++++- tests/e2e_all/scripts/common/stop_daemons.sh | 16 +++++++++------- tests/e2e_all/scripts/srv.sh | 4 ++-- 3 files changed, 25 insertions(+), 10 deletions(-) diff --git a/tests/e2e_all/scripts/common/run_tests.sh b/tests/e2e_all/scripts/common/run_tests.sh index a84a75445..656c8a19f 100755 --- a/tests/e2e_all/scripts/common/run_tests.sh +++ b/tests/e2e_all/scripts/common/run_tests.sh @@ -71,7 +71,7 @@ do > "$stdoutFileName" 2> "$stderrFileName" exitStatus=$? - if (( exitStatus != 0 )); then + if (( exitStatus != 0 && exitStatus != 50 )); then # shellcheck disable=SC2129 echo " test execution's stdout: " | tee -a "$reportFile" sed 's/^/ /' "$stdoutFileName" | tee -a "$reportFile" @@ -147,8 +147,21 @@ do ;; esac echo >> "$reportFile" + + if [[ "$testResult" == "FAILED" ]]; + then + break + fi done + if [[ "$testResult" == "FAILED" ]]; + then + break + fi done + if [[ "$testResult" == "FAILED" ]]; + then + break + fi done # shellcheck disable=SC2129 diff --git a/tests/e2e_all/scripts/common/stop_daemons.sh b/tests/e2e_all/scripts/common/stop_daemons.sh index 44a6a32dd..937d332de 100755 --- a/tests/e2e_all/scripts/common/stop_daemons.sh +++ b/tests/e2e_all/scripts/common/stop_daemons.sh @@ -9,15 +9,17 @@ source "$testScriptsDir/common/check_env.include.sh" || exit $? for pid in $(pgrep -f "sshnpd.*${commitId}") do + echo "Killing $(ps -ef | grep " $pid " | grep -v grep)" kill "$pid" done -for pid in $(pgrep -f "tests/e2e_all/runtime/.*/.* ") +for pid in $(pgrep -f "tests/e2e_all/(runtime|releases)/.*/.* ") do - kill "$pid" -done - -for pid in $(pgrep -f "tests/e2e_all/releases/.*/.* ") -do - kill "$pid" + processInfo=$(ps -ef | grep " $pid " | grep -v grep) + # Allow the srv's to exit in their own time + if ! grep -q "srv " <<< "$processInfo"; + then + echo "Killing $processInfo" + kill "$pid" + fi done diff --git a/tests/e2e_all/scripts/srv.sh b/tests/e2e_all/scripts/srv.sh index 88b9cbd5e..6a7271669 100755 --- a/tests/e2e_all/scripts/srv.sh +++ b/tests/e2e_all/scripts/srv.sh @@ -6,6 +6,6 @@ binDir="$(dirname -- "$0")" mkdir -p /tmp/noports -# "${binDir}/srv" "$@" 2>&1 | tee -a /tmp/noports/srv.sh.$$.log -"${binDir}/srv" "$@" +"${binDir}/srv" "$@" 2>&1 | tee -a /tmp/noports/srv.sh.$$.log +# "${binDir}/srv" "$@" >> /tmp/noports/srv.sh.$$.log 2>&1 echo "Exit code was $? " >> /tmp/noports/srv.sh.$$.log From 1a2881cba7bd7a82320c21f81c7d68aa43b0b00b Mon Sep 17 00:00:00 2001 From: gkc Date: Wed, 27 Mar 2024 14:36:29 +0000 Subject: [PATCH 25/34] feat: noports_core v6.0.6: SrvImplDart: supply a logger to SocketConnector so that the Srv can control what happens with any log messages that SocketConnector emits --- packages/dart/noports_core/CHANGELOG.md | 4 ++++ .../noports_core/lib/src/srv/srv_impl.dart | 22 ++++++++++++------- packages/dart/noports_core/pubspec.yaml | 4 +++- 3 files changed, 21 insertions(+), 9 deletions(-) diff --git a/packages/dart/noports_core/CHANGELOG.md b/packages/dart/noports_core/CHANGELOG.md index e0b9f2a57..cacd98764 100644 --- a/packages/dart/noports_core/CHANGELOG.md +++ b/packages/dart/noports_core/CHANGELOG.md @@ -1,3 +1,7 @@ +# 6.0.6 +- feat: SrvImplDart: supply a logger to SocketConnector so that the Srv can + control what happens with any log messages that SocketConnector emits + # 6.0.5 - fix: Strict validation of device name as alphanumeric snake case - feat: Increase device name max length from 15 to 36 diff --git a/packages/dart/noports_core/lib/src/srv/srv_impl.dart b/packages/dart/noports_core/lib/src/srv/srv_impl.dart index 529234fa9..ad519433d 100644 --- a/packages/dart/noports_core/lib/src/srv/srv_impl.dart +++ b/packages/dart/noports_core/lib/src/srv/srv_impl.dart @@ -67,14 +67,6 @@ class SrvImplExec implements Srv { @override Future run() async { String? command = await Srv.getLocalBinaryPath(); - // - // - // TODO Revert this - // - // - if (command != null) { - command = '$command.sh'; - } String postfix = Platform.isWindows ? '.exe' : ''; if (command == null) { throw SshnpError( @@ -351,6 +343,7 @@ class SrvImplDart implements Srv { this.multi = false, required this.detached, }) { + logger.info('New SrvImplDart - localPort $localPort'); if ((sessionAESKeyString == null && sessionIVString != null) || (sessionAESKeyString != null && sessionIVString == null)) { throw ArgumentError('Both AES key and IV are required, or neither'); @@ -450,10 +443,12 @@ class SrvImplDart implements Srv { addressB: hosts[0], portB: streamingPort, verbose: false, + logger: ioSinkForLogger(logger), transformAtoB: encrypter, transformBtoA: decrypter, multi: multi, beforeJoining: (Side sideA, Side sideB) async { + logger.info('beforeJoining called'); // Authenticate the sideB socket (to the rvd) if (rvdAuthString != null) { logger.info('_runClientSideSingle authenticating' @@ -510,6 +505,7 @@ class SrvImplDart implements Srv { addressB: hosts[0], portB: streamingPort, verbose: false, + logger: ioSinkForLogger(logger), multi: multi, beforeJoining: (Side sideA, Side sideB) { // For some bizarro reason, we can't write to stderr in this callback @@ -600,6 +596,7 @@ class SrvImplDart implements Srv { addressB: hosts[0], portB: streamingPort, verbose: false, + logger: ioSinkForLogger(logger), transformAtoB: createEncrypter(args[1], args[2]), transformBtoA: createDecrypter(args[1], args[2])); if (rvdAuthString != null) { @@ -643,6 +640,7 @@ class SrvImplDart implements Srv { addressB: hosts[0], portB: streamingPort, verbose: false, + logger: ioSinkForLogger(logger), transformAtoB: encrypter, transformBtoA: decrypter); if (rvdAuthString != null) { @@ -653,3 +651,11 @@ class SrvImplDart implements Srv { return socketConnector; } } + +IOSink ioSinkForLogger(AtSignLogger l) { + StreamController> logSinkSc = StreamController>(); + logSinkSc.stream.listen((event) { + l.shout(' (SocketConnector) | ${String.fromCharCodes(event)}'); + }); + return IOSink(logSinkSc.sink); +} \ No newline at end of file diff --git a/packages/dart/noports_core/pubspec.yaml b/packages/dart/noports_core/pubspec.yaml index 436494e3e..f481eec18 100644 --- a/packages/dart/noports_core/pubspec.yaml +++ b/packages/dart/noports_core/pubspec.yaml @@ -2,7 +2,7 @@ name: noports_core description: Core library code for sshnoports homepage: https://docs.atsign.com/ -version: 6.0.5 +version: 6.0.6 environment: sdk: ">=3.0.0 <4.0.0" @@ -25,6 +25,8 @@ dependencies: uuid: ^3.0.7 dependency_overrides: + socket_connector: + path: /Users/gary/dev/atsign/repos/socket_connector args: git: ref: gkc/show-aliases-in-usage From 429d46afbf6c15c7ee2699ea4416e28a312ab96c Mon Sep 17 00:00:00 2001 From: gkc Date: Wed, 27 Mar 2024 14:38:43 +0000 Subject: [PATCH 26/34] build: noports_core: reverted a dependency override --- packages/dart/noports_core/pubspec.yaml | 2 -- 1 file changed, 2 deletions(-) diff --git a/packages/dart/noports_core/pubspec.yaml b/packages/dart/noports_core/pubspec.yaml index f481eec18..e9861c30a 100644 --- a/packages/dart/noports_core/pubspec.yaml +++ b/packages/dart/noports_core/pubspec.yaml @@ -25,8 +25,6 @@ dependencies: uuid: ^3.0.7 dependency_overrides: - socket_connector: - path: /Users/gary/dev/atsign/repos/socket_connector args: git: ref: gkc/show-aliases-in-usage From e5d8dbc635d1a02bbe3cdf6e513c5b935c42b7cd Mon Sep 17 00:00:00 2001 From: gkc Date: Wed, 27 Mar 2024 14:41:53 +0000 Subject: [PATCH 27/34] build: update versions and run dart run melos bootstrap --- packages/dart/noports_core/lib/src/version.dart | 2 +- packages/dart/sshnoports/lib/src/version.dart | 2 +- packages/dart/sshnoports/pubspec.lock | 2 +- packages/dart/sshnoports/pubspec.yaml | 2 +- packages/dart/sshnp_flutter/pubspec.lock | 2 +- 5 files changed, 5 insertions(+), 5 deletions(-) diff --git a/packages/dart/noports_core/lib/src/version.dart b/packages/dart/noports_core/lib/src/version.dart index 9ab030b15..b631523c7 100644 --- a/packages/dart/noports_core/lib/src/version.dart +++ b/packages/dart/noports_core/lib/src/version.dart @@ -1,2 +1,2 @@ // Generated code. Do not modify. -const packageVersion = '6.0.5'; +const packageVersion = '6.0.6'; diff --git a/packages/dart/sshnoports/lib/src/version.dart b/packages/dart/sshnoports/lib/src/version.dart index 4cf79fd0e..791044cdb 100644 --- a/packages/dart/sshnoports/lib/src/version.dart +++ b/packages/dart/sshnoports/lib/src/version.dart @@ -1,2 +1,2 @@ // Generated code. Do not modify. -const packageVersion = '5.1.0-rc.5'; +const packageVersion = '5.1.0-rc.6'; diff --git a/packages/dart/sshnoports/pubspec.lock b/packages/dart/sshnoports/pubspec.lock index 85a471577..e65b16375 100644 --- a/packages/dart/sshnoports/pubspec.lock +++ b/packages/dart/sshnoports/pubspec.lock @@ -584,7 +584,7 @@ packages: path: "../noports_core" relative: true source: path - version: "6.0.5" + version: "6.0.6" openssh_ed25519: dependency: transitive description: diff --git a/packages/dart/sshnoports/pubspec.yaml b/packages/dart/sshnoports/pubspec.yaml index 35d3843ca..739b6d715 100644 --- a/packages/dart/sshnoports/pubspec.yaml +++ b/packages/dart/sshnoports/pubspec.yaml @@ -1,7 +1,7 @@ name: sshnoports publish_to: none -version: 5.1.0-rc.5 +version: 5.1.0-rc.6 environment: sdk: ">=3.0.0 <4.0.0" diff --git a/packages/dart/sshnp_flutter/pubspec.lock b/packages/dart/sshnp_flutter/pubspec.lock index 4080ec919..0a2b3709e 100644 --- a/packages/dart/sshnp_flutter/pubspec.lock +++ b/packages/dart/sshnp_flutter/pubspec.lock @@ -795,7 +795,7 @@ packages: path: "../noports_core" relative: true source: path - version: "6.0.5" + version: "6.0.6" openssh_ed25519: dependency: transitive description: From 0a28f5afda5c4690eff9a651c5d0e97c2e934c6c Mon Sep 17 00:00:00 2001 From: gkc Date: Wed, 27 Mar 2024 14:50:05 +0000 Subject: [PATCH 28/34] fix: Fix issue where the srv process would crash when writing to stderr when spawned by a parent which has exited - Have bin/srv.dart set a LoggingHandler which will write to both a temporary file and stderr while the parent should still be alive but will only write to the temporary file once the parent can be expected to have exited. - The temporary file is placed in the platform-appropriate place (/tmp on unix, %TEMP% on Windows) - The temporary file is removed by the srv process itself if it exits normally, but is not removed if it exits abnormally. This is to enable diagnosis if problems occur. Yes, this is all a bit annoying. --- packages/dart/sshnoports/bin/srv.dart | 123 ++++++++++++-------------- 1 file changed, 57 insertions(+), 66 deletions(-) diff --git a/packages/dart/sshnoports/bin/srv.dart b/packages/dart/sshnoports/bin/srv.dart index 605a7b694..8ab95d26f 100644 --- a/packages/dart/sshnoports/bin/srv.dart +++ b/packages/dart/sshnoports/bin/srv.dart @@ -1,6 +1,7 @@ import 'dart:async'; import 'dart:io'; +import 'package:path/path.dart' as path; import 'package:args/args.dart'; import 'package:at_utils/at_logger.dart'; import 'package:logging/logging.dart'; @@ -9,9 +10,17 @@ import 'package:socket_connector/socket_connector.dart'; import 'package:sshnoports/src/print_version.dart'; class TmpFileLoggingHandler implements LoggingHandler { - File f = File('/tmp/noports/srv.$pid.log'); + late final File f; + + bool logToStderr = true; TmpFileLoggingHandler() { + if (Platform.isWindows) { + f = File(path.normalize('${Platform.environment['TEMP']}' + '/srv.$pid.log')); + } else { + f = File('/tmp/srv.$pid.log'); + } f.createSync(recursive: true); } @@ -23,29 +32,22 @@ class TmpFileLoggingHandler implements LoggingHandler { '|${record.loggerName}' '|${record.message} \n', mode: FileMode.writeOnlyAppend); - try { - AtSignLogger.stdErrLoggingHandler.call(record); - } catch (e) { - f.writeAsStringSync('********** Failed to log to stderr: $e', - mode: FileMode.writeOnlyAppend); + if (logToStderr) { + try { + AtSignLogger.stdErrLoggingHandler.call(record); + } catch (e) { + f.writeAsStringSync('********** Failed to log to stderr: $e', + mode: FileMode.writeOnlyAppend); + } } } } Future main(List args) async { - // For production usage, do not change this to anything below SHOUT or this - // programme will crash when emitting log messages, as this process's parent - // will have exited and closed its stderr. - AtSignLogger.root_level = 'SHOUT'; - AtSignLogger.defaultLoggingHandler = AtSignLogger.stdErrLoggingHandler; - // However if environment has SRV_LOG_TO_TMP == "true" then we will log to a - // file in /tmp and we might as well log everything - var fileLogger=TmpFileLoggingHandler(); - if ((Platform.environment['SRV_LOG_TO_TMP'] ?? "false").toLowerCase() == - 'true') { - AtSignLogger.defaultLoggingHandler = fileLogger; - AtSignLogger.root_level = 'FINEST'; - } + AtSignLogger.root_level = 'INFO'; + var fileLoggingHandler = TmpFileLoggingHandler(); + AtSignLogger.defaultLoggingHandler = fileLoggingHandler; + AtSignLogger logger = AtSignLogger(' srv.main '); final ArgParser parser = ArgParser(showAliasesInUsage: true) @@ -74,6 +76,7 @@ Future main(List args) async { help: 'Set this flag when we want multiple connections via the rvd'); await runZonedGuarded(() async { + final SocketConnector sc; try { final ArgResults parsed; try { @@ -109,59 +112,47 @@ Future main(List args) async { '--rv-e2ee required, but RV_IV is not in environment'); } - logger.shout('About to call Srv.dart(...).run()'); - try { - SocketConnector sc = await Srv.dart( - streamingHost, - streamingPort, - localPort: localPort, - localHost: localHost, - bindLocalPort: bindLocalPort, - rvdAuthString: rvdAuthString, - sessionAESKeyString: sessionAESKeyString, - sessionIVString: sessionIVString, - multi: multi, - detached: true, // by definition - this is the srv binary - ).run(); - - /// Shut myself down once the socket connector closes - logger.shout( - 'About to write "waiting for Srv to close" message to stderr'); - stderr.writeln('Waiting for Srv to close'); - logger.shout('Wrote waiting message to stderr'); - await sc.done; - logger.shout('sc is done'); - } on ArgumentError { - rethrow; - } catch (e) { - // Do not remove this output; it is specifically looked for in - // [SrvImplExec.run]. - logger.shout( - 'About to write "${Srv.completedWithExceptionString}" message to stderr'); - stderr.writeln('${Srv.completedWithExceptionString} : $e'); - logger.shout( - 'Wrote "${Srv.completedWithExceptionString}" message to stderr'); - exit(1); - } - - logger.shout('About to write "Closed - exiting" message to stderr'); - stderr.writeln('Closed - exiting'); - logger.shout('Wrote "Closed - exiting" message to stderr'); - exit(0); + sc = await Srv.dart( + streamingHost, + streamingPort, + localPort: localPort, + localHost: localHost, + bindLocalPort: bindLocalPort, + rvdAuthString: rvdAuthString, + sessionAESKeyString: sessionAESKeyString, + sessionIVString: sessionIVString, + multi: multi, + detached: true, // by definition - this is the srv binary + ).run(); } on ArgumentError catch (e) { printVersion(); stderr.writeln(parser.usage); stderr.writeln('\n$e'); + + /// clean up the log file in /tmp + try {fileLoggingHandler.f.deleteSync();} catch (_) {} + exit(1); } - }, (error, stackTrace) async { - fileLogger.f.writeAsStringSync( - 'direct to log file:' - ' Unhandled exception $error;' - ' stackTrace follows:' - '\n' - '$stackTrace', - mode: FileMode.writeOnlyAppend); + + /// No more writing to stderr, as the parent process will have exited, + /// and stderr no longer exists + fileLoggingHandler.logToStderr = false; + + /// Wait for socket connector to close + await sc.done; + + /// clean up the log file in /tmp + try {fileLoggingHandler.f.deleteSync();} catch (_) {} + + exit(0); + }, (error, StackTrace stackTrace) async { logger.shout('Unhandled exception $error; stackTrace follows\n$stackTrace'); + // // Do not remove this output; it is specifically looked for in + // // [SrvImplExec.run]. + logger.shout('${Srv.completedWithExceptionString} : $error'); + + /// We will leave the log file in /tmp + exit(200); }); } From b37f790b22f9ed45bd5dea08183b48b9f338de43 Mon Sep 17 00:00:00 2001 From: gkc Date: Wed, 27 Mar 2024 14:52:53 +0000 Subject: [PATCH 29/34] fix: srv.dart: leave tmp file in place if exiting because of ArgumentError --- packages/dart/sshnoports/bin/srv.dart | 12 +++++------- 1 file changed, 5 insertions(+), 7 deletions(-) diff --git a/packages/dart/sshnoports/bin/srv.dart b/packages/dart/sshnoports/bin/srv.dart index 8ab95d26f..fc7c1d59f 100644 --- a/packages/dart/sshnoports/bin/srv.dart +++ b/packages/dart/sshnoports/bin/srv.dart @@ -129,9 +129,7 @@ Future main(List args) async { stderr.writeln(parser.usage); stderr.writeln('\n$e'); - /// clean up the log file in /tmp - try {fileLoggingHandler.f.deleteSync();} catch (_) {} - + // We will leave the log file in /tmp since we are exiting abnormally exit(1); } @@ -142,17 +140,17 @@ Future main(List args) async { /// Wait for socket connector to close await sc.done; - /// clean up the log file in /tmp + /// We will clean up the log file in /tmp since we are exiting normally try {fileLoggingHandler.f.deleteSync();} catch (_) {} exit(0); }, (error, StackTrace stackTrace) async { logger.shout('Unhandled exception $error; stackTrace follows\n$stackTrace'); - // // Do not remove this output; it is specifically looked for in - // // [SrvImplExec.run]. + // Do not remove this output; it is specifically looked for in + // [SrvImplExec.run]. logger.shout('${Srv.completedWithExceptionString} : $error'); - /// We will leave the log file in /tmp + // We will leave the log file in /tmp since we are exiting abnormally exit(200); }); } From be609cb1007df8e018e90777c4007a90db9c8731 Mon Sep 17 00:00:00 2001 From: gkc Date: Wed, 27 Mar 2024 14:53:41 +0000 Subject: [PATCH 30/34] chore: run dart format --- packages/dart/noports_core/lib/src/srv/srv_impl.dart | 2 +- packages/dart/sshnoports/bin/srv.dart | 4 +++- 2 files changed, 4 insertions(+), 2 deletions(-) diff --git a/packages/dart/noports_core/lib/src/srv/srv_impl.dart b/packages/dart/noports_core/lib/src/srv/srv_impl.dart index ad519433d..18a1e749e 100644 --- a/packages/dart/noports_core/lib/src/srv/srv_impl.dart +++ b/packages/dart/noports_core/lib/src/srv/srv_impl.dart @@ -658,4 +658,4 @@ IOSink ioSinkForLogger(AtSignLogger l) { l.shout(' (SocketConnector) | ${String.fromCharCodes(event)}'); }); return IOSink(logSinkSc.sink); -} \ No newline at end of file +} diff --git a/packages/dart/sshnoports/bin/srv.dart b/packages/dart/sshnoports/bin/srv.dart index fc7c1d59f..190bf8447 100644 --- a/packages/dart/sshnoports/bin/srv.dart +++ b/packages/dart/sshnoports/bin/srv.dart @@ -141,7 +141,9 @@ Future main(List args) async { await sc.done; /// We will clean up the log file in /tmp since we are exiting normally - try {fileLoggingHandler.f.deleteSync();} catch (_) {} + try { + fileLoggingHandler.f.deleteSync(); + } catch (_) {} exit(0); }, (error, StackTrace stackTrace) async { From 2f4228f8a418c948db6c49713a1026ef5c0bd8a8 Mon Sep 17 00:00:00 2001 From: gkc Date: Wed, 27 Mar 2024 16:03:05 +0000 Subject: [PATCH 31/34] fix: Prevent problem which was causing srv to fail intermittently. - in SrvImplExec, add a grace period of 100 milliseconds after detecting what the child process has written to its stderr - in SrvImplDart, catch any exception thrown by stderr.writeln --- .../dart/noports_core/lib/src/srv/srv_impl.dart | 17 +++++++++++++---- 1 file changed, 13 insertions(+), 4 deletions(-) diff --git a/packages/dart/noports_core/lib/src/srv/srv_impl.dart b/packages/dart/noports_core/lib/src/srv/srv_impl.dart index 18a1e749e..88feeebb1 100644 --- a/packages/dart/noports_core/lib/src/srv/srv_impl.dart +++ b/packages/dart/noports_core/lib/src/srv/srv_impl.dart @@ -142,7 +142,9 @@ class SrvImplExec implements Srv { } }); - await rvPortBound.future.timeout(Duration(seconds: 2)); + await rvPortBound.future.timeout(Duration(seconds: 3)); + + await Future.delayed(Duration(milliseconds: 100)); return p; } @@ -241,7 +243,7 @@ class SrvImplInline implements Srv { return sshSocket; } catch (e) { - AtSignLogger('srv').severe(e.toString()); + logger.severe(e.toString()); rethrow; } } @@ -418,12 +420,19 @@ class SrvImplDart implements Srv { // bound to a port. Looking for specific output when the rv is ready to // do its job seems to be the only way to do this. if (detached) { - stderr.writeln(Srv.startedString); + try { + stderr.writeln(Srv.startedString); + } catch (e, st) { + logger.severe('Failed to write ${Srv.startedString}' + ' to stderr: ${e.toString()} ;' + ' stackTrace follows:\n' + '$st'); + } } return sc; } catch (e) { - AtSignLogger('srv').severe(e.toString()); + logger.severe(e.toString()); rethrow; } } From c95d7c21ebcaeb070b1c8afc36732eefaa223123 Mon Sep 17 00:00:00 2001 From: gkc Date: Wed, 27 Mar 2024 16:22:23 +0000 Subject: [PATCH 32/34] test: Increase max_attempts in e2e tests from 3 (2 retries) to 5 (4 retries). atServers need to get more reliable --- .github/workflows/e2e_all.yaml | 2 -- tests/e2e_all/scripts/common/run_tests.sh | 2 +- 2 files changed, 1 insertion(+), 3 deletions(-) diff --git a/.github/workflows/e2e_all.yaml b/.github/workflows/e2e_all.yaml index 062c0209f..ce9a018aa 100644 --- a/.github/workflows/e2e_all.yaml +++ b/.github/workflows/e2e_all.yaml @@ -39,6 +39,4 @@ jobs: echo "Running git checkout -f $SHA" git checkout -f "$SHA" echo "Running tests" - SRV_LOG_TO_TMP="true" - export SRV_LOG_TO_TMP tests/e2e_all/scripts/main.sh @apricoteventual @combinedbelgian @rv_am diff --git a/tests/e2e_all/scripts/common/run_tests.sh b/tests/e2e_all/scripts/common/run_tests.sh index 656c8a19f..af4c86fab 100755 --- a/tests/e2e_all/scripts/common/run_tests.sh +++ b/tests/e2e_all/scripts/common/run_tests.sh @@ -51,7 +51,7 @@ do export DAEMON_LOG_FRAGMENT_NAME exitStatus=1 - maxAttempts=3 + maxAttempts=5 if [[ $(uname -s) == "Darwin" ]]; then maxAttempts=2 fi From 2a6e94953260f9f6ba695df4c275b00b2f74fd51 Mon Sep 17 00:00:00 2001 From: gkc Date: Wed, 27 Mar 2024 16:37:39 +0000 Subject: [PATCH 33/34] test: Modify scripts/tests/shared/sshnp script to capture the relevant daemon logs for this test --- tests/e2e_all/scripts/common/stop_daemons.sh | 7 +++++++ tests/e2e_all/scripts/tests/shared/sshnp | 13 ++++++++++++- 2 files changed, 19 insertions(+), 1 deletion(-) diff --git a/tests/e2e_all/scripts/common/stop_daemons.sh b/tests/e2e_all/scripts/common/stop_daemons.sh index 937d332de..32a0c183f 100755 --- a/tests/e2e_all/scripts/common/stop_daemons.sh +++ b/tests/e2e_all/scripts/common/stop_daemons.sh @@ -23,3 +23,10 @@ do kill "$pid" fi done + +for pid in $(pgrep -f "tail .*/tmp/e2e_all/.*/daemons") +do + processInfo=$(ps -ef | grep " $pid " | grep -v grep) + echo "Killing $processInfo" + kill "$pid" +done diff --git a/tests/e2e_all/scripts/tests/shared/sshnp b/tests/e2e_all/scripts/tests/shared/sshnp index 71dd9acd7..851c934a0 100755 --- a/tests/e2e_all/scripts/tests/shared/sshnp +++ b/tests/e2e_all/scripts/tests/shared/sshnp @@ -100,6 +100,12 @@ esac # Let's put together the sshnp command we will execute sshnpCommand="$baseSshnpCommand -s ${identityFilename}.pub ${additionalSshnpFlags} " +# We will capture daemon log from now until end of test +outputDir=$(getOutputDir) +daemonLogFile="${outputDir}/daemons/${deviceName}.log" +tail -f -n 0 "$daemonLogFile" >> "$DAEMON_LOG_FRAGMENT_NAME" & +tailPid=$! # We'll kill this later + # Finally, let's run the sshnp and ssh session case "$executionType" in "print") @@ -107,6 +113,7 @@ case "$executionType" in if [[ $(versionIsAtLeast "$clientVersion" "d:5.0.0") == "true" ]] && [[ $(versionIsLessThan "$clientVersion" "d:5.1.0") == "true" ]]; then logInfoAndReport " N/A because of bug in client versions 5.0.x which prevent running except with a real terminal attached " + kill $tailPid exit 50 # test rig interprets this exit status as 'test was not applicable' fi echo "$(iso8601Date) | Executing $sshnpCommand" | tee -a "$(getReportFile)" @@ -118,6 +125,7 @@ case "$executionType" in # 2. Check the exit status sshnpExitStatus=$? if (( sshnpExitStatus != 0 )); then + kill $tailPid exit $sshnpExitStatus fi @@ -126,9 +134,11 @@ case "$executionType" in # 3. Execute the sshCommand # shellcheck disable=SC2091 $(getTestSshCommand "$sshCommand") + sshExitStatus=$? # 4. Exit with the exit status of the ssh command - exit $? + kill $tailPid + exit $sshExitStatus ;; "inline") @@ -146,6 +156,7 @@ case "$executionType" in if (( retCode == 0 )); then echo 'sshnp.expect TEST PASSED' fi + kill $tailPid exit $retCode ;; *) From 8eb9eceaebd22575e120564dee0be3bef0a1a59f Mon Sep 17 00:00:00 2001 From: gkc Date: Wed, 27 Mar 2024 16:47:16 +0000 Subject: [PATCH 34/34] test: chore: clean up some output --- tests/e2e_all/scripts/main.sh | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/tests/e2e_all/scripts/main.sh b/tests/e2e_all/scripts/main.sh index c2544ed70..59ed6a46e 100755 --- a/tests/e2e_all/scripts/main.sh +++ b/tests/e2e_all/scripts/main.sh @@ -124,7 +124,7 @@ done if test "$testsToRun" = "all"; then # shellcheck disable=SC2010 testsToRun=$(ls -1 "$testScriptsDir/tests" | grep -v "^noop$" | grep -v "^shared$") - logInfo "Will run all tests: $testsToRun" + logInfo "Will run all tests: $(tr -d "\n" <<< "$testsToRun")" fi export atDirectoryHost @@ -161,7 +161,7 @@ export testRuntimeDir "$testScriptsDir/common/cleanup_tmp_files.sh" -s -logInfo " --> will execute setup_binaries, start_daemons and tests [$testsToRun] with " +logInfo " --> will execute setup_binaries, start_daemons and run_tests with " logInfo " testRootDir: $testRootDir" logInfo " testRuntimeDir: $testRuntimeDir" logInfo " testScriptsDir: $testScriptsDir" @@ -170,7 +170,7 @@ logInfo " atDirectoryHost: $atDirectoryHost" logInfo " daemonVersions: $daemonVersions" logInfo " clientVersions: $clientVersions" logInfo " commitId: $commitId" -logInfo " testsToRun: $testsToRun" +logInfo " testsToRun: $(tr -d "\n" <<< "$testsToRun")" echo logInfo "Calling setup_binaries.sh"