do not close file writer upon every log invocation #382

alxflam-work · 2023-10-19T12:20:25Z

Hi,

this PR resolves issue #221:

The writer is no longer closed in a finally block upon every log invocation
Instead, the writer is closed inside log only if an Exception is thrown, then the writer is closed immediately. Additionally, closeFile is called also after the writer changed to write to std.err in the catch block (else that writer instance would not be closed)
Unchanged behavior: The writer is still closed, aka closeFile is called, when the actual log file changes (e.g. explicitly or due to log file rotation caused by size limit)
I have added a new test EquinoxLogWriterTest to verify that logs are flushed immediately but the writer is not closed. I tried my best with the Junit4 environment and missing mockito, please let me know if i can improve the testcase. For now, my only solution was using reflection to actually verify the invocations on the writer.
All OSGi Tests launch config runs locally without errors (with these changes)

Greetings,
Alex

bundles/org.eclipse.osgi/container/src/org/eclipse/osgi/internal/log/EquinoxLogWriter.java

github-actions · 2023-10-20T14:28:50Z

Test Results

    24 files ±0     24 suites ±0 11m 17s ⏱️ + 2m 38s
2 151 tests +1 2 106 ✔️ +114 45 💤 ±0 0 ❌ - 1
2 195 runs +1 2 150 ✔️ +114 45 💤 ±0 0 ❌ - 1

Results for commit e63fa9c. ± Comparison against base commit 7208dfa.

♻️ This comment has been updated with latest results.

tjwatson

One more thing. Unfortunately this is the first change for the 2023-12 release in org.eclipse.osgi so we need a version bump to Bundle-Version: 3.18.600.qualifier in the META-INF/MANIFEST.MF and to <version>3.18.600-SNAPSHOT</version> for the pom.xml

Also need to update the versions in org.eclipse.osgi.test project.

alxflam-work · 2023-10-24T06:13:54Z

Thanks for the hints, updated the versions, rebased and squashed commits.

Closes eclipse-equinox#221. The eager behavior can be enabled by setting configuration eclipse.log.closeFile.eagerClose to true (defaults to false).

tjwatson · 2023-10-24T13:56:38Z

Thanks for the PR. It is merged now.

iloveeclipse · 2023-10-25T04:31:51Z

Please take a look on new 5 fails in runtime tests

https://download.eclipse.org/eclipse/downloads/drops4/I20231024-1800/testresults/html/org.eclipse.core.tests.runtime_ep430I-unit-cen64-gtk3-java17_linux.gtk.x86_64_17.html

and 7 fails in p2 tests

https://download.eclipse.org/eclipse/downloads/drops4/I20231024-1800/testresults/html/org.eclipse.equinox.p2.tests_ep430I-unit-cen64-gtk3-java17_linux.gtk.x86_64_17.html

I believe they are all caused by this PR.

alxflam-work · 2023-10-25T06:24:34Z

@iloveeclipse @tjwatson the reason these tests are failing is probably cause they all try to delete the frameworks log file which is now locked as there is still an open writer by the EquinoxLogWriter. Actually, that could have already been previously cause for toggling behavior (Test tries to delete the file, another thread is concurrently invoking log, therefore creating the writer and thereby preventing the deletion - requires bad luck with the timing, but it should have been possible even without this change, now it became a stable behavior).
I would suggest to go ahead like this:

All tests requiring to work with a "clean" log file for easier log file content verification should simply call FrameworkLog#setFile and set some temporary file. Then the test can verify the contents of this explicit test log file. In the test cleanup, the original log file can be reset on the framework log.

Another option is to simply overwrite the log file contents with an empty String (which is pretty similar to deleting the file which is the current attempt in the tests), which works but does not seem as good to me (what if you want the framework log for analysis later on for a failed test but then the content is gone). What do you think?

iloveeclipse · 2023-10-25T09:04:44Z

I honestly have no time to look into this, but it would be nice to fix the test fails soon in some way, as they prevent people to get green platform builds on PR's.

laeubi · 2023-10-25T09:07:22Z

All tests requiring to work with a "clean" log file for easier log file content verification should simply call FrameworkLog#setFile and set some temporary file.

This sounds reasonable, @alxflam-work can you provide a PR for the failing tests to do so?

alxflam-work · 2023-10-25T09:50:00Z

This sounds reasonable, @alxflam-work can you provide a PR for the failing tests to do so?

@laeubi i'd really like to do so, but the situation for me is the following: I only have approval from our internal OSS boards to contribute to the equinox repository. As the failing tests reside in the p2 and eclipse.platform repositories, i'll have to go through some corporate OSS process to get these repositories approved for contributions. Sadly, this can take quite some time. So in the end if i fix the failing tests this will simply take potentially many weeks due to our internal OSS process, which i guess is not acceptable. Therefore, either someone of the eclipse members provides the fix or we revert this PR and we can rework it once i have approval for p2 and eclipse.platform repository contributions? Sorry for the inconveniences caused!

What works locally for the P2 repository failing tests ArtifactMirrorApplicationTest & NewMirrorApplicationArtifactTest is this:

remove the delete invocations for the log file
in setUp add the following code:
FrameworkLog log = ServiceHelper.getService(Activator.getContext(), FrameworkLog.class); originalFrameworkLog = log.getFile(); var tmpLogFile = File.createTempFile(this.getClass().getSimpleName(), null); tmpLogFile.deleteOnExit(); log.setFile(tmpLogFile, false);
in tearDown add the following code:
FrameworkLog log = ServiceHelper.getService(Activator.getContext(), FrameworkLog.class); log.setFile(originalFrameworkLog, false);

The same should work also for the failing test in platform LogSerializationTest, but maybe there junit4 is used and the TemporaryFolder rule could be applied instead.

jukzi · 2023-10-25T14:06:43Z

@tjwatson if nobody works on fixing the tests please revert, it's very frustrating that whole platform is blocked by the current state.

iloveeclipse · 2023-10-25T15:25:03Z

The same should work also for the failing test in platform LogSerializationTest

It doesn't work. The test deletes the log file / logs in the loop. I believe the change here broke that.
My attempt to follow your proposal is:

diff --git a/runtime/tests/org.eclipse.core.tests.runtime/src/org/eclipse/core/tests/internal/runtime/LogSerializationTest.java b/runtime/tests/org.eclipse.core.tests.runtime/src/org/eclipse/core/tests/internal/runtime/LogSerializationTest.java
index 8a9991e..8690403 100644
--- a/runtime/tests/org.eclipse.core.tests.runtime/src/org/eclipse/core/tests/internal/runtime/LogSerializationTest.java
+++ b/runtime/tests/org.eclipse.core.tests.runtime/src/org/eclipse/core/tests/internal/runtime/LogSerializationTest.java
@@ -15,7 +15,16 @@
 
-import java.io.*;
+import java.io.File;
+import java.io.PrintWriter;
+import java.io.StringWriter;
+import java.nio.file.Files;
 import java.util.Arrays;
 import org.eclipse.core.internal.runtime.RuntimeLog;
-import org.eclipse.core.runtime.*;
+import org.eclipse.core.runtime.IStatus;
+import org.eclipse.core.runtime.MultiStatus;
+import org.eclipse.core.runtime.Status;
 import org.eclipse.core.tests.runtime.RuntimeTest;
+import org.eclipse.core.tests.runtime.RuntimeTestsPlugin;
+import org.eclipse.osgi.framework.log.FrameworkLog;
+import org.osgi.framework.BundleContext;
+import org.osgi.framework.ServiceReference;
 
@@ -32,3 +41,4 @@
 
-	protected File logFile = null;
+	protected File logFile;
+	private File originalFrameworkLog;
 
@@ -152,3 +162,3 @@
 
-	protected void doTest(String msg, IStatus[] oldStats) {
+	protected void doTest(String msg, IStatus[] oldStats) throws Exception {
 		writeLog(oldStats);
@@ -158,3 +168,3 @@
 
-	protected void doTest(String msg, IStatus status) {
+	protected void doTest(String msg, IStatus status) throws Exception {
 		doTest(msg, new IStatus[] {status});
@@ -171,5 +181,7 @@
 		//setup the log file
-		if (logFile == null) {
-			logFile = Platform.getLogFileLocation().toFile();
-		}
+		FrameworkLog log = getService(RuntimeTestsPlugin.getContext(), FrameworkLog.class);
+		originalFrameworkLog = log.getFile();
+		logFile = File.createTempFile(this.getClass().getSimpleName(), null);
+		logFile.deleteOnExit();
+		log.setFile(logFile, false);
 	}
@@ -179,6 +191,21 @@
 		super.tearDown();
-		logFile.delete();
+		FrameworkLog log = getService(RuntimeTestsPlugin.getContext(), FrameworkLog.class);
+		log.setFile(originalFrameworkLog, false);
+		Files.delete(logFile.toPath());
 	}
 
-	public void testDeepMultiStatus() {
+	public static <T> T getService(BundleContext context, Class<T> clazz) {
+		if (context == null) {
+			return null;
+		}
+		ServiceReference<T> reference = context.getServiceReference(clazz);
+		if (reference == null) {
+			return null;
+		}
+		T result = context.getService(reference);
+		context.ungetService(reference);
+		return result;
+	}
+
+	public void testDeepMultiStatus() throws Exception {
 		MultiStatus multi = new MultiStatus("id", 1, getInterestingMultiStatuses(), "ok", null);
@@ -190,3 +217,3 @@
 
-	public void testMultiMultiStatusSerialize() {
+	public void testMultiMultiStatusSerialize() throws Exception {
 		IStatus[] interesting = getInterestingMultiStatuses();
@@ -200,3 +227,3 @@
 
-	public void testMultiSerialize() {
+	public void testMultiSerialize() throws Exception {
 		IStatus[] interesting = getInterestingStatuses();
@@ -210,3 +237,3 @@
 
-	public void testMultiStatus() {
+	public void testMultiStatus() throws Exception {
 		IStatus[] interesting = getInterestingMultiStatuses();
@@ -217,3 +244,3 @@
 
-	public void testSimpleSerialize() {
+	public void testSimpleSerialize() throws Exception {
 		IStatus[] interesting = getInterestingStatuses();
@@ -224,3 +251,3 @@
 
-	protected void writeLog(IStatus status) {
+	protected void writeLog(IStatus status) throws Exception {
 		writeLog(new IStatus[] {status});
@@ -228,5 +255,5 @@
 
-	protected void writeLog(IStatus[] statuses) {
+	protected void writeLog(IStatus[] statuses) throws Exception {
 		if (logFile.exists()) {
-			logFile.delete();
+			Files.delete(logFile.toPath());
 		}

merks · 2023-10-25T15:26:42Z

For what it helps, note that there is also a system property to disable the new behavior and restore the old behavior...

iloveeclipse · 2023-10-25T15:35:55Z

For what it helps, note that there is also a system property to disable the new behavior and restore the old behavior...

The question for me is if that new behavior is working properly.

the reason these tests are failing is probably cause they all try to delete the frameworks log file which is now locked as there is still an open writer by the EquinoxLogWriter

If that is not working now, I would say it is a regression. The test LogSerializationTest deletes log file, logs something and expect that the content they log appears in the same file. This makes sense, since that is what can happen at any time in a regular environment too. If that is not working anymore, and the log file contains something different / not what the application has most recently logged, looks like a regression.

Long story short, I would propose a PR reverting the change, and let @tjwatson & @alxflam-work discuss if the new behavior works as expected, shouldn't be default or just has some implementation bug.

invocation" This reverts commit 53dc6b6 as it caused test failures in - org.eclipse.core.tests.internal.runtime.LogSerializationTest - org.eclipse.equinox.p2.tests.mirror.ArtifactMirrorApplicationTest - org.eclipse.equinox.p2.tests.mirror.NewMirrorApplicationArtifactTest Note: pom and manifest files are left unchanged to avoid going back with bundle versions. Original PR: eclipse-equinox#382 Original ticket: eclipse-equinox#221

iloveeclipse · 2023-10-25T15:43:21Z

Revert PR: #388

invocation" This reverts commit 53dc6b6 as it caused test failures in - org.eclipse.core.tests.internal.runtime.LogSerializationTest - org.eclipse.equinox.p2.tests.mirror.ArtifactMirrorApplicationTest - org.eclipse.equinox.p2.tests.mirror.NewMirrorApplicationArtifactTest Note: pom and manifest files are left unchanged to avoid going back with bundle versions. Original PR: #382 Original ticket: #221

tjwatson · 2023-10-25T17:46:24Z

Revert was the right thing to do, although the details on if the file is closed or not are an implementation detail, not an API for the log file. @alxflam-work you will either need to fix the tests, or more likely flip the default to be the old behavior.

alxflam-work · 2023-10-26T06:15:28Z

@tjwatson then i'll provide a PR with the same changes, but defaulting to the old behavior. Once that is done, i can adapt the tests to no longer delete the log file but instead use a dedicated tmp log file - which should not be a semantic change for the tests. The tests should then still be green and afterwards we could flip the default behavior.

jukzi · 2023-10-26T06:24:04Z

@alxflam-work if you propose a new PR please test the mentioned Tests before. It's not enough to assume they would work.

tjwatson reviewed Oct 19, 2023

View reviewed changes

bundles/org.eclipse.osgi/container/src/org/eclipse/osgi/internal/log/EquinoxLogWriter.java Show resolved Hide resolved

tjwatson approved these changes Oct 23, 2023

View reviewed changes

tjwatson self-requested a review October 23, 2023 15:07

tjwatson reviewed Oct 23, 2023

View reviewed changes

alxflam-work force-pushed the ftrLogPerf branch 2 times, most recently from 52b89eb to 532a026 Compare October 24, 2023 06:11

ftr: prevent eager closing of file writer upon every log invocation

e63fa9c

Closes eclipse-equinox#221. The eager behavior can be enabled by setting configuration eclipse.log.closeFile.eagerClose to true (defaults to false).

alxflam-work force-pushed the ftrLogPerf branch from 532a026 to e63fa9c Compare October 24, 2023 06:24

tjwatson merged commit 53dc6b6 into eclipse-equinox:master Oct 24, 2023
16 of 22 checks passed

iloveeclipse mentioned this pull request Oct 25, 2023

Add original exception to the error log eclipse-platform/eclipse.platform#762

Merged

This was referenced Oct 25, 2023

Show number of differences in the Compare editor #504 eclipse-platform/eclipse.platform#731

Merged

regression LogSerializationTest fails on all builds eclipse-platform/eclipse.platform#768

Closed

iloveeclipse mentioned this pull request Oct 25, 2023

Revert "ftr: prevent eager closing of file writer upon every log invocation" #388

Merged

iloveeclipse mentioned this pull request Oct 25, 2023

Possible performance improvement for high frequency logging using EquinoxLogWriter #221

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

do not close file writer upon every log invocation #382

do not close file writer upon every log invocation #382

alxflam-work commented Oct 19, 2023

github-actions bot commented Oct 20, 2023 •

edited

Loading

tjwatson left a comment •

edited

Loading

alxflam-work commented Oct 24, 2023

tjwatson commented Oct 24, 2023

iloveeclipse commented Oct 25, 2023

alxflam-work commented Oct 25, 2023 •

edited

Loading

iloveeclipse commented Oct 25, 2023

laeubi commented Oct 25, 2023

alxflam-work commented Oct 25, 2023

jukzi commented Oct 25, 2023

iloveeclipse commented Oct 25, 2023

merks commented Oct 25, 2023

iloveeclipse commented Oct 25, 2023

iloveeclipse commented Oct 25, 2023

tjwatson commented Oct 25, 2023

alxflam-work commented Oct 26, 2023

jukzi commented Oct 26, 2023

do not close file writer upon every log invocation #382

do not close file writer upon every log invocation #382

Conversation

alxflam-work commented Oct 19, 2023

github-actions bot commented Oct 20, 2023 • edited Loading

Test Results

tjwatson left a comment • edited Loading

Choose a reason for hiding this comment

alxflam-work commented Oct 24, 2023

tjwatson commented Oct 24, 2023

iloveeclipse commented Oct 25, 2023

alxflam-work commented Oct 25, 2023 • edited Loading

iloveeclipse commented Oct 25, 2023

laeubi commented Oct 25, 2023

alxflam-work commented Oct 25, 2023

jukzi commented Oct 25, 2023

iloveeclipse commented Oct 25, 2023

merks commented Oct 25, 2023

iloveeclipse commented Oct 25, 2023

iloveeclipse commented Oct 25, 2023

tjwatson commented Oct 25, 2023

alxflam-work commented Oct 26, 2023

jukzi commented Oct 26, 2023

github-actions bot commented Oct 20, 2023 •

edited

Loading

tjwatson left a comment •

edited

Loading

alxflam-work commented Oct 25, 2023 •

edited

Loading