More accurate log processing. #643

vektory79 · 2018-04-13T09:58:27Z

The Docker logs can come in non normalized form. The line breaks can be not at end of line, the frame's boundary can split multibyte unicode symbols in the middle and so on.

This patch address this problems and normalize logs so, that they can be processed strictly line by line.

To achive this, the extra base class BaseConsumer have been added. That class normalize the incoming in method accept() logs and forward it to method process() for it's child classes. Other *Consumer classes have been reworked to be child to the BaseConsumer class and only do own work.

Adititionally, BaseConsumer have new withRemoveAnsiCodes(boolean) method for ability to disable ANSI color codes removing (true by default).

The Docker logs can come in non normalized form. The line breaks can be not at end of line, the frame's boundary can split multibyte unicode symbols in the middle and so on. This patch address this problems and normalize logs so, that they can be processed strictly line by line. To achive this, the extra base class BaseConsumer have been added. That class normalize the incoming in method accept() logs and forward it to method process() for it's child classes. Other *Consumer classes have been reworked to be child to the BaseConsumer class and only do own work. Adititionally, BaseConsumer have new withRemoveAnsiCodes(boolean) method for ability to disable ANSI color codes removing (true by default).

bsideup · 2018-04-13T10:04:36Z

core/src/main/java/org/testcontainers/containers/output/BaseConsumer.java

+    public abstract void process(OutputFrame outputFrame);
+
+    @Override
+    public final synchronized void accept(OutputFrame outputFrame) {


I'm afraid making it final breaks the binary compatibility because there might be some strategies based on i.e. Slf4jLogConsumer but overriding accept (I think I even have one)

bsideup · 2018-04-13T10:05:27Z

core/src/main/java/org/testcontainers/containers/output/BaseConsumer.java

+import java.util.List;
+import java.util.function.Consumer;
+
+@SuppressWarnings("Duplicates")


I wonder what does it duplicate?

Argh... It's just a refactoring artifact. Will remove this.

bsideup · 2018-04-13T10:06:13Z

core/src/main/java/org/testcontainers/containers/output/BaseConsumer.java

+public abstract class BaseConsumer<SELF extends BaseConsumer<SELF>> implements Consumer<OutputFrame> {
+    private StringBuilder logString = new StringBuilder();
+    private OutputFrame brokenFrame;
+    private boolean removeColorCodes = true;


please also add Lombok's @Setter to this field

plus @Getter

bsideup · 2018-04-13T10:07:19Z

@vektory79 please add a line to CHANGELOG.md about your improvement.
Also, maybe you have an idea how to test it? At least with a Unit test?

It's help to not ruin the API of *Consumer classes.

…llback.

…or codes now. Added record to the changelog.

bsideup · 2018-04-16T06:19:33Z

CHANGELOG.md


 ### Changed
 - Support multiple HTTP status codes for HttpWaitStrategy ([\#630](https://github.com/testcontainers/testcontainers-java/issues/630))
+- Standard log consumers is are subclasses of `BaseConsumer` class. Other consumers can still only implement a `Consumer` interface, but in `BaseConsumer` class added new `removeColorCodes` property and `withRemoveAnsiCodes(boolean)` method, that can control the log preprocessor to remove/not remove ANSI color codes from log frame before send it to the `Consumer`. By default, preprocessor remove the color codes ([PR \#643](https://github.com/testcontainers/testcontainers-java/pull/643)) 


it should be either "Changed" or "Fixed"

no need to go deeply into the details of the change, just something short and simple (check other entries)

bsideup · 2018-04-16T06:22:20Z

core/src/main/java/org/testcontainers/containers/output/FrameConsumerResultCallback.java

                } else {
-                    consumer.accept(outputFrame);
+                    if (frame.getStreamType() == StreamType.RAW) {


both methods have if (outputFrame != null) { if(utf8String != null && !utf8String.isEmpty()) { ... } }, I would move it here

bsideup · 2018-04-16T06:25:44Z

core/src/main/java/org/testcontainers/containers/output/ToStringConsumer.java


 /**
 * Created by rnorth on 26/03/2016.
 */
-public class ToStringConsumer implements Consumer<OutputFrame> {
+public class ToStringConsumer extends BaseConsumer<ToStringConsumer> {
+    private static final byte[] ENTER_BYTES = "\n".getBytes();


Naming: "NEW_LINE" or "LINE_BREAK"

kiview · 2018-04-16T08:10:52Z

core/src/main/java/org/testcontainers/containers/output/BaseConsumer.java

+
+import java.util.function.Consumer;
+
+public abstract class BaseConsumer<S extends BaseConsumer<S>> implements Consumer<OutputFrame> {


Just a question, why S?

Initially I named this like SELF, but Codacity told me, that type parameters should be length one character. And I have trim this name to S 😄

If this has the same semantics than the SELF used in GenericContainer, I'd prefer SELF (and ignore the warning 🙂).

kiview · 2018-04-16T08:13:37Z

core/src/main/java/org/testcontainers/containers/output/FrameConsumerResultCallback.java

+                }
+                // Logger chunks can break the string in middle of multibyte unicode character.
+                // Backup the bytes to reconstruct proper char sequence with bytes from next frame.
+                if (Character.getType(utf8String.charAt(utf8String.length() - 1)) == Character.OTHER_SYMBOL) {


I would like Character.getType(utf8String.charAt(utf8String.length() - 1)) in a variable.

kiview · 2018-04-16T08:15:26Z

core/src/main/java/org/testcontainers/containers/output/FrameConsumerResultCallback.java

+
+    private void normalizeLogLines(String utf8String, Consumer<OutputFrame> consumer) {
+        // Reformat strings to normalize enters.
+        List<String> lines = new ArrayList<>(Arrays.asList(utf8String.split("((\\r?\\n)|(\\r))")));


I would move split regex into a constant.

kiview · 2018-04-16T08:19:13Z

What's the effect of the current implementation when faced with non-normalized logs?

vektory79 · 2018-04-16T09:28:17Z

@kiview For example: instead of receiving this log lines:

13:17:56.189 INFO  - [DOCKER] STDOUT:   [wildfly] 2018-04-09 13:17:56,134 INFO  [ru.krista.common.gui.utils.FormControllersManager] (default task-32) Подключение контроллера к форме: FD_ReportingSubject_All = ru.krista.consolidation.generators.reporting.ReportTreeCollectionForms. 
13:17:56.190 INFO  - [DOCKER] STDOUT:   [wildfly] 2018-04-09 13:17:56,134 INFO  [ru.krista.common.gui.utils.FormControllersManager] (default task-32) Подключение контроллера к форме: FD_ReportingSubject_InOperation = ru.krista.consolidation.generators.reporting.ReportTreeCollectionForms. 
13:17:56.190 INFO  - [DOCKER] STDOUT:   [wildfly] 2018-04-09 13:17:56,134 INFO  [ru.krista.common.gui.utils.FormControllersManager] (default task-32) Подключение контроллера к форме: FD_ReportingSubject_MyInOperation = ru.krista.consolidation.generators.reporting.ReportTreeCollectionForms. 
13:17:56.190 INFO  - [DOCKER] STDOUT:   [wildfly] 2018-04-09 13:17:56,134 INFO  [ru.krista.common.gui.utils.FormControllersManager] (default task-32) Подключение контроллера к форме: FD_ReportingSubject_MyOnCheck = ru.krista.consolidation.generators.reporting.ReportTreeCollectionForms.

I have receive:

13:17:56.189 INFO  - [DOCKER] STDOUT:   [wildfly] 2018-04-09 13:17:56,134 INFO  [ru.krista.common.gui.utils.FormControllersManager] (default task-32) Подключение контроллера к форме: 
13:17:56.189 INFO  - [DOCKER] STDOUT:  FD_ReportingSubject_All = ru.krista.consolidation.generators.reporting.ReportTreeCollectionForms. 
13:17:56.190 INFO  - [DOCKER] STDOUT:   [wildfly] 2018-04-09 13:17:56,134 INFO  [ru.krista.common.gui.utils.FormControllersManager] (default task-32) Подключение контроллера к форме: FD_ReportingSubject_InOperation = ru.krista.consolidation.generators.reporting.ReportTreeCollectionForms. 
13:17:56.190 INFO  - [DOCKER] STDOUT:   [wildfly] 2018-04-09 13:17:56,134 INFO  [ru.krista.common.gui.ut 
13:17:56.190 INFO  - [DOCKER] STDOUT: ils.FormControllersManager] (default task-32) Подключение контроллера к форме: FD_ReportingSubject_MyInOperation = ru.krista.consolidation.generators.reporting.ReportTreeCollectionForms. 
13:17:56.190 INFO  - [DOCKER] STDOUT:   [wildfly] 2018-04-09 13:17:56,134 INFO  [ru.krista.common.gui.utils.FormControllersManager] (default task-32) Подключение контроллера к форме: FD_ReportingSubject_MyOnCheck = ru.krista.consolidation.generators.reporting.Repor 
13:17:56.190 INFO  - [DOCKER] STDOUT: tTreeCollectionForms.

vektory79 · 2018-04-16T09:32:19Z

One more example:

13:16:51.753 INFO  - [DOCKER] STDOUT:   [wildfly] 2018-04-09 13:16:51,741 INFO  [ru.krista.jpa.inflatable.InflatablePersistenceProvider] (default task-1) Для генерации DDL используе� 
13:16:51.753 INFO  - [DOCKER] STDOUT: �ся провайдер [ru.krista.jpa.inflatable.InflatablePersistenceProvider]

Instead of:

13:16:51.753 INFO  - [DOCKER] STDOUT:   [wildfly] 2018-04-09 13:16:51,741 INFO  [ru.krista.jpa.inflatable.InflatablePersistenceProvider] (default task-1) Для генерации DDL используется провайдер [ru.krista.jpa.inflatable.InflatablePersistenceProvider]

kiview · 2018-04-16T10:31:04Z

Thanks for the clarification, maybe #455 could be related to this as well (I think we never analyzed, if we are missing the log lines, or if the lines have been formatted in strange ways).

…t for it. If StreamType is STDERR or STDOUT the log always have newline at line end. Therefore preprocessor should trim it to be consistent with RAW type processing.

…ng directly in Slf4jLogConsumer class.

rnorth

Looks excellent to me - thank you for contributing this @vektory79 !

vektory79 requested review from bsideup, kiview and rnorth as code owners April 13, 2018 09:58

bsideup reviewed Apr 13, 2018

View reviewed changes

bsideup added the type/feature label Apr 13, 2018

Victor Verbitsky and others added 8 commits April 13, 2018 15:53

Move normalization logic directly to FrameConsumerResultCallback

fb7dd2d

It's help to not ruin the API of *Consumer classes.

Added some tests for log normalization in class FrameConsumerResultCa…

503e0d8

…llback.

Fix Codacity warning

1f544bf

More test for the FrameConsumerResultCallback class

656c80d

Stabilize tests

9a693e7

Log consumers, that not derive BaseConsumer class, is not receive col…

aec8bad

…or codes now. Added record to the changelog.

Merge branch 'master' into fix-log-consumption

d5d8959

One more test for FrameConsumerResultCallback class.

4da324f

bsideup reviewed Apr 16, 2018

View reviewed changes

bsideup requested changes Apr 16, 2018

View reviewed changes

kiview requested changes Apr 16, 2018

View reviewed changes

Fixes due to the code review recommendations

489dd9b

Victor Verbitsky and others added 4 commits April 16, 2018 14:30

Fixes due to the code review recommendations (Part 2)

2bacce8

One more use case for FrameConsumerResultCallback class. And unit tes…

6191e6e

…t for it. If StreamType is STDERR or STDOUT the log always have newline at line end. Therefore preprocessor should trim it to be consistent with RAW type processing.

Roll back previouse change doe to failing tests. Doing newline trimmi…

25fec6c

…ng directly in Slf4jLogConsumer class.

Fixes due to the code review recommendations (Part 3)

64b1e0e

bsideup approved these changes Apr 16, 2018

View reviewed changes

rnorth approved these changes Apr 17, 2018

View reviewed changes

bsideup added this to the next milestone Apr 17, 2018

kiview approved these changes Apr 17, 2018

View reviewed changes

bsideup merged commit 9fb8e4b into testcontainers:master Apr 17, 2018

kiview mentioned this pull request May 14, 2018

LogMessageWaitStrategy for PostgreSQLContainer times out #455

Closed

SgtSilvio mentioned this pull request Sep 18, 2022

[Bug]: LogMessageWaitStrategy erroneously assumes each log frame contains a complete log line #5843

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

More accurate log processing. #643

More accurate log processing. #643

vektory79 commented Apr 13, 2018

bsideup Apr 13, 2018

bsideup Apr 13, 2018

vektory79 Apr 13, 2018

bsideup Apr 13, 2018

bsideup Apr 13, 2018 •

edited

Loading

bsideup commented Apr 13, 2018

bsideup Apr 16, 2018

bsideup Apr 16, 2018

bsideup Apr 16, 2018

kiview Apr 16, 2018

vektory79 Apr 16, 2018

kiview Apr 16, 2018

kiview Apr 16, 2018

kiview Apr 16, 2018

kiview commented Apr 16, 2018

vektory79 commented Apr 16, 2018 •

edited

Loading

vektory79 commented Apr 16, 2018

kiview commented Apr 16, 2018

rnorth left a comment


		import java.util.function.Consumer;

		public abstract class BaseConsumer<S extends BaseConsumer<S>> implements Consumer<OutputFrame> {

More accurate log processing. #643

More accurate log processing. #643

Conversation

vektory79 commented Apr 13, 2018

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

bsideup Apr 13, 2018 • edited Loading

Choose a reason for hiding this comment

bsideup commented Apr 13, 2018

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

kiview commented Apr 16, 2018

vektory79 commented Apr 16, 2018 • edited Loading

vektory79 commented Apr 16, 2018

kiview commented Apr 16, 2018

rnorth left a comment

Choose a reason for hiding this comment

bsideup Apr 13, 2018 •

edited

Loading

vektory79 commented Apr 16, 2018 •

edited

Loading