Log statements do not print data in the second parameter

[bandtank]

Describe the bug The array parameter of log statements no longer prints to the application log. This began happening after upgrading to 8.3.0 from 8.2.5.

Here is a test:

$GLOBALS["log"]->debug("afterSave with implode:" . implode(",", [1,2,3]),[]);
$GLOBALS["log"]->debug("afterSave with array:  ",[4,5,6]);

This is what I see in the log:

[2024-06-23 02:20:48] DEBUG: afterSave with implode:1,2,3
[2024-06-23 02:20:48] DEBUG: afterSave with array:

If I set databaseHandler = True, the log statements appear in the UI as expected in the App Log, but the statements still don't have the array data:

[bandtank]

After looking around for quite a while, I noticed this comment. Please update the documentation to explain how to use the new logger. I can't find any notifications about the logger changing from $GLOBALS["log"]->debug() to $log->debug(...).

For anyone else who has this problem, here is what I have figured out so far to fix logging:

...
use Espo\Core\Utils\Log;
...

class MyClass
{
    public function __construct(
        private Log $log,
        ...
    ) {}

    public Stuff() {
        $this->log->debug(...);
    }
}

The logger utility is a direct copy of the monologger class. Here is the file.

Unfortunately, the array still won't print.

    $this->log->debug("afterSave with implode:" . implode(",", [1,2,3]),[]);
    $this->log->debug("afterSave with array  :",[4,5,6]);
    $this->log->debug('my message', ['var1', 'var2']);

Results in:

[2024-06-23 03:04:06] DEBUG: afterSave with implode:1,2,3
[2024-06-23 03:04:06] DEBUG: afterSave with array  :
[2024-06-23 03:04:06] DEBUG: my message

From here: https://stackoverflow.com/a/78447765

    $this->log->info('A message without context');
    $this->log->info('A message with context', ['foo' => 'bar', 'baz' => 'bat']);

Yielded:

[2024-06-23 03:07:28] INFO: A message without context
[2024-06-23 03:07:28] INFO: A message with context

The original logger in $GLOBALS seemed to be easier to use. I can't get the logger to print an array unless I use json_encode, print_r.

[yurikuzn]

This is the same logger. It's still available in GLOBALS.

The difference is that we don't print the context array anymore. Because we now pass exceptions and message placeholder values in context. It is how the logger was designed to be used in the PSR standard. If we print context, we would end up with too long log messages.

[yurikuzn]

You can configure the handler to print context.

https://docs.espocrm.com/administration/log/#handlers

    'handlerList' => [
      [
        'className' => 'Espo\\Core\\Log\\Handler\\EspoRotatingFileHandler',
        'params' => [
          'filename' => 'data/logs/espo.log'
        ],
        'level' => 'NOTICE',
        'formatter' => [
          'className' => 'Espo\\Core\\Log\\DefaultFormatter',
          'params' => [
            'lineFormat' => "[%datetime%] %level_name%: %code% %message% %request% %context%\n"
          ]
        ]
      ]
    ] 

[bandtank]

@yurikuzn - Thanks for the insight. I finally had time to try this solution. Here is what happened:

PHP Fatal error:  Uncaught TypeError: Espo\Core\Log\Handler\EspoRotatingFileHandler::__construct(): Argument #1 ($config) must be of type Espo\Core\Utils\Config, string given in /var/www/crm/application/Espo/Core/Log/Handler/EspoRotatingFileHandler.php:43
Stack trace:
#0 [internal function]: Espo\Core\Log\Handler\EspoRotatingFileHandler->__construct()
#1 /var/www/crm/application/Espo/Core/Log/DefaultHandlerLoader.php(146): ReflectionClass->newInstanceArgs()
#2 /var/www/crm/application/Espo/Core/Log/DefaultHandlerLoader.php(77): Espo\Core\Log\DefaultHandlerLoader->createInstance()
#3 /var/www/crm/application/Espo/Core/Log/HandlerListLoader.php(90): Espo\Core\Log\DefaultHandlerLoader->load()
#4 /var/www/crm/application/Espo/Core/Log/HandlerListLoader.php(55): Espo\Core\Log\HandlerListLoader->loadHandler()
#5 /var/www/crm/application/Espo/Core/Log/LogLoader.php(67): Espo\Core\Log\HandlerListLoader->load()
#6 /var/www/crm/application/Espo/Core/Loaders/Log.php(43): Espo\Core\Log\LogLoader->load()
#7 /var/www/crm/application/Espo/Core/Container.php(338): Espo\Core\Loaders\Log->load()
#8 /var/www/crm/application/Espo/Core/Container.php(101): Espo\Core\Container->load()
#9 /var/www/crm/application/Espo/Core/InjectableFactory.php(328): Espo\Core\Container->get()
#10 /var/www/crm/application/Espo/Core/InjectableFactory.php(266): Espo\Core\InjectableFactory->resolveBinding()
#11 /var/www/crm/application/Espo/Core/InjectableFactory.php(208): Espo\Core\InjectableFactory->getMethodParamInjection()
#12 /var/www/crm/application/Espo/Core/InjectableFactory.php(170): Espo\Core\InjectableFactory->getConstructorInjectionList()
#13 /var/www/crm/application/Espo/Core/InjectableFactory.php(70): Espo\Core\InjectableFactory->createInternal()
#14 /var/www/crm/application/Espo/Core/Container.php(92): Espo\Core\InjectableFactory->create()
#15 /var/www/crm/application/Espo/Core/Container/ContainerBuilder.php(199): Espo\Core\Container->__construct()
#16 /var/www/crm/application/Espo/Core/Application.php(62): Espo\Core\Container\ContainerBuilder->build()
#17 /var/www/crm/application/Espo/Core/Application.php(54): Espo\Core\Application->initContainer()
#18 /var/www/crm/command.php(35): Espo\Core\Application->__construct()
#19 /var/www/crm/bin/command(4): include('...')
#20 {main}
  thrown in /var/www/crm/application/Espo/Core/Log/Handler/EspoRotatingFileHandler.php on line 43

The problem is here. The class is expecting the following parameters:

    public function __construct(
        Config $config,
        string $filename,
        int $maxFiles = 0,
        Level $level = Level::Debug,
        bool $bubble = true
    )

This is what is being passed to it:

Array
(
    [0] => data/logs/espo.log
    [1] => 0
    [2] => Monolog\Level Enum:int
        (
            [name] => Notice
            [value] => 250
        )

    [3] => 1
)

I modified the parameter list here to include the config instance, which worked for the instantiation of the handler, but it broke the instantiation of the formatter because the formatter's constructor does not include config in the parameter list.

The config instance is passed to the constructor here. The specific loader for this class solves the problem by including the config instance in the argument list, which the default handler loader does not do.

In short, the default handler loader does not appear to work.

[bandtank]

It also does not appear that the line format can be modified through a parameter:

crm $ grep -r LINE_FORMAT application/*
application/Espo/Core/Log/DefaultFormatter.php:    private const LINE_FORMAT = "[%datetime%] %level_name%: %code% %message% %request% %exception%\n";
application/Espo/Core/Log/DefaultFormatter.php:            format: self::LINE_FORMAT,
crm $ grep -ri lineformat application/*
application/Espo/Core/Log/DefaultFormatter.php:use Monolog\Formatter\LineFormatter;
application/Espo/Core/Log/DefaultFormatter.php:class DefaultFormatter extends LineFormatter

The line format is set with a constant here. The parameter is never checked or passed to Monolog.

[yurikuzn]

As the constructor has a non-scalar parameter, you need to use loader.

Regarding formatter, you can use the standard monolog formatter. Or extend the standard monolog formatter.

[bandtank]

Ok, I probably didn't make my point very clearly, but I understand what you are saying. I solved the problem already by using custom loaders, which works fine. I was attempting to use the code you posted in a previous comment, which didn't work because the config parameter is not passed using the default loader. I don't think that's an issue because custom loaders and handlers work as expected, but it is not possible to specify custom handlers without custom loaders. I don't think that is what you intended, but I could be wrong. Either way, there is a supported way to customize loggers, which is all that matters in the end.

[yurikuzn]

I wrote that example without looking into the class. My previous explanation is valid. Since that handler requires the Config, which is a non-scalar value, one needs to use the loader.