Active handle/Interval prevents node script exit on Ubuntu 14.04

[chasdevs]

When running a node script on Ubuntu 14.04, winston-loggly-bulk seems to keep an open handler which causes my script to hang (prevents exit).

Using the wtf-node package, I show this upon my script's completion:

- File descriptors: (note: stdio always exists)
  - fd 1 (tty) (stdio)
  - fd 2 (tty) (stdio)
- Intervals:
  - (30000 ~ 30 s) (anonymous) @ /home/ubuntu/<project>/node_modules/node-loggly-bulk/lib/loggly/common.js:224

[mostlyjason]

Interesting hopefully we can have someone look into this in the next few weeks. Let us know if you figure out the solution before we do.

[chasdevs]

Yeah it was a little odd. I ended up falling back on the winston-loggly transport in the meantime.

[sribatchu]

+1. Same issue (process hangs)

[bnayalivne]

Same here. tried using for AWS Lambda function and wasn't able to understand why it gets timed out.

[chasdevs]

Switching to the upstream winston-loggly removed the timeout issue for me.

[mostlyjason]

Thanks everyone for reporting this! Seems to be a common issue for many users. I'm adding it to the next sprint for our developer.

[krazik]

can anyone help/explain what Switching to the upstream winston-loggly removed the timeout means? what do I switch and where? (I'm also experiencing this issue, only on our staging env)

[chasdevs]

I just mean my temporary solution was changing to the original repo by winstonjs: https://github.com/winstonjs/winston-loggly. Their module supported our (currently minimal) logging needs but did not have a hanging connection.

[mostlyjason]

Hey guys can you tell us what version of node you are using? We are testing with the latest stable version which is 6 and unable to reproduce so far. Any other information you can offer about your environment or the situations you see this occurring in would be helpful.

[chasdevs]

I was on node v6.9.5.

This may be extremely tough to track down. I was using the bluebird Promise library in conjunction with just a standard winston implementation; no other major funkiness, except for a couple mysql connections which should be unrelated. The script would hang when running from the command line and reaching the end of the script. If I get some free time I will attempt to recreate it in the simplest way possible.

[mostlyjason]

@cdeveas great that would be very helpful! We will keep trying different scenarios on our end too

[Shwetajain148]

@cdeveas @sribatchu I was not able to reproduce the node process hang issue as you reported above . So I need some additional information that will help me to reproduce it at my end. So I have some queries regarding this which are listed below.

1. Are you experiencing process hang issue consistently or occasionally ?
2. At what rate are you sending the events?
3. What was average event size?

Thanks

[mostlyjason]

We tried running this package in several distributions and under different scenarios like a network outage, promises, and long-running time and they all worked. We're happy to test your environment setup if you provide the details. If we can't reproduce this issue, we will be unable to move forward.

I'd consider using the old winston-loggly a temporary solution only. The main benefits of this package are that the bulk mode is better at handling high volume logs without slowing your app and can handle network outages without exhausting your memory. We'd to encourage people to use this version.

[chasdevs]

Definitely makes sense. Our project will have some breathing room in the near future, and I will be able to try and reproduce then.

Our main app (not the one-time script which caused this bug for me) is a continuously-running server, so I will begin using this package again there.

[btamayo]

@mostlyjason Any progress on this issue?

Getting the exact same problem with the remaining open handler, which seems to be this interval:

timerFunctionForBufferedLogs = setInterval(function () {
 // ...
    }, bufferOptions.retriesInMilliSeconds); 

wtf-node reports:

- File descriptors: (note: stdio always exists)
  - fd 1 (tty) (stdio)
  - fd 2 (tty) (stdio)
- Intervals:
  - (30000 ~ 30 s) (anonymous) @ /Users/btamayo/Development/loggerProject/node_modules/node-loggly-bulk/lib/loggly/common.js:224

See if you can reproduce the issue with this please:

Environment info:

• OS: macOS Sierra (10.12.6)

• Node version: v8.3.0

• winston-loggly-bulk package version:

"winston-loggly-bulk": {
    "version": "2.0.0",
    "resolved": "https://registry.npmjs.org/winston-loggly-bulk/-/winston-loggly-bulk-2.0.0.tgz",
    "integrity": "sha1-olOCeBihS7b+CwbMHCLY0+19EoA=",
    "requires": {
        "node-loggly-bulk": "2.0.0",
        "winston": "2.3.1"
    }
}

Code:

Modified timerFunctionForBufferedLogs interval to show output:

Various console.log calls:

// ./node-loggly-bulk/lib/loggly/common.js:224

if (timerFunctionForBufferedLogs === null) {
    console.log('Pre-timerFunctionForBufferedLogs interval decl, bufferOptions:');
    console.log(bufferOptions);
    timerFunctionForBufferedLogs = setInterval(function () {
      console.log('[!] timerFunctionForBufferedLogs() interval called');
      if (arrBufferedMsg.length) {
        console.log('arrBufferedMsg.length: ', arrBufferedMsg.length);
        sendBufferdLogstoLoggly();
      }
    }, bufferOptions.retriesInMilliSeconds);
  }

Runner

#!/usr/bin/env node

require('dotenv').config();  // To load the API token

const winston = require('winston');
require('winston-loggly-bulk');

winston.add(winston.transports.Loggly, {
  inputToken: process.env.LOGGLY_API_TOKEN,
  subdomain: "sampledomain",
  tags: ["debug-winston-loggly-bulk"],
  json: true,
  level: 'info'
});

winston.remove(winston.transports.Console);

winston.info('An info statement')
winston.debug('A debug statement');
winston.warn('A warn statement');
winston.error('An error statement');

return;

Output:

$ ./log-debug.gitignore.js
Pre-timerFunctionForBufferedLogs interval decl, bufferOptions:
{ size: 500, retriesInMilliSeconds: 30000 }
[!] timerFunctionForBufferedLogs() interval called # printed every 30s
[!] timerFunctionForBufferedLogs() interval called 
[!] timerFunctionForBufferedLogs() interval called
[!] timerFunctionForBufferedLogs() interval called

Does not exit the process.

Note that it only hangs when it tries to send logs. Including the module and the transport itself but preventing it from sending logs does not create/leave in the handler.

[btamayo]

Update: The uncleared timers seems to be the culprit for this issue and #13.

setInterval timers need to be cleared, e.g: loggly/node-loggly-bulk#14

[mostlyjason]

Awesome thanks for the detailed investigation @btamayo! We'll have one of our engineers evaluate this.

[mostlyjason]

We released an update for version 2.0.1 which we believe contains a fix for this issue. Thanks for the help from @btamayo! Please reopen if it happens again after updating.