search

omgnetwork / elixir-omg

OMG-Network repository of Watcher and Watcher Info
https://omg.network
Apache License 2.0
213 stars 59 forks source link

Error submitting transaction to childchain under high load #1377

Open kevsul opened 4 years ago

kevsul commented 4 years ago

Scenario: Stress test of many concurrent calls to childchain/transaction.submit

Blocks had large numbers of transactions: Transaction submitted successfully {3044000, 53587}

Client started receiving server:internal_server_error errors.

Datadog logs here: https://app.datadoghq.com/logs?cols=core_host%2Ccore_service&event&from_ts=1583403956200&index=main&live=false&messageDisplay=inline&query=host%3A%2Astress%2A+service%3Achild_chain&saved_view=80142&stream_sort=desc&to_ts=1583403956250

and here:

https://app.datadoghq.com/apm/resource/web/request/dc4f90c14057f19?end=1583403968575&env=stress-e043a92-ropsten-01&filteredType=web&graphType=span_list&index=apm-search&paused=true&start=1583403906564

pdobacz commented 4 years ago

Pasting the logs for search-ability and retention:

Seems like some transactions took longer than 5s to OMG.State.exec. Some ideas of possible causes to investigate:

Mar 05 11:25:56.248 | 2020-03-05 10:25:56.236 [info] module=Phoenix.Logger function=phoenix_error_rendered/4 request_id=FflhgSCXuXl66KUAkygj trace_id=4888462636568636814 span_id=88029475369324779 ⋅Converted exit {:timeout, {GenServer, :call, [OMG.State, {:exec, %OMG.State.Transaction.Recovered{signed_tx: %OMG.State.Transaction.Signed{raw_tx: %OMG.State.Transaction.Payment{inputs: [{:utxo_position, 3044000, 53311, 0}], metadata: <<0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0>>, outputs: [%OMG.Output{amount: 120, currency: <<0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0>>, output_type: 1, owner: <<207, 206, 254, 127, 249, 79, 209, 52, 105, 105, 240, 99, 172, 194, 113, 158, 191, 216, 124, 194>>}, %OMG.Output{amount: 1, currency: <<0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0>>, output_type: 1, owner: <<138, 232, 155, 238, 199, 10, 143, 67, 111, 48, 85, 173, 254, 158, 19, 94, 139, 111, 93, 175>>}], tx_type: 1}, sigs: [<<101, 43, 71, 20
-- | --
  | Mar 05 11:25:56.248 | Cannot send event because of invalid DSN⋅
  | Mar 05 11:25:56.248 | 2020-03-05 10:25:56.235 [warn] module=Sentry.Client function=log_api_error/1 request_id=FflhgSAf98I3sBoAkyej trace_id=6349860858977258254 span_id=917479095662894246 ⋅Failed to send Sentry event.
  | Mar 05 11:25:56.248 | 2020-03-05 10:25:56.231 [info] module=Phoenix.Logger function=phoenix_error_rendered/4 request_id=FflhgSAf98I3sBoAkyej trace_id=6349860858977258254 span_id=917479095662894246 ⋅Converted exit {:timeout, {GenServer, :call, [OMG.State, {:exec, %OMG.State.Transaction.Recovered{signed_tx: %OMG.State.Transaction.Signed{raw_tx: %OMG.State.Transaction.Payment{inputs: [{:utxo_position, 3044000, 53302, 0}], metadata: <<0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0>>, outputs: [%OMG.Output{amount: 168, currency: <<0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0>>, output_type: 1, owner: <<29, 144, 67, 20, 198, 120, 171, 27, 143, 82, 96, 235, 103, 229, 43, 117, 252, 116, 18, 72>>}, %OMG.Output{amount: 1, currency: <<0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0>>, output_type: 1, owner: <<83, 235, 58, 90, 227, 5, 173, 68, 86, 177, 97, 95, 112, 231, 69, 16, 243, 137, 168, 6>>}], tx_type: 1}, sigs: [<<57, 198, 139, 198, 134, 15
  | Mar 05 11:25:56.245 | Cannot send event because of invalid DSN⋅
  | Mar 05 11:25:56.245 | 2020-03-05 10:25:56.229 [warn] module=Sentry.Client function=log_api_error/1 request_id=FflhgSAE1eBgPW4Akydj trace_id=3702023171718390958 span_id=1510190461064108840 ⋅Failed to send Sentry event.
  | Mar 05 11:25:56.227 | 2020-03-05 10:25:56.225 [info] module=Phoenix.Logger function=phoenix_error_rendered/4 request_id=FflhgSBIKRJgKf0AkyfD trace_id=7088532813036963831 span_id=2468067455409908597 ⋅Converted exit {:timeout, {GenServer, :call, [OMG.State, {:exec, %OMG.State.Transaction.Recovered{signed_tx: %OMG.State.Transaction.Signed{raw_tx: %OMG.State.Transaction.Payment{inputs: [{:utxo_position, 3044000, 53312, 0}], metadata: <<0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0>>, outputs: [%OMG.Output{amount: 150, currency: <<0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0>>, output_type: 1, owner: <<37, 133, 77, 146, 212, 131, 146, 77, 152, 182, 238, 218, 152, 33, 191, 158, 233, 30, 240, 99>>}, %OMG.Output{amount: 1, currency: <<0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0>>, output_type: 1, owner: <<175, 163, 14, 105, 5, 162, 81, 241, 37, 162, 25, 138, 123, 213, 183, 206, 91, 211, 84, 101>>}], tx_type: 1}, sigs: [<<13, 175, 28, 68,
  | Mar 05 11:25:56.226 | 2020-03-05 10:25:56.224 [info] module=Phoenix.Logger function=phoenix_error_rendered/4 request_id=FflhgSAE1eBgPW4Akydj trace_id=3702023171718390958 span_id=1510190461064108840 ⋅Converted exit {:timeout, {GenServer, :call, [OMG.State, {:exec, %OMG.State.Transaction.Recovered{signed_tx: %OMG.State.Transaction.Signed{raw_tx: %OMG.State.Transaction.Payment{inputs: [{:utxo_position, 3044000, 53300, 1}], metadata: <<0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0>>, outputs: [%OMG.Output{amount: 198, currency: <<0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0>>, output_type: 1, owner: <<21, 74, 137, 231, 199, 226, 213, 149, 40, 27, 41, 98, 237, 224, 70, 137, 238, 198, 7, 150>>}, %OMG.Output{amount: 1, currency: <<0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0>>, output_type: 1, owner: <<133, 49, 103, 19, 101, 186, 126, 89, 163, 91, 122, 152, 181, 39, 72, 255, 3, 13, 20, 9>>}], tx_type: 1}, sigs: [<<84, 64, 228, 58, 186, 14
  | Mar 05 11:25:56.223 | ** (EXIT) time out⋅
  | Mar 05 11:25:56.223 | ** (exit) exited in: GenServer.call(OMG.State, {:exec, %OMG.State.Transaction.Recovered{signed_tx: %OMG.State.Transaction.Signed{raw_tx: %OMG.State.Transaction.Payment{inputs: [{:utxo_position, 3044000, 53304, 0}], metadata: <<0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0>>, outputs: [%OMG.Output{amount: 122, currency: <<0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0>>, output_type: 1, owner: <<126, 134, 66, 206, 5, 221, 136, 22, 89, 82, 93, 84, 81, 172, 147, 199, 41, 200, 235, 132>>}, %OMG.Output{amount: 1, currency: <<0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0>>, output_type: 1, owner: <<28, 149, 19, 1, 58, 115, 21, 2, 206, 201, 206, 189, 79, 180, 99, 212, 164, 40, 247, 42>>}], tx_type: 1}, sigs: [<<85, 160, 133, 71, 67, 209, 173, 151, 211, 150, 207, 123, 224, 51, 237, 222, 85, 130, 254, 39, 199, 175, 20, 20, 39, 195, 15, 112, 249, 225, 97, 246, 116, 176, 249, 212, 72, 40, 10, 141, 153, 188, 95, 233, ...>>]}
  | Mar 05 11:25:56.223 | Request: POST /transaction.submit
  | Mar 05 11:25:56.223 | 2020-03-05 10:25:56.220 [error] ⋅#PID<0.16231.8> running OMG.ChildChainRPC.Web.Endpoint (cowboy_protocol) terminated
  | Mar 05 11:25:56.223 | Cannot send event because of invalid DSN⋅
  | Mar 05 11:25:56.223 | 2020-03-05 10:25:56.219 [warn] module=Sentry.Client function=log_api_error/1 request_id=FflhgR_JFVB9iNkAlyai trace_id=7157303536525189353 span_id=8041295377219949982 ⋅Failed to send Sentry event.
  | Mar 05 11:25:56.223 | ** (EXIT) time out⋅
  | Mar 05 11:25:56.223 | ** (exit) exited in: GenServer.call(OMG.State, {:exec, %OMG.State.Transaction.Recovered{signed_tx: %OMG.State.Transaction.Signed{raw_tx: %OMG.State.Transaction.Payment{inputs: [{:utxo_position, 3044000, 53306, 0}], metadata: <<0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0>>, outputs: [%OMG.Output{amount: 188, currency: <<0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0>>, output_type: 1, owner: <<142, 234, 43, 76, 49, 123, 198, 66, 63, 37, 188, 25, 78, 172, 252, 188, 244, 89, 2, 191>>}, %OMG.Output{amount: 1, currency: <<0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0>>, output_type: 1, owner: <<8, 56, 42, 94, 192, 144, 220, 165, 213, 97, 63, 50, 182, 63, 109, 178, 87, 49, 54, 68>>}], tx_type: 1}, sigs: [<<248, 167, 129, 134, 21, 184, 36, 170, 19, 172, 231, 26, 72, 103, 117, 121, 80, 197, 178, 164, 176, 247, 160, 196, 108, 174, 19, 117, 145, 226, 69, 150, 21, 129, 168, 8, 17, 25, 166, 171, 187, 218, 250, 171, ...>>]}
  | Mar 05 11:25:56.222 | Request: POST /transaction.submit
  | Mar 05 11:25:56.222 | 2020-03-05 10:25:56.219 [error] ⋅#PID<0.15870.8> running OMG.ChildChainRPC.Web.Endpoint (cowboy_protocol) terminated
  | Mar 05 11:25:56.221 | Cannot send event because of invalid DSN⋅
  | Mar 05 11:25:56.221 | 2020-03-05 10:25:56.217 [warn] module=Sentry.Client function=log_api_error/1 request_id=FflhgR-WI1Kz59UAiq5k trace_id=9188405520032886398 span_id=719425006149323918 ⋅Failed to send Sentry event.
  | Mar 05 11:25:56.216 | 2020-03-05 10:25:56.215 [info] module=Phoenix.Logger function=phoenix_error_rendered/4 request_id=FflhgR_JFVB9iNkAlyai trace_id=7157303536525189353 span_id=8041295377219949982 ⋅Converted exit {:timeout, {GenServer, :call, [OMG.State, {:exec, %OMG.State.Transaction.Recovered{signed_tx: %OMG.State.Transaction.Signed{raw_tx: %OMG.State.Transaction.Payment{inputs: [{:utxo_position, 3044000, 53304, 0}], metadata: <<0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0>>, outputs: [%OMG.Output{amount: 122, currency: <<0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0>>, output_type: 1, owner: <<126, 134, 66, 206, 5, 221, 136, 22, 89, 82, 93, 84, 81, 172, 147, 199, 41, 200, 235, 132>>}, %OMG.Output{amount: 1, currency: <<0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0>>, output_type: 1, owner: <<28, 149, 19, 1, 58, 115, 21, 2, 206, 201, 206, 189, 79, 180, 99, 212, 164, 40, 247, 42>>}], tx_type: 1}, sigs: [<<85, 160, 133, 71, 67, 209
  | Mar 05 11:25:56.212 | 2020-03-05 10:25:56.210 [info] module=Phoenix.Logger function=phoenix_error_rendered/4 request_id=FflhgR-WI1Kz59UAiq5k trace_id=9188405520032886398 span_id=719425006149323918 ⋅Converted exit {:timeout, {GenServer, :call, [OMG.State, {:exec, %OMG.State.Transaction.Recovered{signed_tx: %OMG.State.Transaction.Signed{raw_tx: %OMG.State.Transaction.Payment{inputs: [{:utxo_position, 3044000, 53306, 0}], metadata: <<0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0>>, outputs: [%OMG.Output{amount: 188, currency: <<0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0>>, output_type: 1, owner: <<142, 234, 43, 76, 49, 123, 198, 66, 63, 37, 188, 25, 78, 172, 252, 188, 244, 89, 2, 191>>}, %OMG.Output{amount: 1, currency: <<0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0>>, output_type: 1, owner: <<8, 56, 42, 94, 192, 144, 220, 165, 213, 97, 63, 50, 182, 63, 109, 178, 87, 49, 54, 68>>}], tx_type: 1}, sigs: [<<248, 167, 129, 134, 21, 184,
jrhite commented 4 years ago

Here is the data view I saved.

https://app.datadoghq.com/logs/patterns?cols=service%2Chost%2C%40env&from_ts=1583403855601&index=main&live=false&messageDisplay=inline&query=host%3A%2Astress%2A+-service%3Ablockexplorer&saved_view=82904&stream_sort=desc&to_ts=1583404060347

For CC, I don't see any problems outside itself and Elixir runtime errors, CPU usage and mem usage looked ok.

For watcher-info, the gce-proxy shows dropped connections would might explain the watcher-info issues.