Session Id in log message missing

[gregos22]

Hello

I have the same problem as @tlanyan in the bug #8036. I always have the string '[-]' in my log file altought my session is active. Exemple : Yii::info('Blablablabla','mhm'); Result : 2016-03-30 13:50:43 [127.0.0.1][XXXXXX][-][info][mhm] Blablablabla

Normaly, the issue was resolved in #8174 with a $this->flush(); (in Logger.php) when the application shutdown. But, it dosn't work anymore. On the other hand, if I change the statement with the param true like this : $this->flush(true); It's work. Maybe it's a good solution ?

This is my log target configuration :

[
  'class' => 'yii\log\FileTarget',
  'logFile' => dirname(dirname(__DIR__)).'/applicationXXXX/logs/app-journal.log',
  'maxFileSize' => 5120, //5mb
  'logVars' => [],
  'levels' => ['error','warning','info'],
  'categories' => ['mhm'],
],

Q	A
Yii version	2.0.7
PHP version	5.6.19
Operating system	Windows

[samdark]

Do you have active session at the end of request?

[gregos22]

Session is active before Yii::info('Blablablabla','mhm'); Session is active after Yii::info('Blablablabla','mhm'); Session is not active in Target.php line 291 : $sessionID = $session && $session->getIsActive() ? $session->getId() : '-';

I think that session is automatically destroy before log is written

[gattir]

It seems, that the problem still exists. Steps to reproduce are the following. Installed basic-app. Made 4 actions in SiteController:

`

public function actionSession()
{
    $session = Yii::$app->session;
    $session->open();
    Yii::warning($session->id);
    return $session->id;
}

public function actionNotFound()
{
    $session = Yii::$app->session;
    $session->open();
    Yii::warning($session->id);
    throw new \yii\web\NotFoundHttpException('not found');
}

public function actionFlush()
{
    $session = Yii::$app->session;
    $session->open();
    Yii::warning($session->id);
    Yii::getLogger()->flush();
    return $session->id;
}

public function actionFinalFlush()
{
    $session = Yii::$app->session;
    $session->open();
    Yii::warning($session->id);
    Yii::getLogger()->flush(true);
    return $session->id;
}

`

And got the results respectively:

2018-08-12 10:58:02 [127.0.0.1][-][-][warning][application] osqk2m5mh4oubnobj1fsgs8dam33e7f2 2018-08-12 10:58:06 [127.0.0.1][-][osqk2m5mh4oubnobj1fsgs8dam33e7f2][warning][application] osqk2m5mh4oubnobj1fsgs8dam33e7f2 2018-08-12 10:58:10 [127.0.0.1][-][-][warning][application] osqk2m5mh4oubnobj1fsgs8dam33e7f2 2018-08-12 10:58:13 [127.0.0.1][-][osqk2m5mh4oubnobj1fsgs8dam33e7f2][warning][application] osqk2m5mh4oubnobj1fsgs8dam33e7f2

As you can see the session persists between action calls, but it disappears in logs prefix. So as I understand, if the log isn't final-flushed (as it is during errors like not found exceptions) it places [-], because during the time of log writing, the session already is not active. And I think it's not correct behavior, as you should be able to write in log several times, so it's not correct to call final flush.

Maybe it is needed to save session when log message is created for later use in prefix. And use that saved session instead of calling $session->getIsActive(). That is method getMessagePrefix in yii\log\Target

Btw, the original discussion thread of this feature (for yii1): https://www.yiiframework.com/forum/index.php/topic/2426-session-id-in-the-logger/

[gattir]

So, as mentioned before when Target tries to get session, it is already closed. This is how it looks like. The order of execution is following:

Logger.init: registering shutdown function - (1)
Session.init: registering shutdown function - Session.close
Application running
Application.run finished
Logger.flush()
(1): registering shutdown function in shutdown function
Session.close
Logger.flush(1)
Target.getMessagePrefix
Target.getMessagePrefix
Target.getMessagePrefix
Target.getMessagePrefix
Target.getMessagePrefix
Target.getMessagePrefix
Target.getMessagePrefix

And when in Target.getMessagePrefix it tries to do this:

        /* @var $session \yii\web\Session */
        $session = Yii::$app->has('session', true) ? Yii::$app->get('session') : null;
        $sessionID = $session && $session->getIsActive() ? $session->getId() : '-';

It sees that there is no session, and it thinks that there were none during all execution (which is wrong). When the reason for that is, that the logging is actually executed after everything is finished.

This order is based on this two pieces of code:

In Session.init:

        register_shutdown_function([$this, 'close']);

In Logger.init:

        register_shutdown_function(function () {
            // make regular flush before other shutdown functions, which allows session data collection and so on
            $this->flush();

            // make sure log entries written by shutdown functions are also flushed
            // ensure "flush()" is called last when there are multiple shutdown functions
            register_shutdown_function([$this, 'flush'], true);
        });

And as mentioned in the comments of code, it is meant to be called last, but unfortunatelly 1) it has no session record 2) it messes all other logging before final flush (cause in has no session in the time of execution) 3) maybe it messes with session, because it executes session tickling in getMessagePrefix

The 3 is a crazy guess, but could that be connected to these long hunted mysteries: https://github.com/yiisoft/yii2/issues/11401 https://github.com/yiisoft/yii2/issues/9438