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.

Sign up for GitHub

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

Attempting to fix failures due to LCM/GCM flags #3094

Closed
wants to merge 3 commits into from
Closed

Attempting to fix failures due to LCM/GCM flags #3094

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
0b09262
Attempting to fix failures due to LCM/GCM flags
krmahadevan Mar 17, 2024
e5e22a7
Adding some debug statements
krmahadevan Mar 20, 2024
16a7b32
Bump the wait to 10 seconds
krmahadevan Mar 21, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
2 changes: 1 addition & 1 deletion testng-core/src/main/java/org/testng/internal/Configuration.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -35,7 +35,7 @@ public class Configuration implements IConfiguration {
private final Map<Class<? extends IConfigurationListener>, IConfigurationListener>
m_configurationListeners = Maps.newLinkedHashMap();
private boolean alwaysRunListeners = true;
private IExecutorServiceFactory executorServiceFactory = ThreadPoolExecutor::new;
private volatile IExecutorServiceFactory executorServiceFactory = ThreadPoolExecutor::new;

private IInjectorFactory injectorFactory = new GuiceBackedInjectorFactory();

Expand Down
173 changes: 56 additions & 117 deletions testng-core/src/test/java/test/listeners/ListenersTest.java
View file
Open in desktop

Large diffs are not rendered by default.

4 changes: 1 addition & 3 deletions testng-core/src/test/java/test/listeners/issue2916/AlterSuiteListenerHolder.java
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,6 +1,5 @@
package test.listeners.issue2916;

import java.util.ArrayList;
import java.util.List;
import org.testng.IAlterSuiteListener;
import org.testng.ITestNGListener;
Expand All @@ -10,7 +9,6 @@ public class AlterSuiteListenerHolder {

public static final String[] EXPECTED_LOGS =
new String[] {"MasterOogway.alter", "MasterShifu.alter", "DragonWarrior.alter"};
public static List<String> LOGS = new ArrayList<>();
private static final String PREFIX = AlterSuiteListenerHolder.class.getName() + "$";

public static final List<ITestNGListener> ALL =
Expand All @@ -25,7 +23,7 @@ public class AlterSuiteListenerHolder {
public abstract static class KungFuWarrior implements IAlterSuiteListener {
@Override
public void alter(List<XmlSuite> suites) {
LOGS.add(getClass().getSimpleName() + ".alter");
LogContainer.instance.log(getClass().getSimpleName() + ".alter");
}
}

Expand Down
6 changes: 2 additions & 4 deletions testng-core/src/test/java/test/listeners/issue2916/ClassListenerHolder.java
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,14 +1,12 @@
package test.listeners.issue2916;

import java.util.ArrayList;
import java.util.List;
import org.testng.IClassListener;
import org.testng.ITestClass;
import org.testng.ITestNGListener;

public class ClassListenerHolder {

public static List<String> LOGS = new ArrayList<>();
private static final String PREFIX = ClassListenerHolder.class.getName() + "$";

public static final String[] EXPECTED_LOGS =
Expand Down Expand Up @@ -37,12 +35,12 @@ public abstract static class KungFuWarrior implements IClassListener {

@Override
public void onBeforeClass(ITestClass testClass) {
LOGS.add(getClass().getSimpleName() + ".onBeforeClass");
LogContainer.instance.log(getClass().getSimpleName() + ".onBeforeClass");
}

@Override
public void onAfterClass(ITestClass testClass) {
LOGS.add(getClass().getSimpleName() + ".onAfterClass");
LogContainer.instance.log(getClass().getSimpleName() + ".onAfterClass");
}
}

Expand Down
10 changes: 4 additions & 6 deletions testng-core/src/test/java/test/listeners/issue2916/ConfigurationListenerHolder.java
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,6 +1,5 @@
package test.listeners.issue2916;

import java.util.ArrayList;
import java.util.List;
import org.testng.IConfigurationListener;
import org.testng.ITestNGListener;
Expand All @@ -9,7 +8,6 @@

public class ConfigurationListenerHolder {

public static List<String> LOGS = new ArrayList<>();
private static final String PREFIX = ConfigurationListenerHolder.class.getName() + "$";

public static final String[] EXPECTED_LOGS =
Expand Down Expand Up @@ -58,25 +56,25 @@ public abstract static class KungFuWarrior implements IConfigurationListener {

@Override
public void beforeConfiguration(ITestResult tr, ITestNGMethod tm) {
LOGS.add(
LogContainer.instance.log(
getClass().getSimpleName() + ".beforeConfiguration_" + tr.getMethod().getMethodName());
}

@Override
public void onConfigurationSuccess(ITestResult tr, ITestNGMethod tm) {
LOGS.add(
LogContainer.instance.log(
getClass().getSimpleName() + ".onConfigurationSuccess_" + tr.getMethod().getMethodName());
}

@Override
public void onConfigurationFailure(ITestResult tr, ITestNGMethod tm) {
LOGS.add(
LogContainer.instance.log(
getClass().getSimpleName() + ".onConfigurationFailure_" + tr.getMethod().getMethodName());
}

@Override
public void onConfigurationSkip(ITestResult tr, ITestNGMethod tm) {
LOGS.add(
LogContainer.instance.log(
getClass().getSimpleName() + ".onConfigurationSkip_" + tr.getMethod().getMethodName());
}
}
Expand Down
5 changes: 2 additions & 3 deletions testng-core/src/test/java/test/listeners/issue2916/DataProviderInterceptorHolder.java
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,13 +1,11 @@
package test.listeners.issue2916;

import java.util.ArrayList;
import java.util.Iterator;
import java.util.List;
import org.testng.*;

public class DataProviderInterceptorHolder {

public static List<String> LOGS = new ArrayList<>();
private static final String PREFIX = DataProviderInterceptorHolder.class.getName() + "$";

public static final String[] EXPECTED_LOGS =
Expand Down Expand Up @@ -39,7 +37,8 @@ public Iterator<Object[]> intercept(
IDataProviderMethod dp,
ITestNGMethod method,
ITestContext iTestContext) {
LOGS.add(getClass().getSimpleName() + ".intercept_" + dp.getMethod().getName());
LogContainer.instance.log(
getClass().getSimpleName() + ".intercept_" + dp.getMethod().getName());
return original;
}
}
Expand Down
8 changes: 3 additions & 5 deletions testng-core/src/test/java/test/listeners/issue2916/DataProviderListenerHolder.java
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,6 +1,5 @@
package test.listeners.issue2916;

import java.util.ArrayList;
import java.util.List;
import org.testng.IDataProviderListener;
import org.testng.IDataProviderMethod;
Expand All @@ -10,7 +9,6 @@

public class DataProviderListenerHolder {

public static List<String> LOGS = new ArrayList<>();
private static final String PREFIX = DataProviderListenerHolder.class.getName() + "$";

public static final String[] EXPECTED_LOGS =
Expand Down Expand Up @@ -48,7 +46,7 @@ public abstract static class KungFuWarrior implements IDataProviderListener {
@Override
public void beforeDataProviderExecution(
IDataProviderMethod dataProviderMethod, ITestNGMethod method, ITestContext iTestContext) {
LOGS.add(
LogContainer.instance.log(
getClass().getSimpleName()
+ ".beforeDataProviderExecution_"
+ dataProviderMethod.getMethod().getName());
Expand All @@ -57,15 +55,15 @@ public void beforeDataProviderExecution(
@Override
public void afterDataProviderExecution(
IDataProviderMethod dataProviderMethod, ITestNGMethod method, ITestContext iTestContext) {
LOGS.add(
LogContainer.instance.log(
getClass().getSimpleName()
+ ".afterDataProviderExecution_"
+ dataProviderMethod.getMethod().getName());
}

@Override
public void onDataProviderFailure(ITestNGMethod method, ITestContext ctx, RuntimeException t) {
LOGS.add(
LogContainer.instance.log(
getClass().getSimpleName()
+ ".onDataProviderFailure_"
+ method.getDataProviderMethod().getMethod().getName());
Expand Down
8 changes: 6 additions & 2 deletions testng-core/src/test/java/test/listeners/issue2916/ElaborateSampleTestCase.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -23,8 +23,12 @@ public void flakyTest() {
}
}

@Test(timeOut = 2, priority = 4)
@Test(timeOut = 25, priority = 4)
public void timingOutTest() throws InterruptedException {
TimeUnit.MILLISECONDS.sleep(10);
TimeUnit.SECONDS.sleep(10);
new Throwable().printStackTrace();
if (counter != 3) {
Assert.fail();
}
}
}
6 changes: 2 additions & 4 deletions testng-core/src/test/java/test/listeners/issue2916/ExecutionListenerHolder.java
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,6 +1,5 @@
package test.listeners.issue2916;

import java.util.ArrayList;
import java.util.List;
import org.testng.IExecutionListener;
import org.testng.ITestNGListener;
Expand All @@ -16,7 +15,6 @@ public class ExecutionListenerHolder {
"MasterShifu.onExecutionFinish",
"MasterOogway.onExecutionFinish"
};
public static List<String> LOGS = new ArrayList<>();
private static final String PREFIX = ExecutionListenerHolder.class.getName() + "$";

public static final List<ITestNGListener> ALL =
Expand All @@ -35,12 +33,12 @@ public class ExecutionListenerHolder {
public abstract static class KungFuWarrior implements IExecutionListener {
@Override
public void onExecutionStart() {
LOGS.add(getClass().getSimpleName() + ".onExecutionStart");
LogContainer.instance.log(getClass().getSimpleName() + ".onExecutionStart");
}

@Override
public void onExecutionFinish() {
LOGS.add(getClass().getSimpleName() + ".onExecutionFinish");
LogContainer.instance.log(getClass().getSimpleName() + ".onExecutionFinish");
}
}

Expand Down
4 changes: 1 addition & 3 deletions testng-core/src/test/java/test/listeners/issue2916/ExecutionVisualiserHolder.java
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,12 +1,10 @@
package test.listeners.issue2916;

import java.util.ArrayList;
import java.util.List;
import org.testng.*;

public class ExecutionVisualiserHolder {

public static List<String> LOGS = new ArrayList<>();
private static final String PREFIX = ExecutionVisualiserHolder.class.getName() + "$";

public static final String[] EXPECTED_LOGS =
Expand Down Expand Up @@ -34,7 +32,7 @@ public abstract static class KungFuWarrior implements IExecutionVisualiser {

@Override
public void consumeDotDefinition(String dotDefinition) {
LOGS.add(getClass().getSimpleName() + ".consumeDotDefinition");
LogContainer.instance.log(getClass().getSimpleName() + ".consumeDotDefinition");
}
}

Expand Down
6 changes: 2 additions & 4 deletions testng-core/src/test/java/test/listeners/issue2916/InvokedMethodListenerHolder.java
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,6 +1,5 @@
package test.listeners.issue2916;

import java.util.ArrayList;
import java.util.List;
import org.testng.IInvokedMethod;
import org.testng.IInvokedMethodListener;
Expand All @@ -9,7 +8,6 @@

public class InvokedMethodListenerHolder {

public static List<String> LOGS = new ArrayList<>();
private static final String PREFIX = InvokedMethodListenerHolder.class.getName() + "$";

public static final String[] EXPECTED_LOGS =
Expand Down Expand Up @@ -107,15 +105,15 @@ public abstract static class KungFuWarrior implements IInvokedMethodListener {
@Override
public void beforeInvocation(IInvokedMethod method, ITestResult testResult) {
IInvokedMethodListener.super.beforeInvocation(method, testResult);
LOGS.add(
LogContainer.instance.log(
getClass().getSimpleName()
+ ".beforeInvocation_"
+ method.getTestMethod().getMethodName());
}

@Override
public void afterInvocation(IInvokedMethod method, ITestResult testResult) {
LOGS.add(
LogContainer.instance.log(
getClass().getSimpleName()
+ ".afterInvocation_"
+ method.getTestMethod().getMethodName());
Expand Down
34 changes: 34 additions & 0 deletions testng-core/src/test/java/test/listeners/issue2916/LogContainer.java
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -0,0 +1,34 @@
package test.listeners.issue2916;

import java.util.ArrayList;
import java.util.Collections;
import java.util.List;
import java.util.Objects;
import org.testng.internal.AutoCloseableLock;

public enum LogContainer {
instance;
Copy link
Contributor

Choose a reason for hiding this comment

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

single instance per JVM would still have issues with concurrent test execution. For instance, if multiple tests execute at the same time, they would log into the same LogContainer thus they would corrupt each others' logs

Copy link
Member Author

Choose a reason for hiding this comment

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

True that. Some additional context:

  • The tests are not running in parallel.
  • The tests in question basically work in 2 modes [ API mode wherein we feed in the listener instance and CLI mode wherein the listener instances are created by TestNG using reflection ]
  • When working with CLI mode, I am not sure as to how to access the listener instance that TestNG created so that I can access the logs captured by the test.
  • I seem to be seeing a pattern in the failure. The failure is always confined to the tests with timeouts. When we run the test with the StressLCM/StressGCM flags, the tests don't seem to be timing out, but instead they are running to completion as seen by the below output

but some elements were not found: |  
-- | --
  | ["DragonWarrior.onTestFailedWithTimeout", |  
  | "MasterShifu.onTestFailedWithTimeout", |  
  | "MasterOogway.onTestFailedWithTimeout"] |  
  | and others were not expected: |  
  | ["DragonWarrior.onTestSuccess", |  
  | "MasterShifu.onTestSuccess", |  
  | "MasterOogway.onTestSuccess"]

This makes me think that there's something wrong with the codebase when it comes to running timing out tests, but am not able to figure out what, since I dont know what to look for. I am looking for static states (non existent). The shared states are being tracked via threadsafe variants (Atomic*).

Any other pointers you can suggest ?

Copy link
Member Author

Choose a reason for hiding this comment

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

This output confirms my hunch. When running with the stress flags, a test that is supposed to be timing out, does not time out. Not sure what will cause that because the code paths that are related to timeouts dont have any global variables etc.,

Copy link
Member Author

Choose a reason for hiding this comment

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

@juherr @vlsi - I have hit a dead end with this. I need some help so that I can proceed further.

Copy link
Contributor

Choose a reason for hiding this comment

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

When running with the stress flags, a test that is supposed to be timing out, does not time out

What is the test that should time out and fails to do so?
Have you investigated if the timeout logic is implemented properly? It might be there is a concurrency issue within the timeout implementation.

Copy link
Member Author

Choose a reason for hiding this comment

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

@vlsi - Its a very simple test that uses the timeout feature that TestNG provides.

This is what the test looks like

  @Test(timeOut = 25, priority = 4)
  public void timingOutTest() throws InterruptedException {
    TimeUnit.MILLISECONDS.sleep(100);
    new Throwable().printStackTrace();
    if (counter != 3) {
      Assert.fail();
    }
  }

The test passed consistently when I don't use those flags. That is what makes me believe that when those flags are enabled, TestNG's approach of basically running these tests has a problem. But no matter how many times I have skimmed through them, I still am not able to identify them :(

This is where TestNG is basically running those tests driven/controlled by timeouts.

Copy link
Contributor

Choose a reason for hiding this comment

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

Well, having timeout of 25ms vs sleep of 100ms might be too optimistic. In other words, "sleep 100ms" within the test might be too small amount of time to "guarantee" the interrupt logic would have enough time to execute.

Could you try increasing sleep to 10sec?

Copy link
Member Author

Choose a reason for hiding this comment

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

@vlsi - Lol.. I should have started off with this as the question. It could have atleast saved me a day's time. Bumping up the sleep time worked. I am now going to create a new PR from master again, with just the timeout bumped to see if the fix is consistent. If it is, then I think I will perhaps want to stick with just that change instead of this elaborate change which still doesn't guarantee thread safety when the tests are run in parallel (which you also rightly called out).

Because there's reflection and since there's no straightforward way of retrieving all the logs from the listeners (especially when the test invokes TestNG via the CLI), I will want the changeset to be as little as possible.

Copy link
Member Author

Choose a reason for hiding this comment

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

Thank you so much @vlsi for spending time and helping me out.


private List<String> logs;

private final AutoCloseableLock lock = new AutoCloseableLock();

public void initialiseLogs() {
try (AutoCloseableLock ignore = lock.lock()) {
logs = new ArrayList<>();
}
}

public void log(String line) {
try (AutoCloseableLock ignore = lock.lock()) {
Objects.requireNonNull(logs).add(line);
}
}

public List<String> allLogs() {
if (logs == null || logs.isEmpty()) {
throw new IllegalStateException("Logs should have been initialised");
}
return Collections.synchronizedList(logs);
}
}
4 changes: 1 addition & 3 deletions testng-core/src/test/java/test/listeners/issue2916/MethodInterceptorHolder.java
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,6 +1,5 @@
package test.listeners.issue2916;

import java.util.ArrayList;
import java.util.List;
import org.testng.IMethodInstance;
import org.testng.IMethodInterceptor;
Expand All @@ -9,7 +8,6 @@

public class MethodInterceptorHolder {

public static List<String> LOGS = new ArrayList<>();
private static final String PREFIX = MethodInterceptorHolder.class.getName() + "$";

public static final String[] EXPECTED_LOGS =
Expand All @@ -32,7 +30,7 @@ public abstract static class KungFuWarrior implements IMethodInterceptor {

@Override
public List<IMethodInstance> intercept(List<IMethodInstance> methods, ITestContext context) {
LOGS.add(getClass().getSimpleName() + ".intercept");
LogContainer.instance.log(getClass().getSimpleName() + ".intercept");
return methods;
}
}
Expand Down
6 changes: 2 additions & 4 deletions testng-core/src/test/java/test/listeners/issue2916/SuiteListenerHolder.java
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,6 +1,5 @@
package test.listeners.issue2916;

import java.util.ArrayList;
import java.util.List;
import org.testng.ISuite;
import org.testng.ISuiteListener;
Expand All @@ -17,7 +16,6 @@ public class SuiteListenerHolder {
"MasterShifu.onFinish",
"MasterOogway.onFinish"
};
public static List<String> LOGS = new ArrayList<>();
private static final String PREFIX = SuiteListenerHolder.class.getName() + "$";

public static final List<ITestNGListener> ALL =
Expand All @@ -36,12 +34,12 @@ public abstract static class KungFuWarrior implements ISuiteListener {

@Override
public void onStart(ISuite suite) {
LOGS.add(getClass().getSimpleName() + ".onStart");
LogContainer.instance.log(getClass().getSimpleName() + ".onStart");
}

@Override
public void onFinish(ISuite suite) {
LOGS.add(getClass().getSimpleName() + ".onFinish");
LogContainer.instance.log(getClass().getSimpleName() + ".onFinish");
}
}

Expand Down
Loading
Loading