Luya's logger alters arguments of method it was called from

[jettero777]

Beware of using \luya\admin\models\Logger::info() or \luya\admin\models\Logger::warning() or \luya\admin\models\Logger::error() inside any method which has object argument passed by reference.

After calling the logger the argument will become array.

Example:

static function test(&$arg)
{
    \Yii::error(gettype($arg)); // object
    \luya\admin\models\Logger::info('test');
    \Yii::error(gettype($arg)); // now it is array!
}

Looks like it is because ['args'] part of array from debug_backtrace() is returned by reference and it is being altered during json encode inside Logger::log() https://www.php.net/manual/en/function.debug-backtrace.php#110237

[nadar]

Do you suggest any fix here? Because it seems to be a "problem" of php's debug backtrace function not the logger itself.

maybe we could add a php doc regarding this?

[jettero777]

I think the problem is here, $fnArgs is a ref to args 'trace_function_args' => Json::encode($fnArgs),

and it being altered after

public static function encode($value, $options = 320)
{
    $expressions = [];
    $value = static::processData($value, $expressions, uniqid('', true));

I think doing clone() before calling Json::encode() should help as it will destroy the reference. Here example https://stackoverflow.com/questions/4123571/how-to-make-a-copy-of-an-object-without-reference

[nadar]

would you please send a pull request? would nice! thanks

[jettero777]

@nadar Yep I will try tomorrow to fix it.

[jettero777]

Hey @nadar, btw what do you think if to remove hardcoded debug_backtrace from Logger::success() and Logger::info()? Or to make it conditional?

Such info log output can be often even in production and it takes time and performance to get and encode backtrace into json and usually it is not needed for info and success types of messages, when you want just echo some information.

PS And I mean not only backtrace but whole bunch of debug info

            'trace_file' => $file,
            'trace_line' => $line,
            'trace_function' => $fn,
            'trace_function_args' => Json::encode($fnArgs),
            'get' => (isset($_GET)) ? Json::encode($_GET) : '{}',
            'post' => (isset($_POST)) ? Json::encode($_POST) : '{}',
            'session' => (isset($_SESSION)) ? Json::encode($_SESSION) : '{}',
            'server' => (isset($_SERVER)) ? Json::encode($_SERVER) : '{}',

PPS Btw the debug_backtrace has an option since 5.3.6 to omit 'args' from output because of memory concerns. DEBUG_BACKTRACE_IGNORE_ARGS | Whether or not to omit the "args" index, and thus all the function/method arguments, to save memory. So the args can impact memory if there is big object in args, but moreover in our case it is also encoded to json afterwards, impacting memory and performance even more.

[nadar]

well i would not change the main intent of the function. Its not just a log mechanism it should also collect its environment, this might help to debug or find informations in certain situations. The trace is limited to 2 rows, which i don't think is a memory problem. But we could add DEBUG_BACKTRACE_IGNORE_ARGS, sure. 👍