Assert Failure on P2P node

[bytemaster]

 witness_node: /root/graphene/libraries/net/node.cpp:2359: void graphene::net::detail::node_impl::on_blockchain_item_ids_inventory_message(graphene::net::peer_connection*, const graphene::net::blockchain_item_ids_inventory_message&): Assertion `item_hashes_received.front() != item_hash_t()' failed.
1586026ms th_a       application.cpp:348           handle_block         ] Got block #19167 from network
1586762ms th_a       application.cpp:383           handle_transaction   ] Got transaction from network
1588028ms th_a       application.cpp:348           handle_block         ] Got block #19168 from network
1589025ms th_a       application.cpp:348           handle_block         ] Got block #19169 from network
1589397ms th_a       application.cpp:492           get_blockchain_synop ] reference_point: 0000000000000000000000000000000000000000 number_of_blocks_after_reference_point: 0 result: ["00000ae1024b96c5bc205e25733195aabb755bcc","00002ae189fd9251a2818babbeeb734cd3b9b330","00003ae19f4ddb2b64dffb81a54ddc663cb8aa01","000042e1ca9dfd610939c22f9ebde2c412aee1ac","000046e11deacc780fcbbb9ba199ec400a651b91","000048e1113e4a3961b9d03adf06c6e390522a14","000049e1116c044a5a19ef817196ab06390c5381","00004a61d7bda5d842a2e16c905fef0bc19004cb","00004aa13154c7cc27516deda3da588d5431b2d1","00004ac129826f3ccd51cc7be5623535058cb05f","00004ad1e1a078d205a7a85d059aa52febcad426","00004ad98b62fc800cdbba2886b8032d16ee4321","00004addcc181dd860bbc7789ea43a70fcd98020","00004adf9ee04bf5dee3258e3ea9c56597b9057c","00004ae0006a7cd59e371ab731d65d51c2bcdd86","00004ae100ab751303b1c28eb71ec14c186fcad3"]
1590027ms th_a       application.cpp:348           handle_block         ] Got block #19170 from network
witness_node: /root/graphene/libraries/net/node.cpp:2359: void graphene::net::detail::node_impl::on_blockchain_item_ids_inventory_message(graphene::net::peer_connection*, const graphene::net::blockchain_item_ids_inventory_message&): Assertion `item_hashes_received.front() != item_hash_t()' failed.

The P2P log at the time:

2015-08-20T23:26:30 p2p:delayed_peer_deletion_task delayed_peer_deletio ] leaving delayed_peer_deletion_task            node.cpp:1501
2015-08-20T23:26:30 p2p:message read_loop           on_message ] handling message current_time_reply_message_type b42b2aedfe60bee1f883565d7a577fb41d000055 size 24 from peer 114.92.254.159:43979           node.cpp:1651
2015-08-20T23:26:30 p2p:message read_loop           on_message ] handling message blockchain_item_ids_inventory_message_type 09f7e18d14a00aeafe1ef3b0c40a58d8a3507cc9 size 309 from peer 114.92.254.159:43979           node.cpp:1651
2015-08-20T23:26:30 p2p:message read_loop on_blockchain_item_i ] sync: received a list of 15 available items from 114.92.254.159:43979          node.cpp:2306
2015-08-20T23:26:30 p2p:message read_loop on_blockchain_item_i ] is_first_item_for_other_peer: false.  item_hashes_received.size() = 15         node.cpp:2352
2015-08-20T23:26:30 p2p:message read_loop on_blockchain_item_i ] popping item because delegate has already seen it.  peer's last block the delegate has seen is now 000049e1116c044a5a19ef817196ab06390c5381 (1)            node.cpp:2364
2015-08-20T23:26:30 p2p:message read_loop on_blockchain_item_i ] popping item because delegate has already seen it.  peer's last block the delegate has seen is now 000049e23971b4963e015ed93fe3588b1e1fae95 (2)            node.cpp:2364
2015-08-20T23:26:30 p2p:message read_loop on_blockchain_item_i ] popping item because delegate has already seen it.  peer's last block the delegate has seen is now 000049e3064f9f4ba5b4bda8616884a333729724 (3)            node.cpp:2364
2015-08-20T23:26:30 p2p:message read_loop on_blockchain_item_i ] popping item because delegate has already seen it.  peer's last block the delegate has seen is now 000049e45094820ba93422bd8fa31c8f3e7d3c92 (4)            node.cpp:2364
2015-08-20T23:26:30 p2p:message read_loop on_blockchain_item_i ] popping item because delegate has already seen it.  peer's last block the delegate has seen is now 000049e54fb6b55b531cc4dd65e475f26821941e (5)            node.cpp:2364
2015-08-20T23:26:30 p2p:message read_loop on_blockchain_item_i ] popping item because delegate has already seen it.  peer's last block the delegate has seen is now 000049e6729b17ba81aed6975f967645e5074517 (6)            node.cpp:2364
2015-08-20T23:26:30 p2p:message read_loop on_blockchain_item_i ] popping item because delegate has already seen it.  peer's last block the delegate has seen is now 000049e7c78642267a650db5c41ae256f9112e76 (7)            node.cpp:2364
2015-08-20T23:26:30 p2p:message read_loop on_blockchain_item_i ] popping item because delegate has already seen it.  peer's last block the delegate has seen is now 000049e8e414242760d64ac14b11419429536f83 (8)            node.cpp:2364
2015-08-20T23:26:30 p2p:message read_loop on_blockchain_item_i ] popping item because delegate has already seen it.  peer's last block the delegate has seen is now 000049e9782cc2024e245dad0e91515995292866 (9)            node.cpp:2364
2015-08-20T23:26:30 p2p:message read_loop on_blockchain_item_i ] popping item because delegate has already seen it.  peer's last block the delegate has seen is now 000049ea317fe14965a0be130688ec140e3fa665 (10)           node.cpp:2364
2015-08-20T23:26:30 p2p:message read_loop on_blockchain_item_i ] popping item because delegate has already seen it.  peer's last block the delegate has seen is now 000049eb39306a1360497002faeea118732d6761 (11)           node.cpp:2364
2015-08-20T23:26:30 p2p:message read_loop on_blockchain_item_i ] popping item because delegate has already seen it.  peer's last block the delegate has seen is now 000049ec75fcfcf5397c8e6941eed82c42517651 (12)           node.cpp:2364
2015-08-20T23:26:30 p2p:message read_loop on_blockchain_item_i ] popping item because delegate has already seen it.  peer's last block the delegate has seen is now 000049ed587a0c63625259c90a08814b49dd48ad (13)           node.cpp:2364

[bytemaster]

Something interesting about this is that the block number (in paren) goes from 1 to 13 but according to the item ids these are blocks 000049e1 to 000049ed (expressed as block number in hex).

[valzav]

Looks like this is the same issue:

#0  0x00007f28006f8cc9 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:56
#1  0x00007f28006fc0d8 in __GI_abort () at abort.c:89
#2  0x00007f28006f1b86 in __assert_fail_base (fmt=0x7f2800842830 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", 
    assertion=assertion@entry=0x2a45160 "item_hashes_received.front() != item_hash_t()", 
    file=file@entry=0x2a42e28 "/home/vagrant/bts/graphene/libraries/net/node.cpp", line=line@entry=2359, 
    function=function@entry=0x2a4c540 <graphene::net::detail::node_impl::on_blockchain_item_ids_inventory_message(graphene::net::peer_connection*, graphene::net::blockchain_item_ids_inventory_message const&)::__PRETTY_FUNCTION__> "void graphene::net::detail::node_impl::on_blockchain_item_ids_inventory_message(graphene::net::peer_connection*, const graphene::net::blockchain_item_ids_inventory_message&)") at assert.c:92
#3  0x00007f28006f1c32 in __GI___assert_fail (assertion=0x2a45160 "item_hashes_received.front() != item_hash_t()", 
    file=0x2a42e28 "/home/vagrant/bts/graphene/libraries/net/node.cpp", line=2359, 
    function=0x2a4c540 <graphene::net::detail::node_impl::on_blockchain_item_ids_inventory_message(graphene::net::peer_connection*, graphene::net::blockchain_item_ids_inventory_message const&)::__PRETTY_FUNCTION__> "void graphene::net::detail::node_impl::on_blockchain_item_ids_inventory_message(graphene::net::peer_connection*, const graphene::net::blockchain_item_ids_inventory_message&)") at assert.c:101
#4  0x00000000026b7656 in graphene::net::detail::node_impl::on_blockchain_item_ids_inventory_message (this=0xfe697b0, originating_peer=0x7f27f00d4ab0, 
    blockchain_item_ids_inventory_message_received=...) at /home/vagrant/bts/graphene/libraries/net/node.cpp:2359
#5  0x00000000026ac1b6 in graphene::net::detail::node_impl::on_message (this=0xfe697b0, originating_peer=0x7f27f00d4ab0, received_message=...)
    at /home/vagrant/bts/graphene/libraries/net/node.cpp:1673
#6  0x000000000279cc35 in graphene::net::peer_connection::on_message (this=0x7f27f00d4ab0, originating_connection=0x7f27f00d4ae0, received_message=...)
    at /home/vagrant/bts/graphene/libraries/net/peer_connection.cpp:263
#7  0x00000000027a5388 in graphene::net::detail::message_oriented_connection_impl::read_loop (this=0x7f27f00ebed0)
    at /home/vagrant/bts/graphene/libraries/net/message_oriented_connection.cpp:174
#8  0x00000000027a4cb3 in graphene::net::detail::message_oriented_connection_impl::__lambda0::operator() (__closure=0x7f27f00d4188)
    at /home/vagrant/bts/graphene/libraries/net/message_oriented_connection.cpp:117
#9  0x00000000027a9f4c in fc::detail::void_functor_run<graphene::net::detail::message_oriented_connection_impl::accept()::__lambda0>::run(void *, void *)
    (functor=0x7f27f00d4188, prom=0x7f27f00d4180) at /home/vagrant/bts/graphene/libraries/fc/include/fc/thread/task.hpp:83
#10 0x00000000024cdfd1 in fc::task_base::run_impl (this=0x7f27f00d4190) at /home/vagrant/bts/graphene/libraries/fc/src/thread/task.cpp:43
#11 0x00000000024cdf62 in fc::task_base::run (this=0x7f27f00d4190) at /home/vagrant/bts/graphene/libraries/fc/src/thread/task.cpp:32
#12 0x00000000024c2982 in fc::thread_d::run_next_task (this=0x7f27f00008c0) at /home/vagrant/bts/graphene/libraries/fc/src/thread/thread_d.hpp:498
#13 0x00000000024c2e26 in fc::thread_d::process_tasks (this=0x7f27f00008c0) at /home/vagrant/bts/graphene/libraries/fc/src/thread/thread_d.hpp:547
#14 0x00000000024c2499 in fc::thread_d::start_process_tasks (my=139809506986176) at /home/vagrant/bts/graphene/libraries/fc/src/thread/thread_d.hpp:475
#15 0x000000000281edd1 in make_fcontext ()

[theoreticalbts]

I was just about to post what is quite possibly same issue:

2015-08-20T23:26:29 p2p:message read_loop           on_message ] handling message current_time_request_message_type 81e5af77bf3fc9724e64b3dee27007a49fdff060 size 8 from peer 114.xx.yy.zz:43978                      node.cpp:1651
2015-08-20T23:26:29 p2p:message read_loop         send_message ] peer_connection::send_message() enqueueing message of type 5013 for peer 114.xx.yy.zz:43978                  peer_connection.cpp:365
2015-08-20T23:26:29 p2p:message read_loop send_queueable_messa ] peer_connection::send_message() is firing up send_queued_message_task                  peer_connection.cpp:354
2015-08-20T23:26:29 p2p:send_queued_messages_task              counter ] entering peer_connection::send_queued_messages_task()                  peer_connection.cpp:279
2015-08-20T23:26:29 p2p:send_queued_messages_task send_queued_messages ] peer_connection::send_queued_messages_task() calling message_oriented_connection::send_message() to send message of type 5013 for peer 114.xx.yy.zz:43978    
                peer_connection.cpp:291
2015-08-20T23:26:29 p2p:send_queued_messages_task send_queued_messages ] peer_connection::send_queued_messages_task()'s call to message_oriented_connection::send_message() completed normally for peer 114.xx.yy.zz:43978            
        peer_connection.cpp:294
2015-08-20T23:26:29 p2p:send_queued_messages_task send_queued_messages ] leaving peer_connection::send_queued_messages_task() due to queue exhaustion                   peer_connection.cpp:326
2015-08-20T23:26:29 p2p:send_queued_messages_task             ~counter ] leaving peer_connection::send_queued_messages_task()                   peer_connection.cpp:280
2015-08-20T23:26:29 p2p:message read_loop           on_message ] handling message fetch_blockchain_item_ids_message_type 574f54f272b7e8bb80f8289a4988583522e45e20 size 325 from peer 114.xx.yy.zz:43978                       node.cpp:1651
2015-08-20T23:26:29 p2p:message read_loop on_fetch_blockchain_ ] sync: received a request for item ids after {"item_type":1001,"item_hash":"000049efc4646a99bad9d78607972719e1a2d79d"} from peer 114.xx.yy.zz:43978 (full request: ["000009ef501ed09bea4e32d71077b13bcd3c28a1","000029ef11981d056e1a70afd0fdac952774b2f7","000039ef9f6d0c5d83c52767cd98c710ac7a2d46","000041efa457c0e455f2569bc98b2e097baf8ace","000045ef42cf7a74580c57dd77cf3be887575d14","000047ef9621e0266c0a7a9195a57cbb0aef6550","000048efd72770d20925e6e74a83d7a93f213f0a","0000496fa7fcba2947cc187a5fa9e7e30d8b5f3a","000049afce3550f6f3a26efa67968d465ac16268","000049cfbf02c4d519b393a93430ee4785076736","000049df2dad0b1b7eb473d9eb6d2e6a31cc3080","000049e7c78642267a650db5c41ae256f9112e76","000049eb39306a1360497002faeea118732d6761","000049ed587a0c63625259c90a08814b49dd48ad","0000000000000000000000000000000000000000","000049efc4646a99bad9d78607972719e1a2d79d"])                 node.cpp:2132
2015-08-20T23:26:29 p2p:message read_loop on_fetch_blockchain_ ] reply_message: {"total_remaining_item_count":17169,"item_type":1001,"item_hashes_available":["0000000188fe15bfb7f2606f324a353e81d8f707","0000000283129935aaaac1f82964c1e79ed416d2",...,"000049ed587a0c63625259c90a08814b49dd48ad","0000000000000000000000000000000000000000","000049efc4646a99bad9d78607972719e1a2d79d"]                       node.cpp:2143
2015-08-20T23:26:29 p2p:message read_loop on_fetch_blockchain_ ] sync: peer is out of sync, sending peer 2000 items ids: first: 0000000188fe15bfb7f2606f324a353e81d8f707, last: 000007d0fc03ea61aacb907a0fd791e5384fa22a                
        node.cpp:2181
2015-08-20T23:26:29 p2p:message read_loop         send_message ] peer_connection::send_message() enqueueing message of type 5002 for peer 114.xx.yy.zz:43978                  peer_connection.cpp:365
2015-08-20T23:26:29 p2p:message read_loop send_queueable_messa ] peer_connection::send_message() is firing up send_queued_message_task                  peer_connection.cpp:354
2015-08-20T23:26:29 p2p:send_queued_messages_task              counter ] entering peer_connection::send_queued_messages_task()                  peer_connection.cpp:279
2015-08-20T23:26:29 p2p:send_queued_messages_task send_queued_messages ] peer_connection::send_queued_messages_task() calling message_oriented_connection::send_message() to send message of type 5002 for peer 114.xx.yy.zz:43978    
                peer_connection.cpp:291
2015-08-20T23:26:29 p2p:send_queued_messages_task send_queued_messages ] peer_connection::send_queued_messages_task()'s call to message_oriented_connection::send_message() completed normally for peer 114.xx.yy.zz:43978            
        peer_connection.cpp:294
2015-08-20T23:26:29 p2p:send_queued_messages_task send_queued_messages ] leaving peer_connection::send_queued_messages_task() due to queue exhaustion                   peer_connection.cpp:326
2015-08-20T23:26:29 p2p:send_queued_messages_task             ~counter ] leaving peer_connection::send_queued_messages_task()                   peer_connection.cpp:280
2015-08-20T23:26:29 p2p:message read_loop           on_message ] handling message current_time_reply_message_type bd29d988d27407e0788d9351f203208ab45d6edc size 24 from peer 114.xx.yy.zz:43978                       node.cpp:1651
2015-08-20T23:26:29 p2p:message read_loop           on_message ] handling message blockchain_item_ids_inventory_message_type 09f7e18d14a00aeafe1ef3b0c40a58d8a3507cc9 size 309 from peer 114.xx.yy.zz:43978                   node.cpp:1651
2015-08-20T23:26:29 p2p:message read_loop on_blockchain_item_i ] sync: received a list of 15 available items from 114.xx.yy.zz:43978                  node.cpp:2306
2015-08-20T23:26:29 p2p:message read_loop on_blockchain_item_i ] is_first_item_for_other_peer: false.  item_hashes_received.size() = 15                 node.cpp:2352
2015-08-20T23:26:29 p2p:message read_loop on_blockchain_item_i ] popping item because delegate has already seen it.  peer's last block the delegate has seen is now 000049e1116c044a5a19ef817196ab06390c5381 (1)                        node.cpp:2364
2015-08-20T23:26:29 p2p:message read_loop on_blockchain_item_i ] popping item because delegate has already seen it.  peer's last block the delegate has seen is now 000049e23971b4963e015ed93fe3588b1e1fae95 (2)                        node.cpp:2364
2015-08-20T23:26:29 p2p:message read_loop on_blockchain_item_i ] popping item because delegate has already seen it.  peer's last block the delegate has seen is now 000049e3064f9f4ba5b4bda8616884a333729724 (3)                        node.cpp:2364
2015-08-20T23:26:29 p2p:message read_loop on_blockchain_item_i ] popping item because delegate has already seen it.  peer's last block the delegate has seen is now 000049e45094820ba93422bd8fa31c8f3e7d3c92 (4)                        node.cpp:2364
2015-08-20T23:26:29 p2p:message read_loop on_blockchain_item_i ] popping item because delegate has already seen it.  peer's last block the delegate has seen is now 000049e54fb6b55b531cc4dd65e475f26821941e (5)                        node.cpp:2364
2015-08-20T23:26:29 p2p:message read_loop on_blockchain_item_i ] popping item because delegate has already seen it.  peer's last block the delegate has seen is now 000049e6729b17ba81aed6975f967645e5074517 (6)                        node.cpp:2364
2015-08-20T23:26:29 p2p:message read_loop on_blockchain_item_i ] popping item because delegate has already seen it.  peer's last block the delegate has seen is now 000049e7c78642267a650db5c41ae256f9112e76 (7)                        node.cpp:2364
2015-08-20T23:26:29 p2p:message read_loop on_blockchain_item_i ] popping item because delegate has already seen it.  peer's last block the delegate has seen is now 000049e8e414242760d64ac14b11419429536f83 (8)                        node.cpp:2364
2015-08-20T23:26:29 p2p:message read_loop on_blockchain_item_i ] popping item because delegate has already seen it.  peer's last block the delegate has seen is now 000049e9782cc2024e245dad0e91515995292866 (9)                        node.cpp:2364
2015-08-20T23:26:29 p2p:message read_loop on_blockchain_item_i ] popping item because delegate has already seen it.  peer's last block the delegate has seen is now 000049ea317fe14965a0be130688ec140e3fa665 (10)                       node.cpp:2364
2015-08-20T23:26:29 p2p:message read_loop on_blockchain_item_i ] popping item because delegate has already seen it.  peer's last block the delegate has seen is now 000049eb39306a1360497002faeea118732d6761 (11)                       node.cpp:2364
2015-08-20T23:26:29 p2p:message read_loop on_blockchain_item_i ] popping item because delegate has already seen it.  peer's last block the delegate has seen is now 000049ec75fcfcf5397c8e6941eed82c42517651 (12)                       node.cpp:2364
2015-08-20T23:26:29 p2p:message read_loop on_blockchain_item_i ] popping item because delegate has already seen it.  peer's last block the delegate has seen is now 000049ed587a0c63625259c90a08814b49dd48ad (13)                       node.cpp:2364

EDIT: Also possibly relevant console messages:

1586135ms th_a       application.cpp:451           get_item             ] Serving up block #19167
1586765ms th_a       application.cpp:383           handle_transaction   ] Got transaction from network
1588033ms th_a       application.cpp:348           handle_block         ] Got block #19168 from network
1588181ms th_a       application.cpp:443           get_item             ] Request for item {"item_type":1001,"item_hash":"00004ae0006a7cd59e371ab731d65d51c2bcdd86"}
1588181ms th_a       application.cpp:451           get_item             ] Serving up block #19168
1589030ms th_a       application.cpp:348           handle_block         ] Got block #19169 from network
1589098ms th_a       application.cpp:443           get_item             ] Request for item {"item_type":1001,"item_hash":"00004ae100ab751303b1c28eb71ec14c186fcad3"}
1589099ms th_a       application.cpp:451           get_item             ] Serving up block #19169
1589229ms th_a       application.cpp:492           get_blockchain_synop ] reference_point: 0000000000000000000000000000000000000000 number_of_blocks_after_reference_point: 0 result: ["00000ae1024b96c5bc205e25733195aabb755bcc","00002ae189fd9251a2818babbeeb734cd3b9b330","00003ae19f4ddb2b64dffb81a54ddc663cb8aa01","000042e1ca9dfd610939c22f9ebde2c412aee1ac","000046e11deacc780fcbbb9ba199ec400a651b91","000048e1113e4a3961b9d03adf06c6e390522a14","000049e1116c044a5a19ef817196ab06390c5381","00004a61d7bda5d842a2e16c905fef0bc19004cb","00004aa13154c7cc27516deda3da588d5431b2d1","00004ac129826f3ccd51cc7be5623535058cb05f","00004ad1e1a078d205a7a85d059aa52febcad426","00004ad98b62fc800cdbba2886b8032d16ee4321","00004addcc181dd860bbc7789ea43a70fcd98020","00004adf9ee04bf5dee3258e3ea9c56597b9057c","00004ae0006a7cd59e371ab731d65d51c2bcdd86","00004ae100ab751303b1c28eb71ec14c186fcad3"]
witness_node: /home/cc/graphene/src/graphene/libraries/net/node.cpp:2359: void graphene::net::detail::node_impl::on_blockchain_item_ids_inventory_message(graphene::net::peer_connection*, const graphene::net::blockchain_item_ids_inventory_message&): Assertion `item_hashes_received.front() != item_hash_t()' failed.

[theoreticalbts]

My initial feeling for what is happening is that on_fetch_blockchain_item_ids_message is checking the item ID and trusting the remote peer not to give it item_hash_t() (i.e. a hash of all zeros), which would obviously be wrong (a malicious peer shouldn't be able to crash the code). However, on closer reading of the code I see that it's actually in this for loop:

        while (!item_hashes_received.empty() &&
               _delegate->has_item(item_id(blockchain_item_ids_inventory_message_received.item_type,
                                           item_hashes_received.front())))

This means the p2p code is assuming _delegate->has_item() will never return true when passed item_id_type().

[theoreticalbts]

@bytemaster and I figured out that block_database::contains should special case the zero ID -- otherwise the block_id_type of all zeros will be compared against the 0th entry in the _block_num_to_pos flat file, which will be all zeros as there is no block. I'll push a patch shortly.