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

TiDB failed to write binlog while Pump TLS is enabled #935

Closed
weekface opened this issue Mar 17, 2020 · 2 comments
Closed

TiDB failed to write binlog while Pump TLS is enabled #935

weekface opened this issue Mar 17, 2020 · 2 comments
Labels
type/bug This issue is a bug

Comments

@weekface
Copy link

weekface commented Mar 17, 2020 •
edited
Loading

Bug Report

Please answer these questions before submitting your issue. Thanks!

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

I followd Enable TLS Authentication and to enable pd/tidb/tikv and pump TLS.

  1. What did you expect to see?

Everything works well.

  1. What did you see instead?

TiDB logs indicate that it failed to write binlog to pump:

[2020/03/17 08:40:19.036 +00:00] [INFO] [config_client.go:50] ["[pd] create pd configuration client with endpoints"] [pd-address="[cluster-tls-pd:2379]"]
[2020/03/17 08:40:19.078 +00:00] [INFO] [base_client.go:226] ["[pd] update member urls"] [old-urls="[http://cluster-tls-pd:2379]"] [new-urls="[https://cluster-tls-pd-0.cluster-tls-pd-peer.cluster-tls.svc:2379]"]
[2020/03/17 08:40:19.078 +00:00] [INFO] [base_client.go:242] ["[pd] switch leader"] [new-leader=https://cluster-tls-pd-0.cluster-tls-pd-peer.cluster-tls.svc:2379] [old-leader=]
[2020/03/17 08:40:19.080 +00:00] [INFO] [base_client.go:92] ["[pd] init cluster id"] [cluster-id=6805091880172613656]
[2020/03/17 08:40:19.083 +00:00] [INFO] [printer.go:41] ["Welcome to TiDB."] ["Release Version"=v4.0.0-beta-436-g164c1e472] ["Git Commit Hash"=164c1e4721a7572d6fa50caca961f7a92b4b5ecd] ["Git Branch"=master] ["UTC Build Time"="2020-03-16 02:17:40"] [GoVersion=go1.13] ["Race Enabled"=false] ["Check Table Before Drop"=false] ["TiKV Min Version"=v3.0.0-60965b006877ca7234adaced7890d7b029ed1306]
[2020/03/17 08:40:19.087 +00:00] [INFO] [printer.go:54] ["loaded config"] [config="{\"host\":\"0.0.0.0\",\"advertise-address\":\"0.0.0.0\",\"port\":4000,\"cors\":\"\",\"store\":\"tikv\",\"path\":\"cluster-tls-pd:2379\",\"socket\":\"\",\"lease\":\"45s\",\"run-ddl\":true,\"split-table\":true,\"token-limit\":1000,\"oom-use-tmp-storage\":true,\"tmp-storage-path\":\"/tmp/tidb/tmp-storage\",\"oom-action\":\"cancel\",\"mem-quota-query\":1073741824,\"enable-streaming\":false,\"enable-batch-dml\":false,\"txn-local-latches\":{\"enabled\":false,\"capacity\":2048000},\"lower-case-table-names\":2,\"server-version\":\"\",\"log\":{\"level\":\"info\",\"format\":\"text\",\"disable-timestamp\":null,\"enable-timestamp\":null,\"disable-error-stack\":null,\"enable-error-stack\":null,\"file\":{\"filename\":\"\",\"max-size\":300,\"max-days\":0,\"max-backups\":0},\"enable-slow-log\":true,\"slow-query-file\":\"tidb-slow.log\",\"slow-threshold\":300,\"expensive-threshold\":10000,\"query-log-max-len\":4096,\"record-plan-in-slow-log\":1},\"security\":{\"skip-grant-table\":false,\"ssl-ca\":\"\",\"ssl-cert\":\"\",\"ssl-key\":\"\",\"cluster-ssl-ca\":\"/var/lib/tidb-tls/ca.crt\",\"cluster-ssl-cert\":\"/var/lib/tidb-tls/tls.crt\",\"cluster-ssl-key\":\"/var/lib/tidb-tls/tls.key\",\"cluster-verify-cn\":null},\"status\":{\"status-host\":\"0.0.0.0\",\"metrics-addr\":\"\",\"status-port\":10080,\"metrics-interval\":15,\"report-status\":true,\"record-db-qps\":false},\"performance\":{\"max-procs\":0,\"max-memory\":0,\"stats-lease\":\"3s\",\"stmt-count-limit\":5000,\"feedback-probability\":0.05,\"query-feedback-limit\":1024,\"pseudo-estimate-ratio\":0.8,\"force-priority\":\"NO_PRIORITY\",\"bind-info-lease\":\"3s\",\"txn-total-size-limit\":104857600,\"tcp-keep-alive\":true,\"cross-join\":true,\"run-auto-analyze\":true},\"prepared-plan-cache\":{\"enabled\":false,\"capacity\":100,\"memory-guard-ratio\":0.1},\"opentracing\":{\"enable\":false,\"rpc-metrics\":false,\"sampler\":{\"type\":\"const\",\"param\":1,\"sampling-server-url\":\"\",\"max-operations\":0,\"sampling-refresh-interval\":0},\"reporter\":{\"queue-size\":0,\"buffer-flush-interval\":0,\"log-spans\":false,\"local-agent-host-port\":\"\"}},\"proxy-protocol\":{\"networks\":\"\",\"header-timeout\":5},\"tikv-client\":{\"grpc-connection-count\":4,\"grpc-keepalive-time\":10,\"grpc-keepalive-timeout\":3,\"commit-timeout\":\"41s\",\"max-batch-size\":128,\"overload-threshold\":200,\"max-batch-wait-time\":0,\"batch-wait-size\":8,\"enable-chunk-rpc\":true,\"region-cache-ttl\":600,\"store-limit\":0,\"copr-cache\":{\"enabled\":false,\"capacity-mb\":0,\"admission-max-result-mb\":0,\"admission-min-process-ms\":0}},\"binlog\":{\"enable\":true,\"ignore-error\":false,\"write-timeout\":\"15s\",\"binlog-socket\":\"\",\"strategy\":\"range\"},\"compatible-kill-query\":false,\"plugin\":{\"dir\":\"\",\"load\":\"\"},\"pessimistic-txn\":{\"enable\":true,\"max-retry-count\":256},\"check-mb4-value-in-utf8\":true,\"max-index-length\":3072,\"alter-primary-key\":false,\"treat-old-version-utf8-as-utf8mb4\":true,\"enable-table-lock\":false,\"delay-clean-table-lock\":0,\"split-region-max-num\":1000,\"stmt-summary\":{\"enable\":true,\"max-stmt-count\":200,\"max-sql-length\":4096,\"refresh-interval\":1800,\"history-size\":24},\"repair-mode\":false,\"repair-table-list\":[],\"isolation-read\":{\"engines\":[\"tikv\",\"tiflash\",\"tidb\"]},\"max-server-connections\":4096,\"new_collations_enabled_on_first_bootstrap\":false,\"experimental\":{\"allow-auto-random\":false},\"enable-dynamic-config\":true}"]
[2020/03/17 08:40:19.087 +00:00] [INFO] [client.go:135] ["[pd] create pd client with endpoints"] [pd-address="[cluster-tls-pd:2379]"]
[2020/03/17 08:40:19.114 +00:00] [INFO] [config_handler.go:212] ["PDConfHandler updates config successfully"] [new_version=] [accepted_conf_items="[]"] [rejected_conf_items="[]"]
[2020/03/17 08:40:19.114 +00:00] [INFO] [config_handler.go:178] ["PDConfHandler register successfully"]
[2020/03/17 08:40:19.116 +00:00] [WARN] [config_handler.go:189] ["write config to disk error"] [error="rename /tmp/tmp_conf_20200317084019.toml /etc/tidb/tidb.toml: invalid cross-device link"]
[2020/03/17 08:40:19.117 +00:00] [INFO] [base_client.go:226] ["[pd] update member urls"] [old-urls="[http://cluster-tls-pd:2379]"] [new-urls="[https://cluster-tls-pd-0.cluster-tls-pd-peer.cluster-tls.svc:2379]"]
[2020/03/17 08:40:19.118 +00:00] [INFO] [base_client.go:242] ["[pd] switch leader"] [new-leader=https://cluster-tls-pd-0.cluster-tls-pd-peer.cluster-tls.svc:2379] [old-leader=]
[2020/03/17 08:40:19.119 +00:00] [INFO] [base_client.go:92] ["[pd] init cluster id"] [cluster-id=6805091880172613656]
[2020/03/17 08:40:19.134 +00:00] [INFO] [main.go:269] [tidb-server] ["create pumps client success, ignore binlog error"=false]
[2020/03/17 08:40:19.134 +00:00] [INFO] [main.go:278] ["disable Prometheus push client"]
[2020/03/17 08:40:19.135 +00:00] [INFO] [store.go:68] ["new store"] [path=tikv://cluster-tls-pd:2379]
[2020/03/17 08:40:19.135 +00:00] [INFO] [client.go:135] ["[pd] create pd client with endpoints"] [pd-address="[cluster-tls-pd:2379]"]
[2020/03/17 08:40:19.135 +00:00] [INFO] [systime_mon.go:25] ["start system time monitor"]
[2020/03/17 08:40:20.214 +00:00] [INFO] [base_client.go:226] ["[pd] update member urls"] [old-urls="[http://cluster-tls-pd:2379]"] [new-urls="[https://cluster-tls-pd-0.cluster-tls-pd-peer.cluster-tls.svc:2379]"]
[2020/03/17 08:40:20.214 +00:00] [INFO] [base_client.go:242] ["[pd] switch leader"] [new-leader=https://cluster-tls-pd-0.cluster-tls-pd-peer.cluster-tls.svc:2379] [old-leader=]
[2020/03/17 08:40:20.215 +00:00] [INFO] [base_client.go:92] ["[pd] init cluster id"] [cluster-id=6805091880172613656]
[2020/03/17 08:40:20.242 +00:00] [INFO] [store.go:74] ["new store with retry success"]
[2020/03/17 08:40:20.345 +00:00] [INFO] [tidb.go:72] ["new domain"] [store=tikv-6805091880172613656] ["ddl lease"=45s] ["stats lease"=3s]
[2020/03/17 08:40:20.362 +00:00] [INFO] [ddl.go:278] ["[ddl] start DDL"] [ID=348137ea-c51b-45ac-9717-8c3d687ec1d3] [runWorker=true]
[2020/03/17 08:40:20.379 +00:00] [INFO] [ddl.go:266] ["[ddl] start delRangeManager OK"] ["is a emulator"=false]
[2020/03/17 08:40:20.379 +00:00] [INFO] [ddl_worker.go:130] ["[ddl] start DDL worker"] [worker="worker 2, tp add index"]
[2020/03/17 08:40:20.380 +00:00] [INFO] [ddl_worker.go:130] ["[ddl] start DDL worker"] [worker="worker 1, tp general"]
[2020/03/17 08:40:20.390 +00:00] [INFO] [manager.go:316] ["get owner"] ["owner info"="[ddl] /tidb/ddl/fg/owner ownerManager 348137ea-c51b-45ac-9717-8c3d687ec1d3"] [ownerID=348137ea-c51b-45ac-9717-8c3d687ec1d3]
[2020/03/17 08:40:20.446 +00:00] [INFO] [domain.go:144] ["full load InfoSchema success"] [usedSchemaVersion=0] [neededSchemaVersion=0] ["start time"=32.7833ms]
[2020/03/17 08:40:20.449 +00:00] [INFO] [domain.go:368] ["full load and reset schema validator"]
[2020/03/17 08:40:20.449 +00:00] [INFO] [tidb.go:200] ["rollbackTxn for ddl/autocommit failed"]
[2020/03/17 08:40:20.450 +00:00] [WARN] [session.go:1044] ["run statement failed"] [schemaVersion=0] [error="[schema:1049]Unknown database 'mysql'"] [session="{\n  \"currDBName\": \"\",\n  \"id\": 0,\n  \"status\": 2,\n  \"strictMode\": true,\n  \"user\": null\n}"]
[2020/03/17 08:40:20.451 +00:00] [WARN] [session.go:1129] ["compile SQL failed"] [error="[schema:1146]Table 'mysql.tidb' doesn't exist"] [SQL="SELECT HIGH_PRIORITY VARIABLE_VALUE FROM mysql.tidb WHERE VARIABLE_NAME=\"bootstrapped\""]
[2020/03/17 08:40:20.453 +00:00] [INFO] [session.go:2105] ["CRUCIAL OPERATION"] [conn=0] [schemaVersion=0] [cur_db=] [sql="CREATE DATABASE IF NOT EXISTS test"] [user=]
[2020/03/17 08:40:20.533 +00:00] [INFO] [ddl_worker.go:253] ["[ddl] add DDL jobs"] ["batch count"=1] [jobs="ID:2, Type:create schema, State:none, SchemaState:none, SchemaID:1, TableID:0, RowCount:0, ArgLen:1, start time: 2020-03-17 08:40:20.488 +0000 UTC, Err:<nil>, ErrCount:0, SnapshotVersion:0; "]
[2020/03/17 08:40:20.533 +00:00] [INFO] [ddl.go:457] ["[ddl] start DDL job"] [job="ID:2, Type:create schema, State:none, SchemaState:none, SchemaID:1, TableID:0, RowCount:0, ArgLen:1, start time: 2020-03-17 08:40:20.488 +0000 UTC, Err:<nil>, ErrCount:0, SnapshotVersion:0"] [query="CREATE DATABASE IF NOT EXISTS test"]
[2020/03/17 08:40:20.543 +00:00] [INFO] [ddl_worker.go:548] ["[ddl] run DDL job"] [worker="worker 1, tp general"] [job="ID:2, Type:create schema, State:none, SchemaState:none, SchemaID:1, TableID:0, RowCount:0, ArgLen:0, start time: 2020-03-17 08:40:20.488 +0000 UTC, Err:<nil>, ErrCount:0, SnapshotVersion:0"]
[2020/03/17 08:40:20.561 +00:00] [WARN] [client.go:295] ["[pumps client] write binlog to pump failed"] [NodeID=cluster-tls-pump-0:8250] ["binlog type"=Prewrite] ["start ts"=415349976737513473] ["commit ts"=0] [length=74] [error="rpc error: code = Unavailable desc = all SubConns are in TransientFailure, latest connection error: connection error: desc = \"transport: authentication handshake failed: x509: certificate is valid for cluster-tls-pump, cluster-tls-pump.cluster-tls, cluster-tls-pump.cluster-tls.svc, cluster-tls-pump-peer, cluster-tls-pump-peer.cluster-tls, cluster-tls-pump-peer.cluster-tls.svc, *.cluster-tls-pump-peer, *.cluster-tls-pump-peer.cluster-tls, *.cluster-tls-pump-peer.cluster-tls.svc, not cluster-tls-pump-0.cluster-tls-pump\""]
[2020/03/17 08:40:20.670 +00:00] [WARN] [client.go:295] ["[pumps client] write binlog to pump failed"] [NodeID=cluster-tls-pump-0:8250] ["binlog type"=Prewrite] ["start ts"=415349976737513473] ["commit ts"=0] [length=74] [error="rpc error: code = Unavailable desc = all SubConns are in TransientFailure, latest connection error: connection error: desc = \"transport: authentication handshake failed: x509: certificate is valid for cluster-tls-pump, cluster-tls-pump.cluster-tls, cluster-tls-pump.cluster-tls.svc, cluster-tls-pump-peer, cluster-tls-pump-peer.cluster-tls, cluster-tls-pump-peer.cluster-tls.svc, *.cluster-tls-pump-peer, *.cluster-tls-pump-peer.cluster-tls, *.cluster-tls-pump-peer.cluster-tls.svc, not cluster-tls-pump-0.cluster-tls-pump\""]

Pump logs:

[2020/03/17 09:51:38.991 +00:00] [INFO] [version.go:50] ["Welcome to Pump"] ["Release Version"=v4.0.0-beta.1-7-gc2c0cccd] ["Git Commit Hash"=c2c0cccd06fff2dea3f59068fc2f8a8dd5a719ce] ["Build TS"="2020-03-15 03:51:47"] ["Go Version"=go1.13] ["Go OS/Arch"=linux/amd64]
[2020/03/17 09:51:38.991 +00:00] [INFO] [main.go:48] ["start pump..."] [config="{\"log-level\":\"info\",\"node-id\":\"\",\"addr\":\"http://10.244.0.51:8250\",\"advertise-addr\":\"http://cluster-tls-pump-0.cluster-tls-pump:8250\",\"socket\":\"\",\"pd-urls\":\"https://cluster-tls-pd:2379\",\"EtcdDialTimeout\":5000000000,\"data-dir\":\"/data\",\"heartbeat-interval\":2,\"gc\":7,\"log-file\":\"\",\"security\":{\"ssl-ca\":\"/var/lib/pump-tls/ca.crt\",\"ssl-cert\":\"/var/lib/pump-tls/tls.crt\",\"ssl-key\":\"/var/lib/pump-tls/tls.key\"},\"gen-binlog-interval\":3,\"MetricsAddr\":\"\",\"MetricsInterval\":15,\"storage\":{\"sync-log\":null,\"kv_chan_cap\":0,\"slow_write_threshold\":0,\"kv\":null,\"stop-write-at-available-space\":10485760}}"]
[2020/03/17 09:51:38.992 +00:00] [INFO] [client.go:135] ["[pd] create pd client with endpoints"] [pd-address="[https://cluster-tls-pd:2379]"]
[2020/03/17 09:51:39.050 +00:00] [INFO] [base_client.go:226] ["[pd] update member urls"] [old-urls="[https://cluster-tls-pd:2379]"] [new-urls="[https://cluster-tls-pd-0.cluster-tls-pd-peer.cluster-tls.svc:2379]"]
[2020/03/17 09:51:39.050 +00:00] [INFO] [base_client.go:242] ["[pd] switch leader"] [new-leader=https://cluster-tls-pd-0.cluster-tls-pd-peer.cluster-tls.svc:2379] [old-leader=]
[2020/03/17 09:51:39.064 +00:00] [INFO] [base_client.go:92] ["[pd] init cluster id"] [cluster-id=6805112225800452120]
[2020/03/17 09:51:39.064 +00:00] [INFO] [server.go:126] ["get clusterID success"] [clusterID=6805112225800452120]
[2020/03/17 09:51:39.064 +00:00] [INFO] [client.go:135] ["[pd] create pd client with endpoints"] [pd-address="[https://cluster-tls-pd:2379]"]
[2020/03/17 09:51:39.090 +00:00] [INFO] [base_client.go:226] ["[pd] update member urls"] [old-urls="[https://cluster-tls-pd:2379]"] [new-urls="[https://cluster-tls-pd-0.cluster-tls-pd-peer.cluster-tls.svc:2379]"]
[2020/03/17 09:51:39.090 +00:00] [INFO] [base_client.go:242] ["[pd] switch leader"] [new-leader=https://cluster-tls-pd-0.cluster-tls-pd-peer.cluster-tls.svc:2379] [old-leader=]
[2020/03/17 09:51:39.092 +00:00] [INFO] [base_client.go:92] ["[pd] init cluster id"] [cluster-id=6805112225800452120]
[2020/03/17 09:51:39.128 +00:00] [WARN] [pd.go:109] ["get timestamp too slow"] ["cost time"=32.157ms]
[2020/03/17 09:51:39.129 +00:00] [INFO] [store.go:68] ["new store"] [path="tikv://cluster-tls-pd:2379?disableGC=true"]
[2020/03/17 09:51:39.129 +00:00] [INFO] [client.go:135] ["[pd] create pd client with endpoints"] [pd-address="[cluster-tls-pd:2379]"]
[2020/03/17 09:51:39.156 +00:00] [INFO] [base_client.go:226] ["[pd] update member urls"] [old-urls="[http://cluster-tls-pd:2379]"] [new-urls="[https://cluster-tls-pd-0.cluster-tls-pd-peer.cluster-tls.svc:2379]"]
[2020/03/17 09:51:39.157 +00:00] [INFO] [base_client.go:242] ["[pd] switch leader"] [new-leader=https://cluster-tls-pd-0.cluster-tls-pd-peer.cluster-tls.svc:2379] [old-leader=]
[2020/03/17 09:51:39.159 +00:00] [INFO] [base_client.go:92] ["[pd] init cluster id"] [cluster-id=6805112225800452120]
[2020/03/17 09:51:39.176 +00:00] [INFO] [store.go:74] ["new store with retry success"]
[2020/03/17 09:51:39.176 +00:00] [INFO] [storage.go:135] [NewAppendWithResolver] [options="{\"ValueLogFileSize\":524288000,\"Sync\":true,\"KVChanCapacity\":1048576,\"SlowWriteThreshold\":1,\"StopWriteAtAvailableSpace\":10485760,\"KVConfig\":null}"]
[2020/03/17 09:51:39.177 +00:00] [INFO] [storage.go:1389] ["open metadata db"] [config="{\"block-cache-capacity\":8388608,\"block-restart-interval\":16,\"block-size\":4096,\"compaction-L0-trigger\":8,\"compaction-table-size\":67108864,\"compaction-total-size\":536870912,\"compaction-total-size-multiplier\":8,\"write-buffer\":67108864,\"write-L0-pause-trigger\":24,\"write-L0-slowdown-trigger\":17}"]
[2020/03/17 09:51:39.205 +00:00] [INFO] [storage.go:217] ["Append info"] [gcTS=0] [maxCommitTS=0] [headPointer="{\"Fid\":0,\"Offset\":0}"] [handlePointer="{\"Fid\":0,\"Offset\":0}"]
[2020/03/17 09:51:39.232 +00:00] [INFO] [registry.go:95] ["node dosen't exist, will create one"] [id=cluster-tls-pump-0:8250]
[2020/03/17 09:51:39.236 +00:00] [INFO] [server.go:432] ["register success"] [NodeID=cluster-tls-pump-0:8250]
[2020/03/17 09:51:39.242 +00:00] [INFO] [server.go:444] ["notify success"]
[2020/03/17 09:51:39.242 +00:00] [INFO] [server.go:449] ["start to server request"] [addr=http://10.244.0.51:8250]
[2020/03/17 09:51:49.212 +00:00] [INFO] [storage.go:384] [DBStats] [DBStats="{\"WriteDelayCount\":0,\"WriteDelayDuration\":0,\"WritePaused\":false,\"AliveSnapshots\":0,\"AliveIterators\":0,\"IOWrite\":461,\"IORead\":0,\"BlockCacheSize\":0,\"OpenedTablesCount\":0,\"LevelSizes\":null,\"LevelTablesCounts\":null,\"LevelRead\":null,\"LevelWrite\":null,\"LevelDurations\":null}"]
[2020/03/17 09:51:49.227 +00:00] [INFO] [server.go:561] ["server info tick"] [writeBinlogCount=0] [alivePullerCount=0] [MaxCommitTS=415351100729458689]
[2020/03/17 09:51:59.176 +00:00] [INFO] [storage.go:384] [DBStats] [DBStats="{\"WriteDelayCount\":0,\"WriteDelayDuration\":0,\"WritePaused\":false,\"AliveSnapshots\":0,\"AliveIterators\":0,\"IOWrite\":1038,\"IORead\":0,\"BlockCacheSize\":0,\"OpenedTablesCount\":0,\"LevelSizes\":null,\"LevelTablesCounts\":null,\"LevelRead\":null,\"LevelWrite\":null,\"LevelDurations\":null}"]
[2020/03/17 09:51:59.206 +00:00] [INFO] [server.go:561] ["server info tick"] [writeBinlogCount=0] [alivePullerCount=0] [MaxCommitTS=415351103102124033]
[2020/03/17 09:52:09.181 +00:00] [INFO] [storage.go:384] [DBStats] [DBStats="{\"WriteDelayCount\":0,\"WriteDelayDuration\":0,\"WritePaused\":false,\"AliveSnapshots\":0,\"AliveIterators\":0,\"IOWrite\":1530,\"IORead\":0,\"BlockCacheSize\":0,\"OpenedTablesCount\":0,\"LevelSizes\":null,\"LevelTablesCounts\":null,\"LevelRead\":null,\"LevelWrite\":null,\"LevelDurations\":null}"]
[2020/03/17 09:52:09.230 +00:00] [INFO] [server.go:561] ["server info tick"] [writeBinlogCount=0] [alivePullerCount=0] [MaxCommitTS=415351105465090049]
[2020/03/17 09:52:12.388 +00:00] [WARN] [pd.go:109] ["get timestamp too slow"] ["cost time"=40.6183ms]
[2020/03/17 09:52:16.576 +00:00] [WARN] [pd.go:109] ["get timestamp too slow"] ["cost time"=400.9387ms]
[2020/03/17 09:52:19.177 +00:00] [INFO] [storage.go:384] [DBStats] [DBStats="{\"WriteDelayCount\":0,\"WriteDelayDuration\":0,\"WritePaused\":false,\"AliveSnapshots\":0,\"AliveIterators\":0,\"IOWrite\":2101,\"IORead\":0,\"BlockCacheSize\":0,\"OpenedTablesCount\":0,\"LevelSizes\":null,\"LevelTablesCounts\":null,\"LevelRead\":null,\"LevelWrite\":null,\"LevelDurations\":null}"]
[2020/03/17 09:52:19.192 +00:00] [INFO] [server.go:561] ["server info tick"] [writeBinlogCount=0] [alivePullerCount=0] [MaxCommitTS=415351108624187393]
[2020/03/17 09:52:26.215 +00:00] [WARN] [pd.go:109] ["get timestamp too slow"] ["cost time"=37.207ms]
[2020/03/17 09:52:29.143 +00:00] [INFO] [storage.go:384] [DBStats] [DBStats="{\"WriteDelayCount\":0,\"WriteDelayDuration\":0,\"WritePaused\":false,\"AliveSnapshots\":0,\"AliveIterators\":0,\"IOWrite\":2678,\"IORead\":0,\"BlockCacheSize\":0,\"OpenedTablesCount\":0,\"LevelSizes\":null,\"LevelTablesCounts\":null,\"LevelRead\":null,\"LevelWrite\":null,\"LevelDurations\":null}"]
[2020/03/17 09:52:29.159 +00:00] [INFO] [server.go:561] ["server info tick"] [writeBinlogCount=0] [alivePullerCount=0] [MaxCommitTS=415351110983221249]
[2020/03/17 09:52:39.148 +00:00] [INFO] [storage.go:384] [DBStats] [DBStats="{\"WriteDelayCount\":0,\"WriteDelayDuration\":0,\"WritePaused\":false,\"AliveSnapshots\":0,\"AliveIterators\":0,\"IOWrite\":3170,\"IORead\":0,\"BlockCacheSize\":0,\"OpenedTablesCount\":0,\"LevelSizes\":null,\"LevelTablesCounts\":null,\"LevelRead\":null,\"LevelWrite\":null,\"LevelDurations\":null}"]
[2020/03/17 09:52:39.171 +00:00] [INFO] [server.go:561] ["server info tick"] [writeBinlogCount=0] [alivePullerCount=0] [MaxCommitTS=415351113346973697]
[2020/03/17 09:52:49.147 +00:00] [INFO] [storage.go:384] [DBStats] [DBStats="{\"WriteDelayCount\":0,\"WriteDelayDuration\":0,\"WritePaused\":false,\"AliveSnapshots\":0,\"AliveIterators\":0,\"IOWrite\":3741,\"IORead\":0,\"BlockCacheSize\":0,\"OpenedTablesCount\":0,\"LevelSizes\":null,\"LevelTablesCounts\":null,\"LevelRead\":null,\"LevelWrite\":null,\"LevelDurations\":null}"]
[2020/03/17 09:52:49.177 +00:00] [INFO] [server.go:561] ["server info tick"] [writeBinlogCount=0] [alivePullerCount=0] [MaxCommitTS=415351116492701697]
[2020/03/17 09:52:59.109 +00:00] [INFO] [storage.go:384] [DBStats] [DBStats="{\"WriteDelayCount\":0,\"WriteDelayDuration\":0,\"WritePaused\":false,\"AliveSnapshots\":0,\"AliveIterators\":0,\"IOWrite\":4318,\"IORead\":0,\"BlockCacheSize\":0,\"OpenedTablesCount\":0,\"LevelSizes\":null,\"LevelTablesCounts\":null,\"LevelRead\":null,\"LevelWrite\":null,\"LevelDurations\":null}"]
[2020/03/17 09:52:59.125 +00:00] [INFO] [server.go:561] ["server info tick"] [writeBinlogCount=0] [alivePullerCount=0] [MaxCommitTS=415351118865367041]
[2020/03/17 09:53:09.109 +00:00] [INFO] [storage.go:384] [DBStats] [DBStats="{\"WriteDelayCount\":0,\"WriteDelayDuration\":0,\"WritePaused\":false,\"AliveSnapshots\":0,\"AliveIterators\":0,\"IOWrite\":4810,\"IORead\":0,\"BlockCacheSize\":0,\"OpenedTablesCount\":0,\"LevelSizes\":null,\"LevelTablesCounts\":null,\"LevelRead\":null,\"LevelWrite\":null,\"LevelDurations\":null}"]
[2020/03/17 09:53:09.125 +00:00] [INFO] [server.go:561] ["server info tick"] [writeBinlogCount=0] [alivePullerCount=0] [MaxCommitTS=415351121215488001]
[2020/03/17 09:53:19.109 +00:00] [INFO] [storage.go:384] [DBStats] [DBStats="{\"WriteDelayCount\":0,\"WriteDelayDuration\":0,\"WritePaused\":false,\"AliveSnapshots\":0,\"AliveIterators\":0,\"IOWrite\":5381,\"IORead\":0,\"BlockCacheSize\":0,\"OpenedTablesCount\":0,\"LevelSizes\":null,\"LevelTablesCounts\":null,\"LevelRead\":null,\"LevelWrite\":null,\"LevelDurations\":null}"]
[2020/03/17 09:53:19.125 +00:00] [INFO] [server.go:561] ["server info tick"] [writeBinlogCount=0] [alivePullerCount=0] [MaxCommitTS=415351124374323201]
[2020/03/17 09:53:29.076 +00:00] [INFO] [storage.go:384] [DBStats] [DBStats="{\"WriteDelayCount\":0,\"WriteDelayDuration\":0,\"WritePaused\":false,\"AliveSnapshots\":0,\"AliveIterators\":0,\"IOWrite\":5958,\"IORead\":0,\"BlockCacheSize\":0,\"OpenedTablesCount\":0,\"LevelSizes\":null,\"LevelTablesCounts\":null,\"LevelRead\":null,\"LevelWrite\":null,\"LevelDurations\":null}"]
[2020/03/17 09:53:29.092 +00:00] [INFO] [server.go:561] ["server info tick"] [writeBinlogCount=0] [alivePullerCount=0] [MaxCommitTS=415351126733619201]
[2020/03/17 09:53:35.110 +00:00] [WARN] [pd.go:109] ["get timestamp too slow"] ["cost time"=34.9492ms]
[2020/03/17 09:53:36.540 +00:00] [WARN] [ts.go:50] ["get timestamp too slow"] [take=65.0157ms]
[2020/03/17 09:53:39.084 +00:00] [INFO] [storage.go:384] [DBStats] [DBStats="{\"WriteDelayCount\":0,\"WriteDelayDuration\":0,\"WritePaused\":false,\"AliveSnapshots\":0,\"AliveIterators\":0,\"IOWrite\":6450,\"IORead\":0,\"BlockCacheSize\":0,\"OpenedTablesCount\":0,\"LevelSizes\":null,\"LevelTablesCounts\":null,\"LevelRead\":null,\"LevelWrite\":null,\"LevelDurations\":null}"]
[2020/03/17 09:53:39.094 +00:00] [INFO] [server.go:561] ["server info tick"] [writeBinlogCount=0] [alivePullerCount=0] [MaxCommitTS=415351129099730945]
[2020/03/17 09:53:48.761 +00:00] [WARN] [ts.go:50] ["get timestamp too slow"] [take=80.9601ms]
[2020/03/17 09:53:49.077 +00:00] [INFO] [storage.go:384] [DBStats] [DBStats="{\"WriteDelayCount\":0,\"WriteDelayDuration\":0,\"WritePaused\":false,\"AliveSnapshots\":0,\"AliveIterators\":0,\"IOWrite\":7021,\"IORead\":0,\"BlockCacheSize\":0,\"OpenedTablesCount\":0,\"LevelSizes\":null,\"LevelTablesCounts\":null,\"LevelRead\":null,\"LevelWrite\":null,\"LevelDurations\":null}"]
[2020/03/17 09:53:49.092 +00:00] [INFO] [server.go:561] ["server info tick"] [writeBinlogCount=0] [alivePullerCount=0] [MaxCommitTS=415351132325675009]
[2020/03/17 09:53:53.824 +00:00] [WARN] [pd.go:109] ["get timestamp too slow"] ["cost time"=40.1159ms]
[2020/03/17 09:53:53.825 +00:00] [WARN] [pd.go:109] ["get timestamp too slow"] ["cost time"=793.8282ms]
[2020/03/17 09:53:53.826 +00:00] [WARN] [pd.go:109] ["get timestamp too slow"] ["cost time"=42.1418ms]
[2020/03/17 09:53:57.064 +00:00] [WARN] [pd.go:109] ["get timestamp too slow"] ["cost time"=32.743ms]
[2020/03/17 09:53:57.948 +00:00] [WARN] [ts.go:50] ["get timestamp too slow"] [take=86.2351ms]
[2020/03/17 09:53:59.048 +00:00] [INFO] [storage.go:384] [DBStats] [DBStats="{\"WriteDelayCount\":0,\"WriteDelayDuration\":0,\"WritePaused\":false,\"AliveSnapshots\":0,\"AliveIterators\":0,\"IOWrite\":7598,\"IORead\":0,\"BlockCacheSize\":0,\"OpenedTablesCount\":0,\"LevelSizes\":null,\"LevelTablesCounts\":null,\"LevelRead\":null,\"LevelWrite\":null,\"LevelDurations\":null}"]
[2020/03/17 09:53:59.065 +00:00] [INFO] [server.go:561] ["server info tick"] [writeBinlogCount=0] [alivePullerCount=0] [MaxCommitTS=415351134670290946]
[2020/03/17 09:54:09.070 +00:00] [WARN] [pd.go:109] ["get timestamp too slow"] ["cost time"=69.1891ms]
[2020/03/17 09:54:09.070 +00:00] [INFO] [server.go:561] ["server info tick"] [writeBinlogCount=0] [alivePullerCount=0] [MaxCommitTS=415351137083588610]
[2020/03/17 09:54:09.140 +00:00] [WARN] [pd.go:109] ["get timestamp too slow"] ["cost time"=70.2243ms]
[2020/03/17 09:54:09.141 +00:00] [INFO] [storage.go:384] [DBStats] [DBStats="{\"WriteDelayCount\":0,\"WriteDelayDuration\":0,\"WritePaused\":false,\"AliveSnapshots\":0,\"AliveIterators\":0,\"IOWrite\":8090,\"IORead\":0,\"BlockCacheSize\":0,\"OpenedTablesCount\":0,\"LevelSizes\":null,\"LevelTablesCounts\":null,\"LevelRead\":null,\"LevelWrite\":null,\"LevelDurations\":null}"]

The certificate has SAN *.cluster-tls-pump-peer.cluster-tls, but TiDB failed to use cluster-tls-pump-0.cluster-tls-pump-peer.cluster-tls to connect Pump.

  1. Please provide the relate downstream type and version of drainer.
    (run drainer -V in terminal to get drainer's version)
@weekface weekface added the type/bug This issue is a bug label Mar 17, 2020
@weekface weekface mentioned this issue Mar 17, 2020
Closed
52 tasks
@july2993
Copy link
Contributor 

  [2020/03/17 08:40:20.561 +00:00] [WARN] [client.go:295] ["[pumps client] write binlog to pump failed"] [NodeID=cluster-tls-pump-0:8250] ["binlog type"=Prewrite] ["start ts"=415349976737513473] ["commit ts"=0] [length=74] [error="rpc error: code = Unavailable desc = all SubConns are in TransientFailure, latest connection error: connection error: desc = \"transport: authentication handshake failed: x509: certificate is valid for cluster-tls-pump, cluster-tls-pump.cluster-tls, cluster-tls-pump.cluster-tls.svc, cluster-tls-pump-peer, cluster-tls-pump-peer.cluster-tls, cluster-tls-pump-peer.cluster-tls.svc, *.cluster-tls-pump-peer, *.cluster-tls-pump-peer.cluster-tls, *.cluster-tls-pump-peer.cluster-tls.svc, not cluster-tls-pump-0.cluster-tls-pump\""]

, *.cluster-tls-pump-peer, *.cluster-tls-pump-peer.cluster-tls, *.cluster-tls-pump-peer.cluster-tls.svc, not cluster-tls-pump-0.cluster-tls-pump

seems you are using cluster-tls-pump-0.cluster-tls-pump not cluster-tls-pump-0.cluster-tls-pump-peer.cluster-tls ?

@weekface
Copy link
Author

@july2993 thank you very much, closing.

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

No branches or pull requests
2 participants
@weekface @july2993