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?

6
  • I think you can pass $bindings as the second param of the function called by Event::listen. So ... , function($sql, $bindings) { ... .
    – Jeemusu
    Oct 2, 2013 at 7: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 2, 2013 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). Oct 2, 2013 at 18:05
  • yes pls - that would be great!
    – ericbae
    Oct 3, 2013 at 1:15
  • @ericbae Added a answer on the ajax-profiler-thing. I hope it's of any use. It's a pretty cool development feature:) Oct 3, 2013 at 16:44

6 Answers 6

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.

6
  • 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 5, 2013 at 6: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, 2013 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 Jul 1, 2014 at 22:04
  • Awesome answer. I'm trying to understand however why does this go in the routes.php file? Jun 24, 2015 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. Jun 24, 2015 at 22:01
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

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/.

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.

2
  • 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, 2014 at 0: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 (an adaption of Step 1). May 20, 2014 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);
    });
}
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
});

Not the answer you're looking for? Browse other questions tagged or ask your own question.