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.core;
015
016import static org.junit.Assert.assertEquals;
017import static org.junit.Assert.assertFalse;
018import static org.junit.Assert.assertTrue;
019
020import org.junit.Before;
021import org.junit.Test;
022
023import ch.qos.logback.core.helpers.NOPAppender;
024import ch.qos.logback.core.read.ListAppender;
025import ch.qos.logback.core.status.OnConsoleStatusListener;
026import ch.qos.logback.core.testUtil.DelayingListAppender;
027import ch.qos.logback.core.testUtil.NPEAppender;
028import ch.qos.logback.core.testUtil.StatusChecker;
029
030/**
031 * @author Ceki Gülcü
032 * @author Torsten Juergeleit
033 */
034public class AsyncAppenderBaseTest {
035
036    Context context = new ContextBase();
037    AsyncAppenderBase<Integer> asyncAppenderBase = new AsyncAppenderBase<Integer>();
038    LossyAsyncAppender lossyAsyncAppender = new LossyAsyncAppender();
039    DelayingListAppender<Integer> delayingListAppender = new DelayingListAppender<Integer>();
040    ListAppender<Integer> listAppender = new ListAppender<Integer>();
041    OnConsoleStatusListener onConsoleStatusListener = new OnConsoleStatusListener();
042    StatusChecker statusChecker = new StatusChecker(context);
043
044    @Before
045    public void setUp() {
046        onConsoleStatusListener.setContext(context);
047        context.getStatusManager().add(onConsoleStatusListener);
048        onConsoleStatusListener.start();
049
050        asyncAppenderBase.setContext(context);
051        lossyAsyncAppender.setContext(context);
052
053        listAppender.setContext(context);
054        listAppender.setName("list");
055        listAppender.start();
056
057        delayingListAppender.setContext(context);
058        delayingListAppender.setName("list");
059        delayingListAppender.start();
060    }
061
062    @Test(timeout = 2000)
063    public void smoke() {
064        asyncAppenderBase.addAppender(listAppender);
065        asyncAppenderBase.start();
066        asyncAppenderBase.doAppend(0);
067        asyncAppenderBase.stop();
068        verify(listAppender, 1);
069    }
070
071    @Test
072    public void exceptionsShouldNotCauseHalting() throws InterruptedException {
073        NPEAppender<Integer> npeAppender = new NPEAppender<Integer>();
074        npeAppender.setName("bad");
075        npeAppender.setContext(context);
076        npeAppender.start();
077
078        asyncAppenderBase.addAppender(npeAppender);
079        asyncAppenderBase.start();
080        assertTrue(asyncAppenderBase.isStarted());
081        for (int i = 0; i < 10; i++)
082            asyncAppenderBase.append(i);
083
084        asyncAppenderBase.stop();
085        assertFalse(asyncAppenderBase.isStarted());
086        assertEquals(AppenderBase.ALLOWED_REPEATS, statusChecker.matchCount("Appender \\[bad\\] failed to append."));
087    }
088
089    @Test(timeout = 2000)
090    public void emptyQueueShouldBeStoppable() {
091        asyncAppenderBase.addAppender(listAppender);
092        asyncAppenderBase.start();
093        asyncAppenderBase.stop();
094        verify(listAppender, 0);
095    }
096
097    @Test(timeout = 2000)
098    public void workerShouldStopEvenIfInterruptExceptionConsumedWithinSubappender() {
099        delayingListAppender.delay = 100;
100        asyncAppenderBase.addAppender(delayingListAppender);
101        asyncAppenderBase.start();
102        asyncAppenderBase.doAppend(0);
103        asyncAppenderBase.stop();
104        verify(delayingListAppender, 1);
105        assertTrue(delayingListAppender.interrupted);
106        Thread.interrupted();
107    }
108
109    @Test(timeout = 2000)
110    public void noEventLoss() {
111        int bufferSize = 10;
112        int loopLen = bufferSize * 2;
113        asyncAppenderBase.addAppender(delayingListAppender);
114        asyncAppenderBase.setQueueSize(bufferSize);
115        asyncAppenderBase.start();
116        for (int i = 0; i < loopLen; i++) {
117            asyncAppenderBase.doAppend(i);
118        }
119        asyncAppenderBase.stop();
120        verify(delayingListAppender, loopLen);
121    }
122
123    @Test(timeout = 2000)
124    public void eventLossIfNeverBlock() {
125        int bufferSize = 10;
126        int loopLen = bufferSize * 200;
127        delayingListAppender.setDelay(5); // (loopLen*delay) much bigger than test timeout
128        asyncAppenderBase.addAppender(delayingListAppender);
129        asyncAppenderBase.setQueueSize(bufferSize);
130        asyncAppenderBase.setNeverBlock(true);
131        asyncAppenderBase.start();
132        for (int i = 0; i < loopLen; i++) {
133            asyncAppenderBase.doAppend(i);
134        }
135        asyncAppenderBase.stop();
136        // ListAppender size isn't a reliable test here, so just make sure we didn't
137        // have any errors, and that we could complete the test in time.
138        statusChecker.assertIsErrorFree();
139    }
140
141    @Test(timeout = 2000)
142    public void lossyAppenderShouldOnlyLoseCertainEvents() {
143        int bufferSize = 5;
144        int loopLen = bufferSize * 2;
145        lossyAsyncAppender.addAppender(delayingListAppender);
146        lossyAsyncAppender.setQueueSize(bufferSize);
147        lossyAsyncAppender.setDiscardingThreshold(1);
148        lossyAsyncAppender.start();
149        for (int i = 0; i < loopLen; i++) {
150            lossyAsyncAppender.doAppend(i);
151        }
152        lossyAsyncAppender.stop();
153        // events 0, 3, 6 and 9 are discardable. However, for events 0 and 3
154        // the buffer is not not yet full. Thus, only events 6 and 9 will be
155        // effectively discarded.
156        verify(delayingListAppender, loopLen - 2);
157    }
158
159    @Test(timeout = 2000)
160    public void lossyAppenderShouldBeNonLossyIfDiscardingThresholdIsZero() {
161        int bufferSize = 5;
162        int loopLen = bufferSize * 2;
163        lossyAsyncAppender.addAppender(delayingListAppender);
164        lossyAsyncAppender.setQueueSize(bufferSize);
165        lossyAsyncAppender.setDiscardingThreshold(0);
166        lossyAsyncAppender.start();
167        for (int i = 0; i < loopLen; i++) {
168            lossyAsyncAppender.doAppend(i);
169        }
170        lossyAsyncAppender.stop();
171        verify(delayingListAppender, loopLen);
172    }
173
174    @Test
175    public void invalidQueueCapacityShouldResultInNonStartedAppender() {
176        asyncAppenderBase.addAppender(new NOPAppender<Integer>());
177        asyncAppenderBase.setQueueSize(0);
178        assertEquals(0, asyncAppenderBase.getQueueSize());
179        asyncAppenderBase.start();
180        assertFalse(asyncAppenderBase.isStarted());
181        statusChecker.assertContainsMatch("Invalid queue size");
182    }
183
184    @SuppressWarnings("deprecation")
185    @Test
186    public void workerThreadFlushesOnStop() {
187        int loopLen = 5;
188        int maxRuntime = (loopLen + 1) * Math.max(1000, delayingListAppender.delay);
189        ListAppender<Integer> la = delayingListAppender;
190        asyncAppenderBase.addAppender(la);
191        asyncAppenderBase.setDiscardingThreshold(0);
192        asyncAppenderBase.setMaxFlushTime(maxRuntime);
193        asyncAppenderBase.start();
194        asyncAppenderBase.worker.suspend();
195
196        for (int i = 0; i < loopLen; i++) {
197            asyncAppenderBase.doAppend(i);
198        }
199        assertEquals(loopLen, asyncAppenderBase.getNumberOfElementsInQueue());
200        assertEquals(0, la.list.size());
201
202        asyncAppenderBase.worker.resume();
203        asyncAppenderBase.stop();
204
205        assertEquals(0, asyncAppenderBase.getNumberOfElementsInQueue());
206        verify(la, loopLen);
207    }
208
209    // @SuppressWarnings("deprecation")
210    @Test
211    public void stopExitsWhenMaxRuntimeReached() throws InterruptedException {
212        int maxFlushTime = 1; // runtime of 0 means wait forever, so use 1 ms instead
213        int loopLen = 10;
214        ListAppender<Integer> la = delayingListAppender;
215        asyncAppenderBase.addAppender(la);
216        asyncAppenderBase.setMaxFlushTime(maxFlushTime);
217        asyncAppenderBase.start();
218
219        for (int i = 0; i < loopLen; i++) {
220            asyncAppenderBase.doAppend(i);
221        }
222
223        asyncAppenderBase.stop();
224
225        // confirms that stop exited when runtime reached
226        statusChecker.assertContainsMatch("Max queue flush timeout \\(" + maxFlushTime + " ms\\) exceeded.");
227
228        asyncAppenderBase.worker.join();
229
230        // confirms that all entries do end up being flushed if we wait long enough
231        verify(la, loopLen);
232    }
233
234    // Interruption of current thread when in doAppend method should not be
235    // consumed by async appender. See also http://jira.qos.ch/browse/LOGBACK-910
236    @Test
237    public void verifyInterruptionIsNotSwallowed() {
238        asyncAppenderBase.addAppender(delayingListAppender);
239        asyncAppenderBase.start();
240        Thread.currentThread().interrupt();
241        asyncAppenderBase.doAppend(Integer.valueOf(0));
242        assertTrue(Thread.currentThread().isInterrupted());
243        // clear interrupt flag for subsequent tests
244        Thread.interrupted();
245    }
246
247    // Interruption of current thread should not prevent logging. 
248    // See also http://jira.qos.ch/browse/LOGBACK-910
249    // and https://jira.qos.ch/browse/LOGBACK-1247
250    @Test
251    public void verifyInterruptionDoesNotPreventLogging() {
252        asyncAppenderBase.addAppender(listAppender);
253        asyncAppenderBase.start();
254        asyncAppenderBase.doAppend(Integer.valueOf(0));
255        Thread.currentThread().interrupt();
256        asyncAppenderBase.doAppend(Integer.valueOf(1));
257        asyncAppenderBase.doAppend(Integer.valueOf(1));
258        assertTrue(Thread.currentThread().isInterrupted());
259        // the interruption needs to be consumed
260        Thread.interrupted();
261        asyncAppenderBase.stop();
262        verify(listAppender, 3);
263    }
264   
265    @Test
266    public void verifyInterruptionFlagWhenStopping_INTERUPPTED() {
267        asyncAppenderBase.addAppender(listAppender);
268        asyncAppenderBase.start();
269        Thread.currentThread().interrupt();
270        asyncAppenderBase.stop();
271        assertTrue(Thread.currentThread().isInterrupted());
272        Thread.interrupted();
273    }
274    
275    @Test
276    public void verifyInterruptionFlagWhenStopping_NOT_INTERUPPTED() {
277        asyncAppenderBase.addAppender(listAppender);
278        asyncAppenderBase.start();
279        asyncAppenderBase.stop();
280        assertFalse(Thread.currentThread().isInterrupted());
281    }
282    
283    
284    @Test
285    public void verifyInterruptionOfWorkerIsSwallowed() {
286        asyncAppenderBase.addAppender(delayingListAppender);
287        asyncAppenderBase.start();
288        asyncAppenderBase.stop();
289        assertFalse(asyncAppenderBase.worker.isInterrupted());
290    }
291
292    private void verify(ListAppender<Integer> la, int atLeast) {
293        assertFalse(la.isStarted());
294        assertTrue(atLeast + " <= " + la.list.size(), atLeast <= la.list.size());
295        statusChecker.assertIsErrorFree();
296        statusChecker.assertContainsMatch("Worker thread will flush remaining events before exiting.");
297    }
298
299    static class LossyAsyncAppender extends AsyncAppenderBase<Integer> {
300        @Override
301        protected boolean isDiscardable(Integer i) {
302            return (i % 3 == 0);
303        }
304    }
305
306    @Test
307    public void checkThatStartMethodIsIdempotent() {
308        asyncAppenderBase.addAppender(lossyAsyncAppender);
309        asyncAppenderBase.start();
310
311        // we don't need mockito for this test, but if we did here is how it would look
312        // AsyncAppenderBase<Integer> spied = Mockito.spy(asyncAppenderBase);
313        // Mockito.doThrow(new IllegalStateException("non idempotent start")).when((UnsynchronizedAppenderBase<Integer>)
314        // spied).start();
315
316        // a second invocation of start will cause a IllegalThreadStateException thrown by the asyncAppenderBase.worker
317        // thread
318        asyncAppenderBase.start();
319    }
320}