Application doesn't exit.

[rajapanidepu]

In a basic index.js code, I addded winston elasticsearch pointing to a server. Winston-elasticsearch trace shows successful connection, but after logging, the application doesn't exit.

Any suggestions?

[ghost]

Can you share some code example to reproduce the issue ?

[rajapanidepu]

`const winston = require('winston');
const winston_es = require('winston-elasticsearch');

const esTransportOpts = {
  name: 'es-log',
  level: 'info',
  clientOpts: {
      host: 'http://10.99.99.999:9200'
  }
};

winston.add(winston.transports.Elasticsearch, esTransportOpts);
winston.info("Hello I am winston !")
console.log("test");`

[ghost]

@vanthome will have to jump in. I haven't touched this project in a very long time. Thomas will know better. He is the one taking care of it nowadays.

I suspect either the checkEsConnection function or the elasticsearch client keepAlive (defaulted to True ) to be the issue here. I believe that you can add winston_es.client.close() to close the underlying elasticsearch client to test the assumption about the keepAlive. (un-tested though).

[eshao]

I am also having this problem.

Setting keepAlive to false doesn't work.

However, as @jackdbernier mentioned, something like winston.transports.elasticsearch.client.close() will work.

[vanthome]

ok, do you have any suggestion when to close it?
I don't think it's efficient to close it after each and every logged entry.
Usually the logging only ends when the application is stopped.

[jdxlabs]

@eshao did you really try this solution ?
it doesn't work for me.

[jdxlabs]

@eshao actually, it works when I close the client directly, but there is a latency of 1.5 seconds at the end of the script.

[christiansaiki]

Hey guys, any updates on this matter?
I'm facing the same issue here.
As @jdxlabs and @vanthome pointed, I don't think that is efficient to close the client at every log entry.
Do you have any suggestion of how to close the client in a efficient manner?

[vanthome]

@christiansaiki can you explain the actual issue, I cannot completely follow @RTSGIT words.
As far as I understand the app does not exit when you want to end it because of the open ES connection?

[christiansaiki]

@vanthome, yes!
That is the issue that I'm facing

[vanthome]

OK and what exactly means existing the application - process.exit()? In our case we stop applications mostly by stopping the container it is running in and so there is no way in node preventing a shutdown.

[edweip3]

any progress on this? what @christiansaiki means is that if you run this in a non-server application, the ES client is keeping the connection open and thus the application never exits.

[vanthome]

ok, in this case, my approach would be to get the ES client via transport.client and then just close() the connection. The problem is that such a method does not exist, I just checked. So even if the transport would take care of it, I don't see how to actively close a connection. Maybe we should ask for this on ES client... anyone?!

[bwinkers]

Would love to see a close() function.

[ScottChapman]

Tragically this makes this really unusable in production...

I tried following the Waiting for Winston logs to finish, but that flow doesn't seem to work. The finished event never gets triggered with this transport.

[vanthome]

Are you sure, have you tried with the latest Winston 3.0 based release?
You can see here in the tests that the event is called finish and that it's fired:
https://github.com/vanthome/winston-elasticsearch/blob/master/test/test.js

[ScottChapman]

Ah, the winston docs use finished. So, I do get that event.
However, I close my client when I get it, but my app still never exits. Here's the code:

var winston = require('winston');
var Elasticsearch = require('winston-elasticsearch')
var elasticsearch = require('elasticsearch')

async function main(data) {
  const client = new elasticsearch.Client({
    host: 'localhost:9200',
    log: 'trace'
  });

  const esTransportOpts = {
    level: 'info',
    client: client
  };

  const transport = new Elasticsearch(esTransportOpts);

  const logger = winston.createLogger({
    transports: [
      transport
    ]
  });

  transport.on('finish', info => {
    console.log("**** All FInished!");
    client.close();
  })
  logger.info("Transaction", data);
  logger.end();
}

var sample = {
  first: "one",
  second: 2
}

main(sample).then(resp => {
  console.log("Completed!")
  console.dir(resp);
}).catch(err => {
  console.log("Failed!")
  console.dir(err);
})

As is, the event never triggers, so client doesn't close, event gets logged, app keeps running. If I use the correct event name, client does close, but event never gets logged.

Am I missing something?

[ScottChapman]

Does anyone have an example where the app exits??

[ScottChapman]

Since I can't figure this out, I've switched to using the elasticsearch client directly which works great... But would really like to use Winston for logging...

[vanthome]

What means "client does close, but event never gets logged."? So if the client gets closed it should exit...

[ScottChapman]

Right it should, but it doesn't (at least for me).

Does anyone have any actual code example where you can log AND have the application exit?

[vanthome]

can you post the output of the logger? I want to see what you makes think that the client "does close".

[ScottChapman]

See my code above, change finished to finish. It prints the "All Finished" line and then just hangs.

[vanthome]

good, then in that event handler, can you try this (what I have proposed earlier in this thread)?

ok, in this case, my approach would be to get the ES client via transport.client and then just close() the connection. The problem is that such a method does not exist, I just checked. So even if the transport would take care of it, I don't see how to actively close a connection. Maybe we should ask for this on ES client... anyone?!

or you provide your own ES client, hold a handle to it and do the same.

[ScottChapman]

I believe that's what my code above does; I create my own ES Client, use it to initialize the transport. And I close that client when I get the finish event.

Or are you proposing something different?

[vanthome]

Yes, sorry, you are right, if you have changed the event name, it's exactly what I propose. And you are sure that there is nothing else going on in your application, and what happens if you add a process.exit()?

[ScottChapman]

Yea, that seems like a rather unfriendly approach. I mean that can't be the right approach, this just seems like a bug.

Seriously is that how folks are running with this? Only in applications which don't actually end on their own?

[NaorManna]

I also notice this issue and can't apply any of the suggested solutions.
the logger.end success trigger the on finish but because i'm working with multi logger instance the process.exit() is not an option.
any suggestions will be welcome.

[chunfengd]

This works:

transport.bulkWriter.schedule = () => {};

[njam]

It seems the timer of the BulkWriter needs to be stopped, so the program can end. Before doing that the BulkWriter should be flushed, so all messages are sent to ES.

To end the program, this works for me:

// Flush the winston stream
winston.end();
await new Promise((resolve, reject) => {
    winston.on('finish', resolve);
});

// Flush the winston-elasticsearch bulk-writer
while (transport.bulkWriter.bulk.length > 0) {
    await transport.bulkWriter.flush();
}
transport.bulkWriter.stop();
transport.client.close();

[vanthome]

I think the solution proposed by @chunfengd is better as it flushes the bulkWriter gracefully and the transport.client.close(); is not needed. I have incorporated this now in the transport itself and in the tests it works. I could remove --exit in package.json to run the mocha tests. So please guys, give me feedback whether this works for you as well.

[njam]

Nice - works fine!

I can confirm that with the new version 0.7.6 when calling winston.end() all messages are sent to ES, and then the program exits.

[trasa]

I'm still running into this problem with winston 3.1.0 and winston-elasticsearch 0.7.7 -- things almost work but I think the logger is terminating before the writer has a chance to finish writing everything.

Typically, if I'm sending less than 15 or so log entries, everything is ok, when I try and send more I get errors.

const winston = require('winston'); // 3.1.0
const winston_es = require('winston-elasticsearch'); // 0.7.7

const transportOps = {}; // use localhost, default everything 

let transport = new winston_es(transportOps);
const logger = winston.createLogger({
    transports: [
        new winston.transports.Console({
            format: winston.format.simple()
        }),
        transport
    ]});

for(let i = 0; i < 50; i++) {
    logger.info("writing data " + i);
}    

// this never fires:
logger.on('finish', info => {
    console.log("finished");
    logger.end();
});

// when this runs, I get error "TypeError: cb is not a function"
logger.end(); 

The full stack of the error (which happens many times):

TypeError: cb is not a function
at afterWrite (node_modules/readable-stream/lib/_stream_writable.js:491:3)
    at onwrite (node_modules/readable-stream/lib/_stream_writable.js:483:7)
    at WritableState.onwrite (node_modules/readable-stream/lib/_stream_writable.js:180:5)
    at bulk.forEach (node_modules/winston-elasticsearch/bulk_writer.js:85:36)
    at Array.forEach (<anonymous>)
    at client.bulk.then (node_modules/winston-elasticsearch/bulk_writer.js:85:10)
    at process.internalTickCallback (internal/process/next_tick.js:77:7)

suggestions?

[trasa]

A few changes to the above script:

// this does fire now, but things still dont work:
logger.on('finish', info => {
    console.log("XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX finished");
});
// this fires too :(
logger.on('error', e => { console.log(e); });

for (...) { logger.info( ... ); }
logger.end();

output:

Error: write after end
    at writeAfterEnd (node_modules/readable-stream/lib/_stream_writable.js:288:12)
    at Elasticsearch.Writable.write (node_modules/readable-stream/lib/_stream_writable.js:332:20)
    at DerivedLogger.ondata (node_modules/readable-stream/lib/_stream_readable.js:619:20)
    at DerivedLogger.emit (events.js:182:13)
    at DerivedLogger.Readable.read (node_modules/readable-stream/lib/_stream_readable.js:469:26)
    at flow (node_modules/readable-stream/lib/_stream_readable.js:813:34)
    at Elasticsearch.<anonymous> (node_modules/readable-stream/lib/_stream_readable.js:683:7)
    at Elasticsearch.emit (events.js:182:13)
    at onwriteDrain (node_modules/readable-stream/lib/_stream_writable.js:501:12)
    at afterWrite (node_modules/readable-stream/lib/_stream_writable.js:489:18)
XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX finished

[trasa]

Here is a working version of winston3 writing to console and elasticsearch. The only safe way I was able to get working is to poll transport.bulkWriter.bulk.length and wait for it to become zero, then call logger.end().

NOTE This doesn't work, see comments below.

const winston = require('winston'); // 3.1.0
const winston_es = require('winston-elasticsearch'); // 0.7.7
const util = require('./lib/util.js');


async function main() {

    const transportOps = {
        'clientOpts': {
            'host': 'http://localhost:9200'
        }
    };

    let transport = new winston_es(transportOps);
    const logger = winston.createLogger({
        transports: [
            new winston.transports.Console({
                format: winston.format.simple()
            }),
            transport
        ]
    });

    logger.on('finish', () => {
        console.log("XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX logger finished");
    });

    // synchronous work - must have all calls to
    // logger done before we start polling bulkWriter
    for (let i = 0; i < 50; i++) {
        logger.info("writing data " + i);
    }

    logger.info("sleeping until all writing is done...");
    // after here it is no longer safe to call logger.info()
    while (transport.bulkWriter.bulk.length > 0) {
        console.log('messages remaining: ' + transport.bulkWriter.bulk.length);
        await util.sleep(1000);
    }

    logger.end(() => {
        console.log('logger end done.');
    });
}

main();

[trasa]

Here's a version using winston3 and the default logger. Since there is no winston.end() method, we don't have a way of shutting the logger down so in a console app, we'd hang. Instead this uses process.exit() to forcibly terminate everything.

NOTE This doesn't work, see comment below...

const winston = require('winston'); // 3.1.0
const winston_es = require('winston-elasticsearch'); // 0.7.7
const util = require('./lib/util.js');

// try and use the default logger to log to elasticsearch.

var transport;

async function setupLogging() {
    console.log("setup logging");
    return new Promise(async (resolve, reject) => {

        const transportOps = {
            'clientOpts': {
                'host': 'http://localhost:9200'
            }
        };

        transport = new winston_es(transportOps);
        winston.configure({
            transports: [
                new winston.transports.Console({format: winston.format.simple()}),
                transport
            ]
        });
        transport.on('finish', () => { console.log("transport finished"); });
        transport.on('error', e => { console.log('error:' + e); });
        resolve();
    });
}

async function doWork() {
    console.log("do work");
    return new Promise(async (resolve, reject) => {
        for (let i = 0; i < 50; i++) {
            winston.info("writing data " + i);
        }
        resolve();
    });
}

async function shutdownLogging() {
    console.log("shutdown logging");
    return new Promise(async (resolve, reject) => {
        while (transport.bulkWriter.bulk.length > 0) {
            console.log('messages remaining: ' + transport.bulkWriter.bulk.length);
            await util.sleep(1000); // sleep for a little bit to flush the bulk out
        }
        // winston default logging doesn't have a "logger.end()"
        // so we try to use transport.end() instead.
        // this works maybe 50% of the time - otherwise we get cascading
        // "TypeError: cb is not a function" errors.
        // transport.end();

        resolve();
    });

}

async function main() {
    await setupLogging();

    await doWork();

    // after here it is no longer safe to call winston.log()
    await shutdownLogging();

    // since we can't stop the transport,
    // we have to forcibly terminate our application.
    process.exit(123);
}

main();

[trasa]

Ok, bad news: the above two samples do not work reliably. There is time between calling logger.info() N times and the data making it into transport.bulkWriter.bulk so that if you're unlucky (and/or manipulating sleep timers and sending to a non-localhost elasticsearch and other environmental factors...) then you'll have transport.end() or process.exit() called before all of the information is logged.

If you're calling process.exit you will not see the log messages. If you're calling transport.end then you'll get errors about write-after-end.

Back to the drawing board ...

I think the core problem is that I need to wait until all log entries have been transmitted through elasticsearch before calling logger.end() and I don't have a reliable way to know when that is.

[Fantus]

why not implement a close funtion like the mongo transport: https://github.com/winstonjs/winston-mongodb/blob/master/lib/winston-mongodb.js#L163

const Elasticsearch = require('winston-elasticsearch');

Elasticsearch.prototype.close = async function () {
    await this.bulkWriter.flush();
    this.bulkWriter.stop();
};

logger.close();

seems to do the trick for me

[vanthome]

Because we assume that the underlying ES client is what needs to be closed. @trasa can you try this and see whether it fixes the problem for you?

[trasa]

Changed my example script around to use .close() and still get problems: https://gist.github.com/trasa/f4c93846d077a740387a630f01a1d4e8
to see the example script I'm using. (Maybe I'm doing something dumb.)

The result is that we're still ending the transport before all the work has been done.

$ node winstondemo.js
setup logging
begin doing work!
info: writing data 0
info: writing data 1
info: writing data 2
info: writing data 3
info: writing data 4
info: writing data 5
info: writing data 6
info: writing data 7
info: writing data 8
info: writing data 9
info: writing data 10
info: writing data 11
info: writing data 12
info: writing data 13
info: writing data 14
info: writing data 15
work done!
closing winston_es
[winston] Attempt to write logs with no transports {"message":"writing data 32","level":"info"}
[winston] Attempt to write logs with no transports {"message":"writing data 33","level":"info"}
[winston] Attempt to write logs with no transports {"message":"writing data 34","level":"info"}
[winston] Attempt to write logs with no transports {"message":"writing data 35","level":"info"}
[winston] Attempt to write logs with no transports {"message":"writing data 36","level":"info"}
[winston] Attempt to write logs with no transports {"message":"writing data 37","level":"info"}
[winston] Attempt to write logs with no transports {"message":"writing data 38","level":"info"}
[winston] Attempt to write logs with no transports {"message":"writing data 39","level":"info"}
[winston] Attempt to write logs with no transports {"message":"writing data 40","level":"info"}
[winston] Attempt to write logs with no transports {"message":"writing data 41","level":"info"}
[winston] Attempt to write logs with no transports {"message":"writing data 42","level":"info"}
[winston] Attempt to write logs with no transports {"message":"writing data 43","level":"info"}
[winston] Attempt to write logs with no transports {"message":"writing data 44","level":"info"}
[winston] Attempt to write logs with no transports {"message":"writing data 45","level":"info"}
[winston] Attempt to write logs with no transports {"message":"writing data 46","level":"info"}
[winston] Attempt to write logs with no transports {"message":"writing data 47","level":"info"}

[trasa]

What I ended up doing is stripping the winston transport down to a minimum: no queues, just sync writes to ES. For my particular console application this is acceptable. There's lots of cases where it wouldn't be.

https://gist.github.com/trasa/1efaee47267db3de079024ec99a1c823

[barlock]

I'm having a similar issue, I've added

ElasticSearch.prototype.end = async function() {
  await this.bulkWriter.flush();
  this.bulkWriter.stop();
};

Which gets called when logger.end does.

This does end my process, but the two issues I'm having is that logger.on('finish') is never being called (which doesn't necessarily mean anything), and not all of my logs are making it to ES.

I noticed that this.bulkwriter.append is still being called after end is called.

This to me signals that end is a signal to stop, but I'm not sure how to know when we've finished getting messages.

The only thing I can think to do is somehow, after end, when append is called, just immediatly flush to keep the event loop going.

[barlock]

Edit This seems to work for continuously flushing until done

ElasticSearch.prototype.end = async function() {
  const bulkWriter = this.bulkWriter;
  bulkWriter.stop();

  await doWhilst(() => bulkWriter.flush(), () => bulkWriter.bulk.length > 0);

  this.emit('finish');
};

[athenawisdoms]

@barlock Did you manage to find a newer solution?

I used yours in this manner below, but the program is still not exiting.

const ElasticsearchWinston = require('winston-elasticsearch');

ElasticsearchWinston.prototype.end = async function() {
    const bulkWriter = this.bulkWriter;
    bulkWriter.stop();
    await doWhilst(() => bulkWriter.flush(), () => bulkWriter.bulk.length > 0);
    this.emit('finish');
};

let logger = winston.createLogger({
    exitOnError: false,
    transports: [
        new (winston.transports.DailyRotateFile)(options.file),
        new winston.transports.Console(options.console),
        new ElasticsearchWinston(options.elasticsearch)
    ]
});

[vanthome]

Is this still an issue?

[nesjett]

I'm still having the issue. Although I see this MR #141

I'm using:
"winston": "^3.6.0", "winston-elasticsearch": "^0.16.1"

Aditional info:

• Tried closing Elastic client, and also flush(), end() and destroy() on the elastic transport -> None worked.

• Even if I don't add the Elastic transport to winston (but still create the ElasticTransport instance in lets say an independent constant) -> The program hangs at the end.

• If I don't create instances of Elastic Transport (but I do isntances of winston and ES client) -> The program ends properly

Conclusion:, I can confirm that the issue seems still to be happening on the elasticsearch transport from this library.

[vanthome]

ok, can you try to do the follwoing (maybe you even already know): what if you set buffering to false, then I suppose the issue is gone?
In this case, I think, we can try to add a this.bulkWriter.stop() here with enabled buffering:

https://github.com/vanthome/winston-elasticsearch/blob/master/index.js#L107

Maybe you can even try this?