missing cache entry #173
Description
There are occasionally posts missing in hive_posts_cache. This condition is rare but concerning. Fortunately it does not affect the hive_posts table so it's easily recoverable. Identifying the cause is important because it touches core operating assumptions.
The latest example: missing: {'id': 68799912, 'author': 'jeffjagoe', 'permlink': 'survey-blockchain-developer-salaries-have-increased-over-the-past-six-months-via-the-block', 'depth': 0, 'created_at': datetime.datetime(2019, 1, 14, 13, 31, 39), 'is_deleted': False}. There's a handful of others dated around December 20th; they could have been explained by a different bug, but not this last case.
The post originated in 9fd5a440e16572662ab6b5f35827f41f19a794db @ 29,449464.
Logs do not show anything particularly suspect. It shows 1 post and 1 edit for this block, which is accurate. The record in question was a new post, not an edit, and has not been edited since. It was registered in hive_posts yet somehow eluded hive_posts_cache. The sync process appears to be completely uninterrupted.
Jan 14 13:31:35 INFO:hive.indexer.sync:[LIVE] Got block 29449460 at 2019-01-14T13:31:27 -- 14 txs, 3 posts, 1 edits, 5 payouts, 5 votes, 2 counts, 9 accts, 2 follows -- 123ms
Jan 14 13:31:38 INFO:hive.indexer.sync:[LIVE] Got block 29449461 at 2019-01-14T13:31:30 -- 23 txs, 0 posts, 0 edits, 4 payouts, 8 votes, 1 counts, 9 accts, 0 follows -- 62ms
Jan 14 13:31:41 INFO:hive.steem.block.schedule:block 29449464 not available. head:29449464 drift:2.778000s
Jan 14 13:31:41 INFO:hive.indexer.sync:[LIVE] Got block 29449462 at 2019-01-14T13:31:33 -- 24 txs, 1 posts, 1 edits, 2 payouts, 5 votes, 1 counts, 8 accts, 0 follows -- 79ms
Jan 14 13:31:44 INFO:hive.steem.block.schedule:block 29449465 not available. head:29449465 drift:2.877000s
Jan 14 13:31:44 INFO:hive.indexer.sync:[LIVE] Got block 29449463 at 2019-01-14T13:31:36 -- 20 txs, 2 posts, 0 edits, 2 payouts, 6 votes, 1 counts, 8 accts, 2 follows -- 95ms
Jan 14 13:31:47 INFO:hive.steem.block.schedule:block 29449466 not available. head:29449466 drift:2.976000s
Jan 14 13:31:47 INFO:hive.indexer.sync:[LIVE] Got block 29449464 at 2019-01-14T13:31:39 -- 22 txs, 1 posts, 1 edits, 6 payouts, 8 votes, 0 counts, 8 accts, 0 follows -- 98ms
Jan 14 13:31:50 INFO:hive.indexer.sync:[LIVE] Got block 29449465 at 2019-01-14T13:31:42 -- 29 txs, 1 posts, 0 edits, 7 payouts, 9 votes, 0 counts, 8 accts, 2 follows -- 104ms
Jan 14 13:31:53 INFO:hive.indexer.sync:[LIVE] Got block 29449466 at 2019-01-14T13:31:45 -- 30 txs, 3 posts, 0 edits, 2 payouts, 10 votes, 3 counts, 8 accts, 0 follows -- 91ms
Jan 14 13:31:56 INFO:hive.indexer.sync:[LIVE] Got block 29449467 at 2019-01-14T13:31:48 -- 30 txs, 2 posts, 0 edits, 0 payouts, 13 votes, 2 counts, 8 accts, 0 follows -- 178ms
Jan 14 13:31:59 INFO:hive.indexer.sync:[LIVE] Got block 29449468 at 2019-01-14T13:31:51 -- 12 txs, 1 posts, 0 edits, 7 payouts, 6 votes, 1 counts, 8 accts, 2 follows -- 124ms
Jan 14 13:32:02 INFO:hive.indexer.sync:[LIVE] Got block 29449469 at 2019-01-14T13:31:54 -- 25 txs, 2 posts, 0 edits, 1 payouts, 9 votes, 2 counts, 8 accts, 0 follows -- 88ms
Jan 14 13:32:05 INFO:hive.indexer.sync:[LIVE] Got block 29449470 at 2019-01-14T13:31:57 -- 25 txs, 2 posts, 0 edits, 2 payouts, 12 votes, 2 counts, 8 accts, 0 follows -- 159ms
Logs from a different node which did cache the post correctly:
Jan 14 13:31:33 INFO:hive.indexer.sync:[LIVE] Got block 29449460 at 2019-01-14T13:31:27 -- 14 txs, 3 posts, 1 edits, 5 payouts, 5 votes, 2 counts, 9 accts, 2 follows -- 152ms
Jan 14 13:31:36 INFO:hive.indexer.sync:[LIVE] Got block 29449461 at 2019-01-14T13:31:30 -- 23 txs, 0 posts, 0 edits, 4 payouts, 8 votes, 1 counts, 9 accts, 0 follows -- 83ms
Jan 14 13:31:39 INFO:hive.indexer.sync:[LIVE] Got block 29449462 at 2019-01-14T13:31:33 -- 24 txs, 1 posts, 1 edits, 2 payouts, 5 votes, 1 counts, 9 accts, 0 follows -- 81ms
Jan 14 13:31:42 INFO:hive.indexer.sync:[LIVE] Got block 29449463 at 2019-01-14T13:31:36 -- 20 txs, 2 posts, 0 edits, 2 payouts, 6 votes, 1 counts, 8 accts, 2 follows -- 99ms
Jan 14 13:31:45 INFO:hive.indexer.sync:[LIVE] Got block 29449464 at 2019-01-14T13:31:39 -- 22 txs, 1 posts, 1 edits, 6 payouts, 8 votes, 0 counts, 8 accts, 0 follows -- 99ms
Jan 14 13:31:48 INFO:hive.indexer.sync:[LIVE] Got block 29449465 at 2019-01-14T13:31:42 -- 29 txs, 1 posts, 0 edits, 1 payouts, 9 votes, 0 counts, 8 accts, 2 follows -- 83ms
Jan 14 13:31:51 INFO:hive.indexer.sync:[LIVE] Got block 29449466 at 2019-01-14T13:31:45 -- 30 txs, 3 posts, 0 edits, 2 payouts, 10 votes, 3 counts, 8 accts, 0 follows -- 108ms
Jan 14 13:31:54 INFO:hive.indexer.sync:[LIVE] Got block 29449467 at 2019-01-14T13:31:48 -- 30 txs, 2 posts, 0 edits, 0 payouts, 13 votes, 2 counts, 8 accts, 0 follows -- 128ms
Jan 14 13:31:57 INFO:hive.indexer.sync:[LIVE] Got block 29449468 at 2019-01-14T13:31:51 -- 12 txs, 1 posts, 0 edits, 7 payouts, 6 votes, 1 counts, 7 accts, 2 follows -- 115ms
Jan 14 13:32:00 INFO:hive.indexer.sync:[LIVE] Got block 29449469 at 2019-01-14T13:31:54 -- 25 txs, 2 posts, 0 edits, 1 payouts, 9 votes, 2 counts, 8 accts, 0 follows -- 79ms
"block not available" messages should not be relevant to this issue because they are an artifact of the follower's block queue (pre-processing).