[Messenger][UX] make basic operational messages from messenger:consume NOTICE instead of INFO

[dkarlovi]

Description

When messenger:consume is running, the verbosity level determines how much logs you get. This, in a cloud environment, translates to money.

With no verbosity, you get basically nothing. Same with -v.

But, with -vv you start getting messages

1. message received
2. all the processing
3. message acknowledged

The issue is, this is either "nothing" or "a lot" (depending on what other loggers start spewing INFO messages, for example FOS Elastica starts outputting full requests / responses at this level, HTTP client will output all requests, etc). This can mean a lot of output gets collected from your workers.

Example

Ideally, we'd have a middle ground where -v produces just enough output to make sure the worker is still running, like

1. message received (optional?)
2. message acked / nacked
3. shutdown

This allows using verbosity more granularly where the developer wants to optimize log costs, while still getting a decent baseline of information.

[cizordj]

Sorry for the ignorance, but what's the difference between NOTICE and INFO? If the messages fall under the NOTICE category, then I don't see any issue with this change.

[dkarlovi]

AFAIK, NOTICE will get outputted with -v, while INFO will not. It's still the same type of log, basically:

INFO - expected thing happened
NOTICE - expected thing happened, you should notice that

[cizordj]

Then that's OK for me

[ostrolucky]

-v gives you error stacktrace in case of error, so it's still useful even if you don't see other stuff.

Bumping verbosity of these messages is not PSR compliant.

Additionally, I don't think you should mix up behaviour of console handler (all the talk with -v, -vv and so on) with general way how monolog logs it.

If you are looking for improvements in console handler, instead of bumping verbosity here on this one place, I would propose more generic improvements for console handler. For example it would be nice if it accepted extra arguments with which you could filter the log messages.

As for usages outside of console handler, it's better to have custom middleware, there you can log whatever you want.

[dkarlovi]

Bumping verbosity of these messages is not PSR compliant

What do you mean exactly by "not PSR compliant", I see you're linking to Monolog?

[ostrolucky]

From the link I sent it's visible monolog describes notice level as "uncommon events". RFC-5424 (that PSR-3 is based on) describes it as "normal but significant condition". I don't think many people here would agree that processing messenger message is uncommon, or significant event. If so, we would need to bump severity of request logs too.

[dkarlovi]

A message arriving to be consumed by a command called messenger:consume is a significant event, it's literally the whole purpose of the command.

If so, we would need to bump severity of request logs too.

Why? Who's talking about requests here? 🤔

[ostrolucky]

Because under same definition, processing the request is significant too

[dkarlovi]

You process those logs in a totally different way and the semantics of a request is unrelated to the issue here, IMO.

[dkarlovi]

i dont like to be notified for each and every receive/ack, in that sense INFO is just fine

You can just run without verbosity then. The issue is no verbosity and first level of verbosity behave exactly the same.

but you got a hint

The hint doesn't invalidate the point from the OP:

this is either "nothing" or "a lot" (depending on what other loggers start spewing INFO messages, for example FOS Elastica starts outputting full requests / responses at this level, HTTP client will output all requests, etc)

[carsonbot]

Thank you for this issue.
There has not been a lot of activity here for a while. Has this been resolved?

[dkarlovi]

Still relevant.

[xabbuh]

@dkarlovi Up for a PR to move things forward?

[dkarlovi]

@xabbuh would this be a new feature or a fix?

[xabbuh]

This looks rather like a feature to me.

[dkarlovi]

OK, so I guess it can wait for 7.3 then. How do we handle BC here?

[dkarlovi]

It can't flood "error logs" since it's not an error, it's a notice.

this issue about console output, not logging

No.

[dkarlovi]

personally i dont think every receive/ack is something significant

For a messenger worker? Then, what is significant?

[dkarlovi]

i dont know

I don't know what we're discussing then. 😄

[dkarlovi]

so i guess this is about console output

But it isn't.

[dkarlovi]

No, it's to differentiate between these messages:

• Message A received
• While handling message A, these things happened

[ostrolucky]

Like I mentioned before, I don't agree that "message received" is a significant event, same as request received is not a significant event. These are all regular events, nothing significant about them. And again, according Monolog NOTICE is not a significant event, but uncommon event. You just picked one of two definition that serves your goal better, ignoring the other one. Either way, even going with this definition, I don't agree it's a significant event.

I don't think I'm the only one with this opinion but if you want to take the risk then go ahead and create a PR. Once released, it's going to flood log servers of lot of companies though ;) I don't want to log every message received same as I don't want to log every request received. However, I do want to log uncommon/significant events (NOTICE level), that's why I use such setup. Bumping messenger to NOTICE would make me to bump logging severity filter to WARNING and I'm going to lose all NOTICE events.

What I would suggest, is to make severity of this log entry you are interested in configurable. This would actually be useful on more places. B2Bs tend to have low enough traffic to also want to log request events or even http client events, so it would be nice to change severity there as well as they see fit. All of this can be configured through separate monolog handlers and channels, but it's tricky, so I can see some value in just changing severity of the event.

[dkarlovi]

I don't agree that "message received" is a significant event, same as request received is not a significant event.

You're free to disagree. 🤷 Obviously, a request received is a significant event for a server serving requests, it's the entire point of its existence, same for worker getting a message. Are you saying you're not logging HTTP requests?

I'm going to lose all NOTICE events.

Since you're arguing getting a message is not really all that important for the worker, I'm fine with that.

[ostrolucky]

Since you keep ignoring this and keep using more vague definition: Can you at least admit receiving a request is not an uncommon event?

[nicolas-grekas]

We need to drive a consensus to make any move. Antagonizing isn't how things work here. Please keep the discussion open.

[dkarlovi]

Can you at least admit receiving a request is not an uncommon event?

For a HTTP server? It's literally the only event it exists for, I don't understand your POV at all. I think your misunderstanding here stems from "common" meaning "not rare", but that's not the intent at all, it's not the volume, it's the importance. For a HTTP server, the request is the only important thing, same as a message for the worker.

Again, do you not log HTTP requests, at least a single log entry per request?

[dkarlovi]

Request happened, but "something"

What's something?

[dkarlovi]

anything that makes it worth noting from a regular request.

You mean like some sort of warning? The "something" here is the key point of the discussion, we can't keep it as a "something", it must be concrete.

[magikid]

Looking over the RFC at the levels, I think whether a message is ack’d or nack’d would be a significant condition that should be logged at the NOTICE level.

[ostrolucky]

That has been already mentioned in this thread. It differs from monolog description and there is a disagreement on this being significant event. RFC itself doesn't elaborate on "significant". But again, if this is classified as significant, request logs are significant as well.

[magikid]

Yes, I saw your posts above. My comment was to weigh in on what I consider to be a significant event for a message handler. I understand that you disagree with that.

[dkarlovi]

IMO, the key point of this issue is

With no verbosity, you get basically nothing. Same with -v.

Something needs to be important enough to be produced while Messenger consume is running, at least on -v if not by default, even though long running commands by default typically don't behave like interactive commands ("if no error, no output"), instead they provide some form of "Yes, I'm still working" output.

We can now argue semantics of "what is significant" (and how it depends on what the meaning of the word ‘is’ is), but in the end, the point remains: something needs to be important enough to be produced if you've requested verbose output for Messenger consume process.

[chalasr]

I tend to disagree with this proposal, notices usually imply some action should be taken. A log telling that a message was successfully handled is informational to me. Dispatched events should be used to trigger side effects when this happens and tooling should be tweaked to align with the meaning of these levels.

[dkarlovi]

tooling should be tweaked

This is what the issue is about, yes:

something needs to be important enough to be produced if you've requested verbose output for Messenger consume process

[dkarlovi]

@ro0NL you're mixing up console and stdout for the N-th time in this issue and I don't understand why (now it's gotta be on purpose?) since I've explained multiple times this is not about console handler at all. What's more, the console handler should IMO be totally disabled (even if configured) when Messenger consume is running in prod, that's what #58715 is all about.

This is about providing a reasonable "heartbeat" from Messenger consume running by default, I can't explain that any clearer and again.