From dev-return-20001-apmail-aries-dev-archive=aries.apache.org@aries.apache.org Fri Jun 1 14:44:05 2018 Return-Path: X-Original-To: apmail-aries-dev-archive@www.apache.org Delivered-To: apmail-aries-dev-archive@www.apache.org Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by minotaur.apache.org (Postfix) with SMTP id 0F9E617D6B for ; Fri, 1 Jun 2018 14:44:05 +0000 (UTC) Received: (qmail 75765 invoked by uid 500); 1 Jun 2018 14:44:05 -0000 Delivered-To: apmail-aries-dev-archive@aries.apache.org Received: (qmail 75716 invoked by uid 500); 1 Jun 2018 14:44:04 -0000 Mailing-List: contact dev-help@aries.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: dev@aries.apache.org Delivered-To: mailing list dev@aries.apache.org Received: (qmail 75705 invoked by uid 99); 1 Jun 2018 14:44:04 -0000 Received: from pnap-us-west-generic-nat.apache.org (HELO spamd2-us-west.apache.org) (209.188.14.142) by apache.org (qpsmtpd/0.29) with ESMTP; Fri, 01 Jun 2018 14:44:04 +0000 Received: from localhost (localhost [127.0.0.1]) by spamd2-us-west.apache.org (ASF Mail Server at spamd2-us-west.apache.org) with ESMTP id 802121A2BFB for ; Fri, 1 Jun 2018 14:44:04 +0000 (UTC) X-Virus-Scanned: Debian amavisd-new at spamd2-us-west.apache.org X-Spam-Flag: NO X-Spam-Score: -110.301 X-Spam-Level: X-Spam-Status: No, score=-110.301 tagged_above=-999 required=6.31 tests=[ENV_AND_HDR_SPF_MATCH=-0.5, RCVD_IN_DNSWL_MED=-2.3, SPF_PASS=-0.001, USER_IN_DEF_SPF_WL=-7.5, USER_IN_WHITELIST=-100] autolearn=disabled Received: from mx1-lw-eu.apache.org ([10.40.0.8]) by localhost (spamd2-us-west.apache.org [10.40.0.9]) (amavisd-new, port 10024) with ESMTP id bLJmlAPeUalu for ; Fri, 1 Jun 2018 14:44:02 +0000 (UTC) Received: from mailrelay1-us-west.apache.org (mailrelay1-us-west.apache.org [209.188.14.139]) by mx1-lw-eu.apache.org (ASF Mail Server at mx1-lw-eu.apache.org) with ESMTP id 989685F51F for ; Fri, 1 Jun 2018 14:44:01 +0000 (UTC) Received: from jira-lw-us.apache.org (unknown [207.244.88.139]) by mailrelay1-us-west.apache.org (ASF Mail Server at mailrelay1-us-west.apache.org) with ESMTP id 9FF5FE0110 for ; Fri, 1 Jun 2018 14:44:00 +0000 (UTC) Received: from jira-lw-us.apache.org (localhost [127.0.0.1]) by jira-lw-us.apache.org (ASF Mail Server at jira-lw-us.apache.org) with ESMTP id 1A72B21092 for ; Fri, 1 Jun 2018 14:44:00 +0000 (UTC) Date: Fri, 1 Jun 2018 14:44:00 +0000 (UTC) From: "Alex Weirig (JIRA)" To: dev@aries.apache.org Message-ID: In-Reply-To: References: Subject: [jira] [Commented] (ARIES-1804) Timeout due to connection loss in RSA fastbin provider? MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: quoted-printable X-JIRA-FingerPrint: 30527f35849b9dde25b450d4833f0394 [ https://issues.apache.org/jira/browse/ARIES-1804?page=3Dcom.atlassian= .jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=3D1649= 8073#comment-16498073 ]=20 Alex Weirig commented on ARIES-1804: ------------------------------------ Hi Johannes, I wrote a scheduled job to test my remote authentication service. The job i= s run every 5 minutes and this is a normal execution: 2018-06-01T16:00:00,002 | INFO=C2=A0 | Karaf_Worker-3 =C2=A0 | job=C2=A0 = =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2= =A0 =C2=A0 =C2=A0 =C2=A0 | 193 - lu.tlk.administration.services.authenticat= ion.job - 0.0.0.201806011221 | AuthenticationServiceJob :: execute :: begin 2018-06-01T16:00:00,003 | INFO=C2=A0 | Karaf_Worker-3 =C2=A0 | job=C2=A0 = =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2= =A0 =C2=A0 =C2=A0 =C2=A0 | 193 - lu.tlk.administration.services.authenticat= ion.job - 0.0.0.201806011221 | AuthenticationServiceJob :: execute :: authe= nticationService =3D org.apache.aries.rsa.provider.fastbin.tcp.ClientInvoke= rImpl$ProxyInvocationHandler@1a288b28 *2018-06-01T16:00:00,065 | INFO=C2=A0 | Karaf_Worker-3 =C2=A0 | job=C2=A0 = =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2= =A0 =C2=A0 =C2=A0 =C2=A0 | 193 - lu.tlk.administration.services.authenticat= ion.job - 0.0.0.201806011221 | AuthenticationServiceJob :: execute :: authe= nticateUser =3D User(userid=3Dawtest, firstname=3DAW, lastname=3DTest, whdA= piKey=3DY1S3nHUdjceVDVMQpQvORVzwTPRuPBO2xW19RLmY, entitlements=3D[technolin= k-administration-technician, technolink-administration, technolink-administ= ration-advanced-technician])* 2018-06-01T16:00:00,065 | INFO=C2=A0 | Karaf_Worker-3 =C2=A0 | job=C2=A0 = =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2= =A0 =C2=A0 =C2=A0 =C2=A0 | 193 - lu.tlk.administration.services.authenticat= ion.job - 0.0.0.201806011221 | AuthenticationServiceJob :: execute :: end the bold part is the result from the remote service that connects to our LD= AP and authenticates a user. I've created a copy of my user. =C2=A0 And then suddenly I get this: 2018-06-01T16:30:00,002 | INFO=C2=A0 | Karaf_Worker-9 =C2=A0 | job=C2=A0 = =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2= =A0 =C2=A0 =C2=A0 =C2=A0 | 193 - lu.tlk.administration.services.authenticat= ion.job - 0.0.0.201806011221 | AuthenticationServiceJob :: execute :: begin 2018-06-01T16:30:00,003 | INFO=C2=A0 | Karaf_Worker-9 =C2=A0 | job=C2=A0 = =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2= =A0 =C2=A0 =C2=A0 =C2=A0 | 193 - lu.tlk.administration.services.authenticat= ion.job - 0.0.0.201806011221 | AuthenticationServiceJob :: execute :: authe= nticationService =3D org.apache.aries.rsa.provider.fastbin.tcp.ClientInvoke= rImpl$ProxyInvocationHandler@1a288b28 *2018-06-01T16:30:00,004 | ERROR | Karaf_Worker-8 =C2=A0 | QuartzScheduler= =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 | 192 - org.= apache.karaf.scheduler.core - 4.2.0 | Exception during job execution of lu.= tlk.administration.services.authentication.job.AuthenticationServiceJob@7b9= 1685d : null* *org.osgi.framework.ServiceException: null* at org.apache.aries.rsa.provider.fastbin.tcp.ClientInvokerImpl$ProxyInvocat= ionHandler.invoke(ClientInvokerImpl.java:328) ~[?:?] at com.sun.proxy.$Proxy68.authenticateUser(Unknown Source) ~[?:?] at lu.tlk.administration.services.authentication.job.AuthenticationServiceJ= ob.execute(AuthenticationServiceJob.java:32) ~[?:?] at org.apache.karaf.scheduler.core.QuartzJobExecutor.execute(QuartzJobExecu= tor.java:52) [192:org.apache.karaf.scheduler.core:4.2.0] at org.quartz.core.JobRunShell.run(JobRunShell.java:202) [192:org.apache.ka= raf.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(Clie= ntInvokerImpl.java:274) ~[?:?] at org.apache.aries.rsa.provider.fastbin.tcp.ClientInvokerImpl$ProxyInvocat= ionHandler.invoke(ClientInvokerImpl.java:312) ~[?:?] ... 5 more at=C2=A0=C2=A0timestamp 2018-06-01T16:30:00,003 it prints the object.toStri= ng from the @Reference of the remote service. So the @Reference variable is= not null ( org.apache.aries.rsa.provider.fastbin.tcp.ClientInvokerImpl$Pro= xyInvocationHandler@1a288b28) but when it tries to call that service it pro= duces 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 authenticate= d the user between the 2 timestamps=C2=A0 2018-06-01T16:30:00,006 and=C2=A0= 2018-06-01T16:30:00,008 2018-06-01T16:30:00,006 | INFO=C2=A0 | pool-11-thread-8 | authentication = =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 | 167 - lu.t= lk.administration.services.authentication - 0.0.0.201805090646 | Authentica= tionServiceImpl::authenticateUser - userid =3D awtest 2018-06-01T16:30:00,008 | INFO=C2=A0 | pool-11-thread-8 | ldap =C2=A0 =C2= =A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 = =C2=A0 =C2=A0 | 148 - lu.tlk.administration.services.authentication_provide= r.ldap - 0.0.0.201805090647 | AuthenticationServiceProviderLDAPImpl::authen= ticateUser - userid =3D awtest 2018-06-01T16:30:00,008 | INFO=C2=A0 | pool-11-thread-8 | ldap =C2=A0 =C2= =A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 = =C2=A0 =C2=A0 | 136 - lu.tlk.common.services.ldap - 0.0.0.201805070851 | Te= chnolinkLDAPServiceImpl::authenticateUser - ldapDn =3D uid=3Dawtest,ou=3Dus= ers,ou=3Daccounts,dc=3Dtechnolink,dc=3Dlu So why would the remote karaf server not return the value to the calling se= rvice? This is the code in the remote service impl: @Override *public* User authenticateUser(*final* String userid, *final* String passwo= rd) { logService.log(LogService.*_LOG_INFO_*, "AuthenticationServiceImpl::authent= icateUser - userid =3D " + userid); User authenticateUser =3D authenticationServiceProvider.authenticateUser(us= erid, password); logService.log(LogService.*_LOG_INFO_*, "AuthenticationServiceImpl::authent= icateUser - authenticateUser =3D " + authenticateUser); *return* authenticateUser; } Any idea is more than welcome because I seem to be blind on the problem? =C2=A0 =C2=A0 > 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, stackt= race.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) serv= ers. In karaf I have deployed the following RSA features: > karaf@appsrvtlk()> feature:list | grep rsa > aries-rsa-core =E2=94=82 1.12.0 =E2=94=82 =E2=94=82 Started =E2=94=82 ari= es-rsa-1.12.0 =E2=94=82 > aries-rsa-provider-tcp =E2=94=82 1.12.0 =E2=94=82 =E2=94=82 Uninstalled = =E2=94=82 aries-rsa-1.12.0 =E2=94=82 > aries-rsa-provider-fastbin =E2=94=82 1.12.0 =E2=94=82 x =E2=94=82 Started= =E2=94=82 aries-rsa-1.12.0 =E2=94=82 > aries-rsa-discovery-local =E2=94=82 1.12.0 =E2=94=82 =E2=94=82 Uninstalle= d =E2=94=82 aries-rsa-1.12.0 =E2=94=82 > aries-rsa-discovery-config =E2=94=82 1.12.0 =E2=94=82 =E2=94=82 Uninstall= ed =E2=94=82 aries-rsa-1.12.0 =E2=94=82 > aries-rsa-discovery-zookeeper =E2=94=82 1.12.0 =E2=94=82 x =E2=94=82 Star= ted =E2=94=82 aries-rsa-1.12.0 =E2=94=82 > aries-rsa-discovery-zookeeper-server =E2=94=82 1.12.0 =E2=94=82 =E2=94=82= Uninstalled =E2=94=82 aries-rsa-1.12.0 =E2=94=82 > 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 zoo= keeper gets lost and I'm getting a timeout when I call my remote service ev= enthough all the servers (karaf and zookeepers) are still available and res= ponding. Exhibitor shows no apparent issues with the zookeepers. > I have attached the=C2=A0 > * relevant parts of my LoginView UI where I declared the @Reference to m= y 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 ti= meout occurs and there is no line in the log that shows that the remote ser= vice was actually called. > Many thanks in advance for your support. > Kind regards, > Alex -- This message was sent by Atlassian JIRA (v7.6.3#76005)