debug_backtrace()を使用してCakePHPの謎のsqlログを調査した

CakePHPを使ってアプリケーションを開発していたときに、debug.logに謎のsqlが出力されていた。sqlをdebug.logに出力するようなコードは書いておらず、CakePHPのログの設定にもそのような設定はしていない。CakePHPではsqlの実行ログは通常、app.php内のLogの設定でlog => trueに設定しておくとqueries.logに出力されるようになっているが、今回のはqueries.logではなくdebug.logにsqlログが出力されていて気になったので、調査してみた。

環境

CakePHP: 3.9
DB: oracle

とりあえず

cakephp-oracle-driverの仕業。

調査

謎のsqlログがCakePHPのLog出力機能を使って出力されているかを調べるために、ドキュメントを参考にして独自のFileLogを作成して試してみる。

ログアダプター作成

app/src/Log/Engine配下にCustomFileLog.phpというファイルを作成。CakePHPのFileLogクラスを継承してlogメソッドをオーバーライドしている。logメソッド内にdebug_backtrace()を仕込んでいることで、このメソッドがどこから呼ばれているかを確認でき、謎のsqlログの呼び出し元がわかるはずである。

<?php

namespace App\Log\Engine;
use Cake\Log\Engine\FileLog;


class CustomFileLog extends FileLog
{
    public function log($level, $message, array $context = [])
    {
        $bt = debug_backtrace();
        var_dump($bt);
        die();
    }
}

ファイルを作成したら、ログアダプター設定のためにapp.phpのLogの設定を変更する。

app.php

...
'Log' => [
        'debug' => [
            // 'className' => FileLog::class,
            'className' => App\Log\Engine\CustomFileLog::class,
            'path' => LOGS,
            'file' => 'debug',
            'url' => env('LOG_DEBUG_URL', null),
            'scopes' => false,
            'levels' => ['notice', 'info', 'debug'],
        ],
...

ここまで設定したら、アプリケーションを実行して表示を確認してみる。

debug_backtrace()実行結果

画面にdebug_backtrace()の実行結果が表示されたので、どうやらcakeの標準機能を使用して実行ログを出力しているみたいだ。出力を確認してみると、/var/www/app/vendor/cakedc/cakephp-oracle-driver/src/Database/Driver/OracleBase.phpが怪しい。

debug_backtrace()の結果(一部抜粋)

/var/www/app/src/Log/Engine/CustomFileLog.php:12:
array (size=41)
  0 => 
    array (size=7)
      'file' => string '/var/www/app/vendor/cakephp/cakephp/src/Log/Log.php' (length=51)
      'line' => int 383
      'function' => string 'log' (length=3)
      'class' => string 'App\Log\Engine\CustomFileLog' (length=28)
      'object' => 
        object(App\Log\Engine\CustomFileLog)[193]
          protected '_defaultConfig' => 
            array (size=8)
              ...
          protected '_path' => string '/var/www/app/logs/' (length=18)
          protected '_file' => string 'debug.log' (length=9)
          protected '_size' => int 1048576
          protected '_config' => 
            array (size=10)
              ...
          protected '_configInitialized' => boolean true
      'type' => string '->' (length=2)
      'args' => 
        array (size=3)
          0 => string 'debug' (length=5)
          1 => string 'SELECT ...'... (length=518)
          2 => 
            array (size=1)
              ...
  1 => 
    array (size=6)
      'file' => string '/var/www/app/vendor/cakedc/cakephp-oracle-driver/src/Database/Driver/OracleBase.php' (length=83)
      'line' => int 164
      'function' => string 'write' (length=5)
      'class' => string 'Cake\Log\Log' (length=12)
      'type' => string '::' (length=2)
      'args' => 
        array (size=2)
          0 => string 'debug' (length=5)
          1 => string 'SELECT ...'... (length=518)
  2 => 
    array (size=7)
      'file' => string '/var/www/app/vendor/cakephp/cakephp/src/Database/Connection.php' (length=63)
      'line' => int 283
      'function' => string 'prepare' (length=7)
      'class' => string 'CakeDC\OracleDriver\Database\Driver\OracleBase' (length=46)
      'object' => ...
      ...

実際のファイルを確認してみると、

OracleBase.php

    /**
     * Prepares a sql statement to be executed
     *
     * @param string|\Cake\Database\Query $query The query to convert into a statement.
     * @return \Cake\Database\StatementInterface
     */
    public function prepare($query)
    {
        $this->connect();
        $isObject = ($query instanceof \Cake\ORM\Query) || ($query instanceof \Cake\Database\Query);
        $queryStringRaw = $isObject ? $query->sql() : $query;
        Log::write('debug', $queryStringRaw);
        // debug($queryStringRaw);
        $queryString = $this->_fromDualIfy($queryStringRaw);
        [$queryString, $paramMap] = self::convertPositionalToNamedPlaceholders($queryString);
        $innerStatement = $this->_connection->prepare($queryString);

        $statement = $this->_wrapStatement($innerStatement);
        $statement->queryString = $queryStringRaw;
        $statement->paramMap = $paramMap;

        $disableBuffer = false;
        $normalizedQuery = substr(strtolower(trim($queryString, " \t\n\r\0\x0B(")), 0, 6);
        if ($normalizedQuery !== 'select') {
            $disableBuffer = true;
        }

        if (
            $isObject
            && $query->isBufferedResultsEnabled() === false
            || $disableBuffer
        ) {
                $statement->bufferResults(false);
        }

        return $statement;
    }

writeメソッドが呼ばれてるので原因はこの箇所でした。