Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

missing cache entry #173

Open
roadscape opened this issue Jan 17, 2019 · 6 comments
Open

missing cache entry #173

roadscape opened this issue Jan 17, 2019 · 6 comments
Labels
bug

Comments

@roadscape
Copy link
Contributor

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).
@roadscape roadscape added the bug label Jan 17, 2019
@emre
Copy link

emre commented Jan 18, 2019

For the reference, my node has that example missing entry.

hive=# select author from hive_posts_cache where permlink = 'survey-blockchain-developer-salaries-have-increased-over-the-past-six-months-via-the-block' and author = 'jeffjagoe';
  author
-----------
 jeffjagoe
(1 row)

This was referenced Jan 25, 2019
Open
Closed
Merged
@inertia186
Copy link

I just observed this situation today while looking at:

https://steemit.com/health/@orgoniteog/bruce-lee-workout-includes-dragon-flag

My hivemind node has a hive_posts record for this, but not hive_posts_cache. So it's something I'm keen to have addressed because materially affects the distribution of my STINGY token.

@roadscape
Copy link
Contributor Author

@inertia186 could you try running the synctune branch? It has stricter enforcement of cached_post gaps.

roadscape added a commit that referenced this issue Aug 6, 2019
@roadscape
monitor post not available condition #173
76e6b87
@roadscape roadscape mentioned this issue Aug 6, 2019
Merged
@roadscape
Copy link
Contributor Author 


hivemindsync Aug 13 03:26:58[2961]: INFO:hive.indexer.sync:[LIVE] Got block 35505415 at 2019-08-13T03:26:51 --  18 txs,  0 posts,  0 edits,  4 payouts,  7 votes,  0 counts,  6 accts,  0 follows --  594ms
hivemindsync Aug 13 03:27:00[2961]: INFO:hive.indexer.sync:[LIVE] Got block 35505416 at 2019-08-13T03:26:54 --  26 txs,  0 posts,  0 edits,  4 payouts, 11 votes,  0 counts,  7 accts,  0 follows --   85ms
hivemindsync Aug 13 03:27:03[2961]: INFO:hive.indexer.sync:[LIVE] Got block 35505417 at 2019-08-13T03:26:57 --  30 txs,  1 posts,  0 edits,  2 payouts, 10 votes,  1 counts,  7 accts,  0 follows --   97ms
hivemindsync Aug 13 03:27:06[2961]: INFO:hive.indexer.sync:[LIVE] Got block 35505418 at 2019-08-13T03:27:00 --  22 txs,  0 posts,  0 edits,  2 payouts,  8 votes,  0 counts,  7 accts,  0 follows --   66ms
hivemindsync Aug 13 03:27:09[2961]: INFO:hive.indexer.sync:[LIVE] Got block 35505419 at 2019-08-13T03:27:03 --  28 txs,  0 posts,  0 edits,  5 payouts, 10 votes,  0 counts,  6 accts,  0 follows --   54ms
hivemindsync Aug 13 03:27:12[2961]: INFO:hive.indexer.sync:[LIVE] Got block 35505420 at 2019-08-13T03:27:06 --  34 txs,  0 posts,  0 edits,  4 payouts, 12 votes,  0 counts,  7 accts,  0 follows --  105ms
hivemindsync Aug 13 03:27:15[2961]: INFO:hive.indexer.sync:[LIVE] Got block 35505421 at 2019-08-13T03:27:09 --  21 txs,  0 posts,  0 edits,  2 payouts, 10 votes,  0 counts,  7 accts,  0 follows --   85ms
hivemindsync Aug 13 03:27:18[2961]: INFO:hive.indexer.sync:[LIVE] Got block 35505422 at 2019-08-13T03:27:12 --  29 txs,  0 posts,  0 edits,  3 payouts,  8 votes,  0 counts,  7 accts,  0 follows --   87ms
hivemindsync Aug 13 03:27:21[2961]: INFO:hive.indexer.sync:[LIVE] Got block 35505423 at 2019-08-13T03:27:15 --  56 txs,  0 posts,  0 edits,  2 payouts, 13 votes,  0 counts,  7 accts,  0 follows --   72ms
hivemindsync Aug 13 03:27:24[2961]: INFO:hive.indexer.sync:[LIVE] Got block 35505424 at 2019-08-13T03:27:18 --  49 txs,  0 posts,  0 edits,  2 payouts, 13 votes,  0 counts,  7 accts,  0 follows --  129ms
hivemindsync Aug 13 03:27:37[2961]: ERROR:hive.steem.http_client:get_content[10] failed in 9.7s. try 1. {'jussi-id': None, 'secs': 9.749, 'try': 1} - RPCError("error[-32003]: `Unable to acquire database lock`  in condenser_api.get_content([['fotostef', 'ntopaz--fotostef--1268423421--ntopaz-bwphotocontest-photocircle-photofeed-travel--2019-02-08-01-09-46--artwork--none'], (9 more)])",)
hivemindsync Aug 13 03:27:46[2961]: ERROR:hive.steem.http_client:get_content[10] failed in 9.1s. try 2. {'jussi-id': None, 'secs': 9.094, 'try': 2} - RPCError("error[-32003]: `Unable to acquire database lock`  in condenser_api.get_content([['fotostef', 'ntopaz--fotostef--1268423421--ntopaz-bwphotocontest-photocircle-photofeed-travel--2019-02-08-01-09-46--artwork--none'], (9 more)])",)
hivemindsync Aug 13 03:27:46[2961]: WARNING:hive.steem.http_client:get_content[10] took 3 tries {'jussi-id': None, 'secs': 0.029, 'try': 3}
hivemindsync Aug 13 03:27:46[2961]: WARNING:hive.utils.stats:[STEEM][19176ms] get_content[10] -- 477.5x par (1910/4)
hivemindsync Aug 13 03:27:46[2961]: INFO:hive.indexer.sync:[LIVE] Got block 35505425 at 2019-08-13T03:27:21 --  22 txs,  1 posts,  0 edits,  2 payouts,  6 votes,  1 counts,  6 accts,  0 follows -- 19211ms SLOW
hivemindsync Aug 13 03:27:46[2961]: WARNING:hive.steem.block.schedule:5 blocks behind
hivemindsync Aug 13 03:27:46[2961]: INFO:hive.indexer.sync:[LIVE] Got block 35505426 at 2019-08-13T03:27:24 --  60 txs,  1 posts,  0 edits,  5 payouts, 18 votes,  1 counts,  7 accts,  0 follows --  176ms
hivemindsync Aug 13 03:27:47[2961]: INFO:hive.indexer.sync:[LIVE] Got block 35505427 at 2019-08-13T03:27:27 --  54 txs,  1 posts,  0 edits,  4 payouts, 13 votes,  2 counts,  7 accts,  0 follows --  102ms
hivemindsync Aug 13 03:27:47[2961]: INFO:hive.steem.block.schedule:block 35505430 not available. head:35505433 drift:2.349000s
hivemindsync Aug 13 03:27:47[2961]: INFO:hive.steem.block.schedule:block 35505430 not available. head:35505433 drift:2.449000s
hivemindsync Aug 13 03:27:48[2961]: INFO:hive.steem.block.schedule:block 35505430 not available. head:35505433 drift:2.549000s
hivemindsync Aug 13 03:27:48[2961]: INFO:hive.steem.block.schedule:block 35505430 not available. head:35505433 drift:2.649000s
hivemindsync Aug 13 03:27:49[2961]: WARNING:hive.steem.block.schedule:4 blocks behind
hivemindsync Aug 13 03:27:49[2961]: INFO:hive.steem.block.schedule:block 35505430 not available. head:35505434 drift:2.749000s
hivemindsync Aug 13 03:27:49[2961]: INFO:hive.steem.block.schedule:block 35505430 not available. head:35505434 drift:2.849000s
hivemindsync Aug 13 03:27:50[2961]: INFO:hive.indexer.sync:[LIVE] Got block 35505428 at 2019-08-13T03:27:30 --  44 txs,  0 posts,  0 edits,  5 payouts,  5 votes,  0 counts,  7 accts,  0 follows --   90ms
hivemindsync Aug 13 03:27:50[2961]: INFO:hive.steem.block.schedule:block 35505431 not available. head:35505434 drift:2.948000s
hivemindsync Aug 13 03:27:50[2961]: INFO:hive.indexer.sync:[LIVE] Got block 35505429 at 2019-08-13T03:27:33 --  22 txs,  1 posts,  0 edits,  3 payouts,  4 votes,  1 counts,  6 accts,  0 follows --   45ms
hivemindsync Aug 13 03:27:50[2961]: INFO:hive.indexer.sync:[LIVE] Got block 35505430 at 2019-08-13T03:27:36 --  23 txs,  1 posts,  0 edits,  2 payouts,  9 votes,  1 counts,  6 accts,  0 follows --   65ms
hivemindsync Aug 13 03:27:50[2961]: INFO:hive.indexer.sync:[LIVE] Got block 35505431 at 2019-08-13T03:27:39 --   7 txs,  1 posts,  0 edits,  3 payouts,  3 votes,  1 counts,  6 accts,  0 follows --   38ms
hivemindsync Aug 13 03:27:50[2961]: WARNING:hive.indexer.cached_post:couldnt load post for insert: (78998781, 'organduo', 'organduo-re-contrabourdon-contrabourdon-re-organduo-organduo-re-laputis-actifit-laputis-20190813t032740475z', False)
hivemindsync Aug 13 03:27:50[2961]: INFO:hive.indexer.sync:[LIVE] Got block 35505432 at 2019-08-13T03:27:42 --  11 txs,  1 posts,  0 edits,  3 payouts,  5 votes,  2 counts,  6 accts,  0 follows --   44ms
hivemindsync Aug 13 03:27:52[2961]: INFO:hive.indexer.sync:[LIVE] Got block 35505433 at 2019-08-13T03:27:45 --  21 txs,  1 posts,  0 edits,  3 payouts, 12 votes,  3 counts,  6 accts,  0 follows --   99ms
hivemindsync Aug 13 03:27:55[2961]: INFO:hive.indexer.sync:[LIVE] Got block 35505434 at 2019-08-13T03:27:48 --  25 txs,  0 posts,  0 edits,  4 payouts,  8 votes,  1 counts,  6 accts,  0 follows --   93ms
hivemindsync Aug 13 03:27:59[2961]: ERROR:hive.steem.http_client:get_block[1] failed in 1.0s. try 1. {'jussi-id': None, 'secs': 1.003, 'try': 1} - RPCError("error[-32003]: `Unable to acquire database lock`  in block_api.get_block({'block_num': 35505437})",)
hivemindsync Aug 13 03:27:59[2961]: WARNING:hive.utils.stats:[STEEM][1105ms] get_block[1] -- 20.6x par (1030/50)
hivemindsync Aug 13 03:27:59[2961]: INFO:hive.steem.block.schedule:block 35505437 not available. head:35505437 drift:3.000000s
hivemindsync Aug 13 03:28:00[2961]: ERROR:hive.steem.http_client:get_block[1] failed in 1.0s. try 1. {'jussi-id': None, 'secs': 1.003, 'try': 1} - RPCError("error[-32003]: `Unable to acquire database lock`  in block_api.get_block({'block_num': 35505437})",)
hivemindsync Aug 13 03:28:00[2961]: WARNING:hive.utils.stats:[STEEM][1105ms] get_block[1] -- 20.6x par (1030/50)
hivemindsync Aug 13 03:28:00[2961]: INFO:hive.steem.block.schedule:block 35505437 not available. head:35505437 drift:3.000000s
hivemindsync Aug 13 03:28:01[2961]: WARNING:hive.steem.block.schedule:1 blocks behind
hivemindsync Aug 13 03:28:02[2961]: WARNING:hive.utils.stats:[STEEM][1026ms] get_block[1] -- 19.0x par (951/50)
hivemindsync Aug 13 03:28:02[2961]: INFO:hive.steem.block.schedule:block 35505437 not available. head:35505438 drift:3.000000s
hivemindsync Aug 13 03:28:03[2961]: WARNING:hive.indexer.cached_post:couldnt load post for insert: (78998783, 'urbangladiator', 're-evlo82-turok-for-nintendo-switch-turok-on-physical-cartridge-for-the-nintendo-switch-20190813t032748671z', False)
hivemindsync Aug 13 03:28:03[2961]: WARNING:hive.indexer.cached_post:couldnt load post for insert: (78998784, 'mosqueteros', 'pw5oa2', False)
hivemindsync Aug 13 03:28:03[2961]: INFO:hive.indexer.sync:[LIVE] Got block 35505435 at 2019-08-13T03:27:51 --  25 txs,  2 posts,  0 edits,  5 payouts, 10 votes,  1 counts,  7 accts,  0 follows --  128ms
hivemindsync Aug 13 03:28:03[2961]: WARNING:hive.indexer.cached_post:couldnt load post for insert: (78998785, 'amsoildealer', 'z9hd6rjvx3a', False)
hivemindsync Aug 13 03:28:03[2961]: WARNING:hive.indexer.cached_post:couldnt load post for insert: (78998786, 'pedrocanella', 're-shoemanchu-44-shoemanchu-is-proud-to-present-another-giveaway-of-5-shares-of-steembasicincome-20190813t032749349z', False)
hivemindsync Aug 13 03:28:03[2961]: WARNING:hive.indexer.cached_post:couldnt load post for insert: (78998787, 'laurelkat', 'amor-a-distancia-mi-presentacion-distance-love-my-presentation', False)
hivemindsync Aug 13 03:28:03[2961]: INFO:hive.indexer.sync:[LIVE] Got block 35505436 at 2019-08-13T03:27:54 --  22 txs,  3 posts,  0 edits,  6 payouts, 10 votes,  1 counts,  6 accts,  0 follows --   94ms
hivemindsync Aug 13 03:28:04[2961]: INFO:hive.indexer.sync:[LIVE] Got block 35505437 at 2019-08-13T03:27:57 --  46 txs,  0 posts,  0 edits,  6 payouts, 12 votes,  0 counts,  7 accts,  0 follows --  127ms
hivemindsync Aug 13 03:28:07[2961]: INFO:hive.indexer.sync:[LIVE] Got block 35505438 at 2019-08-13T03:28:00 --  11 txs,  2 posts,  0 edits,  7 payouts,  6 votes,  1 counts,  6 accts,  0 follows --   83ms
hivemindsync Aug 13 03:28:10[2961]: INFO:hive.indexer.sync:[LIVE] Got block 35505439 at 2019-08-13T03:28:03 --  11 txs,  0 posts,  0 edits,  2 payouts,  5 votes,  0 counts,  6 accts,  0 follows --   49ms
hivemindsync Aug 13 03:28:13[2961]: INFO:hive.indexer.sync:[LIVE] Got block 35505440 at 2019-08-13T03:28:06 --  20 txs,  1 posts,  0 edits,  3 payouts,  8 votes,  1 counts,  6 accts,  0 follows --   84ms
hivemindsync Aug 13 03:28:17[2961]: ERROR:hive.steem.http_client:get_accounts[1] failed in 1.0s. try 1. {'jussi-id': None, 'secs': 1.005, 'try': 1} - RPCError("error[-32003]: `Unable to acquire database lock`  in condenser_api.get_accounts([('wdev', 'cryptojiang', 'victoralfonzodm', 'bonzopoe', 'sugandhaseth', 'otom')])",)
hivemind     Aug 13 03:28:17[2850]: WARNING:hive.server.condenser_api.objects:get_posts do not exist in cache: {78998781} 
hivemind     Aug 13 03:28:17[2850]: ERROR:hive.server.condenser_api.objects:missing post -- force insert {'id': 78998781, 'author': 'organduo', 'permlink': 'organduo-re-contrabourdon-contrabourdon-re-organduo-organduo-re-laputis-actifit-laputis-20190813t032740475z', 'depth': 3, 'created_at': datetime.datetime(2019, 8, 13, 3, 27, 42), 'is_deleted': False}
hivemindsync Aug 13 03:28:18[2961]: ERROR:hive.steem.http_client:get_accounts[1] failed in 1.0s. try 2. {'jussi-id': None, 'secs': 1.004, 'try': 2} - RPCError("error[-32003]: `Unable to acquire database lock`  in condenser_api.get_accounts([('wdev', 'cryptojiang', 'victoralfonzodm', 'bonzopoe', 'sugandhaseth', 'otom')])",)
hivemindsync Aug 13 03:28:18[2961]: WARNING:hive.steem.http_client:get_accounts[1] took 3 tries {'jussi-id': None, 'secs': 0.005, 'try': 3}
hivemindsync Aug 13 03:28:18[2961]: WARNING:hive.utils.stats:[STEEM][2314ms] get_accounts[6] -- 124.3x par (373/3)
hivemindsync Aug 13 03:28:18[2961]: INFO:hive.indexer.sync:[LIVE] Got block 35505441 at 2019-08-13T03:28:09 --  17 txs,  1 posts,  1 edits,  3 payouts,  4 votes,  0 counts,  6 accts,  0 follows -- 2363ms SLOW
hivemindsync Aug 13 03:28:20[2961]: ERROR:hive.steem.http_client:get_block[1] failed in 1.0s. try 1. {'jussi-id': None, 'secs': 1.005, 'try': 1} - RPCError("error[-32003]: `Unable to acquire database lock`  in block_api.get_block({'block_num': 35505444})",)
hivemindsync Aug 13 03:28:21[2961]: ERROR:hive.steem.http_client:get_block[1] failed in 1.0s. try 2. {'jussi-id': None, 'secs': 1.004, 'try': 2} - RPCError("error[-32003]: `Unable to acquire database lock`  in block_api.get_block({'block_num': 35505444})",)
hivemindsync Aug 13 03:28:21[2961]: WARNING:hive.steem.http_client:get_block[1] took 3 tries {'jussi-id': None, 'secs': 0.003, 'try': 3}
hivemindsync Aug 13 03:28:21[2961]: WARNING:hive.utils.stats:[STEEM][2312ms] get_block[1] -- 44.7x par (2237/50)
hivemindsync Aug 13 03:28:26[2961]: ERROR:hive.steem.http_client:get_content[9] failed in 4.4s. try 1. {'jussi-id': None, 'secs': 4.417, 'try': 1} - RPCError("error[-32003]: `Unable to acquire database lock`  in condenser_api.get_content([['fotostef', 'ntopaz--fotostef--1268423421--ntopaz-bwphotocontest-photocircle-photofeed-travel--2019-02-08-01-09-46--artwork--none'], (8 more)])",)
hivemindsync Aug 13 03:28:26[2961]: WARNING:hive.utils.stats:[STEEM][4571ms] get_content[9] -- 124.8x par (499/4)
hivemindsync Aug 13 03:28:26[2961]: INFO:hive.indexer.sync:[LIVE] Got block 35505442 at 2019-08-13T03:28:12 --  17 txs,  1 posts,  0 edits,  2 payouts,  5 votes,  1 counts,  5 accts,  0 follows -- 4607ms SLOW
hivemindsync Aug 13 03:28:26[2961]: WARNING:hive.steem.block.schedule:1 blocks behind
hivemindsync Aug 13 03:28:26[2961]: INFO:hive.indexer.sync:[LIVE] Got block 35505443 at 2019-08-13T03:28:15 --  27 txs,  0 posts,  0 edits,  2 payouts, 14 votes,  1 counts,  6 accts,  0 follows --   73ms
hivemindsync Aug 13 03:28:26[2961]: INFO:hive.steem.block.schedule:block 35505446 not available. head:35505446 drift:3.000000s
hivemindsync Aug 13 03:28:26[2961]: INFO:hive.steem.block.schedule:block 35505446 not available. head:35505446 drift:3.000000s
hivemindsync Aug 13 03:28:27[2961]: INFO:hive.indexer.sync:[LIVE] Got block 35505444 at 2019-08-13T03:28:18 --  16 txs,  1 posts,  0 edits,  2 payouts,  5 votes,  1 counts,  6 accts,  0 follows --  111ms
hivemindsync Aug 13 03:28:28[2961]: WARNING:hive.utils.stats:[STEEM][221ms] get_block[1] -- 2.9x par (146/50)
hivemindsync Aug 13 03:28:28[2961]: INFO:hive.indexer.sync:[LIVE] Got block 35505445 at 2019-08-13T03:28:21 --  11 txs,  1 posts,  0 edits,  2 payouts,  6 votes,  0 counts,  6 accts,  0 follows --   58ms
hivemindsync Aug 13 03:28:31[2961]: INFO:hive.indexer.sync:[LIVE] Got block 35505446 at 2019-08-13T03:28:24 --  19 txs,  0 posts,  0 edits,  5 payouts,  7 votes,  0 counts,  6 accts,  0 follows --   66ms
hivemindsync Aug 13 03:28:34[2961]: INFO:hive.steem.block.schedule:block 35505449 not available. head:35505449 drift:3.000000s
hivemindsync Aug 13 03:28:34[2961]: INFO:hive.steem.block.schedule:block 35505449 not available. head:35505449 drift:3.000000s
hivemindsync Aug 13 03:28:35[2961]: INFO:hive.steem.block.schedule:block 35505449 not available. head:35505449 drift:3.000000s
hivemindsync Aug 13 03:28:35[2961]: INFO:hive.indexer.sync:[LIVE] Got block 35505447 at 2019-08-13T03:28:27 --  23 txs,  2 posts,  0 edits,  3 payouts, 12 votes,  1 counts,  6 accts,  2 follows --  106ms
hivemindsync Aug 13 03:28:37[2961]: INFO:hive.steem.block.schedule:block 35505450 not available. head:35505450 drift:3.000000s
hivemindsync Aug 13 03:28:37[2961]: INFO:hive.indexer.sync:[LIVE] Got block 35505448 at 2019-08-13T03:28:30 --  21 txs,  0 posts,  0 edits,  2 payouts, 13 votes,  0 counts,  7 accts,  0 follows --   76ms
hivemind     Aug 13 03:28:38[2850]: WARNING:hive.server.condenser_api.objects:get_posts do not exist in cache: {78998783}
hivemind     Aug 13 03:28:38[2850]: ERROR:hive.server.condenser_api.objects:missing post -- force insert {'id': 78998783, 'author': 'urbangladiator', 'permlink': 're-evlo82-turok-for-nintendo-switch-turok-on-physical-cartridge-for-the-nintendo-switch-20190813t032748671z', 'depth': 1, 'created_at': datetime.datetime(2019, 8, 13, 3, 27, 51), 'is_deleted': False}
hivemind     Aug 13 03:28:39[2850]: WARNING:hive.server.condenser_api.objects:get_posts do not exist in cache: {78998784}
hivemind     Aug 13 03:28:39[2850]: ERROR:hive.server.condenser_api.objects:missing post -- force insert {'id': 78998784, 'author': 'mosqueteros', 'permlink': 'pw5oa2', 'depth': 1, 'created_at': datetime.datetime(2019, 8, 13, 3, 27, 51), 'is_deleted': False}
hivemindsync Aug 13 03:28:40[2961]: INFO:hive.indexer.sync:[LIVE] Got block 35505449 at 2019-08-13T03:28:33 --  17 txs,  1 posts,  0 edits,  9 payouts,  6 votes,  1 counts,  6 accts,  0 follows --   92ms
hivemind     Aug 13 03:28:40[2835]: WARNING:hive.server.condenser_api.objects:get_posts do not exist in cache: {78998787}
hivemind     Aug 13 03:28:40[2835]: ERROR:hive.server.condenser_api.objects:missing post -- force insert {'id': 78998787, 'author': 'laurelkat', 'permlink': 'amor-a-distancia-mi-presentacion-distance-love-my-presentation', 'depth': 0, 'created_at': datetime.datetime(2019, 8, 13, 3, 27, 54), 'is_deleted': False}
hivemind     Aug 13 03:28:40[2850]: WARNING:hive.server.condenser_api.objects:get_posts do not exist in cache: {78998785}
hivemind     Aug 13 03:28:40[2850]: ERROR:hive.server.condenser_api.objects:missing post -- force insert {'id': 78998785, 'author': 'amsoildealer', 'permlink': 'z9hd6rjvx3a', 'depth': 0, 'created_at': datetime.datetime(2019, 8, 13, 3, 27, 54), 'is_deleted': False}
hivemind     Aug 13 03:28:40[2850]: WARNING:hive.server.condenser_api.objects:get_posts do not exist in cache: {78998786}
hivemind     Aug 13 03:28:40[2850]: ERROR:hive.server.condenser_api.objects:missing post -- force insert {'id': 78998786, 'author': 'pedrocanella', 'permlink': 're-shoemanchu-44-shoemanchu-is-proud-to-present-another-giveaway-of-5-shares-of-steembasicincome-20190813t032749349z', 'depth': 1, 'created_at': datetime.datetime(2019, 8, 13, 3, 27, 54), 'is_deleted': False}
hivemindsync Aug 13 03:28:43[2961]: INFO:hive.indexer.sync:[LIVE] Got block 35505450 at 2019-08-13T03:28:36 --  33 txs,  2 posts,  0 edits,  4 payouts, 12 votes,  2 counts,  7 accts,  0 follows --   76ms
hivemindsync Aug 13 03:28:46[2961]: INFO:hive.indexer.sync:[LIVE] Got block 35505451 at 2019-08-13T03:28:39 --  17 txs,  2 posts,  0 edits,  3 payouts,  7 votes,  2 counts,  7 accts,  0 follows --   63ms
hivemindsync Aug 13 03:28:49[2961]: WARNING:hive.indexer.cached_post:couldnt load post for insert: (78998802, 'anasuleidy', '2s16kq-hoy-afirmo-43', False)
hivemindsync Aug 13 03:28:49[2961]: WARNING:hive.indexer.cached_post:couldnt load post for insert: (78998803, 'jlufer', 'pw5obq', False)
hivemindsync Aug 13 03:28:49[2961]: INFO:hive.indexer.sync:[LIVE] Got block 35505452 at 2019-08-13T03:28:42 --  42 txs,  2 posts,  0 edits,  4 payouts, 10 votes,  1 counts,  7 accts,  0 follows --  127ms
hivemindsync Aug 13 03:28:52[2961]: INFO:hive.indexer.sync:[LIVE] Got block 35505453 at 2019-08-13T03:28:45 --  28 txs,  2 posts,  0 edits,  6 payouts,  6 votes,  3 counts,  7 accts,  0 follows --   88ms
hivemindsync Aug 13 03:28:55[2961]: INFO:hive.indexer.sync:[LIVE] Got block 35505454 at 2019-08-13T03:28:48 --  30 txs,  3 posts,  0 edits,  5 payouts, 11 votes,  2 counts,  8 accts,  0 follows --   99ms
hivemindsync Aug 13 03:28:58[2961]: INFO:hive.indexer.sync:[LIVE] Got block 35505455 at 2019-08-13T03:28:51 --  22 txs,  3 posts,  0 edits,  2 payouts,  9 votes,  4 counts,  8 accts,  0 follows --   99ms
hivemindsync Aug 13 03:29:01[2961]: INFO:hive.indexer.sync:[LIVE] Got block 35505456 at 2019-08-13T03:28:54 --  25 txs,  0 posts,  0 edits,  5 payouts,  9 votes,  1 counts,  8 accts,  0 follows --   74ms
hivemindsync Aug 13 03:29:04[2961]: WARNING:hive.utils.stats:[STEEM][709ms] get_content[15] -- 10.5x par (42/4)
hivemindsync Aug 13 03:29:05[2961]: INFO:hive.indexer.sync:[LIVE] Got block 35505457 at 2019-08-13T03:28:57 --  27 txs,  1 posts,  1 edits,  3 payouts,  9 votes,  1 counts,  8 accts,  0 follows --  755ms
hivemindsync Aug 13 03:29:07[2961]: INFO:hive.indexer.sync:[LIVE] Got block 35505458 at 2019-08-13T03:29:00 --  16 txs,  0 posts,  0 edits,  2 payouts,  5 votes,  0 counts,  7 accts,  0 follows --   34ms
hivemind     Aug 13 03:29:09[2850]: WARNING:hive.server.condenser_api.objects:get_posts do not exist in cache: {78998802}
hivemind     Aug 13 03:29:09[2850]: ERROR:hive.server.condenser_api.objects:missing post -- force insert {'id': 78998802, 'author': 'anasuleidy', 'permlink': '2s16kq-hoy-afirmo-43', 'depth': 0, 'created_at': datetime.datetime(2019, 8, 13, 3, 28, 42), 'is_deleted': False}
hivemind     Aug 13 03:29:09[2850]: WARNING:hive.server.condenser_api.objects:get_posts do not exist in cache: {78998803}
hivemind     Aug 13 03:29:09[2850]: ERROR:hive.server.condenser_api.objects:missing post -- force insert {'id': 78998803, 'author': 'jlufer', 'permlink': 'pw5obq', 'depth': 3, 'created_at': datetime.datetime(2019, 8, 13, 3, 28, 42), 'is_deleted': False}
hivemindsync Aug 13 03:29:10[2961]: INFO:hive.indexer.sync:[LIVE] Got block 35505459 at 2019-08-13T03:29:03 --  20 txs,  1 posts,  1 edits,  4 payouts,  6 votes,  0 counts,  7 accts,  0 follows --   83ms
hivemindsync Aug 13 03:29:13[2961]: INFO:hive.indexer.sync:[LIVE] Got block 35505460 at 2019-08-13T03:29:06 --  21 txs,  3 posts,  0 edits,  2 payouts,  7 votes,  3 counts,  7 accts,  0 follows --  110ms
hivemindsync Aug 13 03:29:13[2961]: WARNING:hive.utils.stats:[STEEM][129ms] get_dynamic_global_properties[1] -- 2.7x par (54/20)
hivemindsync Aug 13 03:29:16[2961]: INFO:hive.indexer.sync:[LIVE] Got block 35505461 at 2019-08-13T03:29:09 --  25 txs,  1 posts,  0 edits,  2 payouts,  8 votes,  2 counts,  7 accts,  2 follows --   77ms
hivemindsync Aug 13 03:29:19[2961]: INFO:hive.indexer.sync:[LIVE] Got block 35505462 at 2019-08-13T03:29:12 --  27 txs,  2 posts,  0 edits,  3 payouts,  9 votes,  3 counts,  7 accts,  2 follows --  104ms
hivemindsync Aug 13 03:29:22[2961]: INFO:hive.indexer.sync:[LIVE] Got block 35505463 at 2019-08-13T03:29:15 --  28 txs,  1 posts,  0 edits,  2 payouts, 14 votes,  0 counts,  7 accts,  0 follows --   92ms
hivemindsync Aug 13 03:29:25[2961]: INFO:hive.indexer.sync:[LIVE] Got block 35505464 at 2019-08-13T03:29:18 --  23 txs,  1 posts,  0 edits,  2 payouts, 10 votes,  1 counts,  7 accts,  2 follows --   83ms
hivemindsync Aug 13 03:29:28[2961]: INFO:hive.indexer.sync:[LIVE] Got block 35505465 at 2019-08-13T03:29:21 --  21 txs,  2 posts,  0 edits,  3 payouts,  7 votes,  2 counts,  6 accts,  0 follows --   55ms

@roadscape
Copy link
Contributor Author

It looks like in these cases, get_content failed to return a post which was just created. This caused the inserts to be skipped over and later picked up by the API node. It may be due to one of the nodes in the balancer falling behind temporarily.

We should throw failed inserts back into the queue to try again next round.

roadscape added a commit that referenced this issue Aug 13, 2019
@roadscape
sync - defer inserts when get_content fails, api - no force insert, t…
a33695b 
…une logging. #173
@roadscape roadscape mentioned this issue Aug 13, 2019
Merged
@roadscape
Copy link
Contributor Author

Fix was merged in #224 and 173-missing-cache-entries-audit contains a startup routine which corrects any missing entries.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@emre @inertia186 @roadscape