Merge pull request #9651 from JakubOnderka/server-sync-debug

Server sync debug
pull/9685/head
Jakub Onderka 2024-04-14 15:38:57 +02:00 committed by GitHub
commit df7ff3d4cd
No known key found for this signature in database
GPG Key ID: B5690EEEBB952194
10 changed files with 63 additions and 25 deletions

View File

@ -269,13 +269,16 @@ jobs:
- name: Check requirements.txt
run: python tests/check_requirements.py
- name: Logs
- name: System logs
if: ${{ always() }}
# update logs_test.sh when adding more logsources here
run: |
tail -n +1 `pwd`/app/tmp/logs/*
tail -n +1 /var/log/apache2/*.log
- name: Application logs
if: ${{ always() }}
run: |
app/Console/cake Log export /tmp/logs.json.gz --without-changes
zcat /tmp/logs.json.gz

View File

@ -145,6 +145,10 @@ class ServerShell extends AppShell
if (!empty($this->args[4]) && $this->args[4] === 'force') {
$force = true;
}
// Try to enable garbage collector as pulling events can use a lot of memory
gc_enable();
try {
$result = $this->Server->pull($user, $technique, $server, $jobId, $force);
if (is_array($result)) {

View File

@ -24,7 +24,7 @@ class HttpSocketHttpException extends Exception
$message .= " for URL $url";
}
if ($response->body) {
$message .= ': ' . substr($response->body, 0, 100);
$message .= ': ' . substr(ltrim($response->body), 0, 100);
}
parent::__construct($message, (int)$response->code);

View File

@ -506,6 +506,16 @@ class ServerSyncTool
return $this->socket->getMetaData();
}
/**
* @param string $message
* @return void
*/
public function debug($message)
{
$memoryUsage = round(memory_get_usage() / 1024 / 1024, 2);
CakeLog::debug("[Server sync #{$this->serverId()}]: $message. Memory: $memoryUsage MB");
}
/**
* @params string $url Relative URL
* @return HttpSocketResponseExtended
@ -556,6 +566,7 @@ class ServerSyncTool
if ($etag) {
// Remove compression marks that adds Apache for compressed content
// This can be removed in future as this is already checked by MISP itself since 2024-03
$etagWithoutQuotes = trim($etag, '"');
$dashPos = strrpos($etagWithoutQuotes, '-');
if ($dashPos && in_array(substr($etagWithoutQuotes, $dashPos + 1), ['br', 'gzip'], true)) {

View File

@ -1,7 +1,6 @@
<?php
class SyncTool
{
const ALLOWED_CERT_FILE_EXTENSIONS = ['pem', 'crt'];
/**

View File

@ -641,9 +641,8 @@ class AnalystData extends AppModel
return [];
}
$this->Server = ClassRegistry::init('Server');
$this->AnalystData = ClassRegistry::init('AnalystData');
$this->log("Starting Analyst Data sync with server #{$server['Server']['id']}", LOG_INFO);
$serverSync->debug("Starting Analyst Data sync");
$analystData = $this->collectDataForPush($serverSync->server());
$keyedAnalystData = [];
@ -1018,7 +1017,6 @@ class AnalystData extends AppModel
}
$this->Server = ClassRegistry::init('Server');
$this->AnalystData = ClassRegistry::init('AnalystData');
try {
$filterRules = $this->buildPullFilterRules($serverSync->server());
$remoteData = $serverSync->fetchIndexMinimal($filterRules)->json();

View File

@ -1845,6 +1845,9 @@ class GalaxyCluster extends AppModel
if (!$compatible) {
return 0;
}
$serverSync->debug("Pulling galaxy clusters with technique $technique");
$clusterIds = $this->getClusterIdListBasedOnPullTechnique($user, $technique, $serverSync);
$successes = 0;
// now process the $clusterIds to pull each of the events sequentially

View File

@ -604,6 +604,7 @@ class Server extends AppModel
* @throws HttpSocketHttpException
* @throws HttpSocketJsonException
* @throws JsonException
* @throws Exception
*/
public function pull(array $user, $technique, array $server, $jobId = false, $force = false)
{
@ -619,7 +620,7 @@ class Server extends AppModel
try {
$server['Server']['version'] = $serverSync->info()['version'];
} catch (Exception $e) {
$this->logException("Could not get remote server `{$server['Server']['name']}` version.", $e);
$this->logException("Could not get remote server `{$serverSync->serverName()}` version.", $e);
if ($e instanceof HttpSocketHttpException && $e->getCode() === 403) {
$message = __('Not authorised. This is either due to an invalid auth key, or due to the sync user not having authentication permissions enabled on the remote server. Another reason could be an incorrect sync server setting.');
} else {
@ -648,6 +649,8 @@ class Server extends AppModel
}
}
$serverSync->debug("Pulling event list with technique $technique");
try {
$eventIds = $this->__getEventIdListBasedOnPullTechnique($technique, $serverSync, $force);
} catch (Exception $e) {
@ -673,26 +676,29 @@ class Server extends AppModel
$job->saveProgress($jobId, __n('Pulling %s event.', 'Pulling %s events.', count($eventIds), count($eventIds)));
}
foreach ($eventIds as $k => $eventId) {
$serverSync->debug("Pulling event $eventId");
$this->__pullEvent($eventId, $successes, $fails, $eventModel, $serverSync, $user, $jobId, $force);
if ($jobId && $k % 10 === 0) {
$job->saveProgress($jobId, null, 10 + 40 * (($k + 1) / count($eventIds)));
}
}
foreach ($fails as $eventid => $message) {
$this->loadLog()->createLogEntry($user, 'pull', 'Server', $server['Server']['id'], "Failed to pull event #$eventid.", 'Reason: ' . $message);
$this->loadLog()->createLogEntry($user, 'pull', 'Server', $serverSync->serverId(), "Failed to pull event #$eventid.", 'Reason: ' . $message);
}
}
if ($jobId) {
$job->saveProgress($jobId, 'Pulling proposals.', 50);
}
$pulledProposals = $pulledSightings = 0;
$pulledProposals = $pulledSightings = $pulledAnalystData = 0;
if ($technique === 'full' || $technique === 'update') {
$pulledProposals = $eventModel->ShadowAttribute->pullProposals($user, $serverSync);
if ($jobId) {
$job->saveProgress($jobId, 'Pulling sightings.', 75);
}
$pulledSightings = $eventModel->Sighting->pullSightings($user, $serverSync);
$this->AnalystData = ClassRegistry::init('AnalystData');
$pulledAnalystData = $this->AnalystData->pull($user, $serverSync);
}
@ -819,7 +825,7 @@ class Server extends AppModel
*/
public function getElligibleClusterIdsFromServerForPull(ServerSyncTool $serverSync, $onlyUpdateLocalCluster=true, array $eligibleClusters=array(), array $conditions=array())
{
$this->log("Fetching eligible clusters from server #{$serverSync->serverId()} for pull: " . JsonTool::encode($conditions), LOG_INFO);
$serverSync->debug("Fetching eligible clusters for pull: " . JsonTool::encode($conditions));
if ($onlyUpdateLocalCluster && empty($eligibleClusters)) {
return []; // no clusters for update
@ -875,7 +881,7 @@ class Server extends AppModel
*/
private function getElligibleClusterIdsFromServerForPush(ServerSyncTool $serverSync, array $localClusters=array(), array $conditions=array())
{
$this->log("Fetching eligible clusters from server #{$serverSync->serverId()} for push: " . JsonTool::encode($conditions), LOG_INFO);
$serverSync->debug("Fetching eligible clusters for push: " . JsonTool::encode($conditions));
$clusterArray = $this->fetchCustomClusterIdsFromServer($serverSync, $conditions=$conditions);
$keyedClusterArray = Hash::combine($clusterArray, '{n}.GalaxyCluster.uuid', '{n}.GalaxyCluster.version');
if (!empty($localClusters)) {
@ -915,9 +921,14 @@ class Server extends AppModel
// Fetch event index from cache if exists and is not modified
$redis = RedisTool::init();
$indexFromCache = $redis->get("misp:event_index:{$serverSync->serverId()}");
$indexFromCache = $redis->get("misp:event_index_cache:{$serverSync->serverId()}");
if ($indexFromCache) {
list($etag, $eventIndex) = RedisTool::deserialize(RedisTool::decompress($indexFromCache));
$etagPos = strpos($indexFromCache, "\n");
if ($etagPos === false) {
throw new RuntimeException("Could not find etag in cache fro server {$serverSync->serverId()}");
}
$etag = substr($indexFromCache, 0, $etagPos);
$serverSync->debug("Event index loaded from Redis cache with etag $etag containing");
} else {
$etag = '""'; // Provide empty ETag, so MISP will compute ETag for returned data
}
@ -925,9 +936,21 @@ class Server extends AppModel
$response = $serverSync->eventIndex($filterRules, $etag);
if ($response->isNotModified() && $indexFromCache) {
return $eventIndex;
return JsonTool::decode(RedisTool::decompress(substr($indexFromCache, $etagPos + 1)));
}
// Save to cache for 24 hours if ETag provided
$etag = $response->getHeader('etag');
if ($etag) {
$serverSync->debug("Event index from remote server has different etag $etag, saving to cache");
$data = "$etag\n" . RedisTool::compress($response->body);
$redis->setex("misp:event_index_cache:{$serverSync->serverId()}", 3600 * 24, $data);
} elseif ($indexFromCache) {
RedisTool::unlink($redis, "misp:event_index_cache:{$serverSync->serverId()}");
}
unset($indexFromCache); // clean up memory
$eventIndex = $response->json();
// correct $eventArray if just one event, probably this response returns old MISP
@ -935,15 +958,6 @@ class Server extends AppModel
$eventIndex = [$eventIndex];
}
// Save to cache for 24 hours if ETag provided
$etag = $response->getHeader('etag');
if ($etag) {
$data = RedisTool::compress(RedisTool::serialize([$etag, $eventIndex]));
$redis->setex("misp:event_index:{$serverSync->serverId()}", 3600 * 24, $data);
} elseif ($indexFromCache) {
RedisTool::unlink($redis, "misp:event_index:{$serverSync->serverId()}");
}
return $eventIndex;
}
@ -1372,7 +1386,7 @@ class Server extends AppModel
return []; // pushing clusters is not enabled
}
$this->log("Starting $technique clusters sync with server #{$serverSync->serverId()}", LOG_INFO);
$serverSync->debug("Starting $technique clusters sync");
$this->GalaxyCluster = ClassRegistry::init('GalaxyCluster');
$this->Event = ClassRegistry::init('Event');

View File

@ -706,6 +706,8 @@ class ShadowAttribute extends AppModel
return 0;
}
$serverSync->debug("Pulling proposals");
$i = 1;
$fetchedCount = 0;
$chunkSize = 1000;

View File

@ -1418,11 +1418,13 @@ class Sighting extends AppModel
*/
public function pullSightings(array $user, ServerSyncTool $serverSync)
{
$serverSync->debug("Fetching event index for pulling sightings");
$this->Server = ClassRegistry::init('Server');
try {
$remoteEvents = $this->Server->getEventIndexFromServer($serverSync);
} catch (Exception $e) {
$this->logException("Could not fetch event IDs from server {$serverSync->server()['Server']['name']}", $e);
$this->logException("Could not fetch event IDs from server {$serverSync->serverName()}", $e);
return 0;
}
// Remove events from list that do not have published sightings.
@ -1452,6 +1454,8 @@ class Sighting extends AppModel
return 0;
}
$serverSync->debug("Pulling sightings for " . count($eventUuids) . " events");
if ($serverSync->isSupported(ServerSyncTool::FEATURE_SIGHTING_REST_SEARCH)) {
return $this->pullSightingNewWay($user, $eventUuids, $serverSync);
} else {