Skip to content
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.

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

The "exit" event will be emitted before written to stdout/stderr. #25

Closed
sounisi5011 opened this issue Jul 3, 2021 · 4 comments
Closed

Comments

@sounisi5011
Copy link

Currently, [email protected] emits an exit event and then writes to stdout and stderr.

spawk/lib/interceptor.js

Lines 287 to 299 in 22a4d5b

this.child.emit('exit', emitCode, emitSignal)
if (this.child.stdout) {
if (stdout) {
this.child.stdout.write(stdout)
}
this.child.stdout.end()
}
if (this.child.stderr) {
if (stderr) {
this.child.stderr.write(stderr)
}
this.child.stderr.end()
}

However, when I tried it with Node.js 12.19.0 and Node.js 16.0.0, the exit event was emitted after it was written to stdout.
Due to this difference in behavior, @actions/[email protected] is unable to get the contents of stdout.
I believe this is a bug in spawk, not in @actions/exec.

@wraithgar
Copy link
Owner

wraithgar commented Jul 3, 2021

This is actually very much intended, for this specific reason. It's meant to help folks weed out bugs in their code from assuming that stdio streams are completely done when the exit event fires.

Yes, in your tests it happens to fire after stdout is written to, but that's not guaranteed. The docs for node's child_process explain further

The 'close' event is emitted after a process has ended and the stdio streams of a child process have been closed. This is distinct from the 'exit' event, since multiple processes might share the same stdio streams. The 'close' event will always emit after 'exit' was already emitted, or 'error' if the child failed to spawn.

So, the 'close' event is the one your code needs to listen to from a child process if it wants to guarantee that the stdio streams are closed and ready to evaluate.

The github offices are closed next week, but when we're all back I'll dig into the @actions/exec code and see if there's somthing I can let them know to fix.

@wraithgar
Copy link
Owner

I took a peek real quick at the actions code and it does look like it makes a distinction between exit and close already. So I don't think there's a bug here.

https://github.com/actions/toolkit/blob/main/packages/exec/src/toolrunner.ts#L517-L523

      cp.on('close', (code: number) => {
        state.processExitCode = code
        state.processExited = true
        state.processClosed = true
        this._debug(`STDIO streams have closed for tool '${this.toolPath}'`)
        state.CheckComplete()
      })

I'm going to close this since it doesn't look like there's anything that needs to happen either in spawk or the github action code.

@wraithgar wraithgar pinned this issue Jul 3, 2021
@sounisi5011
Copy link
Author

After investigating, I found out the cause of my mistake.
In order to avoid confusion for people who come to read this issue, I will leave here what my investigation has revealed.


I was using Jest to run the tests with the exec method in @actions/exec.
The exec method outputs the stdout of the command to Node's stdout.
However, it was not shown in the execution result of Jest.
This led me to believe that a bug existed.

However, the getExecOutput method detected the stdout correctly.
Therefore, there was no bug caused by the timing of the exec event.

In addition, it turned out that lines with a newline code at the end were displayed in the Jest results.
In other words, in the following test code:

spawk.spawn('/path/to/git', ['diff', '--name-only'])
  .stdout(
    'file1\n'
    + 'file2'
  )

file1 will be displayed, but file2 will not be displayed.

So, I tested with Node only, without Jest, and all lines were displayed correctly.

$ node
Welcome to Node.js v12.19.0.
Type ".help" for more information.
> const spawk = require('spawk')
undefined
> const { exec } = require('@actions/exec')
undefined
> spawk.preventUnmatched()
undefined
> void spawk.spawn('/path/to/git', ['diff', '--name-only']).stdout('file1\nfile2')
undefined
> void exec('git diff --name-only').then(v => console.log({v})).catch(e => console.error({e}))
undefined
> [command]/path/to/git diff --name-only
file1
file2{ v: 0 }

> spawk.clean()
undefined
> void spawk.spawn('/path/to/git', ['diff', '--name-only']).stdout('file1\nfile2\n')
undefined
> void exec('git diff --name-only').then(v => console.log({v})).catch(e => console.error({e}))
undefined
> [command]/path/to/git diff --name-only
file1
file2
{ v: 0 }

From this, it seems that the cause is probably in the display process of Jest.


To summarize, there was no bug in spawk and @actions/exec.
Jest seems to be the cause.

@wraithgar
Copy link
Owner

Thank you for that thorough follow up. It does look like jest only ever listens for either a message or exit event from its child processes: https://github.com/facebook/jest/blob/705af6854e2f4b32775d65bb06a30c596fad5612/packages/jest-worker/src/workers/ChildProcessWorker.ts#L119-L120

    child.on('message', this._onMessage.bind(this));
    child.on('exit', this._onExit.bind(this));

Because the stderr and stdout are things that ultimately can be overridden via forkOptions this does feel like a bug. I am not familiar enough with the source code of jest, or what level of support they intend to make for overriding stdio like that, so I can't say for sure.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants