v3.7.0 logging "DEBUG server req-resp mode"

[frankfil]

Shlink version

3.7.0

PHP version

8.2.12

How do you serve Shlink

RoadRunner Docker image

Database engine

MySQL

Database version

5.7

Current behavior

After upgrading from v3.4.0 to v3.7.0 we are seeing the following log entries every 10 seconds, which matches the timing of the health checks being performed by Kubernetes (assuming this is the reason of course):

2023-11-28T00:22:03+0000	DEBUG	server      	req-resp mode	{"pid": 40}
2023-11-28T00:22:13+0000	DEBUG	server      	req-resp mode	{"pid": 41}
2023-11-28T00:22:23+0000	DEBUG	server      	req-resp mode	{"pid": 42}
2023-11-28T00:22:33+0000	DEBUG	server      	req-resp mode	{"pid": 43}

Looking at the RoadRunner config in the container config/roadrunner/.rr.yml and it appears that some type of logging debug level is enabled:

logs:
  mode: production
  channels:
    http:
      mode: 'off' # Disable logging as Shlink handles it internally
    server:
      level: debug # Everything written to worker stderr is logged

Should this debug logging level be enabled?

And if this is the cause of the debug logs, can we disable it?

Expected behavior

Health check calls are no longer logged, which is correct but something else is being logged instead.

How to reproduce

Deploy shlinkio/shlink:3.7.0-non-root and perform HTTP calls to /rest/health.

[acelaya]

Please, try not to report a bug for something which actually has no impact on Shlink normal behavior.

When you need to understand an underlying aspect of the service, open a discussion instead.

RoundRunner logging is a bit confusing and it's been hard to get it right. These lines seem to be logged for every request? It's hard to tell.

Setting server log level to debug is what used to be recommended by the docs (in fact I think that config was automatically generated with that value), otherwise there were important information missing. But it seems to be logging too much information now.

I'll try to fine tune the config to see if it improves.

[acelaya]

See #1939

[frankfil]

Just did a test running the following locally:

docker run --rm -it -p 8080:8080 shlinkio/shlink:3-roadrunner

Then hitting http://localhost:8080/rest/health from another terminal and that debug line is logged on each call.

In hindsight I should have run this test before creating a discussion (and apologies yes I should not have raised a bug issue for this).

[acelaya]

I was testing a bit yesterday with other combinations.

• Those lines are definitely logged on every request to any route.
• Increasing the log level from debug to info removes those lines, but it also removes any information regarding available workers, worker rotation and background job processing (the last one is the most important).
• Using a different mode doesn't have an obvious difference. The docs explain you should use production mode, but they don't explain why, or what's the difference between modes.

I think what I should do is rely less in roadrunner logs, and make Shlink log what's missing itself, like it's done with access logs.

That would couple Shlink less with roadrunner.

[acelaya]

I have found out it is possible define different logs config for server and jobs channels, meaning it is possible to keep the info about background jobs by keeping debug for that channel, and increase the server logs to info, getting rid of these server req-resp mode lines.

I'll try to decouple it for a future minor/major version, and keep a patch to the very minimum.

[acelaya]

I have just released v3.7.1 which changes roadrunner config to log less useless stuff.

[frankfil]

Upgraded to 3.7.1 and all good.

Thank you @acelaya