Skip to content

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

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
dkarlovi opened this issue Feb 26, 2024 · 50 comments

Comments

@dkarlovi
Copy link
Contributor

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
Copy link

cizordj commented Feb 26, 2024

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
Copy link
Contributor Author

dkarlovi commented Feb 26, 2024

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
Copy link

cizordj commented Feb 26, 2024

Then that's OK for me

@ostrolucky
Copy link
Contributor

-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
Copy link
Contributor Author

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
Copy link
Contributor

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
Copy link
Contributor Author

dkarlovi commented Feb 26, 2024

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
Copy link
Contributor

Because under same definition, processing the request is significant too

@dkarlovi
Copy link
Contributor Author

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

@dkarlovi
Copy link
Contributor Author

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
Copy link

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

@dkarlovi
Copy link
Contributor Author

Still relevant.

@carsonbot carsonbot removed the Stalled label Sep 27, 2024
@xabbuh
Copy link
Member

xabbuh commented Oct 1, 2024

@dkarlovi Up for a PR to move things forward?

@dkarlovi
Copy link
Contributor Author

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

@xabbuh
Copy link
Member

xabbuh commented Oct 24, 2024

This looks rather like a feature to me.

@dkarlovi
Copy link
Contributor Author

dkarlovi commented Oct 24, 2024

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

@dkarlovi
Copy link
Contributor Author

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
Copy link
Contributor Author

personally i dont think every receive/ack is something significant

For a messenger worker? Then, what is significant?

@dkarlovi
Copy link
Contributor Author

i dont know

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

@dkarlovi
Copy link
Contributor Author

so i guess this is about console output

But it isn't.

@dkarlovi
Copy link
Contributor Author

No, it's to differentiate between these messages:

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

@ostrolucky
Copy link
Contributor

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
Copy link
Contributor Author

dkarlovi commented Oct 24, 2024

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
Copy link
Contributor

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
Copy link
Member

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

@dkarlovi
Copy link
Contributor Author

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
Copy link
Contributor Author

Request happened, but "something"

What's something?

@dkarlovi
Copy link
Contributor Author

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
Copy link
Contributor

magikid commented Apr 17, 2025

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
Copy link
Contributor

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
Copy link
Contributor

magikid commented Apr 17, 2025

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
Copy link
Contributor Author

dkarlovi commented Apr 17, 2025

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
Copy link
Member

chalasr commented Apr 17, 2025

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
Copy link
Contributor Author

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
Copy link
Contributor Author

@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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

8 participants