Randomly getting Missing required property 'protocol'.

[drajvver]

Hello everyone.

I'm writing there, since I've googled, searched almost everywhere I could and probably exhausted all other resources to get the informations.
I'm using SignalR with AspNetCore App 2.1.1, using the newest version - 1.0.3.
The problem is that once in a while, without apparent pattern, this exception occures:

System.IO.InvalidDataException: Missing required property 'protocol'. at Microsoft.AspNetCore.SignalR.Protocol.HandshakeProtocol.TryParseRequestMessage(ReadOnlySequence1& buffer, HandshakeRequestMessage& requestMessage) at Microsoft.AspNetCore.SignalR.HubConnectionContext.HandshakeAsync(TimeSpan timeout, IReadOnlyList1 supportedProtocols, IHubProtocolResolver protocolResolver, IUserIdProvider userIdProvider, Boolean enableDetailedErrors)

All clients are connecting to the app from native iOS Swift app (here it's using the SignalR-Client-Swift) or native Android app. I wanted to log this issue and corelate it with, for example IP address or other request attributes that could. App creator claims that protocol is being sent correctly, but I don't have access to his codebase to make sure of that.
My bet is that someone else is trying to connect to the socket without sending proper payloads.
I've managed to catch info about payload in logs by setting the Verbose level, getting this:

2018-09-12 14:11:03 [Debug] Establishing new connection.
2018-09-12 14:11:03 [Debug] OnConnectedAsync started.
2018-09-12 14:11:03 [Debug] Socket opened using Sub-Protocol: 'null'.
2018-09-12 14:11:03 [Verbose] Message received. Type: Text, size: 32, EndOfMessage: True.
2018-09-12 14:11:03 [Debug] Found protocol implementation for requested protocol: "json".
2018-09-12 14:11:03 [Information] Completed connection handshake. Using HubProtocol '"json"'.

But how do I corelate this to other stuff that's going on in the request?

I've also tried creating a middleware, and got pretty far with it, but unfortunately after "catching" the request that I need, it stops rest of the app from working, since the request is already read and cannot be passed forward to SignalR to work with.

Anyone have any ideas, or maybe you already stumbled upon that issue and managed to fix it somehow? Or maybe this is completely random and I shouldn't worry much about it?

[davidfowl]

A pretty common client bug is allowing the caller to sending before th negotiation has taken place. It might be that the clients returns from start before receiving the handshake response. Or you might be sending before the handshake is complete. The fact that it’s properly parsing a JSON message leads me to believe it’s that issue.

If you turn our logs on the server the way up, you might see what was being sent (though I’m not sure we dump raw bytes)

[davidfowl]

cc @moozzyk

[drajvver]

@davidfowl I've turned the logs all the way up and as you can see, there is this message (no bytes unfortunately)

2018-09-12 14:11:03 [Verbose] Message received. Type: Text, size: 32, EndOfMessage: True.

My guess is that if an error occures this would have size: 0 or something else, but I cannot really turn on such detailed logging on production, since the app has >100k requests per hour.
Over the course of a day and around ~5mil requests the error shows up around 10 to 30 times. This leads me to believe that it isn't anything super important, but if that could be fixed on server side (without disabling this exception in logs that is) that would be amazing.

[davidfowl]

but if that could be fixed on server side (without disabling this exception in logs that is) that would be amazing.

Fix what? Getting the logs? I think we can improve the exception to show the raw payload. That would help diagnose these types of issues. I think there's a client bug. My guess is:

• You're sending a message before the connection is established.
• There's a bug in the client that's causing the above to happen.

The reason it happens so rarely is because the handshake the very first message so this is happening when the initial connection is made.

[drajvver]

No no, I meant the error - I'll try to refactor our OnConnectedAsync method a little bit, so it won't send anything too fast, maybe that indeed is the problem. Thank you for quick responses!

[davidfowl]

No no, I meant the error - I'll try to refactor our OnConnectedAsync method a little bit, so it won't send anything too fast, maybe that indeed is the problem. Thank you for quick responses!

I'm talking about the client code sending data to the server, not the other way around.

[analogrelay]

It looks like this is an issue in the unofficial Swift client you're using (https://github.com/moozzyk/SignalR-Client-Swift, I presume). Looking at the code, it looks like there's definitely a possible race here, since nothing ensures that the handshake is the first message sent. The handshake is sent by connectionDidOpen but I don't see anything that prevents send from being called before connectionDidOpen completes.

[analogrelay]

Closing this as it seems to be external to our repo. Feel free to comment further or open a new issue if something else comes up!

[moozzyk]

I will take a look - opened moozzyk/SignalR-Client-Swift#29 to track this.