From 51b8dbfd4c52a89f7b06126ecc911c74bf4ca7ee Mon Sep 17 00:00:00 2001 From: labkey-jeckels Date: Wed, 22 Jul 2026 21:11:06 -0700 Subject: [PATCH] GitHub Issue 1332: Reduce per-row logging --- api/src/org/labkey/api/ApiModule.java | 2 + api/src/org/labkey/api/cache/Throttle.java | 20 +++++ .../org/labkey/api/data/DisplayColumn.java | 77 ++++++++++++++++++- .../api/dataiterator/SimpleTranslator.java | 11 ++- .../study/query/PublishResultsQueryView.java | 10 ++- .../labkey/assay/query/TypeDisplayColumn.java | 9 ++- .../org/labkey/issue/query/IssuesTable.java | 19 +++-- .../query/controllers/QueryController.java | 6 +- 8 files changed, 137 insertions(+), 17 deletions(-) diff --git a/api/src/org/labkey/api/ApiModule.java b/api/src/org/labkey/api/ApiModule.java index 1a0ebb21c07..407bae5d230 100644 --- a/api/src/org/labkey/api/ApiModule.java +++ b/api/src/org/labkey/api/ApiModule.java @@ -57,6 +57,7 @@ import org.labkey.api.data.DbSchema; import org.labkey.api.data.DbScope; import org.labkey.api.data.DbSequenceManager; +import org.labkey.api.data.DisplayColumn; import org.labkey.api.data.ExcelColumn; import org.labkey.api.data.ExcelWriter; import org.labkey.api.data.InlineInClauseGenerator; @@ -522,6 +523,7 @@ public void registerServlets(ServletContext servletCtx) DbScope.SchemaNameTestCase.class, DbScope.TransactionTestCase.class, DbSequenceManager.TestCase.class, + DisplayColumn.TestCase.class, DomTestCase.class, DomainTemplateGroup.TestCase.class, Encryption.TestCase.class, diff --git a/api/src/org/labkey/api/cache/Throttle.java b/api/src/org/labkey/api/cache/Throttle.java index 585af71ee66..8c26b4d8c43 100644 --- a/api/src/org/labkey/api/cache/Throttle.java +++ b/api/src/org/labkey/api/cache/Throttle.java @@ -15,6 +15,7 @@ */ package org.labkey.api.cache; +import java.util.concurrent.atomic.AtomicLong; import java.util.function.Consumer; /** @@ -36,15 +37,21 @@ * THROTTLE.execute(user); * } * + * + *

Tracks how many times the consumer actually ran ({@link #getExecutionCount()}) versus was throttled + * ({@link #getThrottledCount()}), useful for metrics and for tests asserting the throttling behavior.

*/ public class Throttle { private final BlockingCache _cache; + private final AtomicLong _executionCount = new AtomicLong(); + private final AtomicLong _requestCount = new AtomicLong(); public Throttle(String name, int limit, long timeToLive, Consumer consumer) { _cache = CacheManager.getBlockingCache(limit, timeToLive, "Throttle for " + name, (key, argument) -> { + _executionCount.incrementAndGet(); consumer.accept(key); return key; }); @@ -52,6 +59,19 @@ public Throttle(String name, int limit, long timeToLive, Consumer consumer) public void execute(K key) { + _requestCount.incrementAndGet(); _cache.get(key); } + + /** @return the number of times the consumer actually ran (i.e., calls that were not throttled) */ + public long getExecutionCount() + { + return _executionCount.get(); + } + + /** @return the number of {@link #execute} calls that were throttled (the consumer did not run) */ + public long getThrottledCount() + { + return _requestCount.get() - _executionCount.get(); + } } diff --git a/api/src/org/labkey/api/data/DisplayColumn.java b/api/src/org/labkey/api/data/DisplayColumn.java index 659a1b69dda..c46fbd12b20 100644 --- a/api/src/org/labkey/api/data/DisplayColumn.java +++ b/api/src/org/labkey/api/data/DisplayColumn.java @@ -24,7 +24,11 @@ import org.apache.poi.ss.usermodel.Workbook; import org.jetbrains.annotations.NotNull; import org.jetbrains.annotations.Nullable; +import org.junit.Assert; +import org.junit.Test; import org.labkey.api.action.HasViewContext; +import org.labkey.api.cache.CacheManager; +import org.labkey.api.cache.Throttle; import org.labkey.api.collections.NullPreventingSet; import org.labkey.api.compliance.PhiTransformedColumnInfo; import org.labkey.api.ontology.Concept; @@ -64,6 +68,7 @@ import java.util.List; import java.util.Map; import java.util.Set; +import java.util.concurrent.atomic.AtomicInteger; import static org.apache.commons.lang3.StringUtils.isBlank; import static org.apache.commons.lang3.StringUtils.trimToEmpty; @@ -112,6 +117,10 @@ public abstract class DisplayColumn extends RenderColumn private String _description = null; private String _displayClass; + // GH Issue 1332: Throttle to one warning per column + value type per hour, across all renders. + private static final Throttle FORMAT_MISMATCH_THROTTLE = new Throttle<>("DisplayColumn format mismatch", 1000, CacheManager.HOUR, key -> + LOG.warn("Unable to apply format to {}, likely a SQL type mismatch between XML metadata and actual ResultSet", key)); + private final List _analyticsProviders = new ArrayList<>(); /** Handles spanning multiple rows in a grid. A separate interface to allow for easier mixing and matching with DisplayColumn implementations. */ @@ -488,7 +497,7 @@ public String getFormattedText(RenderContext ctx) } catch (IllegalArgumentException e) { - LOG.warn("Unable to apply format to {} value \"{}\" for column \"{}\", likely a SQL type mismatch between XML metadata and actual ResultSet", value.getClass().getName(), value, getName()); + warnFormatMismatch(value); return value.toString(); } } @@ -497,6 +506,13 @@ public String getFormattedText(RenderContext ctx) } + private void warnFormatMismatch(Object value) + { + ColumnInfo col = getColumnInfo(); + String key = "column \"" + (col != null ? col.getFieldKey() : getName()) + "\" (value type " + value.getClass().getName() + ")"; + FORMAT_MISMATCH_THROTTLE.execute(key); + } + /** * Render the value as text using the expr or format if provided without * any html encoding. @@ -540,7 +556,7 @@ else if (null != format) } catch (IllegalArgumentException e) { - LOG.warn("Unable to apply format to {} value \"{}\" for column \"{}\", likely a SQL type mismatch between XML metadata and actual ResultSet", value.getClass().getName(), value, getName()); + warnFormatMismatch(value); formattedString = ConvertUtils.convert(value); } } @@ -1344,4 +1360,61 @@ else if (null == formatString && col.isNumericType()) } } } + + // GH Issue 1332: a type-mismatched column logs in format() on every cell; verify we warn once per column, not once per row + public static class TestCase extends Assert + { + // Unique per column so each test gets its own throttle key + private static final AtomicInteger UNIQUE = new AtomicInteger(); + public static final String NOT_A_NUMBER_VALUE = "not-a-number"; + + // A column whose configured format rejects the value type, mimicking XML metadata that disagrees with the ResultSet. + private DisplayColumn columnThatFailsFormatting() + { + String name = "formatMismatchTestColumn-" + UNIQUE.incrementAndGet(); + Format numberFormat = new DecimalFormat("0.00"); // format() throws IllegalArgumentException on a non-Number + return new SimpleDisplayColumn() + { + @Override + public Object getValue(RenderContext ctx) + { + return NOT_A_NUMBER_VALUE; + } + + @Override + public Format getFormat() + { + return numberFormat; + } + + @Override + public String getName() + { + return name; + } + }; + } + + @Test + public void getFormattedTextWarnsOncePerColumn() + { + RenderContext ctx = new RenderContext(new ViewContext()); + DisplayColumn dc = columnThatFailsFormatting(); + long before = FORMAT_MISMATCH_THROTTLE.getExecutionCount(); + for (int row = 0; row < 1000; row++) + assertEquals("Fallback must be the unformatted value", NOT_A_NUMBER_VALUE, dc.getFormattedText(ctx)); + assertEquals("A format mismatch must warn once per column, not once per row", 1, FORMAT_MISMATCH_THROTTLE.getExecutionCount() - before); + } + + @Test + public void formatValueWarnsOncePerColumn() + { + RenderContext ctx = new RenderContext(new ViewContext()); + DisplayColumn dc = columnThatFailsFormatting(); + long before = FORMAT_MISMATCH_THROTTLE.getExecutionCount(); + for (int row = 0; row < 1000; row++) + assertEquals("Fallback must be the converted value", NOT_A_NUMBER_VALUE, dc.formatValue(ctx, NOT_A_NUMBER_VALUE, null, dc.getFormat(), null)); + assertEquals("A format mismatch must warn once per column, not once per row", 1, FORMAT_MISMATCH_THROTTLE.getExecutionCount() - before); + } + } } diff --git a/api/src/org/labkey/api/dataiterator/SimpleTranslator.java b/api/src/org/labkey/api/dataiterator/SimpleTranslator.java index 3dcad2bc631..3d3fe1528bf 100644 --- a/api/src/org/labkey/api/dataiterator/SimpleTranslator.java +++ b/api/src/org/labkey/api/dataiterator/SimpleTranslator.java @@ -692,6 +692,10 @@ public class ContainerColumn implements Supplier final Set allowableContainers = new HashSet<>(); + // GH Issue 1332: a bad container value recurs on every row; warn once per distinct value, not per row + final Set loggedUnresolvedContainers = new HashSet<>(); + final Set loggedRejectedContainers = new HashSet<>(); + public ContainerColumn(UserSchema us, TableInfo tableInfo, String containerId, int idx) { this.us = us; @@ -723,7 +727,8 @@ public Object get() if (!this.us.getContainer().allowRowMutationForContainer(rowContainer)) { getRowError().addError(new SimpleValidationError("Row supplied container value: " + rowContainerVal + " cannot be used for actions against the container: " + us.getContainer().getPath())); - LOG.warn("Resolved container to {} but rejected as valid location for import into {} in {}.{}", rowContainer.getPath(), us.getContainer().getPath(), us.getSchemaName(), tableInfo.getPublicSchemaName()); + if (loggedRejectedContainers.add(rowContainerVal)) + LOG.warn("Resolved container to {} but rejected as valid location for import into {} in {}.{}", rowContainer.getPath(), us.getContainer().getPath(), us.getSchemaName(), tableInfo.getPublicSchemaName()); } else { @@ -734,8 +739,8 @@ public Object get() } else { - // only log if the incoming value is GUID-like - if (rowContainerVal instanceof String && GUID.isGUID((String)rowContainerVal)) + // only log if the incoming value is GUID-like, and only once per distinct value + if (rowContainerVal instanceof String s && GUID.isGUID(s) && loggedUnresolvedContainers.add(rowContainerVal)) { LOG.warn("Failed to resolve container value '{}' to container for import into {}.{}, defaulting to original target container of {}", rowContainerVal, us.getSchemaName(), tableInfo.getPublicSchemaName(), us.getContainer().getPath()); } diff --git a/api/src/org/labkey/api/study/query/PublishResultsQueryView.java b/api/src/org/labkey/api/study/query/PublishResultsQueryView.java index b59a2109d52..bf005ad6d8f 100644 --- a/api/src/org/labkey/api/study/query/PublishResultsQueryView.java +++ b/api/src/org/labkey/api/study/query/PublishResultsQueryView.java @@ -94,22 +94,26 @@ import java.util.Map; import java.util.Objects; import java.util.Set; +import java.util.concurrent.ConcurrentHashMap; import java.util.stream.Collectors; import java.util.stream.Stream; -import static org.labkey.api.util.IntegerUtils.asInteger; -import static org.labkey.api.util.IntegerUtils.asLong; import static org.labkey.api.study.publish.StudyPublishService.LinkToStudyKeys; import static org.labkey.api.util.DOM.Attribute.id; import static org.labkey.api.util.DOM.DIV; import static org.labkey.api.util.DOM.SCRIPT; import static org.labkey.api.util.DOM.at; +import static org.labkey.api.util.IntegerUtils.asInteger; +import static org.labkey.api.util.IntegerUtils.asLong; import static org.labkey.api.util.IntegerUtils.asLongElseNull; public class PublishResultsQueryView extends QueryView { private static final Logger LOG = LogManager.getLogger(PublishResultsQueryView.class); + // GH Issue 1332: Only warn once per distinct column + private static final Set LOGGED_MULTIVALUE_COLUMNS = ConcurrentHashMap.newKeySet(); + private final SimpleFilter _filter; private final Container _targetStudyContainer; private final boolean _mismatched; @@ -303,7 +307,7 @@ public static Object getColumnValue(ColumnInfo col, RenderContext ctx) List values = ((IMultiValuedDisplayColumn)dc).getDisplayValues(ctx); if (values.size() == 1) return values.getFirst(); - else + else if (LOGGED_MULTIVALUE_COLUMNS.add(col.getFieldKey().toString())) LOG.warn("Unable to use the value returned from column : {} because this multi-value column returned more than a single value.", col.getName()); } return col.getValue(ctx); diff --git a/assay/src/org/labkey/assay/query/TypeDisplayColumn.java b/assay/src/org/labkey/assay/query/TypeDisplayColumn.java index e62b1816151..dff03ba31e0 100644 --- a/assay/src/org/labkey/assay/query/TypeDisplayColumn.java +++ b/assay/src/org/labkey/assay/query/TypeDisplayColumn.java @@ -42,6 +42,9 @@ public class TypeDisplayColumn extends DataColumn private static final FieldKey LSID_FIELD_KEY = new FieldKey(null, "LSID"); + // GH Issue 1332: a broken provider pattern misses on every row; warn once per instance, not once per cell + private boolean _loggedProviderMismatch = false; + public TypeDisplayColumn(ColumnInfo colInfo) { super(colInfo); @@ -74,7 +77,11 @@ public void renderGridCellContents(RenderContext ctx, HtmlWriter out) AssayProvider provider = AssayService.get().getProvider(protocol); if (provider != null) { - LOG.warn("Failed to match AssayProvider '{}' using pattern '{}' for LSID: {}", provider.getName(), provider.getProtocolPattern(), lsid); + if (!_loggedProviderMismatch) + { + _loggedProviderMismatch = true; + LOG.warn("Failed to match AssayProvider '{}' using pattern '{}' for LSID: {}", provider.getName(), provider.getProtocolPattern(), lsid); + } out.write(provider.getName()); return; } diff --git a/issues/src/org/labkey/issue/query/IssuesTable.java b/issues/src/org/labkey/issue/query/IssuesTable.java index c5fcb38f569..2da3fe5323b 100644 --- a/issues/src/org/labkey/issue/query/IssuesTable.java +++ b/issues/src/org/labkey/issue/query/IssuesTable.java @@ -114,6 +114,7 @@ import java.util.List; import java.util.Map; import java.util.Set; +import java.util.concurrent.ConcurrentHashMap; import java.util.regex.Matcher; import java.util.regex.Pattern; import java.util.stream.Collectors; @@ -906,6 +907,9 @@ class PullRequestsDisplayColumn extends DataColumn { private static final Pattern GITHUB_HTTP_PR_URL = Pattern.compile("https://github.com/(?[^/]*)/(?[^/]*)/pull/(?\\d*)"); + // GH Issue 1332: parseGithubUrl is a per-cell static call; warn once per distinct unparseable url, not once per row + private static final Set LOGGED_BAD_PR_URLS = ConcurrentHashMap.newKeySet(); + public PullRequestsDisplayColumn(ColumnInfo col) { super(col); @@ -976,13 +980,16 @@ public void renderGridCellContents(RenderContext ctx, HtmlWriter out) } catch (NumberFormatException e) { - // The issueId value can be null if it the column isn't included in the select for a custom query - @Nullable Integer issueId = ctx.get(FieldKey.fromParts("IssueId"), Integer.class); + if (LOGGED_BAD_PR_URLS.add(url)) + { + // The issueId value can be null if it the column isn't included in the select for a custom query + @Nullable Integer issueId = ctx.get(FieldKey.fromParts("IssueId"), Integer.class); - StringBuilder sb = new StringBuilder("Failed to parse pull request url '" + url + "'"); - if (issueId != null) - sb.append(" for issue ").append(issueId); - IssuesTable.LOG.warn(sb.toString()); + StringBuilder sb = new StringBuilder("Failed to parse pull request url '" + url + "'"); + if (issueId != null) + sb.append(" for issue ").append(issueId); + IssuesTable.LOG.warn(sb.toString()); + } } } diff --git a/query/src/org/labkey/query/controllers/QueryController.java b/query/src/org/labkey/query/controllers/QueryController.java index 17ec1971efe..b4ebe9d8ed5 100644 --- a/query/src/org/labkey/query/controllers/QueryController.java +++ b/query/src/org/labkey/query/controllers/QueryController.java @@ -4615,6 +4615,7 @@ protected JSONObject executeJson(JSONObject json, CommandType commandType, boole if (commandType == CommandType.insert || commandType == CommandType.insertWithKeys || commandType == CommandType.delete) f = new RowMapFactory<>(); CaseInsensitiveHashMap referenceCasing = new CaseInsensitiveHashMap<>(); + boolean loggedConflictingCasing = false; for (int idx = 0; idx < rows.length(); ++idx) { @@ -4632,9 +4633,10 @@ protected JSONObject executeJson(JSONObject json, CommandType commandType, boole Map rowMap = null == f ? new CaseInsensitiveHashMap<>(new HashMap<>(), referenceCasing) : f.getRowMap(); // Use shallow copy since jsonObj.toMap() will translate contained JSONObjects into Maps, which we don't want boolean conflictingCasing = JsonUtil.fillMapShallow(jsonObj, rowMap); - if (conflictingCasing) + if (conflictingCasing && !loggedConflictingCasing) { - // Issue 52616 + loggedConflictingCasing = true; + // Issue 52616; GH Issue 1332: log once per request, not once per conflicting row LOG.error("Row contained conflicting casing for key names in the incoming row: {}", jsonObj); } if (allowRowAttachments())