Logs to stdout on scheduler run in background as ->runInBackground()->sendOutputTo('/dev/stdout') are not logged into aws logs

[ghost]

This issue #50081 was noticed while debugging this problem but it would not fix the problem (or would it?).

So I have a command
$schedule->command('system:command')->everyFiveMinutes()
->withoutOverlapping(30)->onOneServer()->runInBackground()->sendOutputTo('/dev/stdout'); // tried also with append ', true'

So basically I have in logs:

Running scheduled command: ('/usr/local/bin/php' 'artisan' system:command > '/dev/stdout' 2>&1 ; '/usr/local/bin/php' 'artisan' schedule:finish "framework/schedule-d43a122d0ae629f720381c0b9bdd5c49acd218d0" "$?") > '/dev/null' 2>&1 &

In that command I have a log that is never logged.
The LOG_CHANNEL is set to stdout and is working fine on other cases.

    'stdout' => [
        'driver' => 'monolog',
        'handler' => StreamHandler::class,
        'with' => [
            'stream' => 'php://stdout',
        ],
    ],

How can I make the logs appear in AWS from this command that is ran in background?

[ghost]

now I notice the parenthesis
('/usr/local/bin/php' 'artisan' system:command > '/dev/stdout' 2>&1 ; '/usr/local/bin/php' 'artisan' schedule:finish "framework/schedule-d43a122d0ae629f720381c0b9bdd5c49acd218d0" "$?") > '/dev/null' 2>&1 &
Those are sending everithing to dev null...

so this issue could fix this #50085 if implemented @driesvints

[ghost]

Temporary solution with macros

$schedule->customCommand('system:command')->everyFiveMinutes()
->withoutOverlapping(30)->onOneServer()->runInBackground()->sendOutputTo('/dev/stdout')

    Schedule::macro(
        'execCustomEvent',
        /**
         * Add a new command event to the schedule.
         * @see \Illuminate\Console\Scheduling\Schedule::exec
         */
        function (string $command, array $parameters = []): Event {
            //** @var Schedule $this */
            if ([] !== $parameters) {
                $command .= ' ' . $this->compileParameters($parameters);
            }

            $this->events[] = $event = new class ($this->eventMutex, $command, $this->timezone) extends Event {
                /**
                 * @inheritDoc
                 */
                public function getDefaultOutput()
                {
                    return (DIRECTORY_SEPARATOR === '\\') ? 'NUL' : '/dev/stdout';
                }

                /**
                 * @inheritDoc
                 */
                protected function ensureOutputIsBeingCaptured()
                {
                    if (is_null($this->output)) {
                        $this->sendOutputTo(storage_path('logs/schedule-' . sha1($this->mutexName()) . '.log'));
                    }
                }
            };

            return $event;
        }
    );

    Schedule::macro(
        'customCommand',
        /**
         * Add a new Artisan command event to the schedule.
         * @see \Illuminate\Console\Scheduling\Schedule::command
         */
        function (string $command, array $parameters = []): Event {
            /** @var Schedule $this */
            if (class_exists($command)) {
                $command = Container::getInstance()->make($command);

                return $this->execCustomEvent(
                    Application::formatCommandString($command->getName()),
                    $parameters,
                )->description($command->getDescription());
            }

            return $this->execCustomEvent(
                Application::formatCommandString($command),
                $parameters
            );
        }
    );
}

But still does not work.
The process from symfony is logging into

    $this->stdout = fopen('php://temp/maxmemory:'.(1024 * 1024), 'w+');
    $this->stderr = fopen('php://temp/maxmemory:'.(1024 * 1024), 'w+');

And if I call $process->getOutput() it is always empty. Also the file logging does not work in background mode, jut ES logging via HTTPS is working.

[ghost]

I added also

                /**
                 * Run the command in the background.
                 */
                protected function runCommandInBackground(\Illuminate\Contracts\Container\Container $container)
                {
                    try {
                        $this->callBeforeCallbacks($container);

                        $p = Process::fromShellCommandline($this->buildCommand(), base_path(), null, null, null);
                        $p->run(
                            function (string $type, string $data): void {
                                LoggerJob::dispatch($data, 'error');
                            }
                        );
                    } catch (\Throwable $exception) {
                        $this->removeMutex();

                        throw $exception;
                    }
                }
            };

            return $event;
        }
    );

But the callback is never called as stated in \Symfony\Component\Process\Process::run

 * Runs the process.
 *
 * The callback receives the type of output (out or err) and
 * some bytes from the output in real-time. It allows to have feedback
 * from the independent process during execution.
 *
 * The STDOUT and STDERR are also available after the process is finished
 * via the getOutput() and getErrorOutput() methods.

So it seems like echo is not writing to a pipe so the above solution will not work.

[ghost]

The only option I found is logging through a queue job from the scheduler's container... The stdout does not work ... even with the changes from the macros..

messages from echo and log are not caught by the pipe...

when I run directly from console
('/usr/local/bin/php' 'artisan' system:command> '/dev/stdout' 2>&1 ; '/usr/local/bin/php' 'artisan' schedule:finish "framework/schedule-16639bb5d90ccf91fa2ccb8e34a71a6f14534f8f" "$?") > '/dev/stdout' 2>&1 &

the logs and echos are being displayed in console.
But when it is run from proc_open symfony process, it does not....

If i remove the & from the BACKGROUND version of the code it works....
('/usr/local/bin/php' 'artisan' system:command> '/dev/stdout' 2>&1 ; '/usr/local/bin/php' 'artisan' schedule:finish "framework/schedule-16639bb5d90ccf91fa2ccb8e34a71a6f14534f8f" "$?") > '/dev/stdout' 2>&1

if I run the command in foreground it does not log to stdout... very strange...

[ghost]

https://symfony.com/doc/current/components/process.html

This explains why if I run without the ending & the stdout works.
I guess that the command ran in BG does not end by the time the wait function exists.

Some breakthrough . Using TTY

Makes the stdout log work but it does not stop the schedule:run process....

[ghost]

I asked a new question: #50118

[ghost]

SOLUTION WITH queue

        Schedule::macro(
            'execCustomEvent',
            /**
             * Add a new command event to the schedule.
             * @see \Illuminate\Console\Scheduling\Schedule::exec
             */
            function (string $command, array $parameters = []): Event {
                //** @var Schedule $this */
                if ([] !== $parameters) {
                    $command .= ' ' . $this->compileParameters($parameters);
                }

                $this->events[] = $event = new class ($this->eventMutex, $command, $this->timezone) extends Event {
                    /**
                     * @inheritDoc
                     */
                    public function getDefaultOutput()
                    {
                        return (DIRECTORY_SEPARATOR === '\\') ? 'NUL' : '/dev/stdout';
                    }

                    /**
                     * @inheritDoc
                     */
                    protected function ensureOutputIsBeingCaptured()
                    {
                        if (is_null($this->output)) {
                            $this->sendOutputTo(storage_path('logs/schedule-' . sha1($this->mutexName()) . '.log'));
                        }
                    }

                    /**
                     * Run the command in the background.
                     */
                    protected function runCommandInBackground(\Illuminate\Contracts\Container\Container $container)
                    {
                        try {
                            $this->callBeforeCallbacks($container);

                            Process::fromShellCommandline($this->buildCommand(), base_path(), [
                                CustomStreamHandler::LOG_VIA_QUEUE_JOB => CustomStreamHandler::LOG_VIA_QUEUE_JOB,
                            ], null, null)->run();
                        } catch (\Throwable $exception) {
                            $this->removeMutex();

                            throw $exception;
                        }
                    }
                };

                return $event;
            }
        );

        Schedule::macro(
            'customCommand',
            /**
             * Add a new Artisan command event to the schedule.
             * @see \Illuminate\Console\Scheduling\Schedule::command
             */
            function (string $command, array $parameters = []): Event {
                /** @var Schedule $this */
                if (class_exists($command)) {
                    $command = Container::getInstance()->make($command);

                    return $this->execCustomEvent(
                        Application::formatCommandString($command->getName()),
                        $parameters,
                    )->description($command->getDescription());
                }

                return $this->execCustomEvent(
                    Application::formatCommandString($command),
                    $parameters
                );
            }
        );

• custom logger

      <?php

       namespace App\LogHandlers;


        use App\Jobs\LoggerJob;
        use Monolog\Handler\StreamHandler;
        use Monolog\Utils;
        
        /**
         * Writes to any queue.
         */
        class CustomStreamHandler extends StreamHandler
        {
            public const LOG_VIA_QUEUE_JOB = 'LOG_VIA_QUEUE_JOB';
            /** 256 KB in bytes - maximum message size in SQS */
            protected const MAX_MESSAGE_SIZE = 262144;
            /** 100 KB in bytes - head message size for new error log */
            protected const HEAD_MESSAGE_SIZE = 102400;
        
            /**
             * @throws \InvalidArgumentException
             */
            protected function write(array $record): void
            {
        
                if (self::LOG_VIA_QUEUE_JOB !== \env(self::LOG_VIA_QUEUE_JOB)) {
                    parent::write($record);
        
                    return;
                }
        
                if (!isset($record['formatted']) || 'string' !== gettype($messageBody = $record['formatted'])) {
                    throw new \InvalidArgumentException('QueueHandler accepts only formatted records as a string' .
                        Utils::getRecordMessageForException($record));
                }
        
                if (strlen($messageBody) >= static::MAX_MESSAGE_SIZE) {
                    $messageBody = Utils::substr($messageBody, 0, static::HEAD_MESSAGE_SIZE);
                }
        
                LoggerJob::dispatch($messageBody, $this->level);
            }
        }

        <?php
        
        namespace App\Jobs;
        
        use Illuminate\Support\Facades\Log;
        
        class LoggerJob extends FailOnTimeoutJob
        {
            public function __construct(protected string $message, protected int $level)
            {
            }
        
            public function handle(): void
            {
                try {
                    Log::log(\strtolower(\Monolog\Logger::getLevelName($this->level)), $this->message);
                } catch (\Throwable $e) {
                    $this->logError($e, \get_object_vars($this));
                }
            }
        
            public function failed(\Throwable $e): void
            {
                $this->logError($e, \get_object_vars($this));
            }
        }



        'stdout' => [
            'driver' => 'monolog',
            'level' => env('LOG_LEVEL', 'debug'),
            'handler' => \App\LogHandlers\CustomStreamHandler::class,
            'with' => [
                'stream' => 'php://stdout',
            ],
        ],


        $schedule->customCommand('system:command')->everyMinute()
            ->withoutOverlapping(30)->onOneServer()->runInBackground();

[rburgst]

the fact that I have to basically do open heart surgery just to get docker compatible logging for my tasks is quite sad IMHO. I would have hoped for something built in. Its 2024 after all.

[ghost]

@rburgst because the command is run in a background shell without PTY ON, it makes the stdout inaccessible. This is just a workaround.

[rburgst]

I know and I am thankful for your workaround. However, one would have thought that this is a quite common requirement (being in the container age and all) and therefore, I would have appreciated something out of the box.

[ghost]

Nothing stops laravel community from incorporating this into laravel and also document it. But so many useful bug fixes are disregarded because they are considered to be edge cases and they are afraid of messing other flows that are not edge cases, so they don't fix them. Example #51825 (comment) , another example #52732 (comment)

[ghost]

I added also the Logger job to the answer.