AWS IoT Core disconnects with an AUTHORIZATION_ERROR randomly between 30 seconds and 5 minutes #1729
Labels
question
It is a question regarding the project
Comments
|
Please enable tracing (see samples) and let me know if the client is able to establish a connection with the server. If we are connected and the client tries to send the CONNECT packet the issue might be located at MQTT protocol level. If we never reach this point the problem might be on transport level. Probably it is related to #1698. |
|
Also please try setting the property AllowPacketFragmentation to False in the client options (It is not yet available in the client options builder). |
|
I ran with and without fragmentation. It did not appear to make any difference. Here are the logs: Fragmentation Enabled Log 1Fragmentation Enabled Log 2Fragmentation Disabled Log 1Fragmentation Disabled Log 2 |
|
And this is the log for connecting via certificates without fragmentation. Although I'm personally more interested in getting the above custom authorizer implementation to work correctly as that is what I need to bridge AWS and Microsoft Azure PlayFab. But for completeness in case there is something of interest, here are the logs when attempting to connect via certificates where it disconnects instantly. Fragmentation Disabled Client Certificate Mode |
TCROC
changed the title
|
Whats make me wonder by just having a short view over the logs is that there is the following line (in thje last log):
How can it be that the connection is accepted AND the reason code is "not authorized" at the same time. I will check the code... |
|
I also included some scripts in the project that reproduce the issue by setting up the AWS environment via the aws cli and then run the client. Let me know if you have any issues reproducing it locally. |
|
Which version of the library do you use? |
|
Protocol: 5.0.0 That is the commit tag that I currently have checked out as a submodule. |
|
And the project that I shared just has a single Program.cs file in it for the mqttnet client. I'll copy it in here for ease of reading: using System.Web;
using MQTTnet;
using MQTTnet.Extensions.WebSocket4Net;
using MQTTnet.Formatter;
using MQTTnet.Protocol;
using MQTTnet.Diagnostics;
using MQTTnet.Client;
using System.Net.Security;
using System.Security.Cryptography.X509Certificates;
Console.WriteLine("Running mqtt example application!");
int i = 0;
string username = args[i++];
string password = args[i++];
string endpoint = args[i++];
string rootTopic = args[i++];
string authType = args[i++]; // lambda | cert
string authorizer = args[i++]; // iot authorizer | cert paths (ca,crt,key)
string transportImplementation = args[i++]; // websocket4net | dotnet
string transport = args[i++]; // websocket | tcp
Console.WriteLine($"{Environment.NewLine}==================={Environment.NewLine}");
Console.WriteLine($"Args Used{Environment.NewLine}");
Console.WriteLine($"{nameof(username)}: {username}");
Console.WriteLine($"{nameof(password)}: {password}");
Console.WriteLine($"{nameof(endpoint)}: {endpoint}");
Console.WriteLine($"{nameof(rootTopic)}: {rootTopic}");
Console.WriteLine($"{nameof(authType)}: {authType}");
Console.WriteLine($"{nameof(authorizer)}: {authorizer}");
Console.WriteLine($"{nameof(transportImplementation)}: {transportImplementation}");
Console.WriteLine($"{nameof(transport)}: {transport}");
Console.WriteLine($"{Environment.NewLine}==================={Environment.NewLine}");
var factory = new MqttFactory();
if (transportImplementation == "websocket4net")
{
factory = factory.UseWebSocket4Net();
}
var optionsBuilder = factory.CreateClientOptionsBuilder();
if (transport == "tcp")
{
optionsBuilder = optionsBuilder.WithTcpServer($"{endpoint}", 443);
}
else if (transport == "websocket")
{
optionsBuilder = optionsBuilder.WithWebSocketServer($"{endpoint}/mqtt");
}
if (authType == "lambda")
{
optionsBuilder = optionsBuilder
.WithCredentials($"username?x-amz-customauthorizer-name={HttpUtility.UrlEncode(authorizer)}", password)
.WithTls(
new MqttClientOptionsBuilderTlsParameters
{
UseTls = true,
ApplicationProtocols = new List<SslApplicationProtocol> { new("mqtt") },
}
);
}
else if (authType == "cert")
{
var caCrtKey = authorizer.Split(",");
var caCert = X509Certificate2.CreateFromPem(File.ReadAllText(caCrtKey[0]));
var cert = X509Certificate2.CreateFromPemFile(caCrtKey[1], caCrtKey[2]);
optionsBuilder = optionsBuilder
.WithTls(
new MqttClientOptionsBuilderTlsParameters
{
UseTls = true,
ApplicationProtocols = new List<SslApplicationProtocol> { new("mqtt") },
Certificates = new X509Certificate[]
{
caCert,
cert
},
}
);
}
else
{
throw new Exception($"Invalid {nameof(authType)}: {authType}");
}
var options = optionsBuilder
.WithClientId(username)
.WithWillTopic($"{rootTopic}/s/{username}")
.WithWillRetain(false)
.WithWillPayload(new byte[] { 0 })
.WithWillQualityOfServiceLevel(MqttQualityOfServiceLevel.AtLeastOnce)
.WithProtocolVersion(MqttProtocolVersion.V500)
.WithKeepAlivePeriod(TimeSpan.FromSeconds(35))
.WithoutPacketFragmentation()
.Build();
var logger = new MqttNetEventLogger("MqttNet");
logger.LogMessagePublished += (obj, logArgs) => Console.WriteLine(logArgs.LogMessage.ToString());
var client = factory.CreateMqttClient(logger);
var result = await client.ConnectAsync(options);
int delaySeconds = 10;
while (client.IsConnected)
{
Console.WriteLine($"Client is connected. Checking again in {delaySeconds} seconds...");
await Task.Delay(TimeSpan.FromSeconds(delaySeconds));
} |
|
It turns out that the wrong value in the log is annoying but related to 3.1.1 compatibility. So the "ConnectionAccepted" is wrong and "NotAuthorized" is OK. I am no AWS expert so is it possible to stick to the TCP variant of the console application you posted? Does the problem happen there as well as in any other cases? |
|
Yep, the error occurs in both websocket and tcp. It also occurs in both dotnet's and websocket4net's implementations of websockets and tcp. I can go generate a quick log for that. Ultimately, I'll need to get it working with websockets as the tcp variant only works with dotnet. It does not work in mono (which is required for Unity). But websockets does work in mono. |
|
OK but it seems that every transport is affected somehow. Are you able to compile and run the code on windows with .NET 6 or 7? We had a similar issue with AWS connections which are not working properly but only Mono under Linux was affected. |
Dotnet TCP Certificate LogsDotnet TCP Custom Authorizer Logs |
|
These were both run with dotnet 7 on Linux. I'll go boot up my Windows machine and check quick one sec. |
Windows 10 dotnet 7 TCP Certificate LogsWindows 10 dotnet 7 TCP Custom Authorizer LogsAnd a side note: The git clone command in the README was incorrectly pointing to one of the submodules. I updated it to point to the correct repo. Edit: typo |
|
I am only wild guessing so I made some changes in the branch which is attached to this ticket:
Please use the MyGet feed in order to use this preview build (Link is in README batch). I will post the exact build number as soon as the build is completed. |
|
Also please check the answer from this ticket: #1359 |
|
Awesome. I'll go try out connecting with cert via the answer in the above ticket. I'll keep an eye on this thread for that build number and test it out when its done. |
|
I tried connecting with the cert by exporting to Pkcs12 as recommended in that above ticket. It did not make a difference. var caCrtKey = authorizer.Split(",");
var caCert = new X509Certificate2(X509Certificate2.CreateFromPem(File.ReadAllText(caCrtKey[0])).Export(X509ContentType.Pkcs12));
var cert = new X509Certificate2(X509Certificate2.CreateFromPemFile(caCrtKey[1], caCrtKey[2]).Export(X509ContentType.Pkcs12));logs |
|
Is the quoted code the code you used? Because in the other ticket it uses other constructor as the one you posted. |
|
The version for MyGet is 4.2.1.740 https://www.myget.org/feed/mqttnet/package/nuget/MQTTnet |
|
Good catch. I updated the code to be: var caCrtKey = authorizer.Split(",");
var tempCaText = File.ReadAllText(caCrtKey[0]);
var tempCrtText = File.ReadAllText(caCrtKey[1]);
var tempKeyText = File.ReadAllText(caCrtKey[2]);
var tempCa = new X509Certificate2(X509Certificate2.CreateFromPem(tempCaText));
var tempCrt = X509Certificate2.CreateFromPem(tempCrtText, tempKeyText);
var ca = new X509Certificate2(tempCa.Export(X509ContentType.Pkcs12));
var cert = new X509Certificate2(tempCrt.Export(X509ContentType.Pkcs12));
optionsBuilder = optionsBuilder
.WithTls(
new MqttClientOptionsBuilderTlsParameters
{
UseTls = true,
ApplicationProtocols = new List<SslApplicationProtocol> { new("mqtt") },
Certificates = new X509Certificate[]
{
ca,
cert
},
}
);And got the same result in the logs logs |
|
And I'll try out that myget and let you know what I find |
|
Apart from the certificate stuff I am wondering why the custom authorizer works but out of a sudden disconnects. Are you sending data between these PING packets? Or is the connection Idle? I started a new build which will write the reason string from the DISCONNECT packet to the log. Hopefully AWS tells more details in that field why it decides to disconnect. Do you maybe need to start a re authentication (feature of MQTT 5.0.0) from time to time and it is not happening? Is there something written down in the AWS docs regarding this? |
|
Version 4.2.1.741 is also now available at MyGet. It writes the response string to the log. Hopefully it contains something set by the broker... |
|
The connection is idle. Just sending pingreq every 35 seconds since AWS specifies we can send every 30 seconds here: |
|
And awesome! I'll go try it out with that MyGet build now! |
|
Is this the branch you are currently working on? If so, its actually easier for me to just check this out than use MyGet. I'm currently using this repo as a git submodule and its really easy to check out different branches. |
|
Here are the logs with the custom authorizer: logDisappointingly, the reason string appears to be empty. I'm going to try increasing the ping interval for keep alive but leave the keep alive setting the same and see what happens. |
|
Thanks for posting the example. I have run your code with a test lambda authorizer over WebSockets (Windows 11, .NET 6) and did not encounter any problems. I have not tried TCP. Would you expect the problem to occur in this environment? |
|
Yes I would have expected the problem to occur. How long did your client stay connected? Mine stays connected for anywhere between 30 seconds and 5 minutes. If yours stays connected beyond that (especially say like 10 minutes), this may indicate there is something wrong on my AWS account in particular. In fact, I'll go try creating a different AWS account with a different email and see what happens. Platforms that I've currently tested on: Pop OS (Ubuntu derivative) |
I set it to ping in half the duration of the keep alive period by halfing the keep alive period ticks in MqttClient.cs on line 994: while (!cancellationToken.IsCancellationRequested)
{
// Values described here: [MQTT-3.1.2-24].
var timeWithoutPacketSent = DateTime.UtcNow - _lastPacketSentTimestamp;
if (timeWithoutPacketSent > new TimeSpan(keepAlivePeriod.Ticks / 2))
{
using (var timeoutCancellationTokenSource = CancellationTokenSource.CreateLinkedTokenSource(cancellationToken))
{
timeoutCancellationTokenSource.CancelAfter(Options.Timeout);
await PingAsync(timeoutCancellationTokenSource.Token).ConfigureAwait(false);
}And the disconnect for "NotAuthorized" still occurred: log |
|
I have let the client run for about 15 minutes without issues. This seems to point to the authorizer. Maybe you could test with your test account and an "allow all" authorizer and then re-introduce conditions until the problem occurs, i.e., start with |
|
Is this the policy you used for your test client? The one that has been connected for 15+ minutes? Or did you get it to work with my lambda authorizer in the test project? |
|
Yes, I have used the "allow all" authorizer for the 15 minutes test. I have tried your authorizer as well (with the account identifiers updated) but it failed to connect immediately and I did not investigate further. |
|
Ok cool. I just updated my authorizer to "allow all". 🤞 it stays connected. |
|
Ok I've been connected for 15+ minutes now! This definitely points to an authorizer / policy doc / AWS error. I'm going to narrow down what the offending policy is. Then we will be able to confirm where the issue actually resides. There is still a possibility that mqttnet is interacting with AWS in a way that AWS doesn't expect when more restrictive policies are in place. Which could still be an AWS error, but it will be nice to narrow down. Then I'll contribute back to the aws docs with the findings from this issue as well as updating some things. There are a few parts that are outdated such as .NET's implementation not working (it does now): https://github.com/dotnet/MQTTnet/wiki/Client#connecting-with-amazon-aws |
|
Thank you for the update; that sounds good so far. Please keep us posted with future developments and also if you get it to work with WebSockets and your version of Mono. |
|
np! :) And regarding dotnet and mono experience so far: dotnet 7:
Mono (specifically tested with Unity Game Engine 2021.3.24f1)
Which I was surprised to find that the mono / dotnet implementation didn't work in Unity since Unity supports .NET Standard 2.1 now and .NET Standard 2.1 now has ALPN support: In fact, I'll open up a separate issue for ALPN in Unity along with the certificate error above once we wrap up this policy issue. |
|
Found the offending policy!!! 🥳🎉🎊 ✅ Policy that works{
"isAuthenticated": true,
"principalId": "testid",
"disconnectAfterInSeconds": 86400,
"refreshAfterInSeconds": 86400,
"policyDocuments": [
{
"Version": "2012-10-17",
"Statement": [
{
"Effect": "Allow",
"Action": [
"iot:Connect"
],
"Resource": [
"arn:aws:iot:us-east-1:144868213084:client/${iot:ClientId}"
]
},
{
"Effect": "Allow",
"Action": [
"iot:Receive"
],
"Resource": [
"arn:aws:iot:us-east-1:144868213084:topic/open/*"
]
},
{
"Effect": "Allow",
"Action": [
"iot:Publish"
],
"Resource": [
"arn:aws:iot:us-east-1:144868213084:topic/open/d/*/${iot:ClientId}",
"arn:aws:iot:us-east-1:144868213084:topic/open/p/*/${iot:ClientId}",
"arn:aws:iot:us-east-1:144868213084:topic/open/s/${iot:ClientId}"
]
},
{
"Effect": "Allow",
"Action": [
"iot:Subscribe"
],
"Resource": [
"arn:aws:iot:us-east-1:144868213084:topicfilter/open/d/${iot:ClientId}/*",
"arn:aws:iot:us-east-1:144868213084:topicfilter/open/p/*/*",
"arn:aws:iot:us-east-1:144868213084:topicfilter/open/s/*",
"arn:aws:iot:us-east-1:144868213084:topicfilter/open/f/*"
]
}
]
}
]
}❌ Policy that disconnects randomly between 30 seconds and 5 minutes{
"isAuthenticated": true,
"principalId": "testid",
"disconnectAfterInSeconds": 86400,
"refreshAfterInSeconds": 86400,
"policyDocuments": [
{
"Version": "2012-10-17",
"Statement": [
{
"Effect": "Allow",
"Action": [
"iot:Connect"
],
"Resource": [
"arn:aws:iot:us-east-1:144868213084:client/${iot:ClientId}"
],
"Condition": {
"ArnEquals": {
"iot:LastWillTopic": [
"arn:aws:iot:us-east-1:144868213084:topic/open/s/${iot:ClientId}"
]
}
}
},
{
"Effect": "Allow",
"Action": [
"iot:Receive"
],
"Resource": [
"arn:aws:iot:us-east-1:144868213084:topic/open/*"
]
},
{
"Effect": "Allow",
"Action": [
"iot:Publish"
],
"Resource": [
"arn:aws:iot:us-east-1:144868213084:topic/open/d/*/${iot:ClientId}",
"arn:aws:iot:us-east-1:144868213084:topic/open/p/*/${iot:ClientId}",
"arn:aws:iot:us-east-1:144868213084:topic/open/s/${iot:ClientId}"
]
},
{
"Effect": "Allow",
"Action": [
"iot:Subscribe"
],
"Resource": [
"arn:aws:iot:us-east-1:144868213084:topicfilter/open/d/${iot:ClientId}/*",
"arn:aws:iot:us-east-1:144868213084:topicfilter/open/p/*/*",
"arn:aws:iot:us-east-1:144868213084:topicfilter/open/s/*",
"arn:aws:iot:us-east-1:144868213084:topicfilter/open/f/*"
]
}
]
}
]
}And when comparing the 2 policy documents to each other in VS Code, it shows that the offending policy is the condition requiring a LastWillTopic:
"Condition": {
"ArnEquals": {
"iot:LastWillTopic": [
"arn:aws:iot:us-east-1:144868213084:topic/open/s/${iot:ClientId}"
]
}
}So what do you guys think? Is this potentially an issue on mqttnet's side still? Does something have to be included in the Or do you guys think this is an issue on AWS's side? My client does specify a LastWill topic in the builder: var options = optionsBuilder
.WithClientId(username)
.WithWillTopic($"{rootTopic}/s/{username}")
.WithWillRetain(false)
.WithWillPayload(new byte[] { 0 })
.WithWillQualityOfServiceLevel(MqttQualityOfServiceLevel.AtLeastOnce)
.WithProtocolVersion(MqttProtocolVersion.V500)
.WithKeepAlivePeriod(TimeSpan.FromSeconds(35))
.WithoutPacketFragmentation()
.Build();Also, I'm perfectly fine with not requiring a LastWill topic for my clients. Its more of a "nice to have" and not "mission critical" for my use case. So I feel comfortable going ahead and using the mqttnet client with this ammended policy! :) I'll happily continue debugging with you guys though if you want to dig in further to make sure its not an issue on mqttnet's end. @logicaloud @chkr1011 You have both been amazing to work with on this! Thank you very much! I'll gladly send Microsoft some nice words of my experience with you guys and this project if there is somewhere for me leave such a thing? If not, I hope they see this issue :) Now I'll go open up a couple more issues with my other findings. All of which currently have workarounds. And I'll go contribute back to the docs. |
|
And if you guys are reasonably confident that its an issue on AWS's end, you can feel free to close this issue |
|
Thank you :) I wouldn't mind having another look at the Last Will condition sometime towards the end of the week, so I'd suggest keeping the issue open for a bit longer. |
|
Glad to hear that. I will also create a PR with the changes I made because they are useful for others. |
|
Funny thing, the only problem with the Last Will condition seems to be that the |
|
Yep I noticed that as well. I tried without the array and got the same behavior. Disconnects between 30 seconds and 5 minutes |
|
Can confirm; I just didn't wait long enough. On a hunch, I have added the following condition after the After that, the connection stayed alive. The AWS docs are not really clear about that, at least not those that I have seen. If it works for you then I think the issue is not in MQTTnet and we can close. |
|
Ok cool. I'll be able to test that this weekend. I'll check it out and let you know. |
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
An example project reproducing the issue as well as automating the deploying of AWS resources can be found here: https://github.com/TCROC/aws-iot-custom-auth
And for Windows 10 users who may have issues cross compiling for ARM64 Linux, a precompiled zip is here: https://github.com/TCROC/aws-iot-custom-auth/releases/download/precompiled-arm64-lambda/aws-iot-auth-issues.zip
For ease of reading, I'll copy the README from that project in here as it explains the issue at hand:
README
aws-iot-custom-auth
Dependencies
Tested on Ubuntu 22.04 and Windows 10.
Windows 10 requires WSL Ubuntu 22.04 for cross compiling to ARM64 processors.
git version 2.40.1rustup 1.26.0 (5af9b9484 2023-04-05), cargo 1.69.0 (6e9a83356 2023-04-12), rustc 1.69.0 (84c898d65 2023-04-16)cargo-lambda 0.19.0 (e7a2b99 2023-04-07Z)aws-cli/2.11.15 Python/3.11.3 Linux/6.2.6-76060206-generic exe/x86_64.pop.22 prompt/off7.0.203NOTE: When running the scripts, you can ignore the aws cli errors that are logged. The scripts do things such as check if the lambda function is deployed by calling
aws lambda get-function. If the command errors, the script assumes it doesn't exist in the cloud and attempts to create one.Create Lambda Authorizer
Run in a bash shell:
Create certificate
Run in a bash shell:
Test Lambda Authorizer
Run in a bash shell:
Expected result: The mqtt client sends keep alive packets for 24 hours as specified in the policy returned from the lambda function.
Actual result: The mqtt client is disconnected anywhere between 30 seconds and 5 minutes.
Documentation: https://docs.aws.amazon.com/iot/latest/developerguide/config-custom-auth.html
You can test the response of the authorizer in the console: https://docs.aws.amazon.com/lambda/latest/dg/testing-functions.html
Example test event:
NOTE: The password is
testpasswordbase64 encoded{ "token": "aToken", "signatureVerified": false, "protocols": [ "tls", "http", "mqtt" ], "protocolData": { "tls": { "serverName": "serverName" }, "http": { "headers": { "#{name}": "#{value}" }, "queryString": "?#{name}=#{value}" }, "mqtt": { "username": "test", "password": "dGVzdHBhc3N3b3Jk", "clientId": "testid" } }, "connectionMetadata": { "id": "UUID" } }Example result:
{ "isAuthenticated": true, "principalId": "testid", "disconnectAfterInSeconds": 86400, "refreshAfterInSeconds": 86400, "policyDocuments": [ { "Version": "2012-10-17", "Statement": [ { "Effect": "Allow", "Action": [ "iot:Connect" ], "Resource": [ "arn:aws:iot:us-east-1:144868213084:client/${iot:ClientId}" ], "Condition": { "ArnEquals": { "iot:LastWillTopic": [ "arn:aws:iot:us-east-1:144868213084:topic/open/s/${iot:ClientId}" ] } } }, { "Effect": "Allow", "Action": [ "iot:Receive" ], "Resource": [ "arn:aws:iot:us-east-1:144868213084:topic/open/*" ], "Condition": {} }, { "Effect": "Allow", "Action": [ "iot:Publish" ], "Resource": [ "arn:aws:iot:us-east-1:144868213084:topic/open/d/*/${iot:ClientId}", "arn:aws:iot:us-east-1:144868213084:topic/open/p/*/${iot:ClientId}", "arn:aws:iot:us-east-1:144868213084:topic/open/s/${iot:ClientId}" ], "Condition": {} }, { "Effect": "Allow", "Action": [ "iot:Subscribe" ], "Resource": [ "arn:aws:iot:us-east-1:144868213084:topicfilter/open/d/${iot:ClientId}/*", "arn:aws:iot:us-east-1:144868213084:topicfilter/open/p/*/*", "arn:aws:iot:us-east-1:144868213084:topicfilter/open/s/*", "arn:aws:iot:us-east-1:144868213084:topicfilter/open/f/*" ], "Condition": {} } ] } ] }Test Lambda Certificates
Run in a bash shell:
Expected result: The mqtt authenticates and connects to IoT.
Actual Result: The client is immediately disconnected due to authorization error.
Documentation: https://docs.aws.amazon.com/iot/latest/developerguide/x509-client-certs.html
Cleanup
The lambda functions, authorizers, and certificates in aws will be deleted.
Run in a bash shell:
Other Information
I've tested this in Unity / Mono and dotnet 7 with websocket4net, dotnet, tcp, and websocket transports. The issue reproduces in all of them.
I am also in discussions with AWS on this particular issue. At the moment, we have not been able to narrow down if it is a client side issue with MQTTnet or on AWS's side.
I've been in an email chain with AWS Support and have recently opened up a ticket here: https://repost.aws/questions/QU-cOKeWC1TACCu_LVjS5BWw/iot-custom-authorizer-not-respecting-refreshafterinseconds-or-disconnectafterinseconds-in-returned-policy
I'm hoping we can narrow down on who's end the issue is and get this resolved soon as it is currently holding up the mobile release of our project: https://store.steampowered.com/app/1343040/Blocky_Ball/
We are using IoT with custom authorizers to bridge AWS and Microsoft Azure PlayFab.
If you would like me to organize a debugging session between this team and the AWS team, let me know and I can see if I can pull some people together.
The text was updated successfully, but these errors were encountered: