question

Upvotes
Accepted
marko.drews avatar image
43 ●1 ●0 ●2

Rdp session expiry / authentication error

Hi there,


we are having issues with RDP v. 1.0.0-alpha connecting to ERT in the cloud.


Our software was running for some weeks without any issues.

Last week our account got blocked internally by refinitiv, stating a massive burst of requests as the source of failure. (1000* p. 5 min)


I dont see how my code can generate this amount of requests, since my reconnection routine attempts to reconnect only every 10 s.


So Id presume RDP is somehow responsible for this issue.

Please find the log provided by refinitv attached.

It states the issue arises on refreshing the session token, which cant be found.


Does anyone has an idea, whats happening internally and can hint me the way?

Thanks a lot?


The UUID GE-A-01570022-3-2451 is using Password grant on rate 1136 requests per 5 min Total amount of password grants in 5 minutes is 1208


Monitor Check Password grant usage just entered alert status. Please investigate the issue.

- Trigger: More than 1000 in 5m

- Severity: 1

- Period start: 2020-08-02T14:33:33.520Z

- Period end: 2020-08-02T14:35:33.520Z.


And more information, with a couple of the errors logged:


UserId: GE-A-01570022-3-2451

First name: Convex1

Location: A-01570022

CONVEX ENERGY GmbH, 1-8WPGVV1 Berlin, EUREF Campus 6-9, Berlin, Germany

There are a lot of requests hit to on-prem that time and just try from the 1st request which error below before flooded requests started.



8/2/20
2:33:07.641 PM

2020-08-02 14:33:07,641 ERROR [ajp-apr-8280-exec-164] LDAPConnectionManager printErrorResultException [GE-2451] - ResultCode: No Such Entry, DiagnosticMessage: Entry uid=59e94897-ae35-4081-ba52-360c7c610860,rtToken=RefreshTokens,ou=Tokens,dc=reuters,dc=com does not exist in the Directory Server
  • host=dtcp-aaacasv07Options|
  • sourcetype=AAA-AS-CASV-AUTHAPI_customOptions




8/2/20
2:33:07.641 PM

2020-08-02 14:33:07,641 INFO  [ajp-apr-8280-exec-164] HistoricalErrorLogger logHistoricalError [GE-2451] - GrantType::refresh, Id::GE-A-01570022-3-2451, SessionId::null, AppId::67d675e104cc4f1bb6f54c5539faaa8b5bfb16cb, RefreshToken::59e94897-ae35-4081-ba52-360c7c610860, Exception::(name=class com.tr.aaa.as.exception.LDAPException, message=null), HTTP Status::404(Not Found), errorCode::102, errorMessage::Refresh token does not exist.

host=dtcp-aaacasv07Options|

sourcetype=AAA-AS-CASV-AUTHAPI_customOptions




8/2/20
2:33:07.640 PM

2020-08-02 14:33:07,640 ERROR [ajp-apr-8280-exec-40] AuthApiController handleLDAPExceptionException [GE-2451] - LDAPException: code: 404, message: null, errorCode: 102, errorMessage: Refresh token does not exist.
com.tr.aaa.as.exception.LDAPException
at com.tr.aaa.as.service.ldap.LDAPConnectionManager.getRefreshToken(LDAPConnectionManager.java:592)
at com.tr.aaa.as.service.RefreshTokenService.getAuthTokenResponse(RefreshTokenService.java:56)
at com.tr.aaa.as.service.ServiceAction.execute(ServiceAction.java:67)
at com.tr.aaa.as.controller.AuthApiController.authentication(AuthApiController.java:112)
at sun.reflect.GeneratedMethodAccessor182.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:205)
at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:133)
at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:97)
at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:827)
at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:738)
at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:85)
at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:967)
at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:901)
at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:970)
at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:872)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:646)

Show all 43 lines

host=dtcp-aaacasv06Options|

sourcetype=AAA-AS-CASV-AUTHAPI_customOptions




8/2/20
2:33:07.640 PM

2020-08-02 14:33:07,640 INFO  [ajp-apr-8280-exec-40] HistoricalErrorLogger logHistoricalError [GE-2451] - GrantType::refresh, Id::null, SessionId::null, AppId::67d675e104cc4f1bb6f54c5539faaa8b5bfb16cb, RefreshToken::59e94897-ae35-4081-ba52-360c7c610860, Exception::(name=class com.tr.aaa.as.exception.LDAPException, message=null), HTTP Status::404(Not Found), errorCode::102, errorMessage::Refresh token does not exist.

host=dtcp-aaacasv06Options|

sourcetype=AAA-AS-CASV-AUTHAPI_customOptions




8/2/20
2:33:07.633 PM

2020-08-02 14:33:07,633 ERROR [ajp-apr-8280-exec-430] AuthApiController handleRefreshTokenException [GE-2451] - RefreshTokenException code: 401, message: null, errorCode: 106, errorMessage: iPlanet session has been expired.
com.tr.aaa.as.exception.RefreshTokenException
at com.tr.aaa.as.service.RefreshTokenService.getAuthTokenResponse(RefreshTokenService.java:83)
at com.tr.aaa.as.service.ServiceAction.execute(ServiceAction.java:67)
at com.tr.aaa.as.controller.AuthApiController.authentication(AuthApiController.java:112)
at sun.reflect.GeneratedMethodAccessor171.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:205)
at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:133)
at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:97)
at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:827)
at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:738)
at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:85)
at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:967)
at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:901)
at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:970)
at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:872)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:646)
at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:846)

Show all 42 lines

host=dtcp-aaacasv05Options|

sourcetype=AAA-AS-CASV-AUTHAPI_customOptions




8/2/20
2:33:07.632 PM

2020-08-02 14:33:07,632 INFO  [ajp-apr-8280-exec-430] HistoricalErrorLogger logHistoricalError [GE-2451] - GrantType::refresh, Id::GE-A-01570022-3-2451, SessionId::null, AppId::67d675e104cc4f1bb6f54c5539faaa8b5bfb16cb, RefreshToken::59e94897-ae35-4081-ba52-360c7c610860, Exception::(name=class com.tr.aaa.as.exception.RefreshTokenException, message=null)

host=dtcp-aaacasv05Options|

sourcetype=AAA-AS-CASV-AUTHAPI_customOptions


rdp-apirefinitiv-data-platform
icon clock
10 |1500

Up to 2 attachments (including images) can be used with a maximum of 5.0 MiB each and 10.0 MiB total.

14 Answers

Upvotes
Accepted
marko.drews avatar image
43 ●1 ●0 ●2

Hi @nick.zincone.1 ,

Ok i have fully integrated rdp logging into our logstream, so the timestamps are captured as well.

Furthermore, I took down all instances but one. So we have only 1 instance run at the same time.

And I incremented the timer to reconnect to 270sec.

We have to unblock again, to see what happens.

icon clock
10 |1500

Up to 2 attachments (including images) can be used with a maximum of 5.0 MiB each and 10.0 MiB total.

Upvotes
wasin.w avatar image
11.5k ●16 ●7 ●10

Hello @marko.drews

The issue seems relate to the ERT in Cloud authentication-session with RDP Auth Service. I strongly suggest you contact the Elektron Real Time in Cloud support team via my.refinitiv.com web site .

icon clock
10 |1500

Up to 2 attachments (including images) can be used with a maximum of 5.0 MiB each and 10.0 MiB total.

Upvotes
Michael Dirian avatar image
1 ●0 ●0 ●0

@Wasin Waeosri, case was already at the helpdesk #09019537, client assumes that there getting something wrong within the API when sending the refresh token to RDP as his code only trying reconnecting ~10s when connection lost. but from the logs of the AuthGateway there are more than 1k requests per sec.

icon clock
10 |1500

Up to 2 attachments (including images) can be used with a maximum of 5.0 MiB each and 10.0 MiB total.

Upvotes
moragodkrit.chumsri_1 avatar image
7.6k ●15 ●6 ●9

@marko.drews

Are you using RDP Library for .NET?

The Authentication controlled by the library, and I never see the case that it send a bulk request like this before. Note that my app has only one Session object and share it among the app/threads.


Have you turned on a trace log from the Library?

For investigation purposes, you can turn on the logger file by setting below value when creating Session.
Log.Level = NLog.LogLevel.Trace;


RDP Library will generate RDPLog_<pid>.log which contains an incoming and outgoing message that the library sends to the server. It can help us verify the messages sent from the library.

icon clock
10 |1500

Up to 2 attachments (including images) can be used with a maximum of 5.0 MiB each and 10.0 MiB total.

Upvotes
marko.drews avatar image
43 ●1 ●0 ●2

@moragodkrit thanks for the advice. I was looking for the logging facility. Although Im not able the reach the crucial part of the code.

04/08/2020 11:21:53:Session is Pending. (State: Pending)04/08/2020 11:21:54:{

"HTTPStatusCode": 403,

"HTTPReason": "Forbidden",

"Contents": "<html>\r\n<head><title>403 Forbidden</title></head>\r\n<body bgcolor=\"white\">\r\n<center><h1>403 Forbidden</h1></center>\r\n</body>\r\n</html>\r\n"

}. (Event: SessionAuthenticationFailed)04/08/2020 11:21:54:Session is Closed. (State: Closed)


Since our account is blocked again, Ill only get the response that the session authentication failed. There is no massive request generation.

I have a suspicion. My code was trying to open a stream connection, without waiting for the session to be authenticated.

Is it possible that the request flood is produced just then?

I will try to reproduce it, although Im not sure if possible with my blocked account.

Can you guys try this at home pls?

Cheers

icon clock
10 |1500

Up to 2 attachments (including images) can be used with a maximum of 5.0 MiB each and 10.0 MiB total.

Upvotes
marko.drews avatar image
43 ●1 ●0 ●2

here is the extended log:

04/08/2020 11:40:26:Session is Pending. (State: Pending)Application: Debug - Sending HTTP request:

"Method: POST, RequestUri: 'https://api.refinitiv.com/auth/oauth2/v1/token', Version: 1.1, Content: System.Net.Http.FormUrlEncodedContent, Headers:

{

Accept: application/json

Authorization: Basic

Content-Type: application/x-www-form-urlencoded

}"

Application: Debug - HTTP Response: "StatusCode: 403, ReasonPhrase: 'Forbidden', Version: 1.1, Content: System.Net.Http.HttpConnectionResponseContent, Headers:

{

Date: Tue, 04 Aug 2020 09:40:26 GMT

Connection: keep-alive

X-Amzn-Trace-Id: Root=1-5f292d0a-b9e780280cfe0ec8285e4c54

X-Served-By: region=eu-west-1; cid=0079e025-0f01-41ee-b7d1-a382a16438a7

X-Tr-Requestid: 8919cfbe-60c2-43ee-bbac-553738a32a3b

Content-Type: text/html

Content-Length: 134

}"

Application: Warn - RDP Grant Password Authorization failed with Status: "{

"HTTPStatusCode": 403,

"HTTPReason": "Forbidden",

"Contents": "<html>\r\n<head><title>403 Forbidden</title></head>\r\n<body bgcolor=\"white\">\r\n<center><h1>403 Forbidden</h1></center>\r\n</body>\r\n</html>\r\n"

}"

04/08/2020 11:40:26:{

"HTTPStatusCode": 403,

"HTTPReason": "Forbidden",

"Contents": "<html>\r\n<head><title>403 Forbidden</title></head>\r\n<body bgcolor=\"white\">\r\n<center><h1>403 Forbidden</h1></center>\r\n</body>\r\n</html>\r\n"

}. (Event: SessionAuthenticationFailed)04/08/2020 11:40:26:Session is Closed. (State: Closed)Application: Debug - Platform Session State is Closed

icon clock
10 |1500

Up to 2 attachments (including images) can be used with a maximum of 5.0 MiB each and 10.0 MiB total.

Upvotes
moragodkrit.chumsri_1 avatar image
7.6k ●15 ●6 ●9

@marko.drews

It's a very strange behavior. I have a chance to test this scenario previously and found that sending a new item request while the session still not ready does not generate an authenticate problem like this. Not sure can the team re-set your account for now so you test it again? and we can inspect your app behavior from the log file.

icon clock
10 |1500

Up to 2 attachments (including images) can be used with a maximum of 5.0 MiB each and 10.0 MiB total.

Upvotes
Michael Dirian avatar image
1 ●0 ●0 ●0

@moragodkrit I've requested to unblocked the MachineID. Marko will update you later.

icon clock
10 |1500

Up to 2 attachments (including images) can be used with a maximum of 5.0 MiB each and 10.0 MiB total.

Upvotes
marko.drews avatar image
43 ●1 ●0 ●2

@moragodkrit I have changed my code not to attempt to open a stream, if the session is not authenticated. So far it works fine.

Id suggest to investigate this issue further.

Anyway, thanks for your help!

icon clock
10 |1500

Up to 2 attachments (including images) can be used with a maximum of 5.0 MiB each and 10.0 MiB total.

Upvotes
nick.zincone avatar image
9.7k ●49 ●38 ●60

Hi @marko.drews,

The recent logs you have provided are related to your account status. Once that status changes, you should be able to successfully open a session.

What I'm interested in is understanding the original logs you provided. You have included logs for a Java application. Can you please confirm what programming language you are using when utilizing the RDP Library for .NET? You also included some details related to grant refreshes. Who provided these logs? Did you open a ticket with the support desk and they reported they observed a burst of requests for grant refresh tokens?

I want to understand what original event happened that generated all this activity. Did your session close? Do you have the actual RDP log file

RDPLog_<pid>.log

related to the event that started all of this? I want to see what is going on in the libraries/your code that could explain the burst of refresh requests. In this version of the library, if the refresh token fails, it will not automatically retry until another ~270 seconds. If you have defined logic to manage recovery when a session fails to refresh a token, you should ensure you are not doing this every 10 ms - you've mentioned 10s but want to ensure your timer isn't in milliseconds (I've made that unintentional mistake in the past). The RDP logs related to these events should provide some kind of clue.

icon clock
10 |1500

Up to 2 attachments (including images) can be used with a maximum of 5.0 MiB each and 10.0 MiB total.

Upvotes
marko.drews avatar image
43 ●1 ●0 ●2

Hi @nick.zincone.1 ,

Im using RDP dotnet library 1.0.0-alpha. you are correct, those logs are Java. They were provided by refinitiv, serverside logs on my clientcode. There is an open ticket: 09019537 EDP-GW authentication Query [ ref:_00D30602X._5001W1huszH:ref ].

Unfortunately I dont have actual client trace logs, since I just activated rdp logging and the issue did not arise again yet.

Im now waiting for authenticated session before I attempt to open a stream.

My timer was 10s, I double checked it as well ;)

As I understand, you should investigate the instantiation of stream objects.

I had quite a long universe list (24 items), which I pass on object instantiation.


I hope this helps


icon clock
10 |1500

Up to 2 attachments (including images) can be used with a maximum of 5.0 MiB each and 10.0 MiB total.

nick.zincone avatar image nick.zincone

Hi @marko.drews,

Your code does not need to wait for an authenticated session before opening an item stream. What is your understanding of the instantiation of stream objects and what have you observed that needs to be investigated? The issue is your application is sending down a burst of requests to refresh a token and we need to verify why? Perhaps you can provide some code specific to the use of the API so we can understand.

BTW, the log file is on by default. You should have a generated log file - it doesn’t have to be one that has the trace level turned on. Please provide that.

Upvotes
marko.drews avatar image
43 ●1 ●0 ●2

Hi @nick.zincone.1 ,

by instantiation of stream object I mean to create an object of IStreamingPrices, find my factory here:


private IStreamingPrices CreateStreamingPrice(IEnumerable<string> universe, IEnumerable<string> fields = null)

=> Pricing.CreateStreamingPrices(new StreamingPrices.Params()

.Universe(universe)

//.WithFields(fields)

.OnError((o, item, error) => OnError(error))

.OnRefresh((o, item, refresh) => OnRefresh(item, refresh))

.OnUpdate((o, item, update) => OnRefresh(item, update))

.OnStatus((o, item, status) => OnStatus(o, item, status)));


as you can see, Im passing universe, which is a ric list, in my case of length 24.

My guess would be, this triggers the amount of requests.

The Log is turned on, but I had to add a delegate to pass the log output to the app log stream

Log.Output = (loginfo, parms) => Console.WriteLine($"Application: {loginfo.Level} - {loginfo.FormattedMessage}");


Cheers

icon clock
10 |1500

Up to 2 attachments (including images) can be used with a maximum of 5.0 MiB each and 10.0 MiB total.

nick.zincone avatar image nick.zincone

Hi @marko.drews,

The opening of streams does not trigger the request to refresh multiple tokens. The session is the only interface that will send down a request to the RDP servers to refresh tokens. Can you provide the code that sets up your session failure and the code that attempts to recover? Also, why are you intercepting important log messages from the library and sending them to the console? Are you capturing these console messages anywhere to share? If not, you have removed the ability to understand/detect issues within the library.

Upvotes
marko.drews avatar image
43 ●1 ●0 ●2

Hey @nick.zincone.1 ,

We run this app in a cluster. So I had to capture the logs somehow. using the console, the log stream is captured. Please find the log file attached.

logs-from-cnvx-scrapers-reuterselektron-in-cnvx-scrapers-reuterselektron-6c667b5878-x2l4s.txt

You can see there was a disconnect. But the reconnection seems to work now. No blocking encountered yet.


As mentioned earlier, I have changed the code:

private async Task ReconnectAsync()

{

if (_session.OpenState != State.Opened)

await _session.OpenAsync();


if (_session.OpenState != State.Opened)

_logger.LogError("RDP Session was not able to authenticate, last event: {code}\n{event}", _session.LastEventCode, _session.LastEventMessage.Dump());

else

{

if (_streamPricing == null)

_streamPricing = CreateStreamingPrice(_symbolNames, _dataFields);


if (_streamPricing.OpenState == Stream.State.Closed)

await _streamPricing.OpenAsync();


if(_streamPricing.OpenState == Stream.State.Closed)

_logger.LogError("Error opening pricing stream, last event:\n", _session.LastEventMessage.Dump());

}

}

I think its evident now, the streampricing object is responsible for the burst of requests.

Although there was a disconnection and reestablishing of a connection, there was no request burst. I also run multiple instances of the app in the cluster. these instances got killed a few times on purpose to potentially recreate the issue.

The problem for me seems to be solved. I did not experience this issue any more. We are connected.


Please file the log, Im happy to help, if you have further questions.





logs-from-cnvx-scrapers-reuterselektron-in-cnvx-sc.txt (358.4 KiB)
icon clock
10 |1500

Up to 2 attachments (including images) can be used with a maximum of 5.0 MiB each and 10.0 MiB total.

nick.zincone avatar image nick.zincone

Hi @marko.drews,

Thanks for the logs. This is what I was looking for. It would be helpful to add a datetime to the output to confirm exactly when the token refresh is going out.

There are a few things concerning. First, the error message you are getting back when a refresh token occurs. I looked at the times as best as I can and I can see the first one going out at ~12:44:57. The RDP authentication gateway indicates it will timeout after 300 seconds (5 minutes). From the logs, I can see a refresh going out < 12:49:28 (I can't tell because the logs don't echo the times for the lib calls). However, that time is less than 5 minutes, yet the logs indicated the session has expired. I'm trying to figure out why this would happen. You do mention that you are running this app within a cluster. Do you mean you are running the same app, using the same ID, simultaneously? If so, this would be a problem. As far as I'm aware, ID's only allow one login at a time. If you are running multiple apps simultaneously, you are "stealing" the session and this will cause a flip flop of session usages across your cluster and all sorts of problems. At present, the RDP Library for .NET will keep retrying to refresh tokens, even upon failure. However, the next version will not and that clients applications will be responsible for managing session failure and retries.

Upvotes
marko.drews avatar image
43 ●1 ●0 ●2

Hi @nick.zincone.1 ,


ok the trap is placed.

logs-from-cnvx-scrapers-reuterselektron-in-cnvx-scrapers-reuterselektron-8f4b564d8-2r485 (1).txt

pls check the logfile if everything is at place.

Next time the error occurs we can trace it down


logs-from-cnvx-scrapers-reuterselektron-in-cnvx-sc.txt (349.4 KiB)
icon clock
10 |1500

Up to 2 attachments (including images) can be used with a maximum of 5.0 MiB each and 10.0 MiB total.

nick.zincone avatar image nick.zincone

Hi @marko.drews,

The behavior I'm seeing in the logs looks good. So long as you don't start another instance with the same ID, we should not see any errors.

marko.drews avatar image marko.drews

hey @nick.zincone.1 ,

Ok, great!

But multiple instances could not generate the burst of requests, right?


nick.zincone avatar image nick.zincone marko.drews

What multiple instances do is invalidate refresh tokens. So, when the application wishes to refresh the access token, it fails - which is what I saw in the logs from yesterday. This puts all the instances in a cycle where they all fail. What causes the burst of requests is difficult to tell unless I see the logs. Perhaps if you email me your logs from earlier where it created a burst of requests, we may be able to see what is going on. How many instances were you running? I would need to see the logs from all of them.

marko.drews avatar image marko.drews marko.drews

Nah, I didnt capture the logs back then.

I had 3 instances max, although Im almost sure there were only 2 running concurrently. Thats why Im having doubts these bursts had something to do with running multiple instances.

nick.zincone avatar image nick.zincone marko.drews

No worries - let's start fresh from what you have and monitor this going forward now that you have logs showing time and a single instance running.

Click below to post an Idea Post Idea