Use '--cursor-after' flag to get recent journal messages #51366
Merged
Conversation
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
When we get Elasticsearch logs from journald, we want to fetch only log messages from the last run. There are two reasons for this. First, if there are many logs, we might get a string that's too large for our utility methods. Second, when we're looking for a specific message or error, we almost certainly want to look only at messages from the last execution. Previously, we've been trying to do this by clearing out the physical files under the journald process. But there seems to be some contention over these directories: if journald writes a log file in between when our deletion command deletes the file and when it deletes the log directory, the deletion will fail. It seems to me that we might be able to use journald's "--since" flag to retrieve only log messages from the last run, and that this might be less likely to fail due to race conditions in file deletion. Unfortunately, it looks as if the "--since" flag has a granularity of one-second. I've added a two-second sleep to make sure that there's a sufficient gap between the test that will read from journald and the test before it.
williamrandolph
added
>non-issue
>test
|
Pinging @elastic/es-core-infra (:Core/Infra/Packaging) |
rjernst
reviewed
Jan 23, 2020
| @@ -342,10 +341,9 @@ public void test90DoNotCloseStderrWhenQuiet() throws Exception { | |||
| append(tempConf.resolve("elasticsearch.yml"), "discovery.zen.ping.unicast.hosts:15172.30.5.3416172.30.5.35, 172.30.5.17]\n"); | |||
|
|
|||
| // Make sure we don't pick up the journal entries for previous ES instances. | |||
| clearJournal(sh); | |||
| String elasticsearchStartTime = sh.run("sleep 2 && date +\"%Y-%m-%d %H:%M:%S\"").stdout.trim(); | |||
There was a problem hiding this comment.
Could we just adjust the since time by 2 seconds instead of sleeping?
There was a problem hiding this comment.
I don't think that would guarantee a gap between Elasticsearch journal messages that's wider than the one-second granularity that the --since flag gives us.
If we have test A and test B and both check for the same error message, but test B is broken, we want to make sure that test A and test B's journal messages don't occur in the same second. I'm not sure how to guarantee that except by introducing a pause.
Another approach might be finding a way to tail journal messages to a test-specific file.
There was a problem hiding this comment.
Some versions of journalctl provide for navigating output with a cursor; I'm going to see if that looks like something we'll have on all platforms.
There was a problem hiding this comment.
I think I have a solution that avoids invoking sleep.
pugnascotia
approved these changes
Jan 24, 2020
williamrandolph
commented
Jan 24, 2020
| * when instantiated, and advancing that cursor when the {@code clear()} | ||
| * method is called. | ||
| */ | ||
| public static class JournaldWrapper { |
There was a problem hiding this comment.
Note: even though this is only invoked in one test on the master branch, I'm going to need it for keystore tests on the feature branch, and it seems like something that could be generally useful later on.
williamrandolph
changed the title
williamrandolph
added a commit
to williamrandolph/elasticsearch
that referenced
this pull request
Jan 24, 2020
When we get Elasticsearch logs from journald, we want to fetch only log messages from the last run. There are two reasons for this. First, if there are many logs, we might get a string that's too large for our utility methods. Second, when we're looking for a specific message or error, we almost certainly want to look only at messages from the last execution. Previously, we've been trying to do this by clearing out the physical files under the journald process. But there seems to be some contention over these directories: if journald writes a log file in between when our deletion command deletes the file and when it deletes the log directory, the deletion will fail. Instead, we can use the cursor capablity of journald to retrieve journal entries that occur only after a certain cursor. This avoids any effort to interfere with the underlying file operations of journald.
williamrandolph
added a commit
to williamrandolph/elasticsearch
that referenced
this pull request
Jan 24, 2020
When we get Elasticsearch logs from journald, we want to fetch only log messages from the last run. There are two reasons for this. First, if there are many logs, we might get a string that's too large for our utility methods. Second, when we're looking for a specific message or error, we almost certainly want to look only at messages from the last execution. Previously, we've been trying to do this by clearing out the physical files under the journald process. But there seems to be some contention over these directories: if journald writes a log file in between when our deletion command deletes the file and when it deletes the log directory, the deletion will fail. Instead, we can use the cursor capablity of journald to retrieve journal entries that occur only after a certain cursor. This avoids any effort to interfere with the underlying file operations of journald.
williamrandolph
added a commit
that referenced
this pull request
Jan 24, 2020
…1445) When we get Elasticsearch logs from journald, we want to fetch only log messages from the last run. There are two reasons for this. First, if there are many logs, we might get a string that's too large for our utility methods. Second, when we're looking for a specific message or error, we almost certainly want to look only at messages from the last execution. Previously, we've been trying to do this by clearing out the physical files under the journald process. But there seems to be some contention over these directories: if journald writes a log file in between when our deletion command deletes the file and when it deletes the log directory, the deletion will fail. Instead, we can use the cursor capablity of journald to retrieve journal entries that occur only after a certain cursor. This avoids any effort to interfere with the underlying file operations of journald.
williamrandolph
added a commit
that referenced
this pull request
Jan 24, 2020
…1447) When we get Elasticsearch logs from journald, we want to fetch only log messages from the last run. There are two reasons for this. First, if there are many logs, we might get a string that's too large for our utility methods. Second, when we're looking for a specific message or error, we almost certainly want to look only at messages from the last execution. Previously, we've been trying to do this by clearing out the physical files under the journald process. But there seems to be some contention over these directories: if journald writes a log file in between when our deletion command deletes the file and when it deletes the log directory, the deletion will fail. Instead, we can use the cursor capablity of journald to retrieve journal entries that occur only after a certain cursor. This avoids any effort to interfere with the underlying file operations of journald.
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
When we get Elasticsearch logs from journald, we want to fetch only log
messages from the last run. There are two reasons for this. First, if
there are many logs, we might get a string that's too large for our
utility methods. Second, when we're looking for a specific message or
error, we almost certainly want to look only at messages from the last
execution.
Previously, we've been trying to do this by clearing out the physical
files under the journald process. But there seems to be some contention
over these directories: if journald writes a log file in between when
our deletion command deletes the file and when it deletes the log
directory, the deletion will fail.
It seems to me that we might be able to use journald's "--since" flag to
retrieve only log messages from the last run, and that this might be
less likely to fail due to race conditions in file deletion.
Unfortunately, it looks as if the "--since" flag has a granularity of
one-second. I've added a two-second sleep to make sure that there's a
sufficient gap between the test that will read from journald and the
test before it.
Specifically, I hope this will fix issues with
test90DoNotCloseStderrWhenQuietinPackageTests. The two error messages related to this issue are:and
See a build-stats report here, if you have access.