fix(#17): log count failures instead of swallowing them #21

Merged
KofTwentyTwo merged 2 commits from feature/GH-17-log-safecount into develop 2026-10-07 00:03:17 +00:00
6 changed files with 175 additions and 22 deletions

No files matched your search

@@ -217,7 +217,11 @@ public class BasepullIndexStep extends AbstractIndexingStep
{
Map<String, Serializable> values = new HashMap<>();
values.put("lastBasepullTime", runStart);
values.put("documentCount", safeCount(client, tableName));
Integer documentCount = ReconcileIndexStep.safeCount(client, tableName);
if(documentCount != null)
{
values.put("documentCount", documentCount);
}
updateIndexRow(index.getId(), values);
}
@@ -413,22 +417,4 @@ public class BasepullIndexStep extends AbstractIndexingStep
}
}
/*******************************************************************************
**
*******************************************************************************/
private static Integer safeCount(QuickSearchOpenSearchClient client, String tableName)
{
try
{
Long count = client.countDocumentsForTable(tableName);
return (count == null ? null : count.intValue());
}
catch(Exception e)
{
return (null);
}
}
}
@@ -150,7 +150,11 @@ public class FullReindexStep extends AbstractIndexingStep
values.put("lastFullReindexTime", Instant.now());
values.put("lastBasepullTime", startTimes.get(tableName));
values.put("recordCount", tableCounts.processed());
values.put("documentCount", ReconcileIndexStep.safeCount(client, tableName));
Integer documentCount = ReconcileIndexStep.safeCount(client, tableName);
if(documentCount != null)
{
values.put("documentCount", documentCount);
}
values.put("searchableFieldsJson", buildSearchableFieldsJson(tableConfig));
values.put("status", STATUS_ACTIVE);
updateIndexRow(runs.get(tableConfig).getQuickSearchIndexId(), values);
@@ -144,7 +144,11 @@ public class ReconcileIndexStep extends AbstractIndexingStep
values.put("lastReconcileTime", Instant.now());
values.put("lastBasepullTime", reconcileStart);
values.put("recordCount", counts.processed());
values.put("documentCount", safeCount(client, tableName));
Integer documentCount = safeCount(client, tableName);
if(documentCount != null)
{
values.put("documentCount", documentCount);
}
values.put("searchableFieldsJson", buildSearchableFieldsJson(tableConfig));
values.put("status", STATUS_ACTIVE);
if(ReconcileIndexStep.RUN_TYPE.equals(runType) == false)
@@ -191,7 +195,8 @@ public class ReconcileIndexStep extends AbstractIndexingStep
/*******************************************************************************
**
** Number of documents indexed for the table, or null when the count fails
** (logged), so callers keep the previous documentCount.
*******************************************************************************/
static Integer safeCount(QuickSearchOpenSearchClient client, String tableName)
{
@@ -202,6 +207,7 @@ public class ReconcileIndexStep extends AbstractIndexingStep
}
catch(Exception e)
{
LOG.warn("Could not count indexed documents for table; keeping the previous documentCount", e, logPair("tableName", tableName));
return (null);
}
}
@@ -30,6 +30,8 @@ import com.kingsrook.qqq.backend.core.actions.tables.QueryAction;
import com.kingsrook.qqq.backend.core.actions.tables.UpdateAction;
import com.kingsrook.qqq.backend.core.context.QContext;
import com.kingsrook.qqq.backend.core.exceptions.QException;
import com.kingsrook.qqq.backend.core.logging.QCollectingLogger;
import com.kingsrook.qqq.backend.core.logging.QLogger;
import com.kingsrook.qqq.backend.core.model.actions.processes.RunBackendStepInput;
import com.kingsrook.qqq.backend.core.model.actions.processes.RunBackendStepOutput;
import com.kingsrook.qqq.backend.core.model.actions.tables.delete.DeleteInput;
@@ -50,6 +52,7 @@ import com.kingsrook.qbits.quicksearch.model.QuickSearchIndexRun;
import com.kingsrook.qbits.quicksearch.opensearch.BulkIndexResult;
import com.kingsrook.qbits.quicksearch.opensearch.OpenSearchDocument;
import com.kingsrook.qbits.quicksearch.opensearch.QuickSearchOpenSearchClient;
import org.apache.logging.log4j.Level;
import org.junit.jupiter.api.BeforeEach;
import org.junit.jupiter.api.Test;
import org.mockito.ArgumentCaptor;
@@ -317,6 +320,53 @@ class BasepullIndexStepTest extends BaseQuickSearchTest
/*******************************************************************************
** Test: a failing document count is logged at WARN with the table name, and
** the run still completes, keeping the previous documentCount.
*******************************************************************************/
@Test
void testDocumentCountFails_loggedAsWarning_previousCountKept() throws QException
{
insertTestEntities(1);
QRecord indexRow = insertIndexRow(TEST_ENTITY_TABLE, true, null, 5);
UpdateInput seedInput = new UpdateInput();
seedInput.setTableName(QuickSearchIndex.TABLE_NAME);
seedInput.setRecords(List.of(new QRecord().withValue("id", indexRow.getValue("id")).withValue("documentCount", 99)));
new UpdateAction().execute(seedInput);
when(mockClient.countDocumentsForTable(TEST_ENTITY_TABLE)).thenThrow(new QException("count failed"));
//////////////////////////////////////////////////////////////////
// the count, and so its warning, belongs to ReconcileIndexStep //
//////////////////////////////////////////////////////////////////
QCollectingLogger collectingLogger = QLogger.activateCollectingLoggerForClass(ReconcileIndexStep.class);
try
{
new BasepullIndexStep().run(new RunBackendStepInput(), new RunBackendStepOutput());
}
finally
{
QLogger.deactivateCollectingLoggerForClass(ReconcileIndexStep.class);
}
assertThat(collectingLogger.getCollectedMessages())
.filteredOn(m -> Level.WARN.equals(m.getLevel()) && m.getMessage().contains("Could not count indexed documents"))
.singleElement()
.satisfies(m ->
{
assertThat(m.getMessage()).contains("\"tableName\":\"" + TEST_ENTITY_TABLE + "\"");
assertThat(m.getMessage()).contains("\"stackTrace\"").contains("count failed");
});
QRecord row = queryAll(QuickSearchIndex.TABLE_NAME).get(0);
assertThat(row.getValueString("lastRunStatus")).isEqualTo("BASEPULL COMPLETED");
assertThat(row.getValue("lastBasepullTime")).isNotNull();
assertThat(row.getValueInteger("documentCount")).isEqualTo(99);
}
/*******************************************************************************
** Test: index with a very recent lastBasepullTime and 60-minute interval is
** skipped (not yet due).
@@ -22,6 +22,8 @@ import java.util.List;
import com.kingsrook.qqq.backend.core.actions.tables.InsertAction;
import com.kingsrook.qqq.backend.core.actions.tables.QueryAction;
import com.kingsrook.qqq.backend.core.exceptions.QException;
import com.kingsrook.qqq.backend.core.logging.QCollectingLogger;
import com.kingsrook.qqq.backend.core.logging.QLogger;
import com.kingsrook.qqq.backend.core.model.actions.processes.RunBackendStepInput;
import com.kingsrook.qqq.backend.core.model.actions.processes.RunBackendStepOutput;
import com.kingsrook.qqq.backend.core.model.actions.tables.insert.InsertInput;
@@ -37,6 +39,7 @@ import com.kingsrook.qbits.quicksearch.model.QuickSearchIndexRun;
import com.kingsrook.qbits.quicksearch.opensearch.BulkIndexResult;
import com.kingsrook.qbits.quicksearch.opensearch.OpenSearchDocument;
import com.kingsrook.qbits.quicksearch.opensearch.QuickSearchOpenSearchClient;
import org.apache.logging.log4j.Level;
import org.junit.jupiter.api.BeforeEach;
import org.junit.jupiter.api.Test;
import org.mockito.ArgumentCaptor;
@@ -121,6 +124,17 @@ class FullReindexStepTest extends BaseQuickSearchTest
** Insert a quickSearchIndex row for testEntity with the given enabled flag.
*******************************************************************************/
private void insertIndexRow(Boolean enabled) throws QException
{
insertIndexRow(enabled, null);
}
/*******************************************************************************
** Insert a quickSearchIndex row for testEntity with the given enabled flag
** and documentCount.
*******************************************************************************/
private void insertIndexRow(Boolean enabled, Integer documentCount) throws QException
{
InsertInput insertInput = new InsertInput();
insertInput.setTableName(QuickSearchIndex.TABLE_NAME);
@@ -128,6 +142,7 @@ class FullReindexStepTest extends BaseQuickSearchTest
.withValue("tableName", TEST_ENTITY_TABLE)
.withValue("enabled", enabled)
.withValue("basepullIntervalMinutes", 5)
.withValue("documentCount", documentCount)
.withValue("status", "ACTIVE")));
new InsertAction().execute(insertInput);
}
@@ -252,6 +267,45 @@ class FullReindexStepTest extends BaseQuickSearchTest
/*******************************************************************************
** Test: a failing document count after the swap is logged at WARN with the
** table name, and the run still completes, keeping the previous
** documentCount.
*******************************************************************************/
@Test
void testAllTables_documentCountFails_loggedAsWarning_previousCountKept() throws QException
{
insertTestEntities(1);
insertIndexRow(true, 99);
when(mockClient.countDocumentsForTable(TEST_ENTITY_TABLE)).thenThrow(new QException("count failed"));
QCollectingLogger collectingLogger = QLogger.activateCollectingLoggerForClass(ReconcileIndexStep.class);
try
{
new FullReindexStep().run(new RunBackendStepInput(), new RunBackendStepOutput());
}
finally
{
QLogger.deactivateCollectingLoggerForClass(ReconcileIndexStep.class);
}
assertThat(collectingLogger.getCollectedMessages())
.filteredOn(m -> Level.WARN.equals(m.getLevel()) && m.getMessage().contains("Could not count indexed documents"))
.singleElement()
.satisfies(m ->
{
assertThat(m.getMessage()).contains("\"tableName\":\"" + TEST_ENTITY_TABLE + "\"");
assertThat(m.getMessage()).contains("\"stackTrace\"").contains("count failed");
});
QRecord row = queryIndexRow();
assertThat(row.getValueString("lastRunStatus")).isEqualTo("FULL_REINDEX COMPLETED");
assertThat(row.getValueInteger("recordCount")).isEqualTo(1);
assertThat(row.getValueInteger("documentCount")).isEqualTo(99);
}
/*******************************************************************************
** Test: an empty source table still produces a new physical index, a
** swap, and a COMPLETED run with zero counts.
@@ -24,6 +24,8 @@ import java.util.List;
import com.kingsrook.qqq.backend.core.actions.tables.InsertAction;
import com.kingsrook.qqq.backend.core.actions.tables.QueryAction;
import com.kingsrook.qqq.backend.core.exceptions.QException;
import com.kingsrook.qqq.backend.core.logging.QCollectingLogger;
import com.kingsrook.qqq.backend.core.logging.QLogger;
import com.kingsrook.qqq.backend.core.model.actions.processes.RunBackendStepInput;
import com.kingsrook.qqq.backend.core.model.actions.processes.RunBackendStepOutput;
import com.kingsrook.qqq.backend.core.model.actions.tables.insert.InsertInput;
@@ -37,6 +39,7 @@ import com.kingsrook.qbits.quicksearch.model.QuickSearchIndexRun;
import com.kingsrook.qbits.quicksearch.opensearch.BulkIndexResult;
import com.kingsrook.qbits.quicksearch.opensearch.OpenSearchDocument;
import com.kingsrook.qbits.quicksearch.opensearch.QuickSearchOpenSearchClient;
import org.apache.logging.log4j.Level;
import org.junit.jupiter.api.BeforeEach;
import org.junit.jupiter.api.Test;
import org.mockito.ArgumentCaptor;
@@ -270,6 +273,44 @@ class ReconcileIndexStepTest extends BaseQuickSearchTest
/*******************************************************************************
** Test: a failing document count is logged at WARN with the table name, and
** the run still completes, keeping the previous documentCount.
*******************************************************************************/
@Test
void testReconcile_documentCountFails_loggedAsWarning_previousCountKept() throws QException
{
insertTestEntities(1);
insertIndexRow(true, 99);
when(mockClient.countDocumentsForTable(TEST_ENTITY_TABLE)).thenThrow(new QException("count failed"));
QCollectingLogger collectingLogger = QLogger.activateCollectingLoggerForClass(ReconcileIndexStep.class);
try
{
new ReconcileIndexStep().run(new RunBackendStepInput(), new RunBackendStepOutput());
}
finally
{
QLogger.deactivateCollectingLoggerForClass(ReconcileIndexStep.class);
}
assertThat(collectingLogger.getCollectedMessages())
.filteredOn(m -> Level.WARN.equals(m.getLevel()) && m.getMessage().contains("Could not count indexed documents"))
.singleElement()
.satisfies(m ->
{
assertThat(m.getMessage()).contains("\"tableName\":\"" + TEST_ENTITY_TABLE + "\"");
assertThat(m.getMessage()).contains("\"stackTrace\"").contains("count failed");
});
QRecord row = queryAll(QuickSearchIndex.TABLE_NAME).get(0);
assertThat(row.getValueString("lastRunStatus")).isEqualTo("RECONCILE COMPLETED");
assertThat(row.getValueInteger("recordCount")).isEqualTo(1);
assertThat(row.getValueInteger("documentCount")).isEqualTo(99);
}
/*******************************************************************************
** Test: the tableName input limits the run to that table.
*******************************************************************************/
@@ -293,6 +334,17 @@ class ReconcileIndexStepTest extends BaseQuickSearchTest
** Insert a quickSearchIndex row for testEntity with the given enabled flag.
*******************************************************************************/
private void insertIndexRow(Boolean enabled) throws QException
{
insertIndexRow(enabled, null);
}
/*******************************************************************************
** Insert a quickSearchIndex row for testEntity with the given enabled flag
** and documentCount.
*******************************************************************************/
private void insertIndexRow(Boolean enabled, Integer documentCount) throws QException
{
InsertInput insertInput = new InsertInput();
insertInput.setTableName(QuickSearchIndex.TABLE_NAME);
@@ -300,6 +352,7 @@ class ReconcileIndexStepTest extends BaseQuickSearchTest
.withValue("tableName", TEST_ENTITY_TABLE)
.withValue("enabled", enabled)
.withValue("basepullIntervalMinutes", 5)
.withValue("documentCount", documentCount)
.withValue("status", "ACTIVE")));
new InsertAction().execute(insertInput);
}