1.0 auth flow doesn't work?

[SimonWoolf]

Customer points out that on getting a new token (as requested by the server sending an AUTH), instead of sending the token in its own AUTH message, the library appears to disconnect and start a new websocket connection, without even attempting a resume. (Note wss url at 18:52:09.869, no resume param)

2017-07-25 18:52:07.728  VERBOSE: RS:0x15f349970 ARTJsonLikeEncoder<msgpack>: protocolMessageFromDictionary {
    action = 17;
}
2017-07-25 18:52:07.789  VERBOSE: R:0x15f16c8d0 ARTRealtime didReceive Protocol Message Auth 
2017-07-25 18:52:07.825  INFO: R:0x15f16c8d0 server has requested an authorise
2017-07-25 18:52:07.856  DEBUG: (ARTRealtime.m:754) R:0x15f16c8d0 connecting with token auth; authorising
2017-07-25 18:52:07.893  VERBOSE: RS:0x15f349970 ARTAuth: requesting new token.
2017-07-25 18:52:07.915  DEBUG: RS:0x15f349970 ARTAuth: using authCallback
2017-07-25 18:52:07.946  DEBUG: (ARTWebSocketTransport.m:365) R:0x15f16c8d0 WS:0x15f365670 websocket did receive data <81a66163 74696f6e 00>
2017-07-25 18:52:07.971  DEBUG: RS:0x15f349970 ARTJsonLikeEncoder<msgpack> decoding '<81a66163 74696f6e 00>'; got: {
    action = 0;
}
2017-07-25 18:52:07.998  VERBOSE: RS:0x15f349970 ARTJsonLikeEncoder<msgpack>: protocolMessageFromDictionary {
    action = 0;
}
2017-07-25 18:52:08.033  VERBOSE: R:0x15f16c8d0 ARTRealtime didReceive Protocol Message Heartbeat 
2017-07-25 18:52:08.053  VERBOSE: R:0x15f16c8d0 ARTRealtime heartbeat received
2017-07-25 18:52:08.798 } timestamp=2017-07-25 11:52:08 +0000
2017-07-25 18:52:08.886  DEBUG: RS:0x15f349970 ARTJsonLikeEncoder<msgpack> encoding '{
    capability = "{\"<redacted>\":[\"presence\",\"subscribe\"]}";
    clientId = 712;
    keyName = "<redacted>";
    mac = "YZWIEAdzN6DBZwTm6mA+7Zz7zf54/Rp3Qn6h2/cOWl4=";
    nonce = 7aba7aa262cd5516f2092077642becb6;
    timestamp = 1500983528636;
    ttl = 60000;
}'; got: <87a36d61 63d92c59 5a574945 41647a4e 3644425a 77546d36 6d412b37 5a7a377a 6635342f 52703351 6e366832 2f634f57 6c343da8 636c6965 6e744964 a3373132 a374746c cdea60aa 63617061 62696c69 7479d941 7b223930 64663166 33312d35 6434322d 34356336 2d396362 662d3534 39386536 35656136 3730223a 5b227072 6573656e 6365222c 22737562 73637269 6265225d 7da76b65 794e616d 65ad6557 59334141 2e366f6a 434367a9 74696d65 7374616d 70cf0000 015d7997 0cbca56e 6f6e6365 d9203761 62613761 61323632 63643535 31366632 30393230 37373634 32626563 6236>
2017-07-25 18:52:08.943  DEBUG: (ARTRest.m:242) RS:0x15f349970 executing request <NSMutableURLRequest: 0x15f201180> { URL: https://rest.ably.io:443/keys/<redacted>/requestToken?format=msgpack }
2017-07-25 18:52:08.998  DEBUG: POST https://rest.ably.io:443/keys/<redacted>/requestToken?format=msgpack
2017-07-25 18:52:09.052  VERBOSE: Headers {
    Accept = "application/json,application/x-msgpack";
    "Content-Type" = "application/x-msgpack";
    "X-Ably-Lib" = "ios-1.0.7";
    "X-Ably-Version" = "1.0";
}
2017-07-25 18:52:09.408  DEBUG: POST https://rest.ably.io:443/keys/<redacted>/requestToken?format=msgpack: statusCode 201
2017-07-25 18:52:09.506  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" = 355;
    "Content-Type" = "application/x-msgpack";
    Date = "Tue, 25 Jul 2017 11:52:09 GMT";
    Vary = Origin;
    "X-Ably-Serverid" = "frontend.5e9f.2.ap-southeast-1-A.i-05d672c40b022dd8a";
}
2017-07-25 18:52:09.599  DEBUG: RS:0x15f349970 ARTJsonLikeEncoder<msgpack> decoding '<86a5746f 6b656ed9 c8655759 3341412e 47453635 38793964 684a6459 74583479 41424d6e 38514237 75435759 7262556e 44557741 77654830 626b3739 79623231 47775836 474e6f55 51517548 51316959 672d4648 73743868 65615762 456e4c36 6a475a73 6e375736 4d4a4766 4b4f6573 77346644 5f717a73 30753659 33483959 74437033 69597263 71577064 6b383671 62666a34 687a5849 57774352 70744968 64667138 4158434f 7672647a 7346524a 724b7a66 31466237 3350424f 6e533063 47416654 656d675f 577a496f 4a525756 7aa76b65 794e616d 65ad6557 59334141 2e366f6a 434367a6 69737375 6564cf00 00015d79 970f96a7 65787069 726573cf 0000015d 7997f9f6 aa636170 6162696c 697479d9 417b2239 30646631 6633312d 35643432 2d343563 362d3963 62662d35 34393865 36356561 36373022 3a5b2270 72657365 6e636522 2c227375 62736372 69626522 5d7da863 6c69656e 744964a3 373132>'; got: {
    capability = "{\"<redacted>\":[\"presence\",\"subscribe\"]}";
    clientId = 712;
    expires = 1500983589366;
    issued = 1500983529366;
    keyName = "<redacted>";
    token = "<redacted>.GE658y9dhJdYtX4yABMn8QB7uCWYrbUnDUwAweH0bk79yb21GwX6GNoUQQuHQ1iYg-FHst8heaWbEnL6jGZsn7W6MJGfKOesw4fD_qzs0u6Y3H9YtCp3iYrcqWpdk86qbfj4hzXIWwCRptIhdfq8AXCOvrdzsFRJrKzf1Fb73PBOnS0cGAfTemg_WzIoJRWVz";
}
2017-07-25 18:52:09.639  VERBOSE: RS:0x15f349970 ARTJsonLikeEncoder<msgpack>: tokenFromDictionary {
    capability = "{\"<redacted>\":[\"presence\",\"subscribe\"]}";
    clientId = 712;
    expires = 1500983589366;
    issued = 1500983529366;
    keyName = "<redacted>";
    token = "<redacted>.GE658y9dhJdYtX4yABMn8QB7uCWYrbUnDUwAweH0bk79yb21GwX6GNoUQQuHQ1iYg-FHst8heaWbEnL6jGZsn7W6MJGfKOesw4fD_qzs0u6Y3H9YtCp3iYrcqWpdk86qbfj4hzXIWwCRptIhdfq8AXCOvrdzsFRJrKzf1Fb73PBOnS0cGAfTemg_WzIoJRWVz";
}
2017-07-25 18:52:09.698  VERBOSE: RS:0x15f349970 ARTAuth: token request succeeded: ARTTokenDetails: token=<redacted>.GE658y9dhJdYtX4yABMn8QB7uCWYrbUnDUwAweH0bk79yb21GwX6GNoUQQuHQ1iYg-FHst8heaWbEnL6jGZsn7W6MJGfKOesw4fD_qzs0u6Y3H9YtCp3iYrcqWpdk86qbfj4hzXIWwCRptIhdfq8AXCOvrdzsFRJrKzf1Fb73PBOnS0cGAfTemg_WzIoJRWVz clientId=712 issued=2017-07-25 11:52:09 +0000 expires=2017-07-25 11:53:09 +0000
2017-07-25 18:52:09.737  DEBUG: (ARTRealtime.m:789) R:0x15f16c8d0 authorised: ARTTokenDetails: token=<redacted>.GE658y9dhJdYtX4yABMn8QB7uCWYrbUnDUwAweH0bk79yb21GwX6GNoUQQuHQ1iYg-FHst8heaWbEnL6jGZsn7W6MJGfKOesw4fD_qzs0u6Y3H9YtCp3iYrcqWpdk86qbfj4hzXIWwCRptIhdfq8AXCOvrdzsFRJrKzf1Fb73PBOnS0cGAfTemg_WzIoJRWVz clientId=712 issued=2017-07-25 11:52:09 +0000 expires=2017-07-25 11:53:09 +0000 error: (null)
2017-07-25 18:52:09.778  VERBOSE: (ARTWebSocketTransport.m:64) R:0x0 WS:0x160563d70 alloc
2017-07-25 18:52:09.811  VERBOSE: (ARTWebSocketTransport.m:70) R:0x0 WS:0x15f365670 dealloc
2017-07-25 18:52:09.841  DEBUG: (ARTWebSocketTransport.m:114) R:0x15f16c8d0 WS:0x160563d70 websocket connect with token
2017-07-25 18:52:09.869  DEBUG: (ARTWebSocketTransport.m:175) R:0x15f16c8d0 WS:0x160563d70 url wss://realtime.ably.io:443/?accessToken=<redacted>.GE658y9dhJdYtX4yABMn8QB7uCWYrbUnDUwAweH0bk79yb21GwX6GNoUQQuHQ1iYg-FHst8heaWbEnL6jGZsn7W6MJGfKOesw4fD_qzs0u6Y3H9YtCp3iYrcqWpdk86qbfj4hzXIWwCRptIhdfq8AXCOvrdzsFRJrKzf1Fb73PBOnS0cGAfTemg_WzIoJRWVz&clientId=712&echo=true&format=msgpack&v=1.0&lib=ios-1.0.7
2017-07-25 18:52:10.082  DEBUG: (ARTWebSocketTransport.m:243) R:0x15f16c8d0 WS:0x160563d70 websocket did open
2017-07-25 18:52:10.120  DEBUG: (ARTWebSocketTransport.m:365) R:0x15f16c8d0 WS:0x160563d70 websocket did receive data <...>; got: {
    action = 4;
    connectionDetails =     {
        clientId = 712;
        connectionKey = "a2dVXI5SwA9Ybm!75J8oZQ-9FXvnf-o-53c48a2dVXI5SwA9Ybm";
        connectionStateTtl = 120000;
        maxFrameSize = 262144;
        maxIdleInterval = 15000;
        maxInboundRate = 15;
        maxMessageSize = 16384;
        serverId = "frontend.308f.1.ap-southeast-1-A.i-05d672c40b022dd8a";
    };
    connectionId = "75J8oZQ-9F";
    connectionKey = "a2dVXI5SwA9Ybm!75J8oZQ-9FXvnf-o-53c48a2dVXI5SwA9Ybm";
    connectionSerial = "-1";
}
2017-07-25 18:52:10.235  VERBOSE: R:0x15f16c8d0 ARTRealtime didReceive Protocol Message Connected
2017-07-25 18:52:10.266  WARN: R:0x15f16c8d0 ARTRealtime: connection has reconnected, but resume failed. Reattaching any attached channels

[SimonWoolf]

Possibly relevant: transportReconnectWithRenewedToken just calls transportConnectForcingNewToken with forceNewToken: true, which appears to trigger a close and reopen of the transport: https://github.com/ably/ably-ios/blob/master/Source/ARTRealtime.m#L796 . (Even so, that claims to do so with resume options, so perhaps there's a second bug for why that doesn't cause the transport to attempt a resume)

[mattheworiordan]

@tcard I see 9f2f84f has been added which tests that the connection is correctly reused. However, is there not a secondary issue which is that even if it had used a new connection, it should have resumed and didn't. Do we have a test for that as well?

[tcard]

I haven't explicitly for this case, since it no longer exists. However, we test by spec item, and there are tests checking that e. g. DISCONNECTED and then CONNECTED connections are resumed properly.