From 1971bbe2fae6566c1b1df0ea88bfd95c926c608f Mon Sep 17 00:00:00 2001 From: Noemi <45180344+unflxw@users.noreply.github.com> Date: Tue, 10 Sep 2024 22:33:38 +0200 Subject: [PATCH 1/2] Ensure stubs are called exactly once Ensure that the stubs are called exactly once -- that is, that the same stub is not used several times, potentially masking a bug where several transmissions happen for the same events, and that no stubs are declared which are left unused. The strange way in which it is implemented is due to certain quirks of how the `webmock` gem works. I could not find a way to have a stub automatically disable itself when called, similar to what the `nock` Node.js package provides -- so I implemented this by passing a number of request bodies to expect to respond to when declaring the mock, and erroring if more requests are made than the request bodies provided. That, however, does not cover the scenario where the stub is not called at all. Somewhat bafflingly, the `have_been_requested` matcher does not check a counter that has been incremented for each request. Instead, it re-runs the requests it has stored by the stubs _again_, and counts how many match. Given the implementation described above, where the stub is exhausting a list of request bodies as it goes, the matcher will fail when attempting to go a second time around. So instead, we increment a counter when a request is processed (without said request having exhausted the matcher) and we return that counter from the stub. The tests store these counters in a `let` binding, and an `after` block checks that each stored counter has been increased to one. This is done in an `after` block not only for convenience, but because some tests are mocking a call that will only be performed in that same `after` block, when the scheduler is stopped. --- spec/lib/appsignal/check_in/cron_spec.rb | 63 ++++----- spec/lib/appsignal/check_in/scheduler_spec.rb | 133 ++++++++---------- spec/support/helpers/api_request_helper.rb | 45 ++++-- 3 files changed, 123 insertions(+), 118 deletions(-) diff --git a/spec/lib/appsignal/check_in/cron_spec.rb b/spec/lib/appsignal/check_in/cron_spec.rb index 9d2598ab..b432d035 100644 --- a/spec/lib/appsignal/check_in/cron_spec.rb +++ b/spec/lib/appsignal/check_in/cron_spec.rb @@ -5,6 +5,7 @@ let(:config) { project_fixture_config } let(:cron_checkin) { described_class.new(:identifier => "cron-checkin-name") } let(:scheduler) { Appsignal::CheckIn.scheduler } + let(:stubs) { [] } before do start_agent( @@ -12,10 +13,13 @@ :internal_logger => test_logger(log_stream) ) end - after { stop_scheduler } - def stop_scheduler + after do scheduler.stop + + stubs.each do |stub| + expect(stub.count).to eq(1) + end end describe "when Appsignal is not active" do @@ -26,7 +30,7 @@ def stop_scheduler cron_checkin.start cron_checkin.finish - stop_scheduler + scheduler.stop expect(logs).to contains_log( :debug, @@ -48,12 +52,14 @@ def stop_scheduler expect(logs).to contains_log( :debug, - "Cannot transmit cron check-in `cron-checkin-name` start event" + /Cannot transmit cron check-in `cron-checkin-name` start event .+: AppSignal is stopped/ ) expect(logs).to contains_log( :debug, - "Cannot transmit cron check-in `cron-checkin-name` finish event" + /Cannot transmit cron check-in `cron-checkin-name` finish event .+: AppSignal is stopped/ ) + + scheduler.stop end end @@ -61,11 +67,10 @@ def stop_scheduler it "sends a cron check-in start" do cron_checkin.start - stub_check_in_request( + stubs << stub_cron_check_in_request( :events => [ "identifier" => "cron-checkin-name", - "kind" => "start", - "check_in_type" => "cron" + "kind" => "start" ] ) @@ -85,11 +90,10 @@ def stop_scheduler it "logs an error if it fails" do cron_checkin.start - stub_check_in_request( + stubs << stub_cron_check_in_request( :events => [ "identifier" => "cron-checkin-name", - "kind" => "start", - "check_in_type" => "cron" + "kind" => "start" ], :response => { :status => 499 } ) @@ -111,11 +115,10 @@ def stop_scheduler it "sends a cron check-in finish" do cron_checkin.finish - stub_check_in_request( + stubs << stub_cron_check_in_request( :events => [ "identifier" => "cron-checkin-name", - "kind" => "finish", - "check_in_type" => "cron" + "kind" => "finish" ] ) @@ -134,11 +137,10 @@ def stop_scheduler it "logs an error if it fails" do cron_checkin.finish - stub_check_in_request( + stubs << stub_cron_check_in_request( :events => [ "identifier" => "cron-checkin-name", - "kind" => "finish", - "check_in_type" => "cron" + "kind" => "finish" ], :response => { :status => 499 } ) @@ -159,19 +161,14 @@ def stop_scheduler describe ".cron" do describe "when a block is given" do it "sends a cron check-in start and finish and return the block output" do - stub_check_in_request( - :events => [ + stubs << stub_cron_check_in_request( + :events => [{ "identifier" => "cron-checkin-with-block", - "kind" => "start", - "check_in_type" => "cron" - ] - ) - stub_check_in_request( - :events => [ + "kind" => "start" + }, { "identifier" => "cron-checkin-with-block", - "kind" => "finish", - "check_in_type" => "cron" - ] + "kind" => "finish" + }] ) output = Appsignal::CheckIn.cron("cron-checkin-with-block") { "output" } @@ -179,11 +176,10 @@ def stop_scheduler end it "does not send a cron check-in finish event when an error is raised" do - stub_check_in_request( + stubs << stub_cron_check_in_request( :events => [ "identifier" => "cron-checkin-with-block", - "kind" => "start", - "check_in_type" => "cron" + "kind" => "start" ] ) @@ -195,11 +191,10 @@ def stop_scheduler describe "when no block is given" do it "only sends a cron check-in finish event" do - stub_check_in_request( + stubs << stub_cron_check_in_request( :events => [ "identifier" => "cron-checkin-without-block", - "kind" => "finish", - "check_in_type" => "cron" + "kind" => "finish" ] ) diff --git a/spec/lib/appsignal/check_in/scheduler_spec.rb b/spec/lib/appsignal/check_in/scheduler_spec.rb index 11cb58bb..096a401e 100644 --- a/spec/lib/appsignal/check_in/scheduler_spec.rb +++ b/spec/lib/appsignal/check_in/scheduler_spec.rb @@ -6,6 +6,7 @@ let(:logs) { log_contents(log_stream) } let(:appsignal_options) { {} } let(:scheduler) { Appsignal::CheckIn.scheduler } + let(:stubs) { [] } before do start_agent(:options => appsignal_options, :internal_logger => test_logger(log_stream)) @@ -16,6 +17,10 @@ after do scheduler.stop + + stubs.each do |stub| + expect(stub.count).to eq(1) + end end describe "when no event is sent" do @@ -60,11 +65,10 @@ describe "when an event is sent" do it "starts a thread" do - stub_check_in_request( + stubs << stub_cron_check_in_request( :events => [ "identifier" => "test", - "kind" => "finish", - "check_in_type" => "cron" + "kind" => "finish" ] ) Appsignal::CheckIn.cron("test") @@ -72,11 +76,10 @@ end it "schedules a debounce" do - stub_check_in_request( + stubs << stub_cron_check_in_request( :events => [ "identifier" => "test", - "kind" => "finish", - "check_in_type" => "cron" + "kind" => "finish" ] ) Appsignal::CheckIn.cron("test") @@ -84,11 +87,10 @@ end it "schedules the event to be transmitted" do - stub_check_in_request( + stubs << stub_cron_check_in_request( :events => [ "identifier" => "test", - "kind" => "finish", - "check_in_type" => "cron" + "kind" => "finish" ] ) @@ -114,11 +116,10 @@ stub_const("Appsignal::CheckIn::Scheduler::INITIAL_DEBOUNCE_SECONDS", 10) stub_const("Appsignal::CheckIn::Scheduler::BETWEEN_TRANSMISSIONS_DEBOUNCE_SECONDS", 10) - stub_check_in_request( + stubs << stub_cron_check_in_request( :events => [ "identifier" => "test", - "kind" => "finish", - "check_in_type" => "cron" + "kind" => "finish" ] ) @@ -148,14 +149,16 @@ stub_const("Appsignal::CheckIn::Scheduler::INITIAL_DEBOUNCE_SECONDS", 10) stub_const("Appsignal::CheckIn::Scheduler::BETWEEN_TRANSMISSIONS_DEBOUNCE_SECONDS", 10) - stub_check_in_request( + stubs << stub_cron_check_in_request( :events => [ "identifier" => "test", "kind" => "finish", "check_in_type" => "cron" ] ) + Appsignal::CheckIn.cron("test") + take_at_most(0.1) do expect { scheduler.stop }.not_to raise_error end @@ -170,33 +173,35 @@ end it "closes the queue when stopped" do - stub_check_in_request( + stubs << stub_cron_check_in_request( :events => [ "identifier" => "test", "kind" => "finish", "check_in_type" => "cron" ] ) + Appsignal::CheckIn.cron("test") scheduler.stop expect(scheduler.queue.closed?).to be(true) end it "kills the thread when stopped" do - stub_check_in_request( + stubs << stub_cron_check_in_request( :events => [ "identifier" => "test", "kind" => "finish", "check_in_type" => "cron" ] ) + Appsignal::CheckIn.cron("test") scheduler.stop expect(scheduler.thread.alive?).to be(false) end it "unschedules the debounce when stopped" do - stub_check_in_request( + stubs << stub_cron_check_in_request( :events => [ "identifier" => "test", "kind" => "finish", @@ -214,15 +219,15 @@ describe "when many events are sent" do describe "within the short debounce interval" do it "transmits all events at once" do - ["first", "second", "third"].map do |identifier| - stub_check_in_request( - :events => [ + stubs << stub_cron_check_in_request( + :events => ["first", "second", "third"].map do |identifier| + { "identifier" => identifier, "kind" => "finish", "check_in_type" => "cron" - ] - ) - end + } + end + ) Appsignal::CheckIn.cron("first") Appsignal::CheckIn.cron("second") @@ -238,15 +243,15 @@ # stopped. stub_const("Appsignal::CheckIn::Scheduler::INITIAL_DEBOUNCE_SECONDS", 10) - ["first", "second", "third"].map do |identifier| - stub_check_in_request( - :events => [ + stubs << stub_cron_check_in_request( + :events => ["first", "second", "third"].map do |identifier| + { "identifier" => identifier, "kind" => "finish", "check_in_type" => "cron" - ] - ) - end + } + end + ) Appsignal::CheckIn.cron("first") Appsignal::CheckIn.cron("second") @@ -260,7 +265,7 @@ describe "further apart than the short debounce interval" do it "transmits the first event and enqueues future events" do - stub_check_in_request( + stubs << stub_cron_check_in_request( :events => [ "identifier" => "first", "kind" => "finish", @@ -272,7 +277,7 @@ wait_for("the first event to be transmitted") { scheduler.transmitted == 1 } - stub_check_in_request( + stubs << stub_cron_check_in_request( :events => [ { "identifier" => "second", @@ -286,6 +291,7 @@ } ] ) + Appsignal::CheckIn.cron("second") Appsignal::CheckIn.cron("third") @@ -299,28 +305,26 @@ end it "transmits the other events after the debounce interval" do - stub_check_in_request( + stubs << stub_cron_check_in_request( :events => [ "identifier" => "first", - "kind" => "finish", - "check_in_type" => "cron" + "kind" => "finish" ] ) + Appsignal::CheckIn.cron("first") wait_for("the first event to be transmitted") { scheduler.transmitted == 1 } - stub_check_in_request( + stubs << stub_cron_check_in_request( :events => [ { "identifier" => "second", - "kind" => "finish", - "check_in_type" => "cron" + "kind" => "finish" }, { "identifier" => "third", - "kind" => "finish", - "check_in_type" => "cron" + "kind" => "finish" } ] ) @@ -348,28 +352,25 @@ # immediately when the scheduler is stopped. stub_const("Appsignal::CheckIn::Scheduler::BETWEEN_TRANSMISSIONS_DEBOUNCE_SECONDS", 10) - stub_check_in_request( + stubs << stub_cron_check_in_request( :events => [ "identifier" => "first", - "kind" => "finish", - "check_in_type" => "cron" + "kind" => "finish" ] ) Appsignal::CheckIn.cron("first") wait_for("the event to be transmitted") { scheduler.transmitted == 1 } - stub_check_in_request( + stubs << stub_cron_check_in_request( :events => [ { "identifier" => "second", - "kind" => "finish", - "check_in_type" => "cron" + "kind" => "finish" }, { "identifier" => "third", - "kind" => "finish", - "check_in_type" => "cron" + "kind" => "finish" } ] ) @@ -400,11 +401,10 @@ # `.cron` helper would use a different digest for each invocation. cron = Appsignal::CheckIn::Cron.new(:identifier => "test") - stub_check_in_request( + stubs << stub_cron_check_in_request( :events => [ "identifier" => "test", - "kind" => "start", - "check_in_type" => "cron" + "kind" => "start" ] ) @@ -466,19 +466,10 @@ describe "when transmitting returns a non-success response code" do it "logs the error and continues" do - stub_check_in_request( + stubs << stub_cron_check_in_request( :events => [ "identifier" => "first", - "kind" => "start", - "check_in_type" => "cron" - ], - :response => { :status => 404 } - ) - stub_check_in_request( - :events => [ - "identifier" => "first", - "kind" => "finish", - "check_in_type" => "cron" + "kind" => "finish" ], :response => { :status => 404 } ) @@ -487,18 +478,10 @@ wait_for("the first event to be transmitted") { scheduler.transmitted == 1 } - stub_check_in_request( + stubs << stub_cron_check_in_request( :events => [ "identifier" => "second", - "kind" => "start", - "check_in_type" => "cron" - ] - ) - stub_check_in_request( - :events => [ - "identifier" => "second", - "kind" => "finish", - "check_in_type" => "cron" + "kind" => "finish" ] ) @@ -519,11 +502,10 @@ describe "when transmitting throws an error" do it "logs the error and continues" do - stub_check_in_request( + stubs << stub_cron_check_in_request( :events => [ "identifier" => "first", - "kind" => "finish", - "check_in_type" => "cron" + "kind" => "finish" ], :response => ExampleStandardError.new("Something went wrong") ) @@ -532,11 +514,10 @@ wait_for("the first event to be transmitted") { scheduler.transmitted == 1 } - stub_check_in_request( + stubs << stub_cron_check_in_request( :events => [ "identifier" => "second", - "kind" => "finish", - "check_in_type" => "cron" + "kind" => "finish" ] ) diff --git a/spec/support/helpers/api_request_helper.rb b/spec/support/helpers/api_request_helper.rb index d03c918a..4f746192 100644 --- a/spec/support/helpers/api_request_helper.rb +++ b/spec/support/helpers/api_request_helper.rb @@ -1,4 +1,16 @@ module ApiRequestHelper + class RequestCounter + attr_reader :count + + def initialize + @count = 0 + end + + def increase + @count += 1 + end + end + def stub_api_request(config, path, body = nil) options = { :query => { @@ -18,7 +30,21 @@ def stub_api_request(config, path, body = nil) stub_request(:post, "#{endpoint}/1/#{path}").with(options) end - def stub_check_in_request(events:, response: { :status => 200 }) + def stub_cron_check_in_request(events:, response: { :status => 200 }) + stub_check_in_requests( + :requests => [events], + :event_shape => { + "identifier" => nil, + "digest" => kind_of(String), + "kind" => nil, + "timestamp" => kind_of(Integer), + "check_in_type" => "cron" + }, + :response => response + ) + end + + def stub_check_in_requests(requests:, event_shape: {}, response: { :status => 200 }) config = Appsignal.config options = { :query => { @@ -31,24 +57,25 @@ def stub_check_in_request(events:, response: { :status => 200 }) :headers => { "Content-Type" => "application/x-ndjson; charset=UTF-8" } } + counter = RequestCounter.new + request_stub = stub_request( :post, "#{config[:logging_endpoint]}/check_ins/json" ).with(options) do |request| + events = requests.shift + expect(events).to_not(be_nil, "More requests were made than expected") + counter.increase # Parse each line as JSON per the NDJSON format payloads = request.body.split("\n").map { |line| JSON.parse(line) } formatted_events = events.map do |event| - { - "identifier" => nil, - "digest" => kind_of(String), - "kind" => "start", - "timestamp" => kind_of(Integer), - "check_in_type" => "cron" - }.merge(event) + a_hash_including(**event_shape.merge(event)) end + expect(payloads).to include(*formatted_events) + expect(payloads.length).to eq(formatted_events.length) end if response.is_a?(Exception) @@ -56,5 +83,7 @@ def stub_check_in_request(events:, response: { :status => 200 }) else request_stub.to_return(response) end + + counter end end From 7ae7152cddae7c257e9d62d3bf2433cce1f4287d Mon Sep 17 00:00:00 2001 From: Noemi <45180344+unflxw@users.noreply.github.com> Date: Mon, 9 Sep 2024 20:21:48 +0200 Subject: [PATCH 2/2] Implement heartbeat check-ins Add an `Appsignal::CheckIn.heartbeat` helper that emits a single heartbeat for the check-in identifier given. When given `continuous: true` as the second argument, it spawns a separate thread that emits a heartbeat every thirty seconds. This is a convenience method for the use case where the heartbeat is only meant as a check that the process is alive. Split functions that deal with different event kinds out of the scheduler and test them independently. --- .changesets/add-heartbeat-check-ins.md | 26 +++ lib/appsignal/check_in.rb | 45 ++++- lib/appsignal/check_in/cron.rb | 8 +- lib/appsignal/check_in/event.rb | 72 ++++++++ lib/appsignal/check_in/scheduler.rb | 44 ++--- spec/lib/appsignal/check_in/event_spec.rb | 169 ++++++++++++++++++ spec/lib/appsignal/check_in/heartbeat_spec.rb | 127 +++++++++++++ spec/support/helpers/api_request_helper.rb | 12 ++ 8 files changed, 463 insertions(+), 40 deletions(-) create mode 100644 .changesets/add-heartbeat-check-ins.md create mode 100644 lib/appsignal/check_in/event.rb create mode 100644 spec/lib/appsignal/check_in/event_spec.rb create mode 100644 spec/lib/appsignal/check_in/heartbeat_spec.rb diff --git a/.changesets/add-heartbeat-check-ins.md b/.changesets/add-heartbeat-check-ins.md new file mode 100644 index 00000000..fcc5cccf --- /dev/null +++ b/.changesets/add-heartbeat-check-ins.md @@ -0,0 +1,26 @@ +--- +bump: minor +type: add +--- + +Add support for heartbeat check-ins. + +Use the `Appsignal::CheckIn.heartbeat` method to send a single heartbeat check-in event from your application. This can be used, for example, in your application's main loop: + +```ruby +loop do + Appsignal::CheckIn.heartbeat("job_processor") + process_job +end +``` + +Heartbeats are deduplicated and sent asynchronously, without blocking the current thread. Regardless of how often the `.heartbeat` method is called, at most one heartbeat with the same identifier will be sent every ten seconds. + +Pass `continuous: true` as the second argument to send heartbeats continuously during the entire lifetime of the current process. This can be used, for example, after your application has finished its boot process: + +```ruby +def main + start_app + Appsignal::CheckIn.heartbeat("my_app", continuous: true) +end +``` diff --git a/lib/appsignal/check_in.rb b/lib/appsignal/check_in.rb index cd4c1d27..42564226 100644 --- a/lib/appsignal/check_in.rb +++ b/lib/appsignal/check_in.rb @@ -2,10 +2,21 @@ module Appsignal module CheckIn + HEARTBEAT_CONTINUOUS_INTERVAL_SECONDS = 30 class << self + # @api private + def continuous_heartbeats + @continuous_heartbeats ||= [] + end + + # @api private + def kill_continuous_heartbeats + continuous_heartbeats.each(&:kill) + end + # Track cron check-ins. # - # Track the execution of certain processes by sending a cron check-in. + # Track the execution of scheduled processes by sending a cron check-in. # # To track the duration of a piece of code, pass a block to {.cron} # to report both when the process starts, and when it finishes. @@ -40,6 +51,37 @@ def cron(identifier) output end + # Track heartbeat check-ins. + # + # Track the execution of long-lived processes by sending a heartbeat + # check-in. + # + # @example Send a heartbeat check-in + # Appsignal::CheckIn.heartbeat("main_loop") + # + # @param identifier [String] identifier of the heartbeat check-in to report. + # @param continuous [Boolean] whether the heartbeats should be sent continuously + # during the lifetime of the process. Defaults to `false`. + # @yield the block to monitor. + # @return [void] + # @since 4.1.0 + # @see https://docs.appsignal.com/check-ins/heartbeat + def heartbeat(identifier, continuous: false) + if continuous + continuous_heartbeats << Thread.new do + loop do + heartbeat(identifier) + sleep HEARTBEAT_CONTINUOUS_INTERVAL_SECONDS + end + end + + return + end + + event = Event.heartbeat(:identifier => identifier) + scheduler.schedule(event) + end + # @api private def transmitter @transmitter ||= Transmitter.new( @@ -60,5 +102,6 @@ def stop end end +require "appsignal/check_in/event" require "appsignal/check_in/scheduler" require "appsignal/check_in/cron" diff --git a/lib/appsignal/check_in/cron.rb b/lib/appsignal/check_in/cron.rb index 7d77540d..9befefd2 100644 --- a/lib/appsignal/check_in/cron.rb +++ b/lib/appsignal/check_in/cron.rb @@ -22,13 +22,11 @@ def finish private def event(kind) - { + Event.cron( :identifier => @identifier, :digest => @digest, - :kind => kind, - :timestamp => Time.now.utc.to_i, - :check_in_type => "cron" - } + :kind => kind + ) end end end diff --git a/lib/appsignal/check_in/event.rb b/lib/appsignal/check_in/event.rb new file mode 100644 index 00000000..8a3cce8d --- /dev/null +++ b/lib/appsignal/check_in/event.rb @@ -0,0 +1,72 @@ +# frozen_string_literal: true + +module Appsignal + module CheckIn + # @api private + class Event + class << self + def new(check_in_type:, identifier:, digest: nil, kind: nil) + { + :identifier => identifier, + :digest => digest, + :kind => kind, + :timestamp => Time.now.utc.to_i, + :check_in_type => check_in_type + }.compact + end + + def cron(identifier:, digest:, kind:) + new( + :check_in_type => "cron", + :identifier => identifier, + :digest => digest, + :kind => kind + ) + end + + def heartbeat(identifier:) + new( + :check_in_type => "heartbeat", + :identifier => identifier + ) + end + + def redundant?(event, other) + return false if + other[:check_in_type] != event[:check_in_type] || + other[:identifier] != event[:identifier] + + return false if event[:check_in_type] == "cron" && ( + other[:digest] != event[:digest] || + other[:kind] != event[:kind] + ) + + return false if + event[:check_in_type] != "cron" && + event[:check_in_type] != "heartbeat" + + true + end + + def describe(events) + if events.empty? + # This shouldn't happen. + "no check-in events" + elsif events.length > 1 + "#{events.length} check-in events" + else + event = events.first + if event[:check_in_type] == "cron" + "cron check-in `#{event[:identifier] || "unknown"}` " \ + "#{event[:kind] || "unknown"} event (digest #{event[:digest] || "unknown"})" + elsif event[:check_in_type] == "heartbeat" + "heartbeat check-in `#{event[:identifier] || "unknown"}` event" + else + "unknown check-in event" + end + end + end + end + end + end +end diff --git a/lib/appsignal/check_in/scheduler.rb b/lib/appsignal/check_in/scheduler.rb index 5b000b8c..62e4e63d 100644 --- a/lib/appsignal/check_in/scheduler.rb +++ b/lib/appsignal/check_in/scheduler.rb @@ -29,7 +29,7 @@ def initialize def schedule(event) unless Appsignal.active? Appsignal.internal_logger.debug( - "Cannot transmit #{describe([event])}: AppSignal is not active" + "Cannot transmit #{Event.describe([event])}: AppSignal is not active" ) return end @@ -37,7 +37,7 @@ def schedule(event) @mutex.synchronize do if @queue.closed? Appsignal.internal_logger.debug( - "Cannot transmit #{describe([event])}: AppSignal is stopped" + "Cannot transmit #{Event.describe([event])}: AppSignal is stopped" ) return end @@ -48,7 +48,7 @@ def schedule(event) start_waker(INITIAL_DEBOUNCE_SECONDS) if @waker.nil? Appsignal.internal_logger.debug( - "Scheduling #{describe([event])} to be transmitted" + "Scheduling #{Event.describe([event])} to be transmitted" ) # Make sure to start the thread after an event has been added. @@ -92,7 +92,7 @@ def run end def transmit(events) - description = describe(events) + description = Event.describe(events) begin response = CheckIn.transmitter.transmit(events, :format => :ndjson) @@ -110,42 +110,18 @@ def transmit(events) end end - def describe(events) - if events.empty? - # This shouldn't happen. - "no check-in events" - elsif events.length > 1 - "#{events.length} check-in events" - else - event = events.first - if event[:check_in_type] == "cron" - "cron check-in `#{event[:identifier] || "unknown"}` " \ - "#{event[:kind] || "unknown"} event (digest #{event[:digest] || "unknown"})" \ - else - "unknown check-in event" - end - end - end - # Must be called from within a `@mutex.synchronize` block. def add_event(event) # Remove redundant events, keeping the newly added one, which # should be the one with the most recent timestamp. - if event[:check_in_type] == "cron" - # Remove any existing cron check-in event with the same identifier, - # digest and kind as the one we're adding. - @events.reject! do |existing_event| - next unless existing_event[:identifier] == event[:identifier] && - existing_event[:digest] == event[:digest] && - existing_event[:kind] == event[:kind] && - existing_event[:check_in_type] == "cron" + @events.reject! do |existing_event| + next unless Event.redundant?(event, existing_event) - Appsignal.internal_logger.debug( - "Replacing previously scheduled #{describe([existing_event])}" - ) + Appsignal.internal_logger.debug( + "Replacing previously scheduled #{Event.describe([existing_event])}" + ) - true - end + true end @events << event diff --git a/spec/lib/appsignal/check_in/event_spec.rb b/spec/lib/appsignal/check_in/event_spec.rb new file mode 100644 index 00000000..12e1ef50 --- /dev/null +++ b/spec/lib/appsignal/check_in/event_spec.rb @@ -0,0 +1,169 @@ +describe Appsignal::CheckIn::Event do + describe "#describe" do + it "describes an empty list of check-ins" do + expect( + described_class.describe([]) + ).to eq("no check-in events") + end + + it "describes a cron check-in by identifier, kind, and digest" do + expect( + described_class.describe([ + described_class.cron( + :identifier => "cron-checkin-name", + :digest => "some-digest", + :kind => "some-kind" + ) + ]) + ).to eq("cron check-in `cron-checkin-name` some-kind event (digest some-digest)") + end + + it "describes a heartbeat check-in by identifier" do + expect( + described_class.describe([ + described_class.heartbeat(:identifier => "heartbeat-checkin-name") + ]) + ).to eq("heartbeat check-in `heartbeat-checkin-name` event") + end + + it "describes an unknown check-in event" do + expect( + described_class.describe([ + described_class.new( + :check_in_type => "unknown-type", + :identifier => "unknown-checkin-name" + ) + ]) + ).to eq("unknown check-in event") + end + + it "describes multiple check-ins by count" do + expect( + described_class.describe([ + described_class.heartbeat(:identifier => "heartbeat-checkin-name"), + described_class.cron( + :identifier => "cron-checkin-name", + :digest => "digest", + :kind => "start" + ) + ]) + ).to eq("2 check-in events") + end + end + + describe "#redundant?" do + it "returns false for different check-in types" do + event = described_class.heartbeat(:identifier => "checkin-name") + other = described_class.cron( + :identifier => "checkin-name", + :digest => "digest", + :kind => "start" + ) + + expect( + described_class.redundant?(event, other) + ).to be(false) + end + + it "returns false for different heartbeat identifiers" do + event = described_class.heartbeat(:identifier => "checkin-name") + other = described_class.heartbeat(:identifier => "other-checkin-name") + + expect( + described_class.redundant?(event, other) + ).to be(false) + end + + it "returns true for the same heartbeat identifier" do + event = described_class.heartbeat(:identifier => "checkin-name") + other = described_class.heartbeat(:identifier => "checkin-name") + + expect( + described_class.redundant?(event, other) + ).to be(true) + end + + it "returns false for different cron identifiers" do + event = described_class.cron( + :identifier => "checkin-name", + :digest => "digest", + :kind => "start" + ) + other = described_class.cron( + :identifier => "other-checkin-name", + :digest => "digest", + :kind => "start" + ) + + expect( + described_class.redundant?(event, other) + ).to be(false) + end + + it "returns false for different cron digests" do + event = described_class.cron( + :identifier => "checkin-name", + :digest => "digest", + :kind => "start" + ) + other = described_class.cron( + :identifier => "checkin-name", + :digest => "other-digest", + :kind => "start" + ) + + expect( + described_class.redundant?(event, other) + ).to be(false) + end + + it "returns false for different cron kinds" do + event = described_class.cron( + :identifier => "checkin-name", + :digest => "digest", + :kind => "start" + ) + other = described_class.cron( + :identifier => "checkin-name", + :digest => "digest", + :kind => "finish" + ) + + expect( + described_class.redundant?(event, other) + ).to be(false) + end + + it "returns true for the same cron identifier, digest, and kind" do + event = described_class.cron( + :identifier => "checkin-name", + :digest => "digest", + :kind => "start" + ) + other = described_class.cron( + :identifier => "checkin-name", + :digest => "digest", + :kind => "start" + ) + + expect( + described_class.redundant?(event, other) + ).to be(true) + end + + it "returns false for unknown check-in event kinds" do + event = described_class.new( + :check_in_type => "unknown", + :identifier => "checkin-name" + ) + other = described_class.new( + :check_in_type => "unknown", + :identifier => "checkin-name" + ) + + expect( + described_class.redundant?(event, other) + ).to be(false) + end + end +end diff --git a/spec/lib/appsignal/check_in/heartbeat_spec.rb b/spec/lib/appsignal/check_in/heartbeat_spec.rb new file mode 100644 index 00000000..c7eec933 --- /dev/null +++ b/spec/lib/appsignal/check_in/heartbeat_spec.rb @@ -0,0 +1,127 @@ +describe "Appsignal::CheckIn.heartbeat" do + include WaitForHelper + include TakeAtMostHelper + + let(:log_stream) { std_stream } + let(:logs) { log_contents(log_stream) } + let(:appsignal_options) { {} } + let(:config) { project_fixture_config } + let(:scheduler) { Appsignal::CheckIn.scheduler } + let(:stubs) { [] } + + before do + start_agent( + :options => appsignal_options, + :internal_logger => test_logger(log_stream) + ) + end + + after do + Appsignal::CheckIn.kill_continuous_heartbeats + scheduler.stop + + stubs.each do |stub| + expect(stub.count).to eq(1) + end + end + + def schedule_heartbeat(**kwargs) + Appsignal::CheckIn.heartbeat("heartbeat-checkin-name", **kwargs) + end + + describe "when Appsignal is not active" do + let(:appsignal_options) { { :active => false } } + + it "does not transmit any events" do + expect(Appsignal).to_not be_started + + schedule_heartbeat + scheduler.stop + + expect(logs).to contains_log( + :debug, + "Cannot transmit heartbeat check-in `heartbeat-checkin-name` event: AppSignal is not active" + ) + end + end + + describe "when AppSignal is stopped" do + it "does not transmit any events" do + Appsignal.stop + + schedule_heartbeat + + expect(logs).to contains_log( + :debug, + "Cannot transmit heartbeat check-in `heartbeat-checkin-name` event: AppSignal is stopped" + ) + + scheduler.stop + end + end + + it "sends a heartbeat" do + schedule_heartbeat + + stubs << stub_heartbeat_check_in_request( + :events => [ + "identifier" => "heartbeat-checkin-name" + ] + ) + + scheduler.stop + + expect(logs).to_not contains_log(:error) + expect(logs).to contains_log( + :debug, + "Scheduling heartbeat check-in `heartbeat-checkin-name` event" + ) + end + + it "logs an error if it fails" do + schedule_heartbeat + + stubs << stub_heartbeat_check_in_request( + :events => [ + "identifier" => "heartbeat-checkin-name" + ], + :response => { :status => 499 } + ) + + scheduler.stop + + expect(logs).to contains_log( + :debug, + "Scheduling heartbeat check-in `heartbeat-checkin-name` event" + ) + expect(logs).to contains_log( + :error, + "Failed to transmit heartbeat check-in `heartbeat-checkin-name` event: 499 status code" + ) + end + + describe "when the continuous option is set" do + it "keeps sending heartbeats continuously" do + stub_const("Appsignal::CheckIn::Scheduler::INITIAL_DEBOUNCE_SECONDS", 0.1) + stub_const("Appsignal::CheckIn::Scheduler::BETWEEN_TRANSMISSIONS_DEBOUNCE_SECONDS", 0.1) + stub_const("Appsignal::CheckIn::HEARTBEAT_CONTINUOUS_INTERVAL_SECONDS", 0.1) + + schedule_heartbeat(:continuous => true) + + stub = stub_check_in_requests( + # Additional requests could be made due to timing issues or when the + # scheduler is stopped in the `after` block -- stub additional requests + # to prevent the test from failing. + :requests => Array.new(5) do + [ + "identifier" => "heartbeat-checkin-name", + "check_in_type" => "heartbeat" + ] + end + ) + + wait_for("the event to be transmitted") { scheduler.transmitted == 2 } + expect(stub.count).to be >= 2 + end + end +end diff --git a/spec/support/helpers/api_request_helper.rb b/spec/support/helpers/api_request_helper.rb index 4f746192..192a2495 100644 --- a/spec/support/helpers/api_request_helper.rb +++ b/spec/support/helpers/api_request_helper.rb @@ -44,6 +44,18 @@ def stub_cron_check_in_request(events:, response: { :status => 200 }) ) end + def stub_heartbeat_check_in_request(events:, response: { :status => 200 }) + stub_check_in_requests( + :requests => [events], + :event_shape => { + "identifier" => nil, + "timestamp" => kind_of(Integer), + "check_in_type" => "heartbeat" + }, + :response => response + ) + end + def stub_check_in_requests(requests:, event_shape: {}, response: { :status => 200 }) config = Appsignal.config options = {