1/*
2 * Copyright (c) 2014, Oracle and/or its affiliates. All rights reserved.
3 * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
4 *
5 * This code is free software; you can redistribute it and/or modify it
6 * under the terms of the GNU General Public License version 2 only, as
7 * published by the Free Software Foundation.
8 *
9 * This code is distributed in the hope that it will be useful, but WITHOUT
10 * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
11 * FITNESS FOR A PARTICULAR PURPOSE.  See the GNU General Public License
12 * version 2 for more details (a copy is included in the LICENSE file that
13 * accompanied this code).
14 *
15 * You should have received a copy of the GNU General Public License version
16 * 2 along with this work; if not, write to the Free Software Foundation,
17 * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
18 *
19 * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA
20 * or visit www.oracle.com if you need additional information or have any
21 * questions.
22 */
23import java.io.ByteArrayInputStream;
24import java.io.ByteArrayOutputStream;
25import java.io.FilePermission;
26import java.io.IOException;
27import java.lang.ref.Reference;
28import java.lang.ref.ReferenceQueue;
29import java.lang.ref.WeakReference;
30import java.nio.file.Files;
31import java.nio.file.Paths;
32import java.security.CodeSource;
33import java.security.Permission;
34import java.security.PermissionCollection;
35import java.security.Permissions;
36import java.security.Policy;
37import java.security.ProtectionDomain;
38import java.util.Arrays;
39import java.util.Collections;
40import java.util.Enumeration;
41import java.util.HashSet;
42import java.util.List;
43import java.util.Properties;
44import java.util.Set;
45import java.util.UUID;
46import java.util.concurrent.Callable;
47import java.util.concurrent.atomic.AtomicBoolean;
48import java.util.logging.FileHandler;
49import java.util.logging.Handler;
50import java.util.logging.LogManager;
51import java.util.logging.Logger;
52import java.util.logging.LoggingPermission;
53
54/**
55 * @test
56 * @bug 8060132
57 * @summary tests that FileHandlers configured on abstract nodes in logging.properties
58 *          will be closed by reset().
59 * @run main/othervm ParentLoggerWithHandlerGC UNSECURE
60 * @run main/othervm ParentLoggerWithHandlerGC SECURE
61 * @author danielfuchs
62 * @key randomness
63 */
64public class ParentLoggerWithHandlerGC {
65
66    /**
67     * We will test the handling of abstract logger nodes with file handlers in
68     * two configurations:
69     * UNSECURE: No security manager.
70     * SECURE: With the security manager present - and the required
71     *         permissions granted.
72     */
73    public static enum TestCase {
74        UNSECURE, SECURE;
75        public void run(Properties propertyFile) throws Exception {
76            System.out.println("Running test case: " + name());
77            Configure.setUp(this, propertyFile);
78            test(this.name() + " " + propertyFile.getProperty("test.name"), propertyFile);
79        }
80    }
81
82
83    private static final String PREFIX =
84            "FileHandler-" + UUID.randomUUID() + ".log";
85    private static final String userDir = System.getProperty("user.dir", ".");
86    private static final boolean userDirWritable = Files.isWritable(Paths.get(userDir));
87
88    static enum ConfigMode { DEFAULT, ENSURE_CLOSE_ON_RESET_TRUE, ENSURE_CLOSE_ON_RESET_FALSE }
89
90    private static final List<Properties> properties;
91    static {
92        Properties props1 = new Properties();
93        props1.setProperty("test.name", "parent logger with handler");
94        props1.setProperty("test.config.mode", ConfigMode.DEFAULT.name());
95        props1.setProperty(FileHandler.class.getName() + ".pattern", PREFIX);
96        props1.setProperty(FileHandler.class.getName() + ".limit", String.valueOf(Integer.MAX_VALUE));
97        props1.setProperty(FileHandler.class.getName() + ".level", "ALL");
98        props1.setProperty(FileHandler.class.getName() + ".formatter", "java.util.logging.SimpleFormatter");
99        props1.setProperty("com.foo.handlers", FileHandler.class.getName());
100        props1.setProperty("com.bar.level", "FINEST");
101
102        Properties props2 = new Properties();
103        props2.setProperty("test.name", "parent logger with handler");
104        props2.setProperty("test.config.mode", ConfigMode.ENSURE_CLOSE_ON_RESET_TRUE.name());
105        props2.setProperty(FileHandler.class.getName() + ".pattern", PREFIX);
106        props2.setProperty(FileHandler.class.getName() + ".limit", String.valueOf(Integer.MAX_VALUE));
107        props2.setProperty(FileHandler.class.getName() + ".level", "ALL");
108        props2.setProperty(FileHandler.class.getName() + ".formatter", "java.util.logging.SimpleFormatter");
109        props2.setProperty("com.foo.handlers", FileHandler.class.getName());
110        props2.setProperty("com.foo.handlers.ensureCloseOnReset", "true");
111        props2.setProperty("com.bar.level", "FINEST");
112
113        Properties props3 = new Properties();
114        props3.setProperty("test.name", "parent logger with handler");
115        props3.setProperty("test.config.mode", ConfigMode.ENSURE_CLOSE_ON_RESET_FALSE.name());
116        props3.setProperty(FileHandler.class.getName() + ".pattern", PREFIX);
117        props3.setProperty(FileHandler.class.getName() + ".limit", String.valueOf(Integer.MAX_VALUE));
118        props3.setProperty(FileHandler.class.getName() + ".level", "ALL");
119        props3.setProperty(FileHandler.class.getName() + ".formatter", "java.util.logging.SimpleFormatter");
120        props3.setProperty("com.foo.handlers", FileHandler.class.getName());
121        props3.setProperty("com.foo.handlers.ensureCloseOnReset", "false");
122        props3.setProperty("com.bar.level", "FINEST");
123
124        properties = Collections.unmodifiableList(Arrays.asList(
125                    props1, props2, props3));
126    }
127
128    public static void main(String... args) throws Exception {
129
130
131        if (args == null || args.length == 0) {
132            args = new String[] {
133                TestCase.UNSECURE.name(),
134                TestCase.SECURE.name(),
135            };
136        }
137
138        try {
139            for (String testName : args) {
140                for (Properties propertyFile : properties) {
141                    TestCase test = TestCase.valueOf(testName);
142                    test.run(propertyFile);
143                }
144            }
145        } finally {
146            if (userDirWritable) {
147                Configure.doPrivileged(() -> {
148                    // cleanup - delete files that have been created
149                    try {
150                        Files.list(Paths.get(userDir))
151                            .filter((f) -> f.toString().contains(PREFIX))
152                            .forEach((f) -> {
153                                try {
154                                    System.out.println("deleting " + f);
155                                    Files.delete(f);
156                                } catch(Throwable t) {
157                                    System.err.println("Failed to delete " + f + ": " + t);
158                                }
159                            });
160                    } catch(Throwable t) {
161                        System.err.println("Cleanup failed to list files: " + t);
162                        t.printStackTrace();
163                    }
164                });
165            }
166        }
167    }
168
169    static class Configure {
170        static Policy policy = null;
171        static final AtomicBoolean allowAll = new AtomicBoolean(false);
172        static void setUp(TestCase test, Properties propertyFile) {
173            switch (test) {
174                case SECURE:
175                    if (policy == null && System.getSecurityManager() != null) {
176                        throw new IllegalStateException("SecurityManager already set");
177                    } else if (policy == null) {
178                        policy = new SimplePolicy(TestCase.SECURE, allowAll);
179                        Policy.setPolicy(policy);
180                        System.setSecurityManager(new SecurityManager());
181                    }
182                    if (System.getSecurityManager() == null) {
183                        throw new IllegalStateException("No SecurityManager.");
184                    }
185                    if (policy == null) {
186                        throw new IllegalStateException("policy not configured");
187                    }
188                    break;
189                case UNSECURE:
190                    if (System.getSecurityManager() != null) {
191                        throw new IllegalStateException("SecurityManager already set");
192                    }
193                    break;
194                default:
195                    new InternalError("No such testcase: " + test);
196            }
197            doPrivileged(() -> {
198                try {
199                    ByteArrayOutputStream bytes = new ByteArrayOutputStream();
200                    propertyFile.store(bytes, propertyFile.getProperty("test.name"));
201                    ByteArrayInputStream bais = new ByteArrayInputStream(bytes.toByteArray());
202                    LogManager.getLogManager().readConfiguration(bais);
203                } catch (IOException ex) {
204                    throw new RuntimeException(ex);
205                }
206            });
207        }
208        static void doPrivileged(Runnable run) {
209            allowAll.set(true);
210            try {
211                run.run();
212            } finally {
213                allowAll.set(false);
214            }
215        }
216        static <T> T callPrivileged(Callable<T> call) throws Exception {
217            allowAll.set(true);
218            try {
219                return call.call();
220            } finally {
221                allowAll.set(false);
222            }
223        }
224    }
225
226    @FunctionalInterface
227    public static interface FileHandlerSupplier {
228        public FileHandler test() throws Exception;
229    }
230
231    static final class TestAssertException extends RuntimeException {
232        TestAssertException(String msg) {
233            super(msg);
234        }
235    }
236
237    private static void assertEquals(long expected, long received, String msg) {
238        if (expected != received) {
239            throw new TestAssertException("Unexpected result for " + msg
240                    + ".\n\texpected: " + expected
241                    +  "\n\tactual:   " + received);
242        } else {
243            System.out.println("Got expected " + msg + ": " + received);
244        }
245    }
246
247
248    public static void test(String name, Properties props) throws Exception {
249        ConfigMode configMode = ConfigMode.valueOf(props.getProperty("test.config.mode"));
250        System.out.println("\nTesting: " + name + " mode=" + configMode);
251        if (!userDirWritable) {
252            throw new RuntimeException("Not writable: "+userDir);
253        }
254        switch(configMode) {
255            case DEFAULT:
256            case ENSURE_CLOSE_ON_RESET_TRUE:
257                testCloseOnResetTrue(name, props); break;
258            case ENSURE_CLOSE_ON_RESET_FALSE:
259                testCloseOnResetFalse(name, props); break;
260            default:
261                throw new RuntimeException("Unknwown mode: " + configMode);
262        }
263    }
264
265
266    // Test a configuration which has either
267    // com.foo.handlers.ensureCloseOnReset=true, or where
268    // com.foo.handlers.ensureCloseOnReset is not specified.
269    public static void testCloseOnResetTrue(String name, Properties props)
270            throws Exception {
271        Logger fooChild = Logger.getLogger("com.foo.child");
272        fooChild.info("hello world");
273        Logger barChild = Logger.getLogger("com.bar.child");
274        barChild.info("hello world");
275
276        ReferenceQueue<Logger> queue = new ReferenceQueue();
277        WeakReference<Logger> fooRef = new WeakReference<>(Logger.getLogger("com.foo"), queue);
278        if (fooRef.get() != fooChild.getParent()) {
279            throw new RuntimeException("Unexpected parent logger: "
280                    + fooChild.getParent() +"\n\texpected: " + fooRef.get());
281        }
282        WeakReference<Logger> barRef = new WeakReference<>(Logger.getLogger("com.bar"), queue);
283        if (barRef.get() != barChild.getParent()) {
284            throw new RuntimeException("Unexpected parent logger: "
285                    + barChild.getParent() +"\n\texpected: " + barRef.get());
286        }
287        fooChild = barChild = null;
288        Reference<? extends Logger> ref2 = null;
289        while ((ref2 = queue.poll()) == null) {
290            System.gc();
291            Thread.sleep(1000);
292        }
293        Throwable failed = null;
294        try {
295            do {
296                if (ref2 != barRef) {
297                    throw new RuntimeException("Unexpected reference: "
298                            + ref2 +"\n\texpected: " + barRef);
299                }
300                if (ref2.get() != null) {
301                    throw new RuntimeException("Referent not cleared: "
302                            + ref2.get());
303                }
304                System.out.println("Got barRef");
305                System.gc();
306                Thread.sleep(1000);
307            } while( (ref2 = queue.poll()) != null);
308            System.out.println("Parent logger GCed");
309        } catch(Throwable t) {
310            failed = t;
311        } finally {
312            final Throwable suppressed = failed;
313            Configure.doPrivileged(() -> LogManager.getLogManager().reset());
314            Configure.doPrivileged(() -> {
315                try {
316                    StringBuilder builder = new StringBuilder();
317                    Files.list(Paths.get(userDir))
318                        .filter((f) -> f.toString().contains(PREFIX))
319                        .filter((f) -> f.toString().endsWith(".lck"))
320                        .forEach((f) -> {
321                                builder.append(f.toString()).append('\n');
322                        });
323                    if (!builder.toString().isEmpty()) {
324                        throw new RuntimeException("Lock files not cleaned:\n"
325                                + builder.toString());
326                    }
327                } catch(RuntimeException | Error x) {
328                    if (suppressed != null) x.addSuppressed(suppressed);
329                    throw x;
330                } catch(Exception x) {
331                    if (suppressed != null) x.addSuppressed(suppressed);
332                    throw new RuntimeException(x);
333                }
334            });
335            while ((ref2 = queue.poll()) == null) {
336                System.gc();
337                Thread.sleep(1000);
338            }
339            if (ref2 != fooRef) {
340                throw new RuntimeException("Unexpected reference: "
341                        + ref2 +"\n\texpected: " + fooRef);
342            }
343            if (ref2.get() != null) {
344                throw new RuntimeException("Referent not cleared: " + ref2.get());
345            }
346            System.out.println("Got fooRef after reset()");
347
348        }
349        if (failed != null) {
350            // should rarely happen...
351            throw new RuntimeException(failed);
352        }
353
354    }
355
356    private static Handler getHandlerToClose() throws Exception {
357        return Configure.callPrivileged(
358                () -> Logger.getLogger("com.foo.child").getParent().getHandlers()[0]);
359    }
360
361    // Test a configuration which has com.foo.handlers.ensureCloseOnReset=false
362    public static void testCloseOnResetFalse(String name, Properties props)
363            throws Exception {
364        Logger fooChild = Logger.getLogger("com.foo.child");
365        fooChild.info("hello world");
366        Logger barChild = Logger.getLogger("com.bar.child");
367        barChild.info("hello world");
368
369        Handler toClose = getHandlerToClose();
370
371        ReferenceQueue<Logger> queue = new ReferenceQueue();
372        WeakReference<Logger> fooRef = new WeakReference<>(Logger.getLogger("com.foo"), queue);
373        if (fooRef.get() != fooChild.getParent()) {
374            throw new RuntimeException("Unexpected parent logger: "
375                    + fooChild.getParent() +"\n\texpected: " + fooRef.get());
376        }
377        WeakReference<Logger> barRef = new WeakReference<>(Logger.getLogger("com.bar"), queue);
378        if (barRef.get() != barChild.getParent()) {
379            throw new RuntimeException("Unexpected parent logger: "
380                    + barChild.getParent() +"\n\texpected: " + barRef.get());
381        }
382        fooChild = barChild = null;
383        Reference<? extends Logger> ref2 = null;
384        Set<WeakReference<Logger>> expectedRefs = new HashSet<>(Arrays.asList(fooRef, barRef));
385        Throwable failed = null;
386        try {
387            int l=0;
388            while (failed == null && !expectedRefs.isEmpty()) {
389                int max = 60;
390                while ((ref2 = queue.poll()) == null) {
391                    if (l > 0 && max-- <= 0) {
392                        throw new RuntimeException("Logger #2 not GC'ed!"
393                                + " max too short (max=60) or "
394                                + "com.foo.handlers.ensureCloseOnReset=false"
395                                + " does not work");
396                    }
397                    System.gc();
398                    Thread.sleep(1000);
399                }
400                do {
401                    if (!expectedRefs.contains(ref2)) {
402                        throw new RuntimeException("Unexpected reference: "
403                                + ref2 +"\n\texpected: " + expectedRefs);
404                    }
405                    if (ref2.get() != null) {
406                        throw new RuntimeException("Referent not cleared: "
407                                + ref2.get());
408                    }
409                    expectedRefs.remove(ref2);
410                    System.out.println("Got "+
411                            (ref2 == barRef ? "barRef"
412                                    : (ref2 == fooRef ? "fooRef"
413                                            : ref2.toString())));
414                    System.gc();
415                    Thread.sleep(1000);
416                    System.out.println("Logger #" + (++l) + " GCed");
417                } while( (ref2 = queue.poll()) != null);
418            }
419        } catch(Throwable t) {
420            failed = t;
421        } finally {
422            final Throwable suppressed = failed;
423            Configure.doPrivileged(() -> LogManager.getLogManager().reset());
424            Configure.doPrivileged(() -> {
425                try {
426                    toClose.close();
427                    StringBuilder builder = new StringBuilder();
428                    Files.list(Paths.get(userDir))
429                        .filter((f) -> f.toString().contains(PREFIX))
430                        .filter((f) -> f.toString().endsWith(".lck"))
431                        .forEach((f) -> {
432                                builder.append(f.toString()).append('\n');
433                        });
434                    if (!builder.toString().isEmpty()) {
435                        throw new RuntimeException("Lock files not cleaned:\n" + builder.toString());
436                    }
437                } catch(RuntimeException | Error x) {
438                    if (suppressed != null) x.addSuppressed(suppressed);
439                    throw x;
440                } catch(Exception x) {
441                    if (suppressed != null) x.addSuppressed(suppressed);
442                    throw new RuntimeException(x);
443                }
444            });
445        }
446        if (failed != null) {
447            // should rarely happen...
448            throw new RuntimeException(failed);
449        }
450
451    }
452
453
454    static final class PermissionsBuilder {
455        final Permissions perms;
456        public PermissionsBuilder() {
457            this(new Permissions());
458        }
459        public PermissionsBuilder(Permissions perms) {
460            this.perms = perms;
461        }
462        public PermissionsBuilder add(Permission p) {
463            perms.add(p);
464            return this;
465        }
466        public PermissionsBuilder addAll(PermissionCollection col) {
467            if (col != null) {
468                for (Enumeration<Permission> e = col.elements(); e.hasMoreElements(); ) {
469                    perms.add(e.nextElement());
470                }
471            }
472            return this;
473        }
474        public Permissions toPermissions() {
475            final PermissionsBuilder builder = new PermissionsBuilder();
476            builder.addAll(perms);
477            return builder.perms;
478        }
479    }
480
481    public static class SimplePolicy extends Policy {
482
483        final Permissions permissions;
484        final Permissions allPermissions;
485        final AtomicBoolean allowAll;
486        public SimplePolicy(TestCase test, AtomicBoolean allowAll) {
487            this.allowAll = allowAll;
488            permissions = new Permissions();
489            permissions.add(new LoggingPermission("control", null));
490            permissions.add(new FilePermission(PREFIX+".lck", "read,write,delete"));
491            permissions.add(new FilePermission(PREFIX, "read,write"));
492
493            // these are used for configuring the test itself...
494            allPermissions = new Permissions();
495            allPermissions.add(new java.security.AllPermission());
496
497        }
498
499        @Override
500        public boolean implies(ProtectionDomain domain, Permission permission) {
501            if (allowAll.get()) return allPermissions.implies(permission);
502            return permissions.implies(permission);
503        }
504
505        @Override
506        public PermissionCollection getPermissions(CodeSource codesource) {
507            return new PermissionsBuilder().addAll(allowAll.get()
508                    ? allPermissions : permissions).toPermissions();
509        }
510
511        @Override
512        public PermissionCollection getPermissions(ProtectionDomain domain) {
513            return new PermissionsBuilder().addAll(allowAll.get()
514                    ? allPermissions : permissions).toPermissions();
515        }
516    }
517
518}
519