Catch random crash when notifying the client

[PavlosTze]

Catch for random error when Electrumx wants to notify a client and it fails, causing the ElectrumX to crash, associated with #966 .

[kyuupichan]

Thanks. I've done the wrapping in a separate function, and logged as an exception not error.

[PavlosTze]

@kyuupichan WIth your fix, the crash still takes place if you run artillery with the following config:

config:
  target: "ws://0.0.0.0:51004"
  tls:
    rejectUnauthorized: false
  plugins:
    fuzzer: {}
  phases:
    - duration: 80
      arrivalRate: 200
subprotocols:
    - json
scenarios:
  - engine: "ws"
    flow:
      - send: '{"id":0,"method":"server.version","params":["1.18.8-dev_289_android","1.4.2"]}'
      - send: '{"id":1,"method":"blockchain.headers.subscribe"}'
      - send: '{"id":2,"method":"blockchain.scripthash.subscribe","params":["963c7985bf4123e2d650c707458d6f731b2a0de6ffebbbcb3198f973aecb52c5"]}'
      - send: '{"id":3,"method":"blockchain.scripthash.subscribe","params":["578b41ac4333609a6216b0595d88df72070e734fcbd6ec58c3f2b6900d1f14cf"]}'
      - send: '{"id":4,"method":"blockchain.scripthash.subscribe","params":["6be90d7a1835ad86fa647e429e7e4f849c8da575abbcbf77178b4e80008217ba"]}'
      - send: '{"id":5,"method":"blockchain.scripthash.subscribe","params":["fc9794b06359653b29a2425f16401dba7e18e2f59ba63275d8146f2e420b8f59"]}'
      - send: '{"id":6,"method":"blockchain.scripthash.subscribe","params":["0f4137ef81c6ce2f533c65a79349faaa6a7a8f3602475bf2b0f4a5fc8a1ab592"]}'
      - send: '{"id":7,"method":"blockchain.scripthash.subscribe","params":["46cfe715fdd8a2be46bf7cab5787f4900754b9d6f250aae16034e7a9259b66a6"]}'
      - send: '{"id":8,"method":"blockchain.scripthash.subscribe","params":["acc65567fc97e2befcc52e072cce9e0806c78183b1cf1e6084cb3553337bbc63"]}'
      - send: '{"id":9,"method":"blockchain.scripthash.subscribe","params":["3ba6d0060218fedafa08c3e18ae5bf563058a60f36d3215928cc1839156faf8b"]}'
      - send: '{"id":10,"method":"blockchain.scripthash.subscribe","params":["8c6f50c964a993d07aec5873929ba9d77dae2daa7cc9318276f18d056dfbd302"]}'
      - send: '{"id":11,"method":"blockchain.scripthash.subscribe","params":["ce8684902c923d671b4bcde5aeebe62b4017bf2e2680937874eebe8cfc9233e8"]}'
      - send: '{"id":12,"method":"blockchain.scripthash.subscribe","params":["53c8835bba229b2d479e03d200e3ab188698c7ec232de3a1b78e2a0dd1118384"]}'
      - send: '{"id":13,"method":"blockchain.scripthash.subscribe","params":["1327368ad941a4581871353259e24df70c7d96413b28071633a4607284684e7b"]}'
      - send: '{"id":14,"method":"blockchain.scripthash.subscribe","params":["1173365fe38eb7c446952524491f0e3c05cf750b800d7e635189078cea1024c0"]}'
      - send: '{"id":15,"method":"blockchain.scripthash.subscribe","params":["793528e69efd213c6acbc615fbd4ab4a1e3618550e8e23638cca1fb597a16d01"]}'
      - send: '{"id":16,"method":"blockchain.scripthash.subscribe","params":["86247c9adaa4887b8ced359fbf5c401f7ef65eb53cc163c6bde38fe875ccb859"]}'
      - send: '{"id":17,"method":"blockchain.scripthash.subscribe","params":["ebaec7981099a799a778a32e5e25605a4bc2d3a6a0e1681238320c4deb9d17b8"]}'
      - send: '{"id":18,"method":"blockchain.scripthash.subscribe","params":["a685f4ff12d16351874b18802fa2151a2704672dc0ab469a0a60f99768f06c80"]}'
      - send: '{"id":19,"method":"blockchain.scripthash.subscribe","params":["d7cf745dc807467a8578ca13dabac5546a1741b8f314bb0fe30c19d9db6187a8"]}'
      - send: '{"id":20,"method":"blockchain.scripthash.subscribe","params":["1185fd57087cc0819b21d9f796a9d5c187b20b809ef5032338a4fa049f5fa19e"]}'
      - send: '{"id":21,"method":"blockchain.scripthash.subscribe","params":["9a020bb0ce6401a199dc370b971e8de8792548f3bb1f47bb42912afbc0249ab5"]}'
      - send: '{"id":22,"method":"blockchain.scripthash.subscribe","params":["08e5848ab80da860b2fc5dbe35d90ea6fdfcef157ed91932f5341aaaa84c4cc8"]}'
      - send: '{"id":23,"method":"blockchain.scripthash.subscribe","params":["7b3fc453b63f226ac3a4e3a0fa985e3b9fd74fbde086ca8ff43d254da18def1c"]}'
      - send: '{"id":24,"method":"blockchain.scripthash.subscribe","params":["cb9119431a300c5fd25cefc61e37ea935b1fc3f4bedcbeea90b745fe3ed05153"]}'
      - send: '{"id":25,"method":"blockchain.scripthash.subscribe","params":["68260af453478e4442c159f4d95464ed8bc1a6f1daf7480892836d71d1bc9895"]}'
      - send: '{"id":26,"method":"blockchain.scripthash.subscribe","params":["889b9cd69ef886a2006471c5c52a42a1bde6a3f14ab56d472cab4dd4df8e832f"]}'
      - send: '{"id":27,"method":"blockchain.scripthash.subscribe","params":["4b79c94172c3997b4ddbee74b0863b4934b63d9657544f62db5e72b09b03cb71"]}'
      - send: '{"id":28,"method":"blockchain.scripthash.subscribe","params":["b56ac7686fcdfb5588b265adc0e8f865b7caca73be383831b6c9ffa2a33f99d7"]}'
      - send: '{"id":29,"method":"blockchain.scripthash.subscribe","params":["943fd31ccf312ac112855eb7dd6fd2154cff05a1bc624a031efacca82dc37bcc"]}'
      - send: '{"id":30,"method":"blockchain.scripthash.subscribe","params":["da7915feb04dba1d249dad666c17678e865d897b2e11cd5bd2c9d46c3d060cf3"]}'
      - send: '{"id":31,"method":"blockchain.scripthash.subscribe","params":["21ca93adc6f9ef1db034bc4ffcdecb262b3f703208576e48d7f42ecb996fb8ca"]}'
      - send: '{"id":32,"method":"blockchain.scripthash.subscribe","params":["00e44d04c89e3b0619688058973d1f8e217b0869f403e61778e9078d3be185e6"]}'
      - send: '{"id":33,"method":"blockchain.scripthash.subscribe","params":["2824474eb29f97279c271c70eadda42ebebc060b3d32e2c1183ca9c78c8d4a6f"]}'
      - send: '{"id":34,"method":"blockchain.scripthash.subscribe","params":["1dcd606b7940cae0cf2f173288c0fa711d7d344901072a8b1e175a17f6d66755"]}'
      - send: '{"id":35,"method":"blockchain.scripthash.subscribe","params":["d59e38c1240a78bd6f888d4a2ad83b4f981f37a17ce31b25fbfc1ab97486d3fb"]}'
      - send: '{"id":36,"method":"blockchain.scripthash.subscribe","params":["5c2a06106d5dcc7b288fee1a8e78640ac111cd4469e2e6531be9307e7838b614"]}'
      - send: '{"id":37,"method":"blockchain.scripthash.subscribe","params":["5ad8ca20949b168ec74f22875611313b940f4941ce2327e225b9aad55d09d40f"]}'
      - send: '{"id":38,"method":"blockchain.scripthash.subscribe","params":["7ae9787644fefdb648835a20ecee085c2abd66952c4a58cbe7aee0fa066a072c"]}'
      - send: '{"id":39,"method":"blockchain.scripthash.subscribe","params":["4ff3ae05a8285ec26aa7bd86e6346d668f31a345de099f4ad818740546c6754e"]}'
      - send: '{"id":40,"method":"blockchain.scripthash.subscribe","params":["30648bcf72cfcf40af3b7a03e7a854e76035ef8e996e0210b0716bd5637373c5"]}'
      - send: '{"id":41,"method":"blockchain.scripthash.subscribe","params":["86540f71b958421bb78f849b7fcdb9cf6b72ee06ec8188daa851263a2bfec7ae"]}'
      - send: '{"id":42,"method":"blockchain.scripthash.subscribe","params":["f6559eee06eff11a371e40e2c0b5649dfd56df305ae9d9ad27f42b00b749eff3"]}'
      - send: '{"id":43,"method":"blockchain.scripthash.subscribe","params":["ed030785921e1c9530c38e26c68afdc460a3cec1ccdee867f56663877401351d"]}'
      - send: '{"id":44,"method":"blockchain.scripthash.subscribe","params":["d090a0d5f0efc77c3ab2eb3853359c583fc845d0f2d58ad575bd960e6231c4c4"]}'
      - send: '{"id":45,"method":"blockchain.scripthash.subscribe","params":["48ad171d9ae4f0b96b13b1aa799c83da61dbee8e8b113a011d864572d593d027"]}'
      - send: '{"id":46,"method":"blockchain.scripthash.subscribe","params":["287b85ba24fbf0a46d3be22c32cbea01d9906823e0569b6b8e71370b294d6473"]}'
      - send: '{"id":47,"method":"blockchain.scripthash.subscribe","params":["53b16b8b88feb9175ee1e57af09a0431d8ecdc78835c302cc0cebb5576fbe0ac"]}'
      - send: '{"id":48,"method":"blockchain.scripthash.subscribe","params":["c7b9ca59c52c278a5a6291da03bb5708d3e3ffefb2165b240542ec11b8ea1e68"]}'
      - send: '{"id":49,"method":"blockchain.scripthash.subscribe","params":["79680920fd2dac3442f1c44e414a5707fda744d4271eb8294469f361b557246f"]}'
      - send: '{"id":50,"method":"blockchain.scripthash.subscribe","params":["1bdbc4027c6f2eeadceed2943fd1323298e7dd71ef1652bce734916a3d27edf5"]}'
      - send: '{"id":51,"method":"blockchain.scripthash.subscribe","params":["a29c9601952695a8f431e8ca1b84135a855eaceaf2ae28f805ff66da77089cb2"]}'
      - send: '{"id":52,"method":"blockchain.scripthash.subscribe","params":["e28641a853e7616d1cf8e53d0e7ea8d6c876217deaca9598a8fd03bea3c8050b"]}'
      - send: '{"id":53,"method":"blockchain.scripthash.subscribe","params":["2fb9881e8818110760e793ff266855423f2c61bf103ca5a3ad249ea4ccd86543"]}'
      - send: '{"id":54,"method":"blockchain.scripthash.subscribe","params":["f57aa7784011b8079dd689d68687778999be6b4051b97e5e3809aa54a56de38d"]}'
      - send: '{"id":55,"method":"blockchain.scripthash.subscribe","params":["0ba5f5cd04f5a664b58b7c7652c39a0f872758a34997aae10715017f87d72f1e"]}'
      - think: 20

Whereas with our fix, it doesn't crash, logs out the error, closes the connection, but no crash (which is we want to achieve after all, not random crashes of ElectrumX). I think self.connection_lost() makes the difference here.

[kyuupichan]

connection_lost() is supposed to be a notification from the (in this case) websocket code that the connection was lost. It isn't right to call it directly IMO. Something isn't right either in the websocket code or how I'm using it, but I have no idea what is wrong. It's noticeable this doesn't happen in the normal TCP socket case.
As you have a reproducible testcase can you try adding "await self.close()" below the self.logger.exception I added?

[PavlosTze]

@kyuupichan I added it, in your code, with the await self.close() the ElectrumX doesn't crash, but closes the server as well so the result is the same, we need to restart it to work.

INFO:SessionManager:closing down server for rpc://0.0.0.0:8000
INFO:SessionManager:closing down server for tcp://all_interfaces:50001
INFO:SessionManager:closing down server for ws://all_interfaces:50004
INFO:SessionManager:closing down server for ssl://all_interfaces:50002

I rerun your code without await self.close(), it crashed again. I added also await self.close() in my code, instead of connection_lost(), it didn't crash even though errors were printed in the console because of my logging, and continued serving (just like it does with the connection_lost()).

So I think that the issue is in your external function, the CancelledError that gets raised that causes the crash (or unresponsiveness). If I delete the 'CancelledError' if statement, and leave it as:

        '''Wrap _notify_inner; websockets raises exceptions for unclear reasons.'''
        try:
            await self._notify_inner(touched, height_changed)
        except Exception:
            self.logger.exception('unexpected exception notifying client')
            await self.close()

Then it works just like my code, shows errors, but continues serving, nor crashing nor closing its servers so becoming unresponsive.