log time

[svipas]

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]

Can you provide a simple example to reproduce the problem ?

[svipas]

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

[svipas]

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]

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]

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:

• pm2 2.4.2
• node 7.6.0
• Debian GNU/Linux 8 (x64)

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]

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]

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 :)