[logback-dev] [JIRA] Commented: (LBCORE-127) Logback auto config closes the jar file previously opened in user code

tomliliu (JIRA) noreply-jira at qos.ch
Tue Dec 1 03:52:44 CET 2009


    [ http://jira.qos.ch/browse/LBCORE-127?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=11392#action_11392 ] 

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

        


More information about the logback-dev mailing list