Jormungandr: SqliteFailure: "no such table: Blocks"

[dkijania]

Topology:

Leader7 is supposed to recieve transactions and test is about to check if all nodes are updated.
However test fail due to Leader7 failure:

Jan 03 06:32:11.640 INFO Starting jormungandr 0.8.5 (master-4bbe7f52, release, linux [x86_64]) - [rustc 1.40.0 (73528e339 2019-12-16)], task: init
Jan 03 06:32:11.640 INFO storing blockchain in memory, task: init
Jan 03 06:32:11.643 INFO connecting to bootstrap peer 127.0.0.1:12013, peer_addr: 127.0.0.1:12013, task: bootstrap
Jan 03 06:32:11.645 WARN unable to reach peer for initial bootstrap, reason: HTTP/2.0 connection error, peer_addr: 127.0.0.1:12013, task: bootstrap
Jan 03 06:32:11.646 INFO start listening and accepting gRPC connections on 127.0.0.1:12011, task: network
Jan 03 06:32:11.646 INFO connecting to peer, node_id: 8b3ce6d78b92e33873831f9bceabcd5402ececba10de4f76, peer_addr: 127.0.0.1:12013, task: network
Jan 03 06:32:11.658 INFO incoming connection on 127.0.0.1:12011, peer_addr: 127.0.0.1:43050, task: network
Jan 03 06:32:12.000 INFO Leader event started, event_remaining_time: 999ms 368us 242ns, event_end: 2020-01-03T06:32:13+00:00, event_start: 2020-01-03T06:32:12+00:00, event_date: 0.3, leader_id: 1, task: leadership
Jan 03 06:32:12.000 INFO receiving block from leadership service, date: 0.3, parent: f86cb1c49767cee759c3c7e8708da983144aa7b35f28560700ff26041eaf383f, hash: fbb3881854607f97905ef0696839ab09cc9dc2daccca50e06d01ea642f4ddd43, task: block
Jan 03 06:32:12.001 INFO block from leader event successfully stored, date: 0.3, parent: f86cb1c49767cee759c3c7e8708da983144aa7b35f28560700ff26041eaf383f, hash: fbb3881854607f97905ef0696839ab09cc9dc2daccca50e06d01ea642f4ddd43, task: block
Jan 03 06:32:12.001 INFO update current branch tip, date: 0.3, parent: f86cb1c49767cee759c3c7e8708da983144aa7b35f28560700ff26041eaf383f, hash: fbb3881854607f97905ef0696839ab09cc9dc2daccca50e06d01ea642f4ddd43, task: block
Jan 03 06:32:12.004 INFO received block announcement, hash: fbb3881854607f97905ef0696839ab09cc9dc2daccca50e06d01ea642f4ddd43, direction: in, stream: block_events, node_id: 8b3ce6d78b92e33873831f9bceabcd5402ececba10de4f76, peer_addr: 127.0.0.1:12013, task: network
Jan 03 06:32:12.004 INFO received block announcement from network, from_node_id: 8b3ce6d78b92e33873831f9bceabcd5402ececba10de4f76, date: 0.3, parent: f86cb1c49767cee759c3c7e8708da983144aa7b35f28560700ff26041eaf383f, hash: fbb3881854607f97905ef0696839ab09cc9dc2daccca50e06d01ea642f4ddd43, task: block
Jan 03 06:32:24.000 INFO Leader event started, event_remaining_time: 999ms 511us 749ns, event_end: 2020-01-03T06:32:25+00:00, event_start: 2020-01-03T06:32:24+00:00, event_date: 0.15, leader_id: 1, task: leadership
Jan 03 06:32:24.000 INFO receiving block from leadership service, date: 0.15, parent: fbb3881854607f97905ef0696839ab09cc9dc2daccca50e06d01ea642f4ddd43, hash: e377176c383d6cf21ef881ab0676f8a22eb8ca867368a2cd3ab305553cc5d4ca, task: block
Jan 03 06:32:24.001 INFO block from leader event successfully stored, date: 0.15, parent: fbb3881854607f97905ef0696839ab09cc9dc2daccca50e06d01ea642f4ddd43, hash: e377176c383d6cf21ef881ab0676f8a22eb8ca867368a2cd3ab305553cc5d4ca, task: block
Jan 03 06:32:24.001 INFO update current branch tip, date: 0.15, parent: fbb3881854607f97905ef0696839ab09cc9dc2daccca50e06d01ea642f4ddd43, hash: e377176c383d6cf21ef881ab0676f8a22eb8ca867368a2cd3ab305553cc5d4ca, task: block
Jan 03 06:32:24.001 INFO connecting to peer, node_id: 8d87757ee85bf020773289c3264078c6a3c9181c4ad8a6bc, peer_addr: 127.0.0.1:12015, task: network
Jan 03 06:32:24.004 INFO received block announcement, hash: e377176c383d6cf21ef881ab0676f8a22eb8ca867368a2cd3ab305553cc5d4ca, direction: in, stream: block_events, node_id: 8b3ce6d78b92e33873831f9bceabcd5402ececba10de4f76, peer_addr: 127.0.0.1:12013, task: network
Jan 03 06:32:24.005 INFO received block announcement from network, from_node_id: 8b3ce6d78b92e33873831f9bceabcd5402ececba10de4f76, date: 0.15, parent: fbb3881854607f97905ef0696839ab09cc9dc2daccca50e06d01ea642f4ddd43, hash: e377176c383d6cf21ef881ab0676f8a22eb8ca867368a2cd3ab305553cc5d4ca, task: block
Jan 03 06:32:24.007 INFO received block announcement, hash: e377176c383d6cf21ef881ab0676f8a22eb8ca867368a2cd3ab305553cc5d4ca, direction: in, stream: block_events, node_id: 8d87757ee85bf020773289c3264078c6a3c9181c4ad8a6bc, peer_addr: 127.0.0.1:12015, task: network
Jan 03 06:32:24.008 INFO received block announcement from network, from_node_id: 8d87757ee85bf020773289c3264078c6a3c9181c4ad8a6bc, date: 0.15, parent: fbb3881854607f97905ef0696839ab09cc9dc2daccca50e06d01ea642f4ddd43, hash: e377176c383d6cf21ef881ab0676f8a22eb8ca867368a2cd3ab305553cc5d4ca, task: block
Jan 03 06:32:30.000 INFO Leader event started, event_remaining_time: 999ms 71us 923ns, event_end: 2020-01-03T06:32:31+00:00, event_start: 2020-01-03T06:32:30+00:00, event_date: 0.21, leader_id: 1, task: leadership
Jan 03 06:32:30.001 INFO receiving block from leadership service, date: 0.21, parent: e377176c383d6cf21ef881ab0676f8a22eb8ca867368a2cd3ab305553cc5d4ca, hash: 819dc906c5ffe02c87ba28a5291f0ca3211ae93be713de66b97846e417d92f52, task: block
Jan 03 06:32:30.002 INFO block from leader event successfully stored, date: 0.21, parent: e377176c383d6cf21ef881ab0676f8a22eb8ca867368a2cd3ab305553cc5d4ca, hash: 819dc906c5ffe02c87ba28a5291f0ca3211ae93be713de66b97846e417d92f52, task: block
Jan 03 06:32:30.002 INFO update current branch tip, date: 0.21, parent: e377176c383d6cf21ef881ab0676f8a22eb8ca867368a2cd3ab305553cc5d4ca, hash: 819dc906c5ffe02c87ba28a5291f0ca3211ae93be713de66b97846e417d92f52, task: block
Jan 03 06:32:30.005 INFO received block announcement, hash: 819dc906c5ffe02c87ba28a5291f0ca3211ae93be713de66b97846e417d92f52, direction: in, stream: block_events, node_id: 8d87757ee85bf020773289c3264078c6a3c9181c4ad8a6bc, peer_addr: 127.0.0.1:12015, task: network
Jan 03 06:32:30.006 INFO received block announcement from network, from_node_id: 8d87757ee85bf020773289c3264078c6a3c9181c4ad8a6bc, date: 0.21, parent: e377176c383d6cf21ef881ab0676f8a22eb8ca867368a2cd3ab305553cc5d4ca, hash: 819dc906c5ffe02c87ba28a5291f0ca3211ae93be713de66b97846e417d92f52, task: block
Jan 03 06:32:30.006 INFO received block announcement, hash: 819dc906c5ffe02c87ba28a5291f0ca3211ae93be713de66b97846e417d92f52, direction: in, stream: block_events, node_id: 8b3ce6d78b92e33873831f9bceabcd5402ececba10de4f76, peer_addr: 127.0.0.1:12013, task: network
Jan 03 06:32:30.006 INFO received block announcement from network, from_node_id: 8b3ce6d78b92e33873831f9bceabcd5402ececba10de4f76, date: 0.21, parent: e377176c383d6cf21ef881ab0676f8a22eb8ca867368a2cd3ab305553cc5d4ca, hash: 819dc906c5ffe02c87ba28a5291f0ca3211ae93be713de66b97846e417d92f52, task: block
Jan 03 06:32:31.632 INFO incoming connection on 127.0.0.1:12011, peer_addr: 127.0.0.1:43082, task: network
Jan 03 06:32:31.635 INFO incoming connection on 127.0.0.1:12011, peer_addr: 127.0.0.1:43088, task: network
Jan 03 06:32:31.637 INFO incoming connection on 127.0.0.1:12011, peer_addr: 127.0.0.1:43098, task: network
Jan 03 06:32:37.001 INFO Leader event started, event_remaining_time: 998ms 621us 311ns, event_end: 2020-01-03T06:32:38+00:00, event_start: 2020-01-03T06:32:37+00:00, event_date: 0.28, leader_id: 1, task: leadership
Jan 03 06:32:37.001 INFO receiving block from leadership service, date: 0.28, parent: 819dc906c5ffe02c87ba28a5291f0ca3211ae93be713de66b97846e417d92f52, hash: 111fe4e3c78c12105299c3534574545477abb44ea14a1d76e85d7b922c6874e0, task: block
Jan 03 06:32:37.002 INFO block from leader event successfully stored, date: 0.28, parent: 819dc906c5ffe02c87ba28a5291f0ca3211ae93be713de66b97846e417d92f52, hash: 111fe4e3c78c12105299c3534574545477abb44ea14a1d76e85d7b922c6874e0, task: block
Jan 03 06:32:37.002 INFO update current branch tip, date: 0.28, parent: 819dc906c5ffe02c87ba28a5291f0ca3211ae93be713de66b97846e417d92f52, hash: 111fe4e3c78c12105299c3534574545477abb44ea14a1d76e85d7b922c6874e0, task: block
Jan 03 06:32:37.002 INFO connecting to peer, node_id: 984f185df8dd698d8431123ec42210473a094994dcafd963, peer_addr: 127.0.0.1:12012, task: network
Jan 03 06:32:37.004 INFO error while streaming response, error: Error { code: Internal, cause: BackendError(SqliteFailure(Error { code: Unknown, extended_code: 1 }, Some("no such table: Blocks"))) }, request: GetBlocks, sub_task: server, task: network
Jan 03 06:32:37.005 INFO error while streaming response, error: Error { code: Internal, cause: BackendError(SqliteFailure(Error { code: Unknown, extended_code: 1 }, Some("no such table: Blocks"))) }, solicitation: UploadBlocks, node_id: 8d87757ee85bf020773289c3264078c6a3c9181c4ad8a6bc, peer_addr: 127.0.0.1:12015, task: network
Jan 03 06:32:37.005 INFO UploadBlocks request failed, error: Error { code: Internal, source: Status { code: Internal, message: "h2 protocol error: protocol error: unexpected internal error encountered" } }, node_id: 8d87757ee85bf020773289c3264078c6a3c9181c4ad8a6bc, peer_addr: 127.0.0.1:12015, task: network
Jan 03 06:32:37.006 INFO received block announcement, hash: 111fe4e3c78c12105299c3534574545477abb44ea14a1d76e85d7b922c6874e0, direction: in, stream: block_events, node_id: 8b3ce6d78b92e33873831f9bceabcd5402ececba10de4f76, peer_addr: 127.0.0.1:12013, task: network
Jan 03 06:32:37.006 INFO received block announcement from network, from_node_id: 8b3ce6d78b92e33873831f9bceabcd5402ececba10de4f76, date: 0.28, parent: 819dc906c5ffe02c87ba28a5291f0ca3211ae93be713de66b97846e417d92f52, hash: 111fe4e3c78c12105299c3534574545477abb44ea14a1d76e85d7b922c6874e0, task: block
Jan 03 06:32:37.011 INFO received block announcement, hash: 111fe4e3c78c12105299c3534574545477abb44ea14a1d76e85d7b922c6874e0, direction: in, stream: block_events, node_id: eba38f70a62e328779d6e3f549ca3fe53cb556bc6f5e9779, sub_task: server, task: network
Jan 03 06:32:37.011 INFO received block announcement, hash: 111fe4e3c78c12105299c3534574545477abb44ea14a1d76e85d7b922c6874e0, direction: in, stream: block_events, node_id: 8d87757ee85bf020773289c3264078c6a3c9181c4ad8a6bc, peer_addr: 127.0.0.1:12015, task: network
Jan 03 06:32:37.011 INFO received block announcement from network, from_node_id: eba38f70a62e328779d6e3f549ca3fe53cb556bc6f5e9779, date: 0.28, parent: 819dc906c5ffe02c87ba28a5291f0ca3211ae93be713de66b97846e417d92f52, hash: 111fe4e3c78c12105299c3534574545477abb44ea14a1d76e85d7b922c6874e0, task: block
Jan 03 06:32:37.011 INFO received block announcement from network, from_node_id: 8d87757ee85bf020773289c3264078c6a3c9181c4ad8a6bc, date: 0.28, parent: 819dc906c5ffe02c87ba28a5291f0ca3211ae93be713de66b97846e417d92f52, hash: 111fe4e3c78c12105299c3534574545477abb44ea14a1d76e85d7b922c6874e0, task: block
Jan 03 06:32:37.012 INFO received block announcement, hash: 111fe4e3c78c12105299c3534574545477abb44ea14a1d76e85d7b922c6874e0, direction: in, stream: block_events, node_id: 0d6f9d55ddb0c90647928ebaa87c5b0ae845b63442856635, sub_task: server, task: network
Jan 03 06:32:37.012 INFO received block announcement from network, from_node_id: 0d6f9d55ddb0c90647928ebaa87c5b0ae845b63442856635, date: 0.28, parent: 819dc906c5ffe02c87ba28a5291f0ca3211ae93be713de66b97846e417d92f52, hash: 111fe4e3c78c12105299c3534574545477abb44ea14a1d76e85d7b922c6874e0, task: block
Jan 03 06:32:37.015 INFO received block announcement, hash: 111fe4e3c78c12105299c3534574545477abb44ea14a1d76e85d7b922c6874e0, direction: in, stream: block_events, node_id: 5cf703e9fa35fd5466150f4c1f955f4f7dcebb7446340fc0, sub_task: server, task: network
Jan 03 06:32:37.015 INFO received block announcement from network, from_node_id: 5cf703e9fa35fd5466150f4c1f955f4f7dcebb7446340fc0, date: 0.28, parent: 819dc906c5ffe02c87ba28a5291f0ca3211ae93be713de66b97846e417d92f52, hash: 111fe4e3c78c12105299c3534574545477abb44ea14a1d76e85d7b922c6874e0, task: block
Jan 03 06:32:37.016 INFO received block announcement, hash: 111fe4e3c78c12105299c3534574545477abb44ea14a1d76e85d7b922c6874e0, direction: in, stream: block_events, node_id: 984f185df8dd698d8431123ec42210473a094994dcafd963, peer_addr: 127.0.0.1:12012, task: network
Jan 03 06:32:37.016 INFO received block announcement from network, from_node_id: 984f185df8dd698d8431123ec42210473a094994dcafd963, date: 0.28, parent: 819dc906c5ffe02c87ba28a5291f0ca3211ae93be713de66b97846e417d92f52, hash: 111fe4e3c78c12105299c3534574545477abb44ea14a1d76e85d7b922c6874e0, task: block
Jan 03 06:32:54.000 INFO Leader event started, event_remaining_time: 999ms 271us 775ns, event_end: 2020-01-03T06:32:55+00:00, event_start: 2020-01-03T06:32:54+00:00, event_date: 0.45, leader_id: 1, task: leadership
Jan 03 06:32:54.000 INFO receiving block from leadership service, date: 0.45, parent: 111fe4e3c78c12105299c3534574545477abb44ea14a1d76e85d7b922c6874e0, hash: 037d74a2fc8529ab071de004fffa01feefe213bfb6e3fa5d7fd003e6f6f6e56f, task: block
Jan 03 06:32:54.001 ERRO cannot process leadership block, reason: cannot process leadership block, date: 0.45, parent: 111fe4e3c78c12105299c3534574545477abb44ea14a1d76e85d7b922c6874e0, hash: 037d74a2fc8529ab071de004fffa01feefe213bfb6e3fa5d7fd003e6f6f6e56f, task: block
Jan 03 06:32:57.001 INFO Leader event started, event_remaining_time: 998ms 858us 689ns, event_end: 2020-01-03T06:32:58+00:00, event_start: 2020-01-03T06:32:57+00:00, event_date: 0.48, leader_id: 1, task: leadership
Jan 03 06:32:57.001 INFO receiving block from leadership service, date: 0.48, parent: 111fe4e3c78c12105299c3534574545477abb44ea14a1d76e85d7b922c6874e0, hash: 75edb9ab47354918762c3bc9e8abac7e8f3a4355af70ef40429bf65465f0e2fd, task: block
Jan 03 06:32:57.001 ERRO cannot process leadership block, reason: cannot process leadership block, date: 0.48, parent: 111fe4e3c78c12105299c3534574545477abb44ea14a1d76e85d7b922c6874e0, hash: 75edb9ab47354918762c3bc9e8abac7e8f3a4355af70ef40429bf65465f0e2fd, task: block
Jan 03 06:33:12.004 INFO Leader event started, event_remaining_time: 995ms 960us 494ns, event_end: 2020-01-03T06:33:13+00:00, event_start: 2020-01-03T06:33:12+00:00, event_date: 1.3, leader_id: 1, task: leadership
Jan 03 06:33:12.004 INFO receiving block from leadership service, date: 1.3, parent: 111fe4e3c78c12105299c3534574545477abb44ea14a1d76e85d7b922c6874e0, hash: dfcaa42d88f7bba0c5cffa0f52fb0d318fd21abc229c3f9ef39c3d0d7284f6e5, task: block
Jan 03 06:33:12.004 ERRO cannot process leadership block, reason: cannot process leadership block, date: 1.3, parent: 111fe4e3c78c12105299c3534574545477abb44ea14a1d76e85d7b922c6874e0, hash: dfcaa42d88f7bba0c5cffa0f52fb0d318fd21abc229c3f9ef39c3d0d7284f6e5, task: block
Jan 03 06:33:19.000 INFO Leader event started, event_remaining_time: 999ms 328us 183ns, event_end: 2020-01-03T06:33:20+00:00, event_start: 2020-01-03T06:33:19+00:00, event_date: 1.10, leader_id: 1, task: leadership
Jan 03 06:33:19.000 INFO receiving block from leadership service, date: 1.10, parent: 111fe4e3c78c12105299c3534574545477abb44ea14a1d76e85d7b922c6874e0, hash: a02e3098b7d18b10e2e264642baf2e10d8b23e5c5c2b6c26fa0b8f9509645f97, task: block
Jan 03 06:33:19.001 ERRO cannot process leadership block, reason: cannot process leadership block, date: 1.10, parent: 111fe4e3c78c12105299c3534574545477abb44ea14a1d76e85d7b922c6874e0, hash: a02e3098b7d18b10e2e264642baf2e10d8b23e5c5c2b6c26fa0b8f9509645f97, task: block
Jan 03 06:33:21.001 INFO Leader event started, event_remaining_time: 998ms 964us 925ns, event_end: 2020-01-03T06:33:22+00:00, event_start: 2020-01-03T06:33:21+00:00, event_date: 1.12, leader_id: 1, task: leadership
Jan 03 06:33:21.001 INFO receiving block from leadership service, date: 1.12, parent: 111fe4e3c78c12105299c3534574545477abb44ea14a1d76e85d7b922c6874e0, hash: 90a6f646659c7e5dbdd54813b55ebcaeee6d5fad86bdcac02c7a3ebeabe9dbe3, task: block
Jan 03 06:33:21.002 ERRO cannot process leadership block, reason: cannot process leadership block, date: 1.12, parent: 111fe4e3c78c12105299c3534574545477abb44ea14a1d76e85d7b922c6874e0, hash: 90a6f646659c7e5dbdd54813b55ebcaeee6d5fad86bdcac02c7a3ebeabe9dbe3, task: block'

Mandatory Information

1. jcli --full-version output;
   jcli 0.8.5 (master-4bbe7f52, release, linux [x86_64]) - [rustc 1.40.0 (73528e339 2019-12-16)]
2. jormungandr --full-version output;
   jormungandr 0.8.5 (master-4bbe7f52, release, linux [x86_64]) - [rustc 1.40.0 (73528e339 2019-12-16)]
   To Reproduce
   Steps to reproduce the behavior:
3. start jormungandr-scenario-tests 'tree' scenario:
4. cd jormungandr-scenario-tests
5. cargo run -- --scenario tree

Expected behavior
No Error

Additional context
Failure occurred during nightly run

[eugene-babichenko]

Is this error repeating consistently?

[eugene-babichenko]

After a quick research I came up with a reason of what is happening.

After #1412 was the node can use multiple connections to the database. However, the :memory: path is special. Unless opened with SQLITE_OPEN_SHARED_CACHE it creates unique per-connection in-memory databases. Due that, once the connection pool returns a connection, different from the one used for initialization, we just hit an empty database with no schema. When called with SQLITE_OPEN_SHARED_CACHE there is in fact one "real" connection hidden behind the caching system (and so there is one in-memory db).

The quick solution to this is to open file::memory:?cache=shared. Another one may be to forcefully enable sqlite shared cache for all connections. This may also give us a performance improvement.