View Javadoc
1   /**
2    * Logback: the reliable, generic, fast and flexible logging framework.
3    * Copyright (C) 1999-2015, QOS.ch. All rights reserved.
4    *
5    * This program and the accompanying materials are dual-licensed under
6    * either the terms of the Eclipse Public License v1.0 as published by
7    * the Eclipse Foundation
8    *
9    *   or (per the licensee's choosing)
10   *
11   * under the terms of the GNU Lesser General Public License version 2.1
12   * as published by the Free Software Foundation.
13   */
14  package ch.qos.logback.classic.turbo;
15  
16  import java.io.File;
17  import java.net.URL;
18  import java.util.List;
19  
20  import ch.qos.logback.classic.util.EnvUtil;
21  import ch.qos.logback.core.CoreConstants;
22  import ch.qos.logback.core.joran.event.SaxEvent;
23  import ch.qos.logback.core.joran.spi.ConfigurationWatchList;
24  import ch.qos.logback.core.joran.util.ConfigurationWatchListUtil;
25  import ch.qos.logback.core.status.StatusUtil;
26  import org.slf4j.Marker;
27  
28  import ch.qos.logback.classic.Level;
29  import ch.qos.logback.classic.Logger;
30  import ch.qos.logback.classic.LoggerContext;
31  import ch.qos.logback.classic.joran.JoranConfigurator;
32  import ch.qos.logback.core.joran.spi.JoranException;
33  import ch.qos.logback.core.spi.FilterReply;
34  
35  import static ch.qos.logback.core.CoreConstants.MILLIS_IN_ONE_SECOND;
36  
37  /**
38   * Reconfigure a LoggerContext when the configuration file changes.
39   *
40   * @author Ceki Gulcu
41   */
42  public class ReconfigureOnChangeFilter extends TurboFilter {
43  
44      /**
45       * Scan for changes in configuration file once every minute.
46       */
47      // 1 minute - value mentioned in documentation
48      public final static long DEFAULT_REFRESH_PERIOD = 60 * MILLIS_IN_ONE_SECOND;
49  
50      long refreshPeriod = DEFAULT_REFRESH_PERIOD;
51      URL mainConfigurationURL;
52      protected volatile long nextCheck;
53  
54      ConfigurationWatchList configurationWatchList;
55  
56      @Override
57      public void start() {
58          configurationWatchList = ConfigurationWatchListUtil.getConfigurationWatchList(context);
59          if (configurationWatchList != null) {
60              mainConfigurationURL = configurationWatchList.getMainURL();
61              if (mainConfigurationURL == null) {
62                  addWarn("Due to missing top level configuration file, automatic reconfiguration is impossible.");
63                  return;
64              }
65              List<File> watchList = configurationWatchList.getCopyOfFileWatchList();
66              long inSeconds = refreshPeriod / 1000;
67              addInfo("Will scan for changes in [" + watchList + "] every " + inSeconds + " seconds. ");
68              synchronized (configurationWatchList) {
69                  updateNextCheck(System.currentTimeMillis());
70              }
71              super.start();
72          } else {
73              addWarn("Empty ConfigurationWatchList in context");
74          }
75      }
76  
77      @Override
78      public String toString() {
79          return "ReconfigureOnChangeFilter{" + "invocationCounter=" + invocationCounter + '}';
80      }
81  
82      // The next fields counts the number of time the decide method is called
83      //
84      // IMPORTANT: This field can be updated by multiple threads. It follows that
85      // its values may *not* be incremented sequentially. However, we don't care
86      // about the actual value of the field except that from time to time the
87      // expression (invocationCounter++ & mask) == mask) should be true.
88      private long invocationCounter = 0;
89  
90      private volatile long mask = 0xF;
91      private volatile long lastMaskCheck = System.currentTimeMillis();
92  
93      @Override
94      public FilterReply decide(Marker marker, Logger logger, Level level, String format, Object[] params, Throwable t) {
95          if (!isStarted()) {
96              return FilterReply.NEUTRAL;
97          }
98  
99          // for performance reasons, skip change detection (MASK-1) times out of MASK.
100         // Only once every MASK calls is change detection code executed
101         // Note that MASK is a variable itself.
102         if (((invocationCounter++) & mask) != mask) {
103             return FilterReply.NEUTRAL;
104         }
105 
106         long now = System.currentTimeMillis();
107 
108         synchronized (configurationWatchList) {
109             updateMaskIfNecessary(now);
110             if (changeDetected(now)) {
111                 // Even though reconfiguration involves resetting the loggerContext,
112                 // which clears the list of turbo filters including this instance, it is
113                 // still possible for this instance to be subsequently invoked by another
114                 // thread if it was already executing when the context was reset.
115                 disableSubsequentReconfiguration();
116                 detachReconfigurationToNewThread();
117             }
118         }
119 
120         return FilterReply.NEUTRAL;
121     }
122 
123     // experiments indicate that even for CPU intensive applications with 200 or more threads MASK
124     // values in the order of 0xFFFF is appropriate
125     private static final int MAX_MASK = 0xFFFF;
126 
127     // if less than MASK_INCREASE_THRESHOLD milliseconds elapse between invocations of updateMaskIfNecessary() method,
128     // then the mask should be increased
129     private static final long MASK_INCREASE_THRESHOLD = 100;
130 
131     // if more than MASK_DECREASE_THRESHOLD milliseconds elapse between invocations of updateMaskIfNecessary() method,
132     // then the mask should be decreased
133     private static final long MASK_DECREASE_THRESHOLD = MASK_INCREASE_THRESHOLD * 8;
134 
135     // update the mask so as to execute change detection code about once every 100 to 8000 milliseconds.
136     private void updateMaskIfNecessary(long now) {
137         final long timeElapsedSinceLastMaskUpdateCheck = now - lastMaskCheck;
138         lastMaskCheck = now;
139         if (timeElapsedSinceLastMaskUpdateCheck < MASK_INCREASE_THRESHOLD && (mask < MAX_MASK)) {
140             mask = (mask << 1) | 1;
141         } else if (timeElapsedSinceLastMaskUpdateCheck > MASK_DECREASE_THRESHOLD) {
142             mask = mask >>> 2;
143         }
144     }
145 
146     // by detaching reconfiguration to a new thread, we release the various
147     // locks held by the current thread, in particular, the AppenderAttachable
148     // reader lock.
149     void detachReconfigurationToNewThread() {
150         addInfo("Detected change in [" + configurationWatchList.getCopyOfFileWatchList() + "]");
151         context.getScheduledExecutorService().submit(new ReconfiguringThread());
152     }
153 
154     void updateNextCheck(long now) {
155         nextCheck = now + refreshPeriod;
156     }
157 
158     protected boolean changeDetected(long now) {
159         if (now >= nextCheck) {
160             updateNextCheck(now);
161             return configurationWatchList.changeDetected();
162         }
163         return false;
164     }
165 
166     void disableSubsequentReconfiguration() {
167         nextCheck = Long.MAX_VALUE;
168     }
169 
170     public long getRefreshPeriod() {
171         return refreshPeriod;
172     }
173 
174     public void setRefreshPeriod(long refreshPeriod) {
175         this.refreshPeriod = refreshPeriod;
176     }
177 
178     class ReconfiguringThread implements Runnable {
179         public void run() {
180             if (mainConfigurationURL == null) {
181                 addInfo("Due to missing top level configuration file, skipping reconfiguration");
182                 return;
183             }
184             LoggerContext lc = (LoggerContext) context;
185             addInfo(CoreConstants.RESET_MSG_PREFIX + "named [" + context.getName() + "]");
186             if (mainConfigurationURL.toString().endsWith("xml")) {
187                 performXMLConfiguration(lc);
188             } else if (mainConfigurationURL.toString().endsWith("groovy")) {
189                 if (EnvUtil.isGroovyAvailable()) {
190                     lc.reset();
191                     // avoid directly referring to GafferConfigurator so as to avoid
192                     // loading groovy.lang.GroovyObject . See also http://jira.qos.ch/browse/LBCLASSIC-214
193 
194                     // GafferUtil.runGafferConfiguratorOn(lc, this, mainConfigurationURL);
195                     addError("Groovy configuration disabled due to Java 9 compilation issues.");
196 
197                 } else {
198                     addError("Groovy classes are not available on the class path. ABORTING INITIALIZATION.");
199                 }
200             }
201         }
202 
203         private void performXMLConfiguration(LoggerContext lc) {
204             JoranConfigurator jc = new JoranConfigurator();
205             jc.setContext(context);
206             StatusUtil statusUtil = new StatusUtil(context);
207             List<SaxEvent> eventList = jc.recallSafeConfiguration();
208             URL mainURL = ConfigurationWatchListUtil.getMainWatchURL(context);
209             lc.reset();
210             long threshold = System.currentTimeMillis();
211             try {
212                 jc.doConfigure(mainConfigurationURL);
213                 if (statusUtil.hasXMLParsingErrors(threshold)) {
214                     fallbackConfiguration(lc, eventList, mainURL);
215                 }
216             } catch (JoranException e) {
217                 fallbackConfiguration(lc, eventList, mainURL);
218             }
219         }
220 
221         private void fallbackConfiguration(LoggerContext lc, List<SaxEvent> eventList, URL mainURL) {
222             JoranConfigurator joranConfigurator = new JoranConfigurator();
223             joranConfigurator.setContext(context);
224             if (eventList != null) {
225                 addWarn("Falling back to previously registered safe configuration.");
226                 try {
227                     lc.reset();
228                     JoranConfigurator.informContextOfURLUsedForConfiguration(context, mainURL);
229                     joranConfigurator.doConfigure(eventList);
230                     addInfo("Re-registering previous fallback configuration once more as a fallback configuration point");
231                     joranConfigurator.registerSafeConfiguration(eventList);
232                 } catch (JoranException e) {
233                     addError("Unexpected exception thrown by a configuration considered safe.", e);
234                 }
235             } else {
236                 addWarn("No previous configuration to fall back on.");
237             }
238         }
239     }
240 }