6.4.19-b3 (#1590)

- Don't try to retrieve messages older than our autodelete timeout, if
active
- Added more debug logging to catch deadlock

Author: tmolitor-stud-tu

Monal/Classes/DataLayer.m

@@ -357,11 +357,19 @@ -(NSMutableDictionary*) readStateForAccount:(NSNumber*) accountNo
         return nil;
     NSString* query = @"SELECT state from account where account_id=?";
     NSArray* params = @[accountNo];
+    DDLogVerbose(@"Outside of transaction: Reading account state: %@", accountNo);
+    [MLSQLite debugTransactions];
     NSData* data = (NSData*)[self.db idReadTransaction:^{
+        DDLogVerbose(@"Inside of transaction: Reading account state: %@", accountNo);
         return [self.db executeScalar:query andArguments:params];
     }];
+    DDLogVerbose(@"After transaction: Reading account state: %@ --> %@", accountNo, data);
     if(data)
-        return [HelperTools unserializeData:data];
+    {
+        NSMutableDictionary* retval = [HelperTools unserializeData:data];
+        DDLogVerbose(@"After unserializeData: Reading account state: %@", accountNo);
+        return retval;
+    }
     return nil;
 }
 

Monal/Classes/MLMessageProcessor.m

@@ -117,12 +117,28 @@ +(MLMessage* _Nullable) processMessage:(XMPPMessage*) messageNode andOuterMessag
         return nil;
     }
 
-    if([messageNode check:@"/<type=headline>/{http://jabber.org/protocol/pubsub#event}event"])
+    if([messageNode check:@"/<type=headline>/{http://jabber.org/protocol/pubsub#event}event"] && !isMLhistory)
     {
         [account.pubsub handleHeadlineMessage:messageNode];
         return nil;
     }
 
+    //ignore messages older than our autodelete time
+    //(history backscrolling ones AND normal ones, both would otherwise disappear again immediately afterwards)
+    //do this before handling the message stanza: only non-MLhistory pubsub messages and error-type stanzas should be processed
+    //regardless of their age (but pubsub messages only if they aren't MLhistory ones)
+    NSInteger autodeleteInterval = [[HelperTools defaultsDB] integerForKey:@"AutodeleteInterval"];
+    if(autodeleteInterval > 0)
+    {
+        NSDate* pastDate = [NSDate dateWithTimeIntervalSinceNow:-autodeleteInterval];
+        NSDate* messageTimestamp = [messageNode findFirst:@"{urn:xmpp:delay}delay@stamp|datetime"];
+        if(messageTimestamp != nil && [messageTimestamp compare:pastDate] == NSOrderedAscending)
+        {
+            DDLogInfo(@"Ignoring incoming message being too old (probably an MLhistory one)...");
+            return nil;
+        }
+    }
+    
     //ignore messages from our own device, see this github issue: https://github.com/monal-im/Monal/issues/941
     if(![messageNode check:@"/<type=groupchat>"] && !isMLhistory && [messageNode.from isEqualToString:account.connectionProperties.identity.fullJid] && [messageNode.toUser isEqualToString:account.connectionProperties.identity.jid])
         return nil;

Monal/Classes/MLSQLite.h

@@ -16,6 +16,8 @@ typedef BOOL (^monal_sqlite_bool_operations_t)(void);
 
 @interface MLSQLite : NSObject
 
++(void) debugTransactions;
+
 +(id) sharedInstanceForFile:(NSString*) dbFile;
 
 -(void) voidReadTransaction:(monal_void_block_t) operations;

Monal/Classes/MLSQLite.m

@@ -38,6 +38,13 @@ +(void) initialize
     DDLogInfo(@"sqlite initialize: using mysql lib version: %s", sqlite3_libversion());
 }
 
++(void) debugTransactions
+{
+    NSMutableDictionary* threadData = [[NSThread currentThread] threadDictionary];
+    DDLogVerbose(@"threadData: %@", threadData);
+    DDLogVerbose(@"currentTransactions: %@", currentTransactions);
+}
+
 //every thread gets its own instance having its own db connection
 //this allows for concurrent reads/writes
 +(id) sharedInstanceForFile:(NSString*) dbFile

Monal/Classes/xmpp.m

@@ -500,6 +500,7 @@ -(BOOL) idle
     //only check unacked count if needed (this makes sure we don't hold the state lock unnecessarily and block the main thread)
     if(retval)
     {
+        DDLogVerbose(@"Before @synchronized of _stateLockObject...");
         @synchronized(_stateLockObject) {
             NSUInteger unacked = [self.unAckedStanzas count];
             if(unacked)
@@ -508,6 +509,7 @@ -(BOOL) idle
                 unackedCount = @(unacked);
             }
         }
+        DDLogVerbose(@"After @synchronized of _stateLockObject...");
     }
     _lastIdleState = retval;
     DDLogVerbose(@("%@ --> Idle check:\n"
@@ -1634,13 +1636,16 @@ -(void) sendPing:(double) timeout
 
 -(void) addSmacksHandler:(monal_void_block_t) handler
 {
+    DDLogVerbose(@"Before @synchronized of _stateLockObject...");
     @synchronized(_stateLockObject) {
         [self addSmacksHandler:handler forValue:self.lastOutboundStanza];
     }
+    DDLogVerbose(@"After @synchronized of _stateLockObject...");
 }
 
 -(void) addSmacksHandler:(monal_void_block_t) handler forValue:(NSNumber*) value
 {
+    DDLogVerbose(@"Before @synchronized of _stateLockObject...");
     @synchronized(_stateLockObject) {
         if([value integerValue] < [self.lastOutboundStanza integerValue])
         {
@@ -1652,10 +1657,12 @@ -(void) addSmacksHandler:(monal_void_block_t) handler forValue:(NSNumber*) value
         NSDictionary* dic = @{@"value":value, @"handler":handler};
         [_smacksAckHandler addObject:dic];
     }
+    DDLogVerbose(@"After @synchronized of _stateLockObject...");
 }
 
 -(void) resendUnackedStanzas
 {
+    DDLogVerbose(@"Before @synchronized of _stateLockObject...");
     @synchronized(_stateLockObject) {
         DDLogInfo(@"Resending unacked stanzas...");
         NSMutableArray* sendCopy = [[NSMutableArray alloc] initWithArray:self.unAckedStanzas];
@@ -1669,12 +1676,14 @@ -(void) resendUnackedStanzas
         DDLogInfo(@"Done resending unacked stanzas...");
         [self persistState];
     }
+    DDLogVerbose(@"After @synchronized of _stateLockObject...");
 }
 
 -(void) resendUnackedMessageStanzasOnly:(NSMutableArray*) stanzas
 {
     if(stanzas)
     {
+        DDLogVerbose(@"Before @synchronized of _stateLockObject...");
         @synchronized(_stateLockObject) {
             DDLogWarn(@"Resending unacked message stanzas only...");
             NSMutableArray* sendCopy = [[NSMutableArray alloc] initWithArray:stanzas];
@@ -1692,11 +1701,13 @@ -(void) resendUnackedMessageStanzasOnly:(NSMutableArray*) stanzas
             //or contain all the resent stanzas (e.g. only resume failed)
             [self persistState];
         }
+        DDLogVerbose(@"After @synchronized of _stateLockObject...");
     }
 }
 
 -(BOOL) shouldTriggerSyncErrorForImportantUnackedOutgoingStanzas
 {
+    DDLogVerbose(@"Before @synchronized of _stateLockObject...");
     @synchronized(_stateLockObject) {
         DDLogInfo(@"Checking for important unacked stanzas...");
         for(NSDictionary* dic in self.unAckedStanzas)
@@ -1711,13 +1722,15 @@ -(BOOL) shouldTriggerSyncErrorForImportantUnackedOutgoingStanzas
                 return YES;
         }
     }
+    DDLogVerbose(@"After @synchronized of _stateLockObject...");
     //no important stanzas found
     return NO;
 }
 
 -(BOOL) removeAckedStanzasFromQueue:(NSNumber*) hvalue
 {
     NSMutableArray* ackHandlerToCall = [[NSMutableArray alloc] initWithCapacity:[_smacksAckHandler count]];
+    DDLogVerbose(@"Before @synchronized of _stateLockObject...");
     @synchronized(_stateLockObject) {
         //sanity check
         MLAssert(([self.unAckedStanzas count]+[self.lastHandledOutboundStanza unsignedIntValue])==[self.lastOutboundStanza unsignedIntValue], @"Calculated outgoing stanza count and counted one differ!", (@{
@@ -1808,6 +1821,7 @@ -(BOOL) removeAckedStanzasFromQueue:(NSNumber*) hvalue
             }
         [_smacksAckHandler removeObjectsInArray:ackHandlerToCall];
     }
+    DDLogVerbose(@"After @synchronized of _stateLockObject...");
 
     //call registered smacksAckHandler that got sorted out
     for(NSDictionary* dic in ackHandlerToCall)
@@ -1823,6 +1837,7 @@ -(void) requestSMAck:(BOOL) force
 {
     //caution: this could be called from sendQueue, too!
     MLXMLNode* rNode;
+    DDLogVerbose(@"Before @synchronized of _stateLockObject...");
     @synchronized(_stateLockObject) {
         unsigned long unackedCount = (unsigned long)[self.unAckedStanzas count];
         if(self.accountState >= kStateInitStarted && self.connectionProperties.supportsSM3 &&
@@ -1835,6 +1850,7 @@ -(void) requestSMAck:(BOOL) force
         else
             DDLogDebug(@"no smacks request, there is nothing pending or a request already in flight...");
     }
+    DDLogVerbose(@"After @synchronized of _stateLockObject...");
     if(rNode)
         [self send:rNode];
 }
@@ -1856,11 +1872,13 @@ -(void) sendSMAck:(BOOL) queuedSend
         return;
 
     NSDictionary* dic;
+    DDLogVerbose(@"Before @synchronized of _stateLockObject...");
     @synchronized(_stateLockObject) {
         dic = @{
             @"h":[NSString stringWithFormat:@"%@",self.lastHandledInboundStanza],
         };
     }
+    DDLogVerbose(@"After @synchronized of _stateLockObject...");
     MLXMLNode* aNode = [[MLXMLNode alloc] initWithElement:@"a" andNamespace:@"urn:xmpp:sm:3" withAttributes:dic andChildren:@[] andData:nil];
     if(queuedSend)
         [self send:aNode];
@@ -1897,13 +1915,15 @@ -(void) processInput:(MLXMLNode*) parsedStanza withDelayedReplay:(BOOL) delayedR
             if(h==nil)
                 return [self invalidXMLError];
 
+            DDLogVerbose(@"Before @synchronized of _stateLockObject...");
             @synchronized(_stateLockObject) {
                 //remove acked messages
                 [self removeAckedStanzasFromQueue:h];
 
                 self.smacksRequestInFlight = NO;        //ack returned
                 [self requestSMAck:NO];                 //request ack again (will only happen if queue is not empty)
             }
+            DDLogVerbose(@"After @synchronized of _stateLockObject...");
         }
         else if([parsedStanza check:@"/{jabber:client}presence"] && self.accountState >= kStateInitStarted)
         {
@@ -2155,6 +2175,7 @@ -(void) processInput:(MLXMLNode*) parsedStanza withDelayedReplay:(BOOL) delayedR
             {
                 //wrap everything in lock instead of writing the boolean result into a temp var because incrementLastHandledStanza
                 //is wrapped in this lock, too (and we don't call anything else here)
+                DDLogVerbose(@"Before @synchronized of _stateLockObject...");
                 @synchronized(_stateLockObject) {
                     if(_runningMamQueries[[outerMessageNode findFirst:@"{urn:xmpp:mam:2}result@queryid"]] == nil)
                     {
@@ -2165,6 +2186,7 @@ -(void) processInput:(MLXMLNode*) parsedStanza withDelayedReplay:(BOOL) delayedR
                         return;
                     }
                 }
+                DDLogVerbose(@"After @synchronized of _stateLockObject...");
 
                 //create a new XMPPMessage node instead of only a MLXMLNode because messages have some convenience properties and methods
                 messageNode = [[XMPPMessage alloc] initWithXMPPMessage:[outerMessageNode findFirst:@"{urn:xmpp:mam:2}result/{urn:xmpp:forward:0}forwarded/{jabber:client}message"]];
@@ -2380,6 +2402,7 @@ -(void) processInput:(MLXMLNode*) parsedStanza withDelayedReplay:(BOOL) delayedR
         else if([parsedStanza check:@"/{urn:xmpp:sm:3}enabled"] && self.accountState == kStateBound)
         {
             NSMutableArray* stanzas;
+            DDLogVerbose(@"Before @synchronized of _stateLockObject...");
             @synchronized(_stateLockObject) {
                 //save old unAckedStanzas queue before it is cleared
                 stanzas = self.unAckedStanzas;
@@ -2396,6 +2419,7 @@ -(void) processInput:(MLXMLNode*) parsedStanza withDelayedReplay:(BOOL) delayedR
                 //persist these changes (streamID and initSM3)
                 [self persistState];
             }
+            DDLogVerbose(@"After @synchronized of _stateLockObject...");
 
             //init session and query disco, roster etc.
             [self initSession];
@@ -2423,11 +2447,13 @@ -(void) processInput:(MLXMLNode*) parsedStanza withDelayedReplay:(BOOL) delayedR
             [[MLNotificationQueue currentQueue] postNotificationName:kMLSessionInitNotice object:self];
             [self accountStatusChanged];
 
+            DDLogVerbose(@"Before @synchronized of _stateLockObject...");
             @synchronized(_stateLockObject) {
                 //remove already delivered stanzas and resend the (still) unacked ones
                 [self removeAckedStanzasFromQueue:h];
                 [self resendUnackedStanzas];
             }
+            DDLogVerbose(@"After @synchronized of _stateLockObject...");
 
             //publish new csi and last active state (but only do so when not in an extension
             //because the last active state does not change when inside an extension)
@@ -2444,6 +2470,7 @@ -(void) processInput:(MLXMLNode*) parsedStanza withDelayedReplay:(BOOL) delayedR
             //ping all mucs to check if we are still connected (XEP-0410)
             [self.mucProcessor pingAllMucs];
 
+            DDLogVerbose(@"Before @synchronized of _stateLockObject...");
             @synchronized(_stateLockObject) {
                 //signal finished catchup if our current outgoing stanza counter is acked, this introduces an additional roundtrip to make sure
                 //all stanzas the *server* wanted to replay have been received, too
@@ -2479,6 +2506,7 @@ -(void) processInput:(MLXMLNode*) parsedStanza withDelayedReplay:(BOOL) delayedR
                     }
                 }];
             }
+            DDLogVerbose(@"After @synchronized of _stateLockObject...");
 
             //initialize stanza counter for statistics
             [self initCatchupStats];
@@ -2489,6 +2517,7 @@ -(void) processInput:(MLXMLNode*) parsedStanza withDelayedReplay:(BOOL) delayedR
 
             __block BOOL error = NO;
             self.resuming = NO;
+            DDLogVerbose(@"Before @synchronized of _stateLockObject...");
             @synchronized(_stateLockObject) {
                 //invalidate stream id
                 self.streamID = nil;
@@ -2500,6 +2529,7 @@ -(void) processInput:(MLXMLNode*) parsedStanza withDelayedReplay:(BOOL) delayedR
                 //persist these changes
                 [self persistState];
             }
+            DDLogVerbose(@"After @synchronized of _stateLockObject...");
 
             //don't try to bind, if removeAckedStanzasFromQueue returned an error (it will trigger a reconnect in these cases)
             if(!error)
@@ -3311,6 +3341,7 @@ -(void) handleFeaturesAfterAuth:(MLXMLNode*) parsedStanza
     }
 
     MLXMLNode* resumeNode = nil;
+    DDLogVerbose(@"Before @synchronized of _stateLockObject...");
     @synchronized(_stateLockObject) {
         //test if smacks is supported and allows resume
         if(self.connectionProperties.supportsSM3 && self.streamID)
@@ -3323,6 +3354,7 @@ -(void) handleFeaturesAfterAuth:(MLXMLNode*) parsedStanza
             self.resuming = YES;      //this is needed to distinguish a failed smacks resume and a failed smacks enable later on
         }
     }
+    DDLogVerbose(@"After @synchronized of _stateLockObject...");
     if(resumeNode)
         [self send:resumeNode];
     else
@@ -3785,6 +3817,7 @@ -(void) readState
 
 -(void) realReadState
 {
+    DDLogVerbose(@"Before @synchronized of _stateLockObject...");
     @synchronized(_stateLockObject) {
         DDLogVerbose(@"%@ --> realReadState before: used/available memory: %.3fMiB / %.3fMiB)...", self.accountNo, [HelperTools report_memory], (CGFloat)os_proc_available_memory() / 1048576);
         NSMutableDictionary* dic = [[DataLayer sharedInstance] readStateForAccount:self.accountNo];
@@ -3815,16 +3848,14 @@ -(void) realReadState
                 self.isDoingFullReconnect = isDoingFullReconnect.boolValue;
             }
 
-            @synchronized(_stateLockObject) {
-                //invalidate corrupt smacks states (this could potentially loose messages, but hey, the state is corrupt anyways)
-                if(self.lastHandledInboundStanza == nil || self.lastHandledOutboundStanza == nil || self.lastOutboundStanza == nil || !self.unAckedStanzas)
-                {
+            //invalidate corrupt smacks states (this could potentially loose messages, but hey, the state is corrupt anyways)
+            if(self.lastHandledInboundStanza == nil || self.lastHandledOutboundStanza == nil || self.lastOutboundStanza == nil || !self.unAckedStanzas)
+            {
 #ifndef IS_ALPHA
-                    [self initSM3];
+                [self initSM3];
 #else
-                    @throw [NSException exceptionWithName:@"RuntimeError" reason:@"corrupt smacks state" userInfo:dic];
+                @throw [NSException exceptionWithName:@"RuntimeError" reason:@"corrupt smacks state" userInfo:dic];
 #endif
-                }
             }
 
             NSDictionary* persistentIqHandlers = [dic objectForKey:@"iqHandlers"];
@@ -3985,6 +4016,7 @@ -(void) realReadState
 
         DDLogVerbose(@"%@ --> realReadState after: used/available memory: %.3fMiB / %.3fMiB)...", self.accountNo, [HelperTools report_memory], (CGFloat)os_proc_available_memory() / 1048576);
     }
+    DDLogVerbose(@"After @synchronized of _stateLockObject...");
 }
 
 +(NSMutableDictionary*) invalidateState:(NSDictionary*) dic
@@ -4020,6 +4052,7 @@ -(void) incrementLastHandledStanzaWithDelayedReplay:(BOOL) delayedReplay
     //don't ack messages twice
     if(delayedReplay)
         return;
+    DDLogVerbose(@"Before @synchronized of _stateLockObject...");
     @synchronized(_stateLockObject) {
         if(self.connectionProperties.supportsSM3)
         {
@@ -4030,11 +4063,13 @@ -(void) incrementLastHandledStanzaWithDelayedReplay:(BOOL) delayedReplay
         }
         [self persistState];        //make sure we persist our state, even if smacks is not supported
     }
+    DDLogVerbose(@"After @synchronized of _stateLockObject...");
 }
 
 -(void) initSM3
 {
     //initialize smacks state
+    DDLogVerbose(@"Before @synchronized of _stateLockObject...");
     @synchronized(_stateLockObject) {
         self.lastHandledInboundStanza = [NSNumber numberWithInteger:0];
         self.lastHandledOutboundStanza = [NSNumber numberWithInteger:0];
@@ -4044,6 +4079,7 @@ -(void) initSM3
         _smacksAckHandler = [NSMutableArray new];
         DDLogDebug(@"initSM3 done");
     }
+    DDLogVerbose(@"After @synchronized of _stateLockObject...");
 }
 
 -(void) bindResource:(NSString*) resource