35

There are already several questions in regards to logging the SQL query in Laravel 4. But I've tried almost all of them and it's still not working the way I want.

Here's my situation

  1. in my php view file, I make AJAX request to the server
  2. The AJAX request is received and runs a RAW parameterized Postgres SQL query (e.g.

    DB::select('select * from my_table where id=?', array(1))

If I use

Event::listen('illuminate.query', function($sql)
{
  Log::error($sql);
});

I just get "select * from my_table where id=?" as the log message without the ID value actually populated.

If I use

$queries = DB::getQueryLog();
$last_query = end($queries);
Log::error(print_r($last_query, true));

I still don't have the final SQL query with the ID populated.

Finally, if I use a logging tool like https://github.com/loic-sharma/profiler - it doesn't display anything since I'm making an AJAX request.

Have I exhausted my options? Is there still another better way?

ericbae
  • 9,604
  • 25
  • 75
  • 108
  • I think you can pass `$bindings` as the second param of the function called by Event::listen. So `... , function($sql, $bindings) { ... `. – Jeemusu Oct 02 '13 at 07:26
  • I believe PDO, which underlies all Laravel queries, never actually gives PHP the opportunity to see the final SQL being ran. It gives the SQL + bindings separately, which is why Laravel's query logger shows the bindings separate - PHP can't see the final thing. At best, we can only attempt to reconstruct it with the raw query and filling in the bindings ourselves. MySQL and other databases, of course, have their own query logger you can use if you'd like. (They usually slow down the DB, so only use to test :D ) – fideloper Oct 02 '13 at 13:30
  • I actually use *loic-sharma* with AJAX-requests. I added a filter to Laravel so that it appends profiler data to all JsonResponses. Then using a jQuerys *ajaxSetup* with *dataFilter* I automatically update the profiler HTML on every json response. If you are interested I can add a answer with my solution (with code). – Matteus Hemström Oct 02 '13 at 18:05
  • yes pls - that would be great! – ericbae Oct 03 '13 at 01:15
  • @ericbae Added a answer on the ajax-profiler-thing. I hope it's of any use. It's a pretty cool development feature:) – Matteus Hemström Oct 03 '13 at 16:44
  • If you are using `Laravel 5` then see this post: http://stackoverflow.com/questions/27753868/how-to-get-the-query-executed-in-laravel-5-dbgetquerylog-returning-empty-arr/34638344#34638344 (ps. I am so foolish that I tried the methods here when using 5.2, hope others not) – ch271828n May 08 '16 at 08:46

6 Answers6

56

Here is what I am currently using for logging of sql queries. You should be able to drop this into your main routes file then add 'log' => true into your database config.

if (Config::get('database.log', false))
{           
    Event::listen('illuminate.query', function($query, $bindings, $time, $name)
    {
        $data = compact('bindings', 'time', 'name');

        // Format binding data for sql insertion
        foreach ($bindings as $i => $binding)
        {   
            if ($binding instanceof \DateTime)
            {   
                $bindings[$i] = $binding->format('\'Y-m-d H:i:s\'');
            }
            else if (is_string($binding))
            {   
                $bindings[$i] = "'$binding'";
            }   
        }       

        // Insert bindings into query
        $query = str_replace(array('%', '?'), array('%%', '%s'), $query);
        $query = vsprintf($query, $bindings); 

        Log::info($query, $data);
    });
}

Thanks to Jeemusu answer for the bit about inserting the bindings into the prepared statement.

Collin James
  • 9,062
  • 2
  • 28
  • 36
  • 2
    this could be a separate question... but would there be any way where we can log not ALL queries, but specific ones we want? – ericbae Oct 05 '13 at 06:04
  • 1
    That logs to the default Laravel log file. How would I log to a file just for queries? For example, log to app/storage/logs/sql.txt – ejunker Oct 11 '13 at 19:43
  • 1
    I fixed this line in $query = str_replace(array('%', '?'), array('%%', '\'%s\''), $query); So you will have strings inside of single quotes – bonaccorso.p Jul 01 '14 at 22:04
  • Awesome answer. I'm trying to understand however why does this go in the routes.php file? – KingKongFrog Jun 24 '15 at 21:49
  • @KingKongFrog The routes file is just something that is always loaded before any sort of app logic is executed. Maybe start/global.php is more appropriate. – Collin James Jun 24 '15 at 22:01
  • FYI this is a really good solution, but will break if your query contains string that naturally have % or ? in it, like in *"car.com/index.php?getCar=17"* ! – Sliq Mar 04 '16 at 13:16
11

You should be able to find the bindings by passing $bindings as the second parameter of the Event function.

Event::listen('illuminate.query', function($sql, $bindings, $time){
    echo $sql;          // select * from my_table where id=? 
    print_r($bindings); // Array ( [0] => 4 )
    echo $time;         // 0.58 

    // To get the full sql query with bindings inserted
    $sql = str_replace(array('%', '?'), array('%%', '%s'), $sql);
    $full_sql = vsprintf($sql, $bindings);
});

In Laravel 3.x I think the event listener was called laravel.query

Jeemusu
  • 10,415
  • 3
  • 42
  • 64
9

Continuing on @Collin James answer.

If you want to log to a seperate file only for sql, you can do it with this:

if (Config::get('database.log', false)) {
    Event::listen('illuminate.query', function($query, $bindings, $time, $name) {
        $data = compact('bindings', 'time', 'name');

        // Format binding data for sql insertion
        foreach ($bindings as $i => $binding) {
            if ($binding instanceof \DateTime) {
                $bindings[$i] = $binding->format('\'Y-m-d H:i:s\'');
            } else if (is_string($binding)) {
                $bindings[$i] = "'$binding'";
            }
        }

        // Insert bindings into query
        $query = str_replace(array('%', '?'), array('%%', '%s'), $query);
        $query = vsprintf($query, $bindings);

        $log = new Logger('sql');
        $log->pushHandler(new StreamHandler(storage_path().'/logs/sql-' . date('Y-m-d') . '.log', Logger::INFO));

        // add records to the log
        $log->addInfo($query, $data);
    });
}

With this at the top of your file:

use Monolog\Logger;
use Monolog\Handler\StreamHandler;

This will log all your queries to a file named sql-YYYY-mm-dd.log in storage/logs/.

Community
  • 1
  • 1
Marwelln
  • 28,492
  • 21
  • 93
  • 117
6

While the accepted answer stands correct, this answer explains how to update loic-sharma profiler when making Ajax requests using jQuery. Using this approach one doesn't need to read file logs.

Step 1

The first problem is to send the updated profiler data to the client on every Ajax-request. This can be solved using the "after" events of the Laravel application.

app/filters.php:

App::after(function($request, $response)
{
    // If it's a JsonResponse and the profiler is enabled, include it in the response.
    if($response instanceof \Illuminate\Http\JsonResponse && Profiler::isEnabled()) {

        $profiler = Profiler::getFacadeRoot();
        $profilerJson = json_encode($profiler->render());
        $content = substr($response->getContent(), 0, -1) . ',"profiler":' . $profilerJson . '}';
        $response->setContent($content);
    }
});

The App::after filter will run upon every Laravel request. The first line of the closure above, makes sure that it will only continue if a the response is of type JsonResponse and the profiler is enabled. If that is the case, render the profiler and append the HTML to the JSON object.

Note: this code assumes that the returned JSON is a object. So it will fail for arrays: Response::json(array(1,2,3)).

Step 2

Now that the updated profiler HTML is being sent to the client, we must update the DOM with the new profiler HTML using javascript. This should happen every time the client gets a JSON response. jQuery provides global Ajax event handlers, which is perfect to achive this.

$(document).ajaxSuccess(function(event, request, settings) {
    try {
        json = jQuery.parseJSON(request.responseText);
        if(json.profiler) {
            renderProfiler(json.profiler);
        }
    } catch(error) {
        // Its not JSON.
        return;
    }
});

Here's a method to replace the old profiler with the new one:

renderProfiler = function(data) {
    // Remove previous 
    $anbu = $('.anbu');
    $anbu.prev().remove(); // Removes <style> tag of profiler
    $anbu.next().next().remove(); // Removes the inline script tag of profiler
    $anbu.next().remove(); // Removes jQuery script tag by the profiler
    $anbu.remove(); // Removes the <div> tag of profiler
    $(document.body).append(data);
};

Using it

Now it is as simple as returning responses as:

return Response::json(array(
    'user' => Auth::user()
));

Laravel will append the profiler HTML. The javascript will catch the JSON response and update the DOM. You will have the SQL queries and timings right on the web page.

Note

While the code is tested, there might be a bug or two. This is also not exactly how I do it. Instead of sending the HTML in the json response, I extend the object with the actual data from the profiler. On the client side I render the profiler using a mustache template.

Matteus Hemström
  • 3,796
  • 2
  • 26
  • 34
  • Okay but where do I put the jQuery code? I don't have any views yet because I'm just testing. My controller routes are just returning models directly, at the moment. It's nice because I have a Chrome extension (JSONView) installed and I get nicely formatted JSON. But I'd like to see the queries it took to get them! – Kenmore May 20 '14 at 00:32
  • @Zuko This answer is using loic-sharma profiler to render profile output as HTML. In your case, that's not what you want. Instead of embedding the profiler data as HTML you can provide the raw data from the profiler directly. If you do that, you can skip _Step 2_. See [this example](http://laravel.io/bin/1b8dv) (an adaption of _Step 1_). – Matteus Hemström May 20 '14 at 15:59
2

While the question was originally targeted at Laravel 4, I still ended up here through google, but I'm using Laravel 5.

There are new ways to log all queries in Laravel 5 using Middleware, but if you prefer the same approach here is the same code provided by Collin James but working for Laravel 5

if (Config::get('database.log', false))
{
    Event::listen('Illuminate\Database\Events\QueryExecuted', function($query)
    {
        $bindings = $query->bindings;
        $time = $query->time;
        $name = $query->connection->getName();
        $data = compact('bindings', 'time', 'name');

        // Format binding data for sql insertion
        foreach ($bindings as $i => $binding)
        {
            if ($binding instanceof \DateTime)
            {
                $bindings[$i] = $binding->format('\'Y-m-d H:i:s\'');
            }
            else if (is_string($binding))
            {
                $bindings[$i] = "'$binding'";
            }
        }

        // Insert bindings into query
        $query = str_replace(array('%', '?'), array('%%', '%s'), $query->sql);
        $query = vsprintf($query, $bindings);

        Log::info($query, $data);
    });
}
Community
  • 1
  • 1
Gonçalo Queirós
  • 1,193
  • 2
  • 9
  • 19
1

That's what I've been using:

DB::listen(function ($query, $bindings, $time, $connection) {
    $fullQuery = vsprintf(str_replace(array('%', '?'), array('%%', '%s'), $query), $bindings);
    $result = $connection . ' (' . $time . '): ' . $fullQuery;

    dump($result);
    // You can of course log the $result
});
Mahmoud Zalt
  • 30,478
  • 7
  • 87
  • 83