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.core;
15  
16  import static org.junit.Assert.assertEquals;
17  import static org.junit.Assert.assertFalse;
18  import static org.junit.Assert.assertTrue;
19  
20  import org.junit.Before;
21  import org.junit.Test;
22  
23  import ch.qos.logback.core.helpers.NOPAppender;
24  import ch.qos.logback.core.read.ListAppender;
25  import ch.qos.logback.core.status.OnConsoleStatusListener;
26  import ch.qos.logback.core.testUtil.DelayingListAppender;
27  import ch.qos.logback.core.testUtil.NPEAppender;
28  import ch.qos.logback.core.testUtil.StatusChecker;
29  
30  /**
31   * @author Ceki Gülcü
32   * @author Torsten Juergeleit
33   */
34  public class AsyncAppenderBaseTest {
35  
36      Context context = new ContextBase();
37      AsyncAppenderBase<Integer> asyncAppenderBase = new AsyncAppenderBase<Integer>();
38      LossyAsyncAppender lossyAsyncAppender = new LossyAsyncAppender();
39      DelayingListAppender<Integer> delayingListAppender = new DelayingListAppender<Integer>();
40      ListAppender<Integer> listAppender = new ListAppender<Integer>();
41      OnConsoleStatusListener onConsoleStatusListener = new OnConsoleStatusListener();
42      StatusChecker statusChecker = new StatusChecker(context);
43  
44      @Before
45      public void setUp() {
46          onConsoleStatusListener.setContext(context);
47          context.getStatusManager().add(onConsoleStatusListener);
48          onConsoleStatusListener.start();
49  
50          asyncAppenderBase.setContext(context);
51          lossyAsyncAppender.setContext(context);
52  
53          listAppender.setContext(context);
54          listAppender.setName("list");
55          listAppender.start();
56  
57          delayingListAppender.setContext(context);
58          delayingListAppender.setName("list");
59          delayingListAppender.start();
60      }
61  
62      @Test(timeout = 2000)
63      public void smoke() {
64          asyncAppenderBase.addAppender(listAppender);
65          asyncAppenderBase.start();
66          asyncAppenderBase.doAppend(0);
67          asyncAppenderBase.stop();
68          verify(listAppender, 1);
69      }
70  
71      @Test
72      public void exceptionsShouldNotCauseHalting() throws InterruptedException {
73          NPEAppender<Integer> npeAppender = new NPEAppender<Integer>();
74          npeAppender.setName("bad");
75          npeAppender.setContext(context);
76          npeAppender.start();
77  
78          asyncAppenderBase.addAppender(npeAppender);
79          asyncAppenderBase.start();
80          assertTrue(asyncAppenderBase.isStarted());
81          for (int i = 0; i < 10; i++)
82              asyncAppenderBase.append(i);
83  
84          asyncAppenderBase.stop();
85          assertFalse(asyncAppenderBase.isStarted());
86          assertEquals(AppenderBase.ALLOWED_REPEATS, statusChecker.matchCount("Appender \\[bad\\] failed to append."));
87      }
88  
89      @Test(timeout = 2000)
90      public void emptyQueueShouldBeStoppable() {
91          asyncAppenderBase.addAppender(listAppender);
92          asyncAppenderBase.start();
93          asyncAppenderBase.stop();
94          verify(listAppender, 0);
95      }
96  
97      @Test(timeout = 2000)
98      public void workerShouldStopEvenIfInterruptExceptionConsumedWithinSubappender() {
99          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 }