System background: Windows/ServiceMix/Camel/Smooks
I have a Camel route
<camel:camelContext id="customsContext" xmlns="http://camel.apache.org/schema/spring">
<camel:route>
<camel:from uri="file://C:\Camel\?delay=2000"/>
<camel:convertBodyTo type="javax.xml.transform.stream.StreamSource"/>
<camel:to uri="smooks:smooks-config.xml"/>
</camel:route>
</camel:camelContext>
which is supposed to pick up a file and stream it to a Smooks custom EDI parser. This works up to the point that Camel copy's the file to the moveNamePrefix directory and then tries to delete the original, when it throws an exception. Since the file is never cleaned up this repeats indefinitely.
2014-06-04 23:43:47,331 | WARN | ://C:%5CCamel%5C | GenericFileOnCompletion | ? ? | 110 - org.apache.camel.camel-core - 2.12.3 | Error during commit. Exchange[Message: [Body is null]]. Caused by: [org.apache.camel.component.file.GenericFileOperationFailedException - Error renaming file from C:\Camel\edi-input.txt to C:\Camel\.camel\edi-input.txt]
org.apache.camel.component.file.GenericFileOperationFailedException: Error renaming file from C:\Camel\edi-input.txt to C:\Camel\.camel\edi-input.txt
at org.apache.camel.component.file.FileOperations.renameFile(FileOperations.java:72)[110:org.apache.camel.camel-core:2.12.3]
at org.apache.camel.component.file.strategy.GenericFileProcessStrategySupport.renameFile(GenericFileProcessStrategySupport.java:113)[110:org.apache.camel.camel-core:2.12.3]
at org.apache.camel.component.file.strategy.GenericFileRenameProcessStrategy.commit(GenericFileRenameProcessStrategy.java:88)[110:org.apache.camel.camel-core:2.12.3]
at org.apache.camel.component.file.GenericFileOnCompletion.processStrategyCommit(GenericFileOnCompletion.java:124)[110:org.apache.camel.camel-core:2.12.3]
at org.apache.camel.component.file.GenericFileOnCompletion.onCompletion(GenericFileOnCompletion.java:80)[110:org.apache.camel.camel-core:2.12.3]
at org.apache.camel.component.file.GenericFileOnCompletion.onComplete(GenericFileOnCompletion.java:54)[110:org.apache.camel.camel-core:2.12.3]
at org.apache.camel.util.UnitOfWorkHelper.doneSynchronizations(UnitOfWorkHelper.java:100)[110:org.apache.camel.camel-core:2.12.3]
at org.apache.camel.impl.DefaultUnitOfWork.done(DefaultUnitOfWork.java:228)[110:org.apache.camel.camel-core:2.12.3]
at org.apache.camel.util.UnitOfWorkHelper.doneUow(UnitOfWorkHelper.java:61)[110:org.apache.camel.camel-core:2.12.3]
at org.apache.camel.processor.CamelInternalProcessor$UnitOfWorkProcessorAdvice.after(CamelInternalProcessor.java:613)[110:org.apache.camel.camel-core:2.12.3]
at org.apache.camel.processor.CamelInternalProcessor$UnitOfWorkProcessorAdvice.after(CamelInternalProcessor.java:581)[110:org.apache.camel.camel-core:2.12.3]
at org.apache.camel.processor.CamelInternalProcessor$InternalCallback.done(CamelInternalProcessor.java:240)[110:org.apache.camel.camel-core:2.12.3]
at org.apache.camel.processor.Pipeline.process(Pipeline.java:106)[110:org.apache.camel.camel-core:2.12.3]
at org.apache.camel.processor.CamelInternalProcessor.process(CamelInternalProcessor.java:191)[110:org.apache.camel.camel-core:2.12.3]
at org.apache.camel.component.file.GenericFileConsumer.processExchange(GenericFileConsumer.java:401)[110:org.apache.camel.camel-core:2.12.3]
at org.apache.camel.component.file.GenericFileConsumer.processBatch(GenericFileConsumer.java:201)[110:org.apache.camel.camel-core:2.12.3]
at org.apache.camel.component.file.GenericFileConsumer.poll(GenericFileConsumer.java:165)[110:org.apache.camel.camel-core:2.12.3]
at org.apache.camel.impl.ScheduledPollConsumer.doRun(ScheduledPollConsumer.java:187)[110:org.apache.camel.camel-core:2.12.3]
at org.apache.camel.impl.ScheduledPollConsumer.run(ScheduledPollConsumer.java:114)[110:org.apache.camel.camel-core:2.12.3]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)[:1.7.0_51]
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:304)[:1.7.0_51]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:178)[:1.7.0_51]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)[:1.7.0_51]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)[:1.7.0_51]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)[:1.7.0_51]
at java.lang.Thread.run(Thread.java:744)[:1.7.0_51]
Caused by: java.io.IOException: Renaming file from: C:\Camel\edi-input.txt to: C:\Camel\.camel\edi-input.txt failed due cannot delete from file: C:\Camel\edi-input.txt after copy succeeded
at org.apache.camel.util.FileUtil.renameFile(FileUtil.java:421)[110:org.apache.camel.camel-core:2.12.3]
at org.apache.camel.component.file.FileOperations.renameFile(FileOperations.java:70)[110:org.apache.camel.camel-core:2.12.3]
... 25 more
So yes, the file is still open which is blocking the delete. But that's where it gets a little interesting. If you list the open files you see it's actually open multiple times, and you get another one every 2 seconds, which is the polling delay.
#1 C:\Camel\edi-input.txt by thread:Camel (customsContext) thread #0 - file://C:%5CCamel%5C on Thu Jun 05 10:08:13 EDT 2014
at java.io.FileInputStream.<init>(FileInputStream.java:147)
at java.io.FileInputStream.<init>(FileInputStream.java:101)
at sun.net.www.protocol.file.FileURLConnection.connect(FileURLConnection.java:90)
at sun.net.www.protocol.file.FileURLConnection.getInputStream(FileURLConnection.java:188)
at java.net.URL.openStream(URL.java:1037)
at org.milyn.delivery.AbstractParser.systemIdToStream(AbstractParser.java:192)
at org.milyn.delivery.AbstractParser.getInputStream(AbstractParser.java:253)
at org.milyn.delivery.AbstractParser.createInputSource(AbstractParser.java:227)
at org.milyn.delivery.sax.SAXParser.parse(SAXParser.java:76)
at org.milyn.delivery.sax.SmooksSAXFilter.doFilter(SmooksSAXFilter.java:86)
at org.milyn.delivery.sax.SmooksSAXFilter.doFilter(SmooksSAXFilter.java:64)
at org.milyn.Smooks._filter(Smooks.java:526)
at org.milyn.Smooks.filterSource(Smooks.java:477)
at org.milyn.smooks.camel.processor.SmooksProcessor.process(SmooksProcessor.java:112)
at org.apache.camel.impl.ProcessorEndpoint.onExchange(ProcessorEndpoint.java:103)
at org.apache.camel.impl.ProcessorEndpoint$1.process(ProcessorEndpoint.java:71)
at org.apache.camel.util.AsyncProcessorConverterHelper$ProcessorToAsyncProcessorBridge.process(AsyncProcessorConverterHelper.java:61)
at org.apache.camel.processor.SendProcessor.process(SendProcessor.java:110)
at org.apache.camel.management.InstrumentationProcessor.process(InstrumentationProcessor.java:72)
at org.apache.camel.processor.RedeliveryErrorHandler.process(RedeliveryErrorHandler.java:398)
at org.apache.camel.processor.CamelInternalProcessor.process(CamelInternalProcessor.java:191)
at org.apache.camel.processor.Pipeline.process(Pipeline.java:118)
at org.apache.camel.processor.Pipeline.process(Pipeline.java:80)
at org.apache.camel.processor.CamelInternalProcessor.process(CamelInternalProcessor.java:191)
at org.apache.camel.component.file.GenericFileConsumer.processExchange(GenericFileConsumer.java:401)
at org.apache.camel.component.file.GenericFileConsumer.processBatch(GenericFileConsumer.java:201)
at org.apache.camel.component.file.GenericFileConsumer.poll(GenericFileConsumer.java:165)
at org.apache.camel.impl.ScheduledPollConsumer.doRun(ScheduledPollConsumer.java:187)
at org.apache.camel.impl.ScheduledPollConsumer.run(ScheduledPollConsumer.java:114)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:304)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:178)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:744)
Yet, there are less than 100 even though it's completed ~7,000 cycles at this point, so yes, all the files close during GC (garbage collection) and then start to accumulate again. Yes, that suggests the stream isn't closed until the object referencing it is cleaned up by GC. However, I've traced the code and the stream is closed in org.milyn.delivery.sax.SmooksSAXFilter.doFilter
try {
Writer writer = parser.parse(source, result, executionContext);
writer.flush();
} catch (TerminateException e) {
if(logger.isDebugEnabled()) {
if(e.isTerminateBefore()) {
logger.debug("Terminated filtering on visitBefore of element '" + SAXUtil.getXPath(e.getElement()) + "'.");
} else {
logger.debug("Terminated filtering on visitAfter of element '" + SAXUtil.getXPath(e.getElement()) + "'.");
}
}
} catch (Exception e) {
throw new SmooksException("Failed to filter source.", e);
} finally {
if(closeSource) {
close(source);
}
if(closeResult) {
close(result);
}
}
So, I'm at a bit of a loss here. Does this mean Camel is trying to commit the transaction on another thread before Smooks finishes?
It's Smooks!
Under some circumstances Smooks opens the stream its self in the org.milyn.delivery.AbstractParser class, but never closes it. So, the open stream hangs out until the defunct object gets collected. In the case of Windows, the open file lock is enforced by the operating system and Camel is unable to rename or delete the file. This might not be the case with other operating systems or Java versions if the lock is not honored there.
I've opened MILYN-662 and am working on a fix.