Push activation fails if already registered #661

paddybyers · 2017-12-12T11:57:08Z

See the attached logs. This is a device that is already activated and registered, but then fails activation.

The state machine should detect that the device is already registered, and should no attempt to re-register.

@ricardopereira are you able to take a look please?

ricardopereira · 2017-12-12T14:43:17Z

Yes, I'll look at it.

ricardopereira · 2017-12-13T08:44:38Z

The app reaches the ARTPushActivationEventGotPushDeviceDetails state but it's not handled because a crash occurs: UI API called on a background thread: -[UIApplication delegate] PID: 2595, TID: 1308688, Thread name: (none), Queue name: io.ably.main, QoS: 0.

2017-12-12 12:32:43.222315+0200 Shop_n_Drop[2595:1308688] attempting to consume pending event: ARTPushActivationEventGotPushDeviceDetails
=================================================================
Main Thread Checker: UI API called on a background thread: -[UIApplication delegate]
PID: 2595, TID: 1308688, Thread name: (none), Queue name: io.ably.main, QoS: 0
Backtrace:
4   Ably                                0x0000000101323230 -[ARTPushActivationStateMachine deviceRegistration:] + 172
5   Ably                                0x0000000101321534 -[ARTPushActivationStateWaitingForPushDeviceDetails transition:] + 568
6   Ably                                0x0000000101322dd4 -[ARTPushActivationStateMachine handleEvent:] + 808
7   Ably                                0x00000001013229d4 __43-[ARTPushActivationStateMachine sendEvent:]_block_invoke + 52
8   libdispatch.dylib                   0x000000010217d2cc _dispatch_call_block_and_release + 24
9   libdispatch.dylib                   0x000000010217d28c _dispatch_client_callout + 16
10  libdispatch.dylib                   0x000000010218bf80 _dispatch_queue_serial_drain + 696
11  libdispatch.dylib                   0x00000001021807ec _dispatch_queue_invoke + 332
12  libdispatch.dylib                   0x000000010218cf6c _dispatch_root_queue_drain_deferred_wlh + 428
13  libdispatch.dylib                   0x0000000102194020 _dispatch_workloop_worker_thread + 652
14  libsystem_pthread.dylib             0x000000018540ef1c _pthread_wqthread + 932
15  libsystem_pthread.dylib             0x000000018540eb6c start_wqthread + 4
2017-12-12 12:32:43.225643+0200 Shop_n_Drop[2595:1308688] [reports] Main Thread Checker: UI API called on a background thread: -[UIApplication delegate]
PID: 2595, TID: 1308688, Thread name: (none), Queue name: io.ably.main, QoS: 0
Backtrace:
4   Ably                                0x0000000101323230 -[ARTPushActivationStateMachine deviceRegistration:] + 172
5   Ably                                0x0000000101321534 -[ARTPushActivationStateWaitingForPushDeviceDetails transition:] + 568
6   Ably                                0x0000000101322dd4 -[ARTPushActivationStateMachine handleEvent:] + 808
7   Ably                                0x00000001013229d4 __43-[ARTPushActivationStateMachine sendEvent:]_block_invoke + 52
8   libdispatch.dylib                   0x000000010217d2cc _dispatch_call_block_and_release + 24
9   libdispatch.dylib                   0x000000010217d28c _dispatch_client_callout + 16
10  libdispatch.dylib                   0x000000010218bf80 _dispatch_queue_serial_drain + 696
11  libdispatch.dylib                   0x00000001021807ec _dispatch_queue_invoke + 332
12  libdispatch.dylib                   0x000000010218cf6c _dispatch_root_queue_drain_deferred_wlh + 428
13  libdispatch.dylib                   0x0000000102194020 _dispatch_workloop_worker_thread + 652
14  libsystem_pthread.dylib             0x000000018540ef1c _pthread_wqthread + 932
15  libsystem_pthread.dylib             0x000000018540eb6c start_wqthread + 4

paddybyers · 2017-12-13T10:12:14Z

OK, so what's the issue with that - is it application code that's attempting a UI update in a context that can't do that? Or is it something we're doing on our side?

ricardopereira · 2017-12-13T10:34:17Z

@paddybyers I think this has been fixed. Can you ask if the client is using a custom register? I mean, If the client has the delegate ablyPushCustomRegister:deviceDetails:callback: method implemented? And if the code is updated (get the latest version by running pod update).

ricardopereira · 2017-12-13T10:43:57Z

Another thing I noticed is this 400 ("device with ID 0001D2XER600GW0X476W5TVBFE already registered") from POST https://rest.ably.io:443/push/deviceRegistrations:

2017-12-12 12:32:45.385793+0200 Shop_n_Drop[2595:1308688] DEBUG: POST https://rest.ably.io:443/push/deviceRegistrations: statusCode 400
2017-12-12 12:32:45.459226+0200 Shop_n_Drop[2595:1308688] VERBOSE: Headers {
    "Access-Control-Allow-Credentials" = true;
    "Access-Control-Allow-Origin" = "*";
    "Access-Control-Expose-Headers" = "Link,Transfer-Encoding,Content-Length,X-Ably-ErrorCode,X-Ably-ErrorMessage,X-Ably-ServerId,Server";
    "Content-Length" = 197;
    "Content-Type" = "application/json";
    Date = "Tue, 12 Dec 2017 10:32:43 GMT";
    Vary = Origin;
    "X-Ably-Errorcode" = 40000;
    "X-Ably-Errormessage" = "device with ID 0001D2XER600GW0X476W5TVBFE already registered";
    "X-Ably-Serverid" = "frontend.0769.2.eu-west-1-A.i-07404cdcf8cd0425f";
}

So, I think it should do a PUT instead of a POST to update a device registration.

paddybyers · 2017-12-13T11:18:26Z

So, I think it should do a PUT instead of a POST to update a device registration.

Yes - we've discussed this and we're going to be making changes to the API so both POST and PUT are supported, and both have upsert semantics.

ricardopereira · 2017-12-13T12:10:37Z

Yes - we've discussed this and we're going to be making changes to the API so both POST and PUT are supported, and both have upsert semantics.

@paddybyers Sorry, I'm confused. Should I change the code to use PUT instead of POST or the API will be updated soon to insert a device if it doesn't already exist or update it if it do?

paddybyers · 2017-12-13T12:11:50Z

I think this has been fixed.

That commit was 3 months ago but I understand he's using the latest on the push branch

paddybyers · 2017-12-13T12:14:47Z

Sorry, I'm confused. Should I change the code to use PUT instead of POST or the API will be updated soon to insert a device if it doesn't already exist or update it if it do?

I'll raise a separate issue here with the changes we need, once we have them implemented in realtime.

avi-kik · 2017-12-13T12:27:40Z

That backtrace is emitted by Xcode 9(.2), for any UIKit method called on a background thread, unless that method has been annotated to be thread safe. I don't know why it triggers on - [UIApplication delegate], but it does.

I am using the HEAD of the push branch.

avi-kik · 2017-12-13T12:28:37Z

I have not implemented the method ablyPushCustomRegister:deviceDetails:callback:.

ricardopereira · 2017-12-13T15:51:27Z

@avi-kik Thanks for your information. I can't reproduce this issue. Could you give me some hint on how to reproduce it? Or any sample project that I can use please?

avi-kik · 2017-12-13T20:04:32Z

@ricardopereira, I sent you an invite to gain read access to my app's repository. You'll want the apn branch.

mezis · 2017-12-18T09:21:26Z

FWIW, I'm also getting Main Thread Checker: UI API called on a background thread when push.activate is first called, right when the notifications popup appears. Looks like it's just a warning as (at least when running locally) I can still send direct-publish notifications find after it occurs.

ricardopereira · 2017-12-18T10:50:48Z

@mezis At what point do you call the UNUserNotificationCenter.current.requestAuthorization: to interact with the remote notifications?

ricardopereira · 2017-12-18T11:20:08Z

Can't reproduce none of those issues 😕 (400 issue and UI thread checker).

mezis · 2017-12-19T08:39:51Z

@ricardopereira: looks like this. Happy to send you the full "demo" app if that's useful as I barely know what I'm doing here.

    func application(_ application: UIApplication, didFinishLaunchingWithOptions launchOptions: [UIApplicationLaunchOptionsKey: Any]?) -> Bool {
        // Override point for customization after application launch.
        print("** hello!")

        self.realtime = self.getAblyRealtime()

        self.realtime.connection.on { (stateChange) in
            print("** Connection state change: \(String(describing: stateChange))")
        }

        UNUserNotificationCenter.current().requestAuthorization() { (ok, err) in
            DispatchQueue.main.async() {
                UIApplication.shared.registerForRemoteNotifications()
                print("** after registerForRemoteNotifications")
            }
        }

        print("** Activating Ably push")
        self.realtime.push.activate()

        return true
    }

ricardopereira · 2018-01-04T12:06:57Z

Sorry for the late reply.

@mezis Thanks, I used your snippet and and works fine:

First time I run the app:

2018-01-04 12:01:27.546465+0000 AblyPush[49729:4661543] ** hello!
    ************************ Crash Handler Notice ************************
    *     App is running in a debugger. Masking out unsafe monitors.     *
    * This means that most crashes WILL NOT BE RECORDED while debugging! *
    **********************************************************************
INFO : KSCrash.m (339): -[KSCrash sendAllReportsWithCompletion:]: Sending 0 crash reports
2018-01-04 12:01:27.630250+0000 AblyPush[49729:4661543] ** Activating Ably push
2018-01-04 12:01:27.631843+0000 AblyPush[49729:4661714] handling event ARTPushActivationEventCalledActivate from ARTPushActivationStateNotActivated
2018-01-04 12:01:27.652636+0000 AblyPush[49729:4661714] transition: ARTPushActivationStateNotActivated -> ARTPushActivationStateWaitingForPushDeviceDetails
2018-01-04 12:01:28.045870+0000 AblyPush[49729:4661543] ** Connection state change: <ARTConnectionStateChange: 0x1c405d880> - 
	 current: Connected; 
	 previous: Connecting; 
	 reason: (null); 
	 retryIn: 0.000000;
2018-01-04 12:01:32.460463+0000 AblyPush[49729:4661543] ** after registerForRemoteNotifications
2018-01-04 12:01:32.697691+0000 AblyPush[49729:4661543] ARTPush: device token received d1204698cfabe4158d5f880b2935ac998a57c51c961be3aa668aee9e6d3c7326
2018-01-04 12:01:32.698407+0000 AblyPush[49729:4661543] ARTPush: device token stored
2018-01-04 12:01:32.698677+0000 AblyPush[49729:4661714] handling event ARTPushActivationEventGotPushDeviceDetails from ARTPushActivationStateWaitingForPushDeviceDetails
2018-01-04 12:01:32.762602+0000 AblyPush[49729:4661714] transition: ARTPushActivationStateWaitingForPushDeviceDetails -> ARTPushActivationStateWaitingForUpdateToken
2018-01-04 12:01:34.154925+0000 AblyPush[49729:4661714] handling event ARTPushActivationEventGotUpdateToken from ARTPushActivationStateWaitingForUpdateToken
2018-01-04 12:01:34.155564+0000 AblyPush[49729:4661543] Activation: (null)
2018-01-04 12:01:34.155690+0000 AblyPush[49729:4661714] transition: ARTPushActivationStateWaitingForUpdateToken -> ARTPushActivationStateWaitingForNewPushDeviceDetails

Second time I run the app:

2018-01-04 12:02:53.897773+0000 AblyPush[49744:4662548] ** hello!
    ************************ Crash Handler Notice ************************
    *     App is running in a debugger. Masking out unsafe monitors.     *
    * This means that most crashes WILL NOT BE RECORDED while debugging! *
    **********************************************************************
INFO : KSCrash.m (339): -[KSCrash sendAllReportsWithCompletion:]: Sending 0 crash reports
2018-01-04 12:02:53.950052+0000 AblyPush[49744:4662548] ** Activating Ably push
2018-01-04 12:02:53.950988+0000 AblyPush[49744:4662566] handling event ARTPushActivationEventCalledActivate from ARTPushActivationStateWaitingForNewPushDeviceDetails
2018-01-04 12:02:53.951654+0000 AblyPush[49744:4662566] transition: ARTPushActivationStateWaitingForNewPushDeviceDetails -> ARTPushActivationStateWaitingForNewPushDeviceDetails
2018-01-04 12:02:53.960549+0000 AblyPush[49744:4662548] Activation: (null)
2018-01-04 12:02:53.961018+0000 AblyPush[49744:4662548] ** after registerForRemoteNotifications
2018-01-04 12:02:53.983464+0000 AblyPush[49744:4662548] ARTPush: device token received d1204698cfabe4158d5f880b2935ac998a57c51c961be3aa668aee9e6d3c7326
2018-01-04 12:02:54.605190+0000 AblyPush[49744:4662548] ** Connection state change: <ARTConnectionStateChange: 0x1c4251b80> - 
	 current: Connected; 
	 previous: Connecting; 
	 reason: (null); 
	 retryIn: 0.000000;

Could you send me a full demo app, please?

ricardopereira · 2018-01-04T12:18:20Z

@mezis Ignore my last comment 😅 I was using Xcode 8.

Now, it's happening:

2018-01-04 12:16:54.945509+0000 AblyPush[49844:4670093] ** hello!
    ************************ Crash Handler Notice ************************
    *     App is running in a debugger. Masking out unsafe monitors.     *
    * This means that most crashes WILL NOT BE RECORDED while debugging! *
    **********************************************************************
INFO : KSCrash.m (339): -[KSCrash sendAllReportsWithCompletion:]: Sending 0 crash reports
2018-01-04 12:16:55.019291+0000 AblyPush[49844:4670093] ** Activating Ably push
2018-01-04 12:16:55.020192+0000 AblyPush[49844:4670196] handling event ARTPushActivationEventCalledActivate from ARTPushActivationStateNotActivated
2018-01-04 12:16:55.117053+0000 AblyPush[49844:4670196] transition: ARTPushActivationStateNotActivated -> ARTPushActivationStateWaitingForPushDeviceDetails
2018-01-04 12:16:55.452804+0000 AblyPush[49844:4670093] ** Connection state change: <ARTConnectionStateChange: 0x1c0454640> - 
	 current: Connected; 
	 previous: Connecting; 
	 reason: (null); 
	 retryIn: 0.000000;
2018-01-04 12:17:00.262355+0000 AblyPush[49844:4670093] ** after registerForRemoteNotifications
2018-01-04 12:17:00.414672+0000 AblyPush[49844:4670093] ARTPush: device token received 8657ce10f81eefd897de653ddaf86c948218da3685621f6dfe6f6c17e5aba034
2018-01-04 12:17:00.415141+0000 AblyPush[49844:4670093] ARTPush: device token stored
2018-01-04 12:17:00.415295+0000 AblyPush[49844:4670196] handling event ARTPushActivationEventGotPushDeviceDetails from ARTPushActivationStateWaitingForPushDeviceDetails
=================================================================
Main Thread Checker: UI API called on a background thread: -[UIApplication delegate]
PID: 49844, TID: 4670196, Thread name: (none), Queue name: io.ably.main, QoS: 0
Backtrace:
4   Ably                                0x0000000102540ebc -[ARTPushActivationStateMachine deviceRegistration:] + 172
5   Ably                                0x000000010253f1c0 -[ARTPushActivationStateWaitingForPushDeviceDetails transition:] + 568
6   Ably                                0x0000000102540830 -[ARTPushActivationStateMachine handleEvent:] + 248
7   Ably                                0x0000000102540660 __43-[ARTPushActivationStateMachine sendEvent:]_block_invoke + 52
8   libdispatch.dylib                   0x0000000102ab12cc _dispatch_call_block_and_release + 24
9   libdispatch.dylib                   0x0000000102ab128c _dispatch_client_callout + 16
10  libdispatch.dylib                   0x0000000102abff80 _dispatch_queue_serial_drain + 696
11  libdispatch.dylib                   0x0000000102ab47ec _dispatch_queue_invoke + 332
12  libdispatch.dylib                   0x0000000102ac0f6c _dispatch_root_queue_drain_deferred_wlh + 428
13  libdispatch.dylib                   0x0000000102ac8020 _dispatch_workloop_worker_thread + 652
14  libsystem_pthread.dylib             0x0000000181e06f1c _pthread_wqthread + 932
15  libsystem_pthread.dylib             0x0000000181e06b6c start_wqthread + 4
2018-01-04 12:17:00.417649+0000 AblyPush[49844:4670196] [reports] Main Thread Checker: UI API called on a background thread: -[UIApplication delegate]
PID: 49844, TID: 4670196, Thread name: (none), Queue name: io.ably.main, QoS: 0
Backtrace:
4   Ably                                0x0000000102540ebc -[ARTPushActivationStateMachine deviceRegistration:] + 172
5   Ably                                0x000000010253f1c0 -[ARTPushActivationStateWaitingForPushDeviceDetails transition:] + 568
6   Ably                                0x0000000102540830 -[ARTPushActivationStateMachine handleEvent:] + 248
7   Ably                                0x0000000102540660 __43-[ARTPushActivationStateMachine sendEvent:]_block_invoke + 52
8   libdispatch.dylib                   0x0000000102ab12cc _dispatch_call_block_and_release + 24
9   libdispatch.dylib                   0x0000000102ab128c _dispatch_client_callout + 16
10  libdispatch.dylib                   0x0000000102abff80 _dispatch_queue_serial_drain + 696
11  libdispatch.dylib                   0x0000000102ab47ec _dispatch_queue_invoke + 332
12  libdispatch.dylib                   0x0000000102ac0f6c _dispatch_root_queue_drain_deferred_wlh + 428
13  libdispatch.dylib                   0x0000000102ac8020 _dispatch_workloop_worker_thread + 652
14  libsystem_pthread.dylib             0x0000000181e06f1c _pthread_wqthread + 932
15  libsystem_pthread.dylib             0x0000000181e06b6c start_wqthread + 4
2018-01-04 12:17:00.528736+0000 AblyPush[49844:4670196] transition: ARTPushActivationStateWaitingForPushDeviceDetails -> ARTPushActivationStateWaitingForUpdateToken
2018-01-04 12:17:02.201251+0000 AblyPush[49844:4670217] handling event ARTPushActivationEventGotUpdateToken from ARTPushActivationStateWaitingForUpdateToken
2018-01-04 12:17:02.201588+0000 AblyPush[49844:4670093] Activation: (null)
2018-01-04 12:17:02.201628+0000 AblyPush[49844:4670217] transition: ARTPushActivationStateWaitingForUpdateToken -> ARTPushActivationStateWaitingForNewPushDeviceDetails

Thanks again!

ricardopereira · 2018-01-04T15:56:15Z

@mezis Fixed 39f766f
Thank you for your patience.

ricardopereira · 2018-01-04T15:57:44Z

@avi-kik The 400 issue still happens?

ricardopereira · 2018-01-04T15:59:14Z

I'll close this because I can't reproduce it. Please open this issue again if it still happens.

paddybyers added the push label Dec 12, 2017

ricardopereira self-assigned this Dec 13, 2017

ricardopereira closed this as completed Jan 4, 2018

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Push activation fails if already registered #661

Push activation fails if already registered #661

paddybyers commented Dec 12, 2017

ricardopereira commented Dec 12, 2017

ricardopereira commented Dec 13, 2017

paddybyers commented Dec 13, 2017

ricardopereira commented Dec 13, 2017

ricardopereira commented Dec 13, 2017

paddybyers commented Dec 13, 2017

ricardopereira commented Dec 13, 2017

paddybyers commented Dec 13, 2017

paddybyers commented Dec 13, 2017

avi-kik commented Dec 13, 2017

avi-kik commented Dec 13, 2017

ricardopereira commented Dec 13, 2017

avi-kik commented Dec 13, 2017

mezis commented Dec 18, 2017

ricardopereira commented Dec 18, 2017

ricardopereira commented Dec 18, 2017

mezis commented Dec 19, 2017

ricardopereira commented Jan 4, 2018

ricardopereira commented Jan 4, 2018

ricardopereira commented Jan 4, 2018

ricardopereira commented Jan 4, 2018

ricardopereira commented Jan 4, 2018

Push activation fails if already registered #661

Push activation fails if already registered #661

Comments

paddybyers commented Dec 12, 2017

ricardopereira commented Dec 12, 2017

ricardopereira commented Dec 13, 2017

paddybyers commented Dec 13, 2017

ricardopereira commented Dec 13, 2017

ricardopereira commented Dec 13, 2017

paddybyers commented Dec 13, 2017

ricardopereira commented Dec 13, 2017

paddybyers commented Dec 13, 2017

paddybyers commented Dec 13, 2017

avi-kik commented Dec 13, 2017

avi-kik commented Dec 13, 2017

ricardopereira commented Dec 13, 2017

avi-kik commented Dec 13, 2017

mezis commented Dec 18, 2017

ricardopereira commented Dec 18, 2017

ricardopereira commented Dec 18, 2017

mezis commented Dec 19, 2017

ricardopereira commented Jan 4, 2018

ricardopereira commented Jan 4, 2018

ricardopereira commented Jan 4, 2018

ricardopereira commented Jan 4, 2018

ricardopereira commented Jan 4, 2018