View Javadoc
1   /*
2    * Copyright (c) 2012-2023, jcabi.com
3    * All rights reserved.
4    *
5    * Redistribution and use in source and binary forms, with or without
6    * modification, are permitted provided that the following conditions
7    * are met: 1) Redistributions of source code must retain the above
8    * copyright notice, this list of conditions and the following
9    * disclaimer. 2) Redistributions in binary form must reproduce the above
10   * copyright notice, this list of conditions and the following
11   * disclaimer in the documentation and/or other materials provided
12   * with the distribution. 3) Neither the name of the jcabi.com nor
13   * the names of its contributors may be used to endorse or promote
14   * products derived from this software without specific prior written
15   * permission.
16   *
17   * THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS
18   * "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT
19   * NOT LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND
20   * FITNESS FOR A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL
21   * THE COPYRIGHT HOLDER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT,
22   * INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES
23   * (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR
24   * SERVICES; LOSS OF USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION)
25   * HOWEVER CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT,
26   * STRICT LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE)
27   * ARISING IN ANY WAY OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED
28   * OF THE POSSIBILITY OF SUCH DAMAGE.
29   */
30  package com.jcabi.log;
31  
32  import java.io.ByteArrayInputStream;
33  import java.io.Closeable;
34  import java.io.File;
35  import java.io.FileInputStream;
36  import java.io.IOException;
37  import java.io.InputStream;
38  import java.io.StringWriter;
39  import java.util.Timer;
40  import java.util.TimerTask;
41  import java.util.concurrent.CountDownLatch;
42  import java.util.concurrent.TimeUnit;
43  import java.util.logging.Level;
44  import org.apache.commons.lang3.StringUtils;
45  import org.apache.commons.lang3.SystemUtils;
46  import org.apache.log4j.SimpleLayout;
47  import org.apache.log4j.WriterAppender;
48  import org.apache.log4j.spi.Filter;
49  import org.apache.log4j.spi.LoggingEvent;
50  import org.hamcrest.MatcherAssert;
51  import org.hamcrest.Matchers;
52  import org.junit.jupiter.api.Assertions;
53  import org.junit.jupiter.api.Assumptions;
54  import org.junit.jupiter.api.Disabled;
55  import org.junit.jupiter.api.Test;
56  import org.mockito.Mockito;
57  
58  /**
59   * Test case for {@link VerboseProcess}.
60   *
61   * @checkstyle MultipleStringLiterals (500 lines)
62   * @checkstyle ClassDataAbstractionCoupling (200 lines)
63   * @todo #18 Locale/encoding problem in two test methods here. I'm not
64   *  sure how to fix them, but they should be fixed. They fail on some
65   *  machines, while run perfectly on others. They also fail when being
66   *  executed from IntelliJ.
67   * @since 0.1
68   */
69  @SuppressWarnings({ "PMD.TooManyMethods", "PMD.AvoidDuplicateLiterals" })
70  final class VerboseProcessTest {
71  
72      @Test
73      @Disabled
74      void runsACommandLineScript() {
75          Assumptions.assumeFalse(SystemUtils.IS_OS_WINDOWS, "");
76          final VerboseProcess process = new VerboseProcess(
77              new ProcessBuilder("echo", "hey \u20ac!").redirectErrorStream(true)
78          );
79          MatcherAssert.assertThat(
80              process.stdout(),
81              Matchers.containsString("\u20ac!")
82          );
83      }
84  
85      @Test
86      @Disabled
87      void echosUnicodeCorrectly() {
88          Assumptions.assumeFalse(SystemUtils.IS_OS_WINDOWS, "");
89          MatcherAssert.assertThat(
90              new VerboseProcess(
91                  new ProcessBuilder(
92                      "/bin/bash", "-c",
93                      "echo -n \u0442\u0435\u0441\u0442 | hexdump"
94                  )
95              ).stdout(),
96              Matchers.containsString("0000000 d1 82 d0 b5 d1 81 d1 82")
97          );
98      }
99  
100     @Test
101     void runsACommandLineScriptWithException() {
102         Assumptions.assumeFalse(SystemUtils.IS_OS_WINDOWS, "");
103         final VerboseProcess process = new VerboseProcess(
104             new ProcessBuilder("cat", "/non-existing-file.txt")
105                 .redirectErrorStream(true)
106         );
107         try {
108             process.stdout();
109             Assertions.fail("exception expected");
110         } catch (final IllegalArgumentException ex) {
111             MatcherAssert.assertThat(
112                 ex.getMessage(),
113                 Matchers.containsString("No such file or directory")
114             );
115         }
116     }
117 
118     @Test
119     void runsACommandLineScriptWithExceptionNoRedir() throws Exception {
120         Assumptions.assumeFalse(SystemUtils.IS_OS_WINDOWS, "");
121         final VerboseProcess process = new VerboseProcess(
122             new ProcessBuilder("cat", "/non-existing-file.txt")
123         );
124         final VerboseProcess.Result result = process.waitFor();
125         MatcherAssert.assertThat(
126             result.code(),
127             Matchers.equalTo(1)
128         );
129         MatcherAssert.assertThat(
130             result.stderr(),
131             Matchers.containsString("No such file or directory")
132         );
133     }
134 
135     @Test
136     void handlesLongRunningCommand() {
137         Assumptions.assumeFalse(SystemUtils.IS_OS_WINDOWS, "");
138         final VerboseProcess process = new VerboseProcess(
139             new ProcessBuilder("/bin/bash", "-c", "sleep 2; echo 'done'")
140         );
141         MatcherAssert.assertThat(
142             process.stdout(),
143             Matchers.startsWith("done")
144         );
145     }
146 
147     @Test
148     void rejectsNullProcesses() {
149         Assertions.assertThrows(
150             RuntimeException.class,
151             () -> {
152                 final ProcessBuilder builder = null;
153                 new VerboseProcess(builder);
154             }
155         );
156     }
157 
158     @Test
159     void rejectsStdoutWithLevelAll() {
160         try {
161             new VerboseProcess(
162                 Mockito.mock(Process.class), Level.ALL, Level.INFO
163             );
164             Assertions.fail("IllegalArgumentException expected");
165         } catch (final IllegalArgumentException ex) {
166             MatcherAssert.assertThat(
167                 ex.getMessage(),
168                 Matchers.equalTo(
169                     StringUtils.join(
170                         "stdout LEVEL can't be set to ALL because it is ",
171                         "intended only for internal configuration"
172                     )
173                 )
174             );
175         }
176     }
177 
178     @Test
179     void rejectsStderrWithLevelAll() {
180         try {
181             new VerboseProcess(
182                 Mockito.mock(Process.class), Level.INFO, Level.ALL
183             );
184             Assertions.fail("IllegalArgumentException expected here");
185         } catch (final IllegalArgumentException ex) {
186             MatcherAssert.assertThat(
187                 ex.getMessage(),
188                 Matchers.equalTo(
189                     StringUtils.join(
190                         "stderr LEVEL can't be set to ALL because it is ",
191                         "intended only for internal configuration"
192                     )
193                 )
194             );
195         }
196     }
197 
198     @Test
199     @SuppressWarnings("PMD.DoNotUseThreads")
200     void quietlyTerminatesLongRunningProcess() throws Exception {
201         Assumptions.assumeFalse(SystemUtils.IS_OS_WINDOWS, "");
202         final Process proc = new ProcessBuilder("sleep", "10000").start();
203         final VerboseProcess process = new VerboseProcess(proc);
204         final CountDownLatch start = new CountDownLatch(1);
205         final CountDownLatch done = new CountDownLatch(1);
206         new Thread(
207             new VerboseRunnable(
208                 () -> {
209                     start.countDown();
210                     process.stdoutQuietly();
211                     done.countDown();
212                 }
213             )
214         ).start();
215         start.await();
216         TimeUnit.SECONDS.sleep(1L);
217         proc.destroy();
218         MatcherAssert.assertThat(
219             done.await(1L, TimeUnit.MINUTES),
220             Matchers.is(true)
221         );
222     }
223 
224     @Test
225     void stdoutQuietlyLogsErrors() {
226         final StringWriter writer = new StringWriter();
227         org.apache.log4j.Logger.getRootLogger().addAppender(
228             new WriterAppender(new SimpleLayout(), writer)
229         );
230         final ProcessBuilder builder;
231         final String message = "hello dear friend";
232         if (SystemUtils.IS_OS_WINDOWS) {
233             builder = new ProcessBuilder("cmd", "/c", "echo", message, "1>&2");
234         } else {
235             builder = new ProcessBuilder(
236                 "cat", String.format("/non-existing-file-%s ", message)
237             );
238         }
239         final VerboseProcess process = new VerboseProcess(
240             builder, Level.OFF, Level.WARNING
241         );
242         process.stdoutQuietly();
243         MatcherAssert.assertThat(
244             writer.toString(),
245             Matchers.containsString(message)
246         );
247     }
248 
249     @Test
250     @SuppressWarnings("PMD.AvoidFileStream")
251     void logsErrorWhenUnderlyingStreamIsClosed() throws Exception {
252         final StringWriter writer = new StringWriter();
253         org.apache.log4j.Logger.getRootLogger().addAppender(
254             new WriterAppender(new SimpleLayout(), writer)
255         );
256         final Process prc = Mockito.mock(Process.class);
257         final Closeable stdout = new FileInputStream(
258             File.createTempFile("temp", "test")
259         );
260         stdout.close();
261         Mockito.doReturn(stdout).when(prc).getInputStream();
262         Mockito.doReturn(new ByteArrayInputStream(new byte[0]))
263             .when(prc).getErrorStream();
264         final VerboseProcess process = new VerboseProcess(
265             prc,
266             Level.FINEST,
267             Level.FINEST
268         );
269         Logger.debug(
270             this,
271             "#logsErrorWhenUnderlyingStreamIsClosed(): vrbPrc.hashCode=%s",
272             process.hashCode()
273         );
274         process.stdout();
275         MatcherAssert.assertThat(
276             writer.toString(),
277             Matchers.containsString("Error reading from process stream")
278         );
279     }
280 
281     @Test
282     void terminatesMonitorsAndProcessIfClosedInstantly()
283         throws Exception {
284         this.terminatesMonitorsAndProcessIfClosed(0L);
285     }
286 
287     @Test
288     void terminatesMonitorsAndProcessIfClosedShortly()
289         throws Exception {
290         // @checkstyle MagicNumberCheck (1 line)
291         this.terminatesMonitorsAndProcessIfClosed(50L);
292     }
293 
294     @Test
295     void terminatesMonitorsAndProcessIfClosedNormal() throws Exception {
296         final long delay = 400L;
297         this.terminatesMonitorsAndProcessIfClosed(delay);
298     }
299 
300     /**
301      * VerboseProcess can terminate its monitors and underlying Process if
302      * closed after specified time since real usage.
303      * @param delay Time in milliseconds between usage of vrbcPrc starts and
304      *  its close() issued
305      * @throws Exception If something goes wrong
306      * @checkstyle ExecutableStatementCountCheck (100 lines)
307      */
308     private void terminatesMonitorsAndProcessIfClosed(final long delay)
309         throws Exception {
310         final InputStream input = new VerboseProcessTest.InfiniteInputStream('i');
311         final InputStream error = new VerboseProcessTest.InfiniteInputStream('e');
312         final Process prc = Mockito.mock(Process.class);
313         Mockito.doReturn(input).when(prc).getInputStream();
314         Mockito.doReturn(error).when(prc).getErrorStream();
315         Mockito.doAnswer(
316             invocation -> {
317                 input.close();
318                 error.close();
319                 return null;
320             }
321         ).when(prc).destroy();
322         final VerboseProcess process = new VerboseProcess(
323             prc,
324             Level.FINEST,
325             Level.FINEST
326         );
327         Logger.debug(
328             this,
329             "terminatesMntrsAndPrcssIfClosed delay=%d vrbPrc.hashCode=%s",
330             delay,
331             process.hashCode()
332         );
333         final StringWriter writer = new StringWriter();
334         final WriterAppender appender = new WriterAppender(
335             new SimpleLayout(),
336             writer
337         );
338         appender.addFilter(new VerboseProcessTest.VrbPrcMonitorFilter(process));
339         org.apache.log4j.Logger.getLogger(
340             VerboseProcess.class
341         ).addAppender(appender);
342         if (delay == 0L) {
343             process.close();
344         } else {
345             new Timer(true).schedule(
346                 new TimerTask() {
347                     @Override
348                     public void run() {
349                         process.close();
350                     }
351                 },
352                 delay
353             );
354         }
355         process.stdoutQuietly();
356         // @checkstyle MagicNumberCheck (1 line)
357         TimeUnit.MILLISECONDS.sleep(1000L);
358         Mockito.verify(
359             prc,
360             Mockito.atLeastOnce()
361         ).destroy();
362         MatcherAssert.assertThat(
363             writer.toString(),
364             Matchers.not(Matchers
365                 .containsString("Error reading from process stream")
366             )
367         );
368     }
369 
370     /**
371      * {@link InputStream} returning endless flow of characters.
372      *
373      * @since 0.1
374      */
375     private final class InfiniteInputStream extends InputStream {
376         /**
377          * End of line.
378          */
379         private static final int LINE_FEED = 0xA;
380 
381         /**
382          * Character, endlessly repeated in the stream.
383          */
384         private final transient char chr;
385 
386         /**
387          * Whether the next char in the stream should be EOL.
388          */
389         private transient boolean feed;
390 
391         /**
392          * Whether this stream is closed.
393          */
394         private transient boolean closed;
395 
396         /**
397          * Construct an InputStream returning endless combination of this
398          * character and end of line.
399          * @param character Character to return in the stream
400          */
401         InfiniteInputStream(final char character) {
402             super();
403             this.chr = character;
404         }
405 
406         @Override
407         public int read() throws IOException {
408             if (this.closed) {
409                 throw new IOException("Stream closed");
410             }
411             final int next;
412             if (this.feed) {
413                 this.feed = false;
414                 next = VerboseProcessTest.InfiniteInputStream.LINE_FEED;
415             } else {
416                 this.feed = true;
417                 next = this.chr;
418             }
419             return next;
420         }
421 
422         @Override
423         public void close() {
424             this.closed = true;
425         }
426     }
427 
428     /**
429      * Filter of log messages of {@link VerboseProcess}'s monitor threads.
430      *
431      * <p>It filters out messages of monitor threads, that doesn't belong to
432      * specific {@link VerboseProcess}.
433      *
434      * @since 0.1
435      */
436     private final class VrbPrcMonitorFilter extends Filter {
437         /**
438          * Monitor's log message start.
439          */
440         private static final String THREADNAME_START = "VrbPrc.Monitor-";
441 
442         /**
443          * HashCode of {@link VerboseProcess} to filter.
444          */
445         private final transient int hash;
446 
447         /**
448          * Create filter for this process.
449          *
450          * <p>The messages from its monitor threads will be filtered in.
451          * @param prc Process
452          */
453         VrbPrcMonitorFilter(final VerboseProcess prc) {
454             super();
455             this.hash = prc.hashCode();
456         }
457 
458         @Override
459         public int decide(final LoggingEvent event) {
460             final String thread = event.getThreadName();
461             final int decision;
462             if (thread.startsWith(VerboseProcessTest.VrbPrcMonitorFilter.THREADNAME_START
463                 + this.hash
464             )) {
465                 decision = Filter.ACCEPT;
466             } else {
467                 decision = Filter.DENY;
468             }
469             return decision;
470         }
471     }
472 }