server.go: refine log when not in online state

[july2993]

as expected to write fails, make it not a tedious error log

What problem does this PR solve?

refine log when not in online state

What is changed and how it works?

as expected to write fails, make it not a tedious error log

Check List

Tests

• Unit test
• Integration test

Code changes

Side effects

Related changes

• Need to cherry-pick to the release branch

[suzaku]

Could you please show some examples so that we can see what the log looks before and after the change?

[WangXiangUSTC]

LGTM

[july2993]

when offline a pump @suzaku

before

...
...
 80 [2019/07/25 16:52:47.935 +08:00] [ERROR] [server.go:236] ["write binlog failed"] [error="no online: closing"] [errorVerbose="no online: closing\ngithub.com/pingcap/tidb-binlog/pump.(*Server).writeBinlog\n\t/Users/huangjiahao/go/src/github.com/ping    cap/tidb-binlog/pump/server.go:222\ngithub.com/pingcap/tidb-binlog/pump.(*Server).WriteBinlog\n\t/Users/huangjiahao/go/src/github.com/pingcap/tidb-binlog/pump/server.go:186\ngithub.com/pingcap/tipb/go-binlog._Pump_WriteBinlog_Handler\n\t/Users/hua    ngjiahao/go/pkg/mod/github.com/pingcap/tipb@v0.0.0-20190428032612-535e1abaa330/go-binlog/pump.pb.go:330\ngoogle.golang.org/grpc.(*Server).processUnaryRPC\n\t/Users/huangjiahao/go/pkg/mod/google.golang.org/grpc@v1.17.0/server.go:966\ngoogle.golang.    org/grpc.(*Server).handleStream\n\t/Users/huangjiahao/go/pkg/mod/google.golang.org/grpc@v1.17.0/server.go:1245\ngoogle.golang.org/grpc.(*Server).serveStreams.func1.1\n\t/Users/huangjiahao/go/pkg/mod/google.golang.org/grpc@v1.17.0/server.go:685\nru    ntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1337"]
 81 [2019/07/25 16:52:48.036 +08:00] [ERROR] [server.go:236] ["write binlog failed"] [error="no online: closing"] [errorVerbose="no online: closing\ngithub.com/pingcap/tidb-binlog/pump.(*Server).writeBinlog\n\t/Users/huangjiahao/go/src/github.com/ping    cap/tidb-binlog/pump/server.go:222\ngithub.com/pingcap/tidb-binlog/pump.(*Server).WriteBinlog\n\t/Users/huangjiahao/go/src/github.com/pingcap/tidb-binlog/pump/server.go:186\ngithub.com/pingcap/tipb/go-binlog._Pump_WriteBinlog_Handler\n\t/Users/hua    ngjiahao/go/pkg/mod/github.com/pingcap/tipb@v0.0.0-20190428032612-535e1abaa330/go-binlog/pump.pb.go:330\ngoogle.golang.org/grpc.(*Server).processUnaryRPC\n\t/Users/huangjiahao/go/pkg/mod/google.golang.org/grpc@v1.17.0/server.go:966\ngoogle.golang.    org/grpc.(*Server).handleStream\n\t/Users/huangjiahao/go/pkg/mod/google.golang.org/grpc@v1.17.0/server.go:1245\ngoogle.golang.org/grpc.(*Server).serveStreams.func1.1\n\t/Users/huangjiahao/go/pkg/mod/google.golang.org/grpc@v1.17.0/server.go:685\nru    ntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1337"]
 82 [2019/07/25 16:52:48.146 +08:00] [ERROR] [server.go:236] ["write binlog failed"] [error="no online: closing"] [errorVerbose="no online: closing\ngithub.com/pingcap/tidb-binlog/pump.(*Server).writeBinlog\n\t/Users/huangjiahao/go/src/github.com/ping    cap/tidb-binlog/pump/server.go:222\ngithub.com/pingcap/tidb-binlog/pump.(*Server).WriteBinlog\n\t/Users/huangjiahao/go/src/github.com/pingcap/tidb-binlog/pump/server.go:186\ngithub.com/pingcap/tipb/go-binlog._Pump_WriteBinlog_Handler\n\t/Users/hua    ngjiahao/go/pkg/mod/github.com/pingcap/tipb@v0.0.0-20190428032612-535e1abaa330/go-binlog/pump.pb.go:330\ngoogle.golang.org/grpc.(*Server).processUnaryRPC\n\t/Users/huangjiahao/go/pkg/mod/google.golang.org/grpc@v1.17.0/server.go:966\ngoogle.golang.    org/grpc.(*Server).handleStream\n\t/Users/huangjiahao/go/pkg/mod/google.golang.org/grpc@v1.17.0/server.go:1245\ngoogle.golang.org/grpc.(*Server).serveStreams.func1.1\n\t/Users/huangjiahao/go/pkg/mod/google.golang.org/grpc@v1.17.0/server.go:685\nru    ntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1337"]
 83 [2019/07/25 16:52:48.257 +08:00] [ERROR] [server.go:236] ["write binlog failed"] [error="no online: closing"] [errorVerbose="no online: closing\ngithub.com/pingcap/tidb-binlog/pump.(*Server).writeBinlog\n\t/Users/huangjiahao/go/src/github.com/ping    cap/tidb-binlog/pump/server.go:222\ngithub.com/pingcap/tidb-binlog/pump.(*Server).WriteBinlog\n\t/Users/huangjiahao/go/src/github.com/pingcap/tidb-binlog/pump/server.go:186\ngithub.com/pingcap/tipb/go-binlog._Pump_WriteBinlog_Handler\n\t/Users/hua    ngjiahao/go/pkg/mod/github.com/pingcap/tipb@v0.0.0-20190428032612-535e1abaa330/go-binlog/pump.pb.go:330\ngoogle.golang.org/grpc.(*Server).processUnaryRPC\n\t/Users/huangjiahao/go/pkg/mod/google.golang.org/grpc@v1.17.0/server.go:966\ngoogle.golang.    org/grpc.(*Server).handleStream\n\t/Users/huangjiahao/go/pkg/mod/google.golang.org/grpc@v1.17.0/server.go:1245\ngoogle.golang.org/grpc.(*Server).serveStreams.func1.1\n\t/Users/huangjiahao/go/pkg/mod/google.golang.org/grpc@v1.17.0/server.go:685\nru    ntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1337"]
 84 [2019/07/25 16:52:48.360 +08:00] [ERROR] [server.go:236] ["write binlog failed"] [error="no online: closing"] [errorVerbose="no online: closing\ngithub.com/pingcap/tidb-binlog/pump.(*Server).writeBinlog\n\t/Users/huangjiahao/go/src/github.com/ping    cap/tidb-binlog/pump/server.go:222\ngithub.com/pingcap/tidb-binlog/pump.(*Server).WriteBinlog\n\t/Users/huangjiahao/go/src/github.com/pingcap/tidb-binlog/pump/server.go:186\ngithub.com/pingcap/tipb/go-binlog._Pump_WriteBinlog_Handler\n\t/Users/hua    ngjiahao/go/pkg/mod/github.com/pingcap/tipb@v0.0.0-20190428032612-535e1abaa330/go-binlog/pump.pb.go:330\ngoogle.golang.org/grpc.(*Server).processUnaryRPC\n\t/Users/huangjiahao/go/pkg/mod/google.golang.org/grpc@v1.17.0/server.go:966\ngoogle.golang.    org/grpc.(*Server).handleStream\n\t/Users/huangjiahao/go/pkg/mod/google.golang.org/grpc@v1.17.0/server.go:1245\ngoogle.golang.org/grpc.(*Server).serveStreams.func1.1\n\t/Users/huangjiahao/go/pkg/mod/google.golang.org/grpc@v1.17.0/server.go:685\nru    ntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1337"]
 85 [2019/07/25 16:52:48.462 +08:00] [ERROR] [server.go:236] ["write binlog failed"] [error="no online: closing"] [errorVerbose="no online: closing\ngithub.com/pingcap/tidb-binlog/pump.(*Server).writeBinlog\n\t/Users/huangjiahao/go/src/github.com/ping    cap/tidb-binlog/pump/server.go:222\ngithub.com/pingcap/tidb-binlog/pump.(*Server).WriteBinlog\n\t/Users/huangjiahao/go/src/github.com/pingcap/tidb-binlog/pump/server.go:186\ngithub.com/pingcap/tipb/go-binlog._Pump_WriteBinlog_Handler\n\t/Users/hua    ngjiahao/go/pkg/mod/github.com/pingcap/tipb@v0.0.0-20190428032612-535e1abaa330/go-binlog/pump.pb.go:330\ngoogle.golang.org/grpc.(*Server).processUnaryRPC\n\t/Users/huangjiahao/go/pkg/mod/google.golang.org/grpc@v1.17.0/server.go:966\ngoogle.golang.    org/grpc.(*Server).handleStream\n\t/Users/huangjiahao/go/pkg/mod/google.golang.org/grpc@v1.17.0/server.go:1245\ngoogle.golang.org/grpc.(*Server).serveStreams.func1.1\n\t/Users/huangjiahao/go/pkg/mod/google.golang.org/grpc@v1.17.0/server.go:685\nru    ntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1337"]
 86 [2019/07/25 16:52:48.502 +08:00] [INFO] [server.go:819] ["safe to offline now"]
 87 [2019/07/25 16:52:48.503 +08:00] [INFO] [server.go:828] ["update state success"] [NodeID=pump:8250] [state=offline]
 88 [2019/07/25 16:52:48.511 +08:00] [INFO] [server.go:847] ["commit status done"]
 89 [2019/07/25 16:52:48.511 +08:00] [INFO] [main.go:80] ["pump exit"]

after

...
...
[2019/07/25 16:55:46.850 +08:00] [INFO] [server.go:472] ["genFakeBinlog exit"]
[2019/07/25 16:55:46.850 +08:00] [INFO] [node.go:216] ["Heartbeat goroutine exited"]
[2019/07/25 16:55:46.850 +08:00] [INFO] [server.go:537] ["gcBinlogFile exit"]
[2019/07/25 16:55:46.850 +08:00] [INFO] [server.go:848] ["background goroutins are stopped"]
[2019/07/25 16:55:46.861 +08:00] [INFO] [server.go:883] ["The max commit ts saved is less than expected commit ts"] ["max commit ts"=410004997730467842] ["expected commit ts"=410004998542065665]
[2019/07/25 16:55:48.869 +08:00] [WARN] [server.go:802] ["Waiting for drainer to consume binlog"] ["Minimum Drainer MaxCommitTS"=410004997690097723] ["FakeBinlog CommiTS"=410004998542065665]
[2019/07/25 16:55:49.336 +08:00] [WARN] [server.go:237] ["reject write binlog for not online state"] [state=closing]
[2019/07/25 16:55:49.441 +08:00] [WARN] [server.go:237] ["reject write binlog for not online state"] [state=closing]
[2019/07/25 16:55:49.552 +08:00] [WARN] [server.go:237] ["reject write binlog for not online state"] [state=closing]
[2019/07/25 16:55:49.657 +08:00] [WARN] [server.go:237] ["reject write binlog for not online state"] [state=closing]
[2019/07/25 16:55:49.761 +08:00] [WARN] [server.go:237] ["reject write binlog for not online state"] [state=closing]
[2019/07/25 16:55:49.863 +08:00] [WARN] [server.go:237] ["reject write binlog for not online state"] [state=closing]
[2019/07/25 16:55:49.880 +08:00] [INFO] [server.go:823] ["safe to offline now"]
[2019/07/25 16:55:49.881 +08:00] [INFO] [server.go:832] ["update state success"] [NodeID=pump:8250] [state=offline]
[2019/07/25 16:55:49.881 +08:00] [INFO] [server.go:851] ["commit status done"]
[2019/07/25 16:55:49.881 +08:00] [INFO] [main.go:80] ["pump exit"]

[suzaku]

LGTM