Class: LogStash::Outputs::Scalyr

Inherits:
Base
  • Object
show all
Defined in:
lib/logstash/outputs/scalyr.rb

Overview

Implements the Scalyr output plugin

Instance Method Summary collapse

Constructor Details

#initialize(*params) ⇒ Scalyr

Returns a new instance of Scalyr.



183
184
185
186
187
188
 
# File 'lib/logstash/outputs/scalyr.rb', line 183

def initialize(*params)
  super
  # Request statistics are accumulated across multiple threads and must be accessed through a mutex
  @stats_lock = Mutex.new
  @send_stats = Mutex.new
end

Instance Method Details

#add_client_timestamp_to_body(body) ⇒ Object

Helper method that adds a client_timestamp to a batch addEvents request body



849
850
851
852
853
854
 
# File 'lib/logstash/outputs/scalyr.rb', line 849

def add_client_timestamp_to_body(body)
  current_time_millis = DateTime.now.strftime('%Q').to_i
  # echee TODO scalyr_agent code suggests this should be "client_time", not "client_timestamp"
  # however, I cannot find any documentation anywhere. Is it even used?
  body[:client_timestamp] = current_time_millis.to_s
end

#build_multi_event_request_array(logstash_events) ⇒ Object

Builds an array of multi-event requests from LogStash events Each array element is a request that groups multiple events (to be posted to Scalyr’s addEvents endpoint)

This function also performs data transformations to support special fields and, optionally, flatten JSON values.

Special fields are those that have special semantics to Scalyr, i.e. ‘message’ contains the main log message, ‘serverHost’ and ‘logfile’ have a dedicated search boxes to facilitate filtering. All Logstash event key/values will be marshalled into a Scalyr addEvents ‘attr` key/value unless they are identified as alternate names for special fields. The special fields (’message’, ‘serverHost’, ‘logfile’) may be remapped from other fields (configured by setting ‘message_field’, ‘serverhost_field’, ‘logfile_field’)

Values that are nested JSON may be optionally flattened (See README.md for some examples).

Certain fields are removed (e.g. @timestamp and @version)

Tags are either propagated as a comma-separated string, or optionally transposed into key-values where the keys are tag names and the values are 1 (may be configured.)



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
589
590
591
592
593
594
595
596
597
598
599
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
634
635
636
637
638
639
640
641
642
643
644
645
646
647
648
649
650
651
652
653
654
655
656
657
658
659
660
661
662
663
664
665
666
667
668
669
670
671
672
673
674
675
676
677
678
679
680
681
682
683
684
685
686
687
688
689
690
691
692
693
694
695
696
697
698
699
700
701
702
703
704
705
706
707
708
709
710
711
712
713
714
715
716
717
718
719
720
721
722
723
724
725
726
727
728
729
730
731
732
733
734
735
736
737
738
739
740
741
742
743
744
745
746
747
748
749
750
751
752
753
754
755
756
757
758
759
760
761
762
763
764
765
766
767
768
769
770
771
772
773
774
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
845
846
 
# File 'lib/logstash/outputs/scalyr.rb', line 558

def build_multi_event_request_array(logstash_events)
  if logstash_events.nil? or logstash_events.empty?
   return []
  end

  multi_event_request_array = Array.new
  total_bytes = 0
  # Set of unique scalyr threads for this chunk
  current_threads = Hash.new
  # Create a Scalyr event object for each record in the chunk
  scalyr_events = Array.new
  # Track the logstash events in each chunk to send them to the dlq in case of an error
  l_events = Array.new

  thread_ids = Hash.new
  next_id = 1 #incrementing thread id for the session

  # per-logfile attributes
  logs = Hash.new
  logs_ids = Hash.new
  next_log_id = 1

  batch_has_event_level_server_host = false

  logstash_events.each {|l_event|

    record = l_event.to_hash

    # Create optional threads hash if serverHost is non-nil
    # echee: TODO I don't think threads are necessary.  Too much info?
    # they seem to be a second level of granularity within a logfile
    serverHost = record.fetch(@serverhost_field, nil)

    if serverHost
      # get thread id or add a new one if we haven't seen this serverHost before
      if thread_ids.key? serverHost
        thread_id = thread_ids[serverHost]
      else
        thread_id = next_id
        thread_ids[serverHost] = thread_id
        next_id += 1
      end
      # then update the map of threads for this chunk
      current_threads[serverHost] = thread_id
    end

    rename = lambda do |renamed_field, standard_field|
      if standard_field != renamed_field
        if record.key? renamed_field
          if record.key? standard_field
            @logger.warn "Overwriting log record field '#{standard_field}'.  You are seeing this warning because in " +
            "your LogStash config file you have configured the '#{renamed_field}' field to be converted to the " +
            "'#{standard_field}' field, but the event already contains a field called '#{standard_field}' and "
            "this is now being overwritten."
          end
          record[standard_field] = record[renamed_field]
          record.delete(renamed_field)
        end
      end
    end

    # Rename user-specified message field -> 'message'
    rename.call(@message_field, 'message')
    # Fix message encoding
    if @message_encoding and !record['message'].to_s.empty?
      if @replace_invalid_utf8 and @message_encoding == Encoding::UTF_8
        record["message"] = record["message"].encode("UTF-8", :invalid => :replace,
                                                     :undef => :replace, :replace => "<?>").force_encoding('UTF-8')
      else
        record["message"].force_encoding(@message_encoding)
      end
    end

    # Rename user-specified serverHost field -> 'serverHost'
    rename.call(@serverhost_field, 'serverHost')

    # Rename user-specified logfile field -> 'logfile'
    rename.call(@logfile_field, 'logfile')

    # Remove "host" attribute
    if @remove_host_attribute_from_events and record.key? "host"
      record.delete("host")
    end

    # Set a default parser is none is present in the event
    if record['parser'].to_s.empty?
      record['parser'] = "logstashParser"
    end

    # Set logfile field if empty and serverHost is supplied
    if record['logfile'].to_s.empty? and serverHost
      record['logfile'] = "/logstash/#{serverHost}"
    end

    # Rename serverHost (if exists) to __origServerHost so sources filtering works correctly
    # It's important that this happens at the very end of the event processing in this function.
    record_has_server_host_attribute = record.key? 'serverHost'
    batch_has_event_level_server_host |= record_has_server_host_attribute

    if record_has_server_host_attribute
      record[EVENT_LEVEL_SERVER_HOST_ATTRIBUTE_NAME] = record['serverHost']
      record.delete('serverHost')
    end

    # To reduce duplication of common event-level attributes, we "fold" them into top-level "logs" attribute
    # and reference log entry inside the event
    log_identifier = nil
    add_log = false
    if serverHost
     log_identifier = serverHost + record['logfile']
    end

    if log_identifier and not logs.key? log_identifier
      add_log = true
      logs[log_identifier] = {
        'id' => next_log_id,
        'attrs' => Hash.new
      }

      if not record['logfile'].to_s.empty?
        logs[log_identifier]['attrs']['logfile'] = record['logfile']
        record.delete('logfile')
      end
      if @log_constants
        @log_constants.each {|log_constant|
          if record.key? log_constant
            logs[log_identifier]['attrs'][log_constant] = record[log_constant]
            record.delete(log_constant)
          end
        }
      end

      logs_ids[log_identifier] = next_log_id
      next_log_id += 1
    end

    # If we already contain "logs" entry for this record, we remove duplicated serverHost from
    # the event attributes since it's already part of the log level attributes which are
    # referenced by the event.
    if log_identifier and logs.key? log_identifier
      if not record[EVENT_LEVEL_SERVER_HOST_ATTRIBUTE_NAME].to_s.empty?
        logs[log_identifier]['attrs'][EVENT_LEVEL_SERVER_HOST_ATTRIBUTE_NAME] = record[EVENT_LEVEL_SERVER_HOST_ATTRIBUTE_NAME]
        record.delete(EVENT_LEVEL_SERVER_HOST_ATTRIBUTE_NAME)
      end
    end

    # Delete unwanted fields from record
    record.delete('@version')
    record.delete('@timestamp')

    # flatten tags
    if @flatten_tags and record.key? 'tags'
      record['tags'].each do |tag|
        record["#{@flat_tag_prefix}#{tag}"] = @flat_tag_value
      end
      record.delete('tags')
    end

    # Record per-event level metrics (flatten duration, event attributes count). Doing this for every single
    # event would be somewhat expensive so we use sampling.
    should_sample_event_metrics = should_sample?

    # flatten record
    if @flatten_nested_values
      start_time = Time.now.to_f
      begin
        record = Scalyr::Common::Util.flatten(record, delimiter=@flatten_nested_values_delimiter, flatten_arrays=@flatten_nested_arrays, fix_deep_flattening_delimiters=@fix_deep_flattening_delimiters, max_key_count=@flattening_max_key_count)
      rescue Scalyr::Common::Util::MaxKeyCountError => e
        @logger.warn("Error while flattening record", :error_message => e.message, :sample_keys => e.sample_keys)
      end
      end_time = Time.now.to_f
      flatten_nested_values_duration = end_time - start_time
    end

    if should_sample_event_metrics
      @stats_lock.synchronize do
        @plugin_metrics[:event_attributes_count].observe(record.count)

        if @flatten_nested_values
          @plugin_metrics[:flatten_values_duration_secs].observe(flatten_nested_values_duration)
        end
      end
    end

    # Use LogStash event.timestamp as the 'ts' Scalyr timestamp.  Note that this may be overwritten by input
    # filters so may not necessarily reflect the actual originating timestamp.
    scalyr_event = {
      :ts => (l_event.timestamp.time.to_f * (10**9)).round,
      :attrs => record
    }

    # optionally set thread and referenced log file
    if serverHost
      scalyr_event[:thread] = thread_id.to_s
      scalyr_event[:log] = logs_ids[log_identifier]
    end

    if @estimate_each_event_size
      # get json string of event to keep track of how many bytes we are sending
      begin
        event_json = self.json_encode(scalyr_event)
        log_json = nil
        if add_log
          log_json = self.json_encode(logs[log_identifier])
        end
      rescue JSON::GeneratorError, Encoding::UndefinedConversionError => e
        @logger.warn "#{e.class}: #{e.message}"

        # Send the faulty event to a label @ERROR block and allow to handle it there (output to exceptions file for ex)
        # TODO
        # atime = Fluent::EventTime.new( sec, nsec )
        # router.emit_error_event(serverHost, time, record, e)

        scalyr_event[:attrs].each do |key, value|
          @logger.debug "\t#{key} (#{value.encoding.name}): '#{value}'"
          scalyr_event[:attrs][key] = value.encode(
              "UTF-8", :invalid => :replace, :undef => :replace, :replace => "<?>"
          ).force_encoding('UTF-8')
        end
        event_json = self.json_encode(scalyr_event)
      rescue Java::JavaLang::ClassCastException => e
        # Most likely we ran into the issue described here: https://github.com/flori/json/issues/336
        # Because of the version of jruby logstash works with we don't have the option to just update this away,
        # so if we run into it we convert bignums into strings so we can get the data in at least.
        # This is fixed in JRuby 9.2.7, which includes json 2.2.0
        @logger.warn("Error serializing events to JSON, likely due to the presence of Bignum values. Converting Bignum values to strings.")
        @stats_lock.synchronize do
          @multi_receive_statistics[:total_java_class_cast_errors] += 1
        end
        Scalyr::Common::Util.convert_bignums(scalyr_event)
        event_json = self.json_encode(scalyr_event)
        log_json = nil
        if add_log
          log_json = self.json_encode(logs[log_identifier])
        end
      end

      # generate new request if json size of events in the array exceed maximum request buffer size
      append_event = true
      add_bytes = event_json.bytesize
      if log_json
        add_bytes = add_bytes + log_json.bytesize
      end

      if total_bytes + add_bytes > @max_request_buffer
        # make sure we always have at least one event
        if scalyr_events.size == 0
          scalyr_events << scalyr_event
          l_events << l_event
          append_event = false
        end

        Scalyr::Common::Util.set_session_level_serverhost_on_events(@session_server_host, scalyr_events, logs, batch_has_event_level_server_host)
        multi_event_request = self.create_multi_event_request(scalyr_events, l_events, current_threads, logs, batch_has_event_level_server_host)
        multi_event_request_array << multi_event_request

        total_bytes = 0
        current_threads = Hash.new
        logs = Hash.new
        logs_ids = Hash.new
        scalyr_events = Array.new
        l_events = Array.new
        batch_has_event_level_server_host = false
      end
    else
      # If size estimation is disabled we simply append the event and handle splitting later on (if needed)
      append_event = true
      add_bytes = 0
    end

    # if we haven't consumed the current event already
    # add it to the end of our array and keep track of the json bytesize
    if append_event
      scalyr_events << scalyr_event
      l_events << l_event
      total_bytes += add_bytes
    end

  }

  # create a final request with any left over events (and make sure there is at least one event)
  if scalyr_events.size >= 1
    Scalyr::Common::Util.set_session_level_serverhost_on_events(@session_server_host, scalyr_events, logs, batch_has_event_level_server_host)
    multi_event_request = self.create_multi_event_request(scalyr_events, l_events, current_threads, logs, batch_has_event_level_server_host)
    multi_event_request_array << multi_event_request
  end

  multi_event_request_array
end

#close ⇒ Object 



190
191
192
193
 
# File 'lib/logstash/outputs/scalyr.rb', line 190

def close
  @running = false
  @client_session.close if @client_session
end

#create_multi_event_request(scalyr_events, logstash_events, current_threads, current_logs, batch_has_event_level_server_host = false) ⇒ Object

A request comprises multiple Scalyr Events. This function creates a request hash for final upload to Scalyr (from an array of events, and an optional hash of current threads) Note: The request body field will be json-encoded.



860
861
862
863
864
865
866
867
868
869
870
871
872
873
874
875
876
877
878
879
880
881
882
883
884
885
886
887
888
889
890
891
892
893
894
895
896
897
898
899
900
901
902
903
904
905
906
907
908
909
910
911
912
913
914
915
916
917
918
919
920
921
922
923
924
925
 
# File 'lib/logstash/outputs/scalyr.rb', line 860

def create_multi_event_request(scalyr_events, logstash_events, current_threads, current_logs, batch_has_event_level_server_host = false)

  body = {
    :session => @session_id + Thread.current.object_id.to_s,
    :token => @api_write_token,
    :events => scalyr_events,
  }

  add_client_timestamp_to_body body

  # build the scalyr thread JSON object
  if current_threads
    threads = Array.new
    current_threads.each do |thread_name, id|
      threads << { :id => id.to_s, :name => "LogStash: #{thread_name}" }
    end
    body[:threads] = threads
  end

  # build the scalyr thread logs object
  if current_logs
    logs = Array.new
    current_logs.each do |identifier, log|
      logs << log
    end
    body[:logs] = logs
  end

  # add serverAttributes
  # If serverHost is defined on any of the events, we don't send it via sessionInfo since
  # sesionInfo has the higest priority and would always overwritte the event level one
  if batch_has_event_level_server_host
    body[:sessionInfo] = @server_attributes_without_serverhost if @server_attributes_without_serverhost
  else
    body[:sessionInfo] = @server_attributes if @server_attributes
  end

  # We time serialization to get some insight on how long it takes to serialize the request body
  start_time = Time.now.to_f
  begin
    serialized_body = self.json_encode(body)
  rescue Java::JavaLang::ClassCastException => e
    @logger.warn("Error serializing events to JSON, likely due to the presence of Bignum values. Converting Bignum values to strings.")
    @stats_lock.synchronize do
      @multi_receive_statistics[:total_java_class_cast_errors] += 1
    end
    Scalyr::Common::Util.convert_bignums(body)
    serialized_body = self.json_encode(body)
  end
  end_time = Time.now.to_f
  serialization_duration = end_time - start_time

  serialized_request_size = serialized_body.bytesize

  # We give it "buffer" since the splitting code allows for some slack and doesn't take into account top-level non-event attributes
  if not @estimate_each_event_size and serialized_request_size >= @max_request_buffer + 5000
    # TODO: If we end up here is estimate config opsion is false, split the request here into multiple ones
    @logger.warn("Serialized request size (#{serialized_request_size}) is larger than max_request_buffer (#{max_request_buffer})!")
  end

  {
    :body => serialized_body, :record_count => scalyr_events.size, :serialization_duration => serialization_duration,
    :logstash_events => logstash_events
  }

end

#dlq_enabled? ⇒ Boolean

Helper method to check if the dead-letter queue is enabled

Returns:

  • (Boolean) 


1078
1079
1080
1081
1082
 
# File 'lib/logstash/outputs/scalyr.rb', line 1078

def dlq_enabled?
  # echee TODO submit to DLQ
  respond_to?(:execution_context) && execution_context.respond_to?(:dlq_writer) &&
      !execution_context.dlq_writer.inner_writer.is_a?(::LogStash::Util::DummyDeadLetterQueueWriter)
end

#get_new_metrics ⇒ Object

Convenience method to create a fresh quantile estimator



347
348
349
350
351
352
353
354
355
356
 
# File 'lib/logstash/outputs/scalyr.rb', line 347

def get_new_metrics
  return {
    :build_multi_duration_secs => Quantile::Estimator.new,
    :multi_receive_duration_secs => Quantile::Estimator.new,
    :multi_receive_event_count => Quantile::Estimator.new,
    :event_attributes_count => Quantile::Estimator.new,
    :flatten_values_duration_secs => Quantile::Estimator.new,
    :batches_per_multi_receive => Quantile::Estimator.new
  }
end

#get_sleep_sec(current_interval) ⇒ Object

Helper method that gets the next sleep time for exponential backoff, capped at a defined maximum



1071
1072
1073
1074
 
# File 'lib/logstash/outputs/scalyr.rb', line 1071

def get_sleep_sec(current_interval)
  doubled = current_interval * 2
  doubled > @retry_max_interval ? @retry_max_interval : doubled
end

#get_stats ⇒ Object

Retrieve batch and other event level metric values



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
 
# File 'lib/logstash/outputs/scalyr.rb', line 929

def get_stats
  @stats_lock.synchronize do
    current_stats = @multi_receive_statistics.clone

    current_stats[:build_multi_duration_secs_p50] = @plugin_metrics[:build_multi_duration_secs].query(0.5)
    current_stats[:build_multi_duration_secs_p90] = @plugin_metrics[:build_multi_duration_secs].query(0.9)
    current_stats[:build_multi_duration_secs_p99] = @plugin_metrics[:build_multi_duration_secs].query(0.99)

    current_stats[:multi_receive_duration_p50] = @plugin_metrics[:multi_receive_duration_secs].query(0.5)
    current_stats[:multi_receive_duration_p90] = @plugin_metrics[:multi_receive_duration_secs].query(0.9)
    current_stats[:multi_receive_duration_p99] = @plugin_metrics[:multi_receive_duration_secs].query(0.99)

    current_stats[:multi_receive_event_count_p50] = @plugin_metrics[:multi_receive_event_count].query(0.5)
    current_stats[:multi_receive_event_count_p90] = @plugin_metrics[:multi_receive_event_count].query(0.9)
    current_stats[:multi_receive_event_count_p99] = @plugin_metrics[:multi_receive_event_count].query(0.99)

    current_stats[:event_attributes_count_p50] = @plugin_metrics[:event_attributes_count].query(0.5)
    current_stats[:event_attributes_count_p90] = @plugin_metrics[:event_attributes_count].query(0.9)
    current_stats[:event_attributes_count_p99] = @plugin_metrics[:event_attributes_count].query(0.99)

    current_stats[:batches_per_multi_receive_p50] = @plugin_metrics[:batches_per_multi_receive].query(0.5)
    current_stats[:batches_per_multi_receive_p90] = @plugin_metrics[:batches_per_multi_receive].query(0.9)
    current_stats[:batches_per_multi_receive_p99] = @plugin_metrics[:batches_per_multi_receive].query(0.99)

    if @flatten_nested_values
      # We only return those metrics in case flattening is enabled
      current_stats[:flatten_values_duration_secs_p50] = @plugin_metrics[:flatten_values_duration_secs].query(0.5)
      current_stats[:flatten_values_duration_secs_p90] = @plugin_metrics[:flatten_values_duration_secs].query(0.9)
      current_stats[:flatten_values_duration_secs_p99] = @plugin_metrics[:flatten_values_duration_secs].query(0.99)
    end

    if @flush_quantile_estimates_on_status_send
      @logger.debug "Recreating / reseting quantile estimator classes for plugin metrics"
      @plugin_metrics = get_new_metrics
    end

    current_stats
  end
end

#log_retry_failure(multi_event_request, exc_data, exc_retries, exc_sleep) ⇒ Object 



520
521
522
523
524
525
526
527
528
529
530
531
532
533
534
535
536
537
538
 
# File 'lib/logstash/outputs/scalyr.rb', line 520

def log_retry_failure(multi_event_request, exc_data, exc_retries, exc_sleep)
  @stats_lock.synchronize do
    @multi_receive_statistics[:total_events_processed] += multi_event_request[:logstash_events].length
    @multi_receive_statistics[:failed_events_processed] += multi_event_request[:logstash_events].length
  end
  message = "Failed to send #{multi_event_request[:logstash_events].length} events after #{exc_retries} tries."
  sample_events = Array.new
  multi_event_request[:logstash_events][0,5].each {|l_event|
    sample_events << Scalyr::Common::Util.truncate(l_event.to_hash.to_json, 256)
  }
  @logger.error(message, :error_data => exc_data, :sample_events => sample_events, :retries => exc_retries, :sleep_time => exc_sleep)
  if @dlq_writer
    multi_event_request[:logstash_events].each {|l_event|
      @dlq_writer.write(l_event, "#{exc_data[:message]}")
    }
  else
    @logger.warn("Dead letter queue not configured, dropping #{multi_event_request[:logstash_events].length} events after #{exc_retries} tries.", :sample_events => sample_events)
  end
end

#multi_receive(events) ⇒ Object 



369
370
371
372
373
374
375
376
377
378
379
380
381
382
383
384
385
386
387
388
389
390
391
392
393
394
395
396
397
398
399
400
401
402
403
404
405
406
407
408
409
410
411
412
413
414
415
416
417
418
419
420
421
422
423
424
425
426
427
428
429
430
431
432
433
434
435
436
437
438
439
440
441
442
443
444
445
446
447
448
449
450
451
452
453
454
455
456
457
458
459
460
461
462
463
464
465
466
467
468
469
470
471
472
473
474
475
476
477
478
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
512
513
514
515
516
517
 
# File 'lib/logstash/outputs/scalyr.rb', line 369

def multi_receive(events)
  # Just return and pretend we did something if running in noop mode
  return events if @noop_mode

  begin
    records_count = events.to_a.length

    # We also time the duration of the build_multi_event_request_array method. To avoid locking twice,
    # we store the duration value here and record metric at the end.
    start_time = Time.now.to_f

    multi_event_request_array = build_multi_event_request_array(events)
    build_multi_duration_secs = Time.now.to_f - start_time

    # Loop over all array of multi-event requests, sending each multi-event to Scalyr
    sleep_interval = @retry_initial_interval
    batch_num = 1
    total_batches = multi_event_request_array.length unless multi_event_request_array.nil?

    result = []

    while !multi_event_request_array.to_a.empty?
      multi_event_request = multi_event_request_array.pop
      # Variables to hold information about exceptions we run into, and our handling of retries for this request. We
      # track this to log it when the retries succeed so we can be sure logs are going through.
      # General exception info we log in the error
      exc_data = nil
      # Whether the exception is commonly retried or not, for determining log level
      exc_commonly_retried = false
      # Count of retries attempted for this request
      exc_retries = 0
      # Total time spent sleeping while retrying this request due to backoff
      exc_sleep = 0
      begin
        # For some reason a retry on the multi_receive may result in the request array containing `nil` elements, we
        # ignore these.
        if !multi_event_request.nil?
          @client_session.post_add_events(multi_event_request[:body], false, multi_event_request[:serialization_duration])

          sleep_interval = @retry_initial_interval
          batch_num += 1
          result.push(multi_event_request)
        end

      rescue Scalyr::Common::Client::ServerError, Scalyr::Common::Client::ClientError => e
        sleep_interval = sleep_for(sleep_interval)
        exc_sleep += sleep_interval
        exc_retries += 1
        @stats_lock.synchronize do
          @multi_receive_statistics[:total_retry_count] += 1
        end
        message = "Error uploading to Scalyr (will backoff-retry)"
        exc_data = {
            :error_class => e.e_class,
            :url => e.url.to_s,
            :message => e.message,
            :batch_num => batch_num,
            :total_batches => total_batches,
            :record_count => multi_event_request[:record_count],
            :payload_size => multi_event_request[:body].bytesize,
            :will_retry_in_seconds => sleep_interval,
        }
        exc_data[:code] = e.code if e.code
        if @logger.debug? and e.body
          exc_data[:body] = e.body
        elsif e.body
          exc_data[:body] = Scalyr::Common::Util.truncate(e.body, 512)
        end
        exc_data[:payload] = "\tSample payload: #{request[:body][0,1024]}..." if @logger.debug?
        if e.is_commonly_retried?
          # well-known retriable errors should be debug
          @logger.debug(message, exc_data)
          exc_commonly_retried = true
        else
          # all other failed uploads should be errors
          @logger.error(message, exc_data)
          exc_commonly_retried = false
        end
        retry if @running and exc_retries < @max_retries
        log_retry_failure(multi_event_request, exc_data, exc_retries, exc_sleep)
        next

      rescue => e
        # Any unexpected errors should be fully logged
        @logger.error(
            "Unexpected error occurred while uploading to Scalyr (will backoff-retry)",
            :error_message => e.message,
            :error_class => e.class.name,
            :backtrace => e.backtrace
        )
        @logger.debug("Failed multi_event_request", :multi_event_request => multi_event_request)
        sleep_interval = sleep_for(sleep_interval)
        exc_data = {
          :error_message => e.message,
          :error_class => e.class.name,
          :backtrace => e.backtrace,
          :multi_event_request => multi_event_request
        }
        exc_sleep += sleep_interval
        exc_retries += 1
        @stats_lock.synchronize do
          @multi_receive_statistics[:total_retry_count] += 1
        end
        retry if @running and exc_retries < @max_retries
        log_retry_failure(multi_event_request, exc_data, exc_retries, exc_sleep)
        next
      end

      @stats_lock.synchronize do
        @multi_receive_statistics[:total_events_processed] += multi_event_request[:logstash_events].length
        @multi_receive_statistics[:successful_events_processed] += multi_event_request[:logstash_events].length
      end

      if !exc_data.nil?
        message = "Retry successful after error."
        if exc_commonly_retried
          @logger.debug(message, :error_data => exc_data, :retries => exc_retries, :sleep_time => exc_sleep)
        else
          @logger.info(message, :error_data => exc_data, :retries => exc_retries, :sleep_time => exc_sleep)
        end
      end
    end

    if records_count > 0
      @stats_lock.synchronize do
        @multi_receive_statistics[:total_multi_receive_secs] += (Time.now.to_f - start_time)
        @plugin_metrics[:build_multi_duration_secs].observe(build_multi_duration_secs)
        @plugin_metrics[:multi_receive_duration_secs].observe(Time.now.to_f - start_time)
        @plugin_metrics[:multi_receive_event_count].observe(records_count)
        @plugin_metrics[:batches_per_multi_receive].observe(total_batches)
      end
    end

    if @report_status_for_empty_batches or records_count > 0
      send_status
    end

    return result

  rescue => e
    # Any unexpected errors should be fully logged
    @logger.error(
        "Unexpected error occurred while executing multi_receive.",
        :error_message => e.message,
        :error_class => e.class.name,
        :backtrace => e.backtrace
    )
  end
end

#register ⇒ Object 



196
197
198
199
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
313
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
 
# File 'lib/logstash/outputs/scalyr.rb', line 196

def register
  # This prng is used exclusively to determine when to sample statistics and no security related purpose, for this
  # reason we do not ensure thread safety for it.
  @prng = Random.new

  if @event_metrics_sample_rate < 0 or @event_metrics_sample_rate > 1
    raise LogStash::ConfigurationError, "Minimum possible value for 'event_metrics_sample_rate' is 0 (dont sample any events) and maximum is 1 (sample every event)"
  end

  @node_hostname = Socket.gethostname

  if @log_constants and not @log_constants.all? { |x| x.is_a? String }
    raise LogStash::ConfigurationError, "All elements of 'log_constants' must be strings."
  end

  if @max_request_buffer > 6000000
    @logger.warn "Maximum request buffer > 6 MB.  This may result in requests being rejected by Scalyr."
  end

  if not @estimate_each_event_size
    @logger.warn("estimate_each_event_size config option is false, this means very large batches may be rejected or partially processed by the server")
  end

  if @json_library != "stdlib" and @json_library != "jrjackson"
    raise LogStash::ConfigurationError, "json_library config option needs to be either stdlib or jrjackson"
  end

  if @json_library == "stdlib"
    define_singleton_method "json_encode" do |data|
      data.to_json
    end
  elsif @json_library == "jrjackson"
    define_singleton_method "json_encode" do |data|
      JrJackson::Json.dump(data)
    end
  end

  @dlq_writer = dlq_enabled? ? execution_context.dlq_writer : nil

  @message_encoding = nil
  if @force_message_encoding.to_s != ''
    begin
      @message_encoding = Encoding.find(@force_message_encoding)
      @logger.debug "Forcing message encoding to '#{@force_message_encoding}'"
    rescue ArgumentError
      @logger.warn "Encoding '#{@force_message_encoding}' not found. Ignoring."
    end
  end

  #evaluate any statements in string value of the server_attributes object
  if @server_attributes
    new_attributes = {}
    @server_attributes.each do |key, value|
      if value.is_a?( String )
        m = /^\#{(.*)}$/.match( value )
        if m
          new_attributes[key] = eval( m[1] )
        else
          new_attributes[key] = value
        end
      end
    end
    @server_attributes = new_attributes
  end

  # See if we should use the hostname as the server_attributes.serverHost (aka if fixed serverHost is not
  # defined as part of server_attributes config option)
  if @server_attributes.nil?
      @server_attributes = {}
  end

  if @use_hostname_for_serverhost
    # only set serverHost if it doesn't currently exist in server_attributes
    # Note: Use strings rather than symbols for the key, because keys coming
    # from the config file will be strings
    unless @server_attributes.key? 'serverHost'
      @server_attributes['serverHost'] = @node_hostname
    end
  end

  # Add monitor server attribute to identify this as coming from a plugin
  @server_attributes['monitor'] = 'pluginLogstash'

  # We create a fixed copy without host here so we can reference this later if needed to avoid
  # some of the copy + manipulate overhead per batch
  @server_attributes_without_serverhost = @server_attributes.clone
  if @server_attributes_without_serverhost.key? "serverHost"
    @server_attributes_without_serverhost.delete "serverHost"
  end

  @session_server_host = @server_attributes["serverHost"]

  @scalyr_server << '/' unless @scalyr_server.end_with?('/')

  @add_events_uri = URI(@scalyr_server) + "addEvents"

  @logger.info "Scalyr LogStash Plugin ID - #{self.id}"

  @session_id = SecureRandom.uuid
  @last_status_transmit_time_lock = Mutex.new
  @last_status_transmit_time = nil
  @last_status_ = false

  # Plugin level (either per batch or event level metrics). Other request
  # level metrics are handled by the HTTP Client class.
  @multi_receive_statistics = {
    :total_multi_receive_secs => 0,
    :total_events_processed => 0,
    :successful_events_processed => 0,
    :failed_events_processed => 0,
    :total_retry_count => 0,
    :total_java_class_cast_errors => 0
  }
  @plugin_metrics = get_new_metrics

  # create a client session for uploading to Scalyr
  @running = true
  @client_session = Scalyr::Common::Client::ClientSession.new(
      @logger, @add_events_uri,
      @compression_type, @compression_level, @ssl_verify_peer, @ssl_ca_bundle_path, @append_builtin_cert,
      @record_stats_for_status, @flush_quantile_estimates_on_status_send,
      @http_connect_timeout, @http_socket_timeout, @http_request_timeout, @http_pool_max, @http_pool_max_per_route
  )

  @logger.info(sprintf("Started Scalyr LogStash output plugin %s (compression_type=%s,compression_level=%s,json_library=%s)." %
                       [PLUGIN_VERSION, @compression_type, @compression_type, @json_library]), :class => self.class.name)

  # Finally, send a status line to Scalyr
  # We use a special separate short lived client session for sending the initial client status.
  # This is done to avoid the overhead in case single logstash instance has many scalyr output 
  # plugins configured with conditionals and majority of them are inactive (aka receive no data).
  # This way we don't need to keep idle long running connection open.
  initial_send_status_client_session = Scalyr::Common::Client::ClientSession.new(
      @logger, @add_events_uri,
      @compression_type, @compression_level, @ssl_verify_peer, @ssl_ca_bundle_path, @append_builtin_cert,
      @record_stats_for_status, @flush_quantile_estimates_on_status_send,
      @http_connect_timeout, @http_socket_timeout, @http_request_timeout, @http_pool_max, @http_pool_max_per_route
  )
  send_status(initial_send_status_client_session)
  initial_send_status_client_session.close

  # We also "prime" the main HTTP client here, one which is used for sending subsequent requests.
  # Here priming just means setting up the client parameters without opening any connections.
  # Since client writes certs to a temporary file there could be a race in case we don't do that
  # here since multi_receive() is multi threaded. An alternative would be to put a look around
  # client init method (aka client_config())
  @client_session.client

end

#send_status(client_session = nil) ⇒ Object

Sends a status update to Scalyr by posting a log entry under the special logfile of ‘logstash_plugin.log’ Instead of creating a separate thread, let this method be invoked once at startup and then every 5 minutes at most. (If no events are received, no status update will be sent even if 5 minutes has elapsed). Finally, note that there could be multiple instances of this plugin (one per worker), in which case each worker thread sends their own status updates. This is intentional so that we know how much data each worker thread is uploading to Scalyr over time.



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
1018
1019
1020
1021
1022
1023
1024
1025
1026
1027
1028
1029
1030
1031
1032
1033
1034
1035
1036
1037
1038
1039
1040
1041
1042
 
# File 'lib/logstash/outputs/scalyr.rb', line 976

def send_status(client_session = nil)
  client_session = @client_session if client_session.nil?

  status_event = {
    :ts => (Time.now.to_f * (10**9)).round,
    :attrs => {
      'logfile' => "scalyr_logstash.log",
      'plugin_id' => self.id,
    }
  }
  @send_stats.synchronize do
    if !@last_status_transmit_time
      status_event[:attrs]['message'] = sprintf("Started Scalyr LogStash output plugin %s (compression_type=%s,compression_level=%s,json_library=%s)." %
                                                [PLUGIN_VERSION, @compression_type, @compression_type, @json_library])
      status_event[:attrs][EVENT_LEVEL_SERVER_HOST_ATTRIBUTE_NAME] = @node_hostname
    else
      cur_time = Time.now()
      return if (cur_time.to_i - @last_status_transmit_time.to_i) < @status_report_interval
      # echee TODO: get instance stats from session and create a status log line
      msg = 'plugin_status: '
      cnt = 0
      client_session.get_stats.each do |k, v|
        val = v.instance_of?(Float) ? sprintf("%.4f", v) : v
        val = val.nil? ? 0 : val
        msg << ' ' if cnt > 0
        msg << "#{k.to_s}=#{val}"
        cnt += 1
      end
      get_stats.each do |k, v|
        val = v.instance_of?(Float) ? sprintf("%.4f", v) : v
        val = val.nil? ? 0 : val
        msg << ' ' if cnt > 0
        msg << "#{k.to_s}=#{val}"
        cnt += 1
      end
      status_event[:attrs]['message'] = msg
      status_event[:attrs][EVENT_LEVEL_SERVER_HOST_ATTRIBUTE_NAME] = @node_hostname
      status_event[:attrs]['parser'] = @status_parser
    end
    multi_event_request = create_multi_event_request([status_event], nil, nil, nil)
    begin
      client_session.post_add_events(multi_event_request[:body], true, 0)
    rescue => e
      if e.body
        @logger.warn(
          "Unexpected error occurred while uploading status to Scalyr",
          :error_message => e.message,
          :error_class => e.class.name,
          :body => Scalyr::Common::Util.truncate(e.body, 512)
        )
      else
        @logger.warn(
          "Unexpected error occurred while uploading status to Scalyr",
          :error_message => e.message,
          :error_class => e.class.name
        )
      end
      return
    end
    @last_status_transmit_time = Time.now()
  end

  if @log_status_messages_to_stdout
    @logger.info msg
  end
  status_event
end

#should_sample? ⇒ Boolean

Returns true if we should sample and record metrics for a specific event based on the sampling rate and random value

Returns:

  • (Boolean) 


1046
1047
1048
 
# File 'lib/logstash/outputs/scalyr.rb', line 1046

def should_sample?
  return @prng.rand(0.0..1.0) < @event_metrics_sample_rate
end

#should_transmit_status? ⇒ Boolean

Returns true if it is time to transmit status

Returns:

  • (Boolean) 


1052
1053
1054
1055
1056
1057
1058
1059
1060
 
# File 'lib/logstash/outputs/scalyr.rb', line 1052

def should_transmit_status?
  @last_status_transmit_time_lock.synchronize do
    saved_last_time = @last_status_transmit_time
    if Time.now.to_i - saved_last_time.to_i > @status_report_interval
      @last_status_transmit_time = Float::INFINITY
      return saved_last_time
    end
  end
end

#sleep_for(sleep_interval) ⇒ Object

Helper method that performs synchronous sleep for a certain time interval



1064
1065
1066
1067
 
# File 'lib/logstash/outputs/scalyr.rb', line 1064

def sleep_for(sleep_interval)
  Stud.stoppable_sleep(sleep_interval) { !@running }
  get_sleep_sec(sleep_interval)
end