[4.5.15]: Delayed logging and high memory usage in Console Controller #14242

romainpoirier · 2024-01-30T08:55:44Z

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 and foreach for 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

The text was updated successfully, but these errors were encountered:

timkelty · 2024-02-01T14:38:30Z

@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?

romainpoirier · 2024-02-01T16:28:10Z

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.

timkelty · 2024-02-01T16:30:57Z

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.

romainpoirier · 2024-02-01T16:45:02Z

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"
            }
        }
    }
}

timkelty · 2024-02-02T02:33:36Z

@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();

timkelty · 2024-02-26T18:15:13Z

@romainpoirier Just following up – were you able to test any of that?

timkelty · 2024-03-16T01:40:14Z

Closing, but let me know if you're still having issues.

romainpoirier · 2024-03-20T15:57:51Z

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?

timkelty · 2024-03-21T01:30:12Z

@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.

romainpoirier added bug craft4 labels Jan 30, 2024

romainpoirier changed the title ~~[4.x]: Delayed logging and high memory usage in Console Controller~~ [4.5.15]: Delayed logging and high memory usage in Console Controller Jan 30, 2024

brandonkelly assigned timkelty Jan 30, 2024

timkelty mentioned this issue Feb 3, 2024

Add getDefaultTarget to Dispatcher #14283

Merged

timkelty closed this as completed Mar 16, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[4.5.15]: Delayed logging and high memory usage in Console Controller #14242

[4.5.15]: Delayed logging and high memory usage in Console Controller #14242

romainpoirier commented Jan 30, 2024 •

edited

Loading

timkelty commented Feb 1, 2024 •

edited

Loading

romainpoirier commented Feb 1, 2024

timkelty commented Feb 1, 2024

romainpoirier commented Feb 1, 2024 •

edited

Loading

timkelty commented Feb 2, 2024 •

edited

Loading

timkelty commented Feb 26, 2024

timkelty commented Mar 16, 2024

romainpoirier commented Mar 20, 2024

timkelty commented Mar 21, 2024

[4.5.15]: Delayed logging and high memory usage in Console Controller #14242

[4.5.15]: Delayed logging and high memory usage in Console Controller #14242

Comments

romainpoirier commented Jan 30, 2024 • edited Loading

Description

Steps to Reproduce

Expected Behavior

Actual Behavior

Question

Code Sample

Craft CMS version

PHP version

timkelty commented Feb 1, 2024 • edited Loading

romainpoirier commented Feb 1, 2024

timkelty commented Feb 1, 2024

romainpoirier commented Feb 1, 2024 • edited Loading

timkelty commented Feb 2, 2024 • edited Loading

timkelty commented Feb 26, 2024

timkelty commented Mar 16, 2024

romainpoirier commented Mar 20, 2024

timkelty commented Mar 21, 2024

romainpoirier commented Jan 30, 2024 •

edited

Loading

timkelty commented Feb 1, 2024 •

edited

Loading

romainpoirier commented Feb 1, 2024 •

edited

Loading

timkelty commented Feb 2, 2024 •

edited

Loading