search

dolthub / dolt

Dolt – Git for Data
Apache License 2.0
17.41k stars 488 forks source link

Flyway and dolt: missing performance_schema #8051

Closed muescha closed 2 weeks ago

muescha commented 3 weeks ago

Setup

using dolt data base:

dolt version
dolt version 1.40.3

and added flyway to the pom.xml as described in tutorial:

https://github.com/springframeworkguru/spring-6-rest-mvc/tree/76-flyway-deps

Error

INFO[0398] NewConnection                                 DisableClientMultiStatements=false connectionID=7
ERRO[0398] unable to prepare query: Access denied for user 'restadmin'@'%' to database 'performance_schema'  query="select VARIABLE_VALUE from performance_schema.global_variables where variable_name = 'pxc_strict_mode'"
ERRO[0398] unable to prepare query: Access denied for user 'restadmin'@'%' to database 'performance_schema' (errno 1105) (sqlstate HY000)
WARN[0398] error running query                           connectTime="2024-06-23 13:57:51.190714 +0200 CEST m=+398.837230084" connectionDb=restdb connectionID=7 error="Access denied for user 'restadmin'@'%' to database 'performance_schema'"
ERRO[0398] unable to prepare query: Access denied for user 'restadmin'@'%' to database 'performance_schema'  query="SELECT variable_name FROM performance_schema.user_variables_by_thread WHERE variable_value IS NOT NULL"
ERRO[0398] unable to prepare query: Access denied for user 'restadmin'@'%' to database 'performance_schema' (errno 1105) (sqlstate HY000)
WARN[0398] error running query                           connectTime="2024-06-23 13:57:51.190714 +0200 CEST m=+398.837230084" connectionDb=restdb connectionID=7 error="Access denied for user 'restadmin'@'%' to database 'performance_schema'"

Flyway Source

It is used in this places:

https://github.com/search?q=repo%3Aflyway%2Fflyway+performance_schema&type=code

muescha commented 3 weeks ago

I tried to create a "fake" performance_schema:

DROP DATABASE IF EXISTS performance_schema;
CREATE DATABASE IF NOT EXISTS performance_schema CHARACTER SET utf8mb4 COLLATE utf8mb4_unicode_ci;

create table performance_schema.user_variables_by_thread
(
    THREAD_ID      bigint unsigned not null,
    VARIABLE_NAME  varchar(64)     not null,
    VARIABLE_VALUE longblob        null,
    primary key (THREAD_ID, VARIABLE_NAME) using hash
)
    engine = PERFORMANCE_SCHEMA;

create table performance_schema.global_variables
(
    VARIABLE_NAME  varchar(64)   not null,
    VARIABLE_VALUE varchar(1024) null,
    primary key (VARIABLE_NAME) using hash
)
    engine = PERFORMANCE_SCHEMA;

GRANT SELECT, INSERT, UPDATE, DELETE, CREATE, DROP, REFERENCES, INDEX, ALTER, EXECUTE, CREATE VIEW, SHOW VIEW,
CREATE ROUTINE, ALTER ROUTINE, EVENT, TRIGGER ON `performance_schema`.* TO `restadmin`@`%`;

the "fake" is working so far :)

muescha commented 3 weeks ago

but then it fails on an other place, but because it is a different error I created new issue:

muescha commented 3 weeks ago

I found this statement that the performance_schema is currently missing by design:

Open Questions Debezium integration support – Debezium integration hasn't been tested yet, and may require additional scope. For example, some replication information is accessible from MySQL's performance_schema database, which Dolt doesn't currently support. We may need to implement portions of this database to unblock Debezium support. Debezium also has it's own initial snapshot feature we relies on global read locks. There are other alternatives for this, but this needs to be investigated.

  • Source: Dolt binlog Provider Support #7512
fulghum commented 3 weeks ago

Hi @muescha, thank you for reporting these details about what Flyway needs from performance_schema in order to work with Dolt. Awesome that you were able to get further along by faking out some of the data in the performance_schema tables. If the tables' existence is really all that is needed to keep Flyway happy, then that's an easy change for us to make. Populating the global variables would be pretty straight-forward, too.

We'll tackle the query issue you hit first (https://github.com/dolthub/dolt/issues/8052) and discuss if we should go ahead and stub out some of the tables in performance_schema. Thanks for helping us test with Flyway and finding some gaps we need to fill in for Dolt! 🙏

muescha commented 3 weeks ago
muescha commented 3 weeks ago

maybe there are more errors come after #8052 is fixed but we can go through step by step ;)

fulghum commented 3 weeks ago

I landed a change that creates the performance_schema database and fixed up a bunch of tests. I'll take a look at getting the two tables above stubbed out next. Although... I'm still a little surprised that Flyway depends on performance_schema, since it's not uncommon to turn it off in MySQL installs, so I'll poke around a little more and see if there's another way to disable needing it. It seems odd to query performance_schema for a global variable value, instead of using the more common show global variables like 'pxc_strict_mode'; syntax.

I'll poke a little deeper on this tomorrow and see what I can find. Let us know if your workaround stops working or is causing any issues in the meantime.

fulghum commented 3 weeks ago

@muescha – As I was digging deeper into this and looking through the Flyway issues and codebase, it seems like Flyway should already be gracefully handling the absence of the performance_schema database, so I'm wondering if there's actually something else going on that we need to find...

For example, the Flyway code that checks for @@pcx_strict_mode wraps exception handling around the database call and should just be returning false when it can't query performance_schema. A few GitHub issues indicate that access issues users reported have also been fixed by gracefully handling failures there.

I'm trying to repro the exact error you got so I can dig in and see if there's something else deeper that needs to be fixed, but so far, Flyway has been working correctly with Dolt in the tests I tried. I wasn't able to find any code in the Boot/Flyway GitHub repository you mentioned, but I did find the Flyway Maven Quickstart docs, and was able to get those to work with a Dolt database that doesn't have performance_schema.

I'll try a few more repro ideas today, but if you can give me specific steps on how to reproduce what you're seeing (or maybe share a GitHub repo even?), then I can keep digging in deeper and help figure out why you're hitting those errors.

muescha commented 3 weeks ago

you are right - the default log only show me the missing performance_schema and I was assuming the error comes from the missing schema:

dolt sql-server --user=root
Starting server with Config HP="localhost:3306"|T="28800000"|R="false"|L="info"|S="/tmp/mysql.sock"
INFO[0000] Server ready. Accepting connections.
WARN[0000] secure_file_priv is set to "", which is insecure.
WARN[0000] Any user with GRANT FILE privileges will be able to read any file which the sql-server process can read.
WARN[0000] Please consider restarting the server with secure_file_priv set to a safe (or non-existent) directory.
INFO[0006] NewConnection                                 DisableClientMultiStatements=false connectionID=1
INFO[0007] NewConnection                                 DisableClientMultiStatements=false connectionID=2
ERRO[0007] unable to prepare query: database not found: performance_schema  query="select VARIABLE_VALUE from performance_schema.global_variables where variable_name = 'pxc_strict_mode'"
ERRO[0007] unable to prepare query: database not found: performance_schema (errno 1049) (sqlstate HY000)
INFO[0007] NewConnection                                 DisableClientMultiStatements=false connectionID=3
WARN[0007] error running query                           connectTime="2024-06-25 20:47:07.737013 +0200 CEST m=+6.979886084" connectionDb=restdb connectionID=1 error="database not found: performance_schema"
ERRO[0007] unable to prepare query: database not found: performance_schema  query="SELECT variable_name FROM performance_schema.user_variables_by_thread WHERE variable_value IS NOT NULL"
ERRO[0007] unable to prepare query: database not found: performance_schema (errno 1049) (sqlstate HY000)
WARN[0007] error running query                           connectTime="2024-06-25 20:47:07.737013 +0200 CEST m=+6.979886084" connectionDb=restdb connectionID=1 error="database not found: performance_schema"
INFO[0007] NewConnection                                 DisableClientMultiStatements=false connectionID=4
INFO[0007] NewConnection                                 DisableClientMultiStatements=false connectionID=5
WARN[0007] error running query                           connectTime="2024-06-25 20:47:07.737013 +0200 CEST m=+6.979886084" connectionDb=restdb connectionID=1 error="command denied to user 'restadmin'@'%'"
INFO[0007] ConnectionClosed                              connectionID=1
INFO[0007] ConnectionClosed                              connectionID=3
INFO[0007] ConnectionClosed                              connectionID=2
INFO[0007] ConnectionClosed                              connectionID=5
INFO[0007] ConnectionClosed                              connectionID=4
^CINFO[0036] Server closing listener. No longer accepting connections.

but the debug loglevel shows that is the #8052 is causing the error command denied to user 'restadmin'@'%' i have seen in the short log:

dolt sql-server -l debug
Starting server with Config HP="localhost:3306"|T="28800000"|R="false"|L="debug"|S="/tmp/mysql.sock"
DEBU[0000] Setting binary logging branch to main
DEBU[0000] Loading events
INFO[0000] Server ready. Accepting connections.
WARN[0000] secure_file_priv is set to "", which is insecure.
WARN[0000] Any user with GRANT FILE privileges will be able to read any file which the sql-server process can read.
WARN[0000] Please consider restarting the server with secure_file_priv set to a safe (or non-existent) directory.
INFO[0004] NewConnection                                 DisableClientMultiStatements=false connectionID=1
DEBU[0004] Starting query                                connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="/* mysql-connector-j-8.0.32 (Revision: fa4912a849140828e48162a2c396c8df0091bed7) */SELECT @@session.auto_increment_increment AS auto_increment_increment, @@character_set_client AS character_set_client, @@character_set_connection AS character_set_connection, @@character_set_results AS character_set_results, @@character_set_server AS character_set_server, @@collation_server AS collation_server, @@collation_connection AS collation_connection, @@init_connect AS init_connect, @@interactive_timeout AS interactive_timeout, @@license AS license, @@lower_case_table_names AS lower_case_table_names, @@max_allowed_packet AS max_allowed_packet, @@net_write_timeout AS net_write_timeout, @@performance_schema AS performance_schema, @@sql_mode AS sql_mode, @@system_time_zone AS system_time_zone, @@time_zone AS time_zone, @@transaction_isolation AS transaction_isolation, @@wait_timeout AS wait_timeout"
DEBU[0004] Query finished in 4 ms                        connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="/* mysql-connector-j-8.0.32 (Revision: fa4912a849140828e48162a2c396c8df0091bed7) */SELECT @@session.auto_increment_increment AS auto_increment_increment, @@character_set_client AS character_set_client, @@character_set_connection AS character_set_connection, @@character_set_results AS character_set_results, @@character_set_server AS character_set_server, @@collation_server AS collation_server, @@collation_connection AS collation_connection, @@init_connect AS init_connect, @@interactive_timeout AS interactive_timeout, @@license AS license, @@lower_case_table_names AS lower_case_table_names, @@max_allowed_packet AS max_allowed_packet, @@net_write_timeout AS net_write_timeout, @@performance_schema AS performance_schema, @@sql_mode AS sql_mode, @@system_time_zone AS system_time_zone, @@time_zone AS time_zone, @@transaction_isolation AS transaction_isolation, @@wait_timeout AS wait_timeout"
DEBU[0004] Starting query                                connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SET character_set_results = NULL"
DEBU[0004] Query finished in 0 ms                        connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SET character_set_results = NULL"
INFO[0004] NewConnection                                 DisableClientMultiStatements=false connectionID=2
DEBU[0004] Starting query                                connectTime="2024-06-25 20:50:42.618338 +0200 CEST m=+4.678587918" connectionDb=restdb connectionID=2 query="SET character_set_results = NULL"
DEBU[0004] Query finished in 0 ms                        connectTime="2024-06-25 20:50:42.618338 +0200 CEST m=+4.678587918" connectionDb=restdb connectionID=2 query="SET character_set_results = NULL"
INFO[0004] NewConnection                                 DisableClientMultiStatements=false connectionID=3
DEBU[0004] Starting query                                connectTime="2024-06-25 20:50:42.632563 +0200 CEST m=+4.692813084" connectionDb=restdb connectionID=3 query="SET character_set_results = NULL"
DEBU[0004] Query finished in 0 ms                        connectTime="2024-06-25 20:50:42.632563 +0200 CEST m=+4.692813084" connectionDb=restdb connectionID=3 query="SET character_set_results = NULL"
INFO[0004] NewConnection                                 DisableClientMultiStatements=false connectionID=4
DEBU[0004] Starting query                                connectTime="2024-06-25 20:50:42.648321 +0200 CEST m=+4.708570793" connectionDb=restdb connectionID=4 query="SET character_set_results = NULL"
DEBU[0004] Query finished in 1 ms                        connectTime="2024-06-25 20:50:42.648321 +0200 CEST m=+4.708570793" connectionDb=restdb connectionID=4 query="SET character_set_results = NULL"dolt sql-server -l debug
Starting server with Config HP="localhost:3306"|T="28800000"|R="false"|L="debug"|S="/tmp/mysql.sock"
DEBU[0000] Setting binary logging branch to main
DEBU[0000] Loading events
INFO[0000] Server ready. Accepting connections.
WARN[0000] secure_file_priv is set to "", which is insecure.
WARN[0000] Any user with GRANT FILE privileges will be able to read any file which the sql-server process can read.
WARN[0000] Please consider restarting the server with secure_file_priv set to a safe (or non-existent) directory.
INFO[0004] NewConnection                                 DisableClientMultiStatements=false connectionID=1
DEBU[0004] Starting query                                connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="/* mysql-connector-j-8.0.32 (Revision: fa4912a849140828e48162a2c396c8df0091bed7) */SELECT @@session.auto_increment_increment AS auto_increment_increment, @@character_set_client AS character_set_client, @@character_set_connection AS character_set_connection, @@character_set_results AS character_set_results, @@character_set_server AS character_set_server, @@collation_server AS collation_server, @@collation_connection AS collation_connection, @@init_connect AS init_connect, @@interactive_timeout AS interactive_timeout, @@license AS license, @@lower_case_table_names AS lower_case_table_names, @@max_allowed_packet AS max_allowed_packet, @@net_write_timeout AS net_write_timeout, @@performance_schema AS performance_schema, @@sql_mode AS sql_mode, @@system_time_zone AS system_time_zone, @@time_zone AS time_zone, @@transaction_isolation AS transaction_isolation, @@wait_timeout AS wait_timeout"
DEBU[0004] Query finished in 4 ms                        connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="/* mysql-connector-j-8.0.32 (Revision: fa4912a849140828e48162a2c396c8df0091bed7) */SELECT @@session.auto_increment_increment AS auto_increment_increment, @@character_set_client AS character_set_client, @@character_set_connection AS character_set_connection, @@character_set_results AS character_set_results, @@character_set_server AS character_set_server, @@collation_server AS collation_server, @@collation_connection AS collation_connection, @@init_connect AS init_connect, @@interactive_timeout AS interactive_timeout, @@license AS license, @@lower_case_table_names AS lower_case_table_names, @@max_allowed_packet AS max_allowed_packet, @@net_write_timeout AS net_write_timeout, @@performance_schema AS performance_schema, @@sql_mode AS sql_mode, @@system_time_zone AS system_time_zone, @@time_zone AS time_zone, @@transaction_isolation AS transaction_isolation, @@wait_timeout AS wait_timeout"
DEBU[0004] Starting query                                connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SET character_set_results = NULL"
DEBU[0004] Query finished in 0 ms                        connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SET character_set_results = NULL"
INFO[0004] NewConnection                                 DisableClientMultiStatements=false connectionID=2
DEBU[0004] Starting query                                connectTime="2024-06-25 20:50:42.618338 +0200 CEST m=+4.678587918" connectionDb=restdb connectionID=2 query="SET character_set_results = NULL"
DEBU[0004] Query finished in 0 ms                        connectTime="2024-06-25 20:50:42.618338 +0200 CEST m=+4.678587918" connectionDb=restdb connectionID=2 query="SET character_set_results = NULL"
INFO[0004] NewConnection                                 DisableClientMultiStatements=false connectionID=3
DEBU[0004] Starting query                                connectTime="2024-06-25 20:50:42.632563 +0200 CEST m=+4.692813084" connectionDb=restdb connectionID=3 query="SET character_set_results = NULL"
DEBU[0004] Query finished in 0 ms                        connectTime="2024-06-25 20:50:42.632563 +0200 CEST m=+4.692813084" connectionDb=restdb connectionID=3 query="SET character_set_results = NULL"
INFO[0004] NewConnection                                 DisableClientMultiStatements=false connectionID=4
DEBU[0004] Starting query                                connectTime="2024-06-25 20:50:42.648321 +0200 CEST m=+4.708570793" connectionDb=restdb connectionID=4 query="SET character_set_results = NULL"
DEBU[0004] Query finished in 1 ms                        connectTime="2024-06-25 20:50:42.648321 +0200 CEST m=+4.708570793" connectionDb=restdb connectionID=4 query="SET character_set_results = NULL"
DEBU[0004] preparing query                               paramsCount=0 query="SELECT version()" statementId=1
DEBU[0004] Starting query                                connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SELECT version()"
DEBU[0004] Query finished in 0 ms                        connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SELECT version()"
INFO[0004] NewConnection                                 DisableClientMultiStatements=false connectionID=5
DEBU[0004] Starting query                                connectTime="2024-06-25 20:50:42.669171 +0200 CEST m=+4.729420668" connectionDb=restdb connectionID=5 query="SET character_set_results = NULL"
DEBU[0004] Query finished in 0 ms                        connectTime="2024-06-25 20:50:42.669171 +0200 CEST m=+4.729420668" connectionDb=restdb connectionID=5 query="SET character_set_results = NULL"
DEBU[0004] preparing query                               paramsCount=0 query="select VARIABLE_VALUE from performance_schema.global_variables where variable_name = 'pxc_strict_mode'" statementId=2
ERRO[0004] unable to prepare query: database not found: performance_schema  query="select VARIABLE_VALUE from performance_schema.global_variables where variable_name = 'pxc_strict_mode'"
ERRO[0004] unable to prepare query: database not found: performance_schema (errno 1049) (sqlstate HY000)
DEBU[0004] Starting query                                connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="select VARIABLE_VALUE from performance_schema.global_variables where variable_name = 'pxc_strict_mode'"
WARN[0004] error running query                           connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 error="database not found: performance_schema" query="select VARIABLE_VALUE from performance_schema.global_variables where variable_name = 'pxc_strict_mode'"
DEBU[0004] preparing query                               paramsCount=0 query="SELECT @@GLOBAL.ENFORCE_GTID_CONSISTENCY" statementId=3
DEBU[0004] Starting query                                connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SELECT @@GLOBAL.ENFORCE_GTID_CONSISTENCY"
DEBU[0004] Query finished in 0 ms                        connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SELECT @@GLOBAL.ENFORCE_GTID_CONSISTENCY"
DEBU[0004] preparing query                               paramsCount=0 query="SELECT DATABASE()" statementId=4
DEBU[0004] Starting query                                connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SELECT DATABASE()"
DEBU[0004] Query finished in 0 ms                        connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SELECT DATABASE()"
DEBU[0004] preparing query                               paramsCount=0 query="SELECT variable_name FROM performance_schema.user_variables_by_thread WHERE variable_value IS NOT NULL" statementId=5
ERRO[0004] unable to prepare query: database not found: performance_schema  query="SELECT variable_name FROM performance_schema.user_variables_by_thread WHERE variable_value IS NOT NULL"
ERRO[0004] unable to prepare query: database not found: performance_schema (errno 1049) (sqlstate HY000)
DEBU[0004] Starting query                                connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SELECT variable_name FROM performance_schema.user_variables_by_thread WHERE variable_value IS NOT NULL"
WARN[0004] error running query                           connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 error="database not found: performance_schema" query="SELECT variable_name FROM performance_schema.user_variables_by_thread WHERE variable_value IS NOT NULL"
DEBU[0004] preparing query                               paramsCount=0 query="SELECT @@foreign_key_checks" statementId=6
DEBU[0004] Starting query                                connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SELECT @@foreign_key_checks"
DEBU[0004] Query finished in 0 ms                        connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SELECT @@foreign_key_checks"
DEBU[0004] preparing query                               paramsCount=0 query="SELECT @@sql_safe_updates" statementId=7
DEBU[0004] Starting query                                connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SELECT @@sql_safe_updates"
DEBU[0004] Query finished in 0 ms                        connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SELECT @@sql_safe_updates"
DEBU[0004] Starting query                                connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SELECT DATABASE()"
DEBU[0004] Query finished in 0 ms                        connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SELECT DATABASE()"
DEBU[0004] Starting query                                connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SELECT DATABASE()"
DEBU[0004] Query finished in 1 ms                        connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SELECT DATABASE()"
DEBU[0004] preparing query                               paramsCount=0 query="SELECT SUBSTRING_INDEX(USER(),'@',1)" statementId=8
DEBU[0004] Starting query                                connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SELECT SUBSTRING_INDEX(USER(),'@',1)"
DEBU[0004] Query finished in 1 ms                        connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SELECT SUBSTRING_INDEX(USER(),'@',1)"
DEBU[0004] Starting query                                connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SELECT version()"
DEBU[0004] Query finished in 0 ms                        connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SELECT version()"
DEBU[0004] preparing query                               paramsCount=1 query="SELECT COUNT(1) FROM information_schema.schemata WHERE schema_name=? LIMIT 1" statementId=9
DEBU[0004] Starting query                                connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SELECT COUNT(1) FROM information_schema.schemata WHERE schema_name=? LIMIT 1"
DEBU[0004] Query finished in 1 ms                        connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SELECT COUNT(1) FROM information_schema.schemata WHERE schema_name=? LIMIT 1"
DEBU[0004] Starting query                                connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SET autocommit=0"
DEBU[0004] Query finished in 0 ms                        connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SET autocommit=0"
DEBU[0004] Starting query                                connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SET foreign_key_checks=1, sql_safe_updates=0"
DEBU[0004] Query finished in 0 ms                        connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SET foreign_key_checks=1, sql_safe_updates=0"
DEBU[0004] Starting query                                connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SELECT TABLE_SCHEMA AS TABLE_CAT, NULL AS TABLE_SCHEM, TABLE_NAME, CASE WHEN TABLE_TYPE='BASE TABLE' THEN CASE WHEN TABLE_SCHEMA = 'mysql' OR TABLE_SCHEMA = 'performance_schema' THEN 'SYSTEM TABLE' ELSE 'TABLE' END WHEN TABLE_TYPE='TEMPORARY' THEN 'LOCAL_TEMPORARY' ELSE TABLE_TYPE END AS TABLE_TYPE, TABLE_COMMENT AS REMARKS, NULL AS TYPE_CAT, NULL AS TYPE_SCHEM, NULL AS TYPE_NAME, NULL AS SELF_REFERENCING_COL_NAME, NULL AS REF_GENERATION FROM INFORMATION_SCHEMA.TABLES WHERE TABLE_SCHEMA = 'restdb' AND TABLE_NAME LIKE 'flyway_schema_history' ORDER BY TABLE_TYPE, TABLE_SCHEMA, TABLE_NAME"
DEBU[0004] Query finished in 2 ms                        connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SELECT TABLE_SCHEMA AS TABLE_CAT, NULL AS TABLE_SCHEM, TABLE_NAME, CASE WHEN TABLE_TYPE='BASE TABLE' THEN CASE WHEN TABLE_SCHEMA = 'mysql' OR TABLE_SCHEMA = 'performance_schema' THEN 'SYSTEM TABLE' ELSE 'TABLE' END WHEN TABLE_TYPE='TEMPORARY' THEN 'LOCAL_TEMPORARY' ELSE TABLE_TYPE END AS TABLE_TYPE, TABLE_COMMENT AS REMARKS, NULL AS TYPE_CAT, NULL AS TYPE_SCHEM, NULL AS TYPE_NAME, NULL AS SELF_REFERENCING_COL_NAME, NULL AS REF_GENERATION FROM INFORMATION_SCHEMA.TABLES WHERE TABLE_SCHEMA = 'restdb' AND TABLE_NAME LIKE 'flyway_schema_history' ORDER BY TABLE_TYPE, TABLE_SCHEMA, TABLE_NAME"
DEBU[0004] Starting query                                connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query=commit
DEBU[0004] Query finished in 0 ms                        connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query=commit
DEBU[0004] Starting query                                connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SET autocommit=1"
DEBU[0004] Query finished in 0 ms                        connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SET autocommit=1"
DEBU[0004] Starting query                                connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SET autocommit=0"
DEBU[0004] Query finished in 0 ms                        connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SET autocommit=0"
DEBU[0004] Starting query                                connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SELECT COUNT(1) FROM information_schema.schemata WHERE schema_name=? LIMIT 1"
DEBU[0004] Query finished in 0 ms                        connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SELECT COUNT(1) FROM information_schema.schemata WHERE schema_name=? LIMIT 1"
DEBU[0004] Starting query                                connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query=commit
DEBU[0004] Query finished in 0 ms                        connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query=commit
DEBU[0004] Starting query                                connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SET autocommit=1"
DEBU[0004] Query finished in 0 ms                        connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SET autocommit=1"
DEBU[0004] Starting query                                connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SET foreign_key_checks=1, sql_safe_updates=0"
DEBU[0004] Query finished in 0 ms                        connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SET foreign_key_checks=1, sql_safe_updates=0"
DEBU[0004] Starting query                                connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SELECT TABLE_SCHEMA AS TABLE_CAT, NULL AS TABLE_SCHEM, TABLE_NAME, CASE WHEN TABLE_TYPE='BASE TABLE' THEN CASE WHEN TABLE_SCHEMA = 'mysql' OR TABLE_SCHEMA = 'performance_schema' THEN 'SYSTEM TABLE' ELSE 'TABLE' END WHEN TABLE_TYPE='TEMPORARY' THEN 'LOCAL_TEMPORARY' ELSE TABLE_TYPE END AS TABLE_TYPE, TABLE_COMMENT AS REMARKS, NULL AS TYPE_CAT, NULL AS TYPE_SCHEM, NULL AS TYPE_NAME, NULL AS SELF_REFERENCING_COL_NAME, NULL AS REF_GENERATION FROM INFORMATION_SCHEMA.TABLES WHERE TABLE_SCHEMA = 'restdb' AND TABLE_NAME LIKE 'flyway_schema_history' ORDER BY TABLE_TYPE, TABLE_SCHEMA, TABLE_NAME"
DEBU[0004] Query finished in 1 ms                        connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SELECT TABLE_SCHEMA AS TABLE_CAT, NULL AS TABLE_SCHEM, TABLE_NAME, CASE WHEN TABLE_TYPE='BASE TABLE' THEN CASE WHEN TABLE_SCHEMA = 'mysql' OR TABLE_SCHEMA = 'performance_schema' THEN 'SYSTEM TABLE' ELSE 'TABLE' END WHEN TABLE_TYPE='TEMPORARY' THEN 'LOCAL_TEMPORARY' ELSE TABLE_TYPE END AS TABLE_TYPE, TABLE_COMMENT AS REMARKS, NULL AS TYPE_CAT, NULL AS TYPE_SCHEM, NULL AS TYPE_NAME, NULL AS SELF_REFERENCING_COL_NAME, NULL AS REF_GENERATION FROM INFORMATION_SCHEMA.TABLES WHERE TABLE_SCHEMA = 'restdb' AND TABLE_NAME LIKE 'flyway_schema_history' ORDER BY TABLE_TYPE, TABLE_SCHEMA, TABLE_NAME"
DEBU[0004] Starting query                                connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SELECT COUNT(1) FROM information_schema.schemata WHERE schema_name=? LIMIT 1"
DEBU[0004] Query finished in 0 ms                        connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SELECT COUNT(1) FROM information_schema.schemata WHERE schema_name=? LIMIT 1"
DEBU[0004] preparing query                               paramsCount=6 query="SELECT SUM(found) FROM ((SELECT 1 as found FROM information_schema.tables WHERE table_schema=?) UNION ALL (SELECT 1 as found FROM information_schema.views WHERE table_schema=? LIMIT 1) UNION ALL (SELECT 1 as found FROM information_schema.table_constraints WHERE table_schema=? LIMIT 1) UNION ALL (SELECT 1 as found FROM information_schema.triggers WHERE event_object_schema=?  LIMIT 1) UNION ALL (SELECT 1 as found FROM information_schema.routines WHERE routine_schema=? LIMIT 1) UNION ALL (SELECT 1 as found FROM information_schema.events WHERE event_schema=? LIMIT 1)) as all_found" statementId=10
DEBU[0004] Starting query                                connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SELECT SUM(found) FROM ((SELECT 1 as found FROM information_schema.tables WHERE table_schema=?) UNION ALL (SELECT 1 as found FROM information_schema.views WHERE table_schema=? LIMIT 1) UNION ALL (SELECT 1 as found FROM information_schema.table_constraints WHERE table_schema=? LIMIT 1) UNION ALL (SELECT 1 as found FROM information_schema.triggers WHERE event_object_schema=? LIMIT 1) UNION ALL (SELECT 1 as found FROM information_schema.routines WHERE routine_schema=? LIMIT 1) UNION ALL (SELECT 1 as found FROM information_schema.events WHERE event_schema=? LIMIT 1)) as all_found"
WARN[0004] error running query                           connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 error="command denied to user 'restadmin'@'%'" query="SELECT SUM(found) FROM ((SELECT 1 as found FROM information_schema.tables WHERE table_schema=?) UNION ALL (SELECT 1 as found FROM information_schema.views WHERE table_schema=? LIMIT 1) UNION ALL (SELECT 1 as found FROM information_schema.table_constraints WHERE table_schema=? LIMIT 1) UNION ALL (SELECT 1 as found FROM information_schema.triggers WHERE event_object_schema=? LIMIT 1) UNION ALL (SELECT 1 as found FROM information_schema.routines WHERE routine_schema=? LIMIT 1) UNION ALL (SELECT 1 as found FROM information_schema.events WHERE event_schema=? LIMIT 1)) as all_found"
DEBU[0004] Starting query                                connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SET foreign_key_checks=1, sql_safe_updates=0"
DEBU[0004] Query finished in 0 ms                        connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SET foreign_key_checks=1, sql_safe_updates=0"
DEBU[0004] Starting query                                connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SET autocommit=0"
DEBU[0004] Query finished in 0 ms                        connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SET autocommit=0"
DEBU[0004] Starting query                                connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query=commit
DEBU[0004] Query finished in 0 ms                        connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query=commit
DEBU[0004] Starting query                                connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SET autocommit=1"
DEBU[0004] Query finished in 0 ms                        connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SET autocommit=1"
INFO[0004] ConnectionClosed                              connectionID=1
INFO[0004] ConnectionClosed                              connectionID=2
INFO[0004] ConnectionClosed                              connectionID=3
INFO[0004] ConnectionClosed                              connectionID=4
INFO[0004] ConnectionClosed                              connectionID=5
DEBU[0004] preparing query                               paramsCount=0 query="SELECT version()" statementId=1
DEBU[0004] Starting query                                connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SELECT version()"
DEBU[0004] Query finished in 0 ms                        connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SELECT version()"
INFO[0004] NewConnection                                 DisableClientMultiStatements=false connectionID=5
DEBU[0004] Starting query                                connectTime="2024-06-25 20:50:42.669171 +0200 CEST m=+4.729420668" connectionDb=restdb connectionID=5 query="SET character_set_results = NULL"
DEBU[0004] Query finished in 0 ms                        connectTime="2024-06-25 20:50:42.669171 +0200 CEST m=+4.729420668" connectionDb=restdb connectionID=5 query="SET character_set_results = NULL"
DEBU[0004] preparing query                               paramsCount=0 query="select VARIABLE_VALUE from performance_schema.global_variables where variable_name = 'pxc_strict_mode'" statementId=2
ERRO[0004] unable to prepare query: database not found: performance_schema  query="select VARIABLE_VALUE from performance_schema.global_variables where variable_name = 'pxc_strict_mode'"
ERRO[0004] unable to prepare query: database not found: performance_schema (errno 1049) (sqlstate HY000)
DEBU[0004] Starting query                                connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="select VARIABLE_VALUE from performance_schema.global_variables where variable_name = 'pxc_strict_mode'"
WARN[0004] error running query                           connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 error="database not found: performance_schema" query="select VARIABLE_VALUE from performance_schema.global_variables where variable_name = 'pxc_strict_mode'"
DEBU[0004] preparing query                               paramsCount=0 query="SELECT @@GLOBAL.ENFORCE_GTID_CONSISTENCY" statementId=3
DEBU[0004] Starting query                                connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SELECT @@GLOBAL.ENFORCE_GTID_CONSISTENCY"
DEBU[0004] Query finished in 0 ms                        connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SELECT @@GLOBAL.ENFORCE_GTID_CONSISTENCY"
DEBU[0004] preparing query                               paramsCount=0 query="SELECT DATABASE()" statementId=4
DEBU[0004] Starting query                                connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SELECT DATABASE()"
DEBU[0004] Query finished in 0 ms                        connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SELECT DATABASE()"
DEBU[0004] preparing query                               paramsCount=0 query="SELECT variable_name FROM performance_schema.user_variables_by_thread WHERE variable_value IS NOT NULL" statementId=5
ERRO[0004] unable to prepare query: database not found: performance_schema  query="SELECT variable_name FROM performance_schema.user_variables_by_thread WHERE variable_value IS NOT NULL"
ERRO[0004] unable to prepare query: database not found: performance_schema (errno 1049) (sqlstate HY000)
DEBU[0004] Starting query                                connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SELECT variable_name FROM performance_schema.user_variables_by_thread WHERE variable_value IS NOT NULL"
WARN[0004] error running query                           connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 error="database not found: performance_schema" query="SELECT variable_name FROM performance_schema.user_variables_by_thread WHERE variable_value IS NOT NULL"
DEBU[0004] preparing query                               paramsCount=0 query="SELECT @@foreign_key_checks" statementId=6
DEBU[0004] Starting query                                connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SELECT @@foreign_key_checks"
DEBU[0004] Query finished in 0 ms                        connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SELECT @@foreign_key_checks"
DEBU[0004] preparing query                               paramsCount=0 query="SELECT @@sql_safe_updates" statementId=7
DEBU[0004] Starting query                                connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SELECT @@sql_safe_updates"
DEBU[0004] Query finished in 0 ms                        connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SELECT @@sql_safe_updates"
DEBU[0004] Starting query                                connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SELECT DATABASE()"
DEBU[0004] Query finished in 0 ms                        connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SELECT DATABASE()"
DEBU[0004] Starting query                                connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SELECT DATABASE()"
DEBU[0004] Query finished in 1 ms                        connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SELECT DATABASE()"
DEBU[0004] preparing query                               paramsCount=0 query="SELECT SUBSTRING_INDEX(USER(),'@',1)" statementId=8
DEBU[0004] Starting query                                connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SELECT SUBSTRING_INDEX(USER(),'@',1)"
DEBU[0004] Query finished in 1 ms                        connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SELECT SUBSTRING_INDEX(USER(),'@',1)"
DEBU[0004] Starting query                                connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SELECT version()"
DEBU[0004] Query finished in 0 ms                        connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SELECT version()"
DEBU[0004] preparing query                               paramsCount=1 query="SELECT COUNT(1) FROM information_schema.schemata WHERE schema_name=? LIMIT 1" statementId=9
DEBU[0004] Starting query                                connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SELECT COUNT(1) FROM information_schema.schemata WHERE schema_name=? LIMIT 1"
DEBU[0004] Query finished in 1 ms                        connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SELECT COUNT(1) FROM information_schema.schemata WHERE schema_name=? LIMIT 1"
DEBU[0004] Starting query                                connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SET autocommit=0"
DEBU[0004] Query finished in 0 ms                        connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SET autocommit=0"
DEBU[0004] Starting query                                connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SET foreign_key_checks=1, sql_safe_updates=0"
DEBU[0004] Query finished in 0 ms                        connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SET foreign_key_checks=1, sql_safe_updates=0"
DEBU[0004] Starting query                                connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SELECT TABLE_SCHEMA AS TABLE_CAT, NULL AS TABLE_SCHEM, TABLE_NAME, CASE WHEN TABLE_TYPE='BASE TABLE' THEN CASE WHEN TABLE_SCHEMA = 'mysql' OR TABLE_SCHEMA = 'performance_schema' THEN 'SYSTEM TABLE' ELSE 'TABLE' END WHEN TABLE_TYPE='TEMPORARY' THEN 'LOCAL_TEMPORARY' ELSE TABLE_TYPE END AS TABLE_TYPE, TABLE_COMMENT AS REMARKS, NULL AS TYPE_CAT, NULL AS TYPE_SCHEM, NULL AS TYPE_NAME, NULL AS SELF_REFERENCING_COL_NAME, NULL AS REF_GENERATION FROM INFORMATION_SCHEMA.TABLES WHERE TABLE_SCHEMA = 'restdb' AND TABLE_NAME LIKE 'flyway_schema_history' ORDER BY TABLE_TYPE, TABLE_SCHEMA, TABLE_NAME"
DEBU[0004] Query finished in 2 ms                        connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SELECT TABLE_SCHEMA AS TABLE_CAT, NULL AS TABLE_SCHEM, TABLE_NAME, CASE WHEN TABLE_TYPE='BASE TABLE' THEN CASE WHEN TABLE_SCHEMA = 'mysql' OR TABLE_SCHEMA = 'performance_schema' THEN 'SYSTEM TABLE' ELSE 'TABLE' END WHEN TABLE_TYPE='TEMPORARY' THEN 'LOCAL_TEMPORARY' ELSE TABLE_TYPE END AS TABLE_TYPE, TABLE_COMMENT AS REMARKS, NULL AS TYPE_CAT, NULL AS TYPE_SCHEM, NULL AS TYPE_NAME, NULL AS SELF_REFERENCING_COL_NAME, NULL AS REF_GENERATION FROM INFORMATION_SCHEMA.TABLES WHERE TABLE_SCHEMA = 'restdb' AND TABLE_NAME LIKE 'flyway_schema_history' ORDER BY TABLE_TYPE, TABLE_SCHEMA, TABLE_NAME"
DEBU[0004] Starting query                                connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query=commit
DEBU[0004] Query finished in 0 ms                        connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query=commit
DEBU[0004] Starting query                                connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SET autocommit=1"
DEBU[0004] Query finished in 0 ms                        connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SET autocommit=1"
DEBU[0004] Starting query                                connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SET autocommit=0"
DEBU[0004] Query finished in 0 ms                        connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SET autocommit=0"
DEBU[0004] Starting query                                connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SELECT COUNT(1) FROM information_schema.schemata WHERE schema_name=? LIMIT 1"
DEBU[0004] Query finished in 0 ms                        connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SELECT COUNT(1) FROM information_schema.schemata WHERE schema_name=? LIMIT 1"
DEBU[0004] Starting query                                connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query=commit
DEBU[0004] Query finished in 0 ms                        connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query=commit
DEBU[0004] Starting query                                connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SET autocommit=1"
DEBU[0004] Query finished in 0 ms                        connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SET autocommit=1"
DEBU[0004] Starting query                                connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SET foreign_key_checks=1, sql_safe_updates=0"
DEBU[0004] Query finished in 0 ms                        connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SET foreign_key_checks=1, sql_safe_updates=0"
DEBU[0004] Starting query                                connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SELECT TABLE_SCHEMA AS TABLE_CAT, NULL AS TABLE_SCHEM, TABLE_NAME, CASE WHEN TABLE_TYPE='BASE TABLE' THEN CASE WHEN TABLE_SCHEMA = 'mysql' OR TABLE_SCHEMA = 'performance_schema' THEN 'SYSTEM TABLE' ELSE 'TABLE' END WHEN TABLE_TYPE='TEMPORARY' THEN 'LOCAL_TEMPORARY' ELSE TABLE_TYPE END AS TABLE_TYPE, TABLE_COMMENT AS REMARKS, NULL AS TYPE_CAT, NULL AS TYPE_SCHEM, NULL AS TYPE_NAME, NULL AS SELF_REFERENCING_COL_NAME, NULL AS REF_GENERATION FROM INFORMATION_SCHEMA.TABLES WHERE TABLE_SCHEMA = 'restdb' AND TABLE_NAME LIKE 'flyway_schema_history' ORDER BY TABLE_TYPE, TABLE_SCHEMA, TABLE_NAME"
DEBU[0004] Query finished in 1 ms                        connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SELECT TABLE_SCHEMA AS TABLE_CAT, NULL AS TABLE_SCHEM, TABLE_NAME, CASE WHEN TABLE_TYPE='BASE TABLE' THEN CASE WHEN TABLE_SCHEMA = 'mysql' OR TABLE_SCHEMA = 'performance_schema' THEN 'SYSTEM TABLE' ELSE 'TABLE' END WHEN TABLE_TYPE='TEMPORARY' THEN 'LOCAL_TEMPORARY' ELSE TABLE_TYPE END AS TABLE_TYPE, TABLE_COMMENT AS REMARKS, NULL AS TYPE_CAT, NULL AS TYPE_SCHEM, NULL AS TYPE_NAME, NULL AS SELF_REFERENCING_COL_NAME, NULL AS REF_GENERATION FROM INFORMATION_SCHEMA.TABLES WHERE TABLE_SCHEMA = 'restdb' AND TABLE_NAME LIKE 'flyway_schema_history' ORDER BY TABLE_TYPE, TABLE_SCHEMA, TABLE_NAME"
DEBU[0004] Starting query                                connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SELECT COUNT(1) FROM information_schema.schemata WHERE schema_name=? LIMIT 1"
DEBU[0004] Query finished in 0 ms                        connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SELECT COUNT(1) FROM information_schema.schemata WHERE schema_name=? LIMIT 1"
DEBU[0004] preparing query                               paramsCount=6 query="SELECT SUM(found) FROM ((SELECT 1 as found FROM information_schema.tables WHERE table_schema=?) UNION ALL (SELECT 1 as found FROM information_schema.views WHERE table_schema=? LIMIT 1) UNION ALL (SELECT 1 as found FROM information_schema.table_constraints WHERE table_schema=? LIMIT 1) UNION ALL (SELECT 1 as found FROM information_schema.triggers WHERE event_object_schema=?  LIMIT 1) UNION ALL (SELECT 1 as found FROM information_schema.routines WHERE routine_schema=? LIMIT 1) UNION ALL (SELECT 1 as found FROM information_schema.events WHERE event_schema=? LIMIT 1)) as all_found" statementId=10
DEBU[0004] Starting query                                connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SELECT SUM(found) FROM ((SELECT 1 as found FROM information_schema.tables WHERE table_schema=?) UNION ALL (SELECT 1 as found FROM information_schema.views WHERE table_schema=? LIMIT 1) UNION ALL (SELECT 1 as found FROM information_schema.table_constraints WHERE table_schema=? LIMIT 1) UNION ALL (SELECT 1 as found FROM information_schema.triggers WHERE event_object_schema=? LIMIT 1) UNION ALL (SELECT 1 as found FROM information_schema.routines WHERE routine_schema=? LIMIT 1) UNION ALL (SELECT 1 as found FROM information_schema.events WHERE event_schema=? LIMIT 1)) as all_found"
WARN[0004] error running query                           connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 error="command denied to user 'restadmin'@'%'" query="SELECT SUM(found) FROM ((SELECT 1 as found FROM information_schema.tables WHERE table_schema=?) UNION ALL (SELECT 1 as found FROM information_schema.views WHERE table_schema=? LIMIT 1) UNION ALL (SELECT 1 as found FROM information_schema.table_constraints WHERE table_schema=? LIMIT 1) UNION ALL (SELECT 1 as found FROM information_schema.triggers WHERE event_object_schema=? LIMIT 1) UNION ALL (SELECT 1 as found FROM information_schema.routines WHERE routine_schema=? LIMIT 1) UNION ALL (SELECT 1 as found FROM information_schema.events WHERE event_schema=? LIMIT 1)) as all_found"
DEBU[0004] Starting query                                connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SET foreign_key_checks=1, sql_safe_updates=0"
DEBU[0004] Query finished in 0 ms                        connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SET foreign_key_checks=1, sql_safe_updates=0"
DEBU[0004] Starting query                                connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SET autocommit=0"
DEBU[0004] Query finished in 0 ms                        connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SET autocommit=0"
DEBU[0004] Starting query                                connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query=commit
DEBU[0004] Query finished in 0 ms                        connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query=commit
DEBU[0004] Starting query                                connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SET autocommit=1"
DEBU[0004] Query finished in 0 ms                        connectTime="2024-06-25 20:50:42.493981 +0200 CEST m=+4.554230626" connectionDb=restdb connectionID=1 query="SET autocommit=1"
INFO[0004] ConnectionClosed                              connectionID=1
INFO[0004] ConnectionClosed                              connectionID=2
INFO[0004] ConnectionClosed                              connectionID=3
INFO[0004] ConnectionClosed                              connectionID=4
INFO[0004] ConnectionClosed                              connectionID=5
muescha commented 3 weeks ago

PS: maybe it would be nice to have on each db error always show the sql statement which throws the error?

For example for this error:

WARN[0007] error running query                           connectTime="2024-06-25 20:47:07.737013 +0200 CEST m=+6.979886084" connectionDb=restdb connectionID=1 error="command denied to user 'restadmin'@'%'"
muescha commented 3 weeks ago

I see the query/command logged at the info level only when it logs as an error (ERRO), but not when it logs as a warning (WARN).

In this case there was a WARN but no ERRO

fulghum commented 3 weeks ago

Ahh, excellent! Thanks for confirming with the logs. 🙏 Glad to see that those performance_schema queries aren't causing Flyway to crash. I can see how those error messages in the Dolt logs are a bit confusing since there are a few queries being executed that fail and some of them are gracefully handled by the application, but not all.

We generally don't include any queries in the logs at the INFO level – we reserve that for DEBUG level, just due to the amount of data written to the logs, but I can see a case for ERRORs to include the query string. I'll take a look in the logging code today and see what I can do.

Thanks for following up with more clues and helping us figure this one out.

muescha commented 3 weeks ago

With an ERRO, the query is included.

If you look at the INFO log level above, for the message command denied to user 'restadmin'@'%', you'll see that at the WARN level there was no preceding ERRO entry.

It seems some WARN entries do not have a previous ERRO.

muescha commented 2 weeks ago

FYI: with 1.41.1 the flyway run without error

Maybe we can close this issue and create a new one for the missing ERRO for some WARN?

fulghum commented 2 weeks ago

Awesome! I was just about to message you and let you 1.41.1 went out last night with the fix for https://github.com/dolthub/dolt/issues/8052 . Glad you found the release already and thank you for testing and confirming Flyway is working for you now! 🎉 🙏

Good suggestion to close out this issue and follow up with a separate issue for the query logging for errors. I'll go ahead and resolve this one and we can use https://github.com/dolthub/dolt/issues/8074 to track the logging improvement.