[LOGS] Monolog StreamHandler message is being split by RR with STDERR

[7krasov]

Hi guys,
I would like to clarify if there is an option to increase a message length that is being logged to stream without splitting on a few messages? Or, what is the right way to log long messages to a stream?
How to reproduce my issue:

RR config

logs:
  mode: production
  output: stdout
  err_output: stderr
  encoding: json
#  line_ending: "\n"
  channels:
    http:
      mode: production
      level: info
      encoding: json
      output: stdout
      err_output: stderr
    server:
      mode: production
      level: info
      encoding: json
      output: stdout
      err_output: stderr
    rpc:
      mode: production
      level: info
      encoding: json
      output: stdout
      err_output: stderr

1. on API request through RR, STDERR output in worker.php

$handler = new StreamHandler(('php://stderr'));
$handler->setFormatter(new LogstashFormatter('PSS'));
$logger = new Logger('PSS',[$handler]);
$appLogger->info('TEST MESSAGE', ['test_value' => str_pad('', 32600,'A')]);

RESULT:

docker-compose logs -f pss_rr
pss_rr       | [INFO] RoadRunner server started; version: 2.8.8, buildtime: 2022-03-31T10:43:33+0000
pss_rr       | {"level":"info","ts":1654943471.2050817,"logger":"server","msg":"{\"@timestamp\":\"2022-06-11T10:31:11.201417+00:00\",\"@version\":1,\"host\":\"4c8ab2b317e9\",\"message\":\"TEST MESSAGE\",\"type\":\"PSS\",\"channel\":\"PSS\",\"level\":\"INFO\",\"monolog_level\":200,\"context\":{\"test_value\":\"AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
.....
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA"}
pss_rr       | {"level":"info","ts":1654943471.2060363,"logger":"server","msg":"AAAAAAAAAAAAAAAAAAAAAAAAAAAAAA\"}}\n"}

As you can see, a message is split on two and wrapped with RR wrapper

2. Using STDOUT:

$handler = new StreamHandler(('php://stdout'));
$handler->setFormatter(new LogstashFormatter('PSS'));
$logger = new Logger('PSS',[$handler]);
$appLogger->info('TEST MESSAGE', ['test_value' => str_pad('', 32600,'A')]);

OUTPUT:

pss_rr       | [INFO] RoadRunner server started; version: 2.8.8, buildtime: 2022-03-31T10:43:33+0000
pss_rr       | {"level":"warn","ts":1654943754.880412,"logger":"server","msg":"network error, worker will be restarted","reason":"network","pid":15,"internal_event_name":"EventWorkerError","error":"sync_worker_exec: Network:\n\tsync_worker_exec_payload:\n\tgoridge_frame_receive: CRC verification failed, bad header: {\"@timestamp\":\"2022-06-11T10:35:54.878237+00"}
pss_rr       | {"level":"error","ts":1654943754.8805096,"logger":"http","msg":"execute","start":1654943754.798306,"elapsed":0.082202166,"error":"sync_worker_exec: Network:\n\tsync_worker_exec_payload:\n\tgoridge_frame_receive: CRC verification failed, bad header: {\"@timestamp\":\"2022-06-11T10:35:54.878237+00"}

With some RR settings (raw, console or smth else, can't reproduce right now) I managed to output the entire message with STDOUT but had the same info in the RR json wrapper: sync_worker_exec: Network:\n\tsync_worker_exec_payload:\n\tgoridge_frame_receive: CRC verification failed, bad header

So far I didn't find any evidence that Monolog breaks this, because if I create a separate test.php file and run it with PHP-CLI, not RR, I can have a message entire, printed in my console and not splitted

Could you please help to get my container stream correct?
I need it for filebeat autodiscover, so this stream messages will be sent to logstash

Thank you!

[rustatian]

Hello @7krasov 👋🏻.
sync_worker_exec: Network:\n\tsync_worker_exec_payload:\n\tgoridge_frame_receive: CRC verification failed, bad header
You'll see the entire message if you update to the v2.10.4.

[rustatian]

As you mentioned before, you may also use a mode: raw:

logs:
  mode: raw
  output: stdout
  err_output: stderr
  encoding: console

[rustatian]

Also, if updating and setting to raw mode doesn't help, try to use development mode. I guess you're faced with a log sampler: https://github.com/uber-go/zap/blob/master/FAQ.md#why-sample-application-logs. In the mode: development sampler will be turned off.

[7krasov]

Hello @rustatian,
Thank for the quick reply!

You'll see the entire message if you update to the v2.10.4.

Yes, I tried to upgrade before but rolled back my image

Now, I upgraded again to 2.10.4

Set only global config as you suggested

logs:
  mode: raw
  output: stdout
  err_output: stderr
  encoding: console

On STDERR nothing is changed regarding message splitting. It is still split with
modes: production, raw, development
encodings: console, json

On STDOUT all such config combinations are output:

pss_rr       | http server was started	{"address": "0.0.0.0:8082"}
pss_rr       | network error, worker will be restarted	{"reason": "network", "pid": 16, "internal_event_name": "EventWorkerError", "error": "sync_worker_exec: Network:\n\tsync_worker_exec_payload:\n\tgoridge_frame_receive: CRC verification failed, bad header: {\"@timestamp\":\"2022-06-11T14:32:06.470585+00:00\",\"@version\":1,\"host\":\"6bd1a79e3aff\",\"message\":\"TEST MESSAGE\",\"type\":\"PSS\",\"channel\":\"PSS\",\"level\":\"INFO\",\"monolog_level\":200,\"context\":{\"test_value\":\"AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
....
AAAAAAAAAAAAAAAAAAAAAAA\"}}\n"}
pss_rr       | execute	{"start": 1654957924030197564, "elapsed": 4443547977, "error": "sync_worker_exec: Network:\n\tsync_worker_exec_payload:\n\tgoridge_frame_receive: CRC verification failed, bad header: {\"@timestamp\":\"2022-06-11T14:32:06.470585+00:00\",\"@version\":1,\"host\":\"6bd1a79e3aff\",\"message\":\"TEST MESSAGE\",\"type\":\"PSS\",\"channel\":\"PSS\",\"level\":\"INFO\",\"monolog_level\":200,\"context\":{\"test_value\":\"AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
......
AAAAAAAAAAAAAAAAAAAAAAAAAAAAA\"}}\n"}
pss_rr       | worker stopped	{"internal_event_name": "EventWorkerWaitExit", "error": "signal: killed; process_wait: signal: killed", "errorCauses": [{"error": "signal: killed"}, {"error": "process_wait: signal: killed"}]}
pss_rr       | worker is allocated	{"pid": 24, "internal_event_name": "EventWorkerConstruct"}

I can see these messages right after after
$appLogger->info('TEST MESSAGE', ['test_value' => str_pad('', 32600,'A')]);

But, it is occurred even if I don't raise message length. For each settings combination. It seems like
$workerPsr->respond($response);
breaks response with a condition that message was logged before in STDOUT. If no message was logged during the working cycle, no error occurred then. Package spiral/roadrunner has version 2.10.4 installed.

pss_rr       | 2022-06-12T09:30:18.540Z	WARN	server      	network error, worker will be restarted	{"reason": "network", "pid": 16, "internal_event_name": "EventWorkerError", "error": "sync_worker_exec: Network:\n\tsync_worker_exec_payload:\n\tgoridge_frame_receive: CRC verification failed, bad header: {\"@timestamp\":\"2022-06-12T09:30:16.537000+00:00\",\"@version\":1,\"host\":\"6bd1a79e3aff\",\"message\":\"TEST MESSAGE\",\"type\":\"PSS\",\"channel\":\"PSS\",\"level\":\"INFO\",\"monolog_level\":200}\n\u0014\u0000A\u0000\u0000\u0000v\ufffd-\n\u0000\u0000?\u0000\u0000\u0000{\"status\":200,\"headers\":{\"content-type\":[\"application\\/json\"]}}[]"}
pss_rr       | 2022-06-12T09:30:18.540Z	ERROR	http        	execute	{"start": "2022-06-12T09:30:16.474Z", "elapsed": "2.065691746s", "error": "sync_worker_exec: Network:\n\tsync_worker_exec_payload:\n\tgoridge_frame_receive: CRC verification failed, bad header: {\"@timestamp\":\"2022-06-12T09:30:16.537000+00:00\",\"@version\":1,\"host\":\"6bd1a79e3aff\",\"message\":\"TEST MESSAGE\",\"type\":\"PSS\",\"channel\":\"PSS\",\"level\":\"INFO\",\"monolog_level\":200}\n\u0014\u0000A\u0000\u0000\u0000v\ufffd-\n\u0000\u0000?\u0000\u0000\u0000{\"status\":200,\"headers\":{\"content-type\":[\"application\\/json\"]}}[]"}
pss_rr       | 2022-06-12T09:30:18.545Z	DEBUG	server      	worker stopped	{"internal_event_name": "EventWorkerWaitExit", "error": "signal: killed; process_wait: signal: killed", "errorCauses": [{"error": "signal: killed"}, {"error": "process_wait: signal: killed"}]}
pss_rr       | 2022-06-12T09:30:18.715Z	DEBUG	server      	worker is allocated	{"pid": 22, "internal_event_name": "EventWorkerConstruct"}

So STDOUT usage seems to be a bit offtop (for STDOUT even a small message causes an error)
Sorry, I haven't found an answer in Discussions and Issues about the error

My further questions:

1. Should I try separate log settings as I did before instead of global settings?
   Because I see you expect this

In the mode: development sampler will be turned off.

but it still splits with development mode for STDERR. Maybe, it is forced to be sampled for STDERR? in what stream do you expect exactly development mode to disable sampling?

2. What is the correct way to log, in STDOUT or STDERR?
   I have found your message [🐛 BUG]: Worker crashed when write logs to stdout #873 (comment) and here it said that we're able to use STDOUT, but in my case, I can't succeed here

3. Should I create a new issue/discussion for error on $workerPsr->respond($response); after logging to STDERR in 2.10.4?

Thank you for the support!

[rustatian]

Should I try separate log settings as I did before instead of global settings?

Yeah, but this won't help you. Tho, if you want to have a separate log configuration per plugin, you may use your previous config.

What is the correct way to log, in STDOUT or STDERR?

STDERR

and here it said that we're able to use STDOUT, but in my case, I can't succeed here

You can use STDOUT, after complete worker initialization in the while loop. I'm not a PHP dev, but IIRC we have an interceptor for the STDOUT, which will redirect your logs to the STDERR anyway.

Should I create a new issue/discussion for error on $workerPsr->respond($response); after logging to STDERR in 2.10.4?

Yeah, you may create a bug with a full description, and a complete worker sample to have the ability to reproduce your issue.

[7krasov]

Should I create a new issue/discussion for error on $workerPsr->respond($response); after logging to STDERR in 2.10.4?

Yeah, you may create a bug with a full description, and a complete worker sample to have the ability to reproduce your issue.

Sorry, @rustatian, that was my mistype, a meant STDOUT, not STDERR.
In my case, STDERR doesn't break logging, just uses a sampler. So no sense to create a bug issue for STDOUT logging inside PHP, unless you want to debug/fix an interceptor

Regarding the sampling https://github.com/uber-go/zap/blob/master/FAQ.md#why-sample-application-logs
Are we able to adjust a length somehow or make a new feature request to do this? Sorry, it is not clear to me whether it depends on uber-go/zap or on rr (length adjusting feature)

Thank you!

[rustatian]

Should I create a new issue/discussion for error on $workerPsr->respond($response); after logging to STDERR in 2.10.4?

Yeah, you may create a bug with a full description, and a complete worker sample to have the ability to reproduce your issue.

Sorry, @rustatian, that was my mistype, a meant STDOUT, not STDERR. In my case, STDERR doesn't break logging, just uses a sampler. So no sense to create a bug issue for STDOUT logging inside PHP, unless you want to debug/fix an interceptor

Regarding the sampling https://github.com/uber-go/zap/blob/master/FAQ.md#why-sample-application-logs Are we able to adjust a length somehow or make a new feature request to do this? Sorry, it is not clear to me whether it depends on uber-go/zap or on rr (length adjusting feature)

Thank you!

No problem 😃 At the moment there is no such option to adjust this parameter. To start working on that problem, please, create an issue in the RR repo, put here your worker sample, and steps on how to reproduce the issue. Based on this bug, I'll either add an option to configure the sample rate or it might be some bug in the logger.

[7krasov]

Here is a new issue report #1171, I hope there is enough information)

Thanks for your time!

[rustatian]

My pleasure 👍🏻

[rustatian]

Starting from the v2.10.5 RR will show unspotted logs up to 64Kb.