Logs showing loads of "Attempted to end HDK call, but none was started" from v0.0.39-alpha4

[Connoropolous]

I am collaborating on https://github.com/h-be/acorn-hc, and we recently updated to v0.0.39-alpha4 very recent version.

We are having issues with slowdown. The app, over the course of between 30 seconds and 5 minutes, goes from Holochain calls returning values in < 1 second, to 11 seconds, or more.

I do not know if it relates to this error log that we are seeing abundantly in the logs or not.

ERROR 2019-11-28 22:17:06 [holochain_core::nucleus::reducers::trace_return_hdk_function] action_loop/puid-0-3d crates/core/src/nucleus/reducers/trace_return_hdk_function.rs:22 Attempted to end HDK call, but none was started!
ERROR 2019-11-28 22:17:10 [holochain_core::nucleus::reducers::trace_return_hdk_function] action_loop/puid-0-3d crates/core/src/nucleus/reducers/trace_return_hdk_function.rs:22 Attempted to end HDK call, but none was started!
ERROR 2019-11-28 22:17:13 [holochain_core::nucleus::reducers::trace_return_hdk_function] action_loop/puid-0-3d crates/core/src/nucleus/reducers/trace_return_hdk_function.rs:22 Attempted to end HDK call, but none was started!
ERROR 2019-11-28 22:17:16 [holochain_core::nucleus::reducers::trace_return_hdk_function] action_loop/puid-0-3d crates/core/src/nucleus/reducers/trace_return_hdk_function.rs:22 Attempted to end HDK call, but none was started!
ERROR 2019-11-28 22:17:18 [holochain_core::nucleus::reducers::trace_return_hdk_function] action_loop/puid-0-3d crates/core/src/nucleus/reducers/trace_return_hdk_function.rs:22 Attempted to end HDK call, but none was started!
ERROR 2019-11-28 22:17:22 [holochain_core::nucleus::reducers::trace_return_hdk_function] action_loop/puid-0-3d crates/core/src/nucleus/reducers/trace_return_hdk_function.rs:22 Attempted to end HDK call, but none was started!
ERROR 2019-11-28 22:17:25 [holochain_core::nucleus::reducers::trace_return_hdk_function] action_loop/puid-0-3d crates/core/src/nucleus/reducers/trace_return_hdk_function.rs:22 Attempted to end HDK call, but none was started!
ERROR 2019-11-28 22:17:28 [holochain_core::nucleus::reducers::trace_return_hdk_function] action_loop/puid-0-3d crates/core/src/nucleus/reducers/trace_return_hdk_function.rs:22 Attempted to end HDK call, but none was started!
ERROR 2019-11-28 22:17:30 [holochain_core::nucleus::reducers::trace_return_hdk_function] action_loop/puid-0-3d crates/core/src/nucleus/reducers/trace_return_hdk_function.rs:22 Attempted to end HDK call, but none was started!
ERROR 2019-11-28 22:17:34 [holochain_core::nucleus::reducers::trace_return_hdk_function] action_loop/puid-0-3d crates/core/src/nucleus/reducers/trace_return_hdk_function.rs:22 Attempted to end HDK call, but none was started!
ERROR 2019-11-28 22:17:37 [holochain_core::nucleus::reducers::trace_return_hdk_function] action_loop/puid-0-3d crates/core/src/nucleus/reducers/trace_return_hdk_function.rs:22 Attempted to end HDK call, but none was started!
ERROR 2019-11-28 22:17:40 [holochain_core::nucleus::reducers::trace_return_hdk_function] action_loop/puid-0-3d crates/core/src/nucleus/reducers/trace_return_hdk_function.rs:22 Attempted to end HDK call, but none was started!
ERROR 2019-11-28 22:17:43 [holochain_core::nucleus::reducers::trace_return_hdk_function] action_loop/puid-0-3d crates/core/src/nucleus/reducers/trace_return_hdk_function.rs:22 Attempted to end HDK call, but none was started!
ERROR 2019-11-28 22:17:47 [holochain_core::nucleus::reducers::trace_return_hdk_function] action_loop/puid-0-3d crates/core/src/nucleus/reducers/trace_return_hdk_function.rs:22 Attempted to end HDK call, but none was started!
ERROR 2019-11-28 22:17:50 [holochain_core::nucleus::reducers::trace_return_hdk_function] action_loop/puid-0-3d crates/core/src/nucleus/reducers/trace_return_hdk_function.rs:22 Attempted to end HDK call, but none was started!
ERROR 2019-11-28 22:17:53 [holochain_core::nucleus::reducers::trace_return_hdk_function] action_loop/puid-0-3d crates/core/src/nucleus/reducers/trace_return_hdk_function.rs:22 Attempted to end HDK call, but none was started!

And it is many more lines than this.

---

After a small bit of sleuthing, I trace this to these files, which were only just introduced a week ago-ish in #1907 and #1885 :

holochain-rust/crates/core/src/nucleus/reducers/trace_return_hdk_function.rs

Lines 17 to 22 in 19f4aaa

	state
	.hdk_function_calls
	.get_mut(zome_fn_call)
	.ok_or_else(|| format!("Cannot record hdk function return for zome call, because its invocation was never recorded. zome call = {:?}, hdk call = {:?}", zome_fn_call, hdk_fn_call))
	.and_then(|zome_fn_call_state| zome_fn_call_state.end_hdk_call(hdk_fn_call.clone(), hdk_fn_call_result.clone()).map_err(|e| e.to_string()))
	.unwrap_or_else(|err| error!("{}", err));

and then

holochain-rust/crates/core/src/nucleus/state.rs

Lines 219 to 238 in 19f4aaa

	if let Some((current_call, current_result)) = self.hdk_fn_invocations.pop() {
	if call != current_call {
	Err(HolochainError::new(
	"HDK call other than the current call was ended.",
	))
	} else if current_result.is_some() {
	Err(HolochainError::new(
	"Ending and HDK which was already ended.",
	))
	} else {
	self.hdk_fn_invocations.push((call, Some(result)));
	Ok(())
	}
	} else {
	Err(HolochainError::new(
	"Attempted to end HDK call, but none was started!",
	))
	}
	}
	}

[Connoropolous]

@lucksus or @maackle can you help/ take a look at this? We are blocked from doing user testing because of whatever is going on that makes it slow down to unresponsive.

[maackle]

@Connoropolous that's definitely a problem. Are there any other conspicuous errors in your logs before that, especially an instance of the other two error cases in state.rs that you posted?

HDK call other than the current call was ended., or Ending and HDK which was already ended.?

[maackle]

Clarification: It's a problem inasmuch as it shouldn't be happening, but it's not clear whether that's causing the performance problem. Perhaps this indicates some state that's not being cleaned up. I wonder if you can also dig up a state dump in your logs and post that here. You'll have do add state_dump = true to your logger config if it's not set already, and then grep for:

=============STATE DUMP===============

[Connoropolous]

I am still seeing a lot of these in the logs, though as you say, I'm not clear that that's causing any problem, let alone the performance slow down.

We've just updated Acorn to v0.0.40 and see major improvements for sure.
Have some new errors to raise that we're seeing doing that testing.

[Connoropolous]

HDK call other than the current call was ended., or Ending and HDK which was already ended

I don't see either of these in log files, no