Fix: connection resume does not fire channel detached #539

ricardopereira · 2016-11-23T00:56:22Z

ricardopereira · 2016-11-23T00:57:01Z

@mattheworiordan PTAL and if it's good then I fix the client.

mattheworiordan · 2016-11-23T01:07:52Z

Spec/RealtimeClientConnection.swift

+                                guard let stateChange = stateChange else {
+                                    fail("ConnectionStateChange is nil"); done(); return
+                                }
+                                expect(client.connection.id).to(equal(disconnectedMessage.connectionId))


Why would this be equal to the fabricated message that was received? Realtime will assign a new connectionId as that ID is now invalid

mattheworiordan · 2016-11-23T01:11:36Z

Spec/RealtimeClientConnection.swift

+
+                        let disconnectedMessage = ARTProtocolMessage()
+                        disconnectedMessage.action = .Disconnected
+                        disconnectedMessage.connectionId = "xxxxxxxxx"


This is a bit unusual as a connectionId is never sent with Disconnected, only Connected. Could you not instead simple do one or both of the following:

Send a new CONNECTED message with a new connectionId whilst the connection is CONNECTED. This should trigger channels to detach anyway, but that behaviour is only really expected in the 0.9 spec.

Manually terminate the connection, change the connectionKey in the object programatically so that it can no longer resume, check that the CONNECTED message received when resuming has a different connectionId to the original, then check that the channels have become DETACHED with a suitable error message as well.

mattheworiordan · 2016-11-23T01:14:35Z

Spec/RealtimeClientConnection.swift

+                        defer { client.dispose(); client.close() }
+                        let channel = client.channels.get("test")
+
+                        expect(client.connection.state).toEventually(equal(ARTRealtimeConnectionState.Connected), timeout: testTimeout)


This is not correct, this is not the behaviour we'd expect as a channel ATTACH that does not become ATTACHED would be resent or timeout.

The process I said we needed to test is:

Connect

Attach a channel (i.e wait for it to be attached)

Token expires and connection is disconnected by Ably

Resume happens automatically, wait until connected

Publish a message over REST on the channel

Ensure the message is received on the channel and the channel is still attached

mattheworiordan · 2016-11-23T01:15:07Z

Spec/RealtimeClientConnection.swift

@@ -1949,7 +1949,7 @@ class RealtimeClientConnection: QuickSpec {
                context("System's response to a resume request") {

                    // RTN15c1
-                    pending("CONNECTED ProtocolMessage with the same connectionId as the current client, and no error") {
+                    it("CONNECTED ProtocolMessage with the same connectionId as the current client, and no error") {


Can you confirm which other tests are marked as pending still? I was not aware we had pending tests.

@mattheworiordan Remaining pending tests:

Pending: when publishing a Message with an explicit clientId that is incompatible with the identified client’s clientId Pending: should be used a PresenceMap to maintain a list of members Pending: should result in an error if the channel is in the FAILED state Pending: should result in an error if the channel moves to the FAILED state

@ricardopereira please add an issue for those pending tests as we should look at them ASAP in case there are other spec requirements that the lib does not meet

ricardopereira · 2016-11-23T09:33:30Z

Spec/RealtimeClientConnection.swift

                            }
                        }

-                        expect(channel.state).to(equal(ARTRealtimeChannelState.Detached))
+                        expect(client.connection.id).toNot(equal(initialConnectionId))


From the logs, when the token expires the connectionId always changes, so I decided to add that and additionally it checks if the channel gets detached.

ricardopereira · 2016-11-23T09:33:57Z

@mattheworiordan PTAL at the last commit.

ricardopereira · 2016-11-23T09:36:45Z

The problems I noticed while debugging:

ARTRealtimeConnectionState.Connected event is not emmited when the connection renews the token
The connection resume only detaches the channels when the connectionId is different from the last one and an error exists

mattheworiordan · 2016-11-23T12:58:56Z

@ricardopereira can you address whilst reviewing the verbose logs, I can unfortunately see that the client library does not output the URL it is connecting to for new WS connections. Can you please ensure all HTTP and WebSocket connections / requests output the complete URL with headers if appropriate when verbose logging is on? as well please? Or is that covered?

mattheworiordan · 2016-11-23T13:02:11Z

Spec/RealtimeClientConnection.swift

+                    it("should resume the connection after an auth renewal and detach all channels if the connectionId changes") {
+                        let options = AblyTests.commonAppSetup()
+                        options.disconnectedRetryTimeout = 1.0
+                        options.tokenDetails = getTestTokenDetails(ttl: 2.0)


This looks a bit brittle, 2s to connect & attach in CI may fail, can we not just give it a bit of buffer, say 6 seconds to make sure we don't get test failures because of delays in running code?

mattheworiordan · 2016-11-23T13:03:05Z

Spec/RealtimeClientConnection.swift

+                        // Wait for token to expire
+                        waitUntil(timeout: testTimeout) { done in
+                            let partialDone = AblyTests.splitDone(2, done: done)
+                            channel.once(.Detached) { error in


Why is the channel becoming detached? If a connection is closed because of an auth failure, the channel does not become detached, it remains attached until the connection is closed or moves to the suspended state?

Sorry, I answered in the other comment #539 (comment)

mattheworiordan · 2016-11-23T13:04:32Z

Spec/RealtimeClientConnection.swift

+                            fail("ConnectionID is nil"); return
+                        }
+                        expect(client.connection.id).to(equal(receivedConnectionId))
+                        expect(client.connection.id).toNot(equal(initialConnectionId))


I don't follow why the connectionId has changed? Why? In a normal operation it won't, and as far as I can tell, you are not doing anything that would force it to change?

@mattheworiordan the connectionId changes and that's why the channel gets detached.

First CONNECTED:

2016-11-23 13:16:04.508 xctest[32837:4092858] VERBOSE: RS:0x7f955c623000 ARTJsonLikeEncoder<msgpack>: protocolMessageFromDictionary { action = 4; connectionDetails = { connectionKey = "e91RTOWlwA0vIq!tCwrawkZGCTS118T-ca6e91RTOWlwA0vIq"; connectionStateTtl = 120000; maxFrameSize = 262144; maxIdleInterval = 15000; maxInboundRate = 250; maxMessageSize = 16384; serverId = "frontend.64d2.1.eu-central-1-A.i-d35f816e"; }; connectionId = tCwrawkZGC; connectionKey = "e91RTOWlwA0vIq!tCwrawkZGCTS118T-ca6e91RTOWlwA0vIq"; connectionSerial = "-1"; }

It gets the DISCONNECTED from Ably:

2016-11-23 13:16:05.998 xctest[32837:4092858] VERBOSE: RS:0x7f955c623000 ARTJsonLikeEncoder<msgpack>: protocolMessageFromDictionary { action = 6; error = { code = 40142; message = "Key/token status changed (expire)"; statusCode = 401; }; }

The second CONNECTED:

2016-11-23 13:16:06.614 xctest[32837:4092858] VERBOSE: RS:0x7f955c623000 ARTJsonLikeEncoder<msgpack>: protocolMessageFromDictionary { action = 4; connectionDetails = { connectionKey = "e91NTgaIgA0vIq!guMApg59VswaKAc4-d86e91NTgaIgA0vIq"; connectionStateTtl = 120000; maxFrameSize = 262144; maxIdleInterval = 15000; maxInboundRate = 250; maxMessageSize = 16384; serverId = "frontend.25af.1.eu-central-1-A.i-305dca8c"; }; connectionId = guMApg59Vs; connectionKey = "e91NTgaIgA0vIq!guMApg59VswaKAc4-d86e91NTgaIgA0vIq"; connectionSerial = "-1"; }

Full log: https://gist.github.com/ricardopereira/15a80610b22c9216d5587f2375359921

mattheworiordan · 2016-11-23T13:05:32Z

This is not correct, please review.

Also, can you confirm that we are testing:

Even with the absence of an error, if the connection ID changes, then all channels should become detached (the error is only informational and not the reason channels are detached)
Auth renewal triggers a reconnect with resume and resumes connections
Auth renewal triggers a reconnect with (fabricated) faulty resume, resumes connection, emits an error, and detaches all channels.

ricardopereira · 2016-11-23T13:28:41Z

@ricardopereira can you address whilst reviewing the verbose logs, I can unfortunately see that the client library does not output the URL it is connecting to for new WS connections. Can you please ensure all HTTP and WebSocket connections / requests output the complete URL with headers if appropriate when verbose logging is on? as well please? Or is that covered?

@mattheworiordan Sorry, can you point me to a log entry where it is missing the URL ouput?
On each WebSocket connect it prints the current URL.

UPDATE: Ok, I think HTTP requests are not logging everthing.

mattheworiordan · 2016-11-23T13:32:58Z

@mattheworiordan Sorry, can you point me to a log entry where it is missing the URL ouput?
On each WebSocket connect it prints the current URL.

The log I sent you had no WebSocket URLs?

ricardopereira · 2016-11-23T13:34:36Z

The log I sent you had no WebSocket URLs?

@mattheworiordan i.e. line 467 R:0x600000132b60 WS:0x6080000b2300 url /?accessToken=FretAw.EuwDunZs3QlP772pw4M6sWJs_kJ8lsmgyTVuReyckGYTv3rT19ecO810t8WhFtIQGlDfPXGseF_eSB0rO-zHXEMP_ZIPppXeFH-oNWRoQ1qV5cruvBwOXN7giWgLPbSEzgiZwYLbNK7lPWxO466ls1A&clientId=development.client/167420&echo=true&format=msgpack&v=0.8&lib=ios-(null) -- wss://realtime.ably.io:443

mattheworiordan · 2016-11-23T13:36:32Z

Ah, my bad, mind including the host in there too though? I was scanning the logs for the host, my mistake, but I am sure it will happen to others.

mattheworiordan · 2016-11-23T16:36:41Z

Spec/RealtimeClientConnection.swift

-                        expect(channel.errorReason!.code).to(equal(80008))
-                        expect(channel.errorReason!.message).to(contain("Unable to recover connection"))
+                        guard let channelError = channel.errorReason else {
+                            fail("Channel error is nil"); return


Btw. Don't change this, but in future we should have an error message that explains the problem rather than the boolean logic i.e. anyone can see from this code that channel error is nil, but what the reader cares about is why nil is a problem i.e. this should instead be fail("Connection resume failed and error should be propagated to the cannel"). This helps the reader of the tests in future understand why this is a problem as opposed to just seeing that it is expected to be nil.

mattheworiordan

Looks good, 👍

Can you confirm when we're ready for the user with the issue to test this now?

ricardopereira · 2016-11-23T16:42:49Z

@mattheworiordan Yes, sure. If it passes then it's good to go. If not then I'll see what's wrong.

…mitted on the channel

ricardopereira changed the title ~~Fix 538~~ Fix: connection resume does not fire channel detached Nov 23, 2016

mattheworiordan reviewed Nov 23, 2016

View reviewed changes

ricardopereira commented Nov 23, 2016

View reviewed changes

ricardopereira force-pushed the fix-538 branch 2 times, most recently from 0c627a1 to 61c4b8b Compare November 23, 2016 11:32

mattheworiordan reviewed Nov 23, 2016

View reviewed changes

ricardopereira force-pushed the fix-538 branch from 7c169fa to 66355dc Compare November 23, 2016 15:46

mattheworiordan reviewed Nov 23, 2016

View reviewed changes

mattheworiordan approved these changes Nov 23, 2016

View reviewed changes

ricardopereira added 6 commits November 23, 2016 22:10

Add test: connection id change and channel state

d32f6a3

Add test: auth renewal and connection resume

b33b686

Remove pending tests from Realtime Connection specs

6ae562c

Fix: detach all channels if the connectionId has changed

6839aee

Fix: emit Connected connection state when a token is renewed

8b6367e

Fix: resume connection when a token has been renewed

79aca61

ricardopereira added 3 commits November 23, 2016 22:10

Fix: If the ATTACHED message contains an error, the error should be e…

8cac966

…mitted on the channel

Fix RTN15h

cd0fa78

Fix: if the token is renewable, then the error should not be set

286b516

ricardopereira force-pushed the fix-538 branch from faadb45 to 286b516 Compare November 23, 2016 22:11

ricardopereira merged commit 87913b8 into master Nov 24, 2016

ricardopereira deleted the fix-538 branch November 24, 2016 09:09

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Fix: connection resume does not fire channel detached #539

Fix: connection resume does not fire channel detached #539

ricardopereira commented Nov 23, 2016 •

edited

Loading

ricardopereira commented Nov 23, 2016

mattheworiordan Nov 23, 2016

mattheworiordan Nov 23, 2016

mattheworiordan Nov 23, 2016

mattheworiordan Nov 23, 2016

ricardopereira Nov 23, 2016 •

edited

Loading

mattheworiordan Nov 23, 2016

ricardopereira Nov 23, 2016

ricardopereira Nov 23, 2016

ricardopereira commented Nov 23, 2016

ricardopereira commented Nov 23, 2016 •

edited

Loading

mattheworiordan commented Nov 23, 2016

mattheworiordan Nov 23, 2016

mattheworiordan Nov 23, 2016

ricardopereira Nov 23, 2016

mattheworiordan Nov 23, 2016

ricardopereira Nov 23, 2016

mattheworiordan commented Nov 23, 2016 •

edited by ricardopereira

Loading

ricardopereira commented Nov 23, 2016 •

edited

Loading

mattheworiordan commented Nov 23, 2016

ricardopereira commented Nov 23, 2016

mattheworiordan commented Nov 23, 2016

mattheworiordan Nov 23, 2016

mattheworiordan left a comment

ricardopereira commented Nov 23, 2016

Fix: connection resume does not fire channel detached #539

Fix: connection resume does not fire channel detached #539

Conversation

ricardopereira commented Nov 23, 2016 • edited Loading

ricardopereira commented Nov 23, 2016

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ricardopereira Nov 23, 2016 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ricardopereira commented Nov 23, 2016

ricardopereira commented Nov 23, 2016 • edited Loading

mattheworiordan commented Nov 23, 2016

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

mattheworiordan commented Nov 23, 2016 • edited by ricardopereira Loading

ricardopereira commented Nov 23, 2016 • edited Loading

mattheworiordan commented Nov 23, 2016

ricardopereira commented Nov 23, 2016

mattheworiordan commented Nov 23, 2016

Choose a reason for hiding this comment

mattheworiordan left a comment

Choose a reason for hiding this comment

ricardopereira commented Nov 23, 2016

ricardopereira commented Nov 23, 2016 •

edited

Loading

ricardopereira Nov 23, 2016 •

edited

Loading

ricardopereira commented Nov 23, 2016 •

edited

Loading

mattheworiordan commented Nov 23, 2016 •

edited by ricardopereira

Loading

ricardopereira commented Nov 23, 2016 •

edited

Loading