"Error occurred during inititalization of VM" when container is starting up

Question

"Error occurred during inititalization of VM" when container is starting up

sjetha-pason opened this issue 7 years ago · 12 comments

Hi.
Here's the error output I get when I start the container. I followed the instructions in the readme but it doesn't like something somewhere.

"Checking Folder: 'C:\MySQL\data\*.*'"
'Data exists, trying to start with your data'
The service already exists!
The current server installed: C:\MySQL\bin\mysqld.exe MySQL
2017.08.23 14:26:07 INFO  app[][o.s.a.AppFileSystem] Cleaning or creating temp directory C:\sonarqube\temp
2017.08.23 14:26:07 INFO  app[][o.s.a.p.JavaProcessLauncherImpl] Launch process[es]: C:\ojdkbuild\jre\bin\java -Djava.awt.headless=true -Xmx1G -Xms256m -Xss256k -Djna.nosys=true -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:CMSInitiatingOccupancyFraction=75 -XX:+UseCMSInitiatingOccupancyOnly -XX:+HeapDumpOnOutOfMemoryError -Djava.io.tmpdir=C:\sonarqube\temp -cp ./lib/common/*;./lib/search/* org.sonar.search.SearchServer C:\sonarqube\temp\sq-process8553778366576639208properties
2017.08.23 14:26:08 INFO  es[][o.s.p.ProcessEntryPoint] Starting es
2017.08.23 14:26:08 INFO  es[][o.s.s.EsSettings] Elasticsearch listening on /127.0.0.1:9001
2017.08.23 14:26:08 INFO  es[][o.elasticsearch.node] [sonarqube] version[2.4.4], pid[1852], build[fcbb46d/2017-01-03T11:33:16Z]
2017.08.23 14:26:08 INFO  es[][o.elasticsearch.node] [sonarqube] initializing ...
2017.08.23 14:26:08 INFO  es[][o.e.plugins] [sonarqube] modules [], plugins [], sites []
2017.08.23 14:26:08 INFO  es[][o.elasticsearch.env] [sonarqube] using [1] data paths, mounts [[(C:)]], net usable_space [19.7gb], net total_space [19.8gb], spins? [unknown], types [NTFS]
2017.08.23 14:26:08 INFO  es[][o.elasticsearch.env] [sonarqube] heap size [1007.3mb], compressed ordinary object pointers [true]
2017.08.23 14:26:11 INFO  es[][o.elasticsearch.node] [sonarqube] initialized
2017.08.23 14:26:11 INFO  es[][o.elasticsearch.node] [sonarqube] starting ...
2017.08.23 14:26:12 INFO  es[][o.e.transport] [sonarqube] publish_address {127.0.0.1:9001}, bound_addresses {127.0.0.1:9001}
2017.08.23 14:26:12 INFO  es[][o.e.discovery] [sonarqube] sonarqube/FzNsE7wIRFSPWf8q4E1Miw
2017.08.23 14:26:16 INFO  es[][o.e.cluster.service] [sonarqube] new_master {sonarqube}{FzNsE7wIRFSPWf8q4E1Miw}{127.0.0.1}{127.0.0.1:9001}{rack_id=sonarqube, master=true}, reason: zen-disco-join(elected_as_master, [0] joins received)
2017.08.23 14:26:16 INFO  es[][o.elasticsearch.node] [sonarqube] started
2017.08.23 14:26:16 INFO  es[][o.e.gateway] [sonarqube] recovered [0] indices into cluster_state
2017.08.23 14:26:16 INFO  app[][o.s.a.SchedulerImpl] Process[es] is up
2017.08.23 14:26:16 INFO  app[][o.s.a.p.JavaProcessLauncherImpl] Launch process[web]: C:\ojdkbuild\jre\bin\java -Djava.awt.headless=true -Dfile.encoding=UTF-8 -Xmx512m -Xms128m -XX:+HeapDumpOnOutOfMemoryError -Djava.security.egd=file:/dev/./urandom -Djava.io.tmpdir=C:\sonarqube\temp -cp ./lib/common/*;./lib/server/*;C:\sonarqube\lib\jdbc\mysql\mysql-connector-java-5.1.42.jar org.sonar.server.app.WebServer C:\sonarqube\temp\sq-process9114110630788114760properties
Error occurred during initialization of VM
Could not reserve enough space for object heap
2017.08.23 14:26:16 INFO  app[][o.s.a.SchedulerImpl] Process [web] is stopped
2017.08.23 14:26:17 INFO  es[][o.s.p.StopWatcher] Stopping process
2017.08.23 14:26:17 INFO  es[][o.elasticsearch.node] [sonarqube] stopping ...
2017.08.23 14:26:17 INFO  es[][o.elasticsearch.node] [sonarqube] stopped
2017.08.23 14:26:17 INFO  es[][o.elasticsearch.node] [sonarqube] closing ...
2017.08.23 14:26:17 INFO  es[][o.elasticsearch.node] [sonarqube] closed
2017.08.23 14:26:17 INFO  app[][o.s.a.SchedulerImpl] Process [es] is stopped
2017.08.23 14:26:17 INFO  app[][o.s.a.SchedulerImpl] SonarQube is stopped

Answer 1 · 2017-08-23T21:34:50.000Z

I just tried this with the nanoserver:lts container and I got pretty much the same result.

Answer 2 · 2017-08-24T16:14:03.000Z

Hello,

Let's figure this out, as I just tried to run it by docker pull on clean AWS Windows 2016 Server machine. Everything was fine for me.

However,

What host OS do you use?
What Docker version do you use?
Did you build it by own self or use the image from DockerHub?
Give me exact command how you ran it, please.
Did the folders you tried to mount have any files?
Did you try to remove all files from folders you mount? Image assumes you had no files there, so it does initialization. It takes some time on initial run to make structure, etc (I will move initialization to build phase in future).

Thanks for your interest, let's fix it if it has any problems!

Answer 3 · 2017-08-24T20:18:40.000Z

What host OS do you use?
Windows 10 Enterprise v15063.540
What Docker version do you use?
Docker version 17.07.0-ce-rc4, build fe143e3
Did you build it by own self or use the image from DockerHub?
Pulled the image from Docker
Give me exact command how you ran it, please.
docker run --name sonar -it -p 9000:9000
-v C:/Dev/sonarqube-mysql:C:/MySQL/data
-v C:/Dev/sonarqube-extensions:C:/sonarqube/extensions
dnikolayev/sonarqube-mysql-windows:latest
Did the folders you tried to mount have any files?
Yes, but I removing the files but kept the directories empty, and I still had the same problem
Did you try to remove all files from folders you mount? Image assumes you had no files there, so it does initialization. It takes some time on initial run to make structure, etc (I will move initialization to build phase in future).
See above. Interestingly enough it seemed to take pre-existing data into account, but that's just a side-note

Answer 4 · 2017-08-25T18:17:50.000Z

Could you please remove all files and folders from C:/Dev/sonarqube-mysql and C:/Dev/sonarqube-extensions, run it again and post a screen of it, thanks

Answer 5 · 2017-08-25T19:10:40.000Z

After clearing out the folders as requested, here's the output:

"Checking Folder: 'C:\MySQL\data\*.*'"
'First run'
2017-08-25T19:09:04.305365Z 0 [Warning] InnoDB: New log files created, LSN=45790
2017-08-25T19:09:05.066791Z 0 [Warning] InnoDB: Creating foreign key constraint system tables.
2017-08-25T19:09:05.474671Z 0 [Warning] No existing UUID has been found, so we assume that this is the first time that this server has been started. Generating a new UUID: dd2627ab-89c8-11e7-9ff8-00155d9c0518.
2017-08-25T19:09:05.552799Z 0 [Warning] Gtid table is not ready to be used. Table 'mysql.gtid_executed' cannot be opened.
2017-08-25T19:09:05.584044Z 1 [Warning] root@localhost is created with an empty password ! Please consider switching off the --initialize-insecure option.
Service successfully installed.
mysql: [Warning] Using a password on the command line interface can be insecure.
C:\sonarqube\original_extensions\jdbc-driver\oracle\README.txt
C:\sonarqube\original_extensions\plugins\README.txt
2 File(s) copied
2017.08.25 12:09:30 INFO  app[][o.s.a.AppFileSystem] Cleaning or creating temp directory C:\sonarqube\temp
2017.08.25 12:09:31 INFO  app[][o.s.a.p.JavaProcessLauncherImpl] Launch process[es]: C:\ojdkbuild\jre\bin\java -Djava.awt.headless=true -Xmx1G -Xms256m -Xss256k -Djna.nosys=true -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:CMSInitiatingOccupancyFraction=75 -XX:+UseCMSInitiatingOccupancyOnly -XX:+HeapDumpOnOutOfMemoryError -Djava.io.tmpdir=C:\sonarqube\temp -cp ./lib/common/*;./lib/search/* org.sonar.search.SearchServer C:\sonarqube\temp\sq-process5006544021686999631properties
2017.08.25 12:09:34 INFO  es[][o.s.p.ProcessEntryPoint] Starting es
2017.08.25 12:09:34 INFO  es[][o.s.s.EsSettings] Elasticsearch listening on /127.0.0.1:9001
2017.08.25 12:09:35 INFO  es[][o.elasticsearch.node] [sonarqube] version[2.4.4], pid[1248], build[fcbb46d/2017-01-03T11:33:16Z]
2017.08.25 12:09:35 INFO  es[][o.elasticsearch.node] [sonarqube] initializing ...
2017.08.25 12:09:35 INFO  es[][o.e.plugins] [sonarqube] modules [], plugins [], sites []
2017.08.25 12:09:35 INFO  es[][o.elasticsearch.env] [sonarqube] using [1] data paths, mounts [[(C:)]], net usable_space [19.7gb], net total_space [19.8gb], spins? [unknown], types [NTFS]
2017.08.25 12:09:35 INFO  es[][o.elasticsearch.env] [sonarqube] heap size [1007.3mb], compressed ordinary object pointers [true]
2017.08.25 12:09:40 INFO  es[][o.elasticsearch.node] [sonarqube] initialized
2017.08.25 12:09:40 INFO  es[][o.elasticsearch.node] [sonarqube] starting ...
2017.08.25 12:09:41 INFO  es[][o.e.transport] [sonarqube] publish_address {127.0.0.1:9001}, bound_addresses {127.0.0.1:9001}
2017.08.25 12:09:41 INFO  es[][o.e.discovery] [sonarqube] sonarqube/EFolWjfKRvugEOU0dgIdqQ
2017.08.25 12:09:45 INFO  es[][o.e.cluster.service] [sonarqube] new_master {sonarqube}{EFolWjfKRvugEOU0dgIdqQ}{127.0.0.1}{127.0.0.1:9001}{rack_id=sonarqube, master=true}, reason: zen-disco-join(elected_as_master, [0] joins received)
2017.08.25 12:09:45 INFO  es[][o.elasticsearch.node] [sonarqube] started
2017.08.25 12:09:45 INFO  es[][o.e.gateway] [sonarqube] recovered [0] indices into cluster_state
2017.08.25 12:09:45 INFO  app[][o.s.a.SchedulerImpl] Process[es] is up
2017.08.25 12:09:45 INFO  app[][o.s.a.p.JavaProcessLauncherImpl] Launch process[web]: C:\ojdkbuild\jre\bin\java -Djava.awt.headless=true -Dfile.encoding=UTF-8 -Xmx512m -Xms128m -XX:+HeapDumpOnOutOfMemoryError -Djava.security.egd=file:/dev/./urandom -Djava.io.tmpdir=C:\sonarqube\temp -cp ./lib/common/*;./lib/server/*;C:\sonarqube\lib\jdbc\mysql\mysql-connector-java-5.1.42.jar org.sonar.server.app.WebServer C:\sonarqube\temp\sq-process657426534075555498properties
Error occurred during initialization of VM
Could not reserve enough space for object heap
2017.08.25 12:09:46 INFO  app[][o.s.a.SchedulerImpl] Process [web] is stopped
2017.08.25 12:09:46 INFO  es[][o.s.p.StopWatcher] Stopping process
2017.08.25 12:09:46 INFO  es[][o.elasticsearch.node] [sonarqube] stopping ...
2017.08.25 12:09:46 INFO  es[][o.elasticsearch.node] [sonarqube] stopped
2017.08.25 12:09:46 INFO  es[][o.elasticsearch.node] [sonarqube] closing ...
2017.08.25 12:09:46 INFO  es[][o.elasticsearch.node] [sonarqube] closed
2017.08.25 12:09:46 INFO  app[][o.s.a.SchedulerImpl] Process [es] is stopped
2017.08.25 12:09:47 INFO  app[][o.s.a.SchedulerImpl] SonarQube is stopped

Answer 6 · 2017-08-26T18:43:36.000Z

Ok, I see
Two questions:
How much RAM does host machine have?
And could you please check HyperV manager and check memory allocation there?
Thanks!

Answer 7 · 2017-08-27T15:15:47.000Z

Also, I read on other forum about issues with windows containers on windows 10.
Just to confirm, could you please do "docker run" as you was doing, but with adding "--memory 2g".
As I got, on windows 10 you get 1GB of memory by default, and on windows 2016 you get full resources of your computer. SonarQube server requires 2GB of RAM according to documentation.
Please check the run with this flag, if it helps, I will add this notes for windows10 into docs

Answer 8 · 2017-08-28T14:20:03.000Z

Hi Dmytro,

The --memory 2g change fixed the issue. Thanks for all your help.

Answer 9 · 2017-08-28T16:14:55.000Z

Hello,

Cool, I will update docs for this case with windows10
Didn't know t works by different ways with memory in windows 2016 server and windows 10 by default

Answer 10 · 2017-11-09T06:22:12.000Z

I ran the exact same command

docker run --name sonarorg -it -p 9000:9000 -v C:/data/mysql:C:/MySQL/data -v C:/data/extensions:C:/sonarqube/extensions dnikolayev/sonarqube-mysql-windows:latest --memory 2g

but still getting same issue

"Checking Folder: 'C:\MySQL\data\*.*'"
'First run'
2017-11-09T06:17:30.171659Z 0 [Warning] InnoDB: New log files created, LSN=45790
2017-11-09T06:17:30.327770Z 0 [Warning] InnoDB: Creating foreign key constraint system tables.
2017-11-09T06:17:30.418601Z 0 [Warning] No existing UUID has been found, so we assume that this is the first time that this server has been started. Generating a new UUID: aa89c9cf-c515-11e7-801b-00155d944f3b.
2017-11-09T06:17:30.434238Z 0 [Warning] Gtid table is not ready to be used. Table 'mysql.gtid_executed' cannot be opened.
2017-11-09T06:17:30.449948Z 1 [Warning] root@localhost is created with an empty password ! Please consider switching off the --initialize-insecure option.
Service successfully installed.
mysql: [Warning] Using a password on the command line interface can be insecure.
C:\sonarqube\original_extensions\jdbc-driver\oracle\README.txt
C:\sonarqube\original_extensions\plugins\README.txt
2 File(s) copied
2017.11.09 14:17:46 INFO  app[][o.s.a.AppFileSystem] Cleaning or creating temp directory C:\sonarqube\temp
2017.11.09 14:17:47 INFO  app[][o.s.a.p.JavaProcessLauncherImpl] Launch process[es]: C:\ojdkbuild\jre\bin\java -Djava.awt.headless=true -Xmx1G -Xms256m -Xss256k -Djna.nosys=true -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:CMSInitiatingOccupancyFraction=75 -XX:+UseCMSInitiatingOccupancyOnly -XX:+HeapDumpOnOutOfMemoryError -Djava.io.tmpdir=C:\sonarqube\temp -cp ./lib/common/*;./lib/search/* org.sonar.search.SearchServer C:\sonarqube\temp\sq-process2627658794005838219properties
2017.11.09 14:17:47 INFO  es[][o.s.p.ProcessEntryPoint] Starting es
2017.11.09 14:17:48 INFO  es[][o.s.s.EsSettings] Elasticsearch listening on /127.0.0.1:9001
2017.11.09 14:17:48 INFO  es[][o.elasticsearch.node] [sonarqube] version[2.4.4], pid[2032], build[fcbb46d/2017-01-03T11:33:16Z]
2017.11.09 14:17:48 INFO  es[][o.elasticsearch.node] [sonarqube] initializing ...
2017.11.09 14:17:48 INFO  es[][o.e.plugins] [sonarqube] modules [], plugins [], sites []
2017.11.09 14:17:48 INFO  es[][o.elasticsearch.env] [sonarqube] using [1] data paths, mounts [[(C:)]], net usable_space [19.7gb], net total_space [19.8gb], spins? [unknown], types [NTFS]
2017.11.09 14:17:48 INFO  es[][o.elasticsearch.env] [sonarqube] heap size [1007.3mb], compressed ordinary object pointers [true]
2017.11.09 14:17:51 INFO  es[][o.elasticsearch.node] [sonarqube] initialized
2017.11.09 14:17:51 INFO  es[][o.elasticsearch.node] [sonarqube] starting ...
2017.11.09 14:17:51 INFO  es[][o.e.transport] [sonarqube] publish_address {127.0.0.1:9001}, bound_addresses {127.0.0.1:9001}
2017.11.09 14:17:51 INFO  es[][o.e.discovery] [sonarqube] sonarqube/XjZ0O4VDTVaidZvf_dbb4A
2017.11.09 14:17:55 INFO  es[][o.e.cluster.service] [sonarqube] new_master {sonarqube}{XjZ0O4VDTVaidZvf_dbb4A}{127.0.0.1}{127.0.0.1:9001}{rack_id=sonarqube, master=true}, reason: zen-disco-join(elected_as_master, [0] joins received)
2017.11.09 14:17:55 INFO  es[][o.elasticsearch.node] [sonarqube] started
2017.11.09 14:17:55 INFO  es[][o.e.gateway] [sonarqube] recovered [0] indices into cluster_state
2017.11.09 14:17:56 INFO  app[][o.s.a.SchedulerImpl] Process[es] is up
2017.11.09 14:17:56 INFO  app[][o.s.a.p.JavaProcessLauncherImpl] Launch process[web]: C:\ojdkbuild\jre\bin\java -Djava.awt.headless=true -Dfile.encoding=UTF-8 -Xmx512m -Xms128m -XX:+HeapDumpOnOutOfMemoryError -Djava.security.egd=file:/dev/./urandom -Djava.io.tmpdir=C:\sonarqube\temp -cp ./lib/common/*;./lib/server/*;C:\sonarqube\lib\jdbc\mysql\mysql-connector-java-5.1.42.jar org.sonar.server.app.WebServer C:\sonarqube\temp\sq-process7538971195426630397properties
Error occurred during initialization of VM
Could not reserve enough space for object heap
2017.11.09 14:17:56 INFO  app[][o.s.a.SchedulerImpl] Process [web] is stopped
2017.11.09 14:17:56 INFO  es[][o.s.p.StopWatcher] Stopping process
2017.11.09 14:17:56 INFO  es[][o.elasticsearch.node] [sonarqube] stopping ...
2017.11.09 14:17:56 INFO  es[][o.elasticsearch.node] [sonarqube] stopped
2017.11.09 14:17:56 INFO  es[][o.elasticsearch.node] [sonarqube] closing ...
2017.11.09 14:17:56 INFO  es[][o.elasticsearch.node] [sonarqube] closed
2017.11.09 14:17:56 INFO  app[][o.s.a.SchedulerImpl] Process [es] is stopped
2017.11.09 14:17:56 INFO  app[][o.s.a.SchedulerImpl] SonarQube is stopped

The process that is giving error is run with options -Xmx512m -Xms128m regardless of the --memory 2g flag. I'm running on 16GB Windows 10 machine with HyperV VM (MobyLinuxVM) set to 3084 MB RAM

Any help?

Answer 11 · 2017-11-09T11:36:07.000Z

Hello,

2GB is needed totally.
As you can see first there is:
.....\bin\java -Djava.awt.headless=true -Xmx1G -Xms256m -Xss256k ...
And the other part does this for web interface:
... -Xmx512m -Xms128m ..
as you mentioned

So, this container is windows one. It was tested in the Windows mode of docker on CE/EE.
Initially it was made for Windows Server, where there were no problems like this with memory.
However, the solution for Windows 10 is listed in the docs and this ticket shows that it solves the problem.

I don't know much about "MobyLinuxVM" - as this is windows container (not linux one). I mean, maybe I am wrong with this. Your docker should be in "windows containers" mode to run this container.
I mean, maybe --memory param is not getting to the target in mixed more?

Here is a good article about windows/linux containers via Hyper V, maybe it will help: https://stefanscherer.github.io/run-linux-and-windows-containers-on-windows-10/

If you find the problem with your environment, please share it here, I will update documentation.
From my side, I will try to find some windows 10 to try to reproduce.

Answer 12 · 2022-05-09T13:47:50.000Z

@dnikolayev, the fix described above does not work on my computer.

Using the following code:
mkdir sonarqube
mkdir sonarqube\mysql
mkdir sonarqube\extensions

docker stop sonar
docker rm sonar

docker run --name sonar -it -p 9000:9000 ^
-v %cd%\sonarqube\mysql:C:\MySQL\data ^
-v %cd%\sonarqube\extensions:C:\sonarqube\extensions ^
dnikolayev/sonarqube-mysql-windows ^
--memory 2g

I receive the error message mentioned above:
2022.05.09 14:42:02 INFO app[][o.s.a.SchedulerImpl] Waiting for Elasticsearch to be up and running Error occurred during initialization of VM Could not reserve enough space for object heap OpenJDK 64-Bit Server VM warning: Option UseConcMarkSweepGC was deprecated in version 9.0 and will likely be removed in a future release. 2022.05.09 14:42:02 WARN app[][o.s.a.p.AbstractProcessMonitor] Process exited with exit value [es]: 1 2022.05.09 14:42:02 INFO app[][o.s.a.SchedulerImpl] Process [es] is stopped 2022.05.09 14:42:02 INFO app[][o.s.a.SchedulerImpl] SonarQube is stopped