[Decoder]: Using assembly version of decoder
[Sentry] 2020/07/30 05:54:35 Integration installed: ContextifyFrames
[Sentry] 2020/07/30 05:54:35 Integration installed: Environment
[Sentry] 2020/07/30 05:54:35 Integration installed: Modules
[Sentry] 2020/07/30 05:54:35 Integration installed: IgnoreErrors
[Decoder]: Using assembly version of decoder
[Sentry] 2020/07/30 05:54:35 Integration installed: ContextifyFrames
[Sentry] 2020/07/30 05:54:35 Integration installed: Environment
[Sentry] 2020/07/30 05:54:35 Integration installed: Modules
[Sentry] 2020/07/30 05:54:35 Integration installed: IgnoreErrors
I0730 05:54:35.728863      13 init.go:99] 

Dgraph version   : v20.03.3
Dgraph SHA-256   : 08424035910be6b6720570427948bab8352a0b5a6d59a0d20c3ec5ed29533121
Commit SHA-1     : fa3c19120
Commit timestamp : 2020-06-02 16:47:25 -0700
Branch           : HEAD
Go version       : go1.14.1

For Dgraph official documentation, visit https://docs.dgraph.io.
For discussions about Dgraph     , visit https://discuss.dgraph.io.
To say hi to the community       , visit https://dgraph.slack.com.

Licensed variously under the Apache Public License 2.0 and Dgraph Community License.
Copyright 2015-2020 Dgraph Labs, Inc.


I0730 05:54:35.729434      13 run.go:608] x.Config: {PortOffset:0 QueryEdgeLimit:1000 NormalizeNodeLimit:1000}
I0730 05:54:35.729466      13 run.go:609] x.WorkerConfig: {ExportPath:export NumPendingProposals:256 Tracing:0.01 MyAddr:10.50.34.68:7080 ZeroAddr:[10.50.34.90:5080] RaftId:4 WhiteListedIPRanges:[{Lower:172.17.0.1 Upper:172.17.0.1}] MaxRetries:3 StrictMutations:false AclEnabled:false AbortOlderThan:5m0s SnapshotAfter:10000 ProposedGroupId:0 StartTime:2020-07-30 05:54:35.25583462 +0000 UTC m=+0.017785348 LudicrousMode:false BadgerKeyFile:}
I0730 05:54:35.729518      13 run.go:610] worker.Config: {PostingDir:/home/ubuntu/server1/p BadgerTables:disk BadgerVlog:disk BadgerKeyFile: BadgerCompressionLevel:3 WALDir:/home/ubuntu/server1/w MutationsMode:0 AuthToken: AllottedMemory:4096 HmacSecret:**** AccessJwtTtl:0s RefreshJwtTtl:0s AclRefreshInterval:0s}
I0730 05:54:35.729711      13 server_state.go:75] Setting Badger Compression Level: 3
I0730 05:54:35.729721      13 server_state.go:84] Setting Badger table load option: disk
I0730 05:54:35.729727      13 server_state.go:96] Setting Badger value log load option: disk
I0730 05:54:35.729734      13 server_state.go:141] Opening write-ahead log BadgerDB with options: {Dir:/home/ubuntu/server1/w ValueDir:/home/ubuntu/server1/w SyncWrites:false TableLoadingMode:1 ValueLogLoadingMode:0 NumVersionsToKeep:1 ReadOnly:false Truncate:true Logger:0x28325d0 Compression:2 InMemory:false MaxTableSize:67108864 LevelSizeMultiplier:10 MaxLevels:7 ValueThreshold:1048576 NumMemtables:5 BlockSize:4096 BloomFalsePositive:0.01 KeepL0InMemory:true MaxCacheSize:10485760 MaxBfCacheSize:0 LoadBloomsOnOpen:false NumLevelZeroTables:5 NumLevelZeroTablesStall:10 LevelOneSize:268435456 ValueLogFileSize:1073741823 ValueLogMaxEntries:10000 NumCompactors:2 CompactL0OnClose:true LogRotatesToFlush:2 ZSTDCompressionLevel:3 VerifyValueChecksum:false EncryptionKey:[] EncryptionKeyRotationDuration:240h0m0s BypassLockGuard:false ChecksumVerificationMode:0 KeepBlockIndicesInCache:false KeepBlocksInCache:false managedTxns:false maxBatchCount:0 maxBatchSize:0}
I0730 05:54:35.742998      13 log.go:34] All 0 tables opened in 0s
I0730 05:54:35.745827      13 server_state.go:75] Setting Badger Compression Level: 3
I0730 05:54:35.745882      13 server_state.go:84] Setting Badger table load option: disk
I0730 05:54:35.745891      13 server_state.go:96] Setting Badger value log load option: disk
I0730 05:54:35.745899      13 server_state.go:164] Opening postings BadgerDB with options: {Dir:/home/ubuntu/server1/p ValueDir:/home/ubuntu/server1/p SyncWrites:false TableLoadingMode:0 ValueLogLoadingMode:0 NumVersionsToKeep:2147483647 ReadOnly:false Truncate:true Logger:0x28325d0 Compression:2 InMemory:false MaxTableSize:67108864 LevelSizeMultiplier:10 MaxLevels:7 ValueThreshold:1024 NumMemtables:5 BlockSize:4096 BloomFalsePositive:0.01 KeepL0InMemory:true MaxCacheSize:1073741824 MaxBfCacheSize:0 LoadBloomsOnOpen:false NumLevelZeroTables:5 NumLevelZeroTablesStall:10 LevelOneSize:268435456 ValueLogFileSize:1073741823 ValueLogMaxEntries:1000000 NumCompactors:2 CompactL0OnClose:true LogRotatesToFlush:2 ZSTDCompressionLevel:3 VerifyValueChecksum:false EncryptionKey:[] EncryptionKeyRotationDuration:240h0m0s BypassLockGuard:false ChecksumVerificationMode:0 KeepBlockIndicesInCache:true KeepBlocksInCache:true managedTxns:false maxBatchCount:0 maxBatchSize:0}
I0730 05:54:35.762425      13 log.go:34] All 0 tables opened in 0s
I0730 05:54:35.766969      13 run.go:480] Bringing up GraphQL HTTP API at 0.0.0.0:8080/graphql
I0730 05:54:35.767004      13 run.go:481] Bringing up GraphQL HTTP admin API at 0.0.0.0:8080/admin
I0730 05:54:35.767032      13 run.go:512] gRPC server started.  Listening on port 9080
I0730 05:54:35.767182      13 run.go:513] HTTP server started.  Listening on port 8080
I0730 05:54:35.767224      13 groups.go:107] Current Raft Id: 0x4
I0730 05:54:35.767308      13 worker.go:96] Worker listening at address: [::]:7080
I0730 05:54:35.882482      13 pool.go:160] CONNECTING to 10.50.34.90:5080
I0730 05:54:35.889380      13 groups.go:135] Connected to group zero. Assigned group: 2
I0730 05:54:35.889400      13 groups.go:137] Raft Id after connection to Zero: 0x4
I0730 05:54:35.889454      13 pool.go:160] CONNECTING to 10.50.34.68:7081
I0730 05:54:35.890140      13 pool.go:160] CONNECTING to 10.50.34.90:7082
I0730 05:54:35.890205      13 pool.go:160] CONNECTING to 10.50.34.90:7081
I0730 05:54:35.890229      13 pool.go:160] CONNECTING to 10.50.34.90:7080
I0730 05:54:35.891430      13 draft.go:200] Node ID: 0x4 with GroupID: 2
I0730 05:54:35.891495      13 node.go:148] Setting raft.Config to: &{ID:4 peers:[] learners:[] ElectionTick:20 HeartbeatTick:1 Storage:0xc0000f6f00 Applied:0 MaxSizePerMsg:262144 MaxCommittedSizePerReady:67108864 MaxUncommittedEntriesSize:0 MaxInflightMsgs:256 CheckQuorum:false PreVote:true ReadOnlyOption:0 Logger:0x28325d0 DisableProposalForwarding:false}
I0730 05:54:35.891580      13 node.go:326] Group 2 found 0 entries
I0730 05:54:35.891589      13 draft.go:1505] Calling IsPeer
I0730 05:54:35.892136      13 draft.go:1510] Done with IsPeer call
I0730 05:54:35.892149      13 draft.go:1567] New Node for group: 2
I0730 05:54:35.892156      13 draft.go:1574] Trying to join peers.
I0730 05:54:35.892163      13 draft.go:1488] Calling JoinCluster via leader: 10.50.34.68:7081
I0730 05:54:35.896062      13 draft.go:1492] Done with JoinCluster call
I0730 05:54:35.896433      13 log.go:34] 4 became follower at term 0
I0730 05:54:35.896793      13 log.go:34] newRaft 4 [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastterm: 0]
I0730 05:54:35.896817      13 log.go:34] 4 became follower at term 1
I0730 05:54:35.897176      13 draft.go:147] Operation started with id: opRollup
I0730 05:54:35.897526      13 groups.go:155] Server is ready
I0730 05:54:35.897700      13 draft.go:962] Found Raft progress: 0
I0730 05:54:35.897906      13 groups.go:782] Got address of a Zero leader: 10.50.34.90:5080
I0730 05:54:35.898300      13 groups.go:796] Starting a new membership stream receive from 10.50.34.90:5080.
I0730 05:54:35.899100      13 groups.go:813] Received first state update from Zero: counter:14 groups:<key:1 value:<members:<key:1 value:<id:1 group_id:1 addr:"10.50.34.90:7080" leader:true last_update:1596088454 > > members:<key:2 value:<id:2 group_id:1 addr:"10.50.34.90:7081" > > members:<key:3 value:<id:3 group_id:1 addr:"10.50.34.90:7082" > > tablets:<key:"dgraph.graphql.schema" value:<group_id:1 predicate:"dgraph.graphql.schema" > > tablets:<key:"dgraph.type" value:<group_id:1 predicate:"dgraph.type" > > checksum:3103359118597316741 > > groups:<key:2 value:<members:<key:4 value:<id:4 group_id:2 addr:"10.50.34.68:7080" > > members:<key:5 value:<id:5 group_id:2 addr:"10.50.34.68:7081" leader:true last_update:1596088475 > > > > zeros:<key:1 value:<id:1 addr:"10.50.34.90:5080" leader:true > > maxTxnTs:10000 cid:"d6fec2d9-89a6-409d-a7b1-8d7871c7247d" license:<maxNodes:18446744073709551615 expiryTs:1598680456 enabled:true > 
I0730 05:54:36.899403      13 pool.go:160] CONNECTING to 10.50.34.68:7082
I0730 05:54:36.928235      13 log.go:34] 4 [term: 1] received a MsgHeartbeat message with higher term from 5 [term: 2]
I0730 05:54:36.928268      13 log.go:34] 4 became follower at term 2
I0730 05:54:36.928291      13 log.go:34] raft.node: 4 elected leader 5 at term 2
I0730 05:54:37.933307      13 node.go:185] Setting conf state to nodes:5 
I0730 05:54:37.933369      13 node.go:185] Setting conf state to nodes:4 nodes:5 
I0730 05:54:37.934202      13 node.go:185] Setting conf state to nodes:4 nodes:5 nodes:6 
I0730 05:54:37.944860      13 draft.go:147] Operation started with id: opIndexing
I0730 05:54:37.944915      13 draft.go:112] Operation completed with id: opRollup
I0730 05:54:37.944967      13 index.go:857] Deleting index for attr dgraph.graphql.xid and tokenizers []
I0730 05:54:37.944975      13 index.go:871] Deleting index for attr dgraph.graphql.xid and tokenizers [exact]
I0730 05:54:37.944987      13 log.go:34] DropPrefix Called
I0730 05:54:37.945711      13 log.go:34] Writes flushed. Stopping compactions now...
I0730 05:54:37.948111      13 log.go:34] DropPrefix done
I0730 05:54:37.948152      13 log.go:34] Resuming writes
I0730 05:54:37.948177      13 log.go:34] DropPrefix Called
I0730 05:54:37.948190      13 log.go:34] Writes flushed. Stopping compactions now...
I0730 05:54:37.950195      13 log.go:34] DropPrefix done
I0730 05:54:37.950254      13 log.go:34] Resuming writes
I0730 05:54:37.950298      13 log.go:34] DropPrefix Called
I0730 05:54:37.950316      13 log.go:34] Writes flushed. Stopping compactions now...
I0730 05:54:37.952062      13 log.go:34] DropPrefix done
I0730 05:54:37.952111      13 log.go:34] Resuming writes
I0730 05:54:37.952135      13 log.go:34] DropPrefix Called
I0730 05:54:37.952152      13 log.go:34] Writes flushed. Stopping compactions now...
I0730 05:54:37.953682      13 log.go:34] DropPrefix done
I0730 05:54:37.953738      13 log.go:34] Resuming writes
I0730 05:54:37.953794      13 index.go:902] Rebuilding index for attr dgraph.graphql.xid and tokenizers [exact]
I0730 05:54:37.964073      13 log.go:34] All 0 tables opened in 0s
I0730 05:54:37.970693      13 log.go:34] Rebuilding index for predicate dgraph.graphql.xid (1/2): Sent 0 keys
I0730 05:54:37.972663      13 log.go:34] Rebuilding index for predicate dgraph.graphql.xid (2/2): Sent 0 keys
I0730 05:54:37.972837      13 log.go:34] Got compaction priority: {level:0 score:1.73 dropPrefix:[]}
I0730 05:54:37.977500      13 mutation.go:193] Done schema update predicate:"dgraph.graphql.xid" value_type:STRING directive:INDEX tokenizer:"exact" upsert:true 
I0730 05:54:37.977606      13 draft.go:112] Operation completed with id: opIndexing
I0730 05:54:37.978601      13 draft.go:147] Operation started with id: opIndexing
I0730 05:54:37.978901      13 draft.go:112] Operation completed with id: opIndexing
I0730 05:54:39.978809      13 draft.go:147] Operation started with id: opIndexing
I0730 05:54:39.979334      13 draft.go:112] Operation completed with id: opIndexing
I0730 05:54:40.775908      13 admin.go:356] Updating GraphQL schema from subscription.
E0730 05:54:40.775928      13 admin.go:386] Error processing GraphQL schema: input: No schema specified.  
I0730 05:54:40.783111      13 admin.go:583] No GraphQL schema in Dgraph; serving empty GraphQL API
I0730 05:54:47.977791      13 draft.go:147] Operation started with id: opRollup
I0730 06:25:00.120332      13 http.go:560] Got alter request via HTTP from 10.50.1.57:51592
I0730 06:25:00.120471      13 server.go:137] Received ALTER op: schema:"<entity_type>: string .\n<entity_value>: string @index(exact) @count .\n<phone>: [uid] @count @reverse .\n<device>: [uid] @count @reverse ." 
I0730 06:25:00.121410      13 server.go:268] Got schema: &{Preds:[predicate:"entity_type" value_type:STRING  predicate:"entity_value" value_type:STRING directive:INDEX tokenizer:"exact" count:true  predicate:"phone" value_type:UID directive:REVERSE count:true list:true  predicate:"device" value_type:UID directive:REVERSE count:true list:true ] Types:[]}
I0730 06:25:00.128997      13 server.go:287] ALTER op: schema:"<entity_type>: string .\n<entity_value>: string @index(exact) @count .\n<phone>: [uid] @count @reverse .\n<device>: [uid] @count @reverse ."  done
W0730 06:50:35.391572      13 draft.go:1183] Raft.Ready took too long to process: Timer Total: 858ms. Breakdown: [{sync 858ms} {disk 0s} {proposals 0s} {advance 0s}] Num entries: 1. MustSync: true
I0730 06:50:35.870576      13 draft.go:557] Creating snapshot at index: 13822. ReadTs: 19544.
W0730 06:52:16.841172      13 draft.go:1183] Raft.Ready took too long to process: Timer Total: 1.388s. Breakdown: [{sync 1.387s} {disk 0s} {proposals 0s} {advance 0s}] Num entries: 1. MustSync: true
I0730 06:52:53.440490      13 log.go:34] Got compaction priority: {level:0 score:1 dropPrefix:[]}
I0730 06:52:53.440546      13 log.go:34] Running for level: 0
I0730 06:52:53.568206      13 log.go:34] LOG Compact 0->1, del 5 tables, add 1 tables, took 127.637272ms
I0730 06:52:53.568281      13 log.go:34] Compaction for level: 0 DONE
I0730 06:53:35.869713      13 draft.go:557] Creating snapshot at index: 26938. ReadTs: 38206.
W0730 06:56:30.666696      13 draft.go:1183] Raft.Ready took too long to process: Timer Total: 997ms. Breakdown: [{sync 997ms} {disk 0s} {proposals 0s} {advance 0s}] Num entries: 1. MustSync: true
I0730 06:56:35.879991      13 draft.go:557] Creating snapshot at index: 40204. ReadTs: 57086.
I0730 06:57:47.440610      13 log.go:34] Got compaction priority: {level:0 score:1 dropPrefix:[]}
I0730 06:57:47.440673      13 log.go:34] Running for level: 0
I0730 06:57:47.662458      13 log.go:34] LOG Compact 0->1, del 6 tables, add 1 tables, took 221.758444ms
I0730 06:57:47.662495      13 log.go:34] Compaction for level: 0 DONE
W0730 06:59:06.422442      13 draft.go:1183] Raft.Ready took too long to process: Timer Total: 1.324s. Breakdown: [{sync 1.323s} {disk 1ms} {proposals 0s} {advance 0s}] Num entries: 1. MustSync: true
I0730 06:59:35.868930      13 draft.go:557] Creating snapshot at index: 53186. ReadTs: 75551.
I0730 07:02:35.877423      13 draft.go:557] Creating snapshot at index: 65652. ReadTs: 93322.
I0730 07:03:09.440524      13 log.go:34] Got compaction priority: {level:0 score:1 dropPrefix:[]}
I0730 07:03:09.440577      13 log.go:34] Running for level: 0
I0730 07:03:09.929538      13 log.go:34] LOG Compact 0->1, del 6 tables, add 1 tables, took 488.938878ms
I0730 07:03:09.929600      13 log.go:34] Compaction for level: 0 DONE
I0730 07:05:35.878644      13 draft.go:557] Creating snapshot at index: 78848. ReadTs: 112099.
W0730 07:07:22.163433      13 draft.go:1183] Raft.Ready took too long to process: Timer Total: 1.907s. Breakdown: [{sync 1.907s} {disk 0s} {proposals 0s} {advance 0s}] Num entries: 1. MustSync: true
I0730 07:08:35.868275      13 draft.go:557] Creating snapshot at index: 90820. ReadTs: 129145.
I0730 07:08:36.440579      13 log.go:34] Got compaction priority: {level:0 score:1 dropPrefix:[]}
I0730 07:08:36.440641      13 log.go:34] Running for level: 0
I0730 07:08:36.797782      13 log.go:34] LOG Compact 0->1, del 6 tables, add 1 tables, took 357.116229ms
I0730 07:08:36.797845      13 log.go:34] Compaction for level: 0 DONE
I0730 07:28:35.856847      13 draft.go:557] Creating snapshot at index: 100890. ReadTs: 143332.