[Question] Could pirates hook be extended to provide more info on failure?

[Smrtnyk]

In CI pretty often pirates library throws error with its source code, but doesn't really say much about the filename where it happened.
Locally It happens once in thousands times so I cannot really debug it locally to reproduce it.
Is it possible to extend the error message to show the file name if pirates hook fails? or to provide at least bit more context.
This is bothering us for a very long time now, especially since we cannot reproduce it and it happens almost exclusively in CI.

Our node version in CI is 16.5.2

[Smrtnyk]

also we are using typescript, esm and type is set to module
shouldn't pirates not be used at all for esm?
at least that is what I infered from digging around some issues that mentioned pirates

[aslushnikov]

@Smrtnyk One reason why it might reproduce on CI and not locally is due to the cache playwright uses for local runs.

Could you try repro'ing locally clearing the cache every time?

Like this:

rm -rf ./pwcache && PWTEST_CACHE_DIR=./pwcache npx playwright test

Without a repro we're not sure what to change where to make your debugging easier.

[Smrtnyk]

I have tried running it your suggestions, tried executing many times but with no luck getting the issue.
But apart from that, why is pirates even being used for esm? Isn't it only needed for require hooks when playwright is in cjs mode?

[Smrtnyk]

I guess pirates is still needed if esm has some interop with cjs
in transform.ts on line 212, maybe that thing could be wrapped in a try catch and error could be rethrown with a filename?

[aslushnikov]

@Smrtnyk Since we're talking at this technical level... Any chance you can do a fork of Playwright with the changes you suggest and show us the CI output without and with your changes?

[Smrtnyk]

Sure, sounds reasonable. Will try it on monday

[Smrtnyk]

Actually I had some spare time. I have forked and pushed changes to my fork.
How do I build this so I can install it from my github fork? Is there some kind of github action that does that automatically?
Never really did this kind of thing before.

[aslushnikov]

How do I build this so I can install it from my github fork?

Once you have a checkout:

$ npm i # install all deps
$ npm run build # build everything
$ ./utils/pack_package.js playwright-core ./pwc.tar.gz # package playwright-core
$ ./utils/pack_package.js playwright-test ./pwt.tar.gz # package playwright-test

Note that you need both playwright-core and playwright-test; playwright-test package depends on a particular version of playwright-core.

Now you can use pwc.tar.gz and pwt.tar.gz with npm:

$ cd <your package>
$ npm i <path-to-pwc.tar.gz> # install your build of playwright-core
$ npm i <path-to-pwt.tar.gz> # install your build of playwright-test

[Smrtnyk]

Tnx, I was able to exercise CI with my changes to the playwright
but seems like adding a try catch and rethrowing error with more info didn't really help
it seems to be caught internally by pirates.
I have a screenshot of the failure

And at the end of pirates source code there is also

[2022-10-01T16:28:45.287Z] TypeError: Cannot read properties of undefined (reading 'isNative')

I suspect this one is coming from source-map-support.
It seems that in transform.ts file stackFrames[1] is undefined, and then isNative() call throws an error
@aslushnikov

Any other ideas of what I could try?
I still can't get this locally to reproduce, just in CI like every 10th build or something

[Smrtnyk]

I have a scenario in CI where it never happened and I executed around 100s of builds
But let me first describe a bit how we run playwright tests in CI.
We have 3 stages, and each stage runs in parallel and executes 1 shard.
It ends up as 1 shard runs chromium, one ff and one webkit and those run in parallel in jenkins.
All three shards are declared to run in playwright docker focal image.

If I only run one stage with 1 shard, in this case I took chromium, I wasn't able to reproduce it.
So it might be having something with parallel execution and sharding?

[Smrtnyk]

@aslushnikov I think I was deceived here by the contents of the files in CI that was in output
and it is not because of pirates but because of source-map-support package. Since this utilsBundleImpl.js is a compiled files of 3rd party packages pirates error message was inlined and put as first thing (seems like jenkins trims) so I thought it was about it, but exception was thrown because isNative is called on undefined.

I have attached here, and an exception occurs in trasnform.ts on the

Error.prepareStackTrace = (error, stackFrames) => {
      const frame: NodeJS.CallSite = sourceMapSupport.wrapCallSite(stackFrames[1]);

seems like stackFrames[1] is undefined
it happens just sometimes in CI, might be because we shard and run shards in parallel so something gets messed up.
I will try to add some logs on this place to see if I can get more context, but do you think that this is solveable on playwright side?
I am not sure we can do anything in our codebase about this issue

[Smrtnyk]

I got a case in CI where stackframes was an empty array
here is a log screenshot, I threw an error when stackframes array is empty,
in this case stackframes[1] was passed in to wrapCallSite and isNative() was called on undefined

this is the change I used to log it

Error.prepareStackTrace = (error, stackFrames) => {
      try {
        const frame: NodeJS.CallSite = sourceMapSupport.wrapCallSite(stackFrames[1]);
        const fileName = frame.getFileName();
        // Node error stacks for modules use file:// urls instead of paths.
        const file = (fileName && fileName.startsWith('file://')) ? url.fileURLToPath(fileName) : fileName;
        return {
          file,
          line: frame.getLineNumber(),
          column: frame.getColumnNumber(),
        };
      } catch (e) {
        throw new Error('stackframe: ' + JSON.stringify(stackFrames) + ', ' + e.message);
      }
    };

update:
I debugged bit further and added original error message
with this change

Error.prepareStackTrace = (error, stackFrames) => {
      try {
        const frame: NodeJS.CallSite = sourceMapSupport.wrapCallSite(stackFrames[1]);
        const fileName = frame.getFileName();
        // Node error stacks for modules use file:// urls instead of paths.
        const file = (fileName && fileName.startsWith('file://')) ? url.fileURLToPath(fileName) : fileName;
        return {
          file,
          line: frame.getLineNumber(),
          column: frame.getColumnNumber(),
        };
      } catch (e) {
        throw new Error('stackframe: ' + JSON.stringify(stackFrames) + ', ' + e.message + ', originalErrorMessage: ' + error.message);
      }
    };

I got this logged in the catch block

Error: stackframe: [], Cannot read properties of undefined (reading 'isNative'), originalErrorMessage: stackframe: [], Cannot read properties of undefined (reading 'isNative'), originalErrorMessage: stackframe: [{},{}], Unexpected end of JSON input, originalErrorMessage: undefined

[yury-s]

@Smrtnyk any chance you can share a repro where stackFrames.length < 2 or stackFrames[1] is undefined somehow?

[Smrtnyk]

Locally I maybe saw it once, so I have no idea how to build something that can reliably cause that.
This happens only in CI.
In CI we use node 16.5.0, but I use locally newer node lts so it might have to do with that.
Will try to downgrade node and see if I can have it happen locally.
Also locally I run playwright on windows, I don't use docker, and in CI it uses docker image.

[pavelfeldman]

We would need exact steps to follow in order to address this. As long as we can't repro it, it is unlikely with can make progress with it. Allow me to close it, but please file a new one and link to this issue if you manage to reproduce it.

[Smrtnyk]

Well I have pointed to a place where code is unguarded.
Exception happens because playwright tries to access array[1] where array is clearly empty.
Can you link at least some source where it says that it is guaranteed that this stack array is never empty?
I tried to google it, seems like it is native to v8, but doesn't say much that it will always have at least 2 members in it.
Only thing I find is that it is recommended to iterate over that array.

I don't know how to reproduce it because I have no idea what happens to come to that.
I have posted above the logs where the exceptions happens, seems like it has to do with some kind of json or something.
Anyway, since I can't reproduce and you guys are not able to provide a fix, I will need to live with this behavior happening from time to time.

[Smrtnyk]

Alright, it is actually possible for that array to be empty
by doing this

Error.prepareStackTrace = (error, stack) => {
    console.log(stack); // stack is empty array here
};
fs.rmdir("dsd", (err) => console.log(err.stack));

you provoke that behavior.
I am doing some fs operations in my codebase, and they might be failing somewhere
and then that causes playwright to throw exception
nodejs/node#30944 there is also an issue for this

[yury-s]

There are definitely cases in general where stack may be an empty array, but Error.prepareStackTrace is overridden in a very limited scope while we call Error.captureStackTrace(obj);, so there must be at least 2 frames on the stack:
0 - for captureStackTrace and
1 - for the wrapper function that calls it.
We need to see an example where this is not the case. Perhaps you have a non standard Error.captureStackTrace?

[Smrtnyk]

We don't override captureStackTrace in our code, but it might be hidden somewhere in some package that we use
will poke around to see if I can figure out more context

[Smrtnyk]

Given the log I provided above and value of this message, seems like it recursed few times in here with empty stack until it had two frames.

Error: stackframe: [], Cannot read properties of undefined (reading 'isNative'), originalErrorMessage: stackframe: [], Cannot read properties of undefined (reading 'isNative'), originalErrorMessage: stackframe: [{},{}], Unexpected end of JSON input, originalErrorMessage: undefined

I see this function is only used for extending of the test object, so I will poke around that function until I figure out the exact place.
I will reopen the issue when I have the exact scenario then.