Improve error and message logging

[jonocodes]

🗣 Suggestion

Discussion began here: #1001 (review)

I am genuinely confused with the logging setup and it has bitten me several times. There is a lot of good info being sent go Hm_Debug::add, but its hard to get the data out from there. I lost several hours trying to fix a sqlite bug that would have been minutes if those logs were simply displayed.

Its possible PHP logging is different because one of the output streams is meant to screen/browser output. I hear Laraval is a commonly used PHP framework, so I looked up their logging setup: laravel.com/docs/11.x/logging

which seems quite standard. It uses monolog which provides simple, immediate, customizable outputs.

Also DEBUG_MODE is only hard-coded in scripts for now. It will be a good idea to extend that to come from the environment.

[jonocodes]

@kroky said:

Hm_Debug uses Hm_list which has get method to get the messages and show method to send them to the error log. PHP error logging might be complex and not everything logged, indeed, it has settings for error_reporting - what kind of errors to report, then displaying errors on screen or writing errors to a log file - thus third option also depends on your backend server setup. So, a lot of moving parts.

Integrating something like monolog is an option but note that cypht started with minimalism in mind while Laravel is enormous, so we still try to depend on fewer external libs. That being said, I think an ENV setting for DEBUG_MODE which is observed and makes sure debugging messages are written to the php error log at the end of a request + screen/cli if necessary seems like a better approach to me.

[jonocodes]

Hm_Debug uses Hm_list which has get method to get the messages and show method to send them to the error log. PHP error logging might be complex and not everything logged, indeed, it has settings for error_reporting - what kind of errors to report, then displaying errors on screen or writing errors to a log file - thus third option also depends on your backend server setup. So, a lot of moving parts.

@kroky
I think I should understand the part where it "displays errors on the screen". I presume that's to the browser? Or is it hidden in the browser source so its not displayed? That may clarify to me why we are queuing it up. Can you show me an example of where I can see that happening?

[kroky]

Yes, site/index.php ends with Hm_Debug::show() if running in debug mode, so these are sent to the error_log php function. These will be also displayed on the browser (screen) if display_errors PHP setting is on but it is usually off in production, so you only see the errors in the php error log (which is either apache error log or php-fpm error log depending on how you run the interpreter). We can write a special output module called after all standard pages or directly modify the dispatch class to also make sure we dump all such errors to the browser (via html code) if we don't want to depend on display_errors PHP setting.

[jonocodes]

Yes, site/index.php ends with Hm_Debug::show() if running in debug mode, so these are sent to the error_log php function. These will be also displayed on the browser (screen) if display_errors PHP setting is on but it is usually off in production, so you only see the errors in the php error log (which is either apache error log or php-fpm error log depending on how you run the interpreter). We can write a special output module called after all standard pages or directly modify the dispatch class to also make sure we dump all such errors to the browser (via html code) if we don't want to depend on display_errors PHP setting.

Do people in practice want errors written to the browser? This seems like a security risk even in development. Do other projects do this? Does wordpress do this? A quick look at their logging makes me think they dont do any queuing. Queuing is delicate since you need to manage when to print it, and maintain state, etc.

In my mind there should always be an error log (file, stdout, etc). Its just a question of how much gets written there. Actual errors and exceptions should always make it there no matter what. And if you are in some kind of "debug" mode, it would just put more details into those logs.

To be clear my question here is:

1. Can we stop logging to the browser, and only log on the server side?
2. Can we do the logging without queuing? This means the error gets logged the moment it happens - which is helpful for debugging.

[kroky]

Log output to the browser is helpful for admins not having direct access to the server and if it is configurable, there is nothing wrong keeping the functionality. We do this with Tiki project which is much bigger PHP project and it helps administrators see/report some errors that developers can't see due to restricted environments that it is deployed to.

Logging without queuing actually happens when there is a code error that triggers PHP error or exception - these are cases when application misbehaves, developers haven't caught it and things get written to the logs immediately. The so-called debug messages are mostly not such cases but things that help debugging - more information on connections to external services, etc. Sometimes these might be mixed with actual error conditions, so I agree we should improve it somehow but queuing is not the main problem here - at the end, the queue will be flushed. We probably need a few different error reporting levels and convert some debugging messages to errors, so they end up in the error log even if debugging mode is off - this way, it will be easier to see such conditions in production and not waste hours of debugging like you did. How does this sound to you?

[jonocodes]

Ok, how about we start with some basics. Do we agree about the following?

1. implement debugging as environment variables. This means removing the define('DEBUG_MODE') statements from the code and instead perhaps create a new env var like ENABLE_DEBUG to be used in its place.

2. Introduce log levels. I dont know how this will work with the queuing up system. And if you dont want to use monolog or something similar, we are going to have to figure out the design of that whole system.

[kroky]

+1 for both. Monolog depends on psr/log only, so it will be a small addition to the project but we would be able to log to files besides php error log which is valuable addition. @marclaporte what do you think?

[marclaporte]

Sounds good to me.

[jonocodes]

@kroky using monolog how do you recommend that be done with the log queue? Will the levels be in each line of the array of the queue? Will there be a single level for the whole queue?

[kroky]

I'd send the log message to monolog immediately as they are queued in the debug system, and definitely separate to at least 3 levels - errors, warnings and info/debug messages. The queue itself becomes a bit redundant now and I don't think we should burden it with levels. Thus, maybe a bridge with monolog where you send specific debug messages with proper level and let the configuration of monolog determine which levels are actually logged? There are about 120 places where Hm_Debug:add is called where we actually need to distinguish if it is an error, warning or a debug message.

[marclaporte]

@jonocodes how do you feel about this?

Thanks!

[jonocodes]

This sounds good though I am not able to implement it any time soon.