Class: Fluent::Plugin::Output

Inherits:
Base
  • Object
show all
Includes:
Fluent::PluginHelper::Mixin, Fluent::PluginId, Fluent::PluginLoggerMixin, UniqueId::Mixin
Defined in:
lib/fluent/plugin/output.rb

Defined Under Namespace

Classes: DequeuedChunkInfo, FlushThreadState

Constant Summary collapse

CHUNK_KEY_PATTERN = 
/^[-_.@a-zA-Z0-9]+$/
CHUNK_KEY_PLACEHOLDER_PATTERN = 
/\$\{[-_.@a-zA-Z0-9]+\}/
CHUNKING_FIELD_WARN_NUM = 
4
FORMAT_MSGPACK_STREAM = 
->(e){ e.to_msgpack_stream }
FORMAT_MSGPACK_STREAM_TIME_INT = 
->(e){ e.to_msgpack_stream(time_int: true) }

Constants included from Configurable

Configurable::CONFIG_TYPE_REGISTRY

Instance Attribute Summary collapse

Attributes included from Fluent::PluginLoggerMixin

#log

Instance Method Summary collapse

Methods included from UniqueId::Mixin

#dump_unique_id_hex, #generate_unique_id

Methods included from Fluent::PluginHelper::Mixin

included

Methods included from Fluent::PluginLoggerMixin

included

Methods included from Fluent::PluginId

#plugin_id, #plugin_id_configured?, #plugin_id_for_test?

Methods inherited from Base

#after_shutdown?, #after_started?, #before_shutdown?, #closed?, #configured?, #has_router?, #inspect, #shutdown?, #started?, #stopped?, #terminated?

Methods included from SystemConfig::Mixin

#system_config, #system_config_override

Methods included from Configurable

#config, included, lookup_type, register_type

Constructor Details

#initialize ⇒ Output

output_enqueue_thread_waiting: for test of output.rb itself in_tests: for tests of plugins with test drivers



151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
 
# File 'lib/fluent/plugin/output.rb', line 151

def initialize
  super
  @counters_monitor = Monitor.new
  @buffering = false
  @delayed_commit = false
  @as_secondary = false
  @in_tests = false
  @primary_instance = nil

  # TODO: well organized counters
  @num_errors = 0
  @emit_count = 0
  @emit_records = 0
  @write_count = 0
  @rollback_count = 0

  # How to process events is decided here at once, but it will be decided in delayed way on #configure & #start
  if implement?(:synchronous)
    if implement?(:buffered) || implement?(:delayed_commit)
      @buffering = nil # do #configure or #start to determine this for full-featured plugins
    else
      @buffering = false
    end
  else
    @buffering = true
  end
  @custom_format = implement?(:custom_format)

  @buffer = nil
  @secondary = nil
  @retry = nil
  @dequeued_chunks = nil
  @output_flush_threads = nil

  @simple_chunking = nil
  @chunk_keys = @chunk_key_time = @chunk_key_tag = nil
  @flush_mode = nil
end

Instance Attribute Details

#as_secondary ⇒ Object (readonly)

Returns the value of attribute as_secondary.



141
142
143
 
# File 'lib/fluent/plugin/output.rb', line 141

def as_secondary
  @as_secondary
end

#buffer ⇒ Object (readonly)

for tests



145
146
147
 
# File 'lib/fluent/plugin/output.rb', line 145

def buffer
  @buffer
end

#chunk_key_tag ⇒ Object (readonly)

for tests



145
146
147
 
# File 'lib/fluent/plugin/output.rb', line 145

def chunk_key_tag
  @chunk_key_tag
end

#chunk_key_time ⇒ Object (readonly)

for tests



145
146
147
 
# File 'lib/fluent/plugin/output.rb', line 145

def chunk_key_time
  @chunk_key_time
end

#chunk_keys ⇒ Object (readonly)

for tests



145
146
147
 
# File 'lib/fluent/plugin/output.rb', line 145

def chunk_keys
  @chunk_keys
end

#delayed_commit ⇒ Object (readonly)

Returns the value of attribute delayed_commit.



141
142
143
 
# File 'lib/fluent/plugin/output.rb', line 141

def delayed_commit
  @delayed_commit
end

#delayed_commit_timeout ⇒ Object (readonly)

Returns the value of attribute delayed_commit_timeout.



141
142
143
 
# File 'lib/fluent/plugin/output.rb', line 141

def delayed_commit_timeout
  @delayed_commit_timeout
end

#emit_count ⇒ Object (readonly)

Returns the value of attribute emit_count.



142
143
144
 
# File 'lib/fluent/plugin/output.rb', line 142

def emit_count
  @emit_count
end

#emit_records ⇒ Object (readonly)

Returns the value of attribute emit_records.



142
143
144
 
# File 'lib/fluent/plugin/output.rb', line 142

def emit_records
  @emit_records
end

#in_tests ⇒ Object

Returns the value of attribute in_tests.



146
147
148
 
# File 'lib/fluent/plugin/output.rb', line 146

def in_tests
  @in_tests
end

#num_errors ⇒ Object (readonly)

Returns the value of attribute num_errors.



142
143
144
 
# File 'lib/fluent/plugin/output.rb', line 142

def num_errors
  @num_errors
end

#output_enqueue_thread_waiting ⇒ Object

Returns the value of attribute output_enqueue_thread_waiting.



146
147
148
 
# File 'lib/fluent/plugin/output.rb', line 146

def output_enqueue_thread_waiting
  @output_enqueue_thread_waiting
end

#retry ⇒ Object (readonly)

for tests



145
146
147
 
# File 'lib/fluent/plugin/output.rb', line 145

def retry
  @retry
end

#rollback_count ⇒ Object (readonly)

Returns the value of attribute rollback_count.



142
143
144
 
# File 'lib/fluent/plugin/output.rb', line 142

def rollback_count
  @rollback_count
end

#secondary ⇒ Object (readonly)

for tests



145
146
147
 
# File 'lib/fluent/plugin/output.rb', line 145

def secondary
  @secondary
end

#write_count ⇒ Object (readonly)

Returns the value of attribute write_count.



142
143
144
 
# File 'lib/fluent/plugin/output.rb', line 142

def write_count
  @write_count
end

Instance Method Details

#acts_as_secondary(primary) ⇒ Object 



190
191
192
193
194
195
196
197
198
 
# File 'lib/fluent/plugin/output.rb', line 190

def acts_as_secondary(primary)
  @as_secondary = true
  @primary_instance = primary
  (class << self; self; end).module_eval do
    define_method(:extract_placeholders){ |str, metadata| @primary_instance.extract_placeholders(str, metadata) }
    define_method(:commit_write){ |chunk_id| @primary_instance.commit_write(chunk_id, delayed: delayed_commit, secondary: true) }
    define_method(:rollback_write){ |chunk_id| @primary_instance.rollback_write(chunk_id) }
  end
end

#after_shutdown ⇒ Object 



419
420
421
422
423
424
425
426
427
428
429
430
431
432
433
434
435
436
437
438
 
# File 'lib/fluent/plugin/output.rb', line 419

def after_shutdown
  try_rollback_all if @buffering && !@as_secondary # rollback regardless with @delayed_commit, because secondary may do it
  @secondary.after_shutdown if @secondary

  if @buffering && @buffer
    @buffer.after_shutdown

    @output_flush_threads_running = false
    if @output_flush_threads && !@output_flush_threads.empty?
      @output_flush_threads.each do |state|
        state.thread.run if state.thread.alive? # to wakeup thread and make it to stop by itself
      end
      @output_flush_threads.each do |state|
        state.thread.join
      end
    end
  end

  super
end

#after_start ⇒ Object 



387
388
389
390
 
# File 'lib/fluent/plugin/output.rb', line 387

def after_start
  super
  @secondary.after_start if @secondary
end

#before_shutdown ⇒ Object 



399
400
401
402
403
404
405
406
407
408
409
410
 
# File 'lib/fluent/plugin/output.rb', line 399

def before_shutdown
  @secondary.before_shutdown if @secondary

  if @buffering && @buffer
    if @flush_at_shutdown
      force_flush
    end
    @buffer.before_shutdown
  end

  super
end

#close ⇒ Object 



440
441
442
443
444
445
 
# File 'lib/fluent/plugin/output.rb', line 440

def close
  @buffer.close if @buffering && @buffer
  @secondary.close if @secondary

  super
end

#commit_write(chunk_id, delayed: @delayed_commit, secondary: false) ⇒ Object 



702
703
704
705
706
707
708
709
710
711
712
713
714
715
716
717
718
719
720
721
 
# File 'lib/fluent/plugin/output.rb', line 702

def commit_write(chunk_id, delayed: @delayed_commit, secondary: false)
  log.trace "committing write operation to a chunk", chunk: dump_unique_id_hex(chunk_id), delayed: delayed
  if delayed
    @dequeued_chunks_mutex.synchronize do
      @dequeued_chunks.delete_if{ |info| info.chunk_id == chunk_id }
    end
  end
  @buffer.purge_chunk(chunk_id)

  @retry_mutex.synchronize do
    if @retry # success to flush chunks in retries
      if secondary
        log.warn "retry succeeded by secondary.", plugin_id: plugin_id, chunk_id: dump_unique_id_hex(chunk_id)
      else
        log.warn "retry succeeded.", plugin_id: plugin_id, chunk_id: dump_unique_id_hex(chunk_id)
      end
      @retry = nil
    end
  end
end

#configure(conf) ⇒ Object 



200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
295
296
297
298
299
300
301
302
303
304
305
306
307
308
309
310
311
312
 
# File 'lib/fluent/plugin/output.rb', line 200

def configure(conf)
  unless implement?(:synchronous) || implement?(:buffered) || implement?(:delayed_commit)
    raise "BUG: output plugin must implement some methods. see developer documents."
  end

  has_buffer_section = (conf.elements(name: 'buffer').size > 0)

  super

  if has_buffer_section
    unless implement?(:buffered) || implement?(:delayed_commit)
      raise Fluent::ConfigError, "<buffer> section is configured, but plugin '#{self.class}' doesn't support buffering"
    end
    @buffering = true
  else # no buffer sections
    if implement?(:synchronous)
      if !implement?(:buffered) && !implement?(:delayed_commit)
        if @as_secondary
          raise Fluent::ConfigError, "secondary plugin '#{self.class}' must support buffering, but doesn't."
        end
        @buffering = false
      else
        if @as_secondary
          # secondary plugin always works as buffered plugin without buffer instance
          @buffering = true
        else
          # @buffering.nil? shows that enabling buffering or not will be decided in lazy way in #start
          @buffering = nil
        end
      end
    else # buffered or delayed_commit is supported by `unless` of first line in this method
      @buffering = true
    end
  end

  if @as_secondary
    if !@buffering && !@buffering.nil?
      raise Fluent::ConfigError, "secondary plugin '#{self.class}' must support buffering, but doesn't"
    end
  end

  if (@buffering || @buffering.nil?) && !@as_secondary
    # When @buffering.nil?, @buffer_config was initialized with default value for all parameters.
    # If so, this configuration MUST success.
    @chunk_keys = @buffer_config.chunk_keys.dup
    @chunk_key_time = !!@chunk_keys.delete('time')
    @chunk_key_tag = !!@chunk_keys.delete('tag')
    if @chunk_keys.any?{ |key| key !~ CHUNK_KEY_PATTERN }
      raise Fluent::ConfigError, "chunk_keys specification includes invalid char"
    end

    if @chunk_key_time
      raise Fluent::ConfigError, "<buffer ...> argument includes 'time', but timekey is not configured" unless @buffer_config.timekey
      Fluent::Timezone.validate!(@buffer_config.timekey_zone)
      @buffer_config.timekey_zone = '+0000' if @buffer_config.timekey_use_utc
      @output_time_formatter_cache = {}
    end

    if (@chunk_key_tag ? 1 : 0) + @chunk_keys.size >= CHUNKING_FIELD_WARN_NUM
      log.warn "many chunk keys specified, and it may cause too many chunks on your system."
    end

    # no chunk keys or only tags (chunking can be done without iterating event stream)
    @simple_chunking = !@chunk_key_time && @chunk_keys.empty?

    @flush_mode = @buffer_config.flush_mode
    if @flush_mode == :default
      @flush_mode = (@chunk_key_time ? :lazy : :interval)
    end

    buffer_type = @buffer_config[:@type]
    buffer_conf = conf.elements(name: 'buffer').first || Fluent::Config::Element.new('buffer', '', {}, [])
    @buffer = Plugin.new_buffer(buffer_type, parent: self)
    @buffer.configure(buffer_conf)

    @flush_at_shutdown = @buffer_config.flush_at_shutdown
    if @flush_at_shutdown.nil?
      @flush_at_shutdown = if @buffer.persistent?
                             false
                           else
                             true # flush_at_shutdown is true in default for on-memory buffer
                           end
    elsif !@flush_at_shutdown && !@buffer.persistent?
      buf_type = Plugin.lookup_type_from_class(@buffer.class)
      log.warn "'flush_at_shutdown' is false, and buffer plugin '#{buf_type}' is not persistent buffer."
      log.warn "your configuration will lose buffered data at shutdown. please confirm your configuration again."
    end
  end

  if @secondary_config
    raise Fluent::ConfigError, "Invalid <secondary> section for non-buffered plugin" unless @buffering
    raise Fluent::ConfigError, "<secondary> section cannot have <buffer> section" if @secondary_config.buffer
    raise Fluent::ConfigError, "<secondary> section cannot have <secondary> section" if @secondary_config.secondary
    raise Fluent::ConfigError, "<secondary> section and 'retry_forever' are exclusive" if @buffer_config.retry_forever

    secondary_type = @secondary_config[:@type]
    unless secondary_type
      secondary_type = conf['@type'] # primary plugin type
    end
    secondary_conf = conf.elements(name: 'secondary').first
    @secondary = Plugin.new_output(secondary_type)
    @secondary.acts_as_secondary(self)
    @secondary.configure(secondary_conf)
    @secondary.router = router if @secondary.has_router?
    if (self.class != @secondary.class) && (@custom_format || @secondary.implement?(:custom_format))
      log.warn "secondary type should be same with primary one", primary: self.class.to_s, secondary: @secondary.class.to_s
    end
  else
    @secondary = nil
  end

  self
end

#emit_buffered(tag, es) ⇒ Object 



533
534
535
536
537
538
539
540
541
542
543
544
545
 
# File 'lib/fluent/plugin/output.rb', line 533

def emit_buffered(tag, es)
  @counters_monitor.synchronize{ @emit_count += 1 }
  begin
    execute_chunking(tag, es, enqueue: (@flush_mode == :immediate))
    if !@retry && @buffer.queued?
      submit_flush_once
    end
  rescue
    # TODO: separate number of errors into emit errors and write/flush errors
    @counters_monitor.synchronize{ @num_errors += 1 }
    raise
  end
end

#emit_events(tag, es) ⇒ Object 



513
514
515
516
517
518
519
520
 
# File 'lib/fluent/plugin/output.rb', line 513

def emit_events(tag, es)
  # actually this method will be overwritten by #configure
  if @buffering
    emit_buffered(tag, es)
  else
    emit_sync(tag, es)
  end
end

#emit_sync(tag, es) ⇒ Object 



522
523
524
525
526
527
528
529
530
531
 
# File 'lib/fluent/plugin/output.rb', line 522

def emit_sync(tag, es)
  @counters_monitor.synchronize{ @emit_count += 1 }
  begin
    process(tag, es)
    @counters_monitor.synchronize{ @emit_records += es.size }
  rescue
    @counters_monitor.synchronize{ @num_errors += 1 }
    raise
  end
end

#enqueue_thread_run ⇒ Object 



912
913
914
915
916
917
918
919
920
921
922
923
924
925
926
927
928
929
930
931
932
933
934
935
936
937
938
939
940
941
942
943
944
945
946
947
948
949
950
951
952
953
954
955
956
957
958
959
960
961
962
963
964
965
966
967
968
969
970
971
972
973
 
# File 'lib/fluent/plugin/output.rb', line 912

def enqueue_thread_run
  value_for_interval = nil
  if @flush_mode == :interval
    value_for_interval = @buffer_config.flush_interval
  end
  if @chunk_key_time
    if !value_for_interval || @buffer_config.timekey < value_for_interval
      value_for_interval = @buffer_config.timekey
    end
  end
  unless value_for_interval
    raise "BUG: both of flush_interval and timekey are disabled"
  end
  interval = value_for_interval / 11.0
  if interval < @buffer_config.flush_thread_interval
    interval = @buffer_config.flush_thread_interval
  end

  while !self.after_started? && !self.stopped?
    sleep 0.5
  end
  log.debug "enqueue_thread actually running"

  begin
    while @output_flush_threads_running
      now_int = Time.now.to_i
      if @output_flush_interrupted
        sleep interval
        next
      end

      @output_enqueue_thread_mutex.lock
      begin
        if @flush_mode == :interval
          flush_interval = @buffer_config.flush_interval.to_i
          # This block should be done by integer values.
          # If both of flush_interval & flush_thread_interval are 1s, expected actual flush timing is 1.5s.
          # If we use integered values for this comparison, expected actual flush timing is 1.0s.
          @buffer.enqueue_all{ |metadata, chunk| chunk.created_at.to_i + flush_interval <= now_int }
        end

        if @chunk_key_time
          timekey_unit = @buffer_config.timekey
          timekey_wait = @buffer_config.timekey_wait
          current_timekey = now_int - now_int % timekey_unit
          @buffer.enqueue_all{ |metadata, chunk| metadata.timekey < current_timekey && metadata.timekey + timekey_unit + timekey_wait <= now_int }
        end
      rescue => e
        log.error "unexpected error while checking flushed chunks. ignored.", plugin_id: plugin_id, error_class: e.class, error: e
        log.error_backtrace
      end
      @output_enqueue_thread_waiting = false
      @output_enqueue_thread_mutex.unlock
      sleep interval
    end
  rescue => e
    # normal errors are rescued by inner begin-rescue clause.
    log.error "error on enqueue thread", plugin_id: plugin_id, error_class: e.class, error: e
    log.error_backtrace
    raise
  end
end

#enqueue_thread_wait ⇒ Object

only for tests of output plugin



893
894
895
896
897
898
899
900
901
902
 
# File 'lib/fluent/plugin/output.rb', line 893

def enqueue_thread_wait
  @output_enqueue_thread_mutex.synchronize do
    @output_flush_interrupted = false
    @output_enqueue_thread_waiting = true
  end
  require 'timeout'
  Timeout.timeout(10) do
    Thread.pass while @output_enqueue_thread_waiting
  end
end

#execute_chunking(tag, es, enqueue: false) ⇒ Object 



590
591
592
593
594
595
596
597
598
 
# File 'lib/fluent/plugin/output.rb', line 590

def execute_chunking(tag, es, enqueue: false)
  if @simple_chunking
    handle_stream_simple(tag, es, enqueue: enqueue)
  elsif @custom_format
    handle_stream_with_custom_format(tag, es, enqueue: enqueue)
  else
    handle_stream_with_standard_format(tag, es, enqueue: enqueue)
  end
end

#extract_placeholders(str, metadata) ⇒ Object

TODO: optimize this code



479
480
481
482
483
484
485
486
487
488
489
490
491
492
493
494
495
496
497
498
499
500
501
502
503
504
505
506
507
508
509
510
511
 
# File 'lib/fluent/plugin/output.rb', line 479

def extract_placeholders(str, metadata)
  if metadata.timekey.nil? && metadata.tag.nil? && metadata.variables.nil?
    str
  else
    rvalue = str
    # strftime formatting
    if @chunk_key_time # this section MUST be earlier than rest to use raw 'str'
      @output_time_formatter_cache[str] ||= Fluent::Timezone.formatter(@buffer_config.timekey_zone, str)
      rvalue = @output_time_formatter_cache[str].call(metadata.timekey)
    end
    # ${tag}, ${tag[0]}, ${tag[1]}, ...
    if @chunk_key_tag
      if str =~ /\$\{tag\[\d+\]\}/
        hash = {'${tag}' => metadata.tag}
        metadata.tag.split('.').each_with_index do |part, i|
          hash["${tag[#{i}]}"] = part
        end
        rvalue = rvalue.gsub(/\$\{tag(\[\d+\])?\}/, hash)
      elsif str.include?('${tag}')
        rvalue = rvalue.gsub('${tag}', metadata.tag)
      end
    end
    # ${a_chunk_key}, ...
    if !@chunk_keys.empty? && metadata.variables
      hash = {'${tag}' => '${tag}'} # not to erase this wrongly
      @chunk_keys.each do |key|
        hash["${#{key}}"] = metadata.variables[key.to_sym]
      end
      rvalue = rvalue.gsub(CHUNK_KEY_PLACEHOLDER_PATTERN, hash)
    end
    rvalue
  end
end

#flush_thread_run(state) ⇒ Object 



975
976
977
978
979
980
981
982
983
984
985
986
987
988
989
990
991
992
993
994
995
996
997
998
999
1000
1001
1002
1003
1004
1005
1006
1007
1008
1009
1010
1011
1012
1013
1014
1015
1016
1017
 
# File 'lib/fluent/plugin/output.rb', line 975

def flush_thread_run(state)
  flush_thread_interval = @buffer_config.flush_thread_interval

  # If the given clock_id is not supported, Errno::EINVAL is raised.
  clock_id = Process::CLOCK_MONOTONIC rescue Process::CLOCK_MONOTONIC_RAW
  state.next_time = Process.clock_gettime(clock_id) + flush_thread_interval

  while !self.after_started? && !self.stopped?
    sleep 0.5
  end
  log.debug "flush_thread actually running"

  begin
    # This thread don't use `thread_current_running?` because this thread should run in `before_shutdown` phase
    while @output_flush_threads_running
      time = Process.clock_gettime(clock_id)
      interval = state.next_time - time

      if state.next_time <= time
        try_flush
        # next_flush_interval uses flush_thread_interval or flush_thread_burst_interval (or retrying)
        interval = next_flush_time.to_f - Time.now.to_f
        # TODO: if secondary && delayed-commit, next_flush_time will be much longer than expected (because @retry still exists)
        #   @retry should be cleard if delayed commit is enabled? Or any other solution?
        state.next_time = Process.clock_gettime(clock_id) + interval
      end

      if @dequeued_chunks_mutex.synchronize{ !@dequeued_chunks.empty? && @dequeued_chunks.first.expired? }
        unless @output_flush_interrupted
          try_rollback_write
        end
      end

      sleep interval if interval > 0
    end
  rescue => e
    # normal errors are rescued by output plugins in #try_flush
    # so this rescue section is for critical & unrecoverable errors
    log.error "error on output thread", plugin_id: plugin_id, error_class: e.class, error: e
    log.error_backtrace
    raise
  end
end

#flush_thread_wakeup ⇒ Object

only for tests of output plugin



905
906
907
908
909
910
 
# File 'lib/fluent/plugin/output.rb', line 905

def flush_thread_wakeup
  @output_flush_threads.each do |state|
    state.next_time = 0
    state.thread.run
  end
end

#force_flush ⇒ Object 



873
874
875
876
877
878
 
# File 'lib/fluent/plugin/output.rb', line 873

def force_flush
  if @buffering
    @buffer.enqueue_all
    submit_flush_all
  end
end

#format(tag, time, record) ⇒ Object

Raises:

  • (NotImplementedError) 


116
117
118
119
 
# File 'lib/fluent/plugin/output.rb', line 116

def format(tag, time, record)
  # standard msgpack_event_stream chunk will be used if this method is not implemented in plugin subclass
  raise NotImplementedError, "BUG: output plugins MUST implement this method"
end

#handle_stream_simple(tag, es, enqueue: false) ⇒ Object 



680
681
682
683
684
685
686
687
688
689
690
691
692
693
694
695
696
697
698
699
700
 
# File 'lib/fluent/plugin/output.rb', line 680

def handle_stream_simple(tag, es, enqueue: false)
  format_proc = nil
  meta = metadata((@chunk_key_tag ? tag : nil), nil, nil)
  records = es.size
  if @custom_format
    records = 0
    data = []
    es.each do |time, record|
      data << format(tag, time, record)
      records += 1
    end
  else
    format_proc = @time_as_integer ? FORMAT_MSGPACK_STREAM_TIME_INT : FORMAT_MSGPACK_STREAM
    data = es
  end
  write_guard do
    @buffer.write({meta => data}, format: format_proc, enqueue: enqueue)
  end
  @counters_monitor.synchronize{ @emit_records += records }
  true
end

#handle_stream_with_custom_format(tag, es, enqueue: false) ⇒ Object

metadata_and_data is a Hash of:

(standard format) metadata => event stream
(custom format)   metadata => array of formatted event

For standard format, formatting should be done for whole event stream, but

"whole event stream" may be a split of "es" here when it's bigger than chunk_limit_size.
`@buffer.write` will do this splitting.

For custom format, formatting will be done here. Custom formatting always requires

iteration of event stream, and it should be done just once even if total event stream size
is biggar than chunk_limit_size because of performance.



647
648
649
650
651
652
653
654
655
656
657
658
659
660
661
 
# File 'lib/fluent/plugin/output.rb', line 647

def handle_stream_with_custom_format(tag, es, enqueue: false)
  meta_and_data = {}
  records = 0
  es.each do |time, record|
    meta = metadata(tag, time, record)
    meta_and_data[meta] ||= []
    meta_and_data[meta] << format(tag, time, record)
    records += 1
  end
  write_guard do
    @buffer.write(meta_and_data, enqueue: enqueue)
  end
  @counters_monitor.synchronize{ @emit_records += records }
  true
end

#handle_stream_with_standard_format(tag, es, enqueue: false) ⇒ Object 



663
664
665
666
667
668
669
670
671
672
673
674
675
676
677
678
 
# File 'lib/fluent/plugin/output.rb', line 663

def handle_stream_with_standard_format(tag, es, enqueue: false)
  format_proc = @time_as_integer ? FORMAT_MSGPACK_STREAM_TIME_INT : FORMAT_MSGPACK_STREAM
  meta_and_data = {}
  records = 0
  es.each do |time, record|
    meta = metadata(tag, time, record)
    meta_and_data[meta] ||= MultiEventStream.new
    meta_and_data[meta].add(time, record)
    records += 1
  end
  write_guard do
    @buffer.write(meta_and_data, format: format_proc, enqueue: enqueue)
  end
  @counters_monitor.synchronize{ @emit_records += records }
  true
end

#implement?(feature) ⇒ Boolean

Returns:

  • (Boolean) 


466
467
468
469
470
471
472
473
474
475
476
 
# File 'lib/fluent/plugin/output.rb', line 466

def implement?(feature)
  methods_of_plugin = self.class.instance_methods(false)
  case feature
  when :synchronous    then methods_of_plugin.include?(:process) || support_in_v12_style?(:synchronous)
  when :buffered       then methods_of_plugin.include?(:write) || support_in_v12_style?(:buffered)
  when :delayed_commit then methods_of_plugin.include?(:try_write)
  when :custom_format  then methods_of_plugin.include?(:format) || support_in_v12_style?(:custom_format)
  else
    raise ArgumentError, "Unknown feature for output plugin: #{feature}"
  end
end

#interrupt_flushes ⇒ Object

only for tests of output plugin



888
889
890
 
# File 'lib/fluent/plugin/output.rb', line 888

def interrupt_flushes
  @output_flush_interrupted = true
end

#metadata(tag, time, record) ⇒ Object

TODO: optimize this code

Raises:

  • (ArgumentError) 


548
549
550
551
552
553
554
555
556
557
558
559
560
561
562
563
564
565
566
567
568
569
570
571
572
573
574
575
576
577
578
579
580
581
582
583
584
585
586
587
588
 
# File 'lib/fluent/plugin/output.rb', line 548

def metadata(tag, time, record)
  # this arguments are ordered in output plugin's rule
  # Metadata 's argument order is different from this one (timekey, tag, variables)

  raise ArgumentError, "tag must be a String: #{tag.class}" unless tag.nil? || tag.is_a?(String)
  raise ArgumentError, "time must be a Fluent::EventTime (or Integer): #{time.class}" unless time.nil? || time.is_a?(Fluent::EventTime) || time.is_a?(Integer)
  raise ArgumentError, "record must be a Hash: #{record.class}" unless record.nil? || record.is_a?(Hash)

  if @chunk_keys.nil? && @chunk_key_time.nil? && @chunk_key_tag.nil?
    # for tests
    return Struct.new(:timekey, :tag, :variables).new
  end

  # timekey is int from epoch, and `timekey - timekey % 60` is assumed to mach with 0s of each minutes.
  # it's wrong if timezone is configured as one which supports leap second, but it's very rare and
  # we can ignore it (especially in production systems).
  if @chunk_keys.empty?
    if !@chunk_key_time && !@chunk_key_tag
      @buffer.metadata()
    elsif @chunk_key_time && @chunk_key_tag
      time_int = time.to_i
      timekey = (time_int - (time_int % @buffer_config.timekey)).to_i
      @buffer.metadata(timekey: timekey, tag: tag)
    elsif @chunk_key_time
      time_int = time.to_i
      timekey = (time_int - (time_int % @buffer_config.timekey)).to_i
      @buffer.metadata(timekey: timekey)
    else
      @buffer.metadata(tag: tag)
    end
  else
    timekey = if @chunk_key_time
                time_int = time.to_i
                (time_int - (time_int % @buffer_config.timekey)).to_i
              else
                nil
              end
    pairs = Hash[@chunk_keys.map{|k| [k.to_sym, record[k]]}]
    @buffer.metadata(timekey: timekey, tag: (@chunk_key_tag ? tag : nil), variables: pairs)
  end
end

#next_flush_time ⇒ Object 



765
766
767
768
769
770
771
772
773
 
# File 'lib/fluent/plugin/output.rb', line 765

def next_flush_time
  if @buffer.queued?
    @retry_mutex.synchronize do
      @retry ? @retry.next_time : Time.now + @buffer_config.flush_thread_burst_interval
    end
  else
    Time.now + @buffer_config.flush_thread_interval
  end
end

#prefer_buffered_processing ⇒ Object 



121
122
123
124
125
126
 
# File 'lib/fluent/plugin/output.rb', line 121

def prefer_buffered_processing
  # override this method to return false only when all of these are true:
  #  * plugin has both implementation for buffered and non-buffered methods
  #  * plugin is expected to work as non-buffered plugin if no `<buffer>` sections specified
  true
end

#prefer_delayed_commit ⇒ Object 



128
129
130
131
 
# File 'lib/fluent/plugin/output.rb', line 128

def prefer_delayed_commit
  # override this method to decide which is used of `write` or `try_write` if both are implemented
  true
end

#process(tag, es) ⇒ Object

Raises:

  • (NotImplementedError) 


104
105
106
 
# File 'lib/fluent/plugin/output.rb', line 104

def process(tag, es)
  raise NotImplementedError, "BUG: output plugins MUST implement this method"
end

#retry_state(randomize) ⇒ Object 



846
847
848
849
850
851
852
853
854
855
856
857
858
859
860
861
862
863
 
# File 'lib/fluent/plugin/output.rb', line 846

def retry_state(randomize)
  if @secondary
    retry_state_create(
      :output_retries, @buffer_config.retry_type, @buffer_config.retry_wait, @buffer_config.retry_timeout,
      forever: @buffer_config.retry_forever, max_steps: @buffer_config.retry_max_times, backoff_base: @buffer_config.retry_exponential_backoff_base,
      max_interval: @buffer_config.retry_max_interval,
      secondary: true, secondary_threshold: @buffer_config.retry_secondary_threshold,
      randomize: randomize
    )
  else
    retry_state_create(
      :output_retries, @buffer_config.retry_type, @buffer_config.retry_wait, @buffer_config.retry_timeout,
      forever: @buffer_config.retry_forever, max_steps: @buffer_config.retry_max_times, backoff_base: @buffer_config.retry_exponential_backoff_base,
      max_interval: @buffer_config.retry_max_interval,
      randomize: randomize
    )
  end
end

#rollback_write(chunk_id) ⇒ Object 



723
724
725
726
727
728
729
730
731
732
733
734
735
736
737
738
 
# File 'lib/fluent/plugin/output.rb', line 723

def rollback_write(chunk_id)
  # This API is to rollback chunks explicitly from plugins.
  # 3rd party plugins can depend it on automatic rollback of #try_rollback_write
  @dequeued_chunks_mutex.synchronize do
    @dequeued_chunks.delete_if{ |info| info.chunk_id == chunk_id }
  end
  # returns true if chunk was rollbacked as expected
  #         false if chunk was already flushed and couldn't be rollbacked unexpectedly
  # in many cases, false can be just ignored
  if @buffer.takeback_chunk(chunk_id)
    @counters_monitor.synchronize{ @rollback_count += 1 }
    true
  else
    false
  end
end

#shutdown ⇒ Object 



412
413
414
415
416
417
 
# File 'lib/fluent/plugin/output.rb', line 412

def shutdown
  @secondary.shutdown if @secondary
  @buffer.shutdown if @buffering && @buffer

  super
end

#start ⇒ Object 



314
315
316
317
318
319
320
321
322
323
324
325
326
327
328
329
330
331
332
333
334
335
336
337
338
339
340
341
342
343
344
345
346
347
348
349
350
351
352
353
354
355
356
357
358
359
360
361
362
363
364
365
366
367
368
369
370
371
372
373
374
375
376
377
378
379
380
381
382
383
384
385
 
# File 'lib/fluent/plugin/output.rb', line 314

def start
  super

  if @buffering.nil?
    @buffering = prefer_buffered_processing
    if !@buffering && @buffer
      @buffer.terminate # it's not started, so terminate will be enough
    end
  end

  if @buffering
    m = method(:emit_buffered)
    (class << self; self; end).module_eval do
      define_method(:emit_events, m)
    end

    @custom_format = implement?(:custom_format)
    @delayed_commit = if implement?(:buffered) && implement?(:delayed_commit)
                        prefer_delayed_commit
                      else
                        implement?(:delayed_commit)
                      end
    @delayed_commit_timeout = @buffer_config.delayed_commit_timeout
  else # !@buffering
    m = method(:emit_sync)
    (class << self; self; end).module_eval do
      define_method(:emit_events, m)
    end
  end

  if @buffering && !@as_secondary
    @retry = nil
    @retry_mutex = Mutex.new

    @buffer.start

    @output_flush_threads = []
    @output_flush_threads_mutex = Mutex.new
    @output_flush_threads_running = true

    # mainly for test: detect enqueue works as code below:
    #   @output.interrupt_flushes
    #   # emits
    #   @output.enqueue_thread_wait
    @output_flush_interrupted = false
    @output_enqueue_thread_mutex = Mutex.new
    @output_enqueue_thread_waiting = false

    @dequeued_chunks = []
    @dequeued_chunks_mutex = Mutex.new

    @buffer_config.flush_thread_count.times do |i|
      thread_title = "flush_thread_#{i}".to_sym
      thread_state = FlushThreadState.new(nil, nil)
      thread = thread_create(thread_title) do
        flush_thread_run(thread_state)
      end
      thread_state.thread = thread
      @output_flush_threads_mutex.synchronize do
        @output_flush_threads << thread_state
      end
    end
    @output_flush_thread_current_position = 0

    unless @in_tests
      if @flush_mode == :interval || @chunk_key_time
        thread_create(:enqueue_thread, &method(:enqueue_thread_run))
      end
    end
  end
  @secondary.start if @secondary
end

#stop ⇒ Object 



392
393
394
395
396
397
 
# File 'lib/fluent/plugin/output.rb', line 392

def stop
  @secondary.stop if @secondary
  @buffer.stop if @buffering && @buffer

  super
end

#submit_flush_all ⇒ Object 



880
881
882
883
884
885
 
# File 'lib/fluent/plugin/output.rb', line 880

def submit_flush_all
  while !@retry && @buffer.queued?
    submit_flush_once
    sleep @buffer_config.flush_thread_burst_interval
  end
end

#submit_flush_once ⇒ Object 



865
866
867
868
869
870
871
 
# File 'lib/fluent/plugin/output.rb', line 865

def submit_flush_once
  # Without locks: it is rough but enough to select "next" writer selection
  @output_flush_thread_current_position = (@output_flush_thread_current_position + 1) % @buffer_config.flush_thread_count
  state = @output_flush_threads[@output_flush_thread_current_position]
  state.next_time = 0
  state.thread.run
end

#support_in_v12_style?(feature) ⇒ Boolean

Returns:

  • (Boolean) 


454
455
456
457
458
459
460
461
462
463
464
 
# File 'lib/fluent/plugin/output.rb', line 454

def support_in_v12_style?(feature)
  # for plugins written in v0.12 styles
  case feature
  when :synchronous    then false
  when :buffered       then false
  when :delayed_commit then false
  when :custom_format  then false
  else
    raise ArgumentError, "unknown feature: #{feature}"
  end
end

#terminate ⇒ Object 



447
448
449
450
451
452
 
# File 'lib/fluent/plugin/output.rb', line 447

def terminate
  @buffer.terminate if @buffering && @buffer
  @secondary.terminate if @secondary

  super
end

#try_flush ⇒ Object 



775
776
777
778
779
780
781
782
783
784
785
786
787
788
789
790
791
792
793
794
795
796
797
798
799
800
801
802
803
804
805
806
807
808
809
810
811
812
813
814
815
816
817
818
819
820
821
822
823
824
825
826
827
828
829
830
831
832
833
834
835
836
837
838
839
840
841
842
843
844
 
# File 'lib/fluent/plugin/output.rb', line 775

def try_flush
  chunk = @buffer.dequeue_chunk
  return unless chunk

  log.debug "trying flush for a chunk", chunk: dump_unique_id_hex(chunk.unique_id)

  output = self
  using_secondary = false
  if @retry_mutex.synchronize{ @retry && @retry.secondary? }
    output = @secondary
    using_secondary = true
  end

  unless @custom_format
    chunk.extend ChunkMessagePackEventStreamer
  end

  begin
    if output.delayed_commit
      log.trace "executing delayed write and commit", chunk: dump_unique_id_hex(chunk.unique_id)
      @counters_monitor.synchronize{ @write_count += 1 }
      output.try_write(chunk)
      @dequeued_chunks_mutex.synchronize do
        # delayed_commit_timeout for secondary is configured in <buffer> of primary (<secondary> don't get <buffer>)
        @dequeued_chunks << DequeuedChunkInfo.new(chunk.unique_id, Time.now, self.delayed_commit_timeout)
      end
    else # output plugin without delayed purge
      chunk_id = chunk.unique_id
      dump_chunk_id = dump_unique_id_hex(chunk_id)
      log.trace "adding write count", instance: self.object_id
      @counters_monitor.synchronize{ @write_count += 1 }
      log.trace "executing sync write", chunk: dump_chunk_id
      output.write(chunk)
      log.trace "write operation done, committing", chunk: dump_chunk_id
      commit_write(chunk_id, secondary: using_secondary)
      log.trace "done to commit a chunk", chunk: dump_chunk_id
    end
  rescue => e
    log.debug "taking back chunk for errors.", plugin_id: plugin_id, chunk: dump_unique_id_hex(chunk.unique_id)
    @buffer.takeback_chunk(chunk.unique_id)

    @retry_mutex.synchronize do
      if @retry
        @counters_monitor.synchronize{ @num_errors += 1 }
        if @retry.limit?
          records = @buffer.queued_records
          log.error "failed to flush the buffer, and hit limit for retries. dropping all chunks in the buffer queue.", plugin_id: plugin_id, retry_times: @retry.steps, records: records, error: e
          log.error_backtrace e.backtrace
          @buffer.clear_queue!
          log.debug "buffer queue cleared", plugin_id: plugin_id
          @retry = nil
        else
          @retry.step
          msg = if using_secondary
                  "failed to flush the buffer with secondary output."
                else
                  "failed to flush the buffer."
                end
          log.warn msg, plugin_id: plugin_id, retry_time: @retry.steps, next_retry: @retry.next_time, chunk: dump_unique_id_hex(chunk.unique_id), error: e
          log.warn_backtrace e.backtrace
        end
      else
        @retry = retry_state(@buffer_config.retry_randomize)
        @counters_monitor.synchronize{ @num_errors += 1 }
        log.warn "failed to flush the buffer.", plugin_id: plugin_id, retry_time: @retry.steps, next_retry: @retry.next_time, chunk: dump_unique_id_hex(chunk.unique_id), error: e
        log.warn_backtrace e.backtrace
      end
    end
  end
end

#try_rollback_all ⇒ Object 



752
753
754
755
756
757
758
759
760
761
762
763
 
# File 'lib/fluent/plugin/output.rb', line 752

def try_rollback_all
  return unless @dequeued_chunks
  @dequeued_chunks_mutex.synchronize do
    until @dequeued_chunks.empty?
      info = @dequeued_chunks.shift
      if @buffer.takeback_chunk(info.chunk_id)
        @counters_monitor.synchronize{ @rollback_count += 1 }
        log.info "delayed commit for buffer chunks was cancelled in shutdown", plugin_id: plugin_id, chunk_id: dump_unique_id_hex(info.chunk_id)
      end
    end
  end
end

#try_rollback_write ⇒ Object 



740
741
742
743
744
745
746
747
748
749
750
 
# File 'lib/fluent/plugin/output.rb', line 740

def try_rollback_write
  @dequeued_chunks_mutex.synchronize do
    while @dequeued_chunks.first && @dequeued_chunks.first.expired?
      info = @dequeued_chunks.shift
      if @buffer.takeback_chunk(info.chunk_id)
        @counters_monitor.synchronize{ @rollback_count += 1 }
        log.warn "failed to flush the buffer chunk, timeout to commit.", plugin_id: plugin_id, chunk_id: dump_unique_id_hex(info.chunk_id), flushed_at: info.time
      end
    end
  end
end

#try_write(chunk) ⇒ Object

Raises:

  • (NotImplementedError) 


112
113
114
 
# File 'lib/fluent/plugin/output.rb', line 112

def try_write(chunk)
  raise NotImplementedError, "BUG: output plugins MUST implement this method"
end

#write(chunk) ⇒ Object

Raises:

  • (NotImplementedError) 


108
109
110
 
# File 'lib/fluent/plugin/output.rb', line 108

def write(chunk)
  raise NotImplementedError, "BUG: output plugins MUST implement this method"
end

#write_guard(&block) ⇒ Object 



600
601
602
603
604
605
606
607
608
609
610
611
612
613
614
615
616
617
618
619
620
621
622
623
624
625
626
627
628
629
630
631
632
633
 
# File 'lib/fluent/plugin/output.rb', line 600

def write_guard(&block)
  begin
    block.call
  rescue Fluent::Plugin::Buffer::BufferOverflowError
    log.warn "failed to write data into buffer by buffer overflow"
    case @buffer_config.overflow_action
    when :throw_exception
      raise
    when :block
      log.debug "buffer.write is now blocking"
      until @buffer.storable?
        sleep 1
      end
      log.debug "retrying buffer.write after blocked operation"
      retry
    when :drop_oldest_chunk
      begin
        oldest = @buffer.dequeue_chunk
        if oldest
          log.warn "dropping oldest chunk to make space after buffer overflow", chunk_id: oldest.unique_id
          @buffer.purge_chunk(oldest.unique_id)
        else
          log.error "no queued chunks to be dropped for drop_oldest_chunk"
        end
      rescue
        # ignore any errors
      end
      raise unless @buffer.storable?
      retry
    else
      raise "BUG: unknown overflow_action '#{@buffer_config.overflow_action}'"
    end
  end
end