Bug 270855 - devel/sonarqube-community: does not start anymore
Summary: devel/sonarqube-community: does not start anymore
Status: New
Alias: None
Product: Ports & Packages
Classification: Unclassified
Component: Individual Port(s) (show other bugs)
Version: Latest
Hardware: Any Any
: --- Affects Only Me
Assignee: Alexander Leidinger
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2023-04-15 06:25 UTC by Matthias Fechner
Modified: 2023-06-21 15:55 UTC (History)
0 users

See Also:
bugzilla: maintainer-feedback? (netchild)


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Matthias Fechner freebsd_committer freebsd_triage 2023-04-15 06:25:52 UTC
I upgraded to version sonarqube-community-10.0.0.68432 and upgraded the configfile as mentioned in UPDATING 20230407:
sonar.search.javaAdditionalOpts=-server

But it does not start.

If I check the logs I do not find anything helpful.
```
2023.04.15 09:13:06 INFO  app[][o.s.a.AppFileSystem] Cleaning or creating temp directory /var/db/sonarqube/temp
2023.04.15 09:13:06 INFO  app[][o.s.a.es.EsSettings] Elasticsearch listening on [HTTP: 127.0.0.1:9005, TCP: 127.0.0.1:17246]
2023.04.15 09:13:06 INFO  app[][o.s.a.ProcessLauncherImpl] Launch process[ELASTICSEARCH] from [/usr/local/libexec/sonarqube/elasticsearch]: /usr/local/openjdk17/bin/java -Xms4m -Xmx64m -XX:+UseSerialGC -Dcli.name=server -Dcli.script=./bin/elasticsearch -Dcli.libs=lib/tools/server-cli -Des.path.home=/usr/local/libexec/sonarqube/elasticsearch -Des.path.conf=/var/db/sonarqube/temp/conf/es -Des.distribution.type=tar -cp /usr/local/libexec/sonarqube/elasticsearch/lib/*:/usr/local/libexec/sonarqube/elasticsearch/lib/cli-launcher/* org.elasticsearch.launcher.CliToolLauncher
2023.04.15 09:13:06 INFO  app[][o.s.a.SchedulerImpl] Waiting for Elasticsearch to be up and running
Failed to load native library:jansi-2.4.0-c836b5eaa762e049-libjansi.so. osinfo: FreeBSD/x86_64
java.lang.UnsatisfiedLinkError: /var/db/sonarqube/temp/jansi-2.4.0-c836b5eaa762e049-libjansi.so: /var/db/sonarqube/temp/jansi-2.4.0-c836b5eaa762e049-libjansi.so: mmap of data failed: Permission denied
bootstrap check failure [1] of [1]: system call filters failed to install; check the logs and fix your configuration
ERROR: Elasticsearch did not exit normally - check the logs at /var/log/sonarqube/sonarqube.log

ERROR: [1] bootstrap checks failed. You must address the points described in the following [1] lines before starting Elasticsearch.
2023.04.15 09:13:11 WARN  app[][o.s.a.p.AbstractManagedProcess] Process exited with exit value [ElasticSearch]: 78
2023.04.15 09:13:11 INFO  app[][o.s.a.SchedulerImpl] Process[ElasticSearch] is stopped
2023.04.15 09:13:11 ERROR app[][o.s.a.p.EsManagedProcess] Failed to check status
org.elasticsearch.ElasticsearchException: java.lang.InterruptedException
        at org.elasticsearch.client.RestHighLevelClient.performClientRequest(RestHighLevelClient.java:2695)
        at org.elasticsearch.client.RestHighLevelClient.internalPerformRequest(RestHighLevelClient.java:2171)
        at org.elasticsearch.client.RestHighLevelClient.performRequest(RestHighLevelClient.java:2137)
        at org.elasticsearch.client.RestHighLevelClient.performRequestAndParseEntity(RestHighLevelClient.java:2105)
        at org.elasticsearch.client.ClusterClient.health(ClusterClient.java:151)
        at org.sonar.application.es.EsConnectorImpl.getClusterHealthStatus(EsConnectorImpl.java:64)
        at org.sonar.application.process.EsManagedProcess.checkStatus(EsManagedProcess.java:92)
        at org.sonar.application.process.EsManagedProcess.checkOperational(EsManagedProcess.java:84)
        at org.sonar.application.process.EsManagedProcess.isOperational(EsManagedProcess.java:62)
        at org.sonar.application.process.ManagedProcessHandler.refreshState(ManagedProcessHandler.java:223)
        at org.sonar.application.process.ManagedProcessHandler$EventWatcher.run(ManagedProcessHandler.java:288)
Caused by: java.lang.InterruptedException: null
        at java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1048)
        at org.elasticsearch.common.util.concurrent.BaseFuture$Sync.get(BaseFuture.java:243)
        at org.elasticsearch.common.util.concurrent.BaseFuture.get(BaseFuture.java:75)
        at org.elasticsearch.client.RestHighLevelClient.performClientRequest(RestHighLevelClient.java:2692)
        ... 10 common frames omitted
2023.04.15 09:13:11 INFO  app[][o.s.a.SchedulerImpl] SonarQube is stopped
```

The sonar.log:
```
2023.04.15 09:13:06 INFO  app[][o.s.a.AppFileSystem] Cleaning or creating temp directory /var/db/sonarqube/temp
2023.04.15 09:13:06 INFO  app[][o.s.a.es.EsSettings] Elasticsearch listening on [HTTP: 127.0.0.1:9005, TCP: 127.0.0.1:17246]
2023.04.15 09:13:06 INFO  app[][o.s.a.ProcessLauncherImpl] Launch process[ELASTICSEARCH] from [/usr/local/libexec/sonarqube/elasticsearch]: /usr/local/openjdk17/bin/java -Xms4m -Xmx64m -XX:+UseSerialGC -Dcli.name=server -Dcli.script=./bin/elasticsearch -Dcli.libs=lib/tools/server-cli -Des.path.home=/usr/local/libexec/sonarqube/elasticsearch -Des.path.conf=/var/db/sonarqube/temp/conf/es -Des.distribution.type=tar -cp /usr/local/libexec/sonarqube/elasticsearch/lib/*:/usr/local/libexec/sonarqube/elasticsearch/lib/cli-launcher/* org.elasticsearch.launcher.CliToolLauncher
2023.04.15 09:13:06 INFO  app[][o.s.a.SchedulerImpl] Waiting for Elasticsearch to be up and running
2023.04.15 09:13:11 WARN  app[][o.s.a.p.AbstractManagedProcess] Process exited with exit value [ElasticSearch]: 78
2023.04.15 09:13:11 INFO  app[][o.s.a.SchedulerImpl] Process[ElasticSearch] is stopped
2023.04.15 09:13:11 ERROR app[][o.s.a.p.EsManagedProcess] Failed to check status
org.elasticsearch.ElasticsearchException: java.lang.InterruptedException
        at org.elasticsearch.client.RestHighLevelClient.performClientRequest(RestHighLevelClient.java:2695)
        at org.elasticsearch.client.RestHighLevelClient.internalPerformRequest(RestHighLevelClient.java:2171)
        at org.elasticsearch.client.RestHighLevelClient.performRequest(RestHighLevelClient.java:2137)
        at org.elasticsearch.client.RestHighLevelClient.performRequestAndParseEntity(RestHighLevelClient.java:2105)
        at org.elasticsearch.client.ClusterClient.health(ClusterClient.java:151)
        at org.sonar.application.es.EsConnectorImpl.getClusterHealthStatus(EsConnectorImpl.java:64)
        at org.sonar.application.process.EsManagedProcess.checkStatus(EsManagedProcess.java:92)
        at org.sonar.application.process.EsManagedProcess.checkOperational(EsManagedProcess.java:84)
        at org.sonar.application.process.EsManagedProcess.isOperational(EsManagedProcess.java:62)
        at org.sonar.application.process.ManagedProcessHandler.refreshState(ManagedProcessHandler.java:223)
        at org.sonar.application.process.ManagedProcessHandler$EventWatcher.run(ManagedProcessHandler.java:288)
Caused by: java.lang.InterruptedException: null
        at java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1048)
        at org.elasticsearch.common.util.concurrent.BaseFuture$Sync.get(BaseFuture.java:243)
        at org.elasticsearch.common.util.concurrent.BaseFuture.get(BaseFuture.java:75)
        at org.elasticsearch.client.RestHighLevelClient.performClientRequest(RestHighLevelClient.java:2692)
        ... 10 common frames omitted
2023.04.15 09:13:11 INFO  app[][o.s.a.SchedulerImpl] SonarQube is stopped
2023.04.15 09:13:12 INFO  app[][o.s.a.AppFileSystem] Cleaning or creating temp directory /var/db/sonarqube/temp
2023.04.15 09:13:12 INFO  app[][o.s.a.es.EsSettings] Elasticsearch listening on [HTTP: 127.0.0.1:9005, TCP: 127.0.0.1:17299]
2023.04.15 09:13:12 INFO  app[][o.s.a.ProcessLauncherImpl] Launch process[ELASTICSEARCH] from [/usr/local/libexec/sonarqube/elasticsearch]: /usr/local/openjdk17/bin/java -Xms4m -Xmx64m -XX:+UseSerialGC -Dcli.name=server -Dcli.script=./bin/elasticsearch -Dcli.libs=lib/tools/server-cli -Des.path.home=/usr/local/libexec/sonarqube/elasticsearch -Des.path.conf=/var/db/sonarqube/temp/conf/es -Des.distribution.type=tar -cp /usr/local/libexec/sonarqube/elasticsearch/lib/*:/usr/local/libexec/sonarqube/elasticsearch/lib/cli-launcher/* org.elasticsearch.launcher.CliToolLauncher
2023.04.15 09:13:12 INFO  app[][o.s.a.SchedulerImpl] Waiting for Elasticsearch to be up and running
2023.04.15 09:13:17 WARN  app[][o.s.a.p.AbstractManagedProcess] Process exited with exit value [ElasticSearch]: 78
2023.04.15 09:13:17 INFO  app[][o.s.a.SchedulerImpl] Process[ElasticSearch] is stopped
2023.04.15 09:13:17 INFO  app[][o.s.a.SchedulerImpl] SonarQube is stopped
```
es.log:
```
2023.04.15 09:13:14 WARN  es[][o.e.b.Natives] unable to load JNA native support library, native methods will be disabled.
java.lang.UnsatisfiedLinkError: /var/db/sonarqube/temp/jna2650993593490345002.tmp: /var/db/sonarqube/temp/jna2650993593490345002.tmp: mmap of data failed: Permission denied
        at jdk.internal.loader.NativeLibraries.load(Native Method) ~[?:?]
        at jdk.internal.loader.NativeLibraries$NativeLibraryImpl.open(NativeLibraries.java:388) ~[?:?]
        at jdk.internal.loader.NativeLibraries.loadLibrary(NativeLibraries.java:232) ~[?:?]
        at jdk.internal.loader.NativeLibraries.loadLibrary(NativeLibraries.java:174) ~[?:?]
        at java.lang.ClassLoader.loadLibrary(ClassLoader.java:2389) ~[?:?]
        at java.lang.Runtime.load0(Runtime.java:755) ~[?:?]
        at java.lang.System.load(System.java:1953) ~[?:?]
        at com.sun.jna.Native.loadNativeDispatchLibraryFromClasspath(Native.java:1045) ~[jna-5.10.0.jar:?]
        at com.sun.jna.Native.loadNativeDispatchLibrary(Native.java:1015) ~[jna-5.10.0.jar:?]
        at com.sun.jna.Native.<clinit>(Native.java:221) ~[jna-5.10.0.jar:?]
        at java.lang.Class.forName0(Native Method) ~[?:?]
        at java.lang.Class.forName(Class.java:375) ~[?:?]
        at org.elasticsearch.bootstrap.Natives.<clinit>(Natives.java:34) ~[elasticsearch-8.6.1.jar:?]
        at org.elasticsearch.bootstrap.Elasticsearch.initializeNatives(Elasticsearch.java:259) ~[elasticsearch-8.6.1.jar:?]
        at org.elasticsearch.bootstrap.Elasticsearch.initPhase2(Elasticsearch.java:166) ~[elasticsearch-8.6.1.jar:?]
        at org.elasticsearch.bootstrap.Elasticsearch.main(Elasticsearch.java:66) ~[elasticsearch-8.6.1.jar:?]
2023.04.15 09:13:14 WARN  es[][o.e.b.Natives] cannot check if running as root because JNA is not available
2023.04.15 09:13:14 WARN  es[][o.e.b.Natives] cannot install system call filter because JNA is not available
2023.04.15 09:13:14 WARN  es[][o.e.b.Natives] cannot register console handler because JNA is not available
2023.04.15 09:13:14 WARN  es[][o.e.b.Natives] cannot getrlimit RLIMIT_NPROC because JNA is not available
2023.04.15 09:13:14 WARN  es[][o.e.b.Natives] cannot getrlimit RLIMIT_AS because JNA is not available
2023.04.15 09:13:14 WARN  es[][o.e.b.Natives] cannot getrlimit RLIMIT_FSIZE because JNA is not available
2023.04.15 09:13:14 WARN  es[][o.e.c.f.FileSystemNatives] unable to load JNA native support library, FileSystemNatives methods will be disabled.
java.lang.NoClassDefFoundError: Could not initialize class com.sun.jna.Native
        at java.lang.Class.forName0(Native Method) ~[?:?]
        at java.lang.Class.forName(Class.java:375) ~[?:?]
        at org.elasticsearch.common.filesystem.FileSystemNatives.loadJnaProvider(FileSystemNatives.java:37) ~[elasticsearch-8.6.1.jar:?]
        at org.elasticsearch.common.filesystem.FileSystemNatives.<clinit>(FileSystemNatives.java:31) ~[elasticsearch-8.6.1.jar:?]
        at org.elasticsearch.bootstrap.Elasticsearch.initializeNatives(Elasticsearch.java:311) ~[elasticsearch-8.6.1.jar:?]
        at org.elasticsearch.bootstrap.Elasticsearch.initPhase2(Elasticsearch.java:166) ~[elasticsearch-8.6.1.jar:?]
        at org.elasticsearch.bootstrap.Elasticsearch.main(Elasticsearch.java:66) ~[elasticsearch-8.6.1.jar:?]
2023.04.15 09:13:14 INFO  es[][o.e.n.Node] version[8.6.1], pid[46098], build[tar/180c9830da956993e59e2cd70eb32b5e383ea42c/2023-01-24T21:35:11.506992272Z], OS[FreeBSD/13.1-RELEASE-p6/amd64], JVM[OpenJDK BSD Porting Team/OpenJDK 64-Bit Server VM/17.0.6/17.0.6+10-1]
2023.04.15 09:13:14 INFO  es[][o.e.n.Node] JVM home [/usr/local/openjdk17], using bundled JDK [false]
2023.04.15 09:13:14 INFO  es[][o.e.n.Node] JVM arguments [-Des.networkaddress.cache.ttl=60, -Des.networkaddress.cache.negative.ttl=10, -Djava.security.manager=allow, -XX:+AlwaysPreTouch, -Xss1m, -Djava.awt.headless=true, -Dfile.encoding=UTF-8, -Djna.nosys=true, -XX:-OmitStackTraceInFastThrow, -Dio.netty.noUnsafe=true, -Dio.netty.noKeySetOptimization=true, -Dio.netty.recycler.maxCapacityPerThread=0, -Dlog4j.shutdownHookEnabled=false, -Dlog4j2.disable.jmx=true, -Dlog4j2.formatMsgNoLookups=true, -Djava.locale.providers=SPI,COMPAT, --add-opens=java.base/java.io=ALL-UNNAMED, -XX:+UseG1GC, -Djava.io.tmpdir=/var/db/sonarqube/temp, -XX:ErrorFile=/var/log/sonarqube/es_hs_err_pid%p.log, -Xlog:disable, -Des.networkaddress.cache.ttl=60, -Des.networkaddress.cache.negative.ttl=10, -XX:+AlwaysPreTouch, -Xss1m, -Djava.awt.headless=true, -Dfile.encoding=UTF-8, -Djna.nosys=true, -Djna.tmpdir=/var/db/sonarqube/temp, -XX:-OmitStackTraceInFastThrow, -Dio.netty.noUnsafe=true, -Dio.netty.noKeySetOptimization=true, -Dio.netty.recycler.maxCapacityPerThread=0, -Dio.netty.allocator.numDirectArenas=0, -Dlog4j.shutdownHookEnabled=false, -Dlog4j2.disable.jmx=true, -Dlog4j2.formatMsgNoLookups=true, -Djava.locale.providers=COMPAT, -Dcom.redhat.fips=false, -Des.enforce.bootstrap.checks=true, -Xmx512m, -Xms512m, -XX:MaxDirectMemorySize=256m, -XX:+HeapDumpOnOutOfMemoryError, -XX:G1HeapRegionSize=4m, -XX:InitiatingHeapOccupancyPercent=30, -XX:G1ReservePercent=15, -Des.distribution.type=tar, --module-path=/usr/local/libexec/sonarqube/elasticsearch/lib, --add-modules=jdk.net, -Djdk.module.main=org.elasticsearch.server]
2023.04.15 09:13:15 INFO  es[][o.e.p.PluginsService] loaded module [aggregations]
2023.04.15 09:13:15 INFO  es[][o.e.p.PluginsService] loaded module [analysis-common]
2023.04.15 09:13:15 INFO  es[][o.e.p.PluginsService] loaded module [apm]
2023.04.15 09:13:15 INFO  es[][o.e.p.PluginsService] loaded module [lang-painless]
2023.04.15 09:13:15 INFO  es[][o.e.p.PluginsService] loaded module [old-lucene-versions]
2023.04.15 09:13:15 INFO  es[][o.e.p.PluginsService] loaded module [parent-join]
2023.04.15 09:13:15 INFO  es[][o.e.p.PluginsService] loaded module [reindex]
2023.04.15 09:13:15 INFO  es[][o.e.p.PluginsService] loaded module [transport-netty4]
2023.04.15 09:13:15 INFO  es[][o.e.p.PluginsService] loaded module [x-pack-aggregate-metric]
2023.04.15 09:13:15 INFO  es[][o.e.p.PluginsService] loaded module [x-pack-core]
2023.04.15 09:13:15 INFO  es[][o.e.p.PluginsService] loaded module [x-pack-security]
2023.04.15 09:13:15 INFO  es[][o.e.p.PluginsService] no plugins loaded
2023.04.15 09:13:16 INFO  es[][o.e.e.NodeEnvironment] using [1] data paths, mounts [[/var/db (zroot/var/db)]], net usable_space [8tb], net total_space [8tb], types [zfs]
2023.04.15 09:13:16 INFO  es[][o.e.e.NodeEnvironment] heap size [512mb], compressed ordinary object pointers [true]
2023.04.15 09:13:16 INFO  es[][o.e.n.Node] node name [sonarqube], node ID [Em3uATWYQEiZY_oGgEvLvA], cluster name [sonarqube], roles [data_frozen, ingest, data_cold, data, remote_cluster_client, master, data_warm, data_content, transform, data_hot, ml]
2023.04.15 09:13:16 INFO  es[][o.e.x.s.Security] Security is disabled
2023.04.15 09:13:16 INFO  es[][o.e.t.n.NettyAllocator] creating NettyAllocator with the following configs: [name=unpooled, suggested_max_allocation_size=1mb, factors={es.unsafe.use_unpooled_allocator=null, g1gc_enabled=true, g1gc_region_size=4mb, heap_size=512mb}]
2023.04.15 09:13:16 INFO  es[][o.e.i.r.RecoverySettings] using rate limit [40mb] with [default=40mb, read=0b, write=0b, max=0b]
2023.04.15 09:13:16 INFO  es[][o.e.d.DiscoveryModule] using discovery type [single-node] and seed hosts providers [settings]
2023.04.15 09:13:17 INFO  es[][o.e.n.Node] initialized
2023.04.15 09:13:17 INFO  es[][o.e.n.Node] starting ...
2023.04.15 09:13:17 INFO  es[][o.e.t.TransportService] publish_address {127.0.0.1:17299}, bound_addresses {127.0.0.1:17299}
2023.04.15 09:13:17 INFO  es[][o.e.b.BootstrapChecks] explicitly enforcing bootstrap checks
2023.04.15 09:13:17 INFO  es[][o.e.n.Node] stopping ...
2023.04.15 09:13:17 INFO  es[][o.e.n.Node] stopped
2023.04.15 09:13:17 INFO  es[][o.e.n.Node] closing ...
2023.04.15 09:13:17 INFO  es[][o.e.n.Node] closed
```

I checked also the permission of the folder and it locks fine:
```
root@server:/var/log/sonarqube # ls -las /var/db/sonarqube/
total 20
 1 drwxr-xr-x   4 sonarqube  sonarqube   4 May  5  2020 .
17 drwxr-xr-x  44 root       wheel      59 Apr  6 21:16 ..
 1 drwxr-xr-x   4 sonarqube  sonarqube   4 Apr 15 08:18 data
 1 drwxr-xr-x   3 sonarqube  sonarqube   4 Apr 15 09:13 temp

root@server:/var/log/sonarqube # ls -las /var/db/sonarqube/temp
total 12
1 drwxr-xr-x  3 sonarqube  sonarqube     4 Apr 15 09:13 .
1 drwxr-xr-x  4 sonarqube  sonarqube     4 May  5  2020 ..
1 drwxr-xr-x  3 sonarqube  sonarqube     3 Apr 15 09:13 conf
9 -rw-r--r--  1 sonarqube  sonarqube  2565 Apr 15 09:13 sharedmemory

```

Do you have an idea what can cause this problem?
Comment 1 Alexander Leidinger freebsd_committer freebsd_triage 2023-04-15 18:50:35 UTC
MAke a diff of sonar.poperties with the sample file. For me the differences are sonar.jdbc.username, sonar.jdbc.password, sonar.jdbc.url (all off them only if you use a jdbc DB instead of the default H2 DB), sonar.auth.jwtBase64Hs256Secret, sonar.secretKeyPath, sonar.ce.javaAdditionalOpts,sonar.search.javaAdditionalOpts  (for both I use -server too, but works without).

Try to reduce the amount of diffs to see if it helps. You can also increase the log level to DEBUG (sonar.log.level or sonar.log.level.*) and check if you see more.
Comment 2 Matthias Fechner freebsd_committer freebsd_triage 2023-04-17 04:24:06 UTC
I modified the following options (I replaced content with <removed>):
```
sonar.jdbc.username=<removed>
sonar.jdbc.password=<removed>
sonar.jdbc.url=jdbc:postgresql://localhost/sonarqube
sonar.web.port=10000
sonar.auth.jwtBase64Hs256Secret=<removed>
sonar.search.port=9005
```

I needed to change ports as they are already used be other services.

I will try next to increase log level.
Comment 3 Matthias Fechner freebsd_committer freebsd_triage 2023-06-19 10:02:35 UTC
sry for the late response.
I increased now the logging to DEBUG and see some error messages (in es.log) like:

```
2023.06.19 11:00:06 INFO  es[][o.e.x.s.Security] Security is disabled
2023.06.19 11:00:06 DEBUG es[][o.e.a.ActionModule] Using REST interceptor from plugin org.elasticsearch.xpack.security.Security
2023.06.19 11:00:06 DEBUG es[][i.n.u.ResourceLeakDetector] -Dio.netty.leakDetection.level: simple
2023.06.19 11:00:06 DEBUG es[][i.n.u.ResourceLeakDetector] -Dio.netty.leakDetection.targetRecords: 4
2023.06.19 11:00:06 INFO  es[][o.e.t.n.NettyAllocator] creating NettyAllocator with the following configs: [name=unpooled, suggested_max_allocation_size=1mb, factors={es.unsafe.use_unpooled_allocator=null, g1gc_enabled=true, g1gc_region_size=4mb, heap_size=512mb}]
2023.06.19 11:00:06 DEBUG es[][o.e.h.n.Netty4HttpServerTransport] using max_chunk_size[8kb], max_header_size[16kb], max_initial_line_length[4kb], max_content_length[100mb], receive_predictor[64kb], max_composite_buffer_components[69905], pipelining_max_events[10000]
2023.06.19 11:00:06 INFO  es[][o.e.i.r.RecoverySettings] using rate limit [40mb] with [default=40mb, read=0b, write=0b, max=0b]
2023.06.19 11:00:06 DEBUG es[][o.e.d.SettingsBasedSeedHostsProvider] using initial hosts [127.0.0.1:42224]
2023.06.19 11:00:06 INFO  es[][o.e.d.DiscoveryModule] using discovery type [single-node] and seed hosts providers [settings]
2023.06.19 11:00:06 DEBUG es[][o.e.n.Node] initializing HTTP handlers ...
2023.06.19 11:00:06 INFO  es[][o.e.n.Node] initialized
2023.06.19 11:00:06 INFO  es[][o.e.n.Node] starting ...
2023.06.19 11:00:06 DEBUG es[][o.e.l.LicenseService] initializing license state
2023.06.19 11:00:06 DEBUG es[][i.n.c.MultithreadEventLoopGroup] -Dio.netty.eventLoopThreads: 32
2023.06.19 11:00:06 DEBUG es[][i.n.u.i.InternalThreadLocalMap] -Dio.netty.threadLocalMap.stringBuilder.initialSize: 1024
2023.06.19 11:00:06 DEBUG es[][i.n.u.i.InternalThreadLocalMap] -Dio.netty.threadLocalMap.stringBuilder.maxSize: 4096
2023.06.19 11:00:06 DEBUG es[][i.n.c.n.NioEventLoop] -Dio.netty.noKeySetOptimization: true
2023.06.19 11:00:06 DEBUG es[][i.n.c.n.NioEventLoop] -Dio.netty.selectorAutoRebuildThreshold: 512
2023.06.19 11:00:06 DEBUG es[][i.n.u.i.PlatformDependent] org.jctools-core.MpscChunkedArrayQueue: unavailable
2023.06.19 11:00:06 DEBUG es[][o.e.t.n.Netty4Transport] using profile[default], worker_count[16], port[42224], bind_host[[127.0.0.1]], publish_host[[127.0.0.1]], receive_predictor[64kb->64kb]
2023.06.19 11:00:06 DEBUG es[][o.e.t.TcpTransport] binding server bootstrap to: [127.0.0.1]
2023.06.19 11:00:06 DEBUG es[][i.n.c.DefaultChannelId] Could not invoke ProcessHandle.current().pid();
java.lang.reflect.InvocationTargetException: null
        at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
        at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77) ~[?:?]
        at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
        at java.lang.reflect.Method.invoke(Method.java:568) ~[?:?]
        at io.netty.channel.DefaultChannelId.processHandlePid(DefaultChannelId.java:116) ~[?:?]
        at io.netty.channel.DefaultChannelId.defaultProcessId(DefaultChannelId.java:178) ~[?:?]
        at io.netty.channel.DefaultChannelId.<clinit>(DefaultChannelId.java:77) ~[?:?]
        at io.netty.channel.AbstractChannel.newId(AbstractChannel.java:113) ~[?:?]
        at io.netty.channel.AbstractChannel.<init>(AbstractChannel.java:73) ~[?:?]
        at io.netty.channel.nio.AbstractNioChannel.<init>(AbstractNioChannel.java:80) ~[?:?]
        at io.netty.channel.nio.AbstractNioMessageChannel.<init>(AbstractNioMessageChannel.java:42) ~[?:?]
        at io.netty.channel.socket.nio.NioServerSocketChannel.<init>(NioServerSocketChannel.java:96) ~[?:?]
        at io.netty.channel.socket.nio.NioServerSocketChannel.<init>(NioServerSocketChannel.java:89) ~[?:?]
        at io.netty.channel.socket.nio.NioServerSocketChannel.<init>(NioServerSocketChannel.java:82) ~[?:?]
        at io.netty.channel.socket.nio.NioServerSocketChannel.<init>(NioServerSocketChannel.java:75) ~[?:?]
        at org.elasticsearch.transport.netty4.CopyBytesServerSocketChannel.<init>(CopyBytesServerSocketChannel.java:39) ~[?:?]
        at jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) ~[?:?]
        at jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:77) ~[?:?]
        at jdk.internal.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) ~[?:?]
        at java.lang.reflect.Constructor.newInstanceWithCaller(Constructor.java:499) ~[?:?]
        at java.lang.reflect.Constructor.newInstance(Constructor.java:480) ~[?:?]
        at io.netty.channel.ReflectiveChannelFactory.newChannel(ReflectiveChannelFactory.java:44) ~[?:?]
        at io.netty.bootstrap.AbstractBootstrap.initAndRegister(AbstractBootstrap.java:310) ~[?:?]
        at io.netty.bootstrap.AbstractBootstrap.doBind(AbstractBootstrap.java:272) ~[?:?]
        at io.netty.bootstrap.AbstractBootstrap.bind(AbstractBootstrap.java:268) ~[?:?]
        at org.elasticsearch.transport.netty4.Netty4Transport.bind(Netty4Transport.java:299) ~[?:?]
        at org.elasticsearch.transport.netty4.Netty4Transport.bind(Netty4Transport.java:63) ~[?:?]
        at org.elasticsearch.transport.TcpTransport.lambda$bindToPort$5(TcpTransport.java:493) ~[elasticsearch-8.6.1.jar:?]
        at org.elasticsearch.common.transport.PortsRange.iterate(PortsRange.java:44) ~[elasticsearch-8.6.1.jar:?]
        at org.elasticsearch.transport.TcpTransport.bindToPort(TcpTransport.java:491) ~[elasticsearch-8.6.1.jar:?]
        at org.elasticsearch.transport.TcpTransport.bindServer(TcpTransport.java:466) ~[elasticsearch-8.6.1.jar:?]
        at org.elasticsearch.transport.netty4.Netty4Transport.doStart(Netty4Transport.java:142) ~[?:?]
        at org.elasticsearch.common.component.AbstractLifecycleComponent.start(AbstractLifecycleComponent.java:43) ~[elasticsearch-8.6.1.jar:?]
        at org.elasticsearch.transport.TransportService.doStart(TransportService.java:311) ~[elasticsearch-8.6.1.jar:?]
        at org.elasticsearch.common.component.AbstractLifecycleComponent.start(AbstractLifecycleComponent.java:43) ~[elasticsearch-8.6.1.jar:?]
        at org.elasticsearch.node.Node.start(Node.java:1343) ~[elasticsearch-8.6.1.jar:?]
        at org.elasticsearch.bootstrap.Elasticsearch.start(Elasticsearch.java:436) ~[elasticsearch-8.6.1.jar:?]
        at org.elasticsearch.bootstrap.Elasticsearch.initPhase3(Elasticsearch.java:229) ~[elasticsearch-8.6.1.jar:?]
        at org.elasticsearch.bootstrap.Elasticsearch.main(Elasticsearch.java:67) ~[elasticsearch-8.6.1.jar:?]
Caused by: java.security.AccessControlException: access denied ("java.lang.RuntimePermission" "manageProcess")
        at java.security.AccessControlContext.checkPermission(AccessControlContext.java:485) ~[?:?]
        at java.security.AccessController.checkPermission(AccessController.java:1068) ~[?:?]
        at java.lang.SecurityManager.checkPermission(SecurityManager.java:416) ~[?:?]
        at java.lang.ProcessHandleImpl.current(ProcessHandleImpl.java:292) ~[?:?]
        at java.lang.ProcessHandle.current(ProcessHandle.java:136) ~[?:?]
        ... 39 more
2023.06.19 11:00:06 DEBUG es[][i.n.c.DefaultChannelId] -Dio.netty.processId: 42631 (auto-detected)
2023.06.19 11:00:06 DEBUG es[][i.n.u.NetUtil] -Djava.net.preferIPv4Stack: true
2023.06.19 11:00:06 DEBUG es[][i.n.u.NetUtil] -Djava.net.preferIPv6Addresses: false
2023.06.19 11:00:06 DEBUG es[][i.n.u.NetUtilInitializations] Loopback interface: lo0 (lo0, 127.0.0.1)
2023.06.19 11:00:06 DEBUG es[][i.n.u.NetUtil] Failed to get SOMAXCONN from sysctl and file /proc/sys/net/core/somaxconn. Default: 128
```

Is this maybe related to java 17:
2023.06.19 11:00:03 INFO  es[][o.e.n.Node] version[8.6.1], pid[42631], build[tar/180c9830da956993e59e2cd70eb32b5e383ea42c/2023-01-24T21:35:11.506992272Z], OS[FreeBSD/13.2-RELEASE/amd64], JVM[OpenJDK BSD Porting Team/OpenJDK 64-Bit Server VM/17.0.7/17.0.7+7-1]
Comment 4 Alexander Leidinger freebsd_committer freebsd_triage 2023-06-19 17:27:59 UTC
I use openjdk 17 myself.

I've read the logs again, even the initial ones. The JNA error is normal (in the past I had JNA working (traces are in the makefile of the port), but with openjdk 17 I seem to overlook something and it fails... or failed when I was switching a while back).

What I don't have here is your error with jansi:
Failed to load native library:jansi-2.4.0-c836b5eaa762e049-libjansi.so. osinfo: FreeBSD/x86_64
java.lang.UnsatisfiedLinkError: /var/db/sonarqube/temp/jansi-2.4.0-c836b5eaa762e049-libjansi.so: /var/db/sonarqube/temp/jansi-2.4.0-c836b5eaa762e049-libjansi.so: mmap of data failed: Permission denied

In /var/db/sonarqube/temp I have jansi-2.4.0-ed33148843ede28b-libjansi.so (15308 bytes), so a different one than you have listed. The plist lists it as a .jar in a different place, not a .so. The jar contains a native FreeBSD libjansi ( :-) ). Maybe it is extracted from there and hashed. So the difference in the checksum/hash looks suspicious. The lib is dates from the last restart, so it will probably not show up when it is not running.

What are the permissions of the temp directory? Mine are sonarqube:sonarqube rwxr-xr-x.
Comment 5 Matthias Fechner freebsd_committer freebsd_triage 2023-06-21 15:29:20 UTC
(In reply to Alexander Leidinger from comment #4)
Permission of temp dir (see also first post):
 ls -las /var/db/sonarqube/temp/
total 12
1 drwxr-xr-x  3 sonarqube  sonarqube     4 Jun 19 11:00 .
1 drwxr-xr-x  4 sonarqube  sonarqube     4 May  5  2020 ..
1 drwxr-xr-x  3 sonarqube  sonarqube     3 Jun 19 11:00 conf
9 -rw-r--r--  1 sonarqube  sonarqube  2565 Jun 19 11:00 sharedmemory

I found the following files have jansi in the filename on my system:
find / -name "*jansi*"
/usr/local/share/intellij-ultimate/plugins/maven/lib/maven3/lib/jansi-native
/usr/local/share/intellij-ultimate/plugins/maven/lib/maven3/lib/jansi-native/freebsd64/libjansi.so
/usr/local/share/intellij-ultimate/plugins/maven/lib/maven3/lib/jansi-native/freebsd32/libjansi.so
/usr/local/share/intellij-ultimate/plugins/maven/lib/maven3/lib/jansi.license
/usr/local/share/intellij-ultimate/plugins/maven/lib/maven3/lib/jansi-1.17.1.jar
/usr/local/share/gradle/lib/jansi-1.18.jar
/usr/local/share/java/maven/lib/jansi.license
/usr/local/share/java/maven/lib/jansi-2.4.0.jar
/usr/local/libexec/sonarqube/elasticsearch/lib/tools/ansi-console/jansi-2.4.0.jar

The file in the sonarqube dir:
/usr/local/libexec/sonarqube/elasticsearch/lib/tools/ansi-console/jansi-2.4.0.jar:
441 -rw-r--r--  1 root  wheel  221009 Jan 24 02:46 jansi-2.4.0.jar
sha256sum jansi-2.4.0.jar
6cd91991323dd7b2fb28ca93d7ac12af5a86a2f53279e2b35827b30313fd0b9f  jansi-2.4.0.jar
But it is listed in the plist, so the file should be ok:
pkg check --checksums sonarqube-community-10.0.0.68432_3
Checking sonarqube-community-10.0.0.68432_3: 100%

I also tried to deinstall sonarqube-community and checked what is left and it was only the config file and the directory extensions/plugins.

I create the sonarqube package using an own poudriere which has the following settings modified, maybe this could be a reason.
/usr/local/etc/poudriere.d/make.conf
DEFAULT_VERSIONS=mysql=10.11m ssl=openssl samba=4.16 java=17

So only the java or ssl change can be related as sonarqube use postgresql it should not be related to the mariadb.

The full log of the last build just now is:
https://pkg.fechner.net/data/132amd64-default/2023-06-21_10h06m32s/logs/sonarqube-community-10.0.0.68432_3.log

I have the following in /etc/fstab, maybe I should remove linprocfs as it seems to be related to oracle jdk but I have openjdk17 installed:
linprocfs               /compat/linux/proc      linprocfs       rw      0       0
# Required for openjdk
fdesc                                   /dev/fd         fdescfs rw              0       0
proc                                    /proc           procfs  rw              0       0

pkg info |grep jdk
openjdk17-17.0.7+7.1           Java Development Kit 17

I will try next to install my poudriere sonarqube package in a VM to see if that works or if it is just related to the upgrade.
Comment 6 Matthias Fechner freebsd_committer freebsd_triage 2023-06-21 15:55:31 UTC
I tested it now on a VM I also use to test the gitlab package.
I did the following steps:
pkg install sonarqube-community postgresql13-server
sysrc postgresql_enable=YES
service postgresql initdb
service postgresql start

echo "fdesc   /dev/fd         fdescfs         rw      0       0" >> /etc/fstab
echo "proc    /proc           procfs          rw      0       0" >> /etc/fstab

mount -t fdescfs fdesc /dev/fd
mount -t procfs proc /proc

psql -U postgres -c "CREATE USER sonarqube with password '<password>'"
psql -U postgres -c "create database sonarqube with owner sonarqube encoding 'UTF8'"

echo -n "type_what_you_want" | openssl dgst -sha256 -hmac "key" -binary | base64

Edit /usr/local/libexec/sonarqube/conf/sonar.properties:
sonar.jdbc.username=sonarqube
sonar.jdbc.password=<password>
sonar.jdbc.url=jdbc:postgresql://localhost/sonarqube
sonar.auth.jwtBase64Hs256Secret=<Your Random String Generated Above Here>

sysrc sonarqube_enable="YES"
service sonarqube start

Exactly the same problem like on my other server:
==> daemon.log <==
2023.06.21 17:51:40 INFO  app[][o.s.a.AppFileSystem] Cleaning or creating temp directory /var/db/sonarqube/temp
2023.06.21 17:51:40 INFO  app[][o.s.a.es.EsSettings] Elasticsearch listening on [HTTP: 127.0.0.1:9001, TCP: 127.0.0.1:28742]
2023.06.21 17:51:40 INFO  app[][o.s.a.ProcessLauncherImpl] Launch process[ELASTICSEARCH] from [/usr/local/libexec/sonarqube/elasticsearch]: /usr/local/openjdk17/bin/java -Xms4m -Xmx64m -XX:+UseSe                                                                                                                          rialGC -Dcli.name=server -Dcli.script=./bin/elasticsearch -Dcli.libs=lib/tools/server-cli -Des.path.home=/usr/local/libexec/sonarqube/elasticsearch -Des.path.conf=/var/db/sonarqube/temp/conf/es -                                                                                                                          Des.distribution.type=tar -cp /usr/local/libexec/sonarqube/elasticsearch/lib/*:/usr/local/libexec/sonarqube/elasticsearch/lib/cli-launcher/* org.elasticsearch.launcher.CliToolLauncher
2023.06.21 17:51:40 INFO  app[][o.s.a.SchedulerImpl] Waiting for Elasticsearch to be up and running

==> sonar.log <==
2023.06.21 17:51:40 INFO  app[][o.s.a.AppFileSystem] Cleaning or creating temp directory /var/db/sonarqube/temp
2023.06.21 17:51:40 INFO  app[][o.s.a.es.EsSettings] Elasticsearch listening on [HTTP: 127.0.0.1:9001, TCP: 127.0.0.1:28742]
2023.06.21 17:51:40 INFO  app[][o.s.a.ProcessLauncherImpl] Launch process[ELASTICSEARCH] from [/usr/local/libexec/sonarqube/elasticsearch]: /usr/local/openjdk17/bin/java -Xms4m -Xmx64m -XX:+UseSe                                                                                                                          rialGC -Dcli.name=server -Dcli.script=./bin/elasticsearch -Dcli.libs=lib/tools/server-cli -Des.path.home=/usr/local/libexec/sonarqube/elasticsearch -Des.path.conf=/var/db/sonarqube/temp/conf/es -                                                                                                                          Des.distribution.type=tar -cp /usr/local/libexec/sonarqube/elasticsearch/lib/*:/usr/local/libexec/sonarqube/elasticsearch/lib/cli-launcher/* org.elasticsearch.launcher.CliToolLauncher
2023.06.21 17:51:40 INFO  app[][o.s.a.SchedulerImpl] Waiting for Elasticsearch to be up and running

==> daemon.log <==
Failed to load native library:jansi-2.4.0-a2a5221888e33038-libjansi.so. osinfo: FreeBSD/x86_64
java.lang.UnsatisfiedLinkError: /var/db/sonarqube/temp/jansi-2.4.0-a2a5221888e33038-libjansi.so: /var/db/sonarqube/temp/jansi-2.4.0-a2a5221888e33038-libjansi.so: mmap of data failed: Permission d                                                                                                                          enied
bootstrap check failure [1] of [1]: system call filters failed to install; check the logs and fix your configuration
ERROR: Elasticsearch did not exit normally - check the logs at /var/log/sonarqube/sonarqube.log

ERROR: [1] bootstrap checks failed. You must address the points described in the following [1] lines before starting Elasticsearch.
2023.06.21 17:51:52 WARN  app[][o.s.a.p.AbstractManagedProcess] Process exited with exit value [ElasticSearch]: 78
2023.06.21 17:51:52 INFO  app[][o.s.a.SchedulerImpl] Process[ElasticSearch] is stopped

==> sonar.log <==
2023.06.21 17:51:52 WARN  app[][o.s.a.p.AbstractManagedProcess] Process exited with exit value [ElasticSearch]: 78
2023.06.21 17:51:52 INFO  app[][o.s.a.SchedulerImpl] Process[ElasticSearch] is stopped

==> daemon.log <==
2023.06.21 17:51:52 INFO  app[][o.s.a.SchedulerImpl] SonarQube is stopped

==> sonar.log <==
2023.06.21 17:51:52 INFO  app[][o.s.a.SchedulerImpl] SonarQube is stopped

==> daemon.log <==
2023.06.21 17:51:54 INFO  app[][o.s.a.AppFileSystem] Cleaning or creating temp directory /var/db/sonarqube/temp

==> sonar.log <==
2023.06.21 17:51:54 INFO  app[][o.s.a.AppFileSystem] Cleaning or creating temp directory /var/db/sonarqube/temp

==> daemon.log <==
2023.06.21 17:51:54 INFO  app[][o.s.a.es.EsSettings] Elasticsearch listening on [HTTP: 127.0.0.1:9001, TCP: 127.0.0.1:54211]

==> sonar.log <==
2023.06.21 17:51:54 INFO  app[][o.s.a.es.EsSettings] Elasticsearch listening on [HTTP: 127.0.0.1:9001, TCP: 127.0.0.1:54211]

==> daemon.log <==
2023.06.21 17:51:54 INFO  app[][o.s.a.ProcessLauncherImpl] Launch process[ELASTICSEARCH] from [/usr/local/libexec/sonarqube/elasticsearch]: /usr/local/openjdk17/bin/java -Xms4m -Xmx64m -XX:+UseSerialGC -Dcli.name=server -Dcli.script=./bin/elasticsearch -Dcli.libs=lib/tools/server-cli -Des.path.home=/usr/local/libexec/sonarqube/elasticsearch -Des.path.conf=/var/db/sonarqube/temp/conf/es -Des.distribution.type=tar -cp /usr/local/libexec/sonarqube/elasticsearch/lib/*:/usr/local/libexec/sonarqube/elasticsearch/lib/cli-launcher/* org.elasticsearch.launcher.CliToolLauncher

==> sonar.log <==
2023.06.21 17:51:54 INFO  app[][o.s.a.ProcessLauncherImpl] Launch process[ELASTICSEARCH] from [/usr/local/libexec/sonarqube/elasticsearch]: /usr/local/openjdk17/bin/java -Xms4m -Xmx64m -XX:+UseSerialGC -Dcli.name=server -Dcli.script=./bin/elasticsearch -Dcli.libs=lib/tools/server-cli -Des.path.home=/usr/local/libexec/sonarqube/elasticsearch -Des.path.conf=/var/db/sonarqube/temp/conf/es -Des.distribution.type=tar -cp /usr/local/libexec/sonarqube/elasticsearch/lib/*:/usr/local/libexec/sonarqube/elasticsearch/lib/cli-launcher/* org.elasticsearch.launcher.CliToolLauncher
2023.06.21 17:51:54 INFO  app[][o.s.a.SchedulerImpl] Waiting for Elasticsearch to be up and running

==> daemon.log <==
2023.06.21 17:51:54 INFO  app[][o.s.a.SchedulerImpl] Waiting for Elasticsearch to be up and running
Failed to load native library:jansi-2.4.0-152a7fff020da306-libjansi.so. osinfo: FreeBSD/x86_64
java.lang.UnsatisfiedLinkError: /var/db/sonarqube/temp/jansi-2.4.0-152a7fff020da306-libjansi.so: /var/db/sonarqube/temp/jansi-2.4.0-152a7fff020da306-libjansi.so: mmap of data failed: Permission denied
bootstrap check failure [1] of [1]: system call filters failed to install; check the logs and fix your configuration
ERROR: Elasticsearch did not exit normally - check the logs at /var/log/sonarqube/sonarqube.log

ERROR: [1] bootstrap checks failed. You must address the points described in the following [1] lines before starting Elasticsearch.
2023.06.21 17:52:00 WARN  app[][o.s.a.p.AbstractManagedProcess] Process exited with exit value [ElasticSearch]: 78

==> sonar.log <==
2023.06.21 17:52:00 WARN  app[][o.s.a.p.AbstractManagedProcess] Process exited with exit value [ElasticSearch]: 78
2023.06.21 17:52:00 INFO  app[][o.s.a.SchedulerImpl] Process[ElasticSearch] is stopped

==> daemon.log <==
2023.06.21 17:52:00 INFO  app[][o.s.a.SchedulerImpl] Process[ElasticSearch] is stopped
2023.06.21 17:52:00 INFO  app[][o.s.a.SchedulerImpl] SonarQube is stopped

==> sonar.log <==
2023.06.21 17:52:00 INFO  app[][o.s.a.SchedulerImpl] SonarQube is stopped