Bulkload fails with no error message

Users Dgraph
1

I have been experimenting with bulkloads on docker containers, but am now running into a rather basic bulkload failure even when running dgraph on my local mac.

For sanity, I’m trying to load the 1million.rdf.gz file with the 1million.schema using the following:
kashesha$ dgraph bulk -f 1million.rdf.gz -s 1million.schema

I have pasted the output log for this command and for zero below.

When I try to run queries via ratel, no data is returned:

{
all(func: has(name)) {
uid

}

}

{
“data”: {
“all”:
},
“extensions”: {
“server_latency”: {
“parsing_ns”: 17091,
“processing_ns”: 420006,
“encoding_ns”: 1729,
“assign_timestamp_ns”: 504655
},
“txn”: {
“start_ts”: 9
}
}
}

Ratel recognises no predicates or types.

In case this is relevant, I have run into a “too many open files” error and changed this setting before.

Would greatly appreciate any pointers as to what’s going on.

[Decoder]: Using assembly version of decoder
I0218 14:04:13.182582 22131 init.go:98]

Dgraph version : v1.1.0
Dgraph SHA-256 : 98db2956f6dd8b7b9b88e02962d2036845b057fe5fe953190eaafac0a83dfcce
Commit SHA-1 : ef7cdb28
Commit timestamp : 2019-09-04 00:12:51 -0700
Branch : HEAD
Go version : go1.12.7

For Dgraph official documentation, visit https://docs.dgraph.io.
For discussions about Dgraph , visit http://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-2018 Dgraph Labs, Inc.

{
“DataFiles”: “1million.rdf.gz”,
“DataFormat”: “”,
“SchemaFile”: “1million.schema”,
“OutDir”: “./out”,
“ReplaceOutDir”: false,
“TmpDir”: “tmp”,
“NumGoroutines”: 3,
“MapBufSize”: 67108864,
“SkipMapPhase”: false,
“CleanupTmp”: true,
“NumReducers”: 1,
“Version”: false,
“StoreXids”: false,
“ZeroAddr”: “localhost:5080”,
“HttpAddr”: “localhost:8080”,
“IgnoreErrors”: false,
“CustomTokenizers”: “”,
“NewUids”: false,
“MapShards”: 1,
“ReduceShards”: 1
}

The bulk loader needs to open many files at once. This number depends on the size of the data set loaded, the map file output size, and the level of indexing. 100,000 is adequate for most data set sizes. See man ulimit for details of how to change the limit.
Current max open files limit: 256

Connecting to zero at localhost:5080
Processing file (1 out of 1): 1million.rdf.gz
[14:04:14-0800] MAP 01s nquad_count:103.4k err_count:0.000 nquad_speed:102.0k/sec edge_count:577.5k edge_speed:569.2k/sec
[14:04:15-0800] MAP 02s nquad_count:235.9k err_count:0.000 nquad_speed:116.9k/sec edge_count:1.315M edge_speed:651.9k/sec
[14:04:16-0800] MAP 03s nquad_count:366.4k err_count:0.000 nquad_speed:121.4k/sec edge_count:2.044M edge_speed:677.2k/sec
[14:04:17-0800] MAP 04s nquad_count:497.5k err_count:0.000 nquad_speed:123.6k/sec edge_count:2.778M edge_speed:690.3k/sec
[14:04:18-0800] MAP 05s nquad_count:636.3k err_count:0.000 nquad_speed:126.6k/sec edge_count:3.501M edge_speed:696.3k/sec
[14:04:19-0800] MAP 06s nquad_count:823.8k err_count:0.000 nquad_speed:136.6k/sec edge_count:4.138M edge_speed:686.4k/sec
[14:04:20-0800] MAP 07s nquad_count:1.025M err_count:0.000 nquad_speed:145.8k/sec edge_count:4.667M edge_speed:664.0k/sec
[14:04:21-0800] MAP 08s nquad_count:1.042M err_count:0.000 nquad_speed:129.7k/sec edge_count:4.719M edge_speed:587.6k/sec
[14:04:22-0800] MAP 09s nquad_count:1.042M err_count:0.000 nquad_speed:115.3k/sec edge_count:4.719M edge_speed:522.4k/sec
GC: 20. InUse: 1.0 GB. Idle: 49 MB
[14:04:23-0800] MAP 10s nquad_count:1.042M err_count:0.000 nquad_speed:103.8k/sec edge_count:4.719M edge_speed:470.2k/sec
[14:04:24-0800] MAP 11s nquad_count:1.042M err_count:0.000 nquad_speed:94.36k/sec edge_count:4.719M edge_speed:427.5k/sec
[14:04:25-0800] MAP 12s nquad_count:1.042M err_count:0.000 nquad_speed:86.27k/sec edge_count:4.719M edge_speed:390.8k/sec
Shard tmp/shards/000 → Reduce tmp/shards/shard_0/000
[14:04:26-0800] REDUCE 13s 22.10% edge_count:1.043M edge_speed:1.043M/sec plist_count:327.5k plist_speed:327.5k/sec
[14:04:27-0800] REDUCE 14s 82.70% edge_count:3.903M edge_speed:3.883M/sec plist_count:588.1k plist_speed:585.2k/sec
[14:04:28-0800] REDUCE 14s 100.00% edge_count:4.719M edge_speed:2.599M/sec plist_count:1.179M plist_speed:649.4k/sec
Total: 14s

Zero log:

[Decoder]: Using assembly version of decoder
I0218 14:02:19.735020 21750 init.go:98]

Dgraph version : v1.1.0
Dgraph SHA-256 : 98db2956f6dd8b7b9b88e02962d2036845b057fe5fe953190eaafac0a83dfcce
Commit SHA-1 : ef7cdb28
Commit timestamp : 2019-09-04 00:12:51 -0700
Branch : HEAD
Go version : go1.12.7

For Dgraph official documentation, visit https://docs.dgraph.io.
For discussions about Dgraph , visit http://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-2018 Dgraph Labs, Inc.

I0218 14:02:19.735528 21750 run.go:102] Setting up grpc listener at: 0.0.0.0:5080
I0218 14:02:19.735754 21750 run.go:102] Setting up http listener at: 0.0.0.0:6080
badger 2020/02/18 14:02:19 INFO: All 0 tables opened in 0s
I0218 14:02:19.769863 21750 node.go:143] Setting raft.Config to: &{ID:1 peers: learners: ElectionTick:20 HeartbeatTick:1 Storage:0xc0004958c0 Applied:0 MaxSizePerMsg:262144 MaxCommittedSizePerReady:67108864 MaxUncommittedEntriesSize:0 MaxInflightMsgs:256 CheckQuorum:false PreVote:true ReadOnlyOption:0 Logger:0x293e798 DisableProposalForwarding:false}
I0218 14:02:19.770759 21750 node.go:321] Group 0 found 1 entries
I0218 14:02:19.770894 21750 log.go:34] 1 became follower at term 0
I0218 14:02:19.771009 21750 log.go:34] newRaft 1 [peers: , term: 0, commit: 0, applied: 0, lastindex: 0, lastterm: 0]
I0218 14:02:19.771023 21750 log.go:34] 1 became follower at term 1
I0218 14:02:19.771590 21750 run.go:262] Running Dgraph Zero…
E0218 14:02:19.771833 21750 raft.go:517] While proposing CID: Not Zero leader. Aborting proposal: cid:“fadd4cae-28bc-47f1-bcb5-e2d7041a3c10” . Retrying…
I0218 14:02:19.778271 21750 node.go:180] Setting conf state to nodes:1
I0218 14:02:19.778714 21750 raft.go:698] Done applying conf change at 0x1
I0218 14:02:20.776448 21750 log.go:34] 1 no leader at term 1; dropping index reading msg
I0218 14:02:22.674616 21750 log.go:34] 1 is starting a new election at term 1
I0218 14:02:22.674671 21750 log.go:34] 1 became pre-candidate at term 1
I0218 14:02:22.674686 21750 log.go:34] 1 received MsgPreVoteResp from 1 at term 1
I0218 14:02:22.674718 21750 log.go:34] 1 became candidate at term 2
I0218 14:02:22.674726 21750 log.go:34] 1 received MsgVoteResp from 1 at term 2
I0218 14:02:22.674744 21750 log.go:34] 1 became leader at term 2
I0218 14:02:22.674772 21750 log.go:34] raft.node: 1 elected leader 1 at term 2
I0218 14:02:22.674830 21750 raft.go:664] I’ve become the leader, updating leases.
I0218 14:02:22.674856 21750 assign.go:41] Updated Lease id: 1. Txn Ts: 1
W0218 14:02:22.780910 21750 node.go:669] [0x1] Read index context timed out
E0218 14:02:22.780951 21750 raft.go:517] While proposing CID: Not Zero leader. Aborting proposal: cid:“6d4d0770-dda6-4bbc-a2ac-d710321d3896” . Retrying…
I0218 14:02:25.793109 21750 raft.go:510] CID set for cluster: fab0f37a-235f-499d-aa11-0210dc98c8c1
I0218 14:02:25.801057 21750 license_ee.go:45] Enterprise state proposed to the cluster: key:“z1-12899234365848207028” license:<maxNodes:18446744073709551615 expiryTs:1584655345 >
I0218 14:04:13.330088 21750 raft.go:384] Could not apply proposal, ignoring: p.MaxLeaseId=113671266855168501, p.MaxTxnTs=0 maxLeaseId=17832296255385728034 maxTxnTs=10000
I0218 14:04:13.399619 21750 raft.go:384] Could not apply proposal, ignoring: p.MaxLeaseId=313244034761207139, p.MaxTxnTs=0 maxLeaseId=18257647252174532533 maxTxnTs=10000
I0218 14:04:13.432963 21750 raft.go:384] Could not apply proposal, ignoring: p.MaxLeaseId=66109461981417990, p.MaxTxnTs=0 maxLeaseId=18257647252174532533 maxTxnTs=10000
I0218 14:04:13.593285 21750 raft.go:384] Could not apply proposal, ignoring: p.MaxLeaseId=12458108322324503, p.MaxTxnTs=0 maxLeaseId=18421302009528801076 maxTxnTs=10000
I0218 14:04:57.300324 21750 zero.go:415] Got connection request: cluster_info_only:true
I0218 14:04:57.300444 21750 zero.go:433] Connected: cluster_info_only:true
I0218 14:04:57.300990 21750 zero.go:415] Got connection request: addr:“localhost:7080”
I0218 14:04:57.301134 21750 pool.go:148] CONNECTED to localhost:7080
I0218 14:04:57.308097 21750 zero.go:554] Connected: id:1 group_id:1 addr:“localhost:7080”

2

Try adding the lang tag

{
  all(func: has(name@en)) {
    count(uid)
  }
}
3

I tried that, but get the same result:

{
all(func: has(name@en)) {
count(uid)
}
}

{
“data”: {
“all”: [
{
“count”: 0
}
]
},
“extensions”: {
“server_latency”: {
“parsing_ns”: 21779,
“processing_ns”: 377715,
“encoding_ns”: 12701,
“assign_timestamp_ns”: 442358
},
“txn”: {
“start_ts”: 3
}
}
}

Another sign that bulkload fails is that ratel recognises no predicates: There are no predicates in the schema. Click the button above to add a new predicate.

4

Live loader appears to work fine. Here is the result of the same query after live load:

{
all(func: has(name@en)) {
count(uid)
}
}

{
“data”: {
“all”: [
{
“count”: 114226
}
]
},
“extensions”: {
“server_latency”: {
“parsing_ns”: 22810,
“processing_ns”: 4840042076,
“encoding_ns”: 19737862,
“assign_timestamp_ns”: 480841
},
“txn”: {
“start_ts”: 6095
}
}
}

This makes me believe that there is an issue with bulkload.

5

Hi @kashesha, are you still having this issue?
I have done several bulkloads using local env, docker and k8s. Never happened this before, unless we commit some mistake in one of the steps.

Can you confirm your steps one by one to reproduce this?

Cheers.

6

Hi, No, we are not seeing this error anymore. I’m sorry I don’t remember the exact issue that was causing this behavior. It was quite a while ago.

7

Okay, I think you had issues loading some sample RDF files via Bulkload. Probably you’re doing good for now, xD If need anything just ping me.

Cheers.

1 Like