Several UrsaDB backends setup in parallel: only single backend works about mquery

[ekorolevanyrun]

I noticed that there was used ursadb backend as a container from dockerhub image, which is updated 2 years ago. I build ursadb image from source code, however it doesn't work anyway. I got the same error:

web_1      | INFO:     172.21.0.1:38738 - "POST /api/query HTTP/1.1" 200 OK
daemon1_1  | [12/04/2022 06:03:49][INFO] search: MOCE25RFYVF3
daemon1_1  | [12/04/2022 06:03:49][INFO] Parsing...
daemon1_1  | [12/04/2022 06:03:49][INFO] New job, generate subtasks...
ursadb1_1  | [2022-04-12 06:03:49.558] [info] TASK: start [11]: topology;
ursadb1_1  | [2022-04-12 06:03:49.558] [info] TASK: done [11] (in 1ms)
daemon1_1  | [12/04/2022 06:03:49][INFO] Get next dataset to query...
web_1      | INFO:     172.21.0.1:38738 - "GET /api/job/MOCE25RFYVF3 HTTP/1.1" 200 OK
daemon1_1  | [12/04/2022 06:03:49][INFO] Querying backend...
ursadb1_1  | [2022-04-12 06:03:49.602] [info] TASK: start [12]: select with datasets ["10334e1a"] into iterator (((min 1 of ({457863657074696f6e}))));
ursadb1_1  | [2022-04-12 06:03:49.604] [info] TASK: done [12] (in 2ms)
ursadb1_1  | [2022-04-12 06:03:49.604] [info] CHANGE: NEW_ITERATOR itermeta.af3e1247.db.ursa
ursadb1_1  | [2022-04-12 06:03:49.604] [info] LOAD: itermeta.af3e1247.db.ursa
ursadb1_1  | [2022-04-12 06:03:49.605] [info] SAVE: db.ursa
daemon1_1  | [12/04/2022 06:03:49][INFO] Iterator af3e1247 contains 36 files
daemon1_1  | [12/04/2022 06:03:49][INFO] search: MOCE25RFYVF3
daemon1_1  | [12/04/2022 06:03:49][INFO] Parsing...
daemon1_1  | [12/04/2022 06:03:49][INFO] Get next dataset to query...
daemon1_1  | [12/04/2022 06:03:49][INFO] Nothing to query, returning...
daemon2_1  | [12/04/2022 06:03:49][INFO] yara: iterator af3e1247
ursadb2_1  | [2022-04-12 06:03:49.612] [info] LOCK: af3e1247
ursadb2_1  | [2022-04-12 06:03:49.612] [info] TASK: start [20]: iterator "af3e1247" pop 10;
ursadb2_1  | [2022-04-12 06:03:49.613] [error] Task 20 failed: tried to read non-existent iterator
ursadb2_1  | [2022-04-12 06:03:49.613] [info] TASK: done [20] (in 0ms)
web_1      | INFO:     172.21.0.1:38738 - "GET /api/matches/MOCE25RFYVF3?offset=0&limit=20 HTTP/1.1" 200 OK
web_1      | INFO:     172.21.0.1:38738 - "GET /api/matches/MOCE25RFYVF3?offset=0&limit=20 HTTP/1.1" 200 OK

Separated logs from all containers

web

web_1      | INFO:     172.21.0.1:38738 - "POST /api/query HTTP/1.1" 200 OK
web_1      | INFO:     172.21.0.1:38738 - "GET /api/job/MOCE25RFYVF3 HTTP/1.1" 200 OK
web_1      | INFO:     172.21.0.1:38738 - "GET /api/matches/MOCE25RFYVF3?offset=0&limit=20 HTTP/1.1" 200 OK
web_1      | INFO:     172.21.0.1:38738 - "GET /api/matches/MOCE25RFYVF3?offset=0&limit=20 HTTP/1.1" 200 OK

daemon1

daemon1_1  | [12/04/2022 06:03:49][INFO] search: MOCE25RFYVF3
daemon1_1  | [12/04/2022 06:03:49][INFO] Parsing...
daemon1_1  | [12/04/2022 06:03:49][INFO] New job, generate subtasks...
daemon1_1  | [12/04/2022 06:03:49][INFO] Get next dataset to query...
daemon1_1  | [12/04/2022 06:03:49][INFO] Querying backend...
daemon1_1  | [12/04/2022 06:03:49][INFO] Iterator af3e1247 contains 36 files
daemon1_1  | [12/04/2022 06:03:49][INFO] search: MOCE25RFYVF3
daemon1_1  | [12/04/2022 06:03:49][INFO] Parsing...
daemon1_1  | [12/04/2022 06:03:49][INFO] Get next dataset to query...
daemon1_1  | [12/04/2022 06:03:49][INFO] Nothing to query, returning...

ursadb1

ursadb1_1  | [2022-04-12 06:03:49.558] [info] TASK: start [11]: topology;
ursadb1_1  | [2022-04-12 06:03:49.558] [info] TASK: done [11] (in 1ms)
ursadb1_1  | [2022-04-12 06:03:49.602] [info] TASK: start [12]: select with datasets ["10334e1a"] into iterator (((min 1 of ({457863657074696f6e}))));
ursadb1_1  | [2022-04-12 06:03:49.604] [info] TASK: done [12] (in 2ms)
ursadb1_1  | [2022-04-12 06:03:49.604] [info] CHANGE: NEW_ITERATOR itermeta.af3e1247.db.ursa
ursadb1_1  | [2022-04-12 06:03:49.604] [info] LOAD: itermeta.af3e1247.db.ursa
ursadb1_1  | [2022-04-12 06:03:49.605] [info] SAVE: db.ursa

daemon2

daemon2_1  | [12/04/2022 06:03:49][INFO] yara: iterator af3e1247

ursadb2

ursadb2_1  | [2022-04-12 06:03:49.612] [info] LOCK: af3e1247
ursadb2_1  | [2022-04-12 06:03:49.612] [info] TASK: start [20]: iterator "af3e1247" pop 10;
ursadb2_1  | [2022-04-12 06:03:49.613] [error] Task 20 failed: tried to read non-existent iterator
ursadb2_1  | [2022-04-12 06:03:49.613] [info] TASK: done [20] (in 0ms)

[ekorolevanyrun]

UPD:

I found out that there is a possibility to add argument to daemon.Dockerfile ENTRYPOINT, that argument is name of a daemons group. That separates daemon's data and make process works smoother

The next step I got an obstacle: task is never finishes. Look at this condition. Function self.db.agent_finish_task() called only once for the daemon which finishes last. For the least daemons job.total_files is never equal job.files_processed.

I forked the repository and add some adjustments to make parallel daemons work, may be it will help: #271

[ekorolevanyrun]

There are another bug: the same query yara rule results with different number of matches (running 24 daemons with 24 ursadb backends)

(Note that there are different matches number, but queries are the same).

That bug is reproduced even wihout my last PR fixes

[williballenthin]

I've experienced similar inconsistencies with the number of results returned across clusters of ursadb instances. Haven't had a chance to triage yet, unfortunately.