From f2d08ea3cd0cef14e5154c5c3a8ee3c7e04f2052 Mon Sep 17 00:00:00 2001 From: Russ <8377044+rdubrock@users.noreply.github.com> Date: Wed, 1 Nov 2023 12:13:21 -0800 Subject: [PATCH 1/4] make the k6 runner timeout configurable --- internal/k6runner/k6runner.go | 27 ++++++++++++--------- internal/k6runner/k6runner_test.go | 11 +++++---- internal/prober/k6/k6.go | 5 ++-- internal/prober/k6/k6_test.go | 2 +- internal/prober/multihttp/multihttp.go | 5 ++-- internal/prober/multihttp/multihttp_test.go | 2 +- internal/prober/multihttp/script_test.go | 5 ++-- internal/scraper/scraper_test.go | 2 +- 8 files changed, 33 insertions(+), 26 deletions(-) diff --git a/internal/k6runner/k6runner.go b/internal/k6runner/k6runner.go index 67faedbc..848dcf3c 100644 --- a/internal/k6runner/k6runner.go +++ b/internal/k6runner/k6runner.go @@ -23,7 +23,7 @@ import ( type Runner interface { WithLogger(logger *zerolog.Logger) Runner - Run(ctx context.Context, script []byte) (*RunResponse, error) + Run(ctx context.Context, script []byte, timeout time.Duration) (*RunResponse, error) } func New(uri string) Runner { @@ -47,14 +47,16 @@ func New(uri string) Runner { } type Script struct { - runner Runner - script []byte + runner Runner + script []byte + timeout time.Duration } -func NewScript(script []byte, k6runner Runner) (*Script, error) { +func NewScript(script []byte, k6runner Runner, timeout time.Duration) (*Script, error) { r := Script{ - runner: k6runner, - script: script, + runner: k6runner, + script: script, + timeout: timeout, } return &r, nil @@ -63,7 +65,7 @@ func NewScript(script []byte, k6runner Runner) (*Script, error) { func (r Script) Run(ctx context.Context, registry *prometheus.Registry, logger logger.Logger, internalLogger zerolog.Logger) (bool, error) { k6runner := r.runner.WithLogger(&internalLogger) - result, err := k6runner.Run(ctx, r.script) + result, err := k6runner.Run(ctx, r.script, r.timeout) if err != nil { internalLogger.Debug(). Err(err). @@ -270,7 +272,8 @@ func (r requestError) Error() string { } type RunRequest struct { - Script []byte `json:"script"` + Script []byte `json:"script"` + Timeout time.Duration `json:"timeout"` } type RunResponse struct { @@ -285,9 +288,10 @@ func (r HttpRunner) WithLogger(logger *zerolog.Logger) Runner { } } -func (r HttpRunner) Run(ctx context.Context, script []byte) (*RunResponse, error) { +func (r HttpRunner) Run(ctx context.Context, script []byte, timeout time.Duration) (*RunResponse, error) { req, err := json.Marshal(&RunRequest{ - Script: script, + Script: script, + Timeout: timeout, }) if err != nil { return nil, fmt.Errorf("running script: %w", err) @@ -343,7 +347,7 @@ func (r LocalRunner) WithLogger(logger *zerolog.Logger) Runner { } } -func (r LocalRunner) Run(ctx context.Context, script []byte) (*RunResponse, error) { +func (r LocalRunner) Run(ctx context.Context, script []byte, timeout time.Duration) (*RunResponse, error) { afs := afero.Afero{Fs: r.fs} workdir, err := afs.TempDir("", "k6-runner") @@ -381,7 +385,6 @@ func (r LocalRunner) Run(ctx context.Context, script []byte) (*RunResponse, erro return nil, fmt.Errorf("cannot find k6 executable: %w", err) } - timeout := 10 * time.Second // TODO(mem): make this configurable ctx, cancel := context.WithTimeout(ctx, timeout) defer cancel() diff --git a/internal/k6runner/k6runner_test.go b/internal/k6runner/k6runner_test.go index a54de693..0bea8f70 100644 --- a/internal/k6runner/k6runner_test.go +++ b/internal/k6runner/k6runner_test.go @@ -11,6 +11,7 @@ import ( "sort" "strings" "testing" + "time" "github.com/grafana/synthetic-monitoring-agent/internal/prober/logger" "github.com/grafana/synthetic-monitoring-agent/internal/testhelper" @@ -35,7 +36,7 @@ func TestNew(t *testing.T) { func TestNewScript(t *testing.T) { runner := New("k6") src := []byte("test") - script, err := NewScript(src, runner) + script, err := NewScript(src, runner, 10*time.Second) require.NoError(t, err) require.NotNil(t, script) require.Equal(t, src, script.script) @@ -48,7 +49,7 @@ func TestScriptRun(t *testing.T) { logs: testhelper.MustReadFile(t, "testdata/test.log"), } - script, err := NewScript(testhelper.MustReadFile(t, "testdata/test.js"), &runner) + script, err := NewScript(testhelper.MustReadFile(t, "testdata/test.js"), &runner, 10*time.Second) require.NoError(t, err) require.NotNil(t, script) @@ -105,7 +106,7 @@ func TestHttpRunnerRun(t *testing.T) { ctx, cancel := testhelper.Context(context.Background(), t) t.Cleanup(cancel) - _, err := runner.Run(ctx, scriptSrc) + _, err := runner.Run(ctx, scriptSrc, 10*time.Second) require.NoError(t, err) } @@ -140,7 +141,7 @@ func TestHttpRunnerRunError(t *testing.T) { ctx, cancel := testhelper.Context(context.Background(), t) t.Cleanup(cancel) - _, err := runner.Run(ctx, scriptSrc) + _, err := runner.Run(ctx, scriptSrc, 10*time.Second) require.Error(t, err) } @@ -151,7 +152,7 @@ type testRunner struct { var _ Runner = &testRunner{} -func (r *testRunner) Run(ctx context.Context, script []byte) (*RunResponse, error) { +func (r *testRunner) Run(ctx context.Context, script []byte, timeout time.Duration) (*RunResponse, error) { return &RunResponse{ Metrics: r.metrics, Logs: r.logs, diff --git a/internal/prober/k6/k6.go b/internal/prober/k6/k6.go index 3ba5316b..6a1a6011 100644 --- a/internal/prober/k6/k6.go +++ b/internal/prober/k6/k6.go @@ -36,9 +36,10 @@ func NewProber(ctx context.Context, check sm.Check, logger zerolog.Logger, runne } p.config = settingsToModule(check.Settings.K6) - p.config.Timeout = time.Duration(check.Timeout) * time.Millisecond + timeout := time.Duration(check.Timeout) * time.Millisecond + p.config.Timeout = timeout - script, err := k6runner.NewScript(check.Settings.K6.Script, runner) + script, err := k6runner.NewScript(check.Settings.K6.Script, runner, timeout) if err != nil { return p, err } diff --git a/internal/prober/k6/k6_test.go b/internal/prober/k6/k6_test.go index 0d99feba..3b9af0ac 100644 --- a/internal/prober/k6/k6_test.go +++ b/internal/prober/k6/k6_test.go @@ -73,7 +73,7 @@ func (noopRunner) WithLogger(logger *zerolog.Logger) k6runner.Runner { return r } -func (noopRunner) Run(ctx context.Context, script []byte) (*k6runner.RunResponse, error) { +func (noopRunner) Run(ctx context.Context, script []byte, timeout time.Duration) (*k6runner.RunResponse, error) { return &k6runner.RunResponse{}, nil } diff --git a/internal/prober/multihttp/multihttp.go b/internal/prober/multihttp/multihttp.go index d123ca35..f511aed6 100644 --- a/internal/prober/multihttp/multihttp.go +++ b/internal/prober/multihttp/multihttp.go @@ -39,14 +39,15 @@ func NewProber(ctx context.Context, check sm.Check, logger zerolog.Logger, runne } p.config = settingsToModule(check.Settings.Multihttp) - p.config.Timeout = time.Duration(check.Timeout) * time.Millisecond + timeout := time.Duration(check.Timeout) * time.Millisecond + p.config.Timeout = timeout script, err := settingsToScript(check.Settings.Multihttp) if err != nil { return p, err } - k6Script, err := k6runner.NewScript(script, runner) + k6Script, err := k6runner.NewScript(script, runner, timeout) if err != nil { return p, err } diff --git a/internal/prober/multihttp/multihttp_test.go b/internal/prober/multihttp/multihttp_test.go index b89011af..bcf69f37 100644 --- a/internal/prober/multihttp/multihttp_test.go +++ b/internal/prober/multihttp/multihttp_test.go @@ -107,6 +107,6 @@ func (noopRunner) WithLogger(logger *zerolog.Logger) k6runner.Runner { return r } -func (noopRunner) Run(ctx context.Context, script []byte) (*k6runner.RunResponse, error) { +func (noopRunner) Run(ctx context.Context, script []byte, timeout time.Duration) (*k6runner.RunResponse, error) { return &k6runner.RunResponse{}, nil } diff --git a/internal/prober/multihttp/script_test.go b/internal/prober/multihttp/script_test.go index b75e85e0..d8f502d7 100644 --- a/internal/prober/multihttp/script_test.go +++ b/internal/prober/multihttp/script_test.go @@ -796,8 +796,9 @@ func TestSettingsToScript(t *testing.T) { require.NotEmpty(t, actual) check := sm.Check{ - Target: settings.Entries[0].Request.Url, - Job: "test", + Target: settings.Entries[0].Request.Url, + Job: "test", + Timeout: 10000, Settings: sm.CheckSettings{ Multihttp: settings, }, diff --git a/internal/scraper/scraper_test.go b/internal/scraper/scraper_test.go index bac650e1..6ceb61a5 100644 --- a/internal/scraper/scraper_test.go +++ b/internal/scraper/scraper_test.go @@ -1340,7 +1340,7 @@ type testRunner struct { var _ k6runner.Runner = &testRunner{} -func (r *testRunner) Run(ctx context.Context, script []byte) (*k6runner.RunResponse, error) { +func (r *testRunner) Run(ctx context.Context, script []byte, timeout time.Duration) (*k6runner.RunResponse, error) { return &k6runner.RunResponse{ Metrics: r.metrics, Logs: r.logs, From 202e5a4f970b9944ae990030571ae2134a5fcd9a Mon Sep 17 00:00:00 2001 From: "Marcelo E. Magallon" Date: Fri, 3 Nov 2023 12:52:35 -0600 Subject: [PATCH 2/4] Pull timeout out of context When a prober is created it gets a context that has the check's timeout added as the deadline for the context. The timeout is measured between the point where the probe is started and the point where it finishes running. For the MultiHTTP case, we _add_ the k6 start up time to that, because this behavior is consistent with the way the other checks work. Signed-off-by: Marcelo E. Magallon --- internal/k6runner/k6runner.go | 33 +++++++++++++-------- internal/k6runner/k6runner_test.go | 11 ++++--- internal/prober/k6/k6.go | 2 +- internal/prober/k6/k6_test.go | 2 +- internal/prober/multihttp/multihttp.go | 2 +- internal/prober/multihttp/multihttp_test.go | 2 +- internal/scraper/scraper_test.go | 2 +- 7 files changed, 30 insertions(+), 24 deletions(-) diff --git a/internal/k6runner/k6runner.go b/internal/k6runner/k6runner.go index 848dcf3c..72131015 100644 --- a/internal/k6runner/k6runner.go +++ b/internal/k6runner/k6runner.go @@ -23,7 +23,7 @@ import ( type Runner interface { WithLogger(logger *zerolog.Logger) Runner - Run(ctx context.Context, script []byte, timeout time.Duration) (*RunResponse, error) + Run(ctx context.Context, script []byte) (*RunResponse, error) } func New(uri string) Runner { @@ -52,11 +52,10 @@ type Script struct { timeout time.Duration } -func NewScript(script []byte, k6runner Runner, timeout time.Duration) (*Script, error) { +func NewScript(script []byte, k6runner Runner) (*Script, error) { r := Script{ - runner: k6runner, - script: script, - timeout: timeout, + runner: k6runner, + script: script, } return &r, nil @@ -65,7 +64,7 @@ func NewScript(script []byte, k6runner Runner, timeout time.Duration) (*Script, func (r Script) Run(ctx context.Context, registry *prometheus.Registry, logger logger.Logger, internalLogger zerolog.Logger) (bool, error) { k6runner := r.runner.WithLogger(&internalLogger) - result, err := k6runner.Run(ctx, r.script, r.timeout) + result, err := k6runner.Run(ctx, r.script) if err != nil { internalLogger.Debug(). Err(err). @@ -272,8 +271,8 @@ func (r requestError) Error() string { } type RunRequest struct { - Script []byte `json:"script"` - Timeout time.Duration `json:"timeout"` + Script []byte `json:"script"` + Timeout int64 `json:"timeout"` } type RunResponse struct { @@ -288,10 +287,10 @@ func (r HttpRunner) WithLogger(logger *zerolog.Logger) Runner { } } -func (r HttpRunner) Run(ctx context.Context, script []byte, timeout time.Duration) (*RunResponse, error) { +func (r HttpRunner) Run(ctx context.Context, script []byte) (*RunResponse, error) { req, err := json.Marshal(&RunRequest{ Script: script, - Timeout: timeout, + Timeout: getTimeout(ctx).Milliseconds(), }) if err != nil { return nil, fmt.Errorf("running script: %w", err) @@ -347,7 +346,7 @@ func (r LocalRunner) WithLogger(logger *zerolog.Logger) Runner { } } -func (r LocalRunner) Run(ctx context.Context, script []byte, timeout time.Duration) (*RunResponse, error) { +func (r LocalRunner) Run(ctx context.Context, script []byte) (*RunResponse, error) { afs := afero.Afero{Fs: r.fs} workdir, err := afs.TempDir("", "k6-runner") @@ -385,8 +384,7 @@ func (r LocalRunner) Run(ctx context.Context, script []byte, timeout time.Durati return nil, fmt.Errorf("cannot find k6 executable: %w", err) } - ctx, cancel := context.WithTimeout(ctx, timeout) - defer cancel() + timeout := getTimeout(ctx) // #nosec G204 -- the variables are not user-controlled cmd := exec.CommandContext( @@ -466,3 +464,12 @@ func mktemp(fs afero.Fs, dir, pattern string) (string, error) { } return f.Name(), nil } + +func getTimeout(ctx context.Context) time.Duration { + deadline, ok := ctx.Deadline() + if !ok { + return 10 * time.Second + } + + return time.Until(deadline) +} diff --git a/internal/k6runner/k6runner_test.go b/internal/k6runner/k6runner_test.go index 0bea8f70..a54de693 100644 --- a/internal/k6runner/k6runner_test.go +++ b/internal/k6runner/k6runner_test.go @@ -11,7 +11,6 @@ import ( "sort" "strings" "testing" - "time" "github.com/grafana/synthetic-monitoring-agent/internal/prober/logger" "github.com/grafana/synthetic-monitoring-agent/internal/testhelper" @@ -36,7 +35,7 @@ func TestNew(t *testing.T) { func TestNewScript(t *testing.T) { runner := New("k6") src := []byte("test") - script, err := NewScript(src, runner, 10*time.Second) + script, err := NewScript(src, runner) require.NoError(t, err) require.NotNil(t, script) require.Equal(t, src, script.script) @@ -49,7 +48,7 @@ func TestScriptRun(t *testing.T) { logs: testhelper.MustReadFile(t, "testdata/test.log"), } - script, err := NewScript(testhelper.MustReadFile(t, "testdata/test.js"), &runner, 10*time.Second) + script, err := NewScript(testhelper.MustReadFile(t, "testdata/test.js"), &runner) require.NoError(t, err) require.NotNil(t, script) @@ -106,7 +105,7 @@ func TestHttpRunnerRun(t *testing.T) { ctx, cancel := testhelper.Context(context.Background(), t) t.Cleanup(cancel) - _, err := runner.Run(ctx, scriptSrc, 10*time.Second) + _, err := runner.Run(ctx, scriptSrc) require.NoError(t, err) } @@ -141,7 +140,7 @@ func TestHttpRunnerRunError(t *testing.T) { ctx, cancel := testhelper.Context(context.Background(), t) t.Cleanup(cancel) - _, err := runner.Run(ctx, scriptSrc, 10*time.Second) + _, err := runner.Run(ctx, scriptSrc) require.Error(t, err) } @@ -152,7 +151,7 @@ type testRunner struct { var _ Runner = &testRunner{} -func (r *testRunner) Run(ctx context.Context, script []byte, timeout time.Duration) (*RunResponse, error) { +func (r *testRunner) Run(ctx context.Context, script []byte) (*RunResponse, error) { return &RunResponse{ Metrics: r.metrics, Logs: r.logs, diff --git a/internal/prober/k6/k6.go b/internal/prober/k6/k6.go index 6a1a6011..492f1800 100644 --- a/internal/prober/k6/k6.go +++ b/internal/prober/k6/k6.go @@ -39,7 +39,7 @@ func NewProber(ctx context.Context, check sm.Check, logger zerolog.Logger, runne timeout := time.Duration(check.Timeout) * time.Millisecond p.config.Timeout = timeout - script, err := k6runner.NewScript(check.Settings.K6.Script, runner, timeout) + script, err := k6runner.NewScript(check.Settings.K6.Script, runner) if err != nil { return p, err } diff --git a/internal/prober/k6/k6_test.go b/internal/prober/k6/k6_test.go index 3b9af0ac..0d99feba 100644 --- a/internal/prober/k6/k6_test.go +++ b/internal/prober/k6/k6_test.go @@ -73,7 +73,7 @@ func (noopRunner) WithLogger(logger *zerolog.Logger) k6runner.Runner { return r } -func (noopRunner) Run(ctx context.Context, script []byte, timeout time.Duration) (*k6runner.RunResponse, error) { +func (noopRunner) Run(ctx context.Context, script []byte) (*k6runner.RunResponse, error) { return &k6runner.RunResponse{}, nil } diff --git a/internal/prober/multihttp/multihttp.go b/internal/prober/multihttp/multihttp.go index f511aed6..0bfeb3b5 100644 --- a/internal/prober/multihttp/multihttp.go +++ b/internal/prober/multihttp/multihttp.go @@ -47,7 +47,7 @@ func NewProber(ctx context.Context, check sm.Check, logger zerolog.Logger, runne return p, err } - k6Script, err := k6runner.NewScript(script, runner, timeout) + k6Script, err := k6runner.NewScript(script, runner) if err != nil { return p, err } diff --git a/internal/prober/multihttp/multihttp_test.go b/internal/prober/multihttp/multihttp_test.go index bcf69f37..b89011af 100644 --- a/internal/prober/multihttp/multihttp_test.go +++ b/internal/prober/multihttp/multihttp_test.go @@ -107,6 +107,6 @@ func (noopRunner) WithLogger(logger *zerolog.Logger) k6runner.Runner { return r } -func (noopRunner) Run(ctx context.Context, script []byte, timeout time.Duration) (*k6runner.RunResponse, error) { +func (noopRunner) Run(ctx context.Context, script []byte) (*k6runner.RunResponse, error) { return &k6runner.RunResponse{}, nil } diff --git a/internal/scraper/scraper_test.go b/internal/scraper/scraper_test.go index 6ceb61a5..bac650e1 100644 --- a/internal/scraper/scraper_test.go +++ b/internal/scraper/scraper_test.go @@ -1340,7 +1340,7 @@ type testRunner struct { var _ k6runner.Runner = &testRunner{} -func (r *testRunner) Run(ctx context.Context, script []byte, timeout time.Duration) (*k6runner.RunResponse, error) { +func (r *testRunner) Run(ctx context.Context, script []byte) (*k6runner.RunResponse, error) { return &k6runner.RunResponse{ Metrics: r.metrics, Logs: r.logs, From 2cb9597500f6e141ce272b9f11554c2af1ee173c Mon Sep 17 00:00:00 2001 From: "Marcelo E. Magallon" Date: Fri, 3 Nov 2023 13:18:47 -0600 Subject: [PATCH 3/4] Remove dead code Signed-off-by: Marcelo E. Magallon --- internal/k6runner/k6runner.go | 5 ++--- 1 file changed, 2 insertions(+), 3 deletions(-) diff --git a/internal/k6runner/k6runner.go b/internal/k6runner/k6runner.go index 72131015..0d261e44 100644 --- a/internal/k6runner/k6runner.go +++ b/internal/k6runner/k6runner.go @@ -47,9 +47,8 @@ func New(uri string) Runner { } type Script struct { - runner Runner - script []byte - timeout time.Duration + runner Runner + script []byte } func NewScript(script []byte, k6runner Runner) (*Script, error) { From 645d28aa5c79598e4cbdaa2d97fd5b0bba740943 Mon Sep 17 00:00:00 2001 From: "Marcelo E. Magallon" Date: Fri, 3 Nov 2023 14:59:06 -0600 Subject: [PATCH 4/4] Add simple test to make sure that the runner is setting the timeout Signed-off-by: Marcelo E. Magallon --- internal/k6runner/k6runner_test.go | 20 +++++++++++++++++++- 1 file changed, 19 insertions(+), 1 deletion(-) diff --git a/internal/k6runner/k6runner_test.go b/internal/k6runner/k6runner_test.go index a54de693..253c5aae 100644 --- a/internal/k6runner/k6runner_test.go +++ b/internal/k6runner/k6runner_test.go @@ -11,6 +11,7 @@ import ( "sort" "strings" "testing" + "time" "github.com/grafana/synthetic-monitoring-agent/internal/prober/logger" "github.com/grafana/synthetic-monitoring-agent/internal/testhelper" @@ -72,6 +73,7 @@ func TestScriptRun(t *testing.T) { func TestHttpRunnerRun(t *testing.T) { scriptSrc := testhelper.MustReadFile(t, "testdata/test.js") + timeout := 1 * time.Second mux := http.NewServeMux() mux.HandleFunc("/run", func(w http.ResponseWriter, r *http.Request) { @@ -82,6 +84,15 @@ func TestHttpRunnerRun(t *testing.T) { err := json.NewDecoder(r.Body).Decode(&req) require.NoError(t, err) require.Equal(t, scriptSrc, req.Script) + // The timeout in the request is not going to be exactly the + // original timeout because computers need some time to process + // data, and the timeout is set based on the remaining time + // until the deadline and the clock starts ticking as soon as + // the context is created. Check that the actual timeout is not + // greater than the expected value and that it's within 1% of + // the expected value. + require.LessOrEqual(t, req.Timeout, timeout.Milliseconds()) + require.InEpsilon(t, timeout.Milliseconds(), req.Timeout, 0.01) w.Header().Set("Content-Type", "application/json") w.WriteHeader(http.StatusOK) @@ -102,7 +113,14 @@ func TestHttpRunnerRun(t *testing.T) { runner := New(srv.URL + "/run") require.IsType(t, &HttpRunner{}, runner) - ctx, cancel := testhelper.Context(context.Background(), t) + ctx := context.Background() + ctx, cancel := testhelper.Context(ctx, t) + t.Cleanup(cancel) + + // By adding a timeout to the context passed to Run, the expectation is + // that the runner extracts the timeout from it and sets the + // corresponding field accordingly. + ctx, cancel = context.WithTimeout(ctx, timeout) t.Cleanup(cancel) _, err := runner.Run(ctx, scriptSrc)