couchbase/couchbase-lite-ios

CBLDatabase mustBeOpen during a timeout error

Brunz opened this issue · 6 comments

Brunz commented

Describe the bug
When replicators detach from Sync Gateway with a timeout error, the database is closed and then reopened. (see the log below). Why is the database closed if the push and pull replicators become disconnected?
If at that moment there is a query in progress the app will crash.

Fatal Exception: NSInternalInconsistencyException
0 CoreFoundation 0x1b5642114 __exceptionPreprocess
1 libobjc.A.dylib 0x1c8e68cb4 objc_exception_throw
2 CoreFoundation 0x1b55452cc -[NSCache init]
3 CouchbaseLiteSwift 0x107ac0640 -[CBLDatabase mustBeOpen] + 666 (CBLDatabase.mm:666)
4 CouchbaseLiteSwift 0x107ac0674 -[CBLDatabase mustBeOpenLocked] + 671 (CBLDatabase.mm:671)
5 CouchbaseLiteSwift 0x107ac9ecc -[CBLQuery check:] + 260 (CBLQuery.mm:260)
6 CouchbaseLiteSwift 0x107ac99a4 -[CBLQuery execute:] + 190 (CBLQuery.mm:190)
7 CouchbaseLiteSwift 0x107969b2c Query.execute() + 56 (Query.swift:56)
8 CouchbaseLiteSwift 0x10796ab30 dispatch thunk of Query.execute()
9 i######LibShared 0x107175c3c specialized GreenLineDocumentsHelper.getWarehouseItemDiz() + 1086 (GreenLineDocumentsHelper.swift:1086)
10 i######LibShared 0x106fe1358 closure #1 in GreenLineQuery.getProductList2020(preloadDoc:priceListId:completionHandler:) + 151 (GreenLineQuery.swift:151)
11 i######LibShared 0x106bcfe5c thunk for @escaping @callee_guaranteed () -> () ()
12 libdispatch.dylib 0x1b527a298 _dispatch_call_block_and_release
13 libdispatch.dylib 0x1b527b280 _dispatch_client_callout
14 libdispatch.dylib 0x1b522d254 _dispatch_root_queue_drain
15 libdispatch.dylib 0x1b522d8e4 _dispatch_worker_thread2
16 libsystem_pthread.dylib 0x1fa284568 _pthread_wqthread
17 libsystem_pthread.dylib 0x1fa287874 start_wqthread

To Reproduce
Run a query and close the database

Expected behavior
We expect the query to fail without crashing the application

Logs
2021-04-14 15:54:41.784456+0200 Eat[7569:3717042] CouchbaseLite Replicator ERROR: {Repl#38} Got LiteCore error: Network error 3 "connection timed out"
2021-04-14 15:54:41.785705+0200 Eat[7569:3717042] CouchbaseLite Replicator Verbose: {Repl#38} progress +0/+0, 0 docs -- now 855 / 855, 128 docs
2021-04-14 15:54:41.786902+0200 Eat[7569:3717042] CouchbaseLite Replicator Info: {Repl#38} activityLevel=busy: connectionState=-1
2021-04-14 15:54:41.787668+0200 Eat[7569:3717042] CouchbaseLite Replicator Info: {Repl#38} now busy
2021-04-14 15:54:41.788845+0200 Eat[7569:3717042] CouchbaseLite Replicator ERROR: {C4Replicator#39} State: busy, progress=100.00%, error=Network error 3 "connection timed out"
2021-04-14 15:54:41.789487+0200 Eat[7569:3717042] CouchbaseLite Replicator Info: {Repl#38} pushStatus=stopped, pullStatus=idle, progress=855/855
2021-04-14 15:54:41.790244+0200 Eat[7569:3717042] CouchbaseLite Replicator Info: {Repl#38} activityLevel=busy: connectionState=-1
2021-04-14 15:54:41.790887+0200 Eat[7569:3717042] CouchbaseLite Replicator Info: {Repl#38} pushStatus=stopped, pullStatus=stopped, progress=855/855
2021-04-14 15:54:41.791397+0200 Eat[7569:3717042] CouchbaseLite Replicator Info: {Repl#38} activityLevel=stopped: connectionState=-1
2021-04-14 15:54:41.792072+0200 Eat[7569:3717042] CouchbaseLite Replicator Info: {Repl#38} now stopped
2021-04-14 15:54:41.792883+0200 Eat[7569:3717042] CouchbaseLite Replicator Info: BLIP sent 261 msgs (17114 bytes), rcvd 212 msgs (22184 bytes) in 1810.060 sec. Max outbox depth was 1, avg 1.00
2021-04-14 15:54:41.793861+0200 Eat[7569:3717045] CouchbaseLite Replicator Info: CBLReplicator[<> URL[wss://sg-lb.****.it:443/]] is busy, progress 855/855, error: Error Domain=CouchbaseLite Code=5003 "connection timed out" UserInfo={NSLocalizedDescription=connection timed out}
2021-04-14 15:54:41.794246+0200 Eat[7569:3717042] CouchbaseLite Database Verbose: {DB#36} Housekeeping: 0 of 10280 pages free (0%)
"Change: ******** - 4 - Complete:855 - Total:855 - error:Optional(Error Domain=CouchbaseLite Code=5003 "connection timed out" UserInfo={NSLocalizedDescription=connection timed out})"
[CouchBaseManager] Replicator: replicationStatusDB, 855/855, error: Error Domain=CouchbaseLite Code=5003 "connection timed out" UserInfo={NSLocalizedDescription=connection timed out}
, error: Error Domain=CouchbaseLite Code=5003 "connection timed out" UserInfo={NSLocalizedDescription=connection timed out}
2021-04-14 15:54:41.797843+0200 Eat[7569:3717042] CouchbaseLite Database Verbose: {DB#36} Closed SQLite database
2021-04-14 15:54:41.799431+0200 Eat[7569:3717042] CouchbaseLite Database Info: {DB#36} Closing database
2021-04-14 15:54:41.800750+0200 Eat[7569:3717042] CouchbaseLite Database Verbose: {DB#46} Housekeeping: 0 of 10280 pages free (0%)
2021-04-14 15:54:41.801997+0200 Eat[7569:3717042] CouchbaseLite Database Verbose: {DB#46} Closed SQLite database
2021-04-14 15:54:41.802578+0200 Eat[7569:3717042] CouchbaseLite Database Info: {DB#46} Closing database
2021-04-14 15:54:41.804051+0200 Eat[7569:3717042] CouchbaseLite Replicator ERROR: {C4Replicator#39} Transient error (Network error 3 "connection timed out"); attempt #2 in 2 sec...
2021-04-14 15:54:41.805810+0200 Eat[7569:3717042] CouchbaseLite Replicator ERROR: {C4Replicator#39} State: offline, progress=100.00%, error=Network error 3 "connection timed out"
2021-04-14 15:54:41.808631+0200 Eat[7569:3717042] CouchbaseLite Replicator Info: Reachability<sg-lb.
.it>: flags=2; starting...
2021-04-14 15:54:41.811189+0200 Eat[7569:3717042] CouchbaseLite Replicator Info: CBLReplicator[<
> URL[wss://sg-lb..it:443/]] is offline, progress 855/855, error: Error Domain=CouchbaseLite Code=5003 "connection timed out" UserInfo={NSLocalizedDescription=connection timed out}
2021-04-14 15:54:41.812068+0200 Eat[7569:3717042] CouchbaseLite Replicator Info: Reachability<sg-lb.********.it>: Reachability flags changed: 2
"Change: ******** - 1 - Complete:855 - Total:855 - error:Optional(Error Domain=CouchbaseLite Code=5003 "connection timed out" UserInfo={NSLocalizedDescription=connection timed out})"
[CouchBaseManager] Replicator: replicationStatusDB, 855/855, error: Error Domain=CouchbaseLite Code=5003 "connection timed out" UserInfo={NSLocalizedDescription=connection timed out}
, error: Error Domain=CouchbaseLite Code=5003 "connection timed out" UserInfo={NSLocalizedDescription=connection timed out}
2021-04-14 15:54:41.813577+0200 Eat[7569:3717042] CouchbaseLite Replicator Info: CBLReplicator[<
> URL[wss://sg-lb..it:443/]]: Reachability reported server may now be reachable ...
2021-04-14 15:54:43.810701+0200 Eat[7569:3710466] CouchbaseLite Replicator Info: {C4Replicator#39} Retrying connection to wss://sg-lb..it:443//_blipsync (attempt #2)...
2021-04-14 15:54:43.811389+0200 Eat[7569:3710466] CouchbaseLite Database Info: {DB#956}==> litecore::SQLiteDataFile /var/mobile/Containers/Data/Application/74F3AECE-B490-4498-8EC7-26818CBFB06A/Library/Application Support/CouchbaseLite/.cblite2/db.sqlite3 @0x10fb39650
2021-04-14 15:54:43.811459+0200 Eat[7569:3710466] CouchbaseLite Database Info: {DB#956} Opening database
2021-04-14 15:54:43.812104+0200 Eat[7569:3710466] CouchbaseLite Network Info: {Connection#957}==> litecore::blip::Connection ->wss://sg-lb.
.it:443//_blipsync @0x283c02110
2021-04-14 15:54:43.812165+0200 Eat[7569:3710466] CouchbaseLite Network Info: {Connection#957} Opening connection...
2021-04-14 15:54:43.812432+0200 Eat[7569:3710466] CouchbaseLite Replicator Info: {Repl#958}==> litecore::repl::Replicator /var/mobile/Containers/Data/Application/74F3AECE-B490-4498-8EC7-26818CBFB06A/Library/Application Support/CouchbaseLite/
.cblite2/ ->wss://sg-lb..it:443//_blipsync @0x10fc52cd8
2021-04-14 15:54:43.812499+0200 Eat[7569:3710466] CouchbaseLite Replicator Info: {Repl#958} Push=continuous, Pull=continuous, Options={{auth:{password:"", type:"Basic", username:""}, channels:["","","_eat"], headers:, heartbeat:300.0, progress:1}}
2021-04-14 15:54:43.812677+0200 Eat[7569:3710466] CouchbaseLite Replicator Verbose: {C4Replicator#39} C4RemoteRepl 0x10fc527e0 created Repl 0x10fc52cd8
2021-04-14 15:54:43.812732+0200 Eat[7569:3710466] CouchbaseLite Replicator Info: {C4Replicator#39} Starting Replicator {Repl#958}
2021-04-14 15:54:43.813035+0200 Eat[7569:3716910] CouchbaseLite Network Info: {C4SocketImpl#959}==> litecore::repl::C4SocketImpl wss://sg-lb..it:443//_blipsync @0x132231740
2021-04-14 15:54:43.813108+0200 Eat[7569:3716910] CouchbaseLite Network Info: {C4SocketImpl#959} Connecting...
2021-04-14 15:54:43.813282+0200 Eat[7569:3717042] CouchbaseLite Query Verbose: RecordEnumerator 0x283c08d80: (default, 110 0)
2021-04-14 15:54:43.813492+0200 Eat[7569:3717042] CouchbaseLite Replicator Info: {Repl#958} Scanning for pre-existing conflicts...
2021-04-14 15:54:43.813625+0200 Eat[7569:3717042] CouchbaseLite Replicator Info: {Repl#958} Found 0 conflicted docs in 0.001 sec
2021-04-14 15:54:43.813798+0200 Eat[7569:3717042] CouchbaseLite Replicator Verbose: {Repl#958} Remote-DB ID 1 found for target wss://sg-lb.********.it:443/********/_blipsync
2021-04-14 15:54:43.814008+0200 Eat[7569:3717042] CouchbaseLite Replicator Info: {Repl#958} Read local checkpoint 'cp-/SuX0aeZ2zOBwg4N5c3QUhAEcWY=': {"time":1618408012,"local":29532,"remote":34636083}
2021-04-14 15:54:43.814199+0200 Eat[7569:3717042] CouchbaseLite Replicator Info: {Repl#958} activityLevel=connecting: connectionState=1
2021-04-14 15:54:43.814350+0200 Eat[7569:3716910] CouchbaseLite Network Verbose: <CBLWebSocket: 0x2827a2040> enabling TLS
2021-04-14 15:54:43.814669+0200 Eat[7569:3716910] CouchbaseLite Network Info: <CBLWebSocket: 0x2827a2040> connecting to sg-lb.********.it:443...
2021-04-14 15:54:43.814887+0200 Eat[7569:3716910] CouchbaseLite Network Verbose: No cookies
2021-04-14 15:54:43.857405+0200 Eat[7569:3717045] CouchbaseLite Network Verbose: <CBLWebSocket: 0x2827a2040>: OpenCompleted on <__NSCFInputStream: 0x28202cc60>
2021-04-14 15:54:43.857495+0200 Eat[7569:3717045] CouchbaseLite Network Verbose: <CBLWebSocket: 0x2827a2040>: OpenCompleted on <__NSCFOutputStream: 0x28202ee20>
2021-04-14 15:54:43.983278+0200 Eat[7569:3717042] CouchbaseLite Network Verbose: <CBLWebSocket: 0x2827a2040>: HasSpaceAvailable

Platform (please complete the following information):

  • Device: [All iPad]
  • OS: [12 - 13 - 14]
  • Couchbase Version [e.g. CouchbaseLiteSwift 2.8.4]
  • Synch Gateway Version [e.g. Sync Gateway 2.8.2]

Replicator should initialize(or retain) its own databases. Could you share some code snippets to show how the replicator and query are used?

Brunz commented

I cannot understand @jayahariv.
If you want to replicate the crash just run a query and immediately close the database

if self.database != nil{ let query = self.queryAllDocWithIds(database: database!, ids: ids) do { for result in try query.execute(){ try database!.close() let item = result.toDictionary() } } catch { debugPrint("Error running the query") } }

Clearly that's not what we do, but we have crashes in production and we can only replicate the crash it in this way.
What we can imagine is that if the database is closed and reopened every time the replicators time out, if at that exact moment we are cycling in a resultset, the app crashes.
is there a way we don't know to get around this?

We would expect the query to fail, not a crash, but we know that everyone has their own philosophy...

If it helps we instantiate the database in a singleton with continuous pull and push replication. We NEVER close it

To better understand the Database object (controlled by our application) it is instantiated but _c4db is nullptr.
if (_c4db == nullptr) { [NSException raise: NSInternalInconsistencyException format: @"%@", kCBLErrorMessageDBClosed]; }

Somehow the db instance is closed when you are querying, can you refer to the comment?
#2781 (comment)

@Brunz Are you still seeing the error, after the fix for linked issue?

Brunz commented

@jayahariv, no, the error no longer happened after having dedicated an instance of the db to the replicators, I'm sorry if I forgot to communicate it.
For me this can be closed.

thank you @Brunz