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

Slow log must use separate underlying logger for each index #47234

Merged
merged 3 commits into from
Oct 17, 2019

Conversation

alexshadow007
Copy link
Contributor

Closes #42432

@dnhatn dnhatn added the :Core/Infra/Logging Log management and logging utilities label Sep 27, 2019
@elasticmachine
Copy link
Collaborator

Pinging @elastic/es-core-infra

Copy link
Contributor

@pgomulka pgomulka left a comment

Choose a reason for hiding this comment

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

@alexshadow007 thank you for looking into this. I think your fix should work.
However we certainly miss testing around this. Do you think you could add appropriate unit tests to reproduce this?

@alexshadow007
Copy link
Contributor Author

@pgomulka I added test for SearchSlowLog, is it fine?
But i have problem with testing of IndexSlowLog.
To call IndexingSlowLog.postIndex i need Engine.IndexResult with correct took time, but took time has package private visibility - so i can't set it from test. Any advices?

@pgomulka
Copy link
Contributor

@alexshadow007 added test is really good! thank you for this
in regards to IndexSLowLogTests how about we simplify the test case there? It is after all only a change about setting LogLevel. I was thinking of something like this

    public void testLevelSettingMultipleIndices() {
        IndexSettings infoSettings = new IndexSettings(
            newIndexMeta("index-1-info", Settings.builder()
                                                 .put(IndexMetaData.SETTING_INDEX_UUID, UUIDs.randomBase64UUID())
                                                 .put(IndexMetaData.SETTING_VERSION_CREATED, Version.CURRENT)
                                                 .put(SearchSlowLog.INDEX_SEARCH_SLOWLOG_THRESHOLD_FETCH_INFO_SETTING.getKey(), "0")
                                                 .put(IndexingSlowLog.INDEX_INDEXING_SLOWLOG_LEVEL_SETTING.getKey(), SlowLogLevel.INFO)
                                                 .build()), Settings.EMPTY);
        IndexingSlowLog infoLog = new IndexingSlowLog(infoSettings);
        assertEquals(infoLog.getLevel(), SlowLogLevel.INFO);


        IndexSettings debugSettings = new IndexSettings(
            newIndexMeta("index-2-debug", Settings.builder()
                                                  .put(IndexMetaData.SETTING_INDEX_UUID, UUIDs.randomBase64UUID())
                                                  .put(IndexMetaData.SETTING_VERSION_CREATED, Version.CURRENT)
                                                  .put(SearchSlowLog.INDEX_SEARCH_SLOWLOG_THRESHOLD_QUERY_DEBUG_SETTING.getKey(), "0")
                                                  .put(IndexingSlowLog.INDEX_INDEXING_SLOWLOG_LEVEL_SETTING.getKey(), SlowLogLevel.DEBUG)
                                                  .build()), Settings.EMPTY);
        IndexingSlowLog debugLog = new IndexingSlowLog(debugSettings);
        assertEquals(debugLog.getLevel(), SlowLogLevel.DEBUG);

        //assert log level is preserved
        assertEquals(infoLog.getLevel(), SlowLogLevel.INFO);
    }

Or maybe we could try that approach in SearchSlowLogTests. What do you think?

@alexshadow007
Copy link
Contributor Author

alexshadow007 commented Oct 11, 2019

@pgomulka
Test case provided by you doesn't verify this bug. Because problem was in underlying logger - log level of slow log instance was right, but log level of underlying log4 logger was different (because instance of log4j logger was shared between all instances of slow log). I can add test case where i verify log level of underlying logger by it's name.

        String uuid = UUIDs.randomBase64UUID();
        IndexSettings infoSettings = new IndexSettings(
            newIndexMeta("index-1-info", Settings.builder()
                                                 .put(IndexMetaData.SETTING_INDEX_UUID, uuid )
                                                 .put(IndexMetaData.SETTING_VERSION_CREATED, Version.CURRENT)
                                                 .put(SearchSlowLog.INDEX_SEARCH_SLOWLOG_THRESHOLD_FETCH_INFO_SETTING.getKey(), "0")
                                                 .put(IndexingSlowLog.INDEX_INDEXING_SLOWLOG_LEVEL_SETTING.getKey(), SlowLogLevel.INFO)
                                                 .build()), Settings.EMPTY);
        IndexingSlowLog infoLog = new IndexingSlowLog(infoSettings);
        assertEquals(LogManager.getLogger("index.search.slowlog.query." + uuid).getLevel, Level.INFO);

@pgomulka
Copy link
Contributor

@alexshadow007 you are right. I was thinking that getLevel would be changed to something to return the level of the underlying logger

 SlowLogLevel getLevel() {
        return SlowLogLevel.parse(indexLogger.getLevel().name());
    }

I am not sure we really need that level variable inside SlowLoggers

@alexshadow007
Copy link
Contributor Author

@pgomulka Yes, i think it is not bad idea. I will do it and add test case.

@alexshadow007
Copy link
Contributor Author

@pgomulka Done

@pgomulka
Copy link
Contributor

ok to test

@pgomulka
Copy link
Contributor

@elasticmachine run elasticsearch-ci/packaging-sample

@pgomulka
Copy link
Contributor

@elasticmachine run elasticsearch-ci/2

1 similar comment
@pgomulka
Copy link
Contributor

@elasticmachine run elasticsearch-ci/2

@pgomulka
Copy link
Contributor

@alexshadow007 there are some test failures in CI, but they seem unrelated. I will try to confirm with the team the reason it is failing (I can't reproduce it).
But once again I wanted to thank you this PR, the change looks great.

@pgomulka
Copy link
Contributor

@elasticmachine update branch

@pgomulka
Copy link
Contributor

@elasticmachine run elasticsearch-ci/packaging-sample

@pgomulka
Copy link
Contributor

@elasticmachine run elasticsearch-ci/packaging-sample-matrix

@pgomulka pgomulka merged commit e905af1 into elastic:master Oct 17, 2019
pgomulka pushed a commit to pgomulka/elasticsearch that referenced this pull request Oct 17, 2019
…47234)

SlowLog instances should not share the same underlying logger, as it would cause different indexes override each other levels. When creating underlying logger, unique per index identifier should be used. Name + IndexSettings.UUID

Closes elastic#42432
pgomulka pushed a commit to pgomulka/elasticsearch that referenced this pull request Oct 17, 2019
…47234)

SlowLog instances should not share the same underlying logger, as it would cause different indexes override each other levels. When creating underlying logger, unique per index identifier should be used. Name + IndexSettings.UUID

Closes elastic#42432
pgomulka added a commit that referenced this pull request Oct 17, 2019
…KPORT(#47234) (#48176)

* Slow log must use separate underlying logger for each index (#47234)

SlowLog instances should not share the same underlying logger, as it would cause different indexes override each other levels. When creating underlying logger, unique per index identifier should be used. Name + IndexSettings.UUID

Closes #42432
pgomulka added a commit that referenced this pull request Oct 17, 2019
…KPORT(#47234) (#48177)

* Slow log must use separate underlying logger for each index (#47234)

SlowLog instances should not share the same underlying logger, as it would cause different indexes override each other levels. When creating underlying logger, unique per index identifier should be used. Name + IndexSettings.UUID

Closes #42432
@jaymode jaymode added the >bug label Nov 19, 2019
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

Successfully merging this pull request may close these issues.

index slowlog settings override other indices settings
6 participants