[ARVADOS] created: 683134fdf9720e39be20b263fddcd4c2793150ef

[Git user]

        at  683134fdf9720e39be20b263fddcd4c2793150ef (commit)


commit 683134fdf9720e39be20b263fddcd4c2793150ef
Author: Peter Amstutz <peter.amstutz at curoverse.com>
Date:   Thu Jun 9 15:53:48 2016 -0400

    9388: Work around ephemeral gaps in log event sequence in websocket server.
    
    Web sockets relies on the fact that the 'id' field is monotonically increasing.
    However, when records are created concurrently in the database, it is possible
    for a record with id '2' to appear in SELECT before id '1'.  This adjusts the
    behavior by performing an additional query to determine which upcoming log
    events are actually visible in the table to ensure that "missing" rows are not
    skipped over.

diff --git a/services/api/app/models/log.rb b/services/api/app/models/log.rb
index b10a491..d0f6c53 100644
--- a/services/api/app/models/log.rb
+++ b/services/api/app/models/log.rb
@@ -5,7 +5,7 @@ class Log < ArvadosModel
   serialize :properties, Hash
   before_validation :set_default_event_at
   attr_accessor :object, :object_kind
-  after_save :send_notify
+  after_commit :send_notify
 
   api_accessible :user, extend: :common do |t|
     t.add :id
diff --git a/services/api/lib/eventbus.rb b/services/api/lib/eventbus.rb
index 9bf95f5..ee19212 100644
--- a/services/api/lib/eventbus.rb
+++ b/services/api/lib/eventbus.rb
@@ -81,15 +81,14 @@ class EventBus
         cond_out = []
         param_out = []
 
+        cond_id = "logs.id > ?"
         if !ws.last_log_id.nil?
           # Client is only interested in log rows that are newer than the
           # last log row seen by the client.
-          cond_id = "logs.id > ?"
           param_out << ws.last_log_id
         elsif !notify_id.nil?
           # No last log id, so look at rows starting with notify id
-          cond_id = "logs.id >= ?"
-          param_out << notify_id
+          param_out << (notify_id-1)
         else
           # No log id to start from, nothing to do, return
           return
@@ -114,28 +113,50 @@ class EventBus
           logs = logs.where(cond_id, *param_out)
         end
 
-        # Execute query and actually send the matching log rows
-        count = 0
-        limit = 10
+        # This is the next value for 'id' that we expect
+        nextid = param_out[0] + 1
+        limit = 0
+
+        # Need to determine how many rows in sequence are are actually in the
+        # logs table.  This is necessary because it is possible for there to be
+        # temporary gaps due to concurrent record creation, for example id '2'
+        # might commit before id '1' but we don't want to skip id '1'.
+        #
+        # This assumes a gap in the sequence will quickly get filled.  If the
+        # row is actually deleted, this will get stuck and we will need to
+        # revisit this assumption.
+        Log.where(cond_id, param_out[0]).order("id asc").select(:id).limit(10).each do |l|
+          if l.id == nextid
+            nextid += 1
+            limit += 1
+          else
+            break
+          end
+        end
+
+        # Record the highest id in sequence as the starting
+        # point the next time around.
+        ws.last_log_id = nextid - 1
 
-        logs.limit(limit).each do |l|
-          ws.send(l.as_api_response.to_json)
-          ws.last_log_id = l.id
-          count += 1
+        count = 0
+        if limit > 0
+          # Now actually send the rows that are readable by the user and match
+          # the filters.
+          logs.limit(limit).each do |l|
+            ws.send(l.as_api_response.to_json)
+            count += 1
+          end
         end
 
         if count == limit
-          # Number of rows returned was capped by limit(), we need to schedule
-          # another query to get more logs (will start from last_log_id
-          # reported by current query)
+          # Number of rows returned may have been capped, there are more logs
+          # so we need to schedule another just query in case.  The next query
+          # will start from last_log_id of the current query.
           EventMachine::next_tick do
-            push_events ws, nil
+            push_events ws, notify_id
           end
-        elsif !notify_id.nil? and (ws.last_log_id.nil? or notify_id > ws.last_log_id)
-          # Number of rows returned was less than cap, but the notify id is
-          # higher than the last id visible to the client, so update last_log_id
-          ws.last_log_id = notify_id
         end
+
       elsif !notify_id.nil?
         # No filters set up, so just record the sequence number
         ws.last_log_id = notify_id

-----------------------------------------------------------------------


hooks/post-receive
--