search

go-mysql-org / go-mysql

a powerful mysql toolset with Go
MIT License
4.58k stars 976 forks source link

set read deadline for new conection to fix handshake stuck #861

Closed tangenta closed 5 months ago

tangenta commented 5 months ago

We encountered a stuck issue caused by BinlogSyncer.close():

There is "syncer is closing" in log, but no "syncer is closed".

[info] binlogsyncer.go:206 syncer is closing...

Here are parts of the goroutines:

                                                 1   100% |   github.com/go-mysql-org/go-mysql/client.ConnectWithDialer github.com/go-mysql-org/go-mysql@v1.6.1-0.20221223014230-81966e15b9c5/client/conn.go:109
         0     0%   100%          1  0.89%                | github.com/go-mysql-org/go-mysql/client.(*Conn).handshake github.com/go-mysql-org/go-mysql@v1.6.1-0.20221223014230-81966e15b9c5/client/conn.go:118
                                                 1   100% |   github.com/go-mysql-org/go-mysql/client.(*Conn).readInitialHandshake github.com/go-mysql-org/go-mysql@v1.6.1-0.20221223014230-81966e15b9c5/client/auth.go:31
----------------------------------------------------------+-------------
                                                 1   100% |   github.com/go-mysql-org/go-mysql/client.(*Conn).handshake github.com/go-mysql-org/go-mysql@v1.6.1-0.20221223014230-81966e15b9c5/client/conn.go:118
         0     0%   100%          1  0.89%                | github.com/go-mysql-org/go-mysql/client.(*Conn).readInitialHandshake github.com/go-mysql-org/go-mysql@v1.6.1-0.20221223014230-81966e15b9c5/client/auth.go:31
                                                 1   100% |   github.com/go-mysql-org/go-mysql/packet.(*Conn).ReadPacket github.com/go-mysql-org/go-mysql@v1.6.1-0.20221223014230-81966e15b9c5/packet/conn.go:87 (inline)
----------------------------------------------------------+-------------
                                                 1   100% |   github.com/go-mysql-org/go-mysql/replication.(*BinlogSyncer).newConnection github.com/go-mysql-org/go-mysql@v1.6.1-0.20221223014230-81966e15b9c5/replication/binlogsyncer.go:891
         0     0%   100%          1  0.89%                | github.com/go-mysql-org/go-mysql/client.ConnectWithDialer github.com/go-mysql-org/go-mysql@v1.6.1-0.20221223014230-81966e15b9c5/client/conn.go:109
                                                 1   100% |   github.com/go-mysql-org/go-mysql/client.(*Conn).handshake github.com/go-mysql-org/go-mysql@v1.6.1-0.20221223014230-81966e15b9c5/client/conn.go:118
----------------------------------------------------------+-------------
                                                 1   100% |   github.com/go-mysql-org/go-mysql/client.(*Conn).readInitialHandshake github.com/go-mysql-org/go-mysql@v1.6.1-0.20221223014230-81966e15b9c5/client/auth.go:31 (inline)
         0     0%   100%          1  0.89%                | github.com/go-mysql-org/go-mysql/packet.(*Conn).ReadPacket github.com/go-mysql-org/go-mysql@v1.6.1-0.20221223014230-81966e15b9c5/packet/conn.go:87
                                                 1   100% |   github.com/go-mysql-org/go-mysql/packet.(*Conn).ReadPacketReuseMem github.com/go-mysql-org/go-mysql@v1.6.1-0.20221223014230-81966e15b9c5/packet/conn.go:97
----------------------------------------------------------+-------------
                                                 1   100% |   github.com/go-mysql-org/go-mysql/packet.(*Conn).ReadPacket github.com/go-mysql-org/go-mysql@v1.6.1-0.20221223014230-81966e15b9c5/packet/conn.go:87
         0     0%   100%          1  0.89%                | github.com/go-mysql-org/go-mysql/packet.(*Conn).ReadPacketReuseMem github.com/go-mysql-org/go-mysql@v1.6.1-0.20221223014230-81966e15b9c5/packet/conn.go:97
                                                 1   100% |   github.com/go-mysql-org/go-mysql/packet.(*Conn).ReadPacketTo github.com/go-mysql-org/go-mysql@v1.6.1-0.20221223014230-81966e15b9c5/packet/conn.go:149
----------------------------------------------------------+-------------
                                                 1   100% |   github.com/go-mysql-org/go-mysql/packet.(*Conn).ReadPacketReuseMem github.com/go-mysql-org/go-mysql@v1.6.1-0.20221223014230-81966e15b9c5/packet/conn.go:97
         0     0%   100%          1  0.89%                | github.com/go-mysql-org/go-mysql/packet.(*Conn).ReadPacketTo github.com/go-mysql-org/go-mysql@v1.6.1-0.20221223014230-81966e15b9c5/packet/conn.go:149
                                                 1   100% |   io.ReadFull io/io.go:351 (inline)
----------------------------------------------------------+-------------
                                                 1   100% |   github.com/pingcap/tiflow/dm/syncer/binlogstream.(*StreamerController).resetReplicationSyncer github.com/pingcap/tiflow/dm/syncer/binlogstream/streamer_controller.go:259
         0     0%   100%          1  0.89%                | github.com/go-mysql-org/go-mysql/replication.(*BinlogSyncer).Close github.com/go-mysql-org/go-mysql@v1.6.1-0.20221223014230-81966e15b9c5/replication/binlogsyncer.go:198
                                                 1   100% |   github.com/go-mysql-org/go-mysql/replication.(*BinlogSyncer).close github.com/go-mysql-org/go-mysql@v1.6.1-0.20221223014230-81966e15b9c5/replication/binlogsyncer.go:223
----------------------------------------------------------+-------------
                                                 1   100% |   github.com/go-mysql-org/go-mysql/replication.(*BinlogSyncer).Close github.com/go-mysql-org/go-mysql@v1.6.1-0.20221223014230-81966e15b9c5/replication/binlogsyncer.go:198
         0     0%   100%          1  0.89%                | github.com/go-mysql-org/go-mysql/replication.(*BinlogSyncer).close github.com/go-mysql-org/go-mysql@v1.6.1-0.20221223014230-81966e15b9c5/replication/binlogsyncer.go:223
                                                 1   100% |   github.com/go-mysql-org/go-mysql/replication.(*BinlogSyncer).newConnection github.com/go-mysql-org/go-mysql@v1.6.1-0.20221223014230-81966e15b9c5/replication/binlogsyncer.go:891
----------------------------------------------------------+-------------
                                                 1   100% |   github.com/go-mysql-org/go-mysql/replication.(*BinlogSyncer).close github.com/go-mysql-org/go-mysql@v1.6.1-0.20221223014230-81966e15b9c5/replication/binlogsyncer.go:223
         0     0%   100%          1  0.89%                | github.com/go-mysql-org/go-mysql/replication.(*BinlogSyncer).newConnection github.com/go-mysql-org/go-mysql@v1.6.1-0.20221223014230-81966e15b9c5/replication/binlogsyncer.go:891
                                                 1   100% |   github.com/go-mysql-org/go-mysql/client.ConnectWithDialer github.com/go-mysql-org/go-mysql@v1.6.1-0.20221223014230-81966e15b9c5/client/conn.go:109

Because there is no deadline/timeout for readPacket, it may block forever.

This PR set timeout for all read operations of a connection.

lance6716 commented 5 months ago

We encountered a stuck issue caused by BinlogSyncer.close():

How long it has been stuck? I see that we set ReadTimeout to 1 minute, not sure it is too long for a cleanup logic in close

rest lgtm

D3Hunter commented 5 months ago

We encountered a stuck issue caused by BinlogSyncer.close():

How long it has been stuck? I see that we set ReadTimeout to 1 minute, not sure it is too long for a cleanup logic in close

rest lgtm

met it again, blocks for 10 more hours, see https://github.com/pingcap/tiflow/issues/11041