Repeated assertion failure mImap == NULL

[ocrickard]

So I've been writing lots of async code around MailCore2, and I repeatedly get an assertion failure at line 488 in MCIMAPSession.cc, which is in this function:

void IMAPSession::setup()
{
    MCAssert(mImap == NULL);

    mImap = mailimap_new(0, NULL);
    mailimap_set_timeout(mImap, timeout());
    mailimap_set_progress_callback(mImap, body_progress, IMAPSession::items_progress, this);
}

And here is the backtrace:

* thread #30: tid = 0x4203, 0x39825350 libsystem_kernel.dylib`__pthread_kill + 8, stop reason = signal SIGABRT
    frame #0: 0x39825350 libsystem_kernel.dylib`__pthread_kill + 8
    frame #1: 0x3979bfb6 libsystem_c.dylib`pthread_kill + 58
    frame #2: 0x397d836a libsystem_c.dylib`abort + 94
    frame #3: 0x001d9332 Mercurius`mailcore::assertInteral(filename=0x002523c5, line=488, cond=0, condString=0x0025241a) + 70 at MCAssert.cc:13
    frame #4: 0x001ea6ae Mercurius`mailcore::IMAPSession::setup(this=0x22265930) + 78 at MCIMAPSession.cc:488
    frame #5: 0x001ea76a Mercurius`mailcore::IMAPSession::connect(this=0x22265930, pError=0x077f6e48) + 18 at MCIMAPSession.cc:516
    frame #6: 0x001eadb8 Mercurius`mailcore::IMAPSession::connectIfNeeded(this=0x22265930, pError=0x077f6e48) + 40 at MCIMAPSession.cc:588
    frame #7: 0x001eaddc Mercurius`mailcore::IMAPSession::loginIfNeeded(this=0x22265930, pError=0x077f6e48) + 20 at MCIMAPSession.cc:597
    frame #8: 0x001eb576 Mercurius`mailcore::IMAPSession::selectIfNeeded(this=0x22265930, folder=0x2228f3f0, pError=0x077f6e48) + 22 at MCIMAPSession.cc:753
    frame #9: 0x001ee51a Mercurius`mailcore::IMAPSession::fetchMessageByUID(this=0x22265930, folder=0x2228f3f0, uid=39180, progressCallback=0x22445848, pError=0x077f6e48) + 34 at MCIMAPSession.cc:1989
    frame #10: 0x001fba88 Mercurius`mailcore::IMAPFetchContentOperation::main(this=0x224457e0) + 220 at MCIMAPFetchContentOperation.cc:72
    frame #11: 0x001e43a6 Mercurius`mailcore::OperationQueue::runOperations(this=0x222d3180) + 586 at MCOperationQueue.cc:79
    frame #12: 0x001e4156 Mercurius`mailcore::OperationQueue::runOperationsOnThread(queue=0x222d3180) + 14 at MCOperationQueue.cc:47
    frame #13: 0x3977e0e0 libsystem_c.dylib`_pthread_start + 308

I have serialized access to MCOIMAPSession instances which my datasources use for submitting fetch requests, and this appears to have made this much less frequent, but it does still appear to happen for < 1% of these asynchronous fetch requests.

Any idea what I'm missing here?

[dinhvh]

Does it happen when the network disconnected or when the server disconnects the client? (try to turn off wifi or unplug to cable to try to reproduce it) Did you update to the latest code? I might have fixed something but I'm not sure.

[ocrickard]

1. Just tested disconnection case - looks like that's just fine. I just turned on airplane mode a couple times, and the normal MCOError code 1 gets returned. No crash.
2. No, I'm about a week behind on the code. Will update and see.

[ocrickard]

Sorry, I accidentally pressed "Close & comment"

[ocrickard]

Just updated to the newest code, and got it to crash again:

/Users/ocrickard/src/Mercurius/MailCore2/build-mac/../src/core/imap/MCIMAPSession.cc:488: assert mImap == NULL
/Users/ocrickard/src/Mercurius/MailCore2/build-mac/../src/core/imap/MCIMAPSession.cc:488: assert mImap == NULL
(lldb) bt
* thread #7: tid = 0x2337, 0x39825350 libsystem_kernel.dylib`__pthread_kill + 8, stop reason = signal SIGABRT
    frame #0: 0x39825350 libsystem_kernel.dylib`__pthread_kill + 8
    frame #1: 0x3979bfb6 libsystem_c.dylib`pthread_kill + 58
    frame #2: 0x397d836a libsystem_c.dylib`abort + 94
    frame #3: 0x001d5022 Mercurius`mailcore::assertInteral(filename=0x0024e3c9, line=488, cond=0, condString=0x0024e41e) + 70 at MCAssert.cc:13
    frame #4: 0x001e639e Mercurius`mailcore::IMAPSession::setup(this=0x21b85c50) + 78 at MCIMAPSession.cc:488
    frame #5: 0x001e645a Mercurius`mailcore::IMAPSession::connect(this=0x21b85c50, pError=0x0515ce48) + 18 at MCIMAPSession.cc:516
    frame #6: 0x001e6aa8 Mercurius`mailcore::IMAPSession::connectIfNeeded(this=0x21b85c50, pError=0x0515ce48) + 40 at MCIMAPSession.cc:588
    frame #7: 0x001e6acc Mercurius`mailcore::IMAPSession::loginIfNeeded(this=0x21b85c50, pError=0x0515ce48) + 20 at MCIMAPSession.cc:597
    frame #8: 0x001e7266 Mercurius`mailcore::IMAPSession::selectIfNeeded(this=0x21b85c50, folder=0x1d8935f0, pError=0x0515ce48) + 22 at MCIMAPSession.cc:753
    frame #9: 0x001e8cbe Mercurius`mailcore::IMAPSession::fetchMessages(this=0x21b85c50, folder=0x1d8935f0, requestKind=IMAPMessagesRequestKindUid, fetchByUID=true, imapset=0x1d8278b0, modseq=0, mapping=0x00000000, startUid=0, progressCallback=0x1d8e9118, pError=0x0515ce48) + 98 at MCIMAPSession.cc:1666
    frame #10: 0x001ea0d8 Mercurius`mailcore::IMAPSession::fetchMessagesByUID(this=0x21b85c50, folder=0x1d8935f0, requestKind=IMAPMessagesRequestKindUid, uids=0x1d88cf40, progressCallback=0x1d8e9118, pError=0x0515ce48) + 120 at MCIMAPSession.cc:1896
    frame #11: 0x001f7322 Mercurius`mailcore::IMAPFetchMessagesOperation::main(this=0x1d8e90b0) + 274 at MCIMAPFetchMessagesOperation.cc:97
    frame #12: 0x001e0096 Mercurius`mailcore::OperationQueue::runOperations(this=0x21b7ca40) + 586 at MCOperationQueue.cc:79
    frame #13: 0x001dfe46 Mercurius`mailcore::OperationQueue::runOperationsOnThread(queue=0x21b7ca40) + 14 at MCOperationQueue.cc:47
    frame #14: 0x3977e0e0 libsystem_c.dylib`_pthread_start + 308

If it helps, I have two separate MCOIMAPSessions for 2 accounts requesting a fetch in separate GCD serial queues, so it is quite possible that both are hitting their respective MCIMAPSessions at exactly the same time? Are MCIMAPSessions shared somewhere inside of mailcore?

[dinhvh]

If you have a sample code that reproduce that, that could help me investigate that.

Meanwhile, you could add some logs (use MCLog) and log the value of mImap and mState when they change. They should be consistent. For example, mState should be STATE_DISCONNECTED when mImap == NULL. mState != STATE_DISCONNECTED when mImap != NULL.

It looks like you're in a state where mState == STATE_DISCONNECTED and mImap != NULL.

[ocrickard]

This code is packaged pretty darn deep in a much larger system. Anything in particular you'd like to see?

I've added some logging lines around the error, and added a breakpoint, here's what I'm seeing when about to crash from mclog:

2013-05-22 18:10:51.068 [9172:e30b] MCOperationQueue.cc:71: quitting 0 0x22b78dc0
2013-05-22 18:10:55.097 [9172:e10b] MCIMAPSession.cc:547: ssl connect imap.gmail.com 993 6
2013-05-22 18:10:55.098 [9172:e10b] MCIMAPSession.cc:549: connect error 6
2013-05-22 18:10:55.101 [9172:e70f] MCIMAPSession.cc:547: ssl connect imap.gmail.com 993 6
2013-05-22 18:10:55.101 [9172:e70f] MCIMAPSession.cc:549: connect error 6
2013-05-22 18:10:55.101 Mercurius[9172:907] Error downloading emails:Error Domain=MCOErrorDomain Code=1 "The operation couldn’t be completed. (MCOErrorDomain error 1.)"
2013-05-22 18:10:55.104 [9172:e10b] MCOperationQueue.cc:71: quitting 0 0x22bf43e0
2013-05-22 18:10:55.105 [9172:e10b] MCIMAPSession.cc:491: mImap is NOT NULL, mState == disconnected:1

Here's the internal state of the IMAPSession:

this    mailcore::IMAPSession * 0x22e5d7e0
mailcore::Object    mailcore::Object    
mHostname   mailcore::String *  0x22d3a720
mPort   unsigned int    993
mUsername   mailcore::String *  0x22e3fb50
mPassword   mailcore::String *  0x22dcd6e0
mAuthType   mailcore::AuthType  AuthTypeSASLNone
mConnectionType mailcore::ConnectionType    ConnectionTypeTLS
mCheckCertificateEnabled    bool    true
mVoIPEnabled    bool    true
mDelimiter  char    '\0'
mDefaultNamespace   mailcore::IMAPNamespace *   0x00000000
mTimeout    time_t  30
mBodyProgressEnabled    bool    true
mIdleEnabled    bool    false
mXListEnabled   bool    false
mCondstoreEnabled   bool    false
mQResyncEnabled bool    false
mIdentityEnabled    bool    false
mWelcomeString  mailcore::String *  0x00000000
mNeedsMboxMailWorkaround    bool    false
mUIDValidity    uint32_t    0
mUIDNext    uint32_t    0
mModSequenceValue   uint64_t    0
mFolderMsgCount unsigned int    0
mLastFetchedSequenceNumber  unsigned int    0
mCurrentFolder  mailcore::String *  0x00000000
mIdleLock   pthread_mutex_t 
mState  int 0
mImap   mailimap *  0x22b23930
mProgressCallback   mailcore::IMAPProgressCallback *    0x00000000
mProgressItemsCount unsigned int    0

[dinhvh]

Here's the fix for that issue. Thanks for the logs! They were very useful.

https://github.com/MailCore/mailcore2/commit/c25fa58728113165cc39007ec5289d83b1cd33a7

Could you check that you cannot reproduce the issue any more and close this issue if that's the case? Thanks!

[ocrickard]

Awesome, I'll definitely test it in just a minute.

In the meantime, here's the test function I've added to my local copy of the iOS demo that can repeat the problem, though again, it's intermittent.

- (void)crazyAsyncFetch {
    for(int i = 0; i < 10; i++) {
        MCOIMAPSession *sesh = [[MCOIMAPSession alloc] init];
        sesh.hostname = self.imapSession.hostname;
        sesh.port = self.imapSession.port;
        sesh.username = self.imapSession.username;
        sesh.password = self.imapSession.password;
        sesh.connectionType = self.imapSession.connectionType;

        NSString *queueName = [NSString stringWithFormat:@"com.mailcore2.fetchQueue%d", i];
        dispatch_queue_t fetchQueue = dispatch_queue_create([queueName cStringUsingEncoding:NSASCIIStringEncoding], 0);

        for(int i = 0; i < 100; i++) {
            dispatch_async(fetchQueue, ^{
                MCOIMAPFetchMessagesOperation *uidOperation = [sesh fetchMessagesByUIDOperationWithFolder:@"INBOX" requestKind:(MCOIMAPMessagesRequestKindUid) uids:[MCOIndexSet indexSetWithRange:MCORangeMake(1, UINT64_MAX)]];

                [uidOperation start:^(NSError *error, NSArray *messages, MCOIndexSet *vanishedMessages) {
                    //Let's get the count of messages
                    NSLog(@"%d messages in folder: %@", messages.count, @"INBOX");

                    __block __strong MCOIndexSet *fetchSet = [[MCOIndexSet alloc] init];

                    //Compose the list of 100 most recent messages.
                    for(int i = messages.count - 1; i >= 0 && fetchSet.count <= 100; i--) {
                        MCOIMAPMessage *msg = messages[i];
                        [fetchSet addIndex:msg.uid];
                    }

                    dispatch_async(fetchQueue, ^{
                        MCOIMAPFetchMessagesOperation *messageOperation = [sesh fetchMessagesByUIDOperationWithFolder:@"INBOX" requestKind:(MCOIMAPMessagesRequestKindFullHeaders) uids:fetchSet];
                        fetchSet = nil;
                        [messageOperation start:^(NSError *error, NSArray *messages, MCOIndexSet *vanishedMessages) {
                            NSLog(@"messages:%@", messages);
                        }];
                    });
                }];
            });
        }
    }
}

[dinhvh]

Just a comment about this code: You don't really need to create the fetch operation in a dispatch queue since fetch is already asynchronous. Just remove the dispatch_async(), it will be fine.

You can probably remove all the "dispatch_async(fetchQueue, ^{" and make immediately the call from main thread.

[ocrickard]

Sounds good. I wasn't positive if I could call it from different threads, and this crash was making me doubt myself.

Hey, do you guys need help with documentation? Over the past two weeks I've gone through the beginner steps with this framework and it's all still fresh. Want me to write a quick start guide?

[dinhvh]

That would be awesome if you could write something. We definitively need some feedback and documentation. Could can find my email address on my profile.

[ocrickard]

OK, after a bit of testing, I can't replicate the problem with your code, so I'm marking this closed. Thanks a ton for your help.