Badger: dgraph alpha painc with badger assert failed error

[QthCN]

What version of Go are you using (go version)?

➜  ~ go version
go version go1.14.3 darwin/amd64

What operating system are you using?

I'm running a program using dgo on a mac, and running dgraph in a virtual box vm. vm operation system info:

thuanqin@devstack:~$ uname -a
Linux devstack 5.3.0-28-generic #30~18.04.1-Ubuntu SMP Fri Jan 17 06:14:09 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux

What version of Badger are you using?

I'm runnig dgraph as the guide/linux said. From the output I guess the version of Badger is :

/go/pkg/mod/github.com/dgraph-io/badger/[email protected]

Does this issue reproduce with the latest master?

I don't know. I'm using the dgraph binary download page, and I download it yesterday.

Steps to Reproduce the issue

Write a lot of add edge request to dgraph, and dgraph panic with following error:

2020/06/15 16:17:04 Assert failed
github.com/dgraph-io/badger/v2/y.AssertTrue
    /go/pkg/mod/github.com/dgraph-io/badger/[email protected]/y/error.go:55
github.com/dgraph-io/badger/v2/table.(*block).decrRef
    /go/pkg/mod/github.com/dgraph-io/badger/[email protected]/table/table.go:244
github.com/dgraph-io/badger/v2/table.BlockEvictHandler
    /go/pkg/mod/github.com/dgraph-io/badger/[email protected]/table/table.go:190
github.com/dgraph-io/badger/v2.Open.func4
    /go/pkg/mod/github.com/dgraph-io/badger/[email protected]/db.go:303
github.com/dgraph-io/ristretto.(*Cache).processItems
    /go/pkg/mod/github.com/dgraph-io/[email protected]/cache.go:285
runtime.goexit
    /usr/local/go/src/runtime/asm_amd64.s:1373

What Badger options were set?

I just running dgraph with following commands:

/usr/local/bin/dgraph alpha --lru_mb 4096
/usr/local/bin/Dgraph Zero

What did you do?

I'm running a program using dgo on a mac, and running dgraph in a virtual box vm. The program I'm working on will write a lot of add edge request to dgraph, and I found the dgraph panic sometime with a error stack about badger.

What did you expect to see?

dgraph running without panic.

What did you see instead?

dgraph alphaa log:

thuanqin@devstack:~$ /usr/local/bin/dgraph alpha --lru_mb 4096
[Decoder]: Using assembly version of decoder
[Sentry] 2020/06/15 15:51:04 Integration installed: ContextifyFrames
[Sentry] 2020/06/15 15:51:04 Integration installed: Environment
[Sentry] 2020/06/15 15:51:04 Integration installed: Modules
[Sentry] 2020/06/15 15:51:04 Integration installed: IgnoreErrors
[Decoder]: Using assembly version of decoder
[Sentry] 2020/06/15 15:51:04 Integration installed: ContextifyFrames
[Sentry] 2020/06/15 15:51:04 Integration installed: Environment
[Sentry] 2020/06/15 15:51:04 Integration installed: Modules
[Sentry] 2020/06/15 15:51:04 Integration installed: IgnoreErrors
I0615 15:51:05.192922    1756 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.


I0615 15:51:05.193388    1756 run.go:608] x.Config: {PortOffset:0 QueryEdgeLimit:1000000 NormalizeNodeLimit:10000}
I0615 15:51:05.193655    1756 run.go:609] x.WorkerConfig: {ExportPath:export NumPendingProposals:256 Tracing:0.01 MyAddr: ZeroAddr:[localhost:5080] RaftId:0 WhiteListedIPRanges:[] MaxRetries:-1 StrictMutations:false AclEnabled:false AbortOlderThan:5m0s SnapshotAfter:10000 ProposedGroupId:0 StartTime:2020-06-15 15:51:04.71701086 +0800 CST m=+0.015543543 LudicrousMode:false BadgerKeyFile:}
I0615 15:51:05.193812    1756 run.go:610] worker.Config: {PostingDir:p BadgerTables:mmap BadgerVlog:mmap BadgerKeyFile: BadgerCompressionLevel:3 WALDir:w MutationsMode:0 AuthToken: AllottedMemory:4096 HmacSecret:**** AccessJwtTtl:0s RefreshJwtTtl:0s AclRefreshInterval:0s}
I0615 15:51:05.193975    1756 server_state.go:75] Setting Badger Compression Level: 3
I0615 15:51:05.194136    1756 server_state.go:84] Setting Badger table load option: mmap
I0615 15:51:05.194248    1756 server_state.go:96] Setting Badger value log load option: mmap
I0615 15:51:05.194301    1756 server_state.go:141] Opening write-ahead log BadgerDB with options: {Dir:w ValueDir:w SyncWrites:false TableLoadingMode:1 ValueLogLoadingMode:2 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}
I0615 15:51:05.343189    1756 log.go:34] All 8 tables opened in 143ms
I0615 15:51:05.348964    1756 log.go:34] Replaying file id: 22 at offset: 53995355
I0615 15:51:05.349127    1756 log.go:34] Replay took: 7.584µs
I0615 15:51:05.349306    1756 server_state.go:75] Setting Badger Compression Level: 3
I0615 15:51:05.349316    1756 server_state.go:84] Setting Badger table load option: mmap
I0615 15:51:05.349319    1756 server_state.go:96] Setting Badger value log load option: mmap
I0615 15:51:05.349325    1756 server_state.go:164] Opening postings BadgerDB with options: {Dir:p ValueDir:p SyncWrites:false TableLoadingMode:2 ValueLogLoadingMode:2 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}
I0615 15:51:05.450251    1756 log.go:34] All 5 tables opened in 79ms
I0615 15:51:05.466089    1756 log.go:34] Replaying file id: 5 at offset: 95043896
I0615 15:51:05.466156    1756 log.go:34] Replay took: 3.67µs
I0615 15:51:05.467551    1756 run.go:480] Bringing up GraphQL HTTP API at 0.0.0.0:8080/graphql
I0615 15:51:05.467569    1756 run.go:481] Bringing up GraphQL HTTP admin API at 0.0.0.0:8080/admin
I0615 15:51:05.467588    1756 run.go:512] gRPC server started.  Listening on port 9080
I0615 15:51:05.467595    1756 run.go:513] HTTP server started.  Listening on port 8080
I0615 15:51:05.467673    1756 groups.go:107] Current Raft Id: 0x1
I0615 15:51:05.467723    1756 worker.go:96] Worker listening at address: [::]:7080
I0615 15:51:05.568676    1756 pool.go:160] CONNECTING to localhost:5080
I0615 15:51:05.580675    1756 groups.go:135] Connected to group zero. Assigned group: 0
I0615 15:51:05.580693    1756 groups.go:137] Raft Id after connection to Zero: 0x1
I0615 15:51:05.580832    1756 pool.go:160] CONNECTING to localhost:7080
W0615 15:51:05.582362    1756 pool.go:254] Connection lost with localhost:7080. Error: rpc error: code = Unknown desc = No node has been set up yet
I0615 15:51:05.583120    1756 draft.go:200] Node ID: 0x1 with GroupID: 1
I0615 15:51:05.583924    1756 node.go:148] Setting raft.Config to: &{ID:1 peers:[] learners:[] ElectionTick:20 HeartbeatTick:1 Storage:0xc02b373940 Applied:67560 MaxSizePerMsg:262144 MaxCommittedSizePerReady:67108864 MaxUncommittedEntriesSize:0 MaxInflightMsgs:256 CheckQuorum:false PreVote:true ReadOnlyOption:0 Logger:0x28325d0 DisableProposalForwarding:false}
I0615 15:51:05.596679    1756 node.go:306] Found Snapshot.Metadata: {ConfState:{Nodes:[1] Learners:[] XXX_unrecognized:[]} Index:67560 Term:11 XXX_unrecognized:[]}
I0615 15:51:05.597173    1756 node.go:317] Found hardstate: {Term:12 Vote:1 Commit:73707 XXX_unrecognized:[]}
I0615 15:51:05.837612    1756 node.go:326] Group 1 found 6147 entries
I0615 15:51:05.837831    1756 draft.go:1544] Restarting node for group: 1
I0615 15:51:05.838403    1756 node.go:185] Setting conf state to nodes:1
I0615 15:51:05.839669    1756 log.go:34] 1 became follower at term 12
I0615 15:51:05.840566    1756 log.go:34] newRaft 1 [peers: [1], term: 12, commit: 73707, applied: 67560, lastindex: 73707, lastterm: 12]
I0615 15:51:05.840798    1756 draft.go:147] Operation started with id: opRollup
I0615 15:51:05.841406    1756 groups.go:155] Server is ready
I0615 15:51:05.841579    1756 groups.go:782] Got address of a Zero leader: localhost:5080
I0615 15:51:05.841773    1756 groups.go:796] Starting a new membership stream receive from localhost:5080.
I0615 15:51:05.842676    1756 draft.go:962] Found Raft progress: 73706
I0615 15:51:05.843135    1756 groups.go:813] Received first state update from Zero: counter:36348 groups: > tablets: > tablets: > tablets: > tablets: > tablets: > tablets: > tablets: > tablets: > tablets: > tablets: > tablets: > tablets: > tablets: > tablets: > tablets: > tablets: > tablets: > tablets: > tablets: > tablets: > tablets: > tablets: > tablets: > tablets: > tablets: > tablets: > tablets: > tablets: > tablets: > tablets: > tablets: > tablets: > tablets: > snapshot_ts:96569 checksum:2530653943050504975 > > zeros: > maxLeaseId:19084664 maxTxnTs:110000 maxRaftId:1 cid:"caaf6a63-71a2-4988-8d46-53ddd0221caf" license:
I0615 15:51:08.643567    1756 log.go:34] 1 is starting a new election at term 12
I0615 15:51:08.643590    1756 log.go:34] 1 became pre-candidate at term 12
I0615 15:51:08.643593    1756 log.go:34] 1 received MsgPreVoteResp from 1 at term 12
I0615 15:51:08.643903    1756 log.go:34] 1 became candidate at term 13
I0615 15:51:08.643911    1756 log.go:34] 1 received MsgVoteResp from 1 at term 13
I0615 15:51:08.644434    1756 log.go:34] 1 became leader at term 13
I0615 15:51:08.644737    1756 log.go:34] raft.node: 1 elected leader 1 at term 13
I0615 15:51:08.842495    1756 groups.go:864] Leader idx=0x1 of group=1 is connecting to Zero for txn updates
I0615 15:51:08.842522    1756 groups.go:873] Got Zero leader: localhost:5080
I0615 15:51:10.511217    1756 admin.go:583] No GraphQL schema in Dgraph; serving empty GraphQL API
I0615 15:54:21.586963    1756 admin.go:356] Updating GraphQL schema from subscription.
E0615 15:54:21.587025    1756 admin.go:386] Error processing GraphQL schema: input: No schema specified.
I0615 16:03:06.827033    1756 draft.go:557] Creating snapshot at index: 77921. ReadTs: 114162.
I0615 16:04:10.593892    1756 log.go:34] Got compaction priority: {level:0 score:1 dropPrefix:[]}
I0615 16:04:10.594106    1756 log.go:34] Running for level: 0
I0615 16:04:17.985405    1756 log.go:34] LOG Compact 0->1, del 10 tables, add 8 tables, took 7.391119401s
I0615 16:04:17.985440    1756 log.go:34] Compaction for level: 0 DONE
I0615 16:05:27.162144    1756 log.go:34] Got compaction priority: {level:0 score:1 dropPrefix:[]}
I0615 16:05:27.162297    1756 log.go:34] Running for level: 0
I0615 16:05:38.546392    1756 log.go:34] LOG Compact 0->1, del 13 tables, add 11 tables, took 11.38405116s
I0615 16:05:38.546545    1756 log.go:34] Compaction for level: 0 DONE
I0615 16:06:44.164347    1756 log.go:34] Got compaction priority: {level:0 score:1 dropPrefix:[]}
I0615 16:06:44.164388    1756 log.go:34] Running for level: 0
I0615 16:06:58.176188    1756 log.go:34] LOG Compact 0->1, del 16 tables, add 14 tables, took 14.011775634s
I0615 16:06:58.176359    1756 log.go:34] Compaction for level: 0 DONE
I0615 16:09:37.593389    1756 log.go:34] Got compaction priority: {level:0 score:1 dropPrefix:[]}
I0615 16:09:37.593536    1756 log.go:34] Running for level: 0
I0615 16:09:53.465275    1756 log.go:34] LOG Compact 0->1, del 19 tables, add 16 tables, took 15.87136244s
I0615 16:09:53.465511    1756 log.go:34] Compaction for level: 0 DONE
I0615 16:10:48.896228    1756 log.go:34] Got compaction priority: {level:0 score:1 dropPrefix:[]}
I0615 16:10:48.896288    1756 log.go:34] Running for level: 0
I0615 16:10:50.470472    1756 log.go:34] LOG Compact 0->1, del 6 tables, add 4 tables, took 1.574168438s
I0615 16:10:50.470501    1756 log.go:34] Compaction for level: 0 DONE
I0615 16:10:56.162170    1756 log.go:34] Got compaction priority: {level:0 score:1 dropPrefix:[]}
I0615 16:10:56.162235    1756 log.go:34] Running for level: 0
I0615 16:11:14.290413    1756 draft.go:557] Creating snapshot at index: 88110. ReadTs: 124279.
I0615 16:11:20.052687    1756 log.go:34] LOG Compact 0->1, del 21 tables, add 19 tables, took 23.89041028s
I0615 16:11:20.053233    1756 log.go:34] Compaction for level: 0 DONE
I0615 16:11:20.053270    1756 log.go:34] Got compaction priority: {level:1 score:1.0411030948162079 dropPrefix:[]}
I0615 16:11:20.053479    1756 log.go:34] Running for level: 1
I0615 16:11:21.097878    1756 log.go:34] LOG Compact 1->2, del 1 tables, add 1 tables, took 1.044162852s
I0615 16:11:21.097923    1756 log.go:34] Compaction for level: 1 DONE
I0615 16:12:26.594967    1756 log.go:34] Got compaction priority: {level:0 score:1 dropPrefix:[]}
I0615 16:12:26.595030    1756 log.go:34] Running for level: 0
I0615 16:12:49.472572    1756 log.go:34] LOG Compact 0->1, del 23 tables, add 21 tables, took 22.877516219s
I0615 16:12:49.472629    1756 log.go:34] Compaction for level: 0 DONE
I0615 16:12:49.472664    1756 log.go:34] Got compaction priority: {level:1 score:1.1536962911486626 dropPrefix:[]}
I0615 16:12:49.472707    1756 log.go:34] Running for level: 1
I0615 16:12:50.162227    1756 log.go:34] Got compaction priority: {level:1 score:1.1092977710068226 dropPrefix:[]}
I0615 16:12:50.162288    1756 log.go:34] Running for level: 1
I0615 16:12:50.499999    1756 log.go:34] LOG Compact 1->2, del 1 tables, add 1 tables, took 1.027274736s
I0615 16:12:50.500076    1756 log.go:34] Compaction for level: 1 DONE
I0615 16:12:50.500095    1756 log.go:34] Got compaction priority: {level:1 score:1.0620409436523914 dropPrefix:[]}
I0615 16:12:50.500150    1756 log.go:34] Running for level: 1
I0615 16:12:51.397956    1756 log.go:34] LOG Compact 1->2, del 1 tables, add 1 tables, took 1.235622196s
I0615 16:12:51.398203    1756 log.go:34] Compaction for level: 1 DONE
I0615 16:12:51.734052    1756 log.go:34] LOG Compact 1->2, del 1 tables, add 1 tables, took 1.233882982s
I0615 16:12:51.734101    1756 log.go:34] Compaction for level: 1 DONE
2020/06/15 16:17:04 Assert failed
github.com/dgraph-io/badger/v2/y.AssertTrue
    /go/pkg/mod/github.com/dgraph-io/badger/[email protected]/y/error.go:55
github.com/dgraph-io/badger/v2/table.(*block).decrRef
    /go/pkg/mod/github.com/dgraph-io/badger/[email protected]/table/table.go:244
github.com/dgraph-io/badger/v2/table.BlockEvictHandler
    /go/pkg/mod/github.com/dgraph-io/badger/[email protected]/table/table.go:190
github.com/dgraph-io/badger/v2.Open.func4
    /go/pkg/mod/github.com/dgraph-io/badger/[email protected]/db.go:303
github.com/dgraph-io/ristretto.(*Cache).processItems
    /go/pkg/mod/github.com/dgraph-io/[email protected]/cache.go:285
runtime.goexit
    /usr/local/go/src/runtime/asm_amd64.s:1373
thuanqin@devstack:~$

[jarifibrahim]

Hey @QthCN, thanks for raising this issue. I'm aware of the bug and I'm working on trying to reproduce it on my end. How much data were you inserting?

[QthCN]

@jarifibrahim thanks for the response. I'm using dgraph for program analysis. I encounter this panic problem when I analysis openstack nova project's source code. The number of dgraph's node is the sum of nova's directory number + nova's file number + nova's all file's token. The number of dgraph's edge is the sum of all nova's tokens' relationship.

For example, in the following program:

[a.py]
a = 100
b = a + 100

There are 9 node in dgraph:

• file: a.py
• token: a
• token: =
• token: 100
• token: b
• token: =
• token: a
• token: +
• token: 100

and there are at least 3 edge in dgraph:

• the definition of variable a: a@line 1 -definition-> a@line 1
• the definition of variable b: b@line 2 -definition -> b@line 2
• the reference of variable a: a@line 1 -reference -> a@line 2

The dataset(dgraph disk space usage) of this project won't be very large, littler than 1GB maybe. But the add edge action(set symbol's relationship) will be execute one by one at very high speed. And the error happend when my analysis program executing these add edge action.

[jarifibrahim]

@QthCN Can you confirm the on-disk size of badger directory?

[QthCN]

Hey @jarifibrahim , dgraph never finish my request...so I don't know th disk size usage exactly.

I run my program again, and dgraph panic again. Before the running, filesystem disk usage:

thuanqin@devstack:~$ du -sh ./*
574M    ./Desktop
4.0K    ./Documents
4.0K    ./Downloads
4.0K    ./Music
58M ./p
4.0K    ./Pictures
4.0K    ./Public
4.0K    ./Templates
4.0K    ./Videos
910M    ./w
17M ./zw

after dgraph panic, filesystem disk usage:

thuanqin@devstack:~$ du -sh ./*
574M    ./Desktop
4.0K    ./Documents
4.0K    ./Downloads
4.0K    ./Music
851M    ./p
4.0K    ./Pictures
4.0K    ./Public
4.0K    ./Templates
4.0K    ./Videos
1.7G    ./w
19M ./zw

I guess the p directory, w directory and zw directory are related to the dgraph(and badger), so the disk usage is around 1.5 GB.

Here is the log for this running:

......

I0615 20:38:44.804826    2627 log.go:34] Running for level: 1
I0615 20:38:44.976013    2627 log.go:34] LOG Compact 1->2, del 1 tables, add 1 tables, took 1.305380568s
I0615 20:38:44.986434    2627 log.go:34] Compaction for level: 1 DONE
I0615 20:38:46.049075    2627 log.go:34] LOG Compact 1->2, del 1 tables, add 1 tables, took 1.244230892s
I0615 20:38:46.049362    2627 log.go:34] Compaction for level: 1 DONE
2020/06/15 20:39:38 Assert failed
github.com/dgraph-io/badger/v2/y.AssertTrue
    /go/pkg/mod/github.com/dgraph-io/badger/[email protected]/y/error.go:55
github.com/dgraph-io/badger/v2/table.(*block).decrRef
    /go/pkg/mod/github.com/dgraph-io/badger/[email protected]/table/table.go:244
github.com/dgraph-io/badger/v2/table.BlockEvictHandler
    /go/pkg/mod/github.com/dgraph-io/badger/[email protected]/table/table.go:190
github.com/dgraph-io/badger/v2.Open.func4
    /go/pkg/mod/github.com/dgraph-io/badger/[email protected]/db.go:303
github.com/dgraph-io/ristretto.(*Cache).processItems
    /go/pkg/mod/github.com/dgraph-io/[email protected]/cache.go:285
runtime.goexit
    /usr/local/go/src/runtime/asm_amd64.s:1373

[jarifibrahim]

@QthCN Can you share your program with me with instructions on how to run it? Since I can't reproduce it I can't figure out what's going wrong. You can send me an email (Ibrahim[at]dgraph.io) if you're not comfortable sharing the code here.

[QthCN]

@jarifibrahim OK, I'll try to remove unreleated code and give you the code to reproduce the problem. Thank you.

[jarifibrahim]

Duplicate of https://github.com/dgraph-io/badger/issues/1369

@QthCN were you able to send the code? I haven't received it yet. I'm eagerly waiting for it :)

[jarifibrahim]

This is fixed in ristretto via https://github.com/dgraph-io/ristretto/issues/167 and ristretto was updated in badger via https://github.com/dgraph-io/badger/pull/1391 .

@QthCN we'll update badger in dgraph soon and that would fix this crash.