JSON Writer leave json file in correct state

[proohit]

Describe the issue Currently, the writer leaves the ] out and keeps the last , which is invalid json. I think we should let the json log file always stay in a syntactic correct state. One would not be able to parse the file while it does not match JSON spec.

Currently the close method performs the last steps needed to bring it in that state by calling postProcess. Maybe we could handle the logic of postProcess everytime we write an entry. The new close method should then only handle writer.flush() and writer.close()

The file currently looks like this:

[
    {
           ...
    },

To Reproduce

1. configure properties to use json writer
2. start application
3. write any entry
4. use the json for anything other while application is running

Environment tinylog version: 2.4 Java version: 15

[pmwmedia]

Sounds plausible. Would you provide a pull request?

[proohit]

I'm having some trouble building tinylog.. Do you have an idea why those errors are occuring?

[INFO] 21 errors
[INFO] -------------------------------------------------------------
[INFO] ------------------------------------------------------------------------
[INFO] Reactor Summary:
[INFO]
[INFO] parent ............................................. SUCCESS [  0.182 s]
[INFO] test core .......................................... SUCCESS [ 10.115 s]
[INFO] tinylog API ........................................ FAILURE [  1.508 s]
[INFO] tinylog implementation ............................. SKIPPED
[INFO] tinylog adapter for JBoss Logging .................. SKIPPED
[INFO] tinylog adapter for java.util.logging .............. SKIPPED
[INFO] tinylog Kotlin API ................................. SKIPPED
[INFO] tinylog Scala API .................................. SKIPPED
[INFO] JBoss Logging binding for tinylog .................. SKIPPED
[INFO] Apache Commons Logging (JCL) binding for tinylog ... SKIPPED
[INFO] java.util.logging to tinylog bridge ................ SKIPPED
[INFO] Log4j 1.2 API for tinylog .......................... SKIPPED
[INFO] SLF4J binding for tinylog .......................... SKIPPED
[INFO] tinylog 1.3 API for tinylog 2 ...................... SKIPPED
[INFO] benchmarks ......................................... SKIPPED
[INFO] ------------------------------------------------------------------------
[INFO] BUILD FAILURE
[INFO] ------------------------------------------------------------------------
[INFO] Total time: 12.783 s
[INFO] Finished at: 2021-04-28T21:55:35+02:00
[INFO] Final Memory: 82M/273M
[INFO] ------------------------------------------------------------------------
[ERROR] Failed to execute goal org.apache.maven.plugins:maven-compiler-plugin:3.8.1:testCompile (default-testCompile) on project tinylog-api: Compilation failure: Compilation failure:
[ERROR] /C:/Users/Diren/Documents/workspace/tinylog/tinylog-api/src/test/java/org/tinylog/format/AdvancedMessageFormatterTest.java:[62,55] diamond operator is not supported in -source 1.6
[ERROR]   (use -source 7 or higher to enable diamond operator)
[ERROR] /C:/Users/Diren/Documents/workspace/tinylog/tinylog-api/src/test/java/org/tinylog/format/AdvancedMessageFormatterTest.java:[107,49] lambda expressions are not supported in -source 1.6
[ERROR]   (use -source 8 or higher to enable lambda expressions)
[ERROR] /C:/Users/Diren/Documents/workspace/tinylog/tinylog-api/src/test/java/org/tinylog/runtime/LegacyTimestampTest.java:[37,103] underscores in literals are not supported in -source 1.6
[ERROR]   (use -source 7 or higher to enable underscores in literals)
[ERROR] /C:/Users/Diren/Documents/workspace/tinylog/tinylog-api/src/test/java/org/tinylog/util/TimestampFactory.java:[111,89] underscores in literals are not supported in -source 1.6
[ERROR]   (use -source 7 or higher to enable underscores in literals)
[ERROR] /C:/Users/Diren/Documents/workspace/tinylog/tinylog-api/src/test/java/org/tinylog/runtime/LegacyJavaRuntimeTest.java:[268,87] underscores in literals are not supported in -source 1.6
[ERROR]   (use -source 7 or higher to enable underscores in literals)
[ERROR] /C:/Users/Diren/Documents/workspace/tinylog/tinylog-api/src/test/java/org/tinylog/format/EndlessIteratorTest.java:[30,73] diamond operator is not supported in -source 1.6
[ERROR]   (use -source 7 or higher to enable diamond operator)
[ERROR] /C:/Users/Diren/Documents/workspace/tinylog/tinylog-api/src/test/java/org/tinylog/LoggerTest.java:[116,63] diamond operator is not supported in -source 1.6
[ERROR]   (use -source 7 or higher to enable diamond operator)
[ERROR] /C:/Users/Diren/Documents/workspace/tinylog/tinylog-api/src/test/java/org/tinylog/provider/BundleContextProviderTest.java:[191,38] diamond operator is not supported in -source 1.6
[ERROR]   (use -source 7 or higher to enable diamond operator)
[ERROR] /C:/Users/Diren/Documents/workspace/tinylog/tinylog-api/src/test/java/org/tinylog/provider/BundleContextProviderTest.java:[191,44] lambda expressions are not supported in -source 1.6
[ERROR]   (use -source 8 or higher to enable lambda expressions)
[ERROR] /C:/Users/Diren/Documents/workspace/tinylog/tinylog-api/src/test/java/org/tinylog/TaggedLoggerTest.java:[112,55] diamond operator is not supported in -source 1.6
[ERROR]   (use -source 7 or higher to enable diamond operator)
[ERROR] /C:/Users/Diren/Documents/workspace/tinylog/tinylog-api/src/test/java/org/tinylog/format/LegacyMessageFormatterTest.java:[73,49] lambda expressions are not supported in -source 1.6
[ERROR]   (use -source 8 or higher to enable lambda expressions)
[ERROR] /C:/Users/Diren/Documents/workspace/tinylog/tinylog-api/src/test/java/org/tinylog/runtime/PreciseTimestampTest.java:[37,104] underscores in literals are not supported in -source 1.6
[ERROR]   (use -source 7 or higher to enable underscores in literals)
[ERROR] /C:/Users/Diren/Documents/workspace/tinylog/tinylog-api/src/test/java/org/tinylog/runtime/LegacyTimestampFormatterTest.java:[54,93] underscores in literals are not supported in -source 1.6
[ERROR]   (use -source 7 or higher to enable underscores in literals)
[ERROR] /C:/Users/Diren/Documents/workspace/tinylog/tinylog-api/src/test/java/org/tinylog/runtime/ModernJavaRuntimeTest.java:[158,87] underscores in literals are not supported in -source 1.6
[ERROR]   (use -source 7 or higher to enable underscores in literals)
[ERROR] /C:/Users/Diren/Documents/workspace/tinylog/tinylog-api/src/test/java/org/tinylog/format/JavaTextMessageFormatFormatterTest.java:[77,49] lambda expressions are not supported in -source 1.6
[ERROR]   (use -source 8 or higher to enable lambda expressions)
[ERROR] /C:/Users/Diren/Documents/workspace/tinylog/tinylog-api/src/test/java/org/tinylog/runtime/AndroidRuntimeTest.java:[303,87] underscores in literals are not supported in -source 1.6
[ERROR]   (use -source 7 or higher to enable underscores in literals)
[ERROR] /C:/Users/Diren/Documents/workspace/tinylog/tinylog-api/src/test/java/org/tinylog/configuration/ConfigurationTest.java:[587,39] lambda expressions are not supported in -source 1.6
[ERROR]   (use -source 8 or higher to enable lambda expressions)
[ERROR] /C:/Users/Diren/Documents/workspace/tinylog/tinylog-api/src/test/java/org/tinylog/format/PrintfStyleFormatterTest.java:[75,49] lambda expressions are not supported in -source 1.6
[ERROR]   (use -source 8 or higher to enable lambda expressions)
[ERROR] /C:/Users/Diren/Documents/workspace/tinylog/tinylog-api/src/test/java/org/tinylog/runtime/PreciseTimestampFormatterTest.java:[54,93] underscores in literals are not supported in -source 1.6
[ERROR]   (use -source 7 or higher to enable underscores in literals)
[ERROR] /C:/Users/Diren/Documents/workspace/tinylog/tinylog-api/src/test/java/org/tinylog/configuration/ServiceLoaderTest.java:[89,61] diamond operator is not supported in -source 1.6
[ERROR]   (use -source 7 or higher to enable diamond operator)
[ERROR] /C:/Users/Diren/Documents/workspace/tinylog/tinylog-api/src/test/java/org/tinylog/configuration/ServiceLoaderTest.java:[130,53] lambda expressions are not supported in -source 1.6
[ERROR]   (use -source 8 or higher to enable lambda expressions)
[ERROR] -> [Help 1]
[ERROR]
[ERROR] To see the full stack trace of the errors, re-run Maven with the -e switch.
[ERROR] Re-run Maven using the -X switch to enable full debug logging.
[ERROR]
[ERROR] For more information about the errors and possible solutions, please read the following articles:
[ERROR] [Help 1] http://cwiki.apache.org/confluence/display/MAVEN/MojoFailureException
[ERROR]
[ERROR] After correcting the problems, you can resume the build with the command
[ERROR]   mvn <goals> -rf :tinylog-api

I assume this leads to the following error when trying to only build tinylog-impl

mvn clean verify
[INFO] Scanning for projects...
[INFO]
[INFO] ------------------------------------------------------------------------
[INFO] Building tinylog implementation 2.4-SNAPSHOT
[INFO] ------------------------------------------------------------------------
[WARNING] The POM for org.tinylog:tinylog-api:jar:2.4-SNAPSHOT is missing, no dependency information available
[INFO] ------------------------------------------------------------------------
[INFO] BUILD FAILURE
[INFO] ------------------------------------------------------------------------
[INFO] Total time: 1.136 s
[INFO] Finished at: 2021-04-28T22:00:46+02:00
[INFO] Final Memory: 17M/56M
[INFO] ------------------------------------------------------------------------
[ERROR] Failed to execute goal on project tinylog-impl: Could not resolve dependencies for project org.tinylog:tinylog-impl:bundle:2.4-SNAPSHOT: Could not find artifact org.tinylog:tinylog-api:jar:2.4-SNAPSHOT -> [Help 1]
[ERROR]
[ERROR] To see the full stack trace of the errors, re-run Maven with the -e switch.
[ERROR] Re-run Maven using the -X switch to enable full debug logging.
[ERROR]
[ERROR] For more information about the errors and possible solutions, please read the following articles:
[ERROR] [Help 1] http://cwiki.apache.org/confluence/display/MAVEN/DependencyResolutionException

env

mvn --version
Apache Maven 3.5.0 (ff8f5e7444045639af65f6095c62210b5713f426; 2017-04-03T21:39:06+02:00)
Maven home: C:\Program Files\Maven\apache-maven-3.5.0\bin\..
Java version: 9.0.4, vendor: Oracle Corporation
Java home: C:\Program Files\Java\jdk-9.0.4+11
Default locale: en_US, platform encoding: Cp1252
OS name: "windows 10", version: "10.0", arch: "amd64", family: "windows"

java --version
openjdk 9.0.4
OpenJDK Runtime Environment (build 9.0.4+11)
OpenJDK 64-Bit Server VM (build 9.0.4+11, mixed mode)

[pmwmedia]

It looks like that the Maven profile "dev" was not active. However, I just updated the parent pom.xml, so that activation of this Maven profile is no longer required. I hope it will compile now.

[proohit]

Yes, your changes fixed it, thanks.:) Please have a look at the PR.

[pmwmedia]

Currently, the JSON writer will place the correct closing ] when closing a file. The objective of this issue is to have a correct closing ] after each flush(). I have converted this bug into an enhancement as this is an improvement rather than a bug.

[Fleshgrinder]

Is there a reason why we try to enclose the file's content with []? Usually JSON logs use the so called JSON lines format, where each line is expected to be valid JSON, without any wrapping array. This makes the writing much easier. It also ensures that you can do things like tail and head and still parse the JSON without issues. Other software like Graylog also expects that it received each line as single JSON object without any array parts to it.

I'd also recommend to not tie JSON with a file, it should be possible to write it anywhere (e.g. standard out).

[davidmoshal]

I think I have the same problem:

LOGGER ERROR: Failed creating service implementation 'org.tinylog.writers.JsonWriter' (java.lang.IllegalArgumentException: Invalid JSON file. The file is missing a closing bracket for the array.)

Any suggestions? It's intermittent. It's possible that it was trying to log a json string when it threw that error.

[proohit]

@davidmoshal usually the check for a valid json executes only once during initialization, e.g. on startup.

Was this state of the file created by the writer? If yes, is there any chance for reproduction?

[proohit]

Is there a reason why we try to enclose the file's content with []? Usually JSON logs use the so called JSON lines format, where each line is expected to be valid JSON, without any wrapping array. This makes the writing much easier. It also ensures that you can do things like tail and head and still parse the JSON without issues. Other software like Graylog also expects that it received each line as single JSON object without any array parts to it.

The initial idea was to generate a JSON conform output so that it can be parsed by JSON parsers. Is the JSON line format valid JSON, i.e. parseable by common parsers??

[rbygrave]

Line-delimited JSON

https://en.wikipedia.org/wiki/JSON_streaming#Line-delimited_JSON

parseable by common parsers??

Generally the parser (like say Jackson core JsonParser) doesn't need to support it directly. That is, the log reader/publisher reads lines and then for each line uses the parser (say Jackson JsonParser) to parse the line. In this way the check for valid JSON is per line.

Things like ElasticSearch take line delimited JSON. So for example, if the logging output is being send to ElasticSearch you can send it to the bulk API: https://www.elastic.co/guide/en/elasticsearch/reference/current/docs-bulk.html

[proohit]

I agree that any large scale, high performance or streaming based use case may require this lighter format. However, I wanted to avoid solutions shown in this SO question only for simply parsing json.

I do think that a configurable format for JSON or e.g. LDJSON would make sense. What are your thoughts?

[rbygrave]

I wanted to avoid solutions shown in this SO question only for simply parsing json.

I think that is somewhat unrelated in that I don't think we ever in practice turn X Mb of logs into a List<T> but we would instead turn it into a Stream<T>. Or said another way, we get a stream of lines Stream<String> and map each line getting Stream<T>.

So as I see it, I don't think that SO answer is practical, useful, helpful wrt logs, in that it will work with really small amounts of data only. With logs we are more conceptually dealing with a stream than a list.

JSON or e.g. LDJSON would make sense. What are your thoughts?

My expectation is that LDJSON is the expected practical output for logging as JSON. That is what I've seen and used in the past via ElasticSearch ECS - Elastic Common Schema.

What is ECS? Elastic Common Schema (ECS) defines a common set of fields for ingesting data into Elasticsearch. For more information about ECS, visit the ECS Reference Documentation.

https://www.elastic.co/guide/en/ecs-logging/overview/master/intro.html https://www.elastic.co/guide/en/ecs-logging/java/current/setup.html

[pmwmedia]

Thank for all the great and useful input. I see four necessary steps:

1. Add support for line-delimited JSON. However, the current behavior will be the standard for compatibility reasons and line-delimited JSON can be activated by a new property for the JSON writer. (see #229)

2. @davidmoshal: Could you provide the log file, so that I can analyze what is the reason for the invalid state and causes the exception. You can either open a new issue here or send me the log to martin@tinylog.org. Feel free to remove sensitive content from the log file.

3. In tinylog 2, we cannot write JSON everywhere as the output format is coupled to the writer by architecture. This will be changed with tinylog 3. However, I would accept also a pull request that can output JSON to another output in tinylog 2.

4. The original intention of this issue to bring the JSON file in a correct state by adding a closing ] at the end of the file with each flush will be implemented for tinylog 2.5.

[davidmoshal]

@proohit @pmwmedia:

• I have only seen the problem while testing a Quarkus application.
• The log file is basically truncated, and looks like this:

[
    {
        "level" : "INFO" ,
        "source" : "au21.engine.framework.commands.EngineCommandHandler.handle()" ,
        "message" : "{\"session_id\":\"\",\"command_json\":[],\"simplename\":\"DbDeleteAuctionsCommand\",\"classname\":\"au21.engine.domain.de.commands.DbDeleteAuctionsCommand\"}" 
    },
       // ... removed hundreds of similar objects ...
    {
        "level" : "INFO" ,
        "source" : "au21.engine.framework.commands.EngineCommandHandler.handle()" ,
        "message" : "{\"session_id\":\"\",\"command_json\":[

Initially I thought that it was due to the test runner killing the process before it could flush the last message to the log file. However, it ALWAYS fails at the same place. ie: at the point it's writing a json object to a json log file!

[pmwmedia]

@davidmoshal Is "message" : "{\"session_id\":\"\",\"command_json\":[ really the last line of the JSON file?

According to the algorithm, something should be written also afterwards. It would be also interesting to know what JSON object should be written there as message.

[github-actions[bot]]

This closed issue has been locked automatically. However, please feel free to file a new issue.