ERROR 2013 (HY000): Lost connection to MySQL server at 'reading initial communication packet', system error: 0

[yahonda]

Steps to reproduce

git clone https://github.com/pingcap/tidb-docker-compose.git
cd tidb-docker-compose && docker-compose pull # Get the latest Docker images
docker-compose up -d
mysql -h 127.0.0.1 -P 4000 -u root

Expected behavior

It connect to TiDB Server and the mysql> prompt should appear.

Actual behavior

It always gets this error.

% mysql -h 127.0.0.1 -P 4000 -u root
ERROR 2013 (HY000): Lost connection to MySQL server at 'reading initial communication packet', system error: 0

Environment

macOS Monterey 12.1

% uname -a
Darwin yahondambp.local 21.2.0 Darwin Kernel Version 21.2.0: Sun Nov 28 20:28:54 PST 2021; root:xnu-8019.61.5~1/RELEASE_X86_64 x86_64
% docker -v
Docker version 20.10.11, build dea9396
% docker-compose -v
docker-compose version 1.29.2, build 5becea4c
% docker images |grep -i pingcap
pingcap/tispark       latest    c18bd7ca57d9   24 hours ago   636MB
pingcap/tidb          latest    778bf9e1e051   8 months ago   145MB
pingcap/tikv          latest    6e34b1d95950   8 months ago   355MB
pingcap/pd            latest    d55858ba1d82   8 months ago   151MB
pingcap/tidb-vision   latest    e9b25d9f7bdb   3 years ago    47.6MB
%

[dveeden]

What does docker ps and docker-compose ps say?

[yahonda]

What does docker ps and docker-compose ps say?

Here are the output of these commands. Looks like process information available docker ps, Some containers has restarted frequently. All of 'CREATED" column say "5 minutes ago". But "STATUS" of some containers are less 2 minutes like 'Up About a minute" , "Up Less than a second".

% docker ps
CONTAINER ID   IMAGE                        COMMAND                  CREATED         STATUS                  PORTS                                               NAMES
1191127d59d2   pingcap/tispark:latest       "/opt/spark/sbin/sta…"   5 minutes ago   Up 5 minutes            0.0.0.0:38081->38081/tcp                            tidb-docker-compose_tispark-slave0_1
06bb744a5824   pingcap/tidb:latest          "/tidb-server --stor…"   5 minutes ago   Up About a minute       0.0.0.0:4000->4000/tcp, 0.0.0.0:10080->10080/tcp    tidb-docker-compose_tidb_1
75df512c2081   pingcap/tispark:latest       "/opt/spark/sbin/sta…"   5 minutes ago   Up 5 minutes            0.0.0.0:7077->7077/tcp, 0.0.0.0:8080->8080/tcp      tidb-docker-compose_tispark-master_1
7d3047b0b905   pingcap/tikv:latest          "/tikv-server --addr…"   5 minutes ago   Up Less than a second   20160/tcp                                           tidb-docker-compose_tikv1_1
b7493002e46e   pingcap/tikv:latest          "/tikv-server --addr…"   5 minutes ago   Up 8 seconds            20160/tcp                                           tidb-docker-compose_tikv0_1
482f3d973700   pingcap/tikv:latest          "/tikv-server --addr…"   5 minutes ago   Up 5 seconds            20160/tcp                                           tidb-docker-compose_tikv2_1
34315f31a862   pingcap/pd:latest            "/pd-server --name=p…"   5 minutes ago   Up 5 minutes            2380/tcp, 0.0.0.0:55422->2379/tcp                   tidb-docker-compose_pd2_1
a56a4eae636f   grafana/grafana:6.0.1        "/run.sh"                5 minutes ago   Up 5 minutes            0.0.0.0:3000->3000/tcp                              tidb-docker-compose_grafana_1
c928e65226d9   prom/pushgateway:v0.3.1      "/bin/pushgateway --…"   5 minutes ago   Up 5 minutes            9091/tcp                                            tidb-docker-compose_pushgateway_1
e7b0fcb0f425   pingcap/pd:latest            "/pd-server --name=p…"   5 minutes ago   Up 5 minutes            2380/tcp, 0.0.0.0:55423->2379/tcp                   tidb-docker-compose_pd0_1
75d5789673fb   prom/prometheus:v2.2.1       "/bin/prometheus --l…"   5 minutes ago   Up 5 minutes            0.0.0.0:9090->9090/tcp                              tidb-docker-compose_prometheus_1
fdb6c333186f   pingcap/tidb-vision:latest   "/bin/sh -c 'sed -i …"   5 minutes ago   Up 5 minutes            80/tcp, 443/tcp, 2015/tcp, 0.0.0.0:8010->8010/tcp   tidb-docker-compose_tidb-vision_1
efd6a6c8450b   pingcap/pd:latest            "/pd-server --name=p…"   5 minutes ago   Up 5 minutes            2380/tcp, 0.0.0.0:55421->2379/tcp                   tidb-docker-compose_pd1_1
%

% docker-compose ps
                Name                              Command                 State                            Ports
--------------------------------------------------------------------------------------------------------------------------------------
tidb-docker-compose_grafana_1          /run.sh                          Up           0.0.0.0:3000->3000/tcp
tidb-docker-compose_pd0_1              /pd-server --name=pd0 --cl ...   Up           0.0.0.0:55423->2379/tcp, 2380/tcp
tidb-docker-compose_pd1_1              /pd-server --name=pd1 --cl ...   Up           0.0.0.0:55421->2379/tcp, 2380/tcp
tidb-docker-compose_pd2_1              /pd-server --name=pd2 --cl ...   Up           0.0.0.0:55422->2379/tcp, 2380/tcp
tidb-docker-compose_prometheus_1       /bin/prometheus --log.leve ...   Up           0.0.0.0:9090->9090/tcp
tidb-docker-compose_pushgateway_1      /bin/pushgateway --log.lev ...   Up           9091/tcp
tidb-docker-compose_tidb-vision_1      /bin/sh -c sed -i -e "s/PD ...   Up           2015/tcp, 443/tcp, 80/tcp, 0.0.0.0:8010->8010/tcp
tidb-docker-compose_tidb_1             /tidb-server --store=tikv  ...   Up           0.0.0.0:10080->10080/tcp, 0.0.0.0:4000->4000/tcp
tidb-docker-compose_tikv0_1            /tikv-server --addr=0.0.0. ...   Up           20160/tcp
tidb-docker-compose_tikv1_1            /tikv-server --addr=0.0.0. ...   Restarting
tidb-docker-compose_tikv2_1            /tikv-server --addr=0.0.0. ...   Up           20160/tcp
tidb-docker-compose_tispark-master_1   /opt/spark/sbin/start-mast ...   Up           0.0.0.0:7077->7077/tcp, 0.0.0.0:8080->8080/tcp
tidb-docker-compose_tispark-slave0_1   /opt/spark/sbin/start-slav ...   Up           0.0.0.0:38081->38081/tcp
%

[dveeden]

Looks like some of the containers are restarting. Could you try to find out why with docker logs etc?

[yahonda]

Sure. Let me try and update the result tomorrow.

[dveeden]

Running docker-compose up instead docker-compose up -d for me helped to troubleshoot the issue. It showed a lot of permission issues. This was caused by incorrect SELinux configuration, and "fixed" by running setenforce 0 to temporarily disable SELinux.

[yahonda]

This issue has been resolved by adding more resources to Docker. Because the docker-compose up without -d option shows tikv2_1 exited with code 137. exit code 137 is likely caused by out of memory. Refer https://support.circleci.com/hc/en-us/articles/115014359648-Exit-code-137-Out-of-memory

Command executed

% docker-compose up 2>&1 | tee issue100.log

• issue100.log

Container tidb-docker-compose_pd0_1  Recreate
Container tidb-docker-compose_tidb-vision_1  Recreate
Container tidb-docker-compose_grafana_1  Recreate
Container tidb-docker-compose_pushgateway_1  Recreate
Container tidb-docker-compose_pd2_1  Recreate
Container tidb-docker-compose_prometheus_1  Recreate
Container tidb-docker-compose_pd1_1  Recreate
Container tidb-docker-compose_pd1_1  Recreated
Container tidb-docker-compose_pd2_1  Recreated
Container tidb-docker-compose_pushgateway_1  Recreated
Container tidb-docker-compose_grafana_1  Recreated
Container tidb-docker-compose_pd0_1  Recreated
Container tidb-docker-compose_tikv1_1  Recreate
Container tidb-docker-compose_tikv0_1  Recreate
Container tidb-docker-compose_tikv2_1  Recreate
Container tidb-docker-compose_tidb-vision_1  Recreated
Container tidb-docker-compose_prometheus_1  Recreated
Container tidb-docker-compose_tikv2_1  Recreated
Container tidb-docker-compose_tikv1_1  Recreated
Container tidb-docker-compose_tikv0_1  Recreated
Container tidb-docker-compose_tidb_1  Recreate
Container tidb-docker-compose_tispark-master_1  Recreate
Container tidb-docker-compose_tispark-master_1  Recreated
Container tidb-docker-compose_tispark-slave0_1  Recreate
Container tidb-docker-compose_tidb_1  Recreated
Container tidb-docker-compose_tispark-slave0_1  Recreated
Attaching to grafana_1, pd0_1, pd1_1, pd2_1, prometheus_1, pushgateway_1, tidb-vision_1, tidb_1, tikv0_1, tikv1_1, tikv2_1, tispark-master_1, tispark-slave0_1
tidb-vision_1     | Activating privacy features... done.
tidb-vision_1     | http://0.0.0.0:8010
grafana_1         | t=2021-12-22T01:49:26+0000 lvl=eror msg="Can't read alert notification provisioning files from directory" logger=provisioning.notifiers path=/etc/grafana/provisioning/notifiers error="open /etc/grafana/provisioning/notifiers: no such file or directory"
tispark-master_1  | starting org.apache.spark.deploy.master.Master, logging to /opt/spark/logs/spark--org.apache.spark.deploy.master.Master-1-2346630cca4c.out
tidb_1            | config file /tidb.toml contained invalid configuration options: log.file.log-rotate, performance.retry-limit, plan-cache, plan-cache.enabled, plan-cache.capacity, plan-cache.shards; check TiDB manual to make sure this option has not been deprecated and removed from your TiDB version if the option does not appear to be a typo
tispark-master_1  | Spark Command: /opt/jdk/bin/java -cp /opt/spark/conf/:/opt/spark/jars/* -Xmx1g org.apache.spark.deploy.master.Master --host 0.0.0.0 --port 7077 --webui-port 8080
tispark-master_1  | ========================================
tispark-slave0_1  | starting org.apache.spark.deploy.worker.Worker, logging to /opt/spark/logs/spark--org.apache.spark.deploy.worker.Worker-1-e9f61d934c69.out
tispark-slave0_1  | Spark Command: /opt/jdk/bin/java -cp /opt/spark/conf/:/opt/spark/jars/* -Xmx1g org.apache.spark.deploy.worker.Worker --webui-port 38081 spark://tispark-master:7077
tispark-slave0_1  | ========================================
tispark-master_1  | 21/12/22 01:49:32 INFO Master: Started daemon with process name: 13@2346630cca4c
tispark-master_1  | 21/12/22 01:49:32 INFO SignalUtils: Registered signal handler for TERM
tispark-master_1  | 21/12/22 01:49:32 INFO SignalUtils: Registered signal handler for HUP
tispark-master_1  | 21/12/22 01:49:32 INFO SignalUtils: Registered signal handler for INT
tispark-slave0_1  | 21/12/22 01:49:33 INFO Worker: Started daemon with process name: 12@e9f61d934c69
tispark-slave0_1  | 21/12/22 01:49:33 INFO SignalUtils: Registered signal handler for TERM
tispark-slave0_1  | 21/12/22 01:49:33 INFO SignalUtils: Registered signal handler for HUP
tispark-slave0_1  | 21/12/22 01:49:33 INFO SignalUtils: Registered signal handler for INT
tispark-master_1  | 21/12/22 01:49:34 WARN NativeCodeLoader: Unable to load native-hadoop library for your platform... using builtin-java classes where applicable
tispark-slave0_1  | 21/12/22 01:49:34 WARN NativeCodeLoader: Unable to load native-hadoop library for your platform... using builtin-java classes where applicable
pd0_1             | [2021/12/22 01:49:38.461 +00:00] [WARN] [retry_interceptor.go:61] ["retrying of unary invoker failed"] [target=endpoint://client-5e25b0a0-8002-41c0-9223-ddf138f6b4de/pd0:2379] [attempt=0] [error="rpc error: code = DeadlineExceeded desc = context deadline exceeded"]
tispark-master_1  | 21/12/22 01:49:38 INFO SecurityManager: Changing view acls to: root
tispark-master_1  | 21/12/22 01:49:38 INFO SecurityManager: Changing modify acls to: root
tispark-master_1  | 21/12/22 01:49:38 INFO SecurityManager: Changing view acls groups to:
tispark-master_1  | 21/12/22 01:49:38 INFO SecurityManager: Changing modify acls groups to:
tispark-master_1  | 21/12/22 01:49:38 INFO SecurityManager: SecurityManager: authentication disabled; ui acls disabled; users  with view permissions: Set(root); groups with view permissions: Set(); users  with modify permissions: Set(root); groups with modify permissions: Set()
tispark-slave0_1  | 21/12/22 01:49:38 INFO SecurityManager: Changing view acls to: root
tispark-slave0_1  | 21/12/22 01:49:38 INFO SecurityManager: Changing modify acls to: root
tispark-slave0_1  | 21/12/22 01:49:38 INFO SecurityManager: Changing view acls groups to:
tispark-slave0_1  | 21/12/22 01:49:38 INFO SecurityManager: Changing modify acls groups to:
tispark-slave0_1  | 21/12/22 01:49:38 INFO SecurityManager: SecurityManager: authentication disabled; ui acls disabled; users  with view permissions: Set(root); groups with view permissions: Set(); users  with modify permissions: Set(root); groups with modify permissions: Set()
pd0_1             | [2021/12/22 01:49:39.574 +00:00] [WARN] [retry_interceptor.go:61] ["retrying of unary invoker failed"] [target=endpoint://client-79a09b21-ab8a-4342-beeb-4d678e2ecc4b/pd0:2379] [attempt=0] [error="rpc error: code = NotFound desc = etcdserver: requested lease not found"]
pd0_1             | [2021/12/22 01:49:39.587 +00:00] [WARN] [retry_interceptor.go:61] ["retrying of unary invoker failed"] [target=endpoint://client-79a09b21-ab8a-4342-beeb-4d678e2ecc4b/pd0:2379] [attempt=0] [error="rpc error: code = NotFound desc = etcdserver: requested lease not found"]
tikv2_1 exited with code 137
tispark-slave0_1  | 21/12/22 01:49:40 INFO Utils: Successfully started service 'sparkWorker' on port 46649.
tispark-master_1  | 21/12/22 01:49:40 INFO Utils: Successfully started service 'sparkMaster' on port 7077.
tispark-master_1  | 21/12/22 01:49:40 INFO Master: Starting Spark master at spark://0.0.0.0:7077
tispark-master_1  | 21/12/22 01:49:40 INFO Master: Running Spark version 2.4.3
tispark-master_1  | 21/12/22 01:49:41 INFO Utils: Successfully started service 'MasterUI' on port 8080.
tispark-slave0_1  | 21/12/22 01:49:41 INFO Worker: Starting Spark worker 172.19.0.14:46649 with 6 cores, 1024.0 MB RAM
tispark-slave0_1  | 21/12/22 01:49:41 INFO Worker: Running Spark version 2.4.3
tispark-slave0_1  | 21/12/22 01:49:41 INFO Worker: Spark home: /opt/spark
tispark-master_1  | 21/12/22 01:49:41 INFO MasterWebUI: Bound MasterWebUI to 0.0.0.0, and started at http://2346630cca4c:8080
tispark-slave0_1  | 21/12/22 01:49:41 INFO Utils: Successfully started service 'WorkerUI' on port 38081.
tispark-slave0_1  | 21/12/22 01:49:41 INFO WorkerWebUI: Bound WorkerWebUI to 0.0.0.0, and started at http://e9f61d934c69:38081
tispark-slave0_1  | 21/12/22 01:49:41 INFO Worker: Connecting to master tispark-master:7077...
tispark-master_1  | 21/12/22 01:49:41 INFO Master: I have been elected leader! New state: ALIVE
tispark-slave0_1  | 21/12/22 01:49:41 INFO TransportClientFactory: Successfully created connection to tispark-master/172.19.0.13:7077 after 63 ms (0 ms spent in bootstraps)
tispark-master_1  | 21/12/22 01:49:42 INFO Master: Registering worker 172.19.0.14:46649 with 6 cores, 1024.0 MB RAM
tispark-slave0_1  | 21/12/22 01:49:42 INFO Worker: Successfully registered with master spark://0.0.0.0:7077
tikv2_1 exited with code 137
tikv2_1 exited with code 137
pd0_1             | [2021/12/22 01:49:54.548 +00:00] [WARN] [retry_interceptor.go:61] ["retrying of unary invoker failed"] [target=endpoint://client-79a09b21-ab8a-4342-beeb-4d678e2ecc4b/pd0:2379] [attempt=0] [error="rpc error: code = NotFound desc = etcdserver: requested lease not found"]
tikv2_1 exited with code 137
tikv1_1 exited with code 137
pd0_1             | [2021/12/22 01:50:11.822 +00:00] [WARN] [retry_interceptor.go:61] ["retrying of unary invoker failed"] [target=endpoint://client-79a09b21-ab8a-4342-beeb-4d678e2ecc4b/pd0:2379] [attempt=0] [error="rpc error: code = NotFound desc = etcdserver: requested lease not found"]
tikv2_1 exited with code 137
pd0_1             | [2021/12/22 01:50:19.995 +00:00] [WARN] [retry_interceptor.go:61] ["retrying of unary invoker failed"] [target=endpoint://client-79a09b21-ab8a-4342-beeb-4d678e2ecc4b/pd0:2379] [attempt=0] [error="rpc error: code = NotFound desc = etcdserver: requested lease not found"]
tikv1_1 exited with code 137
tikv2_1 exited with code 137
pd1_1             | [2021/12/22 01:50:33.157 +00:00] [WARN] [retry_interceptor.go:61] ["retrying of unary invoker failed"] [target=endpoint://client-0fc408b0-a4d0-41d5-abb7-b2b99c052c24/pd1:2379] [attempt=0] [error="rpc error: code = Unavailable desc = etcdserver: leader changed"]
pd0_1             | [2021/12/22 01:50:33.101 +00:00] [WARN] [retry_interceptor.go:61] ["retrying of unary invoker failed"] [target=endpoint://client-5e25b0a0-8002-41c0-9223-ddf138f6b4de/pd0:2379] [attempt=0] [error="rpc error: code = DeadlineExceeded desc = context deadline exceeded"]
pd0_1             | [2021/12/22 01:50:33.863 +00:00] [WARN] [retry_interceptor.go:61] ["retrying of unary invoker failed"] [target=endpoint://client-79a09b21-ab8a-4342-beeb-4d678e2ecc4b/pd0:2379] [attempt=0] [error="rpc error: code = NotFound desc = etcdserver: requested lease not found"]
pd0_1             | [2021/12/22 01:50:33.886 +00:00] [WARN] [retry_interceptor.go:61] ["retrying of unary invoker failed"] [target=endpoint://client-79a09b21-ab8a-4342-beeb-4d678e2ecc4b/pd0:2379] [attempt=0] [error="rpc error: code = NotFound desc = etcdserver: requested lease not found"]
tikv0_1 exited with code 137
tidb_1            | {"level":"warn","ts":"2021-12-22T01:50:49.592Z","caller":"clientv3/retry_interceptor.go:62","msg":"retrying of unary invoker failed","target":"endpoint://client-1469a4ee-07f6-4be4-917d-ee29e251c003/pd0:2379","attempt":0,"error":"rpc error: code = Unknown desc = context deadline exceeded"}
pd2_1             | [2021/12/22 01:50:49.720 +00:00] [WARN] [retry_interceptor.go:61] ["retrying of unary invoker failed"] [target=endpoint://client-4a5a3215-3c35-4046-b65b-894161479b3f/pd2:2379] [attempt=0] [error="rpc error: code = Unavailable desc = etcdserver: leader changed"]
pd0_1             | [2021/12/22 01:50:49.772 +00:00] [WARN] [retry_interceptor.go:61] ["retrying of unary invoker failed"] [target=endpoint://client-79a09b21-ab8a-4342-beeb-4d678e2ecc4b/pd0:2379] [attempt=0] [error="rpc error: code = NotFound desc = etcdserver: requested lease not found"]
pd0_1             | [2021/12/22 01:50:49.816 +00:00] [WARN] [retry_interceptor.go:61] ["retrying of unary invoker failed"] [target=endpoint://client-79a09b21-ab8a-4342-beeb-4d678e2ecc4b/pd0:2379] [attempt=0] [error="rpc error: code = NotFound desc = etcdserver: requested lease not found"]
pd0_1             | [2021/12/22 01:50:49.836 +00:00] [WARN] [retry_interceptor.go:61] ["retrying of unary invoker failed"] [target=endpoint://client-79a09b21-ab8a-4342-beeb-4d678e2ecc4b/pd0:2379] [attempt=0] [error="rpc error: code = NotFound desc = etcdserver: requested lease not found"]
tikv2_1 exited with code 137

• Default configuration, which causes tikv2_1 exited with code 137
  

• Modified configuration to increase Memory and Swap size. Now it works docker-compose up

• TiDB version available.

mysql> select tidb_version()\G
*************************** 1. row ***************************
tidb_version(): Release Version: v5.0.1
Edition: Community
Git Commit Hash: 1145e347d3469d8e89f88dce86f6926ca44b3cd8
Git Branch: heads/refs/tags/v5.0.1
UTC Build Time: 2021-04-23 05:51:17
GoVersion: go1.13
Race Enabled: false
TiKV Min Version: v3.0.0-60965b006877ca7234adaced7890d7b029ed1306
Check Table Before Drop: false
1 row in set (0.00 sec)

mysql>

Yes, this TiDB version v5.0.1 is little bit old which is discussed at #101 .

[yahonda]

Closing this issue as resolved. Thanks for the help!