Fix agent to unregister LB service backends earlier during container shutdown (kontena#3287)

* agent ServicePodWorker#on_container_die(exit_code: ...)

* log service:instance_exit event on container die

* add e2e specs for shutdown of lb service backends

* agent: unregister container from lb service on container kill event

* add testcase for service without healthchecks

* change event type to service:instance_crash

* add affirmative-failure spec using the system default SIGTERM handler

* fixup instance_crash

* use eq for better diff

* switch to POST requests to avoid retries on read timeouts

* tweak timings to make requests more busy

* fix !TRAP case to actually hard-exit! on SIGTERM

* tweak spec name

* show service logs in case of crashes

Author: SpComb

agent/lib/kontena/load_balancers/registrator.rb

@@ -41,7 +41,7 @@ def on_container_event(topic, event)
         if container && container.service_container? && container.load_balanced?
           self.register_container(container)
         end
-      elsif event.status == 'die'
+      elsif event.status == 'die' || event.status == 'kill'
         self.unregister_container(event.id)
       end
     rescue => exc

test/spec/features/stack/shutdown_spec.rb

@@ -0,0 +1,105 @@
+require 'net/http'
+
+describe 'kontena service shutdown' do
+  include ServiceHelper
+
+  context 'for a http test service' do
+    before(:all) do
+      with_fixture_dir('stack/shutdown-test') do
+        run! 'kontena stack build --no-push'
+      end
+    end
+
+    context "using ungraceful shutdown to fail requests" do
+      before(:all) do
+        with_fixture_dir('stack/shutdown-test') do
+          run! "kontena stack install -n shutdown-test-fail -v trap=false"
+        end
+      end
+      after(:all) do
+        run! 'kontena stack rm --force shutdown-test-fail'
+      end
+
+      describe "after re-deploying the server" do
+        before do
+          run! 'kontena service deploy --force shutdown-test-fail/server'
+        end
+
+        it "will result in client errors" do
+          events = service_events('shutdown-test-fail/client')
+
+          expect(events.select{|e| e[:type] == 'instance_crash'}).to_not eq([]), service_logs('shutdown-test-fail/client').join
+        end
+      end
+    end
+    
+    context "using graceful shutdown to close the listening socket" do
+      before(:all) do
+        with_fixture_dir('stack/shutdown-test') do
+          run! "kontena stack install -n shutdown-test-graceful -v graceful_shutdown=true"
+        end
+      end
+      after(:all) do
+        run! 'kontena stack rm --force shutdown-test-graceful'
+      end
+
+      describe "after re-deploying the server" do
+        before do
+          run! 'kontena service deploy --force shutdown-test-graceful/server'
+        end
+
+        it "does not result in any client errors" do
+          events = service_events('shutdown-test-graceful/client')
+
+          expect(events.select{|e| e[:type] == 'instance_crash'}).to eq([]), service_logs('shutdown-test-graceful/client').join
+        end
+      end
+    end
+
+    context "using graceful shutdown without a healthcheck" do
+      before(:all) do
+        with_fixture_dir('stack/shutdown-test') do
+          run! "kontena stack install -n shutdown-test-nohealthcheck -v graceful_shutdown=true -v healthcheck=false"
+        end
+      end
+      after(:all) do
+        run! 'kontena stack rm --force shutdown-test-nohealthcheck'
+      end
+
+      describe "after re-deploying the server" do
+        before do
+          run! 'kontena service deploy --force shutdown-test-nohealthcheck/server'
+        end
+
+        it "does not result in any client errors" do
+          events = service_events('shutdown-test-nohealthcheck/client')
+
+          expect(events.select{|e| e[:type] == 'instance_crash'}).to eq([]), service_logs('shutdown-test-nohealthcheck/client').join
+        end
+      end
+    end
+
+    context "using delayed shutdown without closing the listening socket" do
+      before(:all) do
+        with_fixture_dir('stack/shutdown-test') do
+          run! "kontena stack install -n shutdown-test-delay -v graceful_shutdown=false"
+        end
+      end
+      after(:all) do
+        run! 'kontena stack rm --force shutdown-test-delay'
+      end
+
+      describe "after re-deploying the server" do
+        before do
+          run! 'kontena service deploy --force shutdown-test-delay/server'
+        end
+
+        it "does not result in any client errors" do
+          events = service_events('shutdown-test-delay/client')
+
+          expect(events.select{|e| e[:type] == 'instance_crash'}).to eq([]), service_logs('shutdown-test-delay/client').join
+        end
+      end
+    end
+  end
+end

test/spec/fixtures/stack/shutdown-test/Dockerfile.client

@@ -0,0 +1,7 @@
+FROM alpine
+
+RUN apk update && apk --update add ruby
+
+ADD client.rb .
+
+CMD ["ruby", "client.rb"]

test/spec/fixtures/stack/shutdown-test/Dockerfile.server

@@ -0,0 +1,7 @@
+FROM alpine
+
+RUN apk update && apk --update add ruby 
+
+ADD server.rb .
+
+CMD ["ruby", "server.rb"]

test/spec/fixtures/stack/shutdown-test/client.rb

@@ -0,0 +1,70 @@
+require 'logger'
+require 'net/http'
+require 'thread'
+require 'thwait'
+
+def getenv(name, default = nil, &block)
+  if (value = ENV[name]) && !value.empty?
+    value = yield value if block
+    value
+  elsif default
+    default
+  else
+    fail "Missing ENV #{name}"
+  end
+end
+
+URL = getenv('URL') { |v| URI(v) }
+THREADS = getenv('THREADS', 8) { |v| Integer(v) }
+SKEW = getenv('SKEW', 1.0) { |v| Float(v)}
+
+$logger = Logger.new($stderr)
+$logger.progname = ARGV[0]
+
+def time
+  t = Time.now
+  r = yield
+  return Time.now - t, r
+end
+
+def client_request(url = URL)
+  Net::HTTP.start(url.hostname, url.port) do |http|
+    return http.request_post(url.path, '')
+  end
+end
+
+def client_thread(i)
+  t = Time.now
+  $logger.info "Start #{i}/#{THREADS}..."
+
+  loop do
+    skew = rand() * SKEW
+    sleep(skew)
+
+    latency, response = time { client_request(URL) }
+
+    dt = Time.now - t
+    t = Time.now
+    
+    $logger.info "[thread #{'%2d' % i}/#{THREADS}] POST #{URL} => HTTP #{response.code} in #{'%.3fs' % latency} req + #{'%.3fs' % skew} skew + #{'%.3fs' % (dt - skew - latency)} overhead: #{response.body.strip}"
+
+    response.value # raises
+  end
+end
+
+threads = (1..THREADS).map { |i|
+  thread = Thread.new do
+    begin
+      client_thread(i)
+    rescue => exc
+      $logger.error exc
+      raise
+    end
+  end
+}
+
+$logger.info "Waiting for #{threads.size} threads..."
+
+threads_wait = ThreadsWait.new(*threads)
+thread = threads_wait.next_wait
+thread.value # raises

test/spec/fixtures/stack/shutdown-test/kontena.yml

@@ -0,0 +1,49 @@
+stack: test/shutdown-test
+variables:
+  trap:
+    type: boolean
+    default: true
+  graceful_shutdown:
+    type: boolean
+  healthcheck:
+    type: boolean
+services:
+  lb:
+    image: kontena/lb
+  server:
+    build:
+      context: .
+      dockerfile: Dockerfile.server
+    image: shutdown-test-server
+    instances: 3
+    # {% if healthcheck %}
+    health_check:
+      protocol: http
+      port: 8000
+      uri: "/health?status=200"
+      initial_delay: 5
+    # {% endif %}
+    links:
+      - lb
+    environment:
+      - KONTENA_LB_INTERNAL_PORT=8000
+      - KONTENA_LB_VIRTUAL_PATH=/
+      - REQUEST_DELAY=1.0
+      # {% if trap %}
+      - TRAP=true
+      # {% if graceful_shutdown %}
+      - SHUTDOWN=true
+      # {% endif %}
+      # {% endif %}
+  client:
+    build:
+      context: .
+      dockerfile: Dockerfile.client
+    image: shutdown-test-client
+    instances: 3
+    environment:
+      - SKEW=0.5
+      - THREADS=32
+      - URL=http://lb/
+    depends_on:
+      - server

test/spec/fixtures/stack/shutdown-test/server.rb

@@ -0,0 +1,48 @@
+require 'logger'
+require 'socket'
+require 'webrick'
+
+NAME = Socket.gethostname
+PORT = 8000
+STATUS = 200
+SHUTDOWN = !!ENV['SHUTDOWN']
+TRAP = !!ENV['TRAP']
+REQUEST_DELAY = ENV['REQUEST_DELAY'].to_f
+
+$logger = Logger.new($stderr)
+$logger.progname = ARGV[0]
+
+server = WEBrick::HTTPServer.new(
+    :Port => PORT,
+)
+server.mount_proc '/' do |req, res|
+    q = req.query()
+
+    status = STATUS
+    status = q['status'].to_i if q['status']
+    delay = REQUEST_DELAY
+
+    sleep delay
+
+    res.status = status
+    res.body = "Response from #{NAME} (delay=#{'%.3fs' % delay})\n"
+end
+
+if TRAP
+  trap 'TERM' do
+    if SHUTDOWN
+      $stderr.puts "shutdown on SIGTERM with #{server.tokens.max - server.tokens.size} active clients"
+      server.shutdown # closes listeners after stopping
+    else
+      $stderr.puts "skip SIGTERM"
+    end
+  end
+else
+  # kill the process instead of allowing webrick to handle the SignalException: SIGTERM
+  trap 'TERM' do
+    exit!
+  end
+end
+
+$logger.info "start :#{PORT}"
+server.start

test/spec/support/service_helper.rb

@@ -0,0 +1,20 @@
+require 'json'
+
+module ServiceHelper
+  def service_events(service, lines: 1000)
+    k = run! "kontena service events --lines=#{lines} #{service}"
+
+    lines = k.out.lines[1..-1]
+    lines.map{|l|
+      time, type, data = l.split(' ', 3)
+
+      {time: time, type: type, data: data}
+    }
+  end
+
+  def service_logs(service, lines: 1000)
+    k = run! "kontena service logs --lines=#{lines} #{service}"
+
+    k.out.lines
+  end
+end