Google-cloud-ruby: Query listener eventually receives 0 documents and no more collection updates

[vbeffa]

I'm not sure if this is a bug or a misuse of QueryListener. I am supporting a legacy system that queries entire collections and as a result has poor performance. I am attempting to add caching and convert the queries to use the caches instead. Rewriting the queries is not an option because it would require reworking large portions of the system.

I searched other issues and stackoverflow and could not find a reference to this use of listeners (for entire collections) or problems with it. The closest I found is https://github.com/googleapis/google-cloud-ruby/issues/10872.

Environment details

• OS: Google App Engine
• Ruby version: 2.6.6
• Gem name and version: google-cloud-firestore 2.5.0

Steps to reproduce

1. Deploy caching listeners to GAE. Currently set up with auto-scale, usually two instances are deployed.
2. Wait some time, usually less than an hour. One or more listeners receive updates with 0 documents and X changes, where X is the size of the collection.
3. After that, all listeners receive no more updates even when documents are added to/modified/deleted in the collection.

Code example

# frozen_string_literal: true

require 'singleton'
require 'google/cloud/firestore'

module Admin
  module Cache
    class Users
      include Singleton

      def initialize
        Rails.logger.debug 'Initializing users cache...'

        @users = {}

        firestore = Google::Cloud::Firestore.new
        @listener = firestore.col(:users).listen do |snapshot|
          Rails.logger.debug "Received snapshot change for users: #{snapshot.docs.count} documents and #{snapshot.changes.count} changes"
          snapshot.changes.each do |changed|
            case changed.type
            when :added
              @users[changed.doc.document_id] = changed.doc
            when :modified
              @users[changed.doc.document_id] = changed.doc
            when :removed
              @users.delete(changed.doc.document_id)
            end
          end
          Rails.logger.debug 'Snapshot updates complete for users'
        end
      end

      def all
        @users
      end

      def values
        @users.values
      end

      def [](k)
        @users[k]
      end
    end
  end
end

Full backtrace

One of the instances has these logs:

root@b22a6ad1ec23:/app# grep snapshot log/production.log
D, [2021-04-18T16:27:30.458524 #6] DEBUG -- : Received snapshot change for operators: 734 documents and 734 changes
D, [2021-04-18T16:27:32.725387 #6] DEBUG -- : Received snapshot change for quote_conversation: 1013 documents and 1013 changes
D, [2021-04-18T16:27:43.277899 #6] DEBUG -- : Received snapshot change for message: 2648 documents and 2648 changes
D, [2021-04-18T16:27:59.800244 #6] DEBUG -- : Received snapshot change for quote_requests: 1846 documents and 1846 changes
D, [2021-04-18T16:28:38.734579 #6] DEBUG -- : Received snapshot change for users: 6849 documents and 6849 changes
D, [2021-04-18T16:31:12.452284 #6] DEBUG -- : Received snapshot change for quotes: 6991 documents and 6991 changes
D, [2021-04-18T16:32:07.804127 #6] DEBUG -- : Received snapshot change for alerts: 7628 documents and 7628 changes
D, [2021-04-18T16:48:58.798123 #1] DEBUG -- : Received snapshot change for operators: 734 documents and 734 changes
D, [2021-04-18T16:48:59.179099 #1] DEBUG -- : Received snapshot change for quote_conversation: 1013 documents and 1013 changes
D, [2021-04-18T16:49:06.550983 #1] DEBUG -- : Received snapshot change for quote_requests: 1846 documents and 1846 changes
D, [2021-04-18T16:49:11.748406 #1] DEBUG -- : Received snapshot change for message: 2648 documents and 2648 changes
D, [2021-04-18T16:49:42.172400 #1] DEBUG -- : Received snapshot change for users: 6849 documents and 6849 changes
D, [2021-04-18T16:50:00.375415 #1] DEBUG -- : Received snapshot change for quotes: 6991 documents and 6991 changes
D, [2021-04-18T16:50:03.771087 #1] DEBUG -- : Received snapshot change for alerts: 7628 documents and 7628 changes
D, [2021-04-18T17:49:02.282454 #1] DEBUG -- : Received snapshot change for users: 0 documents and 6849 changes

The other has these logs:

root@004fda557449:/app# grep snapshot log/production.log 
D, [2021-04-18T16:27:30.458524 #6] DEBUG -- : Received snapshot change for operators: 734 documents and 734 changes
D, [2021-04-18T16:27:32.725387 #6] DEBUG -- : Received snapshot change for quote_conversation: 1013 documents and 1013 changes
D, [2021-04-18T16:27:43.277899 #6] DEBUG -- : Received snapshot change for message: 2648 documents and 2648 changes
D, [2021-04-18T16:27:59.800244 #6] DEBUG -- : Received snapshot change for quote_requests: 1846 documents and 1846 changes
D, [2021-04-18T16:28:38.734579 #6] DEBUG -- : Received snapshot change for users: 6849 documents and 6849 changes
D, [2021-04-18T16:31:12.452284 #6] DEBUG -- : Received snapshot change for quotes: 6991 documents and 6991 changes
D, [2021-04-18T16:32:07.804127 #6] DEBUG -- : Received snapshot change for alerts: 7628 documents and 7628 changes
D, [2021-04-18T16:48:59.162978 #1] DEBUG -- : Received snapshot change for operators: 734 documents and 734 changes
D, [2021-04-18T16:49:00.419072 #1] DEBUG -- : Received snapshot change for quote_conversation: 1013 documents and 1013 changes
D, [2021-04-18T16:49:04.469009 #1] DEBUG -- : Received snapshot change for quote_requests: 1846 documents and 1846 changes
D, [2021-04-18T16:49:10.979511 #1] DEBUG -- : Received snapshot change for message: 2648 documents and 2648 changes
D, [2021-04-18T16:49:37.023442 #1] DEBUG -- : Received snapshot change for users: 6849 documents and 6849 changes
D, [2021-04-18T16:49:56.741142 #1] DEBUG -- : Received snapshot change for quotes: 6991 documents and 6991 changes
D, [2021-04-18T16:49:59.730614 #1] DEBUG -- : Received snapshot change for alerts: 7628 documents and 7628 changes

The first 7 lines in both logs are from the initial filling up of the cache. I'm not sure why the listeners receive an additional set of updates with the entire collection after about 15 minutes. An hour after that, one of the instances seems to have its collection drained (users in this case). The collection does in fact still have all documents. After that draining, both instances stop receiving any updates (add/modify/delete) to any collection.

[vbeffa]

If I start up my local Rails server and point it at the same firestore database and leave it running for a while, I don't see this problem. However, I have not done thorough testing to see if it eventually occurs locally as well.

[quartzmo]

Hi @vbeffa, thanks for opening this issue. Can you add an error handler to @listener that logs all errors and try running this again? Also, why don't we see the 'Snapshot updates complete for users' log statement in the logs? It seems like we should.

[vbeffa]

@quartzmo thanks for the quick reply. My bad on the 'Snapshot updates complete' missing - I did a grep for snapshot which is case sensitive so that's why. I'll add the error handler, deploy again, and report back.

[quartzmo]

@vbeffa Thank you. Hopefully the error handler will reveal something helpful.

Also, we just released google-cloud-firestore v2.5.1 to address #10872.

[vbeffa]

@quartzmo here are the relevant logs with the error handlers added. So possibly fixed by v2.5.1?

Instance 1:

I, [2021-04-19T20:11:00.287167 #6]  INFO -- : Initializing caches...
D, [2021-04-19T20:11:00.288853 #6] DEBUG -- : Initializing firestore connection...
D, [2021-04-19T20:11:00.329164 #6] DEBUG -- : Initialized firestore connection
D, [2021-04-19T20:11:00.329888 #6] DEBUG -- : Initializing alerts cache...
D, [2021-04-19T20:11:00.367688 #6] DEBUG -- : Initializing message cache...
D, [2021-04-19T20:11:00.418614 #6] DEBUG -- : Initializing operators cache...
D, [2021-04-19T20:11:00.522492 #6] DEBUG -- : Initializing quote_conversation cache...
D, [2021-04-19T20:11:00.560325 #6] DEBUG -- : Initializing quote_requests cache...
D, [2021-04-19T20:11:00.600227 #6] DEBUG -- : Initializing quotes cache...
D, [2021-04-19T20:11:00.640300 #6] DEBUG -- : Initializing users cache...
D, [2021-04-19T20:11:07.329097 #6] DEBUG -- : Received snapshot change for operators: 734 documents and 734 changes
D, [2021-04-19T20:11:08.138587 #6] DEBUG -- : Snapshot updates complete for operators
D, [2021-04-19T20:11:09.074914 #6] DEBUG -- : Received snapshot change for quote_conversation: 1028 documents and 1028 changes
D, [2021-04-19T20:11:09.316275 #6] DEBUG -- : Snapshot updates complete for quote_conversation
D, [2021-04-19T20:11:30.575073 #6] DEBUG -- : Received snapshot change for quote_requests: 1887 documents and 1887 changes
D, [2021-04-19T20:11:30.875701 #6] DEBUG -- : Snapshot updates complete for quote_requests
D, [2021-04-19T20:11:34.878087 #6] DEBUG -- : Received snapshot change for message: 2669 documents and 2669 changes
D, [2021-04-19T20:11:35.128424 #6] DEBUG -- : Snapshot updates complete for message
D, [2021-04-19T20:12:27.306045 #6] DEBUG -- : Received snapshot change for users: 7229 documents and 7229 changes
D, [2021-04-19T20:12:27.795283 #6] DEBUG -- : Snapshot updates complete for users
D, [2021-04-19T20:13:24.880356 #6] DEBUG -- : Received snapshot change for quotes: 7040 documents and 7040 changes
D, [2021-04-19T20:13:25.046160 #6] DEBUG -- : Snapshot updates complete for quotes
D, [2021-04-19T20:13:35.842088 #6] DEBUG -- : Received snapshot change for alerts: 7678 documents and 7678 changes
D, [2021-04-19T20:13:38.350668 #6] DEBUG -- : Snapshot updates complete for alerts
I, [2021-04-19T20:31:09.963741 #1]  INFO -- : Initializing caches...
D, [2021-04-19T20:31:09.964597 #1] DEBUG -- : Initializing firestore connection...
D, [2021-04-19T20:31:10.015258 #1] DEBUG -- : Initialized firestore connection
D, [2021-04-19T20:31:10.015903 #1] DEBUG -- : Initializing alerts cache...
D, [2021-04-19T20:31:10.106336 #1] DEBUG -- : Initializing message cache...
D, [2021-04-19T20:31:10.211382 #1] DEBUG -- : Initializing operators cache...
D, [2021-04-19T20:31:10.316989 #1] DEBUG -- : Initializing quote_conversation cache...
D, [2021-04-19T20:31:10.410275 #1] DEBUG -- : Initializing quote_requests cache...
D, [2021-04-19T20:31:10.599751 #1] DEBUG -- : Initializing quotes cache...
D, [2021-04-19T20:31:10.927833 #1] DEBUG -- : Initializing users cache...
D, [2021-04-19T20:31:11.770993 #1] DEBUG -- : Received snapshot change for operators: 734 documents and 734 changes
D, [2021-04-19T20:31:11.781654 #1] DEBUG -- : Snapshot updates complete for operators
D, [2021-04-19T20:31:12.587371 #1] DEBUG -- : Received snapshot change for quote_conversation: 1028 documents and 1028 changes
D, [2021-04-19T20:31:12.592879 #1] DEBUG -- : Snapshot updates complete for quote_conversation
D, [2021-04-19T20:31:21.763275 #1] DEBUG -- : Received snapshot change for message: 2669 documents and 2669 changes
D, [2021-04-19T20:31:22.459520 #1] DEBUG -- : Snapshot updates complete for message
D, [2021-04-19T20:31:22.784537 #1] DEBUG -- : Received snapshot change for quote_requests: 1887 documents and 1887 changes
D, [2021-04-19T20:31:22.990021 #1] DEBUG -- : Snapshot updates complete for quote_requests
D, [2021-04-19T20:32:00.376373 #1] DEBUG -- : Received snapshot change for users: 7229 documents and 7229 changes
D, [2021-04-19T20:32:00.585282 #1] DEBUG -- : Snapshot updates complete for users
D, [2021-04-19T20:32:14.504106 #1] DEBUG -- : Received snapshot change for quotes: 7040 documents and 7040 changes
D, [2021-04-19T20:32:15.800079 #1] DEBUG -- : Snapshot updates complete for quotes
D, [2021-04-19T20:32:16.936377 #1] DEBUG -- : Received snapshot change for alerts: 7678 documents and 7678 changes
D, [2021-04-19T20:32:16.953085 #1] DEBUG -- : Snapshot updates complete for alerts
...
E, [2021-04-19T21:31:11.528567 #1] ERROR -- : Message listener error: 2:No status received. debug_error_string:{"created":"@1618867871.528358373","description":"No status received","file":"src/core/lib/surface/call.cc","file_line":1086,"grpc_status":2}
E, [2021-04-19T21:31:16.979536 #1] ERROR -- : Users listener error: 2:No status received. debug_error_string:{"created":"@1618867876.979321115","description":"No status received","file":"src/core/lib/surface/call.cc","file_line":1086,"grpc_status":2}
E, [2021-04-19T21:31:28.467885 #1] ERROR -- : Alerts listener error: 2:No status received. debug_error_string:{"created":"@1618867888.467575290","description":"No status received","file":"src/core/lib/surface/call.cc","file_line":1086,"grpc_status":2}
D, [2021-04-19T21:31:36.588472 #1] DEBUG -- : Received snapshot change for quotes: 0 documents and 7040 changes
D, [2021-04-19T21:31:36.602280 #1] DEBUG -- : Snapshot updates complete for quotes

Instance 2:

I, [2021-04-19T20:11:00.287167 #6]  INFO -- : Initializing caches...
D, [2021-04-19T20:11:00.288853 #6] DEBUG -- : Initializing firestore connection...
D, [2021-04-19T20:11:00.329164 #6] DEBUG -- : Initialized firestore connection
D, [2021-04-19T20:11:00.329888 #6] DEBUG -- : Initializing alerts cache...
D, [2021-04-19T20:11:00.367688 #6] DEBUG -- : Initializing message cache...
D, [2021-04-19T20:11:00.418614 #6] DEBUG -- : Initializing operators cache...
D, [2021-04-19T20:11:00.522492 #6] DEBUG -- : Initializing quote_conversation cache...
D, [2021-04-19T20:11:00.560325 #6] DEBUG -- : Initializing quote_requests cache...
D, [2021-04-19T20:11:00.600227 #6] DEBUG -- : Initializing quotes cache...
D, [2021-04-19T20:11:00.640300 #6] DEBUG -- : Initializing users cache...
D, [2021-04-19T20:11:07.329097 #6] DEBUG -- : Received snapshot change for operators: 734 documents and 734 changes
D, [2021-04-19T20:11:08.138587 #6] DEBUG -- : Snapshot updates complete for operators
D, [2021-04-19T20:11:09.074914 #6] DEBUG -- : Received snapshot change for quote_conversation: 1028 documents and 1028 changes
D, [2021-04-19T20:11:09.316275 #6] DEBUG -- : Snapshot updates complete for quote_conversation
D, [2021-04-19T20:11:30.575073 #6] DEBUG -- : Received snapshot change for quote_requests: 1887 documents and 1887 changes
D, [2021-04-19T20:11:30.875701 #6] DEBUG -- : Snapshot updates complete for quote_requests
D, [2021-04-19T20:11:34.878087 #6] DEBUG -- : Received snapshot change for message: 2669 documents and 2669 changes
D, [2021-04-19T20:11:35.128424 #6] DEBUG -- : Snapshot updates complete for message
D, [2021-04-19T20:12:27.306045 #6] DEBUG -- : Received snapshot change for users: 7229 documents and 7229 changes
D, [2021-04-19T20:12:27.795283 #6] DEBUG -- : Snapshot updates complete for users
D, [2021-04-19T20:13:24.880356 #6] DEBUG -- : Received snapshot change for quotes: 7040 documents and 7040 changes
D, [2021-04-19T20:13:25.046160 #6] DEBUG -- : Snapshot updates complete for quotes
D, [2021-04-19T20:13:35.842088 #6] DEBUG -- : Received snapshot change for alerts: 7678 documents and 7678 changes
D, [2021-04-19T20:13:38.350668 #6] DEBUG -- : Snapshot updates complete for alerts
I, [2021-04-19T20:31:12.596990 #1]  INFO -- : Initializing caches...
D, [2021-04-19T20:31:12.597812 #1] DEBUG -- : Initializing firestore connection...
D, [2021-04-19T20:31:12.714708 #1] DEBUG -- : Initialized firestore connection
D, [2021-04-19T20:31:12.715709 #1] DEBUG -- : Initializing alerts cache...
D, [2021-04-19T20:31:12.813729 #1] DEBUG -- : Initializing message cache...
D, [2021-04-19T20:31:12.912883 #1] DEBUG -- : Initializing operators cache...
D, [2021-04-19T20:31:13.017728 #1] DEBUG -- : Initializing quote_conversation cache...
D, [2021-04-19T20:31:13.150033 #1] DEBUG -- : Initializing quote_requests cache...
D, [2021-04-19T20:31:13.374693 #1] DEBUG -- : Initializing quotes cache...
D, [2021-04-19T20:31:13.772381 #1] DEBUG -- : Initializing users cache...
D, [2021-04-19T20:31:14.252993 #1] DEBUG -- : Received snapshot change for operators: 734 documents and 734 changes
D, [2021-04-19T20:31:14.358617 #1] DEBUG -- : Snapshot updates complete for operators
D, [2021-04-19T20:31:15.604328 #1] DEBUG -- : Received snapshot change for quote_conversation: 1028 documents and 1028 changes
D, [2021-04-19T20:31:15.784584 #1] DEBUG -- : Snapshot updates complete for quote_conversation
D, [2021-04-19T20:31:24.245896 #1] DEBUG -- : Received snapshot change for quote_requests: 1887 documents and 1887 changes
D, [2021-04-19T20:31:24.938538 #1] DEBUG -- : Snapshot updates complete for quote_requests
D, [2021-04-19T20:31:27.636542 #1] DEBUG -- : Received snapshot change for message: 2669 documents and 2669 changes
D, [2021-04-19T20:31:27.771087 #1] DEBUG -- : Snapshot updates complete for message
D, [2021-04-19T20:32:02.733340 #1] DEBUG -- : Received snapshot change for users: 7229 documents and 7229 changes
D, [2021-04-19T20:32:02.751056 #1] DEBUG -- : Snapshot updates complete for users
D, [2021-04-19T20:32:21.416744 #1] DEBUG -- : Received snapshot change for quotes: 7040 documents and 7040 changes
D, [2021-04-19T20:32:21.461326 #1] DEBUG -- : Snapshot updates complete for quotes
D, [2021-04-19T20:32:24.604567 #1] DEBUG -- : Received snapshot change for alerts: 7678 documents and 7678 changes
D, [2021-04-19T20:32:24.624918 #1] DEBUG -- : Snapshot updates complete for alerts
...
E, [2021-04-19T21:31:13.684753 #1] ERROR -- : Operators listener error: 2:No status received. debug_error_string:{"created":"@1618867873.684301255","description":"No status received","file":"src/core/lib/surface/call.cc","file_line":1086,"grpc_status":2}
E, [2021-04-19T21:31:13.697325 #1] ERROR -- : Message listener error: 2:No status received. debug_error_string:{"created":"@1618867873.696958497","description":"No status received","file":"src/core/lib/surface/call.cc","file_line":1086,"grpc_status":2}
E, [2021-04-19T21:31:15.077653 #1] ERROR -- : Quote requests listener error: 2:No status received. debug_error_string:{"created":"@1618867875.077372790","description":"No status received","file":"src/core/lib/surface/call.cc","file_line":1086,"grpc_status":2}
E, [2021-04-19T21:31:16.880074 #1] ERROR -- : Users listener error: 2:No status received. debug_error_string:{"created":"@1618867876.879809362","description":"No status received","file":"src/core/lib/surface/call.cc","file_line":1086,"grpc_status":2}
E, [2021-04-19T21:31:33.530654 #1] ERROR -- : Quotes listener error: 2:No status received. debug_error_string:{"created":"@1618867893.530134411","description":"No status received","file":"src/core/lib/surface/call.cc","file_line":1086,"grpc_status":2}

[quartzmo]

Yes, can you please try upgrading to v2.5.1 to see if the retry for UNKNOWN errors (2:No status received) added in PR #11194 fixes the issue?

[vbeffa]

Yes, will do!

[vbeffa]

@quartzmo unfortunately it is still happening, even though now the listener receives no errors at all. The listener getting emptied happens almost exactly one hour after the previous update, so that must be significant, although I'm not sure why.

Instance 1:

root@db5737f64542:/app# grep -i snapshot log/production.log 
D, [2021-04-19T22:48:00.712706 #6] DEBUG -- : Received snapshot change for operators: 734 documents and 734 changes
D, [2021-04-19T22:48:00.748479 #6] DEBUG -- : Snapshot updates complete for operators
D, [2021-04-19T22:48:05.736754 #6] DEBUG -- : Received snapshot change for quote_conversation: 1028 documents and 1028 changes
D, [2021-04-19T22:48:05.742140 #6] DEBUG -- : Snapshot updates complete for quote_conversation
D, [2021-04-19T22:48:11.036513 #6] DEBUG -- : Received snapshot change for quote_requests: 1887 documents and 1887 changes
D, [2021-04-19T22:48:11.236598 #6] DEBUG -- : Snapshot updates complete for quote_requests
D, [2021-04-19T22:48:11.769147 #6] DEBUG -- : Received snapshot change for message: 2669 documents and 2669 changes
D, [2021-04-19T22:48:12.030550 #6] DEBUG -- : Snapshot updates complete for message
D, [2021-04-19T22:48:45.728848 #6] DEBUG -- : Received snapshot change for users: 7229 documents and 7229 changes
D, [2021-04-19T22:48:45.788848 #6] DEBUG -- : Snapshot updates complete for users
D, [2021-04-19T22:50:05.433655 #6] DEBUG -- : Received snapshot change for quotes: 7040 documents and 7040 changes
D, [2021-04-19T22:50:05.782286 #6] DEBUG -- : Snapshot updates complete for quotes
D, [2021-04-19T22:50:32.967920 #6] DEBUG -- : Received snapshot change for alerts: 7678 documents and 7678 changes
D, [2021-04-19T22:50:32.990999 #6] DEBUG -- : Snapshot updates complete for alerts
D, [2021-04-19T23:04:13.481879 #1] DEBUG -- : Received snapshot change for operators: 734 documents and 734 changes
D, [2021-04-19T23:04:13.484307 #1] DEBUG -- : Snapshot updates complete for operators
D, [2021-04-19T23:04:14.332051 #1] DEBUG -- : Received snapshot change for quote_conversation: 1028 documents and 1028 changes
D, [2021-04-19T23:04:14.335205 #1] DEBUG -- : Snapshot updates complete for quote_conversation
D, [2021-04-19T23:04:18.480846 #1] DEBUG -- : Received snapshot change for message: 2669 documents and 2669 changes
D, [2021-04-19T23:04:18.629303 #1] DEBUG -- : Snapshot updates complete for message
D, [2021-04-19T23:04:18.958873 #1] DEBUG -- : Received snapshot change for quote_requests: 1887 documents and 1887 changes
D, [2021-04-19T23:04:18.971783 #1] DEBUG -- : Snapshot updates complete for quote_requests
D, [2021-04-19T23:04:46.286014 #1] DEBUG -- : Received snapshot change for users: 7229 documents and 7229 changes
D, [2021-04-19T23:04:46.415844 #1] DEBUG -- : Snapshot updates complete for users
D, [2021-04-19T23:04:56.115236 #1] DEBUG -- : Received snapshot change for quotes: 7040 documents and 7040 changes
D, [2021-04-19T23:04:56.227369 #1] DEBUG -- : Snapshot updates complete for quotes
D, [2021-04-19T23:05:00.621274 #1] DEBUG -- : Received snapshot change for alerts: 7678 documents and 7678 changes
D, [2021-04-19T23:05:00.668149 #1] DEBUG -- : Snapshot updates complete for alerts
D, [2021-04-20T00:04:31.988141 #1] DEBUG -- : Received snapshot change for alerts: 0 documents and 7678 changes
D, [2021-04-20T00:04:32.002251 #1] DEBUG -- : Snapshot updates complete for alerts
root@db5737f64542:/app# grep listener log/production.log 
root@db5737f64542:/app# 

Instance 2:

root@867f9b67d6bc:/app# grep -i snapshot log/production.log 
D, [2021-04-19T22:48:00.712706 #6] DEBUG -- : Received snapshot change for operators: 734 documents and 734 changes
D, [2021-04-19T22:48:00.748479 #6] DEBUG -- : Snapshot updates complete for operators
D, [2021-04-19T22:48:05.736754 #6] DEBUG -- : Received snapshot change for quote_conversation: 1028 documents and 1028 changes
D, [2021-04-19T22:48:05.742140 #6] DEBUG -- : Snapshot updates complete for quote_conversation
D, [2021-04-19T22:48:11.036513 #6] DEBUG -- : Received snapshot change for quote_requests: 1887 documents and 1887 changes
D, [2021-04-19T22:48:11.236598 #6] DEBUG -- : Snapshot updates complete for quote_requests
D, [2021-04-19T22:48:11.769147 #6] DEBUG -- : Received snapshot change for message: 2669 documents and 2669 changes
D, [2021-04-19T22:48:12.030550 #6] DEBUG -- : Snapshot updates complete for message
D, [2021-04-19T22:48:45.728848 #6] DEBUG -- : Received snapshot change for users: 7229 documents and 7229 changes
D, [2021-04-19T22:48:45.788848 #6] DEBUG -- : Snapshot updates complete for users
D, [2021-04-19T22:50:05.433655 #6] DEBUG -- : Received snapshot change for quotes: 7040 documents and 7040 changes
D, [2021-04-19T22:50:05.782286 #6] DEBUG -- : Snapshot updates complete for quotes
D, [2021-04-19T22:50:32.967920 #6] DEBUG -- : Received snapshot change for alerts: 7678 documents and 7678 changes
D, [2021-04-19T22:50:32.990999 #6] DEBUG -- : Snapshot updates complete for alerts
D, [2021-04-19T23:04:10.562471 #1] DEBUG -- : Received snapshot change for operators: 734 documents and 734 changes
D, [2021-04-19T23:04:10.570080 #1] DEBUG -- : Snapshot updates complete for operators
D, [2021-04-19T23:04:11.321229 #1] DEBUG -- : Received snapshot change for quote_conversation: 1028 documents and 1028 changes
D, [2021-04-19T23:04:11.349497 #1] DEBUG -- : Snapshot updates complete for quote_conversation
D, [2021-04-19T23:04:14.356974 #1] DEBUG -- : Received snapshot change for quote_requests: 1887 documents and 1887 changes
D, [2021-04-19T23:04:14.569845 #1] DEBUG -- : Snapshot updates complete for quote_requests
D, [2021-04-19T23:04:18.201546 #1] DEBUG -- : Received snapshot change for message: 2669 documents and 2669 changes
D, [2021-04-19T23:04:18.259056 #1] DEBUG -- : Snapshot updates complete for message
D, [2021-04-19T23:04:46.280584 #1] DEBUG -- : Received snapshot change for users: 7229 documents and 7229 changes
D, [2021-04-19T23:04:46.469956 #1] DEBUG -- : Snapshot updates complete for users
D, [2021-04-19T23:04:57.863612 #1] DEBUG -- : Received snapshot change for quotes: 7040 documents and 7040 changes
D, [2021-04-19T23:04:58.203593 #1] DEBUG -- : Snapshot updates complete for quotes
D, [2021-04-19T23:05:04.145560 #1] DEBUG -- : Received snapshot change for alerts: 7678 documents and 7678 changes
D, [2021-04-19T23:05:04.243764 #1] DEBUG -- : Snapshot updates complete for alerts
D, [2021-04-20T00:04:29.606271 #1] DEBUG -- : Received snapshot change for quotes: 0 documents and 7040 changes
D, [2021-04-20T00:04:29.968888 #1] DEBUG -- : Snapshot updates complete for quotes
D, [2021-04-20T00:04:38.099452 #1] DEBUG -- : Received snapshot change for alerts: 0 documents and 7678 changes
D, [2021-04-20T00:04:38.118897 #1] DEBUG -- : Snapshot updates complete for alerts
root@867f9b67d6bc:/app# grep listener log/production.log 
root@867f9b67d6bc:/app# 

[quartzmo]

@vbeffa Thanks for the new logs. I'll try to reproduce this behavior myself. If you can manage to narrow the scope of your example (removing Rails for example) and/or reproduce it in another environment, that could be very helpful.

[vbeffa]

OK, I will try to do that. Give me some time to try to come up with a smaller working example.

[vbeffa]

I was able to reproduce it in my local Rails environment, pointed at the production firestore database, but not running standalone Ruby code. My computer froze up over night so I wasn't able to investigate further, but I did see the draining behavior in both alerts and users. However, it took a lot longer for it to occur, and the listeners continued to receive updates (albeit incorrect since the collections did not shrink in size).

❯ CREDENTIALS_ENV=production bundle exec rails s
warning: parser/current is loading parser/ruby26, which recognizes
warning: 2.6.7-compliant syntax, but you are running 2.6.6.
warning: please see https://github.com/whitequark/parser#compatibility-with-ruby-mri.
=> Booting Puma
=> Rails 5.2.5 application starting in development 
=> Run `rails server -h` for more startup options
I, [2021-04-21T01:03:07.034687 #19515]  INFO -- : Initializing caches...
D, [2021-04-21T01:03:07.035822 #19515] DEBUG -- : Initializing firestore connection...
D, [2021-04-21T01:03:07.951931 #19515] DEBUG -- : Initialized firestore connection
D, [2021-04-21T01:03:07.952580 #19515] DEBUG -- : Initializing alerts cache...
D, [2021-04-21T01:03:09.069856 #19515] DEBUG -- : Initializing message cache...
D, [2021-04-21T01:03:09.974670 #19515] DEBUG -- : Initializing operators cache...
D, [2021-04-21T01:03:10.896510 #19515] DEBUG -- : Initializing quote_conversation cache...
D, [2021-04-21T01:03:11.851235 #19515] DEBUG -- : Initializing quote_requests cache...
D, [2021-04-21T01:03:13.166381 #19515] DEBUG -- : Initializing quotes cache...
D, [2021-04-21T01:03:15.276605 #19515] DEBUG -- : Received snapshot change for message: 1658 documents and 1658 changes
D, [2021-04-21T01:03:15.279412 #19515] DEBUG -- : Snapshot updates complete for message
D, [2021-04-21T01:03:15.876161 #19515] DEBUG -- : Initializing users cache...
D, [2021-04-21T01:03:16.789433 #19515] DEBUG -- : Received snapshot change for operators: 734 documents and 734 changes
D, [2021-04-21T01:03:16.791263 #19515] DEBUG -- : Snapshot updates complete for operators
D, [2021-04-21T01:03:17.534974 #19515] DEBUG -- : Received snapshot change for quote_conversation: 859 documents and 859 changes
D, [2021-04-21T01:03:17.551675 #19515] DEBUG -- : Snapshot updates complete for quote_conversation
Puma starting in single mode...
* Version 3.12.6 (ruby 2.6.6-p146), codename: Llamas in Pajamas
* Min threads: 5, max threads: 5
* Environment: development
* Listening on tcp://localhost:3000
Use Ctrl-C to stop
D, [2021-04-21T01:03:26.352324 #19515] DEBUG -- : Received snapshot change for alerts: 1473 documents and 1473 changes
D, [2021-04-21T01:03:26.381248 #19515] DEBUG -- : Snapshot updates complete for alerts
D, [2021-04-21T01:03:26.889225 #19515] DEBUG -- : Received snapshot change for quote_requests: 522 documents and 522 changes
D, [2021-04-21T01:03:26.891444 #19515] DEBUG -- : Snapshot updates complete for quote_requests
D, [2021-04-21T01:03:37.800320 #19515] DEBUG -- : Received snapshot change for users: 7345 documents and 7345 changes
D, [2021-04-21T01:03:37.815441 #19515] DEBUG -- : Snapshot updates complete for users
D, [2021-04-21T01:03:43.041376 #19515] DEBUG -- : Received snapshot change for quotes: 1370 documents and 1370 changes
D, [2021-04-21T01:03:43.043741 #19515] DEBUG -- : Snapshot updates complete for quotes
D, [2021-04-21T01:47:12.971978 #19515] DEBUG -- : Received snapshot change for users: 7346 documents and 1 changes
D, [2021-04-21T01:47:12.972049 #19515] DEBUG -- : Snapshot updates complete for users
D, [2021-04-21T04:06:42.745417 #19515] DEBUG -- : Received snapshot change for users: 7346 documents and 1 changes
D, [2021-04-21T04:06:42.746103 #19515] DEBUG -- : Snapshot updates complete for users
D, [2021-04-21T04:07:45.473508 #19515] DEBUG -- : Received snapshot change for users: 7346 documents and 1 changes
D, [2021-04-21T04:07:45.473626 #19515] DEBUG -- : Snapshot updates complete for users
D, [2021-04-21T04:10:45.001814 #19515] DEBUG -- : Received snapshot change for users: 7347 documents and 1 changes
D, [2021-04-21T04:10:45.001898 #19515] DEBUG -- : Snapshot updates complete for users
D, [2021-04-21T05:29:42.691316 #19515] DEBUG -- : Received snapshot change for users: 7347 documents and 1 changes
D, [2021-04-21T05:29:42.691995 #19515] DEBUG -- : Snapshot updates complete for users
D, [2021-04-21T05:33:50.360678 #19515] DEBUG -- : Received snapshot change for users: 7347 documents and 1 changes
D, [2021-04-21T05:33:50.360787 #19515] DEBUG -- : Snapshot updates complete for users
D, [2021-04-21T05:48:20.544271 #19515] DEBUG -- : Received snapshot change for users: 7348 documents and 1 changes
D, [2021-04-21T05:48:20.544391 #19515] DEBUG -- : Snapshot updates complete for users
D, [2021-04-21T06:18:11.896863 #19515] DEBUG -- : Received snapshot change for users: 7348 documents and 1 changes
D, [2021-04-21T06:18:11.896945 #19515] DEBUG -- : Snapshot updates complete for users
D, [2021-04-21T06:19:17.907971 #19515] DEBUG -- : Received snapshot change for users: 7348 documents and 1 changes
D, [2021-04-21T06:19:17.908082 #19515] DEBUG -- : Snapshot updates complete for users
D, [2021-04-21T06:21:07.516542 #19515] DEBUG -- : Received snapshot change for quote_requests: 523 documents and 1 changes
D, [2021-04-21T06:21:07.517199 #19515] DEBUG -- : Snapshot updates complete for quote_requests
D, [2021-04-21T06:21:10.278493 #19515] DEBUG -- : Received snapshot change for quote_requests: 523 documents and 1 changes
D, [2021-04-21T06:21:10.278574 #19515] DEBUG -- : Snapshot updates complete for quote_requests
D, [2021-04-21T06:21:10.521939 #19515] DEBUG -- : Received snapshot change for quote_conversation: 860 documents and 1 changes
D, [2021-04-21T06:21:10.522015 #19515] DEBUG -- : Snapshot updates complete for quote_conversation
D, [2021-04-21T06:21:10.869747 #19515] DEBUG -- : Received snapshot change for message: 1659 documents and 1 changes
D, [2021-04-21T06:21:10.869854 #19515] DEBUG -- : Snapshot updates complete for message
D, [2021-04-21T06:37:39.283838 #19515] DEBUG -- : Received snapshot change for quote_requests: 523 documents and 1 changes
D, [2021-04-21T06:37:39.283908 #19515] DEBUG -- : Snapshot updates complete for quote_requests
D, [2021-04-21T06:37:39.416835 #19515] DEBUG -- : Received snapshot change for quotes: 1371 documents and 1 changes
D, [2021-04-21T06:37:39.416901 #19515] DEBUG -- : Snapshot updates complete for quotes
D, [2021-04-21T06:37:42.304287 #19515] DEBUG -- : Received snapshot change for alerts: 1474 documents and 1 changes
D, [2021-04-21T06:37:42.304374 #19515] DEBUG -- : Snapshot updates complete for alerts
D, [2021-04-21T06:38:33.645160 #19515] DEBUG -- : Received snapshot change for quote_requests: 523 documents and 1 changes
D, [2021-04-21T06:38:33.645236 #19515] DEBUG -- : Snapshot updates complete for quote_requests
D, [2021-04-21T06:38:33.918104 #19515] DEBUG -- : Received snapshot change for alerts: 1474 documents and 1 changes
D, [2021-04-21T06:38:33.918188 #19515] DEBUG -- : Snapshot updates complete for alerts
D, [2021-04-21T06:38:45.056919 #19515] DEBUG -- : Received snapshot change for quotes: 1371 documents and 1 changes
D, [2021-04-21T06:38:45.057004 #19515] DEBUG -- : Snapshot updates complete for quotes
D, [2021-04-21T06:39:38.482043 #19515] DEBUG -- : Received snapshot change for quote_requests: 523 documents and 1 changes
D, [2021-04-21T06:39:38.482117 #19515] DEBUG -- : Snapshot updates complete for quote_requests
D, [2021-04-21T06:53:20.516896 #19515] DEBUG -- : Received snapshot change for quote_requests: 523 documents and 1 changes
D, [2021-04-21T06:53:20.518487 #19515] DEBUG -- : Snapshot updates complete for quote_requests
D, [2021-04-21T06:53:21.173393 #19515] DEBUG -- : Received snapshot change for alerts: 1474 documents and 1 changes
D, [2021-04-21T06:53:21.174165 #19515] DEBUG -- : Snapshot updates complete for alerts
D, [2021-04-21T06:54:04.758691 #19515] DEBUG -- : Received snapshot change for quotes: 1371 documents and 1 changes
D, [2021-04-21T06:54:04.758780 #19515] DEBUG -- : Snapshot updates complete for quotes
D, [2021-04-21T06:54:27.029983 #19515] DEBUG -- : Received snapshot change for operators: 734 documents and 1 changes
D, [2021-04-21T06:54:27.030051 #19515] DEBUG -- : Snapshot updates complete for operators
D, [2021-04-21T07:00:14.610492 #19515] DEBUG -- : Received snapshot change for quote_requests: 524 documents and 1 changes
D, [2021-04-21T07:00:14.610586 #19515] DEBUG -- : Snapshot updates complete for quote_requests
D, [2021-04-21T07:00:15.725105 #19515] DEBUG -- : Received snapshot change for quote_requests: 524 documents and 1 changes
D, [2021-04-21T07:00:15.725171 #19515] DEBUG -- : Snapshot updates complete for quote_requests
D, [2021-04-21T07:02:21.309480 #19515] DEBUG -- : Received snapshot change for quote_requests: 524 documents and 1 changes
D, [2021-04-21T07:02:21.309558 #19515] DEBUG -- : Snapshot updates complete for quote_requests
D, [2021-04-21T07:02:46.822732 #19515] DEBUG -- : Received snapshot change for quotes: 1371 documents and 1 changes
D, [2021-04-21T07:02:46.822805 #19515] DEBUG -- : Snapshot updates complete for quotes
D, [2021-04-21T07:05:18.890314 #19515] DEBUG -- : Received snapshot change for users: 7348 documents and 1 changes
D, [2021-04-21T07:05:18.890959 #19515] DEBUG -- : Snapshot updates complete for users
D, [2021-04-21T07:05:42.342116 #19515] DEBUG -- : Received snapshot change for users: 7348 documents and 1 changes
D, [2021-04-21T07:05:42.342238 #19515] DEBUG -- : Snapshot updates complete for users
D, [2021-04-21T07:06:04.453041 #19515] DEBUG -- : Received snapshot change for users: 7348 documents and 1 changes
D, [2021-04-21T07:06:04.453129 #19515] DEBUG -- : Snapshot updates complete for users
D, [2021-04-21T07:07:09.278375 #19515] DEBUG -- : Received snapshot change for users: 7348 documents and 1 changes
D, [2021-04-21T07:07:09.278451 #19515] DEBUG -- : Snapshot updates complete for users
D, [2021-04-21T07:07:38.365927 #19515] DEBUG -- : Received snapshot change for users: 7348 documents and 1 changes
D, [2021-04-21T07:07:38.366650 #19515] DEBUG -- : Snapshot updates complete for users
D, [2021-04-21T07:10:26.840182 #19515] DEBUG -- : Received snapshot change for quote_requests: 524 documents and 1 changes
D, [2021-04-21T07:10:26.840265 #19515] DEBUG -- : Snapshot updates complete for quote_requests
D, [2021-04-21T07:10:26.965391 #19515] DEBUG -- : Received snapshot change for quotes: 1372 documents and 1 changes
D, [2021-04-21T07:10:26.966065 #19515] DEBUG -- : Snapshot updates complete for quotes
D, [2021-04-21T07:10:29.789033 #19515] DEBUG -- : Received snapshot change for alerts: 1475 documents and 1 changes
D, [2021-04-21T07:10:29.790386 #19515] DEBUG -- : Snapshot updates complete for alerts
D, [2021-04-21T07:12:20.541954 #19515] DEBUG -- : Received snapshot change for quote_requests: 524 documents and 1 changes
D, [2021-04-21T07:12:20.542027 #19515] DEBUG -- : Snapshot updates complete for quote_requests
D, [2021-04-21T07:12:20.677069 #19515] DEBUG -- : Received snapshot change for quotes: 1373 documents and 1 changes
D, [2021-04-21T07:12:20.677825 #19515] DEBUG -- : Snapshot updates complete for quotes
D, [2021-04-21T07:12:22.689772 #19515] DEBUG -- : Received snapshot change for alerts: 1476 documents and 1 changes
D, [2021-04-21T07:12:22.689851 #19515] DEBUG -- : Snapshot updates complete for alerts
D, [2021-04-21T07:13:07.176181 #19515] DEBUG -- : Received snapshot change for users: 7348 documents and 1 changes
D, [2021-04-21T07:13:07.176308 #19515] DEBUG -- : Snapshot updates complete for users
D, [2021-04-21T07:13:36.390843 #19515] DEBUG -- : Received snapshot change for users: 7348 documents and 1 changes
D, [2021-04-21T07:13:36.390956 #19515] DEBUG -- : Snapshot updates complete for users
D, [2021-04-21T07:15:57.624863 #19515] DEBUG -- : Received snapshot change for quotes: 1374 documents and 1 changes
D, [2021-04-21T07:15:57.624976 #19515] DEBUG -- : Snapshot updates complete for quotes
D, [2021-04-21T07:15:57.714051 #19515] DEBUG -- : Received snapshot change for quote_requests: 524 documents and 1 changes
D, [2021-04-21T07:15:57.714128 #19515] DEBUG -- : Snapshot updates complete for quote_requests
D, [2021-04-21T07:16:00.041884 #19515] DEBUG -- : Received snapshot change for alerts: 1477 documents and 1 changes
D, [2021-04-21T07:16:00.041983 #19515] DEBUG -- : Snapshot updates complete for alerts
D, [2021-04-21T07:17:06.732768 #19515] DEBUG -- : Received snapshot change for quote_requests: 524 documents and 1 changes
D, [2021-04-21T07:17:06.732844 #19515] DEBUG -- : Snapshot updates complete for quote_requests
D, [2021-04-21T07:17:06.975260 #19515] DEBUG -- : Received snapshot change for quotes: 1375 documents and 1 changes
D, [2021-04-21T07:17:06.975365 #19515] DEBUG -- : Snapshot updates complete for quotes
D, [2021-04-21T07:17:08.650106 #19515] DEBUG -- : Received snapshot change for alerts: 1478 documents and 1 changes
D, [2021-04-21T07:17:08.650838 #19515] DEBUG -- : Snapshot updates complete for alerts
D, [2021-04-21T07:20:50.694734 #19515] DEBUG -- : Received snapshot change for users: 7349 documents and 1 changes
D, [2021-04-21T07:20:50.695417 #19515] DEBUG -- : Snapshot updates complete for users
D, [2021-04-21T07:22:30.530226 #19515] DEBUG -- : Received snapshot change for users: 7350 documents and 1 changes
D, [2021-04-21T07:22:30.530311 #19515] DEBUG -- : Snapshot updates complete for users
D, [2021-04-21T07:28:51.112909 #19515] DEBUG -- : Received snapshot change for users: 7351 documents and 1 changes
D, [2021-04-21T07:28:51.113584 #19515] DEBUG -- : Snapshot updates complete for users
D, [2021-04-21T07:28:58.048734 #19515] DEBUG -- : Received snapshot change for users: 0 documents and 7351 changes
D, [2021-04-21T07:28:58.060934 #19515] DEBUG -- : Snapshot updates complete for users
D, [2021-04-21T07:50:21.432541 #19515] DEBUG -- : Received snapshot change for users: 1 documents and 1 changes
D, [2021-04-21T07:50:21.432677 #19515] DEBUG -- : Snapshot updates complete for users
D, [2021-04-21T07:52:27.985466 #19515] DEBUG -- : Received snapshot change for users: 2 documents and 1 changes
D, [2021-04-21T07:52:27.985565 #19515] DEBUG -- : Snapshot updates complete for users
D, [2021-04-21T07:59:16.217120 #19515] DEBUG -- : Received snapshot change for users: 3 documents and 1 changes
D, [2021-04-21T07:59:16.217276 #19515] DEBUG -- : Snapshot updates complete for users
D, [2021-04-21T08:01:38.259943 #19515] DEBUG -- : Received snapshot change for users: 4 documents and 1 changes
D, [2021-04-21T08:01:38.261624 #19515] DEBUG -- : Snapshot updates complete for users
D, [2021-04-21T08:02:51.954136 #19515] DEBUG -- : Received snapshot change for users: 4 documents and 1 changes
D, [2021-04-21T08:02:51.954243 #19515] DEBUG -- : Snapshot updates complete for users
D, [2021-04-21T08:05:27.048633 #19515] DEBUG -- : Received snapshot change for users: 5 documents and 1 changes
D, [2021-04-21T08:05:27.049467 #19515] DEBUG -- : Snapshot updates complete for users
D, [2021-04-21T08:07:14.355950 #19515] DEBUG -- : Received snapshot change for users: 5 documents and 1 changes
D, [2021-04-21T08:07:14.356019 #19515] DEBUG -- : Snapshot updates complete for users
D, [2021-04-21T08:09:37.937736 #19515] DEBUG -- : Received snapshot change for users: 5 documents and 1 changes
D, [2021-04-21T08:09:37.937804 #19515] DEBUG -- : Snapshot updates complete for users
D, [2021-04-21T08:10:34.048707 #19515] DEBUG -- : Received snapshot change for alerts: 0 documents and 1478 changes
D, [2021-04-21T08:10:34.050653 #19515] DEBUG -- : Snapshot updates complete for alerts
D, [2021-04-21T08:15:49.279881 #19515] DEBUG -- : Received snapshot change for users: 6 documents and 1 changes
D, [2021-04-21T08:15:49.281023 #19515] DEBUG -- : Snapshot updates complete for users
D, [2021-04-21T08:21:06.926926 #19515] DEBUG -- : Received snapshot change for quote_requests: 524 documents and 1 changes
D, [2021-04-21T08:21:06.926999 #19515] DEBUG -- : Snapshot updates complete for quote_requests
D, [2021-04-21T08:21:06.975089 #19515] DEBUG -- : Received snapshot change for quotes: 1376 documents and 1 changes
D, [2021-04-21T08:21:06.975156 #19515] DEBUG -- : Snapshot updates complete for quotes
D, [2021-04-21T08:21:12.843140 #19515] DEBUG -- : Received snapshot change for alerts: 1 documents and 1 changes
D, [2021-04-21T08:21:12.843856 #19515] DEBUG -- : Snapshot updates complete for alerts

[quartzmo]

the listeners continued to receive updates (albeit incorrect since the collections did not shrink in size).

If we ignore the documents values in the log statements, is there any evidence of incorrect behavior in the logged changes since the upgrade to 2.5.1? (You might want to log a summary of the changes' type for more precision.)

[vbeffa]

I'll add the type and run it again. I'm not sure what you're asking - the evidence I see is that the listener receives Received snapshot change for alerts: 0 documents and 1478 changes which can only mean that it's being informed that all 1478 documents in the collection have been deleted, right? And since that isn't the case, there must be an error somewhere along the way. In this last case, I'm certain that the type of all 1478 changes will be removed.

[quartzmo]

In your original code example, above, you have the following logic for updating your @users cache:

          snapshot.changes.each do |changed|
            case changed.type
            when :added
              @users[changed.doc.document_id] = changed.doc
            when :modified
              @users[changed.doc.document_id] = changed.doc
            when :removed
              @users.delete(changed.doc.document_id)
            end
          end

Can you think of a way to demonstrate that the changes being received by your callback are inconsistent with the actual state of the collection? Maybe by comparing to a separate, fresh query?

[vbeffa]

Working on it.

[vbeffa]

I implemented a double cache workaround with one cache being reset and swapped in for the other every 30 min. It runs a fresh query every time it receives a snapshot update to verify that the snapshot and query match. I haven't had a chance yet to test out the fresh query with a single cache and capture the logs, but they will be similar to this one below. The double caching seems to work - I have it running for a few days now, and I've only observed one instance in the logs of the cache seeming to get drained. Not sure what happened in that particular instance to cause it - I think the app engine may have been bringing up new instances, and the old cache stayed around for longer than 30 min.

[2021-04-25T01:01:47.130549 #1] DEBUG -- : [quotes][2][2021-04-25 01:01:46 +0000] Received snapshot change: 0 documents and 1466 changes
[2021-04-25T01:01:47.140194 #1] DEBUG -- : [quotes][2][2021-04-25 01:01:46 +0000] Snapshot updates complete
[2021-04-25T01:01:50.260947 #1]  WARN -- : [quotes][2][2021-04-25 01:01:46 +0000] Actual count 1466 did not match snapshot count 0!

Here is the double cache implementation I am using. I will try to deploy a single cache with the query checking and capture the logs as well.

# frozen_string_literal: true

require 'google/cloud/firestore'

module Admin
  module Cache
    class Cache

      def start
        @cache = {}
        @mutex = Mutex.new
        @listener1 = nil
        @listener2 = nil

        Thread.new do
          Thread.new { @listener1 = listen 1 }
          while true
            sleep(1800)
            Thread.new do
              @listener2 = listen 2
              # stop current listener
              Rails.logger.debug "[#{@coll}][1] Listener stopping..."
              @listener1.stop
              if @listener1.stopped?
                Rails.logger.debug "[#{@coll}][1] Listener stopped"
              else
                Rails.logger.warn "[#{@coll}][1] Listener not stopped!"
              end
            end
            sleep(1800)
            Thread.new do
              @listener1 = listen 1
              # stop current listener
              Rails.logger.debug "[#{@coll}][2] Listener stopping..."
              @listener2.stop
              if @listener2.stopped?
                Rails.logger.debug "[#{@coll}][2] Listener stopped"
              else
                Rails.logger.warn "[#{@coll}][2] Listener not stopped!"
              end
            end
          end
        end
      end

      def all
        return @cache
      end

      def values
        return @cache.values
      end

      def [](k)
        @cache[k]
      end

      private

      def listen(id)
        Rails.logger.debug "[#{@coll}][#{id}] Listener starting..."
        firestore = Google::Cloud::Firestore.new

        Rails.logger.debug "[#{@coll}][#{id}] Fetching collection..."
        @mutex.synchronize do
          firestore.col(@coll).list_documents.each do |doc_ref|
            @cache[doc_ref.document_id] = CacheElem.new doc_ref.get
          end
        end

        Rails.logger.debug "[#{@coll}][#{id}] Creating listener..."
        listener = firestore.col(@coll).listen do |snapshot|
          count = snapshot.docs.count
          change_count = snapshot.changes.count
          read_at = snapshot.read_at
          Rails.logger.debug "[#{@coll}][#{id}][#{read_at}] Received snapshot change: #{count} documents and #{change_count} changes"

          Thread.new do
            actual_count = Google::Cloud::Firestore.new.col(@coll).get.count
            if actual_count == count
              Rails.logger.debug "[#{@coll}][#{id}][#{read_at}] Actual count was #{actual_count} - OK"
            else
              Rails.logger.warn "[#{@coll}][#{id}][#{read_at}] Actual count #{actual_count} did not match snapshot count #{count}!"
            end
          end

          @mutex.synchronize do
            snapshot.changes.each do |changed|
              case changed.type
              when :added
                @cache[changed.doc.document_id] = CacheElem.new changed.doc
              when :modified
                @cache[changed.doc.document_id] = CacheElem.new changed.doc
              when :removed
                @cache.delete(changed.doc.document_id)
              end
            end
          end

          Rails.logger.debug "[#{@coll}][#{id}][#{read_at}] Snapshot updates complete"
        end

        listener.on_error do |error|
          Rails.logger.error "[#{@coll}][#{id}] Listener error: #{error}"
        end

        Rails.logger.debug "[#{@coll}][#{id}] Listener started"

        listener
      end

    end

    class CacheElem < Hash
      def initialize doc
        @document_id = doc.document_id
        self.merge!(doc.data)
      end

      def document_id
        @document_id
      end

      def fields
        self
      end
    end
  end
end

[quartzmo]

@vbeffa I'll try to take a look at this soon!

[quartzmo]

@vbeffa I tried again to reproduce what you are seeing with snapshot.docs.count values of 0 when there are still documents in the collection, but I haven't been able to do it. Admittedly I'm using a small collection with just a few changes that I make manually. Are you still seeing this issue? Or have you any new ideas about what might be causing it?

[vbeffa]

I've been using the double cache and have not been seeing this issue. I will try to test again tomorrow with a single cache and a small collection to see if I can still reproduce it.

[vbeffa]

@quartzmo I tested again with small collections and observed the same behavior.

[2021-04-30T19:18:55.913632 #1] DEBUG -- : [users][2021-04-30 19:18:55 +0000] Received snapshot change: 0 documents and 3 changes
[2021-04-30T19:18:55.913846 #1] DEBUG -- : [users][2021-04-30 19:18:55 +0000] Snapshot updates complete
[2021-04-30T19:18:55.983553 #1]  WARN -- : [users][2021-04-30 19:18:55 +0000] Actual count 3 did not match snapshot count 0!

Here is the cache I am using:

# frozen_string_literal: true

require 'google/cloud/firestore'

module Admin
  module Cache
    class Cache

      def start
        @cache = {}
        @mutex = Mutex.new
        @firestore = Google::Cloud::Firestore.new
        Thread.new { @listener = listen }
      end

      def all
        return @cache
      end

      def values
        return @cache.values
      end

      def size
        return @cache.size
      end

      def [](k)
        @cache[k]
      end

      private

      def listen
        Rails.logger.debug "[#{@coll}] Listener starting..."

        Rails.logger.debug "[#{@coll}] Fetching collection..."
        @mutex.synchronize do
          @firestore.col(@coll).list_documents.each do |doc_ref|
            @cache[doc_ref.document_id] = CacheElem.new doc_ref.get
          end
        end

        Rails.logger.debug "[#{@coll}] Creating listener..."
        listener = @firestore.col(@coll).listen do |snapshot|
          count = snapshot.docs.count
          change_count = snapshot.changes.count
          read_at = snapshot.read_at
          Rails.logger.debug "[#{@coll}][#{read_at}] Received snapshot change: #{count} documents and #{change_count} changes"

          Thread.new do
            actual_count = @firestore.col(@coll).get.count
            if actual_count == count
              Rails.logger.debug "[#{@coll}][#{read_at}] Actual count was #{actual_count} - OK"
            else
              Rails.logger.warn "[#{@coll}][#{read_at}] Actual count #{actual_count} did not match snapshot count #{count}!"
            end
          end

          snapshot.changes.each do |changed|
            case changed.type
            when :added
              @cache[changed.doc.document_id] = CacheElem.new changed.doc
            when :modified
              @cache[changed.doc.document_id] = CacheElem.new changed.doc
            when :removed
              @cache.delete(changed.doc.document_id)
            end
          end

          Rails.logger.debug "[#{@coll}][#{read_at}] Snapshot updates complete"
        end

        listener.on_error do |error|
          Rails.logger.error "[#{@coll}] Listener error: #{error}"
        end

        Rails.logger.debug "[#{@coll}] Listener started"

        listener
      end

    end

    class CacheElem < Hash
      def initialize doc
        @document_id = doc.document_id
        self.merge!(doc.data)
      end

      def document_id
        @document_id
      end

      def fields
        self
      end
    end
  end
end

[quartzmo]

Do the snapshot.changes always correctly reflect the current state of the collection in the service? Is the snapshot.docs.count the only problem?

[vbeffa]

It seems to be both the changes and the count. It took a while this time but I left it running for a day and finally saw the error again. I added logging of the cache size to verify that the snapshot changes are removing documents still in the collection.

[2021-05-01T17:34:46.185048 #1] DEBUG -- : [message][2021-05-01 17:34:46 +0000] Received snapshot change: 0 documents and 1 changes 
[2021-05-01T17:34:46.185280 #1] DEBUG -- : [message][2021-05-01 17:34:46 +0000] Snapshot updates complete. Cache size now 0.
[2021-05-01T17:34:46.326734 #1]  WARN -- : [message][2021-05-01 17:34:46 +0000] Actual count 1 did not match snapshot count 0!

[quartzmo]

Can you turn on the gRPC debug logging? The generic logger configuration instructions are in LOGGING.md, and I'm guessing to adapt them to rails you would use something like the following:

module MyLogger
  def logger
    Rails.logger
  end
end

# Define a gRPC module-level logger method before grpc/logconfig.rb loads.
module GRPC
  extend MyLogger
end

[quartzmo]

Or I guess you could provide a different DEBUG-level logger for gRPC to use... as long as the output goes to the same place as Rails.logger.

[quartzmo]

Also, as explained in Get realtime updates with Cloud Firestore:

Important: The first query snapshot contains added events for all existing documents that match the query. This is because you're getting a set of changes that bring your query snapshot current with the initial state of the query. This allows you, for instance, to directly populate your UI from the changes you receive in the first query snapshot, without needing to add special logic for handling the initial state.

Therefore, I don't think you need this step:

        Rails.logger.debug "[#{@coll}] Fetching collection..."
        @mutex.synchronize do
          @firestore.col(@coll).list_documents.each do |doc_ref|
            @cache[doc_ref.document_id] = CacheElem.new doc_ref.get
          end
        end

[vbeffa]

Right, my latest version takes that out.

Also, as explained in Get realtime updates with Cloud Firestore:

Important: The first query snapshot contains added events for all existing documents that match the query. This is because you're getting a set of changes that bring your query snapshot current with the initial state of the query. This allows you, for instance, to directly populate your UI from the changes you receive in the first query snapshot, without needing to add special logic for handling the initial state.

Therefore, I don't think you need this step:

        Rails.logger.debug "[#{@coll}] Fetching collection..."
        @mutex.synchronize do
          @firestore.col(@coll).list_documents.each do |doc_ref|
            @cache[doc_ref.document_id] = CacheElem.new doc_ref.get
          end
        end

[vbeffa]

Let me try to add the logging.

[vbeffa]

I'm not sure if this will be helpful, but I re-imported the prod database into staging while the double cache was running. The App Engine auto-scaled to 11 instances at one point so it's hard to tell exactly what was going on. I did notice in both the combined logs, and then by SSHing into one of the instance VMs, that one of the listeners seemed to be getting snapshot updates very slowly, one at a time, long after the collection had been restored. These are some of the logs I captured.

W, [2021-05-04T19:29:27.468567 #1]  WARN -- : [users][1][2021-05-04 17:58:36 +0000] Actual count 7892 did not match snapshot count 7886!
D, [2021-05-04T19:29:27.464003 #1] DEBUG -- : found nil; the final response has been sent
D, [2021-05-04T19:29:27.468849 #1] DEBUG -- : [users][1][2021-05-04 17:58:36 +0000] Actual count was 7892 - OK
D, [2021-05-04T19:29:24.502828 #1] DEBUG -- : bidi-read-loop: 15828
D, [2021-05-04T19:29:27.140740 #1] DEBUG -- : bidi-read-loop: 1512
W, [2021-05-04T19:29:27.464140 #1]  WARN -- : [users][1][2021-05-04 17:58:36 +0000] Actual count 7892 did not match snapshot count 7879!
D, [2021-05-04T19:29:27.596203 #1] DEBUG -- : bidi-read-loop: 15829
W, [2021-05-04T19:29:27.601514 #1]  WARN -- : [users][1][2021-05-04 17:58:36 +0000] Actual count 7892 did not match snapshot count 7884!
D, [2021-05-04T19:29:27.715467 #1] DEBUG -- : found nil; the final response has been sent
D, [2021-05-04T19:29:27.731258 #1] DEBUG -- : bidi-read-loop: 15830
D, [2021-05-04T19:29:27.732959 #1] DEBUG -- : found nil; the final response has been sent
D, [2021-05-04T19:29:27.716034 #1] DEBUG -- : found nil; the final response has been sent
W, [2021-05-04T19:29:27.724797 #1]  WARN -- : [users][1][2021-05-04 17:58:36 +0000] Actual count 7892 did not match snapshot count 7887!
W, [2021-05-04T19:29:27.733910 #1]  WARN -- : [users][1][2021-05-04 17:58:36 +0000] Actual count 7892 did not match snapshot count 7883!
W, [2021-05-04T19:29:27.724511 #1]  WARN -- : [users][1][2021-05-04 17:58:36 +0000] Actual count 7892 did not match snapshot count 7888!
W, [2021-05-04T19:29:27.734612 #1]  WARN -- : [users][1][2021-05-04 17:58:36 +0000] Actual count 7892 did not match snapshot count 7890!
W, [2021-05-04T19:29:27.736449 #1]  WARN -- : [users][1][2021-05-04 17:58:36 +0000] Actual count 7892 did not match snapshot count 7891!
W, [2021-05-04T19:29:27.406926 #1]  WARN -- : [users][1][2021-05-04 17:58:36 +0000] Actual count 7892 did not match snapshot count 7885!
D, [2021-05-04T19:29:27.841321 #1] DEBUG -- : bidi-read-loop: 15831
D, [2021-05-04T19:29:27.987141 #1] DEBUG -- : bidi-read-loop: 15832
D, [2021-05-04T19:29:28.095879 #1] DEBUG -- : bidi-read-loop: 15833
...
D, [2021-05-04T19:29:33.964727 #1] DEBUG -- : bidi-read-loop: 15887
D, [2021-05-04T19:29:34.069657 #1] DEBUG -- : bidi-read-loop: 15888
D, [2021-05-04T19:29:34.170729 #1] DEBUG -- : bidi-read-loop: 15889
D, [2021-05-04T19:29:34.170948 #1] DEBUG -- : bidi-read-loop: null batch #<struct Struct::BatchResult send_message=nil, send_metadata=nil, send_close=nil, send_status=nil, message=nil, metadata=nil, status=nil, cancelled=nil>
D, [2021-05-04T19:29:34.171150 #1] DEBUG -- : bidi-read-loop: done status #<struct Struct::Status code=2, details="No status received", metadata={}, debug_error_string="{\"created\":\"@1620156574.171079381\",\"description\":\"No status received\",\"file\":\"src/core/lib/surface/call.cc\",\"file_line\":1091,\"grpc_status\":2}">
D, [2021-05-04T19:29:34.171255 #1] DEBUG -- : Failing with status #<struct Struct::Status code=2, details="No status received", metadata={}, debug_error_string="{\"created\":\"@1620156574.171079381\",\"description\":\"No status received\",\"file\":\"src/core/lib/surface/call.cc\",\"file_line\":1091,\"grpc_status\":2}">
W, [2021-05-04T19:29:34.171362 #1]  WARN -- : bidi: read-loop failed
W, [2021-05-04T19:29:34.171419 #1]  WARN -- : 2:No status received. debug_error_string:{"created":"@1620156574.171079381","description":"No status received","file":"src/core/lib/surface/call.cc","file_line":1091,"grpc_status":2} (GRPC::Unknown)
/app/vendor/bundle/ruby/2.7.0/gems/grpc-1.37.1-x86_64-linux/src/ruby/lib/grpc/generic/active_call.rb:29:in `check_status'
/app/vendor/bundle/ruby/2.7.0/gems/grpc-1.37.1-x86_64-linux/src/ruby/lib/grpc/generic/bidi_call.rb:209:in `block in read_loop'
/app/vendor/bundle/ruby/2.7.0/gems/grpc-1.37.1-x86_64-linux/src/ruby/lib/grpc/generic/bidi_call.rb:195:in `loop'
/app/vendor/bundle/ruby/2.7.0/gems/grpc-1.37.1-x86_64-linux/src/ruby/lib/grpc/generic/bidi_call.rb:195:in `read_loop'
/app/vendor/bundle/ruby/2.7.0/bin/rackup:in `each'
D, [2021-05-04T19:29:35.173725 #1] DEBUG -- : calling firestore.googleapis.com:/google.firestore.v1.Firestore/Listen
D, [2021-05-04T19:29:35.173818 #1] DEBUG -- : bidi-write-loop: 1 writes done
D, [2021-05-04T19:29:35.176213 #1] DEBUG -- : bidi-write-loop: client sent 1, waiting
D, [2021-05-04T19:29:35.176612 #1] DEBUG -- : bidi-write-loop: done
D, [2021-05-04T19:29:35.176707 #1] DEBUG -- : bidi-write-loop: finished
D, [2021-05-04T19:29:35.177315 #1] DEBUG -- : bidi-read-loop: starting
D, [2021-05-04T19:29:37.594892 #1] DEBUG -- : bidi-read-loop: 0
D, [2021-05-04T19:29:37.594978 #1] DEBUG -- : bidi-write-loop: 0
D, [2021-05-04T19:29:37.608553 #1] DEBUG -- : bidi-read-loop: 1
D, [2021-05-04T19:29:37.654049 #1] DEBUG -- : bidi-read-loop: 2
D, [2021-05-04T19:29:37.654350 #1] DEBUG -- : bidi-read-loop: 3
D, [2021-05-04T19:29:37.654777 #1] DEBUG -- : bidi-read-loop: 4
...

And I notice this in the logs of two different instances:

root@ae5023dc0f9f:/app# grep Failing log/production.log 
...
D, [2021-05-04T16:39:46.858198 #1] DEBUG -- : Failing with status #<struct Struct::Status code=2, details="No status received", metadata={}, debug_error_string="{\"created\":\"@1620146386.857803298\",\"description\":\"No status received\",\"file\":\"src/core/lib/surface/call.cc\",\"file_line\":1091,\"grpc_status\":2}">
D, [2021-05-04T17:31:19.540725 #1] DEBUG -- : Failing with status #<struct Struct::Status code=13, details="Received RST_STREAM with error code 0", metadata={}, debug_error_string="{\"created\":\"@1620149479.540389312\",\"description\":\"Error received from peer ipv4:173.194.198.95:443\",\"file\":\"src/core/lib/surface/call.cc\",\"file_line\":1067,\"grpc_message\":\"Received RST_STREAM with error code 0\",\"grpc_status\":13}">
D, [2021-05-04T17:39:45.347726 #1] DEBUG -- : Failing with status #<struct Struct::Status code=13, details="Received RST_STREAM with error code 0", metadata={}, debug_error_string="{\"created\":\"@1620149985.347428650\",\"description\":\"Error received from peer ipv4:74.125.126.95:443\",\"file\":\"src/core/lib/surface/call.cc\",\"file_line\":1067,\"grpc_message\":\"Received RST_STREAM with error code 0\",\"grpc_status\":13}">
D, [2021-05-04T17:39:45.731482 #1] DEBUG -- : Failing with status #<struct Struct::Status code=13, details="Received RST_STREAM with error code 0", metadata={}, debug_error_string="{\"created\":\"@1620149985.731130856\",\"description\":\"Error received from peer ipv4:108.177.111.95:443\",\"file\":\"src/core/lib/surface/call.cc\",\"file_line\":1067,\"grpc_message\":\"Received RST_STREAM with error code 0\",\"grpc_status\":13}">
D, [2021-05-04T17:39:45.959668 #1] DEBUG -- : Failing with status #<struct Struct::Status code=2, details="No status received", metadata={}, debug_error_string="{\"created\":\"@1620149985.959376651\",\"description\":\"No status received\",\"file\":\"src/core/lib/surface/call.cc\",\"file_line\":1091,\"grpc_status\":2}">
D, [2021-05-04T17:39:46.118483 #1] DEBUG -- : Failing with status #<struct Struct::Status code=13, details="Received RST_STREAM with error code 0", metadata={}, debug_error_string="{\"created\":\"@1620149986.118091070\",\"description\":\"Error received from peer ipv4:108.177.111.95:443\",\"file\":\"src/core/lib/surface/call.cc\",\"file_line\":1067,\"grpc_message\":\"Received RST_STREAM with error code 0\",\"grpc_status\":13}">
D, [2021-05-04T17:39:46.175845 #1] DEBUG -- : Failing with status #<struct Struct::Status code=2, details="No status received", metadata={}, debug_error_string="{\"created\":\"@1620149986.175094767\",\"description\":\"No status received\",\"file\":\"src/core/lib/surface/call.cc\",\"file_line\":1091,\"grpc_status\":2}">
D, [2021-05-04T17:39:48.301759 #1] DEBUG -- : Failing with status #<struct Struct::Status code=13, details="Received RST_STREAM with error code 0", metadata={}, debug_error_string="{\"created\":\"@1620149988.301431147\",\"description\":\"Error received from peer ipv4:142.250.128.95:443\",\"file\":\"src/core/lib/surface/call.cc\",\"file_line\":1067,\"grpc_message\":\"Received RST_STREAM with error code 0\",\"grpc_status\":13}">
D, [2021-05-04T18:54:39.063183 #1] DEBUG -- : Failing with status #<struct Struct::Status code=2, details="No status received", metadata={}, debug_error_string="{\"created\":\"@1620154479.057376878\",\"description\":\"No status received\",\"file\":\"src/core/lib/surface/call.cc\",\"file_line\":1091,\"grpc_status\":2}">
D, [2021-05-04T18:55:40.786478 #1] DEBUG -- : Failing with status #<struct Struct::Status code=2, details="No status received", metadata={}, debug_error_string="{\"created\":\"@1620154540.409040936\",\"description\":\"No status received\",\"file\":\"src/core/lib/surface/call.cc\",\"file_line\":1091,\"grpc_status\":2}">
D, [2021-05-04T18:56:09.085663 #1] DEBUG -- : Failing with status #<struct Struct::Status code=2, details="No status received", metadata={}, debug_error_string="{\"created\":\"@1620154569.085414136\",\"description\":\"No status received\",\"file\":\"src/core/lib/surface/call.cc\",\"file_line\":1091,\"grpc_status\":2}">
D, [2021-05-04T19:06:51.185190 #1] DEBUG -- : Failing with status #<struct Struct::Status code=2, details="No status received", metadata={}, debug_error_string="{\"created\":\"@1620155211.184943385\",\"description\":\"No status received\",\"file\":\"src/core/lib/surface/call.cc\",\"file_line\":1091,\"grpc_status\":2}">
D, [2021-05-04T19:27:10.579539 #1] DEBUG -- : Failing with status #<struct Struct::Status code=13, details="Received RST_STREAM with error code 0", metadata={}, debug_error_string="{\"created\":\"@1620156430.579152093\",\"description\":\"Error received from peer ipv4:142.250.148.95:443\",\"file\":\"src/core/lib/surface/call.cc\",\"file_line\":1067,\"grpc_message\":\"Received RST_STREAM with error code 0\",\"grpc_status\":13}">
D, [2021-05-04T19:35:22.012486 #1] DEBUG -- : Failing with status #<struct Struct::Status code=13, details="Received RST_STREAM with error code 0", metadata={}, debug_error_string="{\"created\":\"@1620156922.011512336\",\"description\":\"Error received from peer ipv4:172.217.212.95:443\",\"file\":\"src/core/lib/surface/call.cc\",\"file_line\":1067,\"grpc_message\":\"Received RST_STREAM with error code 0\",\"grpc_status\":13}">
D, [2021-05-04T19:36:52.294434 #1] DEBUG -- : Failing with status #<struct Struct::Status code=13, details="Received RST_STREAM with error code 0", metadata={}, debug_error_string="{\"created\":\"@1620157012.293901728\",\"description\":\"Error received from peer ipv4:74.125.202.95:443\",\"file\":\"src/core/lib/surface/call.cc\",\"file_line\":1067,\"grpc_message\":\"Received RST_STREAM with error code 0\",\"grpc_status\":13}">

[quartzmo]

@vbeffa Did the logging configuration code I provided yesterday work without modifications for Rails, or did you have to do something different? If the latter, can you please post what you did?

[vbeffa]

It worked without modification. I placed it in config/initializers/grpc_logging.rb and the new logging appeared.

[quartzmo]

Thanks! Regarding the logs you just posted, above, can you test again with a single cache and a small collection in a single-instance environment? Or in an even more basic environment? I feel the best way to get to an answer is to reproduce in the narrowest possible scope (if possible, without even Rails or GAE).

[vbeffa]

I've been trying in the dev environment to reproduce with a single cache and a handful of documents, but it seems to take a lot longer when the collection size is small. Note that the above logs from staging don't seem to indicate a problem with the overall functionality - whatever instance is serving traffic seems to have an up-to-date cache and the website (in my brief testing) worked fine. And it didn't exhibit the draining behavior. So those grpc error logs may not indicate an actual problem.

[quartzmo]

those grpc error logs may not indicate an actual problem

I could be wrong, but I'm going to assume that those code 2 (UNKNOWN) and code 13 (INTERNAL) errors are caught in this rescue by the listener and retried. But let me know if you don't think so.

[tseaver]

Symptoms sound similar to this long-lingering python-firestore issue: https://github.com/googleapis/python-firestore/issues/18

[quartzmo]

@tseaver Thanks for the link. I skimmed through a lot of it just now, and followed a comment's link to https://github.com/googleapis/nodejs-firestore/issues/1023 (which discusses the RST_STREAM errors, seen above), but I didn't see anything actionable. If you have any ideas about this issue, feel free to through them our way.

[vbeffa]

@quartzmo here are some logs with a smaller collection where the error finally occurred. Notice that the quote_conversation cache received a snapshot update with 0 documents at 23:17:33.

[2021-05-04T23:16:01.197026 #1] DEBUG -- : bidi-read-loop: 66
[2021-05-04T23:16:02.594623 #1] DEBUG -- : bidi-read-loop: 83
[2021-05-04T23:16:02.710843 #1] DEBUG -- : bidi-read-loop: 83
[2021-05-04T23:16:08.225572 #1] DEBUG -- : bidi-read-loop: 82
[2021-05-04T23:16:08.176557 #1] DEBUG -- : bidi-read-loop: 82
[2021-05-04T23:16:14.069351 #1] DEBUG -- : bidi-read-loop: 82
[2021-05-04T23:16:27.899656 #1] DEBUG -- : bidi-read-loop: 83
[2021-05-04T23:16:28.374098 #1] DEBUG -- : bidi-read-loop: 82
[2021-05-04T23:16:28.766133 #1] DEBUG -- : bidi-read-loop: 41
[2021-05-04T23:16:28.870529 #1] DEBUG -- : bidi-read-loop: 82
[2021-05-04T23:16:33.620474 #1] DEBUG -- : bidi-read-loop: 40
[2021-05-04T23:16:35.386868 #1] DEBUG -- : bidi-read-loop: 58
[2021-05-04T23:16:40.213079 #1] DEBUG -- : bidi-read-loop: 84
[2021-05-04T23:16:46.159630 #1] DEBUG -- : bidi-read-loop: 82
[2021-05-04T23:16:46.208723 #1] DEBUG -- : bidi-read-loop: 67
[2021-05-04T23:16:47.605385 #1] DEBUG -- : bidi-read-loop: 84
[2021-05-04T23:16:47.722446 #1] DEBUG -- : bidi-read-loop: 84
[2021-05-04T23:16:53.238957 #1] DEBUG -- : bidi-read-loop: 83
[2021-05-04T23:16:53.189635 #1] DEBUG -- : bidi-read-loop: 83
[2021-05-04T23:16:59.079703 #1] DEBUG -- : bidi-read-loop: 83
[2021-05-04T23:17:12.910965 #1] DEBUG -- : bidi-read-loop: 84
[2021-05-04T23:17:13.384750 #1] DEBUG -- : bidi-read-loop: 83
[2021-05-04T23:17:13.777047 #1] DEBUG -- : bidi-read-loop: 42
[2021-05-04T23:17:13.881207 #1] DEBUG -- : bidi-read-loop: 83
[2021-05-04T23:17:18.631741 #1] DEBUG -- : bidi-read-loop: 41
[2021-05-04T23:17:20.399208 #1] DEBUG -- : bidi-read-loop: 59
[2021-05-04T23:17:25.222995 #1] DEBUG -- : bidi-read-loop: 85
[2021-05-04T23:17:31.175021 #1] DEBUG -- : bidi-read-loop: 83
[2021-05-04T23:17:31.221233 #1] DEBUG -- : bidi-read-loop: 68
[2021-05-04T23:17:31.935093 #1] DEBUG -- : bidi-read-loop: null batch #<struct Struct::BatchResult send_message=nil, send_metadata=nil, send_close=nil, send_status=nil, message=nil, metadata=nil, status=nil, cancelled=nil>
[2021-05-04T23:17:31.935384 #1] DEBUG -- : bidi-read-loop: done status #<struct Struct::Status code=2, details="No status received", metadata={}, debug_error_string="{\"created\":\"@1620170251.935199917\",\"description\":\"No status received\",\"file\":\"src/core/lib/surface/call.cc\",\"file_line\":1091,\"grpc_status\":2}">
[2021-05-04T23:17:31.935909 #1] DEBUG -- : Failing with status #<struct Struct::Status code=2, details="No status received", metadata={}, debug_error_string="{\"created\":\"@1620170251.935199917\",\"description\":\"No status received\",\"file\":\"src/core/lib/surface/call.cc\",\"file_line\":1091,\"grpc_status\":2}">
[2021-05-04T23:17:31.936041 #1]  WARN -- : bidi: read-loop failed
[2021-05-04T23:17:31.936144 #1]  WARN -- : 2:No status received. debug_error_string:{"created":"@1620170251.935199917","description":"No status received","file":"src/core/lib/surface/call.cc","file_line":1091,"grpc_status":2}
[2021-05-04T23:17:32.061253 #1] DEBUG -- : bidi-read-loop: null batch #<struct Struct::BatchResult send_message=nil, send_metadata=nil, send_close=nil, send_status=nil, message=nil, metadata=nil, status=nil, cancelled=nil>
[2021-05-04T23:17:32.068737 #1] DEBUG -- : bidi-read-loop: done status #<struct Struct::Status code=13, details="Received RST_STREAM with error code 0", metadata={}, debug_error_string="{\"created\":\"@1620170252.067552129\",\"description\":\"Error received from peer ipv4:142.250.152.95:443\",\"file\":\"src/core/lib/surface/call.cc\",\"file_line\":1067,\"grpc_message\":\"Received RST_STREAM with error code 0\",\"grpc_status\":13}">
[2021-05-04T23:17:32.069022 #1] DEBUG -- : Failing with status #<struct Struct::Status code=13, details="Received RST_STREAM with error code 0", metadata={}, debug_error_string="{\"created\":\"@1620170252.067552129\",\"description\":\"Error received from peer ipv4:142.250.152.95:443\",\"file\":\"src/core/lib/surface/call.cc\",\"file_line\":1067,\"grpc_message\":\"Received RST_STREAM with error code 0\",\"grpc_status\":13}">
[2021-05-04T23:17:32.069150 #1]  WARN -- : bidi: read-loop failed
[2021-05-04T23:17:32.069346 #1]  WARN -- : 13:Received RST_STREAM with error code 0. debug_error_string:{"created":"@1620170252.067552129","description":"Error received from peer ipv4:142.250.152.95:443","file":"src/core/lib/surface/call.cc","file_line":1067,"grpc_message":"Received RST_STREAM with error code 0","grpc_status":13}
[2021-05-04T23:17:32.097528 #1] DEBUG -- : bidi-read-loop: null batch #<struct Struct::BatchResult send_message=nil, send_metadata=nil, send_close=nil, send_status=nil, message=nil, metadata=nil, status=nil, cancelled=nil>
[2021-05-04T23:17:32.097799 #1] DEBUG -- : bidi-read-loop: done status #<struct Struct::Status code=2, details="No status received", metadata={}, debug_error_string="{\"created\":\"@1620170252.097611670\",\"description\":\"No status received\",\"file\":\"src/core/lib/surface/call.cc\",\"file_line\":1091,\"grpc_status\":2}">
[2021-05-04T23:17:32.099130 #1] DEBUG -- : Failing with status #<struct Struct::Status code=2, details="No status received", metadata={}, debug_error_string="{\"created\":\"@1620170252.097611670\",\"description\":\"No status received\",\"file\":\"src/core/lib/surface/call.cc\",\"file_line\":1091,\"grpc_status\":2}">
[2021-05-04T23:17:32.099286 #1]  WARN -- : bidi: read-loop failed
[2021-05-04T23:17:32.099505 #1]  WARN -- : 2:No status received. debug_error_string:{"created":"@1620170252.097611670","description":"No status received","file":"src/core/lib/surface/call.cc","file_line":1091,"grpc_status":2}
[2021-05-04T23:17:32.937289 #1] DEBUG -- : calling firestore.googleapis.com:/google.firestore.v1.Firestore/Listen
[2021-05-04T23:17:32.938122 #1] DEBUG -- : bidi-write-loop: 1 writes done
[2021-05-04T23:17:32.938239 #1] DEBUG -- : bidi-write-loop: client sent 1, waiting
[2021-05-04T23:17:32.938372 #1] DEBUG -- : bidi-write-loop: done
[2021-05-04T23:17:32.943838 #1] DEBUG -- : bidi-write-loop: finished
[2021-05-04T23:17:32.961337 #1] DEBUG -- : bidi-read-loop: starting
[2021-05-04T23:17:32.961413 #1] DEBUG -- : bidi-write-loop: starting
[2021-05-04T23:17:32.962746 #1] DEBUG -- : bidi-write-loop: 0
[2021-05-04T23:17:32.962530 #1] DEBUG -- : bidi-read-loop: 0
[2021-05-04T23:17:32.982726 #1] DEBUG -- : bidi-read-loop: 1
[2021-05-04T23:17:32.983069 #1] DEBUG -- : bidi-read-loop: 2
[2021-05-04T23:17:33.070158 #1] DEBUG -- : calling firestore.googleapis.com:/google.firestore.v1.Firestore/Listen
[2021-05-04T23:17:33.070905 #1] DEBUG -- : bidi-write-loop: 1 writes done
[2021-05-04T23:17:33.071026 #1] DEBUG -- : bidi-write-loop: client sent 1, waiting
[2021-05-04T23:17:33.071164 #1] DEBUG -- : bidi-write-loop: done
[2021-05-04T23:17:33.071268 #1] DEBUG -- : bidi-write-loop: finished
[2021-05-04T23:17:33.094549 #1] DEBUG -- : bidi-read-loop: starting
[2021-05-04T23:17:33.095638 #1] DEBUG -- : bidi-read-loop: 0
[2021-05-04T23:17:33.094649 #1] DEBUG -- : bidi-write-loop: starting
[2021-05-04T23:17:33.095788 #1] DEBUG -- : bidi-write-loop: 0
[2021-05-04T23:17:33.131212 #1] DEBUG -- : bidi-read-loop: 1
[2021-05-04T23:17:33.131714 #1] DEBUG -- : bidi-read-loop: 2
[2021-05-04T23:17:33.176924 #1] DEBUG -- : calling firestore.googleapis.com:/google.firestore.v1.Firestore/Listen
[2021-05-04T23:17:33.177217 #1] DEBUG -- : bidi-write-loop: 1 writes done
[2021-05-04T23:17:33.177462 #1] DEBUG -- : bidi-write-loop: client sent 1, waiting
[2021-05-04T23:17:33.177993 #1] DEBUG -- : bidi-write-loop: done
[2021-05-04T23:17:33.178230 #1] DEBUG -- : bidi-write-loop: finished
[2021-05-04T23:17:33.179340 #1] DEBUG -- : bidi-read-loop: starting
[2021-05-04T23:17:33.179393 #1] DEBUG -- : bidi-write-loop: starting
[2021-05-04T23:17:33.180349 #1] DEBUG -- : bidi-read-loop: 0
[2021-05-04T23:17:33.180408 #1] DEBUG -- : bidi-write-loop: 0
[2021-05-04T23:17:33.212847 #1] DEBUG -- : bidi-read-loop: 1
[2021-05-04T23:17:33.269553 #1] DEBUG -- : bidi-read-loop: 2
[2021-05-04T23:17:33.269959 #1] DEBUG -- : bidi-read-loop: 3
[2021-05-04T23:17:33.271218 #1] DEBUG -- : bidi-read-loop: 4
[2021-05-04T23:17:33.271607 #1] DEBUG -- : bidi-read-loop: 5
[2021-05-04T23:17:33.023829 #1] DEBUG -- : bidi-read-loop: 3
[2021-05-04T23:17:33.024589 #1] DEBUG -- : [quote_conversation][1][2021-05-04 23:17:33 +0000] Received snapshot change: 0 documents and 1 changes
[2021-05-04T23:17:33.024873 #1] DEBUG -- : [quote_conversation][1][2021-05-04 23:17:33 +0000] Snapshot updates complete. Cache size now 0.
[2021-05-04T23:17:33.025441 #1] DEBUG -- : bidi-read-loop: 4
[2021-05-04T23:17:33.025499 #1] DEBUG -- : calling firestore.googleapis.com:/google.firestore.v1.Firestore/RunQuery
[2021-05-04T23:17:33.100300 #1] DEBUG -- : calling firestore.googleapis.com:/google.firestore.v1.Firestore/Listen
[2021-05-04T23:17:33.100379 #1] DEBUG -- : bidi-write-loop: 1 writes done
[2021-05-04T23:17:33.101800 #1] DEBUG -- : bidi-write-loop: client sent 1, waiting
[2021-05-04T23:17:33.102103 #1] DEBUG -- : bidi-write-loop: done
[2021-05-04T23:17:33.102314 #1] DEBUG -- : bidi-write-loop: finished
[2021-05-04T23:17:33.122023 #1] DEBUG -- : bidi-read-loop: starting
[2021-05-04T23:17:33.122341 #1] DEBUG -- : bidi-read-loop: 0
[2021-05-04T23:17:33.122121 #1] DEBUG -- : bidi-write-loop: starting
[2021-05-04T23:17:33.123897 #1] DEBUG -- : bidi-write-loop: 0
[2021-05-04T23:17:33.147841 #1] DEBUG -- : bidi-read-loop: 1
[2021-05-04T23:17:33.148125 #1] DEBUG -- : bidi-read-loop: 2
[2021-05-04T23:17:33.271580 #1] DEBUG -- : found nil; the final response has been sent
[2021-05-04T23:17:33.272103 #1]  WARN -- : [quote_conversation][1][2021-05-04 23:17:33 +0000] Actual count 1 did not match snapshot count 0!
[2021-05-04T23:17:33.273192 #1] DEBUG -- : calling firestore.googleapis.com:/google.firestore.v1.Firestore/Listen
[2021-05-04T23:17:33.274195 #1] DEBUG -- : bidi-read-loop: starting
[2021-05-04T23:17:33.274419 #1] DEBUG -- : bidi-read-loop: 0
[2021-05-04T23:17:33.274698 #1] DEBUG -- : bidi-write-loop: starting
[2021-05-04T23:17:33.274880 #1] DEBUG -- : bidi-write-loop: 0
[2021-05-04T23:17:33.275250 #1] DEBUG -- : bidi-write-loop: 1 writes done
[2021-05-04T23:17:33.275402 #1] DEBUG -- : bidi-write-loop: client sent 1, waiting
[2021-05-04T23:17:33.275589 #1] DEBUG -- : bidi-write-loop: done
[2021-05-04T23:17:33.275792 #1] DEBUG -- : bidi-write-loop: finished
[2021-05-04T23:17:33.297110 #1] DEBUG -- : bidi-read-loop: 1
[2021-05-04T23:17:33.341936 #1] DEBUG -- : bidi-read-loop: 2
[2021-05-04T23:17:33.342508 #1] DEBUG -- : bidi-read-loop: 3
[2021-05-04T23:17:33.344331 #1] DEBUG -- : bidi-read-loop: 4
[2021-05-04T23:17:33.344624 #1] DEBUG -- : bidi-read-loop: 5
[2021-05-04T23:17:37.489303 #1] DEBUG -- : bidi-read-loop: null batch #<struct Struct::BatchResult send_message=nil, send_metadata=nil, send_close=nil, send_status=nil, message=nil, metadata=nil, status=nil, cancelled=nil>
[2021-05-04T23:17:37.491205 #1] DEBUG -- : bidi-read-loop: done status #<struct Struct::Status code=13, details="Received RST_STREAM with error code 0", metadata={}, debug_error_string="{\"created\":\"@1620170257.490711572\",\"description\":\"Error received from peer ipv4:142.250.148.95:443\",\"file\":\"src/core/lib/surface/call.cc\",\"file_line\":1067,\"grpc_message\":\"Received RST_STREAM with error code 0\",\"grpc_status\":13}">
[2021-05-04T23:17:37.491353 #1] DEBUG -- : Failing with status #<struct Struct::Status code=13, details="Received RST_STREAM with error code 0", metadata={}, debug_error_string="{\"created\":\"@1620170257.490711572\",\"description\":\"Error received from peer ipv4:142.250.148.95:443\",\"file\":\"src/core/lib/surface/call.cc\",\"file_line\":1067,\"grpc_message\":\"Received RST_STREAM with error code 0\",\"grpc_status\":13}">
[2021-05-04T23:17:37.491553 #1]  WARN -- : bidi: read-loop failed
[2021-05-04T23:17:37.491703 #1]  WARN -- : 13:Received RST_STREAM with error code 0. debug_error_string:{"created":"@1620170257.490711572","description":"Error received from peer ipv4:142.250.148.95:443","file":"src/core/lib/surface/call.cc","file_line":1067,"grpc_message":"Received RST_STREAM with error code 0","grpc_status":13}
[2021-05-04T23:17:37.482054 #1] DEBUG -- : bidi-read-loop: null batch #<struct Struct::BatchResult send_message=nil, send_metadata=nil, send_close=nil, send_status=nil, message=nil, metadata=nil, status=nil, cancelled=nil>
[2021-05-04T23:17:37.484664 #1] DEBUG -- : bidi-read-loop: done status #<struct Struct::Status code=13, details="Received RST_STREAM with error code 0", metadata={}, debug_error_string="{\"created\":\"@1620170257.484335956\",\"description\":\"Error received from peer ipv4:142.250.148.95:443\",\"file\":\"src/core/lib/surface/call.cc\",\"file_line\":1067,\"grpc_message\":\"Received RST_STREAM with error code 0\",\"grpc_status\":13}">
[2021-05-04T23:17:37.484792 #1] DEBUG -- : Failing with status #<struct Struct::Status code=13, details="Received RST_STREAM with error code 0", metadata={}, debug_error_string="{\"created\":\"@1620170257.484335956\",\"description\":\"Error received from peer ipv4:142.250.148.95:443\",\"file\":\"src/core/lib/surface/call.cc\",\"file_line\":1067,\"grpc_message\":\"Received RST_STREAM with error code 0\",\"grpc_status\":13}">
[2021-05-04T23:17:37.485018 #1]  WARN -- : bidi: read-loop failed
[2021-05-04T23:17:37.485191 #1]  WARN -- : 13:Received RST_STREAM with error code 0. debug_error_string:{"created":"@1620170257.484335956","description":"Error received from peer ipv4:142.250.148.95:443","file":"src/core/lib/surface/call.cc","file_line":1067,"grpc_message":"Received RST_STREAM with error code 0","grpc_status":13}
[2021-05-04T23:17:38.492534 #1] DEBUG -- : calling firestore.googleapis.com:/google.firestore.v1.Firestore/Listen
[2021-05-04T23:17:38.494292 #1] DEBUG -- : bidi-write-loop: 1 writes done
[2021-05-04T23:17:38.495214 #1] DEBUG -- : bidi-write-loop: client sent 1, waiting
[2021-05-04T23:17:38.495366 #1] DEBUG -- : bidi-write-loop: done
[2021-05-04T23:17:38.496220 #1] DEBUG -- : bidi-write-loop: finished
[2021-05-04T23:17:38.519061 #1] DEBUG -- : bidi-read-loop: starting
[2021-05-04T23:17:38.519152 #1] DEBUG -- : bidi-read-loop: 0
[2021-05-04T23:17:38.519388 #1] DEBUG -- : bidi-write-loop: starting
[2021-05-04T23:17:38.519687 #1] DEBUG -- : bidi-write-loop: 0
[2021-05-04T23:17:38.544438 #1] DEBUG -- : bidi-read-loop: 1
[2021-05-04T23:17:38.544890 #1] DEBUG -- : bidi-read-loop: 2
[2021-05-04T23:17:38.586912 #1] DEBUG -- : bidi-read-loop: 3
[2021-05-04T23:17:38.587321 #1] DEBUG -- : bidi-read-loop: 4
[2021-05-04T23:17:38.587681 #1] DEBUG -- : bidi-read-loop: 5
[2021-05-04T23:17:38.486084 #1] DEBUG -- : calling firestore.googleapis.com:/google.firestore.v1.Firestore/Listen
[2021-05-04T23:17:38.486974 #1] DEBUG -- : bidi-write-loop: 1 writes done
[2021-05-04T23:17:38.487108 #1] DEBUG -- : bidi-write-loop: client sent 1, waiting
[2021-05-04T23:17:38.487268 #1] DEBUG -- : bidi-write-loop: done
[2021-05-04T23:17:38.487326 #1] DEBUG -- : bidi-write-loop: finished
[2021-05-04T23:17:38.510192 #1] DEBUG -- : bidi-read-loop: starting
[2021-05-04T23:17:38.510336 #1] DEBUG -- : bidi-write-loop: starting
[2021-05-04T23:17:38.510694 #1] DEBUG -- : bidi-read-loop: 0
[2021-05-04T23:17:38.510849 #1] DEBUG -- : bidi-write-loop: 0
[2021-05-04T23:17:38.580695 #1] DEBUG -- : bidi-read-loop: 1
[2021-05-04T23:17:38.581020 #1] DEBUG -- : bidi-read-loop: 2
[2021-05-04T23:17:38.599728 #1] DEBUG -- : bidi-read-loop: 3
[2021-05-04T23:17:38.600144 #1] DEBUG -- : bidi-read-loop: 4
[2021-05-04T23:17:38.600472 #1] DEBUG -- : bidi-read-loop: 5
[2021-05-04T23:17:43.459797 #1] DEBUG -- : bidi-read-loop: null batch #<struct Struct::BatchResult send_message=nil, send_metadata=nil, send_close=nil, send_status=nil, message=nil, metadata=nil, status=nil, cancelled=nil>
[2021-05-04T23:17:43.475011 #1] DEBUG -- : bidi-read-loop: done status #<struct Struct::Status code=13, details="Received RST_STREAM with error code 0", metadata={}, debug_error_string="{\"created\":\"@1620170263.474665688\",\"description\":\"Error received from peer ipv4:142.250.1.95:443\",\"file\":\"src/core/lib/surface/call.cc\",\"file_line\":1067,\"grpc_message\":\"Received RST_STREAM with error code 0\",\"grpc_status\":13}">
[2021-05-04T23:17:43.475134 #1] DEBUG -- : Failing with status #<struct Struct::Status code=13, details="Received RST_STREAM with error code 0", metadata={}, debug_error_string="{\"created\":\"@1620170263.474665688\",\"description\":\"Error received from peer ipv4:142.250.1.95:443\",\"file\":\"src/core/lib/surface/call.cc\",\"file_line\":1067,\"grpc_message\":\"Received RST_STREAM with error code 0\",\"grpc_status\":13}">
[2021-05-04T23:17:43.475243 #1]  WARN -- : bidi: read-loop failed
[2021-05-04T23:17:43.475313 #1]  WARN -- : 13:Received RST_STREAM with error code 0. debug_error_string:{"created":"@1620170263.474665688","description":"Error received from peer ipv4:142.250.1.95:443","file":"src/core/lib/surface/call.cc","file_line":1067,"grpc_message":"Received RST_STREAM with error code 0","grpc_status":13}
[2021-05-04T23:17:44.476001 #1] DEBUG -- : calling firestore.googleapis.com:/google.firestore.v1.Firestore/Listen
[2021-05-04T23:17:44.476825 #1] DEBUG -- : bidi-write-loop: 1 writes done
[2021-05-04T23:17:44.476928 #1] DEBUG -- : bidi-write-loop: client sent 1, waiting
[2021-05-04T23:17:44.477075 #1] DEBUG -- : bidi-write-loop: done
[2021-05-04T23:17:44.477122 #1] DEBUG -- : bidi-write-loop: finished
[2021-05-04T23:17:44.498296 #1] DEBUG -- : bidi-read-loop: starting
[2021-05-04T23:17:44.498528 #1] DEBUG -- : bidi-read-loop: 0
[2021-05-04T23:17:44.498865 #1] DEBUG -- : bidi-write-loop: starting
[2021-05-04T23:17:44.499172 #1] DEBUG -- : bidi-write-loop: 0
[2021-05-04T23:17:44.520026 #1] DEBUG -- : bidi-read-loop: 1
[2021-05-04T23:17:44.520230 #1] DEBUG -- : bidi-read-loop: 2
[2021-05-04T23:17:44.557702 #1] DEBUG -- : bidi-read-loop: 3
[2021-05-04T23:17:44.557943 #1] DEBUG -- : bidi-read-loop: 4
[2021-05-04T23:17:44.559161 #1] DEBUG -- : bidi-read-loop: 5
[2021-05-04T23:17:57.894185 #1] DEBUG -- : bidi-read-loop: null batch #<struct Struct::BatchResult send_message=nil, send_metadata=nil, send_close=nil, send_status=nil, message=nil, metadata=nil, status=nil, cancelled=nil>
[2021-05-04T23:17:57.894484 #1] DEBUG -- : bidi-read-loop: done status #<struct Struct::Status code=2, details="No status received", metadata={}, debug_error_string="{\"created\":\"@1620170277.894345688\",\"description\":\"No status received\",\"file\":\"src/core/lib/surface/call.cc\",\"file_line\":1091,\"grpc_status\":2}">
[2021-05-04T23:17:57.894588 #1] DEBUG -- : Failing with status #<struct Struct::Status code=2, details="No status received", metadata={}, debug_error_string="{\"created\":\"@1620170277.894345688\",\"description\":\"No status received\",\"file\":\"src/core/lib/surface/call.cc\",\"file_line\":1091,\"grpc_status\":2}">
[2021-05-04T23:17:57.894751 #1]  WARN -- : bidi: read-loop failed
[2021-05-04T23:17:57.894883 #1]  WARN -- : 2:No status received. debug_error_string:{"created":"@1620170277.894345688","description":"No status received","file":"src/core/lib/surface/call.cc","file_line":1091,"grpc_status":2}
[2021-05-04T23:17:57.325852 #1] DEBUG -- : bidi-read-loop: null batch #<struct Struct::BatchResult send_message=nil, send_metadata=nil, send_close=nil, send_status=nil, message=nil, metadata=nil, status=nil, cancelled=nil>
[2021-05-04T23:17:57.326103 #1] DEBUG -- : bidi-read-loop: done status #<struct Struct::Status code=2, details="No status received", metadata={}, debug_error_string="{\"created\":\"@1620170277.325941251\",\"description\":\"No status received\",\"file\":\"src/core/lib/surface/call.cc\",\"file_line\":1091,\"grpc_status\":2}">
[2021-05-04T23:17:57.326180 #1] DEBUG -- : Failing with status #<struct Struct::Status code=2, details="No status received", metadata={}, debug_error_string="{\"created\":\"@1620170277.325941251\",\"description\":\"No status received\",\"file\":\"src/core/lib/surface/call.cc\",\"file_line\":1091,\"grpc_status\":2}">
[2021-05-04T23:17:57.326283 #1]  WARN -- : bidi: read-loop failed
[2021-05-04T23:17:57.326361 #1]  WARN -- : 2:No status received. debug_error_string:{"created":"@1620170277.325941251","description":"No status received","file":"src/core/lib/surface/call.cc","file_line":1091,"grpc_status":2}
[2021-05-04T23:17:58.792134 #1] DEBUG -- : bidi-read-loop: 43
[2021-05-04T23:17:58.895629 #1] DEBUG -- : calling firestore.googleapis.com:/google.firestore.v1.Firestore/Listen
[2021-05-04T23:17:58.895729 #1] DEBUG -- : bidi-write-loop: 1 writes done
[2021-05-04T23:17:58.896881 #1] DEBUG -- : bidi-write-loop: client sent 1, waiting
[2021-05-04T23:17:58.897167 #1] DEBUG -- : bidi-write-loop: done
[2021-05-04T23:17:58.897351 #1] DEBUG -- : bidi-write-loop: finished
[2021-05-04T23:17:58.916150 #1] DEBUG -- : bidi-read-loop: starting
[2021-05-04T23:17:58.916523 #1] DEBUG -- : bidi-read-loop: 0
[2021-05-04T23:17:58.916304 #1] DEBUG -- : bidi-write-loop: starting
[2021-05-04T23:17:58.917461 #1] DEBUG -- : bidi-write-loop: 0
[2021-05-04T23:17:58.935668 #1] DEBUG -- : bidi-read-loop: 1
[2021-05-04T23:17:58.936464 #1] DEBUG -- : bidi-read-loop: 2
[2021-05-04T23:17:58.315957 #1] DEBUG -- : bidi-read-loop: null batch #<struct Struct::BatchResult send_message=nil, send_metadata=nil, send_close=nil, send_status=nil, message=nil, metadata=nil, status=nil, cancelled=nil>
[2021-05-04T23:17:58.327120 #1] DEBUG -- : calling firestore.googleapis.com:/google.firestore.v1.Firestore/Listen
[2021-05-04T23:17:58.328882 #1] DEBUG -- : bidi-write-loop: 1 writes done
[2021-05-04T23:17:58.329003 #1] DEBUG -- : bidi-write-loop: client sent 1, waiting
[2021-05-04T23:17:58.329395 #1] DEBUG -- : bidi-write-loop: done
[2021-05-04T23:17:58.329598 #1] DEBUG -- : bidi-write-loop: finished
[2021-05-04T23:17:58.336055 #1] DEBUG -- : bidi-read-loop: done status #<struct Struct::Status code=13, details="Received RST_STREAM with error code 0", metadata={}, debug_error_string="{\"created\":\"@1620170278.334517551\",\"description\":\"Error received from peer ipv4:173.194.195.95:443\",\"file\":\"src/core/lib/surface/call.cc\",\"file_line\":1067,\"grpc_message\":\"Received RST_STREAM with error code 0\",\"grpc_status\":13}">
[2021-05-04T23:17:58.336152 #1] DEBUG -- : Failing with status #<struct Struct::Status code=13, details="Received RST_STREAM with error code 0", metadata={}, debug_error_string="{\"created\":\"@1620170278.334517551\",\"description\":\"Error received from peer ipv4:173.194.195.95:443\",\"file\":\"src/core/lib/surface/call.cc\",\"file_line\":1067,\"grpc_message\":\"Received RST_STREAM with error code 0\",\"grpc_status\":13}">
[2021-05-04T23:17:58.336388 #1]  WARN -- : bidi: read-loop failed
[2021-05-04T23:17:58.336521 #1]  WARN -- : 13:Received RST_STREAM with error code 0. debug_error_string:{"created":"@1620170278.334517551","description":"Error received from peer ipv4:173.194.195.95:443","file":"src/core/lib/surface/call.cc","file_line":1067,"grpc_message":"Received RST_STREAM with error code 0","grpc_status":13}
[2021-05-04T23:17:58.351320 #1] DEBUG -- : bidi-read-loop: starting
[2021-05-04T23:17:58.351718 #1] DEBUG -- : bidi-read-loop: 0
[2021-05-04T23:17:58.351953 #1] DEBUG -- : bidi-write-loop: starting
[2021-05-04T23:17:58.352138 #1] DEBUG -- : bidi-write-loop: 0
[2021-05-04T23:17:58.368657 #1] DEBUG -- : bidi-read-loop: 1
[2021-05-04T23:17:58.369070 #1] DEBUG -- : bidi-read-loop: 2
[2021-05-04T23:17:58.464099 #1] DEBUG -- : bidi-read-loop: 3
[2021-05-04T23:17:58.464590 #1] DEBUG -- : bidi-read-loop: 4
[2021-05-04T23:17:58.464988 #1] DEBUG -- : bidi-read-loop: 5
[2021-05-04T23:17:59.020221 #1] DEBUG -- : calling firestore.googleapis.com:/google.firestore.v1.Firestore/Listen
[2021-05-04T23:17:59.021516 #1] DEBUG -- : bidi-write-loop: 1 writes done
[2021-05-04T23:17:59.022695 #1] DEBUG -- : bidi-write-loop: client sent 1, waiting
[2021-05-04T23:17:59.023638 #1] DEBUG -- : bidi-read-loop: starting
[2021-05-04T23:17:59.023951 #1] DEBUG -- : bidi-read-loop: 0
[2021-05-04T23:17:59.023723 #1] DEBUG -- : bidi-write-loop: done
[2021-05-04T23:17:59.025031 #1] DEBUG -- : bidi-write-loop: finished
[2021-05-04T23:17:59.023443 #1] DEBUG -- : bidi-write-loop: starting
[2021-05-04T23:17:59.026662 #1] DEBUG -- : bidi-write-loop: 0
[2021-05-04T23:17:59.041748 #1] DEBUG -- : bidi-read-loop: 1
[2021-05-04T23:17:59.123519 #1] DEBUG -- : bidi-read-loop: 2
[2021-05-04T23:17:59.123834 #1] DEBUG -- : bidi-read-loop: 3
[2021-05-04T23:17:59.124156 #1] DEBUG -- : bidi-read-loop: 4
[2021-05-04T23:17:59.125998 #1] DEBUG -- : bidi-read-loop: 5
[2021-05-04T23:17:59.126777 #1] DEBUG -- : [users][1][2021-05-04 23:17:59 +0000] Received snapshot change: 3 documents and 3 changes
[2021-05-04T23:17:59.127718 #1] DEBUG -- : [users][1][2021-05-04 23:17:59 +0000] Snapshot updates complete. Cache size now 3.
[2021-05-04T23:17:59.128291 #1] DEBUG -- : calling firestore.googleapis.com:/google.firestore.v1.Firestore/RunQuery
[2021-05-04T23:17:59.128915 #1] DEBUG -- : bidi-read-loop: 6
[2021-05-04T23:17:59.205176 #1] DEBUG -- : found nil; the final response has been sent
[2021-05-04T23:17:59.206428 #1] DEBUG -- : [users][1][2021-05-04 23:17:59 +0000] Actual count was 3 - OK
[2021-05-04T23:17:59.337213 #1] DEBUG -- : calling firestore.googleapis.com:/google.firestore.v1.Firestore/Listen
[2021-05-04T23:17:59.337683 #1] DEBUG -- : bidi-write-loop: 1 writes done
[2021-05-04T23:17:59.337893 #1] DEBUG -- : bidi-write-loop: client sent 1, waiting
[2021-05-04T23:17:59.338179 #1] DEBUG -- : bidi-write-loop: done
[2021-05-04T23:17:59.338402 #1] DEBUG -- : bidi-write-loop: finished
[2021-05-04T23:17:59.362601 #1] DEBUG -- : bidi-read-loop: starting
[2021-05-04T23:17:59.362898 #1] DEBUG -- : bidi-read-loop: 0
[2021-05-04T23:17:59.362703 #1] DEBUG -- : bidi-write-loop: starting
[2021-05-04T23:17:59.363227 #1] DEBUG -- : bidi-write-loop: 0
[2021-05-04T23:17:59.407010 #1] DEBUG -- : bidi-read-loop: 1
[2021-05-04T23:17:59.407696 #1] DEBUG -- : bidi-read-loop: 2
[2021-05-04T23:17:59.489477 #1] DEBUG -- : calling firestore.googleapis.com:/google.firestore.v1.Firestore/Listen
[2021-05-04T23:17:59.489567 #1] DEBUG -- : bidi-write-loop: 1 writes done
[2021-05-04T23:17:59.490313 #1] DEBUG -- : bidi-write-loop: client sent 1, waiting
[2021-05-04T23:17:59.490631 #1] DEBUG -- : bidi-write-loop: done
[2021-05-04T23:17:59.490786 #1] DEBUG -- : bidi-write-loop: finished
[2021-05-04T23:17:59.491267 #1] DEBUG -- : bidi-read-loop: starting
[2021-05-04T23:17:59.491567 #1] DEBUG -- : bidi-read-loop: 0
[2021-05-04T23:17:59.491440 #1] DEBUG -- : bidi-write-loop: starting
[2021-05-04T23:17:59.492048 #1] DEBUG -- : bidi-write-loop: 0
[2021-05-04T23:17:59.523691 #1] DEBUG -- : bidi-read-loop: 1
[2021-05-04T23:17:59.606128 #1] DEBUG -- : bidi-read-loop: 2
[2021-05-04T23:17:59.606442 #1] DEBUG -- : bidi-read-loop: 3
[2021-05-04T23:17:59.607062 #1] DEBUG -- : bidi-read-loop: 4
[2021-05-04T23:17:59.607412 #1] DEBUG -- : bidi-read-loop: 5
[2021-05-04T23:17:59.607805 #1] DEBUG -- : [users][1][2021-05-04 23:17:59 +0000] Received snapshot change: 3 documents and 3 changes
[2021-05-04T23:17:59.608438 #1] DEBUG -- : [users][1][2021-05-04 23:17:59 +0000] Snapshot updates complete. Cache size now 3.
[2021-05-04T23:17:59.608583 #1] DEBUG -- : bidi-read-loop: 6
[2021-05-04T23:17:59.609045 #1] DEBUG -- : calling firestore.googleapis.com:/google.firestore.v1.Firestore/RunQuery
[2021-05-04T23:17:59.700505 #1] DEBUG -- : found nil; the final response has been sent
[2021-05-04T23:17:59.700736 #1] DEBUG -- : [users][1][2021-05-04 23:17:59 +0000] Actual count was 3 - OK
[2021-05-04T23:18:03.641357 #1] DEBUG -- : bidi-read-loop: 42
[2021-05-04T23:18:05.409704 #1] DEBUG -- : bidi-read-loop: 60
[2021-05-04T23:18:16.186688 #1] DEBUG -- : bidi-read-loop: 84
[2021-05-04T23:18:16.234375 #1] DEBUG -- : bidi-read-loop: 69
[2021-05-04T23:18:18.229731 #1] DEBUG -- : bidi-read-loop: 6
[2021-05-04T23:18:18.037999 #1] DEBUG -- : bidi-read-loop: 5
[2021-05-04T23:18:18.314493 #1] DEBUG -- : bidi-read-loop: 6
[2021-05-04T23:18:23.561431 #1] DEBUG -- : bidi-read-loop: 6
[2021-05-04T23:18:23.618219 #1] DEBUG -- : bidi-read-loop: 6
[2021-05-04T23:18:29.537688 #1] DEBUG -- : bidi-read-loop: 6
[2021-05-04T23:18:43.804984 #1] DEBUG -- : bidi-read-loop: 44
[2021-05-04T23:18:43.385326 #1] DEBUG -- : bidi-read-loop: 6
[2021-05-04T23:18:44.061269 #1] DEBUG -- : bidi-read-loop: 7
[2021-05-04T23:18:44.540072 #1] DEBUG -- : bidi-read-loop: 7
[2021-05-04T23:18:48.653326 #1] DEBUG -- : bidi-read-loop: 43
[2021-05-04T23:18:50.422300 #1] DEBUG -- : bidi-read-loop: 61
[2021-05-04T23:19:00.352529 #1] DEBUG -- : bidi-read-loop: null batch #<struct Struct::BatchResult send_message=nil, send_metadata=nil, send_close=nil, send_status=nil, message=nil, metadata=nil, status=nil, cancelled=nil>
[2021-05-04T23:19:00.354047 #1] DEBUG -- : bidi-read-loop: done status #<struct Struct::Status code=2, details="No status received", metadata={}, debug_error_string="{\"created\":\"@1620170340.352972487\",\"description\":\"No status received\",\"file\":\"src/core/lib/surface/call.cc\",\"file_line\":1091,\"grpc_status\":2}">
[2021-05-04T23:19:00.354280 #1] DEBUG -- : Failing with status #<struct Struct::Status code=2, details="No status received", metadata={}, debug_error_string="{\"created\":\"@1620170340.352972487\",\"description\":\"No status received\",\"file\":\"src/core/lib/surface/call.cc\",\"file_line\":1091,\"grpc_status\":2}">
[2021-05-04T23:19:00.354445 #1]  WARN -- : bidi: read-loop failed
[2021-05-04T23:19:00.354626 #1]  WARN -- : 2:No status received. debug_error_string:{"created":"@1620170340.352972487","description":"No status received","file":"src/core/lib/surface/call.cc","file_line":1091,"grpc_status":2}
[2021-05-04T23:19:01.355351 #1] DEBUG -- : calling firestore.googleapis.com:/google.firestore.v1.Firestore/Listen
[2021-05-04T23:19:01.356279 #1] DEBUG -- : bidi-write-loop: 1 writes done
[2021-05-04T23:19:01.356525 #1] DEBUG -- : bidi-write-loop: client sent 1, waiting
[2021-05-04T23:19:01.356777 #1] DEBUG -- : bidi-write-loop: done
[2021-05-04T23:19:01.356970 #1] DEBUG -- : bidi-write-loop: finished
[2021-05-04T23:19:01.376885 #1] DEBUG -- : bidi-read-loop: starting
[2021-05-04T23:19:01.377213 #1] DEBUG -- : bidi-read-loop: 0
[2021-05-04T23:19:01.376971 #1] DEBUG -- : bidi-write-loop: starting
[2021-05-04T23:19:01.378293 #1] DEBUG -- : bidi-write-loop: 0
[2021-05-04T23:19:01.400576 #1] DEBUG -- : bidi-read-loop: 1
[2021-05-04T23:19:01.401611 #1] DEBUG -- : bidi-read-loop: 2
[2021-05-04T23:19:01.574088 #1] DEBUG -- : bidi-read-loop: 3
[2021-05-04T23:19:01.575027 #1] DEBUG -- : bidi-read-loop: 4
[2021-05-04T23:19:01.575494 #1] DEBUG -- : bidi-read-loop: 5
[2021-05-04T23:19:01.244843 #1] DEBUG -- : bidi-read-loop: 70

[quartzmo]

@vbeffa Unfortunately the gRPC logging doesn't appear to contain anything helpful that I can see. I'm still unsure why you are getting 0 documents snapshot that empties your cache when the query still returns document(s): Received snapshot change: 0 documents and 1 changes.

Are any more snapshots received for quote_conversation?

[quartzmo]

I'll look into getting more helpful logs with https://github.com/grpc/grpc/blob/master/TROUBLESHOOTING.md.

[vbeffa]

Are any more snapshots received for quote_conversation?

Yes, one hour later it received an update:

D, [2021-05-05T00:17:34.506253 #1] DEBUG -- : [quote_conversation][1][2021-05-05 00:17:34 +0000] Received snapshot change: 1 documents and 1 changes
D, [2021-05-05T00:17:34.506605 #1] DEBUG -- : [quote_conversation][1][2021-05-05 00:17:34 +0000] Snapshot updates complete. Cache size now 1.
D, [2021-05-05T00:17:34.573274 #1] DEBUG -- : [quote_conversation][1][2021-05-05 00:17:34 +0000] Actual count was 1 - OK

I don't see any other logs for quote_conversation between those times.

[quartzmo]

Did that update restore it to its correct state by any chance?

[vbeffa]

I believe so, but I didn't have a chance to verify that.

[vbeffa]

@quartzmo I haven't been able to do any more testing, and I will shortly be moving from the legacy project to work on the new system. My guess is that the cache draining is somehow related to the App Engine's instance replication, but I don't have a good explanation for how it's happening. Feel free to close or keep this open as you think best.

[quartzmo]

@vbeffa Thank you for all the work you put into this difficult issue!

I'm sorry we never resolved it. However, this public record should be easy to find for anyone who encounters similar behavior in the future. I will close this issue now.