dirigible icon indicating copy to clipboard operation
dirigible copied to clipboard

Published 20 hours ago • verified publisher icon eclipse

Docker image does not come up when using a mounted volume

Open g051051 opened this issue 9 months ago • 8 comments

Describe the bug Running the dirigiblelabe/dirigible:10.4.0 image fails to fully start when using a mounted volume for the target directory.

To Reproduce Steps to reproduce the behavior:

  1. Run the docker image as described in the https://www.dirigible.io/help/setup/docker/ "with Mounted Volume" section. Note that the instructions are incorrect and the -v option should be -v <your-local-directory>:/target -p 8080:8080 -p 8081:8081.
  2. Open localhost:8080 in a browser
  3. Log in as admin/admin
  4. You should see a "busy" page indefinitely and an error in the log

Expected behavior The system runs normally with the mounted volume.

Desktop (please complete the following information):

  • OS: Windows 11
  • Browser: Chrome
  • Version: 124.0.6367.119 (Official Build) (64-bit)

Additional context

2024-05-01 08:33:05 2024-05-01 12:33:05.768 [ERROR] [http-nio-8080-exec-4] [background] o.a.c.c.C.[.[.[.[dispatcherServlet] - Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed: java.lang.RuntimeException: java.nio.file.FileAlreadyExistsException: /target/dirigible/repository/root/registry/public/modules/dist/esm/http/rs] with root cause
2024-05-01 08:33:05 org.graalvm.polyglot.PolyglotException: java.nio.file.FileAlreadyExistsException: /target/dirigible/repository/root/registry/public/modules/dist/esm/http/rs

g051051 avatar May 01 '24 12:05 g051051

Hi @g051051, I was able to run the Docker image with mounted volume without any issues.

I've run it with the following command, where dirigible-volume is a folder on my desktop:

docker run --name dirigible \
-v /Users/thuf/Desktop/dirigible-volume:/target \
--rm -p 8080:8080 -p 8081:8081 \
dirigiblelabs/dirigible:10.4.0

Also via the Docker Desktop app:

Screenshot 2024-05-10 at 17 36 30

I'm able to login and open the Web IDE and create a project that in the end is stored on the persistent volume:

Screenshot 2024-05-10 at 17 33 00

I guess the issue that you've encountered is related actually with the loading screen (http://localhost:8080/index-busy.html, not redirecting to http://localhost:8080/services/web/ide/). It seems that this happens sometimes, before the Dirigible is fully operational. If that's the case, could we close this issue and tackle the loading screen separately?

ThuF avatar May 10 '24 14:05 ThuF

It's not the loading screen issue. ~~It might be the Git line ending thing. I'll test it again now that I've changed that setting and see if it makes a difference.~~

Actually, I was using the stock docker image, so it wouldn't have anything to do with the Git settings. Did you try it on Windows?

g051051 avatar May 10 '24 14:05 g051051

Not yet, we'll investigate it under Windows too. In the meantime could you try to run it via the Windows WSL?

ThuF avatar May 10 '24 16:05 ThuF

I don't know how to run docker stuff under WSL, sorry.

g051051 avatar May 10 '24 16:05 g051051

Pull 10.4.0 from docker hub:

image

Run it:

image

Log file (this is after the system had been sitting for 10 minutes): dirigible_docker_windows_mounted_volume.txt

Log file for running exact same image in docker but without a mounted volume: dirigible_docker_windows_no_mounted_volume.txt

In the first case, after logging in the "busy screen would display indefinitely. In the second case, the UI comes up immediately. Comparing the logs, a lot of the initialization never executed in the first version.

g051051 avatar May 10 '24 17:05 g051051

Hi @g051051, we've managed to reproduce the issue on windows. There seems to be a problem with docker desktop using mounted volume that we have to sort out. Meanwhile as a workaround you could run dirigible directly. To do so you need to download a latest version of the dirigible jar file form the maven central repository, e.g. dirigible-application-10.4.1-executable.jar and then to set the following environment variables (given your target folder resides here D:\Dev\dirigible\target):

DIRIGIBLE_CMS_INTERNAL_ROOT_FOLDER=D:\Dev\dirigible\target\dirigible\cms
DIRIGIBLE_CMS_INTERNAL_ROOT_FOLDER_IS_ABSOLUTE=true
DIRIGIBLE_OPERATIONS_LOGS_ROOT_FOLDER_DEFAULT=D:\Dev\dirigible\logs
DIRIGIBLE_REPOSITORY_LOCAL_ROOT_FOLDER=D:\Dev\dirigible\target
DIRIGIBLE_REPOSITORY_LOCAL_ROOT_FOLDER_IS_ABSOLUTE=true
DIRIGIBLE_REPOSITORY_SEARCH_ROOT_FOLDER=D:\Dev\dirigible\target
DIRIGIBLE_REPOSITORY_SEARCH_ROOT_FOLDER_IS_ABSOLUTE=true

Finally run dirigible (as administrator) with the following command:

java -jar dirigible-application-10.4.1-executable.jar

I hope that helps.

himchev avatar May 14 '24 17:05 himchev

Thanks, I'll give that a try next time I work with it.

g051051 avatar May 14 '24 17:05 g051051

I tried it, and it seemed to work OK.

g051051 avatar May 15 '24 01:05 g051051

I'm closing this issue as solved.

ThuF avatar Aug 15 '24 08:08 ThuF

There seems to be a problem with docker desktop using mounted volume that we have to sort out.

Was it actually fixed, or are you just closing it? I don't see any commits attached to this, so do you just mean to leave the workaround?

g051051 avatar Aug 15 '24 12:08 g051051

There seems to be a problem with docker desktop using mounted volume that we have to sort out.

Was it actually fixed, or are you just closing it? I don't see any commits attached to this, so do you just mean to leave the workaround?

I've just tested the latest image on my Mac and everything works. Please retest on windows. I used the following commands:

export WORKSPACE_DIR='/tmp/dirigible'

docker pull dirigiblelabs/dirigible:latest
docker run --name dirigible --rm -p 8080:8080 \
    -v "$WORKSPACE_DIR:/target/dirigible" \
    dirigiblelabs/dirigible:latest

just change the path which is mounted.

Regarding the mentioned error 2024-05-01 08:33:05 org.graalvm.polyglot.PolyglotException: java.nio.file.FileAlreadyExistsException: /target/dirigible/repository/root/registry/public/modules/dist/esm/http/rs it was fixed. I think with this PR https://github.com/eclipse/dirigible/pull/4184

iliyan-velichkov avatar Aug 15 '24 12:08 iliyan-velichkov

It still doesn't work on Windows. I can see it starting in the logs, and can get a login screen and present a password, but it hangs on the ide-busy page and never becomes ready. The local directory I'm mounting as /target/dirigible only has the h2 and repository directories, and it throws PolyglotExceptions for missing files:

2024-08-15 09:21:18 2024-08-15 13:21:18.046 [ERROR] [http-nio-8080-exec-4] [default-tenant] o.e.d.c.e.j.s.JavascriptHandler - Error on processing JavaScript service from project: [theme], and path: [resources.js], with parameters: [themes] 2024-08-15 09:21:18 org.graalvm.polyglot.PolyglotException: Failed to load resource from path [/META-INF/dirigible/modules/dist/esm/http/client] 2024-08-15 09:21:18 at org.eclipse.dirigible.graalium.core.modules.DirigibleSourceProvider.unpackedToFileSystem(DirigibleSourceProvider.java:202) ~[dirigible-engine-graalium-execution-core-11.0.0-SNAPSHOT.jar!/:na]

dirigiblelog.txt

g051051 avatar Aug 15 '24 13:08 g051051

Can you try with this image ghcr.io/iliyan-velichkov/dirigible:pr-4229 and attach the log? It contains the following change: https://github.com/eclipse/dirigible/pull/4229

iliyan-velichkov avatar Aug 16 '24 07:08 iliyan-velichkov

Can you try with this image ghcr.io/iliyan-velichkov/dirigible:pr-4229 and attach the log? It contains the following change: #4229

@g051051 forget about this comment since it will not help you. After some testing on Windows I found that the file operations are quite slow when the image run on Windows with mounted folder. The exceptions which you receive in the logs are not the root cause of the problem. They happen because you are opening the dirigible before it is fully initialized. Actually, if you wait until a message like 2024-08-16 09:41:11.996 [INFO ] [main] [background] o.e.d.AppLifecycleLoggingListener - ------------------------ Eclipse Dirigible started ------------------------ is logged and then open the dirigible, everything will be fine. In my tests it took around 6-8 minutes until the Dirigible is fully initialized. Here is an example

PS C:\Users\velic> docker run --name dirigible --rm -p 8080:8080 `
>>     -v "D:\work\workspaces\dirigible\docker:/target/dirigible" `
>>     dirigiblelabs/dirigible:latest
09:14:44,126 |-INFO in ch.qos.logback.classic.LoggerContext[default] - This is logback-classic version 1.4.14
09:14:44,136 |-INFO in ch.qos.logback.classic.util.ContextInitializer@1b45c0e - Here is a list of configurators discovered as a service, by rank:
...
2024-08-16 09:21:23.799 [INFO ] [main] [background] o.e.d.c.t.p.TenantProvisioningJob - Configuring tenant provisioning job to fire every [900] seconds
2024-08-16 09:21:23.800 [INFO ] [main] [background] o.e.d.c.jobs.init.JobsInitializer - Scheduled job [JobDetail 'system.TenantsProvisioningJob':  jobClass: 'org.eclipse.dirigible.components.tenants.provisioning.TenantProvisioningJob concurrentExectionDisallowed: false persistJobDataAfterExecution: false isDurable: true requestsRecovers: true] with trigger [Trigger 'system.TenantsProvisioningJobTrigger':  triggerClass: 'org.quartz.impl.triggers.SimpleTriggerImpl calendar: 'null' misfireInstruction: 5 nextFireTime: Fri Aug 16 09:21:23 GMT 2024]
2024-08-16 09:21:23.801 [INFO ] [main] [background] o.e.d.c.jobs.init.JobsInitializer - Completed.
2024-08-16 09:21:23.802 [INFO ] [main] [background] o.e.d.AppLifecycleLoggingListener - ------------------------ Eclipse Dirigible started ------------------------

During the start up, the Dirigible executes a lot of file/disk operations which in this case are quite slow.

I tried a few options to increase the performance on Windows but only one actually worked. To improve the performance, use volume not mounted folder. Here is an example of run commands:

docker volume create dirigible_volume

docker run --name dirigible --rm -p 8080:8080 `
    -v "dirigible_volume:/target/dirigible" `
    dirigiblelabs/dirigible:latest

This way, the Dirigible start for less than 30 seconds

PS C:\Users\velic> docker run --name dirigible --rm -p 8080:8080 `
>>     -v "dirigible_volume:/target/dirigible" `
>>     dirigiblelabs/dirigible:latest
10:23:07,149 |-INFO in ch.qos.logback.classic.LoggerContext[default] - This is logback-classic version 1.4.14
10:23:07,157 |-INFO in ch.qos.logback.classic.util.ContextInitializer@1b45c0e - Here is a list of configurators discovered as a service, by rank:
10:23:07,157 |-INFO in ch.qos.logback.classic.util.ContextInitializer@1b45c0e -   org.springframework.boot.logging.logback.RootLogLevelConfigurator
10:23:07,157 |-INFO in ch.qos.logback.classic.util.ContextInitializer@1b45c0e - They will be invoked in order until ExecutionStatus.DO_NOT_INVOKE_NEXT_IF_ANY is returned.
10:23:07,157 |-INFO in ch.qos.logback.classic.util.ContextInitializer@1b45c0e - Constructed configurator of type class org.springframework.boot.logging.logback.RootLogLevelConfigurator
10:23:07,164 |-INFO in ch.qos.logback.classic.util.ContextInitializer@1b45c0e - org.springframework.boot.logging.logback.RootLogLevelConfigurator.configure() call lasted 0 milliseconds. ExecutionStatus=INVOKE_NEXT_IF_ANY
10:23:07,164 |-INFO in ch.qos.logback.classic.util.ContextInitializer@1b45c0e - Trying to configure with ch.qos.logback.classic.joran.SerializedModelConfigurator
10:23:07,165 |-INFO in ch.qos.logback.classic.util.ContextInitializer@1b45c0e - Constructed configurator of type class ch.qos.logback.classic.joran.SerializedModelConfigurator
10:23:07,168 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.scmo]
10:23:07,170 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.scmo]
10:23:07,171 |-INFO in ch.qos.logback.classic.util.ContextInitializer@1b45c0e - ch.qos.logback.classic.joran.SerializedModelConfigurator.configure() call lasted 5 milliseconds. ExecutionStatus=INVOKE_NEXT_IF_ANY
10:23:07,171 |-INFO in ch.qos.logback.classic.util.ContextInitializer@1b45c0e - Trying to configure with ch.qos.logback.classic.util.DefaultJoranConfigurator
10:23:07,171 |-INFO in ch.qos.logback.classic.util.ContextInitializer@1b45c0e - Constructed configurator of type class ch.qos.logback.classic.util.DefaultJoranConfigurator
10:23:07,173 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml]
10:23:07,174 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [jar:nested:/dirigible.jar/!BOOT-INF/classes/!/logback.xml]
10:23:07,182 |-INFO in ch.qos.logback.core.joran.spi.ConfigurationWatchList@11f0a5a1 - URL [jar:nested:/dirigible.jar/!BOOT-INF/classes/!/logback.xml] is not of type file
10:23:07,232 |-INFO in ch.qos.logback.core.joran.action.ConversionRuleAction - registering conversion word tenant with class [org.eclipse.dirigible.components.base.logging.TenantConverter]
10:23:07,281 |-INFO in ch.qos.logback.classic.model.processor.LoggerContextListenerModelHandler - Adding LoggerContextListener of type [ch.qos.logback.classic.jul.LevelChangePropagator] to the object stack
10:23:07,290 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@10f7f7de - Propagating INFO level on Logger[ROOT] onto the JUL framework
10:23:07,290 |-INFO in ch.qos.logback.classic.model.processor.LoggerContextListenerModelHandler - Starting LoggerContextListener
10:23:07,291 |-INFO in ch.qos.logback.core.model.processor.StatusListenerModelHandler - Added status listener of type [ch.qos.logback.core.status.OnConsoleStatusListener]
10:23:07,299 |-INFO in ch.qos.logback.core.model.processor.TimestampModelHandler - Using current interpretation time, i.e. now, as time reference.
10:23:07,302 |-INFO in ch.qos.logback.core.model.processor.TimestampModelHandler - Adding property to the context with key="date" and value="2024-08-16" to the LOCAL scope
10:23:07,305 |-INFO in ch.qos.logback.core.model.processor.AppenderModelHandler - Processing appender named [STDOUT]
10:23:07,305 |-INFO in ch.qos.logback.core.model.processor.AppenderModelHandler - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
10:23:07,310 |-INFO in ch.qos.logback.core.model.processor.ImplicitModelHandler - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
10:23:07,328 |-INFO in ch.qos.logback.core.model.processor.AppenderModelHandler - Processing appender named [FILE_CORE]
10:23:07,328 |-INFO in ch.qos.logback.core.model.processor.AppenderModelHandler - About to instantiate appender of type [ch.qos.logback.core.FileAppender]
10:23:07,330 |-INFO in ch.qos.logback.core.model.processor.ImplicitModelHandler - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
10:23:07,331 |-INFO in ch.qos.logback.core.FileAppender[FILE_CORE] - File property is set to [../logs/dirigible-core-2024-08-16.log]
10:23:07,333 |-INFO in ch.qos.logback.core.model.processor.AppenderModelHandler - Processing appender named [FILE_APPS]
10:23:07,333 |-INFO in ch.qos.logback.core.model.processor.AppenderModelHandler - About to instantiate appender of type [ch.qos.logback.core.FileAppender]
10:23:07,333 |-INFO in ch.qos.logback.core.model.processor.ImplicitModelHandler - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
10:23:07,334 |-INFO in ch.qos.logback.core.FileAppender[FILE_APPS] - File property is set to [../logs/dirigible-apps-2024-08-16.log]
10:23:07,335 |-INFO in ch.qos.logback.core.model.processor.AppenderModelHandler - Processing appender named [FILE_BASE]
10:23:07,335 |-INFO in ch.qos.logback.core.model.processor.AppenderModelHandler - About to instantiate appender of type [ch.qos.logback.core.FileAppender]
10:23:07,335 |-INFO in ch.qos.logback.core.model.processor.ImplicitModelHandler - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
10:23:07,335 |-INFO in ch.qos.logback.core.FileAppender[FILE_BASE] - File property is set to [../logs/dirigible-base-2024-08-16.log]
10:23:07,336 |-INFO in ch.qos.logback.core.model.processor.AppenderModelHandler - Processing appender named [ConsoleLoggingAppender]
10:23:07,336 |-INFO in ch.qos.logback.core.model.processor.AppenderModelHandler - About to instantiate appender of type [org.eclipse.dirigible.components.ide.console.service.ConsoleLoggingAppender]
10:23:07,338 |-INFO in ch.qos.logback.classic.model.processor.LoggerModelHandler - Setting level of logger [org.eclipse.dirigible] to INFO
10:23:07,339 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@10f7f7de - Propagating INFO level on Logger[org.eclipse.dirigible] onto the JUL framework
10:23:07,341 |-INFO in ch.qos.logback.classic.model.processor.LoggerModelHandler - Setting additivity of logger [org.eclipse.dirigible] to false
10:23:07,342 |-INFO in ch.qos.logback.core.model.processor.AppenderRefModelHandler - Attaching appender named [STDOUT] to Logger[org.eclipse.dirigible]
10:23:07,342 |-INFO in ch.qos.logback.core.model.processor.AppenderRefModelHandler - Attaching appender named [FILE_CORE] to Logger[org.eclipse.dirigible]
10:23:07,343 |-INFO in ch.qos.logback.core.model.processor.AppenderRefModelHandler - Attaching appender named [ConsoleLoggingAppender] to Logger[org.eclipse.dirigible]
10:23:07,343 |-INFO in ch.qos.logback.classic.model.processor.LoggerModelHandler - Setting level of logger [app] to INFO
10:23:07,343 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@10f7f7de - Propagating INFO level on Logger[app] onto the JUL framework
10:23:07,343 |-INFO in ch.qos.logback.classic.model.processor.LoggerModelHandler - Setting additivity of logger [app] to false
10:23:07,343 |-INFO in ch.qos.logback.core.model.processor.AppenderRefModelHandler - Attaching appender named [STDOUT] to Logger[app]
10:23:07,343 |-INFO in ch.qos.logback.core.model.processor.AppenderRefModelHandler - Attaching appender named [FILE_APPS] to Logger[app]
10:23:07,343 |-INFO in ch.qos.logback.core.model.processor.AppenderRefModelHandler - Attaching appender named [ConsoleLoggingAppender] to Logger[app]
10:23:07,343 |-INFO in ch.qos.logback.classic.model.processor.RootLoggerModelHandler - Setting level of ROOT logger to INFO
10:23:07,343 |-INFO in ch.qos.logback.core.model.processor.AppenderRefModelHandler - Attaching appender named [STDOUT] to Logger[ROOT]
10:23:07,343 |-INFO in ch.qos.logback.core.model.processor.AppenderRefModelHandler - Attaching appender named [FILE_BASE] to Logger[ROOT]
10:23:07,344 |-INFO in ch.qos.logback.core.model.processor.AppenderRefModelHandler - Attaching appender named [ConsoleLoggingAppender] to Logger[ROOT]
10:23:07,344 |-INFO in ch.qos.logback.classic.model.processor.LoggerModelHandler - Setting level of logger [org.eclipse.dirigible.components.initializers.synchronizer] to INFO
10:23:07,344 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@10f7f7de - Propagating INFO level on Logger[org.eclipse.dirigible.components.initializers.synchronizer] onto the JUL framework
10:23:07,344 |-INFO in ch.qos.logback.classic.model.processor.LoggerModelHandler - Setting level of logger [org.eclipse.dirigible.components.base.synchronizer] to INFO
10:23:07,344 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@10f7f7de - Propagating INFO level on Logger[org.eclipse.dirigible.components.base.synchronizer] onto the JUL framework
10:23:07,344 |-INFO in ch.qos.logback.classic.model.processor.LoggerModelHandler - Setting level of logger [org.eclipse.dirigible.components.tenants.tenant] to INFO
10:23:07,344 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@10f7f7de - Propagating INFO level on Logger[org.eclipse.dirigible.components.tenants.tenant] onto the JUL framework
10:23:07,344 |-INFO in ch.qos.logback.classic.model.processor.LoggerModelHandler - Setting level of logger [org.springframework.context.support] to INFO
10:23:07,344 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@10f7f7de - Propagating INFO level on Logger[org.springframework.context.support] onto the JUL framework
10:23:07,344 |-INFO in ch.qos.logback.core.model.processor.DefaultProcessor@49ff7d8c - End of configuration.
10:23:07,345 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@7fb95505 - Registering current configuration as safe fallback point
10:23:07,345 |-INFO in ch.qos.logback.classic.util.ContextInitializer@1b45c0e - ch.qos.logback.classic.util.DefaultJoranConfigurator.configure() call lasted 174 milliseconds. ExecutionStatus=DO_NOT_INVOKE_NEXT_IF_ANY
10:23:07,748 |-INFO in ch.qos.logback.core.joran.spi.ConfigurationWatchList@750fe12e - URL [jar:nested:/dirigible.jar/!BOOT-INF/classes/!/logback.xml] is not of type file
10:23:07,754 |-INFO in ch.qos.logback.core.joran.action.ConversionRuleAction - registering conversion word tenant with class [org.eclipse.dirigible.components.base.logging.TenantConverter]
10:23:07,757 |-INFO in ch.qos.logback.classic.model.processor.LoggerContextListenerModelHandler - Adding LoggerContextListener of type [ch.qos.logback.classic.jul.LevelChangePropagator] to the object stack
10:23:07,757 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@f8908f6 - Setting level of jul logger [app] to null
10:23:07,757 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@f8908f6 - Setting level of jul logger [org.springframework.context.support] to null
10:23:07,757 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@f8908f6 - Setting level of jul logger [org.eclipse.dirigible.components.tenants.tenant] to null
10:23:07,757 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@f8908f6 - Setting level of jul logger [org.eclipse.dirigible.components.initializers.synchronizer] to null
10:23:07,757 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@f8908f6 - Setting level of jul logger [org.eclipse.dirigible] to null
10:23:07,757 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@f8908f6 - Setting level of jul logger [org.eclipse.dirigible.components.base.synchronizer] to null
10:23:07,757 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@f8908f6 - Propagating DEBUG level on Logger[ROOT] onto the JUL framework
10:23:07,757 |-INFO in ch.qos.logback.classic.model.processor.LoggerContextListenerModelHandler - Starting LoggerContextListener
10:23:07,758 |-INFO in ch.qos.logback.core.model.processor.StatusListenerModelHandler - Added status listener of type [ch.qos.logback.core.status.OnConsoleStatusListener]
10:23:07,758 |-INFO in ch.qos.logback.core.model.processor.TimestampModelHandler - Using current interpretation time, i.e. now, as time reference.
10:23:07,758 |-INFO in ch.qos.logback.core.model.processor.TimestampModelHandler - Adding property to the context with key="date" and value="2024-08-16" to the LOCAL scope
10:23:07,758 |-INFO in ch.qos.logback.core.model.processor.AppenderModelHandler - Processing appender named [STDOUT]
10:23:07,759 |-INFO in ch.qos.logback.core.model.processor.AppenderModelHandler - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
10:23:07,759 |-INFO in ch.qos.logback.core.model.processor.ImplicitModelHandler - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
10:23:07,760 |-INFO in ch.qos.logback.core.model.processor.AppenderModelHandler - Processing appender named [FILE_CORE]
10:23:07,760 |-INFO in ch.qos.logback.core.model.processor.AppenderModelHandler - About to instantiate appender of type [ch.qos.logback.core.FileAppender]
10:23:07,760 |-INFO in ch.qos.logback.core.model.processor.ImplicitModelHandler - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
10:23:07,760 |-INFO in ch.qos.logback.core.FileAppender[FILE_CORE] - File property is set to [../logs/dirigible-core-2024-08-16.log]
10:23:07,761 |-INFO in ch.qos.logback.core.model.processor.AppenderModelHandler - Processing appender named [FILE_APPS]
10:23:07,761 |-INFO in ch.qos.logback.core.model.processor.AppenderModelHandler - About to instantiate appender of type [ch.qos.logback.core.FileAppender]
10:23:07,761 |-INFO in ch.qos.logback.core.model.processor.ImplicitModelHandler - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
10:23:07,761 |-INFO in ch.qos.logback.core.FileAppender[FILE_APPS] - File property is set to [../logs/dirigible-apps-2024-08-16.log]
10:23:07,761 |-INFO in ch.qos.logback.core.model.processor.AppenderModelHandler - Processing appender named [FILE_BASE]
10:23:07,761 |-INFO in ch.qos.logback.core.model.processor.AppenderModelHandler - About to instantiate appender of type [ch.qos.logback.core.FileAppender]
10:23:07,761 |-INFO in ch.qos.logback.core.model.processor.ImplicitModelHandler - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
10:23:07,762 |-INFO in ch.qos.logback.core.FileAppender[FILE_BASE] - File property is set to [../logs/dirigible-base-2024-08-16.log]
10:23:07,762 |-INFO in ch.qos.logback.core.model.processor.AppenderModelHandler - Processing appender named [ConsoleLoggingAppender]
10:23:07,762 |-INFO in ch.qos.logback.core.model.processor.AppenderModelHandler - About to instantiate appender of type [org.eclipse.dirigible.components.ide.console.service.ConsoleLoggingAppender]
10:23:07,762 |-INFO in ch.qos.logback.classic.model.processor.LoggerModelHandler - Setting level of logger [org.eclipse.dirigible] to INFO
10:23:07,762 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@3e587920 - Propagating INFO level on Logger[org.eclipse.dirigible] onto the JUL framework
10:23:07,762 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@f8908f6 - Propagating INFO level on Logger[org.eclipse.dirigible] onto the JUL framework
10:23:07,762 |-INFO in ch.qos.logback.classic.model.processor.LoggerModelHandler - Setting additivity of logger [org.eclipse.dirigible] to false
10:23:07,762 |-INFO in ch.qos.logback.core.model.processor.AppenderRefModelHandler - Attaching appender named [STDOUT] to Logger[org.eclipse.dirigible]
10:23:07,762 |-INFO in ch.qos.logback.core.model.processor.AppenderRefModelHandler - Attaching appender named [FILE_CORE] to Logger[org.eclipse.dirigible]
10:23:07,762 |-INFO in ch.qos.logback.core.model.processor.AppenderRefModelHandler - Attaching appender named [ConsoleLoggingAppender] to Logger[org.eclipse.dirigible]
10:23:07,762 |-INFO in ch.qos.logback.classic.model.processor.LoggerModelHandler - Setting level of logger [app] to INFO
10:23:07,762 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@3e587920 - Propagating INFO level on Logger[app] onto the JUL framework
10:23:07,763 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@f8908f6 - Propagating INFO level on Logger[app] onto the JUL framework
10:23:07,763 |-INFO in ch.qos.logback.classic.model.processor.LoggerModelHandler - Setting additivity of logger [app] to false
10:23:07,763 |-INFO in ch.qos.logback.core.model.processor.AppenderRefModelHandler - Attaching appender named [STDOUT] to Logger[app]
10:23:07,763 |-INFO in ch.qos.logback.core.model.processor.AppenderRefModelHandler - Attaching appender named [FILE_APPS] to Logger[app]
10:23:07,763 |-INFO in ch.qos.logback.core.model.processor.AppenderRefModelHandler - Attaching appender named [ConsoleLoggingAppender] to Logger[app]
10:23:07,763 |-INFO in ch.qos.logback.classic.model.processor.RootLoggerModelHandler - Setting level of ROOT logger to INFO
10:23:07,763 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@3e587920 - Propagating INFO level on Logger[ROOT] onto the JUL framework
10:23:07,763 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@f8908f6 - Propagating INFO level on Logger[ROOT] onto the JUL framework
10:23:07,763 |-INFO in ch.qos.logback.core.model.processor.AppenderRefModelHandler - Attaching appender named [STDOUT] to Logger[ROOT]
10:23:07,763 |-INFO in ch.qos.logback.core.model.processor.AppenderRefModelHandler - Attaching appender named [FILE_BASE] to Logger[ROOT]
10:23:07,763 |-INFO in ch.qos.logback.core.model.processor.AppenderRefModelHandler - Attaching appender named [ConsoleLoggingAppender] to Logger[ROOT]
10:23:07,763 |-INFO in ch.qos.logback.classic.model.processor.LoggerModelHandler - Setting level of logger [org.eclipse.dirigible.components.initializers.synchronizer] to INFO
10:23:07,763 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@3e587920 - Propagating INFO level on Logger[org.eclipse.dirigible.components.initializers.synchronizer] onto the JUL framework
10:23:07,763 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@f8908f6 - Propagating INFO level on Logger[org.eclipse.dirigible.components.initializers.synchronizer] onto the JUL framework
10:23:07,763 |-INFO in ch.qos.logback.classic.model.processor.LoggerModelHandler - Setting level of logger [org.eclipse.dirigible.components.base.synchronizer] to INFO
10:23:07,763 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@3e587920 - Propagating INFO level on Logger[org.eclipse.dirigible.components.base.synchronizer] onto the JUL framework
10:23:07,764 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@f8908f6 - Propagating INFO level on Logger[org.eclipse.dirigible.components.base.synchronizer] onto the JUL framework
10:23:07,764 |-INFO in ch.qos.logback.classic.model.processor.LoggerModelHandler - Setting level of logger [org.eclipse.dirigible.components.tenants.tenant] to INFO
10:23:07,764 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@3e587920 - Propagating INFO level on Logger[org.eclipse.dirigible.components.tenants.tenant] onto the JUL framework
10:23:07,764 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@f8908f6 - Propagating INFO level on Logger[org.eclipse.dirigible.components.tenants.tenant] onto the JUL framework
10:23:07,764 |-INFO in ch.qos.logback.classic.model.processor.LoggerModelHandler - Setting level of logger [org.springframework.context.support] to INFO
10:23:07,764 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@3e587920 - Propagating INFO level on Logger[org.springframework.context.support] onto the JUL framework
10:23:07,764 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@f8908f6 - Propagating INFO level on Logger[org.springframework.context.support] onto the JUL framework
10:23:07,764 |-INFO in ch.qos.logback.core.model.processor.DefaultProcessor@2ef8a8c3 - End of configuration.
10:23:07,764 |-INFO in org.springframework.boot.logging.logback.SpringBootJoranConfigurator@24f43aa3 - Registering current configuration as safe fallback point
2024-08-16 10:23:07.802 [INFO ] [background-preinit] [background] o.h.validator.internal.util.Version - HV000001: Hibernate Validator 8.0.1.Final
      _ _      _       _ _     _
   __| (_)_ __(_) __ _(_) |__ | | ___
  / _` | | '__| |/ _` | | '_ \| |/ _ \
 ( (_| | | |  | | (_| | | |_) | |  __/
  \__,_|_|_|  |_|\__, |_|_.__/|_|\___)
 ================(___/================

2024-08-16 10:23:07.918 [INFO ] [main] [background] o.e.dirigible.DirigibleApplication - Starting DirigibleApplication using Java 21.0.4 with PID 1 (/dirigible.jar started by root in /)
2024-08-16 10:23:07.919 [INFO ] [main] [background] o.e.dirigible.DirigibleApplication - No active profile set, falling back to 1 default profile: "default"
...
...
...
2024-08-16 10:23:30.044 [INFO ] [main] [background] o.e.d.c.i.s.SynchronizationInitializer - Completed.
2024-08-16 10:23:30.044 [INFO ] [main] [background] o.e.d.c.jobs.init.JobsInitializer - Initializing [2] jobs: [org.eclipse.dirigible.components.initializers.synchronizer.SynchronizationJob@4e0a5927, org.eclipse.dirigible.components.tenants.provisioning.TenantProvisioningJob@552a1498]}
2024-08-16 10:23:30.045 [INFO ] [main] [background] o.e.d.c.i.s.SynchronizationJob - Configuring trigger to fire every [10] seconds
2024-08-16 10:23:30.049 [INFO ] [main] [background] o.e.d.c.jobs.init.JobsInitializer - Scheduled job [JobDetail 'system.SynchronizationJobDetail':  jobClass: 'org.eclipse.dirigible.components.initializers.synchronizer.SynchronizationJob concurrentExectionDisallowed: false persistJobDataAfterExecution: false isDurable: true requestsRecovers: true] with trigger [Trigger 'system.SynchronizationJobTrigger':  triggerClass: 'org.quartz.impl.triggers.SimpleTriggerImpl calendar: 'null' misfireInstruction: 5 nextFireTime: Fri Aug 16 10:23:30 GMT 2024]
2024-08-16 10:23:30.049 [INFO ] [main] [background] o.e.d.c.t.p.TenantProvisioningJob - Configuring tenant provisioning job to fire every [900] seconds
2024-08-16 10:23:30.051 [INFO ] [main] [background] o.e.d.c.jobs.init.JobsInitializer - Scheduled job [JobDetail 'system.TenantsProvisioningJob':  jobClass: 'org.eclipse.dirigible.components.tenants.provisioning.TenantProvisioningJob concurrentExectionDisallowed: false persistJobDataAfterExecution: false isDurable: true requestsRecovers: true] with trigger [Trigger 'system.TenantsProvisioningJobTrigger':  triggerClass: 'org.quartz.impl.triggers.SimpleTriggerImpl calendar: 'null' misfireInstruction: 5 nextFireTime: Fri Aug 16 10:23:30 GMT 2024]
2024-08-16 10:23:30.051 [INFO ] [main] [background] o.e.d.c.jobs.init.JobsInitializer - Completed.
2024-08-16 10:23:30.052 [INFO ] [main] [background] o.e.d.AppLifecycleLoggingListener - ------------------------ Eclipse Dirigible started ------------------------

iliyan-velichkov avatar Aug 16 '24 10:08 iliyan-velichkov

I'll try it, but in previous testing it never worked. I've waited for over 30 minutes without the system becoming operational.

g051051 avatar Aug 16 '24 11:08 g051051

After adding some additional logs to the Dirigible with https://github.com/eclipse/dirigible/pull/4230 It even clearer that the slow loading is caused by the classpath expander logic due to the slow file operations.

Run with volume

  • Command
docker volume create dirigible_volume

docker run --name dirigible --rm -p 8080:8080 `
    -v "dirigible_volume:/target/dirigible" `
    dirigiblelabs/dirigible:latest
  • Logs
2024-08-16 12:03:10.360 [INFO ] [main] [background] o.e.d.c.i.c.ClasspathExpander - Expanding the content of [dirigible]...
2024-08-16 12:03:11.900 [INFO ] [main] [background] o.e.d.c.i.c.ClasspathExpander - The content of [dirigible] has been expanded. It took [1540] millis
2024-08-16 12:03:11.902 [INFO ] [main] [background] o.e.d.c.i.c.ClasspathExpander - Expanding the content of [resources/webjars]...
2024-08-16 12:03:12.798 [INFO ] [Thread-7] [background] org.quartz.core.QuartzScheduler - Scheduler EclipseDirigibleScheduler_$_baa2127844b71723809782769 started.
2024-08-16 12:03:13.178 [INFO ] [main] [background] o.e.d.c.i.c.ClasspathExpander - The content of [resources/webjars] has been expanded. It took [1275] millis
  • Summary dirigible folder expanding took 1 540ms resources/webjars folder expanding took 1 275ms

Run with mounted folder

  • Command
docker run --name dirigible --rm -p 8080:8080 `
    -v "D:\work\workspaces\dirigible\docker:/target/dirigible" `
    dirigiblelabs/dirigible:latest
  • Logs
...
2024-08-16 12:05:31.286 [INFO ] [main] [background] o.e.d.c.i.c.ClasspathExpander - Expanding the content of [dirigible]...
2024-08-16 12:05:33.145 [INFO ] [Thread-7] [background] org.quartz.core.QuartzScheduler - Scheduler EclipseDirigibleScheduler_$_9f263ad232641723809923119 started.
2024-08-16 12:05:40.659 [INFO ] [Quartz Scheduler [EclipseDirigibleScheduler]] [background] o.s.s.quartz.SchedulerFactoryBean - Starting Quartz Scheduler now, after delay of 10 seconds
2024-08-16 12:05:40.659 [INFO ] [Quartz Scheduler [EclipseDirigibleScheduler]] [background] org.quartz.core.QuartzScheduler - Scheduler EclipseDirigibleScheduler_$_9f263ad232641723809923119 started.
WARNING: A restricted method in java.lang.foreign.Linker has been called
WARNING: java.lang.foreign.Linker::downcallHandle has been called by the unnamed module
WARNING: Use --enable-native-access=ALL-UNNAMED to avoid a warning for this module

2024-08-16 12:05:52.833 [INFO ] [Timer-0] [background] o.a.l.s.MemorySegmentIndexInputProvider - Using MemorySegmentIndexInput and native madvise support with Java 21 or later; to disable start with -Dorg.apache.lucene.store.MMapDirectory.enableMemorySegments=false
2024-08-16 12:05:52.928 [WARN ] [Timer-0] [background] o.a.l.i.v.VectorizationProvider - Java vector incubator module is not readable. For optimal vector performance, pass '--add-modules jdk.incubator.vector' to enable Vector API.
2024-08-16 12:06:30.609 [INFO ] [MessageBroker-1] [background] o.s.w.s.c.WebSocketMessageBrokerStats - WebSocketSession[0 current WS(0)-HttpStream(0)-HttpPoll(0), 0 total, 0 closed abnormally (0 connect failure, 0 send limit, 0 transport error)], stompSubProtocol[processed CONNECT(0)-CONNECTED(0)-DISCONNECT(0)], stompBrokerRelay[null], inboundChannel[pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 0], outboundChannel[pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 0], sockJsScheduler[pool size = 1, active threads = 1, queued tasks = 0, completed tasks = 0]
2024-08-16 12:08:27.942 [INFO ] [main] [background] o.e.d.c.i.c.ClasspathExpander - The content of [dirigible] has been expanded. It took [176656] millis
2024-08-16 12:08:27.943 [INFO ] [main] [background] o.e.d.c.i.c.ClasspathExpander - Expanding the content of [resources/webjars]...
2024-08-16 12:11:41.848 [INFO ] [main] [background] o.e.d.c.i.c.ClasspathExpander - The content of [resources/webjars] has been expanded. It took [193905] millis
...
...
...
2024-08-16 12:11:54.464 [INFO ] [main] [background] o.e.d.AppLifecycleLoggingListener - ------------------------ Eclipse Dirigible started ------------------------
  • Summary dirigible folder expanding took 176 656ms ~ 2.9min resources/webjars folder expanding took 193 905ms ~ 3.2min

iliyan-velichkov avatar Aug 16 '24 12:08 iliyan-velichkov

I'll try it, but in previous testing it never worked. I've waited for over 30 minutes without the system becoming operational.

@g051051 let me know if the proposed solution does not work for you

iliyan-velichkov avatar Aug 16 '24 12:08 iliyan-velichkov

I'll try it, but in previous testing it never worked. I've waited for over 30 minutes without the system becoming operational.

note that mentioned times depend on a lot of things like PC, docker version and configurations, used dirigible version, etc.

iliyan-velichkov avatar Aug 16 '24 12:08 iliyan-velichkov

Like I said, I'll try it, but if you've conclusively proved it's a Windows/Java/Docker issue, as opposed to a Dirigible issue, then I'll just have to make do.

The concern that led me to pursue this issue is I was trying to do Dirigible development and testing on pure Windows, and kept running in to issues.

BTW, I just did some searches on this. It's actually an old problem, reported as far back as 2016. From what I can tell, the underlying issue is that the mount is done via SMB(!) as if it was a network share. It's certainly a clever way to do it, but performance is terrible.

g051051 avatar Aug 16 '24 13:08 g051051

Note that most of the team members are using Mac or Linux. That's why you may be facing issues which we haven't. To mitigate this gap, we added some actions which run tests on Windows as well but the tests cannot cover all cases and scenarios.

I would recommend you to use the docker image instead of running the jar. But, as you can see, there are still some issues which are related to Windows. We value your feedback and we will be happy to help you if you find more issues.

iliyan-velichkov avatar Aug 16 '24 13:08 iliyan-velichkov

Sure. As far as feedback, it would be helpful to document exactly how the actual Dirigible devs (the ones employed full time) do their development work. I.E. tools, environment, optimizations to allow rapid turnaround and testing, etc. My struggles came from trying to work on Dirigible the same way I work on other Java projects (on Windows, in Eclipse) and it just not cooperating.

g051051 avatar Aug 16 '24 13:08 g051051

BTW, I tried it again and it did work after several minutes:

2024-08-16 21:08:30 2024-08-17 01:08:30.035 [INFO ] [main] [background] o.e.d.c.i.c.ClasspathExpander - The content of [dirigible] has been expanded. It took [216792] millis

I can only presume that the longer delays I've had in the past were due to other errors which were resolved.

g051051 avatar Aug 17 '24 01:08 g051051

BTW, I tried it again and it did work after several minutes:

2024-08-16 21:08:30 2024-08-17 01:08:30.035 [INFO ] [main] [background] o.e.d.c.i.c.ClasspathExpander - The content of [dirigible] has been expanded. It took [216792] millis

I can only presume that the longer delays I've had in the past were due to other errors which were resolved.

What did you use - path or volume?

iliyan-velichkov avatar Aug 17 '24 05:08 iliyan-velichkov

It was a a path.

g051051 avatar Aug 17 '24 12:08 g051051

It was a a path.

Please try with a dedicated volume and share the result

docker volume create dirigible_volume

docker run --name dirigible --rm -p 8080:8080 `
    -v "dirigible_volume:/target/dirigible" `
    dirigiblelabs/dirigible:latest

iliyan-velichkov avatar Aug 19 '24 06:08 iliyan-velichkov

I was already doing that since we determined it was due to Docker using an SMB share for directory mounting. I only went back and did the other test to see how long it would actually take for it to finish starting, essentially confirming your diagnosis.

g051051 avatar Aug 19 '24 12:08 g051051

@g051051 optimizations have been merged as well to improve the expand logic

  • https://github.com/eclipse/dirigible/commit/13b3f7e110af81086739fb7df73479dcb1e09ecf
  • https://github.com/eclipse/dirigible/commit/66684bdc91974170efddf6114f0456501b5e2c69

iliyan-velichkov avatar Aug 23 '24 08:08 iliyan-velichkov

I'll try it this weekend, thanks.

g051051 avatar Aug 23 '24 11:08 g051051

Using the latest docker image (on 08/26/2024) gave me:

2024-08-26 18:07:33 2024-08-26 22:07:33.159 [INFO ] [main] [background] o.e.d.c.i.c.ClasspathExpander - The content of [dirigible] has been expanded. It took [212930] millis

So about the same as last time I tried it.

g051051 avatar Aug 26 '24 22:08 g051051

Using the latest docker image (on 08/26/2024) gave me:

2024-08-26 18:07:33 2024-08-26 22:07:33.159 [INFO ] [main] [background] o.e.d.c.i.c.ClasspathExpander - The content of [dirigible] has been expanded. It took [212930] millis

So about the same as last time I tried it.

Yes, this is expected. The webjars expand was removed, so overall reduce of the startup time is expected.

iliyan-velichkov avatar Aug 27 '24 06:08 iliyan-velichkov