Skip to content

[Console][Monolog-Bridge] Logs gain extra empty line when used with console sections #50382

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.

Sign up for GitHub

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

Jump to bottom
Closed
kiler129 opened this issue May 21, 2023 · 0 comments
Closed

[Console][Monolog-Bridge] Logs gain extra empty line when used with console sections #50382

kiler129 opened this issue May 21, 2023 · 0 comments
Labels
Bug Console Status: Needs Review

Comments

@kiler129
Copy link
Contributor

Symfony version(s) affected

6.2.10

Description

First of all, apologies if this isn't a bug but some misconfiguration. I tried my best to isolate it however.

Problem

While using multiple progress bars, as shown in the docs, one has to use sections. This produces an expected result. However, when using logging alongside some logs (ref (b) in code) will be swallowed:

normal-log-and-bars.mov 
19:05:08 WARNING   [app] Hello 30
  100/1000 [==>-------------------------]  10%
19:05:08 WARNING   [app] Hello 50
19:05:08 WARNING   [app] Hello 60
19:05:08 WARNING   [app] Hello 70
  100/1000 [==>-------------------------]  10%
  200/1000 [=====>----------------------]  20%
19:05:08 WARNING   [app] Hello 100

Fixing the logs breaks sections spacing

The solution I tracked down is to ensure logs (more specifically \Symfony\Bridge\Monolog\Handler\ConsoleHandler) uses a section above progress bars sections. This entails something I'm not 100% comfortable with - injecting monolog.handler.console and doing a manual ->setOutput() on it (ref (a) in code).

This produces almost correct result with no output being swallowed, but with extra spacing between log lines:

section-log-and-bars.mov 
19:09:07 WARNING   [app] Hello 270

19:09:07 WARNING   [app] Hello 280

19:09:08 WARNING   [app] Hello 290

  200/1000 [=====>----------------------]  20%
  500/1000 [==============>-------------]  50%

Issue with monolog-bridge + section?

I ran two more tests: normal logs (no ->setOutput($section) override) and logs in section but without bars.

section-log-no-bars.mov 
19:13:00 WARNING   [app] Hello 10

19:13:01 WARNING   [app] Hello 20

19:13:01 WARNING   [app] Hello 30
normal-log-no-bars.mov 
19:13:18 WARNING   [app] Hello 10
19:13:18 WARNING   [app] Hello 20
19:13:18 WARNING   [app] Hello 30

As you can see the issue seems to be caused by a combination of console's ConsoleSectionOutput & monolog's bridge ConsoleHandler. I was trying to debug it further but I got stuck.

How to reproduce

<?php
namespace App\Command;

use Psr\Log\LoggerInterface;
use Symfony\Bridge\Monolog\Handler\ConsoleHandler;
use Symfony\Component\Console\Attribute\AsCommand;
use Symfony\Component\Console\Command\Command;
use Symfony\Component\Console\Helper\ProgressBar;
use Symfony\Component\Console\Input\InputInterface;
use Symfony\Component\Console\Output\OutputInterface;
use Symfony\Component\DependencyInjection\Attribute\Autowire;

#[AsCommand(name: 'app:test',)]
class TestCommand extends Command
{
    public function __construct(
        private LoggerInterface $log,
        #[Autowire(service: 'monolog.handler.console')] private ConsoleHandler $consoleHandler
    ) {
        parent::__construct();
    }

    protected function execute(InputInterface $input, OutputInterface $output): int
    {
        //Without this the output of some logs will be swallowed once progress bars start rendering
        $this->consoleHandler->setOutput($output->section()); //ref. (a)

        //Example adapted from https://symfony.com/doc/current/components/console/helpers/progressbar.html#displaying-multiple-progress-bars
        $section1 = $output->section();
        $section2 = $output->section();

        $progress1 = new ProgressBar($section1);
        $progress2 = new ProgressBar($section2);
        $progress1->start(1000);
        $progress2->start(1000);

        $i = 0;
        while (++$i < 1000) {
            $progress1->advance();
            if ($i % 2 === 0) {
                $progress2->advance(4);
            }

            if ($i % 10 === 0) {
                $this->log->warning('Hello ' . $i); //ref. (b)
            }

            usleep(5000);
        }

        return Command::SUCCESS;
    }
}

Possible Solution

No response

Additional Context

No response
@kiler129 kiler129 added the Bug label May 21, 2023
@joelwurtz joelwurtz mentioned this issue Aug 14, 2023
Merged
nicolas-grekas added a commit that referenced this issue Aug 16, 2023
@nicolas-grekas
bug #51378 [Console] avoid multiple new line when message already end…
2991661 
…s with a new line in section output (joelwurtz)

This PR was merged into the 6.3 branch.

Discussion
----------

[Console] avoid multiple new line when message already ends with a new line in section output

| Q             | A
| ------------- | ---
| Branch?       | 6.3
| Bug fix?      | yes
| New feature?  | no
| Deprecations? | no
| Tickets       | #50382
| License       | MIT
| Doc PR        |

When we write to the section with a new line in the message it ends up adding a double new line, it can be easily seen when we set a section as a console handler for the logs, each line of log will have a double new line ending adding a lot of noise.

I began to fix the implementation to correctly handle this case, but with all the logic of the max height and other stuff it appears to be way more complicated.

Simulating this case by removing the new line at the end of the message and recalling the write function with the newline parameter to true was way easier and avoid too many headcache when looking at the code.

Should fix #50382

Commits
-------

1f20f72 fix(console): avoid multiple new line when message already ends with a new line
symfony-splitter pushed a commit to symfony/console that referenced this issue Aug 16, 2023
@nicolas-grekas
bug #51378 [Console] avoid multiple new line when message already end…
eca495f 
…s with a new line in section output (joelwurtz)

This PR was merged into the 6.3 branch.

Discussion
----------

[Console] avoid multiple new line when message already ends with a new line in section output

| Q             | A
| ------------- | ---
| Branch?       | 6.3
| Bug fix?      | yes
| New feature?  | no
| Deprecations? | no
| Tickets       | symfony/symfony#50382
| License       | MIT
| Doc PR        |

When we write to the section with a new line in the message it ends up adding a double new line, it can be easily seen when we set a section as a console handler for the logs, each line of log will have a double new line ending adding a lot of noise.

I began to fix the implementation to correctly handle this case, but with all the logic of the max height and other stuff it appears to be way more complicated.

Simulating this case by removing the new line at the end of the message and recalling the write function with the newline parameter to true was way easier and avoid too many headcache when looking at the code.

Should fix symfony/symfony#50382

Commits
-------

1f20f72640 fix(console): avoid multiple new line when message already ends with a new line
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
Bug Console Status: Needs Review
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@nicolas-grekas @kiler129 @carsonbot