craftcms
[4.5.15]: Delayed logging and high memory usage in Console Controller
Description
I'm experiencing issues with delayed logging and high memory usage in a Craft CMS console controller. The issue arises while handling a large feed with over 40,000 elements, segmented into pages of 5 elements each. The logs are only written after the entire script execution is complete, leading to inaccurate timestamps and excessive memory consumption. In cases where the script is abruptly stopped, no logs are recorded.
Steps to Reproduce
- Create a console controller in Craft CMS
4.5.15. - The controller fetches JSON data from an external Element API.
- Use
do { while }for pagination andforeachfor processing the data. - During and after the script execution, observe issues with delayed logging and memory usage.
Expected Behavior
I expected the logs to be written immediately or at more frequent intervals for accurate timestamping. Additionally, the memory usage should be optimized to handle the high volume of data without causing controller crashes.
Actual Behavior
The actual behavior observed was a significant delay in log writing, resulting in inaccurate timestamps. If the script execution was interrupted, no logs were recorded at all. When processing the large volume of elements, the high memory usage led to crashes of the controller.
Question
I'm aware of the reset() function in Monolog, for handling long-running processes and avoiding memory leaks (Monolog documentation), that maybe could help. Is there a similar functionality available in Craft CMS that can help in managing log writing more effectively?
Code Sample
<?php
use yii\helpers\Console;
use yii\console\ExitCode;
public function actionImport($url, $page = 1)
{
$client = new \GuzzleHttp\Client();
$maxAttempts = 10;
do {
$currentAttempt = 0;
$apiUrl = "{$url}?page={$page}";
do {
try {
$response = $client->get($apiUrl);
$data = json_decode($response->getBody(), true);
$meta = $data['meta'];
$pagination = $meta['pagination'];
// Verify 'data' node in response
if (isset($data['data']) && is_array($data['data'])) {
foreach ($data['data'] as $item) {
$this->stdout($data['title']."\n");
}
}
Craft::info([
'message' => "Page {$page} finished"
], 'migration');
// Update the page for pagination
$page++;
// Update the loop condition to exit the loop
$currentAttempt = $maxAttempts;
break; // Exit the attempt loop on success
} catch (\GuzzleHttp\Exception\RequestException $e) {
$currentAttempt++;
// Pause before retry
if ($currentAttempt == 1) {
sleep(10);
} else if ($currentAttempt > 1 && $currentAttempt <= 5) {
sleep(60);
} else {
sleep(300);
}
if ($currentAttempt >= $maxAttempts) {
// Return the error in the console
$message = "Error encountered on page {$page} after {$maxAttempts} attempts: " . $e->getMessage();
$this->stderr("{$message}\n", Console::FG_RED);
// Save error to log file
Craft::error([
'message' => $message
], 'migration');
// Break loop to process next page
break;
}
}
} while ($currentAttempt < $maxAttempts);
} while (isset($pagination['links']['next']) && !empty($pagination['links']['next'])); // Check for the 'next' pagination link
return ExitCode::OK;
}
Craft CMS version
4.5.15
PHP version
8.1.13
@romainpoirier are you able to privately share the URL, so I can reproduce exactly what you're seeing?
You can share with me on Discord (timkelty) or to [email protected].
Also, could you share your composer.json, composer.lock, and config/project/* files, so I can reproduce?
There's no URL to share as this Controller is run from the console.
Currently, the solution I found is to use Monolog\Logger instead of Craft::error();
That way, it's working as expected, the logs are written as soon as they should be, and I'm also able to use the reset() function.
There's no URL to share as this Controller is run from the console.
I mean the URL you're passing to the console command, that has the element API response.
I'm not able to share you the URL as it's a protected URL. However, here's the content of the first page (with fake data for testing purpose):
{
"data": [
{
"userEmail": "[email protected]",
"bike": {
"brand": "DummyBrand1",
"model": "DummyModel1",
"mainColor": "DummyColor1",
"secondaryColor": "DummySecondaryColor1",
"type": "DUMMY_TYPE1",
"lastUpdateTimestamp": "2023-01-01 00:00:00.000000",
"creationTimestamp": "2022-01-01 00:00:00.000000",
"status": "DUMMY_STATUS",
"codeQrBody": {
"code": "DUMMYCODE1234",
"creationTimestamp": "2023-01-01 00:00:00.000000"
}
},
"code": "ABC1913SPL9",
"externalReferences": [],
"attachments": [],
"events": [],
"transfers": []
},
{
"userEmail": "[email protected]",
"bike": {
"brand": "DummyBrand2",
"model": "DummyModel2",
"mainColor": "DummyColor2",
"secondaryColor": "DummySecondaryColor2",
"type": "DUMMY_TYPE2",
"lastUpdateTimestamp": "2023-01-02 00:00:00.000000",
"creationTimestamp": "2022-01-02 00:00:00.000000",
"status": "DUMMY_STATUS",
"codeQrBody": {
"code": "DUMMYCODE1235",
"creationTimestamp": "2023-01-02 00:00:00.000000"
}
},
"code": "ABC19CV11A8",
"externalReferences": [],
"attachments": [],
"events": [],
"transfers": []
},
{
"userEmail": "[email protected]",
"bike": {
"brand": "DummyBrand3",
"model": "DummyModel3",
"mainColor": "DummyColor3",
"secondaryColor": "DummySecondaryColor3",
"type": "DUMMY_TYPE3",
"lastUpdateTimestamp": "2023-01-03 00:00:00.000000",
"creationTimestamp": "2022-01-03 00:00:00.000000",
"status": "DUMMY_STATUS",
"codeQrBody": {
"code": "DUMMYCODE1236",
"creationTimestamp": "2023-01-03 00:00:00.000000"
}
},
"code": "ABC197WN6VD",
"externalReferences": [],
"attachments": [],
"events": [],
"transfers": []
},
{
"userEmail": "[email protected]",
"bike": {
"brand": "DummyBrand4",
"model": "DummyModel4",
"mainColor": "DummyColor4",
"secondaryColor": "DummySecondaryColor4",
"type": "DUMMY_TYPE4",
"lastUpdateTimestamp": "2023-01-04 00:00:00.000000",
"creationTimestamp": "2022-01-04 00:00:00.000000",
"status": "DUMMY_STATUS",
"codeQrBody": {
"code": "DUMMYCODE1237",
"creationTimestamp": "2023-01-04 00:00:00.000000"
}
},
"code": "ABC19Y1Q4GS",
"externalReferences": [],
"attachments": [],
"events": [],
"transfers": []
},
{
"userEmail": "[email protected]",
"bike": {
"brand": "DummyBrand5",
"model": "DummyModel5",
"mainColor": "DummyColor5",
"secondaryColor": "DummySecondaryColor5",
"type": "DUMMY_TYPE5",
"lastUpdateTimestamp": "2023-01-05 00:00:00.000000",
"creationTimestamp": "2022-01-05 00:00:00.000000",
"status": "DUMMY_STATUS",
"codeQrBody": {
"code": "DUMMYCODE1238",
"creationTimestamp": "2023-01-05 00:00:00.000000"
}
},
"code": "ABC1973C551",
"externalReferences": [],
"attachments": [],
"events": [],
"transfers": []
}
],
"meta": {
"pagination": {
"total": 47519,
"count": 5,
"per_page": 5,
"current_page": 1,
"total_pages": 9504,
"links": {
"next": "https://example.com/fr/items.json?token=secret&page=2"
}
}
}
}
@romainpoirier a couple things to try:
Within your loop, add:
// Flush in-memory logs to targets (Monolog)
Craft::$app->getLog()->getLogger()->flush();
I suspect this will help with the memory consumption.
Also, instead of replacing Craft::error, you can try calling reset() directly on the Monolog logger already in use, like so:
/** @var MonologTarget $logTarget */
$logTarget = Craft::$app->getLog()->targets[Dispatcher::TARGET_CONSOLE];
$logTarget->getLogger()->reset();
Sorry for the late reply, I'm was very busy working on this project. As the switch to Monolog works like a charm, and massive tests gone using this, I finally didn't go back to the Craft method. For a future case, what would be the advantage/disadvantage to use Craft instead of Monolog?
@romainpoirier Craft's default loggers use Monolog log targets, so either way you're using Monolog. Using monolog directly wouldn't be going through Yii at all, so you wouldn't get any of the log filtering Yii provides.