AWSPinpointSessionClient blocks main thread

[jberkel]

To help us solve your problem better, please answer the following list of questions.

• What service are you using?

AWSPinPoint

• In what version of SDK are you facing the problem?

2.5.2

• Is the issue limited to Simulators / Actual Devices?

Devices

• Can your problem be resolved if you bump to a higher version of SDK?

No

• Is this problem related to specific iOS version?

No

• How are you consuming the SDK? CocoaPods / Carthage / Prebuilt frameworks?

CocoaPods

• Can you give us steps to reproduce with a minimal, complete, and verifiable example? Please include any specific network conditions that might be required to reproduce the problem.

I use AWSPinpointAnalyticsClient in my app to track some events, using the default configuration (5 sec session timeout).

When my application goes into background state I noticed a couple of warnings in the console:

Mar 15 14:44:40 iPhone moti[765] <Warning>: Warning: A long-running operation is being executed on the main thread.
     Break on awsbf_warnBlockingOperationOnMainThread() to debug.

Followed (occasionally) by the process getting killed by the watchdog:

Exception Type:  00000020
Exception Codes: 0x000000008badf00d
Exception Note:  SIMULATED (this is NOT a crash)
Highlighted by Thread:  2

Application Specific Information:
<BKNewProcess: 0x15d6efd0; com.zegoggles.moti; pid: 736; hostpid: -1> has active assertions beyond permitted time: 
{(
    <BKProcessAssertion: 0x15e5bfb0> id: 736-966B0D80-6F3B-4522-B114-6D36360D9DA0 name: com.amazonaws.AWSPinpointSessionBackgroundTask process: <BKNewProcess: 0x15d6efd0; com.zegoggles.moti; pid: 736; hostpid: -1> permittedBackgroundDuration: 180.000000 reason: finishTask owner pid:736 preventSuspend  preventIdleSleep  preventSuspendOnSleep 
)}

I attach the debugger as hinted in the log message:

(lldb) b awsbf_warnBlockingOperationOnMainThread
Breakpoint 2: where = AWSCore`awsbf_warnBlockingOperationOnMainThread, address = 0x003b7b00

Getting the following backtrace:

(lldb) bt
* thread #1: tid = 0x33700, 0x003b7b00 AWSCore`awsbf_warnBlockingOperationOnMainThread, queue = 'com.apple.main-thread', stop reason = breakpoint 2.1
  * frame #0: 0x003b7b00 AWSCore`awsbf_warnBlockingOperationOnMainThread
    frame #1: 0x003ba0fc AWSCore`-[AWSTask waitUntilFinished] + 132
    frame #2: 0x00505930 AWSPinpoint`-[AWSPinpointSessionClient endCurrentSessionWithBlock:] + 252
    frame #3: 0x0050582a AWSPinpoint`-[AWSPinpointSessionClient endCurrentSessionTimeoutWithTimer:] + 100
    frame #4: 0x240d2654 Foundation`__NSFireTimer + 64
    frame #5: 0x2386a58e CoreFoundation`__CFRUNLOOP_IS_CALLING_OUT_TO_A_TIMER_CALLBACK_FUNCTION__ + 14
    frame #6: 0x2386a1c0 CoreFoundation`__CFRunLoopDoTimer + 936
    frame #7: 0x2386800c CoreFoundation`__CFRunLoopRun + 1484
    frame #8: 0x237b7228 CoreFoundation`CFRunLoopRunSpecific + 520
    frame #9: 0x237b7014 CoreFoundation`CFRunLoopRunInMode + 108
    frame #10: 0x24da7ac8 GraphicsServices`GSEventRunModal + 160
    frame #11: 0x27e8b188 UIKit`UIApplicationMain + 144
    frame #12: 0x000337dc moti`_mh_execute_header + 26588
    frame #13: 0x2345f872 libdyld.dylib`start 

After checking the code it looks like NSTimer fires after the prefined timeout without passing a block in the userInfo dictionary:

https://github.com/aws/aws-sdk-ios/blob/master/AWSPinpoint/AWSPinpointSessionClient.m#L122

It ends up calling endCurrentSessionTimeoutWithTimer:(NSTimer*), followed by endCurrentSessionWithBlock:block (with the block still being nil).

In endCurrentSessionWithBlock: the application finally hangs in waitUntilFinished on the main thread.

[jberkel]

Anyone out there? It's quite a serious problem and prevents the use of Pinpoint in production.

[rohandubal]

Hi,

Thanks for reporting this. I will reach out to the service team and revert.

Thanks,
Rohan

[yinglin83]

@jberkel did you figure a solution to this problem? Our app is already in production. now it gets killed by system all the time due to this bug.

[jberkel]

@yinglin83 Well I debugged the app and identified the problem (see above), a fix is probably not too complicated but I have other priorities right now. very likely won't use the service anyway, given the low quality of the code and the slow response times.

[yinglin83]

@jberkel Thanks for pointing that out. I agreed that they need to improve the quality of pinpoint code before asking everyone to jump onboard. I wonder how many poor mobile startups out there having this code in production. This issue has huge impact on our app store ranking. This update drop our ratings from 5 stars to 3.5 stars. This is SERIOUS!

[cheruvian]

Great catch @jberkel and appreciate the thorough write up and debug.

Looks like we not only have some work to do in the Pinpoint session client but also with our GitHub issue response times.

We apologize for the lack of responsiveness along with any problems this may have caused.

You should expect a fix shortly and please know that we value your continued patience as we actively dive in and resolve this issue.

[cheruvian]

Ok looks like the change is all approved and will be released shortly.

[cheruvian]

Unfortunately looks like the change broke existing functional tests and is pending further work.

[decentralisedkev]

A band-aid solution would be to find the waitUntilFinsihed function, and when it checks if the thread is running on the main, put it in the back, So:

• (void)waitUntilFinished {

  if ([NSThread isMainThread]) {
  [self warnOperationOnMainThread];
  NSLog(@"Moving to background thread");
  dispatch_queue_t queue = dispatch_get_global_queue(DISPATCH_QUEUE_PRIORITY_DEFAULT, 0ul);
  dispatch_async(queue, ^{

        @synchronized(self.lock) {
            if (self.completed) {
                return;
            }
            [self.condition lock];
        }
        // TODO: (nlutsenko) Restructure this to use Bolts-Swift thread access synchronization architecture
        // In the meantime, it's absolutely safe to get `_completed` aka an ivar, as long as it's a `BOOL` aka less than word size.
        while (!_completed) {
            [self.condition wait];
        }
        [self.condition unlock];
        
        
     });
  

  } else {

    @synchronized(self.lock) {
        if (self.completed) {
            return;
        }
        [self.condition lock];
    }
    // TODO: (nlutsenko) Restructure this to use Bolts-Swift thread access synchronization architecture
    // In the meantime, it's absolutely safe to get `_completed` aka an ivar, as long as it's a `BOOL` aka less than word size.
    while (!_completed) {
        [self.condition wait];
    }
    [self.condition unlock];
  

  }

}

This should help those looking for a quick fix, just comment out the [self warnOperationOnMainThread]; part to stop it showing up now

[lexmakali]

We have fixed it in 2.5.9