Timeouts during tests

Technical Discussion
#1

I’m getting consistent timeout errors during tests in a couple of scenarios. Note that the timeouts do not occur with the same scenarios on the development instance.

  1. When using 2 players (alice, carol). alice calls create_collective, s.consistency(), then carol calls get_collective

  2. When using 1 player (alice). alice calls create_collective, get_collective, then get_actions. The last call to get_actions causes the timeout.

I reproduced scenario 2 in the development instance & did not get the timeout.

Here is the implementation: https://github.com/cogov/CoGov.rust/blob/master/zomes/cogov/code/src/lib.rs

Here is the test (with get_actions commented out): https://github.com/cogov/CoGov.rust/blob/master/test/index.js

Here is the error response:

05:24:23 [tryorama: tryorama conductor alice] debug: -> {
  Err: {
    Internal: '{"kind":"Timeout","file":"crates/core/src/nucleus/ribosome/runtime.rs","line":"220"}'
  }
}
not ok 4 should be equivalent
  ---
    operator: deepEqual
    expected: |-
      { Ok: [ { collective_address: 'QmRnmJweZynzpQ92jj5fYxnubWNSVpoo7xfXWowshz3ZBi', collective: { name: 'Collective 1' } } ] }
    actual: |-
      { Err: { Internal: '{"kind":"Timeout","file":"crates/core/src/nucleus/ribosome/runtime.rs","line":"220"}' } }
    stack: |-
      Error: should be equivalent
          at Test.assert [as _assert] (/home/brian/work/cogov/cogov-dev/test/node_modules/tape/lib/test.js:226:54)
          at Test.bound [as _assert] (/home/brian/work/cogov/cogov-dev/test/node_modules/tape/lib/test.js:78:32)
          at Test.tapeDeepEqual (/home/brian/work/cogov/cogov-dev/test/node_modules/tape/lib/test.js:424:10)
          at Test.bound [as deepEqual] (/home/brian/work/cogov/cogov-dev/test/node_modules/tape/lib/test.js:78:32)
          at /home/brian/work/cogov/cogov-dev/test/index.js:47:5
          at processTicksAndRejections (internal/process/task_queues.js:93:5)
  ...
Get_links causing timeout
#2

In an attempt to debug, I added a sleep, with the hopes it’s due to a simple race condition. Doesn’t seem to help though.

Here’s the implementation of sleep in the test.

function sleep(ms) {
	return new Promise(resolve => {
		setTimeout(resolve, ms)
	})
}
#3

This is quiet odd, it’s timing out in holochain itself. I’ll have a dig.

1 Like
#4

Here’s the logging from the development instance.

DEBUG 2020-01-13 02:33:45 [tokio_reactor::registration] http.worker00 /home/docker/project/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-reactor-0.1.11/src/registration.rs:518 scheduling Read for: 0
DEBUG 2020-01-13 02:33:45 [tokio_reactor] http.worker00 /home/docker/project/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-reactor-0.1.11/src/lib.rs:680 adding I/O source: 8388609
DEBUG 2020-01-13 02:33:45 [tokio_reactor::registration] http.worker00 /home/docker/project/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-reactor-0.1.11/src/registration.rs:518 scheduling Read for: 1
DEBUG 2020-01-13 02:33:45 [hyper::proto::h1::io] http.worker00 /home/docker/project/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.12.25/src/proto/h1/io.rs:180 read 355 bytes
DEBUG 2020-01-13 02:33:45 [hyper::proto::h1::io] http.worker00 /home/docker/project/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.12.25/src/proto/h1/io.rs:149 parsed 5 headers
DEBUG 2020-01-13 02:33:45 [hyper::proto::h1::conn] http.worker00 /home/docker/project/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.12.25/src/proto/h1/conn.rs:149 incoming body is content-length (223 bytes)
DEBUG 2020-01-13 02:33:45 [hyper::proto::h1::conn] http.worker00 /home/docker/project/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.12.25/src/proto/h1/conn.rs:199 incoming body completed
DEBUG 2020-01-13 02:33:45 [rpc] http.worker00 /home/docker/project/.cargo/registry/src/github.com-1ecc6299db9ec823/jsonrpc-core-14.0.1/src/io.rs:198 Response: {"jsonrpc":"2.0","result":{"signature":"4Pqz1dmwq69z9OswVXBnIj77wNnXNuiR0BJ9i5XVbiE2tUEbcE9VSmYwRJkIHgsMlXKGahqx4HGWyvvX5TQfBQ=="},"id":"puid-10-f7"}.
DEBUG 2020-01-13 02:33:45 [holochain::test-instance] http.worker00 crates/core/src/nucleus/actions/call_zome_function.rs:72 actions/call_zome_fn: Validating call: ZomeFnCall { id: ProcessUniqueId { prefix: 16, offset: 249 }, zome_name: "cogov", cap: CapabilityRequest { cap_token: HashString("QmZg2pPuppvav6dUwXKDfZS1QXkdXim6wGYT39HrE4znEt"), provenance: Provenance(HashString("HcScjN8wBwrn3tuyg89aab3a69xsIgdzmX5P9537BqQZ5A7TEZu7qCY4Xzzjhma"), Signature("4Pqz1dmwq69z9OswVXBnIj77wNnXNuiR0BJ9i5XVbiE2tUEbcE9VSmYwRJkIHgsMlXKGahqx4HGWyvvX5TQfBQ==")) }, fn_name: "get_collective", parameters: JsonString("{\"collective_address\":\"QmYUZh1MvPpsJSY3kcNghwMUTbxVTAsdhxajtkumt1Yx7N\"}") }
DEBUG 2020-01-13 02:33:45 [holochain::test-instance] http.worker00 crates/core/src/nucleus/actions/call_zome_function.rs:81 actions/call_zome_fn: executing call: ZomeFnCall { id: ProcessUniqueId { prefix: 16, offset: 249 }, zome_name: "cogov", cap: CapabilityRequest { cap_token: HashString("QmZg2pPuppvav6dUwXKDfZS1QXkdXim6wGYT39HrE4znEt"), provenance: Provenance(HashString("HcScjN8wBwrn3tuyg89aab3a69xsIgdzmX5P9537BqQZ5A7TEZu7qCY4Xzzjhma"), Signature("4Pqz1dmwq69z9OswVXBnIj77wNnXNuiR0BJ9i5XVbiE2tUEbcE9VSmYwRJkIHgsMlXKGahqx4HGWyvvX5TQfBQ==")) }, fn_name: "get_collective", parameters: JsonString("{\"collective_address\":\"QmYUZh1MvPpsJSY3kcNghwMUTbxVTAsdhxajtkumt1Yx7N\"}") }
DEBUG 2020-01-13 02:33:45 [holochain::test-instance] http.worker00 crates/core/src/nucleus/actions/call_zome_function.rs:95 actions/call_zome_fn: awaiting for future call result of ZomeFnCall { id: ProcessUniqueId { prefix: 16, offset: 249 }, zome_name: "cogov", cap: CapabilityRequest { cap_token: HashString("QmZg2pPuppvav6dUwXKDfZS1QXkdXim6wGYT39HrE4znEt"), provenance: Provenance(HashString("HcScjN8wBwrn3tuyg89aab3a69xsIgdzmX5P9537BqQZ5A7TEZu7qCY4Xzzjhma"), Signature("4Pqz1dmwq69z9OswVXBnIj77wNnXNuiR0BJ9i5XVbiE2tUEbcE9VSmYwRJkIHgsMlXKGahqx4HGWyvvX5TQfBQ==")) }, fn_name: "get_collective", parameters: JsonString("{\"collective_address\":\"QmYUZh1MvPpsJSY3kcNghwMUTbxVTAsdhxajtkumt1Yx7N\"}") }
ERROR 2020-01-13 02:33:45 [holochain_core::nucleus::reducers::trace_return_hdk_function] action_loop/puid-0-33 crates/core/src/nucleus/reducers/trace_return_hdk_function.rs:22 Attempted to end HDK call, but none was started!
DEBUG 2020-01-13 02:33:45 [holochain::test-instance] ZomeFnCall { id: ProcessUniqueId { prefix: 16, offset: 249 }, zome_name: "cogov", cap: CapabilityRequest { cap_token: HashString("QmZg2pPuppvav6dUwXKDfZS1QXkdXim6wGYT39HrE4znEt"), provenance: Provenance(HashString("HcScjN8wBwrn3tuyg89aab3a69xsIgdzmX5P9537BqQZ5A7TEZu7qCY4Xzzjhma"), Signature("4Pqz1dmwq69z9OswVXBnIj77wNnXNuiR0BJ9i5XVbiE2tUEbcE9VSmYwRJkIHgsMlXKGahqx4HGWyvvX5TQfBQ==")) }, fn_name: "get_collective", parameters: JsonString("{\"collective_address\":\"QmYUZh1MvPpsJSY3kcNghwMUTbxVTAsdhxajtkumt1Yx7N\"}") } crates/core/src/nucleus/actions/call_zome_function.rs:288 actions/call_zome_fn: got call_result from ribosome::run_dna.
DEBUG 2020-01-13 02:33:45 [holochain::test-instance] ZomeFnCall { id: ProcessUniqueId { prefix: 16, offset: 249 }, zome_name: "cogov", cap: CapabilityRequest { cap_token: HashString("QmZg2pPuppvav6dUwXKDfZS1QXkdXim6wGYT39HrE4znEt"), provenance: Provenance(HashString("HcScjN8wBwrn3tuyg89aab3a69xsIgdzmX5P9537BqQZ5A7TEZu7qCY4Xzzjhma"), Signature("4Pqz1dmwq69z9OswVXBnIj77wNnXNuiR0BJ9i5XVbiE2tUEbcE9VSmYwRJkIHgsMlXKGahqx4HGWyvvX5TQfBQ==")) }, fn_name: "get_collective", parameters: JsonString("{\"collective_address\":\"QmYUZh1MvPpsJSY3kcNghwMUTbxVTAsdhxajtkumt1Yx7N\"}") } crates/core/src/nucleus/actions/call_zome_function.rs:295 actions/call_zome_fn: sending ReturnZomeFunctionResult action.
DEBUG 2020-01-13 02:33:45 [holochain::test-instance] ZomeFnCall { id: ProcessUniqueId { prefix: 16, offset: 249 }, zome_name: "cogov", cap: CapabilityRequest { cap_token: HashString("QmZg2pPuppvav6dUwXKDfZS1QXkdXim6wGYT39HrE4znEt"), provenance: Provenance(HashString("HcScjN8wBwrn3tuyg89aab3a69xsIgdzmX5P9537BqQZ5A7TEZu7qCY4Xzzjhma"), Signature("4Pqz1dmwq69z9OswVXBnIj77wNnXNuiR0BJ9i5XVbiE2tUEbcE9VSmYwRJkIHgsMlXKGahqx4HGWyvvX5TQfBQ==")) }, fn_name: "get_collective", parameters: JsonString("{\"collective_address\":\"QmYUZh1MvPpsJSY3kcNghwMUTbxVTAsdhxajtkumt1Yx7N\"}") } crates/core/src/nucleus/actions/call_zome_function.rs:304 actions/call_zome_fn: sent ReturnZomeFunctionResult action.
DEBUG 2020-01-13 02:33:45 [holochain_metrics::logger] http.worker00 crates/metrics/src/logger.rs:24 2020-01-13 07:33:45  METRIC call_zome_function.cogov.get_collective.latency 19
DEBUG 2020-01-13 02:33:45 [rpc] http.worker00 /home/docker/project/.cargo/registry/src/github.com-1ecc6299db9ec823/jsonrpc-core-14.0.1/src/io.rs:198 Response: {"jsonrpc":"2.0","result":"{\"Ok\":{\"collective_address\":\"QmYUZh1MvPpsJSY3kcNghwMUTbxVTAsdhxajtkumt1Yx7N\",\"collective\":{\"name\":\"Collective 0\"}}}","id":"0"}.
DEBUG 2020-01-13 02:33:45 [hyper::proto::h1::io] http.worker00 /home/docker/project/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.12.25/src/proto/h1/io.rs:216 flushed 290 bytes
DEBUG 2020-01-13 02:33:45 [tokio_reactor::registration] http.worker00 /home/docker/project/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-reactor-0.1.11/src/registration.rs:518 scheduling Read for: 1
DEBUG 2020-01-13 02:33:45 [tokio_reactor::registration] http.worker00 /home/docker/project/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-reactor-0.1.11/src/registration.rs:518 scheduling Read for: 1
DEBUG 2020-01-13 02:33:45 [hyper::proto::h1::io] http.worker00 /home/docker/project/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.12.25/src/proto/h1/io.rs:180 read 0 bytes
DEBUG 2020-01-13 02:33:45 [hyper::proto::h1::conn] http.worker00 /home/docker/project/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.12.25/src/proto/h1/conn.rs:186 read eof
DEBUG 2020-01-13 02:33:45 [tokio_reactor] http.worker00 /home/docker/project/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-reactor-0.1.11/src/lib.rs:698 dropping I/O source: 1
DEBUG 2020-01-13 02:33:48 [tokio_reactor::registration] http.worker00 /home/docker/project/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-reactor-0.1.11/src/registration.rs:518 scheduling Read for: 0
DEBUG 2020-01-13 02:33:48 [tokio_reactor] http.worker00 /home/docker/project/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-reactor-0.1.11/src/lib.rs:680 adding I/O source: 12582913
DEBUG 2020-01-13 02:33:48 [tokio_reactor::registration] http.worker00 /home/docker/project/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-reactor-0.1.11/src/registration.rs:518 scheduling Read for: 1
DEBUG 2020-01-13 02:33:48 [hyper::proto::h1::io] http.worker00 /home/docker/project/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.12.25/src/proto/h1/io.rs:180 read 352 bytes
DEBUG 2020-01-13 02:33:48 [hyper::proto::h1::io] http.worker00 /home/docker/project/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.12.25/src/proto/h1/io.rs:149 parsed 5 headers
DEBUG 2020-01-13 02:33:48 [hyper::proto::h1::conn] http.worker00 /home/docker/project/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.12.25/src/proto/h1/conn.rs:149 incoming body is content-length (220 bytes)
DEBUG 2020-01-13 02:33:48 [hyper::proto::h1::conn] http.worker00 /home/docker/project/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.12.25/src/proto/h1/conn.rs:199 incoming body completed
DEBUG 2020-01-13 02:33:48 [rpc] http.worker00 /home/docker/project/.cargo/registry/src/github.com-1ecc6299db9ec823/jsonrpc-core-14.0.1/src/io.rs:198 Response: {"jsonrpc":"2.0","result":{"signature":"H32RsvHLY8sKSObSA62w0GBwe0Xb/15cm2Ao02yr/P/tOETCCvUnuE2cpkDiOhQfQpAcuQ/9X++KeyC6E6MAAw=="},"id":"puid-10-11e"}.
DEBUG 2020-01-13 02:33:48 [holochain::test-instance] http.worker00 crates/core/src/nucleus/actions/call_zome_function.rs:72 actions/call_zome_fn: Validating call: ZomeFnCall { id: ProcessUniqueId { prefix: 16, offset: 288 }, zome_name: "cogov", cap: CapabilityRequest { cap_token: HashString("QmZg2pPuppvav6dUwXKDfZS1QXkdXim6wGYT39HrE4znEt"), provenance: Provenance(HashString("HcScjN8wBwrn3tuyg89aab3a69xsIgdzmX5P9537BqQZ5A7TEZu7qCY4Xzzjhma"), Signature("H32RsvHLY8sKSObSA62w0GBwe0Xb/15cm2Ao02yr/P/tOETCCvUnuE2cpkDiOhQfQpAcuQ/9X++KeyC6E6MAAw==")) }, fn_name: "get_actions", parameters: JsonString("{\"collective_address\":\"QmYUZh1MvPpsJSY3kcNghwMUTbxVTAsdhxajtkumt1Yx7N\"}") }
DEBUG 2020-01-13 02:33:48 [holochain::test-instance] http.worker00 crates/core/src/nucleus/actions/call_zome_function.rs:81 actions/call_zome_fn: executing call: ZomeFnCall { id: ProcessUniqueId { prefix: 16, offset: 288 }, zome_name: "cogov", cap: CapabilityRequest { cap_token: HashString("QmZg2pPuppvav6dUwXKDfZS1QXkdXim6wGYT39HrE4znEt"), provenance: Provenance(HashString("HcScjN8wBwrn3tuyg89aab3a69xsIgdzmX5P9537BqQZ5A7TEZu7qCY4Xzzjhma"), Signature("H32RsvHLY8sKSObSA62w0GBwe0Xb/15cm2Ao02yr/P/tOETCCvUnuE2cpkDiOhQfQpAcuQ/9X++KeyC6E6MAAw==")) }, fn_name: "get_actions", parameters: JsonString("{\"collective_address\":\"QmYUZh1MvPpsJSY3kcNghwMUTbxVTAsdhxajtkumt1Yx7N\"}") }
DEBUG 2020-01-13 02:33:48 [holochain::test-instance] http.worker00 crates/core/src/nucleus/actions/call_zome_function.rs:95 actions/call_zome_fn: awaiting for future call result of ZomeFnCall { id: ProcessUniqueId { prefix: 16, offset: 288 }, zome_name: "cogov", cap: CapabilityRequest { cap_token: HashString("QmZg2pPuppvav6dUwXKDfZS1QXkdXim6wGYT39HrE4znEt"), provenance: Provenance(HashString("HcScjN8wBwrn3tuyg89aab3a69xsIgdzmX5P9537BqQZ5A7TEZu7qCY4Xzzjhma"), Signature("H32RsvHLY8sKSObSA62w0GBwe0Xb/15cm2Ao02yr/P/tOETCCvUnuE2cpkDiOhQfQpAcuQ/9X++KeyC6E6MAAw==")) }, fn_name: "get_actions", parameters: JsonString("{\"collective_address\":\"QmYUZh1MvPpsJSY3kcNghwMUTbxVTAsdhxajtkumt1Yx7N\"}") }
DEBUG 2020-01-13 02:33:48 [holochain::test-instance] ZomeFnCall { id: ProcessUniqueId { prefix: 16, offset: 288 }, zome_name: "cogov", cap: CapabilityRequest { cap_token: HashString("QmZg2pPuppvav6dUwXKDfZS1QXkdXim6wGYT39HrE4znEt"), provenance: Provenance(HashString("HcScjN8wBwrn3tuyg89aab3a69xsIgdzmX5P9537BqQZ5A7TEZu7qCY4Xzzjhma"), Signature("H32RsvHLY8sKSObSA62w0GBwe0Xb/15cm2Ao02yr/P/tOETCCvUnuE2cpkDiOhQfQpAcuQ/9X++KeyC6E6MAAw==")) }, fn_name: "get_actions", parameters: JsonString("{\"collective_address\":\"QmYUZh1MvPpsJSY3kcNghwMUTbxVTAsdhxajtkumt1Yx7N\"}") } crates/core/src/nucleus/ribosome/api/get_links.rs:19 zome/get_links: invoke_get_links called with GetLinksArgs { entry_address: HashString("QmYUZh1MvPpsJSY3kcNghwMUTbxVTAsdhxajtkumt1Yx7N"), link_type: "^collective_action$", tag: ".*", options: GetLinksOptions { status_request: Live, headers: false, timeout: Timeout(60000) } }
DEBUG 2020-01-13 02:33:48 [holochain::test-instance] net_worker_thread/puid-5-30 crates/core/src/network/handler/mod.rs:185 net/handle: HandleQueryEntry: QueryEntryData { space_address: SpaceHash(HashString("QmekUG4dFS5vrVGQA169jVv9k46TXqSaqQ6LADX45mm1eM")), entry_address: EntryHash(HashString("QmYUZh1MvPpsJSY3kcNghwMUTbxVTAsdhxajtkumt1Yx7N")), request_id: "puid-15-2", requester_agent_id: AgentPubKey(HashString("HcScjN8wBwrn3tuyg89aab3a69xsIgdzmX5P9537BqQZ5A7TEZu7qCY4Xzzjhma")), query: "{\"GetLinks\":[\"^collective_action$\",\".*\",\"live\",{\"Links\":{\"headers\":false}}]}" }
DEBUG 2020-01-13 02:33:48 [holochain::test-instance] net_worker_thread/puid-5-30 crates/core/src/network/handler/mod.rs:206 net/handle: HandleQueryEntryResult: QueryEntryResultData { space_address: SpaceHash(HashString("QmekUG4dFS5vrVGQA169jVv9k46TXqSaqQ6LADX45mm1eM")), entry_address: EntryHash(HashString("QmYUZh1MvPpsJSY3kcNghwMUTbxVTAsdhxajtkumt1Yx7N")), request_id: "puid-15-2", requester_agent_id: AgentPubKey(HashString("HcScjN8wBwrn3tuyg89aab3a69xsIgdzmX5P9537BqQZ5A7TEZu7qCY4Xzzjhma")), responder_agent_id: AgentPubKey(HashString("HcScjN8wBwrn3tuyg89aab3a69xsIgdzmX5P9537BqQZ5A7TEZu7qCY4Xzzjhma")), query_result: "{\"Links\":[{\"Links\":[{\"address\":\"QmfPq4aP8RSLGvBJaHbtB8wVHQjcZJDNRT1D38a9vNg27N\",\"crud_status\":\"live\",\"target\":\"QmSPJRHFa1bRsyA7Esw3CmftEWHJN71z71R7N71DJo8qGN\",\"tag\":\"create_collective\",\"headers\":null}]},\"^collective_action$\",\".*\"]}" }
ERROR 2020-01-13 02:33:48 [holochain_core::nucleus::reducers::trace_return_hdk_function] action_loop/puid-0-33 crates/core/src/nucleus/reducers/trace_return_hdk_function.rs:22 Attempted to end HDK call, but none was started!
DEBUG 2020-01-13 02:33:48 [holochain::test-instance] ZomeFnCall { id: ProcessUniqueId { prefix: 16, offset: 288 }, zome_name: "cogov", cap: CapabilityRequest { cap_token: HashString("QmZg2pPuppvav6dUwXKDfZS1QXkdXim6wGYT39HrE4znEt"), provenance: Provenance(HashString("HcScjN8wBwrn3tuyg89aab3a69xsIgdzmX5P9537BqQZ5A7TEZu7qCY4Xzzjhma"), Signature("H32RsvHLY8sKSObSA62w0GBwe0Xb/15cm2Ao02yr/P/tOETCCvUnuE2cpkDiOhQfQpAcuQ/9X++KeyC6E6MAAw==")) }, fn_name: "get_actions", parameters: JsonString("{\"collective_address\":\"QmYUZh1MvPpsJSY3kcNghwMUTbxVTAsdhxajtkumt1Yx7N\"}") } crates/core/src/nucleus/actions/call_zome_function.rs:288 actions/call_zome_fn: got call_result from ribosome::run_dna.
DEBUG 2020-01-13 02:33:48 [holochain::test-instance] ZomeFnCall { id: ProcessUniqueId { prefix: 16, offset: 288 }, zome_name: "cogov", cap: CapabilityRequest { cap_token: HashString("QmZg2pPuppvav6dUwXKDfZS1QXkdXim6wGYT39HrE4znEt"), provenance: Provenance(HashString("HcScjN8wBwrn3tuyg89aab3a69xsIgdzmX5P9537BqQZ5A7TEZu7qCY4Xzzjhma"), Signature("H32RsvHLY8sKSObSA62w0GBwe0Xb/15cm2Ao02yr/P/tOETCCvUnuE2cpkDiOhQfQpAcuQ/9X++KeyC6E6MAAw==")) }, fn_name: "get_actions", parameters: JsonString("{\"collective_address\":\"QmYUZh1MvPpsJSY3kcNghwMUTbxVTAsdhxajtkumt1Yx7N\"}") } crates/core/src/nucleus/actions/call_zome_function.rs:295 actions/call_zome_fn: sending ReturnZomeFunctionResult action.
DEBUG 2020-01-13 02:33:48 [holochain::test-instance] ZomeFnCall { id: ProcessUniqueId { prefix: 16, offset: 288 }, zome_name: "cogov", cap: CapabilityRequest { cap_token: HashString("QmZg2pPuppvav6dUwXKDfZS1QXkdXim6wGYT39HrE4znEt"), provenance: Provenance(HashString("HcScjN8wBwrn3tuyg89aab3a69xsIgdzmX5P9537BqQZ5A7TEZu7qCY4Xzzjhma"), Signature("H32RsvHLY8sKSObSA62w0GBwe0Xb/15cm2Ao02yr/P/tOETCCvUnuE2cpkDiOhQfQpAcuQ/9X++KeyC6E6MAAw==")) }, fn_name: "get_actions", parameters: JsonString("{\"collective_address\":\"QmYUZh1MvPpsJSY3kcNghwMUTbxVTAsdhxajtkumt1Yx7N\"}") } crates/core/src/nucleus/actions/call_zome_function.rs:304 actions/call_zome_fn: sent ReturnZomeFunctionResult action.
#5

Here’s the output for the test, which times out:

☸
02:31:10 info:
☮☮☮ {{{CONDUCTOR alice}}}
☮ DEBUG 2020-01-13 02:31:10 [holochain_net::sim2h_worker] net_worker_thread/puid-4-30 crates/net/src/sim2h_worker.rs:235 WireMessage: queueing ClientToLib3h(PublishEntry(ProvidedEntryData { space_address: SpaceHash(HashString("QmbyqnAJmQZCNeqUJYDAjCCVVHacmLkWdKpgVKcKrnMEiU")), provider_agent_id: AgentPubKey(HashString("HcSCjJZ7qZ4HoifmczAvyJb48HVftd5b58iD7yJk65QbCviq3bDvyHzBh3wmtga")), entry: EntryData { entry_address: EntryHash(HashString("QmRnmJweZynzpQ92jj5fYxnubWNSVpoo7xfXWowshz3ZBi")), aspect_list: [EntryAspectData { aspect_address: AspectHash(HashString("QmVmjWNuydoPQFvYP2ixmNwMbYZ9MF1UsBqia49WrJju1v")), type_hint: "link_add", aspect: "{\"LinkAdd\":[{\"action_kind\":\"ADD\",\"link\":{\"base\":\"QmRnmJweZynzpQ92jj5fYxnubWNSVpoo7xfXWowshz3ZBi\",\"target\":\"QmeGdWo6p28tDAi4Mnmqzq2jgYXXXq1JhNHYN7RsSG8Lzd\",\"link_type\":\"collective_action\",\"tag\":\"create_collective\"},\"top_chain_header\":{\"entry_type\":{\"App\":\"action\"},\"entry_address\":\"QmeGdWo6p28tDAi4Mnmqzq2jgYXXXq1JhNHYN7RsSG8Lzd\",\"provenances\":[[\"HcSCjJZ7qZ4HoifmczAvyJb48HVftd5b58iD7yJk65QbCviq3bDvyHzBh3wmtga\",\"F/3s/3rNP/V2UaOst/wx1QKdh5nRHFjuFeimTDBfX4ciaXLrsavQJ0HK1SW8IFEKQOQX3S4BgcoVxm4QsN4xDg==\"]],\"link\":\"QmaGzq4zDQaNM5uTajyrg8gBJcbc5h8fgWbKJbNyKhNeeX\",\"link_same_type\":null,\"link_update_delete\":null,\"timestamp\":\"2020-01-13T07:31:10+00:00\"},\"agent_id\":{\"nick\":\"alice::cogov::81787673-a1af-4100-a8e7-9a78064e17d3\",\"pub_sign_key\":\"HcSCjJZ7qZ4HoifmczAvyJb48HVftd5b58iD7yJk65QbCviq3bDvyHzBh3wmtga\"}},{\"entry_type\":\"LinkAdd\",\"entry_address\":\"QmT75hgZCsQ8SNUaj32YmnmZAA8ps2Ph4Zuc3a6jzzHmAi\",\"provenances\":[[\"HcSCjJZ7qZ4HoifmczAvyJb48HVftd5b58iD7yJk65QbCviq3bDvyHzBh3wmtga\",\"6QNuuhSj0jRzIUp7+elhSlF5EbWr3mKid4KkVRPiVWYnf2jU1aDJBD1pGq5WVBoB72+iRMY8eJJOZHvBiESxBw==\"]],\"link\":\"QmU8B6SoqG1rXhS3e8Fi3HrDP3K37947BeqCHN2WciXoQd\",\"link_same_type\":\"QmaGzq4zDQaNM5uTajyrg8gBJcbc5h8fgWbKJbNyKhNeeX\",\"link_update_delete\":null,\"timestamp\":\"2020-01-13T07:31:10+00:00\"}]}", publish_ts: 1578900670 }] } }))
☮ DEBUG 2020-01-13 02:31:10 [holochain_metrics::logger] net_worker_thread/puid-4-30 crates/metrics/src/logger.rs:24 2020-01-13 07:31:10  METRIC sim2h_worker.tick.latency 0
☮ DEBUG 2020-01-13 02:31:10 [holochain::cogov] ZomeFnCall { id: ProcessUniqueId { prefix: 7, offset: 10 }, zome_name: "cogov", cap: CapabilityRequest { cap_token: HashString("QmZg2pPuppvav6dUwXKDfZS1QXkdXim6wGYT39HrE4znEt"), provenance: Provenance(HashString("HcSCjJZ7qZ4HoifmczAvyJb48HVftd5b58iD7yJk65QbCviq3bDvyHzBh3wmtga"), Signature("GFTlN+kkESM/Yk1wKZCDgEkXhf23zv8EmbhtgijCRXHu1ysP2d6z0Jqfgl6LDt2aTfvjqPO6DXrmigArrv+4Bg==")) }, fn_name: "create_collective", parameters: JsonString("{\"collective\":{\"name\":\"Collective 1\"}}") } crates/core/src/workflows/author_entry.rs:102 debug/workflow/authoring_entry/QmT75hgZCsQ8SNUaj32YmnmZAA8ps2Ph4Zuc3a6jzzHmAi: header published!
☮ DEBUG 2020-01-13 02:31:10 [holochain_net::sim2h_worker] net_worker_thread/puid-4-30 crates/net/src/sim2h_worker.rs:572 CORE >> Sim2h: PublishEntry(ProvidedEntryData { space_address: SpaceHash(HashString("QmbyqnAJmQZCNeqUJYDAjCCVVHacmLkWdKpgVKcKrnMEiU")), provider_agent_id: AgentPubKey(HashString("HcSCjJZ7qZ4HoifmczAvyJb48HVftd5b58iD7yJk65QbCviq3bDvyHzBh3wmtga")), entry: EntryData { entry_address: EntryHash(HashString("QmUaDnF93rNAHxJbCdFFNMheU1zRA2BtaV8ZnYQZy4pizA")), aspect_list: [EntryAspectData { aspect_address: AspectHash(HashString("Qme7EwxShbY9Ec1fuTRcwf1s6fLcL45NNULKbza6xrGciP")), type_hint: "content", aspect: "{\"Content\":[{\"ChainHeader\":{\"entry_type\":\"LinkAdd\",\"entry_address\":\"QmT75hgZCsQ8SNUaj32YmnmZAA8ps2Ph4Zuc3a6jzzHmAi\",\"provenances\":[[\"HcSCjJZ7qZ4HoifmczAvyJb48HVftd5b58iD7yJk65QbCviq3bDvyHzBh3wmtga\",\"6QNuuhSj0jRzIUp7+elhSlF5EbWr3mKid4KkVRPiVWYnf2jU1aDJBD1pGq5WVBoB72+iRMY8eJJOZHvBiESxBw==\"]],\"link\":\"QmU8B6SoqG1rXhS3e8Fi3HrDP3K37947BeqCHN2WciXoQd\",\"link_same_type\":\"QmaGzq4zDQaNM5uTajyrg8gBJcbc5h8fgWbKJbNyKhNeeX\",\"link_update_delete\":null,\"timestamp\":\"2020-01-13T07:31:10+00:00\"}},{\"entry_type\":\"ChainHeader\",\"entry_address\":\"QmUaDnF93rNAHxJbCdFFNMheU1zRA2BtaV8ZnYQZy4pizA\",\"provenances\":[[\"HcSCjJZ7qZ4HoifmczAvyJb48HVftd5b58iD7yJk65QbCviq3bDvyHzBh3wmtga\",\"4quKBBOugMEHt16593GefE3/lSuCfwb9vAz7lTKeMifqXYBb2T48j9zK0/76ejr0oUB91u64KVx59P/xPZ3CBw==\"]],\"link\":null,\"link_same_type\":null,\"link_update_delete\":null,\"timestamp\":\"2020-01-13T07:31:10+00:00\"}]}", publish_ts: 1578900670 }] } })
☮ DEBUG 2020-01-13 02:31:10 [holochain_net::sim2h_worker] net_worker_thread/puid-4-30 crates/net/src/sim2h_worker.rs:235 WireMessage: queueing ClientToLib3h(PublishEntry(ProvidedEntryData { space_address: SpaceHash(HashString("QmbyqnAJmQZCNeqUJYDAjCCVVHacmLkWdKpgVKcKrnMEiU")), provider_agent_id: AgentPubKey(HashString("HcSCjJZ7qZ4HoifmczAvyJb48HVftd5b58iD7yJk65QbCviq3bDvyHzBh3wmtga")), entry: EntryData { entry_address: EntryHash(HashString("QmUaDnF93rNAHxJbCdFFNMheU1zRA2BtaV8ZnYQZy4pizA")), aspect_list: [EntryAspectData { aspect_address: AspectHash(HashString("Qme7EwxShbY9Ec1fuTRcwf1s6fLcL45NNULKbza6xrGciP")), type_hint: "content", aspect: "{\"Content\":[{\"ChainHeader\":{\"entry_type\":\"LinkAdd\",\"entry_address\":\"QmT75hgZCsQ8SNUaj32YmnmZAA8ps2Ph4Zuc3a6jzzHmAi\",\"provenances\":[[\"HcSCjJZ7qZ4HoifmczAvyJb48HVftd5b58iD7yJk65QbCviq3bDvyHzBh3wmtga\",\"6QNuuhSj0jRzIUp7+elhSlF5EbWr3mKid4KkVRPiVWYnf2jU1aDJBD1pGq5WVBoB72+iRMY8eJJOZHvBiESxBw==\"]],\"link\":\"QmU8B6SoqG1rXhS3e8Fi3HrDP3K37947BeqCHN2WciXoQd\",\"link_same_type\":\"QmaGzq4zDQaNM5uTajyrg8gBJcbc5h8fgWbKJbNyKhNeeX\",\"link_update_delete\":null,\"timestamp\":\"2020-01-13T07:31:10+00:00\"}},{\"entry_type\":\"ChainHeader\",\"entry_address\":\"QmUaDnF93rNAHxJbCdFFNMheU1zRA2BtaV8ZnYQZy4pizA\",\"provenances\":[[\"HcSCjJZ7qZ4HoifmczAvyJb48HVftd5b58iD7yJk65QbCviq3bDvyHzBh3wmtga\",\"4quKBBOugMEHt16593GefE3/lSuCfwb9vAz7lTKeMifqXYBb2T48j9zK0/76ejr0oUB91u64KVx59P/xPZ3CBw==\"]],\"link\":null,\"link_same_type\":null,\"link_update_delete\":null,\"timestamp\":\"2020-01-13T07:31:10+00:00\"}]}", publish_ts: 1578900670 }] } }))
☮ DEBUG 2020-01-13 02:31:10 [holochain_metrics::logger] net_worker_thread/puid-4-30 crates/metrics/src/logger.rs:24 2020-01-13 07:31:10  METRIC sim2h_worker.tick.latency 0
☮ DEBUG 2020-01-13 02:31:10 [holochain::cogov] ZomeFnCall { id: ProcessUniqueId { prefix: 7, offset: 10 }, zome_name: "cogov", cap: CapabilityRequest { cap_token: HashString("QmZg2pPuppvav6dUwXKDfZS1QXkdXim6wGYT39HrE4znEt"), provenance: Provenance(HashString("HcSCjJZ7qZ4HoifmczAvyJb48HVftd5b58iD7yJk65QbCviq3bDvyHzBh3wmtga"), Signature("GFTlN+kkESM/Yk1wKZCDgEkXhf23zv8EmbhtgijCRXHu1ysP2d6z0Jqfgl6LDt2aTfvjqPO6DXrmigArrv+4Bg==")) }, fn_name: "create_collective", parameters: JsonString("{\"collective\":{\"name\":\"Collective 1\"}}") } crates/core/src/nucleus/actions/call_zome_function.rs:288 actions/call_zome_fn: got call_result from ribosome::run_dna.
☮ DEBUG 2020-01-13 02:31:10 [holochain::cogov] ZomeFnCall { id: ProcessUniqueId { prefix: 7, offset: 10 }, zome_name: "cogov", cap: CapabilityRequest { cap_token: HashString("QmZg2pPuppvav6dUwXKDfZS1QXkdXim6wGYT39HrE4znEt"), provenance: Provenance(HashString("HcSCjJZ7qZ4HoifmczAvyJb48HVftd5b58iD7yJk65QbCviq3bDvyHzBh3wmtga"), Signature("GFTlN+kkESM/Yk1wKZCDgEkXhf23zv8EmbhtgijCRXHu1ysP2d6z0Jqfgl6LDt2aTfvjqPO6DXrmigArrv+4Bg==")) }, fn_name: "create_collective", parameters: JsonString("{\"collective\":{\"name\":\"Collective 1\"}}") } crates/core/src/nucleus/actions/call_zome_function.rs:295 actions/call_zome_fn: sending ReturnZomeFunctionResult action.
☮
02:31:10 [tryorama: tryorama conductor alice] debug: -> {
  Ok: {
    collective_address: 'QmRnmJweZynzpQ92jj5fYxnubWNSVpoo7xfXWowshz3ZBi',
    collective: { name: 'Collective 1' }
  }
}
ok 1 collective_address should be truthy
ok 2 collective should be truthy
02:31:10 [tryorama: player alice] debug: call(cogov, cogov, get_collective, {"collective_address":"QmRnmJweZynzpQ92jj5fYxnubWNSVpoo7xfXWowshz3ZBi"})
02:31:10 [tryorama: tryorama conductor alice] debug: zome call [alice]: {id: cogov, zome: cogov, fn: get_collective}
02:31:10 [tryorama: tryorama conductor alice] debug: params: {
  "collective_address": "QmRnmJweZynzpQ92jj5fYxnubWNSVpoo7xfXWowshz3ZBi"
}
02:31:10 [tryorama: tryorama conductor alice] debug: -> {
  Ok: {
    collective_address: 'QmRnmJweZynzpQ92jj5fYxnubWNSVpoo7xfXWowshz3ZBi',
    collective: { name: 'Collective 1' }
  }
}
ok 3 should be equivalent
02:31:10 [tryorama: player alice] debug: call(cogov, cogov, get_actions, {"collective_address":"QmRnmJweZynzpQ92jj5fYxnubWNSVpoo7xfXWowshz3ZBi"})
02:31:10 [tryorama: tryorama conductor alice] debug: zome call [alice]: {id: cogov, zome: cogov, fn: get_actions}
02:31:10 [tryorama: tryorama conductor alice] debug: params: {
  "collective_address": "QmRnmJweZynzpQ92jj5fYxnubWNSVpoo7xfXWowshz3ZBi"
}
02:31:10 info:
☉☉☉ {{{CONDUCTOR alice}}}
☉ DEBUG 2020-01-13 02:31:10 [holochain::cogov] ZomeFnCall { id: ProcessUniqueId { prefix: 7, offset: 10 }, zome_name: "cogov", cap: CapabilityRequest { cap_token: HashString("QmZg2pPuppvav6dUwXKDfZS1QXkdXim6wGYT39HrE4znEt"), provenance: Provenance(HashString("HcSCjJZ7qZ4HoifmczAvyJb48HVftd5b58iD7yJk65QbCviq3bDvyHzBh3wmtga"), Signature("GFTlN+kkESM/Yk1wKZCDgEkXhf23zv8EmbhtgijCRXHu1ysP2d6z0Jqfgl6LDt2aTfvjqPO6DXrmigArrv+4Bg==")) }, fn_name: "create_collective", parameters: JsonString("{\"collective\":{\"name\":\"Collective 1\"}}") } crates/core/src/nucleus/actions/call_zome_function.rs:304 actions/call_zome_fn: sent ReturnZomeFunctionResult action.
☉ DEBUG 2020-01-13 02:31:10 [holochain_metrics::logger] event.loop0 crates/metrics/src/logger.rs:24 2020-01-13 07:31:10  METRIC call_zome_function.cogov.create_collective.latency 175
☉ DEBUG 2020-01-13 02:31:10 [ws::handler]  /home/docker/project/.cargo/registry/src/github.com-1ecc6299db9ec823/ws-0.9.1/src/handler.rs:219 Handler received:
☉ <FRAME>
☉ final: true
☉ reserved: false false false
☉ opcode: TEXT
☉ length: 199
☉ payload length: 195
☉ payload: 0x7b226a736f6e727063223a22322e30222c226d6574686f64223a2263616c6c222c22706172616d73223a7b22696e7374616e63655f6964223a22636f676f76222c227a6f6d65223a22636f676f76222c2266756e6374696f6e223a226765745f636f6c6c656374697665222c2261726773223a7b22636f6c6c6563746976655f61646472657373223a22516d526e6d4a77655a796e7a705139326a6a356659786e7562574e5356706f6f37786658576f7773687a335a4269227d7d2c226964223a357d
☉
☉ DEBUG 2020-01-13 02:31:10 [holochain::cogov] event.loop0 crates/core/src/nucleus/actions/call_zome_function.rs:72 actions/call_zome_fn: Validating call: ZomeFnCall { id: ProcessUniqueId { prefix: 7, offset: 181 }, zome_name: "cogov", cap: CapabilityRequest { cap_token: HashString("QmZg2pPuppvav6dUwXKDfZS1QXkdXim6wGYT39HrE4znEt"), provenance: Provenance(HashString("HcSCjJZ7qZ4HoifmczAvyJb48HVftd5b58iD7yJk65QbCviq3bDvyHzBh3wmtga"), Signature("oafHmiHen2e1HdfaMeO1ecl1orMw9v3gEfsosDrQfSF9+tsCpXtPd2LZjgLT0iPT/Bx++bM/bTAWXZP8zstwBA==")) }, fn_name: "get_collective", parameters: JsonString("{\"collective_address\":\"QmRnmJweZynzpQ92jj5fYxnubWNSVpoo7xfXWowshz3ZBi\"}") }
☉ DEBUG 2020-01-13 02:31:10 [holochain::cogov] event.loop0 crates/core/src/nucleus/actions/call_zome_function.rs:81 actions/call_zome_fn: executing call: ZomeFnCall { id: ProcessUniqueId { prefix: 7, offset: 181 }, zome_name: "cogov", cap: CapabilityRequest { cap_token: HashString("QmZg2pPuppvav6dUwXKDfZS1QXkdXim6wGYT39HrE4znEt"), provenance: Provenance(HashString("HcSCjJZ7qZ4HoifmczAvyJb48HVftd5b58iD7yJk65QbCviq3bDvyHzBh3wmtga"), Signature("oafHmiHen2e1HdfaMeO1ecl1orMw9v3gEfsosDrQfSF9+tsCpXtPd2LZjgLT0iPT/Bx++bM/bTAWXZP8zstwBA==")) }, fn_name: "get_collective", parameters: JsonString("{\"collective_address\":\"QmRnmJweZynzpQ92jj5fYxnubWNSVpoo7xfXWowshz3ZBi\"}") }
☉ DEBUG 2020-01-13 02:31:10 [holochain::cogov] event.loop0 crates/core/src/nucleus/actions/call_zome_function.rs:95 actions/call_zome_fn: awaiting for future call result of ZomeFnCall { id: ProcessUniqueId { prefix: 7, offset: 181 }, zome_name: "cogov", cap: CapabilityRequest { cap_token: HashString("QmZg2pPuppvav6dUwXKDfZS1QXkdXim6wGYT39HrE4znEt"), provenance: Provenance(HashString("HcSCjJZ7qZ4HoifmczAvyJb48HVftd5b58iD7yJk65QbCviq3bDvyHzBh3wmtga"), Signature("oafHmiHen2e1HdfaMeO1ecl1orMw9v3gEfsosDrQfSF9+tsCpXtPd2LZjgLT0iPT/Bx++bM/bTAWXZP8zstwBA==")) }, fn_name: "get_collective", parameters: JsonString("{\"collective_address\":\"QmRnmJweZynzpQ92jj5fYxnubWNSVpoo7xfXWowshz3ZBi\"}") }
☉ ERROR 2020-01-13 02:31:10 [holochain_core::nucleus::reducers::trace_return_hdk_function] action_loop/puid-0-23 crates/core/src/nucleus/reducers/trace_return_hdk_function.rs:22 Attempted to end HDK call, but none was started!
☉ DEBUG 2020-01-13 02:31:10 [holochain::cogov] ZomeFnCall { id: ProcessUniqueId { prefix: 7, offset: 181 }, zome_name: "cogov", cap: CapabilityRequest { cap_token: HashString("QmZg2pPuppvav6dUwXKDfZS1QXkdXim6wGYT39HrE4znEt"), provenance: Provenance(HashString("HcSCjJZ7qZ4HoifmczAvyJb48HVftd5b58iD7yJk65QbCviq3bDvyHzBh3wmtga"), Signature("oafHmiHen2e1HdfaMeO1ecl1orMw9v3gEfsosDrQfSF9+tsCpXtPd2LZjgLT0iPT/Bx++bM/bTAWXZP8zstwBA==")) }, fn_name: "get_collective", parameters: JsonString("{\"collective_address\":\"QmRnmJweZynzpQ92jj5fYxnubWNSVpoo7xfXWowshz3ZBi\"}") } crates/core/src/nucleus/actions/call_zome_function.rs:288 actions/call_zome_fn: got call_result from ribosome::run_dna.
☉ DEBUG 2020-01-13 02:31:10 [holochain::cogov] ZomeFnCall { id: ProcessUniqueId { prefix: 7, offset: 181 }, zome_name: "cogov", cap: CapabilityRequest { cap_token: HashString("QmZg2pPuppvav6dUwXKDfZS1QXkdXim6wGYT39HrE4znEt"), provenance: Provenance(HashString("HcSCjJZ7qZ4HoifmczAvyJb48HVftd5b58iD7yJk65QbCviq3bDvyHzBh3wmtga"), Signature("oafHmiHen2e1HdfaMeO1ecl1orMw9v3gEfsosDrQfSF9+tsCpXtPd2LZjgLT0iPT/Bx++bM/bTAWXZP8zstwBA==")) }, fn_name: "get_collective", parameters: JsonString("{\"collective_address\":\"QmRnmJweZynzpQ92jj5fYxnubWNSVpoo7xfXWowshz3ZBi\"}") } crates/core/src/nucleus/actions/call_zome_function.rs:295 actions/call_zome_fn: sending ReturnZomeFunctionResult action.
☉ DEBUG 2020-01-13 02:31:10 [holochain::cogov] ZomeFnCall { id: ProcessUniqueId { prefix: 7, offset: 181 }, zome_name: "cogov", cap: CapabilityRequest { cap_token: HashString("QmZg2pPuppvav6dUwXKDfZS1QXkdXim6wGYT39HrE4znEt"), provenance: Provenance(HashString("HcSCjJZ7qZ4HoifmczAvyJb48HVftd5b58iD7yJk65QbCviq3bDvyHzBh3wmtga"), Signature("oafHmiHen2e1HdfaMeO1ecl1orMw9v3gEfsosDrQfSF9+tsCpXtPd2LZjgLT0iPT/Bx++bM/bTAWXZP8zstwBA==")) }, fn_name: "get_collective", parameters: JsonString("{\"collective_address\":\"QmRnmJweZynzpQ92jj5fYxnubWNSVpoo7xfXWowshz3ZBi\"}") } crates/core/src/nucleus/actions/call_zome_function.rs:304 actions/call_zome_fn: sent ReturnZomeFunctionResult action.
☉ DEBUG 2020-01-13 02:31:10 [holochain_metrics::logger] event.loop0 crates/metrics/src/logger.rs:24 2020-01-13 07:31:10  METRIC call_zome_function.cogov.get_collective.latency 14
☉ DEBUG 2020-01-13 02:31:10 [ws::handler]  /home/docker/project/.cargo/registry/src/github.com-1ecc6299db9ec823/ws-0.9.1/src/handler.rs:219 Handler received:
☉ <FRAME>
☉ final: true
☉ reserved: false false false
☉ opcode: TEXT
☉ length: 196
☉ payload length: 192
☉ payload: 0x7b226a736f6e727063223a22322e30222c226d6574686f64223a2263616c6c222c22706172616d73223a7b22696e7374616e63655f6964223a22636f676f76222c227a6f6d65223a22636f676f76222c2266756e6374696f6e223a226765745f616374696f6e73222c2261726773223a7b22636f6c6c6563746976655f61646472657373223a22516d526e6d4a77655a796e7a705139326a6a356659786e7562574e5356706f6f37786658576f7773687a335a4269227d7d2c226964223a367d
☉
☉ DEBUG 2020-01-13 02:31:10 [holochain::cogov] event.loop0 crates/core/src/nucleus/actions/call_zome_function.rs:72 actions/call_zome_fn: Validating call: ZomeFnCall { id: ProcessUniqueId { prefix: 7, offset: 219 }, zome_name: "cogov", cap: CapabilityRequest { cap_token: HashString("QmZg2pPuppvav6dUwXKDfZS1QXkdXim6wGYT39HrE4znEt"), provenance: Provenance(HashString("HcSCjJZ7qZ4HoifmczAvyJb48HVftd5b58iD7yJk65QbCviq3bDvyHzBh3wmtga"), Signature("qCbE5cO0HpUXIstL02t0jU79hVHRKIbcwW6FNtcYUOLYzT8DIAoxcpj1Ln4Kimvf3AlqYZlgTjC+T7GZ+q9xAg==")) }, fn_name: "get_actions", parameters: JsonString("{\"collective_address\":\"QmRnmJweZynzpQ92jj5fYxnubWNSVpoo7xfXWowshz3ZBi\"}") }
☉
02:31:38 info:
★★★ {{{CONDUCTOR alice}}}
★ DEBUG 2020-01-13 02:31:10 [holochain::cogov] event.loop0 crates/core/src/nucleus/actions/call_zome_function.rs:81 actions/call_zome_fn: executing call: ZomeFnCall { id: ProcessUniqueId { prefix: 7, offset: 219 }, zome_name: "cogov", cap: CapabilityRequest { cap_token: HashString("QmZg2pPuppvav6dUwXKDfZS1QXkdXim6wGYT39HrE4znEt"), provenance: Provenance(HashString("HcSCjJZ7qZ4HoifmczAvyJb48HVftd5b58iD7yJk65QbCviq3bDvyHzBh3wmtga"), Signature("qCbE5cO0HpUXIstL02t0jU79hVHRKIbcwW6FNtcYUOLYzT8DIAoxcpj1Ln4Kimvf3AlqYZlgTjC+T7GZ+q9xAg==")) }, fn_name: "get_actions", parameters: JsonString("{\"collective_address\":\"QmRnmJweZynzpQ92jj5fYxnubWNSVpoo7xfXWowshz3ZBi\"}") }
★ DEBUG 2020-01-13 02:31:10 [holochain::cogov] event.loop0 crates/core/src/nucleus/actions/call_zome_function.rs:95 actions/call_zome_fn: awaiting for future call result of ZomeFnCall { id: ProcessUniqueId { prefix: 7, offset: 219 }, zome_name: "cogov", cap: CapabilityRequest { cap_token: HashString("QmZg2pPuppvav6dUwXKDfZS1QXkdXim6wGYT39HrE4znEt"), provenance: Provenance(HashString("HcSCjJZ7qZ4HoifmczAvyJb48HVftd5b58iD7yJk65QbCviq3bDvyHzBh3wmtga"), Signature("qCbE5cO0HpUXIstL02t0jU79hVHRKIbcwW6FNtcYUOLYzT8DIAoxcpj1Ln4Kimvf3AlqYZlgTjC+T7GZ+q9xAg==")) }, fn_name: "get_actions", parameters: JsonString("{\"collective_address\":\"QmRnmJweZynzpQ92jj5fYxnubWNSVpoo7xfXWowshz3ZBi\"}") }
★ DEBUG 2020-01-13 02:31:11 [holochain::cogov] ZomeFnCall { id: ProcessUniqueId { prefix: 7, offset: 219 }, zome_name: "cogov", cap: CapabilityRequest { cap_token: HashString("QmZg2pPuppvav6dUwXKDfZS1QXkdXim6wGYT39HrE4znEt"), provenance: Provenance(HashString("HcSCjJZ7qZ4HoifmczAvyJb48HVftd5b58iD7yJk65QbCviq3bDvyHzBh3wmtga"), Signature("qCbE5cO0HpUXIstL02t0jU79hVHRKIbcwW6FNtcYUOLYzT8DIAoxcpj1Ln4Kimvf3AlqYZlgTjC+T7GZ+q9xAg==")) }, fn_name: "get_actions", parameters: JsonString("{\"collective_address\":\"QmRnmJweZynzpQ92jj5fYxnubWNSVpoo7xfXWowshz3ZBi\"}") } crates/core/src/nucleus/ribosome/api/get_links.rs:19 zome/get_links: invoke_get_links called with GetLinksArgs { entry_address: HashString("QmRnmJweZynzpQ92jj5fYxnubWNSVpoo7xfXWowshz3ZBi"), link_type: "^collective_action$", tag: ".*", options: GetLinksOptions { status_request: Live, headers: false, timeout: Timeout(60000) } }
★ DEBUG 2020-01-13 02:31:11 [holochain_net::sim2h_worker] net_worker_thread/puid-4-30 crates/net/src/sim2h_worker.rs:572 CORE >> Sim2h: QueryEntry(QueryEntryData { space_address: SpaceHash(HashString("QmbyqnAJmQZCNeqUJYDAjCCVVHacmLkWdKpgVKcKrnMEiU")), entry_address: EntryHash(HashString("QmRnmJweZynzpQ92jj5fYxnubWNSVpoo7xfXWowshz3ZBi")), request_id: "puid-a-2", requester_agent_id: AgentPubKey(HashString("HcSCjJZ7qZ4HoifmczAvyJb48HVftd5b58iD7yJk65QbCviq3bDvyHzBh3wmtga")), query: "{\"GetLinks\":[\"^collective_action$\",\".*\",\"live\",{\"Links\":{\"headers\":false}}]}" })
★ DEBUG 2020-01-13 02:31:11 [holochain_net::sim2h_worker] net_worker_thread/puid-4-30 crates/net/src/sim2h_worker.rs:235 WireMessage: queueing ClientToLib3h(QueryEntry(QueryEntryData { space_address: SpaceHash(HashString("QmbyqnAJmQZCNeqUJYDAjCCVVHacmLkWdKpgVKcKrnMEiU")), entry_address: EntryHash(HashString("QmRnmJweZynzpQ92jj5fYxnubWNSVpoo7xfXWowshz3ZBi")), request_id: "puid-a-2", requester_agent_id: AgentPubKey(HashString("HcSCjJZ7qZ4HoifmczAvyJb48HVftd5b58iD7yJk65QbCviq3bDvyHzBh3wmtga")), query: "{\"GetLinks\":[\"^collective_action$\",\".*\",\"live\",{\"Links\":{\"headers\":false}}]}" }))
★ DEBUG 2020-01-13 02:31:11 [holochain_metrics::logger] net_worker_thread/puid-4-30 crates/metrics/src/logger.rs:24 2020-01-13 07:31:11  METRIC sim2h_worker.tick.latency 0
★ WARN 2020-01-13 02:31:14 [in_stream::tcp] net_worker_thread/puid-4-30 crates/in_stream/src/tcp.rs:293 dropping tcp stream Url2 { url: "tcp://localhost:9000/" }
★ ERROR 2020-01-13 02:31:14 [holochain_net::sim2h_worker] net_worker_thread/puid-4-30 crates/net/src/sim2h_worker.rs:174 connection handshake error: Custom { kind: ConnectionRefused, error: "wss_cli: HandshakeError::Failure(Io(Kind(TimedOut)))" }
★ WARN 2020-01-13 02:31:14 [holochain_net::sim2h_worker] net_worker_thread/puid-4-30 crates/net/src/sim2h_worker.rs:153 BACKOFF attempting reconnect, connection state: None
★ DEBUG 2020-01-13 02:31:14 [holochain_net::sim2h_worker] net_worker_thread/puid-4-30 crates/net/src/sim2h_worker.rs:127 BACKOFF setting reconnect interval to 8000
★ DEBUG 2020-01-13 02:31:19 [holochain_locksmith::tracker] locksmith_guard_watcher/puid-0-0 crates/locksmith/src/tracker.rs:126 no active guards alive > 1000ms for the last 10 seconds
★ WARN 2020-01-13 02:31:22 [holochain_net::sim2h_worker] net_worker_thread/puid-4-30 crates/net/src/sim2h_worker.rs:153 BACKOFF attempting reconnect, connection state: Some(InStreamWss { state: Some(MidCliHandshake(MidHandshake { role: ClientHandshake { verify_data: VerifyData { accept_key: "RrpvczOJEdEcjgCgzjJkEfWJWqY=" }, config: None, _marker: PhantomData }, machine: HandshakeMachine { stream: StdStreamAdapter { stream: InStreamTcp { stream: TcpStream { addr: V4(127.0.0.1:39236), fd: 7 }, url: Url2 { url: "tcp://localhost:9000/" }, connecting: Some(TcpConnectingData { addr: V4(127.0.0.1:9000), connect_timeout: Some(Instant { tv_sec: 221551, tv_nsec: 287184187 }) }), write_buf: [71, 69, 84, 32, 47, 32, 72, 84, 84, 80, 47, 49, 46, 49, 13, 10, 72, 111, 115, 116, 58, 32, 108, 111, 99, 97, 108, 104, 111, 115, 116, 58, 57, 48, 48, 48, 13, 10, 67, 111, 110, 110, 101, 99, 116, 105, 111, 110, 58, 32, 85, 112, 103, 114, 97, 100, 101, 13, 10, 85, 112, 103, 114, 97, 100, 101, 58, 32, 119, 101, 98, 115, 111, 99, 107, 101, 116, 13, 10, 83, 101, 99, 45, 87, 101, 98, 83, 111, 99, 107, 101, 116, 45, 86, 101, 114, 115, 105, 111, 110, 58, 32, 49, 51, 13, 10, 83, 101, 99, 45, 87, 101, 98, 83, 111, 99, 107, 101, 116, 45, 75, 101, 121, 58, 32, 70, 99, 116, 112, 82, 56, 79, 48, 65, 66, 43, 87, 98, 53, 79, 51, 114, 84, 116, 70, 43, 103, 61, 61, 13, 10, 13, 10] } }, state: Reading(InputBuffer(Cursor { inner: [], pos: 0 })) } })), remote_url: Url2 { url: "ws://localhost:9000/" }, write_buf: [] })
★ DEBUG 2020-01-13 02:31:22 [holochain_net::sim2h_worker] net_worker_thread/puid-4-30 crates/net/src/sim2h_worker.rs:127 BACKOFF setting reconnect interval to 16000
★ WARN 2020-01-13 02:31:22 [in_stream::tcp] net_worker_thread/puid-4-30 crates/in_stream/src/tcp.rs:293 dropping tcp stream Url2 { url: "tcp://localhost:9000/" }
★ DEBUG 2020-01-13 02:31:30 [holochain_locksmith::tracker] locksmith_guard_watcher/puid-0-0 crates/locksmith/src/tracker.rs:126 no active guards alive > 1000ms for the last 10 seconds
★ WARN 2020-01-13 02:31:38 [in_stream::tcp] net_worker_thread/puid-4-30 crates/in_stream/src/tcp.rs:293 dropping tcp stream Url2 { url: "tcp://localhost:9000/" }
★ ERROR 2020-01-13 02:31:38 [holochain_net::sim2h_worker] net_worker_thread/puid-4-30 crates/net/src/sim2h_worker.rs:174 connection handshake error: Custom { kind: ConnectionRefused, error: "wss_cli: HandshakeError::Failure(Io(Kind(TimedOut)))" }
★ WARN 2020-01-13 02:31:38 [holochain_net::sim2h_worker] net_worker_thread/puid-4-30 crates/net/src/sim2h_worker.rs:153 BACKOFF attempting reconnect, connection state: None
★
02:31:55 [tryorama: tryorama conductor alice] warn: Zome call 'cogov/get_actions' has been running for more than 45 seconds. Continuing to wait...
02:32:11 [tryorama: tryorama conductor alice] debug: -> {
  Err: {
    Internal: '{"kind":"Timeout","file":"crates/core/src/nucleus/ribosome/runtime.rs","line":"220"}'
  }
}
not ok 4 should be equivalent
  ---
    operator: deepEqual
    expected: |-
      { Ok: [ { collective_address: 'QmRnmJweZynzpQ92jj5fYxnubWNSVpoo7xfXWowshz3ZBi', collective: { name: 'Collective 1' } } ] }
    actual: |-
      { Err: { Internal: '{"kind":"Timeout","file":"crates/core/src/nucleus/ribosome/runtime.rs","line":"220"}' } }
    at: assert_actions (/home/brian/work/cogov/cogov-dev/test/index.js:56:6)
    stack: |-
      Error: should be equivalent
          at Test.assert [as _assert] (/home/brian/work/cogov/cogov-dev/test/node_modules/tape/lib/test.js:226:54)
          at Test.bound [as _assert] (/home/brian/work/cogov/cogov-dev/test/node_modules/tape/lib/test.js:78:32)
          at Test.tapeDeepEqual (/home/brian/work/cogov/cogov-dev/test/node_modules/tape/lib/test.js:424:10)
          at Test.bound [as deepEqual] (/home/brian/work/cogov/cogov-dev/test/node_modules/tape/lib/test.js:78:32)
          at assert_actions (/home/brian/work/cogov/cogov-dev/test/index.js:56:6)
          at processTicksAndRejections (internal/process/task_queues.js:93:5)
          at async /home/brian/work/cogov/cogov-dev/test/index.js:24:3
  ...
success for  create_collective; get_collective
02:32:11 [tryorama] debug: Done with test: create_collective; get_collective
02:32:11 [tryorama: player alice] debug: Killing...
02:32:11 [tryorama: tryorama conductor alice] debug: Killing...
02:32:11 info:
☯☯☯ [[[CONDUCTOR alice]]]
☯ Gracefully shutting down conductor...
☯ Stopping interface tryorama-interface
☯ Stopping instance "cogov"...
☯
02:32:11 [tryorama: player alice] debug: Killed.
{ successes: 1, errors: [] }
02:32:13 info:
☸☸☸ {{{CONDUCTOR alice}}}
☸ DEBUG 2020-01-13 02:31:38 [holochain_net::sim2h_worker] net_worker_thread/puid-4-30 crates/net/src/sim2h_worker.rs:127 BACKOFF setting reconnect interval to 32000
☸ DEBUG 2020-01-13 02:31:41 [holochain_locksmith::tracker] locksmith_guard_watcher/puid-0-0 crates/locksmith/src/tracker.rs:126 no active guards alive > 1000ms for the last 10 seconds
☸ DEBUG 2020-01-13 02:31:52 [holochain_locksmith::tracker] locksmith_guard_watcher/puid-0-0 crates/locksmith/src/tracker.rs:126 no active guards alive > 1000ms for the last 10 seconds
☸ DEBUG 2020-01-13 02:32:03 [holochain_locksmith::tracker] locksmith_guard_watcher/puid-0-0 crates/locksmith/src/tracker.rs:126 no active guards alive > 1000ms for the last 10 seconds
☸ WARN 2020-01-13 02:32:10 [in_stream::tcp] net_worker_thread/puid-4-30 crates/in_stream/src/tcp.rs:293 dropping tcp stream Url2 { url: "tcp://localhost:9000/" }
☸ ERROR 2020-01-13 02:32:10 [holochain_net::sim2h_worker] net_worker_thread/puid-4-30 crates/net/src/sim2h_worker.rs:174 connection handshake error: Custom { kind: ConnectionRefused, error: "wss_cli: HandshakeError::Failure(Io(Kind(TimedOut)))" }
☸ WARN 2020-01-13 02:32:10 [holochain_net::sim2h_worker] net_worker_thread/puid-4-30 crates/net/src/sim2h_worker.rs:153 BACKOFF attempting reconnect, connection state: None
☸ DEBUG 2020-01-13 02:32:10 [holochain_net::sim2h_worker] net_worker_thread/puid-4-30 crates/net/src/sim2h_worker.rs:127 BACKOFF setting reconnect interval to 64000
☸ ERROR 2020-01-13 02:32:11 [holochain_core::nucleus::reducers::trace_return_hdk_function] action_loop/puid-0-23 crates/core/src/nucleus/reducers/trace_return_hdk_function.rs:22 Attempted to end HDK call, but none was started!
☸ DEBUG 2020-01-13 02:32:11 [holochain::cogov] ZomeFnCall { id: ProcessUniqueId { prefix: 7, offset: 219 }, zome_name: "cogov", cap: CapabilityRequest { cap_token: HashString("QmZg2pPuppvav6dUwXKDfZS1QXkdXim6wGYT39HrE4znEt"), provenance: Provenance(HashString("HcSCjJZ7qZ4HoifmczAvyJb48HVftd5b58iD7yJk65QbCviq3bDvyHzBh3wmtga"), Signature("qCbE5cO0HpUXIstL02t0jU79hVHRKIbcwW6FNtcYUOLYzT8DIAoxcpj1Ln4Kimvf3AlqYZlgTjC+T7GZ+q9xAg==")) }, fn_name: "get_actions", parameters: JsonString("{\"collective_address\":\"QmRnmJweZynzpQ92jj5fYxnubWNSVpoo7xfXWowshz3ZBi\"}") } crates/core/src/nucleus/actions/call_zome_function.rs:288 actions/call_zome_fn: got call_result from ribosome::run_dna.
☸ DEBUG 2020-01-13 02:32:11 [holochain::cogov] ZomeFnCall { id: ProcessUniqueId { prefix: 7, offset: 219 }, zome_name: "cogov", cap: CapabilityRequest { cap_token: HashString("QmZg2pPuppvav6dUwXKDfZS1QXkdXim6wGYT39HrE4znEt"), provenance: Provenance(HashString("HcSCjJZ7qZ4HoifmczAvyJb48HVftd5b58iD7yJk65QbCviq3bDvyHzBh3wmtga"), Signature("qCbE5cO0HpUXIstL02t0jU79hVHRKIbcwW6FNtcYUOLYzT8DIAoxcpj1Ln4Kimvf3AlqYZlgTjC+T7GZ+q9xAg==")) }, fn_name: "get_actions", parameters: JsonString("{\"collective_address\":\"QmRnmJweZynzpQ92jj5fYxnubWNSVpoo7xfXWowshz3ZBi\"}") } crates/core/src/nucleus/actions/call_zome_function.rs:295 actions/call_zome_fn: sending ReturnZomeFunctionResult action.
☸ DEBUG 2020-01-13 02:32:11 [holochain::cogov] ZomeFnCall { id: ProcessUniqueId { prefix: 7, offset: 219 }, zome_name: "cogov", cap: CapabilityRequest { cap_token: HashString("QmZg2pPuppvav6dUwXKDfZS1QXkdXim6wGYT39HrE4znEt"), provenance: Provenance(HashString("HcSCjJZ7qZ4HoifmczAvyJb48HVftd5b58iD7yJk65QbCviq3bDvyHzBh3wmtga"), Signature("qCbE5cO0HpUXIstL02t0jU79hVHRKIbcwW6FNtcYUOLYzT8DIAoxcpj1Ln4Kimvf3AlqYZlgTjC+T7GZ+q9xAg==")) }, fn_name: "get_actions", parameters: JsonString("{\"collective_address\":\"QmRnmJweZynzpQ92jj5fYxnubWNSVpoo7xfXWowshz3ZBi\"}") } crates/core/src/nucleus/actions/call_zome_function.rs:304 actions/call_zome_fn: sent ReturnZomeFunctionResult action.
☸ DEBUG 2020-01-13 02:32:11 [holochain_metrics::logger] event.loop0 crates/metrics/src/logger.rs:24 2020-01-13 07:31:10  METRIC call_zome_function.cogov.get_actions.latency 60534
☸ DEBUG 2020-01-13 02:32:11 [ws::io]  /home/docker/project/.cargo/registry/src/github.com-1ecc6299db9ec823/ws-0.9.1/src/io.rs:544 Received shutdown signal. WebSocket is attempting to shut down.
☸ DEBUG 2020-01-13 02:32:11 [ws::handler]  /home/docker/project/.cargo/registry/src/github.com-1ecc6299db9ec823/ws-0.9.1/src/handler.rs:26 Handler received WebSocket shutdown request.
☸ DEBUG 2020-01-13 02:32:11 [ws::factory]  /home/docker/project/.cargo/registry/src/github.com-1ecc6299db9ec823/ws-0.9.1/src/factory.rs:14 Factory received WebSocket shutdown request.
☸ DEBUG 2020-01-13 02:32:11 [holochain_net::sim2h_worker] net_worker_thread/puid-4-30 crates/net/src/sim2h_worker.rs:572 CORE >> Sim2h: LeaveSpace(SpaceData { request_id: "puid-4-17f", space_address: SpaceHash(HashString("QmbyqnAJmQZCNeqUJYDAjCCVVHacmLkWdKpgVKcKrnMEiU")), agent_id: AgentPubKey(HashString("HcSCjJZ7qZ4HoifmczAvyJb48HVftd5b58iD7yJk65QbCviq3bDvyHzBh3wmtga")) })
☸ DEBUG 2020-01-13 02:32:11 [holochain_net::sim2h_worker] net_worker_thread/puid-4-30 crates/net/src/sim2h_worker.rs:235 WireMessage: queueing ClientToLib3h(LeaveSpace(SpaceData { request_id: "puid-4-17f", space_address: SpaceHash(HashString("QmbyqnAJmQZCNeqUJYDAjCCVVHacmLkWdKpgVKcKrnMEiU")), agent_id: AgentPubKey(HashString("HcSCjJZ7qZ4HoifmczAvyJb48HVftd5b58iD7yJk65QbCviq3bDvyHzBh3wmtga")) }))
☸ DEBUG 2020-01-13 02:32:11 [holochain_metrics::logger] net_worker_thread/puid-4-30 crates/metrics/src/logger.rs:24 2020-01-13 07:32:11  METRIC sim2h_worker.tick.latency 0
☸ DEBUG 2020-01-13 02:32:12 [holochain_locksmith::tracker] locksmith_guard_watcher/puid-0-0 crates/locksmith/src/tracker.rs:116 tracking 3 active guard(s) alive for > 1000ms:
☸ KIND       PUID      ELAPSED (ms)
☸ Lock   puid-0-8b         1292
☸ Write  puid-0-8c         1292
☸ Write  puid-4-17e         1291
☸ DEBUG 2020-01-13 02:32:13 [holochain_net::connection::net_connection_thread] action_loop/puid-0-23 crates/net/src/connection/net_connection_thread.rs:154 Telling NetWorker to stop
☸
02:32:13 info:
☮☮☮ {{{CONDUCTOR alice}}}
☮ thread 'thread 'thread 'stats<unnamed>holding_loop/puid-0-24' panicked at '' panicked at '' panicked at 'Tried to use dropped stateTried to use dropped stateTried to use dropped state', ', ', src/libcore/option.rssrc/libcore/option.rssrc/libcore/option.rs:::118711871187:::555
☮
☮
☮ stack backtrace:
☮
02:32:13 [tryorama] info: conductor 'alice' exited with code 0

1..4
# tests 4
# pass  3
# fail  1

Error: command node test/index.js was not successful
#6

I had a discussion with @rayzer. One workaround is to run the development node & run a “functional” test off of the dev node. Of course, an issue is consistency can only be tested with multiple nodes.

@freesig I’m not familiar with the setup between the test & development nodes. I’m wondering what the issues are. Is a test node a separate process for example?

#7

Hi I just cloned your repo and ran hc test on master with sim2h-server running like: sim2h-server -s 0 and I did not get the timeouts.

Could you try firstly running sim2h-server with -s 0
If that doesn’t work could you please describe how you are running these tests?

#8

Thank you for running the tests @freesig. I commented out the api request that caused the timeout. To reproduce, please use the test-timeout branch.

I ran the test using hc test in the nix environment:

I havn’t used sim2h-server. Having issues installing it. I’m using rust-nightly from rustup.

$ cargo install -f sim2h_server
    Updating crates.io index
error: could not find `sim2h_server` in registry `https://github.com/rust-lang/crates.io-index`
#9

Ok I’ll try that.
Also FYI sim2h_server is available in the nix-shell. Also I made a typo, it’s not sim2h-server it’s sim2h_server.