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 #6957

Closed
CrazyNash opened this issue Jul 2, 2018 · 15 comments
Closed

DB created successfully but failure returned #6957

CrazyNash opened this issue Jul 2, 2018 · 15 comments
Labels
type/question The issue belongs to a question.

Comments

@CrazyNash
Copy link

CrazyNash commented Jul 2, 2018 •
edited
Loading

Please answer these questions before submitting your issue. Thanks!

  1. What did you do?
    If possible, provide a recipe for reproducing the error.

docker deploy TiDB cluster, then start same shell script from two servers at the same time.
for each script:
"show database like XXX"
if the database doesn't exist then "create database XXX"

  1. What did you expect to see?

only one agent could create the DB, and TiDB should return success from that agent.

  1. What did you see instead?

At the beginning, I can see mysql connection timeout errors, and also connection refused errors later
After several times retries(around 30s later, mysql client connected successfully)
both agent got empty result for "show databases XXX", that means the db doesn't exist.
both agent start to create same DB
both agent got "failed, the database already exists"

Got exactly same log from my script from two servers, interesting show database command took around 5s to complete

2018-07-02 09:18:47 show databases like 'grafana';
2018-07-02 09:18:53 DB doesn't exist, create it first
2018-07-02 09:18:54 ERROR 1007 (HY000) at line 1: Can't create database 'grafana'; database exists
  1. What version of TiDB are you using (tidb-server -V or run select tidb_version(); on TiDB)?
    v2.04

Note: can't hit this issue every time, roughly 1 from 20
@shenli
Copy link
Member

shenli commented Jul 2, 2018

@CrazyNash Thanks for your feedback!
Could you make the description more clear? Especially about "mysql connection timeout errors". Why there is a timeout error? Could you show me your scripts?

@shenli shenli added the type/question The issue belongs to a question. label Jul 2, 2018
@jackysp
Copy link
Member

jackysp commented Jul 2, 2018

PTAL @zimulala

@CrazyNash
Copy link
Author

@shenli

2018-07-02 11:09:44 show databases like 'grafana';
2018-07-02 11:09:44 ERROR 2003 (HY000): Can't connect to MySQL server on '172.31.145.198' (111 "Connection refused")
ERROR 2003 (HY000): Can't connect to MySQL server on '172.31.145.198' (111 "Connection refused")

2018-07-02 11:09:47 show databases like 'grafana';
2018-07-02 11:09:57 ERROR 9001 (HY000) at line 1: Max connect timeout reached while reaching hostgroup 0 after 10000ms
ERROR 9001 (HY000) at line 1: Max connect timeout reached while reaching hostgroup 0 after 10000ms

2018-07-02 11:10:24 show databases like 'grafana';
2018-07-02 11:10:26 ERROR 1045 (28000) at line 1: Access denied for user 'XXXX'@'172.28.245.61' (using password: YES)
ERROR 1045 (28000) at line 1: Access denied for user 'XXX'@'172.28.245.61' (using password: YES)

2018-07-02 11:10:26 show databases like 'grafana';
2018-07-02 11:10:26 ERROR 1045 (28000) at line 1: Access denied for user 'XXXX'@'172.28.245.61' (using password: YES)
ERROR 1045 (28000) at line 1: Access denied for user 'XXXX'@'172.28.245.61' (using password: YES)

Note that, proxysql run above TiDB, seems timeout returned from proxysql. You can ignore the timeout, the db creation failure must be from TiDB.

@zimulala
Copy link
Contributor

zimulala commented Jul 2, 2018

@CrazyNash
How many TiDB are there in your cluster?

@CrazyNash
Copy link
Author

@zimulala

OK I recreated this again just now, with TiDB logs captured. Although slightly different this time.

[set up]

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

[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

[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.

@zimulala
Copy link
Contributor

zimulala commented Jul 2, 2018

@CrazyNash
From the second TiDB log, the statement of "create database grafana" is finished by connection 3.
From the first TiDB log, the statement is failed.
The second TiDB received the statement is earlier than the first TiDB.

@CrazyNash
Copy link
Author

@zimulala from client perspective, it shouldn't return failure, because the db was created. so this is a bug, right? any plan to fix it?

@zimulala
Copy link
Contributor

zimulala commented Jul 3, 2018

@CrazyNash
I didn't see the second TiDB return failure. And after it handles the statement of create database grafana, we can see the connection 3 is close. Could you check if the client closes this connection？

@CrazyNash
Copy link
Author

@zimulala for this recreation, there were two servers running my script.

  • the script from server 172.28.245.61 did NOT issue "create database"
  • only the script from server 172.18.180.138 issued "create database", and creation failure returned but database was created.

[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 ~]#

@zimulala
Copy link
Contributor

zimulala commented Jul 3, 2018

@CrazyNash
Do you mean that only "172.18.180.138" client sends the statement of create database，and it is failed ？
I see "Retrying query" before the log of "Can't create database ...". Could you show me the log of this TiDB that the client “172.18.180.138” sent the request to?

@CrazyNash
Copy link
Author

@zimulala Yes, all the logs has been pasted to comment #6, client didn't work with TiDB directly, proxysql works in the middle, and you can find all logs from proxysql from comment #10

@zimulala
Copy link
Contributor

zimulala commented Jul 3, 2018

@CrazyNash
I think the second TiDB's IP is "172.28.245.54" and the first TiDB's IP is "172.18.130.72". Is that right?
What's the meaning of "Detected an offline server during query"? I think it executes “create database” successfully. And it's the connection 3 in the second TiDB log.

@CrazyNash
Copy link
Author

@zimulala
From client perspective, it's definitely a bug.
I don't have much knowledge of Proxysql, if you think everything worked from TiDB, can you pls summarise what happened from TiDB perspective, and then I can talk to Proxysql team

@zimulala
Copy link
Contributor

zimulala commented Jul 9, 2018

@CrazyNash
TiDB executes “create database” successfully. And I think it executes the statement by connection 3 in the second TiDB log. But your client/proxy loses the connection before it gets the successful result of "create database", and we can see the log of "Detected an offline server during query" in the second instance of proxysql. I don't know what's meaningful of this log, I think the connection is closed by your client/proxy.

@CrazyNash CrazyNash mentioned this issue Jul 9, 2018
Open
@zimulala
Copy link
Contributor

If you still have problems, you can reopen.

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

No branches or pull requests
4 participants
@shenli @zimulala @jackysp @CrazyNash