Multi-threaded JBehave logging mess

Question

While it is qute clear how to configure multi-threaded jBehave run,
it is not qute clear for me how to deal with logging mess.

What are the options here?

Answer 1

1. Rederect application's output to std out (JBehave's one is already there). Notice follow=true

   log4j.appender.stdout=org.apache.log4j.ConsoleAppender
   log4j.appender.stdout.follow=true
   log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
   log4j.appender.stdout.layout.ConversionPattern=%d{ISO8601} | %-5.5p | %-16.16t | %-32.32c{1} | %-64.64C %4L | %m%n
   
   log4j.rootLogger=error, stdout
   log4j.logger.com.company.app.interesting.module=debug
   ...
   

2. Per thread file output

   @SuppressWarnings("resource")
   public class ThreadFileOutput extends PrintStream {
   
       private static ThreadLocal<FileOutputStream> threadOutput = new ThreadLocal<>();
       private static PrintStream stdout = System.out;
       private static PrintStream stderr = System.err;
   
       static {
           System.setOut(new ThreadFileOutput(stdout));
           System.setErr(new ThreadFileOutput(stderr));
       }
   
       public ThreadFileOutput(OutputStream out) {
           super(out);
       }
   
       public static void startThreadOutputRedirect(FileOutputStream stream) {
           threadOutput.set(stream);
       }
   
       public static void stopThreadOutputRedirect() {
           FileOutputStream stream = threadOutput.get();
           if (stream != null) {
               threadOutput.set(null);
               try {
                   stream.close();
               } catch (IOException e) {
                   throw new RuntimeException(e);
               }
           }
       }
   
       public static void forceOut(String line) {
           stdout.println(line);
       }
   
       public static void forceErr(String line) {
           stderr.println(line);
       }
   
       @Override
       public void write(byte[] b) throws IOException {
           FileOutputStream stream = threadOutput.get();
           if (stream != null) {
               try {
                   stream.write(b);
               } catch (IOException e) {
                   threadOutput.set(null);
                   throw new RuntimeException(e);
               }
           } else {
               super.write(b);
           }
       }
   
       @Override
       public void write(int b) {
           FileOutputStream stream = threadOutput.get();
           if (stream != null) {
               try {
                   stream.write(b);
               } catch (IOException e) {
                   threadOutput.set(null);
                   throw new RuntimeException(e);
               }
           } else {
               super.write(b);
           }
       }
   
       @Override
       public void write(byte[] buf, int off, int len) {
           FileOutputStream stream = threadOutput.get();
           if (stream != null) {
               try {
                   stream.write(buf, off, len);
               } catch (IOException e) {
                   threadOutput.set(null);
                   throw new RuntimeException(e);
               }
           } else {
               super.write(buf, off, len);
           }
       }
   
       @Override
       public void flush() {
           FileOutputStream stream = threadOutput.get();
           if (stream != null) {
               try {
                   stream.flush();
               } catch (IOException e) {
                   threadOutput.set(null);
                   throw new RuntimeException(e);
               }
           } else {
               super.flush();
           }
       }
   }
   

3. Start redirecting thread output to the file befor the test and stop it after the test

   startThreadOutputRedirect(new FileOutputStream(new File(workDirRelative(story.getPath())))); 
   stopThreadOutputRedirect();
   

   in

   /**
    * JBehave to TC integration.
    */
   public class TeamCityReporter extends NullStoryReporter {
   
       private static final LookupTranslator ESCAPE_TABLE = new LookupTranslator(new String[][] {
               { "'", "|'" },
               { "\n", "|n" },
               { "\r", "|r" },
               { "\\u", "|0x" },
               { "|", "||" },
               { "[", "|[" },
               { "]", "|]" }
       });
   
       private ThreadLocal<Story> story = new ThreadLocal<>();
       private ThreadLocal<String> scenario = new ThreadLocal<>();
   
       @Override
       @SuppressWarnings("resource")
       public void beforeStory(Story story, boolean givenStory) {
           this.story.set(story);
           this.scenario.set(null);
   
           try {
               startThreadOutputRedirect(new FileOutputStream(new File(workDirRelative(story.getPath()))));
           } catch (FileNotFoundException e) {
               throw new RuntimeException(e);
           }
   
           forceOut(format("##teamcity[testSuiteStarted name='%s']", escape(story.getPath())));
           out.println(story.getPath());
   
           super.beforeStory(story, givenStory);
       }
   
       @Override
       public void afterStory(boolean givenStory) {
           forceOut(format("##teamcity[testSuiteFinished name='%s']", escape(story.get().getPath())));
           stopThreadOutputRedirect();
   
           super.afterStory(givenStory);
       }
   
       @Override
       public void beforeScenario(String scenario) {
           this.scenario.set(scenario);
   
           forceOut(format("##teamcity[testStarted name='%s']", escape(scenario)));
           out.println(scenario);
   
           super.beforeScenario(scenario);
       }
   
       @Override
       public void afterScenario() {
           forceOut(format("##teamcity[testFinished name='%s']", escape(scenario.get())));
   
           this.scenario.set(null);
           super.afterScenario();
       }
   
       @Override
       public void beforeStep(String step) {
           out.println(format("\n%s\n", step));
           super.beforeStep(step);
       }
   
       @Override
       public void storyNotAllowed(Story story, String filter) {
           forceOut(format("##teamcity[message text='story not allowed %s' status='WARNING']", escape(story.getName())));
           out.println(format("\n(Not allowed) %s\n", story.getPath()));
           super.storyNotAllowed(story, filter);
       }
   
       @Override
       public void failed(String step, Throwable cause) {
           forceOut(format("##teamcity[testFailed  name='%s' message='%s' details='%s']", new String[] { escape(scenario.get()), escape(getRootCauseMessage(cause)), escape(getStackTrace(cause)) }));
           out.println(format("\n(Failed) %s\n", step));
           cause.printStackTrace();
           super.failed(step, cause);
       }
   
       @Override
       public void pending(String step) {
           forceOut(format("##teamcity[testFailed  name='%s' message='Step in PENDING state: %s']", escape(scenario.get()), escape(step)));
           out.println(format("\n(Pending) %s\n", step));
           super.pending(step);
       }
   
       @Override
       public void notPerformed(String step) {
           out.println(format("\n(Not performed) %s\n", step));
           super.notPerformed(step);
       }
   
       private static String escape(String string) {
           return ESCAPE_TABLE.translate(string);
       }
   }
   

4. Turn on parallel JBehave execution

   @RunWith(SpringJUnit4ClassRunner.class)
   @ContextConfiguration(locations = {
       ...
   })
   public class Stories extends JUnitStories {
   
       @Before
       public void setUp() throws Exception {
           configuredEmbedder()
                   // turn on parallel test execution
                   .useExecutorService(newFixedThreadPool(30, new ThreadFactoryBuilder()
                       .setDaemon(true)
                       .build()));
   
           configuredEmbedder()
                   .embedderControls()
                   ...
                   // don't use it this way not to produce multiThreading = true and delayed StoryReporter callbacks
                   // and you will see your application logging 'for each jbehave step'
                   // .useThreads(30);
       }
   
       @Override
       public Configuration configuration() {
           return new MostUsefulConfiguration()
                   ...
                   .useStoryReporterBuilder(new StoryReporterBuilder()
                           ...
                           .withFormats(HTML)
                           .withReporters(teamCityReporter));
       }
   }
   

As a result, there will be a log file for each parallel test having both test output and application output (only the code being executed by test runner thread).
Bonus - TeamCityReporter (JBehave to TC integration) will successfully count running parallel tests in real time and report any test failures on TC GUI. Configure test output directory as TC artifact path to access each test output.