Skip to content

More resilient stdout parsing of dialer stdout #224

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
MarcoPolo merged 3 commits into from
Jul 13, 2023
Merged

More resilient stdout parsing of dialer stdout #224

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
80306c5
More resilient stdout parsing of dialer stdout
MarcoPolo Jul 5, 2023
b2e9006
Add another test case
MarcoPolo Jul 5, 2023
e7865dc
Handle JS cases where timings aren't the only thing on stdout
MarcoPolo Jul 6, 2023
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
2 changes: 1 addition & 1 deletion multidim-interop/package.json
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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",
Copy link
Contributor

@thomaseizinger thomaseizinger Jul 6, 2023

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Does shell glob expansion work in here? We could move these files to a tests dir and just run all of them.

Copy link
Contributor

@thomaseizinger thomaseizinger Jul 6, 2023

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

For that, I'd then probably be cleaner to keep the helper in src and just make another small file that runs the function.

Copy link
Contributor Author

@MarcoPolo MarcoPolo Jul 19, 2023

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

That makes sense. Will do this change once we have more than one test file :)

"renderResults": "ts-node renderResults.ts",
"cache": "ts-node helpers/cache.ts"
},
Expand Down
13 changes: 5 additions & 8 deletions multidim-interop/src/compose-runner.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -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) {
Expand All @@ -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("")
Expand Down
105 changes: 105 additions & 0 deletions multidim-interop/src/compose-stdout-helper.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -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 | > [email protected] 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 | > [email protected] 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();
}