Grpc Echo timeout

[hhtlxhhxy]

If you suspect this could be a bug, follow the template.

• What version of Dgraph are you using?
  Dgraph version : v1.0.12-rc3
  Commit SHA-1 : a136935
  Commit timestamp : 2019-01-14 10:49:15 -0800
  Branch : HEAD
  Go version : go1.11.1

• Have you tried reproducing the issue with latest release?
  Yes

• What is the hardware spec (RAM, OS)?
  RAM: 256G
  OS: CentOS Linux release 7.2.1511 (Core)

• Steps to reproduce the issue (command/config used to run Dgraph).
  Zero:

dgraph zero --my 10.237.7.231:5080 --replicas 3 --log_dir /export/data/dgraph

Alpha:

dgraph alpha --debugmode --pending_proposals 20 --max_retries 10 --my 10.237.7.231:7083 --lru_mb 163840 --zero 10.237.7.231:5080 -o 3  --log_dir /export/data/dgraph
dgraph alpha --debugmode --pending_proposals 20 --max_retries 10 --my 10.237.7.230:7083 --lru_mb 163840 --zero 10.237.7.231:5080 -o 3  --log_dir /export/data/dgraph
dgraph alpha --debugmode --pending_proposals 20 --max_retries 10 --my 10.237.7.232:7083 --lru_mb 163840 --zero 10.237.7.231:5080 -o 3  --log_dir /export/data/dgraph

the alpha error log:

E0122 12:14:10.083323   76857 pool.go:204] Echo error from 10.237.7.231:7083. Err: rpc error: code = DeadlineExceeded desc = context deadline exceeded
E0122 12:14:18.083198   76857 pool.go:204] Echo error from 10.237.7.231:7083. Err: rpc error: code = DeadlineExceeded desc = context deadline exceeded
E0122 12:14:28.083152   76857 pool.go:204] Echo error from 10.237.7.231:7083. Err: rpc error: code = DeadlineExceeded desc = context deadline exceeded
E0122 12:14:35.419328   76857 groups.go:869] Error in oracle delta stream. Error: rpc error: code = Canceled desc = context canceled
E0122 12:14:41.083193   76857 pool.go:204] Echo error from 10.237.7.231:7083. Err: rpc error: code = DeadlineExceeded desc = context deadline exceeded
E0122 12:14:48.083247   76857 pool.go:204] Echo error from 10.237.7.231:7083. Err: rpc error: code = DeadlineExceeded desc = context deadline exceeded
E0122 12:14:58.389756   76857 groups.go:869] Error in oracle delta stream. Error: rpc error: code = Canceled desc = context canceled
E0122 12:21:17.083762   76857 pool.go:204] Echo error from 10.237.7.231:7083. Err: rpc error: code = DeadlineExceeded desc = context deadline exceeded
E0122 12:22:28.189989   76857 groups.go:869] Error in oracle delta stream. Error: rpc error: code = Canceled desc = context canceled
E0122 12:22:28.189797   76857 pool.go:204] Echo error from 10.237.7.231:5080. Err: rpc error: code = DeadlineExceeded desc = context deadline exceeded
E0122 12:22:29.352068   76857 pool.go:204] Echo error from 10.237.7.232:7083. Err: rpc error: code = DeadlineExceeded desc = context deadline exceeded
E0122 12:27:56.728473   76857 groups.go:869] Error in oracle delta stream. Error: rpc error: code = Canceled desc = context canceled
E0122 12:28:25.083196   76857 pool.go:204] Echo error from 10.237.7.231:7083. Err: rpc error: code = DeadlineExceeded desc = context deadline exceeded
E0122 12:37:59.083484   76857 pool.go:204] Echo error from 10.237.7.231:7083. Err: rpc error: code = DeadlineExceeded desc = context deadline exceeded
E0122 12:45:55.083246   76857 pool.go:204] Echo error from 10.237.7.231:7083. Err: rpc error: code = DeadlineExceeded desc = context deadline exceeded
E0122 12:58:25.083267   76857 pool.go:204] Echo error from 10.237.7.231:7083. Err: rpc error: code = DeadlineExceeded desc = context deadline exceeded
E0122 13:02:27.083230   76857 pool.go:204] Echo error from 10.237.7.231:7083. Err: rpc error: code = DeadlineExceeded desc = context deadline exceeded
E0122 13:02:29.083274   76857 pool.go:204] Echo error from 10.237.7.231:7083. Err: rpc error: code = DeadlineExceeded desc = context deadline exceeded

the ping log:

64 bytes from 10.237.7.231: icmp_seq=2976 ttl=64 time=0.088 ms  2019-01-22 12:14:00
64 bytes from 10.237.7.231: icmp_seq=2977 ttl=64 time=0.053 ms  2019-01-22 12:14:01
64 bytes from 10.237.7.231: icmp_seq=2978 ttl=64 time=0.090 ms  2019-01-22 12:14:02
64 bytes from 10.237.7.231: icmp_seq=2979 ttl=64 time=0.107 ms  2019-01-22 12:14:03
64 bytes from 10.237.7.231: icmp_seq=2980 ttl=64 time=0.067 ms  2019-01-22 12:14:04
64 bytes from 10.237.7.231: icmp_seq=2981 ttl=64 time=0.056 ms  2019-01-22 12:14:05
64 bytes from 10.237.7.231: icmp_seq=2982 ttl=64 time=0.055 ms  2019-01-22 12:14:06
64 bytes from 10.237.7.231: icmp_seq=2983 ttl=64 time=0.089 ms  2019-01-22 12:14:07
64 bytes from 10.237.7.231: icmp_seq=2984 ttl=64 time=0.062 ms  2019-01-22 12:14:08
64 bytes from 10.237.7.231: icmp_seq=2985 ttl=64 time=0.056 ms  2019-01-22 12:14:09
64 bytes from 10.237.7.231: icmp_seq=2986 ttl=64 time=0.099 ms  2019-01-22 12:14:10
64 bytes from 10.237.7.231: icmp_seq=2987 ttl=64 time=0.128 ms  2019-01-22 12:14:11
64 bytes from 10.237.7.231: icmp_seq=2988 ttl=64 time=0.100 ms  2019-01-22 12:14:12
64 bytes from 10.237.7.231: icmp_seq=2989 ttl=64 time=0.093 ms  2019-01-22 12:14:13
64 bytes from 10.237.7.231: icmp_seq=2990 ttl=64 time=0.115 ms  2019-01-22 12:14:14
64 bytes from 10.237.7.231: icmp_seq=2991 ttl=64 time=0.057 ms  2019-01-22 12:14:15
64 bytes from 10.237.7.231: icmp_seq=2992 ttl=64 time=0.066 ms  2019-01-22 12:14:16
64 bytes from 10.237.7.231: icmp_seq=2993 ttl=64 time=0.065 ms  2019-01-22 12:14:17
64 bytes from 10.237.7.231: icmp_seq=2994 ttl=64 time=0.072 ms  2019-01-22 12:14:18
64 bytes from 10.237.7.231: icmp_seq=2995 ttl=64 time=0.052 ms  2019-01-22 12:14:19
64 bytes from 10.237.7.231: icmp_seq=2996 ttl=64 time=0.054 ms  2019-01-22 12:14:20
64 bytes from 10.237.7.231: icmp_seq=2997 ttl=64 time=0.068 ms  2019-01-22 12:14:21
64 bytes from 10.237.7.231: icmp_seq=2998 ttl=64 time=0.068 ms  2019-01-22 12:14:22
64 bytes from 10.237.7.231: icmp_seq=2999 ttl=64 time=0.075 ms  2019-01-22 12:14:23
64 bytes from 10.237.7.231: icmp_seq=3000 ttl=64 time=0.063 ms  2019-01-22 12:14:24
64 bytes from 10.237.7.231: icmp_seq=3001 ttl=64 time=0.085 ms  2019-01-22 12:14:25
64 bytes from 10.237.7.231: icmp_seq=3002 ttl=64 time=0.061 ms  2019-01-22 12:14:26
64 bytes from 10.237.7.231: icmp_seq=3003 ttl=64 time=0.061 ms  2019-01-22 12:14:27
64 bytes from 10.237.7.231: icmp_seq=3004 ttl=64 time=0.122 ms  2019-01-22 12:14:28
64 bytes from 10.237.7.231: icmp_seq=3005 ttl=64 time=0.047 ms  2019-01-22 12:14:29
64 bytes from 10.237.7.231: icmp_seq=3006 ttl=64 time=0.047 ms  2019-01-22 12:14:30
64 bytes from 10.237.7.231: icmp_seq=3007 ttl=64 time=0.055 ms  2019-01-22 12:14:31
64 bytes from 10.237.7.231: icmp_seq=3008 ttl=64 time=0.080 ms  2019-01-22 12:14:32
64 bytes from 10.237.7.231: icmp_seq=3009 ttl=64 time=0.087 ms  2019-01-22 12:14:33
64 bytes from 10.237.7.231: icmp_seq=3010 ttl=64 time=0.058 ms  2019-01-22 12:14:34
64 bytes from 10.237.7.231: icmp_seq=3011 ttl=64 time=0.071 ms  2019-01-22 12:14:35
64 bytes from 10.237.7.231: icmp_seq=3012 ttl=64 time=0.049 ms  2019-01-22 12:14:36
64 bytes from 10.237.7.231: icmp_seq=3013 ttl=64 time=0.056 ms  2019-01-22 12:14:37
64 bytes from 10.237.7.231: icmp_seq=3014 ttl=64 time=0.062 ms  2019-01-22 12:14:38
64 bytes from 10.237.7.231: icmp_seq=3015 ttl=64 time=0.069 ms  2019-01-22 12:14:39
64 bytes from 10.237.7.231: icmp_seq=3016 ttl=64 time=0.118 ms  2019-01-22 12:14:40
64 bytes from 10.237.7.231: icmp_seq=3017 ttl=64 time=0.067 ms  2019-01-22 12:14:41
64 bytes from 10.237.7.231: icmp_seq=3018 ttl=64 time=0.070 ms  2019-01-22 12:14:42
64 bytes from 10.237.7.231: icmp_seq=3019 ttl=64 time=0.077 ms  2019-01-22 12:14:43
64 bytes from 10.237.7.231: icmp_seq=3020 ttl=64 time=0.104 ms  2019-01-22 12:14:44
64 bytes from 10.237.7.231: icmp_seq=3021 ttl=64 time=0.069 ms  2019-01-22 12:14:45
64 bytes from 10.237.7.231: icmp_seq=3022 ttl=64 time=0.071 ms  2019-01-22 12:14:46
64 bytes from 10.237.7.231: icmp_seq=3023 ttl=64 time=0.063 ms  2019-01-22 12:14:47
64 bytes from 10.237.7.231: icmp_seq=3024 ttl=64 time=0.050 ms  2019-01-22 12:14:48
64 bytes from 10.237.7.231: icmp_seq=3025 ttl=64 time=0.055 ms  2019-01-22 12:14:49
64 bytes from 10.237.7.231: icmp_seq=3026 ttl=64 time=0.059 ms  2019-01-22 12:14:50
64 bytes from 10.237.7.231: icmp_seq=3027 ttl=64 time=0.063 ms  2019-01-22 12:14:51
64 bytes from 10.237.7.231: icmp_seq=3028 ttl=64 time=0.107 ms  2019-01-22 12:14:52
64 bytes from 10.237.7.231: icmp_seq=3029 ttl=64 time=0.055 ms  2019-01-22 12:14:53
64 bytes from 10.237.7.231: icmp_seq=3030 ttl=64 time=0.049 ms  2019-01-22 12:14:54
64 bytes from 10.237.7.231: icmp_seq=3031 ttl=64 time=0.054 ms  2019-01-22 12:14:55
64 bytes from 10.237.7.231: icmp_seq=3032 ttl=64 time=0.068 ms  2019-01-22 12:14:56
64 bytes from 10.237.7.231: icmp_seq=3033 ttl=64 time=0.074 ms  2019-01-22 12:14:57
64 bytes from 10.237.7.231: icmp_seq=3034 ttl=64 time=0.061 ms  2019-01-22 12:14:58
64 bytes from 10.237.7.231: icmp_seq=3035 ttl=64 time=0.059 ms  2019-01-22 12:14:59
64 bytes from 10.237.7.231: icmp_seq=3036 ttl=64 time=0.071 ms  2019-01-22 12:15:00
64 bytes from 10.237.7.231: icmp_seq=3037 ttl=64 time=0.065 ms  2019-01-22 12:15:01
64 bytes from 10.237.7.231: icmp_seq=3038 ttl=64 time=0.126 ms  2019-01-22 12:15:02



64 bytes from 10.237.7.231: icmp_seq=3476 ttl=64 time=0.098 ms  2019-01-22 12:22:20
64 bytes from 10.237.7.231: icmp_seq=3477 ttl=64 time=0.109 ms  2019-01-22 12:22:21
64 bytes from 10.237.7.231: icmp_seq=3478 ttl=64 time=0.115 ms  2019-01-22 12:22:22
64 bytes from 10.237.7.231: icmp_seq=3479 ttl=64 time=0.098 ms  2019-01-22 12:22:23
64 bytes from 10.237.7.231: icmp_seq=3480 ttl=64 time=0.144 ms  2019-01-22 12:22:24
64 bytes from 10.237.7.231: icmp_seq=3481 ttl=64 time=0.092 ms  2019-01-22 12:22:25
64 bytes from 10.237.7.231: icmp_seq=3482 ttl=64 time=0.105 ms  2019-01-22 12:22:26
64 bytes from 10.237.7.231: icmp_seq=3483 ttl=64 time=0.096 ms  2019-01-22 12:22:27
64 bytes from 10.237.7.231: icmp_seq=3484 ttl=64 time=0.119 ms  2019-01-22 12:22:28
64 bytes from 10.237.7.231: icmp_seq=3485 ttl=64 time=0.100 ms  2019-01-22 12:22:29
64 bytes from 10.237.7.231: icmp_seq=3486 ttl=64 time=0.087 ms  2019-01-22 12:22:30
64 bytes from 10.237.7.231: icmp_seq=3487 ttl=64 time=0.090 ms  2019-01-22 12:22:31
64 bytes from 10.237.7.231: icmp_seq=3488 ttl=64 time=0.115 ms  2019-01-22 12:22:32
64 bytes from 10.237.7.231: icmp_seq=3489 ttl=64 time=0.092 ms  2019-01-22 12:22:33
64 bytes from 10.237.7.231: icmp_seq=3490 ttl=64 time=0.104 ms  2019-01-22 12:22:34
64 bytes from 10.237.7.231: icmp_seq=3491 ttl=64 time=0.095 ms  2019-01-22 12:22:35

there are no packet loss

[codexnull]

I am unable to reproduce this behavior. Does the problem still happen if you run

dgraph alpha --debugmode --pending_proposals 20 --max_retries 10 --my 10.237.7.231:7081 --lru_mb 163840 --zero 10.237.7.231:5080 -o 1 --log_dir /export/data/dgraph
dgraph alpha --debugmode --pending_proposals 20 --max_retries 10 --my 10.237.7.231:7082 --lru_mb 163840 --zero 10.237.7.231:5080 -o 2 --log_dir /export/data/dgraph
dgraph alpha --debugmode --pending_proposals 20 --max_retries 10 --my 10.237.7.231:7083 --lru_mb 163840 --zero 10.237.7.231:5080 -o 3 --log_dir /export/data/dgraph

instead? That is, use the same IP address but different port and offset for the alphas.

[hhtlxhhxy]

I can not do that because my p/ dir size is 1.3T, and I have almost 20 billion edges. I upgrade my CentOS to CentOS Linux release 7.6.1810 (Core) and update the network card drive. But the error still exist. I have a question that the size of your test data? And as far as I know, I'm not alone in this error, I have a friend who has the same problem . It seems like the data size increase, errors begin to appear.

I don't think it was an error caused by too much load on the server, because as below:
alpha log in 10.237.7.231

I0125 11:26:39.549462 124843 groups.go:768] Running cleaning at Node: 3 Group: 1
I0125 11:26:39.564621 124843 groups.go:807] Cleanup Done
E0125 11:30:33.417548 124843 pool.go:204] Echo error from 10.237.7.232:7083. Err: rpc error: code = DeadlineExceeded desc = context deadline exceeded
W0125 11:30:33.429461 124843 node.go:352] No healthy connection to node Id: 1 addr: [10.237.7.232:7083], err: Unhealthy connection
I0125 11:30:33.470797 124843 pool.go:215] Connection established with 10.237.7.232:7083
I0125 11:31:39.549386 124843 groups.go:768] Running cleaning at Node: 3 Group: 1
I0125 11:31:39.562811 124843 groups.go:807] Cleanup Done
I0125 11:36:39.549418 124843 groups.go:768] Running cleaning at Node: 3 Group: 1

At the same time , alpha log in 10.237.7.232

I0125 11:24:39.986394 122124 node.go:83] Rolling up Sent 23591 keys
I0125 11:24:39.986801 122124 draft.go:802] Rolled up 23591 keys. Done
I0125 11:24:39.986810 122124 draft.go:350] List rollup at Ts 131259: OK.
E0125 11:30:33.504069 122124 pool.go:204] Echo error from 10.237.7.231:7083. Err: rpc error: code = DeadlineExceeded desc = context deadline exceeded
E0125 11:30:33.504281 122124 pool.go:204] Echo error from 10.237.7.230:7083. Err: rpc error: code = DeadlineExceeded desc = context deadline exceeded
W0125 11:30:33.504532 122124 node.go:352] No healthy connection to node Id: 3 addr: [10.237.7.231:7083], err: Unhealthy connection
I0125 11:30:33.505922 122124 pool.go:215] Connection established with 10.237.7.231:7083
I0125 11:30:33.506119 122124 pool.go:215] Connection established with 10.237.7.230:7083

And the server monitor in zabbix:

And there are no query and mutation when the error occur:

[manishrjain]

I've merged the change above and cherry picked it in release/v1.0. Can you try building from that branch, and seeing how Dgraph behaves?

[hhtlxhhxy]

e...I build the dgraph from the branch master , I find that the change has been merged into matser branch.But I get another error like that:

2019-01-31 13:49:24.568 ERROR - btc grapher mutate error, insert again:%!(EXTRA *status.statusError=rpc error: code = Unknown desc = cannot add value with uid 32a8e7ee to predicate include because one of the existing values does not match this uid, either delete the existing values first or modify the schema to 'include: [uid]')

my program can not run ...

Now I try to build the dgraph from v1.0

[manishrjain]

Build from Release/v1.0 branch as mentioned above.

[hhtlxhhxy]

the same error in Release/v1.0

2019-01-31 17:51:05.480 ERROR - btc grapher mutate error, insert again:%!(EXTRA *status.statusError=rpc error: code = Unknown desc = cannot add value with uid 32a8feef to predicate include because one of the existing values does not match this uid, either delete the existing values first or modify the schema to 'include: [uid]')

Then I change dgraph to version v1.0.12-rc3 , the error does not exist.

[martinmr]

Can you check again if your build is actually from that branch? I check release/v1.0's history and the commit that would give you that error is not there so I don't know how it is you are getting that error.

[manishrjain]

Hey @hhtlxhhxy : Can you confirm that this change works? Otherwise, if we don't hear back from you, I'll go ahead and close this issue.