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 }