GitHub Issue 1332: Reduce per-row logging

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,

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,22 +37,41 @@
  *        THROTTLE.execute(user);
  * }
  * </pre>
+ *
+ * <p>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.</p>
  */
 public class Throttle<K>
 {
     private final BlockingCache<K, K> _cache;
+    private final AtomicLong _executionCount = new AtomicLong();
+    private final AtomicLong _requestCount = new AtomicLong();
 
     public Throttle(String name, int limit, long timeToLive, Consumer<K> consumer)
     {
         _cache = CacheManager.getBlockingCache(limit, timeToLive, "Throttle for " + name, (key, argument) ->
         {
+            _executionCount.incrementAndGet();
             consumer.accept(key);
             return key;
         });
     }
 
     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();
+    }
 }

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<String> 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<ColumnAnalyticsProvider> _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 <code>expr</code> or <code>format</code> 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);
+        }
+    }
 }

api/src/org/labkey/api/dataiterator/SimpleTranslator.java

@@ -692,6 +692,10 @@ public class ContainerColumn implements Supplier
 
         final Set<Object> allowableContainers = new HashSet<>();
 
+        // GH Issue 1332: a bad container value recurs on every row; warn once per distinct value, not per row
+        final Set<Object> loggedUnresolvedContainers = new HashSet<>();
+        final Set<Object> 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());
                     }

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<String> 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<Object> 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);

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;
                 }

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/(?<org>[^/]*)/(?<project>[^/]*)/pull/(?<pullId>\\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<String> 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());
+                }
             }
         }
 

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<Object> 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<String, Object> 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())