[
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)
