[ http://jira.qos.ch/browse/LBCORE-127?page=com.atlassian.jira.plugin.system.i... ] Ceki Gulcu commented on LBCORE-127: ----------------------------------- I've added a test case based on this report. See [1]. In contrast to what you state, the pre-existing code in GenericConfigrator does the correct job. Invoking "urlConnection.setUseCaches(false)" instead of "urlConnection.setDefaultUseCaches(false);" makes the new test case fail. So either I misunderstood your description and my new test case does *not* reproduce the case you are illustrating, or this entry is invalid. [1] http://github.com/ceki/logback/commit/b018525e30ef54b8096d9c9cb9ae7db67eed1a...

Logback auto config closes the jar file previously opened in user code ----------------------------------------------------------------------

Key: LBCORE-127 URL: http://jira.qos.ch/browse/LBCORE-127 Project: logback-core Issue Type: Bug Components: Joran Affects Versions: 0.9.17 Reporter: tomliliu Assignee: Ceki Gulcu Priority: Blocker

User code opens an input stream from a jar file first. Then logback auto config loads the configuration file from the same jar. User code will get the following exception when read the input stream later. {code title="Stack Trace"} java.util.zip.ZipException: ZipFile closed at java.util.zip.ZipFile.ensureOpenOrZipException(ZipFile.java:413) at java.util.zip.ZipFile.access$1100(ZipFile.java:29) at java.util.zip.ZipFile$ZipFileInputStream.read(ZipFile.java:445) at java.io.FilterInputStream.read(FilterInputStream.java:116) at sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:264) at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:306) at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:158) at java.io.InputStreamReader.read(InputStreamReader.java:167) at java.io.BufferedReader.fill(BufferedReader.java:136) at java.io.BufferedReader.readLine(BufferedReader.java:299) at java.io.BufferedReader.readLine(BufferedReader.java:362) {code} {code title="Reproduce"} InputStream resourceAsStream = Thread.currentThread().getContextClassLoader().getResourceAsStream(logLocation); BufferedReader reader = new BufferedReader(new InputStreamReader(resourceAsStream)); final Logger logger = LoggerFactory.getLogger(LogbackBugReproduce.class); logger.debug(reader.readLine()); {code} It looks like in ch.qos.logback.core.joran.GenericConfigurator.doConfigure(URL url) method: urlConnection.setDefaultUseCaches(false); InputStream in = urlConnection.getInputStream(); doConfigure(in); in.close(); The input stream is associated with the same zip file instance of the users. Then close the input stream will close the zip file that user currently is using. After changing it to: urlConnection.setUseCaches(false); InputStream in = urlConnection.getInputStream(); doConfigure(in); in.close(); The input stream is associated with a different zip file instance. Then close the input stream will not affect the zip file used by the user code.

-- This message is automatically generated by JIRA. - If you think it was sent incorrectly contact one of the administrators: http://jira.qos.ch/secure/Administrators.jspa - For more information on JIRA, see: http://www.atlassian.com/software/jira

[ http://jira.qos.ch/browse/LBCORE-127?page=com.atlassian.jira.plugin.system.i... ] tomliliu commented on LBCORE-127: --------------------------------- Hi Ceki, Thanks for looking into this issue. I've run your test case with logback-0.9.17, it fails. My env is: Windows XP SP2 JDK 1.6.0_16 CLASSPATH: logback-core-0.9.17.jar (no other libs) The junit failure stack trace is: {code} java.util.zip.ZipException: ZipFile closed at java.util.zip.ZipFile.ensureOpenOrZipException(ZipFile.java:413) at java.util.zip.ZipFile.access$1100(ZipFile.java:29) at java.util.zip.ZipFile$ZipFileInputStream.read(ZipFile.java:445) at java.util.zip.ZipFile$1.fill(ZipFile.java:230) at java.util.zip.InflaterInputStream.read(InflaterInputStream.java:141) at java.io.FilterInputStream.read(FilterInputStream.java:116) at sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:264) at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:306) at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:158) at java.io.InputStreamReader.read(InputStreamReader.java:167) at java.io.BufferedReader.fill(BufferedReader.java:136) at java.io.BufferedReader.readLine(BufferedReader.java:299) at java.io.BufferedReader.readLine(BufferedReader.java:362) at ch.qos.logback.core.joran.TrivialConfiguratorTest.lbcore127(TrivialConfiguratorTest.java:87) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:597) at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:44) at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:15) at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:41) at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:20) at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:28) at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:31) at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:73) at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:46) at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:180) at org.junit.runners.ParentRunner.access$000(ParentRunner.java:41) at org.junit.runners.ParentRunner$1.evaluate(ParentRunner.java:173) at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:28) at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:31) at org.junit.runners.ParentRunner.run(ParentRunner.java:220) at org.eclipse.jdt.internal.junit4.runner.JUnit4TestReference.run(JUnit4TestReference.java:46) at org.eclipse.jdt.internal.junit.runner.TestExecution.run(TestExecution.java:38) at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:467) at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:683) at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.run(RemoteTestRunner.java:390) at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.main(RemoteTestRunner.java:197) {code} I've removed modified your test case to remove the irrelevant test cases: {code} /** * Logback: the reliable, generic, fast and flexible logging framework. * Copyright (C) 1999-2009, QOS.ch. All rights reserved. * * This program and the accompanying materials are dual-licensed under * either the terms of the Eclipse Public License v1.0 as published by * the Eclipse Foundation * * or (per the licensee's choosing) * * under the terms of the GNU Lesser General Public License version 2.1 * as published by the Free Software Foundation. */ package ch.qos.logback.core.joran; import static org.junit.Assert.assertFalse; import static org.junit.Assert.assertTrue; import java.io.BufferedReader; import java.io.File; import java.io.FileOutputStream; import java.io.IOException; import java.io.InputStream; import java.io.InputStreamReader; import java.net.URL; import java.util.HashMap; import java.util.UUID; import java.util.jar.JarOutputStream; import java.util.zip.ZipEntry; import org.junit.Test; import ch.qos.logback.core.Context; import ch.qos.logback.core.ContextBase; import ch.qos.logback.core.joran.action.Action; import ch.qos.logback.core.joran.spi.Interpreter; import ch.qos.logback.core.joran.spi.JoranException; import ch.qos.logback.core.joran.spi.Pattern; import ch.qos.logback.core.joran.spi.RuleStore; class TrivialConfigurator extends GenericConfigurator { HashMap<Pattern, Action> rulesMap; public TrivialConfigurator(HashMap<Pattern, Action> rules) { this.rulesMap = rules; } @Override protected void addImplicitRules(Interpreter interpreter) { } @Override protected void addInstanceRules(RuleStore rs) { for (Pattern pattern : rulesMap.keySet()) { Action action = rulesMap.get(pattern); rs.addRule(pattern, action); } } } public class TrivialConfiguratorTest { Context context = new ContextBase(); HashMap<Pattern, Action> rulesMap = new HashMap<Pattern, Action>(); @Test public void lbcore127() throws IOException, JoranException { String jarEntry = "buzz.xml"; String jarEntry2 = "Lightyear.xml"; File jarFile = makeJarFile(); fillInJarFile(jarFile, jarEntry, jarEntry2); URL url = asURL(jarFile, jarEntry); URL url2 = asURL(jarFile, jarEntry2); InputStream resourceAsStream = url2.openStream(); BufferedReader reader = new BufferedReader(new InputStreamReader(resourceAsStream)); TrivialConfigurator tc = new TrivialConfigurator(rulesMap); tc.setContext(context); tc.doConfigure(url); reader.readLine(); reader.close(); // deleting an open file fails assertTrue(jarFile.delete()); assertFalse(jarFile.exists()); } File makeJarFile() { File outputDir = new File("c:/var/tmp"); outputDir.mkdirs(); return new File("c:/var/tmp" + "/foo." + UUID.randomUUID().toString() + ".jar"); } private void fillInJarFile(File jarFile, String jarEntryName, String secondJarEntry) throws IOException { JarOutputStream jos = new JarOutputStream(new FileOutputStream(jarFile)); jos.putNextEntry(new ZipEntry(jarEntryName)); jos.write("<x/>".getBytes()); jos.closeEntry(); if (secondJarEntry != null) { jos.putNextEntry(new ZipEntry(secondJarEntry)); jos.write("<y/>".getBytes()); jos.closeEntry(); } jos.close(); } URL asURL(File jarFile, String jarEntryName) throws IOException { URL innerURL = jarFile.toURI().toURL(); return new URL("jar:" + innerURL + "!/" + jarEntryName); } } {code} Thanks, Tom

Logback auto config closes the jar file previously opened in user code ----------------------------------------------------------------------

Key: LBCORE-127 URL: http://jira.qos.ch/browse/LBCORE-127 Project: logback-core Issue Type: Bug Components: Joran Affects Versions: 0.9.17 Reporter: tomliliu Assignee: Ceki Gulcu Priority: Blocker

User code opens an input stream from a jar file first. Then logback auto config loads the configuration file from the same jar. User code will get the following exception when read the input stream later. {code title="Stack Trace"} java.util.zip.ZipException: ZipFile closed at java.util.zip.ZipFile.ensureOpenOrZipException(ZipFile.java:413) at java.util.zip.ZipFile.access$1100(ZipFile.java:29) at java.util.zip.ZipFile$ZipFileInputStream.read(ZipFile.java:445) at java.io.FilterInputStream.read(FilterInputStream.java:116) at sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:264) at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:306) at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:158) at java.io.InputStreamReader.read(InputStreamReader.java:167) at java.io.BufferedReader.fill(BufferedReader.java:136) at java.io.BufferedReader.readLine(BufferedReader.java:299) at java.io.BufferedReader.readLine(BufferedReader.java:362) {code} {code title="Reproduce"} InputStream resourceAsStream = Thread.currentThread().getContextClassLoader().getResourceAsStream(logLocation); BufferedReader reader = new BufferedReader(new InputStreamReader(resourceAsStream)); final Logger logger = LoggerFactory.getLogger(LogbackBugReproduce.class); logger.debug(reader.readLine()); {code} It looks like in ch.qos.logback.core.joran.GenericConfigurator.doConfigure(URL url) method: urlConnection.setDefaultUseCaches(false); InputStream in = urlConnection.getInputStream(); doConfigure(in); in.close(); The input stream is associated with the same zip file instance of the users. Then close the input stream will close the zip file that user currently is using. After changing it to: urlConnection.setUseCaches(false); InputStream in = urlConnection.getInputStream(); doConfigure(in); in.close(); The input stream is associated with a different zip file instance. Then close the input stream will not affect the zip file used by the user code.

-- This message is automatically generated by JIRA. - If you think it was sent incorrectly contact one of the administrators: http://jira.qos.ch/secure/Administrators.jspa - For more information on JIRA, see: http://www.atlassian.com/software/jira

[ http://jira.qos.ch/browse/LBCORE-127?page=com.atlassian.jira.plugin.system.i... ] Ceki Gulcu commented on LBCORE-127: ----------------------------------- The URLConnection.setDefaultUseCaches instance method actually acts on a static variable called 'defaultUseCaches which sets the default value of 'useCahces' for subsequent connections. I have changed GenericConfigrator to invoke URLConnection.settUseCaches(false) instead of URLConnection.setDefaultUseCaches(false). This explains the unexpected correlation between lbcore105() and lbcore127(). With this change this bug as *initially* reported is solved. However, lbcore127() still fails, not on inputStream.read (the subject of the initial report) but on jarFile.delete. Indeed, if the file is opened in the cache mode, it is not closed even if the close method is invoked. You need to open the other file with UseCaches set to false. Anyway, the problem is solved.

Logback auto config closes the jar file previously opened in user code ----------------------------------------------------------------------

Key: LBCORE-127 URL: http://jira.qos.ch/browse/LBCORE-127 Project: logback-core Issue Type: Bug Components: Joran Affects Versions: 0.9.17 Reporter: tomliliu Assignee: Ceki Gulcu Priority: Blocker

User code opens an input stream from a jar file first. Then logback auto config loads the configuration file from the same jar. User code will get the following exception when read the input stream later. {code title="Stack Trace"} java.util.zip.ZipException: ZipFile closed at java.util.zip.ZipFile.ensureOpenOrZipException(ZipFile.java:413) at java.util.zip.ZipFile.access$1100(ZipFile.java:29) at java.util.zip.ZipFile$ZipFileInputStream.read(ZipFile.java:445) at java.io.FilterInputStream.read(FilterInputStream.java:116) at sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:264) at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:306) at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:158) at java.io.InputStreamReader.read(InputStreamReader.java:167) at java.io.BufferedReader.fill(BufferedReader.java:136) at java.io.BufferedReader.readLine(BufferedReader.java:299) at java.io.BufferedReader.readLine(BufferedReader.java:362) {code} {code title="Reproduce"} InputStream resourceAsStream = Thread.currentThread().getContextClassLoader().getResourceAsStream(logLocation); BufferedReader reader = new BufferedReader(new InputStreamReader(resourceAsStream)); final Logger logger = LoggerFactory.getLogger(LogbackBugReproduce.class); logger.debug(reader.readLine()); {code} It looks like in ch.qos.logback.core.joran.GenericConfigurator.doConfigure(URL url) method: urlConnection.setDefaultUseCaches(false); InputStream in = urlConnection.getInputStream(); doConfigure(in); in.close(); The input stream is associated with the same zip file instance of the users. Then close the input stream will close the zip file that user currently is using. After changing it to: urlConnection.setUseCaches(false); InputStream in = urlConnection.getInputStream(); doConfigure(in); in.close(); The input stream is associated with a different zip file instance. Then close the input stream will not affect the zip file used by the user code.

-- This message is automatically generated by JIRA. - If you think it was sent incorrectly contact one of the administrators: http://jira.qos.ch/secure/Administrators.jspa - For more information on JIRA, see: http://www.atlassian.com/software/jira

[ http://jira.qos.ch/browse/LBCORE-127?page=com.atlassian.jira.plugin.system.i... ] Ceki Gulcu resolved LBCORE-127. ------------------------------- Fix Version/s: 0.9.18 Resolution: Fixed Fixed in http://github.com/ceki/logback/commit/f73e9afc1951ff45ebaae0d0806e6126aab37b...

Logback auto config closes the jar file previously opened in user code ----------------------------------------------------------------------

Key: LBCORE-127 URL: http://jira.qos.ch/browse/LBCORE-127 Project: logback-core Issue Type: Bug Components: Joran Affects Versions: 0.9.17 Reporter: tomliliu Assignee: Ceki Gulcu Priority: Blocker Fix For: 0.9.18

User code opens an input stream from a jar file first. Then logback auto config loads the configuration file from the same jar. User code will get the following exception when read the input stream later. {code title="Stack Trace"} java.util.zip.ZipException: ZipFile closed at java.util.zip.ZipFile.ensureOpenOrZipException(ZipFile.java:413) at java.util.zip.ZipFile.access$1100(ZipFile.java:29) at java.util.zip.ZipFile$ZipFileInputStream.read(ZipFile.java:445) at java.io.FilterInputStream.read(FilterInputStream.java:116) at sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:264) at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:306) at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:158) at java.io.InputStreamReader.read(InputStreamReader.java:167) at java.io.BufferedReader.fill(BufferedReader.java:136) at java.io.BufferedReader.readLine(BufferedReader.java:299) at java.io.BufferedReader.readLine(BufferedReader.java:362) {code} {code title="Reproduce"} InputStream resourceAsStream = Thread.currentThread().getContextClassLoader().getResourceAsStream(logLocation); BufferedReader reader = new BufferedReader(new InputStreamReader(resourceAsStream)); final Logger logger = LoggerFactory.getLogger(LogbackBugReproduce.class); logger.debug(reader.readLine()); {code} It looks like in ch.qos.logback.core.joran.GenericConfigurator.doConfigure(URL url) method: urlConnection.setDefaultUseCaches(false); InputStream in = urlConnection.getInputStream(); doConfigure(in); in.close(); The input stream is associated with the same zip file instance of the users. Then close the input stream will close the zip file that user currently is using. After changing it to: urlConnection.setUseCaches(false); InputStream in = urlConnection.getInputStream(); doConfigure(in); in.close(); The input stream is associated with a different zip file instance. Then close the input stream will not affect the zip file used by the user code.

-- This message is automatically generated by JIRA. - If you think it was sent incorrectly contact one of the administrators: http://jira.qos.ch/secure/Administrators.jspa - For more information on JIRA, see: http://www.atlassian.com/software/jira