git.net

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

[jira] [Comment Edited] (ARIES-1804) Timeout due to connection loss in RSA fastbin provider?


    [ https://issues.apache.org/jira/browse/ARIES-1804?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16498073#comment-16498073 ] 

Alex Weirig edited comment on ARIES-1804 at 6/1/18 2:48 PM:
------------------------------------------------------------

Hi Johannes,

I wrote a scheduled job to test my remote authentication service. The job is run every 5 minutes and this is a normal execution:

2018-06-01T16:00:00,002 | INFO  | Karaf_Worker-3   | job                              | 193 - lu.tlk.administration.services.authentication.job - 0.0.0.201806011221 | AuthenticationServiceJob :: execute :: begin

2018-06-01T16:00:00,003 | INFO  | Karaf_Worker-3   | job                              | 193 - lu.tlk.administration.services.authentication.job - 0.0.0.201806011221 | AuthenticationServiceJob :: execute :: authenticationService = org.apache.aries.rsa.provider.fastbin.tcp.ClientInvokerImpl$ProxyInvocationHandler@1a288b28

*2018-06-01T16:00:00,065 | INFO  | Karaf_Worker-3   | job                              | 193 - lu.tlk.administration.services.authentication.job - 0.0.0.201806011221 | AuthenticationServiceJob :: execute :: authenticateUser = User(userid=awtest, firstname=AW, lastname=Test, whdApiKey=Y1S3nHUdjceVDVMQpQvORVzwTPRuPBO2xW19RLmY, entitlements=[technolink-administration-technician, technolink-administration, technolink-administration-advanced-technician])*

2018-06-01T16:00:00,065 | INFO  | Karaf_Worker-3   | job                              | 193 - lu.tlk.administration.services.authentication.job - 0.0.0.201806011221 | AuthenticationServiceJob :: execute :: end

the bold part is the result from the remote service that connects to our LDAP and authenticates a user. I've created a copy of my user.

 

And then suddenly I get this:

2018-06-01T16:30:00,002 | INFO  | Karaf_Worker-9   | job                              | 193 - lu.tlk.administration.services.authentication.job - 0.0.0.201806011221 | AuthenticationServiceJob :: execute :: begin

2018-06-01T16:30:00,003 | INFO  | Karaf_Worker-9   | job                              | 193 - lu.tlk.administration.services.authentication.job - 0.0.0.201806011221 | AuthenticationServiceJob :: execute :: authenticationService = org.apache.aries.rsa.provider.fastbin.tcp.ClientInvokerImpl$ProxyInvocationHandler@1a288b28

*2018-06-01T16:30:00,004 | ERROR | Karaf_Worker-8   | QuartzScheduler                  | 192 - org.apache.karaf.scheduler.core - 4.2.0 | Exception during job execution of lu.tlk.administration.services.authentication.job.AuthenticationServiceJob@7b91685d : null*

*org.osgi.framework.ServiceException: null*

at org.apache.aries.rsa.provider.fastbin.tcp.ClientInvokerImpl$ProxyInvocationHandler.invoke(ClientInvokerImpl.java:328) ~[?:?]

at com.sun.proxy.$Proxy68.authenticateUser(Unknown Source) ~[?:?]

at lu.tlk.administration.services.authentication.job.AuthenticationServiceJob.execute(AuthenticationServiceJob.java:32) ~[?:?]

at org.apache.karaf.scheduler.core.QuartzJobExecutor.execute(QuartzJobExecutor.java:52) [192:org.apache.karaf.scheduler.core:4.2.0]

at org.quartz.core.JobRunShell.run(JobRunShell.java:202) [192:org.apache.karaf.scheduler.core:4.2.0]

at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573) [192:org.apache.karaf.scheduler.core:4.2.0]

Caused by: java.util.concurrent.TimeoutException

at java.util.concurrent.FutureTask.get(FutureTask.java:205) ~[?:?]

at org.apache.aries.rsa.provider.fastbin.tcp.ClientInvokerImpl.request(ClientInvokerImpl.java:274) ~[?:?]

at org.apache.aries.rsa.provider.fastbin.tcp.ClientInvokerImpl$ProxyInvocationHandler.invoke(ClientInvokerImpl.java:312) ~[?:?]

... 5 more

at  timestamp 2018-06-01T16:30:00,003 it prints the object.toString from the @Reference of the remote service. So the @Reference variable is not null ( org.apache.aries.rsa.provider.fastbin.tcp.ClientInvokerImpl$ProxyInvocationHandler@1a288b28) but when it tries to call that service it produces the message in bold.

And from that point on the authentication is no longer working anymore ...

On my remote karaf I see that the remote service has correctly authenticated the user between the 2 timestamps  2018-06-01T16:30:00,006 and  2018-06-01T16:30:00,008

2018-06-01T16:30:00,006 | INFO  | pool-11-thread-8 | authentication                   | 167 - lu.tlk.administration.services.authentication - 0.0.0.201805090646 | AuthenticationServiceImpl::authenticateUser - userid = awtest

2018-06-01T16:30:00,008 | INFO  | pool-11-thread-8 | ldap                             | 148 - lu.tlk.administration.services.authentication_provider.ldap - 0.0.0.201805090647 | AuthenticationServiceProviderLDAPImpl::authenticateUser - userid = awtest

2018-06-01T16:30:00,008 | INFO  | pool-11-thread-8 | ldap                             | 136 - lu.tlk.common.services.ldap - 0.0.0.201805070851 | TechnolinkLDAPServiceImpl::authenticateUser - ldapDn = uid=awtest,ou=users,ou=accounts,dc=technolink,dc=lu

So why would the remote karaf server not return the value to the calling service?

This is the code in the remote service impl:

@Override

*public* User authenticateUser(*final* String userid, *final* String password) { logService.log(LogService.LOG_INFO, "AuthenticationServiceImpl::authenticateUser - userid = " + userid); 
User authenticateUser = authenticationServiceProvider.authenticateUser(userid, password);
logService.log(LogService.LOG_INFO, "AuthenticationServiceImpl::authenticateUser - authenticateUser = " + authenticateUser);
return authenticateUser;
 }

Any idea is more than welcome because I seem to be blind on the problem?

 

 


was (Author: alexweirig):
Hi Johannes,

I wrote a scheduled job to test my remote authentication service. The job is run every 5 minutes and this is a normal execution:

2018-06-01T16:00:00,002 | INFO  | Karaf_Worker-3   | job                              | 193 - lu.tlk.administration.services.authentication.job - 0.0.0.201806011221 | AuthenticationServiceJob :: execute :: begin

2018-06-01T16:00:00,003 | INFO  | Karaf_Worker-3   | job                              | 193 - lu.tlk.administration.services.authentication.job - 0.0.0.201806011221 | AuthenticationServiceJob :: execute :: authenticationService = org.apache.aries.rsa.provider.fastbin.tcp.ClientInvokerImpl$ProxyInvocationHandler@1a288b28

*2018-06-01T16:00:00,065 | INFO  | Karaf_Worker-3   | job                              | 193 - lu.tlk.administration.services.authentication.job - 0.0.0.201806011221 | AuthenticationServiceJob :: execute :: authenticateUser = User(userid=awtest, firstname=AW, lastname=Test, whdApiKey=Y1S3nHUdjceVDVMQpQvORVzwTPRuPBO2xW19RLmY, entitlements=[technolink-administration-technician, technolink-administration, technolink-administration-advanced-technician])*

2018-06-01T16:00:00,065 | INFO  | Karaf_Worker-3   | job                              | 193 - lu.tlk.administration.services.authentication.job - 0.0.0.201806011221 | AuthenticationServiceJob :: execute :: end

the bold part is the result from the remote service that connects to our LDAP and authenticates a user. I've created a copy of my user.

 

And then suddenly I get this:

2018-06-01T16:30:00,002 | INFO  | Karaf_Worker-9   | job                              | 193 - lu.tlk.administration.services.authentication.job - 0.0.0.201806011221 | AuthenticationServiceJob :: execute :: begin

2018-06-01T16:30:00,003 | INFO  | Karaf_Worker-9   | job                              | 193 - lu.tlk.administration.services.authentication.job - 0.0.0.201806011221 | AuthenticationServiceJob :: execute :: authenticationService = org.apache.aries.rsa.provider.fastbin.tcp.ClientInvokerImpl$ProxyInvocationHandler@1a288b28

*2018-06-01T16:30:00,004 | ERROR | Karaf_Worker-8   | QuartzScheduler                  | 192 - org.apache.karaf.scheduler.core - 4.2.0 | Exception during job execution of lu.tlk.administration.services.authentication.job.AuthenticationServiceJob@7b91685d : null*

*org.osgi.framework.ServiceException: null*

at org.apache.aries.rsa.provider.fastbin.tcp.ClientInvokerImpl$ProxyInvocationHandler.invoke(ClientInvokerImpl.java:328) ~[?:?]

at com.sun.proxy.$Proxy68.authenticateUser(Unknown Source) ~[?:?]

at lu.tlk.administration.services.authentication.job.AuthenticationServiceJob.execute(AuthenticationServiceJob.java:32) ~[?:?]

at org.apache.karaf.scheduler.core.QuartzJobExecutor.execute(QuartzJobExecutor.java:52) [192:org.apache.karaf.scheduler.core:4.2.0]

at org.quartz.core.JobRunShell.run(JobRunShell.java:202) [192:org.apache.karaf.scheduler.core:4.2.0]

at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573) [192:org.apache.karaf.scheduler.core:4.2.0]

Caused by: java.util.concurrent.TimeoutException

at java.util.concurrent.FutureTask.get(FutureTask.java:205) ~[?:?]

at org.apache.aries.rsa.provider.fastbin.tcp.ClientInvokerImpl.request(ClientInvokerImpl.java:274) ~[?:?]

at org.apache.aries.rsa.provider.fastbin.tcp.ClientInvokerImpl$ProxyInvocationHandler.invoke(ClientInvokerImpl.java:312) ~[?:?]

... 5 more

at  timestamp 2018-06-01T16:30:00,003 it prints the object.toString from the @Reference of the remote service. So the @Reference variable is not null ( org.apache.aries.rsa.provider.fastbin.tcp.ClientInvokerImpl$ProxyInvocationHandler@1a288b28) but when it tries to call that service it produces the message in bold.

And from that point on the authentication is no longer working anymore ...

On my remote karaf I see that the remote service has correctly authenticated the user between the 2 timestamps  2018-06-01T16:30:00,006 and  2018-06-01T16:30:00,008

2018-06-01T16:30:00,006 | INFO  | pool-11-thread-8 | authentication                   | 167 - lu.tlk.administration.services.authentication - 0.0.0.201805090646 | AuthenticationServiceImpl::authenticateUser - userid = awtest

2018-06-01T16:30:00,008 | INFO  | pool-11-thread-8 | ldap                             | 148 - lu.tlk.administration.services.authentication_provider.ldap - 0.0.0.201805090647 | AuthenticationServiceProviderLDAPImpl::authenticateUser - userid = awtest

2018-06-01T16:30:00,008 | INFO  | pool-11-thread-8 | ldap                             | 136 - lu.tlk.common.services.ldap - 0.0.0.201805070851 | TechnolinkLDAPServiceImpl::authenticateUser - ldapDn = uid=awtest,ou=users,ou=accounts,dc=technolink,dc=lu

So why would the remote karaf server not return the value to the calling service?

This is the code in the remote service impl:

@Override

*public* User authenticateUser(*final* String userid, *final* String password) {

logService.log(LogService.*_LOG_INFO_*, "AuthenticationServiceImpl::authenticateUser - userid = " + userid);

User authenticateUser = authenticationServiceProvider.authenticateUser(userid, password);

logService.log(LogService.*_LOG_INFO_*, "AuthenticationServiceImpl::authenticateUser - authenticateUser = " + authenticateUser);

*return* authenticateUser;

}

Any idea is more than welcome because I seem to be blind on the problem?

 

 

> Timeout due to connection loss in RSA fastbin provider?
> -------------------------------------------------------
>
>                 Key: ARIES-1804
>                 URL: https://issues.apache.org/jira/browse/ARIES-1804
>             Project: Aries
>          Issue Type: Bug
>          Components: Remote Service Admin
>    Affects Versions: rsa-1.12.0
>         Environment: Karaf 4.2.0
> RSA 1.12.0
> zookeeper 3.4.12
> java 1.8.0_172-b11
> RHEL 7.5
>            Reporter: Alex Weirig
>            Priority: Critical
>         Attachments: AuthenticationServiceImpl.txt, LoginView.txt, stacktrace.txt, zoo.cfg.txt
>
>
> Hello,
> I'm running two karaf (4.2.0) servers, one is running the frontend of my application, the second one is running the backend.
> The backend services are published to 3 clustered zookeeper (3.4.12) servers. In karaf I have deployed the following RSA features:
> karaf@appsrvtlk()> feature:list | grep rsa
> aries-rsa-core │ 1.12.0 │ │ Started │ aries-rsa-1.12.0 │
> aries-rsa-provider-tcp │ 1.12.0 │ │ Uninstalled │ aries-rsa-1.12.0 │
> aries-rsa-provider-fastbin │ 1.12.0 │ x │ Started │ aries-rsa-1.12.0 │
> aries-rsa-discovery-local │ 1.12.0 │ │ Uninstalled │ aries-rsa-1.12.0 │
> aries-rsa-discovery-config │ 1.12.0 │ │ Uninstalled │ aries-rsa-1.12.0 │
> aries-rsa-discovery-zookeeper │ 1.12.0 │ x │ Started │ aries-rsa-1.12.0 │
> aries-rsa-discovery-zookeeper-server │ 1.12.0 │ │ Uninstalled │ aries-rsa-1.12.0 │
> When I start my karaf servers everything is working fine and my frontend can call my backend service and gets the result. But after some time (I can't figure out when) it seems that the connections between the karaf and zookeeper gets lost and I'm getting a timeout when I call my remote service eventhough all the servers (karaf and zookeepers) are still available and responding. Exhibitor shows no apparent issues with the zookeepers.
> I have attached the 
>  * relevant parts of my LoginView UI where I declared the @Reference to my service and where I call the remote service
>  * relevant parts of my AuthenticationService implementation that should be called on the remote karaf
>  * the stacktrace that I'm getting on the frontend karaf when the timeout occurs
>  * my zoo.cfg file
> From the stacktrace one can see that the LoginView has a non-null fastbin proxy handler for the authentication service but that after 5 minutes a timeout occurs and there is no line in the log that shows that the remote service was actually called.
> Many thanks in advance for your support.
> Kind regards,
> Alex



--
This message was sent by Atlassian JIRA
(v7.6.3#76005)