conn.Close() is not called on read-timeout connections

[seiya-annie]

Bug Report

Please answer these questions before submitting your issue. Thanks!

1. Minimal reproduce step (Required)

1. get_lock('test1', 200) in session 1;
2. SELECT GET_LOCK('test1',0), GET_LOCK('test2',0); in session 2;
3. close the network and two sessions are disconnected;
4. reconnect the network
5. check with select * from information_schema.data_lock_waits;
6. get_lock('test1', 200) in session 3;
7. get_lock('test2',200) in session 4;

2. What did you expect to see? (Required)

for step 6: expect return 1
for step 7: expect return 1

3. What did you see instead (Required)

1. after reconnect, lock test1 and test2 can't acquire in any session

2. test2 was never acquired successfully by any session, and can't find wait_lock in data_lock_waits table, why can't it be acquired after reconnecting?

+------------------------------------------------------------+----------------------------------------------------------------------------------------------------------------------------------------+--------------------+------------------------+------------------------------------------------------------------+-----------------+
| KEY | KEY_INFO | TRX_ID | CURRENT_HOLDING_TRX_ID | SQL_DIGEST | SQL_DIGEST_TEXT |
+------------------------------------------------------------+----------------------------------------------------------------------------------------------------------------------------------------+--------------------+------------------------+------------------------------------------------------------------+-----------------+
| 7480000000000000435F698000000000000001017465737431000000FC | {"db_id":3,"db_name":"mysql","table_id":67,"table_name":"advisory_locks","index_id":1,"index_name":"PRIMARY","index_values":["test1"]} | 433260456328298499 | 433260404148535299 | 503fd5b0bd3ca476326b20cdb82e8088bb82376f9a3b81c2f1887bcf46bb3da6 | NULL |
+------------------------------------------------------------+----------------------------------------------------------------------------------------------------------------------------------------+--------------------+------------------------+------------------------------------------------------------------+-----------------+
1 row in set (0.01 sec)
mysql> select get_lock('test2',200);
+-----------------------+
| get_lock('test2',200) |
+-----------------------+
| 0 |
+-----------------------+
1 row in set (3 min 20.01 sec)

4. What is your TiDB version? (Required)

| Release Version: v6.1.0-alpha
Edition: Community
Git Commit Hash: 90e24b9
Git Branch: heads/refs/tags/v6.1.0-alpha
UTC Build Time: 2022-05-15 14:57:27
GoVersion: go1.18
Race Enabled: false
TiKV Min Version: v3.0.0-60965b006877ca7234adaced7890d7b029ed1306
Check Table Before Drop: false |

[morgo]

This same bug will be present in pessimistic locking, and it's not unique to named locks. It is infact more likely to be serious with regular pessimistic locking because it means all session resources won't be freed (memory and locks).

If a session exits cleanly, TiDB will call session.Close(), which releases named locks and rolls back any open transaction (freeing locks). If it doesn't exit cleanly, it will only detect the failure in trying to readPacket from the client:

tidb/server/conn.go

Lines 1083 to 1112 in 828a255

	data, err := cc.readPacket()
	if err != nil {
	if terror.ErrorNotEqual(err, io.EOF) {
	if netErr, isNetErr := errors.Cause(err).(net.Error); isNetErr && netErr.Timeout() {
	if atomic.LoadInt32(&cc.status) == connStatusWaitShutdown {
	logutil.Logger(ctx).Info("read packet timeout because of killed connection")
	} else {
	idleTime := time.Since(start)
	logutil.Logger(ctx).Info("read packet timeout, close this connection",
	zap.Duration("idle", idleTime),
	zap.Uint64("waitTimeout", waitTimeout),
	zap.Error(err),
	)
	}
	} else if errors.ErrorEqual(err, errNetPacketTooLarge) {
	err := cc.writeError(ctx, err)
	if err != nil {
	terror.Log(err)
	}
	} else {
	errStack := errors.ErrorStack(err)
	if !strings.Contains(errStack, "use of closed network connection") {
	logutil.Logger(ctx).Warn("read packet failed, close this connection",
	zap.Error(errors.SuspendStack(err)))
	}
	}
	}
	disconnectByClientWithError.Inc()
	return
	}

This returns to server/server.go:onConn() which does various auditing, but I think there is a missing final conn.Close() to free all the resources of a connection if there is a read-packet error:

tidb/server/server.go

Lines 527 to 578 in 828a255

	terror.Log(conn.Close())
	return
	}
	logutil.Logger(ctx).Debug("new connection", zap.String("remoteAddr", conn.bufReadConn.RemoteAddr().String()))
	defer func() {
	logutil.Logger(ctx).Debug("connection closed")
	}()
	s.rwlock.Lock()
	s.clients[conn.connectionID] = conn
	connections := len(s.clients)
	s.rwlock.Unlock()
	metrics.ConnGauge.Set(float64(connections))
	sessionVars := conn.ctx.GetSessionVars()
	if plugin.IsEnable(plugin.Audit) {
	sessionVars.ConnectionInfo = conn.connectInfo()
	}
	err := plugin.ForeachPlugin(plugin.Audit, func(p *plugin.Plugin) error {
	authPlugin := plugin.DeclareAuditManifest(p.Manifest)
	if authPlugin.OnConnectionEvent != nil {
	return authPlugin.OnConnectionEvent(context.Background(), plugin.Connected, sessionVars.ConnectionInfo)
	}
	return nil
	})
	if err != nil {
	return
	}
	connectedTime := time.Now()
	conn.Run(ctx)
	err = plugin.ForeachPlugin(plugin.Audit, func(p *plugin.Plugin) error {
	// Audit plugin may be disabled before a conn is created, leading no connectionInfo in sessionVars.
	if sessionVars.ConnectionInfo == nil {
	sessionVars.ConnectionInfo = conn.connectInfo()
	}
	authPlugin := plugin.DeclareAuditManifest(p.Manifest)
	if authPlugin.OnConnectionEvent != nil {
	sessionVars.ConnectionInfo.Duration = float64(time.Since(connectedTime)) / float64(time.Millisecond)
	err := authPlugin.OnConnectionEvent(context.Background(), plugin.Disconnect, sessionVars.ConnectionInfo)
	if err != nil {
	logutil.BgLogger().Warn("do connection event failed", zap.String("plugin", authPlugin.Name), zap.Error(err))
	}
	}
	return nil
	})
	if err != nil {
	return
	}
	}

There is a conn.Close() above, but that only handles handshake errors. There is a defer, but it only logs to debug on disconnect.