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