Failed to start a fresh install of Steampipe

[nhalstead]

Describe the bug

First time installing steampipe on my laptop. I tried to run the query command and it fails.

Steampipe version (steampipe -v) v0.16.4

To reproduce

1. Fresh Install
2. Run steampipe query

Expected behavior 🤔 Startup the Pg server so I can use the cli.

Additional context

Fresh First Run (no steampipe path)

 STEAMPIPE_LOG=trace steampipe query

2022-10-12 22:23:09.977 UTC [TRACE] steampipe: Sending HTTP Request &{POST https://hub.steampipe.io/api/cli/version/latest HTTP/1.1 1 1 map[Content-Type:[application/json] User-Agent:[Turbot Steampipe/0.16.4 (+https://steampipe.io)]] {{"arch":"amd64","os_platform":"darwin","signature":"e72c4c15-5f6e-4eeb-90f2-4e22f64eafec","version":"0.16.4"}} 0x15014a0 109 [] false hub.steampipe.io map[] map[] <nil> map[]   <nil> <nil> <nil> 0xc000192000}
2022-10-12 22:23:10.506 UTC [TRACE] steampipe: No memory limit set
2022-10-12 22:23:10.506 UTC [TRACE] steampipe: modfile exists in workspace folder - creating pseudo-resources and loading files recursively
2022-10-12 22:23:10.544 UTC [TRACE] steampipe: parse complete after 1 decode passes
2022-10-12 22:23:10.570 UTC [TRACE] steampipe: parse complete after 1 decode passes
2022-10-12 22:23:10.570 UTC [TRACE] steampipe: telemetry.Init service 'steampipe', tracingEnabled: false, metricsEnabled: false
2022-10-12 22:23:10.570 UTC [TRACE] steampipe: metrics and tracing disabled' - returning
Welcome to Steampipe v0.16.4
2022-10-12 22:23:10.570 UTC [TRACE] steampipe: GetRunStatus - loadRunningInstanceInfo returned nil
For more information, type .help
2022-10-12 22:23:10.570 UTC [TRACE] steampipe: calling removeRunningInstanceInfo
⠋ Prepare database install location...2022-10-12 22:23:10.570 UTC [TRACE] steampipe: ociDownloader.Download: downloading us-docker.pkg.dev/steampipe/steampipe/db:14.2.0
2022-10-12 22:23:10.570 UTC [TRACE] steampipe: ociDownloader.Pull: pulling us-docker.pkg.dev/steampipe/steampipe/db:14.2.0
⠏ Download & install embedded PostgreSQL database...2022-10-12 22:23:13.566 UTC [TRACE] steampipe: looking for application/vnd.turbot.steampipe.db.darwin-amd64.layer.v1+tar
2022-10-12 22:23:13.566 UTC [TRACE] steampipe: looking for application/vnd.turbot.steampipe.db.doc.layer.v1+text
2022-10-12 22:23:13.566 UTC [TRACE] steampipe: looking for application/vnd.turbot.steampipe.db.license.layer.v1+text
⠋ Download & install embedded PostgreSQL database...2022-10-12 22:23:13.655 UTC [TRACE] steampipe: GetRunStatus - loadRunningInstanceInfo returned nil
2022-10-12 22:23:13.658 UTC [TRACE] steampipe: ociDownloader.Download: downloading us-docker.pkg.dev/steampipe/steampipe/fdw:1.4.2
2022-10-12 22:23:13.658 UTC [TRACE] steampipe: ociDownloader.Pull: pulling us-docker.pkg.dev/steampipe/steampipe/fdw:1.4.2
⠋ Download & install steampipe-postgres-fdw...2022-10-12 22:23:14.626 UTC [TRACE] steampipe: looking for application/vnd.turbot.steampipe.fdw.darwin-amd64.layer.v1+gzip
2022-10-12 22:23:14.626 UTC [TRACE] steampipe: looking for application/vnd.turbot.steampipe.fdw.control.layer.v1+text
2022-10-12 22:23:14.626 UTC [TRACE] steampipe: looking for application/vnd.turbot.steampipe.fdw.sql.layer.v1+text
2022-10-12 22:23:14.626 UTC [TRACE] steampipe: looking for application/vnd.turbot.steampipe.fdw.doc.layer.v1+text
2022-10-12 22:23:14.626 UTC [TRACE] steampipe: looking for application/vnd.turbot.steampipe.fdw.license.layer.v1+text
2022-10-12 22:23:14.826 UTC [TRACE] steampipe: initdb start: /Users/nhalstead/.steampipe/db/14.2.0/postgres/bin/initdb --auth=trust --username=root --pgdata=/Users/nhalstead/.steampipe/db/14.2.0/data --encoding=UTF-8 --wal-segsize=1 --debug
⠋ Initializing database...2022-10-12 22:23:18.638 UTC [TRACE] steampipe: Connection string:  host=localhost port=63227 user=root dbname=postgres sslmode=disable
2022-10-12 22:23:18.655 UTC [TRACE] steampipe: SERVICE: 2022-10-12 18:23:18.655 EDT [91338] LOG:  starting PostgreSQL 14.2 on x86_64-apple-darwin20.6.0, compiled by Apple clang version 12.0.0 (clang-1200.0.32.29), 64-bit
2022-10-12 22:23:18.656 UTC [TRACE] steampipe: SERVICE: 2022-10-12 18:23:18.656 EDT [91338] LOG:  listening on IPv6 address "::1", port 63227
2022-10-12 22:23:18.656 UTC [TRACE] steampipe: SERVICE: 2022-10-12 18:23:18.656 EDT [91338] LOG:  listening on IPv4 address "127.0.0.1", port 63227
2022-10-12 22:23:18.657 UTC [TRACE] steampipe: SERVICE: 2022-10-12 18:23:18.657 EDT [91338] LOG:  listening on Unix socket "/tmp/.s.PGSQL.63227"
2022-10-12 22:23:18.660 UTC [TRACE] steampipe: SERVICE: 2022-10-12 18:23:18.660 EDT [91338] LOG:  hostssl record cannot match because SSL is disabled
2022-10-12 22:23:18.660 UTC [TRACE] steampipe: SERVICE: 2022-10-12 18:23:18.660 EDT [91338] HINT:  Set ssl = on in postgresql.conf.
2022-10-12 22:23:18.660 UTC [TRACE] steampipe: SERVICE: 2022-10-12 18:23:18.660 EDT [91338] CONTEXT:  line 2 of configuration file "/Users/nhalstead/.steampipe/db/14.2.0/data/pg_hba.conf"
2022-10-12 22:23:18.661 UTC [TRACE] steampipe: SERVICE: 2022-10-12 18:23:18.661 EDT [91340] LOG:  database system was shut down at 2022-10-12 18:23:18 EDT
2022-10-12 22:23:18.664 UTC [TRACE] steampipe: SERVICE: 2022-10-12 18:23:18.664 EDT [91338] LOG:  database system is ready to accept connections
⠙ Connection to database...2022-10-12 22:23:18.724 UTC [TRACE] steampipe: valid database name: steampipe
2022-10-12 22:23:18.724 UTC [TRACE] steampipe: installing database with name steampipe
⠹ Configuring database...2022-10-12 22:23:18.860 UTC [TRACE] steampipe: Install Foreign Server:  drop extension if exists "steampipe_postgres_fdw" cascade
2022-10-12 22:23:18.860 UTC [TRACE] steampipe: Install Foreign Server:  create extension if not exists "steampipe_postgres_fdw"
⠴ Configuring Steampipe...2022-10-12 22:23:19.206 UTC [TRACE] steampipe: SERVICE: 2022-10-12 22:23:19.206 UTC [INFO]  hub: .
2022-10-12 22:23:19.206 UTC [TRACE] steampipe: SERVICE: ******************************************************
2022-10-12 22:23:19.206 UTC [TRACE] steampipe: SERVICE: 		steampipe postgres fdw init
2022-10-12 22:23:19.206 UTC [TRACE] steampipe: SERVICE: ******************************************************
2022-10-12 22:23:19.206 UTC [TRACE] steampipe: SERVICE: 2022-10-12 22:23:19.206 UTC [INFO]  hub: Version:   v1.4.2
2022-10-12 22:23:19.206 UTC [TRACE] steampipe: SERVICE: 2022-10-12 22:23:19.206 UTC [INFO]  hub: Log level: trace
2022-10-12 22:23:19.207 UTC [TRACE] steampipe: Install Foreign Server:  create server "steampipe" foreign data wrapper "steampipe_postgres_fdw"
2022-10-12 22:23:19.208 UTC [TRACE] steampipe: SERVICE: 2022-10-12 22:23:19.208 UTC [INFO]  hub: .
2022-10-12 22:23:19.208 UTC [TRACE] steampipe: SERVICE: ******************************************************
2022-10-12 22:23:19.208 UTC [TRACE] steampipe: SERVICE: 		steampipe postgres fdw shutdown
2022-10-12 22:23:19.208 UTC [TRACE] steampipe: SERVICE: ******************************************************
2022-10-12 22:23:19.208 UTC [TRACE] steampipe: SERVICE: 2022-10-12 18:23:19.208 EDT [91338] LOG:  received smart shutdown request
2022-10-12 22:23:19.208 UTC [TRACE] steampipe: SERVICE: 2022-10-12 22:23:19.208 UTC [TRACE] hub: init telemetry
2022-10-12 22:23:19.209 UTC [TRACE] steampipe: SERVICE: 2022-10-12 22:23:19.208 UTC [TRACE] hub: telemetry.Init service 'steampipe-postgres-fdw', tracingEnabled: false, metricsEnabled: false
2022-10-12 22:23:19.209 UTC [TRACE] steampipe: SERVICE: 2022-10-12 22:23:19.209 UTC [TRACE] hub: metrics and tracing disabled' - returning
2022-10-12 22:23:19.209 UTC [TRACE] steampipe: SERVICE: 2022-10-12 22:23:19.209 UTC [TRACE] hub: hub: close
2022-10-12 22:23:19.209 UTC [TRACE] steampipe: SERVICE: 2022-10-12 22:23:19.209 UTC [TRACE] hub: shutdown telemetry
2022-10-12 22:23:19.212 UTC [TRACE] steampipe: SERVICE: 2022-10-12 18:23:19.212 EDT [91338] LOG:  background worker "logical replication launcher" (PID 91346) exited with exit code 1
2022-10-12 22:23:19.212 UTC [TRACE] steampipe: SERVICE: 2022-10-12 18:23:19.212 EDT [91341] LOG:  shutting down
⠦ Completing configuration2022-10-12 22:23:19.221 UTC [TRACE] steampipe: SERVICE: 2022-10-12 18:23:19.221 EDT [91338] LOG:  database system is shut down
2022-10-12 22:23:19.313 UTC [TRACE] steampipe: GetRunStatus - loadRunningInstanceInfo returned nil
2022-10-12 22:23:19.313 UTC [TRACE] steampipe: StartDB invoker query
2022-10-12 22:23:19.313 UTC [TRACE] steampipe: StartDB started plugin manager
2022-10-12 22:23:19.313 UTC [TRACE] steampipe: loadRootPrivateKey - failed to load key from /Users/nhalstead/.steampipe/db/14.2.0/data/root.key: open /Users/nhalstead/.steampipe/db/14.2.0/data/root.key: no such file or directory
2022-10-12 22:23:19.611 UTC [TRACE] steampipe: Connection string:  host=localhost port=9193 user=root dbname=postgres sslmode=disable
2022-10-12 22:23:19.656 UTC [TRACE] steampipe: SERVICE: 2022-10-12 22:23:19.656 UTC [91489] LOG:  redirecting log output to logging collector process
2022-10-12 22:23:19.656 UTC [TRACE] steampipe: SERVICE: 2022-10-12 22:23:19.656 UTC [91489] HINT:  Future log output will appear in directory "/Users/nhalstead/.steampipe/logs".
2022-10-12 22:23:19.776 UTC [TRACE] steampipe: status:  {"pid":91489,"port":9193,"listen":["localhost","127.0.0.1"],"listen_type":"local","invoker":"query","password":"XXXX-XXXX-XXXX","user":"steampipe","database":"steampipe","struct_version":20220411}
2022-10-12 22:23:19.776 UTC [TRACE] steampipe: Connection string:  host=localhost port=9193 user=root dbname=postgres sslmode=require

Error: failed to connect to `host=localhost user=root database=postgres`: failed to write startup message (x509: certificate signed by unknown authority)

Followup steampipe query

 STEAMPIPE_LOG=trace steampipe query

2022-10-12 22:23:48.025 UTC [TRACE] steampipe: No memory limit set
2022-10-12 22:23:48.025 UTC [TRACE] steampipe: modfile exists in workspace folder - creating pseudo-resources and loading files recursively
2022-10-12 22:23:48.054 UTC [TRACE] steampipe: parse complete after 1 decode passes
2022-10-12 22:23:48.080 UTC [TRACE] steampipe: parse complete after 1 decode passes
2022-10-12 22:23:48.081 UTC [TRACE] steampipe: telemetry.Init service 'steampipe', tracingEnabled: false, metricsEnabled: false
2022-10-12 22:23:48.081 UTC [TRACE] steampipe: metrics and tracing disabled' - returning
Welcome to Steampipe v0.16.4
For more information, type .help
2022-10-12 22:23:48.081 UTC [TRACE] steampipe: GetRunStatus - loadRunningInstanceInfo returned nil
> 2022-10-12 22:23:48.129 UTC [TRACE] steampipe: StartDB invoker query
2022-10-12 22:23:48.129 UTC [TRACE] steampipe: StartDB started plugin manager
2022-10-12 22:23:48.132 UTC [TRACE] steampipe: Connection string:  host=localhost port=9193 user=root dbname=postgres sslmode=disable
2022-10-12 22:23:48.172 UTC [TRACE] steampipe: SERVICE: 2022-10-12 22:23:48.172 UTC [92724] LOG:  redirecting log output to logging collector process
2022-10-12 22:23:48.172 UTC [TRACE] steampipe: SERVICE: 2022-10-12 22:23:48.172 UTC [92724] HINT:  Future log output will appear in directory "/Users/nhalstead/.steampipe/logs".
2022-10-12 22:23:48.248 UTC [TRACE] steampipe: status:  {"pid":92724,"port":9193,"listen":["localhost","127.0.0.1"],"listen_type":"local","invoker":"query","password":"XXXX-XXXX-XXXX","user":"steampipe","database":"steampipe","struct_version":20220411}
2022-10-12 22:23:48.248 UTC [TRACE] steampipe: Connection string:  host=localhost port=9193 user=root dbname=postgres sslmode=require

Error: failed to connect to `host=localhost user=root database=postgres`: failed to write startup message (x509: certificate signed by unknown authority)

Logs

2022-10-12 22:23:19.656 UTC [91489] LOG:  starting PostgreSQL 14.2 on x86_64-apple-darwin20.6.0, compiled by Apple clang version 12.0.0 (clang-1200.0.32.29), 64-bit
2022-10-12 22:23:19.657 UTC [91489] LOG:  listening on IPv6 address "::1", port 9193
2022-10-12 22:23:19.657 UTC [91489] LOG:  listening on IPv4 address "127.0.0.1", port 9193
2022-10-12 22:23:19.658 UTC [91489] LOG:  listening on Unix socket "/tmp/.s.PGSQL.9193"
2022-10-12 22:23:19.662 UTC [91493] LOG:  database system was shut down at 2022-10-12 22:23:19 UTC
2022-10-12 22:23:19.663 UTC [91494] LOG:  connection received: host=127.0.0.1 port=63230
2022-10-12 22:23:19.663 UTC [91494] FATAL:  the database system is starting up
2022-10-12 22:23:19.665 UTC [91495] LOG:  connection received: host=::1 port=63231
2022-10-12 22:23:19.665 UTC [91495] FATAL:  the database system is starting up
2022-10-12 22:23:19.666 UTC [91489] LOG:  database system is ready to accept connections
2022-10-12 22:23:19.712 UTC [91514] LOG:  connection received: host=127.0.0.1 port=63232
2022-10-12 22:23:19.713 UTC [91514] LOG:  connection authorized: user=root database=postgres
2022-10-12 22:23:19.721 UTC [91514] LOG:  disconnection: session time: 0:00:00.008 user=root database=postgres host=127.0.0.1 port=63232
2022-10-12 22:23:19.831 UTC [91535] LOG:  connection received: host=127.0.0.1 port=63233
2022-10-12 22:23:19.838 UTC [91535] LOG:  could not accept SSL connection: sslv3 alert bad certificate
2022-10-12 22:23:19.840 UTC [91536] LOG:  connection received: host=::1 port=63234
2022-10-12 22:23:19.843 UTC [91536] LOG:  could not accept SSL connection: sslv3 alert bad certificate
2022-10-12 22:23:19.879 UTC [91538] LOG:  connection received: host=127.0.0.1 port=63235
...
...
...
2022-10-12 22:23:24.786 UTC [91894] LOG:  could not accept SSL connection: sslv3 alert bad certificate
2022-10-12 22:23:48.172 UTC [92724] LOG:  starting PostgreSQL 14.2 on x86_64-apple-darwin20.6.0, compiled by Apple clang version 12.0.0 (clang-1200.0.32.29), 64-bit
2022-10-12 22:23:48.173 UTC [92724] LOG:  listening on IPv6 address "::1", port 9193
2022-10-12 22:23:48.173 UTC [92724] LOG:  listening on IPv4 address "127.0.0.1", port 9193
2022-10-12 22:23:48.173 UTC [92724] LOG:  listening on Unix socket "/tmp/.s.PGSQL.9193"
2022-10-12 22:23:48.176 UTC [92726] LOG:  database system was interrupted; last known up at 2022-10-12 22:23:19 UTC
2022-10-12 22:23:48.177 UTC [92726] LOG:  database system was not properly shut down; automatic recovery in progress
2022-10-12 22:23:48.179 UTC [92726] LOG:  redo starts at 0/835B08
2022-10-12 22:23:48.179 UTC [92726] LOG:  invalid record length at 0/835B40: wanted 24, got 0
2022-10-12 22:23:48.179 UTC [92726] LOG:  redo done at 0/835B08 system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s
2022-10-12 22:23:48.185 UTC [92724] LOG:  database system is ready to accept connections
2022-10-12 22:23:48.186 UTC [92733] LOG:  connection received: host=127.0.0.1 port=63436
2022-10-12 22:23:48.187 UTC [92733] LOG:  connection authorized: user=root database=postgres
2022-10-12 22:23:48.194 UTC [92733] LOG:  disconnection: session time: 0:00:00.007 user=root database=postgres host=127.0.0.1 port=63436
2022-10-12 22:23:48.301 UTC [92737] LOG:  connection received: host=127.0.0.1 port=63437
2022-10-12 22:23:48.306 UTC [92737] LOG:  could not accept SSL connection: sslv3 alert bad certificate
2022-10-12 22:23:48.307 UTC [92738] LOG:  connection received: host=::1 port=63440

Out of curiosity, I did try adding the root to Keychain with no change.

The directories seem to be fine and Postgres is happily running but seems like a config issue.

Again this was the OOBE install, no configs were put in yet.

[e-gineer]

Sorry you've hit this bump @nhalstead ... thanks for letting us know and for the comprehensive logs!

It appears that something has gone wrong with the self-signed certificate we automatically install with postgres.

In troubleshoot, I have some questions:

1. What's in the file /Users/nhalstead/.steampipe/db/14.2.0/data/root.key? Are you able to open that file? We seem to fail to load it, and / or get a bad certificate error.
2. Do you have postgres already installed on this machine? I'm wondering if they might be interacting somehow...
3. What OS are you installing on?

As a suggested workaround / fix, can you please try:

# ensure steampipe is not running
steampipe service stop --force
ps aux | grep steampipe

# delete the DB install
rm -rf ~/.steampipe/db

# start steampipe again, which should reinstall the database
steampipe query

[nhalstead]

Hi @e-gineer,

1. It's a valid Private RSA Key file and the corresponding certificate was able to be read by Keychain.
2. Yes I have Postgres already installed on the host. I noticed that steampipe runs on a semi-random port so I have doubts it's connecting to the wrong port (plus logs indicate it's trying to connect to the server and the server is seeing it)
3. MacOS 12.6

I have run through the steps and got the same results.

Had also read up on alike issues to no avail. (#1417, #2465, #2377)

[e-gineer]

I'm wondering if you may be hitting this issue https://github.com/turbot/steampipe/issues/1417

Do you have a ~/.postgresql/root.crt file on your machine? Why did you rule out #1417?

[nhalstead]

So moving to rename the root certificate to root.crt.bak allowed it to work.

Is it possible for steampipe to use the existing root certificate (in the ~/.postgresql/root.crt) to sign the Postgres server certificate? This would allow it to coincide or override the server to explicitly use the path to the existing certificate (~/.steampipe/db/14.2.0/data/root.key).

https://github.com/turbot/steampipe/blob/main/pkg/db/db_local/ssl.go

[github-actions[bot]]

'This issue is stale because it has been open 60 days with no activity. Remove stale label or comment or this will be closed in 30 days.'

[github-actions[bot]]

'This issue was closed because it has been stalled for 90 days with no activity.'