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
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)
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)
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
Best Answer
-
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.
0
Answers
-
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 .
0 -
@wasin.w, 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.
0 -
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.0 -
@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
0 -
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
0 -
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.
0 -
@moragodkrit.chumsri_1 I've requested to unblocked the MachineID. Marko will update you later.
0 -
@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!
0 -
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.
0 -
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
0 -
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.
0 -
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
0 -
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.
0 -
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.
0 -
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.
0 -
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
0 -
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.
0 -
0
-
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.
0 -
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.
0 -
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.
0
Categories
- All Categories
- 3 Polls
- 6 AHS
- 36 Alpha
- 166 App Studio
- 6 Block Chain
- 4 Bot Platform
- 18 Connected Risk APIs
- 47 Data Fusion
- 34 Data Model Discovery
- 684 Datastream
- 1.4K DSS
- 615 Eikon COM
- 5.2K Eikon Data APIs
- 10 Electronic Trading
- Generic FIX
- 7 Local Bank Node API
- 3 Trading API
- 2.9K Elektron
- 1.4K EMA
- 249 ETA
- 554 WebSocket API
- 37 FX Venues
- 14 FX Market Data
- 1 FX Post Trade
- 1 FX Trading - Matching
- 12 FX Trading – RFQ Maker
- 5 Intelligent Tagging
- 2 Legal One
- 23 Messenger Bot
- 3 Messenger Side by Side
- 9 ONESOURCE
- 7 Indirect Tax
- 60 Open Calais
- 275 Open PermID
- 44 Entity Search
- 2 Org ID
- 1 PAM
- PAM - Logging
- 6 Product Insight
- Project Tracking
- ProView
- ProView Internal
- 22 RDMS
- 1.9K Refinitiv Data Platform
- 643 Refinitiv Data Platform Libraries
- 4 LSEG Due Diligence
- LSEG Due Diligence Portal API
- 4 Refinitiv Due Dilligence Centre
- Rose's Space
- 1.2K Screening
- 18 Qual-ID API
- 13 Screening Deployed
- 23 Screening Online
- 12 World-Check Customer Risk Screener
- 1K World-Check One
- 46 World-Check One Zero Footprint
- 45 Side by Side Integration API
- 2 Test Space
- 3 Thomson One Smart
- 10 TR Knowledge Graph
- 151 Transactions
- 143 REDI API
- 1.8K TREP APIs
- 4 CAT
- 26 DACS Station
- 121 Open DACS
- 1.1K RFA
- 104 UPA
- 192 TREP Infrastructure
- 228 TRKD
- 915 TRTH
- 5 Velocity Analytics
- 9 Wealth Management Web Services
- 90 Workspace SDK
- 11 Element Framework
- 5 Grid
- 18 World-Check Data File
- 1 Yield Book Analytics
- 46 中文论坛
