A lot of 'JSON error' in the log

[rlinxy]

Describe the bug A clear and concise description of what the bug is.

I have been running the stratum for several days, there are always planty 'JSON error' in the log, then the worker got dropped. Below just a little part from the log. On the rig side, it got disconnected to the server, and reconnects in several seconds.

20190123 20:31:15.600 WARN grin_servers::mining::stratumserver - (Server ID: 0) Failed to parse JSONRpc: JSON error - [] 20190123 20:31:15.601 WARN grin_servers::mining::stratumserver - (Server ID: 0) Dropping worker: 193456

20190123 20:31:15.572 WARN grin_servers::mining::stratumserver - (Server ID: 0) Failed to parse JSONRpc: JSON error - [123, 34, 105, 100, 34, 58, 34, 51, 34, 44, 34, 106, 115, 111, 110, 114, 112, 99, 34, 58, 34, 50, 46, 48, 34, 44, 34, 109, 101, 116, 104, 111, 100, 34, 58, 34, 115, 117, 98, 109, 105, 116, 34, 44, 34, 112, 97, 114, 97, 109, 115, 34, 58, 123, 34, 101, 100, 103, 101, 95, 98, 105, 116, 115, 34, 58, 50, 57, 44, 34, 104, 101, 105, 103, 104, 116, 34, 58, 49, 49, 48, 51, 56, 44, 34, 106, 111, 98, 95, 105, 100, 34, 58, 48, 44, 34, 110, 111, 110, 99, 101, 34, 58, 53, 54, 55, 48, 52, 49, 55, 48, 55, 49, 57, 55, 52, 56, 48, 56, 49, 49, 50, 44, 34, 112, 111, 119, 34, 58, 91, 51, 56, 55, 56, 55, 53, 54, 50, 44, 53, 53, 55, 48, 52, 50, 57, 50, 44, 54, 50, 52, 55, 56, 49, 53, 49, 44, 54, 57, 57, 57, 52, 53, 57, 48, 44, 55, 50, 57, 57, 49, 50, 56, 54, 44, 56, 50, 56, 52, 54, 54, 53, 54, 44, 57, 52, 51, 51, 57, 56, 52, 48, 44, 49, 49, 50, 56, 48, 50, 53, 51, 52, 44, 49, 51, 51, 50, 53, 52, 51, 50, 57, 44, 49, 51, 55, 48, 53, 51, 55, 53, 50, 44, 49, 53, 57, 48, 54, 52, 50, 48, 57, 44, 49, 53, 57, 55, 51, 48, 55, 54, 50, 44, 49, 55, 48, 50, 49, 51, 53, 52, 53, 44, 49, 55, 50, 54, 49, 57, 56, 55, 53, 44, 49, 55, 52, 56, 48, 48, 51, 49, 56, 44, 49, 55, 57, 53, 48, 50, 50, 55, 54, 44, 50, 48, 57, 49, 54, 56, 50, 54, 50, 44, 50, 49, 48, 57, 48, 55, 52, 57, 50, 44, 50, 51, 50, 52, 52, 48, 57, 57, 55, 44, 50, 52, 50, 55, 56, 52, 51, 52, 57, 44, 50, 52, 57, 55, 52, 54, 50, 48, 53, 44, 50, 54, 57, 54, 50, 55, 52, 50, 53, 44, 50, 56, 55, 51, 48, 55, 57, 54, 50, 44, 50, 57, 51, 54, 50, 57, 52, 49, 56, 44, 51, 48, 49, 57, 52, 50, 51, 54, 56, 44, 51, 50, 53, 55, 52, 55, 50, 48, 49, 44, 51, 51, 53, 49, 48, 48, 48, 49, 57, 44, 51, 53, 54, 48, 50, 53, 54, 49, 56, 44, 51, 53, 54, 56, 53, 49, 48, 51, 52, 44, 51, 54, 50, 55, 48, 56, 53, 53, 48, 44, 51, 55, 48, 48, 49, 48, 55, 48, 48, 44, 52, 49, 52, 53, 49, 57, 55, 54, 51, 44, 52, 50, 56, 51, 55, 50, 54, 48, 55, 44, 52, 51, 51, 55, 50, 51, 51, 48, 56, 44, 52, 54, 49, 49, 56, 51, 55, 48, 57, 44, 52, 54, 50, 49, 52, 50, 51, 49, 55, 44, 52, 55, 52, 50, 55, 56, 54, 50, 53, 44, 52, 56, 54, 54, 54, 52, 51, 49, 57, 44, 52, 57, 49, 48, 53, 57, 51, 48, 49, 44, 53, 48, 51, 56, 55, 53, 50, 48, 52, 44, 53, 48, 52, 52, 48, 54, 55, 49, 56, 44, 53, 50, 54, 52, 49, 50, 49, 49, 56, 93, 125, 125, 10, 123, 34, 105, 100, 34, 58, 34, 51, 34, 44, 34, 106, 115, 111, 110, 114, 112, 99, 34, 58, 34, 50, 46, 48, 34, 44, 34, 109, 101, 116, 104, 111, 100, 34, 58, 34, 115, 117, 98, 109, 105, 116, 34, 44, 34, 112, 97, 114, 97, 109, 115, 34, 58, 123, 34, 101, 100, 103, 101, 95, 98, 105, 116, 115, 34, 58, 50, 57, 44, 34, 104, 101, 105, 103, 104, 116, 34, 58, 49, 49, 48, 51, 56, 44, 34, 106, 111, 98, 95, 105, 100, 34, 58, 48, 44, 34, 110, 111, 110, 99, 101, 34, 58, 49, 51, 52, 51, 55, 51, 52, 57, 53, 55, 54, 50, 57, 49, 56, 50, 50, 57, 56, 50, 44, 34, 112, 111, 119, 34, 58, 91, 54, 53, 49, 48, 48, 51, 54, 44, 49, 55, 50, 54, 57, 53, 56, 49, 44, 51, 50, 57, 54, 54, 57, 48, 48, 44, 53, 49, 56, 53, 50, 55, 55, 48, 44, 54, 52, 56, 49, 49, 57, 52, 53, 44, 54, 54, 52, 55, 57, 55, 53, 55, 44, 54, 55, 54, 55, 55, 53, 51, 51, 44, 55, 49, 57, 48, 53, 51, 56, 48, 44, 55, 54, 53, 52, 50, 50, 57, 53, 44, 49, 48, 49, 55, 57, 54, 55, 52, 51, 44, 49, 49, 48, 50, 52, 48, 50, 50, 55, 44, 49, 54, 52, 49, 53, 51, 49, 48, 55, 44, 50, 48, 55, 53, 56, 57, 50, 53, 53, 44, 50, 48, 56, 48, 56, 53, 55, 52, 56, 44, 50, 49, 48, 54, 54, 57, 55, 52, 55, 44, 50, 50, 53, 55, 50, 54, 56, 49, 55, 44, 50, 51, 50, 55, 55, 51, 49, 51, 55, 44, 50, 52, 48, 51, 54, 50, 53, 53, 53, 44, 50, 53, 50, 53, 48, 55, 57, 57, 55, 44, 50, 53, 55, 54, 52, 54, 55, 53, 56, 44, 50, 53, 57, 49, 52, 53, 57, 51, 48, 44, 50, 56, 53, 57, 57, 55, 52, 51, 54, 44, 50, 57, 49, 49, 56, 48, 53, 56, 54, 44, 50, 57, 51, 51, 50, 56, 49, 50, 52, 44, 51, 49, 53, 49, 55, 53, 53, 48, 52, 44, 51, 50, 48, 51, 49, 55, 56, 52, 54, 44, 51, 52, 53, 52, 57, 57, 52, 51, 54, 44, 51, 54, 52, 54, 54, 53, 54, 54, 48, 44, 51, 55, 56, 49, 48, 49, 57, 53, 53, 44, 51, 57, 50, 55, 53, 56, 52, 53, 52, 44, 51, 57, 57, 56, 51, 51, 49, 51, 54, 44, 52, 49, 53, 53, 52, 50, 53, 51, 51, 44, 52, 49, 57, 50, 57, 50, 48, 56, 50, 44, 52, 53, 48, 52, 54, 54, 52, 57, 50, 44, 52, 55, 49, 55, 55, 48, 53, 49, 51, 44, 52, 56, 51, 57, 50, 52, 57, 56, 57, 44, 52, 56, 54, 53, 50, 51, 53, 54, 56, 44, 52, 57, 49, 51, 57, 49, 50, 54, 53, 44, 53, 48, 52, 54, 52, 57, 57, 52, 57, 44, 53, 48, 56, 49, 49, 49, 56, 50, 48, 44, 53, 49, 57, 49, 48, 54, 52, 49, 53, 44, 53, 50, 56, 49, 52, 54, 50, 54, 53, 93, 125, 125, 10] 20190123 20:31:15.572 WARN grin_servers::mining::stratumserver - (Server ID: 0) Dropping worker: 193109

To Reproduce Steps to reproduce the behavior:

1. Just run the built in grin stratum, connect and mine with GGM or Hsp miner.
2. Several minutes later, probably there would be thoes errors in the grin-server.log file.

[hashmap]

2459 may fix it

[rlinxy]

@hashmap seems nothing changed

20190124 00:10:25.683 WARN grin_servers::mining::stratumserver - (Server ID: 0) Failed to parse JSONRpc: JSON error - [123, 34, 105, 100, 34, 58, 34, 49, 34, 44, 34, 106, 115, 111, 110, 114, 112, 99, 34, 58, 34, 50, 46, 48, 34, 44, 34, 109, 101, 116, 104, 111, 100, 34, 58, 34, 108, 111, 103, 105, 110, 34, 44, 34, 112, 97, 114, 97, 109, 115, 34, 58, 123, 34, 97, 103, 101, 110, 116, 34, 58, 34, 104, 115, 112, 109, 105, 110, 101, 114, 34, 44, 34, 108, 111, 103, 105, 110, 34, 58, 34, 102, 108, 121, 115, 104, 115, 104, 121, 64, 113, 113, 46, 99, 111, 109, 47, 67, 79, 76, 79, 82, 48, 51, 80, 49, 48, 54, 34, 44, 34, 112, 97, 115, 115, 34, 58, 34, 120, 34, 125, 125, 10, 123, 34, 105, 100, 34, 58, 34, 49, 34, 44, 34, 106, 115, 111, 110, 114, 112, 99, 34, 58, 34, 50, 46, 48, 34, 44, 34, 109, 101, 116, 104, 111, 100, 34, 58, 34, 108, 111, 103, 105, 110, 34, 44, 34, 112, 97, 114, 97, 109, 115, 34, 58, 123, 34, 97, 103, 101, 110, 116, 34, 58, 34, 104, 115, 112, 109, 105, 110, 101, 114, 34, 44, 34, 108, 111, 103, 105, 110, 34, 58, 34, 104, 117, 105, 104, 117, 105, 64, 49, 54, 51, 46, 99, 111, 109, 47, 78, 79, 48, 48, 57, 34, 44, 34, 112, 97, 115, 115, 34, 58, 34, 120, 34, 125, 125, 10] 20190124 00:10:25.683 WARN grin_servers::mining::stratumserver - (Server ID: 0) Failed to parse JSONRpc: JSON error - [123, 34, 105, 100, 34, 58, 34, 49, 34, 44, 34, 106, 115, 111, 110, 114, 112, 99, 34, 58, 34, 50, 46, 48, 34, 44, 34, 109, 101, 116, 104, 111, 100, 34, 58, 34, 108, 111, 103, 105, 110, 34, 44, 34, 112, 97, 114, 97, 109, 115, 34, 58, 123, 34, 97, 103, 101, 110, 116, 34, 58, 34, 104, 115, 112, 109, 105, 110, 101, 114, 34, 44, 34, 108, 111, 103, 105, 110, 34, 58, 34, 109, 49, 51, 49, 54, 51, 56, 53, 54, 57, 55, 56, 64, 49, 54, 51, 46, 99, 111, 109, 47, 102, 97, 49, 49, 34, 44, 34, 112, 97, 115, 115, 34, 58, 34, 120, 34, 125, 125, 10, 123, 34, 105, 100, 34, 58, 34, 49, 34, 44, 34, 106, 115, 111, 110, 114, 112, 99, 34, 58, 34, 50, 46, 48, 34, 44, 34, 109, 101, 116, 104, 111, 100, 34, 58, 34, 108, 111, 103, 105, 110, 34, 44, 34, 112, 97, 114, 97, 109, 115, 34, 58, 123, 34, 97, 103, 101, 110, 116, 34, 58, 34, 104, 115, 112, 109, 105, 110, 101, 114, 34, 44, 34, 108, 111, 103, 105, 110, 34, 58, 34, 49, 49, 52, 55, 51, 48, 53, 48, 52, 64, 113, 113, 46, 99, 111, 109, 47, 48, 48, 51, 34, 44, 34, 112, 97, 115, 115, 34, 58, 34, 120, 34, 125, 125, 10] 20190124 00:10:25.683 WARN grin_servers::mining::stratumserver - (Server ID: 0) Failed to parse JSONRpc: JSON error - [123, 34, 105, 100, 34, 58, 34, 49, 34, 44, 34, 106, 115, 111, 110, 114, 112, 99, 34, 58, 34, 50, 46, 48, 34, 44, 34, 109, 101, 116, 104, 111, 100, 34, 58, 34, 108, 111, 103, 105, 110, 34, 44, 34, 112, 97, 114, 97, 109, 115, 34, 58, 123, 34, 97, 103, 101, 110, 116, 34, 58, 34, 104, 115, 112, 109, 105, 110, 101, 114, 34, 44, 34, 108, 111, 103, 105, 110, 34, 58, 34, 109, 49, 51, 49, 54, 51, 56, 53, 54, 57, 55, 56, 64, 49, 54, 51, 46, 99, 111, 109, 47, 102, 97, 48, 52, 34, 44, 34, 112, 97, 115, 115, 34, 58, 34, 120, 34, 125, 125, 10, 123, 34, 105, 100, 34, 58, 34, 49, 34, 44, 34, 106, 115, 111, 110, 114, 112, 99, 34, 58, 34, 50, 46, 48, 34, 44, 34, 109, 101, 116, 104, 111, 100, 34, 58, 34, 108, 111, 103, 105, 110, 34, 44, 34, 112, 97, 114, 97, 109, 115, 34, 58, 123, 34, 97, 103, 101, 110, 116, 34, 58, 34, 104, 115, 112, 109, 105, 110, 101, 114, 34, 44, 34, 108, 111, 103, 105, 110, 34, 58, 34, 99, 97, 110, 110, 99, 110, 64, 49, 50, 54, 46, 99, 111, 109, 47, 54, 50, 57, 34, 44, 34, 112, 97, 115, 115, 34, 58, 34, 120, 34, 125, 125, 10] 20190124 00:10:25.683 WARN grin_servers::mining::stratumserver - (Server ID: 0) Dropping worker: 177 20190124 00:10:25.683 WARN grin_servers::mining::stratumserver - (Server ID: 0) Dropping worker: 188 20190124 00:10:25.683 WARN grin_servers::mining::stratumserver - (Server ID: 0) Dropping worker: 197

[hashmap]

@rlinxy have you tested my branch? You have 2 messages concatenated because of that bug, if it doesn't work I'll revert my original pr which introduced that regression

[rlinxy]

@hashmap Yes, did you only added this line: the_message.clear(); Correct? So I added this line to the source code, complied and ran again. Nothing changed. Thanks.

[githubusrR]

Also have this problem, how to solve?

[hashmap]

@rlinxy I tested the latest master, can't reproduce the bug anymore, also @githubusrR confirmed Do you still experience it?

[githubusrR]

no thanks

[rlinxy]

@hashmap Seems the error message is much shorter now, no those bytes info in the []. But only several minutes later I got a 'panic' as #2421. So I am not sure it would reproduce the bug or not, need more research and test.

20190125 10:29:43.512 WARN grin_servers::mining::stratumserver - (Server ID: 0) New connection: 180.104.231.127:30362 20190125 10:29:43.512 WARN grin_servers::mining::stratumserver - (Server ID: 0) New connection: 180.104.231.127:30363 20190125 10:29:43.512 WARN grin_servers::mining::stratumserver - (Server ID: 0) Failed to parse JSONRpc: JSON error - [] 20190125 10:29:43.512 WARN grin_servers::mining::stratumserver - (Server ID: 0) Failed to parse JSONRpc: JSON error - [] 20190125 10:29:43.512 WARN grin_servers::mining::stratumserver - (Server ID: 0) Dropping worker: 692 20190125 10:29:43.513 WARN grin_servers::mining::stratumserver - (Server ID: 0) Dropping worker: 695 20190125 10:29:43.513 DEBUG grin_servers::mining::stratumserver - (Server ID: 0) sending block 13344 with id 0 to single worker 20190125 10:29:43.513 WARN grin_servers::mining::stratumserver - (Server ID: 0) Failed to parse JSONRpc: JSON error - [] 20190125 10:29:43.517 WARN grin_servers::mining::stratumserver - (Server ID: 0) Dropping worker: 656 20190125 10:29:43.517 WARN grin_servers::mining::stratumserver - (Server ID: 0) Failed to parse JSONRpc: JSON error - [] 20190125 10:29:43.517 WARN grin_servers::mining::stratumserver - (Server ID: 0) Dropping worker: 697 20190125 10:29:43.517 DEBUG grin_servers::mining::stratumserver - (Server ID: 0) sending block 13344 with id 0 to single worker 20190125 10:29:43.517 DEBUG grin_servers::mining::stratumserver - (Server ID: 0) sending block 13344 with id 0 to single worker 20190125 10:29:43.521 WARN grin_servers::mining::stratumserver - (Server ID: 0) New connection: 49.82.197.240:5885 20190125 10:29:43.522 DEBUG grin_servers::mining::stratumserver - (Server ID: 0) sending block 13344 with id 0 to single worker 20190125 10:29:43.526 WARN grin_servers::mining::stratumserver - (Server ID: 0) New connection: 220.202.118.30:32981 20190125 10:29:43.526 ERROR grin_servers::mining::stratumserver - (Server ID: 0) Share at height 13343, edge_bits 29, nonce 4371294360813793587, job_id 1 submitted too late 20190125 10:29:43.573 ERROR grin_util::logger - thread 'stratum_server' panicked at 'called Option::unwrap() on a None value': src/libcore/option.rs:355stack backtrace: 0: 0x55624932171d - backtrace::backtrace::trace::h2309a19e9582c4ed 1: 0x556249320842 - backtrace::capture::Backtrace::new::h93a1fac54c6e6f9e 2: 0x5562492aa5e0 - grin_util::logger::send_panic_to_log::{{closure}}::h47e4e241f95c3029 3: 0x5562493ec3f9 - std::panicking::rust_panic_with_hook::h8cbdfe43764887be at src/libstd/panicking.rs:495 4: 0x5562493ebea1 - std::panicking::continue_panic_fmt::h3d3c5a833c00a5e1 at src/libstd/panicking.rs:398 5: 0x5562493ebd85 - rust_begin_unwind at src/libstd/panicking.rs:325 6: 0x556249408ffc - core::panicking::panic_fmt::h4d67173bc68f6d5a at src/libcore/panicking.rs:95 7: 0x556249408f2b - core::panicking::panic::h6f50c0de2dcd7974 at src/libcore/panicking.rs:59 8: 0x556248d5d65b - grin_servers::mining::stratumserver::StratumServer::handle_rpc_requests::h7be71a3aae6f471d 9: 0x556248d60398 - grin_servers::mining::stratumserver::StratumServer::run_loop::ha43b1af80fe23777 10: 0x556248d3b505 - std::sys_common::backtrace::rust_begin_short_backtrace::ha323e8865aef0cd8 11: 0x556248d729c5 - std::panicking::try::do_call::h7d55ef3d3c7b3d9e 12: 0x556249402329 - rust_maybe_catch_panic at src/libpanic_unwind/lib.rs:102 13: 0x556248d818a7 - <F as alloc::boxed::FnBox>::call_box::h206946f6b63301ce 14: 0x5562493f5f0d - <alloc::boxed::Box<(dyn alloc::boxed::FnBox<A, Output=R> + 'a)> as core::ops::function::FnOnce>::call_once::hece536cf07b94f8d at /rustc/9fda7c2237db910e41d6a712e9a2139b352e558b/src/liballoc/boxed.rs:683

• std::sys_common::thread::start_thread::h9605a7df0f911844 at src/libstd/sys_common/thread.rs:24
• std::sys::unix::thread::Thread::new::thread_start::hca8e72c41fa9d291 at src/libstd/sys/unix/thread.rs:90 15: 0x7f6e2af2e6b9 - start_thread 16: 0x7f6e2aa4e41c - clone 17: 0x0 -

@hashmap This bug probably solved for now. I add this line the_message.clear(); to the code from #2421 updated by @sesam, now seems everything perfect. No panic, no tcp connection keep growing. But it just has been running for 1 hour, let's see if it would still works good several hours later. Thanks.

[rlinxy]

Has been running for 4 hours, the tcp connection grew from 300 to 1.5K, and keep increasing. So seems the 'dead' tcp connections still can not be cloesed properly.

[sesam]

@rlinxy thanks a lot for testing! There's an asynchronous stratum server being implemented, see it here: https://github.com/mimblewimble/grin/pull/2468 Maybe your easiest path forward will be using this new async version, which will be able to handle more than 400 simultaneous workers.

[rlinxy]

@sesam Nice, I will try, thank you!

[hashmap]

Ok, closing for now, feel free to reopen if needed

[rlinxy]

I guess this issue solved by using your update together @hashmap @sesam, my pool has been running smoothly for 2 days without big problem, no panic, no tcp connection increasing. Still testing, later I will post the code. Thanks a lot!