`/in_flight_exit.get_data` crashes on attempt to IFE transactions spending spent deposits

[0x234]

watcher-0 watcher 2019-11-12 05:32:11.728 [info] module=Phoenix.Logger function=phoenix_error_rendered/4 request_id=FdZTUg-b4_1fYRkABSMB trace_id=6798762404176944400 span_id=3860092244967034233 ⋅Converted error {:case_clause, {:error, :no_deposit_for_given_blknum}} to 500 response⋅
watcher-0 watcher 2019-11-12 05:32:11.730 [error] ⋅#PID<0.24608.6> running OMG.WatcherRPC.Web.Endpoint (cowboy_protocol) terminated
watcher-0 watcher Server: audit-e3c15df-watcher-rinkeby-01.omg.network:80 (http)
watcher-0 watcher Request: POST /in_flight_exit.get_data
watcher-0 watcher ** (exit) an exception was raised:
watcher-0 watcher     ** (CaseClauseError) no case clause matching: {:error, :no_deposit_for_given_blknum}
watcher-0 watcher         (omg_watcher) lib/omg_watcher/api/in_flight_exit.ex:102: OMG.Watcher.API.InFlightExit.find_single_input_data/2
watcher-0 watcher         (elixir) lib/enum.ex:3317: Enumerable.List.reduce/3
watcher-0 watcher         (elixir) lib/enum.ex:1990: Enum.reduce_while/3
watcher-0 watcher         (omg_watcher) lib/omg_watcher/api/in_flight_exit.ex:40: OMG.Watcher.API.InFlightExit.get_in_flight_exit/1
watcher-0 watcher         (omg_watcher_rpc) lib/web/controllers/in_flight_exit.ex:61: OMG.WatcherRPC.Web.Controller.InFlightExit.handle_txbytes_based_request/4
watcher-0 watcher         (omg_watcher_rpc) lib/web/controllers/in_flight_exit.ex:15: OMG.WatcherRPC.Web.Controller.InFlightExit.action/2
watcher-0 watcher         (omg_watcher_rpc) lib/web/controllers/in_flight_exit.ex:15: OMG.WatcherRPC.Web.Controller.InFlightExit.phoenix_controller_pipeline/2
watcher-0 watcher         (omg_watcher_rpc) lib/web/endpoint.ex:15: OMG.WatcherRPC.Web.Endpoint.instrument/4⋅
watcher-0 watcher 2019-11-12 05:36:53.086 [info] module=OMG.Watcher.BlockGetter.Core function=log_downloading_blocks/2 trace_id=6532029999212419176 ⋅Child chain seen at block #3000. Downloading blocks [2000]⋅
watcher-0 watcher 2019-11-12 05:36:59.619 [info] module=OMG.Watcher.BlockGetter function=handle_continue/2 trace_id=7615059001162239816 ⋅Applied block: #2000, from eth height: 5426525 with 1 txs⋅
watcher-0 watcher 2019-11-12 05:38:47.957 [info] module=Phoenix.Logger function=phoenix_error_rendered/4 request_id=FdZTrlDD52OA4LEAAtyi trace_id=7662785271466693007 span_id=4075807591394983521 ⋅Converted error {:case_clause, {:error, :no_deposit_for_given_blknum}} to 500 response⋅
watcher-0 watcher 2019-11-12 05:38:47.960 [error] ⋅#PID<0.25874.6> running OMG.WatcherRPC.Web.Endpoint (cowboy_protocol) terminated
watcher-0 watcher Server: audit-e3c15df-watcher-rinkeby-01.omg.network:80 (http)
watcher-0 watcher Request: POST /in_flight_exit.get_data
watcher-0 watcher ** (exit) an exception was raised:
watcher-0 watcher     ** (CaseClauseError) no case clause matching: {:error, :no_deposit_for_given_blknum}
watcher-0 watcher         (omg_watcher) lib/omg_watcher/api/in_flight_exit.ex:102: OMG.Watcher.API.InFlightExit.find_single_input_data/2
watcher-0 watcher         (elixir) lib/enum.ex:3317: Enumerable.List.reduce/3
watcher-0 watcher         (elixir) lib/enum.ex:1990: Enum.reduce_while/3
watcher-0 watcher         (omg_watcher) lib/omg_watcher/api/in_flight_exit.ex:40: OMG.Watcher.API.InFlightExit.get_in_flight_exit/1
watcher-0 watcher         (omg_watcher_rpc) lib/web/controllers/in_flight_exit.ex:61: OMG.WatcherRPC.Web.Controller.InFlightExit.handle_txbytes_based_request/4
watcher-0 watcher         (omg_watcher_rpc) lib/web/controllers/in_flight_exit.ex:15: OMG.WatcherRPC.Web.Controller.InFlightExit.action/2
watcher-0 watcher         (omg_watcher_rpc) lib/web/controllers/in_flight_exit.ex:15: OMG.WatcherRPC.Web.Controller.InFlightExit.phoenix_controller_pipeline/2
watcher-0 watcher         (omg_watcher_rpc) lib/web/endpoint.ex:15: OMG.WatcherRPC.Web.Endpoint.instrument/4⋅
watcher-0 watcher 2019-11-12 05:40:43.935 [info] module=Phoenix.Logger function=phoenix_error_rendered/4 request_id=FdZTyVGg4yzpwkMABTGh ⋅Converted error Plug.Parsers.ParseError to 400 response⋅

[thec00n]

POST /in_flight_exit.get_data HTTP/1.1
Content-Type: application/json
host: XXX
Content-Length: 473
Connection: close

{"txbytes":"0xf8d7f843b84106c1ee0eab776eb3d7dfa37781063a749e28651bc63b15e176407e8fc4d0de6933965955aaac555e4bdbabd432bdd179e487eb2560ebfc9fc9d427b3d2e05e691c01c58477359400f868f30194ca3e399bead9718cb147beada70816726064c14594000000000000000000000000000000000000000087b1a2bc2ec50000f30194d42b31665b93c128541c8b89a0e545afb08b7dd894000000000000000000000000000000000000000087b1a2bc2ec4fff6a00000000000000000000000000000000000000000000000000000000000000000","jsonrpc":"2.0","id":0}

[thec00n]

HTTP/1.1 500 Internal Server Error
...

{"data":{"code":"server:internal_server_error","description":null,"object":"error"},"service_name":"watcher","success":false,"version":"0.3.0+fe94fbc"}

[InoMurko]

Logging and crashing is normal for elixir/erlang BEAM programs. In this case, only the request process died and was isolated crash. What needs to be done is:

• [ ] transform these exceptions into bad request responses, (or 404 not found - actually I think it's 200 and success: false)

  defp find_single_input_data(input_utxo_pos, {:ok, {proofs, txbyteses, utxo_positions}}) do
  input_utxo_pos
  |> API.Utxo.compose_utxo_exit()
  |> case do
    {:ok, %{proof: proof, txbytes: txbytes}} ->
      utxo_pos = Utxo.Position.encode(input_utxo_pos)
      {:cont, {:ok, {[proof | proofs], [txbytes | txbyteses], [utxo_pos | utxo_positions]}}}
  
    {:error, :utxo_not_found} ->
      {:halt, {:error, :tx_for_input_not_found}}
  end
  end

• [ ] tweak Sentry

[pdobacz]

Thanks! I just ran into this same thing during the Watcher exit load/perf testing too :(.

It is caused by an attempt to start an IFE using a spent deposit as an input. It is not what one normally would do, so the inability isn't hurting us terribly, but it definitely shouldn't crash and ideally should be made possible (for consistency, where IFEing from a spent non-deposit works just fine).

[InoMurko]

@pdobacz care to rename the issue to something that describes the problem appropriately?

[sentry-io[bot]]

Humans, I have a report in Sentry, that references this issue of yours!

Sentry issue: ELIXIR-OMG-21

[pdobacz]

Ay, I just realized there is a case for starting such an IFE, so I'll add some more priority to this. The use is where the IFE spends a spent deposit as one of its inputs and it is the other inputs that we're concerned about.

[pdobacz]

Here is an alice-bobbing scenario relevant:

(it is a variant of this)

1. Alice spends UTXO1a (not necessarily a deposit), Malory spends UTXO1m (a deposit) in TX1 to Bob, creating UTXO2.
2. TX1 is in-flight.
3. Mallory spends UTXO1m (that deposit) in TX2 to Mallory (a double spend)
4. TX2 is included
5. Alice should start an in-flight exit from TX1 to save her UTXO1a (Alice would later piggyback her input, the IFE would finalize non-canonical, Alice would get UTXO1a out)
6. This bug prevents Alice from (5.)

So the endpoint in question should give all the necessary start IFE data, despite the deposit UTXO1m having been spent.