Issue after upgrading CBL to latest master #148

Closed
march44 opened this Issue Oct 4, 2013 · 13 comments

2 participants

@march44

I have been running with a stable release (for me) of CBL a while, I have just upgraded to latest master and built from source.

I am now hitting this assertion in CBL_Server.m line 129.

- (void) queue: (void(^)())block {
    Assert(_serverThread, @"-queue: called after -close");
    MYOnThread(_serverThread, block);
}

This happens when I try to create new documents, I'm making all CBL calls in the main thread.

What scenarios might trigger this assertion?

@march44

I have been through the code path that trigger the assertion, here are the calls, all made on the main thread.

CBLManager *dbManager = [CBLManager sharedInstance];
CBLDatabase *db = [dbManager createDatabaseNamed:@"mydb" error:&error ];

//Document 1 with attachment, data is an NSURL object returning YES to the isFileURL selector,  this points to a file on the local ios file system.
CBLDocument *newdoc = [db documentWithID:docId];
CBLNewRevision *newRevision = [newdoc newRevision];
[newRevision.properties addEntriesFromDictionary:docProps];
CBLAttachment *dataAttach = [[CBLAttachment alloc] initWithContentType: @"application/octet-stream" body:data];
[newRevision addAttachment:dataAttach named:@"data"];
NSError* error;
if (![newRevision save:&error])
    NSLog(@"U:%@",error);

//Document 2 with attachment, data is NSData object
CBLDocument *newdoc = [db documentWithID:docId];
CBLNewRevision *newRevision = [newdoc newRevision];
[newRevision.properties addEntriesFromDictionary:docProps];
CBLAttachment *dataAttach = [[CBLAttachment alloc] initWithContentType: @"application/octet-stream" body:data];
[newRevision addAttachment:dataAttach named:@"data"];
NSError* error;
if (![newRevision save:&error])
    NSLog(@"U:%@",error);

//Document 3 no attachment
CBLDocument *newdoc = [db documentWithID:docId];
[newdoc putProperties:structuredData error: &error];
if (error)
        NSLog(@"U:%@",error);

These calls all complete without error, it appears the assertion is thrown in the enqueued jobs running on the background thread.

This code has been unchanged for a few months now and runs without error, reverting to my previous CBL build resolves the issue.

@snej
couchbase member

What's the backtrace of the exception when the assertion fails?

@march44

There is no stack trace as such,I turned the database logging on and got the following prior to the assertion.

18:35:45.010| CBL_BlobStore /var/mobile/Applications/87E42AF5-AA30-4DD4-85CF-714A208202B9/Library/Application Support/CouchbaseLite/mydb attachments created tempDir /private/var/mobile/Applications/87E42AF5-AA30-4DD4-85CF-714A208202B9/tmp/(A Document Being Saved By voco 14)
18:35:45.065| CBLDatabase: PUT rev={AC1E4410ECFCD8F6F8CEEBD145B2EE43332CAD0D #(null)}, prevRevID=(null), allowConflict=0
18:35:45.065| CBLDatabase: Begin transaction (level 1)...
18:35:45.068| CBLDatabase: Commit transaction (level 1)
18:35:45.075| CBLDatabase: Added: {AC1E4410ECFCD8F6F8CEEBD145B2EE43332CAD0D #1-99a40902bd0c2949a9c1e758db6c9474} (seq=58)
18:35:45.075| CBLDatabase: CBLDatabase[<0x16539d60>mydb]: Posting change notifications: seq 58
18:35:45.080| CBLDatabase: PUT rev={72FD85DF5D6909CB8E769DB15779202FA6CD8938 #(null)}, prevRevID=(null), allowConflict=0
18:35:45.080| CBLDatabase: Begin transaction (level 1)...
18:35:45.082| CBLDatabase: Commit transaction (level 1)
18:35:45.084| CBLDatabase: Added: {72FD85DF5D6909CB8E769DB15779202FA6CD8938 #1-32aba03e4b978991ad460ddbcd3cf80a} (seq=59)
18:35:45.084| CBLDatabase: CBLDatabase[<0x16539d60>mydb]: Posting change notifications: seq 59
18:35:45.085| CBLDatabase: PUT rev={urn:sha1:288EE264FCD0F7F49E571D27FF1CDF2159B2E1FC #(null)}, prevRevID=(null), allowConflict=0
18:35:45.086| CBLDatabase: Begin transaction (level 1)...
18:35:45.086| CBLDatabase: Commit transaction (level 1)
18:35:45.089| CBLDatabase: Added: {urn:sha1:288EE264FCD0F7F49E571D27FF1CDF2159B2E1FC #1-548c42940695cef81277774fe422ca95} (seq=60)
18:35:45.089| CBLDatabase: CBLDatabase[<0x16539d60>mydb]: Posting change notifications: seq 60
2013-10-04 18:35:45.091 voco[3906:60b] *** ASSERTION FAILED: -queue: called after -close
2013-10-04 18:35:45.093 voco[3906:60b] *** Assertion failure in -CBL_Server queue:, /Users/andy/projects/couchbase-lite-ios/Source/CBL_Server.m:129
2013-10-04 18:35:45.096 voco[3906:60b] *** Terminating app due to uncaught exception 'NSInternalInconsistencyException', reason: 'Assertion failed: -queue: called after -close'
*** First throw call stack:
(0x2dcbbe8b 0x37fb56c7 0x2dcbbd5d 0x2e66429b 0x2dac4b 0x25f84d 0x25f955 0x2bbb33 0x2b3623 0x2b4833 0x2e6964cf 0x2dc86e87 0x2dc86aa3 0x2dc84e2b 0x2dbef541 0x2dbef323 0x329262eb 0x304a61e5 0xc2259 0x384aeab7)
libc++abi.dylib: terminating with uncaught exception of type NSException

@snej
couchbase member

Set an all-exceptions breakpoint using the "+" button at the bottom of the breakpoints pane. When the exception is hit you can get the backtrace by typing "bt" in the debug console.

@march44

Sorry, brain saw stacktrace, here is the backtrace, looks like it is a live query I have setup that is triggering the assertion. I have set three up to ensure that all views are updated after every DB update to improve UI response times.

They all have the form:

query1 = [[[mydb viewNamed:@"view1"] query] asLiveQuery];

//This should trigger automatic updates
CBLQueryEnumerator* rowEnum = query1.rows;

* thread #1: tid = 0xfc699, 0x37fb56a0 libobjc.A.dylib`objc_exception_throw, queue = 'com.apple.main-thread, stop reason = breakpoint 1.1
    frame #0: 0x37fb56a0 libobjc.A.dylib`objc_exception_throw
    frame #1: 0x2dcbbd5c CoreFoundation`+[NSException raise:format:arguments:] + 104
    frame #2: 0x2e66429a Foundation`-[NSAssertionHandler handleFailureInFunction:file:lineNumber:description:] + 86
    frame #3: 0x00334c4a myapp`_AssertFailed(selOrFn=0x004c8824, sourceFile=0x004c86d2, sourceLine=129, condString=0x004c8839, message=0x16520650) + 514 at Test.m:230
    frame #4: 0x002b984c my app`-[CBL_Server queue:](self=0x1655aeb0, _cmd=0x004fd549, block=0x27d32a88) + 144 at CBL_Server.m:129
    frame #5: 0x002b9954 myapp`-[CBL_Server tellDatabaseNamed:to:](self=0x1655aeb0, _cmd=0x004fd5ed, dbName=0x16671de0, block=0x27d32b4c) + 220 at CBL_Server.m:135
    frame #6: 0x00315b32 myapp`-[CBLManager asyncTellDatabaseNamed:to:](self=0x1654ad50, _cmd=0x00500f7c, dbName=0x16671de0, block=0x27d32b4c) + 142 at CBLManager.m:250
    frame #7: 0x0030d622 myapp`-[CBLQuery runAsync:](self=0x16558820, _cmd=0x00500f97, onComplete=0x27d32c0c) + 774 at CBLQuery.m:171
    frame #8: 0x0030e832 my app`-[CBLLiveQuery update](self=0x16558820, _cmd=0x30a6a561) + 178 at CBLQuery.m:281
    frame #9: 0x2e6964ce Foundation`__NSFireDelayedPerform + 414
    frame #10: 0x2dc86e86 CoreFoundation`__CFRUNLOOP_IS_CALLING_OUT_TO_A_TIMER_CALLBACK_FUNCTION__ + 14
    frame #11: 0x2dc86aa2 CoreFoundation`__CFRunLoopDoTimer + 794
    frame #12: 0x2dc84e2a CoreFoundation`__CFRunLoopRun + 1218
    frame #13: 0x2dbef540 CoreFoundation`CFRunLoopRunSpecific + 524
    frame #14: 0x2dbef322 CoreFoundation`CFRunLoopRunInMode + 106
    frame #15: 0x329262ea GraphicsServices`GSEventRunModal + 138
    frame #16: 0x304a61e4 UIKit`UIApplicationMain + 1136
    frame #17: 0x0011c258 voco`main(argc=7, argv=0x27d34c44) + 116 at main.m:17
@snej
couchbase member

OK, that makes it clearer. A live-query is updating in response to a database-changed notification, but by the time it starts its async query the CBL_Server that runs the background tasks has been closed. The question is why it was closed, since it doesn't look like you explicitly closed the database.

Sorry to ask this, but would you mind updating to the latest revision and trying your code again? Because I made a bunch of changes this morning to CBLManager's code that starts the CBLServer (as part of making persistent replications run in the background, see #146 and #147) and I think they might have fixed this. Thanks!

@march44

I appologise in advance if whats below sounds a bit implausible, but I have gone round the cycle three times with exact same results.

The good news, is that the latest build no longer throws the same assertion.

The odd news is the following:

I have a UICollectionView and associated controller.

After writing the new docs, I return the UICollectionViewController and update from the latest data.

My -(NSInteger)collectionView:(UICollectionView *)collectionView numberOfItemsInSection:(NSInteger)section selector is called and returns the correct number of entries for section 0 e.g. 4.

My -(UICollectionViewCell *)collectionView:(UICollectionView *)collectionView cellForItemAtIndexPath:(NSIndexPath *)indexPath is then called the correct number of times to retrieve each cell.

With the old CBL and with the CBL from (my a.m) last night? This behavior is as described above.

When I drop in the latest CBL downloaded a few minutes ago, then I see the first method called and the correct number of entries for section 0 returned, but the cellForItemAtIndexPath selector is never called and the data never rendered.

I have deleted the App and replaced the frameworks 3 times with exactly the same results reproduceable each time.

I have no explanation for this, except perhaps an interaction with the main run loop? I said it sounds implausible.

Any thoughts on how to proceed with testing welcome.

@march44

I meant to say, running App on ios7 7.0.1

building with xcode 5

@snej
couchbase member

Is the app's runloop still active? It isn't locked up before the collection view can ask for its items?
Are there any other collection view delegate methods you implement, and do they get called after that first one?

@march44

OK, I was right in one respect that was implausible.

At almost 1am I missed that the UiCollection view contained empty cells where the images should have been, but my callback was not creating them. SO I'll park that as a red herring for now.

With some sleep and some more digging, it now appears the root cause of the issue is that documents with attachments passed as NSData are only being passed to my view functions with _id and _rev, no _attachments.

These docs pass through the same code path (second post) as attachments that are passed as an NSURL, which do get passed to the view function with _attachments.

I have tried with various NSData objects, and I have tried not creating the previous NSURL attachment document. In both these cases the NSData attachment creates a document with just an _id and _rev.

But by placing the NSData attachment creation before the NSURL attachment creation, then both documents are passed to the view function with attachments and the Cells are populated in the view again.

It appears that the NSURL attachment creation is somehow flushing the NSData attachment creation?

@snej
couchbase member

This smells like a problem with commit 3e27f03, which suppresses fetching attachment metadata for docs that don't have any. Sounds like it somehow thinks some of your docs don't have attachments when they do. Let me investigate.

@snej snej closed this in 6446f88 Oct 7, 2013
@snej
couchbase member

OK, try that and see if it fixes it. It was a bug with reading that new no_attachments flag while querying a view, and changing the order of the inserts would definitely affect whether it triggered, as you found.

@march44

I reverted to the original document create sequence and it runs without issue against the latest master.

Thank you.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment