More resilient stdout parsing of dialer stdout (#224)

* More resilient stdout parsing of dialer stdout

* Add another test case

* Handle JS cases where timings aren't the only thing on stdout
This commit is contained in:
Marco Munizaga 2023-07-13 12:14:43 -07:00 committed by GitHub
parent f954fd8522
commit fff587f66f
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
3 changed files with 111 additions and 9 deletions

View File

@ -4,7 +4,7 @@
"description": "Tests libp2p implementations against each other across various dimensions.",
"main": "testplans.ts",
"scripts": {
"test": "ts-node testplans.ts",
"test": "ts-node src/compose-stdout-helper.ts && ts-node testplans.ts",
"renderResults": "ts-node renderResults.ts",
"cache": "ts-node helpers/cache.ts"
},

View File

@ -4,8 +4,9 @@ import path from 'path';
import { exec as execStd } from 'child_process';
import util from 'util';
import { env } from 'process';
import { ComposeSpecification, PropertiesServices } from "../compose-spec/compose-spec"
import { ComposeSpecification, PropertiesServices } from "../compose-spec/compose-spec";
import { stringify } from 'yaml';
import { dialerStdout, dialerTimings } from './compose-stdout-helper';
const exec = util.promisify(execStd);
const timeoutSecs = 3 * 60
@ -35,7 +36,7 @@ export async function run(namespace: string, compose: ComposeSpecification, opts
// Create compose.yaml file
// Some docker compose environments don't like the name field to have special characters
const sanitizedComposeName = compose?.name.replace(/[^a-zA-Z0-9_-]/g, "_")
await fs.writeFile(path.join(dir, "compose.yaml"), stringify({...compose, name: sanitizedComposeName}))
await fs.writeFile(path.join(dir, "compose.yaml"), stringify({ ...compose, name: sanitizedComposeName }))
const upFlags: Array<string> = []
if (opts.up.exitCodeFrom) {
@ -51,15 +52,11 @@ export async function run(namespace: string, compose: ComposeSpecification, opts
const { signal } = controller;
const { stdout, stderr } = await exec(`docker compose -f ${path.join(dir, "compose.yaml")} up ${upFlags.join(" ")}`, { signal })
clearTimeout(timeoutId)
const testResults = stdout.match(/.*dialer.*({.*)/)
if (testResults === null || testResults.length < 2) {
throw new Error("Test JSON results not found")
}
try {
const testResultsParsed = JSON.parse(testResults[1])
const testResultsParsed = dialerTimings(dialerStdout(stdout))
console.log("Finished:", namespace, testResultsParsed)
} catch (e) {
console.log("Failed to parse test results:", testResults[1])
console.log("Failed to parse test results.")
console.log("stdout:")
console.log(stdout)
console.log("")

View File

@ -0,0 +1,105 @@
// Helpers for parsing stdout from docker-compose. Includes tests that are run if you run this file directly.
// Given Compose stdout, return Dialer stdout
export function dialerStdout(composeStdout: string): string {
let dialerLines = composeStdout.split("\n").filter(line => line.includes("dialer"))
dialerLines = dialerLines.filter(line => !line.includes("exited with code"))
dialerLines = dialerLines.filter(line => line.includes("|"))
dialerLines = dialerLines.map(line => {
const [preLine, ...rest] = line.split("|")
return rest.join("|")
})
return dialerLines.join("\n")
}
export function dialerTimings(dialerStdout: string): Object {
const openBracket = dialerStdout.indexOf("{")
if (openBracket === -1) throw new Error("Invalid JSON. No opening curly bracket found")
const closeBracket = dialerStdout.indexOf("}", openBracket)
if (closeBracket === -1) throw new Error("Invalid JSON. No closing curly bracket found")
return JSON.parse(dialerStdout.substring(openBracket, closeBracket + 1))
}
// simple test case - avoids bringing in a whole test framework
function test() {
const assert = (b: boolean) => { if (!b) throw new Error("assertion failed") }
{
// This came up in CI, not sure why compose split these lines up. Nothing else was using stdout
const exampleComposeStdout = `
2023-07-05T20:53:32.7346588Z Attaching to zig-v0_0_1_x_zig-v0_0_1__quic-v1_-dialer-1, zig-v0_0_1_x_zig-v0_0_1__quic-v1_-listener-1, zig-v0_0_1_x_zig-v0_0_1__quic-v1_-redis-1
2023-07-05T20:53:32.7347413Z zig-v0_0_1_x_zig-v0_0_1__quic-v1_-redis-1 | 1:C 05 Jul 2023 20:53:31.482 # oO0OoO0OoO0Oo Redis is starting oO0OoO0OoO0Oo
2023-07-05T20:53:32.7348271Z zig-v0_0_1_x_zig-v0_0_1__quic-v1_-redis-1 | 1:C 05 Jul 2023 20:53:31.482 # Redis version=7.0.11, bits=64, commit=00000000, modified=0, pid=1, just started
2023-07-05T20:53:32.7349285Z zig-v0_0_1_x_zig-v0_0_1__quic-v1_-redis-1 | 1:C 05 Jul 2023 20:53:31.482 # Warning: no config file specified, using the default config. In order to specify a config file use redis-server /path/to/redis.conf
2023-07-05T20:53:32.7350098Z zig-v0_0_1_x_zig-v0_0_1__quic-v1_-redis-1 | 1:M 05 Jul 2023 20:53:31.483 * monotonic clock: POSIX clock_gettime
2023-07-05T20:53:32.7350785Z zig-v0_0_1_x_zig-v0_0_1__quic-v1_-redis-1 | 1:M 05 Jul 2023 20:53:31.483 * Running mode=standalone, port=6379.
2023-07-05T20:53:32.7351427Z zig-v0_0_1_x_zig-v0_0_1__quic-v1_-redis-1 | 1:M 05 Jul 2023 20:53:31.483 # Server initialized
2023-07-05T20:53:32.7353510Z zig-v0_0_1_x_zig-v0_0_1__quic-v1_-redis-1 | 1:M 05 Jul 2023 20:53:31.483 # WARNING Memory overcommit must be enabled! Without it, a background save or replication may fail under low memory condition. Being disabled, it can can also cause failures without low memory condition, see https://github.com/jemalloc/jemalloc/issues/1328. To fix this issue add 'vm.overcommit_memory = 1' to /etc/sysctl.conf and then reboot or run the command 'sysctl vm.overcommit_memory=1' for this to take effect.
2023-07-05T20:53:32.7354714Z zig-v0_0_1_x_zig-v0_0_1__quic-v1_-redis-1 | 1:M 05 Jul 2023 20:53:31.483 * Ready to accept connections
2023-07-05T20:53:32.7355190Z zig-v0_0_1_x_zig-v0_0_1__quic-v1_-dialer-1 | {
2023-07-05T20:53:32.7355819Z zig-v0_0_1_x_zig-v0_0_1__quic-v1_-dialer-1 | "handshakePlusOneRTTMillis": 7.342, "pingRTTMilllis": 7.113}
2023-07-05T20:53:32.7356363Z zig-v0_0_1_x_zig-v0_0_1__quic-v1_-dialer-1 exited with code 0
`
const expectedParsed = JSON.stringify({ "handshakePlusOneRTTMillis": 7.342, "pingRTTMilllis": 7.113 })
assert(JSON.stringify(JSON.parse(dialerStdout(exampleComposeStdout))) === expectedParsed)
assert(JSON.stringify(dialerTimings(dialerStdout(exampleComposeStdout))) === expectedParsed)
}
{
const exampleComposeStdout = `2023-07-05T22:41:18.8080447Z Attaching to zig-v0_0_1_x_zig-v0_0_1__quic-v1_-dialer-1, zig-v0_0_1_x_zig-v0_0_1__quic-v1_-listener-1, zig-v0_0_1_x_zig-v0_0_1__quic-v1_-redis-1
2023-07-05T22:41:18.8081556Z zig-v0_0_1_x_zig-v0_0_1__quic-v1_-redis-1 | 1:C 05 Jul 2023 22:41:17.438 # oO0OoO0OoO0Oo Redis is starting oO0OoO0OoO0Oo
2023-07-05T22:41:18.8082800Z zig-v0_0_1_x_zig-v0_0_1__quic-v1_-redis-1 | 1:C 05 Jul 2023 22:41:17.438 # Redis version=7.0.11, bits=64, commit=00000000, modified=0, pid=1, just started
2023-07-05T22:41:18.8184401Z zig-v0_0_1_x_zig-v0_0_1__quic-v1_-redis-1 | 1:C 05 Jul 2023 22:41:17.438 # Warning: no config file specified, using the default config. In order to specify a config file use redis-server /path/to/redis.conf
2023-07-05T22:41:18.8185351Z zig-v0_0_1_x_zig-v0_0_1__quic-v1_-redis-1 | 1:M 05 Jul 2023 22:41:17.439 * monotonic clock: POSIX clock_gettime
2023-07-05T22:41:18.8186133Z zig-v0_0_1_x_zig-v0_0_1__quic-v1_-redis-1 | 1:M 05 Jul 2023 22:41:17.439 * Running mode=standalone, port=6379.
2023-07-05T22:41:18.8186846Z zig-v0_0_1_x_zig-v0_0_1__quic-v1_-redis-1 | 1:M 05 Jul 2023 22:41:17.439 # Server initialized
2023-07-05T22:41:18.8188914Z zig-v0_0_1_x_zig-v0_0_1__quic-v1_-redis-1 | 1:M 05 Jul 2023 22:41:17.439 # WARNING Memory overcommit must be enabled! Without it, a background save or replication may fail under low memory condition. Being disabled, it can can also cause failures without low memory condition, see https://github.com/jemalloc/jemalloc/issues/1328. To fix this issue add 'vm.overcommit_memory = 1' to /etc/sysctl.conf and then reboot or run the command 'sysctl vm.overcommit_memory=1' for this to take effect.
2023-07-05T22:41:18.8190173Z zig-v0_0_1_x_zig-v0_0_1__quic-v1_-redis-1 | 1:M 05 Jul 2023 22:41:17.439 * Ready to accept connections
2023-07-05T22:41:18.8190833Z zig-v0_0_1_x_zig-v0_0_1__quic-v1_-dialer-1 | {"handshakePlusOneRTTMillis":
2023-07-05T22:41:18.8191389Z zig-v0_0_1_x_zig-v0_0_1__quic-v1_-dialer-1 | 8.849
2023-07-05T22:41:18.8191930Z zig-v0_0_1_x_zig-v0_0_1__quic-v1_-dialer-1 | , "pingRTTMilllis":
2023-07-05T22:41:18.8192455Z zig-v0_0_1_x_zig-v0_0_1__quic-v1_-dialer-1 | 7.897}
2023-07-05T22:41:18.8192987Z zig-v0_0_1_x_zig-v0_0_1__quic-v1_-dialer-1 exited with code 0`
const expectedParsed = JSON.stringify({ "handshakePlusOneRTTMillis": 8.849, "pingRTTMilllis": 7.897 })
assert(JSON.stringify(JSON.parse(dialerStdout(exampleComposeStdout))) === expectedParsed)
assert(JSON.stringify(dialerTimings(dialerStdout(exampleComposeStdout))) === expectedParsed)
}
{
const exampleComposeStdout = `
2023-07-06T00:36:52.6198781Z firefox-js-v0_45_x_firefox-js-v0_45__webrtc__noise__yamux_-redis-1 | 1:M 06 Jul 2023 00:36:19.136 * Ready to accept connections
2023-07-06T00:36:52.6199494Z firefox-js-v0_45_x_firefox-js-v0_45__webrtc__noise__yamux_-listener-1 |
2023-07-06T00:36:52.6200270Z firefox-js-v0_45_x_firefox-js-v0_45__webrtc__noise__yamux_-listener-1 | > multidim-interop@1.0.0 test
2023-07-06T00:36:52.6201247Z firefox-js-v0_45_x_firefox-js-v0_45__webrtc__noise__yamux_-listener-1 | > aegir test --build false --types false -t browser -- --browser firefox
2023-07-06T00:36:52.6202009Z firefox-js-v0_45_x_firefox-js-v0_45__webrtc__noise__yamux_-listener-1 |
2023-07-06T00:36:52.6202659Z firefox-js-v0_45_x_firefox-js-v0_45__webrtc__noise__yamux_-listener-1 |
2023-07-06T00:36:52.6203296Z firefox-js-v0_45_x_firefox-js-v0_45__webrtc__noise__yamux_-dialer-1 |
2023-07-06T00:36:52.6204045Z firefox-js-v0_45_x_firefox-js-v0_45__webrtc__noise__yamux_-dialer-1 | > multidim-interop@1.0.0 test
2023-07-06T00:36:52.6205016Z firefox-js-v0_45_x_firefox-js-v0_45__webrtc__noise__yamux_-dialer-1 | > aegir test --build false --types false -t browser -- --browser firefox
2023-07-06T00:36:52.6205760Z firefox-js-v0_45_x_firefox-js-v0_45__webrtc__noise__yamux_-dialer-1 |
2023-07-06T00:36:52.6206397Z firefox-js-v0_45_x_firefox-js-v0_45__webrtc__noise__yamux_-dialer-1 |
2023-07-06T00:36:52.6207074Z firefox-js-v0_45_x_firefox-js-v0_45__webrtc__noise__yamux_-listener-1 | test browser
2023-07-06T00:36:52.6207782Z firefox-js-v0_45_x_firefox-js-v0_45__webrtc__noise__yamux_-dialer-1 | test browser
2023-07-06T00:36:52.6208473Z firefox-js-v0_45_x_firefox-js-v0_45__webrtc__noise__yamux_-dialer-1 | 
2023-07-06T00:36:52.6209191Z firefox-js-v0_45_x_firefox-js-v0_45__webrtc__noise__yamux_-dialer-1 |  ping test
2023-07-06T00:36:52.6209998Z firefox-js-v0_45_x_firefox-js-v0_45__webrtc__noise__yamux_-dialer-1 |  - should listen for ping
2023-07-06T00:36:52.6210724Z firefox-js-v0_45_x_firefox-js-v0_45__webrtc__noise__yamux_-listener-1 | 
2023-07-06T00:36:52.6211440Z firefox-js-v0_45_x_firefox-js-v0_45__webrtc__noise__yamux_-listener-1 |  ping test
2023-07-06T00:36:52.6212401Z firefox-js-v0_45_x_firefox-js-v0_45__webrtc__noise__yamux_-dialer-1 | {"handshakePlusOneRTTMillis":4155,"pingRTTMilllis":781}
2023-07-06T00:36:52.6213383Z firefox-js-v0_45_x_firefox-js-v0_45__webrtc__noise__yamux_-dialer-1 |   should dial and ping (5939ms)
2023-07-06T00:36:52.6214272Z firefox-js-v0_45_x_firefox-js-v0_45__webrtc__noise__yamux_-dialer-1 |   1 passing (7s)
2023-07-06T00:36:52.6214968Z firefox-js-v0_45_x_firefox-js-v0_45__webrtc__noise__yamux_-dialer-1 |   1 pending
2023-07-06T00:36:52.6215606Z firefox-js-v0_45_x_firefox-js-v0_45__webrtc__noise__yamux_-dialer-1 exited with code 0`
const expectedParsed = JSON.stringify({ "handshakePlusOneRTTMillis": 4155, "pingRTTMilllis": 781 })
assert(JSON.stringify(dialerTimings(dialerStdout(exampleComposeStdout))) === expectedParsed)
}
}
if (typeof require !== 'undefined' && require.main === module) {
// Run the test case if this file is run directly.
test();
}