vstreamer leaking binlog streams?

[aquarapid]

On current master (d6c9ddf71cefdaa13d0e57fb1353e347523dd713).

Scenario:

• Setup local examples with unsharded commerce and customer keyspaces:

  $ cd examples/local/
  $ sh -x 101_initial_cluster.sh ; sleep 5 ; sh -x 201_customer_tablets.sh
  .
  .

  • Populate some (small) amount of rows in commerce.corder:

    $ echo 'insert into corder (order_id, customer_id, sku, price) values (1, 1, 123, 100), (2, 2, 123, 100), (3, 3, 123, 100), (4, 4, 123, 100), (5, 5, 123, 100), (6, 6, 123, 100), (7, 7, 123, 100), (8, 8, 123, 100), (9, 9, 123, 100), (10, 10, 123, 100); ' | 
    mysql -c -h 127.0.0.1 -P 15306 -u root commerce

• Start a MoveTables workflow to copy commerce.corder to customer.corder:

  $ vtctlclient -server localhost:15999 MoveTables -workflow=commerce2customer commerce customer '{"corder":{}}'

• You can validate the workflow is running (should complete immediately, since there is so little data), by running:

  $ vtctlclient -server localhost:15999 WorkFlow customer.commerce2customer show

• Now, we want to run VDiff on this flow. But first log into the REPLICA tablet in commerce keyspace that VDiff will be running against, and do a show full processlist;:

  $ mysql -S ~/go/vtdataroot/vt_0000000101/mysql.sock -u root   -A --binary-as-hex=false

• Now run the VDiff:

  $ vtctlclient -server localhost:15999 VDiff customer.commerce2customer

• Now, wait a few seconds, and run the VDiff again, and then again and again. After running the VDiff a bunch of times, do show full processlist; again. You will notice that the number of binlog streaming connections are increasing, and not being closed. They will, in fact, only time out when the MySQL wait_timeout is reached (default, 8 hours). An example after a large number VDiff runs could be:

  |  80 | vt_app          | localhost       | vt_commerce | Binlog Dump GTID |  230 | Master has sent all binlog to slave; waiting for more updates | NULL                  |         0 |             0 |
  |  84 | vt_app          | localhost       | vt_commerce | Binlog Dump GTID |  188 | Master has sent all binlog to slave; waiting for more updates | NULL                  |         0 |             0 |
  |  86 | vt_app          | localhost       | vt_commerce | Binlog Dump GTID |  185 | Master has sent all binlog to slave; waiting for more updates | NULL                  |         0 |             0 |
  |  90 | vt_app          | localhost       | vt_commerce | Binlog Dump GTID |  182 | Master has sent all binlog to slave; waiting for more updates | NULL                  |         0 |             0 |
  |  92 | vt_app          | localhost       | vt_commerce | Binlog Dump GTID |  149 | Master has sent all binlog to slave; waiting for more updates | NULL                  |         0 |             0 |
  |  94 | vt_app          | localhost       | vt_commerce | Binlog Dump GTID |  115 | Master has sent all binlog to slave; waiting for more updates | NULL                  |         0 |             0 |
  |  98 | vt_app          | localhost       | vt_commerce | Binlog Dump GTID |  112 | Master has sent all binlog to slave; waiting for more updates | NULL                  |         0 |             0 |
  | 102 | vt_app          | localhost       | vt_commerce | Binlog Dump GTID |   79 | Master has sent all binlog to slave; waiting for more updates | NULL                  |         0 |             0 |
  | 104 | vt_app          | localhost       | vt_commerce | Binlog Dump GTID |   76 | Master has sent all binlog to slave; waiting for more updates | NULL                  |         0 |             0 |
  | 106 | vt_app          | localhost       | vt_commerce | Binlog Dump GTID |   73 | Master has sent all binlog to slave; waiting for more updates | NULL                  |         0 |             0 |
  | 108 | vt_app          | localhost       | vt_commerce | Binlog Dump GTID |   40 | Master has sent all binlog to slave; waiting for more updates | NULL                  |         0 |             0 |
  | 110 | vt_app          | localhost       | vt_commerce | Binlog Dump GTID |   37 | Master has sent all binlog to slave; waiting for more updates | NULL                  |         0 |             0 |
  | 114 | vt_app          | localhost       | vt_commerce | Binlog Dump GTID |   34 | Master has sent all binlog to slave; waiting for more updates | NULL                  |         0 |             0 |
  | 116 | vt_app          | localhost       | vt_commerce | Binlog Dump GTID |   30 | Master has sent all binlog to slave; waiting for more updates | NULL                  |         0 |             0 |
  | 120 | vt_app          | localhost       | vt_commerce | Binlog Dump GTID |   27 | Master has sent all binlog to slave; waiting for more updates | NULL                  |         0 |             0 |
  | 122 | vt_app          | localhost       | vt_commerce | Binlog Dump GTID |   24 | Master has sent all binlog to slave; waiting for more updates | NULL                  |         0 |             0 |
  | 124 | vt_app          | localhost       | vt_commerce | Binlog Dump GTID |   21 | Master has sent all binlog to slave; waiting for more updates | NULL                  |         0 |             0 |
  | 126 | vt_app          | localhost       | vt_commerce | Binlog Dump GTID |   18 | Master has sent all binlog to slave; waiting for more updates | NULL                  |         0 |             0 |
  | 128 | vt_app          | localhost       | vt_commerce | Binlog Dump GTID |   15 | Master has sent all binlog to slave; waiting for more updates | NULL                  |         0 |             0 |
  | 130 | vt_app          | localhost       | vt_commerce | Binlog Dump GTID |   12 | Master has sent all binlog to slave; waiting for more updates | NULL                  |         0 |             0 |
  | 132 | vt_app          | localhost       | vt_commerce | Binlog Dump GTID |    9 | Master has sent all binlog to slave; waiting for more updates | NULL                  |         0 |             0 |

• If you continue running VDiffs, you will eventually hit the max connections for the MySQL server...

• If you consult the vttablet log for the source vttablet (tablet zone1-0000000101 in the examples case), you will see something like this on every VDiff run:

  I1023 21:40:34.565374  207989 vstreamer.go:825] stream (at source tablet) ended @ 80526356-15b0-11eb-914a-00259085bb84:1-19
  I1023 21:40:34.565455  207989 binlog_connection.go:271] closing binlog socket to unblock reads
  I1023 21:40:34.565642  207989 binlog_connection.go:279] waiting for binlog dump thread to end
  I1023 21:40:34.565663  207989 binlog_connection.go:145] connection closed during binlog stream (possibly intentional): read unix @->/home/jacques/go/vtdataroot/vt_0000000101/mysql.sock: use of closed network connection
  io.ReadFull(header size) failed (errno 2013) (sqlstate HY000)
  I1023 21:40:34.565738  207989 binlog_connection.go:285] closing binlog MySQL client with connID 2018713064
  I1023 21:40:34.645879  207989 uvstreamer.go:361] Stream() called
  I1023 21:40:34.647161  207989 vstreamer.go:151] Starting Stream() with startPos MySQL56/80526356-15b0-11eb-914a-00259085bb84:1-19
  I1023 21:40:34.648326  207989 binlog_connection.go:72] new binlog connection: connID=288126451
  I1023 21:40:34.648342  207989 binlog_connection.go:117] sending binlog dump command: startPos=80526356-15b0-11eb-914a-00259085bb84:1-19, connID=288126451

[aquarapid]

It was pointed out that these binlog steams will die off as soon as the server tries to send an event down them (e.g. there is an update/insert/delete to the upstream MySQL instance). So if the underlying MySQL instance is receiving regular updates, you might not notice this at all.

[aquarapid]

After some experimentation, I found that AWS Aurora still "leaks" binlog streams even if you reuse the server_id. So, unless the upstream instance is actively receiving writes, you could eventually exhaust all the db connections. It looks like the only approach that is guaranteed to work is that followed by the binlog streamer in go-mysql, which is to open a separate connection and kill the binlog dump session using KILL xxx

[enisoc]

It looks like the only approach that is guaranteed to work is that followed by the binlog streamer in go-mysql, which is to open a separate connection and kill the binlog dump session using KILL xxx

How does a real mysql replica tell the server that it's going away? Or does it not, and this orphan problem exists for real replicas too when no transactions are flowing?

[aquarapid]

It re-uses the server_id. Things in AWS Aurora seem to work differently; because I suspect under the covers they're using a completely different binlog "server" implementation.

[mattlord]

I'm going to close this for now as SO much in this area has changed in the last 3.5 years and I don't see a test case here to know if it's still an issue.

If you believe that this is still an issue then please provide additional details and we can reopen the issue at any time. Thanks!