Source code

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.sift;
015
016import static org.junit.Assert.assertEquals;
017import static org.junit.Assert.assertFalse;
018import static org.junit.Assert.assertNotNull;
019import static org.junit.Assert.assertNull;
020import static org.junit.Assert.assertTrue;
021import static ch.qos.logback.core.testUtil.CoreTestConstants.OUTPUT_DIR_PREFIX;
022import static org.assertj.core.api.Assertions.*;
023
024import java.util.List;
025
026import org.junit.After;
027import org.junit.Before;
028import org.junit.Ignore;
029import org.junit.Test;
030import org.slf4j.MDC;
031
032import ch.qos.logback.classic.ClassicConstants;
033import ch.qos.logback.classic.ClassicTestConstants;
034import ch.qos.logback.classic.Level;
035import ch.qos.logback.classic.Logger;
036import ch.qos.logback.classic.LoggerContext;
037import ch.qos.logback.classic.encoder.PatternLayoutEncoder;
038import ch.qos.logback.classic.joran.JoranConfigurator;
039import ch.qos.logback.classic.spi.ILoggingEvent;
040import ch.qos.logback.classic.spi.LoggingEvent;
041import ch.qos.logback.core.Appender;
042import ch.qos.logback.core.Context;
043import ch.qos.logback.core.FileAppender;
044import ch.qos.logback.core.helpers.NOPAppender;
045import ch.qos.logback.core.joran.spi.JoranException;
046import ch.qos.logback.core.read.ListAppender;
047import ch.qos.logback.core.rolling.RollingFileAppender;
048import ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP;
049import ch.qos.logback.core.rolling.TimeBasedRollingPolicy;
050import ch.qos.logback.core.sift.AppenderFactory;
051import ch.qos.logback.core.sift.AppenderTracker;
052import ch.qos.logback.core.spi.AbstractComponentTracker;
053import ch.qos.logback.core.spi.ComponentTracker;
054import ch.qos.logback.core.status.ErrorStatus;
055import ch.qos.logback.core.testUtil.CoreTestConstants;
056import ch.qos.logback.core.testUtil.RandomUtil;
057import ch.qos.logback.core.testUtil.StatusChecker;
058import ch.qos.logback.core.testUtil.StringListAppender;
059import ch.qos.logback.core.util.FileSize;
060import ch.qos.logback.core.util.StatusPrinter;
061
062public class SiftingAppenderTest {
063
064    static String SIFT_FOLDER_PREFIX = ClassicTestConstants.JORAN_INPUT_PREFIX + "sift/";
065
066    LoggerContext loggerContext = new LoggerContext();
067    Logger logger = loggerContext.getLogger(this.getClass().getName());
068    Logger root = loggerContext.getLogger(Logger.ROOT_LOGGER_NAME);
069    StatusChecker statusChecker = new StatusChecker(loggerContext);
070    int diff = RandomUtil.getPositiveInt();
071    String randomOutputDir = OUTPUT_DIR_PREFIX + diff + "/";
072    int now = 0;
073
074    protected void configure(String file) throws JoranException {
075        JoranConfigurator jc = new JoranConfigurator();
076        jc.setContext(loggerContext);
077        jc.doConfigure(file);
078    }
079
080    @Before
081    public void setUp() {
082        MDC.clear();
083    }
084
085    @After
086    public void tearDown() {
087        MDC.clear();
088    }
089
090    @Test
091    public void unsetDefaultValueProperty() throws JoranException {
092        configure(SIFT_FOLDER_PREFIX + "unsetDefaultValueProperty.xml");
093        logger.debug("hello");
094        SiftingAppender sa = (SiftingAppender) root.getAppender("SIFT");
095        assertFalse(sa.isStarted());
096    }
097
098    @Test
099    public void smoke() throws JoranException {
100        configure(SIFT_FOLDER_PREFIX + "smoke.xml");
101        logger.debug("smoke");
102        Appender<ILoggingEvent> appender = getAppenderTracker().find("smokeDefault");
103        assertNotNull(appender);
104        ListAppender<ILoggingEvent> listAppender = (ListAppender<ILoggingEvent>) appender;
105        List<ILoggingEvent> eventList = listAppender.list;
106        assertEquals(1, listAppender.list.size());
107        assertEquals("smoke", eventList.get(0).getMessage());
108    }
109
110    private AppenderTracker<ILoggingEvent> getAppenderTracker() {
111        SiftingAppender ha = (SiftingAppender) root.getAppender("SIFT");
112        return ha.getAppenderTracker();
113    }
114
115    @Test
116    public void zeroNesting() throws JoranException {
117        configure(SIFT_FOLDER_PREFIX + "zeroNesting.xml");
118        logger.debug("hello");
119        logger.debug("hello");
120        logger.debug("hello");
121        logger.debug("hello");
122        logger.debug("hello");
123
124        Appender<ILoggingEvent> nopa = getAppenderTracker().find("zeroDefault");
125        assertNotNull(nopa);
126        assertThat(nopa).isInstanceOf(NOPAppender.class);
127        StatusPrinter.printInCaseOfErrorsOrWarnings(loggerContext);
128
129        statusChecker.assertContainsMatch(ErrorStatus.ERROR, "No nested appenders found");
130    }
131
132    @Test
133    public void multipleNesting() throws JoranException {
134        configure(SIFT_FOLDER_PREFIX + "multipleNesting.xml");
135        logger.debug("hello");
136        logger.debug("hello");
137        logger.debug("hello");
138
139        Appender<ILoggingEvent> listAppender = getAppenderTracker().find("multipleDefault");
140        StatusPrinter.printInCaseOfErrorsOrWarnings(loggerContext);
141
142        assertNotNull(listAppender);
143        statusChecker.assertContainsMatch(ErrorStatus.ERROR, "Only and only one appender can be nested");
144    }
145
146    @Test
147    public void defaultLayoutRule() throws JoranException {
148        configure(SIFT_FOLDER_PREFIX + "defaultLayoutRule.xml");
149        logger.debug("hello");
150        SiftingAppender ha = (SiftingAppender) root.getAppender("SIFT");
151        StringListAppender<ILoggingEvent> listAppender = (StringListAppender<ILoggingEvent>) ha.getAppenderTracker().find("default");
152
153        assertNotNull(listAppender);
154        List<String> strList = listAppender.strList;
155        assertEquals(1, strList.size());
156        assertEquals("DEBUG hello", strList.get(0));
157    }
158
159    @Test
160    public void fileAppenderCollision() throws JoranException, InterruptedException {
161        loggerContext.putProperty("DIR_PREFIX", randomOutputDir);
162        String key = "collision";
163        configure(SIFT_FOLDER_PREFIX + "fileAppender.xml");
164        SiftingAppender sa = (SiftingAppender) root.getAppender("SIFT");
165
166        long timestamp = System.currentTimeMillis();
167
168        MDC.put(key, "A-"+diff);
169        logNewEventViaSiftingAppender(sa, timestamp);
170        FileAppender<ILoggingEvent> fileAppenderA = (FileAppender<ILoggingEvent>) sa.getAppenderTracker().find("A-"+diff);
171        assertNotNull(fileAppenderA);
172        assertTrue(fileAppenderA.isStarted());
173        timestamp += ComponentTracker.DEFAULT_TIMEOUT + 1;
174        MDC.put(key, "B-"+diff);
175        logNewEventViaSiftingAppender(sa, timestamp);
176        assertFalse(fileAppenderA.isStarted());
177        
178        MDC.put(key, "A-"+diff);
179        timestamp += 1;
180        logNewEventViaSiftingAppender(sa, timestamp);
181        FileAppender<ILoggingEvent> fileAppenderA_2 = (FileAppender<ILoggingEvent>) sa.getAppenderTracker().find("A-"+diff);
182        assertTrue(fileAppenderA_2.isStarted());
183        
184    }
185
186    private void logNewEventViaSiftingAppender(SiftingAppender sa, long timestamp) {
187        LoggingEvent le = new LoggingEvent("x", logger, Level.INFO, "hello", null, null);
188        le.setTimeStamp(timestamp + ComponentTracker.DEFAULT_TIMEOUT + 1);
189        sa.doAppend(le);
190    }
191
192    @Test
193    public void testWholeCycle() throws JoranException {
194        String mdcKey = "cycle";
195        configure(SIFT_FOLDER_PREFIX + "completeCycle.xml");
196        MDC.put(mdcKey, "a");
197        logger.debug("smoke");
198        long timestamp = System.currentTimeMillis();
199        SiftingAppender sa = (SiftingAppender) root.getAppender("SIFT");
200        ListAppender<ILoggingEvent> listAppender = (ListAppender<ILoggingEvent>) sa.getAppenderTracker().find("a");
201        assertNotNull(listAppender);
202        List<ILoggingEvent> eventList = listAppender.list;
203        assertEquals(1, listAppender.list.size());
204        assertEquals("smoke", eventList.get(0).getMessage());
205
206        MDC.remove(mdcKey);
207        logNewEventViaSiftingAppender(sa, timestamp);
208        assertFalse(listAppender.isStarted());
209        assertEquals(1, sa.getAppenderTracker().allKeys().size());
210        assertTrue(sa.getAppenderTracker().allKeys().contains("cycleDefault"));
211    }
212
213    @Test
214    public void sessionFinalizationShouldCauseLingering() throws JoranException {
215        String mdcKey = "linger";
216        String mdcVal = "session" + diff;
217        configure(SIFT_FOLDER_PREFIX + "lingering.xml");
218        MDC.put(mdcKey, mdcVal);
219        logger.debug("linger 1");
220        logger.debug(ClassicConstants.FINALIZE_SESSION_MARKER, "linger 2");
221        long now = System.currentTimeMillis();
222        SiftingAppender sa = (SiftingAppender) root.getAppender("SIFT");
223        AppenderTracker<ILoggingEvent> tracker = sa.getAppenderTracker();
224
225        assertEquals(1, tracker.allKeys().size());
226        Appender<ILoggingEvent> appender = tracker.find(mdcVal);
227        assertTrue(appender.isStarted());
228
229        tracker.removeStaleComponents(now + AppenderTracker.LINGERING_TIMEOUT + 1);
230        // previously lingering appenders should be closed upon timeout
231        assertFalse(appender.isStarted());
232        // and they should be gone
233        assertEquals(0, tracker.allKeys().size());
234    }
235
236    @Test
237    public void localPropertiesShouldBeVisible() throws JoranException {
238        String mdcKey = "localProperty";
239        String mdcVal = "" + diff;
240        String msg = "localPropertiesShouldBeVisible";
241        String prefix = "Y";
242        configure(SIFT_FOLDER_PREFIX + "propertyPropagation.xml");
243        MDC.put(mdcKey, mdcVal);
244        logger.debug(msg);
245        SiftingAppender sa = (SiftingAppender) root.getAppender("SIFT");
246        StringListAppender<ILoggingEvent> listAppender = (StringListAppender<ILoggingEvent>) sa.getAppenderTracker().find(mdcVal);
247        assertNotNull(listAppender);
248        List<String> strList = listAppender.strList;
249        assertEquals(1, listAppender.strList.size());
250        assertEquals(prefix + msg, strList.get(0));
251    }
252
253    @Test
254    public void propertyDefinedWithinSiftElementShouldBeVisible() throws JoranException {
255        String mdcKey = "propertyDefinedWithinSift";
256        String mdcVal = "" + diff;
257        String msg = "propertyDefinedWithinSiftElementShouldBeVisible";
258        String prefix = "Y";
259        configure(SIFT_FOLDER_PREFIX + "propertyDefinedInSiftElement.xml");
260        MDC.put(mdcKey, mdcVal);
261        logger.debug(msg);
262        SiftingAppender sa = (SiftingAppender) root.getAppender("SIFT");
263        StringListAppender<ILoggingEvent> listAppender = (StringListAppender<ILoggingEvent>) sa.getAppenderTracker().find(mdcVal);
264        assertNotNull(listAppender);
265        List<String> strList = listAppender.strList;
266        assertEquals(1, listAppender.strList.size());
267        assertEquals(prefix + msg, strList.get(0));
268    }
269
270    @Test
271    public void compositePropertyShouldCombineWithinAndWithoutSiftElement() throws JoranException {
272        String mdcKey = "compositeProperty";
273        String mdcVal = "" + diff;
274        String msg = "compositePropertyShouldCombineWithinAndWithoutSiftElement";
275        String prefix = "composite";
276        configure(SIFT_FOLDER_PREFIX + "compositeProperty.xml");
277        MDC.put(mdcKey, mdcVal);
278        logger.debug(msg);
279        SiftingAppender sa = (SiftingAppender) root.getAppender("SIFT");
280        StringListAppender<ILoggingEvent> listAppender = (StringListAppender<ILoggingEvent>) sa.getAppenderTracker().find(mdcVal);
281        assertNotNull(listAppender);
282        List<String> strList = listAppender.strList;
283        assertEquals(1, listAppender.strList.size());
284        assertEquals(prefix + msg, strList.get(0));
285    }
286
287    @Test
288    public void maxAppendersCountPropertyShouldBeHonored() throws JoranException {
289        configure(SIFT_FOLDER_PREFIX + "maxAppenderCount.xml");
290        int max = 5;
291        SiftingAppender sa = (SiftingAppender) root.getAppender("SIFT");
292        String mdcKey = "max";
293        for (int i = 0; i <= max; i++) {
294            MDC.put(mdcKey, "" + (diff + i));
295            LoggingEvent event = new LoggingEvent("", logger, Level.DEBUG, "max" + i, null, null);
296            event.setTimeStamp(now);
297            sa.doAppend(event);
298            now += AbstractComponentTracker.WAIT_BETWEEN_SUCCESSIVE_REMOVAL_ITERATIONS;
299        }
300        AppenderTracker<ILoggingEvent> tracker = sa.getAppenderTracker();
301        assertEquals(max, tracker.allKeys().size());
302        assertNull(tracker.find("" + (diff + 0)));
303        for (int i = 1; i <= max; i++) {
304            assertNotNull(tracker.find("" + (diff + i)));
305        }
306    }
307
308    @Test
309    public void timeoutPropertyShouldBeHonored() throws JoranException, InterruptedException {
310        configure(SIFT_FOLDER_PREFIX + "timeout.xml");
311        long timeout = 30 * 1000;
312        SiftingAppender sa = (SiftingAppender) root.getAppender("SIFT");
313
314        LoggingEvent event = new LoggingEvent("", logger, Level.DEBUG, "timeout", null, null);
315        event.setTimeStamp(now);
316        sa.doAppend(event);
317
318        AppenderTracker<ILoggingEvent> tracker = sa.getAppenderTracker();
319
320        assertEquals(1, tracker.getComponentCount());
321
322        now += timeout + 1;
323        tracker.removeStaleComponents(now);
324        assertEquals(0, tracker.getComponentCount());
325        statusChecker.assertIsErrorFree();
326    }
327
328    // LOGBACK-1127
329    @Ignore
330    @Test
331    public void programmicSiftingAppender() {
332
333        SiftingAppender connectorAppender = new SiftingAppender();
334        connectorAppender.setContext(loggerContext);
335        connectorAppender.setName("SIFTING_APPENDER");
336
337        MDCBasedDiscriminator discriminator = new MDCBasedDiscriminator();
338        discriminator.setKey("SKEY");
339        discriminator.setDefaultValue("DEF_KEY");
340        discriminator.start();
341        connectorAppender.setDiscriminator(discriminator);
342
343        connectorAppender.setAppenderFactory(new AppenderFactory<ILoggingEvent>() {
344
345            @Override
346            public Appender<ILoggingEvent> buildAppender(Context context, String discriminatingValue) throws JoranException {
347
348                RollingFileAppender<ILoggingEvent> appender = new RollingFileAppender<ILoggingEvent>();
349                appender.setName("ROLLING_APPENDER_" + discriminatingValue);
350                appender.setContext(context);
351                appender.setFile("/var/logs/active_" + discriminatingValue + ".log");
352
353                TimeBasedRollingPolicy<ILoggingEvent> policy = new TimeBasedRollingPolicy<ILoggingEvent>();
354                policy.setContext(context);
355                policy.setMaxHistory(365);
356                policy.setFileNamePattern(CoreTestConstants.OUTPUT_DIR_PREFIX + "/logback1127/" + discriminatingValue + "_%d{yyyy_MM_dd}_%i.log");
357                policy.setParent(appender);
358                policy.setCleanHistoryOnStart(true);
359
360                SizeAndTimeBasedFNATP<ILoggingEvent> innerpolicy = new SizeAndTimeBasedFNATP<ILoggingEvent>();
361                innerpolicy.setContext(context);
362                innerpolicy.setMaxFileSize(FileSize.valueOf("5KB"));
363                innerpolicy.setTimeBasedRollingPolicy(policy);
364
365                policy.setTimeBasedFileNamingAndTriggeringPolicy(innerpolicy);
366                policy.start();
367                appender.setRollingPolicy(policy);
368
369                PatternLayoutEncoder pl = new PatternLayoutEncoder();
370                pl.setContext(context);
371                pl.setPattern("%d{yyyy/MM/dd'T'HH:mm:ss} %-5level - %msg\n");
372
373                pl.start();
374                appender.setEncoder(pl);
375
376                appender.start();
377                return appender;
378            }
379        });
380        connectorAppender.start();
381
382        ch.qos.logback.classic.Logger logger = loggerContext.getLogger("org.test");
383        logger.addAppender(connectorAppender);
384        logger.setLevel(Level.DEBUG);
385        logger.setAdditive(false);
386
387        MDC.put("SKEY", "K1");
388        logger.info("bla1");
389        MDC.clear();
390
391        MDC.put("SKEY", "K2");
392        logger.info("bla2");
393        MDC.clear();
394
395        StatusPrinter.print(loggerContext);
396
397    }
398}