Add --wait-interval and $DBMATE_WAIT_INTERVAL to make wait interval configurable at runtime

[jessebye]

Description

When using the --wait flag and dbmate up is run before the DB is ready, the logs are flooded with this message:

[mysql] 2024/01/24 19:58:12 packets.go:37: unexpected EOF

Eventually it stops when the DB is ready and it can run migrations:

[mysql] 2024/01/24 19:58:12 packets.go:37: unexpected EOF
[mysql] 2024/01/24 19:58:12 packets.go:37: unexpected EOF
Waiting for database.....................................................................................................................
Migrations complete.
Connecting to 127.0.0.1:15020 (127.0.0.1:15020)

• Version: 2.11
• Database: mysql
• Operating System: Linux (official Docker container)

Steps To Reproduce
Set up a K8S job that will run the dbmate container against a K8S mysql pod. Restart the mysql pod then kick off the dbmate job with --wait flag. Observe the log messages.

Expected Behavior
I would expect to see the message Waiting for database and a . for each time it attempts connection until it succeeds.

[dossy]

So, the error is being logged by the go-sql-driver/mysql driver, not by dbmate itself.

I suspect the issue is caused by how k8s implements cluster networking, specifically in the case where there's a Service that registers the port for the service but has no Pods available to forward that traffic to, yet. In this case, K8s is accepting the connection on its ingress, but then drops the connection as there's no Pod to forward it to, which the MySQL client treats as an unexpected EOF (end of file, or in this case, server-closed network connection) and the driver is implemented to log that occurrence.

We have no direct control over the MySQL driver's behavior itself, so the best we could do from the dbmate end would be to expose the DB.WaitInterval as a command-line argument, as it's currently defaulted to 1 second which could be quite noisy if it takes a few minutes for the Pod to become available.

I think adding --wait-interval and $DBMATE_WAIT_INTERVAL as ways of setting the interval could be a useful addition, but ultimately I suspect just ignoring the noisy logging from the go-sql-driver/mysql driver is the path of least resistance ... 😄

@jessebye, what do you think?

[jessebye]

@dossy seems like a reasonable approach, given the context 👍

[Mizaro]

I would like to contribute code to this issue if we decide that it should be implemented @dossy .

[dossy]

I would like to contribute code to this issue if we decide that it should be implemented @dossy .

I think that as long as the implementation preserves the current behavior by default, I think a contribution implementing this configurability would be useful to those who need it.

While there don't appear to be too many people who have come forward look for or needing this functionality, it is certainly a quality-of-life improvement that some folks may appreciate.

[amacneil]

I think we should silence any errors from mysql driver while we are in the "wait" operation. If there are any real error messages people need to uncover for debugging, they can run any other dbmate command.

Adding --wait-interval cli flag seems reasonable (it is already exposed to API users), but it's not going to prevent this spam going to the console. So let's fix that first.

[dossy]

I think we should silence any errors from mysql driver while we are in the "wait" operation. If there are any real error messages people need to uncover for debugging, they can run any other dbmate command.

Adding --wait-interval cli flag seems reasonable (it is already exposed to API users), but it's not going to prevent this spam going to the console. So let's fix that first.

How do you feel about emitting the errors if and when --verbose is also specified?

[amacneil]

How do you feel about emitting the errors if and when --verbose is also specified?

Do we need it?

The wait command expects an error. Encountering an error is a normal part of its operation - that is the whole point of the command, to attempt a connection, and if there is an error to catch it and retry. For all other database drivers today we handle and suppress the error details.

In this case, the mysql driver is taking matters into its own hands and spewing some console output about an error in addition to returning an error. I think that is bad behavior of the driver and we should suppress it (along with the error which we already suppress).