ElasticSearch with test-6.0.2

[sschiessl-bcp]

Bug Description
ES fails to sync with bitshares/bitshares-core:test-6.0.2 and

blockchain_plugins:
 - elasticsearch
 - es_objects
blockchain_args: >
    --replay
    --ignore-api-helper-indexes-warning
    --elasticsearch-start-es-after-block=51150525
    --es-objects-start-es-after-block=51150525
    --es-objects-keep-only-current=true
    --elasticsearch-operation-object=true
    --elasticsearch-operation-string=false
    --elasticsearch-index-prefix=testnet-
    --es-objects-index-prefix=testnet-objects-

The error is

1583954ms th_a       elasticsearch_plugin.cpp:338  add_elasticsearch    ] es.bulk_lines[i]: {"index":{"_index":"testnet-2021-11","_type":"data","_id":"2.9.166396376"}} 
1583954ms th_a       elasticsearch_plugin.cpp:338  add_elasticsearch    ] es.bulk_lines[i]: {"account_history":{"id":"2.9.166396376","account":"1.2.25983","operation_id":"1.11.84519114","sequence":3554082,"next":"2.9.166396374"},"operation_history":{"trx_in_block":4,"op_in_trx":4,"operation_result":"[0,{}]","virtual_op":0,"op":"","op_object":{"fee":{"amount":100,"asset_id":"1.3.0"},"from":"1.2.25983","to":"1.2.25661","extensions":[],"amount_":{"amount":1,"asset_id":"1.3.0"}}},"operation_type":0,"operation_id_num":84519114,"block_data":{"block_num":51517550,"block_time":"2021-11-08T18:19:18","trx_id":"5de88b52fbb630ae9cb3e45e0d78b1d62c0daf7d"}} 
1583954ms th_a       elasticsearch_plugin.cpp:193  update_account_histo ] Error adding data to Elastic Search: block num 51517626, account 1.2.25661, data {"id":"1.11.84521613","op":[0,{"fee":{"amount":100,"asset_id":"1.3.0"},"from":"1.2.25983","to":"1.2.25661","amount":{"amount":1,"asset_id":"1.3.0"},"extensions":[]}],"result":[0,{}],"block_num":51517626,"trx_in_block":4,"op_in_trx":3,"virtual_op":0}
1583969ms th_a       db_notify.cpp:572             notify_applied_block ] Caught plugin exception: 3100000 plugin_exception: plugin exception
Error populating ES database, we are going to keep trying.
    {}
    th_a  elasticsearch_plugin.cpp:543 operator()
1583970ms th_a       db_block.cpp:222              _push_block          ] Failed to push new block:
3100000 plugin_exception: plugin exception
Error populating ES database, we are going to keep trying.
    {}
    th_a  elasticsearch_plugin.cpp:543 operator()

    {"next_block.block_num()":51517626}
    th_a  db_block.cpp:669 _apply_block
1583971ms th_a       db_management.cpp:227         open                 ] 3100000 plugin_exception: plugin exception
Error populating ES database, we are going to keep trying.
    {}
    th_a  elasticsearch_plugin.cpp:543 operator()

    {"next_block.block_num()":51517626}
    th_a  db_block.cpp:669 _apply_block

    {"new_block":{"previous":"031218b9a0f9e9fed7b08d8950563ee13df9f9d9","timestamp":"2021-11-08T18:23:15","witness":"1.6.2","transaction_merkle_root":"a49bdb7d7e62b1f1aaa0d8ccf9007e46ad83119b","extensions":[],"witness_signature":"1f34cba655058b85632de7830d96a2ae0e6a9dea20301e64b10b5d54512388c54e71e45bb98c73739f168edc105f12419d4a5940ff6c2df872a1cb63e99fa37f9b","transactions":[{"ref_block_num":6317,"ref_block_prefix":3855047144,"expiration":"2021-11-08T18:23:40","operations":[[0,{"fee":{"amount":100,"asset_id":"1.3.0"},"from":"1.2.25957","to":"1.2.25661","amount":{"amount":1,"asset_id":"1.3.0"},"extensions":[]}]],"extensions":[],"signatures":["1f577d48c338eec736ea73b197b47dd77cd9695d5e0c92d42784202e027775701976192148b806c5457e308a2bbeabd8aacd4c93970a1674db5f4da6edada1f2e1"],"operation_results":[]},{"ref_block_num":6317,"ref_block_prefix":3855047144,"expiration":"2021-11-08T18:23:41","operations":[[0,{"fee":{"amount":100,"asset_id":"1.3.0"},"from":"1.2.25957","to":"1.2.25661","amount":{"amount":1,"asset_id":"1.3.0"},"extensions":[]}]],"extensions":[],"signatures":["204e9114cf31b6c329bef053c11d2305079ccd0fcb811216b0cf1dfc8c52a7b40f0a7a72dd6f063cdeeecf9cb021cc9ac0bb513bc6dc2bfd4c260114e8fd01f061"],"operation_results":[]},{"ref_block_num":6317,"ref_block_prefix":3855047144,"expiration":"2021-11-08T18:23:41","operations":[[0,{"fee":{"amount":100,"asset_id":"1.3.0"},"from":"1.2.25983","to":"1.2.25661","amount":{"amount":1,"asset_id":"1.3.0"},"extensions":[]}],[0,{"fee":{"amount":100,"asset_id":"1.3.0"},"from":"1.2.25983","to":"1.2.25661","amount":{"amount":1,"asset_id":"1.3.0"},"extensions":[]}],[0,{"fee":{"amount":100,"asset_id":"1.3.0"},"from":"1.2.25983","to":"1.2.25661","amount":{"amount":1,"asset_id":"1.3.0"},"extensions":[]}],[0,{"fee":{"amount":100,"asset_id":"1.3.0"},"from":"1.2.25983","to":"1.2.25661","amount":{"amount":1,"asset_id":"1.3.0"},"extensions":[]}],[0,{"fee":{"amount":100,"asset_id":"1.3.0"},"from":"1.2.25983","to":"1.2.25661","amount":{"amount":1,"asset_id":"1.3.0"},"extensions":[]}],[0,{"fee":{"amount":100,"asset_id":"1.3.0"},"from":"1.2.25983","to":"1.2.25661","amount":{"amount":1,"asset_id":"1.3.0"},"extensions":[]}],[0,{"fee":{"amount":100,"asset_id":"1.3.0"},"from":"1.2.25983","to":"1.2.25661","amount":{"amount":1,"asset_id":"1.3.0"},"extensions":[]}],[0,{"fee":{"amount":100,"asset_id":"1.3.0"},"from":"1.2.25983","to":"1.2.25661","amount":{"amount":1,"asset_id":"1.3.0"},"extensions":[]}],[0,{"fee":{"amount":100,"asset_id":"1.3.0"},"from":"1.2.25983","to":"1.2.25661","amount":{"amount":1,"asset_id":"1.3.0"},"extensions":[]}],[0,{"fee":{"amount":100,"asset_id":"1.3.0"},"from":"1.2.25983","to":"1.2.25661","amount":{"amount":1,"asset_id":"1.3.0"},"extensions":[]}],[0,{"fee":{"amount":100,"asset_id":"1.3.0"},"from":"1.2.25983","to":"1.2.25661","amount":{"amount":1,"asset_id":"1.3.0"},"extensions":[]}],[0,{"fee":{"amount":100,"asset_id":"1.3.0"},"from":"1.2.25983","to":"1.2.25661","amount":{"amount":1,"asset_id":"1.3.0"},"extensions":[]}]],"extensions":[],"signatures":["1f18d7bf9d91392e9de53de2d4da4e7e55b496bd41539deccb67dc4a2e9a11b2a23dfd406ac72bfdf0c5ca159d7bb026d66a79bb336a4d873183587bae54b89bd3"],"operation_results":[]},{"ref_block_num":6317,"ref_block_prefix":3855047144,"expiration":"2021-11-08T18:23:42","operations":[[0,{"fee":{"amount":100,"asset_id":"1.3.0"},"from":"1.2.25957","to":"1.2.25661","amount":{"amount":1,"asset_id":"1.3.0"},"extensions":[]}]],"extensions":[],"signatures":["1f667fd420f8f0986e73d27daf2e4946f30ba0f79acd502f8d9fc2d89eca429f1b5db90d1d3462744ca072ffebf44032e568b1dd73716a43c586305d9f482104d4"],"operation_results":[]},{"ref_block_num":6317,"ref_block_prefix":3855047144,"expiration":"2021-11-08T18:23:42","operations":[[0,{"fee":{"amount":100,"asset_id":"1.3.0"},"from":"1.2.25983","to":"1.2.25661","amount":{"amount":1,"asset_id":"1.3.0"},"extensions":[]}],[0,{"fee":{"amount":100,"asset_id":"1.3.0"},"from":"1.2.25983","to":"1.2.25661","amount":{"amount":1,"asset_id":"1.3.0"},"extensions":[]}],[0,{"fee":{"amount":100,"asset_id":"1.3.0"},"from":"1.2.25983","to":"1.2.25661","amount":{"amount":1,"asset_id":"1.3.0"},"extensions":[]}],[0,{"fee":{"amount":100,"asset_id":"1.3.0"},"from":"1.2.25983","to":"1.2.25661","amount":{"amount":1,"asset_id":"1.3.0"},"extensions":[]}],[0,{"fee":{"amount":100,"asset_id":"1.3.0"},"from":"1.2.25983","to":"1.2.25661","amount":{"amount":1,"asset_id":"1.3.0"},"extensions":[]}],[0,{"fee":{"amount":100,"asset_id":"1.3.0"},"from":"1.2.25983","to":"1.2.25661","amount":{"amount":1,"asset_id":"1.3.0"},"extensions":[]}],[0,{"fee":{"amount":100,"asset_id":"1.3.0"},"from":"1.2.25983","to":"1.2.25661","amount":{"amount":1,"asset_id":"1.3.0"},"extensions":[]}],[0,{"fee":{"amount":100,"asset_id":"1.3.0"},"from":"1.2.25983","to":"1.2.25661","amount":{"amount":1,"asset_id":"1.3.0"},"extensions":[]}],[0,{"fee":{"amount":100,"asset_id":"1.3.0"},"from":"1.2.25983","to":"1.2.25661","amount":{"amount":1,"asset_id":"1.3.0"},"extensions":[]}],[0,{"fee":{"amount":100,"asset_id":"1.3.0"},"from":"1.2.25983","to":"1.2.25661","amount":{"amount":1,"asset_id":"1.3.0"},"extensions":[]}],[0,{"fee":{"amount":100,"asset_id":"1.3.0"},"from":"1.2.25983","to":"1.2.25661","amount":{"amount":1,"asset_id":"1.3.0"},"extensions":[]}],[0,{"fee":{"amount":100,"asset_id":"1.3.0"},"from":"1.2.25983","to":"1.2.25661","amount":{"amount":1,"asset_id":"1.3.0"},"extensions":[]}]],"extensions":[],"signatures":["1f106d79e2d6923c52e7527487eec17b3534d4394dd351662ac8cf94cacbe15ba417f16c8e4f20db7de986e8e6c070fb2bce100c3e44de1ad5758e8803b7b86ed9"],"operation_results":[]},{"ref_block_num":6317,"ref_block_prefix":3855047144,"expiration":"2021-11-08T18:23:43","operations":[[0,{"fee":{"amount":100,"asset_id":"1.3.0"},"from":"1.2.25957","to":"1.2.25661","amount":{"amount":1,"asset_id":"1.3.0"},"extensions":[]}]],"extensions":[],"signatures":["1f72b1ce5f0638609896d396aa2de16814c56bf4333f801ea1329c2127b3f0ca715cdf49bbf259adadf94529b4212e0c1fda435f14de8f2f18c81c2f767548bcd1"],"operation_results":[]}]}}
    th_a  db_block.cpp:228 _push_block

    {"data_dir":"/var/lib/bitshares/blockchain"}
    th_a  db_management.cpp:163 reindex
1583971ms th_a       db_management.cpp:227         open                 ] data_dir: /var/lib/bitshares/blockchain 
1583981ms th_a       application.cpp:551           open_chain_database  ] Caught exception 3100000 plugin_exception: plugin exception
Error populating ES database, we are going to keep trying.

Impacts
Describe which portion(s) of BitShares Core may be impacted by this bug. Please tick at least one box.

• ES

Steps To Reproduce
Steps to reproduce the behavior (example outlined below):
Try syncing ES

Expected Behavior
Syncing works

CORE TEAM TASK LIST

• Evaluate / Prioritize Bug Report
• Refine User Stories / Requirements
• Define Test Cases
• Design / Develop Solution
• Perform QA/Testing
• Update Documentation

[sschiessl-bcp]

Mainnet feeder is running version 6 as well, so far no issue.

[abitmore]

@sschiessl-bcp there should be more log messages about the error before the lines you pasted here. Can you please check?

[sschiessl-bcp]

testnet-2021-11","_type":"data","_id":"2.9.166401363","_version":584,"result":"updated","_shards":{"total":2,"successful":1,"failed":0},"_seq_no":4786125333,"_primary_term":1,"status":200}},{"index":{"_index":"testnet-2021-11","_type":"data","_id":"2.9.166401364","_version":584,"result":"updated","_shards":{"total":2,"successful":1,"failed":0},"_seq_no":4786125334,"_primary_term":1,"status":200}},{"index":{"_index":"testnet-2021-11","_type":"data","_id":"2.9.166401365","_version":584,"result":"updated","_shards":{"total":2,"successful":1,"failed":0},"_seq_no":4786125335,"_primary_term":1,"status":200}},{"index":{"_index":"testnet-2021-11","_type":"data","_id":"2.9.166401366","_version":584,"result":"updated","_shards":{"total":2,"successful":1,"failed":0},"_seq_no":4786125336,"_primary_term":1,"status":200}},{"index":{"_index":"testnet-2021-11","_type":"data","_id":"2.9.166401367","_version":584,"result":"updated","_shards":{"total":2,"successful":1,"failed":0},"_seq_no":4786125337,"_primary_term":1,"status":200}},{"index":{"_index":"testnet-2021-11","_type":"data","_id":"2.9.166401368","_version":584,"result":"updated","_shards":{"total":2,"successful":1,"failed":0},"_seq_no":4786125338,"_primary_term":1,"status":200}},{"index":{"_index":"testnet-2021-11","_type":"data","_id":"2.9.166401369","_version":584,"result":"updated","_shards":{"total":2,"successful":1,"failed":0},"_seq_no":4786125339,"_primary_term":1,"status":200}},{"index":{"_index":"testnet-2021-11","_type":"data","_id":"2.9.166401370","_version":584,"result":"updated","_shards":{"total":2,"successful":1,"failed":0},"_seq_no":4786125340,"_primary_term":1,"status":200}},{"index":{"_index":"testnet-2021-11","_type":"data","_id":"2.9.166401371","_version":584,"result":"updated","_shards":{"total":2,"successful":1,"failed":0},"_seq_no":4786125341,"_primary_term":1,"status":200}}]}
802929ms th_a       elasticsearch_plugin.cpp:334  add_elasticsearch    ] Error sending 10000 lines of bulk data to Elastic Search, the first lines are:
802929ms th_a       elasticsearch_plugin.cpp:338  add_elasticsearch    ] es.bulk_lines[i]: {"index":{"_index":"testnet-2021-11","_type":"data","_id":"2.9.166396372"}} 
802929ms th_a       elasticsearch_plugin.cpp:338  add_elasticsearch    ] es.bulk_lines[i]: {"account_history":{"id":"2.9.166396372","account":"1.2.25983","operation_id":"1.11.84519112","sequence":3554080,"next":"2.9.166396370"},"operation_history":{"trx_in_block":4,"op_in_trx":2,"operation_result":"[0,{}]","virtual_op":0,"op":"","op_object":{"fee":{"amount":100,"asset_id":"1.3.0"},"from":"1.2.25983","to":"1.2.25661","extensions":[],"amount_":{"amount":1,"asset_id":"1.3.0"}}},"operation_type":0,"operation_id_num":84519112,"block_data":{"block_num":51517550,"block_time":"2021-11-08T18:19:18","trx_id":"5de88b52fbb630ae9cb3e45e0d78b1d62c0daf7d"}} 
802929ms th_a       elasticsearch_plugin.cpp:338  add_elasticsearch    ] es.bulk_lines[i]: {"index":{"_index":"testnet-2021-11","_type":"data","_id":"2.9.166396373"}} 
802929ms th_a       elasticsearch_plugin.cpp:338  add_elasticsearch    ] es.bulk_lines[i]: {"account_history":{"id":"2.9.166396373","account":"1.2.25661","operation_id":"1.11.84519113","sequence":40747492,"next":"2.9.166396371"},"operation_history":{"trx_in_block":4,"op_in_trx":3,"operation_result":"[0,{}]","virtual_op":0,"op":"","op_object":{"fee":{"amount":100,"asset_id":"1.3.0"},"from":"1.2.25983","to":"1.2.25661","extensions":[],"amount_":{"amount":1,"asset_id":"1.3.0"}}},"operation_type":0,"operation_id_num":84519113,"block_data":{"block_num":51517550,"block_time":"2021-11-08T18:19:18","trx_id":"5de88b52fbb630ae9cb3e45e0d78b1d62c0daf7d"}} 
802929ms th_a       elasticsearch_plugin.cpp:338  add_elasticsearch    ] es.bulk_lines[i]: {"index":{"_index":"testnet-2021-11","_type":"data","_id":"2.9.166396374"}} 
802929ms th_a       elasticsearch_plugin.cpp:338  add_elasticsearch    ] es.bulk_lines[i]: {"account_history":{"id":"2.9.166396374","account":"1.2.25983","operation_id":"1.11.84519113","sequence":3554081,"next":"2.9.166396372"},"operation_history":{"trx_in_block":4,"op_in_trx":3,"operation_result":"[0,{}]","virtual_op":0,"op":"","op_object":{"fee":{"amount":100,"asset_id":"1.3.0"},"from":"1.2.25983","to":"1.2.25661","extensions":[],"amount_":{"amount":1,"asset_id":"1.3.0"}}},"operation_type":0,"operation_id_num":84519113,"block_data":{"block_num":51517550,"block_time":"2021-11-08T18:19:18","trx_id":"5de88b52fbb630ae9cb3e45e0d78b1d62c0daf7d"}} 
802929ms th_a       elasticsearch_plugin.cpp:338  add_elasticsearch    ] es.bulk_lines[i]: {"index":{"_index":"testnet-2021-11","_type":"data","_id":"2.9.166396375"}} 
802929ms th_a       elasticsearch_plugin.cpp:338  add_elasticsearch    ] es.bulk_lines[i]: {"account_history":{"id":"2.9.166396375","account":"1.2.25661","operation_id":"1.11.84519114","sequence":40747493,"next":"2.9.166396373"},"operation_history":{"trx_in_block":4,"op_in_trx":4,"operation_result":"[0,{}]","virtual_op":0,"op":"","op_object":{"fee":{"amount":100,"asset_id":"1.3.0"},"from":"1.2.25983","to":"1.2.25661","extensions":[],"amount_":{"amount":1,"asset_id":"1.3.0"}}},"operation_type":0,"operation_id_num":84519114,"block_data":{"block_num":51517550,"block_time":"2021-11-08T18:19:18","trx_id":"5de88b52fbb630ae9cb3e45e0d78b1d62c0daf7d"}} 
802929ms th_a       elasticsearch_plugin.cpp:338  add_elasticsearch    ] es.bulk_lines[i]: {"index":{"_index":"testnet-2021-11","_type":"data","_id":"2.9.166396376"}} 
802929ms th_a       elasticsearch_plugin.cpp:338  add_elasticsearch    ] es.bulk_lines[i]: {"account_history":{"id":"2.9.166396376","account":"1.2.25983","operation_id":"1.11.84519114","sequence":3554082,"next":"2.9.166396374"},"operation_history":{"trx_in_block":4,"op_in_trx":4,"operation_result":"[0,{}]","virtual_op":0,"op":"","op_object":{"fee":{"amount":100,"asset_id":"1.3.0"},"from":"1.2.25983","to":"1.2.25661","extensions":[],"amount_":{"amount":1,"asset_id":"1.3.0"}}},"operation_type":0,"operation_id_num":84519114,"block_data":{"block_num":51517550,"block_time":"2021-11-08T18:19:18","trx_id":"5de88b52fbb630ae9cb3e45e0d78b1d62c0daf7d"}} 
802929ms th_a       elasticsearch_plugin.cpp:193  update_account_histo ] Error adding data to Elastic Search: block num 51517626, account 1.2.25661, data {"id":"1.11.84521613","op":[0,{"fee":{"amount":100,"asset_id":"1.3.0"},"from":"1.2.25983","to":"1.2.25661","amount":{"amount":1,"asset_id":"1.3.0"},"extensions":[]}],"result":[0,{}],"block_num":51517626,"trx_in_block":4,"op_in_trx":3,"virtual_op":0}
802940ms th_a       db_notify.cpp:572             notify_applied_block ] Caught plugin exception: 3100000 plugin_exception: plugin exception
Error populating ES database, we are going to keep trying.
    {}
    th_a  elasticsearch_plugin.cpp:543 operator()
802941ms th_a       db_block.cpp:222              _push_block          ] Failed to push new block:
3100000 plugin_exception: plugin exception
Error populating ES database, we are going to keep trying.
    {}
    th_a  elasticsearch_plugin.cpp:543 operator()

    {"next_block.block_num()":51517626}
    th_a  db_block.cpp:669 _apply_block
802942ms th_a       db_management.cpp:227         open                 ] 3100000 plugin_exception: plugin exception

[abitmore]

The log messages are still truncated. There may be an error among the 10000 lines of bulk data.
BTW I have synced a testnet ES node without trouble. But I didn't enable es_objects plugin. I re-enabled it and it's replaying.

[abitmore]

OK I caught that error on my node. Will look into it.

[abitmore]

Here is the error message:

{"index":{"_index":"btstesthis-2021-11","_type":"data","_id":"2.9.166398662","status":400,"error":{"type":"illegal_argument_exception","reason":"mapper [operation_history.op_object.acceptable_collateral] cannot be
changed from type [text] to [ObjectMapper]"}}}

[abitmore]

FWIW the error message was found in default.log.

[abitmore]

It was explained here: #1396 (comment), In ES,

... all values in the array must be of the same datatype ...

But the data to process now is like this

"acceptable_collateral":[["1.3.1515",{"base":{"amount":10000000,"asset_id":"1.3.0"},"quote":{"amount":4000000,"asset_id":"1.3.1515"}}],["1.3.1516",{"base":{"amount":100000,"asset_id":"1.3.0"},"quote":{"amount":3000,"asset_id":"1.3.1516"}}]],
"acceptable_borrowers":[["1.2.0",5000000],["1.2.6",8000000]],"extensions":[]}]],

By the way, it is strange that the error didn't pop up on the first sync, but popped up on replay. (UPDATE: see #2693 and #2493)

[sschiessl-bcp]

Thanks for the investigation. Do you have an idea how to fix it?

[abitmore]

@sschiessl-bcp Yes, I'm working on a fix.

[abitmore]

Actually I had anticipated this issue (see #2554) but forgot to re-check or fix.

Anyway now I expect that #2553 will fix it.

[abitmore]

Fixed by #2553.