View Javadoc
1   /*
2    * Logback: the reliable, generic, fast and flexible logging framework.
3    * Copyright (C) 1999-2022, 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  
15  package ch.qos.logback.core;
16  
17  import org.junit.jupiter.api.Assertions;
18  import org.junit.jupiter.api.BeforeEach;
19  import org.junit.jupiter.api.Disabled;
20  import org.junit.jupiter.api.Test;
21  
22  import ch.qos.logback.core.helpers.NOPAppender;
23  import ch.qos.logback.core.read.ListAppender;
24  import ch.qos.logback.core.status.OnConsoleStatusListener;
25  import ch.qos.logback.core.testUtil.DelayingListAppender;
26  import ch.qos.logback.core.testUtil.NPEAppender;
27  import ch.qos.logback.core.status.testUtil.StatusChecker;
28  import org.junit.jupiter.api.Timeout;
29  
30  import java.util.concurrent.TimeUnit;
31  
32  /**
33   * @author Ceki Gülcü
34   * @author Torsten Juergeleit
35   */
36  public class AsyncAppenderBaseTest {
37  
38      Context context = new ContextBase();
39      AsyncAppenderBase<Integer> asyncAppenderBase = new AsyncAppenderBase<Integer>();
40      LossyAsyncAppender lossyAsyncAppender = new LossyAsyncAppender();
41      DelayingListAppender<Integer> delayingListAppender = new DelayingListAppender<Integer>();
42      ListAppender<Integer> listAppender = new ListAppender<Integer>();
43      OnConsoleStatusListener onConsoleStatusListener = new OnConsoleStatusListener();
44      StatusChecker statusChecker = new StatusChecker(context);
45  
46      @BeforeEach
47      public void setUp() {
48          onConsoleStatusListener.setContext(context);
49          context.getStatusManager().add(onConsoleStatusListener);
50          onConsoleStatusListener.start();
51  
52          asyncAppenderBase.setContext(context);
53          lossyAsyncAppender.setContext(context);
54  
55          listAppender.setContext(context);
56          listAppender.setName("list");
57          listAppender.start();
58  
59          delayingListAppender.setContext(context);
60          delayingListAppender.setName("list");
61          delayingListAppender.start();
62      }
63  
64      @Test
65      @Timeout(value=2, unit = TimeUnit.SECONDS)
66      public void smoke() {
67          asyncAppenderBase.addAppender(listAppender);
68          asyncAppenderBase.start();
69          asyncAppenderBase.doAppend(0);
70          asyncAppenderBase.stop();
71          verify(listAppender, 1);
72      }
73  
74      @Test
75      public void exceptionsShouldNotCauseHalting() throws InterruptedException {
76          NPEAppender<Integer> npeAppender = new NPEAppender<Integer>();
77          npeAppender.setName("bad");
78          npeAppender.setContext(context);
79          npeAppender.start();
80  
81          asyncAppenderBase.addAppender(npeAppender);
82          asyncAppenderBase.start();
83          Assertions.assertTrue(asyncAppenderBase.isStarted());
84          for (int i = 0; i < 10; i++)
85              asyncAppenderBase.append(i);
86  
87          asyncAppenderBase.stop();
88          Assertions.assertFalse(asyncAppenderBase.isStarted());
89          Assertions.assertEquals(AppenderBase.ALLOWED_REPEATS, statusChecker.matchCount("Appender \\[bad\\] failed to append."));
90      }
91  
92      @Test
93      @Timeout(value=2, unit = TimeUnit.SECONDS)
94      public void emptyQueueShouldBeStoppable() {
95          asyncAppenderBase.addAppender(listAppender);
96          asyncAppenderBase.start();
97          asyncAppenderBase.stop();
98          verify(listAppender, 0);
99      }
100 
101     @Test
102     @Timeout(value=2, unit = TimeUnit.SECONDS)
103     public void workerShouldStopEvenIfInterruptExceptionConsumedWithinSubappender() {
104         delayingListAppender.delay = 100;
105         asyncAppenderBase.addAppender(delayingListAppender);
106         asyncAppenderBase.start();
107         asyncAppenderBase.doAppend(0);
108         asyncAppenderBase.stop();
109         verify(delayingListAppender, 1);
110         Assertions.assertTrue(delayingListAppender.interrupted);
111         Thread.interrupted();
112     }
113 
114     @Test
115     @Timeout(value=2, unit = TimeUnit.SECONDS)
116     public void noEventLoss() throws InterruptedException {
117         int bufferSize = 10;
118         int loopLen = bufferSize * 2;
119         asyncAppenderBase.addAppender(delayingListAppender);
120         asyncAppenderBase.setQueueSize(bufferSize);
121         asyncAppenderBase.setMaxFlushTime(2000);
122         asyncAppenderBase.start();
123         for (int i = 0; i < loopLen; i++) {
124             asyncAppenderBase.doAppend(i);
125         }
126 
127         asyncAppenderBase.stop();
128         verify(delayingListAppender, loopLen);
129     }
130 
131     @Test
132     @Timeout(value=2, unit = TimeUnit.SECONDS)
133     public void eventLossIfNeverBlock() {
134         int bufferSize = 10;
135         int loopLen = bufferSize * 200;
136         delayingListAppender.setDelay(5); // (loopLen*delay) much bigger than test timeout
137         asyncAppenderBase.addAppender(delayingListAppender);
138         asyncAppenderBase.setQueueSize(bufferSize);
139         asyncAppenderBase.setNeverBlock(true);
140         asyncAppenderBase.start();
141         for (int i = 0; i < loopLen; i++) {
142             asyncAppenderBase.doAppend(i);
143         }
144         asyncAppenderBase.stop();
145         // ListAppender size isn't a reliable test here, so just make sure we didn't
146         // have any errors, and that we could complete the test in time.
147         statusChecker.assertIsErrorFree();
148     }
149 
150     @Test
151     @Timeout(value=2, unit = TimeUnit.SECONDS)
152     public void lossyAppenderShouldOnlyLoseCertainEvents() {
153         int bufferSize = 5;
154         int loopLen = bufferSize * 2;
155         lossyAsyncAppender.addAppender(delayingListAppender);
156         lossyAsyncAppender.setQueueSize(bufferSize);
157         lossyAsyncAppender.setDiscardingThreshold(1);
158         lossyAsyncAppender.start();
159         for (int i = 0; i < loopLen; i++) {
160             lossyAsyncAppender.doAppend(i);
161         }
162         lossyAsyncAppender.stop();
163         // events 0, 3, 6 and 9 are discardable. However, for events 0 and 3
164         // the buffer is not yet full. Thus, only events 6 and 9 will be
165         // effectively discarded.
166         verify(delayingListAppender, loopLen - 2);
167     }
168 
169     @Test
170     @Timeout(value=2, unit = TimeUnit.SECONDS)
171     public void lossyAppenderShouldBeNonLossyIfDiscardingThresholdIsZero() {
172         int bufferSize = 5;
173         int loopLen = bufferSize * 2;
174         lossyAsyncAppender.addAppender(delayingListAppender);
175         lossyAsyncAppender.setQueueSize(bufferSize);
176         lossyAsyncAppender.setDiscardingThreshold(0);
177         lossyAsyncAppender.start();
178         for (int i = 0; i < loopLen; i++) {
179             lossyAsyncAppender.doAppend(i);
180         }
181         lossyAsyncAppender.stop();
182         verify(delayingListAppender, loopLen);
183     }
184 
185     @Test
186     public void invalidQueueCapacityShouldResultInNonStartedAppender() {
187         asyncAppenderBase.addAppender(new NOPAppender<Integer>());
188         asyncAppenderBase.setQueueSize(0);
189         Assertions.assertEquals(0, asyncAppenderBase.getQueueSize());
190         asyncAppenderBase.start();
191         Assertions.assertFalse(asyncAppenderBase.isStarted());
192         statusChecker.assertContainsMatch("Invalid queue size");
193     }
194 
195     @Test
196     @Disabled
197     public void workerThreadFlushesOnStop() throws InterruptedException {
198         int loopLen = 5;
199         int maxRuntime = (loopLen + 1) * Math.max(1000, delayingListAppender.delay);
200         ListAppender<Integer> la = delayingListAppender;
201         asyncAppenderBase.addAppender(la);
202         asyncAppenderBase.setDiscardingThreshold(0);
203         asyncAppenderBase.setMaxFlushTime(maxRuntime);
204         asyncAppenderBase.start();
205         asyncAppenderBase.worker.suspend();
206 
207         for (int i = 0; i < loopLen; i++) {
208             asyncAppenderBase.doAppend(i);
209         }
210         Assertions.assertEquals(loopLen, asyncAppenderBase.getNumberOfElementsInQueue());
211         Assertions.assertEquals(0, la.list.size());
212 
213         asyncAppenderBase.worker.resume();
214         asyncAppenderBase.stop();
215 
216         Assertions.assertEquals(0, asyncAppenderBase.getNumberOfElementsInQueue());
217         verify(la, loopLen);
218     }
219 
220     @Test
221     public void stopExitsWhenMaxRuntimeReached() throws InterruptedException {
222         int maxFlushTime = 1; // runtime of 0 means wait forever, so use 1 ms instead
223         int loopLen = 10;
224         ListAppender<Integer> la = delayingListAppender;
225         asyncAppenderBase.addAppender(la);
226         asyncAppenderBase.setMaxFlushTime(maxFlushTime);
227         asyncAppenderBase.start();
228 
229         for (int i = 0; i < loopLen; i++) {
230             asyncAppenderBase.doAppend(i);
231         }
232 
233         asyncAppenderBase.stop();
234 
235         // confirms that stop exited when runtime reached
236         statusChecker.assertContainsMatch("Max queue flush timeout \\(" + maxFlushTime + " ms\\) exceeded.");
237 
238         asyncAppenderBase.worker.join();
239 
240         // confirms that all entries do end up being flushed if we wait long enough
241         verify(la, loopLen);
242     }
243 
244     // Interruption of current thread when in doAppend method should not be
245     // consumed by async appender. See also http://jira.qos.ch/browse/LOGBACK-910
246     @Test
247     public void verifyInterruptionIsNotSwallowed() {
248         asyncAppenderBase.addAppender(delayingListAppender);
249         asyncAppenderBase.start();
250         Thread.currentThread().interrupt();
251         asyncAppenderBase.doAppend(Integer.valueOf(0));
252         Assertions.assertTrue(Thread.currentThread().isInterrupted());
253         // clear interrupt flag for subsequent tests
254         Thread.interrupted();
255     }
256 
257     // Interruption of current thread should not prevent logging.
258     // See also http://jira.qos.ch/browse/LOGBACK-910
259     // and https://jira.qos.ch/browse/LOGBACK-1247
260     @Test
261     public void verifyInterruptionDoesNotPreventLogging() {
262         asyncAppenderBase.addAppender(listAppender);
263         asyncAppenderBase.start();
264         asyncAppenderBase.doAppend(Integer.valueOf(0));
265         Thread.currentThread().interrupt();
266         asyncAppenderBase.doAppend(Integer.valueOf(1));
267         asyncAppenderBase.doAppend(Integer.valueOf(1));
268         Assertions.assertTrue(Thread.currentThread().isInterrupted());
269         // the interruption needs to be consumed
270         Thread.interrupted();
271         asyncAppenderBase.stop();
272         verify(listAppender, 3);
273     }
274 
275     @Test
276     public void verifyInterruptionFlagWhenStopping_INTERUPPTED() {
277         asyncAppenderBase.addAppender(listAppender);
278         asyncAppenderBase.start();
279         Thread.currentThread().interrupt();
280         asyncAppenderBase.stop();
281         Assertions.assertTrue(Thread.currentThread().isInterrupted());
282         Thread.interrupted();
283     }
284 
285     @Test
286     public void verifyInterruptionFlagWhenStopping_NOT_INTERUPPTED() {
287         asyncAppenderBase.addAppender(listAppender);
288         asyncAppenderBase.start();
289         asyncAppenderBase.stop();
290         Assertions.assertFalse(Thread.currentThread().isInterrupted());
291     }
292 
293     // In JDK non started threads can be interrupted
294     @Disabled
295     @Test
296     public void verifyInterruptionOfWorkerIsSwallowed() {
297         asyncAppenderBase.addAppender(delayingListAppender);
298         asyncAppenderBase.start();
299         Thread.yield();
300         asyncAppenderBase.stop();
301         Assertions.assertFalse(asyncAppenderBase.worker.isInterrupted());
302     }
303 
304     private void verify(ListAppender<Integer> la, int atLeast) {
305         // ListAppender passes as parameter should be stopped at this stage
306         Assertions.assertFalse(la.isStarted());
307         Assertions.assertTrue( atLeast <= la.list.size(), atLeast + " <= " + la.list.size());
308         statusChecker.assertIsErrorFree();
309         statusChecker.assertContainsMatch("Worker thread will flush remaining events before exiting.");
310     }
311 
312     static class LossyAsyncAppender extends AsyncAppenderBase<Integer> {
313         @Override
314         protected boolean isDiscardable(Integer i) {
315             return (i % 3 == 0);
316         }
317     }
318 
319     @Test
320     public void checkThatStartMethodIsIdempotent() {
321         asyncAppenderBase.addAppender(lossyAsyncAppender);
322         asyncAppenderBase.start();
323 
324         // we don't need mockito for this test, but if we did here is how it would look
325         // AsyncAppenderBase<Integer> spied = Mockito.spy(asyncAppenderBase);
326         // Mockito.doThrow(new IllegalStateException("non idempotent
327         // start")).when((UnsynchronizedAppenderBase<Integer>)
328         // spied).start();
329 
330         // a second invocation of start will cause a IllegalThreadStateException thrown
331         // by the asyncAppenderBase.worker
332         // thread
333         asyncAppenderBase.start();
334     }
335 }