From issues-return-49476-archive-asf-public=cust-asf.ponee.io@camel.apache.org Tue Feb 13 16:28:10 2018 Return-Path: X-Original-To: archive-asf-public@cust-asf.ponee.io Delivered-To: archive-asf-public@cust-asf.ponee.io Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by mx-eu-01.ponee.io (Postfix) with SMTP id 41CB2180656 for ; Tue, 13 Feb 2018 16:28:09 +0100 (CET) Received: (qmail 27672 invoked by uid 500); 13 Feb 2018 15:28:08 -0000 Mailing-List: contact issues-help@camel.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: dev@camel.apache.org Delivered-To: mailing list issues@camel.apache.org Received: (qmail 27663 invoked by uid 99); 13 Feb 2018 15:28:08 -0000 Received: from pnap-us-west-generic-nat.apache.org (HELO spamd1-us-west.apache.org) (209.188.14.142) by apache.org (qpsmtpd/0.29) with ESMTP; Tue, 13 Feb 2018 15:28:08 +0000 Received: from localhost (localhost [127.0.0.1]) by spamd1-us-west.apache.org (ASF Mail Server at spamd1-us-west.apache.org) with ESMTP id B6D3DC0C94 for ; Tue, 13 Feb 2018 15:28:02 +0000 (UTC) X-Virus-Scanned: Debian amavisd-new at spamd1-us-west.apache.org X-Spam-Flag: NO X-Spam-Score: -109.511 X-Spam-Level: X-Spam-Status: No, score=-109.511 tagged_above=-999 required=6.31 tests=[ENV_AND_HDR_SPF_MATCH=-0.5, KAM_ASCII_DIVIDERS=0.8, RCVD_IN_DNSWL_MED=-2.3, SPF_PASS=-0.001, T_RP_MATCHES_RCVD=-0.01, USER_IN_DEF_SPF_WL=-7.5, USER_IN_WHITELIST=-100] autolearn=disabled Received: from mx1-lw-us.apache.org ([10.40.0.8]) by localhost (spamd1-us-west.apache.org [10.40.0.7]) (amavisd-new, port 10024) with ESMTP id KGkABKPrpCDT for ; Tue, 13 Feb 2018 15:28:01 +0000 (UTC) Received: from mailrelay1-us-west.apache.org (mailrelay1-us-west.apache.org [209.188.14.139]) by mx1-lw-us.apache.org (ASF Mail Server at mx1-lw-us.apache.org) with ESMTP id ED2AC5F3CD for ; Tue, 13 Feb 2018 15:28:00 +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 7916DE0026 for ; Tue, 13 Feb 2018 15:28: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 39AD821E84 for ; Tue, 13 Feb 2018 15:28:00 +0000 (UTC) Date: Tue, 13 Feb 2018 15:28:00 +0000 (UTC) From: "Claus Ibsen (JIRA)" To: issues@camel.apache.org Message-ID: In-Reply-To: References: Subject: [jira] [Updated] (CAMEL-12244) RemoteFileProducer stopped instead of being released to the pool when "interceptSendToEndpoint" is used 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/CAMEL-12244?page=3Dcom.atlassi= an.jira.plugin.system.issuetabpanels:all-tabpanel ] Claus Ibsen updated CAMEL-12244: -------------------------------- Fix Version/s: 2.21.0 > RemoteFileProducer stopped instead of being released to the pool when "in= terceptSendToEndpoint" is used > -------------------------------------------------------------------------= ------------------------------ > > Key: CAMEL-12244 > URL: https://issues.apache.org/jira/browse/CAMEL-12244 > Project: Camel > Issue Type: Bug > Affects Versions: 2.19.0 > Reporter: Krzysztof Szafra=C5=84ski > Priority: Major > Fix For: 2.21.0 > > > In our application we're using an SFTP producer with "fileExist=3DMove" a= nd a specific "moveExisting" expression. I encountered a problem where this= would sometimes work, and sometimes not (i.e. there would be no ".archived= " file). Upon further investigation I found the problem and it seems to be = a bug in Camel. > Our SFTP endpoint looks like this: > {code:none} > sftp://...:.../...?username=3D...&privateKeyPassphrase=3D...&privateKeyFi= le=3D...&useUserKnownHostsFile=3Dfalse&jschLoggingLevel=3DERROR&fileExist= =3DMove&moveExisting=3D${file:name}.archived${date:now:yyyyMMddHHmmssSSS} > {code} > We also have an interceptor: > {code:none} > route.interceptSendToEndpoint("sftp://.*").process(exchange -> LOG.info("= Sending file {} to {}", ...)); > {code} > As I discovered, using the interceptor wraps the RemoteFileProducer with = InterceptSendToEndpoint. This however changes the behavior of the ProducerC= ache: > {code} > public boolean doInAsyncProducer(...) { > ... > return producerCallback.doInAsyncProducer(producer, asyncProcessor, e= xchange, pattern, doneSync -> { > ... > if (producer instanceof ServicePoolAware) { > // release back to the pool > pool.release(endpoint, producer); > } else if (!producer.isSingleton()) { > // stop and shutdown non-singleton producers as we should not= leak resources > try { > ServiceHelper.stopAndShutdownService(producer); > } catch (Exception e) { > ... > } > } > ... > }); > ... > } > {code} > RemoteFileProducer implements ServicePoolAware so it would normally go ba= ck to the pool, but InterceptSendToEndpoint _does not_. As a result, our pr= oducers keep getting stopped (note that RemoteFileProducer#isSingleton alwa= ys returns false). > What's more, somehow they _are_ being reused and in the end we run into s= ituations, where one thread is closing a producer, while another thread is = trying to write with it. > I set up some breakpoints that log the thread name and System#identityHas= hCode of the producer: > {code} > 2018-02-08 15:05:25.070 TRACE o.a.c.c.file.remote.RemoteFileProducer = : Starting producer: RemoteFileProducer[...] > 2018-02-08 15:05:25.073 TRACE o.a.c.c.file.remote.RemoteFileProducer = : Processing file: [my_file] for exchange: ... > 2018-02-08 15:05:25.073 DEBUG o.a.c.c.file.remote.RemoteFileProducer = : Not already connected/logged in. Connecting to: ... > doStop(), time: 1518098725112, thread [Camel (camel-1) thread #35 - Came= lInvocationHandler], producer: 889747012 > =09at org.apache.camel.component.file.remote.RemoteFileProducer.doStop(Re= moteFileProducer.java:175) > =09at org.apache.camel.support.ServiceSupport.stop(ServiceSupport.java:10= 2) > =09at org.apache.camel.util.ServiceHelper.stopService(ServiceHelper.java:= 142) > =09at org.apache.camel.impl.InterceptSendToEndpoint$1.stop(InterceptSendT= oEndpoint.java:196) > =09at org.apache.camel.support.ServiceSupport.shutdown(ServiceSupport.jav= a:164) > =09at org.apache.camel.util.ServiceHelper.stopAndShutdownService(ServiceH= elper.java:211) > =09at org.apache.camel.impl.ProducerCache.lambda$doInAsyncProducer$2(Prod= ucerCache.java:450) > =09at org.apache.camel.processor.SendProcessor$2$1.done(SendProcessor.jav= a:178) > =09at org.apache.camel.impl.InterceptSendToEndpoint$1.process(InterceptSe= ndToEndpoint.java:171) > =09at org.apache.camel.processor.SendProcessor$2.doInAsyncProducer(SendPr= ocessor.java:173) > =09at org.apache.camel.impl.ProducerCache.doInAsyncProducer(ProducerCache= .java:436) > =09at org.apache.camel.processor.SendProcessor.process(SendProcessor.java= :168) > =09at org.apache.camel.management.InstrumentationProcessor.process(Instru= mentationProcessor.java:77) > =09at org.apache.camel.processor.Pipeline.process(Pipeline.java:120) > =09at org.apache.camel.processor.Pipeline.process(Pipeline.java:83) > =09at org.apache.camel.processor.DelegateAsyncProcessor.process(DelegateA= syncProcessor.java:110) > =09at org.apache.camel.processor.RedeliveryErrorHandler.process(Redeliver= yErrorHandler.java:541) > =09at org.apache.camel.processor.CamelInternalProcessor.process(CamelInte= rnalProcessor.java:198) > =09at org.apache.camel.processor.Pipeline.process(Pipeline.java:120) > =09at org.apache.camel.processor.Pipeline.process(Pipeline.java:83) > =09at org.apache.camel.processor.RedeliveryErrorHandler.process(Redeliver= yErrorHandler.java:541) > =09at org.apache.camel.processor.CamelInternalProcessor.process(CamelInte= rnalProcessor.java:198) > =09at org.apache.camel.processor.MulticastProcessor.doProcessSequential(M= ulticastProcessor.java:695) > =09at org.apache.camel.processor.MulticastProcessor.doProcessSequential(M= ulticastProcessor.java:623) > =09at org.apache.camel.processor.MulticastProcessor.process(MulticastProc= essor.java:247) > =09at org.apache.camel.processor.Splitter.process(Splitter.java:114) > =09at org.apache.camel.management.InstrumentationProcessor.process(Instru= mentationProcessor.java:77) > =09at org.apache.camel.processor.Pipeline.process(Pipeline.java:120) > =09at org.apache.camel.processor.Pipeline.process(Pipeline.java:83) > =09at org.apache.camel.processor.DelegateAsyncProcessor.process(DelegateA= syncProcessor.java:110) > =09at org.apache.camel.processor.RedeliveryErrorHandler.process(Redeliver= yErrorHandler.java:541) > =09at org.apache.camel.processor.CamelInternalProcessor.process(CamelInte= rnalProcessor.java:198) > =09at org.apache.camel.processor.CamelInternalProcessor.process(CamelInte= rnalProcessor.java:198) > =09at org.apache.camel.processor.DelegateAsyncProcessor.process(DelegateA= syncProcessor.java:97) > =09at org.apache.camel.component.direct.DirectProducer.process(DirectProd= ucer.java:47) > =09at org.apache.camel.impl.DeferProducer.process(DeferProducer.java:72) > =09at org.apache.camel.component.bean.AbstractCamelInvocationHandler$1.ca= ll(AbstractCamelInvocationHandler.java:192) > =09at java.util.concurrent.FutureTask.run$$$capture(FutureTask.java:266) > =09at java.util.concurrent.FutureTask.run(FutureTask.java) > =09at java.util.concurrent.Executors$RunnableAdapter.call$$$capture(Execu= tors.java:511) > =09at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java) > =09at java.util.concurrent.FutureTask.run$$$capture(FutureTask.java:266) > =09at java.util.concurrent.FutureTask.run(FutureTask.java) > =09at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecuto= r.java:1142) > =09at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecut= or.java:617) > =09at java.lang.Thread.run(Thread.java:748) > 2018-02-08 15:05:25.966 DEBUG o.a.c.c.file.remote.RemoteFileProducer = : Connected and logged in to: ... > 2018-02-08 15:05:25.966 DEBUG o.a.c.c.file.remote.RemoteFileProducer = : Disconnecting from: ... > 2018-02-08 15:05:25.973 TRACE o.a.c.c.file.remote.RemoteFileProducer = : About to write [my_file] to [...] from exchange [...] > 2018-02-08 15:05:25.974 TRACE o.a.c.c.file.remote.RemoteFileProducer = : Stopping producer: RemoteFileProducer[...] > 2018-02-08 15:05:25.974 DEBUG o.a.c.c.file.remote.RemoteFileProducer = : Starting > 2018-02-08 15:05:25.974 TRACE o.a.c.c.file.remote.RemoteFileProducer = : Starting producer: RemoteFileProducer[...] > 2018-02-08 15:05:25.977 TRACE o.a.c.c.file.remote.RemoteFileProducer = : Processing file: [another_file] for exchange: Exchange[...] > 2018-02-08 15:05:25.977 DEBUG o.a.c.c.file.remote.RemoteFileProducer = : Not already connected/logged in. Connecting to: ... > handleFailedWrite(), time: 1518098726072, thread [Camel (camel-1) thread = #37 - CamelInvocationHandler], producer: 889747012 > =09at org.apache.camel.component.file.remote.RemoteFileProducer.handleFai= ledWrite(RemoteFileProducer.java:81) > =09at org.apache.camel.component.file.GenericFileProducer.processExchange= (GenericFileProducer.java:227) > =09at org.apache.camel.component.file.remote.RemoteFileProducer.process(R= emoteFileProducer.java:58) > =09at org.apache.camel.impl.InterceptSendToEndpoint$1.process(InterceptSe= ndToEndpoint.java:167) > =09at org.apache.camel.processor.SendProcessor$2.doInAsyncProducer(SendPr= ocessor.java:173) > =09at org.apache.camel.impl.ProducerCache.doInAsyncProducer(ProducerCache= .java:436) > =09at org.apache.camel.processor.SendProcessor.process(SendProcessor.java= :168) > =09at org.apache.camel.management.InstrumentationProcessor.process(Instru= mentationProcessor.java:77) > =09at org.apache.camel.processor.Pipeline.process(Pipeline.java:120) > =09at org.apache.camel.processor.Pipeline.process(Pipeline.java:83) > =09at org.apache.camel.processor.DelegateAsyncProcessor.process(DelegateA= syncProcessor.java:110) > =09at org.apache.camel.processor.RedeliveryErrorHandler.process(Redeliver= yErrorHandler.java:541) > =09at org.apache.camel.processor.CamelInternalProcessor.process(CamelInte= rnalProcessor.java:198) > =09at org.apache.camel.processor.Pipeline.process(Pipeline.java:120) > =09at org.apache.camel.processor.Pipeline.process(Pipeline.java:83) > =09at org.apache.camel.processor.RedeliveryErrorHandler.process(Redeliver= yErrorHandler.java:541) > =09at org.apache.camel.processor.CamelInternalProcessor.process(CamelInte= rnalProcessor.java:198) > =09at org.apache.camel.processor.MulticastProcessor.doProcessSequential(M= ulticastProcessor.java:695) > =09at org.apache.camel.processor.MulticastProcessor.doProcessSequential(M= ulticastProcessor.java:623) > =09at org.apache.camel.processor.MulticastProcessor.process(MulticastProc= essor.java:247) > =09at org.apache.camel.processor.Splitter.process(Splitter.java:114) > =09at org.apache.camel.management.InstrumentationProcessor.process(Instru= mentationProcessor.java:77) > =09at org.apache.camel.processor.Pipeline.process(Pipeline.java:120) > =09at org.apache.camel.processor.Pipeline.process(Pipeline.java:83) > =09at org.apache.camel.processor.DelegateAsyncProcessor.process(DelegateA= syncProcessor.java:110) > =09at org.apache.camel.processor.RedeliveryErrorHandler.process(Redeliver= yErrorHandler.java:541) > =09at org.apache.camel.processor.CamelInternalProcessor.process(CamelInte= rnalProcessor.java:198) > =09at org.apache.camel.processor.CamelInternalProcessor.process(CamelInte= rnalProcessor.java:198) > =09at org.apache.camel.processor.DelegateAsyncProcessor.process(DelegateA= syncProcessor.java:97) > =09at org.apache.camel.component.direct.DirectProducer.process(DirectProd= ucer.java:47) > =09at org.apache.camel.impl.DeferProducer.process(DeferProducer.java:72) > =09at org.apache.camel.component.bean.AbstractCamelInvocationHandler$1.ca= ll(AbstractCamelInvocationHandler.java:192) > =09at java.util.concurrent.FutureTask.run$$$capture(FutureTask.java:266) > =09at java.util.concurrent.FutureTask.run(FutureTask.java) > =09at java.util.concurrent.Executors$RunnableAdapter.call$$$capture(Execu= tors.java:511) > =09at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java) > =09at java.util.concurrent.FutureTask.run$$$capture(FutureTask.java:266) > =09at java.util.concurrent.FutureTask.run(FutureTask.java) > =09at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecuto= r.java:1142) > =09at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecut= or.java:617) > =09at java.lang.Thread.run(Thread.java:748) > Caused by: org.apache.camel.component.file.GenericFileOperationFailedExce= ption: Cannot change directory to: [my_directory] > =09at org.apache.camel.component.file.remote.SftpOperations.doChangeDirec= tory(SftpOperations.java:596) > =09at org.apache.camel.component.file.remote.SftpOperations.changeCurrent= Directory(SftpOperations.java:584) > =09at org.apache.camel.component.file.remote.SftpOperations.storeFile(Sft= pOperations.java:830) > =09at org.apache.camel.component.file.GenericFileProducer.writeFile(Gener= icFileProducer.java:277) > =09at org.apache.camel.component.file.GenericFileProducer.processExchange= (GenericFileProducer.java:165) > =09... 39 more > Caused by: 4: > =09at com.jcraft.jsch.ChannelSftp.cd(ChannelSftp.java:359) > =09at org.apache.camel.component.file.remote.SftpOperations.doChangeDirec= tory(SftpOperations.java:594) > =09... 43 more > Caused by: java.io.IOException: Pipe closed > =09at java.io.PipedInputStream.read(PipedInputStream.java:307) > =09at com.jcraft.jsch.Channel$MyPipedInputStream.updateReadSide(Channel.j= ava:362) > =09at com.jcraft.jsch.ChannelSftp.cd(ChannelSftp.java:337) > =09... 44 more > 2018-02-08 15:05:26.186 DEBUG o.a.c.c.file.remote.RemoteFileProducer = : Exception occurred during stopping: Cannot change directory to: [my_direc= tory] > {code} > So thread #35 stopped the producer, while thread #37 was trying to use it= . > One more ugly thing about it is that when SftpOperations fail due to a cl= osed pipe, by the time we get to RemoteFileProducer#handleFailedWrite: > {code} > public void handleFailedWrite(...) throws Exception { > ... > if (isStopping() || isStopped()) { > // if we are stopping then ignore any exception during a poll > log.debug("Exception occurred during stopping: " + exception.getM= essage()); > } else { > log.warn("Writing file failed with: " + exception.getMessage()); > ... > throw exception; > } > } > {code} > the producer is already stopped, *so the exception is logged on DEBUG and= not rethrown*. > Note that I'm writing multiple files in parallel (three in my case), I'm = using this to send data to the route ending in the SFTP endpoint: > {code} > @Produce(uri =3D "direct:myDir") > private MyDir myDir; > ... > myDir.sendAsync(...) > {code} > where > {code} > public interface MyDir { > Future sendAsync(...); > } > {code} > We're using Camel 2.19.0, but so far that I've looked at the github repos= itory, the issue is most likely present in the current version too. -- This message was sent by Atlassian JIRA (v7.6.3#76005)