Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Push device registration omits clientId #877

Closed
paddybyers opened this issue Jul 23, 2019 · 5 comments
Closed

Push device registration omits clientId #877

paddybyers opened this issue Jul 23, 2019 · 5 comments
Assignees
@ricardopereira
Labels
bug Something isn't working. It's clear that this does need to be fixed.

Comments

@paddybyers
Copy link
Member

Below is an extract from a log. The issue we're seeing is that the Ably instance is being initialised with ClientOptions.clientId = null, but then later:

  • it is given auth details with a TokenRequest that does contain a clientId (see line 87 in the extract: ARTTokenRequest: keyName=lM4PsA.RZWvBw clientId=297455 )

  • but still the push device registration created does not have a clientId. (We know that by decoding the deviceIdentityToken received, and also from backend logs.

Can you think of a reason why the LocalDevice.clientId was not set?

2019-07-23 16:32:33.082185+0200 <redacted>[3324:926778] VERBOSE: (ARTRest.m:96) RS:0x282663cc0 0x28148eb20 alloc HTTP
2019-07-23 16:32:33.082655+0200 <redacted>[3324:926778] DEBUG: (ARTAuth.m:105) RS:0x282663cc0 validating <ARTClientOptions: 0x282867200> - 
	 key: (null); 
	 token: (null); 
	 authUrl: (null); 
	 authMethod: GET; 
	 hasAuthCallback: 1;
	 clientId: (null);
2019-07-23 16:32:33.082745+0200 <redacted>[3324:926778] DEBUG: (ARTAuth.m:130) RS:0x282663cc0 setting up auth method Token with authCallback
2019-07-23 16:32:33.082947+0200 <redacted>[3324:926778] VERBOSE: (ARTRest.m:114) RS:0x282663cc0 initialized
2019-07-23 16:32:33.087181+0200 <redacted>[3324:926778] INFO: Ably client library exception reporting enabled. Unhandled failures will be automatically submitted to errors.ably.io to help improve our service. To find out more about this feature, see https://help.ably.io/exceptions
2019-07-23 16:32:33.114146+0200 <redacted>[3324:926778] VERBOSE: (ARTRealtime.m:100) R:0x282b50960 initialized with RS:0x282663cc0
2019-07-23 16:32:33.114381+0200 <redacted>[3324:926778] DEBUG: (ARTRealtime.m:418) R:0x282b50960 realtime state transitions to 1 - Connecting
2019-07-23 16:32:33.114715+0200 <redacted>[3324:926778] VERBOSE: R:0x282b50960 realtime is transitioning from Initialized to Connecting
2019-07-23 16:32:33.115215+0200 <redacted>[3324:926778] VERBOSE: (ARTWebSocketTransport.m:69) R:0x0 WS:0x283f73800 alloc
2019-07-23 16:32:33.115495+0200 <redacted>[3324:926778] DEBUG: (ARTRealtime.m:897) R:0x282b50960 connecting with token auth; authorising (timeout of 10.000000)
2019-07-23 16:32:33.116125+0200 <redacted>[3324:926778] VERBOSE: RS:0x282663cc0 ARTAuth [authorize.184B7C3B-1CA6-4ED0-8F87-DF2247CC296C, delegate=NO]: requesting new token
2019-07-23 16:32:33.116359+0200 <redacted>[3324:926778] DEBUG: RS:0x282663cc0 ARTAuth: using authCallback
2019-07-23 16:32:33.117074+0200 <redacted>[3324:926778] INFO: Reachability: started listening for host realtime.ably.io
2019-07-23 16:32:33.117763+0200 <redacted>[3324:926778] VERBOSE: PublicEventEmitter Notification emitted 0x2837cb930-ARTRealtimeConnectionEventConnecting
2019-07-23 16:32:33.117787+0200 <redacted>[3324:926778] VERBOSE: PublicEventEmitter Notification emitted 0x2837cb930

2019-07-23 16:32:48.996853+0200 <redacted>[3324:926910] VERBOSE: (ARTRealtime.m:835) R:0x282b50960 connection timed out
2019-07-23 16:32:48.999182+0200 <redacted>[3324:926902] Task <006F108F-9430-4186-8C28-B899F7C07BEB>.<1> finished with error - code: -1001
2019-07-23 16:32:48.999932+0200 <redacted>[3324:926923] Task <E3CC0549-126B-4445-AEE9-B131F6AD2E09>.<1> finished with error - code: -1001
2019-07-23 16:32:49.000109+0200 <redacted>[3324:926910] DEBUG: (ARTRealtime.m:418) R:0x282b50960 realtime state transitions to 3 - Disconnected
2019-07-23 16:32:49.001469+0200 <redacted>[3324:926910] VERBOSE: R:0x282b50960 realtime is transitioning from Connecting to Disconnected
o
019-07-23 16:32:49.116955+0200 <redacted>[3324:926778] DEBUG: (ARTRestChannel.m:45) RS:0x283f03aa0 instantiating under 'private-notifications-user-297455'
2019-07-23 16:32:49.117771+0200 <redacted>[3324:926778] DEBUG: (ARTRealtimeChannel.m:597) R:0x282b50960 C:0x282d69260 (private-notifications-user-297455) channel state transitions from 0 - Initialized to 1 - Attaching
2019-07-23 16:32:49.118083+0200 <redacted>[3324:926778] VERBOSE: PublicEventEmitter Notification emitted 0x28373bd40-ARTChannelEventAttaching
2019-07-23 16:32:49.118101+0200 <redacted>[3324:926778] VERBOSE: PublicEventEmitter Notification emitted 0x28373bd40

2019-07-23 16:32:53.754137+0200 <redacted>[3324:926910] DEBUG: (ARTRealtime.m:418) R:0x282b50960 realtime state transitions to 1 - Connecting
2019-07-23 16:32:53.759203+0200 <redacted>[3324:926910] VERBOSE: R:0x282b50960 realtime is transitioning from Disconnected to Connecting
2019-07-23 16:32:53.762303+0200 <redacted>[3324:926910] VERBOSE: (ARTWebSocketTransport.m:69) R:0x0 WS:0x283f45c00 alloc
2019-07-23 16:32:53.765588+0200 <redacted>[3324:926910] DEBUG: (ARTRealtime.m:897) R:0x282b50960 connecting with token auth; authorising (timeout of 10.000000)
2019-07-23 16:32:53.768188+0200 <redacted>[3324:926910] VERBOSE: RS:0x282663cc0 ARTAuth [authorize.76682D76-F986-40BF-B794-6210C278F028, delegate=NO]: requesting new token
2019-07-23 16:32:53.770112+0200 <redacted>[3324:926910] DEBUG: RS:0x282663cc0 ARTAuth: using authCallback
2019-07-23 16:32:53.775814+0200 <redacted>[3324:926910] INFO: Reachability: stopped listening for host realtime.ably.io
2019-07-23 16:32:53.778078+0200 <redacted>[3324:926910] INFO: Reachability: started listening for host realtime.ably.io
2019-07-23 16:32:53.782970+0200 <redacted>[3324:926910] VERBOSE: PublicEventEmitter Notification emitted 0x2837cb930-ARTRealtimeConnectionEventConnecting
2019-07-23 16:32:53.783063+0200 <redacted>[3324:926910] VERBOSE: PublicEventEmitter Notification emitted 0x2837cb930

2019-07-23 16:33:03.600906+0200 <redacted>[3324:926778] ARTPush: device token received b378a2a0881217aa0333a78b0e8026731f4c5c7002991eb835b10f7ef4e086a4

2019-07-23 16:33:03.615363+0200 <redacted>[3324:926778] DEBUG: (ARTLocalDeviceStorage.m:45) Device Secret not found

2019-07-23 16:33:03.625924+0200 <redacted>[3324:926778] ARTPush: device token stored

2019-07-23 16:33:03.627198+0200 <redacted>[3324:926887] handling event ARTPushActivationEventGotPushDeviceDetails from ARTPushActivationStateNotActivated
2019-07-23 16:33:03.627329+0200 <redacted>[3324:926887] ARTPushActivationStateNotActivated state: handling ARTPushActivationEventGotPushDeviceDetails event
2019-07-23 16:33:03.627395+0200 <redacted>[3324:926887] enqueuing event: ARTPushActivationEventGotPushDeviceDetails

"Registered for remote notifications with token:b378a2a0881217aa0333a78b0e8026731f4c5c7002991eb835b10f7ef4e086a4"

2019-07-23 16:33:33.774717+0200 <redacted>[3324:926965] VERBOSE: (ARTRealtime.m:835) R:0x282b50960 connection timed out

2019-07-23 16:33:33.786663+0200 <redacted>[2019-07-23 16:33:33.786903+0200 <redacted>[3324:926965] VERBOSE: R:0x282b50960 realtime is transitioning from Connecting to Disconnected

2019-07-23 16:33:33.790596+0200 <redacted>[3324:926965] handling event ARTPushActivationEventCalledActivate from ARTPushActivationStateNotActivated
2019-07-23 16:33:33.790625+0200 <redacted>[3324:926965] ARTPushActivationStateNotActivated state: handling ARTPushActivationEventCalledActivate event
2019-07-23 16:33:33.790680+0200 <redacted>[3324:926965] transition: ARTPushActivationStateNotActivated -> ARTPushActivationStateWaitingForPushDeviceDetails

2019-07-23 16:33:33.791373+0200 <redacted>[3324:926965] attempting to consume pending event: ARTPushActivationEventGotPushDeviceDetails
2019-07-23 16:33:33.791490+0200 <redacted>[3324:926965] ARTPushActivationStateWaitingForPushDeviceDetails state: handling ARTPushActivationEventGotPushDeviceDetails event

2019-07-23 16:33:33.795054+0200 <redacted>[3324:926965] DEBUG: (ARTPushActivationStateMachine.m:172) device registration with request <NSMutableURLRequest: 0x28167f810> { URL: /push/deviceRegistrations }
2019-07-23 16:33:33.795927+0200 <redacted>[3324:926965] DEBUG: (ARTRest.m:213) RS:0x282663cc0 calculating authorization 1

2019-07-23 16:33:33.798033+0200 <redacted>[3324:926965] VERBOSE: RS:0x282663cc0 ARTAuth [authorize.254EA3B5-2DDF-42FC-9048-A1D8F0873245, delegate=YES]: requesting new token
2019-07-23 16:33:33.798532+0200 <redacted>[3324:926965] DEBUG: RS:0x282663cc0 ARTAuth: using authCallback
2019-07-23 16:33:33.801038+0200 <redacted>[3324:926965] transition: ARTPushActivationStateWaitingForPushDeviceDetails -> ARTPushActivationStateWaitingForDeviceRegistration
2019-07-23 16:33:33.802765+0200 <redacted>[3324:926965] handling event ARTPushActivationEventGotPushDeviceDetails from ARTPushActivationStateWaitingForDeviceRegistration
2019-07-23 16:33:33.802826+0200 <redacted>[3324:926965] ARTPushActivationStateWaitingForDeviceRegistration state: handling ARTPushActivationEventGotPushDeviceDetails event
2019-07-23 16:33:33.802847+0200 <redacted>[3324:926965] enqueuing event: ARTPushActivationEventGotPushDeviceDetails

2019-07-23 16:33:33.806390+0200 <redacted>[3324:926965] VERBOSE: (ARTWebSocketTransport.m:75) R:0x0 WS:0x283f45c00 dealloc

2019-07-23 16:33:46.494095+0200 <redacted>[3324:926778] ARTPush: device token received b378a2a0881217aa0333a78b0e8026731f4c5c7002991eb835b10f7ef4e086a4
2019-07-23 16:33:46.500192+0200 <redacted>[3324:927109] handling event ARTPushActivationEventCalledActivate from ARTPushActivationStateWaitingForDeviceRegistration
2019-07-23 16:33:46.500381+0200 <redacted>[3324:927109] ARTPushActivationStateWaitingForDeviceRegistration state: handling ARTPushActivationEventCalledActivate event
2019-07-23 16:33:46.500523+0200 <redacted>[3324:927109] transition: ARTPushActivationStateWaitingForDeviceRegistration -> ARTPushActivationStateWaitingForDeviceRegistration
2019-07-23 16:33:46.500625+0200 <redacted>[3324:927109] attempting to consume pending event: ARTPushActivationEventGotPushDeviceDetails
2019-07-23 16:33:46.500779+0200 <redacted>[3324:927109] ARTPushActivationStateWaitingForDeviceRegistration state: handling ARTPushActivationEventGotPushDeviceDetails event

2019-07-23 16:33:46.808722+0200 <redacted>[3324:926910] VERBOSE: RS:0x282663cc0 ARTJsonLikeEncoder<msgpack>: tokenRequestToDictionary ARTTokenRequest: keyName=lM4PsA.RZWvBw clientId=297455 nonce=1779222482735578 mac=KS5ytS7Q8pUuTnA61NgS468cttgeeCly9zq7nD3m1V8= ttl=3600 capability={"*":["push-subscribe","subscribe"]} timestamp=2019-07-23 14:33:46 +0000

2019-07-23 16:33:46.811624+0200 <redacted>[3324:926910] DEBUG: RS:0x282663cc0 ARTJsonLikeEncoder<msgpack> encoding '{
    capability = "{\"*\":[\"push-subscribe\",\"subscribe\"]}";
    clientId = 297455;
    keyName = "lM4PsA.RZWvBw";
    mac = "KS5ytS7Q8pUuTnA61NgS468cttgeeCly9zq7nD3m1V8=";
    nonce = 1779222482735578;
    timestamp = 1563892426736;
    ttl = 3600000;
}'; got: <87a36d61 63d92c4b 53357974 53375138 70557554 6e413631 4e675334 36386374 74676565 436c7939 7a71376e 44336d31 56383da8 636c6965 6e744964 a6323937 343535a3 74746cce 0036ee80 aa636170 6162696c 697479d9 247b222a 223a5b22 70757368 2d737562 73637269 6265222c 22737562 73637269 6265225d 7da76b65 794e616d 65ad6c4d 34507341 2e525a57 764277a9 74696d65 7374616d 70cf0000 016c1f40 a7f0a56e 6f6e6365 b0313737 39323232 34383237 33353537 38>
2019-07-23 16:33:46.814284+0200 <redacted>[3324:926910] DEBUG: (ARTRest.m:268) RS:0x282663cc0 executing request <NSMutableURLRequest: 0x2816532e0> { URL: https://rest.ably.io:443/keys/lM4PsA.RZWvBw/requestToken?format=msgpack }
2019-07-23 16:33:46.816110+0200 <redacted>[3324:926910] DEBUG: POST https://rest.ably.io:443/keys/lM4PsA.RZWvBw/requestToken?format=msgpack
2019-07-23 16:33:46.818059+0200 <redacted>[3324:926910] VERBOSE: Headers {
    Accept = "application/x-msgpack,application/json";
    "Content-Type" = "application/x-msgpack";
    "X-Ably-Lib" = "ios-1.1.9";
    "X-Ably-Version" = "1.1";
}

2019-07-23 16:33:47.119835+0200 <redacted>[3324:927110] VERBOSE: RS:0x282663cc0 ARTJsonLikeEncoder<msgpack>: tokenRequestToDictionary ARTTokenRequest: keyName=lM4PsA.RZWvBw clientId=297455 nonce=8777171839784222 mac=THZbKXdrG6ZhvbU76spR77TuAY5CiQz/Yd80gC972OE= ttl=3600 capability={"*":["push-subscribe","subscribe"]} timestamp=2019-07-23 14:33:47 +0000
2019-07-23 16:33:47.120976+0200 <redacted>[3324:927110] DEBUG: RS:0x282663cc0 ARTJsonLikeEncoder<msgpack> encoding '{
    capability = "{\"*\":[\"push-subscribe\",\"subscribe\"]}";
    clientId = 297455;
    keyName = "lM4PsA.RZWvBw";
    mac = "THZbKXdrG6ZhvbU76spR77TuAY5CiQz/Yd80gC972OE=";
    nonce = 8777171839784222;
    timestamp = 1563892427035;
    ttl = 3600000;
}'; got: <87a36d61 63d92c54 485a624b 58647247 365a6876 62553736 73705237 37547541 59354369 517a2f59 64383067 43393732 4f453da8 636c6965 6e744964 a6323937 343535a3 74746cce 0036ee80 aa636170 6162696c 697479d9 247b222a 223a5b22 70757368 2d737562 73637269 6265222c 22737562 73637269 6265225d 7da76b65 794e616d 65ad6c4d 34507341 2e525a57 764277a9 74696d65 7374616d 70cf0000 016c1f40 a91ba56e 6f6e6365 b0383737 37313731 38333937 38343232 32>
2019-07-23 16:33:47.122125+0200 <redacted>[3324:927110] DEBUG: (ARTRest.m:268) RS:0x282663cc0 executing request <NSMutableURLRequest: 0x281647b40> { URL: https://rest.ably.io:443/keys/lM4PsA.RZWvBw/requestToken?format=msgpack }
2019-07-23 16:33:47.123135+0200 <redacted>[3324:927110] DEBUG: POST https://rest.ably.io:443/keys/lM4PsA.RZWvBw/requestToken?format=msgpack
2019-07-23 16:33:47.124219+0200 <redacted>[3324:927110] VERBOSE: Headers {
    Accept = "application/x-msgpack,application/json";
    "Content-Type" = "application/x-msgpack";
    "X-Ably-Lib" = "ios-1.1.9";
    "X-Ably-Version" = "1.1";
}
2019-07-23 16:33:47.125578+0200 <redacted>[3324:926910] 6.5.0 - [Firebase/Performance][I-PRF300005] URL length exceeds limits, truncating recorded URL - https://rest.ably.io:443/keys/lM4PsA.RZWvBw/requestToken.
2019-07-23 16:33:47.125840+0200 <redacted>[3324:926910] 6.5.0 - [Firebase/Performance][I-PRF300005] URL length exceeds limits, truncating recorded URL - https://rest.ably.io:443/keys/lM4PsA.RZWvBw/requestToken.
2019-07-23 16:33:47.270457+0200 <redacted>[3324:927109] VERBOSE: RS:0x282663cc0 ARTJsonLikeEncoder<msgpack>: tokenRequestToDictionary ARTTokenRequest: keyName=lM4PsA.RZWvBw clientId=297455 nonce=5326695640742833 mac=Ap2TwlddXKRnDf4MOvX+ywvVU4KhCvFgu1pBcw9/Bes= ttl=3600 capability={"*":["push-subscribe","subscribe"]} timestamp=2019-07-23 14:33:47 +0000
2019-07-23 16:33:47.273054+0200 <redacted>[3324:927109] DEBUG: RS:0x282663cc0 ARTJsonLikeEncoder<msgpack> encoding '{
    capability = "{\"*\":[\"push-subscribe\",\"subscribe\"]}";
    clientId = 297455;
    keyName = "lM4PsA.RZWvBw";
    mac = "Ap2TwlddXKRnDf4MOvX+ywvVU4KhCvFgu1pBcw9/Bes=";
    nonce = 5326695640742833;
    timestamp = 1563892427190;
    ttl = 3600000;
}'; got: <87a36d61 63d92c41 70325477 6c646458 4b526e44 66344d4f 76582b79 77765655 344b6843 76466775 31704263 77392f42 65733da8 636c6965 6e744964 a6323937 343535a3 74746cce 0036ee80 aa636170 6162696c 697479d9 247b222a 223a5b22 70757368 2d737562 73637269 6265222c 22737562 73637269 6265225d 7da76b65 794e616d 65ad6c4d 34507341 2e525a57 764277a9 74696d65 7374616d 70cf0000 016c1f40 a9b6a56e 6f6e6365 b0353332 36363935 36343037 34323833 33>
2019-07-23 16:33:47.275077+0200 <redacted>[3324:927109] DEBUG: (ARTRest.m:268) RS:0x282663cc0 executing request <NSMutableURLRequest: 0x281619320> { URL: https://rest.ably.io:443/keys/lM4PsA.RZWvBw/requestToken?format=msgpack }
2019-07-23 16:33:47.277030+0200 <redacted>[3324:927109] DEBUG: POST https://rest.ably.io:443/keys/lM4PsA.RZWvBw/requestToken?format=msgpack
2019-07-23 16:33:47.278979+0200 <redacted>[3324:927109] VERBOSE: Headers {
    Accept = "application/x-msgpack,application/json";
    "Content-Type" = "application/x-msgpack";
    "X-Ably-Lib" = "ios-1.1.9";
    "X-Ably-Version" = "1.1";
}

2019-07-23 16:33:47.753493+0200 <redacted>[3324:926903] DEBUG: POST https://rest.ably.io:443/keys/lM4PsA.RZWvBw/requestToken?format=msgpack: statusCode 201

2019-07-23 16:33:47.754954+0200 <redacted>[3324:926903] VERBOSE: Headers {
    "Access-Control-Allow-Origin" = "*";
    "Content-Length" = 308;
    "Content-Type" = "application/x-msgpack";
    Date = "Tue, 23 Jul 2019 14:33:47 GMT";
    Vary = Origin;
    Via = "1.1 4085d0fb63bcf1447db3c47a72df12a4.cloudfront.net (CloudFront)";
    "access-control-allow-credentials" = true;
    "access-control-expose-headers" = "Link,Transfer-Encoding,Content-Length,X-Ably-ErrorCode,X-Ably-ErrorMessage,X-Ably-ServerId,Server";
    "x-ably-serverid" = "frontend.a257.2.us-east-1-A.i-07a30573fb1b6b47d";
    "x-amz-cf-id" = "WvgRbyzTsZTyF63hyKUUWoWcKWB0HExyUx5aXqkR6acAP0xSm9l5ug==";
    "x-amz-cf-pop" = "IAD79-C2";
    "x-cache" = "Miss from cloudfront";
}
2019-07-23 16:33:47.757141+0200 <redacted>[3324:926903] DEBUG: RS:0x282663cc0 ARTJsonLikeEncoder<msgpack> decoding '<86a5746f 6b656ed9 b36c4d34 5073412e 462d3545 4b4e576a 46713556 48524c32 47736377 49644667 30386b79 354c2d4a 68436e54 336f5872 2d446b45 30496966 374b4259 4141642d 504b4d63 5a6d7243 7a357a71 68725178 7869326a 57617875 73345949 46344969 5375464b 61564364 4f513177 46795566 66322d73 76462d64 535a636a 58443742 6d536d4c 6559546f 456c4a70 45467644 324d5f39 41776a4f 75454650 6f496349 79657037 714a436d 6e457845 46716b53 65693138 a76b6579 4e616d65 ad6c4d34 5073412e 525a5776 4277a669 73737565 64cf0000 016c1f40 aba3a765 78706972 6573cf00 00016c1f 779a23aa 63617061 62696c69 7479d924 7b222a22 3a5b2270 7573682d 73756273 63726962 65222c22 73756273 63726962 65225d7d a8636c69 656e7449 64a63239 37343535>'; got: {
    capability = "{\"*\":[\"push-subscribe\",\"subscribe\"]}";
    clientId = 297455;
    expires = 1563896027683;
    issued = 1563892427683;
    keyName = "lM4PsA.RZWvBw";
    token = "lM4PsA.F-5EKNWjFq5VHRL2GscwIdFg08ky5L-JhCnT3oXr-DkE0Iif7KBYAAd-PKMcZmrCz5zqhrQxxi2jWaxus4YIF4IiSuFKaVCdOQ1wFyUff2-svF-dSZcjXD7BmSmLeYToElJpEFvD2M_9AwjOuEFPoIcIyep7qJCmnExEFqkSei18";
}
2019-07-23 16:33:47.758407+0200 <redacted>[3324:926903] VERBOSE: RS:0x282663cc0 ARTJsonLikeEncoder<msgpack>: tokenFromDictionary {
    capability = "{\"*\":[\"push-subscribe\",\"subscribe\"]}";
    clientId = 297455;
    expires = 1563896027683;
    issued = 1563892427683;
    keyName = "lM4PsA.RZWvBw";
    token = "lM4PsA.F-5EKNWjFq5VHRL2GscwIdFg08ky5L-JhCnT3oXr-DkE0Iif7KBYAAd-PKMcZmrCz5zqhrQxxi2jWaxus4YIF4IiSuFKaVCdOQ1wFyUff2-svF-dSZcjXD7BmSmLeYToElJpEFvD2M_9AwjOuEFPoIcIyep7qJCmnExEFqkSei18";
}
2019-07-23 16:33:47.759313+0200 <redacted>[3324:926903] DEBUG: RS:0x282663cc0 ARTAuth [authorize.184B7C3B-1CA6-4ED0-8F87-DF2247CC296C]: token request succeeded: ARTTokenDetails: token=lM4PsA.F-5EKNWjFq5VHRL2GscwIdFg08ky5L-JhCnT3oXr-DkE0Iif7KBYAAd-PKMcZmrCz5zqhrQxxi2jWaxus4YIF4IiSuFKaVCdOQ1wFyUff2-svF-dSZcjXD7BmSmLeYToElJpEFvD2M_9AwjOuEFPoIcIyep7qJCmnExEFqkSei18 clientId=297455 issued=2019-07-23 14:33:47 +0000 expires=2019-07-23 15:33:47 +0000
2019-07-23 16:33:47.760200+0200 <redacted>[3324:926903] VERBOSE: RS:0x282663cc0 ARTAuth [authorize.184B7C3B-1CA6-4ED0-8F87-DF2247CC296C]: success callback: ARTTokenDetails: token=lM4PsA.F-5EKNWjFq5VHRL2GscwIdFg08ky5L-JhCnT3oXr-DkE0Iif7KBYAAd-PKMcZmrCz5zqhrQxxi2jWaxus4YIF4IiSuFKaVCdOQ1wFyUff2-svF-dSZcjXD7BmSmLeYToElJpEFvD2M_9AwjOuEFPoIcIyep7qJCmnExEFqkSei18 clientId=297455 issued=2019-07-23 14:33:47 +0000 expires=2019-07-23 15:33:47 +0000
2019-07-23 16:33:47.762210+0200 <redacted>[3324:926903] DEBUG: (ARTRealtime.m:935) R:0x282b50960 authorized: ARTTokenDetails: token=lM4PsA.F-5EKNWjFq5VHRL2GscwIdFg08ky5L-JhCnT3oXr-DkE0Iif7KBYAAd-PKMcZmrCz5zqhrQxxi2jWaxus4YIF4IiSuFKaVCdOQ1wFyUff2-svF-dSZcjXD7BmSmLeYToElJpEFvD2M_9AwjOuEFPoIcIyep7qJCmnExEFqkSei18 clientId=297455 issued=2019-07-23 14:33:47 +0000 expires=2019-07-23 15:33:47 +0000 error: (null)
2019-07-23 16:33:47.771547+0200 <redacted>[3324:927108] DEBUG: POST https://rest.ably.io:443/keys/lM4PsA.RZWvBw/requestToken?format=msgpack: statusCode 201

2019-07-23 16:33:47.772676+0200 <redacted>[3324:927108] VERBOSE: Headers {
    "Access-Control-Allow-Origin" = "*";
    "Content-Length" = 308;
    "Content-Type" = "application/x-msgpack";
    Date = "Tue, 23 Jul 2019 14:33:47 GMT";
    Vary = Origin;
    Via = "1.1 4085d0fb63bcf1447db3c47a72df12a4.cloudfront.net (CloudFront)";
    "access-control-allow-credentials" = true;
    "access-control-expose-headers" = "Link,Transfer-Encoding,Content-Length,X-Ably-ErrorCode,X-Ably-ErrorMessage,X-Ably-ServerId,Server";
    "x-ably-serverid" = "frontend.7acc.1.us-east-1-A.i-0f195c323f84cb818";
    "x-amz-cf-id" = "VeLkZCKOF3cYsvTMWty2Ku5fPMH9vS4eF7O-_yTnQrAZ7l6mwuo0Nw==";
    "x-amz-cf-pop" = "IAD79-C2";
    "x-cache" = "Miss from cloudfront";
}
2019-07-23 16:33:47.775149+0200 <redacted>[3324:927108] DEBUG: RS:0x282663cc0 ARTJsonLikeEncoder<msgpack> decoding '<86a5746f 6b656ed9 b36c4d34 5073412e 46437455 6c315373 72634245 5f516a33 7935724f 776d654c 7042594d 70786348 45717a6d 4868372d 76384336 6c517964 64624332 4e585a30 6a756b39 42597770 32305736 44323243 655f7635 33797a4f 4c346a73 6f473275 6a772d37 6f394269 61653570 572d6b79 32545056 49644b73 34692d78 61746d6e 326f746b 456a7657 39444d47 32696656 6e41565f 70776b4c 5966384d 4c48394c 744c4b4b 616c3753 4a4e4e38 59614138 675a4434 a76b6579 4e616d65 ad6c4d34 5073412e 525a5776 4277a669 73737565 64cf0000 016c1f40 abafa765 78706972 6573cf00 00016c1f 779a2faa 63617061 62696c69 7479d924 7b222a22 3a5b2270 7573682d 73756273 63726962 65222c22 73756273 63726962 65225d7d a8636c69 656e7449 64a63239 37343535>'; got: {
    capability = "{\"*\":[\"push-subscribe\",\"subscribe\"]}";
    clientId = 297455;
    expires = 1563896027695;
    issued = 1563892427695;
    keyName = "lM4PsA.RZWvBw";
    token = "lM4PsA.FCtUl1SsrcBE_Qj3y5rOwmeLpBYMpxcHEqzmHh7-v8C6lQyddbC2NXZ0juk9BYwp20W6D22Ce_v53yzOL4jsoG2ujw-7o9Biae5pW-ky2TPVIdKs4i-xatmn2otkEjvW9DMG2ifVnAV_pwkLYf8MLH9LtLKKal7SJNN8YaA8gZD4";
}
2019-07-23 16:33:47.776514+0200 <redacted>[3324:927108] VERBOSE: RS:0x282663cc0 ARTJsonLikeEncoder<msgpack>: tokenFromDictionary {
    capability = "{\"*\":[\"push-subscribe\",\"subscribe\"]}";
    clientId = 297455;
    expires = 1563896027695;
    issued = 1563892427695;
    keyName = "lM4PsA.RZWvBw";
    token = "lM4PsA.FCtUl1SsrcBE_Qj3y5rOwmeLpBYMpxcHEqzmHh7-v8C6lQyddbC2NXZ0juk9BYwp20W6D22Ce_v53yzOL4jsoG2ujw-7o9Biae5pW-ky2TPVIdKs4i-xatmn2otkEjvW9DMG2ifVnAV_pwkLYf8MLH9LtLKKal7SJNN8YaA8gZD4";
}
2019-07-23 16:33:47.777520+0200 <redacted>[3324:927108] DEBUG: RS:0x282663cc0 ARTAuth [authorize.254EA3B5-2DDF-42FC-9048-A1D8F0873245]: token request succeeded: ARTTokenDetails: token=lM4PsA.FCtUl1SsrcBE_Qj3y5rOwmeLpBYMpxcHEqzmHh7-v8C6lQyddbC2NXZ0juk9BYwp20W6D22Ce_v53yzOL4jsoG2ujw-7o9Biae5pW-ky2TPVIdKs4i-xatmn2otkEjvW9DMG2ifVnAV_pwkLYf8MLH9LtLKKal7SJNN8YaA8gZD4 clientId=297455 issued=2019-07-23 14:33:47 +0000 expires=2019-07-23 15:33:47 +0000
2019-07-23 16:33:47.779102+0200 <redacted>[3324:927108] DEBUG: (ARTRealtime.m:179) RS:0x282663cc0 new connection from successfull authorize ARTTokenDetails: token=lM4PsA.FCtUl1SsrcBE_Qj3y5rOwmeLpBYMpxcHEqzmHh7-v8C6lQyddbC2NXZ0juk9BYwp20W6D22Ce_v53yzOL4jsoG2ujw-7o9Biae5pW-ky2TPVIdKs4i-xatmn2otkEjvW9DMG2ifVnAV_pwkLYf8MLH9LtLKKal7SJNN8YaA8gZD4 clientId=297455 issued=2019-07-23 14:33:47 +0000 expires=2019-07-23 15:33:47 +0000
2019-07-23 16:33:47.779996+0200 <redacted>[3324:927108] DEBUG: (ARTRealtime.m:418) R:0x282b50960 realtime state transitions to 1 - Connecting
2019-07-23 16:33:47.781484+0200 <redacted>[3324:927108] VERBOSE: R:0x282b50960 realtime is transitioning from Disconnected to Connecting
2019-07-23 16:33:47.782562+0200 <redacted>[3324:927108] VERBOSE: (ARTWebSocketTransport.m:69) R:0x0 WS:0x283fe0a10 alloc
2019-07-23 16:33:47.783522+0200 <redacted>[3324:927108] DEBUG: (ARTRealtime.m:897) R:0x282b50960 connecting with token auth; authorising (timeout of 10.000000)
2019-07-23 16:33:47.784450+0200 <redacted>[3324:927108] DEBUG: (ARTWebSocketTransport.m:129) R:0x282b50960 WS:0x283fe0a10 websocket connect with token
2019-07-23 16:33:47.785476+0200 <redacted>[3324:927108] DEBUG: (ARTWebSocketTransport.m:195) R:0x282b50960 WS:0x283fe0a10 url wss://realtime.ably.io:443/?accessToken=lM4PsA.FCtUl1SsrcBE_Qj3y5rOwmeLpBYMpxcHEqzmHh7-v8C6lQyddbC2NXZ0juk9BYwp20W6D22Ce_v53yzOL4jsoG2ujw-7o9Biae5pW-ky2TPVIdKs4i-xatmn2otkEjvW9DMG2ifVnAV_pwkLYf8MLH9LtLKKal7SJNN8YaA8gZD4&echo=true&format=msgpack&v=1.1&lib=ios-1.1.9

2019-07-23 16:33:47.800656+0200 <redacted>[3324:927108] DEBUG: POST https://rest.ably.io:443/keys/lM4PsA.RZWvBw/requestToken?format=msgpack: statusCode 201
2019-07-23 16:33:47.802034+0200 <redacted>[3324:927108] VERBOSE: Headers {
    "Access-Control-Allow-Origin" = "*";
    "Content-Length" = 308;
    "Content-Type" = "application/x-msgpack";
    Date = "Tue, 23 Jul 2019 14:33:47 GMT";
    Vary = Origin;
    Via = "1.1 4085d0fb63bcf1447db3c47a72df12a4.cloudfront.net (CloudFront)";
    "access-control-allow-credentials" = true;
    "access-control-expose-headers" = "Link,Transfer-Encoding,Content-Length,X-Ably-ErrorCode,X-Ably-ErrorMessage,X-Ably-ServerId,Server";
    "x-ably-serverid" = "frontend.9598.1.us-east-1-A.i-09430d67b976ceb41";
    "x-amz-cf-id" = "mmsfVX6hpsvAWL2o1vyT-1JXQodn3z3elhQLACeLo-Aoy08o-eLbeQ==";
    "x-amz-cf-pop" = "IAD79-C2";
    "x-cache" = "Miss from cloudfront";
}
2019-07-23 16:33:47.804431+0200 <redacted>[3324:927108] DEBUG: RS:0x282663cc0 ARTJsonLikeEncoder<msgpack> decoding '<86a5746f 6b656ed9 b36c4d34 5073412e 46682d4a 6a6f5567 426e3336 6b315070 6759684c 626a536f 38614357 586c4754 6f613648 54534f6a 59796147 37556c6a 6a5a2d65 6b776a44 452d6578 5f474b33 6248504f 64304c33 31787834 5f355f50 2d6e426b 32634e4f 31685863 4f36652d 72743558 71773670 39706731 62754654 4b6a6b51 586d4a37 65545835 35733230 5356464e 467a566e 32333548 67633263 636a6d46 762d646c 5359452d 4f6d6150 78447475 4750565a 36754841 a76b6579 4e616d65 ad6c4d34 5073412e 525a5776 4277a669 73737565 64cf0000 016c1f40 abd2a765 78706972 6573cf00 00016c1f 779a52aa 63617061 62696c69 7479d924 7b222a22 3a5b2270 7573682d 73756273 63726962 65222c22 73756273 63726962 65225d7d a8636c69 656e7449 64a63239 37343535>'; got: {
    capability = "{\"*\":[\"push-subscribe\",\"subscribe\"]}";
    clientId = 297455;
    expires = 1563896027730;
    issued = 1563892427730;
    keyName = "lM4PsA.RZWvBw";
    token = "lM4PsA.Fh-JjoUgBn36k1PpgYhLbjSo8aCWXlGToa6HTSOjYyaG7UljjZ-ekwjDE-ex_GK3bHPOd0L31xx4_5_P-nBk2cNO1hXcO6e-rt5Xqw6p9pg1buFTKjkQXmJ7eTX55s20SVFNFzVn235Hgc2ccjmFv-dlSYE-OmaPxDtuGPVZ6uHA";
}
2019-07-23 16:33:47.805944+0200 <redacted>[3324:927108] VERBOSE: RS:0x282663cc0 ARTJsonLikeEncoder<msgpack>: tokenFromDictionary {
    capability = "{\"*\":[\"push-subscribe\",\"subscribe\"]}";
    clientId = 297455;
    expires = 1563896027730;
    issued = 1563892427730;
    keyName = "lM4PsA.RZWvBw";
    token = "lM4PsA.Fh-JjoUgBn36k1PpgYhLbjSo8aCWXlGToa6HTSOjYyaG7UljjZ-ekwjDE-ex_GK3bHPOd0L31xx4_5_P-nBk2cNO1hXcO6e-rt5Xqw6p9pg1buFTKjkQXmJ7eTX55s20SVFNFzVn235Hgc2ccjmFv-dlSYE-OmaPxDtuGPVZ6uHA";
}
2019-07-23 16:33:47.807017+0200 <redacted>[3324:927108] DEBUG: RS:0x282663cc0 ARTAuth [authorize.76682D76-F986-40BF-B794-6210C278F028]: token request succeeded: ARTTokenDetails: token=lM4PsA.Fh-JjoUgBn36k1PpgYhLbjSo8aCWXlGToa6HTSOjYyaG7UljjZ-ekwjDE-ex_GK3bHPOd0L31xx4_5_P-nBk2cNO1hXcO6e-rt5Xqw6p9pg1buFTKjkQXmJ7eTX55s20SVFNFzVn235Hgc2ccjmFv-dlSYE-OmaPxDtuGPVZ6uHA clientId=297455 issued=2019-07-23 14:33:47 +0000 expires=2019-07-23 15:33:47 +0000
2019-07-23 16:33:47.808229+0200 <redacted>[3324:927108] VERBOSE: RS:0x282663cc0 ARTAuth [authorize.76682D76-F986-40BF-B794-6210C278F028]: success callback: ARTTokenDetails: token=lM4PsA.Fh-JjoUgBn36k1PpgYhLbjSo8aCWXlGToa6HTSOjYyaG7UljjZ-ekwjDE-ex_GK3bHPOd0L31xx4_5_P-nBk2cNO1hXcO6e-rt5Xqw6p9pg1buFTKjkQXmJ7eTX55s20SVFNFzVn235Hgc2ccjmFv-dlSYE-OmaPxDtuGPVZ6uHA clientId=297455 issued=2019-07-23 14:33:47 +0000 expires=2019-07-23 15:33:47 +0000
2019-07-23 16:33:47.811077+0200 <redacted>[3324:927108] DEBUG: (ARTRealtime.m:935) R:0x282b50960 authorized: ARTTokenDetails: token=lM4PsA.Fh-JjoUgBn36k1PpgYhLbjSo8aCWXlGToa6HTSOjYyaG7UljjZ-ekwjDE-ex_GK3bHPOd0L31xx4_5_P-nBk2cNO1hXcO6e-rt5Xqw6p9pg1buFTKjkQXmJ7eTX55s20SVFNFzVn235Hgc2ccjmFv-dlSYE-OmaPxDtuGPVZ6uHA clientId=297455 issued=2019-07-23 14:33:47 +0000 expires=2019-07-23 15:33:47 +0000 error: (null)

2019-07-23 16:33:47.814107+0200 <redacted>[3324:927108] DEBUG: (ARTWebSocketTransport.m:129) R:0x282b50960 WS:0x283fe0a10 websocket connect with token
2019-07-23 16:33:47.815427+0200 <redacted>[3324:927108] DEBUG: (ARTWebSocketTransport.m:195) R:0x282b50960 WS:0x283fe0a10 url wss://realtime.ably.io:443/?accessToken=lM4PsA.Fh-JjoUgBn36k1PpgYhLbjSo8aCWXlGToa6HTSOjYyaG7UljjZ-ekwjDE-ex_GK3bHPOd0L31xx4_5_P-nBk2cNO1hXcO6e-rt5Xqw6p9pg1buFTKjkQXmJ7eTX55s20SVFNFzVn235Hgc2ccjmFv-dlSYE-OmaPxDtuGPVZ6uHA&echo=true&format=msgpack&v=1.1&lib=ios-1.1.9

2019-07-23 16:33:48.666994+0200 <redacted>[3324:926887] DEBUG: (ARTWebSocketTransport.m:266) R:0x282b50960 WS:0x283fe0a10 websocket did open
2019-07-23 16:33:48.670340+0200 <redacted>[3324:926887] VERBOSE: (ARTWebSocketTransport.m:339) R:0x282b50960 WS:0x283fe0a10 websocket did receive message



2019-07-23 16:33:48.671671+0200 <redacted>[3324:926887] DEBUG: (ARTWebSocketTransport.m:365) R:0x282b50960 WS:0x283fe0a10 websocket in Connecting state did receive data <85a66163 74696f6e 04ac636f 6e6e6563 74696f6e 4964aa54 396a4371 58774541 54ad636f 6e6e6563 74696f6e 4b6579d9 32653764 61715767 34674161 42707721 54396a43 71587745 4154342d 455a5a2d 2d333230 39653764 61715767 34674161 427077b0 636f6e6e 65637469 6f6e5365 7269616c ffb1636f 6e6e6563 74696f6e 44657461 696c7389 a8636c69 656e7449 64a63239 37343535 ad636f6e 6e656374 696f6e4b 6579d932 65376461 71576734 67416142 70772154 396a4371 58774541 54342d45 5a5a2d2d 33323039 65376461 71576734 67416142 7077ae6d 61784d65 73736167 6553697a 65cd4000 ae6d6178 496e626f 756e6452 61746532 af6d6178 4f757462 6f756e64 52617465 32ac6d61 78467261 6d655369 7a65ce00 040000a8 73657276 65724964 d92f6672 6f6e7465 6e642e37 3863662e 322e7573 2d656173 742d312d 412e692d 30626262 36363434 39616565 33333930 66b2636f 6e6e6563 74696f6e 53746174 6554746c ce0001d4 c0af6d61 7849646c 65496e74 65727661 6ccd3a98>
2019-07-23 16:33:48.673244+0200 <redacted>[3324:926887] DEBUG: RS:0x282663cc0 ARTJsonLikeEncoder<msgpack> decoding '<85a66163 74696f6e 04ac636f 6e6e6563 74696f6e 4964aa54 396a4371 58774541 54ad636f 6e6e6563 74696f6e 4b6579d9 32653764 61715767 34674161 42707721 54396a43 71587745 4154342d 455a5a2d 2d333230 39653764 61715767 34674161 427077b0 636f6e6e 65637469 6f6e5365 7269616c ffb1636f 6e6e6563 74696f6e 44657461 696c7389 a8636c69 656e7449 64a63239 37343535 ad636f6e 6e656374 696f6e4b 6579d932 65376461 71576734 67416142 70772154 396a4371 58774541 54342d45 5a5a2d2d 33323039 65376461 71576734 67416142 7077ae6d 61784d65 73736167 6553697a 65cd4000 ae6d6178 496e626f 756e6452 61746532 af6d6178 4f757462 6f756e64 52617465 32ac6d61 78467261 6d655369 7a65ce00 040000a8 73657276 65724964 d92f6672 6f6e7465 6e642e37 3863662e 322e7573 2d656173 742d312d 412e692d 30626262 36363434 39616565 33333930 66b2636f 6e6e6563 74696f6e 53746174 6554746c ce0001d4 c0af6d61 7849646c 65496e74 65727661 6ccd3a98>'; got: {
    action = 4;
    connectionDetails =     {
        clientId = 297455;
        connectionKey = "e7daqWg4gAaBpw!T9jCqXwEAT4-EZZ--3209e7daqWg4gAaBpw";
        connectionStateTtl = 120000;
        maxFrameSize = 262144;
        maxIdleInterval = 15000;
        maxInboundRate = 50;
        maxMessageSize = 16384;
        maxOutboundRate = 50;
        serverId = "frontend.78cf.2.us-east-1-A.i-0bbb66449aee3390f";
    };
    connectionId = T9jCqXwEAT;
    connectionKey = "e7daqWg4gAaBpw!T9jCqXwEAT4-EZZ--3209e7daqWg4gAaBpw";
    connectionSerial = "-1";
}
2019-07-23 16:33:48.675132+0200 <redacted>[3324:926887] VERBOSE: RS:0x282663cc0 ARTJsonLikeEncoder<msgpack>: protocolMessageFromDictionary {
    action = 4;
    connectionDetails =     {
        clientId = 297455;
        connectionKey = "e7daqWg4gAaBpw!T9jCqXwEAT4-EZZ--3209e7daqWg4gAaBpw";
        connectionStateTtl = 120000;
        maxFrameSize = 262144;
        maxIdleInterval = 15000;
        maxInboundRate = 50;
        maxMessageSize = 16384;
        maxOutboundRate = 50;
        serverId = "frontend.78cf.2.us-east-1-A.i-0bbb66449aee3390f";
    };
    connectionId = T9jCqXwEAT;
    connectionKey = "e7daqWg4gAaBpw!T9jCqXwEAT4-EZZ--3209e7daqWg4gAaBpw";
    connectionSerial = "-1";
}
2019-07-23 16:33:48.677447+0200 <redacted>[3324:926887] VERBOSE: (ARTRealtime.m:1291) R:0x282b50960 activity
2019-07-23 16:33:48.678817+0200 <redacted>[3324:926887] VERBOSE: R:0x282b50960 set idle timer had been ignored
2019-07-23 16:33:48.680162+0200 <redacted>[3324:926887] VERBOSE: R:0x282b50960 did receive Protocol Message Connected (connection state is Connecting)
2019-07-23 16:33:48.682384+0200 <redacted>[3324:926887] WARN: R:0x282b50960 ARTRealtime: connection has reconnected, but resume failed. Reattaching any attached channels
2019-07-23 16:33:48.683730+0200 <redacted>[3324:926887] DEBUG: (ARTRealtimeChannel.m:940) R:0x282b50960 C:0x282d69260 (private-notifications-user-297455) already attaching
2019-07-23 16:33:48.685006+0200 <redacted>[3324:926887] DEBUG: RT:0x282b50960 connection "(null)" has reconnected and resumed successfully
2019-07-23 16:33:48.688077+0200 <redacted>[3324:926887] DEBUG: (ARTRealtime.m:418) R:0x282b50960 realtime state transitions to 2 - Connected
2019-07-23 16:33:48.690967+0200 <redacted>[3324:926887] VERBOSE: R:0x282b50960 realtime is transitioning from Connecting to Connected
2019-07-23 16:33:48.692329+0200 <redacted>[3324:926887] VERBOSE: RS:0x282663cc0 ARTJsonLikeEncoder<msgpack>: protocolMessageToDictionary {
    action = 10;
    channel = "private-notifications-user-297455";
}
2019-07-23 16:33:48.693616+0200 <redacted>[3324:926887] DEBUG: RS:0x282663cc0 ARTJsonLikeEncoder<msgpack> encoding '{
    action = 10;
    channel = "private-notifications-user-297455";
}'; got: <82a76368 616e6e65 6cd92170 72697661 74652d6e 6f746966 69636174 696f6e73 2d757365 722d3239 37343535 a6616374 696f6e0a>
2019-07-23 16:33:48.694921+0200 <redacted>[3324:926887] DEBUG: (ARTRealtime.m:1083) R:0x282b50960 sending action 10 - Attach
2019-07-23 16:33:48.696347+0200 <redacted>[3324:926887] VERBOSE: PublicEventEmitter Notification emitted 0x2837cb930-ARTRealtimeConnectionEventConnected
2019-07-23 16:33:48.696371+0200 <redacted>[3324:926887] VERBOSE: PublicEventEmitter Notification emitted 0x2837cb930
2019-07-23 16:33:48.697288+0200 <redacted>[3324:926887] VERBOSE: RS:0x282663cc0 ARTAuth [authorize.254EA3B5-2DDF-42FC-9048-A1D8F0873245]: success callback: ARTTokenDetails: token=lM4PsA.FCtUl1SsrcBE_Qj3y5rOwmeLpBYMpxcHEqzmHh7-v8C6lQyddbC2NXZ0juk9BYwp20W6D22Ce_v53yzOL4jsoG2ujw-7o9Biae5pW-ky2TPVIdKs4i-xatmn2otkEjvW9DMG2ifVnAV_pwkLYf8MLH9LtLKKal7SJNN8YaA8gZD4 clientId=297455 issued=2019-07-23 14:33:47 +0000 expires=2019-07-23 15:33:47 +0000
GenesisNotifications: [2019-07-23 16:33:48.697] A connection exists and is active.
2019-07-23 16:33:48.700250+0200 <redacted>[3324:926887] VERBOSE: RS:0x282663cc0 ARTRest reissuing token: authorization bearer in Base64 Bearer bE00UHNBLkZDdFVsMVNzcmNCRV9RajN5NXJPd21lTHBCWU1weGNIRXF6bUhoNy12OEM2bFF5ZGRiQzJOWFowanVrOUJZd3AyMFc2RDIyQ2VfdjUzeXpPTDRqc29HMnVqdy03bzlCaWFlNXBXLWt5MlRQVklkS3M0aS14YXRtbjJvdGtFanZXOURNRzJpZlZuQVZfcHdrTFlmOE1MSDlMdExLS2FsN1NKTk44WWFBOGdaRDQ=
2019-07-23 16:33:48.702533+0200 <redacted>[3324:926887] DEBUG: (ARTRest.m:268) RS:0x282663cc0 executing request <NSMutableURLRequest: 0x28167f810> { URL: https://rest.ably.io:443/push/deviceRegistrations }
2019-07-23 16:33:48.703838+0200 <redacted>[3324:926887] DEBUG: POST https://rest.ably.io:443/push/deviceRegistrations
2019-07-23 16:33:48.705175+0200 <redacted>[3324:926887] VERBOSE: Headers {
    Accept = "application/x-msgpack,application/json";
    Authorization = "Bearer bE00UHNBLkZDdFVsMVNzcmNCRV9RajN5NXJPd21lTHBCWU1weGNIRXF6bUhoNy12OEM2bFF5ZGRiQzJOWFowanVrOUJZd3AyMFc2RDIyQ2VfdjUzeXpPTDRqc29HMnVqdy03bzlCaWFlNXBXLWt5MlRQVklkS3M0aS14YXRtbjJvdGtFanZXOURNRzJpZlZuQVZfcHdrTFlmOE1MSDlMdExLS2FsN1NKTk44WWFBOGdaRDQ=";
    "Content-Type" = "application/x-msgpack";
    "X-Ably-Lib" = "ios-1.1.9";
    "X-Ably-Version" = "1.1";
}
2019-07-23 16:33:48.708909+0200 <redacted>[3324:926887] DEBUG: (ARTWebSocketTransport.m:266) R:0x282b50960 WS:0x283fe0a10 websocket did open
2019-07-23 16:33:48.891488+0200 <redacted>[3324:927110] VERBOSE: (ARTWebSocketTransport.m:339) R:0x282b50960 WS:0x283fe0a10 websocket did receive message
2019-07-23 16:33:48.894132+0200 <redacted>[3324:927110] DEBUG: (ARTWebSocketTransport.m:365) R:0x282b50960 WS:0x283fe0a10 websocket in Open state did receive data <85a66163 74696f6e 04ac636f 6e6e6563 74696f6e 4964aa51 7a52487a 52725f33 34ad636f 6e6e6563 74696f6e 4b6579d9 32653764 61676d6d 39674161 42724321 517a5248 7a52725f 33344773 43335469 2d376536 63653764 61676d6d 39674161 427243b0 636f6e6e 65637469 6f6e5365 7269616c ffb1636f 6e6e6563 74696f6e 44657461 696c7389 a8636c69 656e7449 64a63239 37343535 ad636f6e 6e656374 696f6e4b 6579d932 65376461 676d6d39 67416142 72432151 7a52487a 52725f33 34477343 3354692d 37653663 65376461 676d6d39 67416142 7243ae6d 61784d65 73736167 6553697a 65cd4000 ae6d6178 496e626f 756e6452 61746532 af6d6178 4f757462 6f756e64 52617465 32ac6d61 78467261 6d655369 7a65ce00 040000a8 73657276 65724964 d92f6672 6f6e7465 6e642e37 3266312e 322e7573 2d656173 742d312d 412e692d 30653863 66353565 37653763 31643464 62b2636f 6e6e6563 74696f6e 53746174 6554746c ce0001d4 c0af6d61 7849646c 65496e74 65727661 6ccd3a98>
2019-07-23 16:33:48.896791+0200 <redacted>[3324:927110] DEBUG: RS:0x282663cc0 ARTJsonLikeEncoder<msgpack> decoding '<85a66163 74696f6e 04ac636f 6e6e6563 74696f6e 4964aa51 7a52487a 52725f33 34ad636f 6e6e6563 74696f6e 4b6579d9 32653764 61676d6d 39674161 42724321 517a5248 7a52725f 33344773 43335469 2d376536 63653764 61676d6d 39674161 427243b0 636f6e6e 65637469 6f6e5365 7269616c ffb1636f 6e6e6563 74696f6e 44657461 696c7389 a8636c69 656e7449 64a63239 37343535 ad636f6e 6e656374 696f6e4b 6579d932 65376461 676d6d39 67416142 72432151 7a52487a 52725f33 34477343 3354692d 37653663 65376461 676d6d39 67416142 7243ae6d 61784d65 73736167 6553697a 65cd4000 ae6d6178 496e626f 756e6452 61746532 af6d6178 4f757462 6f756e64 52617465 32ac6d61 78467261 6d655369 7a65ce00 040000a8 73657276 65724964 d92f6672 6f6e7465 6e642e37 3266312e 322e7573 2d656173 742d312d 412e692d 30653863 66353565 37653763 31643464 62b2636f 6e6e6563 74696f6e 53746174 6554746c ce0001d4 c0af6d61 7849646c 65496e74 65727661 6ccd3a98>'; got: {
    action = 4;
    connectionDetails =     {
        clientId = 297455;
        connectionKey = "e7dagmm9gAaBrC!QzRHzRr_34GsC3Ti-7e6ce7dagmm9gAaBrC";
        connectionStateTtl = 120000;
        maxFrameSize = 262144;
        maxIdleInterval = 15000;
        maxInboundRate = 50;
        maxMessageSize = 16384;
        maxOutboundRate = 50;
        serverId = "frontend.72f1.2.us-east-1-A.i-0e8cf55e7e7c1d4db";
    };
    connectionId = "QzRHzRr_34";
    connectionKey = "e7dagmm9gAaBrC!QzRHzRr_34GsC3Ti-7e6ce7dagmm9gAaBrC";
    connectionSerial = "-1";
}
2019-07-23 16:33:48.899860+0200 <redacted>[3324:927110] VERBOSE: RS:0x282663cc0 ARTJsonLikeEncoder<msgpack>: protocolMessageFromDictionary {
    action = 4;
    connectionDetails =     {
        clientId = 297455;
        connectionKey = "e7dagmm9gAaBrC!QzRHzRr_34GsC3Ti-7e6ce7dagmm9gAaBrC";
        connectionStateTtl = 120000;
        maxFrameSize = 262144;
        maxIdleInterval = 15000;
        maxInboundRate = 50;
        maxMessageSize = 16384;
        maxOutboundRate = 50;
        serverId = "frontend.72f1.2.us-east-1-A.i-0e8cf55e7e7c1d4db";
    };
    connectionId = "QzRHzRr_34";
    connectionKey = "e7dagmm9gAaBrC!QzRHzRr_34GsC3Ti-7e6ce7dagmm9gAaBrC";
    connectionSerial = "-1";
}
2019-07-23 16:33:48.903984+0200 <redacted>[3324:927110] VERBOSE: (ARTRealtime.m:1291) R:0x282b50960 activity
2019-07-23 16:33:48.906404+0200 <redacted>[3324:927110] VERBOSE: R:0x282b50960 did receive Protocol Message Connected (connection state is Connected)
2019-07-23 16:33:48.910258+0200 <redacted>[3324:927110] DEBUG: (ARTRealtime.m:437) R:0x282b50960 update requested
2019-07-23 16:33:48.912566+0200 <redacted>[3324:927110] VERBOSE: R:0x282b50960 realtime is transitioning from Connected to Connected
2019-07-23 16:33:48.914323+0200 <redacted>[3324:927110] VERBOSE: PublicEventEmitter Notification emitted 0x2837cb930-ARTRealtimeConnectionEventUpdate
2019-07-23 16:33:48.914347+0200 <redacted>[3324:927110] VERBOSE: PublicEventEmitter Notification emitted 0x2837cb930

2019-07-23 16:33:52.107421+0200 <redacted>[3324:926887] DEBUG: POST https://rest.ably.io:443/push/deviceRegistrations: statusCode 201

2019-07-23 16:33:52.120991+0200 <redacted>[3324:926887] VERBOSE: Headers {
    "Access-Control-Allow-Origin" = "*";
    "Content-Length" = 467;
    "Content-Type" = "application/x-msgpack";
    Date = "Tue, 23 Jul 2019 14:33:52 GMT";
    Vary = Origin;
    Via = "1.1 4085d0fb63bcf1447db3c47a72df12a4.cloudfront.net (CloudFront)";
    "access-control-allow-credentials" = true;
    "access-control-expose-headers" = "Link,Transfer-Encoding,Content-Length,X-Ably-ErrorCode,X-Ably-ErrorMessage,X-Ably-ServerId,Server";
    "x-ably-serverid" = "frontend.fcd4.1.us-east-1-A.i-0bbb66449aee3390f";
    "x-amz-cf-id" = "ac4you-ijuHP-UlcD6EIJ8fR0Y6E33tH1qfI2pDT1yhHJEVUujb50g==";
    "x-amz-cf-pop" = "IAD79-C2";
    "x-cache" = "Miss from cloudfront";
}
2019-07-23 16:33:52.142675+0200 <redacted>[3324:926887] DEBUG: RS:0x282663cc0 ARTJsonLikeEncoder<msgpack> decoding '<87a26964 ba303030 31454b45 364d5a30 30475730 58343736 57355456 424645a5 61707049 64a66c4d 34507341 a8706c61 74666f72 6da3696f 73aa666f 726d4661 63746f72 a570686f 6e65a86d 65746164 61746180 a4707573 6882a972 65636970 69656e74 82ad7472 616e7370 6f727454 797065a4 61706e73 ab646576 69636554 6f6b656e d9406233 37386132 61303838 31323137 61613033 33336137 38623065 38303236 37333166 34633563 37303032 39393165 62383335 62313066 37656634 65303836 6134a573 74617465 a6414354 495645b3 64657669 63654964 656e7469 7479546f 6b656e85 a5746f6b 656ed99e 6c4d3450 73412e45 55467975 35347170 54307179 7476466f 73535530 594c6468 31734e67 4c4b6557 6e556655 326f4856 5f4a3477 76675f41 71394c55 69334178 70345663 4c65575f 45634a57 6c655166 796e2d35 346c3432 344d7547 6d525334 38337061 325f7444 3855775a 76465777 7a4e6342 47503245 7a726957 72693669 706c4d4b 6f765077 32355958 34453565 7a554365 4232302d 37505f48 3767a76b 65794e61 6d65ad6c 4d345073 412e525a 57764277 a6697373 756564cf 0000016c 1f40bc8e a7657870 69726573 cf000001 7376f1e8 8eaa6361 70616269 6c697479 a27b7d>'; got: {
    appId = lM4PsA;
    deviceIdentityToken =     {
        capability = "{}";
        expires = 1595428432014;
        issued = 1563892432014;
        keyName = "lM4PsA.RZWvBw";
        token = "lM4PsA.EUFyu54qpT0qytvFosSU0YLdh1sNgLKeWnUfU2oHV_J4wvg_Aq9LUi3Axp4VcLeW_EcJWleQfyn-54l424MuGmRS483pa2_tD8UwZvFWwzNcBGP2EzriWri6iplMKovPw25YX4E5ezUCeB20-7P_H7g";
    };
    formFactor = phone;
    id = 0001EKE6MZ00GW0X476W5TVBFE;
    metadata =     {
    };
    platform = ios;
    push =     {
        recipient =         {
            deviceToken = b378a2a0881217aa0333a78b0e8026731f4c5c7002991eb835b10f7ef4e086a4;
            transportType = apns;
        };
        state = ACTIVE;
    };
}
2019-07-23 16:33:52.148589+0200 <redacted>[3324:926887] VERBOSE: RS:0x282663cc0 ARTJsonLikeEncoder<msgpack>: deviceIdentityTokenDetailsFromDictionary {
    appId = lM4PsA;
    deviceIdentityToken =     {
        capability = "{}";
        expires = 1595428432014;
        issued = 1563892432014;
        keyName = "lM4PsA.RZWvBw";
        token = "lM4PsA.EUFyu54qpT0qytvFosSU0YLdh1sNgLKeWnUfU2oHV_J4wvg_Aq9LUi3Axp4VcLeW_EcJWleQfyn-54l424MuGmRS483pa2_tD8UwZvFWwzNcBGP2EzriWri6iplMKovPw25YX4E5ezUCeB20-7P_H7g";
    };
    formFactor = phone;
    id = 0001EKE6MZ00GW0X476W5TVBFE;
    metadata =     {
    };
    platform = ios;
    push =     {
        recipient =         {
            deviceToken = b378a2a0881217aa0333a78b0e8026731f4c5c7002991eb835b10f7ef4e086a4;
            transportType = apns;
        };
        state = ACTIVE;
    };
}
@paddybyers paddybyers added push bug Something isn't working. It's clear that this does need to be fixed. labels Jul 23, 2019
@Srushtika
Copy link
Member

@ricardopereira I'm able to reproduce this issue where we don't receive the clientId upon an activation request from a device.

Essentially in the example app's AppDelegate file. If you try and instantiate the library, but not connect to it (possibly by setting the autoConnect client option to false) and then call activate() immediately, the registered device then seems to be missing the clientId in our database, causing the issues raised by the customer.

So within didFinishLaunchingWithOptions():

self.realtime = self.getAblyRealtime() //with autoConnect false
self.realtime.push.activate() //registers the device with Ably without a clientId

@ricardopereira
Copy link
Contributor

we don't receive the clientId upon an activation request from a device.

@Srushtika This makes sense. I've already a PR #874 which probably fixes that. Can you try that branch please?

Remember, change the Podfile to pod 'Ably', :git => 'https://github.com/ably/ably-cocoa.git', :branch => 'update-localdevice-clientid'

@paddybyers
Copy link
Member Author

#874 doesn't appear to fix it

@paddybyers
Copy link
Member Author

@tcard are you able to look at this please? @Srushtika can help you to reproduce it if necessary.

@ricardopereira
Copy link
Contributor

@paddybyers I think you mean me right? 😄 I can see this in the afternoon.

ricardopereira added a commit that referenced this issue Jul 26, 2019
@ricardopereira
Test for #877: should update LocalDevice.clientId with auth.clientId"
e705ed7
@ricardopereira ricardopereira mentioned this issue Jul 26, 2019
Merged
@ricardopereira ricardopereira mentioned this issue Jul 29, 2019
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@ricardopereira ricardopereira

Labels
bug Something isn't working. It's clear that this does need to be fixed.
Milestone
No milestone
Development

No branches or pull requests
3 participants
@paddybyers @ricardopereira @Srushtika