stale race: use atomic methods for deletions, mark deleted nodes

Refactor of `S3::FileRepository` to avoid several closely-related race
conditions:

 - prevent `get_factory()` from yielding a factory that was
   mid-deletion by the stale watcher, which could cause the plugin
   crash due to the file no longer existing on disk. This is solved
   by marking a factory's prefix wrapper as deleted while the stale
   watcher has exclusive access to it, and checking for deletion
   status before yielding exclusive access to a prefix wrapper's factory.
 - eliminates `get_factory()`'s non-atomic `Concurrent::Map#fetch_or_store`,
   which could cause multiple factories to be created for a single
   prefix, only one of which would be retained and bytes written to
   the other(s) would be lost.
 - introduce `each_factory`, which _avoids_ creating new factories
   or yielding deleted ones.
 - refactor `each_files` to use new `each_factory` to avoid yielding
   files whose factories have been deleted.

Additionally, `S3#rotate_if_needed` was migrated to use the now-safer
`S3::FileRepository#each_factory` that _avoids_ initializing new
factories (and therefore avoids creating empty files on disk after
the existing ones had been stale-reaped).

Author: yaauie

CHANGELOG.md

@@ -1,3 +1,9 @@
+## 4.4.1
+  - Fixes several closely-related race conditions that could cause plugin crashes or data-loss
+    - race condition in initializing a prefix could cause one or more local temp files to be abandoned and only recovered after next pipeline start
+    - race condition in stale watcher could cause the plugin to crash when working with a stale (empty) file that had been deleted
+    - race condition in stale watcher could cause a non-empty file to be deleted if bytes were written to it after it was detected as stale
+
 ## 4.4.0
   - Logstash recovers corrupted gzip and uploads to S3 [#249](https://github.com/logstash-plugins/logstash-output-s3/pull/249)
 

lib/logstash/outputs/s3.rb

@@ -344,22 +344,22 @@ def bucket_resource
   end
 
   def rotate_if_needed(prefixes)
-    prefixes.each do |prefix|
-      # Each file access is thread safe,
-      # until the rotation is done then only
-      # one thread has access to the resource.
-      @file_repository.get_factory(prefix) do |factory|
-        temp_file = factory.current
-
-        if @rotation.rotate?(temp_file)
-          @logger.debug? && @logger.debug("Rotate file",
-                                          :key => temp_file.key,
-                                          :path => temp_file.path,
-                                          :strategy => @rotation.class.name)
-
-          upload_file(temp_file)
-          factory.rotate!
-        end
+    # Each file access is thread safe,
+    # until the rotation is done then only
+    # one thread has access to the resource.
+    @file_repository.each_factory(prefixes) do |factory|
+      # we have exclusive access to the one-and-only
+      # prefix WRAPPER for this factory.
+      temp_file = factory.current
+
+      if @rotation.rotate?(temp_file)
+        @logger.debug? && @logger.debug("Rotate file",
+                                        :key => temp_file.key,
+                                        :path => temp_file.path,
+                                        :strategy => @rotation.class.name)
+
+        upload_file(temp_file) # may be async or blocking
+        factory.rotate!
       end
     end
   end

lib/logstash/outputs/s3/file_repository.rb

@@ -15,8 +15,9 @@ class FileRepository
         class PrefixedValue
           def initialize(file_factory, stale_time)
             @file_factory = file_factory
-            @lock = Mutex.new
+            @lock = Monitor.new
             @stale_time = stale_time
+            @is_deleted = false
           end
 
           def with_lock
@@ -34,7 +35,14 @@ def apply(prefix)
           end
 
           def delete!
-            with_lock{ |factory| factory.current.delete! }
+            with_lock do |factory|
+              factory.current.delete!
+              @is_deleted = true
+            end
+          end
+
+          def deleted?
+            with_lock { |_| @is_deleted }
           end
         end
 
@@ -72,17 +80,52 @@ def keys
         end
 
         def each_files
-          @prefixed_factories.values.each do |prefixed_file|
-            prefixed_file.with_lock { |factory| yield factory.current }
+          each_factory(keys) do |factory|
+            yield factory.current
           end
         end
 
-        # Return the file factory
+        ##
+        # Yields the file factory while the current thread has exclusive access to it, creating a new
+        # one if one does not exist or if the current one is being reaped by the stale watcher.
+        # @param prefix_key [String]: the prefix key
+        # @yieldparam factory [TemporaryFileFactory]: a temporary file factory that this thread has exclusive access to
+        # @yieldreturn [Object]: a value to return; should NOT be the factory, which should be contained by the exclusive access scope.
+        # @return [Object]: the value returned by the provided block
         def get_factory(prefix_key)
-          prefix_val = @prefixed_factories.fetch_or_store(prefix_key) { @factory_initializer.create_value(prefix_key) }
+
+          # fast-path: if factory exists and is not deleted, yield it with exclusive access and return
+          prefix_val = @prefixed_factories.get(prefix_key)
+          prefix_val&.with_lock do |factory|
+            # intentional local-jump to ensure deletion detection
+            # is done inside the exclusive access.
+            return yield(factory) unless prefix_val.deleted?
+          end
+
+          # slow-path:
+          # the Concurrent::Map#get operation is lock-free, but may have returned an entry that was being deleted by
+          # another thread (such as via stale detection). If we failed to retrieve a value, or retrieved one that had
+          # been marked deleted, use the atomic Concurrent::Map#compute to retrieve a non-deleted entry.
+          prefix_val = @prefixed_factories.compute(prefix_key) do |existing|
+            existing && !existing.deleted? ? existing : @factory_initializer.create_value(prefix_key)
+          end
           prefix_val.with_lock { |factory| yield factory }
         end
 
+        ##
+        # Yields each non-deleted file factory while the current thread has exclusive access to it.
+        # @param prefixes [Array<String>]: the prefix keys
+        # @yieldparam factory [TemporaryFileFactory]
+        # @return [void]
+        def each_factory(prefixes)
+          prefixes.each do |prefix_key|
+            prefix_val = @prefixed_factories.get(prefix_key)
+            prefix_val&.with_lock do |factory|
+              yield factory unless prefix_val.deleted?
+            end
+          end
+        end
+
         def get_file(prefix_key)
           get_factory(prefix_key) { |factory| yield factory.current }
         end
@@ -95,18 +138,31 @@ def size
           @prefixed_factories.size
         end
 
-        def remove_stale(k, v)
-          if v.stale?
-            @prefixed_factories.delete_pair(k, v)
-            v.delete!
+        def remove_if_stale(prefix_key)
+          # we use the ATOMIC `Concurrent::Map#compute_if_present` to atomically
+          # detect the staleness, mark a stale prefixed factory as deleted, and delete from the map.
+          @prefixed_factories.compute_if_present(prefix_key) do |prefixed_factory|
+            # once we have retrieved an instance, we acquire exclusive access to it
+            # for stale detection, marking it as deleted before releasing the lock
+            # and causing it to become deleted from the map.
+            prefixed_factory.with_lock do |_|
+              if prefixed_factory.stale?
+                prefixed_factory.delete! # mark deleted to prevent reuse
+                nil # cause deletion
+              else
+                prefixed_factory # keep existing
+              end
+            end
           end
         end
 
         def start_stale_sweeper
           @stale_sweeper = Concurrent::TimerTask.new(:execution_interval => @sweeper_interval) do
             LogStash::Util.set_thread_name("S3, Stale factory sweeper")
 
-            @prefixed_factories.each { |k, v| remove_stale(k,v) }
+            @prefixed_factories.keys.each do |prefix|
+              remove_if_stale(prefix)
+            end
           end
 
           @stale_sweeper.execute

logstash-output-s3.gemspec

@@ -1,6 +1,6 @@
 Gem::Specification.new do |s|
   s.name            = 'logstash-output-s3'
-  s.version         = '4.4.0'
+  s.version         = '4.4.1'
   s.licenses        = ['Apache-2.0']
   s.summary         = "Sends Logstash events to the Amazon Simple Storage Service"
   s.description     = "This gem is a Logstash plugin required to be installed on top of the Logstash core pipeline using $LS_HOME/bin/logstash-plugin install gemname. This gem is not a stand-alone program"