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