CakePHP Request logging ala Rails

AppController.php

class AppController extends Controller {
  
  function beforeFilter()  {
    $this->capture_request_head_for_log();
  }

  /*
  Log some basic basic details of the HTTP Request:
  
  Started GET "/users/lost" for 127.0.0.1 at 2012-10-24 19:18:25 -0700
  Processing by UsersController#fullcalendar as JSON
    Parameters: {"foo"=>"bar", "user"=>"1352620800"}
  */
  private function capture_request_head_for_log() {
    $url = $this->request->here;
    $parameters = null;
    if(!empty($this->request->query)) {
      $params_for_params = array();
      $params_for_url = array();
      foreach($this->request->query as $key => $value) {
        if($key === 'url') { 
          continue;
        }
        $params_for_params[] = '"' . $key . '" => ' . $value . '"';
        $params_for_url[] = $key . '=' . $value;
      }
      
      if(!empty($params_for_url)) {
        $url .= '?' . implode("&", $params_for_url);
      }
      // log any post params
      $post_params = null;
      if($this->request->isPost()) {
        $post_params = "\n POST parameters: " . print_r($this->request->data, true);
      }
      $parameters = sprintf("\n Parameters: {%s}%s", implode(", ", $params_for_params), $post_params);
    }
    $client_ip = $this->request->clientIp();
    $time = date('Y-m-d H:i:s P', time());
    $controller = ucfirst($this->request->controller) . 'Controller';
    $action = $this->request->action;
    $content_type = $this->request->header('Accept');
    $processing_by = sprintf("\n Processing by %s#%s as %s", $controller, $action, $content_type);
    $msg = sprintf('Started %s "%s" for %s at %s%s%s', $this->request->method(), $url, $client_ip, $time,
      $processing_by, $parameters);
    Configure::write('current_start_request_time', microtime(true));
    CakeLog::write('request', "\n" . $msg);
  }
  
  public function beforeRedirect() {
    parent::beforeRedirect();
    $this->log_request_tail();
  }
  
  private function log_request_tail() {
    $start = Configure::read('current_start_request_time');
    $end = microtime(true);
    $tail = "Completed";
    
    $statusCode = $this->response->statusCode(null);
    $statusDescription = $this->response->httpCodes($statusCode);
    if(is_array($statusDescription) && count($statusDescription) == 1) {
      $keys = array_keys($statusDescription);
      $vals = array_values($statusDescription);
      $tail .= " " . $keys[0] . ' ' . $vals[0];
    }
    $tail .= sprintf(" in %.2fms", ($end-$start) * 1000);
    CakeLog::write('request', "\n" . $tail . "\n\n");
  }
  
  public function afterFilter() {
    parent::afterFilter();
    $this->log_request_tail();
  }
  
  
}

bootstrap.php

App::uses('RequestLog', 'Lib');

CakeLog::config('request', array(
  'engine' => 'RequestLog',
  'scopes' => array('request'),
  'file' => 'request'
));

RequestLog.php

// app/Lig/Log/Engine/RequestLog.php

App::uses('BaseLog', 'Log');

class RequestLog extends FileLog {  
  public function write($type, $message) {
    $filename = $this->_path . $this->_file;
    $output = $message;
    return file_put_contents($filename, $output, FILE_APPEND);
  }
}

Writes to app/tmp/logs/request.log request lines like:

Started GET "/econtacts" for 127.0.0.1 at 2012-10-24 21:48:40 -07:00
Processing by EcontactsController#index as text/html,application/xhtml+xml,application/xml;q=0.9,/;q=0.8
Parameters: {}
Completed 200 OK in 196.50ms

TODO:

• Support for PUT & DELETE via POST with _method

Thank you, thank you, thank you.