Skip to content

[Console] Log exit codes as debug messages instead of errors #23828

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

Merged
merged 1 commit into from
Aug 8, 2017
Merged

[Console] Log exit codes as debug messages instead of errors #23828

merged 1 commit into from
Aug 8, 2017

Conversation

haroldiedema
Copy link

@haroldiedema haroldiedema commented Aug 8, 2017

Q A
Branch? 3.3
Bug fix? yes
New feature? no
BC breaks? no
Deprecations? no
Tests pass? yes
Fixed tickets n/a
License MIT
Doc PR n/a

Fixes PR #21003

This patch stops logging exit_codes != 0 to error and logs it to debug instead, since it's not an error. The console application exited without uncaught exceptions, and the console application deliberately returned a specific exit code, therefore it shouldn't be logged as an error.

A valid use case would be to let a caller script in bash (the script spawning the console command) know what action to take based on the exit code. More specifically, exit codes other than 1, 2, 127+n isn't necessarily considered an error.

Monolog is hooked to our mailbox, so we can see what is happening in our production environment. However, it's currently being spammed for no reason because of #21003.

tl;dr: user-programmed exit codes (return in execute()) should NOT log an error message to monolog. I find it a bit iffy to leave the console.terminiate event listener in since it now logs to debug instead. I'm unsure if people want/need this, so I might as well remove the terminate listener entirely.

@linaori
Copy link
Contributor

linaori commented Aug 8, 2017

To summarize the exit codes; Symfony now treats error codes other than 0 as error, but that doesn't mean they are errors.

Every command returns an exit status (sometimes referred to as a return status or exit code). A successful command returns a 0, while an unsuccessful one returns a non-zero value that usually can be interpreted as an error code. Well-behaved UNIX commands, programs, and utilities return a 0 exit code upon successful completion, though there are some exceptions.

@chalasr
Copy link
Member

chalasr commented Aug 8, 2017

Also there is no error event dispatched if no exception has been thrown, logging an error in this case seems inconsistent.

@haroldiedema
Copy link
Author

I think you're right. I got the same comment from a colleague immediately after I made this PR. Guess the gut feeling was right.

I'll update the PR. Stand by.

@chalasr
Copy link
Member

chalasr commented Aug 8, 2017

I mean that using the debug level seems more appropriate. What change would you do? Removing the log completely? I find it useful as purely informative.

@haroldiedema
Copy link
Author

haroldiedema commented Aug 8, 2017

I was going to remove the onConsoleTerminate event listener entirely. It feels a bit 'iffly', since it's in an error listener, but it has nothing to do with errors, nor do I personally find the information very helpful to be in a log. This was also the remark I got from my colleague.

@iltar what do you think?

I think that the console.terminate event listener, if it's going to log to debug, has no place in a class named ErrorListener, since this specific part has nothing to do with it.

@chalasr
Copy link
Member

chalasr commented Aug 8, 2017

Indeed, that's an error listener. OK for removing it if others think it's not useful.

@chalasr
Copy link
Member

chalasr commented Aug 8, 2017

But that's a public method, we can't remove it from 3.3. Needs to be deprecated in 3.4 first.

@chalasr chalasr added this to the 3.3 milestone Aug 8, 2017
@haroldiedema
Copy link
Author

haroldiedema commented Aug 8, 2017

Oh dear, I didn't think of that 🤣

Alright, in that case I'm in for leaving it as it is now then. It solves our issues and we could always mark it as deprecated for 3.4 and make a separate TerminateListener if people find this information useful.

@chalasr
Copy link
Member

chalasr commented Aug 8, 2017

About dropping the log entirely, I suggest opening an issue first so that you can get feedbacks (one may be happy to find this log if that means the command did fail, better have logs that are not useful most of the times than nothing at all).

@chalasr
Copy link
Member

chalasr commented Aug 8, 2017

Thank you @haroldiedema.

@chalasr chalasr merged commit cadbed3 into symfony:3.3 Aug 8, 2017
chalasr pushed a commit that referenced this pull request Aug 8, 2017
…rs (haroldiedema)

This PR was merged into the 3.3 branch.

Discussion
----------

[Console] Log exit codes as debug messages instead of errors

| Q             | A
| ------------- | ---
| Branch?       | 3.3
| Bug fix?      | yes
| New feature?  | no
| BC breaks?    | no
| Deprecations? | no
| Tests pass?   | yes
| Fixed tickets | n/a
| License       | MIT
| Doc PR        | n/a

Fixes PR #21003

This patch stops logging `exit_codes != 0` to _error_ and logs it to _debug_ instead, since it's not an error. The console application exited without uncaught exceptions, and the console application deliberately returned a specific exit code, therefore it shouldn't be logged as an error.

A valid use case would be to let a caller script in bash (the script spawning the console command) know what action to take based on the exit code. More specifically, exit codes other than 1, 2, 127+n isn't necessarily considered an error.

Monolog is hooked to our mailbox, so we can see what is happening in our production environment. However, it's currently being spammed for no reason because of #21003.

tl;dr: user-programmed exit codes (return <int> in `execute()`) should NOT log an error message to monolog. I find it a bit iffy to leave the `console.terminiate` event listener in since it now logs to `debug` instead. I'm unsure if people want/need this, so I might as well remove the terminate listener entirely.

Commits
-------

cadbed3 [Console] Log exit codes as debug messages instead of errors
@VasekPurchart
Copy link
Contributor

I stumbled upon this after investigating why the messages for exit != 0 are not seen in console in SF standard edition (symfony/symfony-standard#1107). I think, that as cited above "Well-behaved UNIX commands, programs, and utilities return a 0 exit code upon successful completion", which means that although there was no PHP error, it should be treated as errored, the rest of the UNIX system will treat it this way anyway, for example:

bin/console hello:world && echo "OK" || echo "ERROR"
ERROR

The same obviously applies for running the CLI command in a container etc.

So I really think, that this should be treated as an error, because in this context, it is considered an error. I think this is important both for dev and production:

If you do not want to see it in the dev environment in the console, you can always reconfigure the console handler as was the case in the referenced SF standard issue, that is only a matter of personal preference.

So the only thing where treating it as an error is when you use codes for something else, which is non-standard and then I think it should be excluded by the given app from logging.

Anyways, in these cases, there is something you can do about that. But if this is kept changed to debug only, then I don't think you have much possibilities? In dev, you can always run everything in -vvv (unconfortable and unreal not to forget to), but that's probably it.

@linaori
Copy link
Contributor

linaori commented Aug 16, 2017

@VasekPurchart if you read my link, you will see that error codes other than 0 are not implying errors. In this case, a command returns an error status other than 0 when done in a scenario where more processing needs doing. This is perfectly legit and doesn't mean it errored, even though it didn't result in an exit code of 0.

It's not about messages on the console, it's about errors being logged to monolog and processed by whichever handler is listening (in this case a mailer). It's simply wrong to treat codes other than 0 as errors, because according to the definition, they are not always errors.

@VasekPurchart
Copy link
Contributor

@iltar I have read the link and I also tried to elaborate on that in my post. They might not be errors by definition, but the whole unix/bash ecosystem is constructed around differentiating 0 ~ ok, !=0 ~ not ok, as seen with the && handling.

So what I am saying here is that sticking to the the common behavior means playing nicely with the other parts. And that it can be worker around when using something non-standard - excluding from the mailer for example.

Do you have any proposals how the use cases I was mentioning could be solved? - The fingers crossed in production and seeing failed commands in dev? Or do you not consider them as valid?

@haroldiedema
Copy link
Author

haroldiedema commented Aug 16, 2017

@VasekPurchart

The script making the exit_code != 0 comparison should handle the logic. Very much how your PHP scripts catch different types of exceptions and handle them accordingly.

@VasekPurchart
Copy link
Contributor

I think everyone in this discussion understands the mechanics how things work. Using other scripts/cli applications from other scripts is just a tiny fraction of the entire ecosystem. I am not arguing that exit code cannot be non-error. I am making the case that a lot of other things around are designed as to treat it that way and that is is actually no problem if it is treated that way. Also I hope, that we can agree that in most scripts/cli applications they actually are errors.

I think the situation the intention here is "not to call an error something which might not be an error". This is something I of course am generally behind. But here we are very limited on one side by the semantics of the logging severity vs the ambigous nature of the exit codes. I am trying to look at this from the practical point of view as I have been writing a lot of CLI applications for a long time and have gone trough a lot of usecases around them. Also I have a very long "history" with the feature introduced in #21003 since I have been maintaining a bundle providing exactly this for a long time: https://github.com/VasekPurchart/Console-Errors-Bundle.

My point is that this being logged as something lower than error, due to how things are set up in Symfony around this is actually net less comfortable.

So while I appreciate your responses, could you please see the cases above, and let me know if you have any ideas, how they click together with this PR?

Another option would be to make this configurable, because there are clearly varying expectations around this. This is how I had it set up in my bundle anyway, so I will be happy to prepare a PR for that.

@linaori
Copy link
Contributor

linaori commented Aug 17, 2017

I've been thinking about about an interface describing the return codes and mapping them to an exit type, that way the developer can indicate how or what

@haroldiedema
Copy link
Author

In reality, I wanted to remove the exit code logic that is in this PR all together, but that would introduce a BC-break and our company software would essentially be broken for a few months.

Maybe it is me, but I really don't see why you can't simply throw an exception instead of typing return 123; in your command to test bin/console hello:world && echo "OK" || echo "ERROR".

Here are my throughs on this subject summarized:

  • PHP code, if faulty, should throw exceptions.
  • An error stating that an error occurred with an arbitrary number, isn't a proper error.
  • Your code doesn't actually "crash". YOU - the programmer - typed the return <exit code>;

So, throwing an InvalidArgumentException in your command, then doing bin/console hello:world && echo "OK" || echo "ERROR", will still result in ERROR, and a proper error message would be available too.

Whereas returning an arbitrary number in your controller, allows for more control in your bash scripts without a mailbox attached to monolog is being spammed for no reason.

You could make it configurable, I don't have any problems with that, but to me, it really feels like a "hack" to something that shouldn't exist in the first place.

If you really want this feature to exist, then please create a custom exception where an exit code can be passed as an argument. For example:

public function execute(InputInterface $input, OutputInterface $output)
{
    throw new CommandException("This is a proper error message", 123);
}
$ bin/console my:command
$ echo $?
> 123

@linaori
Copy link
Contributor

linaori commented Aug 17, 2017

The exception handling part might actually be a nice solution 👍

@chalasr
Copy link
Member

chalasr commented Aug 17, 2017

Note that when an exception/error occurs, the code of the thrown exception/error is used as exit code for the command.
As of 3.3, you can set a custom exit code by listening on the ConsoleErrorEvent and call setExitCode().

@VasekPurchart
Copy link
Contributor

Maybe it is me, but I really don't see why you can't simply throw an exception instead of typing return 123; in your command to test bin/console hello:world && echo "OK" || echo "ERROR".

I can and in almost all cases I can think of, I would. Its the same as "regular" error handling in PHP - return values vs exceptions. But in you application there are not only commands you have written personally and you have control of. There can be (and in most current SF applications there will be) more commands that come registered with bundles.

So it's not really about, how the command is written (if we allow the return -> exit codes to be a thing), but rather, how it is/can be consumed by the client. This is the same for the issue with the mailer handler you mentioned originally as with the usecases I mentioned above. You want the application to be behaving uniformly, and then its about the expectations you have.

So I think, the configuration is needed not on the command level, but rather at the application level. Because only then, you can know, what to expect.

@haroldiedema
Copy link
Author

Note that when an exception/error occurs, the code of the thrown exception/error is used as exit code for the command.

^ QFT.

I'm saying this again (final word):

You want to enforce the code return 123; to be handled as an error, while the same should be accomplished by typing throw new Exception("Some error", 123);.

If you've ever used the old MS-DOS commands like choice, exit codes (present in %ERRORLEVEL%) would contain the keycode of the key you pressed. This is a perfect example of how exit codes are utilized. Simply assuming that a deliberate return 123; in your PHP code is an error, is just plain wrong IMO.

@fabpot fabpot mentioned this pull request Aug 28, 2017
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging this pull request may close these issues.

5 participants