Adding DB Logging to select controllers (#1746)

* Adding DB Logging to select controllers

We currently only have logging for requests that go through the REST
stack but would like to have visibility into when some html controller
operations are requested.

This commit adds request logging for the following controllers:
  - metric_explorer/get_data
  - metric_explorer/get_rawdata
  - user_interface/get_charts

* Adding documentation to the RequestLogger class

* Appeasing the style gods

* Resolving `undefined index` errors

While this code works when deployed it fills up the apache error logs
w/ undefined index messages due to not checking if the `$tokenProperty`
exists prior to accessing it in `$tokenSource`. This commit adds a
pre-check so that we don't get these errors anymore.

* More checking

* even more checking

* blah

* super blah

classes/CCR/RequestLogger.php

@@ -0,0 +1,130 @@
+<?php
+
+namespace CCR;
+
+use Exception;
+use Psr\Log\LoggerInterface;
+use Rest\Utilities\Authentication;
+
+/**
+ * This class is meant to provide logging functionality for use with the html controller operations akin to the logging
+ * done for requests to REST stack endpoints.
+ */
+class RequestLogger
+{
+    /**
+     * @var Logger|LoggerInterface
+     */
+    private $logger;
+
+    public function __construct($ident = 'controller.log', $logLevel = \CCR\Log::INFO)
+    {
+        $this->logger = Log::factory($ident, array(
+            'console' => false,
+            'file' => false,
+            'mail' => false,
+            'dbLogLevel' => $logLevel
+        ));
+    }
+
+    /**
+     * Log request related data to the database.
+     *
+     * @param float $start the result of a call to `microtime(true)` that indicates the start of a request.
+     * @param float $end the result of a call to `microtime(true)` that indicates the end of a request.
+     * @param int $level at which level the log request should be made. Corresponds to \CCR\Log::[EMERG|ALERT|CRIT|ERR|WARNING|NOTICE|INFO|DEBUG]
+     * @return void
+     */
+    public function log($start, $end, $level = \CCR\Log::INFO)
+    {
+        $authInfo = $this->getAuthenticationInfo();
+
+        $retval = array(
+            'message' => 'Route called',
+            'path' => $this->arrayGetOr('REQUEST_URI', $_SERVER),
+            'query' => $this->arrayGetOr('QUERY_STRING', $_SERVER),
+            'referer' => $this->arrayGetOr('HTTP_REFERER', $_SERVER),
+            'elapsed' => $end - $start,
+            'post' => $_POST,
+            'data' => array(
+                'ip' => $this->arrayGetOr('REMOTE_ADDR', $_SERVER),
+                'method' => $this->arrayGetOr('REQUEST_METHOD', $_SERVER),
+                'host' => $this->arrayGetOr('REMOTE_HOST', $_SERVER),
+                'port' => $this->arrayGetOr('REMOTE_PORT', $_SERVER),
+                'username' => $authInfo['username'],
+                'token' => $authInfo['token'],
+                'timestamp' => null
+            )
+        );
+
+        $requestTime = $this->arrayGetOr('REQUEST_TIME', $_SERVER);
+        if (isset($requestTime)) {
+            $retval['data']['timestamp'] = date("Y-m-d H:i:s", $requestTime);
+        }
+
+        $this->logger->log($level, $retval);
+    }
+
+    /**
+     * Just a helper function to increase readability so there aren't ternaries all over the place.
+     *
+     * @param string $property
+     * @param array $array
+     * @param mixed|null $default
+     * @return mixed|null
+     */
+    private function arrayGetOr($property, $array, $default = null)
+    {
+        return array_key_exists($property, $array) ? $array[$property] : $default;
+    }
+
+    /**
+     * Retrieve username, token from the current request, if present.
+     *
+     * @return array
+     */
+    private function getAuthenticationInfo()
+    {
+        $username = null;
+        $token = null;
+        $headers = getallheaders();
+
+        # Determine if basic auth is being used.
+        $useBasicAuth = false;
+        try {
+            $useBasicAuth = \xd_utilities\getConfiguration('rest', 'basic_auth') === 'on';
+        } catch (Exception $e) {
+        }
+
+        # If we're using basic auth, than the username value should be included in the headers.
+        if ($useBasicAuth) {
+            $username = array_key_exists(Authentication::_DEFAULT_USER, $headers)
+                ? $headers[Authentication::_DEFAULT_USER]
+                : null;
+        }
+
+        # If $username is still not set ( because we're not using basic auth ) than check for it in the request parameters.
+        if (!isset($username)) {
+            $username = array_key_exists(Authentication::_DEFAULT_USER, $_REQUEST)
+                ? $_REQUEST[Authentication::_DEFAULT_USER]
+                : null;
+        }
+
+        # Now that we have th username, find where they've hid the token value.
+        $tokenProperties = array(Authentication::_DEFAULT_TOKEN, Authentication::_DEFAULT_AUTH_TOKEN, Authentication::_DEFAULT_COOKIE_TOKEN);
+        $tokenSources = array($_REQUEST, $_COOKIE, $headers);
+        foreach ($tokenProperties as $tokenProperty) {
+            foreach ($tokenSources as $tokenSource) {
+                $token = array_key_exists($tokenProperty, $tokenSource) ? $tokenSource[$tokenProperty] : null;
+                if (isset($token)) {
+                    break;
+                }
+            }
+        }
+
+        return array(
+            'username' => $username,
+            'token' => $token
+        );
+    }
+}

html/controllers/metric_explorer/get_data.php

@@ -1,6 +1,6 @@
 <?php
 
-/* 
+/*
  * html/controllers/metric_explorer/get_data.php
  *
  * Glue code to call MetricExplorer::get_data(). All exceptions go to the
@@ -9,15 +9,23 @@
 
 // 5 minute exec time max
 ini_set('max_execution_time', 300);
+$logger = new \CCR\RequestLogger();
 
 $user = \xd_security\detectUser(
     array(XDUser::INTERNAL_USER, XDUser::PUBLIC_USER)
 );
 
 $m = new \DataWarehouse\Access\MetricExplorer($_REQUEST);
 
+$start = microtime(true);
+
 $result = $m->get_data($user);
 
+$end = microtime(true);
+
+$logger->log($start, $end);
+
+
 foreach($result['headers'] as $k => $v) {
     header( $k . ": " . $v);
 }

html/controllers/metric_explorer/get_rawdata.php

@@ -8,8 +8,11 @@
 // 5 minute exec time max
 ini_set('max_execution_time', 300);
 
+$logger = new \CCR\RequestLogger();
+
 $returnData = array();
 
+$start = microtime(true);
 try {
     if (isset($_REQUEST['config'])) {
         $config = json_decode($_REQUEST['config'], true);
@@ -166,14 +169,21 @@
         $ret['data'] = $dataset->getResults($limit, $offset);
         $ret['totalCount'] = $totalCount;
 
+        $end = microtime(true);
+        $logger->log($start, $end);
+
         print json_encode($ret);
         exit(0);
 
     }
 } catch (SessionExpiredException $see) {
     // TODO: Refactor generic catch block below to handle specific exceptions,
     //       which would allow this block to be removed.
+    $end = microtime(true);
+    $logger->log($start, $end);
     throw $see;
 } catch (Exception $ex) {
+    $end = microtime(true);
+    $logger->log($start, $end);
     \xd_response\presentError($ex);
 }

html/controllers/user_interface/get_charts.php

@@ -2,6 +2,8 @@
 
 use DataWarehouse\Access\Usage;
 
+$logger = new \CCR\RequestLogger();
+
 // Attempt authentication by API token.
 $user = \Models\Services\Tokens::authenticateToken();
 
@@ -11,10 +13,16 @@
     $user = \xd_security\detectUser(array(\XDUser::PUBLIC_USER));
 }
 
+$start = microtime(true);
+
 // Send the request and user to the Usage-to-Metric Explorer adapter.
 $usageAdapter = new Usage($_REQUEST);
 $chartResponse = $usageAdapter->getCharts($user);
 
+$end = microtime(true);
+
+$logger->log($start, $end);
+
 // Set the headers returned in the charts response.
 foreach ($chartResponse['headers'] as $headerName => $headerValue) {
     header("$headerName: $headerValue");