A label looked up at runtime during a graceful reload can keep dropping the events of a tag

Start with plugin_helper/event_emitter.rb and engine.rb to trace how event_emitter_router selects a label during Engine#reload_config; then read event_router.rb and agent.rb for match caching and rule setup. Use the reproduction script in the issue to confirm the lost events during reload and after it. Done means events reach the label belonging to their configuration through graceful reload without leaving tags cached as unmatched.

Describe the bug

During a graceful reload (Engine#reload_config), a plugin of the old configuration that looks up a label with event_emitter_router while it runs sends its events to that label of the new configuration. If they come before the new <label> gets its <match>, they are dropped with "no patterns matched". After that, the new configuration drops its own events of that tag to that label too, until the next reload, or until 1,024 other tags push the tag out of the MatchCache.

Two things cause this (line numbers of v1.20.1, and master has the same code):

1. event_emitter_router(label_name) looks up the label in Fluent::Engine.root_agent (plugin_helper/event_emitter.rb:62-67). Engine#reload_config makes the new configuration Fluent::Engine.root_agent before it configures it (engine.rb:195, 197), and the old inputs keep emitting until stop_phase(old_agent) (engine.rb:213). So the old plugins send to the labels of the new configuration, which are not configured or started yet.
2. EventRouter keeps the result of matching a tag in its MatchCache, including NoMatchMatch (event_router.rb:134). add_rule does not clear it (event_router.rb:84-86). So once an event of a tag arrives before Agent#add_match adds the <match> (agent.rb:143), the tag stays unmatched in the new configuration, until the MatchCache drops it after 1,024 other tags.

The plugins that look up the label while they run cause this, such as fluent-plugin-rewrite-tag-filter (the label of a rule) and fluent-plugin-concat (timeout_label). relabel and @label look up the label once in configure, so they do not cause it. But once the tag is unmatched in the new label, the events that they send there with that tag are dropped too.

To Reproduce

This script needs no plugin other than Fluentd. It uses the test helpers of Fluentd, so it needs test-unit too, for example with this Gemfile and bundle exec ruby repro.rb:

source "https://rubygems.org"
gem "fluentd", "1.20.1"
gem "test-unit"

The output label_at_runtime looks up its label for each event stream, as the plugins above do. The script emits one event from the old configuration while the new <label @L> is configured, before its <match> is added. The hook on Agent#add_match only makes this timing certain. Then it emits 5 events into the new configuration.

require "fluent/version"
require "fluent/test"
require "fluent/plugin/output"
Fluent::Test.setup

# Looks up the label for each event stream, as some plugins do.
class LabelAtRuntimeOutput < Fluent::Plugin::Output
  Fluent::Plugin.register_output("label_at_runtime", self)
  helpers :event_emitter
  config_param :to, :string
  def process(tag, es)
    event_emitter_router(@to).emit_stream("#{tag}.out", es)
  end
end

class CountOutput < Fluent::Plugin::Output
  Fluent::Plugin.register_output("count", self)
  def self.events; @events ||= []; end
  def process(tag, es)
    es.each { |_time, record| self.class.events << record["message"] }
  end
end

def conf
  Fluent::Config.parse(<<~CONF, "(test)", "(test_dir)", syntax: :v1)
    <match t>
      @type label_at_runtime
      to @L
    </match>
    <label @L>
      <match **>
        @type count
      </match>
    </label>
  CONF
end

Fluent::Engine.run_configure(conf)
Fluent::Engine.root_agent.start
$old_output = Fluent::Engine.root_agent.outputs.find { |o| o.is_a?(LabelAtRuntimeOutput) }

# The old configuration emits one event while the new <label @L> is configured, before its <match> is added.
module EmitDuringReload
  def add_match(type, pattern, conf)
    if @context == "@L" && !$emitted && !ENV["NO_EVENT_DURING_RELOAD"]
      $emitted = true
      $old_output.process("t", Fluent::OneEventStream.new(Fluent::EventTime.now, { "message" => "during" }))
    end
    super
  end
end
Fluent::Agent.prepend(EmitDuringReload)

Fluent::Engine.reload_config(conf)
5.times { |i| Fluent::Engine.root_agent.event_router.emit("t", Fluent::EventTime.now, { "message" => "after#{i}" }) }
puts "Fluentd #{Fluent::VERSION}: #{CountOutput.events.inspect}"

It prints Fluentd 1.20.1: []. The event during the reload and all the 5 events after it are lost. With NO_EVENT_DURING_RELOAD=1, it prints the 5 events.

Expected behavior

The events that a plugin sends to a label go to that label of the configuration that the plugin belongs to, as with relabel, and the new configuration routes its own events.

Graceful reload is no longer the main way to restart (#3415, #4624), but it is still used with the RPC /api/config.gracefulReload, with SIGUSR2 to a worker, and on Windows. If this is not going to be fixed, it would help to document it as a limitation of graceful reload.

Your Environment

• Fluentd version: 1.20.1 (also 1.19.3)
• Ruby version: 4.0.9
• Operating system: Linux

Your Configuration

The configuration is in the script above.

Your Error Log

[warn]: no patterns matched tag="t.out"

Additional context

• I tried two changes with the script on 1.20.1:

  • event_emitter_router looks up the label in the root agent of the plugin's own context_router, which Agent#add_match sets before configure (agent.rb:131). All the 6 events arrive, and the event during the reload goes to the old @L.
  • add_rule clears the MatchCache. The 5 events after the reload arrive, but the event during the reload is still lost. Another window stays too, as #175 describes: an event that reaches a new output after the new configuration is configured, but before it starts, is discarded by a memory buffer when it starts.

  The comment at engine.rb:193-194 says that @root_agent is replaced first for event_emitter_router, so that the new plugins find the new labels in configure. The first change keeps that, as context_router is set before configure.

• fluent/fluent-plugin-rewrite-tag-filter#175 analyzed this in detail and works around it in that plugin. It measured that 5 of 20 graceful reloads dropped a tag on 1.20.1. We'd rather not work around it in each plugin, as the workaround depends on how Fluentd shuts down the plugins.

• #175 also describes a problem that a fix in Fluentd needs to handle: an event of the old configuration that comes late in its shutdown can reach a plugin that has already dropped its router in after_shutdown.

• #2259 is another case of lost events at graceful shutdown, with a different cause.