new: [log] Add ability to log sql queries for access log

pull/8757/head
Jakub Onderka 2022-11-15 14:38:22 +01:00
parent 00fa78e6ea
commit b3fd267105
8 changed files with 154 additions and 28 deletions

View File

@ -61,6 +61,9 @@ class AccessLogsController extends AppController
if (empty(Configure::read('MISP.log_skip_access_logs_in_application_logs'))) {
$this->Flash->warning(__('Access logs are logged in both application logs and access logs. Make sure you reconfigure your log monitoring tools and update MISP.log_skip_access_logs_in_application_logs.'));
}
$this->AccessLog->virtualFields['has_query_log'] = 'query_log IS NOT NULL';
$this->paginate['fields'][] = 'has_query_log';
$this->paginate['conditions'] = $conditions;
$list = $this->paginate();
@ -102,6 +105,23 @@ class AccessLogsController extends AppController
$this->set('request', $data);
}
public function admin_queryLog($id)
{
$request = $this->AccessLog->find('first', [
'conditions' => ['AccessLog.id' => $id],
'fields' => ['AccessLog.query_log'],
]);
if (empty($request)) {
throw new NotFoundException(__('Access log not found'));
}
if (empty($request['AccessLog']['query_log'])) {
throw new NotFoundException(__('Query log is empty'));
}
$this->set('queryLog', $request['AccessLog']['query_log']);
}
/**
* @param array $params
* @return array

View File

@ -396,6 +396,7 @@ class ACLComponent extends Component
'accessLogs' => [
'admin_index' => [],
'admin_request' => [],
'admin_queryLog' => [],
],
'modules' => array(
'index' => array('perm_auth'),

View File

@ -57,6 +57,9 @@ class AccessLog extends AppModel
$result['AccessLog']['request'] = false;
}
}
if (!empty($result['AccessLog']['query_log'])) {
$result['AccessLog']['query_log'] = JsonTool::decode($this->decompress($result['AccessLog']['query_log']));
}
if (!empty($result['AccessLog']['memory_usage'])) {
$result['AccessLog']['memory_usage'] = $result['AccessLog']['memory_usage'] * 1024;
}
@ -90,8 +93,12 @@ class AccessLog extends AppModel
$accessLog['request_method'] = $requestMethodIds[$accessLog['request_method']] ?? 0;
}
if (isset($accessLog['request'])) {
$accessLog['request'] = $this->encodeRequest($accessLog['request']);
if (!empty($accessLog['request'])) {
$accessLog['request'] = $this->compress($accessLog['request']);
}
if (!empty($accessLog['query_log'])) {
$accessLog['query_log'] = $this->compress(JsonTool::encode($accessLog['query_log']));
}
// In database save size in kb to avoid overflow signed int type
@ -113,6 +120,11 @@ class AccessLog extends AppModel
$requestTime = $_SERVER['REQUEST_TIME_FLOAT'] ?? microtime(true);
$now = DateTime::createFromFormat('U.u', $requestTime);
$logClientIp = Configure::read('MISP.log_client_ip');
$includeSqlQueries = Configure::read('MISP.log_paranoid_include_sql_queries');
if ($includeSqlQueries) {
$this->getDataSource()->fullDebug = true; // Enable SQL logging
}
$dataToSave = [
'created' => $now->format('Y-m-d H:i:s.u'),
@ -133,9 +145,9 @@ class AccessLog extends AppModel
}
// Save data on shutdown
register_shutdown_function(function () use ($dataToSave, $requestTime) {
register_shutdown_function(function () use ($dataToSave, $requestTime, $includeSqlQueries) {
session_write_close(); // close session to allow concurrent requests
$this->saveOnShutdown($dataToSave, $requestTime);
$this->saveOnShutdown($dataToSave, $requestTime, $includeSqlQueries);
});
return true;
@ -162,12 +174,23 @@ class AccessLog extends AppModel
/**
* @param array $data
* @param float $requestTime
* @param bool $includeSqlQueries
* @return bool
* @throws Exception
*/
private function saveOnShutdown(array $data, $requestTime)
private function saveOnShutdown(array $data, $requestTime, $includeSqlQueries)
{
$queryCount = $this->getDataSource()->getLog(false, false)['count'];
$sqlLog = $this->getDataSource()->getLog(false, false);
$queryCount = $sqlLog['count'];
if ($includeSqlQueries && !empty($sqlLog['log'])) {
foreach ($sqlLog['log'] as &$log) {
$log['query'] = $this->escapeNonUnicode($log['query']);
unset($log['affected']); // affected is the same as numRows
unset($log['params']); // no need to save for your use case
}
$data['query_log'] = ['time' => $sqlLog['time'], 'log' => $sqlLog['log']];
}
$data['response_code'] = http_response_code();
$data['memory_usage'] = memory_get_peak_usage();
@ -198,21 +221,15 @@ class AccessLog extends AppModel
/**
* @param string $request
* @return array|bool
* @return array|false
*/
private function decodeRequest($request)
{
$header = substr($request, 0, 4);
if ($header === self::BROTLI_HEADER) {
if (function_exists('brotli_uncompress')) {
$request = brotli_uncompress(substr($request, 4));
if ($request === false) {
return false;
}
} else {
return false;
}
$request = $this->decompress($request);
if ($request === false) {
return false;
}
list($contentType, $encoding, $data) = explode("\n", $request, 3);
if ($encoding === 'gzip') {
@ -229,17 +246,69 @@ class AccessLog extends AppModel
}
/**
* @param string $request
* @param string $data
* @return false|string
*/
private function decompress($data)
{
$header = substr($data, 0, 4);
if ($header === self::BROTLI_HEADER) {
if (function_exists('brotli_uncompress')) {
$data = brotli_uncompress(substr($data, 4));
if ($data === false) {
return false;
}
} else {
return false;
}
}
return $data;
}
/**
* @param string $data
* @return string
*/
private function encodeRequest($request)
private function compress($data)
{
$compressionEnabled = Configure::read('MISP.log_new_audit_compress') &&
function_exists('brotli_compress');
if ($compressionEnabled && strlen($request) >= self::COMPRESS_MIN_LENGTH) {
return self::BROTLI_HEADER . brotli_compress($request, 4, BROTLI_TEXT);
if ($compressionEnabled && strlen($data) >= self::COMPRESS_MIN_LENGTH) {
return self::BROTLI_HEADER . brotli_compress($data, 4, BROTLI_TEXT);
}
return $request;
return $data;
}
/**
* @param $string
* @return string
*/
private function escapeNonUnicode($string)
{
if (json_encode($string, JSON_UNESCAPED_SLASHES | JSON_UNESCAPED_UNICODE | JSON_UNESCAPED_LINE_TERMINATORS) !== false) {
return $string; // string is valid unicode
}
if (function_exists('mb_str_split')) {
$result = mb_str_split($string);
} else {
$result = [];
$length = mb_strlen($string);
for ($i = 0; $i < $length; $i++) {
$result[] = mb_substr($string, $i, 1);
}
}
$string = '';
foreach ($result as $char) {
if (strlen($char) === 1 && !preg_match('/[[:print:]]/', $char)) {
$string .= '\x' . bin2hex($char);
} else {
$string .= $char;
}
}
return $string;
}
}

View File

@ -83,7 +83,7 @@ class AppModel extends Model
81 => false, 82 => false, 83 => false, 84 => false, 85 => false, 86 => false,
87 => false, 88 => false, 89 => false, 90 => false, 91 => false, 92 => false,
93 => false, 94 => false, 95 => true, 96 => false, 97 => true, 98 => false,
99 => false, 100 => false, 101 => false, 102 => false, 103 => false,
99 => false, 100 => false, 101 => false, 102 => false, 103 => false, 104 => false,
);
const ADVANCED_UPDATES_DESCRIPTION = array(
@ -1926,6 +1926,9 @@ class AppModel extends Model
case 103:
$sqlArray[] = "ALTER TABLE `taxonomies` ADD `highlighted` tinyint(1) DEFAULT 0;";
break;
case 104:
$sqlArray[] = "ALTER TABLE `access_logs` ADD `query_log` blob DEFAULT NULL";
break;
case 'fixNonEmptySharingGroupID':
$sqlArray[] = 'UPDATE `events` SET `sharing_group_id` = 0 WHERE `distribution` != 4;';
$sqlArray[] = 'UPDATE `attributes` SET `sharing_group_id` = 0 WHERE `distribution` != 4;';

View File

@ -5539,7 +5539,7 @@ class Server extends AppModel
),
'log_client_ip_header' => array(
'level' => 1,
'description' => __('If log_client_ip is enabled, you can customize which header field contains the client\'s IP address. This is generally used when you have a reverse proxy infront of your MISP instance.'),
'description' => __('If log_client_ip is enabled, you can customize which header field contains the client\'s IP address. This is generally used when you have a reverse proxy in front of your MISP instance.'),
'value' => 'REMOTE_ADDR',
'test' => 'testForEmpty',
'type' => 'string',
@ -5595,7 +5595,7 @@ class Server extends AppModel
),
'log_paranoid_skip_db' => array(
'level' => 0,
'description' => __('You can decide to skip the logging of the paranoid logs to the database.'),
'description' => __('You can decide to skip the logging of the paranoid logs to the database. Logs will be just published to ZMQ or Kafka.'),
'value' => false,
'test' => 'testParanoidSkipDb',
'type' => 'boolean',
@ -5609,6 +5609,14 @@ class Server extends AppModel
'type' => 'boolean',
'null' => true
),
'log_paranoid_include_sql_queries' => [
'level' => 0,
'description' => __('If paranoid logging is enabled, include the SQL queries in the entries.'),
'value' => false,
'test' => 'testBool',
'type' => 'boolean',
'null' => true
],
'log_user_ips' => array(
'level' => 0,
'description' => __('Log user IPs on each request. 30 day retention for lookups by IP to get the last authenticated user ID for the given IP, whilst on the reverse, indefinitely stores all associated IPs for a user ID.'),

View File

@ -315,13 +315,14 @@
</td>
<td class="short" data-search="request_method" data-search-value="<?= h($item['AccessLog']['request_method']) ?>">
<?= h($item['AccessLog']['request_method']) ?>
<?= in_array($item['AccessLog']['request_method'], ['POST', 'PUT']) ? ' <a href="#" class="far fa-file request" data-log-id="' . h($item['AccessLog']['id']) . '"></i>' : '' ?>
<?= in_array($item['AccessLog']['request_method'], ['POST', 'PUT']) ? ' <a href="#" class="far fa-file request" title="' . __('Show HTTP request') . '" data-log-id="' . h($item['AccessLog']['id']) . '"></i>' : '' ?>
</td>
<td class="short" data-search="controller:action" data-search-value="<?= h($item['AccessLog']['controller']) . ':' . h($item['AccessLog']['action']) ?>" title="<?= __('Controller: %s, action: %s', h($item['AccessLog']['controller']), h($item['AccessLog']['action'])) ?>"><?= h($item['AccessLog']['url']) ?></td>
<td class="short" data-search="response_code" data-search-value="<?= h($item['AccessLog']['response_code']) ?>"><?= h($item['AccessLog']['response_code']) ?></td>
<td class="short"><?= CakeNumber::toReadableSize($item['AccessLog']['memory_usage']) ?></td>
<td class="short"><?= $item['AccessLog']['duration'] ?> ms</td>
<td class="short"><?= $item['AccessLog']['query_count'] ?></td>
<td class="short"><?= $item['AccessLog']['query_count'] . ($item['AccessLog']['has_query_log'] ? ' <a href="#" class="fas fa-database query-log" title="' . __('Show SQL queries') . '" data-log-id="' . h($item['AccessLog']['id']) . '"></i>' : '') ?>
</td>
</tr>
<?php endforeach; ?>
</table>
@ -347,6 +348,17 @@
return false;
});
$('.query-log').click(function (e) {
e.preventDefault();
var id = $(this).data('log-id');
$.get(baseurl + "/admin/access_logs/queryLog/" + id, function(data) {
var $popoverFormLarge = $('#popover_form_large');
$popoverFormLarge.html(data);
openPopup($popoverFormLarge);
}).fail(xhrFailCallback);
return false;
});
$(function() {
filterSearch(function (e, searchKey, searchValue) {
if (searchKey === 'controller:action') {

View File

@ -0,0 +1,14 @@
<table class="table table-striped table-hover table-condensed">
<tr>
<th><?= __('Query') ?></th>
<th><?= __('Num. rows') ?></th>
<th><?= __('Took (ms)') ?></th>
</tr>
<?php foreach ($queryLog['log'] as $query): ?>
<tr>
<td><?= h($query['query']) ?></td>
<td><?= h($query['numRows']) ?></td>
<td><?= h($query['took']) ?></td>
</tr>
<?php endforeach; ?>
</table>

View File

@ -1035,7 +1035,6 @@ a.black-white:hover {
left:calc(50% - 350px);
position: fixed;
background-color:#f4f4f4;
border-radius: 11px 11px 10px 10px;
box-shadow: 4px 4px 4px #333;
z-index:5;
}