Yii2: yii\log\EmailTarget includes trace even when traceLevel is set to zero

[fillup]

I have log trace level set to zero, with targets configured for syslog and email, and for some reason the email messages include stack trace information.

What steps will reproduce the problem?

Configuration:

'log' => [
    'traceLevel' => 0,
    'targets' => [
        [
            'class' => 'Sil\JsonSyslog\JsonSyslogTarget',
            'levels' => ['error', 'warning'],
            'except' => [
                'yii\web\HttpException:401',
                'yii\web\HttpException:404',
            ],
            'logVars' => [], // Disable logging of _SERVER, _POST, etc.
            'prefix' => function($message) use ($appEnv) {
                $prefixData = [
                    'env' => $appEnv,
                ];

                // There is no user when a console command is run
                try {
                    $appUser = \Yii::$app->user;
                } catch (\Exception $e) {
                    $appUser = null;
                }
                if ($appUser && ! \Yii::$app->user->isGuest) {
                    $prefixData['user'] = \Yii::$app->user->identity->email;
                }
                return \yii\helpers\Json::encode($prefixData);
            },
        ],
        [
            'class' => 'yii\log\EmailTarget',
            'levels' => ['error'],
            'except' => [
                'yii\web\HttpException:401',
                'yii\web\HttpException:404',
            ],
            'logVars' => [], // Disable logging of _SERVER, _POST, etc.
            'message' => [
                'from' => $fromEmail,
                'to' => $alertsEmail,
                'subject' => 'ALERT - ' . $idpName . ' PW [env=' . $appEnv .']',
            ],
            'prefix' => function($message) use ($appEnv) {
                $prefix = 'env=' . $appEnv . PHP_EOL;

                // There is no user when a console command is run
                try {
                    $appUser = \Yii::$app->user;
                } catch (\Exception $e) {
                    $appUser = Null;
                }
                if ($appUser && ! \Yii::$app->user->isGuest){
                    $prefix .= 'user='.\Yii::$app->user->identity->email . PHP_EOL;
                }

                // Try to get requested url and method
                try {
                    $request = \Yii::$app->request;
                    $prefix .= 'Requested URL: ' . $request->getUrl() . PHP_EOL;
                    $prefix .= 'Request method: ' . $request->getMethod() . PHP_EOL;
                } catch (\Exception $e) {
                    $prefix .= 'Requested URL: not available';
                }

                return PHP_EOL . $prefix;
            },
            'enabled' => $alertsEmailEnabled,
        ],
    ],
],

Here is an example email received when an exception occurred:

2016-07-23 02:17:20
env=staging
[email protected]
Requested URL: /password
Request method: PUT
[error][application] [
    'action' => 'save password',
    'employee_id' => '12345',
    'status' => 'error',
    'error' => 'Unable to update user\'s password, server error.',
    'previous' => [
        'code' => 2,
        'message' => 'ldap_mod_replace(): Modify: Constraint
        violation',
    ],
]
2016-07-23 02:17:20
env=staging
[email protected]
Requested URL: /password
Request method: PUT
[error][yii\web\HttpException:500] yii\web\ServerErrorHttpException:
Unable to update password in /data/common/models/Password.php:182
Stack trace:
#0 /data/common/models/User.php(420): common\models\Password->save()
#1 /data/frontend/controllers/PasswordController.php(58):
common\models\User->setPassword('password showed up here!!!')
#2 [internal function]:
frontend\controllers\PasswordController->actionUpdate()
#3 /data/vendor/yiisoft/yii2/base/InlineAction.php(55):
call_user_func_array(Array, Array)
#4 /data/vendor/yiisoft/yii2/base/Controller.php(151):
yii\base\InlineAction->runWithParams(Array)
#5 /data/vendor/yiisoft/yii2/base/Module.php(455):
yii\base\Controller->runAction('update', Array)
#6 /data/vendor/yiisoft/yii2/web/Application.php(84):
yii\base\Module->runAction('password/update', Array)
#7 /data/vendor/yiisoft/yii2/base/Application.php(375):
yii\web\Application->handleRequest(Object(yii\web\Request))
#8 /data/frontend/web/index.php(17): yii\base\Application->run()
#9 {main}

Here is the same log event from syslog:

22 Jul 2016 22:17:20.151  {
    "env": "staging",
    "user": "[email protected]",
    "level": "error",
    "category": "application",
    "message": {
        "action": "save password",
        "employee_id": "12345",
        "status": "error",
        "error": "Unable to update user's password, server error.",
        "previous": {
            "code": 2,
            "message": "ldap_mod_replace(): Modify: Constraint violation"
        }
    }
}

What is the expected result?

I would expect the email to look the same as the syslog message and not include any stack trace.

What do you get instead?

A stack trace is included in the email message.

Additional info

| Q | A |
| --- | --- |
| Yii version | 2.0.6 |
| PHP version | 7.0.4 |
| Operating system | Ubuntu 16.04 |

[fillup]

@pstddc I'm not sure what you mean by your comment. I'm not concerned about the LDAP error, that part is irrelevant, my concern is about the stack trace being present in the email even though it is configured not to be.

[RSalo]

@fillup i think it may happen due debug mode... try turn it off plz.

[fillup]

Thanks @RSalo , its already off:

defined('YII_DEBUG') || define('YII_DEBUG', false);
defined('YII_ENV') || define('YII_ENV', 'production');

[bizley]

I'm afraid this is expected behavior. Every logged exception looks like this.
Stack trace is the part of Exception message because of its __toString() implementation and because of this it's being logged regardless a traceLevel value.

I have not checked this but I think Logger could check the type of $message and fetch only what's needed in case of exception and/or use its stack trace instead of building another one.

This might be a secure warning case as well because of this password showing stack trace line...

[fillup]

Thanks @bizley but I dont think that is really right. It seems to be the problem is with the Target::formatMessage function on line 257 in that it checks if traces are present and then includes them without checking what level of them should be included. I'll see if I can work on a PR to fix this.

Do you agree this is a bug?

And now I see the reason the traces are not in the syslog messages is because the SyslogTarget overrides this method and doesn't even check for traces. So that seems to be another bug that if you had traceLevel set to 3 and used syslog as a target you'd get no trace at all.

[bizley]

@fillup This is not the case. Traces are not present when traceLevel is set to 0. You can verify this by checking if condition at line 258 is met.
This is exception's __toString() issue and you can verify this by calling echo $text; die; after line 247 (when Exception is about to be logged) - stack trace is a part of $text there.

[bizley]

Simple

if ($message instanceof \Exception) {
    $message = $message->getMessage();
}

at the beginning of Logger::log() method would be enough to get rid of the unexpected stack trace (also it can be moved to $traces there maybe) but I'm not sure if this is something that Yii team wants.

[fillup]

@bizley I see what you mean now. I didn't realize that the exception itself also caused a message. In Target::formatMessage on line 252 I think is really my problem. when the message is an exception type it is just cast to string which serializes the whole thing. So now I'm thinking perhaps the fix is really a combination of yii\base\Exception overriding the \Exception::__toString() function to include an optional $traceLevel parameter that could serialize the exception with or without the trace as appropriate. That would allow the call in Target to not just cast to string but explicitly call __toString with the configured $traceLevel value. With that in place the $traceLevel parameter would have more meaning on the logger component.

What do you think of that approach? I think in the mean time I'll write my own email target and modify the existing to do like you suggested of just getting the message and probably code from the exception.

[bizley]

@fillup Your own EmailTarget solution is indeed good idea for now. As for the idea of fixing or not fixing the exception message logging we need to wait for Yii core developers.

[samdark]

@yiisoft/core-developers need opinions.

[cebe]

The traceLevel configuration of the logger is for normal messages so you can get an idea where they where generated in case the error message itself is not clear enough. The stacktrace that is logged from exceptions is completely different and very relevant in case an exception is thrown. Imo stack trace of exceptions should not be truncated. It makes debugging much harder.

[bizley]

What about truncating the message to just a message text and moving the exception stack trace to Logger stack trace (so it doesn't have to be built again)?

[cebe]

the purpose of the logger trace is different from exception trace. I would want to limit the logger trace but not limit the exception trace so they should be configurable separately.

[fillup]

I'd be fine with configuring them separately since they are different, but it does seem important that we be able to exclude or limit the trace on exceptions since they can include sensitive information like credentials.

[cebe]

in which case can exception trace contain sensitive information? Can you elaborate on that part? also you do not know in which level that may occur so it is unclear to me how limiting the trace helps in that case.

[fillup]

@cebe I noticed this was a problem when I was getting an exception writing to an ldap server and the trace included the function call which was updating a user's password and the trace included the password in clear text. I can also imagine this happening with a database connection exception including database credentials. Also, the definition of sensitive is relative so being able to prevent the trace from being logged is important. The ability to limit the trace is primarily to prevent it from being included at all. So a boolean includeTrace config option would be sufficient for my needs, but I thought to be consistent with normal message logging being able to specify a level and/or use the same existing config would be better.

[samdark]

@fillup the issue is that such sensitive data could be in any level of the trace starting from the very error so limiting trace depth to certain number won't solve this issue.

[fillup]

@samdark that is fine, but do you agree a configuration option should be available to prevent trace from being logged at all?

[samdark]

That's level of zero.

[fillup]

Exactly, but your comment about "limiting trace depth to a certain number wont solve the problem", it would if the number was zero so I was just getting at confirming such an option would be acceptable. Thanks for confirming.

[samdark]

No, it still would not since the data could be in the error message itself.

[samdark]

The option is, of course, acceptable.

[samdark]

Won't be implemented in 2.0.