Allow Phabricator to write an access log using PhutilDeferredLog

Summary: Provide a configurable access log.

Test Plan:
Got a sensible-looking log including logged-in, logged-out, conduit, 404, etc:

  [Mon, 23 Apr 2012 20:08:12 -0700]	32599	orbital	-	epriestley	DifferentialCommentPreviewController	-	/differential/comment/preview/42/	http://local.aphront.com:8080/D42	200	65406
  [Mon, 23 Apr 2012 20:08:12 -0700]	32881	orbital	-	epriestley	DifferentialChangesetViewController	-	/differential/changeset/	http://local.aphront.com:8080/D42	200	72669
  [Mon, 23 Apr 2012 20:08:39 -0700]	32882	orbital	127.0.0.1	epriestley	DifferentialRevisionListController	-	/differential/	http://local.aphront.com:8080/D42	200	106444
  [Mon, 23 Apr 2012 20:08:54 -0700]	32867	orbital	127.0.0.1	epriestley	DifferentialRevisionListController	-	/differential/	http://local.aphront.com:8080/differential/	200	112229
  [Mon, 23 Apr 2012 20:09:05 -0700]	32530	orbital	127.0.0.1	epriestley	PhabricatorDirectoryMainController	-	/	http://local.aphront.com:8080/differential/	200	141350
  [Mon, 23 Apr 2012 20:09:10 -0700]	32598	orbital	127.0.0.1	epriestley	PhabricatorDirectoryCategoryViewController	-	/directory/6/	http://local.aphront.com:8080/	200	43474
  [Mon, 23 Apr 2012 20:09:12 -0700]	32880	orbital	127.0.0.1	epriestley	PhabricatorConduitConsoleController	-	/conduit/	http://local.aphront.com:8080/directory/6/	200	139340
  [Mon, 23 Apr 2012 20:09:15 -0700]	32868	orbital	127.0.0.1	epriestley	PhabricatorConduitAPIController	arcanist.projectinfo	/api/arcanist.projectinfo	http://local.aphront.com:8080/conduit/	200	128774
  [Mon, 23 Apr 2012 20:10:04 -0700]	32599	orbital	127.0.0.1	epriestley	Phabricator404Controller	-	/asdbmabdmbsm	-	404	38782
  [Mon, 23 Apr 2012 20:10:04 -0700]	32881	orbital	127.0.0.1	-	CelerityResourceController	-	/res/c9a43002/rsrc/css/aphront/request-failure-view.css	http://local.aphront.com:8080/asdbmabdmbsm	200	25160
  [Mon, 23 Apr 2012 20:10:57 -0700]	32882	orbital	127.0.0.1	epriestley	PhabricatorLogoutController	-	/logout/	http://local.aphront.com:8080/asdbmabdmbsm	200	40810
  [Mon, 23 Apr 2012 20:10:57 -0700]	32867	orbital	127.0.0.1	-	PhabricatorLoginController	-	/login/	http://local.aphront.com:8080/asdbmabdmbsm	200	42526
  [Mon, 23 Apr 2012 20:10:59 -0700]	32919	orbital	127.0.0.1	-	PhabricatorLoginController	-	/login/	http://local.aphront.com:8080/asdbmabdmbsm	200	49052
  [Mon, 23 Apr 2012 20:10:59 -0700]	32880	orbital	127.0.0.1	-	CelerityResourceController	-	/res/c80156c4/rsrc/js/application/core/behavior-dark-console.js	http://local.aphront.com:8080/login/	200	33166
  [Mon, 23 Apr 2012 20:10:59 -0700]	32868	orbital	127.0.0.1	-	CelerityResourceController	-	/res/4965d970/rsrc/css/aphront/dark-console.css	http://local.aphront.com:8080/login/	200	38078
  [Mon, 23 Apr 2012 20:10:59 -0700]	32599	orbital	127.0.0.1	-	CelerityResourceController	-	/res/pkg/8a5de8a3/javelin.pkg.js	http://local.aphront.com:8080/login/	200	40534
  [Mon, 23 Apr 2012 20:10:59 -0700]	32882	orbital	127.0.0.1	-	CelerityResourceController	-	/res/pkg/9c4e265b/core.pkg.css	http://local.aphront.com:8080/login/	200	41262
  [Mon, 23 Apr 2012 20:10:59 -0700]	32881	orbital	127.0.0.1	-	CelerityResourceController	-	/res/pkg/0c96375e/core.pkg.js	http://local.aphront.com:8080/login/	200	43720
  [Mon, 23 Apr 2012 20:10:59 -0700]	32921	orbital	127.0.0.1	-	CelerityResourceController	-	/res/caa86a45/rsrc/js/javelin/core/init.js	http://local.aphront.com:8080/login/	200	47566
  [Mon, 23 Apr 2012 20:10:59 -0700]	32867	orbital	127.0.0.1	-	CelerityResourceController	-	/res/f46289e9/rsrc/js/application/core/behavior-error-log.js	http://local.aphront.com:8080/login/	200	29328
  [Mon, 23 Apr 2012 20:10:59 -0700]	32919	orbital	127.0.0.1	-	CelerityResourceController	-	/res/7e62ff40/rsrc/image/phabricator_logo.png	http://local.aphront.com:8080/login/	200	25583
  [Mon, 23 Apr 2012 20:10:59 -0700]	32880	orbital	127.0.0.1	-	CelerityResourceController	-	/res/8c6200d3/rsrc/image/sprite.png	http://local.aphront.com:8080/login/	200	29829
  [Mon, 23 Apr 2012 20:11:01 -0700]	32868	orbital	127.0.0.1	-	PhabricatorOAuthLoginController	-	/oauth/facebook/login/  http://local.aphront.com:8080/login/	200	855931
  [Mon, 23 Apr 2012 20:11:02 -0700]	32882	orbital	127.0.0.1	epriestley789	PhabricatorLoginValidateController	-	/login/validate/	http://local.aphront.com:8080/login/	200	29793
  [Mon, 23 Apr 2012 20:11:02 -0700]	32881	orbital	127.0.0.1	epriestley789	PhabricatorDirectoryMainController	-	/	http://local.aphront.com:8080/login/	200	91638

Reviewers: jungejason, btrahan, vrana

Reviewed By: btrahan

CC: aran

Differential Revision: https://secure.phabricator.com/D2310

conf/default.conf.php

@@ -81,6 +81,45 @@ return array(
   'policy.allow-public'         => false,
 
 
+// -- Logging --------------------------------------------------------------- //
+
+  // To enable the Phabricator access log, specify a path here. The Phabricator
+  // access log can provide more detailed information about Phabricator access
+  // than normal HTTP access logs (for instance, it can show logged-in users,
+  // controllers, and other application data). If not set, no log will be
+  // written.
+  //
+  // Make sure the PHP process can write to the log!
+  'log.access.path'             => null,
+
+  // Format for the access log. If not set, the default format will be used:
+  //
+  //  "[%D]\t%h\t%u\t%M\t%C\t%m\t%U\t%c\t%T"
+  //
+  // Available variables are:
+  //
+  //  - %c The HTTP response code.
+  //  - %C The controller which handled the request.
+  //  - %D The request date.
+  //  - %e Epoch timestamp.
+  //  - %h The webserver's host name.
+  //  - %p The PID of the server process.
+  //  - %R The HTTP referrer.
+  //  - %r The remote IP.
+  //  - %T The request duration, in microseconds.
+  //  - %U The request path.
+  //  - %u The logged-in user, if one is logged in.
+  //  - %M The HTTP method.
+  //  - %m For conduit, the Conduit method which was invoked.
+  //
+  // If a variable isn't available (for example, %m appears in the file format
+  // but the request is not a Conduit request), it will be rendered as "-".
+  //
+  // Note that the default format is subject to change in the future, so if you
+  // rely on the log's format, specify it explicitly.
+  'log.access.format'           => null,
+
+
 // -- DarkConsole ----------------------------------------------------------- //
 
   // DarkConsole is a administrative debugging/profiling tool built into

src/__phutil_library_map__.php

@@ -501,6 +501,7 @@ phutil_register_library_map(array(
     'MetaMTAConstants' => 'applications/metamta/constants/base',
     'MetaMTANotificationType' => 'applications/metamta/constants/notificationtype',
     'Phabricator404Controller' => 'applications/base/controller/404',
+    'PhabricatorAccessLog' => 'infrastructure/accesslog',
     'PhabricatorAphlictTestPageController' => 'applications/notifications/controller/test',
     'PhabricatorAuditActionConstants' => 'applications/audit/constants/action',
     'PhabricatorAuditAddCommentController' => 'applications/audit/controller/addcomment',

src/applications/conduit/controller/api/PhabricatorConduitAPIController.php

@@ -125,6 +125,20 @@ final class PhabricatorConduitAPIController
         }
       }
 
+      $access_log = PhabricatorAccessLog::getLog();
+      if ($access_log) {
+        $conduit_username = '-';
+        $conduit_user = $api_request->getUser();
+        if ($conduit_user && $conduit_user->getPHID()) {
+          $conduit_username = $conduit_user->getUsername();
+        }
+        $access_log->setData(
+          array(
+            'u' => $conduit_username,
+            'm' => $method,
+          ));
+      }
+
       if ($method_handler->shouldAllowUnguardedWrites()) {
         $allow_unguarded_writes = true;
       }

src/applications/conduit/controller/api/__init__.php

@@ -17,6 +17,7 @@ phutil_require_module('phabricator', 'applications/oauthserver/scope');
 phutil_require_module('phabricator', 'applications/oauthserver/server');
 phutil_require_module('phabricator', 'applications/oauthserver/storage/accesstoken');
 phutil_require_module('phabricator', 'applications/people/storage/user');
+phutil_require_module('phabricator', 'infrastructure/accesslog');
 phutil_require_module('phabricator', 'storage/queryfx');
 phutil_require_module('phabricator', 'view/control/table');
 phutil_require_module('phabricator', 'view/layout/panel');

src/infrastructure/accesslog/PhabricatorAccessLog.php

@@ -0,0 +1,57 @@
+<?php
+
+/*
+ * Copyright 2012 Facebook, Inc.
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *   http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+final class PhabricatorAccessLog {
+
+  static $log;
+
+  public static function init() {
+    // NOTE: This currently has no effect, but some day we may reuse PHP
+    // interpreters to run multiple requests. If we do, it has the effect of
+    // throwing away the old log.
+    self::$log = null;
+  }
+
+  public static function getLog() {
+    if (!self::$log) {
+      $path = PhabricatorEnv::getEnvConfig('log.access.path');
+      $format = PhabricatorEnv::getEnvConfig('log.access.format');
+      $format = nonempty(
+        $format,
+        "[%D]\t%p\t%h\t%r\t%u\t%C\t%m\t%U\t%R\t%c\t%T");
+
+      if (!$path) {
+        return null;
+      }
+
+      $log = new PhutilDeferredLog($path, $format);
+      $log->setData(
+        array(
+          'D' => date('r'),
+          'h' => php_uname('n'),
+          'p' => getmypid(),
+          'e' => time(),
+        ));
+
+      self::$log = $log;
+    }
+
+    return self::$log;
+  }
+
+}

src/infrastructure/accesslog/__init__.php

@@ -0,0 +1,15 @@
+<?php
+/**
+ * This file is automatically generated. Lint this module to rebuild it.
+ * @generated
+ */
+
+
+
+phutil_require_module('phabricator', 'infrastructure/env');
+
+phutil_require_module('phutil', 'filesystem/deferredlog');
+phutil_require_module('phutil', 'utils');
+
+
+phutil_require_source('PhabricatorAccessLog.php');

webroot/index.php

@@ -71,6 +71,18 @@ try {
   phutil_require_module('phabricator', 'infrastructure/env');
   PhabricatorEnv::setEnvConfig($conf);
 
+  // This is the earliest we can get away with this, we need env config first.
+  PhabricatorAccessLog::init();
+  $access_log = PhabricatorAccessLog::getLog();
+  if ($access_log) {
+    $access_log->setData(
+      array(
+        'R' => idx($_SERVER, 'HTTP_REFERER', '-'),
+        'r' => idx($_SERVER, 'REMOTE_ADDR', '-'),
+        'M' => idx($_SERVER, 'REQUEST_METHOD', '-'),
+      ));
+  }
+
   phutil_require_module('phabricator', 'aphront/console/plugin/xhprof/api');
   DarkConsoleXHProfPluginAPI::hookProfiler();
 
@@ -129,8 +141,27 @@ PhabricatorEventEngine::initialize();
 
 $application->setRequest($request);
 list($controller, $uri_data) = $application->buildController();
+
+if ($access_log) {
+  $access_log->setData(
+    array(
+      'U' => (string)$request->getRequestURI()->getPath(),
+      'C' => get_class($controller),
+    ));
+}
+
 try {
   $response = $controller->willBeginExecution();
+
+  if ($access_log) {
+    if ($request->getUser() && $request->getUser()->getPHID()) {
+      $access_log->setData(
+        array(
+          'u' => $request->getUser()->getUserName(),
+        ));
+    }
+  }
+
   if (!$response) {
     $controller->willProcessRequest($uri_data);
     $response = $controller->processRequest();
@@ -148,6 +179,9 @@ try {
   $response_string = $response->buildResponseString();
 } catch (Exception $ex) {
   $write_guard->dispose();
+  if ($access_log) {
+    $access_log->write();
+  }
   phabricator_fatal('[Rendering Exception] '.$ex->getMessage());
 }
 
@@ -186,6 +220,15 @@ if (isset($_REQUEST['__profile__']) &&
 
 $sink->writeData($response_string);
 
+if ($access_log) {
+  $access_log->setData(
+    array(
+      'c' => $response->getHTTPResponseCode(),
+      'T' => (int)(1000000 * (microtime(true) - $__start__)),
+    ));
+  $access_log->write();
+}
+
 /**
  * @group aphront
  */
@@ -304,6 +347,15 @@ function phabricator_shutdown() {
 }
 
 function phabricator_fatal($msg) {
+  $log = PhabricatorAccessLog::getLog();
+  if ($log) {
+    $log->setData(
+      array(
+        'c' => 500,
+      ));
+    $log->write();
+  }
+
   header(
     'Content-Type: text/plain; charset=utf-8',
     $replace = true,
@@ -314,3 +366,4 @@ function phabricator_fatal($msg) {
 
   exit(1);
 }
+