Always "process did not exit on its own; invetigate what is keeping the event loop active"

[duccio]

Hello,

this code:

const http = require("http");
const { createLightship } = require("lightship");

const server = http.createServer();
server.listen(3000);

const lightship = createLightship({ detectKubernetes: false });

lightship.registerShutdownHandler(() => {
  console.log("Closing HTTP server...");
  server.close();
});

lightship.signalReady();

Produce, on SIGINT (CTRL+C), always:

{"context":{"package":"lightship","namespace":"factories/createLightship","logLevel":40},"message":"process did not exit on its own; invetigate what is keeping the event loop active","sequence":3,"time":1556275546783,"version":"1.0.0"}

[tizmagik]

~I think it's because you need to return a promise that rejects or resolves for it to wait. Your shutdown handler doesn't return anything so there's nothing for lightship to wait on.~

Hmm actually I think I have a similar question. So if you await a promise and resolve only after the server.close() callback is called it doesn't complain about the process not exiting on its own, but it still complains about handlers not running to completion. How to signal that the handler ran to completion?

For example:

  // graceful shutdown
  lightship.registerShutdownHandler(async () => {
    lightship.signalNotReady();
    logger.log("Server is shutting down...");
    await new Promise(resolve => {
      setTimeout(() => {
        logger.log("Server shutting down now.");
        server.close(resolve);
      }, 3000).unref(); // 30 seconds
    });
  });

{"context":{"package":"lightship","namespace":"factories/createLightship","logLevel":30},"message":"Lightship HTTP service is running on port 9000","sequence":0,"time":1572629608226,"version":"1.0.0"}

{"context":{"package":"lightship","namespace":"factories/createLightship","logLevel":30},"message":"signaling that the server is ready","sequence":1,"time":1572629608228,"version":"1.0.0"}
^C{"context":{"package":"lightship","namespace":"factories/createLightship","logLevel":20,"signal":"SIGINT"},"message":"received a shutdown signal","sequence":2,"time":1572629612473,"version":"1.0.0"}
{"context":{"package":"lightship","namespace":"factories/createLightship","logLevel":30},"message":"received request to shutdown the service","sequence":3,"time":1572629612474,"version":"1.0.0"}
{"context":{"package":"lightship","namespace":"factories/createLightship","logLevel":40},"message":"server is already shutting down","sequence":4,"time":1572629612474,"version":"1.0.0"}

Server is shutting down...

Server shutting down now.
{"context":{"package":"lightship","namespace":"factories/createLightship","logLevel":40},"message":"timeout occured before all the shutdown handlers could run to completion; forcing termination","sequence":5,"time":1572629672480,"version":"1.0.0"}

[Kikobeats]

I've experimented with the same problem.

This is my graceful code:

const closeServer = promisify(server.close)

lightship.registerShutdownHandler(async () => {
  debug({ status: 'shutting down' })
  clearInterval(timer)
  await delay(REQ_TIMEOUT)
  debug({ status: 'closing server' })
  await closeServer()
  debug({ status: 'shutdown' })
})

I added logs per every steps to be sure the last log is printed, and that's correct:

microlink-api status="shutting down" +1ms
microlink-api status="closing server"
microlink-api status="shutdown"

but after that, the process doesn't restart properly:

microlink-api npm ERR! code ELIFECYCLE
microlink-api npm ERR! errno 1
microlink-api npm ERR! microlink-api@2.4.8 start: `node index.js`
microlink-api npm ERR! Exit status 1
microlink-api npm ERR!
microlink-api npm ERR! Failed at the microlink-api@2.4.8 start script.
microlink-api npm ERR! This is probably not a problem with npm. There is likely additional logging output above.
microlink-api npm ERR! A complete log of this run can be found in:
microlink-api npm ERR!     /home/blessuser/.npm/_logs/2019-11-05T09_44_11_600Z-debug.log

At the beginning I thought could be a thing related to how much time Kubernetes is considering something is a timeout and instantly kill it, so I setup terminationGracePeriodSeconds to a reasonably high value, but this is still happening.

I suppose setup minikube on my local will me better insights about what's happening there.

[gajus]

This means you still have some active event handlers.

Do:

const log = require('why-is-node-running');
const closeServer = promisify(server.close)

lightship.registerShutdownHandler(async () => {
  debug({ status: 'shutting down' })
  clearInterval(timer)
  await delay(REQ_TIMEOUT)
  debug({ status: 'closing server' })
  await closeServer()
  debug({ status: 'shutdown' });
  log();
})

[Kikobeats]

Thanks for the tip, now I'm gracefully shutdown 🎉