System Test sometime freeze on eclipse start with message related to messagingsystem.ui

[dvojtise]

Bug description

when running the system test (using the docker image)

The eclipse start sometimes 🤔 freezes apparently on the org.eclipse.gemoc.commons.eclipse.messagingsystem.ui start job (https://github.com/eclipse/gemoc-studio-commons/blob/28b5ee4a53a0f14ae47020840fe97cf45a2d3ea8/plugins/org.eclipse.gemoc.commons.eclipse.messagingsystem.ui/src/main/java/org/eclipse/gemoc/commons/eclipse/messagingsystem/ui/Activator.java#L57)

When this event occurs, the console shows that the workbench is available, but a message "Waiting workbench to redirect system.out to console" is visible in the UI

How to reproduce

Steps to reproduce the behavior:

from the folder that contains all the git repositories:

mkdir cache-m2
docker run -it --rm --name gemoc-builder -v $PWD:/home/ubuntu/src -v $PWD/cache-m2:/home/ubuntu/.m2 --env UID=$(id -u) --env GID=$(id -g) -p 5901:5901 "gemoc/gemoc-builder:latest" ./generate_protocols.sh |& ts -s |& tee generate_protocols.log
docker run -it --rm --name gemoc-builder -v $PWD:/home/ubuntu/src -v $PWD/cache-m2:/home/ubuntu/.m2 --env UID=$(id -u) --env GID=$(id -g) -p 5901:5901 "gemoc/gemoc-builder:latest" ./tycho_build.sh linux_no_system_test |& ts -s |& tee linux_build.log

then launching the system test + vncviewer

docker run -it --rm --name gemoc-builder -v $PWD:/home/ubuntu/src -v $PWD/cache-m2:/home/ubuntu/.m2 --env UID=$(id -u) --env GID=$(id -g) -p 5901:5901 "gemoc/gemoc-builder:latest" ./tycho_build.sh linux_system_test_only |& ts -s |& tee linux_system_test_only.log

vncviewer localhost:5901

sometimes, the GUI is frozen as shown in the screenshot

Screenshot

copy of the end of console log:

00:00:22 [INFO] --- tycho-surefire:3.0.4:test (default-test) @ org.eclipse.gemoc.studio.tests.system.lwb ---
00:00:22 [INFO] Publishing 2 bundles to /home/ubuntu/src/gemoc-studio/gemoc_studio/tests/org.eclipse.gemoc.studio.tests.system.lwb/target/p2temp/additionalBundles
00:00:22 Generating metadata for ..
00:00:23 Generation completed with success [0 seconds].
00:00:23 [INFO] Installing IUs [org.eclipse.gemoc.studio.tests.system.lwb, org.eclipse.tycho.surefire.osgibooter, org.eclipse.tycho.surefire.junit4, org.eclipse.gemoc.studio.tests.logging.config, gemoc_studio] to /home/ubuntu/src/gemoc-studio/gemoc_studio/tests/org.eclipse.gemoc.studio.tests.system.lwb/target/work
00:00:23 Installing org.eclipse.gemoc.studio.tests.system.lwb 3.6.1.202409050929.
00:00:23 Installing org.eclipse.tycho.surefire.osgibooter 3.0.4.
00:00:23 Installing org.eclipse.tycho.surefire.junit4 3.0.4.
00:00:23 Installing org.eclipse.gemoc.studio.tests.logging.config 3.6.1.202409041345.
00:00:23 Installing gemoc_studio 3.6.1.202409041345.
00:00:36 [WARNING] [1cf772b3-3cad-40f1-affd-cf02011d8a44][extension>org.eclipse.tycho:tycho-maven-plugin:3.0.4] Failed creating shared configuration url for null.
00:00:37 Operation completed in 14091 ms.
00:00:37 [INFO] Could not find a java toolchain of type jdk and JAVA_HOME is not set, trying java from PATH instead
00:00:37 [INFO] Executing Test Runtime with timeout 0, logs (if any) will be placed at: /home/ubuntu/src/gemoc-studio/gemoc_studio/tests/org.eclipse.gemoc.studio.tests.system.lwb/target/work/data/.metadata/.log
00:00:37 [INFO] Command line:
00:00:37        [java, -Dosgi.noShutdown=false, -Dosgi.os=linux, -Dosgi.ws=gtk, -Dosgi.arch=x86_64, -Xmx1500m, -Dosgi.clean=true, -DWORKSPACE=/home/ubuntu/src/gemoc-studio/gemoc_studio/tests/org.eclipse.gemoc.studio.tests.system.lwb/../../../.., -jar, /home/ubuntu/src/gemoc-studio/gemoc_studio/tests/org.eclipse.gemoc.studio.tests.system.lwb/target/work/plugins/org.eclipse.equinox.launcher_1.6.400.v20210924-0641.jar, -data, /home/ubuntu/src/gemoc-studio/gemoc_studio/tests/org.eclipse.gemoc.studio.tests.system.lwb/target/work/data, -install, /home/ubuntu/src/gemoc-studio/gemoc_studio/tests/org.eclipse.gemoc.studio.tests.system.lwb/target/work, -configuration, /home/ubuntu/src/gemoc-studio/gemoc_studio/tests/org.eclipse.gemoc.studio.tests.system.lwb/target/work/configuration, -application, org.eclipse.tycho.surefire.osgibooter.uitest, -testproperties, /home/ubuntu/src/gemoc-studio/gemoc_studio/tests/org.eclipse.gemoc.studio.tests.system.lwb/target/surefire.properties, -testApplication, org.eclipse.ui.ide.workbench, -product, org.eclipse.gemoc.gemoc_studio.branding.gemoc_studio, -nouithread]
00:01:31 SLF4J: No SLF4J providers were found.
00:01:31 SLF4J: Defaulting to no-operation (NOP) logger implementation
00:01:31 SLF4J: See https://www.slf4j.org/codes.html#noProviders for further details.
00:01:32 Launching application org.eclipse.ui.ide.workbench...
00:01:33 
00:01:33 (java:337): dbind-WARNING **: 09:30:39.050: AT-SPI: Error retrieving accessibility bus address: org.freedesktop.DBus.Error.ServiceUnknown: The name org.a11y.Bus was not provided by any .service files
00:01:37 Running org.eclipse.gemoc.studio.tests.system.lwb.userstory.DeployOfficialExampleMelangeK3FSM_Test
00:01:37 ignoring addTestSuiteVideoLog
00:01:37 /home/ubuntu/src/gemoc-studio/gemoc_studio/tests/org.eclipse.gemoc.studio.tests.system.lwb/../../../../gemoc-studio/dev_support/tycho_full_compilation/target/system_test_timeline.log not found
00:01:43 [WorkspaceTestHelper] Workbench is available
00:01:43 Workbench is available

copy of the log in .metadata (obtained via access using docker exec -it gemoc-builder /bin/bash)

root@2789334470c2:~/src/gemoc-studio/gemoc_studio/tests/org.eclipse.gemoc.studio.tests.system.lwb/target/work/data/.metadata# cat .log
!SESSION 2024-09-05 09:57:30.137 -----------------------------------------------
eclipse.buildId=unknown
java.version=17.0.12
java.vendor=Ubuntu
BootLoader constants: OS=linux, ARCH=x86_64, WS=gtk, NL=en_US
Framework arguments:  -application org.eclipse.tycho.surefire.osgibooter.uitest -testproperties /home/ubuntu/src/gemoc-studio/gemoc_studio/tests/org.eclipse.gemoc.studio.tests.system.lwb/target/surefire.properties -testApplication org.eclipse.ui.ide.workbench -product org.eclipse.gemoc.gemoc_studio.branding.gemoc_studio -nouithread
Command-line arguments:  -data /home/ubuntu/src/gemoc-studio/gemoc_studio/tests/org.eclipse.gemoc.studio.tests.system.lwb/target/work/data -application org.eclipse.tycho.surefire.osgibooter.uitest -testproperties /home/ubuntu/src/gemoc-studio/gemoc_studio/tests/org.eclipse.gemoc.studio.tests.system.lwb/target/surefire.properties -testApplication org.eclipse.ui.ide.workbench -product org.eclipse.gemoc.gemoc_studio.branding.gemoc_studio -nouithread

!ENTRY org.apache.felix.scr 4 0 2024-09-05 09:57:30.402
!MESSAGE FrameworkEvent ERROR
!STACK 0
org.osgi.framework.BundleException: Could not resolve module: org.apache.felix.scr [4]
  Unresolved requirement: Import-Package: org.osgi.service.cm; version="[1.6.0,2.0.0)"; resolution:="optional"
  Unresolved requirement: Import-Package: org.osgi.service.metatype; version="[1.2.0,2.0.0)"; resolution:="optional"
  Unresolved requirement: Import-Package: org.apache.felix.service.command; version="[1.0.0,2.0.0)"; resolution:="optional"
  Unresolved requirement: Import-Package: org.osgi.service.component; version="[1.5.0,1.6.0)"

        at org.eclipse.osgi.container.Module.start(Module.java:463)
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel$2.run(ModuleContainer.java:1852)
        at org.eclipse.osgi.internal.framework.EquinoxContainerAdaptor$1$1.execute(EquinoxContainerAdaptor.java:136)
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1845)
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1788)
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.doContainerStartLevel(ModuleContainer.java:1750)
        at org.eclipse.osgi.container.SystemModule.startWorker(SystemModule.java:269)
        at org.eclipse.osgi.container.Module.doStart(Module.java:605)
        at org.eclipse.osgi.container.Module.start(Module.java:468)
        at org.eclipse.osgi.container.SystemModule.start(SystemModule.java:193)
        at org.eclipse.osgi.internal.framework.EquinoxBundle.start(EquinoxBundle.java:445)
        at org.eclipse.osgi.internal.framework.EquinoxBundle.start(EquinoxBundle.java:464)
        at org.eclipse.osgi.launch.Equinox.start(Equinox.java:139)
        at org.eclipse.core.runtime.adaptor.EclipseStarter.startup(EclipseStarter.java:338)
        at org.eclipse.core.runtime.adaptor.EclipseStarter.run(EclipseStarter.java:251)
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
        at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.base/java.lang.reflect.Method.invoke(Method.java:569)
        at org.eclipse.equinox.launcher.Main.invokeFramework(Main.java:659)
        at org.eclipse.equinox.launcher.Main.basicRun(Main.java:596)
        at org.eclipse.equinox.launcher.Main.run(Main.java:1467)
        at org.eclipse.equinox.launcher.Main.main(Main.java:1440)

!ENTRY org.eclipse.emf.ecore 2 0 2024-09-05 09:58:34.579
!MESSAGE Both 'fr.inria.aoste.timesquare.duration.model' and 'fr.inria.aoste.timesquare.duration.xtext.ui' register an extension parser for 'duration'

!ENTRY org.eclipse.jface 2 0 2024-09-05 09:58:38.604
!MESSAGE Keybinding conflicts occurred.  They may interfere with normal accelerator operation.
!SUBENTRY 1 org.eclipse.jface 2 0 2024-09-05 09:58:38.604
!MESSAGE A conflict occurred for CTRL+SHIFT+T:
Binding(CTRL+SHIFT+T,
        ParameterizedCommand(Command(org.eclipse.jdt.ui.navigate.open.type,Open Type,
                Open a type in a Java editor,
                Category(org.eclipse.ui.category.navigate,Navigate,null,true),
                WorkbenchHandlerServiceHandler("org.eclipse.jdt.ui.navigate.open.type"),
                ,,true),null),
        org.eclipse.ui.defaultAcceleratorConfiguration,
        org.eclipse.ui.contexts.window,,,system)
Binding(CTRL+SHIFT+T,
        ParameterizedCommand(Command(org.eclipse.lsp4e.symbolinworkspace,Go to Symbol in Workspace,
                ,
                Category(org.eclipse.lsp4e.category,Language Servers,null,true),
                WorkbenchHandlerServiceHandler("org.eclipse.lsp4e.symbolinworkspace"),
                ,,true),null),
        org.eclipse.ui.defaultAcceleratorConfiguration,
        org.eclipse.ui.contexts.window,,,system)

!ENTRY org.eclipse.urischeme 4 0 2024-09-05 09:58:41.888
!MESSAGE Cannot run program "xdg-mime": error=2, No such file or directory
!STACK 0
java.io.IOException: Cannot run program "xdg-mime": error=2, No such file or directory
        at java.base/java.lang.ProcessBuilder.start(ProcessBuilder.java:1143)
        at java.base/java.lang.ProcessBuilder.start(ProcessBuilder.java:1073)
        at org.eclipse.urischeme.internal.registration.ProcessExecutor.execute(ProcessExecutor.java:36)
        at org.eclipse.urischeme.internal.registration.RegistrationLinux.getRegisteredDesktopFileForScheme(RegistrationLinux.java:145)
        at org.eclipse.urischeme.internal.registration.RegistrationLinux.determineHandlerLocation(RegistrationLinux.java:87)
        at org.eclipse.urischeme.internal.registration.RegistrationLinux.getSchemesInformation(RegistrationLinux.java:76)
        at org.eclipse.urischeme.AutoRegisterSchemeHandlersJob.run(AutoRegisterSchemeHandlersJob.java:87)
        at org.eclipse.core.internal.jobs.Worker.run(Worker.java:63)
Caused by: java.io.IOException: error=2, No such file or directory
        at java.base/java.lang.ProcessImpl.forkAndExec(Native Method)
        at java.base/java.lang.ProcessImpl.<init>(ProcessImpl.java:314)
        at java.base/java.lang.ProcessImpl.start(ProcessImpl.java:244)
        at java.base/java.lang.ProcessBuilder.start(ProcessBuilder.java:1110)
        ... 7 more

[dvojtise]

after some (println-based 🙄) investigations
it seems that this is the line https://github.com/eclipse/gemoc-studio-commons/blob/28b5ee4a53a0f14ae47020840fe97cf45a2d3ea8/plugins/org.eclipse.gemoc.commons.eclipse.messagingsystem.ui/src/main/java/org/eclipse/gemoc/commons/eclipse/messagingsystem/ui/Activator.java#L151

that is called but never ends

[dvojtise]

after more investigation:
getConsoleIO tries to create 2 console in parallel

of from the testuite

00:01:40 java.lang.Throwable
00:01:40 	at org.eclipse.gemoc.commons.eclipse.messagingsystem.ui.Activator.getConsoleIO(Activator.java:142)
00:01:40 	at org.eclipse.gemoc.commons.eclipse.messagingsystem.ui.EclipseMessagingSystem.getConsoleIO(EclipseMessagingSystem.java:55)
00:01:40 	at org.eclipse.gemoc.commons.eclipse.messagingsystem.ui.EclipseMessagingSystem.log(EclipseMessagingSystem.java:248)
00:01:40 	at org.eclipse.gemoc.commons.eclipse.messagingsystem.api.MessagingSystem.important(MessagingSystem.java:101)
00:01:40 	at org.eclipse.gemoc.studio.tests.system.lwb.userstory.DeployOfficialExampleMelangeK3FSM_Test.beforeClass(DeployOfficialExampleMelangeK3FSM_Test.java:67)
00:01:40 	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
00:01:40 	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
00:01:40 	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
00:01:40 	at java.base/java.lang.reflect.Method.invoke(Method.java:569)
00:01:40 	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:59)
00:01:40 	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
00:01:40 	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:56)
00:01:40 	at org.junit.internal.runners.statements.RunBefores.invokeMethod(RunBefores.java:33)
00:01:40 	at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:24)
00:01:40 	at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
00:01:40 	at org.junit.runners.ParentRunner.run(ParentRunner.java:413)
00:01:40 	at org.eclipse.swtbot.swt.finder.junit.SWTBotJunit4ClassRunner.run(SWTBotJunit4ClassRunner.java:62)
00:01:40 	at org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:364)
00:01:40 	at org.apache.maven.surefire.junit4.JUnit4Provider.executeWithRerun(JUnit4Provider.java:272)
00:01:40 	at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:237)
00:01:40 	at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:158)
00:01:40 	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
00:01:40 	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
00:01:40 	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
00:01:40 	at java.base/java.lang.reflect.Method.invoke(Method.java:569)
00:01:40 	at org.apache.maven.surefire.api.util.ReflectionUtils.invokeMethodWithArray2(ReflectionUtils.java:167)
00:01:40 	at org.apache.maven.surefire.booter.ProviderFactory$ProviderProxy.invoke(ProviderFactory.java:161)
00:01:40 	at org.apache.maven.surefire.booter.ProviderFactory.invokeProvider(ProviderFactory.java:84)
00:01:40 	at org.eclipse.tycho.surefire.osgibooter.OsgiSurefireBooter.run(OsgiSurefireBooter.java:142)
00:01:40 	at org.eclipse.tycho.surefire.osgibooter.AbstractUITestApplication.runTests(AbstractUITestApplication.java:49)
00:01:40 	at org.eclipse.e4.ui.internal.workbench.swt.E4Testable.lambda$0(E4Testable.java:79)
00:01:40 	at java.base/java.lang.Thread.run(Thread.java:840)

and one from the activator

00:01:40 java.lang.Throwable
00:01:40 	at org.eclipse.gemoc.commons.eclipse.messagingsystem.ui.Activator.getConsoleIO(Activator.java:142)
00:01:40 	at org.eclipse.gemoc.commons.eclipse.messagingsystem.ui.Activator.captureSystemOutAndErr(Activator.java:164)
00:01:40 	at org.eclipse.gemoc.commons.eclipse.messagingsystem.ui.Activator$1$2.run(Activator.java:89)
00:01:40 	at org.eclipse.swt.widgets.RunnableLock.run(RunnableLock.java:40)
00:01:40 	at org.eclipse.swt.widgets.Synchronizer.runAsyncMessages(Synchronizer.java:132)
00:01:40 	at org.eclipse.swt.widgets.Display.runAsyncMessages(Display.java:5040)
00:01:40 	at org.eclipse.swt.widgets.Display.readAndDispatch(Display.java:4520)
00:01:40 	at org.eclipse.e4.ui.internal.workbench.swt.PartRenderingEngine$5.run(PartRenderingEngine.java:1155)
00:01:40 	at org.eclipse.core.databinding.observable.Realm.runWithDefault(Realm.java:338)
00:01:40 	at org.eclipse.e4.ui.internal.workbench.swt.PartRenderingEngine.run(PartRenderingEngine.java:1046)
00:01:40 	at org.eclipse.e4.ui.internal.workbench.E4Workbench.createAndRunUI(E4Workbench.java:155)
00:01:40 	at org.eclipse.ui.internal.Workbench.lambda$3(Workbench.java:643)
00:01:40 	at org.eclipse.core.databinding.observable.Realm.runWithDefault(Realm.java:338)
00:01:40 	at org.eclipse.ui.internal.Workbench.createAndRunWorkbench(Workbench.java:550)
00:01:40 	at org.eclipse.ui.PlatformUI.createAndRunWorkbench(PlatformUI.java:171)
00:01:40 	at org.eclipse.ui.internal.ide.application.IDEApplication.start(IDEApplication.java:152)
00:01:40 	at org.eclipse.tycho.surefire.osgibooter.UITestApplication.runApplication(UITestApplication.java:33)
00:01:40 	at org.eclipse.tycho.surefire.osgibooter.AbstractUITestApplication.run(AbstractUITestApplication.java:127)
00:01:40 	at org.eclipse.tycho.surefire.osgibooter.UITestApplication.start(UITestApplication.java:42)
00:01:40 	at org.eclipse.equinox.internal.app.EclipseAppHandle.run(EclipseAppHandle.java:203)
00:01:40 	at org.eclipse.core.runtime.internal.adaptor.EclipseAppLauncher.runApplication(EclipseAppLauncher.java:136)
00:01:40 	at org.eclipse.core.runtime.internal.adaptor.EclipseAppLauncher.start(EclipseAppLauncher.java:104)
00:01:40 	at org.eclipse.core.runtime.adaptor.EclipseStarter.run(EclipseStarter.java:402)
00:01:40 	at org.eclipse.core.runtime.adaptor.EclipseStarter.run(EclipseStarter.java:255)
00:01:40 	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
00:01:40 	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
00:01:40 	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
00:01:40 	at java.base/java.lang.reflect.Method.invoke(Method.java:569)
00:01:40 	at org.eclipse.equinox.launcher.Main.invokeFramework(Main.java:659)
00:01:40 	at org.eclipse.equinox.launcher.Main.basicRun(Main.java:596)
00:01:40 	at org.eclipse.equinox.launcher.Main.run(Main.java:1467)
00:01:40 	at org.eclipse.equinox.launcher.Main.main(Main.java:1440)