001/**
002 * Logback: the reliable, generic, fast and flexible logging framework.
003 * Copyright (C) 1999-2015, QOS.ch. All rights reserved.
004 *
005 * This program and the accompanying materials are dual-licensed under
006 * either the terms of the Eclipse Public License v1.0 as published by
007 * the Eclipse Foundation
008 *
009 *   or (per the licensee's choosing)
010 *
011 * under the terms of the GNU Lesser General Public License version 2.1
012 * as published by the Free Software Foundation.
013 */
014package ch.qos.logback.classic.turbo;
015
016import static ch.qos.logback.core.CoreConstants.MILLIS_IN_ONE_SECOND;
017
018import java.io.File;
019import java.net.URL;
020import java.util.List;
021
022import org.slf4j.Marker;
023
024import ch.qos.logback.classic.Level;
025import ch.qos.logback.classic.Logger;
026import ch.qos.logback.classic.LoggerContext;
027import ch.qos.logback.classic.joran.JoranConfigurator;
028import ch.qos.logback.core.CoreConstants;
029import ch.qos.logback.core.joran.spi.ConfigurationWatchList;
030import ch.qos.logback.core.joran.spi.JoranException;
031import ch.qos.logback.core.joran.util.ConfigurationWatchListUtil;
032import ch.qos.logback.core.model.Model;
033import ch.qos.logback.core.model.ModelUtil;
034import ch.qos.logback.core.spi.FilterReply;
035import ch.qos.logback.core.status.StatusUtil;
036
037/**
038 * Reconfigure a LoggerContext when the configuration file changes.
039 *
040 * @author Ceki Gulcu
041 */
042public class ReconfigureOnChangeFilter extends TurboFilter {
043
044    /**
045     * Scan for changes in configuration file once every minute.
046     */
047    // 1 minute - value mentioned in documentation
048    public final static long DEFAULT_REFRESH_PERIOD = 60 * MILLIS_IN_ONE_SECOND;
049
050    long refreshPeriod = DEFAULT_REFRESH_PERIOD;
051    URL mainConfigurationURL;
052    protected volatile long nextCheck;
053
054    ConfigurationWatchList configurationWatchList;
055
056    @Override
057    public void start() {
058        configurationWatchList = ConfigurationWatchListUtil.getConfigurationWatchList(context);
059        if (configurationWatchList != null) {
060            mainConfigurationURL = configurationWatchList.getMainURL();
061            if (mainConfigurationURL == null) {
062                addWarn("Due to missing top level configuration file, automatic reconfiguration is impossible.");
063                return;
064            }
065            List<File> watchList = configurationWatchList.getCopyOfFileWatchList();
066            long inSeconds = refreshPeriod / 1000;
067            addInfo("Will scan for changes in [" + watchList + "] every " + inSeconds + " seconds. ");
068            synchronized (configurationWatchList) {
069                updateNextCheck(System.currentTimeMillis());
070            }
071            super.start();
072        } else {
073            addWarn("Empty ConfigurationWatchList in context");
074        }
075    }
076
077    @Override
078    public String toString() {
079        return "ReconfigureOnChangeFilter{" + "invocationCounter=" + invocationCounter + '}';
080    }
081
082    // The next fields counts the number of time the decide method is called
083    //
084    // IMPORTANT: This field can be updated by multiple threads. It follows that
085    // its values may *not* be incremented sequentially. However, we don't care
086    // about the actual value of the field except that from time to time the
087    // expression (invocationCounter++ & mask) == mask) should be true.
088    private long invocationCounter = 0;
089
090    private volatile long mask = 0xF;
091    private volatile long lastMaskCheck = System.currentTimeMillis();
092
093    @Override
094    public FilterReply decide(Marker marker, Logger logger, Level level, String format, Object[] params, Throwable t) {
095        if (!isStarted()) {
096            return FilterReply.NEUTRAL;
097        }
098
099        // 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
124    // 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
129    // of updateMaskIfNecessary() method,
130    // then the mask should be increased
131    private static final long MASK_INCREASE_THRESHOLD = 100;
132
133    // if more than MASK_DECREASE_THRESHOLD milliseconds elapse between invocations
134    // of updateMaskIfNecessary() method,
135    // then the mask should be decreased
136    private static final long MASK_DECREASE_THRESHOLD = MASK_INCREASE_THRESHOLD * 8;
137
138    // update the mask so as to execute change detection code about once every 100
139    // to 8000 milliseconds.
140    private void updateMaskIfNecessary(long now) {
141        final long timeElapsedSinceLastMaskUpdateCheck = now - lastMaskCheck;
142        lastMaskCheck = now;
143        if (timeElapsedSinceLastMaskUpdateCheck < MASK_INCREASE_THRESHOLD && (mask < MAX_MASK)) {
144            mask = (mask << 1) | 1;
145        } else if (timeElapsedSinceLastMaskUpdateCheck > MASK_DECREASE_THRESHOLD) {
146            mask = mask >>> 2;
147        }
148    }
149
150    // by detaching reconfiguration to a new thread, we release the various
151    // locks held by the current thread, in particular, the AppenderAttachable
152    // reader lock.
153    void detachReconfigurationToNewThread() {
154        addInfo("Detected change in [" + configurationWatchList.getCopyOfFileWatchList() + "]");
155        context.getScheduledExecutorService().submit(new ReconfiguringThread());
156    }
157
158    void updateNextCheck(long now) {
159        nextCheck = now + refreshPeriod;
160    }
161
162    protected boolean changeDetected(long now) {
163        if (now >= nextCheck) {
164            updateNextCheck(now);
165            return configurationWatchList.changeDetected();
166        }
167        return false;
168    }
169
170    void disableSubsequentReconfiguration() {
171        nextCheck = Long.MAX_VALUE;
172    }
173
174    public long getRefreshPeriod() {
175        return refreshPeriod;
176    }
177
178    public void setRefreshPeriod(long refreshPeriod) {
179        this.refreshPeriod = refreshPeriod;
180    }
181
182    class ReconfiguringThread implements Runnable {
183        public void run() {
184            if (mainConfigurationURL == null) {
185                addInfo("Due to missing top level configuration file, skipping reconfiguration");
186                return;
187            }
188            LoggerContext lc = (LoggerContext) context;
189            addInfo(CoreConstants.RESET_MSG_PREFIX + "named [" + context.getName() + "]");
190            if (mainConfigurationURL.toString().endsWith("xml")) {
191                performXMLConfiguration(lc);
192            } else if (mainConfigurationURL.toString().endsWith("groovy")) {
193                addError("Groovy configuration disabled due to Java 9 compilation issues.");
194            }
195        }
196
197        private void performXMLConfiguration(LoggerContext lc) {
198            JoranConfigurator jc = new JoranConfigurator();
199            jc.setContext(context);
200            StatusUtil statusUtil = new StatusUtil(context);
201            Model failSafeTop = jc.recallSafeConfiguration();
202            URL mainURL = ConfigurationWatchListUtil.getMainWatchURL(context);
203            lc.reset();
204            long threshold = System.currentTimeMillis();
205            try {
206                jc.doConfigure(mainConfigurationURL);
207                if (statusUtil.hasXMLParsingErrors(threshold)) {
208                    fallbackConfiguration(lc, failSafeTop, mainURL);
209                }
210            } catch (JoranException e) {
211                fallbackConfiguration(lc, failSafeTop, mainURL);
212            }
213        }
214
215        private void fallbackConfiguration(LoggerContext lc, Model failSafeTop, URL mainURL) {
216            JoranConfigurator joranConfigurator = new JoranConfigurator();
217            joranConfigurator.setContext(context);
218            if (failSafeTop != null) {
219                addWarn("Falling back to previously registered safe configuration.");
220                try {
221                    lc.reset();
222                    JoranConfigurator.informContextOfURLUsedForConfiguration(context, mainURL);
223                    ModelUtil.resetForReuse(failSafeTop);
224                    joranConfigurator.processModel(failSafeTop);
225                    addInfo("Re-registering previous fallback configuration once more as a fallback configuration point");
226                    joranConfigurator.registerSafeConfiguration(failSafeTop);
227                } catch (Exception e) {
228                    addError("Unexpected exception thrown by a configuration considered safe.", e);
229                }
230            } else {
231                addWarn("No previous configuration to fall back on.");
232            }
233        }
234    }
235}