micrometer: "Duplicate call to publish" error since 1.11.0-RC1

Describe the bug As part of some internal testing with our Dynatrace meter registry, I recently saw the following error message for the first time:

Publishing is already in progress. Skipping duplicate call to publish().

This log message was introduced in https://github.com/micrometer-metrics/micrometer/pull/3714 and first released with Micrometer 1.11.0-RC1.

I was trying to debug this a little bit, but it’s really hard to reproduce (which is a good thing, I guess 😄). One thing that I did find out was that some change in 1.11.0-RC1 seems to lead to multiple publishing threads being created. E.g., when running the registry with micrometer core version 1.9.10 (the default for Spring Boot 2.7.11), I get 1 thread named dynatrace-metrics-publisher, which is responsible for pushing metrics every X seconds. The thread is created using the default thread factory, which is an instance of NamedThreadFactory. Everything is fine and seems to work in this version.

However, when I switch over to Micrometer 1.11.0-RC1, I suddenly have two publishing threads ( dynatrace-metrics-publisher and dynatrace-metrics-publisher-2). It, therefore, seems as if the NewThread method on the ThreadFactory is called twice. I am not quite sure how this happens, since I assume the threads are created here and the SingleThreadScheduledExecutor should not create two threads (maybe?).

I have also tried another registry (I randomly picked the elastic registry), and it seems to also be creating two export threads instead of one. Hence, I believe this might have something to do with the base class (maybe StepMeterRegistry?). Have you seen this before? Any ideas where it could come from? As I said, I am having a hard time getting a reproducer ready (getting two threads is easy, but they seem to not interfere most of the time). I assume the error comes from a race condition when both threads try to export at the same time. This would also explain why it only shows up once in a blue moon.

Environment

  • Micrometer version: 1.11.0-RC1
  • Micrometer registry: I assume StepMeterRegistry, confirmed in DynatraceMeterRegistry and ElasticMeterRegistry, possibly others.
  • OS: WSL2 on Windows 11
  • Java version: openjdk version "17.0.4" 2022-07-19

To Reproduce How to reproduce the bug: -

Expected behavior I expected to not see that error and to only have one live publishing thread.

About this issue

  • Original URL
  • State: closed
  • Created a year ago
  • Comments: 21 (21 by maintainers)

Most upvoted comments

@lenin-jaganathan @jonatan-ivanov @shakuzen Thank you very much for looking into this issue with me. I opened #3872 in order to track the potential addition of a timeout to wait for the final export to finish.

I don’t think you are missing anything, but I am missing my last value and I don’t yet know why 😄