steelbrain / exec

Node's Process spawning APIs beautified
MIT License
9 stars 4 forks source link

`exitCode === null` #97

Open cgalvarez opened 6 years ago

cgalvarez commented 6 years ago

I've detected that in the Atom package linter-codeclimate, all executions of the CodeClimate CLI using this package sb-exec are being mistakingly interpreted as failed executions.

I've checked that in this line, the exitCode has a value of null, and that's making linter-codeclimate printing a lot of error messages in the console.

I've checked that the command is fine, works flawlessly on the terminal command line, with an exit code of 0, and the output captured by sb-exec is fine too. The only problem is that it's taking null as the exit code and it's interpreting it as a failure, thus rejecting the promise with an Error object.

I'm preparing a PR for that project to temporary elude this issue in linter-codeclimate, which sets ignoreExitCode = true, but I think this issue should get fixed here.

steelbrain commented 6 years ago

Hi @cgalvarez

According to the docs, child_process.on('exit') ALWAYS returns an exit code. If it doesn't, either Node.js has a bug that should be fixed or you're running some custom mod of it?

Can you please report back the versions of apm --version? Thanks!

cgalvarez commented 6 years ago

Hi @steelbrain

Can you please report back the versions of apm --version? Thanks!

$ apm --version
apm  1.18.12
npm  3.10.10
node 6.9.5 x64
atom 1.24.0
python 2.7.12
git 2.7.4

These are screenshots with the devTools open, showing the value of exitCode and the error message. I've temporarily removed ignoreExitCode = true locally so you can see it printing the error messages to the console:

screenshot-exitcode-null

screenshot-exitcode-null-err-msg

I've seen that now I only get one error message, and think I found the reason of the error messages.

The linter-codeclimate code is currently relying on the option uniqueKey to spawn only one process per file. I detected that it was spawning two processes on each save. My PR leverages a debounced approach to minimize triggering consecutive analyses on the same project files, and I suppose that's why I only see one error message in the console (the initial, on Atom start, because the time between the two executions exceeds my debounce delay, 2s vs 150ms).

So the only explanation I can come across is that sb-exec receives exitCode === null when a previous execution having the same uniqueKey is killed, which makes most sense since, as seen in the screenshot (didn't see it previously, sorry), it has received signalCode === SIGTERM.

Being so, I have two questions:

  1. Should a killed process (based on uniqueKey) print its output as an error?
  2. Should a process sharing same uniqueKey be killed at the end of its group?

The reason for 2) is that I can see the two execs starting at the same time, and I think the 1st process should be killed as soon as the 2nd one is executed (based on uniqueKey). Right now, I'm seeing that both run until finished, and then the 1st one prints the error.

steelbrain commented 6 years ago

Thanks for the insight, will investigate

cgalvarez commented 6 years ago

Digging a bit more in this, I've found that this issue has to do with atom-linter too, which linter-codeclimate also uses.

Inserting some strategic console.logs, I got next:

screenshot-devtools-atom-linter

Summarizing and making the screenshot readable and understandable, linter-codeclimate spawns two processes with same uniqueId, and this is the sequence of events with timestamps:

1519663122825 atom-linter Helpers.exec() 1st call
1519663124730 atom-linter Helpers.exec() 2nd call (~2s after)
1519663124731 atom-linter invokes spawned.kill() for 1st call (right after 2nd call)
1519663145424 sb-exec prints to console.error() because of exitCode=null (~21s AFTER calling spawned.kill()
1519663145425 atom-linter returns null on mirror reject
1519663145425 linter-codeclimate receives Helpers.exec() output from 1st call (killed)
1519663145930 linter-codeclimate receives Helpers.exec() output from 2nd call (winning, last one) (~0.5s after killed one)

This confirm my previous insight.

Don't know if it an sb-exec or atom-linter issue, but I hope this new info helps to get the bug addressed.

EDIT: I've been able to detect this because a CodeClimate analysis is a heavy task. It usually takes 20-30s locally. In my PR I've just needed to increase the timeout for promises to 5min because its heaviness. That's why it is so overkill to have more than one process running without ensuring previous ones are killed. Feel free to ask any question. I will be glad to help :wink: