Service Call slowdown with empty credentials

ServiceStack Authentication
1

Since deploying our most recent service pack, we are encountering some stability issues with the server running at 100%CPU levels sometimes after a few hours and other times a couple of days.

The main changes with our release has been the inclusion of credential and jwt authorization in our micro services.

After trawling log files, event viewers etc I found evidence of a slowdown on service calls where username and password are empty during authentication. Below you will see log files for a number of occurrences of this from the logs.

When username and password are empty, authentication is not hit, it is intercepted with the message below. Any ideas if this could be causing a leak somehow?

{
“ResponseStatus”: {
“ErrorCode”: “ValidationException”,
“Message”: “Validation failed: \r\n – ‘User Name’ should not be empty.\r\n – ‘Password’ should not be empty.”,
“StackTrace”: “[Authenticate: 20/07/2018 9:11:15 AM]:\n[REQUEST: {provider:credentials}]\nServiceStack.FluentValidation.ValidationException: Validation failed: \r\n – ‘User Name’ should not be empty.\r\n – ‘Password’ should not be empty.\r\n at ServiceStack.FluentValidation.DefaultValidatorExtensions.ValidateAndThrow[T](IValidator1 validator, T instance, String ruleSet)\r\n at ServiceStack.Auth.CredentialsAuthProvider.Authenticate(IServiceBase authService, IAuthSession session, Authenticate request)\r\n at ServiceStack.Auth.AuthenticateService.Authenticate(Authenticate request, String provider, IAuthSession session, IAuthProvider oAuthConfig)\r\n at ServiceStack.Auth.AuthenticateService.Post(Authenticate request)\r\n at lambda_method(Closure , Object , Object )\r\n at ServiceStack.Host.ServiceRunner1.d__13.MoveNext()”,
“Errors”: [
{
“ErrorCode”: “NotEmpty”,
“FieldName”: “UserName”,
“Message”: “‘User Name’ should not be empty.”,
“Meta”: {
“PropertyName”: “User Name”
}
},
{
“ErrorCode”: “NotEmpty”,
“FieldName”: “Password”,
“Message”: “‘Password’ should not be empty.”,
“Meta”: {
“PropertyName”: “Password”
}
}
]
}
}

IIS Logs:

Note that service call times (last number in line) increase shortly after each libcurl line

2018-07-18 22:53:57 ::1 GET /accounts/my/e7c6ac96ee1d4b118038e9400c39269a - 9000 - ::1 ServiceStack+.NET+Client+5.02 - 200 0 0 4
2018-07-18 22:53:57 ::1 GET /accounts/my/69f2e7ecbfea4112117b01bd5a70c539 - 9000 - ::1 ServiceStack+.NET+Client+5.02 - 200 0 0 4
2018-07-18 22:53:59 ::1 GET /accounts/my/69f2e7ecbfea4112117b01bd5a70c539 - 9000 - ::1 ServiceStack+.NET+Client+5.02 - 200 0 0 5
2018-07-18 22:54:02 ::1 GET /accounts/my/69f2e7ecbfea4112117b01bd5a70c539 - 9000 - ::1 ServiceStack+.NET+Client+5.02 - 200 0 0 4
2018-07-18 22:54:05 172.31.39.192 GET /authenticate provider=credentials&username=&password=&format=json 443 - 104.180.19.190 libcurl-agent/1.0 - 400 0 0 65
2018-07-18 22:54:09 ::1 GET /accounts/my/69f2e7ecbfea4112117b01bd5a70c539 - 9000 - ::1 ServiceStack+.NET+Client+5.02 - 200 0 0 4
2018-07-18 22:54:13 ::1 GET /accounts/my/69f2e7ecbfea4112117b01bd5a70c539 - 9000 - ::1 ServiceStack+.NET+Client+5.02 - 200 0 0 5
2018-07-18 22:54:15 ::1 GET /accounts/my/69f2e7ecbfea4112117b01bd5a70c539 - 9000 - ::1 ServiceStack+.NET+Client+5.02 - 200 0 0 3
2018-07-18 22:54:18 ::1 GET /accounts/my/69f2e7ecbfea4112117b01bd5a70c539 - 9000 - ::1 ServiceStack+.NET+Client+5.02 - 200 0 0 4
2018-07-18 22:54:28 ::1 GET /accounts/my/69f2e7ecbfea4112117b01bd5a70c539 - 9000 - ::1 ServiceStack+.NET+Client+5.02 - 200 0 0 4
2018-07-18 22:54:30 172.31.39.192 GET /authenticate provider=credentials&username=&password=&format=json 443 - 104.180.19.190 libcurl-agent/1.0 - 400 0 0 59
2018-07-18 22:54:30 ::1 GET /accounts/my/69f2e7ecbfea4112117b01bd5a70c539 - 9000 - ::1 ServiceStack+.NET+Client+5.02 - 200 0 0 4
2018-07-18 22:54:43 ::1 GET /accounts/my/69f2e7ecbfea4112117b01bd5a70c539 - 9000 - ::1 ServiceStack+.NET+Client+5.02 - 200 0 0 441
2018-07-18 22:54:53 ::1 GET /accounts/my/69f2e7ecbfea4112117b01bd5a70c539 - 9000 - ::1 ServiceStack+.NET+Client+5.02 - 200 0 0 472
2018-07-18 22:55:05 ::1 GET /accounts/my/69f2e7ecbfea4112117b01bd5a70c539 - 9000 - ::1 ServiceStack+.NET+Client+5.02 - 200 0 0 571
2018-07-18 22:55:10 ::1 GET /accounts/my/69f2e7ecbfea4112117b01bd5a70c539 - 9000 - ::1 ServiceStack+.NET+Client+5.02 - 200 0 0 576
2018-07-18 22:55:16 ::1 GET /accounts/my/69f2e7ecbfea4112117b01bd5a70c539 - 9000 - ::1 ServiceStack+.NET+Client+5.02 - 200 0 0 571
2018-07-18 22:55:29 ::1 GET /accounts/my/a9acfa6069ec4f50ae237775b5aa3734 - 9000 - ::1 ServiceStack+.NET+Client+5.02 - 200 0 0 586

2018-07-18 22:57:12 ::1 GET /accounts/my/69f2e7ecbfea4112117b01bd5a70c539 - 9000 - ::1 ServiceStack+.NET+Client+5.02 - 200 0 0 495
2018-07-18 22:57:37 ::1 GET /accounts/my/69f2e7ecbfea4112117b01bd5a70c539 - 9000 - ::1 ServiceStack+.NET+Client+5.02 - 200 0 0 489
2018-07-18 22:57:41 ::1 GET /accounts/my/69f2e7ecbfea4112117b01bd5a70c539 - 9000 - ::1 ServiceStack+.NET+Client+5.02 - 200 0 0 574
2018-07-18 22:57:44 ::1 GET /accounts/my/69f2e7ecbfea4112117b01bd5a70c539 - 9000 - ::1 ServiceStack+.NET+Client+5.02 - 200 0 0 479
2018-07-18 22:58:12 ::1 GET /accounts/my/69f2e7ecbfea4112117b01bd5a70c539 - 9000 - ::1 ServiceStack+.NET+Client+5.02 - 200 0 0 518
2018-07-18 22:58:19 ::1 GET /accounts/my/69f2e7ecbfea4112117b01bd5a70c539 - 9000 - ::1 ServiceStack+.NET+Client+5.02 - 200 0 0 382
2018-07-18 22:58:25 ::1 GET /accounts/my/69f2e7ecbfea4112117b01bd5a70c539 - 9000 - ::1 ServiceStack+.NET+Client+5.02 - 200 0 0 470
2018-07-18 22:58:29 ::1 GET /accounts/my/69f2e7ecbfea4112117b01bd5a70c539 - 9000 - ::1 ServiceStack+.NET+Client+5.02 - 200 0 0 383
2018-07-18 22:58:33 172.31.39.192 GET /authenticate provider=credentials&username=&password=&format=json 443 - 104.180.19.190 libcurl-agent/1.0 - 400 0 0 449
2018-07-18 22:58:37 ::1 GET /accounts/my/a9acfa6069ec4f50ae237775b5aa3734 - 9000 - ::1 ServiceStack+.NET+Client+5.02 - 200 0 0 575
2018-07-18 22:58:46 ::1 GET /accounts/my/69f2e7ecbfea4112117b01bd5a70c539 - 9000 - ::1 ServiceStack+.NET+Client+5.02 - 200 0 0 570
2018-07-18 22:58:57 ::1 GET /accounts/my/69f2e7ecbfea4112117b01bd5a70c539 - 9000 - ::1 ServiceStack+.NET+Client+5.02 - 200 0 0 577
2018-07-18 22:59:01 ::1 GET /accounts/my/69f2e7ecbfea4112117b01bd5a70c539 - 9000 - ::1 ServiceStack+.NET+Client+5.02 - 200 0 0 579
2018-07-18 22:59:08 ::1 GET /accounts/my/69f2e7ecbfea4112117b01bd5a70c539 - 9000 - ::1 ServiceStack+.NET+Client+5.02 - 200 0 0 578
2018-07-18 22:59:26 ::1 GET /accounts/my/69f2e7ecbfea4112117b01bd5a70c539 - 9000 - ::1 ServiceStack+.NET+Client+5.02 - 200 0 0 572
2018-07-18 22:59:34 ::1 GET /accounts/my/69f2e7ecbfea4112117b01bd5a70c539 - 9000 - ::1 ServiceStack+.NET+Client+5.02 - 200 0 0 589
2018-07-18 22:59:42 ::1 GET /accounts/my/69f2e7ecbfea4112117b01bd5a70c539 - 9000 - ::1 ServiceStack+.NET+Client+5.02 - 200 0 0 569
2018-07-18 23:00:01 ::1 GET /accounts/my/e7c6ac96ee1d4b77852329400c39269a - 9000 - ::1 ServiceStack+.NET+Client+5.02 - 200 0 0 965
2018-07-18 23:00:06 ::1 GET /accounts/my/69f2e7ecbfea4112117b01bd5a70c539 - 9000 - ::1 ServiceStack+.NET+Client+5.02 - 200 0 0 795
2018-07-18 23:00:11 ::1 GET /accounts/my/69f2e7ecbfea4112117b01bd5a70c539 - 9000 - ::1 ServiceStack+.NET+Client+5.02 - 200 0 0 955
2018-07-18 23:00:24 ::1 GET /accounts/my/69f2e7ecbfea4112117b01bd5a70c539 - 9000 - ::1 ServiceStack+.NET+Client+5.02 - 200 0 0 760
2018-07-18 23:00:42 ::1 GET /accounts/my/69f2e7ecbfea4112117b01bd5a70c539 - 9000 - ::1 ServiceStack+.NET+Client+5.02 - 200 0 0 824
2018-07-18 23:00:52 ::1 GET /accounts/my/69f2e7ecbfea4112117b01bd5a70c539 - 9000 - ::1 ServiceStack+.NET+Client+5.02 - 200 0 0 765
2018-07-18 23:01:01 ::1 GET /accounts/my/69f2e7ecbfea4112117b01bd5a70c539 - 9000 - ::1 ServiceStack+.NET+Client+5.02 - 200 0 0 760
2018-07-18 23:01:07 ::1 GET /accounts/my/69f2e7ecbfea4112117b01bd5a70c539 - 9000 - ::1 ServiceStack+.NET+Client+5.02 - 200 0 0 845
2018-07-18 23:01:09 172.31.39.192 GET /authenticate provider=credentials&username=&password=&format=json 443 - 104.180.19.190 libcurl-agent/1.0 - 400 0 0 914
2018-07-18 23:01:22 ::1 GET /accounts/my/69f2e7ecbfea4112117b01bd5a70c539 - 9000 - ::1 ServiceStack+.NET+Client+5.02 - 200 0 0 1157
2018-07-18 23:01:34 ::1 GET /accounts/my/69f2e7ecbfea4112117b01bd5a70c539 - 9000 - ::1 ServiceStack+.NET+Client+5.02 - 200 0 0 1187
2018-07-18 23:01:41 ::1 GET /accounts/my/69f2e7ecbfea4112117b01bd5a70c539 - 9000 - ::1 ServiceStack+.NET+Client+5.02 - 200 0 0 1143
2018-07-18 23:01:53 ::1 GET /accounts/my/69f2e7ecbfea4112117b01bd5a70c539 - 9000 - ::1 ServiceStack+.NET+Client+5.02 - 200 0 0 1138
2018-07-18 23:02:08 ::1 GET /accounts/my/69f2e7ecbfea4112117b01bd5a70c539 - 9000 - ::1 ServiceStack+.NET+Client+5.02 - 200 0 0 1373

AFTER REBOOT OF WEB SERVICES

2018-07-18 23:28:02 ::1 GET /accounts/my/69f2e7ecbfea4112117b01bd5a70c539 - 9000 - ::1 ServiceStack+.NET+Client+5.02 - 200 0 0 5
2018-07-18 23:28:03 ::1 GET /accounts/my/69f2e7ecbfea4112117b01bd5a70c539 - 9000 - ::1 ServiceStack+.NET+Client+5.02 - 200 0 0 5
2018-07-18 23:28:14 ::1 GET /accounts/my/69f2e7ecbfea4112117b01bd5a70c539 - 9000 - ::1 ServiceStack+.NET+Client+5.02 - 200 0 0 4
2018-07-18 23:28:17 ::1 GET /accounts/my/69f2e7ecbfea4112117b01bd5a70c539 - 9000 - ::1 ServiceStack+.NET+Client+5.02 - 200 0 0 4
2018-07-18 23:28:18 ::1 GET /accounts/my/69f2e7ecbfea4112117b01bd5a70c539 - 9000 - ::1 ServiceStack+.NET+Client+5.02 - 200 0 0 5
2018-07-18 23:28:24 172.31.39.192 GET /authenticate provider=credentials&username=&password=&format=json 443 - 104.180.19.190 libcurl-agent/1.0 - 400 0 0 120
2018-07-18 23:28:29 ::1 GET /accounts/my/69f2e7ecbfea4112117b01bd5a70c539 - 9000 - ::1 ServiceStack+.NET+Client+5.02 - 200 0 0 6
2018-07-18 23:28:33 ::1 GET /accounts/my/69f2e7ecbfea4112117b01bd5a70c539 - 9000 - ::1 ServiceStack+.NET+Client+5.02 - 200 0 0 5
2018-07-18 23:28:35 ::1 GET /accounts/my/69f2e7ecbfea4112117b01bd5a70c539 - 9000 - ::1 ServiceStack+.NET+Client+5.02 - 200 0 0 4
2018-07-18 23:28:35 172.31.39.192 GET /authenticate provider=credentials&username=&password=&format=json 443 - 104.180.19.190 libcurl-agent/1.0 - 400 0 0 76
2018-07-18 23:28:47 ::1 GET /accounts/my/69f2e7ecbfea4112117b01bd5a70c539 - 9000 - ::1 ServiceStack+.NET+Client+5.02 - 200 0 0 572
2018-07-18 23:28:58 ::1 GET /accounts/my/69f2e7ecbfea4112117b01bd5a70c539 - 9000 - ::1 ServiceStack+.NET+Client+5.02 - 200 0 0 384
2018-07-18 23:29:04 ::1 GET /accounts/my/69f2e7ecbfea4112117b01bd5a70c539 - 9000 - ::1 ServiceStack+.NET+Client+5.02 - 200 0 0 547
2018-07-18 23:29:09 ::1 GET /accounts/my/69f2e7ecbfea4112117b01bd5a70c539 - 9000 - ::1 ServiceStack+.NET+Client+5.02 - 200 0 0 554
2018-07-18 23:29:23 ::1 GET /accounts/my/69f2e7ecbfea4112117b01bd5a70c539 - 9000 - ::1 ServiceStack+.NET+Client+5.02 - 200 0 0 578
2018-07-18 23:29:27 ::1 GET /accounts/my/a9acfa6069ec4f50ae237775b5aa3734 - 9000 - ::1 ServiceStack+.NET+Client+5.02 - 200 0 0 587
2018-07-18 23:29:30 ::1 GET /accounts/my/69f2e7ecbfea4112117b01bd5a70c539 - 9000 - ::1 ServiceStack+.NET+Client+5.02 - 200 0 0 579
2

You have something making this request which is trying to authenticate with no username or password:

/authenticate provider=credentials&username=&password=&format=json

It appears the UserAgent used in this request is libcurl-agent/1.0

This is unrelated to JWT.

3

Yes that line is indeed the trigger for the fault, as mentioned above. This is a standard authenticate call with credentials although I am using custom credentials approach.

Indeed, an attempt to authenticate with no username and no password is erroneous, but the problem here is that the request is intercepted by built-in handling which in turn causes the service to become unstable, increasing call times from that point onwards.

I guess I can override more sections of the CredentialsAuthProvider, to prevent whatever is causing the slow down, but something is not correct here under the hood as the log times show.

4

Whatever it is we’d need to be able to reproduce the issue with a stand-alone repro in order to be able to identify the issue.

If you’re able to profile it, it should hopefully show where the time is being spent and if the slowdown is due to a memory leak.

5

I’ll see if I can create a standalone example of the fault. Ill come back to you.

6

Hi Mythz, my apologies.

It appears the issue was indeed a memory leak, but not in service-stack, but another 3rd party component. I am unsure why the pattern occurred in the logs during authentication, I guess as the default auth handler was creating new response objects and doing some serialization.

I think this issue ticket should be removed, so it does not reflect poorly on service-stack

7

Great glad you were able to identify the issue.

This thread doesn’t reflect poorly on ServiceStack, it highlights the importance of analysis and profiling to isolate and determine where the actual issue is, which is an important approach for others to follow when faced with similar issues.

8

As you pointed out, I agree that analysis and profiling is vital to determine root cause. In this particular case, all analysis did point to ServiceStack, it would be good to have a mechanism to determine otherwise. While the service stack mini profiler seems good for MVC, is there a way to profile the memory usage of the microservice call stack?

9

My preferred Memory profiler for .NET Apps is dotMemory by JetBrains:

1 Like
10

Thanks, good to know. I use JetBrains ReSharper but have not used dotMemory, will give it a try.

11

The update on this issue is that I’ve profiled memory leaks away they are good now as far as I can tell. Slow queries have also been dealt with.

Currently every 2-3 days one of our (the highest loaded one) micro services suddenly jumps from 5% cpu to 100% cpu and stays there.

No exceptions in any logs, no increase in traffic volumes, nothing in event viewer.

The micro service uses ormlite for mysql and the service occassionally queues a redis queue item.

Still trying to find a way to determine what is failing, but if you have any thoughts or suggestions I would appreciate it.

Service is running on 5.1.1 as of ~June 6th