JS script stack traces not referencing the correct lines of code in imported modules #1804

SaberStrat · 2021-01-16T17:10:03Z

If k6 run aborts due to a JS code error/exception in a portion of script code that's imported as a module, the stack trace k6 prints out is not displaying the correct line numbers of the calls leading to the error.
If the code error happens in the main script file -- i.e. the one that contains the default export -- the line number is correct.

Environment

k6 version: k6 v0.29.0 (2020-11-11T13:27:19+0000/d9bced3, go1.15.3, darwin/amd64)

k6 version: 0.29.0
OS and version: macOS 10.14.6; also happening on Windows 10

Expected Behavior

k6 run should print the correct line number in the stack, whether the exception happened in the main JS or an imported module.

Actual Behavior

k6 run prints an incorrect line number if the exception happens in an imported module JS. This makes debugging in bigger k6 projects really bothersome, as I have to resort to good old "printf debugging".

Steps to Reproduce the Problem

Here's a short simplified example code, consisting of the 'main' file with the default export and two further modules:

stacktrace_linenumbers.js

import {f1} from "./module1.js"

export default function(){
//    throw "exception in default"
    f1()
    console.log("in default")
}

module1.js

import {f2} from "./module2.js"

export function f1(){
//    throw "exception in module1"
    f2()
    console.log("in f1")
}

module2.js

export function f2(){
//    throw "exception in module2"
    console.log("in f2")
}

Uncommenting the throw in the main JS leads to the following printout:

Mes-MacBook-Pro:k6-v0.29.0-mac me$ ./k6 run stacktrace_linenumbers.js

          /\      |‾‾| /‾‾/   /‾‾/   
     /\  /  \     |  |/  /   /  /    
    /  \/    \    |     (   /   ‾‾\  
   /          \   |  |\  \ |  (‾)  | 
  / __________ \  |__| \__\ \_____/ .io


  execution: local
     script: stacktrace_linenumbers.js
     output: -

  scenarios: (100.00%) 1 scenario, 1 max VUs, 10m30s max duration (incl. graceful stop):
           * default: 1 iterations for each of 1 VUs (maxDuration: 10m0s, gracefulStop: 30s)

ERRO[0000] exception in default
        at file:///Users/me/Downloads/k6-v0.29.0-mac/stacktrace_linenumbers.js:4:11(2)  executor=per-vu-iterations scenario=default source=stacktrace

running (00m00.0s), 0/1 VUs, 1 complete and 0 interrupted iterations
default ✓ [======================================] 1 VUs  00m00.0s/10m0s  1/1 iters, 1 per VU

    data_received........: 0 B 0 B/s
    data_sent............: 0 B 0 B/s
    iteration_duration...: avg=13.7µs min=13.7µs med=13.7µs max=13.7µs p(90)=13.7µs p(95)=13.7µs
    iterations...........: 1   66.835984/s

The stack trace says at file:///Users/me/Downloads/k6-v0.29.0-mac/stacktrace_linenumbers.js:4:11(2); the throw is in line 4. Correct

Uncommenting the throw in the module1.js leads to the following printout:

Mes-MacBook-Pro:k6-v0.29.0-mac me$ ./k6 run stacktrace_linenumbers.js

          /\      |‾‾| /‾‾/   /‾‾/   
     /\  /  \     |  |/  /   /  /    
    /  \/    \    |     (   /   ‾‾\  
   /          \   |  |\  \ |  (‾)  | 
  / __________ \  |__| \__\ \_____/ .io

  execution: local
     script: stacktrace_linenumbers.js
     output: -

  scenarios: (100.00%) 1 scenario, 1 max VUs, 10m30s max duration (incl. graceful stop):
           * default: 1 iterations for each of 1 VUs (maxDuration: 10m0s, gracefulStop: 30s)

ERRO[0000] exception in module1
        at f1 (file:///Users/me/Downloads/k6-v0.29.0-mac/module1.js:5:11(2))
        at file:///Users/me/Downloads/k6-v0.29.0-mac/stacktrace_linenumbers.js:5:20(4)  executor=per-vu-iterations scenario=default source=stacktrace

running (00m00.0s), 0/1 VUs, 1 complete and 0 interrupted iterations
default ✓ [======================================] 1 VUs  00m00.0s/10m0s  1/1 iters, 1 per VU

    data_received........: 0 B 0 B/s
    data_sent............: 0 B 0 B/s
    iteration_duration...: avg=34.31µs min=34.31µs med=34.31µs max=34.31µs p(90)=34.31µs p(95)=34.31µs
    iterations...........: 1   61.938681/s

The stack trace says at f1 (file:///Users/me/Downloads/k6-v0.29.0-mac/module1.js:5:11(2)); the throw is in line 4. Not correct

Uncommenting the throw in the module2.js leads to the following printout:

Mes-MacBook-Pro:k6-v0.29.0-mac me$ ./k6 run stacktrace_linenumbers.js

          /\      |‾‾| /‾‾/   /‾‾/   
     /\  /  \     |  |/  /   /  /    
    /  \/    \    |     (   /   ‾‾\  
   /          \   |  |\  \ |  (‾)  | 
  / __________ \  |__| \__\ \_____/ .io

  execution: local
     script: stacktrace_linenumbers.js
     output: -

  scenarios: (100.00%) 1 scenario, 1 max VUs, 10m30s max duration (incl. graceful stop):
           * default: 1 iterations for each of 1 VUs (maxDuration: 10m0s, gracefulStop: 30s)

ERRO[0000] exception in module2
        at f2 (file:///Users/me/Downloads/k6-v0.29.0-mac/module2.js:3:11(2))
        at f1 (file:///Users/me/Downloads/k6-v0.29.0-mac/module1.js:6:20(4))
        at file:///Users/me/Downloads/k6-v0.29.0-mac/stacktrace_linenumbers.js:5:20(4)  executor=per-vu-iterations scenario=default source=stacktrace

running (00m00.0s), 0/1 VUs, 1 complete and 0 interrupted iterations
default ✓ [======================================] 1 VUs  00m00.0s/10m0s  1/1 iters, 1 per VU

    data_received........: 0 B 0 B/s
    data_sent............: 0 B 0 B/s
    iteration_duration...: avg=35.55µs min=35.55µs med=35.55µs max=35.55µs p(90)=35.55µs p(95)=35.55µs
    iterations...........: 1   64.193093/s

The stack trace says at f2 (file:///Users/me/Downloads/k6-v0.29.0-mac/module2.js:3:11(2)); the throw is in line 2. Not correct
Also, the line in module1.js where the f2() call is in is incorrect too: stack trace says at f1 (file:///Users/me/Downloads/k6-v0.29.0-mac/module1.js:6:20(4)); f2() is in line 5 of module1.js.

The text was updated successfully, but these errors were encountered:

na-- · 2021-01-18T08:29:47Z

Thanks for reporting this! I think it's caused by the newline in this module wrapping code https://github.com/loadimpact/k6/blob/c00a85bfea21d748f0f9d11fdbc326087f34c411/js/initcontext.go#L203

I guess we can remove the first \n without any issues, so that the line numbers match. But the offsets in a single line will still be off, and I think the only way to fix that is either refactor our module importing code, or add and support source maps (#1789). And we shouldn't remove the second \n above, since scripts ending with a // comment will break the hack... 😅

na-- · 2021-01-26T18:08:52Z

Duplicate old issue with fewer details, closed in favor of this one, but featuring some sourcemap details: #1107

mjkapkan · 2021-08-11T05:19:20Z

Have a similar issue on Ubuntu. Any pointer on how I could fix this in a custom build?
version: k6 v0.33.0 (2021-06-29T10:38:31+0000/cc0361c, go1.16.5, linux/amd64)

mstoykov · 2021-08-11T09:34:46Z

@mjkapkan I would recommend to just know that you need to look at the line above for anything that isn't the main module until we fix it ;)

mjkapkan · 2021-08-11T09:39:46Z

Oh I guess this could be a different problem then. The referenced lines are off by 100s of lines. Will add an example a bit later.

mjkapkan · 2021-08-12T07:37:33Z

@mstoykov here is the example.
Script:

import { group, check, sleep } from 'k6'
import http from 'k6/http'
import { URL } from './lib/k6jslib.js'

export function handleResponse(rqResponse) {
    checking = undefined
}

export default function() {
    const rootUrl = 'google.com'
    group('maps', () => {
        handleResponse(http.request('GET', rootUrl, '{}'))
    })
}

Log:

ERRO[0003] ReferenceError: checking is not defined
	at handleResponse (file:///tmp/testScript.js:14:284(3))
	at file:///tmp/testScript.js:12:23(10)
	at go.k6.io/k6/js/common.Bind.func1 (native)
	at file:///tmp/testScript.js:11:19(7)  executor=shared-iterations scenario=default source=stacktrace

As you can see the test script only has 15 lines, but the lines referenced are way off. This gets even worse with big files.

For example the error here is in line 163 on file mainTest.js

Run     at selectRequiredFields (file:///tmp/mainTest.js:546:2818(50))
default at generateRqBody (file:///tmp/mainTest.js:546:3453(13))
	at file:///tmp/mainTest.js:549:814(136)
	at go.k6.io/k6/js/common.Bind.func1 (native)
	at processMethod (file:///tmp/mainTest.js:547:1439(14))
	at file:///tmp/mainTest.js:519:37(27)
	at file:///tmp/mainTest.js:514:9(105)

So it's a bit hard to trace the error this way.

mstoykov · 2021-08-12T08:08:05Z

In the first one, the error is on line 13 instead of 14 which is what we are mostly talking about in this issue.

Can you please open a new one referencing this one but providing the script(or something that reproduces it) where the difference is between 163 and 5xx lines as that is more interesting

SaberStrat · 2021-08-12T10:30:16Z

Yes! This amount of lines off is what I was actually dealing with in my real scripts. I made my simple example, it reproduced the issue with a line off, so I called it a day.
I can't tell for sure as it's a long time ago and I don't have the time to get into my original script again, but I'm 51% sure the actual error line was not in the near vicinity of the line given in the error trace.

mstoykov · 2021-08-12T12:00:16Z

@SaberStrat, well the one line off is easy to explain and fix as @na-- but anything other than that likely has another source which I don't think even #1789 will help with.

I would really would like to have an example of what actually gets some bigger difference in the lines numbers so we can better figure out what the problem actually is

mjkapkan · 2021-08-12T12:45:19Z

I may try to come up with something.

SaberStrat · 2021-08-13T10:23:49Z

Got it!
I wondered why not more people are complaining about this. Wondered if it might be that I modularized out the huge wall of functions into a module that I import into main.
And indeed, if a module is 'too' long, the discrepancy between the actual error line and line reported in the stack becomes more than just 1 line.

Example:

stacktrace_linenumbers.js

import * as module1 from "./module1.js"

export default function(){
//    throw "exception in line 4"
    module1.f2()
    console.log("in default")
}

module1.js

export function f1(){
    throw "exception in line 2"
    console.log("in f1")
}
export function f2(){
    throw "exception in line 6"
    console.log("in f2")
}
export function f3(){
    throw "exception in line 10"
    console.log("in f3")
}
export function f4(){
    throw "exception in line 14"
    console.log("in f4")
}
export function f5(){
    throw "exception in line 18"
    console.log("in f5")
}
export function f6(){
    throw "exception in line 22"
    console.log("in f6")
}
export function f7(){
    throw "exception in line 26"
    console.log("in f7")
}
export function f8(){
    throw "exception in line 30"
    console.log("in f8")
}
export function f9(){
    throw "exception in line 34"
    console.log("in f9")
}
export function f10(){
    throw "exception in line 38"
    console.log("in f10")
}

Output:

>k6.exe run C:\Users\me\Documents\loadtesting\tools\k6\bugs\#1804\stacktrace_linenumbers.js

          /\      |‾‾| /‾‾/   /‾‾/
     /\  /  \     |  |/  /   /  /
    /  \/    \    |     (   /   ‾‾\
   /          \   |  |\  \ |  (‾)  |
  / __________ \  |__| \__\ \_____/ .io

  execution: local 
     script: C:\Users\me\Documents\loadtesting\tools\k6\bugs\#1804\stacktrace_linenumbers.js
     output: -

  scenarios: (100.00%) 1 scenario, 1 max VUs, 10m30s max duration (incl. graceful stop):
           * default: 1 iterations for each of 1 VUs (maxDuration: 10m0s, gracefulStop: 30s)

ERRO[0000] exception in line 6
        at f2 (file:///C:/Users/me/Documents/loadtesting/tools/k6/bugs/%231804/module1.js:38:97(2))
        at file:///C:/Users/me/Documents/loadtesting/tools/k6/bugs/%231804/stacktrace_linenumbers.js:5:15(4)  executor=per-vu-iterations scenario=default source=stacktrace

running (00m00.0s), 0/1 VUs, 1 complete and 0 interrupted iterations
default ✓ [======================================] 1 VUs  00m00.0s/10m0s  1/1 iters, 1 per VU

    data_received........: 0 B 0 B/s
    data_sent............: 0 B 0 B/s
    iteration_duration...: avg=0s min=0s med=0s max=0s p(90)=0s p(95)=0s
    iterations...........: 1   35.892853/s

They offset seem to accumulate with the length of the module.

mjkapkan · 2021-08-13T14:43:40Z

Thanks @SaberStrat ! I import a lot of modules, so it explains the huge diffs in line numbers I got.
Now a question to the go devs, is there a quick and easy fix for this? 😅

mstoykov · 2021-08-13T14:47:27Z

from my quick look at this, this is mostly due to the large amount of export than the lines. Unfortunately, it seems that my source map patch isn't working with that ... which it definitely should've .. .and also that disabling the retainLines babel configuration option ... "fixes" it (being +1 off) which is totally the opposite of what that option is supposed to do 🤣 .

So no quick fixes, sorry.

mstoykov · 2021-08-20T13:44:32Z

can you guys try #2082 and see if that helps you ?

SaberStrat · 2021-08-20T14:50:55Z

Pulled the master branch, did a go build on it, and ran that new executable.

Alas no change, if I did everything correctly. Still shows line 38 instead of 6. :/

>k6.exe version
k6 v0.33.0 ((devel), go1.16.7, windows/amd64)

>k6.exe run C:\Users\me\Documents\loadtesting\tools\k6\bugs\#1804\stacktrace_linenumbers.js

          /\      |‾‾| /‾‾/   /‾‾/
     /\  /  \     |  |/  /   /  /
    /  \/    \    |     (   /   ‾‾\
   /          \   |  |\  \ |  (‾)  |
  / __________ \  |__| \__\ \_____/ .io

  execution: local
     script: C:\Users\me\Documents\loadtesting\tools\k6\bugs\#1804\stacktrace_linenumbers.js
     output: -

  scenarios: (100.00%) 1 scenario, 1 max VUs, 10m30s max duration (incl. graceful stop):
           * default: 1 iterations for each of 1 VUs (maxDuration: 10m0s, gracefulStop: 30s)

ERRO[0000] exception in line 6
        at f2 (file:///C:/Users/me/Documents/loadtesting/tools/k6/bugs/%231804/module1.js:38:97(2))
        at file:///C:/Users/me/Documents/loadtesting/tools/k6/bugs/%231804/stacktrace_linenumbers.js:5:15(4)  executor=per-vu-iterations scenario=default source=stacktrace

running (00m00.0s), 0/1 VUs, 1 complete and 0 interrupted iterations
default ✓ [======================================] 1 VUs  00m00.0s/10m0s  1/1 iters, 1 per VU

     data_received........: 0 B 0 B/s
     data_sent............: 0 B 0 B/s
     iteration_duration...: avg=0s min=0s med=0s max=0s p(90)=0s p(95)=0s
     iterations...........: 1   250.651694/s

mstoykov · 2021-08-20T14:54:27Z

it's not merged (and likely won't be for the next version) so you need to pull feature/SourceMaps

SaberStrat · 2021-08-20T15:39:01Z

Oops, right, sorry.

Line numbers are correct now! 🤩 Thank you!

>k6.exe run C:\Users\me\Documents\loadtesting\tools\k6\bugs\#1804\stacktrace_linenumbers.js

          /\      |‾‾| /‾‾/   /‾‾/
     /\  /  \     |  |/  /   /  /
    /  \/    \    |     (   /   ‾‾\
   /          \   |  |\  \ |  (‾)  |
  / __________ \  |__| \__\ \_____/ .io

  execution: local
     script: C:\Users\me\Documents\loadtesting\tools\k6\bugs\#1804\stacktrace_linenumbers.js
     output: -

  scenarios: (100.00%) 1 scenario, 1 max VUs, 10m30s max duration (incl. graceful stop):
           * default: 1 iterations for each of 1 VUs (maxDuration: 10m0s, gracefulStop: 30s)

ERRO[0000] exception in line 6
        at f2 (file:///C:/Users/me/Documents/loadtesting/tools/k6/bugs/%231804/module1.js:6:10(2))
        at file:///C:/Users/me/Documents/loadtesting/tools/k6/bugs/%231804/stacktrace_linenumbers.js:5:4(4)  executor=per-vu-iterations scenario=default source=stacktrace

running (00m00.0s), 0/1 VUs, 1 complete and 0 interrupted iterations
default ✓ [======================================] 1 VUs  00m00.0s/10m0s  1/1 iters, 1 per VU

     data_received........: 0 B 0 B/s
     data_sent............: 0 B 0 B/s
     iteration_duration...: avg=0s min=0s med=0s max=0s p(90)=0s p(95)=0s
     iterations...........: 1   70.740869/s

Column numbers seem to be 0-based, but I assume that's fine?

mjkapkan · 2021-08-24T10:18:26Z

I tried to build it with xk6 but it still show incorrect lines. How can I make sure I have built the fixed version? (I am new to go).
Build Log:

$ git branch
* feature/SourceMaps
$ XK6_K6_REPO="$PWD" xk6 build
2021/08/24 13:15:51 [INFO] Temporary folder: /tmp/buildenv_2021-08-24-1315.170800038
2021/08/24 13:15:51 [INFO] Writing main module: /tmp/buildenv_2021-08-24-1315.170800038/main.go
2021/08/24 13:15:51 [INFO] Initializing Go module
2021/08/24 13:15:51 [INFO] exec (timeout=10s): /home/jaunius/.gvm/gos/go1.16.6/bin/go mod init k6 
go: creating new go.mod: module k6
go: to add module requirements and sums:
	go mod tidy
2021/08/24 13:15:51 [INFO] Pinning versions
2021/08/24 13:15:51 [INFO] exec (timeout=0s): /home/jaunius/.gvm/gos/go1.16.6/bin/go mod edit -require go.k6.io/k6@latest 
2021/08/24 13:15:51 [INFO] exec (timeout=0s): /home/jaunius/.gvm/gos/go1.16.6/bin/go mod tidy 
2021/08/24 13:15:52 [INFO] exec (timeout=10s): /home/jaunius/.gvm/gos/go1.16.6/bin/go mod edit -replace go.k6.io/k6=/home/jaunius/dev/builds/xk6/k6 
2021/08/24 13:15:52 [INFO] Build environment ready
2021/08/24 13:15:52 [INFO] Building k6
2021/08/24 13:15:52 [INFO] exec (timeout=0s): /home/jaunius/.gvm/gos/go1.16.6/bin/go mod tidy 
2021/08/24 13:15:52 [INFO] exec (timeout=0s): /home/jaunius/.gvm/gos/go1.16.6/bin/go build -o /home/jaunius/dev/builds/xk6/k6/k6 -ldflags -w -s -trimpath 
2021/08/24 13:15:53 [INFO] Build complete: ./k6
2021/08/24 13:15:53 [INFO] Cleaning up temporary folder: /tmp/buildenv_2021-08-24-1315.170800038

mstoykov · 2021-09-28T12:15:58Z

sorry @mjkapkan I just now see that you wrote 🤦. I think what you did should've correctly created a k6 binary locally with the correct version that you should then call with ./k6, but just in case I have also attached a binary build by me. Remember you need to run that binary not just k6
k6-sourcemaps.zip

This includes both support for any sourcemap found through the source file and generating sourcemaps when going through babel. There are additional fixes for trying to fix off by 1 line errors in imports, but those may need further work. On not being able to load a sourcemap a warning is emitted but the file is still parsed and compiled just without sourcemaps fixes #1789, #1804

mstoykov · 2022-01-17T12:23:09Z

This should get fixed with #2082 and a version with it should be released until the end of the week or the beginning of the next.

SaberStrat added the bug label Jan 16, 2021

na-- added the good first issue label Jan 18, 2021

na-- mentioned this issue Jan 26, 2021

Fix line numbers in imports #1107

Closed

na-- removed the good first issue label Dec 9, 2021

mstoykov closed this as completed Jan 17, 2022

na-- added this to the v0.36.0 milestone Jan 18, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

JS script stack traces not referencing the correct lines of code in imported modules #1804

JS script stack traces not referencing the correct lines of code in imported modules #1804

SaberStrat commented Jan 16, 2021 •

edited

Loading

na-- commented Jan 18, 2021

na-- commented Jan 26, 2021

mjkapkan commented Aug 11, 2021

mstoykov commented Aug 11, 2021

mjkapkan commented Aug 11, 2021

mjkapkan commented Aug 12, 2021

mstoykov commented Aug 12, 2021 •

edited

Loading

SaberStrat commented Aug 12, 2021

mstoykov commented Aug 12, 2021

mjkapkan commented Aug 12, 2021

SaberStrat commented Aug 13, 2021 •

edited

Loading

mjkapkan commented Aug 13, 2021

mstoykov commented Aug 13, 2021

mstoykov commented Aug 20, 2021

SaberStrat commented Aug 20, 2021 •

edited

Loading

mstoykov commented Aug 20, 2021

SaberStrat commented Aug 20, 2021

mjkapkan commented Aug 24, 2021

mstoykov commented Sep 28, 2021

mstoykov commented Jan 17, 2022

JS script stack traces not referencing the correct lines of code in imported modules #1804

JS script stack traces not referencing the correct lines of code in imported modules #1804

Comments

SaberStrat commented Jan 16, 2021 • edited Loading

Environment

Expected Behavior

Actual Behavior

Steps to Reproduce the Problem

stacktrace_linenumbers.js

module1.js

module2.js

na-- commented Jan 18, 2021

na-- commented Jan 26, 2021

mjkapkan commented Aug 11, 2021

mstoykov commented Aug 11, 2021

mjkapkan commented Aug 11, 2021

mjkapkan commented Aug 12, 2021

mstoykov commented Aug 12, 2021 • edited Loading

SaberStrat commented Aug 12, 2021

mstoykov commented Aug 12, 2021

mjkapkan commented Aug 12, 2021

SaberStrat commented Aug 13, 2021 • edited Loading

Example:

stacktrace_linenumbers.js

module1.js

Output:

mjkapkan commented Aug 13, 2021

mstoykov commented Aug 13, 2021

mstoykov commented Aug 20, 2021

SaberStrat commented Aug 20, 2021 • edited Loading

mstoykov commented Aug 20, 2021

SaberStrat commented Aug 20, 2021

mjkapkan commented Aug 24, 2021

mstoykov commented Sep 28, 2021

mstoykov commented Jan 17, 2022

SaberStrat commented Jan 16, 2021 •

edited

Loading

mstoykov commented Aug 12, 2021 •

edited

Loading

SaberStrat commented Aug 13, 2021 •

edited

Loading

SaberStrat commented Aug 20, 2021 •

edited

Loading