Skip to content

Trim the JSON source in indexing slow logs#38081

Merged
pgomulka merged 3 commits intoelastic:masterfrom
pgomulka:feature/slow_logs
Feb 1, 2019
Merged

Trim the JSON source in indexing slow logs#38081
pgomulka merged 3 commits intoelastic:masterfrom
pgomulka:feature/slow_logs

Conversation

@pgomulka
Copy link
Contributor

@pgomulka pgomulka commented Jan 31, 2019 •
edited
Loading

The '{' as a first character in log line is causing problems for beats when parsing plaintext logs.
This is used to distinguish if the logs are in JSON or plaintext (they want to keep the logic consistent for docker and standalone deployments, so file extension can not be used).

When the JSON in source element is not reformatted (index.indexing.slowlog.reformat: false) and the user send a document with an additional \n like here:

curl --request PUT \
  --url http://localhost:9200/index1/doc/2 \
  --header 'content-type: application/json' \
  --data '
{
      "network":{
        "name":"lo0",
        "in":{
          "errors":0,
          "dropped":0,
          "bytes":77666873,
          "packets":244595},
          "out":{
            "packets":244595,
            "bytes":77666873,
            "errors":0,
            "dropped":0
          }
        }
      }'

Then the { will endup in a new line

[2018-07-04T21:51:30,411][INFO ][index.indexing.slowlog.index] [v_VJhjV] [metricbeat-6.3.0-2018.07.04/VLKxBLvUSYuIMKzpacGjRg] took[1.7ms], took_millis[1], type[doc], id[s01HZ2QBk9jw4gtgaFtn], routing[], source[
{
  "@timestamp":"2018-07-04T21:27:30.730Z",
  "metricset":{
...

Trimming the source part of a SlowLog will solve the problem and will keep the logs readable.

2018-07-04T21:51:30,411][INFO ][index.indexing.slowlog.index] [v_VJhjV] [metricbeat-6.3.0-2018.07.04/VLKxBLvUSYuIMKzpacGjRg] took[1.7ms], took_millis[1], type[doc], id[s01HZ2QBk9jw4gtgaFtn], routing[], source[{
  "@timestamp":"2018-07-04T21:27:30.730Z",
...
...
}]

This won't happen for Search slow logs, as we repackage the user's request into our own SearchRequest object.
closes #38080

@pgomulka pgomulka self-assigned this Jan 31, 2019
@pgomulka pgomulka changed the title Trim the source to avoid problems when parsing by beats Trim the JSON source in slog logs Jan 31, 2019
@pgomulka pgomulka added the :Core/Infra/Logging Log management and logging utilities label Jan 31, 2019
@elasticmachine
Copy link
Collaborator

elasticmachine commented Jan 31, 2019

Pinging @elastic/es-core-infra

@ycombinator ycombinator mentioned this pull request Jan 31, 2019
Merged
@ycombinator ycombinator changed the title Trim the JSON source in slog logs Trim the JSON source in slow logs Jan 31, 2019
alpar-t
alpar-t approved these changes Jan 31, 2019
View reviewed changes
Copy link
Contributor

@alpar-t alpar-t left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM

danielmitterdorfer
danielmitterdorfer reviewed Jan 31, 2019
View reviewed changes
Copy link
Member

@danielmitterdorfer danielmitterdorfer left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I left a comment. Based on the PR description I also could not grasp the purpose of this. It only became apparent after reading the related issue. Could you please reword the PR description as well so this becomes clearer?

server/src/main/java/org/elasticsearch/index/IndexingSlowLog.java
try {
String source = XContentHelper.convertToJson(doc.source(), reformat, doc.getXContentType());
sb.append(", source[").append(Strings.cleanTruncate(source, maxSourceCharsToLog)).append("]");
sb.append(", source[").append(Strings.cleanTruncate(source, maxSourceCharsToLog).trim()).append("]");
Copy link
Member

@danielmitterdorfer danielmitterdorfer Jan 31, 2019

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I wonder whether it is possible to create source without any leading line breaks so we can avoid the trim() at all?

Copy link
Contributor Author

@pgomulka pgomulka Jan 31, 2019

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

once you mentioned that I started to investigate how this could even happen.. It turns out that only when reformat=false then the code is just logging whatever data user provided.
So the trim is necessary.
Also I confirmed that this can only happen for the IndexingSLowLog. For search slow log we repackage user's request into our own object SearchRequest.

@pgomulka pgomulka changed the title Trim the JSON source in slow logs Trim the JSON source in indexing slow logs Jan 31, 2019
danielmitterdorfer
danielmitterdorfer reviewed Jan 31, 2019
View reviewed changes
Copy link
Member

@danielmitterdorfer danielmitterdorfer left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The changes themselves look fine but I think we should not reformat unrelated changes here so I left a bunch of comments around that.

server/src/test/java/org/elasticsearch/index/IndexingSlowLogTests.java Outdated
.put(IndexMetaData.SETTING_NUMBER_OF_REPLICAS, 1)
.put(IndexMetaData.SETTING_NUMBER_OF_SHARDS, 1)
.put(indexSettings)
.build();
Copy link
Member

@danielmitterdorfer danielmitterdorfer Jan 31, 2019

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

That looks a bit odd to me and also unrelated to this change? Can you please restore the old formatting?

Copy link
Contributor Author

@pgomulka pgomulka Jan 31, 2019

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I reverted back to previous formatting. must have done this by accident. sorry

server/src/test/java/org/elasticsearch/index/IndexingSlowLogTests.java Outdated
final IllegalArgumentException cause = (IllegalArgumentException) e.getCause();
final String causeExpected =
"failed to parse setting [" + key + "] with value [NOT A TIME VALUE] as a time value: unit is missing or unrecognized";
"failed to parse setting [" + key + "] with value [NOT A TIME VALUE] as a time value: unit is missing or unrecognized";
Copy link
Member

@danielmitterdorfer danielmitterdorfer Jan 31, 2019

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

That looks unrelated to this change? Can you please restore the old formatting?

server/src/test/java/org/elasticsearch/index/IndexingSlowLogTests.java Outdated
settings.updateIndexMetaData(newIndexMeta("index",
Settings.builder().put(IndexingSlowLog.INDEX_INDEXING_SLOWLOG_THRESHOLD_INDEX_WARN_SETTING.getKey(), "NOT A TIME VALUE")
.build()));
.build()));
Copy link
Member

@danielmitterdorfer danielmitterdorfer Jan 31, 2019

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

That looks unrelated to this change? Can you please restore the old formatting?

server/src/test/java/org/elasticsearch/index/IndexingSlowLogTests.java Outdated
settings.updateIndexMetaData(newIndexMeta("index",
Settings.builder().put(IndexingSlowLog.INDEX_INDEXING_SLOWLOG_THRESHOLD_INDEX_INFO_SETTING.getKey(), "NOT A TIME VALUE")
.build()));
.build()));
Copy link
Member

@danielmitterdorfer danielmitterdorfer Jan 31, 2019

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

That looks unrelated to this change? Can you please restore the old formatting?

server/src/test/java/org/elasticsearch/index/IndexingSlowLogTests.java Outdated
settings.updateIndexMetaData(newIndexMeta("index",
Settings.builder().put(IndexingSlowLog.INDEX_INDEXING_SLOWLOG_THRESHOLD_INDEX_DEBUG_SETTING.getKey(), "NOT A TIME VALUE")
.build()));
.build()));
Copy link
Member

@danielmitterdorfer danielmitterdorfer Jan 31, 2019

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

That looks unrelated to this change? Can you please restore the old formatting?

server/src/test/java/org/elasticsearch/index/IndexingSlowLogTests.java Outdated
metaData = newIndexMeta("index", Settings.builder()
.put(IndexMetaData.SETTING_VERSION_CREATED, Version.CURRENT)
.build());
.put(IndexMetaData.SETTING_VERSION_CREATED, Version.CURRENT)
Copy link
Member

@danielmitterdorfer danielmitterdorfer Jan 31, 2019

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

That looks unrelated to this change? Can you please restore the old formatting?

server/src/test/java/org/elasticsearch/index/IndexingSlowLogTests.java Outdated
.put(IndexMetaData.SETTING_VERSION_CREATED, Version.CURRENT)
.put(IndexingSlowLog.INDEX_INDEXING_SLOWLOG_REFORMAT_SETTING.getKey(), false)
.build());
.put(IndexMetaData.SETTING_VERSION_CREATED, Version.CURRENT)
Copy link
Member

@danielmitterdorfer danielmitterdorfer Jan 31, 2019

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

That looks unrelated to this change? Can you please restore the old formatting?

server/src/test/java/org/elasticsearch/index/IndexingSlowLogTests.java Outdated
assertThat(e.getCause(), hasToString(containsString("Unrecognized token 'invalid':"
+ " was expecting ('true', 'false' or 'null')\n"
+ " at [Source: org.elasticsearch.common.bytes.BytesReference$MarkSupportingStreamInputWrapper")));
+ " was expecting ('true', 'false' or 'null')\n"
Copy link
Member

@danielmitterdorfer danielmitterdorfer Jan 31, 2019

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

That looks unrelated to this change? Can you please restore the old formatting?

server/src/test/java/org/elasticsearch/index/IndexingSlowLogTests.java Outdated
ParsedDocument pd = new ParsedDocument(new NumericDocValuesField("version", 1),
SeqNoFieldMapper.SequenceIDFields.emptySeqID(), "id",
"test", null, null, source, XContentType.JSON, null);
"test", null, null, source, XContentType.JSON, null);
Copy link
Member

@danielmitterdorfer danielmitterdorfer Jan 31, 2019

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

That looks unrelated to this change? Can you please restore the old formatting?

server/src/test/java/org/elasticsearch/index/IndexingSlowLogTests.java Outdated
public void testSlowLogParsedDocumentPrinterSourceToLog() throws IOException {
BytesReference source = BytesReference.bytes(JsonXContent.contentBuilder()
.startObject().field("foo", "bar").endObject());
.startObject().field("foo", "bar").endObject());
Copy link
Member

@danielmitterdorfer danielmitterdorfer Jan 31, 2019

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

That looks unrelated to this change? Can you please restore the old formatting?

danielmitterdorfer
danielmitterdorfer approved these changes Feb 1, 2019
View reviewed changes
Copy link
Member

@danielmitterdorfer danielmitterdorfer left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks for iterating. LGTM

@pgomulka pgomulka merged commit 2758578 into elastic:master Feb 1, 2019
pgomulka added a commit to pgomulka/elasticsearch that referenced this pull request Feb 1, 2019
@pgomulka
Trim the JSON source in indexing slow logs (elastic#38081)
07240dc 
The '{' as a first character in log line is causing problems for beats when parsing plaintext logs. This can happen if the submitted document has an additional '\n' at the beginning and we are not reformatting. 
Trimming the source part of a SlogLog solves that and keeps the logs readable.

closes elastic#38080
@pgomulka pgomulka mentioned this pull request Feb 1, 2019
Merged
pgomulka added a commit that referenced this pull request Feb 1, 2019
@pgomulka
Trim the JSON source in indexing slow logs #38156 Backport#38081
b10e95f 
The '{' as a first character in log line is causing problems for beats when parsing plaintext logs. This can happen if the submitted document has an additional '\n' at the beginning and we are not reformatting.
Trimming the source part of a SlogLog solves that and keeps the logs readable.

relates #38080
backport #38081
This was referenced Apr 21, 2023
Closed
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Reviewers

@danielmitterdorfer danielmitterdorfer danielmitterdorfer approved these changes

@alpar-t alpar-t alpar-t approved these changes

Assignees

No one assigned

Labels

:Core/Infra/Logging Log management and logging utilities >enhancement v6.7.0 v7.0.0-beta1

Projects

None yet

Milestone

No milestone

Development

Successfully merging this pull request may close these issues.

Plaintext slow logs with multiline causing problems when parsing

5 participants

@pgomulka @elasticmachine @danielmitterdorfer @alpar-t @colings86