Setting log_level via environment variable requires cache clear

[kevinreniers]

Hi, I'm trying to use the log_level from env vars implemented in #357 but I can't seem to get it to work without clearing the cache between command executions.

I'm using v3.7 of this bundle:

root@9e633aa0c868:/app# composer show symfony/monolog-bundle
name     : symfony/monolog-bundle
descrip. : Symfony MonologBundle
keywords : log, logging
versions : * v3.7.0

I have this configuration:

# config/packages/probe/monolog.yaml
parameters:
    log_level: "%env(APP_LOG_LEVEL)%"

monolog:
    handlers:
        main:
            type: stream
            path: php://stderr
            level: '%log_level%'

And I'm testing with this command:

<?php
declare(strict_types=1);

namespace App\Command;

use Psr\Log\LoggerInterface;
use Symfony\Component\Console\Command\Command;
use Symfony\Component\Console\Input\InputInterface;
use Symfony\Component\Console\Output\OutputInterface;
use Symfony\Component\DependencyInjection\ContainerInterface;

class TestCommand extends Command
{
    protected static $defaultName = 'app:test';
    private ContainerInterface $container;
    private LoggerInterface $logger;

    public function __construct(ContainerInterface $container, LoggerInterface $logger, string $name = null)
    {
        parent::__construct($name);
        $this->container = $container;
        $this->logger = $logger;
    }

    protected function execute(InputInterface $input, OutputInterface $output)
    {
        $output->writeln('log_level: ' . $this->container->getParameter('log_level'));

        $this->logger->debug('debug');
        $this->logger->info('info');
        $this->logger->notice('notice');
        $this->logger->warning('warning');
        $this->logger->error('error');
        $this->logger->critical('critical');
        $this->logger->alert('alert');
        $this->logger->emergency('emergency');

        return Command::SUCCESS;
    }
}

I expected the APP_LOG_LEVEL to be able to change between subsequent runs of the command w/o clearing the cache, but that doesn't seem to work. As soon as I start the command with a valid value for log_level, I can never change it until I clear the cache.

This is also annoying when I already have a .env/.env.local file since it always seems to take that value.

In this example, I have APP_LOG_LEVEL=warning in the .env file.

root@9e633aa0c868:/app# APP_ENV=probe php bin/console app:test                  
log_level: warning
[2021-07-05T16:27:13.541340+00:00] app.WARNING: warning [] []
[2021-07-05T16:27:13.545269+00:00] app.ERROR: error [] []
[2021-07-05T16:27:13.547210+00:00] app.CRITICAL: critical [] []
[2021-07-05T16:27:13.548159+00:00] app.ALERT: alert [] []
[2021-07-05T16:27:13.549459+00:00] app.EMERGENCY: emergency [] []
root@9e633aa0c868:/app# APP_LOG_LEVEL=debug APP_ENV=probe php bin/console app:test
log_level: debug
[2021-07-05T16:27:17.861489+00:00] app.WARNING: warning [] []
[2021-07-05T16:27:17.864648+00:00] app.ERROR: error [] []
[2021-07-05T16:27:17.866875+00:00] app.CRITICAL: critical [] []
[2021-07-05T16:27:17.868456+00:00] app.ALERT: alert [] []
[2021-07-05T16:27:17.869008+00:00] app.EMERGENCY: emergency [] []

If I remove APP_LOG_LEVEL from .env or remove the cache and then restart my command passing APP_LOG_LEVEL=debug it'll use that value for all subsequent runs. It won't change until I clear:cache or remove the cache.

root@9e633aa0c868:/app# rm -rf var/cache/probe/*
root@9e633aa0c868:/app# APP_LOG_LEVEL=debug APP_ENV=probe php bin/console app:test                    
log_level: debug
[2021-07-05T16:28:58.107361+00:00] app.DEBUG: debug [] []
[2021-07-05T16:28:58.107665+00:00] app.INFO: info [] []
[2021-07-05T16:28:58.107821+00:00] app.NOTICE: notice [] []
[2021-07-05T16:28:58.107951+00:00] app.WARNING: warning [] []
[2021-07-05T16:28:58.108081+00:00] app.ERROR: error [] []
[2021-07-05T16:28:58.108239+00:00] app.CRITICAL: critical [] []
[2021-07-05T16:28:58.109731+00:00] app.ALERT: alert [] []
[2021-07-05T16:28:58.110578+00:00] app.EMERGENCY: emergency [] []

Am I doing something wrong or is this intended behavior?

[dbrumann]

I'm afraid this is by design. We need to resolve the env var during compile time of the container to ensure it contains a valid value, so the logger will not throw an exception when it is initialized.

I imagine making this work without resolving the env var preemptively in the extension will be tricky and I am not sure it is worth it. Apart from all the edge cases, having a dynamic log level will make your logging experience inconsistent (was there nothing logged because there was no error or did someone change the log level?). Not to mention, once you fetch the logger from the container for the first time the log level will again be pinned again (for that shared service instance during the request).

[kevinreniers]

I see. I'll just clear the cache if I need to change it then, thanks! :-)