Issue when using Xk6-distributed-tracing with xk6-dynatrace-output

Grafana k6 Extensions
1

Hi,

I just build a new extension that sends the k6 statistics into Dynatrace.
To explain the value of K6 I’m creating a dedicated episode on isitobservable. This episode has a dedicated tutorial.
In this tutorial I’m using the experimental dynatrace extensions and the xk6-distributed-tracing extensions.

when i run a test using the core http from ‘k6/http’ or grpc from ‘k6/net/grpc’ ( so without any tracing enabled) then everything is working fine.
But if i run the same test replacing htttp from ‘k6/http’ by { Http } from ‘k6/x/tracing’; i’m getting lots of errors :

time="2022-06-01T07:24:48Z" level=warning msg="Request Failed" error="unknown request body type []goja.Value"
time="2022-06-01T07:24:48Z" level=error msg="panic: runtime error: invalid memory address or nil pointer dereference\ngoroutine 89 [running]:\nruntime/debug.Stack()\n\truntime/debug/stack.go:24 +0x65\[ngo.k6.io/k6/js.(*VU).runFn.func1.1()](ngo.k6.io/k6/js.(*VU).runFn.func1.1())\n\[tgo.k6.io/k6@v0.37.0/js/runner.go:798](go.k6.io/k6@v0.37.0/js/runner.go:798) +0x134\npanic({0xffbd80, 0x1e2c200})\n\truntime/panic.go:1038 +0x215\[ngithub.com/dop251/goja.AssertFunction.func1.1()](github.com/dop251/goja.AssertFunction.func1.1())\n\[tgithub.com/dop251/goja@v0.0.0-20220124171016-cfb079cdc7b4/runtime.go:2285] ( tgithub.com/dop251/goja@v0.0.0-20220124171016-cfb079cdc7b4/runtime.go:2285) +0x6e\npanic({0xffbd80, 0x1e2c200})\n\truntime/panic.go:1038 +0x215\[ngithub.com/dop251/goja.(*vm).try.func1()](github.com/dop251/goja.(*vm).try.func1())\n\[tgithub.com/dop251/goja@v0.0.0-20220124171016-cfb079cdc7b4/vm.go:539](github.com/dop251/goja@v0.0.0-20220124171016-cfb079cdc7b4/vm.go:539) +0x635\npanic({0xffbd80, 0x1e2c200})\n\truntime/panic.go:1038 +0x215\[ngo.opentelemetry.io/otel/sdk/trace.(*span).End](go.opentelemetry.io/otel/sdk/trace.(*span).End)·dwrap·11()\n\[tgo.opentelemetry.io/otel/sdk@v0.20.0/trace/span.go:213](go.opentelemetry.io/otel/sdk@v0.20.0/trace/span.go:213) +0x2a\[ngo.opentelemetry.io/otel/sdk/trace.(*span).End(0xc003b40a80](go.opentelemetry.io/otel/sdk/trace.(*span).End(0xc003b40a80), {0x0, 0x0, 0x0})\n\[tgo.opentelemetry.io/otel/sdk@v0.20.0/trace/span.go:245](go.opentelemetry.io/otel/sdk@v0.20.0/trace/span.go:245) +0x698\npanic({0xffbd80, 0x1e2c200})\n\truntime/panic.go:1038 +0x215\[github.com/grafana/xk6-distributed-tracing/client.(*TracingClient).WithTrace(0x116284b](github.com/grafana/xk6-distributed-tracing/client.(*TracingClient).WithTrace(0x116284b), 0xc001305d80, {0x1167619, 0x8}, {0x13dd000, 0xc002aa08b0}, {0xc002aa08e0, 0x1, 0x1})\n\[tgithub.com/grafana/xk6-distributed-tracing@v0.2.2/client/client.go:85](github.com/grafana/xk6-distributed-tracing@v0.2.2/client/client.go:85) +0x2d3\[ngithub.com/grafana/xk6-distributed-tracing/client.(*TracingClient).Get(0xc001a339c8](github.com/grafana/xk6-distributed-tracing/client.(*TracingClient).Get(0xc001a339c8), {0x13dd000, 0xc002aa08b0}, {0x1e7e570, 0x0, 0x1})\n\[tgithub.com/grafana/xk6-distributed-tracing@v0.2.2/client/client.go:48](github.com/grafana/xk6-distributed-tracing@v0.2.2/client/client.go:48) +0x173\nreflect.Value.call({0xfe6a60, 0xc000514a40, 0x7f9c066b65b8}, {0x1162d5a, 0x4}, {0xc001a339f8, 0x1, 0xc0005ab158})\n\treflect/value.go:556 +0x845\nreflect.Value.Call({0xfe6a60, 0xc000514a40, 0xc002aa08b0}, {0xc001a339f8, 0x1, 0x1})\n\treflect/value.go:339 +0xc5\[ngithub.com/dop251/goja.(*Runtime).wrapReflectFunc.func1({{0x13dcbd8](github.com/dop251/goja.(*Runtime).wrapReflectFunc.func1(%7B%7B0x13dcbd8), 0xc004498180}, {0xc003a49410, 0x1, 0x3}})\n\[tgithub.com/dop251/goja@v0.0.0-20220124171016-cfb079cdc7b4/runtime.go:1871](github.com/dop251/goja@v0.0.0-20220124171016-cfb079cdc7b4/runtime.go:1871) +0x1c5\[ngithub.com/dop251/goja.(*vm)._nativeCall(0xc00030cf00](github.com/dop251/goja.(*vm)._nativeCall(0xc00030cf00), 0xc004134a00, 0x1)\n\[github.com/dop251/goja@v0.0.0-20220124171016-cfb079cdc7b4/vm.go:2725](github.com/dop251/goja@v0.0.0-20220124171016-cfb079cdc7b4/vm.go:2725) +0x223\[ngithub.com/dop251/goja.call.exec(0x2](github.com/dop251/goja.call.exec(0x2), 0xc00030cf00)\n\[tgithub.com/dop251/goja@v0.0.0-20220124171016-cfb079cdc7b4/vm.go:2697](github.com/dop251/goja@v0.0.0-20220124171016-cfb079cdc7b4/vm.go:2697) +0x95b\[ngithub.com/dop251/goja.(*vm).run(0xc00030cf00)](github.com/dop251/goja.(*vm).run(0xc00030cf00))\n\[tgithub.com/dop251/goja@v0.0.0-20220124171016-cfb079cdc7b4/vm.go:410](github.com/dop251/goja@v0.0.0-20220124171016-cfb079cdc7b4/vm.go:410) +0x8b\[ngithub.com/dop251/goja.(*baseJsFuncObject)._call(0xc0029fe210](github.com/dop251/goja.(*baseJsFuncObject)._call(0xc0029fe210), {{0x13dd428, 0x1e7e180}, {0xc002aa06d0, 0x1, 0x1}}, {0x0, 0x0}, {0x13dd428, 0x1e7e180})\n\[tgithub.com/dop251/goja@v0.0.0-20220124171016-cfb079cdc7b4/func.go:193](github.com/dop251/goja@v0.0.0-20220124171016-cfb079cdc7b4/func.go:193) +0x3ff\[ngithub.com/dop251/goja.(*baseJsFuncObject).call(...)](github.com/dop251/goja.(*baseJsFuncObject).call(...))\n\[tgithub.com/dop251/goja@v0.0.0-20220124171016-cfb079cdc7b4/func.go:203](github.com/dop251/goja@v0.0.0-20220124171016-cfb079cdc7b4/func.go:203)\[ngithub.com/dop251/goja.(*baseJsFuncObject).Call(0x0](github.com/dop251/goja.(*baseJsFuncObject).Call(0x0), {{0x13dd428, 0x1e7e180}, {0xc002aa06d0, 0x1, 0x1}})\n\[tgithub.com/dop251/goja@v0.0.0-20220124171016-cfb079cdc7b4/func.go:156](github.com/dop251/goja@v0.0.0-20220124171016-cfb079cdc7b4/func.go:156) +0xc7\[ngithub.com/dop251/goja.AssertFunction.func1.2()](github.com/dop251/goja.AssertFunction.func1.2())\n\[tgithub.com/dop251/goja@v0.0.0-20220124171016-cfb079cdc7b4/runtime.go:2290](github.com/dop251/goja@v0.0.0-20220124171016-cfb079cdc7b4/runtime.go:2290) +0x7d\[ngithub.com/dop251/goja.(*vm).try(0x7000103](github.com/dop251/goja.(*vm).try(0x7000103), 0x0)\n\[tgithub.com/dop251/goja@v0.0.0-20220124171016-cfb079cdc7b4/vm.go:547](github.com/dop251/goja@v0.0.0-20220124171016-cfb079cdc7b4/vm.go:547) +0x17d\[ngithub.com/dop251/goja.AssertFunction.func1({0x13dd428](github.com/dop251/goja.AssertFunction.func1(%7B0x13dd428), 0x1e7e180}, {0xc002aa06d0, 0x1, 0xc0005ab8b0})\n\[tgithub.com/dop251/goja@v0.0.0-20220124171016-cfb079cdc7b4/runtime.go:2289](github.com/dop251/goja@v0.0.0-20220124171016-cfb079cdc7b4/runtime.go:2289) +0x110\[ngo.k6.io/k6/js.(*VU).runFn.func1()](go.k6.io/k6/js.(*VU).runFn.func1())\n\[tgo.k6.io/k6@v0.37.0/js/runner.go:801](go.k6.io/k6@v0.37.0/js/runner.go:801) +0x9c\[ngo.k6.io/k6/js.(*eventLoop).start(0xc00387f680](go.k6.io/k6/js.(*eventLoop).start(0xc00387f680), 0xc000514980)\n\[tgo.k6.io/k6@v0.37.0/js/eventloop.go:110](go.k6.io/k6@v0.37.0/js/eventloop.go:110) +0x177\[ngo.k6.io/k6/js.(*VU).runFn(0xc00331cc80](go.k6.io/k6/js.(*VU).runFn(0xc00331cc80), {0x13bce40, 0xc000514940}, 0x80, 0xc002182198, 0xc002aa06c0, {0xc002aa06d0, 0x1, 0x1})\n\[tgo.k6.io/k6@v0.37.0/js/runner.go:784](go.k6.io/k6@v0.37.0/js/runner.go:784) +0x2bb\[ngo.k6.io/k6/js.(*ActiveVU).RunOnce(0xc000b12d80)](go.k6.io/k6/js.(*ActiveVU).RunOnce(0xc000b12d80))\n\[tgo.k6.io/k6@v0.37.0/js/runner.go:736](go.k6.io/k6@v0.37.0/js/runner.go:736) +0x414\[ngo.k6.io/k6/lib/executor.getIterationRunner.func1({0x13bcee8](go.k6.io/k6/lib/executor.getIterationRunner.func1(%7B0x13bcee8), 0xc003821290}, {0x139fc40, 0xc000b12d80})\n\[tgo.k6.io/k6@v0.37.0/lib/executor/helpers.go:145](go.k6.io/k6@v0.37.0/lib/executor/helpers.go:145) +0x64\[ngo.k6.io/k6/lib/executor.ConstantVUs.Run.func3({0x13b3140](go.k6.io/k6/lib/executor.ConstantVUs.Run.func3(%7B0x13b3140), 0xc00331cc80})\n\[tgo.k6.io/k6@v0.37.0/lib/executor/constant_vus.go:209](go.k6.io/k6@v0.37.0/lib/executor/constant_vus.go:209) +0x34f\ncreated by [go.k6.io/k6/lib/executor.ConstantVUs.Run](go.k6.io/k6/lib/executor.ConstantVUs.Run)\n\[tgo.k6.io/k6@v0.37.0/lib/executor/constant_vus.go:220](go.k6.io/k6@v0.37.0/lib/executor/constant_vus.go:220) +0x8ed\n\nGoja stack:\nnative"
time="2022-06-01T07:24:48Z" level=error msg="a panic occurred in VU code but was caught: runtime error: invalid memory address or nil pointer dereference" executor=constant-vus scenario=default
time="2022-06-01T07:24:48Z" level=warning msg="Request Failed" error="unknown request body type []goja.Value"
time="2022-06-01T07:24:48Z" level=error msg="panic: runtime error: invalid memory address or nil pointer dereference\ngoroutine 89 [running]:\nruntime/debug.Stack()\n\truntime/debug/stack.go:24 +0x65\[ngo.k6.io/k6/js.(*VU).runFn.func1.1()](go.k6.io/k6/js.(*VU).runFn.func1.1())\n\[tgo.k6.io/k6@v0.37.0/js/runner.go:798](go.k6.io/k6@v0.37.0/js/runner.go:798) +0x134\npanic({0xffbd80, 0x1e2c200})\n\truntime/panic.go:1038 +0x215\[ngithub.com/dop251/goja.AssertFunction.func1.1()](github.com/dop251/goja.AssertFunction.func1.1())\n\[tgithub.com/dop251/goja@v0.0.0-20220124171016-cfb079cdc7b4/runtime.go:2285](github.com/dop251/goja@v0.0.0-20220124171016-cfb079cdc7b4/runtime.go:2285) +0x6e\npanic({0xffbd80, 0x1e2c200})\n\truntime/panic.go:1038 +0x215\[ngithub.com/dop251/goja.(*vm).try.func1()](github.com/dop251/goja.(*vm).try.func1())\n\[tgithub.com/dop251/goja@v0.0.0-20220124171016-cfb079cdc7b4/vm.go:539](github.com/dop251/goja@v0.0.0-20220124171016-cfb079cdc7b4/vm.go:539) +0x635\npanic({0xffbd80, 0x1e2c200})\n\truntime/panic.go:1038 +0x215\[ngo.opentelemetry.io/otel/sdk/trace.(*span).End](go.opentelemetry.io/otel/sdk/trace.(*span).End)·dwrap·11()\n\[tgo.opentelemetry.io/otel/sdk@v0.20.0/trace/span.go:213](go.opentelemetry.io/otel/sdk@v0.20.0/trace/span.go:213) +0x2a\[ngo.opentelemetry.io/otel/sdk/trace.(*span).End(0xc003b41080](go.opentelemetry.io/otel/sdk/trace.(*span).End(0xc003b41080), {0x0, 0x0, 0x0})\n\[tgo.opentelemetry.io/otel/sdk@v0.20.0/trace/span.go:245](go.opentelemetry.io/otel/sdk@v0.20.0/trace/span.go:245) +0x698\npanic({0xffbd80, 0x1e2c200})\n\truntime/panic.go:1038 +0x215\[ngithub.com/grafana/xk6-distributed-tracing/client.(*TracingClient).WithTrace(0x116284b](github.com/grafana/xk6-distributed-tracing/client.(*TracingClient).WithTrace(0x116284b), 0xc000ac53c0, {0x1167619, 0x8}, {0x13dd000, 0xc002165920}, {0xc0021659c0, 0x1, 0x1})\n\[tgithub.com/grafana/xk6-distributed-tracing@v0.2.2/client/client.go:85](github.com/grafana/xk6-distributed-tracing@v0.2.2/client/client.go:85) +0x2d3\[ngithub.com/grafana/xk6-distributed-tracing/client.(*TracingClient).Get(0xc0014b2018](github.com/grafana/xk6-distributed-tracing/client.(*TracingClient).Get(0xc0014b2018), {0x13dd000, 0xc002165920}, {0x1e7e570, 0x0, 0x1})\n\[tgithub.com/grafana/xk6-distributed-tracing@v0.2.2/client/client.go:48](github.com/grafana/xk6-distributed-tracing@v0.2.2/client/client.go:48) +0x173\nreflect.Val

if i run the same test using xk6-output-prometheus-remote and xk6-distributed-tracing then this error disapear.
it seems that something in the code of my extension is not compatible with xk6-distributed-tracing.
can someone help me to understand i should resolve in my extensions (GitHub - Dynatrace/xk6-output-dynatrace: repo for the k6 extension)

Best regards,

Henrik Rexed

2

Hi @henrikrexed, welcome to the community forum :tada:

From the previous log and the panic that you get it seems that in the tracing client there is no check that there is are response and it’s just used on this line which panics when the response errored out.

Given the error this is likely due to changes to k6 that broke something the tracing extension uses - like using the internal k6/http API (which to be honest isn’t stable for use like that either way).

This likely will mean that the extension needs to be updated, which I don’t know if that will happen as this seems to not have been updated in a while. @dgzlopesk6, how do you feel about trying to fix this :smiling_imp:

The dynatrace extension just bumps the version of k6 that is required and that possibly breaks the extension.

You can try xk6 v0.35.0 --with ... to build with the version xk6-distributed-tracing uses otherwise. This might mean that the dynatrace output one will not compile as it uses something from after v0.35.0 … :person_shrugging:

Hope this helps you at least somewhat.