NullMetricsScope warning message in the log

[xujiaxj]

We are seeing this warning in our KCL application log:
No metrics scope set in thread Session worker pool-1, getMetricsScope returning NullMetricsScope.
16 Sep 2015 09:59:03.479 -0700 Session worker pool-1 amazonaws.MetricsHelper WARN No metrics scope set in thread Session worker pool-1, getMetricsScope returning NullMetricsScope.

This seems to due to the fact KCL is assuming single-threaded processing. Kinesis Record Processor sets a metrics scope in thread local storage, but because we are doing checkpointing in a different thread, the checkpointer can not find a metrics scope from its own thread local, so it complains.

[boneill42]

+1, we are seeing this as well.

(FWIW, we are running inside of Spark)

[sfeinstein]

Also checkpointing in a different thread, and seeing that warning.

[apara]

We too are performing checkpointing on different thread as to not delay the actual processing thread.

Has anyone attempted to solve this issue? Tracing through the code, I see no way to "carry" the Metrics Scope from the processing thread to the checkpointing thread since the MetricsHelper has a start/end connotations.

In other words, you cannot simply "set" the Metrics Scope of the thread executing checkpoint. You must use the startScope..endScope methods on MetricsHelper. Those methods also take a IMetricsFactory which is not exposed to implementations of IRecordProcessor.

The actual warning comes up during an attempt to renew the lease which appears to be a consequence of check pointing.

I don't see a clean way of fixing this issue from the client code.

[az3]

@apara , you can use logback with EvaluatorFilter (+janino). That way it is possible to omit unwanted logs from certain classes.

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
    <appender name="MainLogFile" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
            <level>INFO</level>
        </filter>
        <filter class="ch.qos.logback.core.filter.EvaluatorFilter">      
            <evaluator>
                <expression>
                    if( logger.startsWith("com.amazonaws.services.kinesis.metrics.impl.CWPublisherRunnable")
                        &amp;&amp; level == INFO ) {
                    return true;
                    } else if( logger.startsWith("com.amazonaws.services.kinesis.metrics.impl.MetricsHelper")
                        &amp;&amp; level == WARN ) {
                    return true;
                    }
                    return false;
                </expression>
            </evaluator>
            <OnMismatch>NEUTRAL</OnMismatch>
            <OnMatch>DENY</OnMatch>
        </filter>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>${LOG_DIR}/application.%d{yyyy-MM-dd}.log</fileNamePattern>
        </rollingPolicy>
        <encoder>
            <pattern>%d{"yyyy-MM-dd HH:mm:ss,SSS", "UTC"} %-5level [%logger] \(%thread\) %msg%n</pattern>
            <immediateFlush>true</immediateFlush>
        </encoder>
    </appender>
    <!-- ... -->

    <root level="INFO">
        <appender-ref ref="MainLogFile"/>
        <!-- ... -->
    </root>
</configuration>

[apara]

If course, I could even just set the logger level to ERROR on that package/log to filter the specific message out. The point, however, is that if you look at the implementation of NullMetricScope, it merely ignores requests to add metrics. So, the end result, (if you care for it), is that some metrics are not getting captured and/or reported.

When I traced the code, the "checkpoint" process renews the leases and it is the renewal of the leases that attempts to capture some metric timings/reporting. If you are OK with not having that path of code reported on, then absolutely, simply ignoring the WARN will work just fine.

The end result, however, is that the code fails on it's initial design to report metrics when checkpointing is happening on a separate thread as would be with any performance minded implementations that attempt to separate the processes of:

1. getting data from Kinesis
2. processing data
3. checkpointing

on to separate threads to remove the overhead of remote http/rest invocations while data is being processed.

Failure of the code to live up to original design when threading is introduced, is the essence of this "BUG".

-AP_

[pfifer]

Thanks for reporting this. In investigating this does it only happen when you checkpoint on another thread, or does it occur at other times.

Out of curiosity do you wait for the checkpoint to have been completed before returning from the processRecords method?

[xujiaxj]

I didn't see the warning message at other times. We always perform the checkpointing at a separate thread.

Like others said, we too are not comfortable with the design that clutters Kinesis reading, processing, checkpointing and downstream I/O in the same thread, given the nature of our use case and the fact Kinesis and our downstream service have different I/O profile.

So no, we don't wait for the checkpoint to finish before returning from processRecords. This also implies we have to do some bookkeeping in our code to keep track of the sequence number we processed so far to checkpoint later on.

[saj1th]

@pfifer - issue seems to be polluting the log while using spark-streaming-kinesis-asl

[gregakespret]

+1 running spark-streaming-kinesis-asl_2.11

[adrian-baker]

Still occurs in 1.9.3 combined with dynamodb-streams-kinesis-adapter:1.4.0.

Most of our logback configuration file is now made up of config to suppress kinesis warnings.