昨天在开发一新接口时，遇到一问题，nginx时不时出现502错。

打开nginx错误日志，发现如下报错：

2014/09/15 14:34:28 [error] 5103#0: *114 upstream sent too big header while reading response header from upstream, client: 127.0.0.1, ...

这个属于比较常规的问题了，header长度超出，之前遇到过

    fastcgi_buffer_size 128k;
    fastcgi_buffers 4 256k;
    fastcgi_busy_buffers_size 256k;

于是按照之前的方法适当调整nginx配置，发现问题依旧。

程序逻辑比较简单，大致流程是：

  • 检查redis缓存看是否有数据，有则直接返回
  • 否则查询数据库
  • 写入redis缓存
  • 返回数据

调试发现，每次写入redis缓存都会导致nginx报502

开始觉得不可能，因为系统其它很多地方也用到redis但一直没遇到过这个问题.

于是怀疑是不是snc redis的bug？ 经过一番调试发现，如果执行redis命令的时候不记录日志，则能正常工作，否则就报502错，代码为下面的$this->logger->logCommand这一行。

    public function __call($name, array $arguments)
    {
        $log = true;

		...

        $startTime = microtime(true);
        $result = call_user_func_array(array($this->redis, $name), $arguments);
        $duration = (microtime(true) - $startTime) * 1000;

        if ($log && null !== $this->logger) {
            $this->logger->logCommand($this->getCommandString($name, $arguments), $duration, $this->alias, false);
        }

        return $result;
    }

进一步debug，发现这里调用到了Symfony内的Monolog的方法用于记录日志。

    public function addRecord($level, $message, array $context = array())
    {
		...

        // check if any handler will handle this message
        $handlerKey = null;
        foreach ($this->handlers as $key => $handler) {
            if ($handler->isHandling($record)) {
                $handlerKey = $key;
                break;
            }
        }
        // none found
        if (null === $handlerKey) {
            return false;
        }

        // found at least one, process message and dispatch it
        foreach ($this->processors as $processor) {
            $record = call_user_func($processor, $record);
        }
        while (isset($this->handlers[$handlerKey]) &&
            false === $this->handlers[$handlerKey]->handle($record)) {
            $handlerKey++;
        }

        return true;
    }

问题就出在上面的 handlers里，打印出来发现这里面包含了4个handler，经过排查发现是ChromePhpHandler的问题，进一步抠代码：

    public function onKernelResponse(FilterResponseEvent $event)
    {
		...
		
        $this->response = $event->getResponse();
        foreach ($this->headers as $header => $content) {
            $this->response->headers->set($header, $content);
        }
        $this->headers = array();
    }

打印出这里的header后发现问题了，header内的X-ChromeLogger-Data值长度达到165952字节，大约162K，超出了我本地nginx配置里设定的128K，于是出现502. 如图：

chromephp-headers

为弄清具体是什么数据，经过base64_decode和json_decode后，如图：

chromephp-headers-print

原来是snc_redis完整记录了redis操作数据，所以如果写入到redis的数据过大，可能超出web服务器设置的header最大长度，导致报错。

这尼玛。。这种方式简直反人类啊，绝逼不靠谱，于是准备跟symfony官方反馈这个问题，不过发现官方已经解决过了。。 解决办法是，去掉Symfony配置文件config_dev.yml内的chromephp相关配置。

到这里问题解决了，简直太坑。。

不过，调试过程中发现snc redis的另外一个坑，下次有空再写出来。