Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

JSON Writer leave json file in correct state #205

Closed
proohit opened this issue Apr 28, 2021 · 16 comments
Closed

JSON Writer leave json file in correct state #205

proohit opened this issue Apr 28, 2021 · 16 comments
Milestone

Comments

@proohit
Copy link
Contributor

proohit commented Apr 28, 2021

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

@proohit proohit added the bug label Apr 28, 2021
@pmwmedia pmwmedia added this to the 2.4 milestone Apr 28, 2021
@pmwmedia
Copy link
Member

Sounds plausible. Would you provide a pull request?

@proohit
Copy link
Contributor Author

proohit commented Apr 28, 2021

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
Copy link
Member

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 added a commit to proohit/tinylog that referenced this issue Apr 28, 2021
- Everytime an entry is written, the needed closing array bracket is written too.
- Every entry checks for itself, if it's the first one and appends a comma accordingly
- No post processing is needed anymore
- To append, the file is checked for a valid array
proohit added a commit to proohit/tinylog that referenced this issue Apr 28, 2021
proohit added a commit to proohit/tinylog that referenced this issue Apr 28, 2021
proohit added a commit to proohit/tinylog that referenced this issue Apr 28, 2021
@proohit proohit mentioned this issue Apr 28, 2021
9 tasks
@proohit
Copy link
Contributor Author

proohit commented Apr 28, 2021

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

proohit added a commit to proohit/tinylog that referenced this issue Apr 30, 2021
proohit added a commit to proohit/tinylog that referenced this issue Apr 30, 2021
@pmwmedia pmwmedia modified the milestones: 2.4, 2.5 Oct 30, 2021
@pmwmedia
Copy link
Member

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
Copy link

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
Copy link

davidmoshal commented Dec 19, 2021

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
Copy link
Contributor Author

proohit commented Dec 19, 2021

@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
Copy link
Contributor Author

proohit commented Dec 19, 2021

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
Copy link

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
Copy link
Contributor Author

proohit commented Dec 19, 2021

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
Copy link

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
Copy link
Member

pmwmedia commented Dec 20, 2021

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 Line-delimited JSON support #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
Copy link

@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
Copy link
Member

pmwmedia commented Dec 21, 2021

@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
Copy link

github-actions bot commented Oct 9, 2022

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

@github-actions github-actions bot locked as resolved and limited conversation to collaborators Oct 9, 2022
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Development

No branches or pull requests

5 participants