merge_logs flag is causing each process per request when cluster_mode is on to write to the log

[askhogan]

Logger is writing multiple logs when merge_logs flag is set to true and cluster_mode is true.

This makes it appear as though all processes are working on the same request, so it makes it appear that the cluster_mode has a bug in it. However, if the merge_logs flag is off it doesn't occur. So this is a logging issue.

SUGGESTION: If using cluster mode and this is occurring to you, set merge_logs to false

process.json

{ "apps" : [{ "exec_interpreter" : "node", "exec_mode" : "cluster_mode", "instances" : 0, "log_date_format" : "YYYY-MM-DD HH:mm Z", "max_memory_restart" : "160", "merge_logs" : true, "name" : "testapp", "script" : "server.js", "cwd" : "dashboard", "node_args" : "--harmony", "ignoreWatch" : ["[\/\]./", "log"], "watch" : true }] } dashboard/server.js

var express = require('express'); var app = express();

app.get('/', function (req, res) { console.log("req", req.method, req.url); res.send('hey from pm2 worker #' + process.env.pm_id + '\n' + new Date()); });

var server = app.listen(3045, function () { var host = server.address().address; var port = server.address().port; console.log('Example app listening at http://%s:%s', host, port); }); node 0.12 pm2 0.12.5

Run the command pm2 start process.json Run the command pm2 logs

Then run a GET command to http://localhost:3045/

pm2 logs outputs a console.log for each worker process

testapp-3 (out): 2015-02-15 14:55 -06:00: req GET /? testapp-4 (out): 2015-02-15 14:55 -06:00: req GET /? testapp-2 (out): 2015-02-15 14:55 -06:00: req GET /? testapp-1 (out): 2015-02-15 14:55 -06:00: req GET /? testapp-0 (out): 2015-02-15 14:55 -06:00: req GET /? testapp-7 (out): 2015-02-15 14:55 -06:00: req GET /? testapp-5 (out): 2015-02-15 14:55 -06:00: req GET /? testapp-6 (out): 2015-02-15 14:55 -06:00: req GET /? However in the GET request response you get just one reply from one worker

hey from pm2 worker #6 Sun Feb 15 2015 14:55:01 GMT-0600 (CST)

[bwin]

Ok, if merge_logs is true I can reprodce this. (Although it doesn't make sense to me.)

[bwin]

If you modify the server.js to log which worker actually responded it becomes clearer whats happening:

...
app.get('/', function (req, res) {
    console.log('['+process.env.pm_id+']', req.method, req.url); // <-
    res.send('hey from pm2 worker #' + process.env.pm_id + '\n' + new Date());
});
...

Then the output of pm2 logs testapp after one request is:

testapp-35 (out): 2015-02-16 17:29 +01:00: [36] GET /
testapp-36 (out): 2015-02-16 17:29 +01:00: [36] GET /
testapp-37 (out): 2015-02-16 17:29 +01:00: [36] GET /
testapp-38 (out): 2015-02-16 17:29 +01:00: [36] GET /

That shows, that only one worker responded. So definitely a logging issue.

With pm2 info testapp you can check where the actual logfile is. Looking into it you will see, there is only 1 entry in there. So up to this point everything is ok.

pm2 logs testapp will show your logs for each instance of testapp (which in case of merge_logs: true is just one log file), so the one log line will get displayed multiple times. This is actually a bug.

I always set merge_logs to false, because pm2 logs will merge the log entries on the fly for me. Edit: correction: I don't explicitly set it to false, I just don't set it to true.

[askhogan]

@bwin makes sense to me. The way I and Thomas came to this was due to the example for cluster which defaults to true. I was a newcomer to PM2, so it just threw me off. Totally understand now it was benign, but my mindset then was it gave me a lack of confidence to move forward.

https://github.com/Unitech/PM2/pull/1022

Potentially with this pull it wont affect newcomers as much

[jshkurti]

@Tjatse, can you take a look at it ? :)

Thanks.

[bwin]

Short version: When using clusterMode and mergeLogs the actual log is ok. When viewing logs with pm2 logs pm2 shows logs from the same log file (since there is only one) for each instance. It prepends the appName and workerId, so it seems that more than one worker responded to a request.

A possible solution would (in case of merge_logs: true) be, to prepend only the appname (since pm2 can't know from which worker a log msg was) and show the log entries once. Having said that, it may be a bad idea to use clusterMode and mergeLogs because you would have to manually log what instance was responsible. Seems unnecessary to me. And not having the info which instance logged something seems stupid to me since this is essential information. So maybe, just discourage(/forbid?) the use of mergeLogs [in clusterMode]? (It only makes sense in clusterMode in the first place or am I missing something?).

[jshkurti]

Related #925

[soyuka]

1042 should fix this.

$ npm install git://github.com/Unitech/pm2#development -g

[soyuka]

@askhogan is this fixed?