Skip to content

Commit 849f868

Browse files
josbeirjosbeir
committed
Redirect stdout loggers to stderr preventing json response polutions
1 parent 3ccfd9a commit 849f868

5 files changed

Lines changed: 168 additions & 3 deletions

File tree

‎src/Command/SubprocessJobRunnerCommand.php‎

Lines changed: 52 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -20,12 +20,15 @@
2020
use Cake\Console\Arguments;
2121
use Cake\Console\ConsoleIo;
2222
use Cake\Core\ContainerInterface;
23+
use Cake\Log\Engine\ConsoleLog;
24+
use Cake\Log\Log;
2325
use Cake\Queue\Job\Message;
2426
use Cake\Queue\Queue\Processor;
2527
use Enqueue\Null\NullConnectionFactory;
2628
use Enqueue\Null\NullMessage;
2729
use Interop\Queue\Message as QueueMessage;
2830
use Interop\Queue\Processor as InteropProcessor;
31+
use Psr\Log\LoggerInterface;
2932
use Psr\Log\NullLogger;
3033
use RuntimeException;
3134
use Throwable;
@@ -160,8 +163,10 @@ protected function executeJob(array $data): string
160163
}
161164
}
162165

166+
$logger = $this->configureLogging($data);
167+
163168
$message = new Message($queueMessage, $context, $this->container);
164-
$processor = new Processor(new NullLogger(), $this->container);
169+
$processor = new Processor($logger, $this->container);
165170

166171
$result = $processor->processMessage($message);
167172

@@ -170,6 +175,52 @@ protected function executeJob(array $data): string
170175
return is_string($result) ? $result : (string)$result;
171176
}
172177

178+
/**
179+
* Configure logging to use STDERR to prevent job logs from contaminating STDOUT.
180+
* Reconfigures all CakePHP loggers to write to STDERR.
181+
*
182+
* @param array<string, mixed> $data Job data
183+
* @return \Psr\Log\LoggerInterface
184+
*/
185+
protected function configureLogging(array $data): LoggerInterface
186+
{
187+
if (Log::drop('stderr')) {
188+
// Logger was already configured, remove it first
189+
}
190+
191+
Log::setConfig('stderr', [
192+
'className' => ConsoleLog::class,
193+
'stream' => 'php://stderr',
194+
]);
195+
196+
$loggerName = $data['logger'] ?? 'stderr';
197+
if ($loggerName === 'stdout') {
198+
$loggerName = 'stderr';
199+
}
200+
201+
$logger = Log::engine($loggerName);
202+
if (!$logger instanceof LoggerInterface) {
203+
$logger = new NullLogger();
204+
}
205+
206+
// Reconfigure all CakePHP logs to use stderr to prevent job logs from appearing in STDOUT
207+
$loggers = Log::configured();
208+
foreach ($loggers as $configLoggerName) {
209+
if ($configLoggerName === 'stderr') {
210+
continue;
211+
}
212+
213+
Log::drop($configLoggerName);
214+
}
215+
216+
Log::setConfig('default', [
217+
'className' => ConsoleLog::class,
218+
'stream' => 'php://stderr',
219+
]);
220+
221+
return $logger;
222+
}
223+
173224
/**
174225
* Output result as JSON to STDOUT.
175226
*

‎src/Command/WorkerCommand.php‎

Lines changed: 22 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -172,6 +172,21 @@ protected function getLogger(Arguments $args): LoggerInterface
172172
return $logger ?? new NullLogger();
173173
}
174174

175+
/**
176+
* Get logger for subprocess output.
177+
* Always returns a real logger for subprocess mode to show job logs.
178+
*
179+
* @param \Cake\Console\Arguments $args Arguments
180+
* @return \Psr\Log\LoggerInterface
181+
*/
182+
protected function getSubprocessLogger(Arguments $args): LoggerInterface
183+
{
184+
$loggerName = (string)$args->getOption('logger');
185+
$logger = Log::engine($loggerName);
186+
187+
return $logger ?? new NullLogger();
188+
}
189+
175190
/**
176191
* Creates and returns a Processor object
177192
*
@@ -201,15 +216,20 @@ protected function getProcessor(Arguments $args, ConsoleIo $io, LoggerInterface
201216
if ($args->getOption('subprocess') || ($config['subprocess']['enabled'] ?? false)) {
202217
$subprocessConfig = array_merge(
203218
$config['subprocess'] ?? [],
204-
['enabled' => true],
219+
[
220+
'enabled' => true,
221+
'logger' => $config['logger'] ?? (string)$args->getOption('logger'),
222+
],
205223
);
206224

207225
if ($processorClass !== Processor::class && !is_subclass_of($processorClass, Processor::class)) {
208226
$io->error('Subprocess mode is only supported with the default Processor class');
209227
$this->abort();
210228
}
211229

212-
$processor = new SubprocessProcessor($logger, $subprocessConfig, $this->container);
230+
// Use a real logger for subprocess output so logs are visible
231+
$subprocessLogger = $this->getSubprocessLogger($args);
232+
$processor = new SubprocessProcessor($subprocessLogger, $subprocessConfig, $this->container);
213233
} else {
214234
$processor = new $processorClass($logger, $this->container);
215235
}

‎src/Queue/SubprocessProcessor.php‎

Lines changed: 10 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -185,6 +185,7 @@ protected function prepareJobData(QueueMessage $message): array
185185
'messageClass' => get_class($message),
186186
'body' => $body,
187187
'properties' => $properties,
188+
'logger' => $this->config['logger'] ?? 'stderr',
188189
];
189190
}
190191

@@ -281,6 +282,15 @@ protected function executeInSubprocess(array $jobData): array
281282
}
282283

283284
$errorOutput .= $chunk;
285+
// Stream logs in real-time via logger if available
286+
if (isset($this->logger)) {
287+
// Log each line as it comes in for real-time visibility
288+
foreach (explode(PHP_EOL, rtrim($chunk, PHP_EOL)) as $line) {
289+
if (!empty($line)) {
290+
$this->logger->debug($line);
291+
}
292+
}
293+
}
284294
}
285295
}
286296

‎tests/TestCase/Command/SubprocessJobRunnerCommandTest.php‎

Lines changed: 58 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -24,6 +24,7 @@
2424
use Enqueue\Null\NullMessage;
2525
use Interop\Queue\Processor;
2626
use ReflectionClass;
27+
use TestApp\Job\LogToDebugJob;
2728
use TestApp\TestProcessor;
2829

2930
class SubprocessJobRunnerCommandTest extends TestCase
@@ -252,4 +253,61 @@ public function testOutputResult(): void
252253

253254
$method->invoke($command, $io, ['success' => true, 'result' => 'ack']);
254255
}
256+
257+
/**
258+
* Test that logs are redirected to STDERR and don't corrupt JSON output
259+
*/
260+
public function testLogsRedirectedToStderr(): void
261+
{
262+
$jobData = [
263+
'messageClass' => NullMessage::class,
264+
'body' => [
265+
'class' => [LogToDebugJob::class, 'execute'],
266+
'args' => [['foo' => 'bar']],
267+
],
268+
'properties' => [],
269+
];
270+
271+
$command = 'php ' . ROOT . 'bin/cake.php queue subprocess-runner';
272+
273+
$descriptors = [
274+
0 => ['pipe', 'r'],
275+
1 => ['pipe', 'w'],
276+
2 => ['pipe', 'w'],
277+
];
278+
279+
$process = proc_open($command, $descriptors, $pipes);
280+
$this->assertIsResource($process);
281+
282+
// Write job data to STDIN
283+
$jobDataJson = json_encode($jobData);
284+
if ($jobDataJson !== false) {
285+
fwrite($pipes[0], $jobDataJson);
286+
}
287+
288+
fclose($pipes[0]);
289+
290+
// Read STDOUT (should be clean JSON only)
291+
$stdout = stream_get_contents($pipes[1]);
292+
fclose($pipes[1]);
293+
294+
// Read STDERR to prevent pipe blocking
295+
stream_get_contents($pipes[2]);
296+
fclose($pipes[2]);
297+
298+
proc_close($process);
299+
300+
// STDOUT should be valid JSON without any log messages
301+
$result = json_decode($stdout, true);
302+
$this->assertIsArray($result, 'STDOUT should contain valid JSON: ' . $stdout);
303+
$this->assertArrayHasKey('success', $result);
304+
$this->assertTrue($result['success']);
305+
$this->assertSame(Processor::ACK, $result['result']);
306+
307+
// STDOUT should not contain log text
308+
$this->assertStringNotContainsString('Debug job was run', $stdout);
309+
310+
// STDERR may contain log messages (depends on log configuration)
311+
// We just verify it doesn't interfere with JSON parsing
312+
}
255313
}

‎tests/test_app/src/Job/MultilineLogJob.php‎

Lines changed: 26 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,26 @@
1+
<?php
2+
declare(strict_types=1);
3+
4+
namespace TestApp\Job;
5+
6+
use Cake\Log\LogTrait;
7+
use Cake\Queue\Job\JobInterface;
8+
use Cake\Queue\Job\Message;
9+
use Interop\Queue\Processor;
10+
use Psr\Log\LogLevel;
11+
12+
class MultilineLogJob implements JobInterface
13+
{
14+
use LogTrait;
15+
16+
public function execute(Message $message): ?string
17+
{
18+
$this->log('Job execution started', LogLevel::INFO);
19+
$this->log('Processing step 1 completed', LogLevel::INFO);
20+
$this->log('Processing step 2 completed', LogLevel::INFO);
21+
$this->log('Processing step 3 completed', LogLevel::INFO);
22+
$this->log('Job execution finished', LogLevel::INFO);
23+
24+
return Processor::ACK;
25+
}
26+
}

0 commit comments

Comments
 (0)