search

Unitech / pm2

Node.js Production Process Manager with a built-in Load Balancer.
https://pm2.keymetrics.io/docs/usage/quick-start/
Other
41.15k stars 2.6k forks source link

log time #2792

Open svipas opened 7 years ago

svipas commented 7 years ago

Expected behaviour

0|server   | 2017-03-25 18:29:46.4920: Using files from public directory.
0|server   | 2017-03-25 18:29:46.5040: Server successfully launched at http://localhost:3000?react_perf (development)
0|server   | 2017-03-25 18:29:46.5040: To profile components open Chrome DevTools Timeline tab. Events grouped under User Timing.
0|server   | 2017-03-25 18:29:46.5040: To stop development server use yarn pm2:stop
0|server   | 2017-03-25 18:29:46.5040: ———————————————————————————————————————————————————————————————————————————
0|server   | 2017-03-25 18:29:49.6250: webpack built 49b71f7f794f7dcf59f8 in 3146ms

Actual behaviour

0|server   | 2017-03-25 18:29:46.4920: Using files from public directory.
0|server   | 2017-03-25 18:29:46.5040: Server successfully launched at http://localhost:3000?react_perf (development)
0|server   | 2017-03-25 18:29:46.5040: To profile components open Chrome DevTools Timeline tab. Events grouped under User Timing.
0|server   | To stop development server use yarn pm2:stop
0|server   | 2017-03-25 18:29:46.5040: ———————————————————————————————————————————————————————————————————————————
0|server   | 2017-03-25 18:29:49.6250: webpack built 49b71f7f794f7dcf59f8 in 3146ms

Problem

As you can see I don't get time for To stop development server use yarn pm2:stop and this happens randomly...

Software versions used

OS         : Linux Ubuntu 16.04
node.js    : 7.7.4
PM2        : 2.4.2
vmarchaud commented 7 years ago

Can you provide a simple example to reproduce the problem ?

svipas commented 7 years ago

Check my gist repo https://github.com/svipben/react-boilerplate

svipas commented 7 years ago

As I say it happens randomly, so right now I get this:

0|server   | 2017-03-25 21:25:09.4640: Using files from public directory.
0|server   | 2017-03-25 21:25:09.4730: Server successfully launched at http://localhost:3000?react_perf (development)
0|server   | 2017-03-25 21:25:09.4730: To profile components open Chrome DevTools Timeline tab. Events grouped under User Timing.
0|server   | To stop development server use yarn pm2:stop
0|server   | ——————————————————————————————————————————————————————————————————————————————————————————
0|server   | 2017-03-25 21:25:13.1200: webpack built 53eb2450da59992a473f in 3679ms

As you can see not all messages get log time.

sumeetkpatel commented 7 years ago

I am experiencing the same behavior everywhere that I use PM2. I think it has something to do with the speed of log calls or perhaps async nature of the log calls. Whilst random, it seems highly reproducible.

Example

ecosystem.config.js

module.exports = {
  apps : [
    {
      "name": 'test',
      "script": 'test.js',
      "log_date_format": "YYYY-MM-DD HH:mm",
    },
  ]
};

test.js

for (var i = 0; i < 500; i++) {
    console.log(i);
}

Start it

pm2 start ecosystem.config.js pm2 logs

Example output:

3|test     | 2017-06-04 16:08: 0
3|test     | 2017-06-04 16:08: 1
3|test     | 2017-06-04 16:08: 2
3|test     | 3
3|test     | 4
3|test     | 2017-06-04 16:08: 5
3|test     | 6
3|test     | 7
3|test     | 8
3|test     | 9
3|test     | 2017-06-04 16:08: 10

Code for above: issue 2792.tar.gz

warpdesign commented 7 years ago

I am running into the same issue.

This is how I start my node app: pm2 start js/server.js --name node_export --log-date-format="DD-MM-YYYY HH:mm"

And here is an extract of my log:

0|node_exp | 04-08-2017 11:36: adding file NOMIA_ACCOUNT/962/ATT_ELJ_ICON/fr/Logo_OnMap attributeId: 89
0|node_exp | 04-08-2017 11:36: need to add file NOMIA_ACCOUNT/962/ATT_ELJ_ICON/fr/Logo_OnMap
0|node_exp | adding file 66f0a294-0db1-4c11-8ccf-260a6c4cdeb5/246858/ATT_ELJ_BACKGROUND_IMAGE/fr/Agence_SicoBank_floutA_ attributeId: 86
0|node_exp | 04-08-2017 11:36: need to add file 66f0a294-0db1-4c11-8ccf-260a6c4cdeb5/246858/ATT_ELJ_BACKGROUND_IMAGE/fr/Agence_SicoBank_floutA_
0|node_exp | 04-08-2017 11:36: [export] success http://localhost:8080/OnMapV6/rest/mission/6dc4eb13-76da-489b-9eed-d5de346ee897/flownodethresholdobjectifs
0|node_exp | 04-08-2017 11:36: [export] success http://localhost:8080/OnMapV6/rest/game/416e0312-fd2f-40ab-8fcf-5b44d3170030/mission/6dc4eb13-76da-489b-9eed-d5de346ee897/config/249379
0|node_exp | 04-08-2017 11:36: adding iconUrl: icones/default.png

It happens randomly but quite often.

Some details:

update: I tried updating to the latest version (2.6.1) and it's worse: I'm getting lots of lines where the time isn't appended as expected.

sumeetkpatel commented 6 years ago

Having a look at lib/God/ForkMode.js it appears that each 'data' event from stdout contains multiple lines of output and the timestamp is only prefixed once per 'data' payload. This should explain the unexpected behavior somewhat, but why are multiple lines coming through each stdout 'data' event? Just normal stream byte chunking, but at least each payload has a complete lines.

One hacky solution would be to split 'data' on '\n' and simply prefix each 'line' with the timestamp and output that instead. I did implement this and it does work.

Hack Solution A:

lib/God/ForkMode.js: ~ line 164

var lines = data.toString().split('\n');
var formatted = [];
for (var i = 0; i < lines.length - 1; i++) {
   if (pm2_env.log_date_format){
     formatted.push(moment().format(pm2_env.log_date_format) + ': ' + lines[i]);
  }
  else {
     formatted.push(lines[i]);
  }
}
log_data = '\n' + formatted.join('\n');

Example output:

0|test     | 2017-08-11 17:18: 0
0|test     | 2017-08-11 17:18: 1
0|test     | 2017-08-11 17:18: 2
0|test     | 2017-08-11 17:18: 3
0|test     | 2017-08-11 17:18: 4
0|test     | 2017-08-11 17:18: 5
0|test     | 2017-08-11 17:18: 6
0|test     | 2017-08-11 17:18: 7
0|test     | 2017-08-11 17:18: 8
0|test     | 2017-08-11 17:18: 9
0|test     | 2017-08-11 17:18: 10

There are many instances of this type of chunk handling in many places (stdout, stderr, formatted/unformatted) and the timestamps basically end up grouped/inaccurate, but something better isn't really possible within the process container stdout structure.

Is there a better way?

Wouter0100 commented 6 years ago

At first, thanks for PM2. Really loving the experience so far.

Although unfortunately this issue is still open, but there is a PR for this? Why is that not merged yet - if I may ask? Would be really useful to have fixed in pm2. Currently experiencing the same issue, where consistently prefixes are missing.

3087 @vmarchaud @Unitech

Thanks :)