Common crashes just after startup

[neilschelly]

I have been having trouble starting the container version. It will work more often than not with a small configuration (one database and just the default metrics). But it may take 3-5 times restarting it to get it to run when I load all 6 of the databases I want to monitor and the custom additional metrics queries I have too.

I am working to to track down the exact cause, but I'm confident that this happens sometimes with a single-database configuration (as follows) and only the default metrics. I'll post more as I learn more.

The config.yml is as follows:

databases:
    alpha:
        username: USERNAME
        password: PASSWORD
        url: SERVERNAME:1521/SERVICENAME
        maxOpenConns: 10
        maxIdleConns: 10
      
log:
    # This is for querying the v%diag_alert_ext table and dumping it's contents
    # to /log/alert.log inside the container.
    disable: 1

Our container is built from the following Dockerfile:

FROM container-registry.oracle.com/database/observability-exporter:2.0.1

ADD config.yml /config.yml

CMD ["--config.file", "/config.yml"]

Here's what a successful run looks like:

docker run -it --rm  -p 9161:9161 \
  --log-opt max-size=100M \
  --name oracle_exporter \
  -m 50m \
  -v `pwd`/configuration:/configuration \
ird-oracle_exporter:latest  # --log.level=debug
time=2025-06-16T20:12:46.496Z level=INFO source=main.go:75 msg="FREE_INTERVAL end var is not present, will not periodically attempt to release memory"
time=2025-06-16T20:12:46.496Z level=INFO source=main.go:82 msg="RESTART_INTERVAL env var is not present, so will not restart myself periodically"
time=2025-06-16T20:12:46.496Z level=INFO source=main.go:116 msg="alpha database max idle connections is greater than 0, so will use go-sql connection pool and pooling settings will be ignored"
time=2025-06-16T20:12:46.496Z level=INFO source=database.go:91 msg="Using Username/Password Authentication." database=alpha
godror WARNING: discrepancy between SESSIONTIMEZONE ("+00:00"=0) and SYSTIMESTAMP ("-04:00"=-400) - set connection timezone, see https://github.com/godror/godror/blob/master/doc/timezone.md
time=2025-06-16T20:12:47.046Z level=INFO source=database.go:161 msg="Connected as SYSDBA? FALSE" database=alpha
time=2025-06-16T20:12:48.221Z level=INFO source=main.go:131 msg="Starting oracledb_exporter" version=2.0.1
time=2025-06-16T20:12:48.221Z level=INFO source=main.go:132 msg="Build context" build="(go=go1.23.8, platform=linux/amd64, user=, date=, tags=unknown)"
time=2025-06-16T20:12:48.221Z level=INFO source=main.go:133 msg="Collect from: " metricPath=/metrics
time=2025-06-16T20:12:48.221Z level=INFO source=main.go:184 msg="log.disable set to 1, so will not export the alert logs"
time=2025-06-16T20:12:48.221Z level=INFO source=tls_config.go:347 msg="Listening on" address=[::]:9161
time=2025-06-16T20:12:48.221Z level=INFO source=tls_config.go:350 msg="TLS is disabled." http2=false address=[::]:9161

With no changes, just stopping and running the same container again moments later, here's the output:

docker run -it --rm  -p 9161:9161 \
  --log-opt max-size=100M \
  --name oracle_exporter \
  -m 50m \
  -v `pwd`/configuration:/configuration \
ird-oracle_exporter:latest  # --log.level=debug
time=2025-06-16T20:12:54.070Z level=INFO source=main.go:75 msg="FREE_INTERVAL end var is not present, will not periodically attempt to release memory"
time=2025-06-16T20:12:54.070Z level=INFO source=main.go:82 msg="RESTART_INTERVAL env var is not present, so will not restart myself periodically"
time=2025-06-16T20:12:54.070Z level=INFO source=main.go:116 msg="alpha database max idle connections is greater than 0, so will use go-sql connection pool and pooling settings will be ignored"
time=2025-06-16T20:12:54.070Z level=INFO source=database.go:91 msg="Using Username/Password Authentication." database=alpha
godror WARNING: discrepancy between SESSIONTIMEZONE ("+00:00"=0) and SYSTIMESTAMP ("-04:00"=-400) - set connection timezone, see https://github.com/godror/godror/blob/master/doc/timezone.md
time=2025-06-16T20:12:54.631Z level=INFO source=database.go:161 msg="Connected as SYSDBA? FALSE" database=alpha
double free or corruption (top)
SIGABRT: abort
PC=0x7f16230a95ef m=3 sigcode=18446744073709551610
signal arrived during cgo execution```

The above error is followed by a very long stack track that I'll attach here.

[stacktrace.txt](https://github.com/user-attachments/files/20763971/stacktrace.txt)

[neilschelly]

I meant to add that if I do use custom metrics files, then the crash is always just after loading those (when it crashes):

godror WARNING: discrepancy between SESSIONTIMEZONE ("+00:00"=0) and SYSTIMESTAMP ("-04:00"=-400) - set connection timezone, see https://github.com/godror/godror/blob/master/doc/timezone.md
time=2025-06-16T19:07:24.148Z level=INFO source=database.go:161 msg="Connected as SYSDBA? FALSE" database=beta
time=2025-06-16T19:07:24.148Z level=INFO source=collector.go:333 msg="/configuration/custom-metrics-generic.toml has been changed. Reloading metrics..."
time=2025-06-16T19:07:24.149Z level=INFO source=collector.go:369 msg="Successfully loaded custom metrics from /configuration/custom-metrics-generic.toml"
time=2025-06-16T19:07:24.150Z level=INFO source=collector.go:369 msg="Successfully loaded custom metrics from /configuration/custom-metrics-raceservers.toml"
double free or corruption (!prev)
SIGABRT: abort
PC=0x7f3b2ffcf5ef m=32 sigcode=18446744073709551610
signal arrived during cgo execution```

[neilschelly]

I can confirm that this occurs somewhere in the call to MustRegister at https://github.com/oracle/oracle-db-appdev-monitoring/blob/main/main.go#L128, but there's obviously a lot going on in there. I haven't dug in deeper to try and decipher what the prometheus client library doesn't like about the exporter configuration.

[neilschelly]

I can confirm that this occurs somewhere in the first call to MustRegister at https://github.com/oracle/oracle-db-appdev-monitoring/blob/main/main.go#L128, but there's obviously a lot going on in there. I haven't dug in deeper to try and decipher what the prometheus client library doesn't like about the exporter configuration.

[markxnelson]

Hi @neilschelly , thanks for reporting the issue. We will also try to reproduce and debug. Could you confirm in the six database case, when you see the error - are they all using the same kind of basic connection? No wallet or vault involved? Thanks!

[neilschelly]

Yes, all the databases are identically configured. If it helps, they are all configured in OCI, using Oracle Base DB systems running 19.24.0.0.0.

[neilschelly]

My GoLang debugging is rusty at best, but here's what I've learned. 1.6.1 does not cause this problem. 2.0.0 and 2.0.1 both cause this problem within the first 2-3 startups for me usually. My minimalist configuration (no config.yml, no multiple databases, just env var config) test case now is:

$ docker run -it --rm -p 9161:9161 --entrypoint="" container-registry.oracle.com/database/observability-exporter:2.0.0 /bin/bash
bash-4.4$ DB_USERNAME=user DB_PASSWORD=pass DB_CONNECT_STRING=server:1521/service ./oracledb_exporter --log.level=debug

When the crash happens, it's during the initial scrape of the queries for metrics that happens at initialization. The code launches a number of goroutines to scrape each metric, and they all seem to launch off. The crash happens either before any of those goroutines have completed successfully or after only a couple have reached the "Successfully scraped metric" debug line.

Based on the timing and the sometimes-it-just-works behavior, it appears to be a race condition somewhere in that initial population of the metrics, and I'm theorizing it has to do with the metric data structures that had to change for the multiple database support, but I don't know for sure yet.

[anders-swanson]

@neilschelly Thanks for the information, we're taking a look at this. Could you attach the full stack trace? The link https://github.com/user-attachments/files/20763971/stacktrace.txt doesn't exist.

[anders-swanson]

I'm getting a cgo stack trace here, from the godror cgo execution layer: _Cfunc_dpiConn_create which tries to create a connection

goroutine 31 gp=0xc0002901c0 m=3 mp=0xc000066e08 [syscall, locked to thread]:
runtime.cgocall(0xb31ef0, 0xc000321830)
	/usr/local/go/src/runtime/cgocall.go:167 +0x4b fp=0xc000321808 sp=0xc0003217d0 pc=0x47980b
github.com/godror/godror._Cfunc_dpiConn_create(0x1b079b0, 0x7f7f2800cab0, 0x8, 0x7f7f2800cad0, 0x7, 0x7f7f2800caf0, 0x18, 0xc00014c2d0, 0xc00013a120, 0xc000122048)

[anders-swanson]

this also occurs in 1.6.1

[anders-swanson]

On testing, this appears to be related to concurrently creating connections with godror, specifically, when it calls _Cfunc_dpiConn_create. Going to check in godror about this if there's a preferred way to create connections.

[anders-swanson]

If you like, have a try with #264 . trying a workaround for perceived errors when rapidly acquiring connections.

[anders-swanson]

Will be fixed in next release