node left hanging after read #106

mrbrahman · 2021-12-27T16:08:02Z

Describe the bug
It seems exiftool-vendored (or one of it's dependencies) is causing node to hold / hang after a simple read of file. Also, this "hold" seems to last for about 5 mins.

To Reproduce

$ cat test-exiftool-close.mjs
import {exiftool} from 'exiftool-vendored';
import process from 'process';

function log(str){
  console.log(`${new Date()} ${str}`)
}

process.on('exit', ()=>{
  log('exit signal received. closing exiftool')
  exiftool.end();
  log('gracefully exiting now')
});

log('Starting to read file now')
exiftool.read('IMG_06565.JPG')
  .then(tags=>log('done reading file'))
;

$ time node test-exiftool-close.mjs 
Mon Dec 27 2021 10:59:34 GMT-0500 (Eastern Standard Time) Starting to read file now
Mon Dec 27 2021 10:59:34 GMT-0500 (Eastern Standard Time) done reading file
Mon Dec 27 2021 11:04:34 GMT-0500 (Eastern Standard Time) exit signal received. closing exiftool
Mon Dec 27 2021 11:04:34 GMT-0500 (Eastern Standard Time) gracefully exiting now

real	5m0.519s
user	0m0.794s
sys	0m0.124s

Expected behavior
Program should have exited immediately after completion of promise.

Environment (please complete the following information):
All latest and greatest

Linux Mint 20.2 Cinnamon
Node.js v17.3.0

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

mceachen · 2021-12-27T22:09:20Z

Thanks for including the example 👍

I was able to reproduce locally, even on node 14, not using modules, and a (much) older version of exiftool-vendored (v10.1.0) and old version of batch-cluster (v5.9.5), so this is a long-standing bug. 😞

Here's with the current versions:

$ why-is-node-running test.js 
probing program /tmp/test/test.js
kill -SIGUSR1 2905069 for logging
Mon Dec 27 2021 14:08:23 GMT-0800 (Pacific Standard Time) Starting to read file now
Mon Dec 27 2021 14:08:23 GMT-0800 (Pacific Standard Time) done reading file
There are 9 handle(s) keeping the process running

# TTYWRAP
/home/mrm/.nvm/versions/node/v14.18.2/lib/node_modules/why-is-node-running/node_modules/siginfo/index.js:3 - if (process.stderr.isTTY || force === true) {
/home/mrm/.nvm/versions/node/v14.18.2/lib/node_modules/why-is-node-running/include.js:3                    - require('siginfo')(why, true)

# SIGNALWRAP
/home/mrm/.nvm/versions/node/v14.18.2/lib/node_modules/why-is-node-running/node_modules/siginfo/index.js:3 - if (process.stderr.isTTY || force === true) {
/home/mrm/.nvm/versions/node/v14.18.2/lib/node_modules/why-is-node-running/include.js:3                    - require('siginfo')(why, true)

# SIGNALWRAP
/home/mrm/.nvm/versions/node/v14.18.2/lib/node_modules/why-is-node-running/node_modules/siginfo/index.js:6 - process.on('SIGUSR1', onsiginfo)
/home/mrm/.nvm/versions/node/v14.18.2/lib/node_modules/why-is-node-running/include.js:3                    - require('siginfo')(why, true)

# TTYWRAP
(unknown stack trace)

# TTYWRAP
(unknown stack trace)

# PROCESSWRAP
/tmp/test/node_modules/exiftool-vendored/dist/ExifTool.js:146 - : _cp.spawn(o.exiftoolPath, o.exiftoolArgs, spawnOpts);
/tmp/test/node_modules/batch-cluster/dist/BatchCluster.js:326 - const child = await this.options.processFactory();
/tmp/test/node_modules/batch-cluster/dist/BatchCluster.js:318 - void this._mayLaunchNewChild();
/tmp/test/node_modules/batch-cluster/dist/BatchCluster.js:255 - void this.maybeLaunchNewChild();
/tmp/test/node_modules/batch-cluster/dist/BatchCluster.js:133 - setImmediate(() => this.onIdle());

# PIPEWRAP
/tmp/test/node_modules/exiftool-vendored/dist/ExifTool.js:146 - : _cp.spawn(o.exiftoolPath, o.exiftoolArgs, spawnOpts);
/tmp/test/node_modules/batch-cluster/dist/BatchCluster.js:326 - const child = await this.options.processFactory();

# PIPEWRAP
/tmp/test/node_modules/exiftool-vendored/dist/ExifTool.js:146 - : _cp.spawn(o.exiftoolPath, o.exiftoolArgs, spawnOpts);
/tmp/test/node_modules/batch-cluster/dist/BatchCluster.js:326 - const child = await this.options.processFactory();

# PIPEWRAP
/tmp/test/node_modules/exiftool-vendored/dist/ExifTool.js:146 - : _cp.spawn(o.exiftoolPath, o.exiftoolArgs, spawnOpts);
/tmp/test/node_modules/batch-cluster/dist/BatchCluster.js:326 - const child = await this.options.processFactory();

Here's with the old versions:

$ why-is-node-running test.js 
probing program /tmp/test/test.js
kill -SIGUSR1 2904597 for logging
Mon Dec 27 2021 14:07:02 GMT-0800 (Pacific Standard Time) Starting to read file now
Mon Dec 27 2021 14:07:02 GMT-0800 (Pacific Standard Time) done reading file
There are 9 handle(s) keeping the process running

# TTYWRAP
/home/mrm/.nvm/versions/node/v14.18.2/lib/node_modules/why-is-node-running/node_modules/siginfo/index.js:3 - if (process.stderr.isTTY || force === true) {
/home/mrm/.nvm/versions/node/v14.18.2/lib/node_modules/why-is-node-running/include.js:3                    - require('siginfo')(why, true)

# SIGNALWRAP
/home/mrm/.nvm/versions/node/v14.18.2/lib/node_modules/why-is-node-running/node_modules/siginfo/index.js:3 - if (process.stderr.isTTY || force === true) {
/home/mrm/.nvm/versions/node/v14.18.2/lib/node_modules/why-is-node-running/include.js:3                    - require('siginfo')(why, true)

# SIGNALWRAP
/home/mrm/.nvm/versions/node/v14.18.2/lib/node_modules/why-is-node-running/node_modules/siginfo/index.js:6 - process.on('SIGUSR1', onsiginfo)
/home/mrm/.nvm/versions/node/v14.18.2/lib/node_modules/why-is-node-running/include.js:3                    - require('siginfo')(why, true)

# TTYWRAP
(unknown stack trace)

# TTYWRAP
(unknown stack trace)

# PROCESSWRAP
/tmp/test/node_modules/exiftool-vendored/dist/ExifTool.js:133                                - : _cp.spawn(o.exiftoolPath, o.exiftoolArgs, spawnOpts);
/tmp/test/node_modules/exiftool-vendored/node_modules/batch-cluster/dist/BatchCluster.js:144 - return [4 /*yield*/, this.options.processFactory()];
/tmp/test/node_modules/exiftool-vendored/node_modules/batch-cluster/dist/BatchCluster.js:56  - op = body.call(thisArg, _);
/tmp/test/node_modules/exiftool-vendored/node_modules/batch-cluster/dist/BatchCluster.js:37  - function verb(n) { return function (v) { return step([n, v]); }; }
/tmp/test/node_modules/exiftool-vendored/node_modules/batch-cluster/dist/BatchCluster.js:31  - step((generator = generator.apply(thisArg, _arguments || [])).next());

# PIPEWRAP
/tmp/test/node_modules/exiftool-vendored/dist/ExifTool.js:133                                - : _cp.spawn(o.exiftoolPath, o.exiftoolArgs, spawnOpts);
/tmp/test/node_modules/exiftool-vendored/node_modules/batch-cluster/dist/BatchCluster.js:144 - return [4 /*yield*/, this.options.processFactory()];

# PIPEWRAP
/tmp/test/node_modules/exiftool-vendored/dist/ExifTool.js:133                                - : _cp.spawn(o.exiftoolPath, o.exiftoolArgs, spawnOpts);
/tmp/test/node_modules/exiftool-vendored/node_modules/batch-cluster/dist/BatchCluster.js:144 - return [4 /*yield*/, this.options.processFactory()];

# PIPEWRAP
/tmp/test/node_modules/exiftool-vendored/dist/ExifTool.js:133                                - : _cp.spawn(o.exiftoolPath, o.exiftoolArgs, spawnOpts);
/tmp/test/node_modules/exiftool-vendored/node_modules/batch-cluster/dist/BatchCluster.js:144 - return [4 /*yield*/, this.options.processFactory()];

mceachen · 2021-12-27T22:57:09Z

Full disclosure, my consumption of exiftool-vendored always involves explicit calls to .end() on instances of the ExifTool class, which is why I was unaware of this issue.

The more I look at this, the more it looks like Node.js is missing an analogous .unref() function for file descriptors.

Your test exits immediately if I change ExifTool's SpawnOptions.stdio to "ignore", but that's invalid: I have to pipe at least stdin and stdout to get the output of exiftool.

I'll update the docs to make calling .end() a requirement to ending.

If you know of a solution, please do share, I'd be happy to add that if all existing tests also pass.

mrbrahman · 2021-12-28T17:11:56Z

Thanks.

For anyone else that might come here, I solved this by introducing emitters and listeners to the process that utilized exiftool-vendored. So, rather than depending on process.on('exit'), I created my own emitter that was able to capture the end of my process (that called exiftool-vendored), and cleanly execute exiftool.end().

mceachen · 2021-12-28T19:22:40Z

Not sure that I understand what you're asking, but to call .end() at the end of your script, you might want to just use a finally block.

import { exiftool } from "exiftool-vendored";

async function run() {
  try {
    const tags = await exiftool.read("IMG_06565.JPG");
    console.log(tags);
  } finally {
    await exiftool.end();
  }
}

void run()

mrbrahman · 2021-12-28T20:42:20Z

Initially, I thought ExifTool.end() was different from exiftool.end(). Then I realized you just meant to call the .end() explicitly, and deleted my comment.

Thanks for clarifying. I figured out I need to handle this in the calling procedures, which I noted above.

mceachen · 2021-12-28T20:46:19Z

Initially, I thought ExifTool.end() was different from exiftool.end().

Ah, I can see how that'd be confusing! I updated my comment above to clarify that I meant the ExifTool class's instance method .end().

mceachen closed this as completed Dec 27, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

node left hanging after read #106

node left hanging after read #106

mrbrahman commented Dec 27, 2021 •

edited

Loading

mceachen commented Dec 27, 2021

mceachen commented Dec 27, 2021 •

edited

Loading

mrbrahman commented Dec 28, 2021

mceachen commented Dec 28, 2021

mrbrahman commented Dec 28, 2021

mceachen commented Dec 28, 2021

node left hanging after read #106

node left hanging after read #106

Comments

mrbrahman commented Dec 27, 2021 • edited Loading

mceachen commented Dec 27, 2021

mceachen commented Dec 27, 2021 • edited Loading

mrbrahman commented Dec 28, 2021

mceachen commented Dec 28, 2021

mrbrahman commented Dec 28, 2021

mceachen commented Dec 28, 2021

mrbrahman commented Dec 27, 2021 •

edited

Loading

mceachen commented Dec 27, 2021 •

edited

Loading