1 /*
   2  * Copyright (c) 2015, 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.List;
  42 import java.util.Properties;
  43 import java.util.UUID;
  44 import java.util.concurrent.Callable;
  45 import java.util.concurrent.atomic.AtomicBoolean;
  46 import java.util.function.BiFunction;
  47 import java.util.function.Function;
  48 import java.util.logging.FileHandler;
  49 import java.util.logging.LogManager;
  50 import java.util.logging.Logger;
  51 import java.util.logging.LoggingPermission;
  52 
  53 /**
  54  * @test
  55  * @bug 8033661
  56  * @summary tests that FileHandlers configured on abstract nodes in logging.properties
  57  *          will be closed on reset and reopened on updateConfiguration().
  58  *          Test a complex reconfiguration where a logger with handlers
  59  *          suddenly appears in the hierarchy between a child logger and the
  60  *          root logger.
  61  * @run main/othervm HandlersOnComplexResetUpdate UNSECURE
  62  * @run main/othervm HandlersOnComplexResetUpdate SECURE
  63  * @author danielfuchs
  64  */
  65 public class HandlersOnComplexResetUpdate {
  66 
  67     /**
  68      * We will test the handling of abstract logger nodes with file handlers in
  69      * two configurations:
  70      * UNSECURE: No security manager.
  71      * SECURE: With the security manager present - and the required
  72      *         permissions granted.
  73      */
  74     public static enum TestCase {
  75         UNSECURE, SECURE;
  76         public void run(List<Properties> properties) throws Exception {
  77             System.out.println("Running test case: " + name());
  78             Configure.setUp(this, properties.get(0));
  79             test(this.name(), properties);
  80         }
  81     }
  82 
  83 
  84     private static final String PREFIX =
  85             "FileHandler-" + UUID.randomUUID() + ".log";
  86     private static final String userDir = System.getProperty("user.dir", ".");
  87     private static final boolean userDirWritable = Files.isWritable(Paths.get(userDir));
  88 
  89     private static final List<Properties> properties;
  90     static {
  91         // The test will call reset() and updateConfiguration() with each of these
  92         // properties in sequence. The child logger is not released between each
  93         // configuration. What is interesting here is mostly what happens between
  94         // props4 and props5:
  95         //
  96         // In step 4 (props4) the configuration defines a handler for the
  97         // logger com.foo (the direct parent of com.foo.child - which is the
  98         // logger we hold on to).
  99         //
 100         // In step 5 (props5) the configuration has nothing concerning
 101         // 'com.foo', but the handler has been migrated to 'com'.
 102         // Since there doesn't exist any logger for 'com' (the previous
 103         // configuration didn't have any configuration for 'com'), then
 104         // 'com' will not be found when we process the existing loggers named
 105         // in the configuration.
 106         //
 107         // So if we didn't also process the existing loggers not named in the
 108         // configuration (such as com.foo.child) then no logger for 'com'
 109         // would be created, which means that com.foo.child would not be
 110         // able to inherit its configuration for 'com' until someone explicitely
 111         // creates a logger for 'com'.
 112         //
 113         // This test check that a logger for 'com' will be created because
 114         // 'com.foo.child' still exists when updateConfiguration() is called.
 115 
 116         Properties props1 = new Properties();
 117         props1.setProperty("test.name", "parent logger with handler");
 118         props1.setProperty(FileHandler.class.getName() + ".pattern", PREFIX);
 119         props1.setProperty(FileHandler.class.getName() + ".limit", String.valueOf(Integer.MAX_VALUE));
 120         props1.setProperty(FileHandler.class.getName() + ".level", "ALL");
 121         props1.setProperty(FileHandler.class.getName() + ".formatter", "java.util.logging.SimpleFormatter");
 122         props1.setProperty("com.foo.handlers", FileHandler.class.getName());
 123         props1.setProperty("test.checkHandlersOnParent", "true");
 124         props1.setProperty("test.checkHandlersOn", "com.foo");
 125         props1.setProperty("com.bar.level", "FINEST");
 126 
 127         Properties props2 = new Properties();
 128         props2.setProperty("java.util.logging.LogManager.reconfigureHandlers", "true");
 129         props2.setProperty(FileHandler.class.getName() + ".pattern", PREFIX);
 130         props2.setProperty(FileHandler.class.getName() + ".limit", String.valueOf(Integer.MAX_VALUE));
 131         props2.setProperty(FileHandler.class.getName() + ".level", "ALL");
 132         props2.setProperty(FileHandler.class.getName() + ".formatter", "java.util.logging.SimpleFormatter");
 133         props2.setProperty("com.foo.handlers", FileHandler.class.getName());
 134         props2.setProperty("test.checkHandlersOnParent", "true");
 135         props2.setProperty("test.checkHandlersOn", "com.foo");
 136         props2.setProperty("com.bar.level", "FINEST");
 137 
 138         Properties props3 = new Properties();
 139         props3.setProperty("test.name", "parent logger with handler");
 140         props3.setProperty(FileHandler.class.getName() + ".pattern", PREFIX);
 141         props3.setProperty(FileHandler.class.getName() + ".limit", String.valueOf(Integer.MAX_VALUE));
 142         props3.setProperty(FileHandler.class.getName() + ".level", "ALL");
 143         props3.setProperty(FileHandler.class.getName() + ".formatter", "java.util.logging.SimpleFormatter");
 144         props3.setProperty("com.foo.handlers", FileHandler.class.getName());
 145         props3.setProperty("test.checkHandlersOnParent", "true");
 146         props3.setProperty("test.checkHandlersOn", "com.foo");
 147         props3.setProperty("com.bar.level", "FINEST");
 148 
 149         Properties props4 = new Properties();
 150         props4.setProperty("java.util.logging.LogManager.reconfigureHandlers", "true");
 151         props4.setProperty(FileHandler.class.getName() + ".pattern", PREFIX);
 152         props4.setProperty(FileHandler.class.getName() + ".limit", String.valueOf(Integer.MAX_VALUE));
 153         props4.setProperty(FileHandler.class.getName() + ".level", "ALL");
 154         props4.setProperty(FileHandler.class.getName() + ".formatter", "java.util.logging.SimpleFormatter");
 155         props4.setProperty("test.checkHandlersOnParent", "true");
 156         props4.setProperty("test.checkHandlersOn", "com.foo");
 157         props4.setProperty("com.foo.handlers", FileHandler.class.getName());
 158 
 159         Properties props5 = new Properties();
 160         props5.setProperty("test.name", "parent logger with handler");
 161         props5.setProperty(FileHandler.class.getName() + ".pattern", PREFIX);
 162         props5.setProperty(FileHandler.class.getName() + ".limit", String.valueOf(Integer.MAX_VALUE));
 163         props5.setProperty(FileHandler.class.getName() + ".level", "ALL");
 164         props5.setProperty(FileHandler.class.getName() + ".formatter", "java.util.logging.SimpleFormatter");
 165         props5.setProperty("test.checkHandlersOnParent", "false");
 166         props5.setProperty("test.checkHandlersOn", "com");
 167         props5.setProperty("com.handlers", FileHandler.class.getName());
 168 
 169         properties = Collections.unmodifiableList(Arrays.asList(
 170                     props1, props2, props3, props4, props5));
 171     }
 172 
 173     /**
 174      * This is the main test method. The rest is infrastructure.
 175      * Creates a child of the 'com.foo' logger (com.foo.child) and holds on to
 176      * it.
 177      * <p>
 178      * Then applies all given configurations in sequence and verifies assumptions
 179      * about the handlers that com.foo should have, or not have.
 180      * In the last configuration (props5) it also verifies that the
 181      * logger 'com' has been created and has now the expected handler.
 182      * <p>
 183      * Finally releases the child logger after all configurations have been
 184      * applied.
 185      *
 186      * @param name
 187      * @param properties
 188      * @throws Exception
 189      */
 190     static void test(String name, List<Properties> properties)
 191             throws Exception {
 192 
 193         System.out.println("\nTesting: " + name);
 194         if (!userDirWritable) {
 195             throw new RuntimeException("Not writable: "+userDir);
 196         }
 197 
 198         // Then create a child of the com.foo logger.
 199         Logger fooChild = Logger.getLogger("com.foo.child");
 200         fooChild.info("hello world");
 201         Logger barChild = Logger.getLogger("com.bar.child");
 202         barChild.info("hello world");
 203 
 204         ReferenceQueue<Logger> queue = new ReferenceQueue();
 205         WeakReference<Logger> fooRef = new WeakReference<>(Logger.getLogger("com.foo"), queue);
 206         if (fooRef.get() != fooChild.getParent()) {
 207             throw new RuntimeException("Unexpected parent logger: "
 208                     + fooChild.getParent() +"\n\texpected: " + fooRef.get());
 209         }
 210         WeakReference<Logger> barRef = new WeakReference<>(Logger.getLogger("com.bar"), queue);
 211         if (barRef.get() != barChild.getParent()) {
 212             throw new RuntimeException("Unexpected parent logger: "
 213                     + barChild.getParent() +"\n\texpected: " + barRef.get());
 214         }
 215         Reference<? extends Logger> ref2;
 216         int max = 3;
 217         barChild = null;
 218         while ((ref2 = queue.poll()) == null) {
 219             System.gc();
 220             Thread.sleep(100);
 221             if (--max == 0) break;
 222         }
 223 
 224         Throwable failed = null;
 225         try {
 226             if (ref2 != null) {
 227                 String refName = ref2 == fooRef ? "fooRef" : ref2 == barRef ? "barRef" : "unknown";
 228                 if (ref2 != barRef) {
 229                     throw new RuntimeException("Unexpected logger reference cleared: " + refName);
 230                 } else {
 231                     System.out.println("Reference " + refName + " cleared as expected");
 232                 }
 233             } else if (ref2 == null) {
 234                 throw new RuntimeException("Expected 'barRef' to be cleared");
 235             }
 236             // Now lets try to reset, check that ref2 has no handlers, and
 237             // attempt to configure again.
 238             Properties previousProps  = properties.get(0);
 239             int expectedHandlersCount = 1;
 240             boolean checkHandlersOnParent = Boolean.parseBoolean(
 241                     previousProps.getProperty("test.checkHandlersOnParent", "true"));
 242             String checkHandlersOn = previousProps.getProperty("test.checkHandlersOn", null);
 243             for (int i=1; i<properties.size(); i++) {
 244                 System.out.println("\n*** Reconfiguration with properties["+i+"]\n");
 245                 Properties nextProps = properties.get(i);
 246                 boolean reconfigureHandlers = true;
 247 
 248                 if (checkHandlersOnParent) {
 249                     assertEquals(expectedHandlersCount,
 250                             fooChild.getParent().getHandlers().length,
 251                             "fooChild.getParent().getHandlers().length");
 252                 }
 253                 if (checkHandlersOn != null) {
 254                     Logger loggerWithHandlers = LogManager.getLogManager().getLogger(checkHandlersOn);
 255                     if (loggerWithHandlers == null) {
 256                         throw new RuntimeException("Logger with handlers not found: " + checkHandlersOn);
 257                     }
 258                     assertEquals(expectedHandlersCount,
 259                             loggerWithHandlers.getHandlers().length,
 260                             checkHandlersOn + ".getHandlers().length");
 261                 }
 262 
 263                 // Reset
 264                 Configure.doPrivileged(() -> LogManager.getLogManager().reset());
 265                 assertEquals(0, fooChild.getParent().getHandlers().length, "fooChild.getParent().getHandlers().length");
 266                 if (checkHandlersOn != null) {
 267                     Logger loggerWithHandlers = LogManager.getLogManager().getLogger(checkHandlersOn);
 268                     if (loggerWithHandlers == null) {
 269                         throw new RuntimeException("Logger with handlers not found: " + checkHandlersOn);
 270                     }
 271                     assertEquals(0, loggerWithHandlers.getHandlers().length,
 272                             checkHandlersOn + ".getHandlers().length");
 273                 }
 274 
 275                 if (i == 4) {
 276                     System.out.println("Last configuration...");
 277                 }
 278                 // Read configuration
 279                 Configure.doPrivileged(() -> Configure.updateConfigurationWith(nextProps, false));
 280 
 281                 expectedHandlersCount = reconfigureHandlers ? 1 : 0;
 282                 checkHandlersOnParent = Boolean.parseBoolean(
 283                     nextProps.getProperty("test.checkHandlersOnParent", "true"));
 284                 checkHandlersOn = nextProps.getProperty("test.checkHandlersOn", null);
 285 
 286                 if (checkHandlersOnParent) {
 287                     assertEquals(expectedHandlersCount,
 288                         fooChild.getParent().getHandlers().length,
 289                         "fooChild.getParent().getHandlers().length");
 290                 } else {
 291                     assertEquals(0,
 292                         fooChild.getParent().getHandlers().length,
 293                         "fooChild.getParent().getHandlers().length");
 294                 }
 295                 if (checkHandlersOn != null) {
 296                     Logger loggerWithHandlers = LogManager.getLogManager().getLogger(checkHandlersOn);
 297                     if (loggerWithHandlers == null) {
 298                         throw new RuntimeException("Logger with handlers not found: " + checkHandlersOn);
 299                     }
 300                     assertEquals(expectedHandlersCount,
 301                             loggerWithHandlers.getHandlers().length,
 302                             checkHandlersOn + ".getHandlers().length");
 303                 }
 304             }
 305         } catch (Throwable t) {
 306             failed = t;
 307         } finally {
 308             final Throwable suppressed = failed;
 309             Configure.doPrivileged(() -> LogManager.getLogManager().reset());
 310             Configure.doPrivileged(() -> {
 311                 try {
 312                     StringBuilder builder = new StringBuilder();
 313                     Files.list(Paths.get(userDir))
 314                         .filter((f) -> f.toString().contains(PREFIX))
 315                         .filter((f) -> f.toString().endsWith(".lck"))
 316                         .forEach((f) -> {
 317                                 builder.append(f.toString()).append('\n');
 318                         });
 319                     if (!builder.toString().isEmpty()) {
 320                         throw new RuntimeException("Lock files not cleaned:\n"
 321                                 + builder.toString());
 322                     }
 323                 } catch(RuntimeException | Error x) {
 324                     if (suppressed != null) x.addSuppressed(suppressed);
 325                     throw x;
 326                 } catch(Exception x) {
 327                     if (suppressed != null) x.addSuppressed(suppressed);
 328                     throw new RuntimeException(x);
 329                 }
 330             });
 331             fooChild = null;
 332             System.out.println("Setting fooChild to: " + fooChild);
 333             while ((ref2 = queue.poll()) == null) {
 334                 System.gc();
 335                 Thread.sleep(1000);
 336             }
 337             if (ref2 != fooRef) {
 338                 throw new RuntimeException("Unexpected reference: "
 339                         + ref2 +"\n\texpected: " + fooRef);
 340             }
 341             if (ref2.get() != null) {
 342                 throw new RuntimeException("Referent not cleared: " + ref2.get());
 343             }
 344             System.out.println("Got fooRef after reset(), fooChild is " + fooChild);
 345 
 346         }
 347         if (failed != null) {
 348             // should rarely happen...
 349             throw new RuntimeException(failed);
 350         }
 351 
 352     }
 353 
 354     public static void main(String... args) throws Exception {
 355 
 356 
 357         if (args == null || args.length == 0) {
 358             args = new String[] {
 359                 TestCase.UNSECURE.name(),
 360                 TestCase.SECURE.name(),
 361             };
 362         }
 363 
 364         try {
 365             for (String testName : args) {
 366                 TestCase test = TestCase.valueOf(testName);
 367                 test.run(properties);
 368             }
 369         } finally {
 370             if (userDirWritable) {
 371                 Configure.doPrivileged(() -> {
 372                     // cleanup - delete files that have been created
 373                     try {
 374                         Files.list(Paths.get(userDir))
 375                             .filter((f) -> f.toString().contains(PREFIX))
 376                             .forEach((f) -> {
 377                                 try {
 378                                     System.out.println("deleting " + f);
 379                                     Files.delete(f);
 380                                 } catch(Throwable t) {
 381                                     System.err.println("Failed to delete " + f + ": " + t);
 382                                 }
 383                             });
 384                     } catch(Throwable t) {
 385                         System.err.println("Cleanup failed to list files: " + t);
 386                         t.printStackTrace();
 387                     }
 388                 });
 389             }
 390         }
 391     }
 392 
 393     static class Configure {
 394         static Policy policy = null;
 395         static final ThreadLocal<AtomicBoolean> allowAll = new ThreadLocal<AtomicBoolean>() {
 396             @Override
 397             protected AtomicBoolean initialValue() {
 398                 return  new AtomicBoolean(false);
 399             }
 400         };
 401         static void setUp(TestCase test, Properties propertyFile) {
 402             switch (test) {
 403                 case SECURE:
 404                     if (policy == null && System.getSecurityManager() != null) {
 405                         throw new IllegalStateException("SecurityManager already set");
 406                     } else if (policy == null) {
 407                         policy = new SimplePolicy(TestCase.SECURE, allowAll);
 408                         Policy.setPolicy(policy);
 409                         System.setSecurityManager(new SecurityManager());
 410                     }
 411                     if (System.getSecurityManager() == null) {
 412                         throw new IllegalStateException("No SecurityManager.");
 413                     }
 414                     if (policy == null) {
 415                         throw new IllegalStateException("policy not configured");
 416                     }
 417                     break;
 418                 case UNSECURE:
 419                     if (System.getSecurityManager() != null) {
 420                         throw new IllegalStateException("SecurityManager already set");
 421                     }
 422                     break;
 423                 default:
 424                     new InternalError("No such testcase: " + test);
 425             }
 426             doPrivileged(() -> {
 427                 updateConfigurationWith(propertyFile, false);
 428             });
 429         }
 430 
 431         static void updateConfigurationWith(Properties propertyFile, boolean append) {
 432             try {
 433                 ByteArrayOutputStream bytes = new ByteArrayOutputStream();
 434                 propertyFile.store(bytes, propertyFile.getProperty("test.name"));
 435                 ByteArrayInputStream bais = new ByteArrayInputStream(bytes.toByteArray());
 436                 Function<String, BiFunction<String,String,String>> remapper =
 437                         append ? (x) -> ((o, n) -> n == null ? o : n)
 438                                : (x) -> ((o, n) -> n);
 439                 LogManager.getLogManager().updateConfiguration(bais, remapper);
 440             } catch (IOException ex) {
 441                 throw new RuntimeException(ex);
 442             }
 443         }
 444 
 445         static void doPrivileged(Runnable run) {
 446             final boolean old = allowAll.get().getAndSet(true);
 447             try {
 448                 run.run();
 449             } finally {
 450                 allowAll.get().set(old);
 451             }
 452         }
 453         static <T> T callPrivileged(Callable<T> call) throws Exception {
 454             final boolean old = allowAll.get().getAndSet(true);
 455             try {
 456                 return call.call();
 457             } finally {
 458                 allowAll.get().set(old);
 459             }
 460         }
 461     }
 462 
 463     @FunctionalInterface
 464     public static interface FileHandlerSupplier {
 465         public FileHandler test() throws Exception;
 466     }
 467 
 468     static final class TestAssertException extends RuntimeException {
 469         TestAssertException(String msg) {
 470             super(msg);
 471         }
 472     }
 473 
 474     private static void assertEquals(long expected, long received, String msg) {
 475         if (expected != received) {
 476             throw new TestAssertException("Unexpected result for " + msg
 477                     + ".\n\texpected: " + expected
 478                     +  "\n\tactual:   " + received);
 479         } else {
 480             System.out.println("Got expected " + msg + ": " + received);
 481         }
 482     }
 483 
 484     final static class PermissionsBuilder {
 485         final Permissions perms;
 486         public PermissionsBuilder() {
 487             this(new Permissions());
 488         }
 489         public PermissionsBuilder(Permissions perms) {
 490             this.perms = perms;
 491         }
 492         public PermissionsBuilder add(Permission p) {
 493             perms.add(p);
 494             return this;
 495         }
 496         public PermissionsBuilder addAll(PermissionCollection col) {
 497             if (col != null) {
 498                 for (Enumeration<Permission> e = col.elements(); e.hasMoreElements(); ) {
 499                     perms.add(e.nextElement());
 500                 }
 501             }
 502             return this;
 503         }
 504         public Permissions toPermissions() {
 505             final PermissionsBuilder builder = new PermissionsBuilder();
 506             builder.addAll(perms);
 507             return builder.perms;
 508         }
 509     }
 510 
 511     public static class SimplePolicy extends Policy {
 512 
 513         final Permissions permissions;
 514         final Permissions allPermissions;
 515         final ThreadLocal<AtomicBoolean> allowAll; // actually: this should be in a thread locale
 516         public SimplePolicy(TestCase test, ThreadLocal<AtomicBoolean> allowAll) {
 517             this.allowAll = allowAll;
 518             permissions = new Permissions();
 519             permissions.add(new LoggingPermission("control", null));
 520             permissions.add(new FilePermission(PREFIX+".lck", "read,write,delete"));
 521             permissions.add(new FilePermission(PREFIX, "read,write"));
 522 
 523             // these are used for configuring the test itself...
 524             allPermissions = new Permissions();
 525             allPermissions.add(new java.security.AllPermission());
 526 
 527         }
 528 
 529         @Override
 530         public boolean implies(ProtectionDomain domain, Permission permission) {
 531             if (allowAll.get().get()) return allPermissions.implies(permission);
 532             return permissions.implies(permission);
 533         }
 534 
 535         @Override
 536         public PermissionCollection getPermissions(CodeSource codesource) {
 537             return new PermissionsBuilder().addAll(allowAll.get().get()
 538                     ? allPermissions : permissions).toPermissions();
 539         }
 540 
 541         @Override
 542         public PermissionCollection getPermissions(ProtectionDomain domain) {
 543             return new PermissionsBuilder().addAll(allowAll.get().get()
 544                     ? allPermissions : permissions).toPermissions();
 545         }
 546     }
 547 
 548 }