Crash due to failed assertion in fill_order

[theoreticalbts]

#0  0x00007ffff6c01cc9 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:56
#1  0x00007ffff6c050d8 in __GI_abort () at abort.c:89
#2  0x00007ffff6bfab86 in __assert_fail_base (fmt=0x7ffff6d4b830 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=assertion@entry=0x2b959d0 "order.get_collateral() >= pays", 
    file=file@entry=0x2b956b8 "src/graphene/libraries/chain/db_market.cpp", line=line@entry=290, 
    function=function@entry=0x2bc02c0 <graphene::chain::database::fill_order(graphene::chain::call_order_object const&, graphene::chain::asset const&, graphene::chain::asset const&)::__PRETTY_FUNCTION__> "bool graphene::chain::database::fill_order(const graphene::chain::call_order_object&, const graphene::chain::asset&, const graphene::chain::asset&)") at assert.c:92
#3  0x00007ffff6bfac32 in __GI___assert_fail (assertion=0x2b959d0 "order.get_collateral() >= pays", file=0x2b956b8 "src/graphene/libraries/chain/db_market.cpp", line=290, 
    function=0x2bc02c0 <graphene::chain::database::fill_order(graphene::chain::call_order_object const&, graphene::chain::asset const&, graphene::chain::asset const&)::__PRETTY_FUNCTION__> "bool graphene::chain::database::fill_order(const graphene::chain::call_order_object&, const graphene::chain::asset&, const graphene::chain::asset&)") at assert.c:101
#4  0x00000000023dd9b0 in graphene::chain::database::fill_order (this=0x7062278, order=..., pays=..., receives=...) at src/graphene/libraries/chain/db_market.cpp:290
#5  0x00000000023dd237 in graphene::chain::database::match (this=0x7062278, call=..., settle=..., match_price=..., max_settlement=...) at src/graphene/libraries/chain/db_market.cpp:239
#6  0x00000000023e30b1 in graphene::chain::database::clear_expired_orders (this=0x7062278) at src/graphene/libraries/chain/db_update.cpp:237
#7  0x00000000023c3b50 in graphene::chain::database::_apply_block (this=0x7062278, next_block=...) at src/graphene/libraries/chain/db_block.cpp:490
#8  0x00000000023c301a in graphene::chain::database::__lambda19::operator() (__closure=0x7ffff63c9070) at src/graphene/libraries/chain/db_block.cpp:448
#9  0x00000000023e4137 in graphene::chain::detail::with_skip_flags<graphene::chain::database::apply_block(const graphene::chain::signed_block&, uint32_t)::__lambda19>(graphene::chain::database &, uint32_t, graphene::chain::database::__lambda19) (db=..., skip_flags=0, callback=...) at src/graphene/libraries/chain/include/graphene/chain/db_with.hpp:123
#10 0x00000000023c3431 in graphene::chain::database::apply_block (this=0x7062278, next_block=..., skip=0) at src/graphene/libraries/chain/db_block.cpp:449
#11 0x00000000023bc64c in graphene::chain::database::_push_block (this=0x7062278, new_block=...) at src/graphene/libraries/chain/db_block.cpp:185
#12 0x00000000023bbc31 in graphene::chain::database::__lambda15::__lambda16::operator() (__closure=0x7ffff63c9610) at src/graphene/libraries/chain/db_block.cpp:112
#13 0x00000000023e3f40 in graphene::chain::detail::without_pending_transactions<graphene::chain::database::push_block(const graphene::chain::signed_block&, uint32_t)::__lambda15::__lambda16>(graphene::chain::database &, <unknown type in src/graphene/programs/witness_node/witness_node, CU 0x10d33a9, DIE 0x13264b4>, graphene::chain::database::__lambda15::__lambda16) (db=..., 
    pending_transactions=<unknown type in src/graphene/programs/witness_node/witness_node, CU 0x10d33a9, DIE 0x13264b4>, callback=...)
    at src/graphene/libraries/chain/include/graphene/chain/db_with.hpp:140
#14 0x00000000023bbcad in graphene::chain::database::__lambda15::operator() (__closure=0x7ffff63c96b0) at src/graphene/libraries/chain/db_block.cpp:113
#15 0x00000000023e3fbb in graphene::chain::detail::with_skip_flags<graphene::chain::database::push_block(const graphene::chain::signed_block&, uint32_t)::__lambda15>(graphene::chain::database &, uint32_t, graphene::chain::database::__lambda15) (db=..., skip_flags=0, callback=...) at src/graphene/libraries/chain/include/graphene/chain/db_with.hpp:123
#16 0x00000000023bbd06 in graphene::chain::database::push_block (this=0x7062278, new_block=..., skip=0) at src/graphene/libraries/chain/db_block.cpp:114
#17 0x000000000204359a in graphene::app::detail::application_impl::handle_block (this=0x7062140, blk_msg=..., sync_mode=false, contained_transaction_message_ids=...) at src/graphene/libraries/app/application.cpp:396
#18 0x00000000028ec941 in graphene::net::detail::statistics_gathering_node_delegate_wrapper::__lambda54::operator() (__closure=0x7fffd8268cf8) at src/graphene/libraries/net/node.cpp:5325
#19 0x00000000028fcf7e in fc::detail::functor_run<graphene::net::detail::statistics_gathering_node_delegate_wrapper::handle_block(const graphene::net::block_message&, bool, std::vector<fc::ripemd160>&)::__lambda54>::run(void *, void *)
    (functor=0x7fffd8268cf8, prom=0x7fffd8268de8) at src/graphene/libraries/fc/include/fc/thread/task.hpp:77
#20 0x00000000026c7035 in fc::task_base::run_impl (this=0x7fffd8268d20) at src/graphene/libraries/fc/src/thread/task.cpp:43
#21 0x00000000026c6fc6 in fc::task_base::run (this=0x7fffd8268d20) at src/graphene/libraries/fc/src/thread/task.cpp:32
#22 0x00000000026bb9e6 in fc::thread_d::run_next_task (this=0x7096110) at src/graphene/libraries/fc/src/thread/thread_d.hpp:498
#23 0x00000000026bbe8a in fc::thread_d::process_tasks (this=0x7096110) at src/graphene/libraries/fc/src/thread/thread_d.hpp:547
#24 0x00000000026bb4fd in fc::thread_d::start_process_tasks (my=118055184) at src/graphene/libraries/fc/src/thread/thread_d.hpp:475
#25 0x0000000002a14691 in make_fcontext () at libs/context/src/asm/make_x86_64_sysv_elf_gas.S:64
#26 0x0000000000000000 in ?? ()

[theoreticalbts]

1203002ms th_a       witness.cpp:176               block_production_loo ] Generated block #314814 with timestamp 2015-09-30T08:20:03 at time 2015-09-30T08:20:03
1203020ms th_a       application.cpp:518           get_item             ] Serving up block #314814
1203029ms th_a       application.cpp:518           get_item             ] Serving up block #314814
1203085ms th_a       application.cpp:518           get_item             ] Serving up block #314814
1203102ms th_a       application.cpp:518           get_item             ] Serving up block #314814
1203104ms th_a       application.cpp:518           get_item             ] Serving up block #314814
1203111ms th_a       application.cpp:518           get_item             ] Serving up block #314814
1203115ms th_a       application.cpp:518           get_item             ] Serving up block #314814
1203258ms th_a       application.cpp:518           get_item             ] Serving up block #314814
1203366ms th_a       application.cpp:518           get_item             ] Serving up block #314814
1203520ms th_a       application.cpp:518           get_item             ] Serving up block #314814
1206000ms th_a       witness.cpp:182               block_production_loo ] Not producing block because it isn't my turn
1206944ms th_a       application.cpp:388           handle_block         ] Got block #314814 with time 2015-09-30T08:20:06 from network with latency of 940 ms from mr.agsexplorer
1207000ms th_a       witness.cpp:182               block_production_loo ] Not producing block because it isn't my turn
1207022ms th_a       application.cpp:518           get_item             ] Serving up block #314814
1207024ms th_a       application.cpp:518           get_item             ] Serving up block #314814
1207051ms th_a       application.cpp:518           get_item             ] Serving up block #314814
1207260ms th_a       application.cpp:518           get_item             ] Serving up block #314814
1208000ms th_a       witness.cpp:182               block_production_loo ] Not producing block because it isn't my turn
1209000ms th_a       witness.cpp:182               block_production_loo ] Not producing block because it isn't my turn
1209175ms th_a       application.cpp:388           handle_block         ] Got block #314815 with time 2015-09-30T08:20:09 from network with latency of 170 ms from dele-puppy
witness_node:src/graphene/libraries/chain/db_market.cpp:290: bool graphene::chain::database::fill_order(const graphene::chain::call_order_object&, const graphene::chain::asset&, const graphene::chain::asset&): Assertion `order.get_collateral() >= pays' failed.

[bytemaster]

Sometime between block 134000 and 135000 a margin position was updated

nt_feed.settlement_price: {"base":{"amount":995,"asset_id":"1.3.626"},"quote":{"amount":100000,"asset_id":"1.3.0"}}
   42.5677%   134000 of 314793
505722ms th_a       market_evaluator.cpp:186      operator()           ] call.call_price: {"base":{"amount":24451451,"asset_id":"1.3.0"},"quote":{"amount":14000,"asset_id":"1.3.626"}} call.call_price.to_real(): 1746.53221428571418983 (~call.call_price).to_real(): 0.00057256315790830
505722ms th_a       market_evaluator.cpp:189      operator()           ] swan_price: {"base":{"amount":1000000,"asset_id":"1.3.626"},"quote":{"amount":3056431375,"asset_id":"1.3.0"}} swan_price.to_real(): 0.00032717894737617 (~swan_price).to_real(): 3056.43137500000011642
505722ms th_a       market_evaluator.cpp:251      do_apply             ] ~call_obj->call_price: {"base":{"amount":14000,"asset_id":"1.3.626"},"quote":{"amount":24451451,"asset_id":"1.3.0"}} "<": < _bitasset_data->current_feed.settlement_price: {"base":{"amount":62164,"asset_id":"1.3.626"},"quote":{"amount":95000000,"asset_id":"1.3.0"}}
   43.203%   136000 of 314793
505926ms th_a       market_evaluator.cpp:204      operator()           ] call.call_price: {"base":{"amount":100502513,"asset_id":"1.3.0"},"quote":{"amount":87500,"asset_id":"1.3.626"}} call.call_price.to_real(): 1148.60014857142846267 (~call.call_price).to_real(): 0.00087062499621278
505926ms th_a       market_evaluator.cpp:205      operator()           ] swan_price: {"base":{"amount":100000,"asset_id":"1.3.626"},"quote":{"amount":201005026,"asset_id":"1.3.0"}} swan_price.to_real(): 0.00049749999783588 (~swan_price).to_real(): 2010.05025999999998021
505926ms th_a       market_evaluator.cpp:208      operator()           ] _bitasset_data->current_feed.settlement_price.to_real(): 0.00995000000000000 (~_bitasset_data->current_feed.settlement_price).to_real(): 100.50251256281407564 _bitasset_data->current_feed.settlement_price: {"base":{"amount":995,"asset_id":"1.3.626"},"quote":{"amount":100000,"asset_id":"1.3.0"}}
505926ms th_a       market_evaluator.cpp:251      do_apply             ] ~call_obj->call_price: {"base":{"amount":87500,"asset_id":"1.3.626"},"quote":{"amount":100502513,"asset_id":"1.3.0"}} "<": < _bitasset_data->current_feed.settlement_price: {"base":{"amount":995,"asset_id":"1.3.626"},"quote":{"amount":100000,"asset_id":"1.3.0"}}
505928ms th_a       market_evaluator.cpp:204      operator()           ] call.call_price: {"base":{"amount":9547739,"asset_id":"1.3.0"},"quote":{"amount":87500,"asset_id":"1.3.626"}} call.call_price.to_real(): 109.11701714285713649 (~call.call_price).to_real(): 0.00916447338998270
505935ms th_a       market_evaluator.cpp:205      operator()           ] swan_price: {"base":{"amount":100000,"asset_id":"1.3.626"},"quote":{"amount":19095478,"asset_id":"1.3.0"}} swan_price.to_real(): 0.00523684193713297 (~swan_price).to_real(): 190.95477999999999952
505935ms th_a       market_evaluator.cpp:208      operator()           ] _bitasset_data->current_feed.settlement_price.to_real(): 0.00995000000000000 (~_bitasset_data->current_feed.settlement_price).to_real(): 100.50251256281407564 _bitasset_data->current_feed.settlement_price: {"base":{"amount":995,"asset_id":"1.3.626"},"quote":{"amount":100000,"asset_id":"1.3.0"}}

This margin position set the call price to .0052 (non normalized for USD/CORE precision) which is about 10x higher than the normal price. This was allowed at the time because the price feed was off by a factor of 10.

Time passes and the feed is corrected.

Someone issues a force settle operation, but the force settle price is beyond black swan. This needs to be anticipated and trigger a black swan rather than halt the network.

The question remains is should the black swan have occurred between the price feed correction and the force settlement and if so, why didn't it.