Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

DB created successfully but failure returned #1598

Open
CrazyNash opened this issue Jul 9, 2018 · 2 comments
Open

DB created successfully but failure returned #1598

CrazyNash opened this issue Jul 9, 2018 · 2 comments

Comments

@CrazyNash
Copy link

If you are submitting a reproducible bug report, please provide:
[ ] A clear description of your issue

DB created successfully but error returned.

[ ] The version of OS and ProxySQL

CentOS 7.2 v1.4.8

[ ] Every step to reproduce the issue

Deploy and start TiDB, proxysql, and scripts in the short time.
in the script:
show database like grafana
create it if it doesn't exist.

[set up]

  1. my same script run from two servers
  2. two instances proxysql set up above TiDB
  3. three PD + three tidb + three tikv setup for TiDB

[my scrip log from 172.28.245.61]

2018-07-02 11:41:16 show databases like 'grafana';
2018-07-02 11:41:21 Database grafana
2018-07-02 11:41:21 DB exists already, sleep 150s to make sure the other node has complete import operations

[my script log from 172.18.180.138]

2018-07-02 11:41:15 show databases like 'grafana';
2018-07-02 11:41:20
2018-07-02 11:41:20 DB doesn't exist, create it first
2018-07-02 11:41:21 ERROR 1007 (HY000) at line 1: Can't create database 'grafana'; database exists
ERROR 1007 (HY000) at line 1: Can't create database 'grafana'; database exists

[Here is log from first instance of proxysql]

2018-07-02 19:40:53 mysql_connection.cpp:628:handler(): [ERROR] Failed to mysql_real_connect() on 172.27.176.239:10353 , FD (Conn:0 , MyDS:25) , 2003: Can't connect to MySQL server on '172.27.176.239' (107).
2018-07-02 19:40:53 mysql_connection.cpp:628:handler(): [ERROR] Failed to mysql_real_connect() on 172.28.245.54:10369 , FD (Conn:25 , MyDS:25) , 2013: Lost connection to MySQL server at 'handshake: reading inital communication packet', system error: 107.
2018-07-02 19:40:53 mysql_connection.cpp:628:handler(): [ERROR] Failed to mysql_real_connect() on 172.18.130.72:10373 , FD (Conn:25 , MyDS:25) , 2013: Lost connection to MySQL server at 'handshake: reading inital communication packet', system error: 107.
2018-07-02 19:40:53 mysql_connection.cpp:628:handler(): [ERROR] Failed to mysql_real_connect() on 172.18.130.72:10373 , FD (Conn:25 , MyDS:25) , 2013: Lost connection to MySQL server at 'handshake: reading inital communication packet', system error: 107.
2018-07-02 19:40:53 mysql_connection.cpp:628:handler(): [ERROR] Failed to mysql_real_connect() on 172.27.176.239:10353 , FD (Conn:25 , MyDS:25) , 2013: Lost connection to MySQL server at 'handshake: reading inital communication packet', system error: 107.
2018-07-02 19:40:53 mysql_connection.cpp:628:handler(): [ERROR] Failed to mysql_real_connect() on 172.18.130.72:10373 , FD (Conn:25 , MyDS:25) , 2013: Lost connection to MySQL server at 'handshake: reading inital communication packet', system error: 107.
2018-07-02 19:40:53 MySQL_HostGroups_Manager.cpp:302:connect_error(): [ERROR] Shunning server 172.18.130.72:10373 with 5 errors/sec. Shunning for 10 seconds
2018-07-02 19:40:53 mysql_connection.cpp:628:handler(): [ERROR] Failed to mysql_real_connect() on 172.27.176.239:10353 , FD (Conn:25 , MyDS:25) , 2013: Lost connection to MySQL server at 'handshake: reading inital communication packet', system error: 107.
2018-07-02 19:40:53 MySQL_HostGroups_Manager.cpp:302:connect_error(): [ERROR] Shunning server 172.27.176.239:10353 with 5 errors/sec. Shunning for 10 seconds
2018-07-02 19:40:53 mysql_connection.cpp:628:handler(): [ERROR] Failed to mysql_real_connect() on 172.28.245.54:10369 , FD (Conn:25 , MyDS:25) , 2013: Lost connection to MySQL server at 'handshake: reading inital communication packet', system error: 107.
2018-07-02 19:40:53 mysql_connection.cpp:628:handler(): [ERROR] Failed to mysql_real_connect() on 172.28.245.54:10369 , FD (Conn:25 , MyDS:25) , 2013: Lost connection to MySQL server at 'handshake: reading inital communication packet', system error: 107.
2018-07-02 19:40:53 MySQL_HostGroups_Manager.cpp:302:connect_error(): [ERROR] Shunning server 172.28.245.54:10369 with 5 errors/sec. Shunning for 10 seconds
2018-07-02 19:41:03 mysql_connection.cpp:628:handler(): [ERROR] Failed to mysql_real_connect() on 172.28.245.54:10369 , FD (Conn:25 , MyDS:25) , 2013: Lost connection to MySQL server at 'handshake: reading inital communication packet', system error: 107.
2018-07-02 19:41:03 mysql_connection.cpp:628:handler(): [ERROR] Failed to mysql_real_connect() on 172.28.245.54:10369 , FD (Conn:25 , MyDS:25) , 2013: Lost connection to MySQL server at 'handshake: reading inital communication packet', system error: 107.
2018-07-02 19:41:04 mysql_connection.cpp:628:handler(): [ERROR] Failed to mysql_real_connect() on 172.27.176.239:10353 , FD (Conn:0 , MyDS:25) , 2003: Can't connect to MySQL server on '172.27.176.239' (107).
2018-07-02 19:41:04 mysql_connection.cpp:628:handler(): [ERROR] Failed to mysql_real_connect() on 172.28.245.54:10369 , FD (Conn:25 , MyDS:25) , 2013: Lost connection to MySQL server at 'handshake: reading inital communication packet', system error: 107.
2018-07-02 19:41:04 mysql_connection.cpp:628:handler(): [ERROR] Failed to mysql_real_connect() on 172.18.130.72:10373 , FD (Conn:25 , MyDS:25) , 2013: Lost connection to MySQL server at 'handshake: reading inital communication packet', system error: 107.
2018-07-02 19:41:04 mysql_connection.cpp:628:handler(): [ERROR] Failed to mysql_real_connect() on 172.18.130.72:10373 , FD (Conn:25 , MyDS:25) , 2013: Lost connection to MySQL server at 'handshake: reading inital communication packet', system error: 107.
2018-07-02 19:41:04 mysql_connection.cpp:628:handler(): [ERROR] Failed to mysql_real_connect() on 172.27.176.239:10353 , FD (Conn:25 , MyDS:25) , 2013: Lost connection to MySQL server at 'handshake: reading inital communication packet', system error: 107.
2018-07-02 19:41:04 mysql_connection.cpp:628:handler(): [ERROR] Failed to mysql_real_connect() on 172.18.130.72:10373 , FD (Conn:25 , MyDS:25) , 2013: Lost connection to MySQL server at 'handshake: reading inital communication packet', system error: 107.
2018-07-02 19:41:04 MySQL_HostGroups_Manager.cpp:302:connect_error(): [ERROR] Shunning server 172.18.130.72:10373 with 5 errors/sec. Shunning for 10 seconds
2018-07-02 19:41:04 mysql_connection.cpp:628:handler(): [ERROR] Failed to mysql_real_connect() on 172.27.176.239:10353 , FD (Conn:25 , MyDS:25) , 2013: Lost connection to MySQL server at 'handshake: reading inital communication packet', system error: 107.
2018-07-02 19:41:04 MySQL_HostGroups_Manager.cpp:302:connect_error(): [ERROR] Shunning server 172.27.176.239:10353 with 5 errors/sec. Shunning for 10 seconds
2018-07-02 19:41:04 mysql_connection.cpp:628:handler(): [ERROR] Failed to mysql_real_connect() on 172.28.245.54:10369 , FD (Conn:25 , MyDS:25) , 2013: Lost connection to MySQL server at 'handshake: reading inital communication packet', system error: 107.
2018-07-02 19:41:04 mysql_connection.cpp:628:handler(): [ERROR] Failed to mysql_real_connect() on 172.28.245.54:10369 , FD (Conn:25 , MyDS:25) , 2013: Lost connection to MySQL server at 'handshake: reading inital communication packet', system error: 107.
2018-07-02 19:41:04 MySQL_HostGroups_Manager.cpp:302:connect_error(): [ERROR] Shunning server 172.28.245.54:10369 with 5 errors/sec. Shunning for 10 seconds
2018-07-02 19:41:21 MySQL_Monitor.cpp:1419:monitor_ping(): [ERROR] Server 172.27.176.239:10353 missed 3 heartbeats, shunning it and killing all the connections. Disabling other checks until the node comes back online.

[Here is log from second instance of proxysql]

2018-07-02 19:40:52 mysql_connection.cpp:628:handler(): [ERROR] Failed to mysql_real_connect() on 172.28.245.54:10369 , FD (Conn:25 , MyDS:25) , 2013: Lost connection to MySQL server at 'handshake: reading inital communication packet', system error: 107.
2018-07-02 19:40:52 mysql_connection.cpp:628:handler(): [ERROR] Failed to mysql_real_connect() on 172.18.130.72:10373 , FD (Conn:25 , MyDS:25) , 2013: Lost connection to MySQL server at 'handshake: reading inital communication packet', system error: 107.
2018-07-02 19:40:52 mysql_connection.cpp:628:handler(): [ERROR] Failed to mysql_real_connect() on 172.18.130.72:10373 , FD (Conn:25 , MyDS:25) , 2013: Lost connection to MySQL server at 'handshake: reading inital communication packet', system error: 107.
2018-07-02 19:40:52 mysql_connection.cpp:628:handler(): [ERROR] Failed to mysql_real_connect() on 172.27.176.239:10353 , FD (Conn:25 , MyDS:25) , 2013: Lost connection to MySQL server at 'handshake: reading inital communication packet', system error: 107.
2018-07-02 19:40:52 mysql_connection.cpp:628:handler(): [ERROR] Failed to mysql_real_connect() on 172.18.130.72:10373 , FD (Conn:25 , MyDS:25) , 2013: Lost connection to MySQL server at 'handshake: reading inital communication packet', system error: 107.
2018-07-02 19:40:52 MySQL_HostGroups_Manager.cpp:302:connect_error(): [ERROR] Shunning server 172.18.130.72:10373 with 5 errors/sec. Shunning for 10 seconds
2018-07-02 19:40:52 mysql_connection.cpp:628:handler(): [ERROR] Failed to mysql_real_connect() on 172.27.176.239:10353 , FD (Conn:25 , MyDS:25) , 2013: Lost connection to MySQL server at 'handshake: reading inital communication packet', system error: 107.
2018-07-02 19:40:52 MySQL_HostGroups_Manager.cpp:302:connect_error(): [ERROR] Shunning server 172.27.176.239:10353 with 5 errors/sec. Shunning for 10 seconds
2018-07-02 19:40:52 mysql_connection.cpp:628:handler(): [ERROR] Failed to mysql_real_connect() on 172.28.245.54:10369 , FD (Conn:25 , MyDS:25) , 2013: Lost connection to MySQL server at 'handshake: reading inital communication packet', system error: 107.
2018-07-02 19:40:52 mysql_connection.cpp:628:handler(): [ERROR] Failed to mysql_real_connect() on 172.28.245.54:10369 , FD (Conn:25 , MyDS:25) , 2013: Lost connection to MySQL server at 'handshake: reading inital communication packet', system error: 107.
2018-07-02 19:40:52 MySQL_HostGroups_Manager.cpp:302:connect_error(): [ERROR] Shunning server 172.28.245.54:10369 with 5 errors/sec. Shunning for 10 seconds
2018-07-02 19:41:02 mysql_connection.cpp:628:handler(): [ERROR] Failed to mysql_real_connect() on 172.28.245.54:10369 , FD (Conn:25 , MyDS:25) , 2013: Lost connection to MySQL server at 'handshake: reading inital communication packet', system error: 107.
2018-07-02 19:41:02 mysql_connection.cpp:628:handler(): [ERROR] Failed to mysql_real_connect() on 172.28.245.54:10369 , FD (Conn:25 , MyDS:25) , 2013: Lost connection to MySQL server at 'handshake: reading inital communication packet', system error: 107.
2018-07-02 19:41:03 mysql_connection.cpp:628:handler(): [ERROR] Failed to mysql_real_connect() on 172.27.176.239:10353 , FD (Conn:0 , MyDS:25) , 2003: Can't connect to MySQL server on '172.27.176.239' (107).
2018-07-02 19:41:03 mysql_connection.cpp:628:handler(): [ERROR] Failed to mysql_real_connect() on 172.28.245.54:10369 , FD (Conn:25 , MyDS:25) , 2013: Lost connection to MySQL server at 'handshake: reading inital communication packet', system error: 107.
2018-07-02 19:41:03 mysql_connection.cpp:628:handler(): [ERROR] Failed to mysql_real_connect() on 172.18.130.72:10373 , FD (Conn:25 , MyDS:25) , 2013: Lost connection to MySQL server at 'handshake: reading inital communication packet', system error: 107.
2018-07-02 19:41:03 mysql_connection.cpp:628:handler(): [ERROR] Failed to mysql_real_connect() on 172.18.130.72:10373 , FD (Conn:25 , MyDS:25) , 2013: Lost connection to MySQL server at 'handshake: reading inital communication packet', system error: 107.
2018-07-02 19:41:03 mysql_connection.cpp:628:handler(): [ERROR] Failed to mysql_real_connect() on 172.27.176.239:10353 , FD (Conn:25 , MyDS:25) , 2013: Lost connection to MySQL server at 'handshake: reading inital communication packet', system error: 107.
2018-07-02 19:41:03 mysql_connection.cpp:628:handler(): [ERROR] Failed to mysql_real_connect() on 172.18.130.72:10373 , FD (Conn:25 , MyDS:25) , 2013: Lost connection to MySQL server at 'handshake: reading inital communication packet', system error: 107.
2018-07-02 19:41:03 MySQL_HostGroups_Manager.cpp:302:connect_error(): [ERROR] Shunning server 172.18.130.72:10373 with 5 errors/sec. Shunning for 10 seconds
2018-07-02 19:41:03 mysql_connection.cpp:628:handler(): [ERROR] Failed to mysql_real_connect() on 172.27.176.239:10353 , FD (Conn:25 , MyDS:25) , 2013: Lost connection to MySQL server at 'handshake: reading inital communication packet', system error: 107.
2018-07-02 19:41:03 MySQL_HostGroups_Manager.cpp:302:connect_error(): [ERROR] Shunning server 172.27.176.239:10353 with 5 errors/sec. Shunning for 10 seconds
2018-07-02 19:41:03 mysql_connection.cpp:628:handler(): [ERROR] Failed to mysql_real_connect() on 172.28.245.54:10369 , FD (Conn:25 , MyDS:25) , 2013: Lost connection to MySQL server at 'handshake: reading inital communication packet', system error: 107.
2018-07-02 19:41:03 mysql_connection.cpp:628:handler(): [ERROR] Failed to mysql_real_connect() on 172.28.245.54:10369 , FD (Conn:25 , MyDS:25) , 2013: Lost connection to MySQL server at 'handshake: reading inital communication packet', system error: 107.
2018-07-02 19:41:03 MySQL_HostGroups_Manager.cpp:302:connect_error(): [ERROR] Shunning server 172.28.245.54:10369 with 5 errors/sec. Shunning for 10 seconds
2018-07-02 19:41:20 MySQL_Monitor.cpp:1419:monitor_ping(): [ERROR] Server 172.28.245.54:10369 missed 3 heartbeats, shunning it and killing all the connections. Disabling other checks until the node comes back online.
2018-07-02 19:41:20 MySQL_Monitor.cpp:1419:monitor_ping(): [ERROR] Server 172.27.176.239:10353 missed 3 heartbeats, shunning it and killing all the connections. Disabling other checks until the node comes back online.
2018-07-02 19:41:21 MySQL_Session.cpp:2777:handler(): [ERROR] Detected an offline server during query: 172.28.245.54, 10369
2018-07-02 19:41:21 MySQL_Session.cpp:2785:handler(): [WARNING] Retrying query.
2018-07-02 19:41:21 MySQL_Session.cpp:2863:handler(): [WARNING] Error during query on (0,172.18.130.72,10373): 1007, Can't create database 'grafana'; database exists
2018-07-02 19:43:55 MySQL_Session.cpp:2863:handler(): [WARNING] Error during query on (0,172.28.245.54,10369): 1061, index already exist UQE_user_login
2018-07-02 19:46:33 MySQL_Session.cpp:2863:handler(): [WARNING] Error during query on (0,172.27.176.239,10353): 1061, index already exist IDX_alert_org_id_id
[root@bj-fty-wakanda-180-138 ~]#

[log from first tidb]

2018/07/02 19:41:20.214 server.go:303: [info] [con:1] new connection 172.18.180.138:50796
2018/07/02 19:41:20.218 set.go:181: [info] [con:1] set system variable wait_timeout = 100
2018/07/02 19:41:20.500 ddl_worker.go:342: [info] [ddl] run DDL job ID:46, Type:create schema, State:none, SchemaState:none, SchemaID:45, TableID:0, RowCount:0, ArgLen:0, start time: 2018-07-02 

19:41:20.157 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0
2018/07/02 19:41:20.515 domain.go:102: [info] [ddl] diff load InfoSchema from version 15 to 16, in 846.792µs
2018/07/02 19:41:20.566 ddl_worker.go:476: [info] [ddl] wait latest schema version 16 changed, take time 55.625858ms
2018/07/02 19:41:20.569 ddl_worker.go:217: [info] [ddl] finish DDL job ID:46, Type:create schema, State:synced, SchemaState:public, SchemaID:45, TableID:0, RowCount:0, ArgLen:0, start time: 2018-

07-02 19:41:20.157 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0
2018/07/02 19:41:21.007 server.go:303: [info] [con:2] new connection 172.28.245.61:47238
2018/07/02 19:41:21.011 set.go:181: [info] [con:2] set system variable wait_timeout = 100
2018/07/02 19:41:21.055 server.go:303: [info] [con:3] new connection 172.18.180.138:50828
2018/07/02 19:41:21.055 session.go:1399: [info] [CRUCIAL OPERATION] [con:3] create database grafana (by [email protected]).
2018/07/02 19:41:21.056 tidb.go:183: [info] RollbackTxn for ddl/autocommit error.
2018/07/02 19:41:21.056 session.go:743: [warning] [3] session error:
/home/jenkins/workspace/build_tidb_2.0/go/src/github.com/pingcap/tidb/ddl/ddl_api.go:45: [schema:1007]Can't create database 'grafana'; database exists
/home/jenkins/workspace/build_tidb_2.0/go/src/github.com/pingcap/tidb/executor/ddl.go:119:
/home/jenkins/workspace/build_tidb_2.0/go/src/github.com/pingcap/tidb/executor/ddl.go:69:
/home/jenkins/workspace/build_tidb_2.0/go/src/github.com/pingcap/tidb/executor/adapter.go:268:
/home/jenkins/workspace/build_tidb_2.0/go/src/github.com/pingcap/tidb/session/tidb.go:200:
{
  "currDBName": "information_schema",
  "id": 3,
  "status": 2,
  "strictMode": true,
  "user": {
    "Username": "admin",
    "Hostname": "172.18.180.138",
    "CurrentUser": false
  }
}
2018/07/02 19:41:21.056 conn.go:487: [warning] [con:3] dispatch error:
id:3, addr:172.18.180.138:50828 status:2, collation:utf8_general_ci, user:admin
"create database grafana"
/home/jenkins/workspace/build_tidb_2.0/go/src/github.com/pingcap/tidb/ddl/ddl_api.go:45: [schema:1007]Can't create database 'grafana'; database exists
/home/jenkins/workspace/build_tidb_2.0/go/src/github.com/pingcap/tidb/executor/ddl.go:119:
/home/jenkins/workspace/build_tidb_2.0/go/src/github.com/pingcap/tidb/executor/ddl.go:69:
/home/jenkins/workspace/build_tidb_2.0/go/src/github.com/pingcap/tidb/executor/adapter.go:268:
/home/jenkins/workspace/build_tidb_2.0/go/src/github.com/pingcap/tidb/session/tidb.go:200:
/home/jenkins/workspace/build_tidb_2.0/go/src/github.com/pingcap/tidb/session/session.go:745:
/home/jenkins/workspace/build_tidb_2.0/go/src/github.com/pingcap/tidb/session/session.go:836:
/home/jenkins/workspace/build_tidb_2.0/go/src/github.com/pingcap/tidb/server/conn.go:859:
2018/07/02 19:41:50.213 server.go:303: [info] [con:4] new connection 172.18.180.138:53698
2018/07/02 19:41:50.213 server.go:305: [info] [con:4] close connection
2018/07/02 19:41:50.998 server.go:303: [info] [con:5] new connection 172.28.245.61:49198
2018/07/02 19:41:50.999 server.go:305: [info] [con:5] close connection

[log from second tidb]

2018/07/02 19:41:20.182 session.go:1399: [info] [CRUCIAL OPERATION] [con:3] create database grafana (by [email protected]).
2018/07/02 19:41:20.189 session.go:976: [info] [con:3] NewTxn() inside a transaction auto commit: 401219696763076614
2018/07/02 19:41:20.198 ddl.go:436: [info] [ddl] start DDL job ID:46, Type:create schema, State:none, SchemaState:none, SchemaID:45, TableID:0, RowCount:0, ArgLen:1, start time: 2018-07-02 

19:41:20.157 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0, Query:create database grafana
2018/07/02 19:41:20.371 server.go:303: [info] [con:4] new connection 172.18.180.138:41918
2018/07/02 19:41:20.377 set.go:181: [info] [con:4] set system variable wait_timeout = 100
2018/07/02 19:41:20.668 domain.go:102: [info] [ddl] diff load InfoSchema from version 15 to 16, in 2.243774ms
2018/07/02 19:41:21.007 server.go:303: [info] [con:5] new connection 172.28.245.61:40308
2018/07/02 19:41:21.160 server.go:303: [info] [con:6] new connection 172.28.245.61:40342
2018/07/02 19:41:21.164 set.go:181: [info] [con:6] set system variable wait_timeout = 100
2018/07/02 19:41:21.200 ddl.go:468: [info] [ddl] DDL job 46 is finished
2018/07/02 19:41:21.200 domain.go:412: [info] [ddl] on DDL change, must reload
2018/07/02 19:41:21.202 adapter.go:353: [warning] [SLOW_QUERY] cost_time:1.020726075s succ:true connection_id:3 txn_start_ts:401219696763076617 database:information_schema table_ids:[] index_ids:[] 

sql:create database grafana
2018/07/02 19:41:21.203 server.go:305: [info] [con:3] close connection
2018/07/02 19:41:50.393 server.go:303: [info] [con:7] new connection 172.18.180.138:44822
2018/07/02 19:41:50.394 server.go:305: [info] [con:7] close connection

[log from the third tidb]
no interested log from the third tidb.

issue 6957 raised to TiDB and they thought it's not their issue.
@renecannao
Copy link
Contributor

There are a lot of system error: 107 in the above logs, as well as errors related to ProxySQL not able to ping the backends.
I am not familiar with TiDB: do these servers act like normal MySQL backend?
172.27.176.239
172.28.245.54
172.18.130.72

I think the connectivity issue is the first thing to troubleshoot before everything else.

@CrazyNash
Copy link
Author

@renecannao Thnaks for the update.

Sorry I should have made this clearer.

  • TiDB is mysql compatible and yes we use it exactly like how we use mysql.
  • In the case we started TiDB and proxqy at same time, so each of them would go through their own init process, TiDB is a big system, usually it takes ~30s to get ready for service, and takes another few minute to get into normal performance ( I mean the performance is bad during the few minute, but it works correctly).

I know both system have challenges in the scenario, but both should work correctly. Can you pls take another look?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@renecannao @CrazyNash