在 Laravel 应用中,记录日志我们可以这样:

<?php

namespace Tests\Unit;

use Illuminate\Support\Facades\Log;
use Tests\TestCase;

class ExampleTest extends TestCase
{
    /**
     * A basic test example.
     *
     * @return void
     */
    public function testBasicTest()
    {
        Log::debug(1);
        Log::debug(2);
        Log::debug(3);
        Log::debug(4);
        $this->assertTrue(true);
    }
}

这里我们在测试文件中做演示。

运行这个测试之后,生成的日志文件内容如下:

[2019-08-18 07:54:37] testing.DEBUG: 1  
[2019-08-18 07:54:37] testing.DEBUG: 2  
[2019-08-18 07:54:37] testing.DEBUG: 3  
[2019-08-18 07:54:37] testing.DEBUG: 4  

可以看到日志按照顺序记录在文件里面了。正常看的话基本上没有问题。但是我们来思考一个问题,如果我们的系统并发较高,在同一时间都触发了日志的记录操作,这个时候日志的记录可能是这样的:

[2019-08-18 07:54:37] testing.DEBUG: 1  
[2019-08-18 07:54:37] testing.DEBUG: 1  
[2019-08-18 07:54:37] testing.DEBUG: 2  
[2019-08-18 07:54:37] testing.DEBUG: 3  
[2019-08-18 07:54:37] testing.DEBUG: 4  
[2019-08-18 07:54:37] testing.DEBUG: 4  
[2019-08-18 07:54:37] testing.DEBUG: 1  
...

如果是这样话,其实就暗示了一个问题,那就是我们如何分辨某一个请求的日志记录顺序和具体的值。很明显,在这种情况下,我们根本分不清楚某一个请求的顺序和记录的值。分不清某一个请求的日志顺序和具体的值带来的问题就是bug无法有效定位和处理。那么我们该怎么办呢?这里就涉涉及到了日志的链路追踪。在 Laravel 中可以这样实现,我们在 AppServiceProvider 中这样:

<?php

namespace App\Providers;

use Illuminate\Support\ServiceProvider;
use Illuminate\Support\Str;
use Monolog\Logger;

class AppServiceProvider extends ServiceProvider
{
    /**
     * Register any application services.
     *
     * @return void
     */
    public function register()
    {
        //
    }

    /**
     * Bootstrap any application services.
     *
     * @return void
     */
    public function boot()
    {
        /**
         * @var $logger Logger
         */
        $logger = $this->app->make('log');
        $randomId = Str::random();
        $logger->pushProcessor(function ($record) use ($randomId) {
            $record['extra']['random_id'] = $randomId;

            return $record;
        });
    }
}

然后在跑下测试,可以看到日志的记录结果是这样的:

[2019-08-18 07:56:25] testing.DEBUG: 1  {"random_id":"RoJLfc3kbe1HaeOr"}
[2019-08-18 07:56:25] testing.DEBUG: 2  {"random_id":"RoJLfc3kbe1HaeOr"}
[2019-08-18 07:56:25] testing.DEBUG: 3  {"random_id":"RoJLfc3kbe1HaeOr"}
[2019-08-18 07:56:25] testing.DEBUG: 4  {"random_id":"RoJLfc3kbe1HaeOr"}

这里我们注意到,每个日志结尾都存在一个 random_id 的值,且在同一次的请求中,这个 random_id 的值是一样的。有了这个 random_id 的值就可以很清晰的找出某一个请求的日志记录栈,也就方便我们排查问题啦。

原理分析:

Laravel 的日志组件是使用 monolog 的,该库有一个功能就是 添加额外信息到日志记录中,我们利用这个功能,就可以实现上面的效果。具体链接地址:https://github.com/Seldaek/monolog/blob/master/doc/01-usage.md#adding-extra-data-in-the-records

分布式系统的考虑:

单机应用的日志记录非常简单,如果是分布式的日志链路追踪我们该怎么实现呢?其实原理是一样的,我们需要在分布式系统中记录这一次请求的一个唯一 id ,但是具体的实现还是较为复杂的,当然也有第三方工具提供此类的支持。这个后面有机会在分享个小伙伴们。