Response content must be a string or object ？（上）lumen日志格式修改

100.jpg

前述

  如果laravel和lumen框架使用的多，一定会碰到这个异常： The Response content must be a string or object implementing __toString(), "boolean" given，也正是由这个异常，我开始决定写相关的笔记。

起因

  公司项目使用的lumen框架，前负责人还是很良心的，对lumen框架也是十分精通。通过框架依赖注入和服务注册的能力，添加了一个异常处理的类，在任何异常发生时捕获并把错误信息记录到日志文件，向前端返回一个json数据。之所以这么做，我猜是因为lumen自身默认的异常处理类会返回一个状态吗为500且渲染过的页面，不适用于前后端分离的项目使用；同时状态码为500更容易看出是服务挂掉了，显得有点low。最近我在重构此项目时，有一个需求是要修改日志的格式。
  使用过的同学应该知道lumen的日志格式很友好，message+array的格式，并会通过formater注入日志时间。

Log::info("index_action_info", [$request->input()]);
//[2021-03-07 02:47:13] local.INFO: index_action_info [{"info":"1","query_info":"test_log_info"}]

  为什么修改呢，因为响应平台化运维要求，把日志文件接入到ELK，要求上报的数据每条都是json格式，实际上这个修改也比较简单，异常处理的日志格式修改稍微复杂一点，不过也能处理，下面记录一下实现过程。

经过

日志格式修改
lumen5.5版本及之前，bootstrap/app.php文件开启门面加载配置$app->withFacades()，使用的日志类facade（门面类）Illuminate\Support\Facades\Log很容易找到。

namespace Illuminate\Support\Facades;

use Psr\Log\LoggerInterface;

/**
 * @see \Illuminate\Log\Writer
 */
class Log extends Facade
{
    /**
     * Get the registered name of the component.
     *
     * @return string
     */
    protected static function getFacadeAccessor()
    {
        return LoggerInterface::class;
    }
}

可以看出日志写入时使用的对象是Psr\Log\LoggerInterface,但很明显它只是一个接口。深入了解可以看到lumen在laravel\lumen\Application核心类文件中使用IOC容器注册服务绑定了log与Psr\Log\LoggerInterface这两个服务别名。

        'log' => 'registerLogBindings',
        'Psr\Log\LoggerInterface' => 'registerLogBindings',

    /**
     * Register container bindings for the application.
     *
     * @return void
     */
    protected function registerLogBindings()
    {
        $this->singleton('Psr\Log\LoggerInterface', function () {
            if ($this->monologConfigurator) {
                return call_user_func($this->monologConfigurator, new Logger('lumen'));
            } else {
                return new Logger('lumen', [$this->getMonologHandler()]);
            }
        });
    }

服务容器的具体实现过程我就不赘述了，可以点击查看这里。总之如果使用log门面，那么最终处理日志记录的是registerLogBindings函数中返回的Logger对象,那么改写日志格式有两种方式：

  • 一是注册一个新的门面类NewLog,注册自己的日志处理类app->bind('newLog', MyNewLog::class),不过这种修改方式的缺点很明显，很多处理方法都要自己写，还很容易出bug。
  • 二是修改日志处理类的处理方法。通过上面的registerLogBindings函数可以看出，最终处理日志的类是Monolog\Logger,如果app对象中monologConfigurator属性被赋值为匿名函数，那么会返回被其处理之后的Logger对象，我理解这算是装饰器的设计模式的使用吧。

综上选择第二种实现方法
  步骤一：在/app/Providers目录下创建一个服务

<?php
/**
 * @Copyright    ***
 * @Name LogServiceProvider.php
 * @Version Beta 1.0
 * @Date: 2019-01-16
 * @Description 文件
 * <author>     <time>        <version >    <desc>
 *       ***         2019-01-16     Beta 1.0      第一次建立该文件
 */
namespace App\Providers;

//use Monolog\Formatter\LineFormatter;
use App\Services\Formatter\LineFormatter;
use Monolog\Logger as Monolog;
use Illuminate\Support\ServiceProvider;
use App\Utils\Monolog\Writer;

class LogServiceProvider extends ServiceProvider
{
    /**
     * @desc 日志处理类
     * @var Monolog
     */
    protected $logger;

    /**
     * Register the service provider.
     *
     * @return void
     */
    public function register()
    {
        $format = "{\"datetime\":%datetime%, \"channel\":%channel%, \"level\":%level_name%, \"message\":%message%, \"context\":%context%, \"extra\": %extra%}\n";
        //日志处理
        $this->app->configureMonologUsing(function (Monolog $logger) use($format) {
            $monologHandlers = $logger->getHandlers();
            if(empty($monologHandlers))
            {
                $monologHandler = new \Monolog\Handler\RotatingFileHandler($this->app->storagePath() . '/logs/lumen.log', 30, true);
                $monologHandler->setFormatter(new LineFormatter($format, 'Y-m-d H:i:s.u', true, true));
                $logger->pushHandler($monologHandler);
            }
            return $logger;
        });
    }
}

可以看到在register方法里，先定义日志格式$format字符串，模拟了一个json字符串。LineFormatter是lumen用于日志格式化的类，$format就是其格式化所使用的的格式。
写入日志的调用如Log::info($mesage, $content)正常会传入两个参数，上面说了Log服务别名对应的日志服务是Monolog/Logger;它须有一个日志处理者$monologHandler。
$monologHandler提供日志文件创建，日志写入等功能。方法中使用的\Monolog\Handler\RotatingFileHandler是lumen提供的按天生成日志文件写、入日志，并删除超过30天的日志处理服务。

//lumen框架里Monolog/Logger类中定义了info方法
public function info($message, array $context = array())
{
  return $this->addRecord(static::INFO, $message, $context);
}
//而addRecord方法中会创建一个$record数组，然后调用$handler->handle($record)
$record = array(
   'message' => (string) $message,
   'context' => $context,
   'level' => $level,
   'level_name' => $levelName,
   'channel' => $this->name,
   'datetime' => $ts,
   'extra' => array(),
);
try {
   foreach ($this->processors as $processor) {
     $record = call_user_func($processor, $record);
  }
  while ($handler = current($this->handlers)) {
     if (true === $handler->handle($record)) {
       break;
    }
    next($this->handlers);
  }
} catch (Exception $e) {
  $this->handleException($e, $record);
}
//其如datetime,level,context参数根据字符串或数组的格式输入，这样就可以把整条日志用$format格式改写，达到目的。其过程是handler方法中执行$record['formatted'] = $this->getFormatter()->format($record);然后fwrite($stream, (string) $record['formatted']);把格式化的结果写入到日志文件中

  步骤二：改写LineFormatter类
在正常的lumen日志中，其每行展示均是字符串，如果修改了$format就要兼容数组的展示。所以需要把$record['formatted']的每个json对象的value转为json格式，再使用$format格式化才可以变成完整的json格式。于是我复制了MonoLog/Formatter/LineFormatter.php文件，改写后注册到$monologHandler对象中。

<?php

/*
 * This file is part of the Monolog package.
 *
 * (c) Jordi Boggiano <j.boggiano@seld.be>
 *
 * For the full copyright and license information, please view the LICENSE
 * file that was distributed with this source code.
 */

namespace App\Services\Formatter;

use Monolog\Formatter\NormalizerFormatter;
use Monolog\Utils;

/**
 * Formats incoming records into a one-line string
 *
 * This is especially useful for logging to files
 *
 * @author Jordi Boggiano <j.boggiano@seld.be>
 * @author Christophe Coevoet <stof@notk.org>
 */
class LineFormatter extends NormalizerFormatter
{
    const SIMPLE_FORMAT = "[%datetime%] %channel%.%level_name%: %message% %context% %extra%\n";

    protected $format;
    protected $allowInlineLineBreaks;
    protected $ignoreEmptyContextAndExtra;
    protected $includeStacktraces;

    /**
     * @param string $format                     The format of the message
     * @param string $dateFormat                 The format of the timestamp: one supported by DateTime::format
     * @param bool   $allowInlineLineBreaks      Whether to allow inline line breaks in log entries
     * @param bool   $ignoreEmptyContextAndExtra
     */
    public function __construct($format = null, $dateFormat = null, $allowInlineLineBreaks = false, $ignoreEmptyContextAndExtra = false)
    {
        $this->format = $format ?: static::SIMPLE_FORMAT;
        $this->allowInlineLineBreaks = $allowInlineLineBreaks;
        $this->ignoreEmptyContextAndExtra = $ignoreEmptyContextAndExtra;
        parent::__construct($dateFormat);
    }

    public function includeStacktraces($include = true)
    {
        $this->includeStacktraces = $include;
        if ($this->includeStacktraces) {
            $this->allowInlineLineBreaks = true;
        }
    }

    public function allowInlineLineBreaks($allow = true)
    {
        $this->allowInlineLineBreaks = $allow;
    }

    public function ignoreEmptyContextAndExtra($ignore = true)
    {
        $this->ignoreEmptyContextAndExtra = $ignore;
    }

    /**
     * {@inheritdoc}
     */
    public function format(array $record)
    {
        $vars = parent::format($record);

        $output = $this->format;

        if(!empty($var['extra']))
        {
            foreach ($vars['extra'] as $var => $val) {
                if (false !== strpos($output, '%extra.'.$var.'%')) {
                    $output = str_replace('%extra.'.$var.'%', $this->stringify($val), $output);
                    unset($vars['extra'][$var]);
                }
            }
        }
        else
        {
            $var['extra'] = [];
        }

        if(!empty($var['context']))
        {
            foreach ($vars['context'] as $var => $val) {
                if (false !== strpos($output, '%context.'.$var.'%')) {
                    $output = str_replace('%context.'.$var.'%', $this->stringify($val), $output);
                    unset($vars['context'][$var]);
                }
            }
        }
        else
        {
            $var['context'] = [];
        }

        if ($this->ignoreEmptyContextAndExtra) {
            if (empty($vars['context'])) {
                unset($vars['context']);
                $output = str_replace('%context%', '[]', $output);
            }

            if (empty($vars['extra'])) {
                unset($vars['extra']);
                $output = str_replace('%extra%', '[]', $output);
            }
        }

        foreach ($vars as $var => $val) {
            if (false !== strpos($output, '%'.$var.'%')) {
                $output = str_replace('%'.$var.'%', $this->stringify($val), $output);
            }
        }

        // remove leftover %extra.xxx% and %context.xxx% if any
        if (false !== strpos($output, '%')) {
            $output = preg_replace('/%(?:extra|context)\..+?%/', '', $output);
        }

        return $output;
    }

    public function formatBatch(array $records)
    {
        $message = '';
        foreach ($records as $record) {
            $message .= $this->format($record);
        }

        return $message;
    }

    public function stringify($value)
    {
        $retValue = $this->replaceNewlines($this->convertToString($value));
        $res = json_encode($retValue);
        if($res === false && json_last_error() === JSON_ERROR_UTF8)
        {
            return json_encode(mb_convert_encoding($retValue, "UTF-8", "UTF-8"));
        }
        return $res;
    }

    protected function normalizeException($e)
    {
        // TODO 2.0 only check for Throwable
        if (!$e instanceof \Exception && !$e instanceof \Throwable) {
            throw new \InvalidArgumentException('Exception/Throwable expected, got '.gettype($e).' / '.Utils::getClass($e));
        }

        $previousText = '';
        if ($previous = $e->getPrevious()) {
            do {
                $previousText .= ', '.Utils::getClass($previous).'(code: '.$previous->getCode().'): '.$previous->getMessage().' at '.$previous->getFile().':'.$previous->getLine();
            } while ($previous = $previous->getPrevious());
        }

        $str = '[object] ('.Utils::getClass($e).'(code: '.$e->getCode().'): '.$e->getMessage().' at '.$e->getFile().':'.$e->getLine().$previousText.')';
        if ($this->includeStacktraces) {
            $str .= "\n[stacktrace]\n".$e->getTraceAsString()."\n";
        }

        return $str;
    }

    protected function convertToString($data)
    {
        if (null === $data || is_bool($data)) {
            return var_export($data, true);
        }

        if (is_scalar($data)) {
            return (string) $data;
        }

        if (version_compare(PHP_VERSION, '5.4.0', '>=')) {
            return $this->toJson($data, true);
        }

        return str_replace('\\/', '/', $this->toJson($data, true));
    }

    protected function replaceNewlines($str)
    {
        if ($this->allowInlineLineBreaks) {
            if (0 === strpos($str, '{')) {
                return str_replace(array('\r', '\n'), array("\r", "\n"), $str);
            }

            return $str;
        }
        return str_replace(array("\r\n", "\r", "\n"), ' ', $str);
    }
}

对比原文件，我修改了format方法与stringify方法；前者是为了在extra、context和其他日志数组元素为空时赋值为空数组，后者是将这些元素的值转为json格式。

  步骤三：在bootstrap/app.php注册一个服务提供者

$app->register(App\Providers\LogServiceProvider::class);
最终日志效果
{"datetime":"2021-03-08 10:28:43.978073", "level":"lumen.INFO", "message":"_login_user_info_:", "context":{"user_id":1,"user_name":"admin","input":{"uid":"20458","portal_id":"870","table_id":"12935","distinct":"1","field_id":["168208"],"paging":{"page":"1","size":"21"},"count":"0"},"php://input":""}, "extra": ""}
{"datetime":"2021-03-08 10:28:46.085127", "level":"lumen.ERROR", "message":"PDOException: PDO::__construct(): php_network_getaddresses: getaddrinfo failed: ��֪������������  in F:\server\vendor\illuminate\database\Connectors\Connector.php:67
Stack trace:
#0 F:\server\vendor\illuminate\database\Connectors\Connector.php(67): PDO->__construct('mysql:host=tbds...', 'ponybi', 'ponyb1@MB', Array)
#1 F:\server\vendor\illuminate\database\Connectors\Connector.php(43): Illuminate\Database\Connectors\Connector->createPdoConnection('mysql:host=tbds...', 'ponybi', 'ponyb1@MB', Array)
#2 F:\server\vendor\illuminate\database\Connectors\MySqlConnector.php(24): Illuminate\Database\Connectors\Connector->createConnection('mysql:host=tbds...', Array, Array)
······
#47 F:\server\public\index.php(34): Laravel\Lumen\Application->run()
#48 {main}", "context":, "extra": ""}
{"datetime":"2021-03-08 10:28:46.086727", "level":"lumen.ERROR", "message":"用户查询数据错误", "context":null, "extra": ""}

可以看到无论是用户主动记录的日志还是抛出的异常，以及系统异常都会被记录，格式也都符合json格式

异常的错误日志

测试抛出了一个关键异常
  改完了日志格式后就是测试阶段，我在写测试用例时，模拟了http，system，MySQL链接超时中断异常等等。
上面的最终效果展示中有这样一段,实际上这是修改了报错处理类修改之后的日志展示

getaddrinfo failed: ��֪������������  
{"datetime":"2021-03-08 10:28:46.086727", "level":"lumen.ERROR", "message":"用户查询数据错误", "context":null, "extra": ""}

之所以修改，是因为当测试到pdo异常时突然发现多了一个异常。这个相信也有不少人见到过：

{"datetime":"2021-03-08 11:37:05.929497", "level":"lumen.ERROR", "message":"用户查询数据错误", "context":null, "extra": ""}
{"datetime":"2021-03-08 11:37:05.931661", "level":"lumen.ERROR", "message":"UnexpectedValueException: The Response content must be a string or object implementing __toString(), "boolean" given. in F:\server\vendor\symfony\http-foundation\Response.php:399
Stack trace:
#0 F:\server\vendor\illuminate\http\Response.php(45): Symfony\Component\HttpFoundation\Response->setContent(false)
#1 F:\server\vendor\symfony\http-foundation\Response.php(206): Illuminate\Http\Response->setContent(false)
#2 F:\server\app\Services\Exceptions\Handler.php(65): Symfony\Component\HttpFoundation\Response->__construct(Array, 200)
#3 F:\server\vendor\laravel\lumen-framework\src\Routing\Pipeline.php(78): App\Services\Exceptions\Handler->render(Object(Illuminate\Http\Request), Object(Symfony\Component\HttpKernel\Exception\HttpException))
#4 F:\server\vendor\laravel\lumen-framework\src\Routing\Pipeline.php(54): Laravel\Lumen\Routing\Pipeline->handleException(Object(Illuminate\Http\Request), Object(Symfony\Component\HttpKernel\Exception\HttpException))
#5 F:\server\app\Http\Middleware\Authenticate.php(89): Laravel\Lumen\Routing\Pipeline->Laravel\Lumen\Routing\{closure}(Object(Illuminate\Http\Request))
#6 F:\server\vendor\illuminate\pipeline\Pipeline.php(148): App\Http\Middleware\Authenticate->handle(Object(Illuminate\Http\Request), Object(Closure))
#7 [internal function]: Illuminate\Pipeline\Pipeline->Illuminate\Pipeline\{closure}(Object(Illuminate\Http\Request))
#8 F:\server\vendor\laravel\lumen-framework\src\Routing\Pipeline.php(32): call_user_func(Object(Closure), Object(Illuminate\Http\Request))
#9 F:\server\app\Http\Middleware\AuthOrigin.php(50): Laravel\Lumen\Routing\Pipeline->Laravel\Lumen\Routing\{closure}(Object(Illuminate\Http\Request))
#10 F:\server\vendor\illuminate\pipeline\Pipeline.php(148): App\Http\Middleware\AuthOrigin->handle(Object(Illuminate\Http\Request), Object(Closure))
#11 [internal function]: Illuminate\Pipeline\Pipeline->Illuminate\Pipeline\{closure}(Object(Illuminate\Http\Request))
#12 F:\server\vendor\laravel\lumen-framework\src\Routing\Pipeline.php(32): call_user_func(Object(Closure), Object(Illuminate\Http\Request))
#13 F:\server\vendor\illuminate\pipeline\Pipeline.php(101): Laravel\Lumen\Routing\Pipeline->Laravel\Lumen\Routing\{closure}(Object(Illuminate\Http\Request))
#14 F:\server\vendor\laravel\lumen-framework\src\Concerns\RoutesRequests.php(410): Illuminate\Pipeline\Pipeline->then(Object(Closure))
#15 F:\server\vendor\laravel\lumen-framework\src\Concerns\RoutesRequests.php(256): Laravel\Lumen\Application->sendThroughPipeline(Array, Object(Closure))
#16 F:\server\vendor\laravel\lumen-framework\src\Concerns\RoutesRequests.php(230): Laravel\Lumen\Application->handleFoundRoute(Array)
#17 F:\server\vendor\laravel\lumen-framework\src\Concerns\RoutesRequests.php(164): Laravel\Lumen\Application->handleDispatcherResponse(Array)
#18 F:\server\vendor\laravel\lumen-framework\src\Concerns\RoutesRequests.php(413): Laravel\Lumen\Application->Laravel\Lumen\Concerns\{closure}()
#19 F:\server\vendor\laravel\lumen-framework\src\Concerns\RoutesRequests.php(166): Laravel\Lumen\Application->sendThroughPipeline(Array, Object(Closure))
#20 F:\server\vendor\laravel\lumen-framework\src\Concerns\RoutesRequests.php(107): Laravel\Lumen\Application->dispatch(NULL)
#21 F:\server\public\index.php(34): Laravel\Lumen\Application->run()
#22 {main}", "context":, "extra": ""}

The Response content must be a string or object implementing __toString(), "boolean" given
错误的意思很明显，response只能是字符串。这就很奇怪了，明明抛出了异常，返回的必定是一个数组，为什么底层异常处理类会说是一个bool类型呢？具体修复过程，下篇文章:Response content must be a string or object ? (中) lumen的异常处理我再说明

最后编辑于 ：
©著作权归作者所有,转载或内容合作请联系作者
  • 人面猴
    序言：七十年代末，一起剥皮案震惊了整个滨河市，随后出现的几起案子，更是在滨河造成了极大的恐慌，老刑警刘岩，带你破解...
    沈念sama阅读 159,458评论 4赞 363
  • 死咒
    序言：滨河连续发生了三起死亡事件，死亡现场离奇诡异，居然都是意外死亡，警方通过查阅死者的电脑和手机，发现死者居然都...
    沈念sama阅读 67,454评论 1赞 294
  • 救了他两次的神仙让他今天三更去死
    文/潘晓璐 我一进店门，熙熙楼的掌柜王于贵愁眉苦脸地迎上来，“玉大人，你说我怎么就摊上这事。” “怎么了？”我有些...
    开封第一讲书人阅读 109,171评论 0赞 243
  • 道士缉凶录：失踪的卖姜人
    文/不坏的土叔 我叫张陵，是天一观的道长。 经常有香客问我，道长，这世上最难降的妖魔是什么？ 我笑而不...
    开封第一讲书人阅读 44,062评论 0赞 207
  • 港岛之恋（遗憾婚礼）
    正文 为了忘掉前任，我火速办了婚礼，结果婚礼上，老公的妹妹穿的比我还像新娘。我一直安慰自己，他们只是感情好，可当我...
    茶点故事阅读 52,440评论 3赞 287
  • 恶毒庶女顶嫁案：这布局不是一般人想出来的
    文/花漫 我一把揭开白布。 她就那样静静地躺着，像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上，一...
    开封第一讲书人阅读 40,661评论 1赞 219
  • 城市分裂传说
    那天，我揣着相机与录音，去河边找鬼。 笑死，一个胖子当着我的面吹牛，可吹牛的内容都是我干的。 我是一名探鬼主播，决...
    沈念sama阅读 31,906评论 2赞 313
  • 双鸳鸯连环套：你想象不到人心有多黑
    文/苍兰香墨 我猛地睁开眼，长吁一口气：“原来是场噩梦啊……” “哼！你这毒妇竟也来了？” 一声冷哼从身侧响起，我...
    开封第一讲书人阅读 30,609评论 0赞 200
  • 万荣杀人案实录
    序言：老挝万荣一对情侣失踪，失踪者是张志新（化名）和其女友刘颖，没想到半个月后，有当地人在树林里发现了一具尸体，经...
    沈念sama阅读 34,379评论 1赞 246
  • 护林员之死
    正文 独居荒郊野岭守林人离奇死亡，尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 30,600评论 2赞 246
  • 白月光启示录
    正文 我和宋清朗相恋三年，在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 32,085评论 1赞 261
  • 活死人
    序言：一个原本活蹦乱跳的男人离奇死亡，死状恐怖，灵堂内的尸体忽然破棺而出，到底是诈尸还是另有隐情，我是刑警宁泽，带...
    沈念sama阅读 28,409评论 2赞 254
  • 日本核电站爆炸内幕
    正文 年R本政府宣布，位于F岛的核电站，受9级特大地震影响，放射性物质发生泄漏。R本人自食恶果不足惜，却给世界环境...
    茶点故事阅读 33,072评论 3赞 237
  • 男人毒药：我在死后第九天来索命
    文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹，春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 26,088评论 0赞 8
  • 一桩弑父案，背后竟有这般阴谋
    文/苍兰香墨 我抬头看了看天上的太阳。三九已至，却和暖如春，着一层夹袄步出监牢的瞬间，已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 26,860评论 0赞 195
  • 情欲美人皮
    我被黑心中介骗来泰国打工， 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留，地道东北人。 一个月前我还...
    沈念sama阅读 35,704评论 2赞 276
  • 代替公主和亲
    正文 我出身青楼，却偏偏与公主长得像，于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子，可洞房花烛夜当晚...
    茶点故事阅读 35,608评论 2赞 270