logging for cache put failures

CHANGELOG.md

@@ -74,6 +74,9 @@ Current
     * Created `LegacyGenerator` as a bridge interface from the existing constructor based api request impls and the factory based value object usage.
 
 ### Added:
+- [Add logging for cache put failures](https://github.com/yahoo/fili/pull/??)
+   * Added `BardCacheInfo` logging for cache put failures.
+
 - [Add withLogicalMetricInfo to MetricInstance class](https://github.com/yahoo/fili/pull/1105)
    * Supporting method added to `MetricInstance` to replace `LogicalMetricInfo`.
 

fili-core/src/main/java/com/yahoo/bard/webservice/data/cache/MemDataCache.java

@@ -4,9 +4,16 @@
 
 import static net.spy.memcached.DefaultConnectionFactory.DEFAULT_OPERATION_TIMEOUT;
 
+import com.yahoo.bard.webservice.application.MetricRegistryFactory;
 import com.yahoo.bard.webservice.config.SystemConfig;
 import com.yahoo.bard.webservice.config.SystemConfigException;
 import com.yahoo.bard.webservice.config.SystemConfigProvider;
+import com.yahoo.bard.webservice.logging.RequestLog;
+import com.yahoo.bard.webservice.logging.blocks.BardCacheInfo;
+import com.yahoo.bard.webservice.web.responseprocessors.CacheV2ResponseProcessor;
+
+import com.codahale.metrics.Meter;
+import com.codahale.metrics.MetricRegistry;
 
 import org.joda.time.DateTime;
 import org.slf4j.Logger;
@@ -38,6 +45,8 @@ public class MemDataCache<T extends Serializable> implements DataCache<T> {
     );
 
     private static final String SERVER_CONFIG = SYSTEM_CONFIG.getStringProperty(SERVER_CONFIG_KEY);
+    private static final MetricRegistry REGISTRY = MetricRegistryFactory.getRegistry();
+    public static final Meter CACHE_SET_FAILURES = REGISTRY.meter("queries.meter.cache.put.failures");
 
     /**
      * Memcached uses the actual value sent, and it may either be Unix time (number of seconds since January 1, 1970, as
@@ -131,6 +140,13 @@ private boolean setInSeconds(String key, T value, int expirationInSeconds) throw
             // An exception will be thrown by the memcached client.
             return client.set(key, expirationInSeconds, value) != null;
         } catch (Exception e) {
+            //mark and log the cache put failure
+            CACHE_SET_FAILURES.mark(1);
+            RequestLog.record(new BardCacheInfo(
+                    key,
+                    CacheV2ResponseProcessor.getMD5Cksum(key),
+                    value.toString().length()
+            ));
             LOG.warn("set failed {} {}", key, e.toString());
             throw new IllegalStateException(e);
         }

fili-core/src/main/java/com/yahoo/bard/webservice/logging/blocks/BardCacheInfo.java

@@ -0,0 +1,32 @@
+// Copyright 2016 Yahoo Inc.
+// Licensed under the terms of the Apache license. Please see LICENSE.md file distributed with this work for terms.
+//
+package com.yahoo.bard.webservice.logging.blocks;
+
+import com.yahoo.bard.webservice.logging.LogInfo;
+
+
+import com.fasterxml.jackson.annotation.JsonAutoDetect;
+
+/**
+ * Log that keep tracks for cache set failures.
+ */
+@JsonAutoDetect(getterVisibility = JsonAutoDetect.Visibility.PUBLIC_ONLY)
+public class BardCacheInfo implements LogInfo {
+    String cacheKey;
+    String cacheKeyCksum;
+    int cacheValLength;
+
+    /**
+     * Constructor.
+     *
+     * @param cacheKey  The cache Key
+     * @param cacheKeyCksum  The cache Key MD5 checksum
+     * @param cacheValLength  The cache value length
+     */
+    public BardCacheInfo(String cacheKey, String cacheKeyCksum, int cacheValLength) {
+        this.cacheKey = cacheKey;
+        this.cacheKeyCksum = cacheKeyCksum;
+        this.cacheValLength = cacheValLength;
+    }
+}

fili-core/src/main/java/com/yahoo/bard/webservice/web/responseprocessors/CacheV2ResponseProcessor.java

@@ -6,23 +6,32 @@
 import static com.yahoo.bard.webservice.web.handlers.PartialDataRequestHandler.getPartialIntervalsWithDefault;
 import static com.yahoo.bard.webservice.web.handlers.VolatileDataRequestHandler.getVolatileIntervalsWithDefault;
 
+import com.yahoo.bard.webservice.application.MetricRegistryFactory;
 import com.yahoo.bard.webservice.config.SystemConfig;
 import com.yahoo.bard.webservice.config.SystemConfigProvider;
 import com.yahoo.bard.webservice.data.cache.TupleDataCache;
 import com.yahoo.bard.webservice.druid.client.FailureCallback;
 import com.yahoo.bard.webservice.druid.client.HttpErrorCallback;
 import com.yahoo.bard.webservice.druid.model.query.DruidAggregationQuery;
+import com.yahoo.bard.webservice.logging.RequestLog;
+import com.yahoo.bard.webservice.logging.blocks.BardCacheInfo;
 import com.yahoo.bard.webservice.metadata.QuerySigningService;
 import com.yahoo.bard.webservice.util.SimplifiedIntervalList;
 
+import com.codahale.metrics.Meter;
+import com.codahale.metrics.MetricRegistry;
 import com.fasterxml.jackson.databind.JsonNode;
 import com.fasterxml.jackson.databind.ObjectMapper;
 import com.fasterxml.jackson.databind.ObjectWriter;
 
 import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;
 
+import java.security.MessageDigest;
+import java.util.Locale;
+
 import javax.validation.constraints.NotNull;
+import javax.xml.bind.DatatypeConverter;
 
 /**
  * A response processor which caches the results if appropriate after completing a query.
@@ -31,6 +40,8 @@ public class CacheV2ResponseProcessor implements ResponseProcessor {
 
     private static final Logger LOG = LoggerFactory.getLogger(CacheV2ResponseProcessor.class);
     private static final SystemConfig SYSTEM_CONFIG = SystemConfigProvider.getInstance();
+    private static final MetricRegistry REGISTRY = MetricRegistryFactory.getRegistry();
+    public static final Meter CACHE_SET_FAILURES = REGISTRY.meter("queries.meter.cache.put.failures");
 
     private final long maxDruidResponseLengthToCache = SYSTEM_CONFIG.getLongProperty(
             SYSTEM_CONFIG.getPackageVariableName(
@@ -105,6 +116,13 @@ public void processResponse(JsonNode json, DruidAggregationQuery<?> druidQuery,
                     );
                 }
             } catch (Exception e) {
+                //mark and log the cache put failure
+                CACHE_SET_FAILURES.mark(1);
+                assert valueString != null;
+                RequestLog.record(new BardCacheInfo(
+                        cacheKey,
+                        getMD5Cksum(cacheKey),
+                        valueString.length()));
                 LOG.warn(
                         "Unable to cache {}value of size: {}",
                         valueString == null ? "null " : "",
@@ -128,4 +146,28 @@ protected boolean isCacheable() {
 
         return missingIntervals.isEmpty() && volatileIntervals.isEmpty();
     }
+
+    /**
+     * Generate the Checksum of cacheKey using MD5 algorithm.
+     * @param cacheKey cache key
+     *
+     * @return String representation of the Cksum
+     */
+    public static String getMD5Cksum(String cacheKey) {
+        String result = null;
+        try {
+            MessageDigest digest = MessageDigest.getInstance("MD5");
+            byte[] hash = digest.digest(cacheKey.getBytes("UTF-8"));
+            return bytesToHex(hash); // make it readable
+        } catch (Exception ex) {
+            LOG.warn("failed to generate cksum");
+            ex.printStackTrace();
+        }
+        return result;
+    }
+
+    public static String  bytesToHex(byte[] hash) {
+        return DatatypeConverter.printHexBinary(hash)
+                .toLowerCase(Locale.ENGLISH);
+    }
 }

fili-core/src/main/java/com/yahoo/bard/webservice/web/util/QuerySignedCacheService.java

@@ -13,6 +13,7 @@
 import com.fasterxml.jackson.databind.ObjectWriter;
 import com.yahoo.bard.webservice.config.SystemConfig;
 import com.yahoo.bard.webservice.config.SystemConfigProvider;
+import com.yahoo.bard.webservice.logging.blocks.BardCacheInfo;
 import com.yahoo.bard.webservice.util.SimplifiedIntervalList;
 import com.yahoo.bard.webservice.application.MetricRegistryFactory;
 import com.yahoo.bard.webservice.data.cache.TupleDataCache;
@@ -22,6 +23,7 @@
 import com.yahoo.bard.webservice.metadata.QuerySigningService;
 import com.yahoo.bard.webservice.util.Utils;
 import com.yahoo.bard.webservice.web.handlers.RequestContext;
+import com.yahoo.bard.webservice.web.responseprocessors.CacheV2ResponseProcessor;
 import com.yahoo.bard.webservice.web.responseprocessors.ResponseProcessor;
 
 import com.fasterxml.jackson.databind.JsonNode;
@@ -53,6 +55,7 @@ public class QuerySignedCacheService implements CacheService {
     public static final Meter CACHE_POTENTIAL_HITS = REGISTRY.meter("queries.meter.cache.potential_hits");
     public static final Meter CACHE_MISSES = REGISTRY.meter("queries.meter.cache.misses");
     public static final Meter CACHE_REQUESTS = REGISTRY.meter("queries.meter.cache.total");
+    public static final Meter CACHE_SET_FAILURES = REGISTRY.meter("queries.meter.cache.put.failures");
 
     TupleDataCache<String, Long, String> dataCache;
     QuerySigningService<Long> querySigningService;
@@ -148,6 +151,13 @@ public void writeCache(
                     );
                 }
             } catch (Exception e) {
+                //mark and log the cache put failure
+                CACHE_SET_FAILURES.mark(1);
+                assert valueString != null;
+                RequestLog.record(new BardCacheInfo(
+                        cacheKey,
+                        CacheV2ResponseProcessor.getMD5Cksum(cacheKey),
+                        valueString.length()));
                 LOG.warn(
                         "Unable to cache {}value of size: {}",
                         valueString == null ? "null " : "",

fili-core/src/main/resources/moduleConfig.properties

@@ -138,7 +138,7 @@ bard__updated_metadata_collection_names_enabled = false
 # Statically define the order of LogInfo parts in the RequestLog mega log line. If not set, the order matches the
 # insertion order of the parts. Each part is represented by the simple name of its java class. This setting does not
 # change the predefined order of Durations, Threads, Preface at the start and of Epilogue at the end of the log line.
-# bard__requestlog_loginfo_order = BardQueryInfo,DataRequest,DimensionRequest,MetricRequest,SliceRequest,TableRequest,FeatureFlagRequest,DruidResponse
+# bard__requestlog_loginfo_order = BardQueryInfo,BardCacheInfo,DataRequest,DimensionRequest,MetricRequest,SliceRequest,TableRequest,FeatureFlagRequest,DruidResponse
 
 # List of allowed user roles, must provide value if uncommented
 # bard__user_roles=