Skip to content

Commit

Permalink
[TASK] Improve logging for Indexer database actions, closes #59
Browse files Browse the repository at this point in the history 
Additionally, fix the "debugOnly"
parameter for inserting or updating.
This had no effect other
than outputting the result of the
query. Also, a different database
method had been used than the one
which would actually insert or
update the record. This has now been
fixed. If the debugOnly parameter is
set, now inserting or updating is
skipped and only the values are logged
(if LogLevel is set to "Debug").

Additionally, a part of the
errors is directly shown in
the indexing report.
  • Loading branch information
@christianbltr
christianbltr committed May 3, 2024
1 parent 30cbcde commit 448a464
Show file tree
Hide file tree
Showing 3 changed files with 143 additions and 88 deletions.
1 change: 1 addition & 0 deletions ChangeLog
View file
Original file line number Diff line number Diff line change
Expand Up @@ -4,6 +4,7 @@ Upcoming version
[FEATURE] Add pagination in the backend module "Indexed content" function and avoid out of memory error. https://github.com/tpwd/ke_search/issues/100
[TASK] Add BEGIN and COMMIT statements needed to run ke_search in a Percona-Database-Cluster with strict-mode. Thanks to rentz-skygate. https://github.com/tpwd/ke_search/issues/222
[BUGFIX] Render file preview in result list only for files which are in the "imagefile_ext" list (images and PDF files). https://github.com/tpwd/ke_search/issues/60
[TASK] Improve logging for Indexer database actions and output errors in indexing report. https://github.com/tpwd/ke_search/issues/59

Version 5.4.1, 19 April 2024
[BUGFIX] Always remove duplicates from tags, not only when a tag is set in the indexer configuration. https://github.com/tpwd/ke_search/issues/211
Expand Down
227 changes: 141 additions & 86 deletions Classes/Indexer/IndexerRunner.php
View file
Original file line number Diff line number Diff line change
Expand Up @@ -36,7 +36,6 @@
use TYPO3\CMS\Core\Log\Logger;
use TYPO3\CMS\Core\Log\LogManager;
use TYPO3\CMS\Core\Mail\MailMessage;
use TYPO3\CMS\Core\Utility\DebugUtility;
use TYPO3\CMS\Core\Utility\GeneralUtility;
use TYPO3\CMS\Core\Utility\StringUtility;

Expand Down Expand Up @@ -209,6 +208,7 @@ public function startIndexing($verbose = true, array $_unused = [], $mode = '',
$message .= $searchObj->startIndexing();
}
}
$this->checkIfIndexerHadErrors($searchObj);
$content .= $this->renderIndexingReport($searchObj, $message);
} else {
$errorMessage = 'Could not find class ' . $className;
Expand All @@ -232,6 +232,7 @@ public function startIndexing($verbose = true, array $_unused = [], $mode = '',
} else {
$message = $searchObj->startIncrementalIndexing($indexerConfig, $this);
}
$this->checkIfIndexerHadErrors($searchObj);
if ($message) {
$content .= $this->renderIndexingReport($searchObj, $message);
}
Expand All @@ -254,16 +255,30 @@ public function startIndexing($verbose = true, array $_unused = [], $mode = '',
$indexingTime = $this->endTime - $this->startTime;
$content .= '<div class="alert alert-success">';
$content .= chr(10) . '<h3>Finished</h3>' . chr(10);

$message = 'Indexing finished at ' . SearchHelper::formatTimestamp($this->endTime) . ' (took ' . $this->formatTime($indexingTime) . ').';
$content .= $message;
$this->logger->info($message);

$message = '<br />Index contains ' . $this->indexRepository->getTotalNumberOfRecords() . ' entries.';
$content .= $message;
$this->logger->info($message);
$content .= '</div>' . chr(10);

// check if there have been errors during indexing and output them
if (count($this->indexingErrors)) {
$content .= '<div class="alert alert-warning">';
$content .= chr(10) . '<h3>Errors</h3>' . chr(10);
$content .= '<p>There have been errors during the indexing process.</p>';
$content .= '<p>As a hint here\'s a small part of the errors.</p>';
$errorMessageSlices = array_slice(array_unique($this->indexingErrors), 0, 20);
$content .= '<ul>';
foreach ($errorMessageSlices as $errorMessage) {
$content .= '<li>' . htmlspecialchars($errorMessage, ENT_QUOTES, 'UTF-8') . '</li>' . chr(10);
}
$content .= '</ul>';
$content .= '<p>Please refer to the error log (typically in var/log/ of your TYPO3 installation) for the full list of errors.</p>';
$content .= '</div>';
}

$content .= '</div>';
$content .= '</div></div>';

$this->indexerStatusService->setLastRunTime($this->startTime, $this->endTime, $indexingTime);
Expand Down Expand Up @@ -327,7 +342,7 @@ public function renderIndexingReport($searchObj, $message = '')

// indexing mode
$content .= '<td>';
if (is_subclass_of($searchObj, '\Tpwd\KeSearch\Indexer\IndexerBase')) {
if (is_subclass_of($searchObj, IndexerBase::class)) {
if (method_exists($searchObj, 'getIndexingMode')) {
if ($searchObj->getIndexingMode() == IndexerBase::INDEXING_MODE_INCREMENTAL) {
$content .= '<span class="indexingMode">Incremental mode</span>';
Expand All @@ -342,19 +357,11 @@ public function renderIndexingReport($searchObj, $message = '')
$content .= '<td>';
$content .= nl2br(htmlspecialchars($message, ENT_QUOTES, 'UTF-8'));

// errors
if (is_subclass_of($searchObj, '\Tpwd\KeSearch\Indexer\IndexerBase')) {
$errors = method_exists($searchObj, 'getErrors') ? $searchObj->getErrors() : [];
if (count($errors)) {
$content .= '<p class="badge badge-warning">Warning: There have been errors. Please refer to the error log (typically in var/log/)</p>';
}
}

$content .= '</td>' . chr(10);

// duration, show sec or ms
$content .= '<td>';
if (is_subclass_of($searchObj, '\Tpwd\KeSearch\Indexer\IndexerBase')) {
if (is_subclass_of($searchObj, IndexerBase::class)) {
$duration = method_exists($searchObj, 'getDuration') ? $searchObj->getDuration() : 0;
if ($duration > 0) {
$content .= '<i>Indexing process took ';
Expand Down Expand Up @@ -432,51 +439,75 @@ public function prepareStatements()

// Statement to check if record already exists in db
$databaseConnection = Db::getDatabaseConnection('tx_kesearch_index');
$databaseConnection->exec('PREPARE searchStmt FROM "
SELECT *
FROM tx_kesearch_index
WHERE orig_uid = ?
AND pid = ?
AND type = ?
AND language = ?
LIMIT 1
"');
try {
$databaseConnection->executeStatement('PREPARE searchStmt FROM "
SELECT *
FROM tx_kesearch_index
WHERE orig_uid = ?
AND pid = ?
AND type = ?
AND language = ?
LIMIT 1
"');
} catch (Exception $e) {
$errorMessage = 'Error while preparing searchStmt: ' . $e->getMessage();
$this->logger->error($errorMessage);
$this->indexingErrors[] = $errorMessage;
}

// Statement to update an existing record in indexer table
$databaseConnection = Db::getDatabaseConnection('tx_kesearch_index');
$databaseConnection->exec('PREPARE updateStmt FROM "
UPDATE tx_kesearch_index
SET pid=?,
title=?,
type=?,
targetpid=?,
content=?,
tags=?,
params=?,
abstract=?,
language=?,
starttime=?,
endtime=?,
fe_group=?,
tstamp=?' . $addUpdateQuery . '
WHERE uid=?
"');
try {
$databaseConnection->executeStatement('PREPARE updateStmt FROM "
UPDATE tx_kesearch_index
SET pid=?,
title=?,
type=?,
targetpid=?,
content=?,
tags=?,
params=?,
abstract=?,
language=?,
starttime=?,
endtime=?,
fe_group=?,
tstamp=?' . $addUpdateQuery . '
WHERE uid=?
"');
} catch (Exception $e) {
$errorMessage = 'Error while preparing updateStmt: ' . $e->getMessage();
$this->logger->error($errorMessage);
$this->indexingErrors[] = $errorMessage;
}

// Statement to insert a new records to index table
$databaseConnection = Db::getDatabaseConnection('tx_kesearch_index');
$databaseConnection->exec('PREPARE insertStmt FROM "
INSERT INTO tx_kesearch_index
(pid, title, type, targetpid, content, tags, params, abstract, language,'
. ' starttime, endtime, fe_group, tstamp, crdate' . $addInsertQueryFields . ')
VALUES(?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?' . $addInsertQueryValues . ', ?)
"');
try {
$databaseConnection->executeStatement('PREPARE insertStmt FROM "
INSERT INTO tx_kesearch_index
(pid, title, type, targetpid, content, tags, params, abstract, language,'
. ' starttime, endtime, fe_group, tstamp, crdate' . $addInsertQueryFields . ')
VALUES(?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?' . $addInsertQueryValues . ', ?)
"');
} catch (Exception $e) {
$errorMessage = 'Error while preparing insertStmt: ' . $e->getMessage();
$this->logger->error($errorMessage);
$this->indexingErrors[] = $errorMessage;
}

// disable keys only if indexer table was truncated (has 0 records)
// this speeds up the first indexing process
// don't use this for updating index table
// if you activate this for updating 40.000 existing records, indexing process needs 1 hour longer
if ($this->indexRepository->getTotalNumberOfRecords() == 0) {
Db::getDatabaseConnection('tx_kesearch_index')->exec('ALTER TABLE tx_kesearch_index DISABLE KEYS');
try {
Db::getDatabaseConnection('tx_kesearch_index')->executeStatement('ALTER TABLE tx_kesearch_index DISABLE KEYS');
} catch (Exception $e) {
$errorMessage = 'Error while disabling keys: ' . $e->getMessage();
$this->logger->error($errorMessage);
$this->indexingErrors[] = $errorMessage;
}
}
}

Expand All @@ -486,17 +517,41 @@ public function prepareStatements()
public function cleanUpProcessAfterIndexing()
{
// enable keys (may have been disabled because it was the first indexing)
Db::getDatabaseConnection('tx_kesearch_index')
->exec('ALTER TABLE tx_kesearch_index ENABLE KEYS');
try {
Db::getDatabaseConnection('tx_kesearch_index')
->executeStatement('ALTER TABLE tx_kesearch_index ENABLE KEYS');
} catch (Exception $e) {
$errorMessage = 'Error while enabling keys: ' . $e->getMessage();
$this->logger->error($errorMessage);
$this->indexingErrors[] = $errorMessage;
}

Db::getDatabaseConnection('tx_kesearch_index')
->exec('DEALLOCATE PREPARE searchStmt');
try {
Db::getDatabaseConnection('tx_kesearch_index')
->executeStatement('DEALLOCATE PREPARE searchStmt');
} catch (Exception $e) {
$errorMessage = 'Error while deallocating searchStmt: ' . $e->getMessage();
$this->logger->error($errorMessage);
$this->indexingErrors[] = $errorMessage;
}

Db::getDatabaseConnection('tx_kesearch_index')
->exec('DEALLOCATE PREPARE updateStmt');
try {
Db::getDatabaseConnection('tx_kesearch_index')
->executeStatement('DEALLOCATE PREPARE updateStmt');
} catch (Exception $e) {
$errorMessage = 'Error while deallocating updateStmt: ' . $e->getMessage();
$this->logger->error($errorMessage);
$this->indexingErrors[] = $errorMessage;
}

Db::getDatabaseConnection('tx_kesearch_index')
->exec('DEALLOCATE PREPARE insertStmt');
try {
Db::getDatabaseConnection('tx_kesearch_index')
->executeStatement('DEALLOCATE PREPARE insertStmt');
} catch (Exception $e) {
$errorMessage = 'Error while deallocating insertStmt: ' . $e->getMessage();
$this->logger->error($errorMessage);
$this->indexingErrors[] = $errorMessage;
}

$this->indexerStatusService->clearAll();
}
Expand Down Expand Up @@ -545,7 +600,7 @@ public function cleanUpIndex(int $indexingMode)
->where($where)
->executeStatement();

$content .= '<strong>' . $count . '</strong> entries deleted.' . "<br />\n";
$content .= '<strong>' . $count . '</strong> entries deleted.' . '<br />';
$this->logger->info('CleanUpIndex: ' . $count . ' entries deleted.');

// rotate Sphinx Index (ke_search_premium function)
Expand Down Expand Up @@ -770,45 +825,29 @@ public function storeInIndex(
}

if ($recordExists) { // update existing record
$where = 'uid=' . (int)($this->currentRow['uid']);
unset($fieldValues['crdate']);
if ($debugOnly) { // do not process - just debug query
DebugUtility::debug(
(string)Db::getDatabaseConnection($table)
->update(
$table,
$fieldValues,
['uid' => (int)($this->currentRow['uid'])]
)
);
} else { // process storing of index record and return true
$this->updateRecordInIndex($fieldValues);
return true;
}
} else { // insert new record
if ($debugOnly) { // do not process - just debug query
DebugUtility::debug(
(string)Db::getDatabaseConnection($table)
->insert(
$table,
$fieldValues
)
);
} else { // process storing of index record and return uid
$this->insertRecordIntoIndex($fieldValues);
return (int)Db::getDatabaseConnection('tx_kesearch_index')->lastInsertId($table);
}
$this->updateRecordInIndex($fieldValues, $debugOnly);
return true;
} // insert new record
$this->insertRecordIntoIndex($fieldValues, $debugOnly);
if (!$debugOnly) {
return (int)Db::getDatabaseConnection('tx_kesearch_index')->lastInsertId($table);
}

return 0;
}

/**
* inserts a new record into the index using a prepared statement
* @param $fieldValues array
*/
public function insertRecordIntoIndex($fieldValues)
public function insertRecordIntoIndex($fieldValues, bool $debugOnly = false)
{
$this->logger->debug('Inserting: ' . json_encode($this->getDebugValuesFromFieldValues($fieldValues)));
if ($debugOnly) {
$this->logger->debug('Not executing (debugOnly is activated)');
return;
}
$queryBuilder = Db::getQueryBuilder('tx_kesearch_index');
$addQueryPartFor = $this->getQueryPartForAdditionalFields($fieldValues);

Expand Down Expand Up @@ -855,16 +894,21 @@ public function insertRecordIntoIndex($fieldValues)
Db::getDatabaseConnection('tx_kesearch_index')->executeStatement('COMMIT;');
} catch (Exception $e) {
$this->logger->error($e->getMessage());
$this->indexingErrors[] = $e->getMessage();
}
}

/**
* updates a record in the index using a prepared statement
* @param $fieldValues
*/
public function updateRecordInIndex($fieldValues)
public function updateRecordInIndex($fieldValues, bool $debugOnly = false)
{
$this->logger->debug('Updating: ' . json_encode($this->getDebugValuesFromFieldValues($fieldValues)));
if ($debugOnly) {
$this->logger->debug('Not executing (debugOnly is activated)');
return;
}
$queryBuilder = Db::getQueryBuilder('tx_kesearch_index');
$addQueryPartFor = $this->getQueryPartForAdditionalFields($fieldValues);

Expand Down Expand Up @@ -912,6 +956,7 @@ public function updateRecordInIndex($fieldValues)
} catch (Exception $e) {
// @extensionScannerIgnoreLine
$this->logger->error($e->getMessage());
$this->indexingErrors[] = $e->getMessage();
}
}

Expand Down Expand Up @@ -1128,7 +1173,7 @@ public function checkIfRecordHasErrorsBeforeIndexing($storagePid, $title, $type,
$errormessage .= 'STORAGE PID: ' . $storagePid . '; ';
}
$this->logger->error($errormessage);
$this->indexingErrors[] = ' (' . $errormessage . ')';
$this->indexingErrors[] = $errormessage;

// break indexing and wait for next record to store
return false;
Expand Down Expand Up @@ -1212,4 +1257,14 @@ public function setConsoleIo(SymfonyStyle $io): void
$this->io = $io;
$this->indexerStatusService->setConsoleIo($io);
}

protected function checkIfIndexerHadErrors($searchObj)
{
if (is_subclass_of($searchObj, IndexerBase::class)) {
$errors = method_exists($searchObj, 'getErrors') ? $searchObj->getErrors() : [];
if (count($errors)) {
$this->indexingErrors = array_merge($this->indexingErrors, $errors);
}
}
}
}
3 changes: 1 addition & 2 deletions Classes/Indexer/Types/Page.php
View file
Original file line number Diff line number Diff line change
Expand Up @@ -159,7 +159,6 @@ class Page extends IndexerBase
protected IndexerStatusService $indexerStatusService;

/**
* tx_kesearch_indexer_types_page constructor.
* @param IndexerRunner $pObj
*/
public function __construct($pObj)
Expand Down Expand Up @@ -765,7 +764,7 @@ public function getPageContent($uid)
foreach ($pageContent as $language_uid => $content) {
$pageTitle = $this->cachedPageRecords[$language_uid][$uid]['title'] ?? '[empty title]';
if (!$pageAccessRestrictions['hidden'] && $this->checkIfpageShouldBeIndexed($uid, $language_uid)) {
$this->pObj->logger->debug('Indexing page ' . $pageTitle . ' (UID ' . $uid . ', L ' . $language_uid . ')');
$this->pObj->logger->debug('Indexing page "' . $pageTitle . '" (UID ' . $uid . ', L ' . $language_uid . ')');
// overwrite access restrictions with language overlay values
$accessRestrictionsLanguageOverlay = $pageAccessRestrictions;
$pageAccessRestrictions['fe_group'] = $indexEntryDefaultValues['feGroupsPages'];
Expand Down

0 comments on commit 448a464

Please sign in to comment.