More useful connection logging

[Kricket]

Is your feature request related to a problem? Please describe.

I'm currently trying to use sql_exporter to fetch data from a Clickhouse database.
For now, I'm just trying to get a simple query to work.
Here's my configuration:

global:
  scrape_timeout_offset: 500ms
  min_interval: 0s
  max_connections: 3
  max_idle_connections: 3
reuse.
  max_connection_lifetime: 5m

target:
  data_source_name: 'ch://user:pass@myhost:8123/default'
  collectors: [my_clickhouse]

collector_files:
  - "*.collector.yml"

With the collector file:

collector_name: my_clickhouse

metrics:
  - metric_name: row_count_my_table
    type: gauge
    help: 'Number of rows in table my_table.'
    values: [num_rows]
    query: |
      SELECT COUNT(*) AS num_rows FROM my_table;

When I run it, I get the following output:

$ ./sql_exporter -log.level debug
ts=2022-11-14T08:30:25.473Z caller=klog.go:108 level=warn func=Warningf msg="Starting SQL exporter (version=0.9.1, branch=HEAD, revision=aa29c91a6d31d614dc2b20c429d6fd8699a12d1c) (go=go1.19.1, user=root@11ce5d80fd8d, date=20220921-15:11:16)"
ts=2022-11-14T08:30:25.473Z caller=klog.go:84 level=debug func=Infof msg="Loading configuration from sql_exporter.yml"
ts=2022-11-14T08:30:25.473Z caller=klog.go:84 level=debug func=Infof msg="Loaded collector 'my_clickhouse' from clickhouse.collector.yml"
ts=2022-11-14T08:30:25.473Z caller=klog.go:96 level=warn func=Warning msg="Listening on :9399"
ts=2022-11-14T08:30:25.473Z caller=tls_config.go:195 level=info msg="TLS is disabled." http2=false
ts=2022-11-14T08:30:31.754Z caller=klog.go:84 level=debug func=Infof msg="Database handle successfully opened with 'clickhouse' driver"
ts=2022-11-14T08:30:41.254Z caller=klog.go:84 level=debug func=Infof msg="Error gathering metrics: [from Gatherer #1] context deadline exceeded"

As you can see, even with debug logging, I have no idea what the problem is:

• I've verified that the credentials are correct, using a different clickhouse client
• I've verified that the SQL is correct and works

As a test, I tried changing the database connection string:

• from "ch" to "sqlserver" or "mysql"
• using a nonexistent username
  The result was the exact same log message (just with the driver name changed)!

Describe the solution you'd like

At the very least, the logging should provide more information about what's going on with the database. As it is, I have no idea what the problem is, much less what I might do about it.

• Did the database connection work? Obviously there's something wrong if I can use the wrong driver and it still thinks it connected OK.
• Did the query timeout? Or was there an error in the query? Or unable to connect?
• Shouldn't the program exit with an error if it can't connect to the database?

Describe alternatives you've considered

Using a different tool

Additional context

[jakob-reesalu]

I want to second this! Been working with the exporter for some time now, been thinking of doing a post like this. More specific logging would be helpful.

[Kricket]

Side note: I ended up figuring out what the problem was - I was using the HTTP port 8123 instead of the TCP port 9000.

How did I figure this out (being a newcomer to Clickhouse as well...)?

I found this alternative and tried to use it. It was harder to get running, but once I did it at least gave me the message "failed to connect", which led me to eventually figure out the problem.

[burningalchemist]

@Kricket @jakob-reesalu The difficulty here is that the error handling (this also includes message propagation) in the exporter depends on each underlying driver's error handling. So we need to catch all the possible scenarios and map them to specific human-readable errors, which limits flexibility of adding more drivers, since there is no single standard.

Nevertheless, I'll try to take a look at the UX improvements next year. I also plan to release a static documentation webpage to cover configuration, functionality and limitations in a better way. Thanks for reporting. 👍

---

@Kricket answering some of your questions:

• The connection in this implementation happens the first time when you hit the endpoint and not when you start the server, so when you tried open the connection, the driver was successfully loaded and the connection string seems to be valid, so we can create a handle and try to connect to the database using the underlying driver.

• Query-specific errors and timeouts are reported back and available in the logs.

• If the database is unavailable for some reason or amount of time this would cause a cascade issue for connected clients. In our case, we don't want to exit, yet report that there is a connection timeout.

I agree though, that context deadline exceeded may sound pretty misleading if you don't deal with Golang regularly or this particular code, so we definitely miss better human-readable messages here. The challenge with that I explained above, but I'll see what I can do. 😉 Still happy that you've found a solution to your problem. 👍