Consider implementing Laravel Logging Service

[henriqueramos]

Currently, to send data to the syslog, we only have the built-in method error_log.

We should consider implement the Laravel Logging Service.

This will help us to create log channels and use different levels for logs.

[henriqueramos]

@asmecher Could you please take a look on this PRs? If it's okay, I will create the ones for OMP/OPS.

OJS
#7721

[jonasraoni]

Just tagging a related issue with some supporting discussion, that depends on this: #7568

[NateWr]

@henriqueramos can you please provide some more information about the different logging channels configured in your PR, how devs would use these logs, what they look like when we read them, etc? It's impossible to evaluate the benefits of this without some concrete examples.

[henriqueramos]

Of course @NateWr! On the link I added at the description, there's a description about the channels, how they work and so on. But for historical purposes, I will add it here.

About Logging

Logging is based on "channels". Each channel represents a specific way of writing log information.

For example, the single channel writes log files to a single log file, while the syslog channel sends log messages to syslog. Log messages may be written to multiple channels based on their severity (or using a stack driver for channel)

Laravel under the hood uses Monolog. So we could create multiple handlers to customize the message payload, for example.

Log Levels

Take note of the level configuration option present on the channels configurations. This option determines the minimum "level" a message must be in order to be logged to that channel. Currently logs with level greater than and equals debug will be logged into files.

The log levels defined in the RFC 5424 specification: emergency, alert, critical, error, warning, notice, info, and debug, are available to use.

Channels

Each log channel is powered by a "driver". The driver determines how and where the log message is actually recorded. On our implementation (at this moment) there's the following channels available:

Channel	Driver	Description
`stack`	`stack`	Could send log to multiple channels. Currently implementation sends log data only to channel `single`
`single`	`single`	Sends log data to `cache/storage/logs/laravel.log` file.
`daily`	`daily`	Sends log data to `cache/storage/logs/laravel-Y-m-d.log` file. This rotates every day.
`syslog`	`syslog`	Sends log data to `syslog`.
`errorlog`	`errorlog`	Sends log data over `error_log`.
`null`	`monolog`	Sends log data to `/dev/null`
`emergency`	NULL	Sends log data to `cache/storage/logs/laravel.log` file in any case.

How to use

Inject the Log dependency in your class with use Illuminate\Support\Facades\Log; and call it across the code.

Log::emergency("Bad, bad server. No donut for you!");
Log::alert("Bad, bad server. No donut for you!");
Log::critical("Bad, bad server. No donut for you!");
Log::error("Bad, bad server. No donut for you!");
Log::warning("Bad, bad server. No donut for you!");
Log::notice("Bad, bad server. No donut for you!");
Log::info("Bad, bad server. No donut for you!");
Log::debug("Bad, bad server. No donut for you!");

Your logs will reside on cache/storage/logs/laravel.log.

[2022-02-22 12:20:56] production.EMERGENCY: Bad, bad server. No donut for you!  
[2022-02-22 12:20:57] production.ALERT: Bad, bad server. No donut for you!  
[2022-02-22 12:20:57] production.CRITICAL: Bad, bad server. No donut for you!  
[2022-02-22 12:20:57] production.ERROR: Bad, bad server. No donut for you!  
[2022-02-22 12:20:57] production.WARNING: Bad, bad server. No donut for you!  
[2022-02-22 12:20:57] production.NOTICE: Bad, bad server. No donut for you!  
[2022-02-22 12:20:57] production.INFO: Bad, bad server. No donut for you!  
[2022-02-22 12:20:57] production.DEBUG: Bad, bad server. No donut for you!  

And there's more, you could customizing Monolog for Channels, customize the Monolog Handler with formatters and much more.

[NateWr]

Thanks @henriqueramos! In addition to the Laravel docs, the key questions I want to be answered for our project are:

1. What are the problems we want to solve with this?
2. How will this solve the problems?
3. What channels should we use and in what cases?
4. Are there additional channels we should consider beyond the default ones? (ie - do we want a separate channel for emails, one for scheduled tasks/jobs)
5. How will developers keep track of errors across all three logs in their daily work? Right now I can tail -f a single file and see anything that happens. What's the equivalent here for viewing/tracking issues?

[henriqueramos]

@NateWr

1. The main goal of implementing this is to have a better logging granularity.
2. We will have the ability to choose which channel will be used (on the fly) and which level of logging will be used.
3. stack channel should be used as default, others will depend on the dev's needs, daily should be used if you want more granularity;
4. At this moment I don't think we need more channels;
5. You could keep using the tail -f, just need to pass the path of other files (i.e tail -f ./cache/storage/logs/laravel.log /var/logs/apache2/error.log)

[asmecher]

@henriqueramos, this is not a bad idea, but I'd like to put it on ice for the moment; it's not a high priority and we have plenty of other things that come first.

[NateWr]

At this moment I don't think we need more channels;

This is my concern. It seems like we're adding a new pattern, but not really gaining much. What I'm hoping to see is a proposal for a coding convention that identifies what type of events should lead to what type of logs. If it's all going to one log, it doesn't seem to add much beyond the apache error.log.

[henriqueramos]

This is my concern. It seems like we're adding a new pattern, but not really gaining much. What I'm hoping to see is a proposal for a coding convention that identifies what type of events should lead to what type of logs. If it's all going to one log, it doesn't seem to add much beyond the apache error.log.

I think there's a misconception about Logging here (and what this implementation does). The location where logs will reside doesn't matter, after all. You could send to one file inside your application (like storage/logs/laravel.log), to a 3rd party logging tool Saas like papertrail, to a Logstash instance or even to apache error.log. The main goal of using a standard logging toolset (like Monolog per se) its to provide granularity to you and your data. The way you're using to ingest (and process this data) deserves another topic.

Let me try to explain how granularity help the Devs/Sysadmins with a simple metaphor.

Imagine you have an android friend and you ask him about how his day.

"I woke up, opened my left eye, checked the surrounds, opened my right eye, moved my nose five inches to the left (...)"
"No! There's too much information. Decrease the granularity level from 10 to 3."
"I woke up, changed my clothes, had a good breakfast with triple A batteries, caught the jetpack to downtown (...)"
"That’s so better."

This is what granularity does for you. Instead of sending lots of data (and probably non-formatted ones) to your log ingestion tool (file, Saas or on-promise instances), you have the possibility to choose which kind of logging level you want to persist and how transform this data before send it. You could even add contextual information using the Laravel's Monolog implementation withContext.

It's far easier to parse (and read) this kind of data on your ingestion tool (or search using vi/vim/nano/gedit/(any CLI tool):

[2022-02-22 12:20:57] production.ERROR: User Florence hit an error during adding review on article ID 5. Stack trace:
[2022-02-22 12:20:57] production.WARNING: Was impossible to send the article ID 10 to crossref
[2022-02-22 12:20:57] production.INFO: User Matt send the 100 article on the system
[2022-02-22 12:20:57] production.DEBUG: Here's the output of SQL statement: INSERT INTO bogus_data_table

than this normal apache's error.log:

[Wed Feb 23 00:08:05.960722 2022] [proxy_fcgi:error] [pid 271844] [client 127.0.0.1:54872] AH01071: Got error 'PHP message: PHP Warning:  foreach() argument must be of type array|object, string given in
[Wed Feb 23 09:31:36.927492 2022] [proxy_fcgi:error] [pid 271844] [client 127.0.0.1:54974] AH01071: Got error 'plication { ... }; public $_dispatcher = class PKP\\core\\Dispatcher { ... }; public $_contextDepth = 1; public $_contextList = [...]; public $_flippedContextList = [...]; public $_contextPaths = [...]; public $_contexts = [...]; public $_handler = NULL; public $_component = NULL; public $_op = NULL; public $_rpcServiceEndpointParts = FALSE; public $_rpcServiceEndpoint = FALSE; public $_indexUrl = 'http://ojs/index.php' };
[Wed Feb 23 09:32:01.272367 2022] [proxy_fcgi:error] [pid 271846] [client 127.0.0.1:54980] AH01071: Got error 'PHP message: Find me if you can!
[Wed Feb 23 09:33:02.346250 2022] [proxy_fcgi:error] [pid 276665] [client 127.0.0.1:54986] AH01071: Got error 's = ['SCRIPT_NAME' => class Smarty_Variable { ... }, 'defaultCharset' => class Smarty_Variable { ... }, 'baseUrl' => class Smarty_Variable { ... }, 'currentContext' => class Smarty_Variable { ... }, 'currentLocale' => class Smarty_Variable { ... }, 'currentLocaleLangDir' => class Smarty_Variable { ... }, 'applicationName' => class Smarty_Variable { ... }

And on the context of logs being one of the three pillars of Observability, he's alone isn't a silver bullet, of course.

[asmecher]

@henriqueramos, this is bikeshedding; as I said it's not necessarily a bad idea but it's not a current requirement in the software and I asked you not to work on it for the moment. There are other higher priorities.

[henriqueramos]

@henriqueramos, this is bikeshedding; as I said it's not necessarily a bad idea but it's not a current requirement in the software and I asked you not to work on it for the moment. There are other higher priorities.

Understood @asmecher. Besides the Scheduling Task on #4622, we have the Laravel Routing system on #7698 to be done. But I'd like to highlight there's this log stuff comes alive during the rewrite of Scheduling Task on #4622 as a side effect.

I just splitted the tasks to do a better tracking of it.

[steinmb]

Laravel uses Monolog - https://github.com/Seldaek/monolog. Not sure what Laravel brings to the table compare to bare bone Monolog, though I am sure Laravel dev. in here can point out? The most important part is to make sure the lib is PSR-3 - https://www.php-fig.org/psr/psr-3/meta/ compliment. These days most modern libraries are.

+1 from me pulling out any custom logging and leverage libs like Monolog that is widely used - https://packagist.org/packages/monolog/monolog

[asmecher]

@steinmb, is there a motivating use case for adopting Monolog (or Laravel logging) over PHP error_log, or would this just be for the sake of modenization? It'll help us prioritize.

[jonasraoni]

@asmecher these logging tools normally allows us to configure the logs in a generic way, e.g.:

• Configure critical errors to be sent by email to the administrator
• Configure the level of errors we're interested (for a production environment we could set it to log only errors or worse events)
• Add a plugin to provide extra functionality (e.g. use a SMS service)

It also provides such constructions:

if ($logger->isDebugEnabled()) {
  $message = possiblySlowOperationJustUsedByTheLog();
  $logger->debug($message);
}

[NateWr]

@jonasraoni right now we don't have any code in the system that logs events like this. We're still looking for a motivating use case that demonstrates where exactly in the code we would implement $logger->debug() and why. The way I put it before is:

What I'm hoping to see is a proposal for a coding convention that identifies what type of events should lead to what type of logs.

For example: when Event A happens we should be logging to Channel B because User C wants to observe that event.

[steinmb]

It should make sense to log events outside what php automagically sends of notices, warnings and errors to server default configured log. Example, user created, access blocked, payment events, and so on.

If the core developers think there is no use case for logging events in the running application, perhaps this issue should be closed? (ps: I am new to this code base).

[jonasraoni]

About the different levels of logging, here's a good reasoning:

About deciding what's interesting to listen to, and what to do with the events I think that's a responsibility of the sysadmin/developer. For example a sysadmin might decide to collect more detailed logs to discover why an operation is failing, so he might temporarily increase the granularity before attempting to simulate an issue (a high granular log could contain HTTP requests/responses, SQL queries, etc).

By default, we just can provide some reasonably good defaults (like the php.ini, which comes with a development and production advices), targeting probably end-users.

[jonasraoni]

Ah, about priorities: I don't see this type of logging as a requirement for our use case, we're not dealing with high sensitive information, so it's just an improvement that might be adopted slowly :)

[NateWr]

I think we're going around in circles here because we don't quite understand each other. Let's talk about this on the dev call today.

[jonasraoni]

Just leaving this minor issue, which depends on the Laravel's Log: #7568
The PRs just have the minimum code to make it funcional.

[jonasraoni]

• As a sysadmin I want to have log messages grouped by level (e.g. critical, error, warning, etc.), in order to monitor the application status, and detect potential bad issues earlier. This way I won't have to monitor every entry in the error.log (and any other log that the application has, such as the scheduledTaskLogs) or wait for users to detect and complain about a malfunctioning feature.

• As a developer, possibly without physical access to the installation, I want the log messages to be detailed enough, so I'll be able to know what the user was doing, the input data and the outcome, without having to ask the sysadmin to help with the debugging (e.g. modify the code). This way a sysadmin can temporarily increase the log sensitivity, simulate the issue and forward the logs to me.

[NateWr]

As a sysadmin I want to have log messages grouped by level (e.g. critical, error, warning, etc.), in order to monitor the application status, and detect potential bad issues earlier.

Does the Laravel Logging service allow you to route different PHP error messages to different logs automatically? For example, can I tell it to route all exceptions and fatal errors to a critical log and notices to a warning log or something?

know what the user was doing, the input data and the outcome, without having to ask the sysadmin to help with the debugging

It seems to me like this is a different proposal. The proposal would be something like: Log all activity in the application, such as requests, database writes, and HTTP responses. Do you have a technical proposal for how to do that with minimal intervention in the code base? Or did you think we'd just add lines of code that call the logger everywhere in the codebase?