V5-pre1: State Channels FSM entered unknown state

Hi! On our tests for a payment hub application over SC. We tested:

js-sdk v4.6.0 (with fixes from https://github.com/aeternity/aepp-sdk-js/issues/657 ) and node v5.0.0-pre1 connected to #testnet.

-Node just deployed connected to testnet, synced.

Hub & client spawned: Error: State Channels FSM entered unknown state:

Hub (responder) log:

[Nest] 21348   - 09/11/2019, 9:47 PM   [Channel] Server: ak_2irGVQoj1U4YqHQfBWJSdb7xrML1rPSJoDC7pAiimkBPLX1q4t balance: 9999999999999999988
[Nest] 21348   - 09/11/2019, 9:51 PM   [merchant] ak_25VJ5qBunt1D|init:ak_25VJ5qBunt1D5jCs2rxHciRjuPAUqRRsjzQt9ey7zK4Yw4Vs1h
[Nest] 21348   - 09/11/2019, 9:51 PM   [merchant] ak_25VJ5qBunt1D|resp:ak_2irGVQoj1U4YqHQfBWJSdb7xrML1rPSJoDC7pAiimkBPLX1q4t
[Nest] 21348   - 09/11/2019, 9:51 PM   [merchant] ak_25VJ5qBunt1D|opts:{"responderId":"ak_2irGVQoj1U4YqHQfBWJSdb7xrML1rPSJoDC7pAiimkBPLX1q4t","pushAmount":0,"responderAmount":1,"channelReserve":1,"host":"localhost","port":3001,"lockPeriod":1,"url":"wss://aehub2.coinfabrik.com/channel","initiatorAmount":"1000000000000000","role":"responder","initiatorId":"ak_25VJ5qBunt1D5jCs2rxHciRjuPAUqRRsjzQt9ey7zK4Yw4Vs1h"}
1 wss://aehub2.coinfabrik.com/channel
[Nest] 21348   - 09/11/2019, 9:51 PM   [Channel] client:{"responderId":"ak_2irGVQoj1U4YqHQfBWJSdb7xrML1rPSJoDC7pAiimkBPLX1q4t","pushAmount":0,"responderAmount":1,"channelReserve":1,"host":"localhost","port":3001,"lockPeriod":1,"initiatorId":"ak_25VJ5qBunt1D5jCs2rxHciRjuPAUqRRsjzQt9ey7zK4Yw4Vs1h","initiatorAmount":"1000000000000000","url":"wss://aehub2.coinfabrik.com/channel","role":"initiator"}
[Nest] 21348   - 09/11/2019, 9:51 PM   [merchant] ak_25VJ5qBunt1D|[CONNECTED]
[Nest] 21348   - 09/11/2019, 9:51 PM   [merchant] ak_25VJ5qBunt1D|[HALFSIGNED]
[Nest] 21348   - 09/11/2019, 9:51 PM   [merchant] ak_25VJ5qBunt1D|
[Nest] 21348   - 09/11/2019, 9:51 PM   [merchant] ak_25VJ5qBunt1D|tag: responder_sign tx_+HwyAaEBjeLjHR1XTABqrJDIV9M5ILajZ8AaGh6ObKpM1niSWCeHA41+pMaAAKEB4rho5jrPiwlzeNU+7mEi/XxgcdCQEQbXLgPJ7/Am2LcBAQEAhg/vMWBgAMCg1P3BXKlDTQmGglXay4jtb7yanzo6tCo45TofI+fJbAcJrxRn8Q==
[Nest] 21348   - 09/11/2019, 9:51 PM   [merchant] ak_25VJ5qBunt1D|tag: responder_sign/undefined: {"tag":"50","VSN":"1","initiator":"ak_25VJ5qBunt1D5jCs2rxHciRjuPAUqRRsjzQt9ey7zK4Yw4Vs1h","initiatorAmount":"1000000000000000","responder":"ak_2irGVQoj1U4YqHQfBWJSdb7xrML1rPSJoDC7pAiimkBPLX1q4t","responderAmount":"1","channelReserve":"1","lockPeriod":"1","ttl":"0","fee":"17520000000000","delegateIds":"","stateHash":"st_1P3BXKlDTQmGglXay4jtb7yanzo6tCo45TofI+fJbAe7HlZb","nonce":"9"}
[Nest] 21348   - 09/11/2019, 9:51 PM   [merchant] ak_25VJ5qBunt1D|responder_sign - signed: tx_+MYLAfhCuEAu/j+PZF7NNR32iPB0rMhs77Idu5h8wEZR1zkxhlUemKyK/Pn/ZNe0+OJ//M1m4XW8lX/Tcyo/FScRG7costMBuH74fDIBoQGN4uMdHVdMAGqskMhX0zkgtqNnwBoaHo5sqkzWeJJYJ4cDjX6kxoAAoQHiuGjmOs+LCXN41T7uYSL9fGBx0JARBtcuA8nv8CbYtwEBAQCGD+8xYGAAwKDU/cFcqUNNCYaCVdrLiO1vvJqfOjq0KjjlOh8j58lsBwlmRgGW
(node:21348) UnhandledPromiseRejectionWarning: Error: State Channels FSM entered unknown state
    at Fu (/home/coinfabrik/hubv5/node_modules/@aeternity/aepp-sdk/dist/webpack:/Ae/es/channel/internal.js:53:34)
    at /home/coinfabrik/hubv5/node_modules/@aeternity/aepp-sdk/dist/webpack:/Ae/es/channel/internal.js:111:1
    at arg (/home/coinfabrik/hubv5/node_modules/@aeternity/aepp-sdk/dist/webpack:/Ae/node_modules/regenerator-runtime/runtime.js:293:32)
    at Generator.arg [as _invoke] (/home/coinfabrik/hubv5/node_modules/@aeternity/aepp-sdk/dist/webpack:/Ae/node_modules/regenerator-runtime/runtime.js:263:45)
    at Generator.forEach.t.<computed> [as next] (/home/coinfabrik/hubv5/node_modules/@aeternity/aepp-sdk/dist/webpack:/Ae/node_modules/regenerator-runtime/runtime.js:95:14)
    at key (/home/coinfabrik/hubv5/node_modules/@aeternity/aepp-sdk/dist/webpack:/Ae/node_modules/@babel/runtime/helpers/defineProperty.js:10:9)
    at c (/home/coinfabrik/hubv5/node_modules/@aeternity/aepp-sdk/dist/webpack:/Ae/node_modules/@babel/runtime/helpers/asyncToGenerator.js:21:5)
    at processTicksAndRejections (internal/process/task_queues.js:85:5)
(node:21348) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). (rejection id: 2)
(node:21348) [DEP0018] DeprecationWarning: Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the Node.js process with a non-zero exit code.
[Nest] 21348   - 09/11/2019, 9:57 PM   [merchant] ak_25VJ5qBunt1D|[DISCONNECTED]

client (initiator) log:

[email protected]:~/hubv5$ AENODE=https://aehub2.coinfabrik.com HUB=localhost HUBPORT=3005 node tools/merchtest3b.js tools/merchantx
hub>   localhost
node>  https://aehub2.coinfabrik.com
{ 
  hostname: 'localhost',
  port: 3005,
  path: "/merchant/ak_25VJ5qBunt1D5jCs2rxHciRjuPAUqRRsjzQt9ey7zK4Yw4Vs1h/1000000000000000/dave's%20beer"
}
 we:  ak_25VJ5qBunt1D5jCs2rxHciRjuPAUqRRsjzQt9ey7zK4Yw4Vs1h
{ 
  responderId: 'ak_2irGVQoj1U4YqHQfBWJSdb7xrML1rPSJoDC7pAiimkBPLX1q4t',
  pushAmount: 0,
  responderAmount: 1,
  channelReserve: 1,
  host: 'localhost',
  port: 3001,
  lockPeriod: 1,
  initiatorId: 'ak_25VJ5qBunt1D5jCs2rxHciRjuPAUqRRsjzQt9ey7zK4Yw4Vs1h',
  initiatorAmount: '1000000000000000',
  url: 'wss://aehub2.coinfabrik.com/channel',
  role: 'initiator'
}
[CONNECTED]
[ACCEPTED]
initiator_sign tx_+HwyAaEBjeLjHR1XTABqrJDIV9M5ILajZ8AaGh6ObKpM1niSWCeHA41+pMaAAKEB4rho5jrPiwlzeNU+7mEi/XxgcdCQEQbXLgPJ7/Am2LcBAQEAhg/vMWBgAMCg1P3BXKlDTQmGglXay4jtb7yanzo6tCo45TofI+fJbAcJrxRn8Q==
[SIGNED]
(node:22347) UnhandledPromiseRejectionWarning: Error: State Channels FSM entered unknown state
    at Fu (/home/coinfabrik/hubv5/node_modules/@aeternity/aepp-sdk/dist/aepp-sdk.js:1:189641)
    at /home/coinfabrik/hubv5/node_modules/@aeternity/aepp-sdk/dist/aepp-sdk.js:1:190913
    at u (/home/coinfabrik/hubv5/node_modules/@aeternity/aepp-sdk/dist/aepp-sdk.js:1:16546)
    at Generator._invoke (/home/coinfabrik/hubv5/node_modules/@aeternity/aepp-sdk/dist/aepp-sdk.js:1:16334)
    at Generator.forEach.t.<computed> [as next] (/home/coinfabrik/hubv5/node_modules/@aeternity/aepp-sdk/dist/aepp-sdk.js:1:16969)
    at n (/home/coinfabrik/hubv5/node_modules/@aeternity/aepp-sdk/dist/aepp-sdk.js:1:2195)
    at c (/home/coinfabrik/hubv5/node_modules/@aeternity/aepp-sdk/dist/aepp-sdk.js:1:2406)
    at processTicksAndRejections (internal/process/task_queues.js:85:5)
(node:22347) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). (rejection id: 1)
(node:22347) [DEP0018] DeprecationWarning: Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the Node.js process with a non-zero exit code.
[DISCONNECTED]
switching to disconnected...
  • node log console at DISCONNECTED point:
21:53:59.365 [info] Starting new sync task #Ref<0.2056165025.2213281793.225708> target is #{hash => <<51,152,195,114,5,13,198,219,36,213,237,146,66,126,200,92,184,255,244,99,36,1,216,200,104,71,198,106,246,170,250,112>>,height => 137777}
21:53:59.760 [info] Couldn't insert received block ({illegal_orphan,<<229,167,101,141,44,243,10,244,44,9,238,83,166,240,203,42,82,195,11,227,249,156,161,42,174,126,76,235,53,126,24,236>>})
21:53:59.761 [info] Sync done (according to "pp_ncxEXhZ...gTKAi6k")
21:54:00.442 [info] Synced blocks 137776 - 137777
21:54:00.827 [info] Removing/ending sync task #Ref<0.2056165025.2213281793.225708> target was #{hash => <<51,152,195,114,5,13,198,219,36,213,237,146,66,126,200,92,184,255,244,99,36,1,216,200,104,71,198,106,246,170,250,112>>,height => 137777}
21:54:00.828 [info] Sync done (according to "pp_2Kkcknw...ZWqLVKn")
21:57:49.227 [error] gen_statem <0.7913.0> in state awaiting_locked terminated with reason: no function clause matching aesc_fsm:handle_recoverable_error/2 line 2705
21:57:49.227 [error] CRASH REPORT Process <0.7913.0> with 1 neighbours crashed with reason: no function clause matching aesc_fsm:handle_recoverable_error/2 line 2705
21:57:49.227 [error] Supervisor aesc_fsm_sup had child aesc_fsm started with {aesc_fsm,start_link,undefined} at <0.7913.0> exit with reason no function clause matching aesc_fsm:handle_recoverable_error/2 line 2705 in context child_terminated
21:57:49.242 [error] gen_statem <0.7930.0> in state awaiting_locked terminated with reason: no function clause matching aesc_offchain_state:fallback_to_stable_state({state,{trees,{mpt,<<5,85,188,121,113,29,165,38,177,140,219,108,64,240,37,22,159,113,174,230,24,...>>,...},...},...}) line 340
21:57:49.243 [error] CRASH REPORT Process <0.7930.0> with 1 neighbours crashed with reason: no function clause matching aesc_offchain_state:fallback_to_stable_state({state,{trees,{mpt,<<5,85,188,121,113,29,165,38,177,140,219,108,64,240,37,22,159,113,174,230,24,...>>,...},...},...}) line 340
21:57:49.243 [error] Supervisor aesc_fsm_sup had child aesc_fsm started with {aesc_fsm,start_link,undefined} at <0.7930.0> exit with reason no function clause matching aesc_offchain_state:fallback_to_stable_state({state,{trees,{mpt,<<5,85,188,121,113,29,165,38,177,140,219,108,64,240,37,22,159,113,174,230,24,...>>,...},...},...}) line 340 in context child_terminated
22:03:17.167 [info] Missing txs: [<<99,80,110,90,65,154,204,160,88,146,9,140,227,0,118,19,145,26,177,62,15,94,151,72,137,100,250,116,110,202,128,251>>]
22:03:17.198 [info] Assembled new block: <<84,58,163,172,...,162,123,143,168>>
22:03:37.294 [info] Missing txs: [<<51,219,130,35,50,143,3,102,234,122,179,188,201,37,168,110,216,208,228,150,104,168,79,215,9,58,17,101,139,20,125,230>>]
22:03:37.324 [info] Assembled new block: <<219,145,48,11,...,99,163,90,241>>

Full node log: https://drive.google.com/file/d/1BJi97M9c6Eu9oYHklLzz4HSETcvO7UDV/view?usp=sharing mainly:

2019-09-11 21:57:49.221 [debug] <0.7913.0>@aesc_fsm:awaiting_locked:529 Unexpected timeout: Msg = awaiting_locked, Op = {op_min_depth,funding,<<176,69,217,188,244,71,14,164,140,153,10,127,230,163,75,205,224,143,72,94,38,236,231,168,167,237,132,105,26,27,238,208>>,{op_data,{signed_tx,{aetx,channel_create_tx,aesc_create_tx,126,{channel_create_tx,{id,account,<<141,226,227,29,29,87,76,0,106,172,144,200,87,211,57,32,182,163,103,192,26,26,30,142,108,170,76,214,120,146,88,39>>},1000000000000000,{id,account,<<226,184,104,230,58,207,139,9,115,120,213,62,238,97,34,253,124,96,113,208,144,17,6,215,46,3,201,239,240,38,216,183>>},1,1,1,0,17520000000000,[],<<212,253,193,92,169,67,77,9,134,130,85,218,203,136,237,111,188,154,159,58,58,180,42,56,229,58,31,35,231,201,108,7>>,9}},[<<65,88,245,253,57,229,179,76,24,180,178,65,240,40,241,163,230,172,215,115,30,195,249,60,44,130,128,143,200,158,78,61,116,166,248,200,5,35,42,68,197,87,207,96,72,70,172,5,10,176,180,64,179,65,133,73,151,92,184,46,116,236,50,8>>,<<46,254,63,143,100,94,205,53,29,246,136,240,116,172,200,108,239,178,29,187,152,124,192,70,81,215,57,49,134,85,30,152,172,138,252,249,255,100,215,180,248,226,127,252,205,102,225,117,188,149,127,211,115,42,63,21,39,17,27,183,40,178,211,1>>]},[],<<36,76,94,195,48,58,84,9,116,174,190,81,138,187,247,185,32,253,39,76,73,201,73,154,24,61,245,228,202,223,194,175>>}}
2019-09-11 21:57:49.222 [debug] <0.7913.0>@aesc_fsm:handle_common_event:4271 handle_common_event(timeout, awaiting_locked, awaiting_locked, error, D)
2019-09-11 21:57:49.222 [debug] <0.7913.0>@aesc_fsm:handle_common_event_:4275 timeout (awaiting_locked) - recovering (update_error)
2019-09-11 21:57:49.222 [debug] <0.7913.0>@aesc_fsm:handle_recoverable_error:2700 ErrorInfo = #{code => 3}
2019-09-11 21:57:49.222 [debug] <0.7913.0>@aesc_fsm:handle_recoverable_error:2704 CAUGHT function_clause
2019-09-11 21:57:49.222 [debug] <0.7913.0>@aesc_fsm:terminate:3501 terminate(function_clause, awaiting_locked, _)
2019-09-11 21:57:49.222 [debug] <0.7913.0>@aesc_fsm:report_info:3029 responder report_info(true, Client = <0.7911.0>, Msg = #{channel_id => <<125,101,32,238,127,123,143,255,6,216,240,32,236,229,213,14,188,5,59,175,194,234,41,151,247,96,93,195,125,24,146,123>>,info => {died,function_clause},tag => info,type => report})
2019-09-11 21:57:49.224 [debug] <0.7913.0>@aesc_fsm:report_info:3033 responder report_info(false, #{info => {log,[{snd,funding_created,{1568,238709,217183},#{block_hash => <<36,76,94,195,48,58,84,9,116,174,190,81,138,187,247,185,32,253,39,76,73,201,73,154,24,61,245,228,202,223,194,175>>,data => #{tx => <<249,1,8,11,1,248,132,184,64,46,254,63,143,100,94,205,53,29,246,136,240,116,172,200,108,239,178,29,187,152,124,192,70,81,215,57,49,134,85,30,152,172,138,252,249,255,100,215,180,248,226,127,252,205,102,225,117,188,149,127,211,115,42,63,21,39,17,27,183,40,178,211,1,184,64,65,88,245,253,57,229,179,76,24,180,178,65,240,40,241,163,230,172,215,115,30,195,249,60,44,130,128,143,200,158,78,61,116,166,248,200,5,35,42,68,197,87,207,96,72,70,172,5,10,176,180,64,179,65,133,73,151,92,184,46,116,236,50,8,184,126,248,124,50,1,161,1,141,226,227,29,29,87,76,0,106,172,144,200,87,211,57,32,182,163,103,192,26,26,30,142,108,170,76,214,120,146,88,39,135,3,141,126,164,198,128,0,161,1,226,184,104,230,58,207,139,9,115,120,213,62,238,97,34,253,124,96,113,208,144,17,6,215,46,3,201,239,240,38,216,183,1,1,1,0,134,15,239,49,96,96,0,192,160,212,253,193,92,169,67,77,9,134,130,85,218,203,136,237,111,188,154,159,58,58,180,42,56,229,58,31,35,231,201,108,7,9>>},temporary_channel_id => <<35,48,24,201,215,174,140,100,253,164,11,171,166,222,166,135,216,118,233,105,220,43,31,154,92,215,231,194,227,30,39,104>>}},{rcv,signed,{1568,238709,216753},{signed,funding_created,{signed_tx,{aetx,channel_create_tx,aesc_create_tx,126,{channel_create_tx,{id,account,<<141,226,227,29,29,87,76,0,106,172,144,200,87,211,57,32,182,163,103,192,26,26,30,142,108,170,76,214,120,146,88,39>>},1000000000000000,{id,account,<<226,184,104,230,58,207,139,9,115,120,213,62,238,97,34,253,124,96,113,208,144,17,6,215,46,3,201,239,240,38,216,183>>},1,1,1,0,17520000000000,[],<<212,253,193,92,169,67,77,9,134,130,85,218,203,136,237,111,188,154,159,58,58,180,42,56,229,58,31,35,231,201,108,7>>,9}},[<<65,88,245,253,57,229,179,76,24,180,178,65,240,40,241,163,230,172,215,115,30,195,249,60,44,130,128,143,200,158,78,61,116,166,248,200,5,35,42,68,197,87,207,96,72,70,172,5,10,176,180,64,179,65,133,73,151,92,184,46,116,236,50,8>>,<<46,254,63,143,100,94,205,53,29,246,136,240,116,172,200,108,239,178,29,187,152,124,192,70,81,215,57,49,134,85,30,152,172,138,252,249,255,100,215,180,248,226,127,252,205,102,225,117,188,149,127,211,115,42,63,21,39,17,27,183,40,178,211,1>>]}}},{req,sign,{1568,238709,154169},#{info => #{signed_tx => {signed_tx,{aetx,channel_create_tx,aesc_create_tx,126,{channel_create_tx,{id,account,<<141,226,227,29,29,87,76,0,106,172,144,200,87,211,57,32,182,163,103,192,26,26,30,142,108,170,76,214,120,146,88,39>>},1000000000000000,{id,account,<<226,184,104,230,58,207,139,9,115,120,213,62,238,97,34,253,124,96,113,208,144,17,6,215,46,3,201,239,240,38,216,183>>},1,1,1,0,17520000000000,[],<<212,253,193,92,169,67,77,9,134,130,85,218,203,136,237,111,188,154,159,58,58,180,42,56,229,58,31,35,231,201,108,7>>,9}},[<<65,88,245,253,57,229,179,76,24,180,178,65,240,40,241,163,230,172,215,115,30,195,249,60,44,130,128,143,200,158,78,61,116,166,248,200,5,35,42,68,197,87,207,96,72,70,172,5,10,176,180,64,179,65,133,73,151,92,184,46,116,236,50,8>>]},updates => []},tag => funding_created,type => sign}},{rcv,funding_created,{1568,238709,153533},#{block_hash => <<36,76,94,195,48,58,84,9,116,174,190,81,138,187,247,185,32,253,39,76,73,201,73,154,24,61,245,228,202,223,194,175>>,data => #{tx => <<248,198,11,1,248,66,184,64,65,88,245,253,57,229,179,76,24,180,178,65,240,40,241,163,230,172,215,115,30,195,249,60,44,130,128,143,200,158,78,61,116,166,248,200,5,35,42,68,197,87,207,96,72,70,172,5,10,176,180,64,179,65,133,73,151,92,184,46,116,236,50,8,184,126,248,124,50,1,161,1,141,226,227,29,29,87,76,0,106,172,144,200,87,211,57,32,182,163,103,192,26,26,30,142,108,170,76,214,120,146,88,39,135,3,141,126,164,198,128,0,161,1,226,184,104,230,58,207,139,9,115,120,213,62,238,97,34,253,124,96,113,208,144,17,6,215,46,3,201,239,240,38,216,183,1,1,1,0,134,15,239,49,96,96,0,192,160,212,253,193,92,169,67,77,9,134,130,85,218,203,136,237,111,188,154,159,58,58,180,42,56,229,58,31,35,231,201,108,7,...>>,...},...}},...]},...})
2019-09-11 21:57:49.224 [debug] <0.7913.0>@aesc_session_noise:call:412 Call to noise session <0.7914.0>: close
2019-09-11 21:57:49.225 [debug] <0.7914.0>@aesc_session_noise:handle_call:280 got close request
2019-09-11 21:57:49.225 [debug] <0.7911.0>@sc_ws_handler:set_channel_id:183 Msg=#{channel_id => <<125,101,32,238,127,123,143,255,6,216,240,32,236,229,213,14,188,5,59,175,194,234,41,151,247,96,93,195,125,24,146,123>>,info => {died,function_clause},tag => info,type => report} (Id0=undefined) -> <<125,101,32,238,127,123,143,255,6,216,240,32,236,229,213,14,188,5,59,175,194,234,41,151,247,96,93,195,125,24,146,123>>
2019-09-11 21:57:49.226 [debug] <0.7911.0>@sc_ws_handler:terminate:202 WebSocket dying because of stop
2019-09-11 21:57:49.227 [error] <0.7913.0>@aesc_fsm:handle_recoverable_error:2705 gen_statem <0.7913.0> in state awaiting_locked terminated with reason: no function clause matching aesc_fsm:handle_recoverable_error/2 line 2705
2019-09-11 21:57:49.227 [error] <0.7913.0>@aesc_fsm:handle_recoverable_error:2705 CRASH REPORT Process <0.7913.0> with 1 neighbours crashed with reason: no function clause matching aesc_fsm:handle_recoverable_error/2 line 2705
2019-09-11 21:57:49.227 [error] <0.1394.0>@aesc_fsm:handle_recoverable_error:2705 Supervisor aesc_fsm_sup had child aesc_fsm started with {aesc_fsm,start_link,undefined} at <0.7913.0> exit with reason no function clause matching aesc_fsm:handle_recoverable_error/2 line 2705 in context child_terminated
2019-09-11 21:57:49.232 [debug] <0.7931.0>@aesc_fsm:connection_died:170 connection to participant died(<0.7930.0>)
2019-09-11 21:57:49.233 [debug] <0.7930.0>@aesc_fsm:awaiting_locked:529 Unexpected cast: Msg = disconnect, Op = {op_min_depth,funding,<<176,69,217,188,244,71,14,164,140,153,10,127,230,163,75,205,224,143,72,94,38,236,231,168,167,237,132,105,26,27,238,208>>,{op_data,{signed_tx,{aetx,channel_create_tx,aesc_create_tx,126,{channel_create_tx,{id,account,<<141,226,227,29,29,87,76,0,106,172,144,200,87,211,57,32,182,163,103,192,26,26,30,142,108,170,76,214,120,146,88,39>>},1000000000000000,{id,account,<<226,184,104,230,58,207,139,9,115,120,213,62,238,97,34,253,124,96,113,208,144,17,6,215,46,3,201,239,240,38,216,183>>},1,1,1,0,17520000000000,[],<<212,253,193,92,169,67,77,9,134,130,85,218,203,136,237,111,188,154,159,58,58,180,42,56,229,58,31,35,231,201,108,7>>,9}},[<<46,254,63,143,100,94,205,53,29,246,136,240,116,172,200,108,239,178,29,187,152,124,192,70,81,215,57,49,134,85,30,152,172,138,252,249,255,100,215,180,248,226,127,252,205,102,225,117,188,149,127,211,115,42,63,21,39,17,27,183,40,178,211,1>>,<<65,88,245,253,57,229,179,76,24,180,178,65,240,40,241,163,230,172,215,115,30,195,249,60,44,130,128,143,200,158,78,61,116,166,248,200,5,35,42,68,197,87,207,96,72,70,172,5,10,176,180,64,179,65,133,73,151,92,184,46,116,236,50,8>>]},[],<<36,76,94,195,48,58,84,9,116,174,190,81,138,187,247,185,32,253,39,76,73,201,73,154,24,61,245,228,202,223,194,175>>}}
2019-09-11 21:57:49.233 [debug] <0.7930.0>@aesc_fsm:handle_common_event:4271 handle_common_event(cast, disconnect, awaiting_locked, error, D)
2019-09-11 21:57:49.233 [debug] <0.7930.0>@aesc_fsm:report_info:3029 initiator report_info(true, Client = <0.7928.0>, Msg = #{channel_id => <<125,101,32,238,127,123,143,255,6,216,240,32,236,229,213,14,188,5,59,175,194,234,41,151,247,96,93,195,125,24,146,123>>,info => peer_disconnected,tag => info,type => report})
2019-09-11 21:57:49.234 [debug] <0.7928.0>@sc_ws_handler:set_channel_id:183 Msg=#{channel_id => <<125,101,32,238,127,123,143,255,6,216,240,32,236,229,213,14,188,5,59,175,194,234,41,151,247,96,93,195,125,24,146,123>>,info => peer_disconnected,tag => info,type => report} (Id0=undefined) -> <<125,101,32,238,127,123,143,255,6,216,240,32,236,229,213,14,188,5,59,175,194,234,41,151,247,96,93,195,125,24,146,123>>
2019-09-11 21:57:49.234 [debug] <0.7930.0>@aesc_fsm:terminate:3501 terminate(function_clause, awaiting_locked, _)
2019-09-11 21:57:49.234 [debug] <0.7930.0>@aesc_fsm:report_info:3029 initiator report_info(true, Client = <0.7928.0>, Msg = #{channel_id => <<125,101,32,238,127,123,143,255,6,216,240,32,236,229,213,14,188,5,59,175,194,234,41,151,247,96,93,195,125,24,146,123>>,info => {died,function_clause},tag => info,type => report})
2019-09-11 21:57:49.239 [debug] <0.7928.0>@sc_ws_handler:set_channel_id:183 Msg=#{channel_id => <<125,101,32,238,127,123,143,255,6,216,240,32,236,229,213,14,188,5,59,175,194,234,41,151,247,96,93,195,125,24,146,123>>,info => {died,function_clause},tag => info,type => report} (Id0=<<125,101,32,238,127,123,143,255,6,216,240,32,236,229,213,14,188,5,59,175,194,234,41,151,247,96,93,195,125,24,146,123>>) -> <<125,101,32,238,127,123,143,255,6,216,240,32,236,229,213,14,188,5,59,175,194,234,41,151,247,96,93,195,125,24,146,123>>
2019-09-11 21:57:49.241 [debug] <0.7930.0>@aesc_fsm:report_info:3033 initiator report_info(false, #{info => {log,[{rcv,funding_signed,{1568,238709,220531},#{block_hash => <<36,76,94,195,48,58,84,9,116,174,190,81,138,187,247,185,32,253,39,76,73,201,73,154,24,61,245,228,202,223,194,175>>,data => #{tx => <<249,1,8,11,1,248,132,184,64,46,254,63,143,100,94,205,53,29,246,136,240,116,172,200,108,239,178,29,187,152,124,192,70,81,215,57,49,134,85,30,152,172,138,252,249,255,100,215,180,248,226,127,252,205,102,225,117,188,149,127,211,115,42,63,21,39,17,27,183,40,178,211,1,184,64,65,88,245,253,57,229,179,76,24,180,178,65,240,40,241,163,230,172,215,115,30,195,249,60,44,130,128,143,200,158,78,61,116,166,248,200,5,35,42,68,197,87,207,96,72,70,172,5,10,176,180,64,179,65,133,73,151,92,184,46,116,236,50,8,184,126,248,124,50,1,161,1,141,226,227,29,29,87,76,0,106,172,144,200,87,211,57,32,182,163,103,192,26,26,30,142,108,170,76,214,120,146,88,39,135,3,141,126,164,198,128,0,161,1,226,184,104,230,58,207,139,9,115,120,213,62,238,97,34,253,124,96,113,208,144,17,6,215,46,3,201,239,240,38,216,183,1,1,1,0,134,15,239,49,96,96,0,192,160,212,253,193,92,169,67,77,9,134,130,85,218,203,136,237,111,188,154,159,58,58,180,42,56,229,58,31,35,231,201,108,7,9>>},temporary_channel_id => <<35,48,24,201,215,174,140,100,253,164,11,171,166,222,166,135,216,118,233,105,220,43,31,154,92,215,231,194,227,30,39,104>>}},{snd,funding_created,{1568,238709,144184},#{block_hash => <<36,76,94,195,48,58,84,9,116,174,190,81,138,187,247,185,32,253,39,76,73,201,73,154,24,61,245,228,202,223,194,175>>,data => #{tx => <<248,198,11,1,248,66,184,64,65,88,245,253,57,229,179,76,24,180,178,65,240,40,241,163,230,172,215,115,30,195,249,60,44,130,128,143,200,158,78,61,116,166,248,200,5,35,42,68,197,87,207,96,72,70,172,5,10,176,180,64,179,65,133,73,151,92,184,46,116,236,50,8,184,126,248,124,50,1,161,1,141,226,227,29,29,87,76,0,106,172,144,200,87,211,57,32,182,163,103,192,26,26,30,142,108,170,76,214,120,146,88,39,135,3,141,126,164,198,128,0,161,1,226,184,104,230,58,207,139,9,115,120,213,62,238,97,34,253,124,96,113,208,144,17,6,215,46,3,201,239,240,38,216,183,1,1,1,0,134,15,239,49,96,96,0,192,160,212,253,193,92,169,67,77,9,134,130,85,218,203,136,237,111,188,154,159,58,58,180,42,56,229,58,31,35,231,201,108,7,9>>,updates => []},temporary_channel_id => <<35,48,24,201,215,174,140,100,253,164,11,171,166,222,166,135,216,118,233,105,220,43,31,154,92,215,231,194,227,30,39,104>>}},{rcv,signed,{1568,238709,143771},{signed,create_tx,{signed_tx,{aetx,channel_create_tx,aesc_create_tx,126,{channel_create_tx,{id,account,<<141,226,227,29,29,87,76,0,106,172,144,200,87,211,57,32,182,163,103,192,26,26,30,142,108,170,76,214,120,146,88,39>>},1000000000000000,{id,account,<<226,184,104,230,58,207,139,9,115,120,213,62,238,97,34,253,124,96,113,208,144,17,6,215,46,3,201,239,240,38,216,183>>},1,1,1,0,17520000000000,[],<<212,253,193,92,169,67,77,9,134,130,85,218,203,136,237,111,188,154,159,58,58,180,42,56,229,58,31,35,231,201,108,7>>,9}},[<<65,88,245,253,57,229,179,76,24,180,178,65,240,40,241,163,230,172,215,115,30,195,249,60,44,130,128,143,200,158,78,61,116,166,248,200,5,35,42,68,197,87,207,96,72,70,172,5,10,176,180,64,179,65,133,73,151,92,184,46,116,236,50,8>>]}}},{req,sign,{1568,238709,94983},#{info => #{signed_tx => {signed_tx,{aetx,channel_create_tx,aesc_create_tx,126,{channel_create_tx,{id,account,<<141,226,227,29,29,87,76,0,106,172,144,200,87,211,57,32,182,163,103,192,26,26,30,142,108,170,76,214,120,146,88,39>>},1000000000000000,{id,account,<<226,184,104,230,58,207,139,9,115,120,213,62,238,97,34,253,124,96,113,208,144,17,6,215,46,3,201,239,240,38,216,183>>},1,1,1,0,17520000000000,[],<<212,253,193,92,169,67,77,9,134,130,85,218,203,136,237,111,188,154,159,58,58,180,42,56,229,58,31,35,231,201,108,7>>,9}},[]},updates => []},tag => create_tx,type => sign}},{rcv,channel_accept,{1568,238709,36838},#{chain_hash => <<123,173,180,20,178,230,65,254,59,198,234,129,117,11,11,80,142,52,238,147,191,98,135,252,203,203,175,212,7,8,237,83>>,channel_reserve => 1,initiator => <<141,226,227,29,29,87,76,0,106,172,144,200,87,211,57,32,182,163,103,192,26,26,30,142,108,170,76,214,120,...>>,...}},...]},...})
2019-09-11 21:57:49.241 [debug] <0.7930.0>@aesc_session_noise:call:412 Call to noise session <0.7931.0>: close
2019-09-11 21:57:49.241 [debug] <0.7930.0>@aesc_fsm:terminate:3505 CAUGHT {case_clause,{{noproc,{gen_server,call,[<0.7931.0>,close]}},exit}}
2019-09-11 21:57:49.242 [debug] <0.7928.0>@sc_ws_handler:terminate:202 WebSocket dying because of stop
2019-09-11 21:57:49.242 [error] <0.7930.0>@aesc_offchain_state:fallback_to_stable_state:340 gen_statem <0.7930.0> in state awaiting_locked terminated with reason: no function clause matching aesc_offchain_state:fallback_to_stable_state({state,{trees,{mpt,<<5,85,188,121,113,29,165,38,177,140,219,108,64,240,37,22,159,113,174,230,24,...>>,...},...},...}) line 340
2019-09-11 21:57:49.243 [error] <0.7930.0>@aesc_offchain_state:fallback_to_stable_state:340 CRASH REPORT Process <0.7930.0> with 1 neighbours crashed with reason: no function clause matching aesc_offchain_state:fallback_to_stable_state({state,{trees,{mpt,<<5,85,188,121,113,29,165,38,177,140,219,108,64,240,37,22,159,113,174,230,24,...>>,...},...},...}) line 340
2019-09-11 21:57:49.243 [error] <0.1394.0>@aesc_offchain_state:fallback_to_stable_state:340 Supervisor aesc_fsm_sup had child aesc_fsm started with {aesc_fsm,start_link,undefined} at <0.7930.0> exit with reason no function clause matching aesc_offchain_state:fallback_to_stable_state({state,{trees,{mpt,<<5,85,188,121,113,29,165,38,177,140,219,108,64,240,37,22,159,113,174,230,24,...>>,...},...},...}) line 340 in context child_terminated

have this anything to do with https://www.pivotaltracker.com/n/projects/2124891/stories/167956796 ?

Thanks!!

What I get from the log is that a timeout kicked in while participants were waiting for confirmations, so the channel dies in flames. Possible solutions would be:
so either:

  • if too many confirmations set ( minimum_depth in opening arguments), possibly lower the amount of confirmations. This must be a sane number so 1000 is too many, 1 is too low. I would pick 10, 20, 30 depending on specific use case and how much risk I personally would like to take with regards ofchannel_create` transaction being rejected in a fork.
  • the value of the timeout is too low: timeout_funding_lock in opening arguments, it must be at least 1000 * 60 * 3 * minimum_depth in order to have a chance of being enough. I’d personally double that number so I am both safe from newtork being picky and not waiting too long.
1 Like