Token request timeout, channel attach failure and debugging

[mattheworiordan]

@marto83 this from a client stating they cannot connect to Ably (well the channel):

Ably: [Debug] 04:38:44.995 #8 Protocol set to: MsgPack
Ably: [Debug] 04:38:44.996 #8 Initializing message encodings. json,utf-8,cipher,base64 initialized
Ably: [Info] 04:38:44.998 #8 Using token authentication.
Ably: [Info] 04:38:44.998 #8 Authentication method: Token auth with URL
Ably: [Debug] 04:38:45.019 #16 ConnectionManager thread created
Ably: [Debug] 04:38:45.020 #8 xx Changing state from Initialized => Connecting. SkipAttach = False.
Customer: [Error] {timeStamp} #{Thread.CurrentThread.ManagedThreadId} Definitiv hier!
Customer: [Error] {timeStamp} #{Thread.CurrentThread.ManagedThreadId} Definitiv hier regKez!
Ably: [Debug] 04:38:45.023 #16 xx Connecting: BeforeTransition
Ably: [Debug] 04:38:45.024 #16 Connection notifying subscribers for state change `Connecting`
Ably: [Debug] 04:38:45.024 #16 xx Connecting: Attaching state 
Ably: [Debug] 04:38:45.025 #16 Creating transport
Customer: [Error] {timeStamp} #{Thread.CurrentThread.ManagedThreadId} GetChannel!
Ably: [Debug] 04:38:45.029 #11 #private-OBFUSCATED: Changing state to: 'Attaching'. 
Ably: [Debug] 04:38:45.030 #11 Aborting timer '#private-OBFUSCATED timer'
Ably: [Debug] 04:38:45.030 #11 Setting up timer '#private-OBFUSCATED timer' to run action after 10 seconds. Autoreset: False
Ably: [Debug] 04:38:45.033 #11 Current state: Connecting. Sending message: { action=Attach }
Ably: [Debug] 04:38:45.034 #11 Queuing message with action: Attach. Connection State: Connecting
Ably: [Info] 04:38:45.049 #16 Sending POST request to https://api.CUSTOMER.com/rtc/auth/
Ably: [Debug] 04:38:45.054 #16 Executing request: https://api.CUSTOMER.com/rtc/auth/
Ably: [Info] 04:38:45.285 #16 Sending POST request to /keys/CUSTOMER.6iZXjw/requestToken
Customer: [Debug] {timeStamp} #{Thread.CurrentThread.ManagedThreadId} Update Failed
Ably: [Debug] 04:38:55.037 #11 Timer '#private-OBFUSCATED timer' interval 10 seconds elapsed and calling action.
Ably: [Debug] 04:38:55.040 #16 #private-OBFUSCATED: Changing state to: 'Failed'. Error: Reason: Channel didn't attach within the default timeout; Code: 50000
Customer: [Error] {timeStamp} #{Thread.CurrentThread.ManagedThreadId} Definitiv hier 2!
Customer: [Error] {timeStamp} #{Thread.CurrentThread.ManagedThreadId} Presence Channel State:Initialized
Ably: [Debug] 04:38:55.051 #27 #presence-OBFUSCATED: Changing state to: 'Attaching'. 
Ably: [Debug] 04:38:55.051 #27 Aborting timer '#presence-OBFUSCATED timer'
Ably: [Debug] 04:38:55.051 #27 Setting up timer '#presence-OBFUSCATED timer' to run action after 10 seconds. Autoreset: False
Ably: [Debug] 04:38:55.051 #27 Current state: Connecting. Sending message: { action=Attach }
Ably: [Debug] 04:38:55.051 #27 Queuing message with action: Attach. Connection State: Connecting
Ably: [Debug] 04:39:05.053 #11 Timer '#presence-OBFUSCATED timer' interval 10 seconds elapsed and calling action.
Ably: [Debug] 04:39:05.053 #16 #presence-OBFUSCATED: Changing state to: 'Failed'. Error: Reason: Channel didn't attach within the default timeout; Code: 50000
Customer: [Error] {timeStamp} #{Thread.CurrentThread.ManagedThreadId} Definitiv hier 2!

I think there are a few problems here:

• [ ] It seems the requestToken request is made but there is no feedback on the result. I've searched the logs on our end and seen no indication of any failures or timeouts
• [ ] It looks like the channel attach is timing out yet there is no connection. I do not think this is right given no ATTACH message has been sent as far as I can see, see http://docs.ably.io/client-lib-development-guide/features/#RTL4f. It should only time out when the ATTACH message is actually sent.
• [ ] It would be useful to a) have examples of how to enable verbose logging in the README, and also the most verbose logging level should probably include all protocol messages and HTTP requests so that it's easier to debug what's going on.

[marto83]

Can you let me know all the versions of the dependencies the customer is using?

Also does it work when using TextEncoding instead of Binary.

[tulpn]

Hi marto83, We are using 0.8.3, the latest version installed via the NuGet Package Manager.

The dependencies installed are:

Newtonsoft.Json 9.0.1
Nito.AsyncEx 3.0.1
WebSocket4Net  0.14.1
MsgPack.Cli 0.8.0

We are sending custom headers along to the Auth URL as well:

This is our setup:

System.Collections.Generic.Dictionary<string, string> AH =
                new System.Collections.Generic.Dictionary<string, string>
                {
                    {"Authorization", "Token " + Common.GetHTTPFileAuthToken()},
                    {"X-DEVICEID", FingerPrint.Value()}
                };
            Logger.LogLevel = LogLevel.Debug;
            APIConnection = new AblyRealtime(new ClientOptions
            {
                AuthUrl = new System.Uri(ProgGlobals.API_RTC_AUTH_URL),
                AuthMethod = HttpMethod.Post,
                AuthHeaders = AH,
                Key = ProgGlobals.RTC_ABLY_API
            });

Before the upgrade this code worked perfectly fine in our DEBUG/staging built. However, once we set it to production we experienced these issues.

[mattheworiordan]

@marto83 this from the customer when using text protocol:

I see, we just tested that as well, but there was not change. it is the same output as already seen in the github From the Dashboard I can see though that there are peak connections. Which means that the library can actually connect to Ably right? But it cannot attach to any channels. Wouldn't that mean, that there is an issue with the authentication & authorisation ?

[marto83]

@tulpn Everything looks right with your setup.

I'm going to send you a debug build that will include more logging around sending the request.

It sounds like something is going wrong during auth. Do you control this endpoint https://api.CUSTOMER.com/rtc/auth/? If you do can you see in the logs whether it's being accessed at all.

[tulpn]

@marto83 yes, indeed we are controlling that URL and I can see from the logs the requests to our endpoint.

[marto83]

@tulpn Can you send me the format of the returned json? There is a bug on this version where it doesn't support all the different types specified in the Spec.

[tulpn]

OK the JSON return is:

{'nonce': '...4073', 'timestamp': 1476984110974, 'clientId': '...e098a', 'capability': u'{"*": ["*"]}', 'mac': u'...5ZKg=', 'keyName': '...Xjw', 'ttl': 3600000}

[marto83]

that looks good as well. It's probably a long shot but does it have application/json Content-Type Header.

I'm going to check if the capability parsing is ok. I'll try and get a version of extra logging to you asap. It's not anything obvious but it does seem like it happens in the library.

[tulpn]

Yes, it does have that as well. When we had it running in DEBUG & dev environment everything was working fine, there wasn't any change of code. Even when we upgraded from 0.8.2-beta to 0.8.3.

[marto83]

@tulpn I've added some extra logging so we can see the request and response when request token happens. Are you using the .net 4.5 version of the dll? Let me know and I'll send you the dlls.

[marto83]

io.ably-0.8.3-custom.zip

Can you use this version and let me know what the logs show. Thanks. Hopefully we should be able to figure it out now.

[tulpn]

We have used the custom build and it produced the following output;

09:16:00.697 #23 xx Connecting: BeforeTransition: CLIENT Ably: [{0}] {1}
09:16:00.698 #23 Connection notifying subscribers for state change `Connecting`: CLIENT Ably: [{0}] {1}
09:16:00.698 #23 xx Connecting: Attaching state : CLIENT Ably: [{0}] {1}
09:16:00.700 #23 Creating transport: CLIENT Ably: [{0}] {1}
09:16:00.702 #10 #private-97d3f755782044bba6a30e49d4de098a: Changing state to: 'Attaching'. : CLIENT Ably: [{0}] {1}
09:16:00.703 #10 Aborting timer '#private-97d3f755782044bba6a30e49d4de098a timer': CLIENT Ably: [{0}] {1}
09:16:00.703 #10 Setting up timer '#private-97d3f755782044bba6a30e49d4de098a timer' to run action after 10 seconds. Autoreset: False: CLIENT Ably: [{0}] {1}
09:16:00.705 #10 Current state: Connecting. Sending message: { action=Attach }: CLIENT Ably: [{0}] {1}
09:16:00.707 #10 Queuing message with action: Attach. Connection State: Connecting: CLIENT Ably: [{0}] {1}
09:16:00.707 #10 #presence-97d3f755782044bba6a30e49d4de098a: Changing state to: 'Attaching'. : CLIENT Ably: [{0}] {1}
09:16:00.707 #10 Aborting timer '#presence-97d3f755782044bba6a30e49d4de098a timer': CLIENT Ably: [{0}] {1}
09:16:00.707 #10 Setting up timer '#presence-97d3f755782044bba6a30e49d4de098a timer' to run action after 10 seconds. Autoreset: False: CLIENT Ably: [{0}] {1}
09:16:00.707 #10 Current state: Connecting. Sending message: { action=Attach }: CLIENT Ably: [{0}] {1}
09:16:00.707 #10 Queuing message with action: Attach. Connection State: Connecting: CLIENT Ably: [{0}] {1}
09:16:00.717 #23 Sending POST request to https://api.MASKED.com/rtc/auth/: CLIENT Ably: [{0}] {1}
09:16:00.719 #23 Executing request: https://api.MASKED.com/rtc/auth/: CLIENT Ably: [{0}] {1}
09:16:00.722 #23 ---- Headers ----: CLIENT Ably: [{0}] {1}
09:16:00.722 #23 Authorization:Token fd07fce3ab46ecc7960b0c61874fd4efca24319ed16902a33b5917da60dac6fe.KMqnwenXK8uUhLKhFQsrUr6mFUOq8q9s9v7by6f1Pk8=: CLIENT Ably: [{0}] {1}
09:16:00.722 #23 X-DEVICEID:EB62-A654-97A0-F66C-5D51-B006-7688-9936: CLIENT Ably: [{0}] {1}
09:16:00.722 #23 Accept:application/x-msgpack, application/json: CLIENT Ably: [{0}] {1}
09:16:00.722 #23 -----------------: CLIENT Ably: [{0}] {1}
09:16:00.726 #23 ---- Body ----: CLIENT Ably: [{0}] {1}
09:16:00.726 #23 ttl=3600000&capability=%7B+%22%2A%22%3A+%5B+%22%2A%22+%5D+%7D: CLIENT Ably: [{0}] {1}
09:16:00.726 #23 --------------: CLIENT Ably: [{0}] {1}
Newtonsoft.Json.Linq.JValue enthält keine Definition für Count.
09:16:00.895 #23 Response from: https://api.MASKED.com/rtc/auth/: CLIENT Ably: [{0}] {1}
09:16:00.895 #23 Status code: 200 OK: CLIENT Ably: [{0}] {1}
09:16:00.895 #23 ---- Response Headers ----: CLIENT Ably: [{0}] {1}
09:16:00.895 #23 Vary: Accept, Accept-Language, Cookie: CLIENT Ably: [{0}] {1}
09:16:00.895 #23 x-content-type-options: nosniff, nosniff: CLIENT Ably: [{0}] {1}
09:16:00.895 #23 X-Frame-Options: SAMEORIGIN, sameorigin: CLIENT Ably: [{0}] {1}
09:16:00.895 #23 x-xss-protection: 1; mode=block: CLIENT Ably: [{0}] {1}
09:16:00.895 #23 Connection: keep-alive: CLIENT Ably: [{0}] {1}
09:16:00.895 #23 Date: Mon, 24 Oct 2016 09:16:04 GMT: CLIENT Ably: [{0}] {1}
09:16:00.895 #23 Server: Apache: CLIENT Ably: [{0}] {1}
09:16:00.895 #23 Content Type: application/json: CLIENT Ably: [{0}] {1}
09:16:00.895 #23 Encoding: utf-8: CLIENT Ably: [{0}] {1}
09:16:00.895 #23 Type: Json: CLIENT Ably: [{0}] {1}
09:16:00.895 #23 ---- Response Body ----: CLIENT Ably: [{0}] {1}
09:16:00.895 #23 {"nonce":"5a570e5be80a4660","timestamp":1477300564513,"clientId":"97d3f755782044bba6a30e49d4XXXXXX","capability":"{\"*\": [\"*\"]}","mac":"+M3uW1lnTLwkgPTuwIHaPQt6g+zcIM6TLfLc/ZqX3PI=","keyName":"XXXXX.YYYYY","ttl":3600000}: CLIENT Ably: [{0}] {1}
09:16:00.974 #23 Sending POST request to /keys/XXXXX.6iZXjw/requestToken: CLIENT Ably: [{0}] {1
09:16:01.338 #10 #private-cc-53bfc7bc7fa84e9797e2416c90d25644: Changing state to: 'Attaching'. : CLIENT Ably: [{0}] {1}
09:16:01.338 #10 Aborting timer '#private-cc-53bfc7bc7fa84e9797e2416c90d25644 timer': CLIENT Ably: [{0}] {1}
09:16:01.338 #10 Setting up timer '#private-cc-53bfc7bc7fa84e9797e2416c90d25644 timer' to run action after 10 seconds. Autoreset: False: CLIENT Ably: [{0}] {1}
09:16:01.338 #10 Current state: Connecting. Sending message: { action=Attach }: CLIENT Ably: [{0}] {1}
09:16:01.338 #10 Queuing message with action: Attach. Connection State: Connecting: CLIENT Ably: [{0}] {1}
09:16:10.706 #6 Timer '#private-97d3f755782044bba6a30e49d4de098a timer' interval 10 seconds elapsed and calling action.: CLIENT Ably: [{0}] {1}
09:16:10.706 #23 #private-97d3f755782044bba6a30e49d4de098a: Changing state to: 'Failed'. Error: Reason: Channel didn't attach within the default timeout; Code: 50000: CLIENT Ably: [{0}] {1}
09:16:10.717 #28 Timer '#presence-97d3f755782044bba6a30e49d4de098a timer' interval 10 seconds elapsed and calling action.: CLIENT Ably: [{0}] {1}
09:16:10.717 #23 #presence-97d3f755782044bba6a30e49d4de098a: Changing state to: 'Failed'. Error: Reason: Channel didn't attach within the default timeout; Code: 50000: CLIENT Ably: [{0}] {1}
09:16:11.350 #17 Timer '#private-cc-53bfc7bc7fa84e9797e2416c90d25644 timer' interval 10 seconds elapsed and calling action.: CLIENT Ably: [{0}] {1}
09:16:11.350 #23 #private-cc-53bfc7bc7fa84e9797e2416c90d25644: Changing state to: 'Failed'. Error: Reason: Channel didn't attach within the default timeout; Code: 50000: CLIENT Ably: [{0}] {1}

Could it be that: 09:16:00.974 #23 Sending POST request to /keys/XXXXX.6iZXjw/requestToken Is not a full URL ? The other message with POST request uses a full url, including domain.

I just recognised, I have not mentioned that our dev environment does not use HTTPS, but the production does.

[marto83]

It's ok to be a partial url; internally the host it set depending on the fallback settings. I don't think it being https should be an issue either.

What is happening here is the request is about to be made but it fails silently before even the goes to the internal HttpClient. I suspect it is happening when trying to set the body.

I'll try to put a try catch around that section and will send you another build if you don't mind.

[tulpn]

Sure. Sounds good to me.

[marto83]

Hi @tulpn. Here is another custom build: Ably 0.8.3 custom v2.zip

I've added more logging and I wrapped the suspected part in a try catch block to see if anything happens there.

Also if you want you can add me to skype (same username) so we can continue the discussion quicker.

[marto83]

The issue was caused by MsgPack library failing to encode the TokenRequest and crashing the ConnectionManager thread.

The current workaround is to use the Json protocol until 0.8.4 is released.