output.log from micro_blog test command

output.log

Packaging files for testing to file: "/home/simwilso/Code/TestDemo/txrx/dist/txrx.dna.json"
> CARGO_TARGET_DIR=${CARGO_TARGET_DIR:-/tmp/my_first_app/target} && echo $CARGO_TARGET_DIR 
"CARGO_TARGET_DIR=${CARGO_TARGET_DIR:-/tmp/my_first_app/target} && echo $CARGO_TARGET_DIR "
/home/simwilso/Code/TestDemo/txrx/target
> CARGO_TARGET_DIR=${CARGO_TARGET_DIR:-/tmp/my_first_app/target} && cargo build --release --target=wasm32-unknown-unknown --target-dir=$CARGO_TARGET_DIR
"CARGO_TARGET_DIR=${CARGO_TARGET_DIR:-/tmp/my_first_app/target} && cargo build --release --target=wasm32-unknown-unknown --target-dir=$CARGO_TARGET_DIR"
> CARGO_TARGET_DIR=${CARGO_TARGET_DIR:-/tmp/my_first_app/target} && wasm-gc $CARGO_TARGET_DIR/wasm32-unknown-unknown/release/txrx.wasm
"CARGO_TARGET_DIR=${CARGO_TARGET_DIR:-/tmp/my_first_app/target} && wasm-gc $CARGO_TARGET_DIR/wasm32-unknown-unknown/release/txrx.wasm"
> CARGO_TARGET_DIR=${CARGO_TARGET_DIR:-/tmp/my_first_app/target} && wasm-opt -Oz --vacuum $CARGO_TARGET_DIR/wasm32-unknown-unknown/release/txrx.wasm
"CARGO_TARGET_DIR=${CARGO_TARGET_DIR:-/tmp/my_first_app/target} && wasm-opt -Oz --vacuum $CARGO_TARGET_DIR/wasm32-unknown-unknown/release/txrx.wasm"
> CARGO_TARGET_DIR=${CARGO_TARGET_DIR:-/tmp/my_first_app/target} && wasm2wat $CARGO_TARGET_DIR/wasm32-unknown-unknown/release/txrx.wasm -o $CARGO_TARGET_DIR/wasm32-unknown-unknown/release/txrx.wat
"CARGO_TARGET_DIR=${CARGO_TARGET_DIR:-/tmp/my_first_app/target} && wasm2wat $CARGO_TARGET_DIR/wasm32-unknown-unknown/release/txrx.wasm -o $CARGO_TARGET_DIR/wasm32-unknown-unknown/release/txrx.wat"
> CARGO_TARGET_DIR=${CARGO_TARGET_DIR:-/tmp/my_first_app/target} && wat2wasm $CARGO_TARGET_DIR/wasm32-unknown-unknown/release/txrx.wat -o $CARGO_TARGET_DIR/wasm32-unknown-unknown/release/txrx.wasm
"CARGO_TARGET_DIR=${CARGO_TARGET_DIR:-/tmp/my_first_app/target} && wat2wasm $CARGO_TARGET_DIR/wasm32-unknown-unknown/release/txrx.wat -o $CARGO_TARGET_DIR/wasm32-unknown-unknown/release/txrx.wasm"
> CARGO_TARGET_DIR=${CARGO_TARGET_DIR:-/tmp/my_first_app/target} && echo $CARGO_TARGET_DIR 
"CARGO_TARGET_DIR=${CARGO_TARGET_DIR:-/tmp/my_first_app/target} && echo $CARGO_TARGET_DIR "
/home/simwilso/Code/TestDemo/txrx/target
> CARGO_TARGET_DIR=${CARGO_TARGET_DIR:-/tmp/my_first_app/target} && cargo build --release --target=wasm32-unknown-unknown --target-dir=$CARGO_TARGET_DIR
"CARGO_TARGET_DIR=${CARGO_TARGET_DIR:-/tmp/my_first_app/target} && cargo build --release --target=wasm32-unknown-unknown --target-dir=$CARGO_TARGET_DIR"
> CARGO_TARGET_DIR=${CARGO_TARGET_DIR:-/tmp/my_first_app/target} && wasm-gc $CARGO_TARGET_DIR/wasm32-unknown-unknown/release/txrx.wasm
"CARGO_TARGET_DIR=${CARGO_TARGET_DIR:-/tmp/my_first_app/target} && wasm-gc $CARGO_TARGET_DIR/wasm32-unknown-unknown/release/txrx.wasm"
> CARGO_TARGET_DIR=${CARGO_TARGET_DIR:-/tmp/my_first_app/target} && wasm-opt -Oz --vacuum $CARGO_TARGET_DIR/wasm32-unknown-unknown/release/txrx.wasm
"CARGO_TARGET_DIR=${CARGO_TARGET_DIR:-/tmp/my_first_app/target} && wasm-opt -Oz --vacuum $CARGO_TARGET_DIR/wasm32-unknown-unknown/release/txrx.wasm"
> CARGO_TARGET_DIR=${CARGO_TARGET_DIR:-/tmp/my_first_app/target} && wasm2wat $CARGO_TARGET_DIR/wasm32-unknown-unknown/release/txrx.wasm -o $CARGO_TARGET_DIR/wasm32-unknown-unknown/release/txrx.wat
"CARGO_TARGET_DIR=${CARGO_TARGET_DIR:-/tmp/my_first_app/target} && wasm2wat $CARGO_TARGET_DIR/wasm32-unknown-unknown/release/txrx.wasm -o $CARGO_TARGET_DIR/wasm32-unknown-unknown/release/txrx.wat"
> CARGO_TARGET_DIR=${CARGO_TARGET_DIR:-/tmp/my_first_app/target} && wat2wasm $CARGO_TARGET_DIR/wasm32-unknown-unknown/release/txrx.wat -o $CARGO_TARGET_DIR/wasm32-unknown-unknown/release/txrx.wasm
"CARGO_TARGET_DIR=${CARGO_TARGET_DIR:-/tmp/my_first_app/target} && wat2wasm $CARGO_TARGET_DIR/wasm32-unknown-unknown/release/txrx.wat -o $CARGO_TARGET_DIR/wasm32-unknown-unknown/release/txrx.wasm"
Created DNA package file at "/home/simwilso/Code/TestDemo/txrx/dist/txrx.dna.json"
DNA hash: QmUuWbf1wJ9oSzspEwPJ3UnNuMYjn3XTmVmXZ2z9sAUSLv
Running tests in test/index.js
> node test/index.js
"node test/index.js"
16:18:58 [tryorama] info: Using the following settings from environment variables:
16:18:58 [tryorama] info: {
  "interfaceId": "tryorama-interface",
  "stateDumpOnError": true,
  "zomeCallTimeoutMs": 90000,
  "conductorTimeoutMs": 125000,
  "strictConductorTimeout": false,
  "chooseFreePort": false,
  "portRange": [
    33000,
    34000
  ]
}
16:18:58 [tryorama] debug: About to execute 1 tests
TAP version 13
# Test hello holo
16:18:58 [tryorama] debug: api.players: creating players
16:18:58 [tryorama] debug: api.players: seed args generated for alice = {"configDir":"/tmp/tmp.dwX71VMUbB/tryorama/tNTJpj","interfacePort":33000,"scenarioName":"Test hello holo","playerName":"alice","uuid":"2ea86eb8-9551-4f12-9485-774a744c9ebc"}
16:18:58 [tryorama] debug: api.players: seed args generated for bob = {"configDir":"/tmp/tmp.dwX71VMUbB/tryorama/k1XEN8","interfacePort":33001,"scenarioName":"Test hello holo","playerName":"bob","uuid":"2ea86eb8-9551-4f12-9485-774a744c9ebc"}
16:18:58 [tryorama] debug: api.players: unique agent name check passed
16:18:58 [tryorama] debug: api.players: player config committed for bob
16:18:58 [tryorama] debug: api.players: player config committed for alice
16:18:58 [tryorama] debug: api.players: players built
16:18:58 [tryorama] info: api.players: auto-spawning player alice
16:18:58 [tryorama: player alice] debug: spawning
16:18:58 [tryorama] info: Using conductor path: holochain
16:18:58 [tryorama] info: Holochain version: holochain 0.0.42-alpha5

16:18:58 info: 
☉☉☉ [[[CONDUCTOR alice]]]
☉ Using config path: /tmp/tmp.dwX71VMUbB/tryorama/tNTJpj/conductor-config.toml
☉ 
16:18:58 info: 
★★★ [[[CONDUCTOR alice]]]
★ Reading DNA from /home/simwilso/Code/TestDemo/txrx/dist/txrx.dna.json
★ 
16:18:58 info: 
☯☯☯ [[[CONDUCTOR alice]]]
☯ Unlocking agent keys:
☯ Unlocking key for agent 'txrx': 
☯ 
16:18:58 info: 
☸☸☸ [[[CONDUCTOR alice]]]
☸ conductor: boot_from_config
☸ Reading DNA from /home/simwilso/Code/TestDemo/txrx/dist/txrx.dna.json
☸ 
16:18:58 info: 
☮☮☮ [[[CONDUCTOR alice]]]
☮ Reading DNA from /home/simwilso/Code/TestDemo/txrx/dist/txrx.dna.json
☮ 
16:18:58 info: 
☉☉☉ [[[CONDUCTOR alice]]]
☉ conductor: build_conductor_api instance_id=txrx, config=Configuration { agents: [AgentConfiguration { id: "txrx", name: "alice::txrx::2ea86eb8-9551-4f12-9485-774a744c9ebc", public_address: "HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra", keystore_file: "[UNUSED]", holo_remote_key: None, test_agent: Some(true) }], dnas: [DnaConfiguration { id: "txrx", file: "/home/simwilso/Code/TestDemo/txrx/dist/txrx.dna.json", hash: "QmUuWbf1wJ9oSzspEwPJ3UnNuMYjn3XTmVmXZ2z9sAUSLv", uuid: Some("2ea86eb8-9551-4f12-9485-774a744c9ebc") }], instances: [InstanceConfiguration { id: "txrx", dna: "txrx", agent: "txrx", storage: Lmdb { path: "/tmp/tmp.dwX71VMUbB/tryorama/tNTJpj/txrx", initial_mmap_bytes: None } }], interfaces: [InterfaceConfiguration { id: "tryorama-interface", driver: Websocket { port: 33000 }, admin: true, instances: [InstanceReferenceConfiguration { id: "txrx", alias: None }], choose_free_port: Some(false) }], bridges: [], ui_bundles: [], ui_interfaces: [], logger: LoggerConfiguration { logger_level: "debug", rules: LogRules { rules: [LogRule { pattern: ^parity, exclude: true, color: None }, LogRule { pattern: ^mio, exclude: true, color: None }, LogRule { pattern: ^tokio, exclude: true, color: None }, LogRule { pattern: ^hyper, exclude: true, color: None }, LogRule { pattern: ^rusoto_core, exclude: true, color: None }, LogRule { pattern: ^want, exclude: true, color: None }, LogRule { pattern: ^rpc, exclude: true, color: None }, LogRule { pattern: ^holochain, exclude: false, color: None }, LogRule { pattern: ^lib3h, exclude: false, color: None }] }, state_dump: false }, network: Some(Sim2h(Sim2hConfig { sim2h_url: "ws://localhost:9000" })), persistence_dir: "/tmp/tmp.dwX71VMUbB/tryorama/tNTJpj", signing_service_uri: None, encryption_service_uri: None, decryption_service_uri: None, dpki: None, signals: SignalConfig { trace: false, consistency: true }, passphrase_service: Cmd, metric_publisher: None }
☉ 
16:18:58 info: 
★★★ [[[CONDUCTOR alice]]]
★ Reading DNA from /home/simwilso/Code/TestDemo/txrx/dist/txrx.dna.json
★ 
16:18:59 info: 
☯☯☯ [[[CONDUCTOR alice]]]
☯ Failed to load instance txrx from storage: ErrorGeneric("State could not be loaded due to NoneError")
☯ Initializing new chain...
☯ 
16:18:59 info: 
☸☸☸ [[[CONDUCTOR alice]]]
☸ Successfully loaded 1 instance configurations
☸ Starting instances...
☸ Start all instances
☸ 
16:18:59 info: 
☮☮☮ [[[CONDUCTOR alice]]]
☮ Starting instance "txrx"...
☮ Starting interfaces...
☮ *** Bound interface 'tryorama-interface' to port: 33000
☮ 
16:18:59 [tryorama] info: Conductor 'alice' process spawning successful. Interface port detected: 33000
16:18:59 [tryorama] debug: (stdout line parsed: Starting instance "txrx"...
Starting interfaces...
*** Bound interface 'tryorama-interface' to port: 33000
)
16:18:59 [tryorama: tryorama conductor alice] debug: Conductor constructing
16:18:59 [tryorama: player alice] debug: spawned
16:18:59 [tryorama: player alice] debug: initializing
16:18:59 [tryorama: tryorama conductor alice] debug: connectInterface :: connecting to ws://localhost:33000
16:18:59 info: 
☉☉☉ [[[CONDUCTOR alice]]]
☉ *** Done. All interfaces started.
☉ Starting UI servers
☉ Starting all servers
☉ 
16:18:59 [tryorama: tryorama conductor alice] debug: connectInterface :: connected to ws://localhost:33000
16:18:59 [tryorama: tryorama conductor alice] debug: [setup call on alice]: admin/agent/list
16:18:59 [tryorama: tryorama conductor alice] debug: {}
16:18:59 [tryorama: tryorama conductor alice] debug: -> [
  {
    id: 'txrx',
    name: 'alice::txrx::2ea86eb8-9551-4f12-9485-774a744c9ebc',
    public_address: 'HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra',
    keystore_file: '[UNUSED]',
    holo_remote_key: null,
    test_agent: true
  },
  [length]: 1
]
16:18:59 [tryorama: tryorama conductor alice] debug: [setup call on alice]: admin/dna/list
16:18:59 [tryorama: tryorama conductor alice] debug: {}
16:18:59 [tryorama: tryorama conductor alice] debug: -> [
  {
    id: 'txrx',
    hash: 'QmRXwCKqhcdga3e2LwGwT4maYpwQMudJ9zvLFcsQv3asFU'
  },
  [length]: 1
]
16:18:59 [tryorama: tryorama conductor alice] debug: [setup call on alice]: admin/instance/list
16:18:59 [tryorama: tryorama conductor alice] debug: {}
16:18:59 [tryorama: tryorama conductor alice] debug: -> [ { id: 'txrx', dna: 'txrx', agent: 'txrx' }, [length]: 1 ]
16:18:59 [tryorama: player alice] debug: initialized
16:18:59 [tryorama] info: api.players: awaiting consistency while spawning player alice
16:18:59 [tryorama] info: api.players: spawn complete for alice
16:18:59 [tryorama] info: api.players: auto-spawning player bob
16:18:59 [tryorama: player bob] debug: spawning
16:18:59 [tryorama] info: Using conductor path: holochain
16:18:59 [tryorama] info: Holochain version: holochain 0.0.42-alpha5

16:18:59 info: 
★★★ [[[CONDUCTOR bob]]]
★ Using config path: /tmp/tmp.dwX71VMUbB/tryorama/k1XEN8/conductor-config.toml
★ Reading DNA from /home/simwilso/Code/TestDemo/txrx/dist/txrx.dna.json
★ 
16:18:59 info: 
☯☯☯ [[[CONDUCTOR bob]]]
☯ Unlocking agent keys:
☯ Unlocking key for agent 'txrx': 
☯ 
16:19:00 info: 
☸☸☸ [[[CONDUCTOR bob]]]
☸ conductor: boot_from_config
☸ Reading DNA from /home/simwilso/Code/TestDemo/txrx/dist/txrx.dna.json
☸ 
16:19:00 info: 
☮☮☮ [[[CONDUCTOR bob]]]
☮ Reading DNA from /home/simwilso/Code/TestDemo/txrx/dist/txrx.dna.json
☮ 
16:19:00 info: 
☉☉☉ [[[CONDUCTOR bob]]]
☉ conductor: build_conductor_api instance_id=txrx, config=Configuration { agents: [AgentConfiguration { id: "txrx", name: "bob::txrx::2ea86eb8-9551-4f12-9485-774a744c9ebc", public_address: "HcSCIzV7HGwCraosnaGuHW3vI3Txxq3x6whKnBjIC794h9kpPcwPuH3n7Kd89bz", keystore_file: "[UNUSED]", holo_remote_key: None, test_agent: Some(true) }], dnas: [DnaConfiguration { id: "txrx", file: "/home/simwilso/Code/TestDemo/txrx/dist/txrx.dna.json", hash: "QmUuWbf1wJ9oSzspEwPJ3UnNuMYjn3XTmVmXZ2z9sAUSLv", uuid: Some("2ea86eb8-9551-4f12-9485-774a744c9ebc") }], instances: [InstanceConfiguration { id: "txrx", dna: "txrx", agent: "txrx", storage: Lmdb { path: "/tmp/tmp.dwX71VMUbB/tryorama/k1XEN8/txrx", initial_mmap_bytes: None } }], interfaces: [InterfaceConfiguration { id: "tryorama-interface", driver: Websocket { port: 33001 }, admin: true, instances: [InstanceReferenceConfiguration { id: "txrx", alias: None }], choose_free_port: Some(false) }], bridges: [], ui_bundles: [], ui_interfaces: [], logger: LoggerConfiguration { logger_level: "debug", rules: LogRules { rules: [LogRule { pattern: ^parity, exclude: true, color: None }, LogRule { pattern: ^mio, exclude: true, color: None }, LogRule { pattern: ^tokio, exclude: true, color: None }, LogRule { pattern: ^hyper, exclude: true, color: None }, LogRule { pattern: ^rusoto_core, exclude: true, color: None }, LogRule { pattern: ^want, exclude: true, color: None }, LogRule { pattern: ^rpc, exclude: true, color: None }, LogRule { pattern: ^holochain, exclude: false, color: None }, LogRule { pattern: ^lib3h, exclude: false, color: None }] }, state_dump: false }, network: Some(Sim2h(Sim2hConfig { sim2h_url: "ws://localhost:9000" })), persistence_dir: "/tmp/tmp.dwX71VMUbB/tryorama/k1XEN8", signing_service_uri: None, encryption_service_uri: None, decryption_service_uri: None, dpki: None, signals: SignalConfig { trace: false, consistency: true }, passphrase_service: Cmd, metric_publisher: None }
☉ 
16:19:00 info: 
★★★ [[[CONDUCTOR bob]]]
★ Reading DNA from /home/simwilso/Code/TestDemo/txrx/dist/txrx.dna.json
★ 
16:19:00 info: 
☯☯☯ [[[CONDUCTOR bob]]]
☯ Failed to load instance txrx from storage: ErrorGeneric("State could not be loaded due to NoneError")
☯ Initializing new chain...
☯ 
16:19:00 info: 
☸☸☸ [[[CONDUCTOR bob]]]
☸ Successfully loaded 1 instance configurations
☸ Starting instances...
☸ Start all instances
☸ 
16:19:00 info: 
☮☮☮ [[[CONDUCTOR bob]]]
☮ Starting instance "txrx"...
☮ Starting interfaces...
☮ *** Bound interface 'tryorama-interface' to port: 33001
☮ 
16:19:00 [tryorama] info: Conductor 'bob' process spawning successful. Interface port detected: 33001
16:19:00 [tryorama] debug: (stdout line parsed: Starting instance "txrx"...
Starting interfaces...
*** Bound interface 'tryorama-interface' to port: 33001
)
16:19:00 [tryorama: tryorama conductor bob] debug: Conductor constructing
16:19:00 [tryorama: player bob] debug: spawned
16:19:00 [tryorama: player bob] debug: initializing
16:19:00 [tryorama: tryorama conductor bob] debug: connectInterface :: connecting to ws://localhost:33001
16:19:00 info: 
☉☉☉ [[[CONDUCTOR bob]]]
☉ *** Done. All interfaces started.
☉ Starting UI servers
☉ Starting all servers
☉ 
16:19:00 [tryorama: tryorama conductor bob] debug: connectInterface :: connected to ws://localhost:33001
16:19:00 [tryorama: tryorama conductor bob] debug: [setup call on bob]: admin/agent/list
16:19:00 [tryorama: tryorama conductor bob] debug: {}
16:19:00 [tryorama: tryorama conductor bob] debug: -> [
  {
    id: 'txrx',
    name: 'bob::txrx::2ea86eb8-9551-4f12-9485-774a744c9ebc',
    public_address: 'HcSCIzV7HGwCraosnaGuHW3vI3Txxq3x6whKnBjIC794h9kpPcwPuH3n7Kd89bz',
    keystore_file: '[UNUSED]',
    holo_remote_key: null,
    test_agent: true
  },
  [length]: 1
]
16:19:00 [tryorama: tryorama conductor bob] debug: [setup call on bob]: admin/dna/list
16:19:00 [tryorama: tryorama conductor bob] debug: {}
16:19:00 [tryorama: tryorama conductor bob] debug: -> [
  {
    id: 'txrx',
    hash: 'QmRXwCKqhcdga3e2LwGwT4maYpwQMudJ9zvLFcsQv3asFU'
  },
  [length]: 1
]
16:19:00 [tryorama: tryorama conductor bob] debug: [setup call on bob]: admin/instance/list
16:19:00 [tryorama: tryorama conductor bob] debug: {}
16:19:00 [tryorama: tryorama conductor bob] debug: -> [ { id: 'txrx', dna: 'txrx', agent: 'txrx' }, [length]: 1 ]
16:19:00 [tryorama: player bob] debug: initialized
16:19:00 [tryorama] info: api.players: awaiting consistency while spawning player bob
16:19:00 [tryorama] info: api.players: spawn complete for bob
16:19:00 [tryorama: player alice] debug: call(txrx, txrx, hello_holo, {})
16:19:00 [tryorama: tryorama conductor alice] debug: zome call [alice]: {id: txrx, zome: txrx, fn: hello_holo}
16:19:00 [tryorama: tryorama conductor alice] debug: params: {}
16:19:00 info: 
★★★ {{{CONDUCTOR alice}}}
★ DEBUG 2020-02-03 16:18:59 [holochain::txrx] main crates/core/src/workflows/application.rs:51 dna/initialize: No DNA and agent in chain so assuming uninitialized: ErrorGeneric("Agent entry not found")
★ DEBUG 2020-02-03 16:18:59 [holochain::txrx] main crates/core/src/nucleus/actions/initialize.rs:155 initialize: created public token: HashString("QmWC9f1twbikMhi1GvxtD4CfLNdSEueaiuNVgJXK8cykL6")
★ DEBUG 2020-02-03 16:18:59 [holochain::txrx] main crates/core/src/workflows/application.rs:57 dna/initialize: Initializing new chain from given DNA...
★ DEBUG 2020-02-03 16:18:59 [holochain::txrx] main crates/core/src/network/actions/initialize_network.rs:26 waiting for network
★ DEBUG 2020-02-03 16:18:59 [holochain_net::sim2h_worker] net_worker_thread/puid-4-30 crates/net/src/sim2h_worker.rs:235 WireMessage: queueing Status
★ WARN 2020-02-03 16:18:59 [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-02-03 16:18:59 [holochain_net::sim2h_worker] net_worker_thread/puid-4-30 crates/net/src/sim2h_worker.rs:127 BACKOFF setting reconnect interval to 4000
★ DEBUG 2020-02-03 16:18:59 [holochain_net::sim2h_worker] net_worker_thread/puid-4-30 crates/net/src/sim2h_worker.rs:572 CORE >> Sim2h: JoinSpace(SpaceData { request_id: "puid-4-31", space_address: SpaceHash(HashString("QmRXwCKqhcdga3e2LwGwT4maYpwQMudJ9zvLFcsQv3asFU")), agent_id: AgentPubKey(HashString("HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra")) })
★ DEBUG 2020-02-03 16:18:59 [holochain_net::sim2h_worker] net_worker_thread/puid-4-30 crates/net/src/sim2h_worker.rs:235 WireMessage: queueing ClientToLib3h(JoinSpace(SpaceData { request_id: "puid-4-31", space_address: SpaceHash(HashString("QmRXwCKqhcdga3e2LwGwT4maYpwQMudJ9zvLFcsQv3asFU")), agent_id: AgentPubKey(HashString("HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra")) }))
★ DEBUG 2020-02-03 16:18:59 [holochain_metrics::logger] net_worker_thread/puid-4-30 crates/metrics/src/logger.rs:24 2020-02-03 05:18:59  METRIC sim2h_worker.tick.latency 0
★ DEBUG 2020-02-03 16:18:59 [holochain::txrx] main crates/conductor_lib/src/holochain.rs:168 conductor: Holochain App Name instantiated
★ INFO 2020-02-03 16:18:59 [ws] main /home/docker/project/.cargo/registry/src/github.com-1ecc6299db9ec823/ws-0.9.1/src/lib.rs:308 Listening for new connections on 0.0.0.0:33000.
★ DEBUG 2020-02-03 16:18:59 [jsonrpc_ws_server::server] main /home/docker/project/.cargo/registry/src/github.com-1ecc6299db9ec823/jsonrpc-ws-server-14.0.5/src/server.rs:101 Bound to local address: 0.0.0.0:33000
★ DEBUG 2020-02-03 16:18:59 [holochain_conductor_lib::conductor::base] main crates/conductor_lib/src/conductor/base.rs:1390 conductor: adding broadcaster to map Broadcaster::Ws
★ DEBUG 2020-02-03 16:18:59 [holochain_conductor_lib::conductor::base] main crates/conductor_lib/src/conductor/base.rs:338 starting signal loop
★ INFO 2020-02-03 16:18:59 [ws::io]  /home/docker/project/.cargo/registry/src/github.com-1ecc6299db9ec823/ws-0.9.1/src/io.rs:614 Accepted a new tcp connection from 127.0.0.1:34424.
★ DEBUG 2020-02-03 16:18:59 [ws::handshake]  /home/docker/project/.cargo/registry/src/github.com-1ecc6299db9ec823/ws-0.9.1/src/handshake.rs:625 Built response from request:
★ HTTP/1.1 101 Switching Protocols
★ Connection: Upgrade
★ Sec-WebSocket-Accept: z3LSsu4wXtganou+kcAcmfnRu9I=
★ Upgrade: websocket
★ 
★ 
★ DEBUG 2020-02-03 16:18:59 [ws::handler]  /home/docker/project/.cargo/registry/src/github.com-1ecc6299db9ec823/ws-0.9.1/src/handler.rs:35 Connection with 127.0.0.1 now open
★ DEBUG 2020-02-03 16:18:59 [ws::connection]  /home/docker/project/.cargo/registry/src/github.com-1ecc6299db9ec823/ws-0.9.1/src/connection.rs:564 Connection to 127.0.0.1:34424 is now open.
★ DEBUG 2020-02-03 16:18:59 [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: 66
★ payload length: 64
★ payload: 0x7b226a736f6e727063223a22322e30222c226d6574686f64223a2261646d696e2f6167656e742f6c697374222c22706172616d73223a7b7d2c226964223a317d
★             
★ DEBUG 2020-02-03 16:18:59 [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: 64
★ payload length: 62
★ payload: 0x7b226a736f6e727063223a22322e30222c226d6574686f64223a2261646d696e2f646e612f6c697374222c22706172616d73223a7b7d2c226964223a327d
★             
★ DEBUG 2020-02-03 16:18:59 [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: 69
★ payload length: 67
★ payload: 0x7b226a736f6e727063223a22322e30222c226d6574686f64223a2261646d696e2f696e7374616e63652f6c697374222c22706172616d73223a7b7d2c226964223a337d
★             
★ DEBUG 2020-02-03 16:19:00 [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: 122
★ payload length: 120
★ payload: 0x7b226a736f6e727063223a22322e30222c226d6574686f64223a2263616c6c222c22706172616d73223a7b22696e7374616e63655f6964223a2274787278222c227a6f6d65223a2274787278222c2266756e6374696f6e223a2268656c6c6f5f686f6c6f222c2261726773223a7b7d7d2c226964223a347d
★             
★ DEBUG 2020-02-03 16:19:00 [holochain::txrx] event.loop0 crates/core/src/nucleus/actions/call_zome_function.rs:72 actions/call_zome_fn: Validating call: ZomeFnCall { id: ProcessUniqueId { prefix: 7, offset: 10 }, zome_name: "txrx", cap: CapabilityRequest { cap_token: HashString("QmWC9f1twbikMhi1GvxtD4CfLNdSEueaiuNVgJXK8cykL6"), provenance: Provenance(HashString("HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra"), Signature("EUyxDA+uVlUjzunFgSntmfBhP4i0AoQSipaWk+ZgJJt8rZEy+JQyS2uteK2NoCAm3v8H+V5tlt1wJDzigxHlBw==")) }, fn_name: "hello_holo", parameters: JsonString("{}") }
★ DEBUG 2020-02-03 16:19:00 [holochain::txrx] event.loop0 crates/core/src/nucleus/actions/call_zome_function.rs:81 actions/call_zome_fn: executing call: ZomeFnCall { id: ProcessUniqueId { prefix: 7, offset: 10 }, zome_name: "txrx", cap: CapabilityRequest { cap_token: HashString("QmWC9f1twbikMhi1GvxtD4CfLNdSEueaiuNVgJXK8cykL6"), provenance: Provenance(HashString("HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra"), Signature("EUyxDA+uVlUjzunFgSntmfBhP4i0AoQSipaWk+ZgJJt8rZEy+JQyS2uteK2NoCAm3v8H+V5tlt1wJDzigxHlBw==")) }, fn_name: "hello_holo", parameters: JsonString("{}") }
★ 
16:19:00 [tryorama: tryorama conductor alice] debug: -> { Ok: 'Hello Holo' }
ok 1 HELLO HOLO WORKED
ok 2 should be equivalent
16:19:00 [tryorama: player alice] debug: call(txrx, txrx, create_post, {"message":"Hello blog","timestamp":1580707140672})
16:19:00 [tryorama: tryorama conductor alice] debug: zome call [alice]: {id: txrx, zome: txrx, fn: create_post}
16:19:00 [tryorama: tryorama conductor alice] debug: params: {
  "message": "Hello blog",
  "timestamp": 1580707140672
}
16:19:00 info: 
☯☯☯ {{{CONDUCTOR alice}}}
☯ DEBUG 2020-02-03 16:19:00 [holochain::txrx] 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: 10 }, zome_name: "txrx", cap: CapabilityRequest { cap_token: HashString("QmWC9f1twbikMhi1GvxtD4CfLNdSEueaiuNVgJXK8cykL6"), provenance: Provenance(HashString("HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra"), Signature("EUyxDA+uVlUjzunFgSntmfBhP4i0AoQSipaWk+ZgJJt8rZEy+JQyS2uteK2NoCAm3v8H+V5tlt1wJDzigxHlBw==")) }, fn_name: "hello_holo", parameters: JsonString("{}") }
☯ DEBUG 2020-02-03 16:19:00 [holochain::txrx] ZomeFnCall { id: ProcessUniqueId { prefix: 7, offset: 10 }, zome_name: "txrx", cap: CapabilityRequest { cap_token: HashString("QmWC9f1twbikMhi1GvxtD4CfLNdSEueaiuNVgJXK8cykL6"), provenance: Provenance(HashString("HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra"), Signature("EUyxDA+uVlUjzunFgSntmfBhP4i0AoQSipaWk+ZgJJt8rZEy+JQyS2uteK2NoCAm3v8H+V5tlt1wJDzigxHlBw==")) }, fn_name: "hello_holo", parameters: JsonString("{}") } crates/core/src/nucleus/actions/call_zome_function.rs:288 actions/call_zome_fn: got call_result from ribosome::run_dna.
☯ DEBUG 2020-02-03 16:19:00 [holochain::txrx] ZomeFnCall { id: ProcessUniqueId { prefix: 7, offset: 10 }, zome_name: "txrx", cap: CapabilityRequest { cap_token: HashString("QmWC9f1twbikMhi1GvxtD4CfLNdSEueaiuNVgJXK8cykL6"), provenance: Provenance(HashString("HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra"), Signature("EUyxDA+uVlUjzunFgSntmfBhP4i0AoQSipaWk+ZgJJt8rZEy+JQyS2uteK2NoCAm3v8H+V5tlt1wJDzigxHlBw==")) }, fn_name: "hello_holo", parameters: JsonString("{}") } crates/core/src/nucleus/actions/call_zome_function.rs:295 actions/call_zome_fn: sending ReturnZomeFunctionResult action.
☯ DEBUG 2020-02-03 16:19:00 [holochain::txrx] ZomeFnCall { id: ProcessUniqueId { prefix: 7, offset: 10 }, zome_name: "txrx", cap: CapabilityRequest { cap_token: HashString("QmWC9f1twbikMhi1GvxtD4CfLNdSEueaiuNVgJXK8cykL6"), provenance: Provenance(HashString("HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra"), Signature("EUyxDA+uVlUjzunFgSntmfBhP4i0AoQSipaWk+ZgJJt8rZEy+JQyS2uteK2NoCAm3v8H+V5tlt1wJDzigxHlBw==")) }, fn_name: "hello_holo", parameters: JsonString("{}") } crates/core/src/nucleus/actions/call_zome_function.rs:304 actions/call_zome_fn: sent ReturnZomeFunctionResult action.
☯ DEBUG 2020-02-03 16:19:00 [holochain_metrics::logger] event.loop0 crates/metrics/src/logger.rs:24 2020-02-03 05:19:00  METRIC call_zome_function.txrx.hello_holo.latency 13
☯ DEBUG 2020-02-03 16:19:00 [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: 173
☯ payload length: 169
☯ payload: 0x7b226a736f6e727063223a22322e30222c226d6574686f64223a2263616c6c222c22706172616d73223a7b22696e7374616e63655f6964223a2274787278222c227a6f6d65223a2274787278222c2266756e6374696f6e223a226372656174655f706f7374222c2261726773223a7b226d657373616765223a2248656c6c6f20626c6f67222c2274696d657374616d70223a313538303730373134303637327d7d2c226964223a357d
☯             
☯ DEBUG 2020-02-03 16:19:00 [holochain::txrx] event.loop0 crates/core/src/nucleus/actions/call_zome_function.rs:72 actions/call_zome_fn: Validating call: ZomeFnCall { id: ProcessUniqueId { prefix: 7, offset: 35 }, zome_name: "txrx", cap: CapabilityRequest { cap_token: HashString("QmWC9f1twbikMhi1GvxtD4CfLNdSEueaiuNVgJXK8cykL6"), provenance: Provenance(HashString("HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra"), Signature("JORg2oDV1/ekK5rfyX14rQTKye7bKoULzNshc9eRH77KFVYp7j/r0DLAJKmY0EUiHB7kDh0ym9QuQOEtP3mcAQ==")) }, fn_name: "create_post", parameters: JsonString("{\"message\":\"Hello blog\",\"timestamp\":1580707140672}") }
☯ DEBUG 2020-02-03 16:19:00 [holochain::txrx] event.loop0 crates/core/src/nucleus/actions/call_zome_function.rs:81 actions/call_zome_fn: executing call: ZomeFnCall { id: ProcessUniqueId { prefix: 7, offset: 35 }, zome_name: "txrx", cap: CapabilityRequest { cap_token: HashString("QmWC9f1twbikMhi1GvxtD4CfLNdSEueaiuNVgJXK8cykL6"), provenance: Provenance(HashString("HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra"), Signature("JORg2oDV1/ekK5rfyX14rQTKye7bKoULzNshc9eRH77KFVYp7j/r0DLAJKmY0EUiHB7kDh0ym9QuQOEtP3mcAQ==")) }, fn_name: "create_post", parameters: JsonString("{\"message\":\"Hello blog\",\"timestamp\":1580707140672}") }
☯ DEBUG 2020-02-03 16:19:00 [holochain::txrx] 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: 35 }, zome_name: "txrx", cap: CapabilityRequest { cap_token: HashString("QmWC9f1twbikMhi1GvxtD4CfLNdSEueaiuNVgJXK8cykL6"), provenance: Provenance(HashString("HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra"), Signature("JORg2oDV1/ekK5rfyX14rQTKye7bKoULzNshc9eRH77KFVYp7j/r0DLAJKmY0EUiHB7kDh0ym9QuQOEtP3mcAQ==")) }, fn_name: "create_post", parameters: JsonString("{\"message\":\"Hello blog\",\"timestamp\":1580707140672}") }
☯ ERROR 2020-02-03 16:19:00 [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-02-03 16:19:00 [holochain::txrx] ZomeFnCall { id: ProcessUniqueId { prefix: 7, offset: 35 }, zome_name: "txrx", cap: CapabilityRequest { cap_token: HashString("QmWC9f1twbikMhi1GvxtD4CfLNdSEueaiuNVgJXK8cykL6"), provenance: Provenance(HashString("HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra"), Signature("JORg2oDV1/ekK5rfyX14rQTKye7bKoULzNshc9eRH77KFVYp7j/r0DLAJKmY0EUiHB7kDh0ym9QuQOEtP3mcAQ==")) }, fn_name: "create_post", parameters: JsonString("{\"message\":\"Hello blog\",\"timestamp\":1580707140672}") } crates/core/src/workflows/author_entry.rs:32 workflow/authoring_entry: QmV3dVBMbo5FgqdN8CCbMX9mNcxZwhtRxgh799Sojpstyw with content: App(AppEntryType("post"), JsonString("{\"message\":\"Hello blog\",\"timestamp\":1580707140672,\"author_id\":\"HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra\"}"))
☯ DEBUG 2020-02-03 16:19:00 [holochain::txrx] ZomeFnCall { id: ProcessUniqueId { prefix: 7, offset: 35 }, zome_name: "txrx", cap: CapabilityRequest { cap_token: HashString("QmWC9f1twbikMhi1GvxtD4CfLNdSEueaiuNVgJXK8cykL6"), provenance: Provenance(HashString("HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra"), Signature("JORg2oDV1/ekK5rfyX14rQTKye7bKoULzNshc9eRH77KFVYp7j/r0DLAJKmY0EUiHB7kDh0ym9QuQOEtP3mcAQ==")) }, fn_name: "create_post", parameters: JsonString("{\"message\":\"Hello blog\",\"timestamp\":1580707140672}") } crates/core/src/workflows/author_entry.rs:55 workflow/authoring_entry/QmV3dVBMbo5FgqdN8CCbMX9mNcxZwhtRxgh799Sojpstyw: validating...
☯ 
16:19:00 info: 
☸☸☸ {{{CONDUCTOR alice}}}
☸ DEBUG 2020-02-03 16:19:00 [holochain::txrx] ZomeFnCall { id: ProcessUniqueId { prefix: 7, offset: 35 }, zome_name: "txrx", cap: CapabilityRequest { cap_token: HashString("QmWC9f1twbikMhi1GvxtD4CfLNdSEueaiuNVgJXK8cykL6"), provenance: Provenance(HashString("HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra"), Signature("JORg2oDV1/ekK5rfyX14rQTKye7bKoULzNshc9eRH77KFVYp7j/r0DLAJKmY0EUiHB7kDh0ym9QuQOEtP3mcAQ==")) }, fn_name: "create_post", parameters: JsonString("{\"message\":\"Hello blog\",\"timestamp\":1580707140672}") } crates/core/src/nucleus/validation/mod.rs:81 workflow/validate_entry: App(AppEntryType("post"), JsonString("{\"message\":\"Hello blog\",\"timestamp\":1580707140672,\"author_id\":\"HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra\"}"))
☸ DEBUG 2020-02-03 16:19:00 [holochain_metrics::logger] ZomeFnCall { id: ProcessUniqueId { prefix: 7, offset: 35 }, zome_name: "txrx", cap: CapabilityRequest { cap_token: HashString("QmWC9f1twbikMhi1GvxtD4CfLNdSEueaiuNVgJXK8cykL6"), provenance: Provenance(HashString("HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra"), Signature("JORg2oDV1/ekK5rfyX14rQTKye7bKoULzNshc9eRH77KFVYp7j/r0DLAJKmY0EUiHB7kDh0ym9QuQOEtP3mcAQ==")) }, fn_name: "create_post", parameters: JsonString("{\"message\":\"Hello blog\",\"timestamp\":1580707140672}") } crates/metrics/src/logger.rs:24 2020-02-03 05:19:00  METRIC run_validation_callback.txrx.__hdk_validate_app_entry.latency 17
☸ DEBUG 2020-02-03 16:19:00 [holochain::txrx] ZomeFnCall { id: ProcessUniqueId { prefix: 7, offset: 35 }, zome_name: "txrx", cap: CapabilityRequest { cap_token: HashString("QmWC9f1twbikMhi1GvxtD4CfLNdSEueaiuNVgJXK8cykL6"), provenance: Provenance(HashString("HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra"), Signature("JORg2oDV1/ekK5rfyX14rQTKye7bKoULzNshc9eRH77KFVYp7j/r0DLAJKmY0EUiHB7kDh0ym9QuQOEtP3mcAQ==")) }, fn_name: "create_post", parameters: JsonString("{\"message\":\"Hello blog\",\"timestamp\":1580707140672}") } crates/core/src/workflows/author_entry.rs:67 worflow/authoring_entry QmV3dVBMbo5FgqdN8CCbMX9mNcxZwhtRxgh799Sojpstyw: is valid!
☸ DEBUG 2020-02-03 16:19:00 [holochain::txrx] ZomeFnCall { id: ProcessUniqueId { prefix: 7, offset: 35 }, zome_name: "txrx", cap: CapabilityRequest { cap_token: HashString("QmWC9f1twbikMhi1GvxtD4CfLNdSEueaiuNVgJXK8cykL6"), provenance: Provenance(HashString("HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra"), Signature("JORg2oDV1/ekK5rfyX14rQTKye7bKoULzNshc9eRH77KFVYp7j/r0DLAJKmY0EUiHB7kDh0ym9QuQOEtP3mcAQ==")) }, fn_name: "create_post", parameters: JsonString("{\"message\":\"Hello blog\",\"timestamp\":1580707140672}") } crates/core/src/workflows/author_entry.rs:70 workflow/authoring_entry/QmV3dVBMbo5FgqdN8CCbMX9mNcxZwhtRxgh799Sojpstyw: committing...
☸ DEBUG 2020-02-03 16:19:00 [holochain::txrx] ZomeFnCall { id: ProcessUniqueId { prefix: 7, offset: 35 }, zome_name: "txrx", cap: CapabilityRequest { cap_token: HashString("QmWC9f1twbikMhi1GvxtD4CfLNdSEueaiuNVgJXK8cykL6"), provenance: Provenance(HashString("HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra"), Signature("JORg2oDV1/ekK5rfyX14rQTKye7bKoULzNshc9eRH77KFVYp7j/r0DLAJKmY0EUiHB7kDh0ym9QuQOEtP3mcAQ==")) }, fn_name: "create_post", parameters: JsonString("{\"message\":\"Hello blog\",\"timestamp\":1580707140672}") } crates/core/src/workflows/author_entry.rs:76 workflow/authoring_entry/QmV3dVBMbo5FgqdN8CCbMX9mNcxZwhtRxgh799Sojpstyw: committed
☸ DEBUG 2020-02-03 16:19:00 [holochain::txrx] ZomeFnCall { id: ProcessUniqueId { prefix: 7, offset: 35 }, zome_name: "txrx", cap: CapabilityRequest { cap_token: HashString("QmWC9f1twbikMhi1GvxtD4CfLNdSEueaiuNVgJXK8cykL6"), provenance: Provenance(HashString("HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra"), Signature("JORg2oDV1/ekK5rfyX14rQTKye7bKoULzNshc9eRH77KFVYp7j/r0DLAJKmY0EUiHB7kDh0ym9QuQOEtP3mcAQ==")) }, fn_name: "create_post", parameters: JsonString("{\"message\":\"Hello blog\",\"timestamp\":1580707140672}") } crates/core/src/workflows/author_entry.rs:80 workflow/authoring_entry/QmV3dVBMbo5FgqdN8CCbMX9mNcxZwhtRxgh799Sojpstyw: publishing...
☸ DEBUG 2020-02-03 16:19:00 [holochain::txrx] ZomeFnCall { id: ProcessUniqueId { prefix: 7, offset: 35 }, zome_name: "txrx", cap: CapabilityRequest { cap_token: HashString("QmWC9f1twbikMhi1GvxtD4CfLNdSEueaiuNVgJXK8cykL6"), provenance: Provenance(HashString("HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra"), Signature("JORg2oDV1/ekK5rfyX14rQTKye7bKoULzNshc9eRH77KFVYp7j/r0DLAJKmY0EUiHB7kDh0ym9QuQOEtP3mcAQ==")) }, fn_name: "create_post", parameters: JsonString("{\"message\":\"Hello blog\",\"timestamp\":1580707140672}") } crates/core/src/workflows/author_entry.rs:86 workflow/authoring_entry/QmV3dVBMbo5FgqdN8CCbMX9mNcxZwhtRxgh799Sojpstyw: published!
☸ DEBUG 2020-02-03 16:19:00 [holochain::txrx] ZomeFnCall { id: ProcessUniqueId { prefix: 7, offset: 35 }, zome_name: "txrx", cap: CapabilityRequest { cap_token: HashString("QmWC9f1twbikMhi1GvxtD4CfLNdSEueaiuNVgJXK8cykL6"), provenance: Provenance(HashString("HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra"), Signature("JORg2oDV1/ekK5rfyX14rQTKye7bKoULzNshc9eRH77KFVYp7j/r0DLAJKmY0EUiHB7kDh0ym9QuQOEtP3mcAQ==")) }, fn_name: "create_post", parameters: JsonString("{\"message\":\"Hello blog\",\"timestamp\":1580707140672}") } crates/core/src/workflows/author_entry.rs:96 debug/workflow/authoring_entry/QmV3dVBMbo5FgqdN8CCbMX9mNcxZwhtRxgh799Sojpstyw: publishing header...
☸ DEBUG 2020-02-03 16:19:00 [holochain::txrx] ZomeFnCall { id: ProcessUniqueId { prefix: 7, offset: 35 }, zome_name: "txrx", cap: CapabilityRequest { cap_token: HashString("QmWC9f1twbikMhi1GvxtD4CfLNdSEueaiuNVgJXK8cykL6"), provenance: Provenance(HashString("HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra"), Signature("JORg2oDV1/ekK5rfyX14rQTKye7bKoULzNshc9eRH77KFVYp7j/r0DLAJKmY0EUiHB7kDh0ym9QuQOEtP3mcAQ==")) }, fn_name: "create_post", parameters: JsonString("{\"message\":\"Hello blog\",\"timestamp\":1580707140672}") } crates/core/src/workflows/author_entry.rs:102 debug/workflow/authoring_entry/QmV3dVBMbo5FgqdN8CCbMX9mNcxZwhtRxgh799Sojpstyw: header published!
☸ 
16:19:00 info: 
☮☮☮ {{{CONDUCTOR alice}}}
☮ DEBUG 2020-02-03 16:19:00 [holochain::txrx] ZomeFnCall { id: ProcessUniqueId { prefix: 7, offset: 35 }, zome_name: "txrx", cap: CapabilityRequest { cap_token: HashString("QmWC9f1twbikMhi1GvxtD4CfLNdSEueaiuNVgJXK8cykL6"), provenance: Provenance(HashString("HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra"), Signature("JORg2oDV1/ekK5rfyX14rQTKye7bKoULzNshc9eRH77KFVYp7j/r0DLAJKmY0EUiHB7kDh0ym9QuQOEtP3mcAQ==")) }, fn_name: "create_post", parameters: JsonString("{\"message\":\"Hello blog\",\"timestamp\":1580707140672}") } crates/core/src/workflows/author_entry.rs:32 workflow/authoring_entry: QmScKnjosuFdJgLUjWzGHWk8kXNTAKWTWCji18Kq8wy8PV with content: LinkAdd(LinkData { action_kind: ADD, link: Link { base: HashString("HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra"), target: HashString("QmV3dVBMbo5FgqdN8CCbMX9mNcxZwhtRxgh799Sojpstyw"), link_type: "author_post", tag: "" }, top_chain_header: ChainHeader { entry_type: App(AppEntryType("post")), entry_address: HashString("QmV3dVBMbo5FgqdN8CCbMX9mNcxZwhtRxgh799Sojpstyw"), provenances: [Provenance(HashString("HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra"), Signature("9ytWLbiqVL7cbwqT1cFAMnxk024O3U83ZY3CL2JmcI0sWh8JhWs6feXPe//KJbGKBOq+152vdsrbHyOemK13Dg=="))], link: Some(HashString("QmS3qpXfEyM7znhfjDQKppC4iMGHV4RYUEqtDhdoS4bELu")), link_same_type: None, link_update_delete: None, timestamp: Iso8601(2020-02-03T05:19:00+00:00) }, agent_id: AgentId { nick: "alice::txrx::2ea86eb8-9551-4f12-9485-774a744c9ebc", pub_sign_key: "HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra" } })
☮ DEBUG 2020-02-03 16:19:00 [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("QmRXwCKqhcdga3e2LwGwT4maYpwQMudJ9zvLFcsQv3asFU")), provider_agent_id: AgentPubKey(HashString("HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra")), entry: EntryData { entry_address: EntryHash(HashString("QmV3dVBMbo5FgqdN8CCbMX9mNcxZwhtRxgh799Sojpstyw")), aspect_list: [EntryAspectData { aspect_address: AspectHash(HashString("QmR2zKNw1YfHEYd1j3k6z8ik6NHmRiypQ2AworwdE62vrN")), type_hint: "content", aspect: "{\"Content\":[{\"App\":[\"post\",\"{\\\"message\\\":\\\"Hello blog\\\",\\\"timestamp\\\":1580707140672,\\\"author_id\\\":\\\"HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra\\\"}\"]},{\"entry_type\":{\"App\":\"post\"},\"entry_address\":\"QmV3dVBMbo5FgqdN8CCbMX9mNcxZwhtRxgh799Sojpstyw\",\"provenances\":[[\"HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra\",\"9ytWLbiqVL7cbwqT1cFAMnxk024O3U83ZY3CL2JmcI0sWh8JhWs6feXPe//KJbGKBOq+152vdsrbHyOemK13Dg==\"]],\"link\":\"QmS3qpXfEyM7znhfjDQKppC4iMGHV4RYUEqtDhdoS4bELu\",\"link_same_type\":null,\"link_update_delete\":null,\"timestamp\":\"2020-02-03T05:19:00+00:00\"}]}", publish_ts: 1580707140 }] } })
☮ DEBUG 2020-02-03 16:19:00 [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("QmRXwCKqhcdga3e2LwGwT4maYpwQMudJ9zvLFcsQv3asFU")), provider_agent_id: AgentPubKey(HashString("HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra")), entry: EntryData { entry_address: EntryHash(HashString("QmV3dVBMbo5FgqdN8CCbMX9mNcxZwhtRxgh799Sojpstyw")), aspect_list: [EntryAspectData { aspect_address: AspectHash(HashString("QmR2zKNw1YfHEYd1j3k6z8ik6NHmRiypQ2AworwdE62vrN")), type_hint: "content", aspect: "{\"Content\":[{\"App\":[\"post\",\"{\\\"message\\\":\\\"Hello blog\\\",\\\"timestamp\\\":1580707140672,\\\"author_id\\\":\\\"HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra\\\"}\"]},{\"entry_type\":{\"App\":\"post\"},\"entry_address\":\"QmV3dVBMbo5FgqdN8CCbMX9mNcxZwhtRxgh799Sojpstyw\",\"provenances\":[[\"HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra\",\"9ytWLbiqVL7cbwqT1cFAMnxk024O3U83ZY3CL2JmcI0sWh8JhWs6feXPe//KJbGKBOq+152vdsrbHyOemK13Dg==\"]],\"link\":\"QmS3qpXfEyM7znhfjDQKppC4iMGHV4RYUEqtDhdoS4bELu\",\"link_same_type\":null,\"link_update_delete\":null,\"timestamp\":\"2020-02-03T05:19:00+00:00\"}]}", publish_ts: 1580707140 }] } }))
☮ DEBUG 2020-02-03 16:19:00 [holochain_metrics::logger] net_worker_thread/puid-4-30 crates/metrics/src/logger.rs:24 2020-02-03 05:19:00  METRIC sim2h_worker.tick.latency 0
☮ DEBUG 2020-02-03 16:19:00 [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("QmRXwCKqhcdga3e2LwGwT4maYpwQMudJ9zvLFcsQv3asFU")), provider_agent_id: AgentPubKey(HashString("HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra")), entry: EntryData { entry_address: EntryHash(HashString("QmcL9f1NnLv169nVBpoDJ7ndEeiuQqM8PYM6hmPT2bAn8Y")), aspect_list: [EntryAspectData { aspect_address: AspectHash(HashString("QmTUnDA5ALZZaZBT6VSMQLJ95BnnyVHhyYKnTCojRjycRS")), type_hint: "content", aspect: "{\"Content\":[{\"ChainHeader\":{\"entry_type\":{\"App\":\"post\"},\"entry_address\":\"QmV3dVBMbo5FgqdN8CCbMX9mNcxZwhtRxgh799Sojpstyw\",\"provenances\":[[\"HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra\",\"9ytWLbiqVL7cbwqT1cFAMnxk024O3U83ZY3CL2JmcI0sWh8JhWs6feXPe//KJbGKBOq+152vdsrbHyOemK13Dg==\"]],\"link\":\"QmS3qpXfEyM7znhfjDQKppC4iMGHV4RYUEqtDhdoS4bELu\",\"link_same_type\":null,\"link_update_delete\":null,\"timestamp\":\"2020-02-03T05:19:00+00:00\"}},{\"entry_type\":\"ChainHeader\",\"entry_address\":\"QmcL9f1NnLv169nVBpoDJ7ndEeiuQqM8PYM6hmPT2bAn8Y\",\"provenances\":[[\"HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra\",\"8LOJ3mKq49Mkgn8xO3/nE9fAHBfVsoLHLB/T1ZrukOrCGSN1wkhpiI6dNqzum2MuBHPG684pVpyk0brfxvIUAw==\"]],\"link\":null,\"link_same_type\":null,\"link_update_delete\":null,\"timestamp\":\"2020-02-03T05:19:00+00:00\"}]}", publish_ts: 1580707140 }] } })
☮ DEBUG 2020-02-03 16:19:00 [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("QmRXwCKqhcdga3e2LwGwT4maYpwQMudJ9zvLFcsQv3asFU")), provider_agent_id: AgentPubKey(HashString("HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra")), entry: EntryData { entry_address: EntryHash(HashString("QmcL9f1NnLv169nVBpoDJ7ndEeiuQqM8PYM6hmPT2bAn8Y")), aspect_list: [EntryAspectData { aspect_address: AspectHash(HashString("QmTUnDA5ALZZaZBT6VSMQLJ95BnnyVHhyYKnTCojRjycRS")), type_hint: "content", aspect: "{\"Content\":[{\"ChainHeader\":{\"entry_type\":{\"App\":\"post\"},\"entry_address\":\"QmV3dVBMbo5FgqdN8CCbMX9mNcxZwhtRxgh799Sojpstyw\",\"provenances\":[[\"HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra\",\"9ytWLbiqVL7cbwqT1cFAMnxk024O3U83ZY3CL2JmcI0sWh8JhWs6feXPe//KJbGKBOq+152vdsrbHyOemK13Dg==\"]],\"link\":\"QmS3qpXfEyM7znhfjDQKppC4iMGHV4RYUEqtDhdoS4bELu\",\"link_same_type\":null,\"link_update_delete\":null,\"timestamp\":\"2020-02-03T05:19:00+00:00\"}},{\"entry_type\":\"ChainHeader\",\"entry_address\":\"QmcL9f1NnLv169nVBpoDJ7ndEeiuQqM8PYM6hmPT2bAn8Y\",\"provenances\":[[\"HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra\",\"8LOJ3mKq49Mkgn8xO3/nE9fAHBfVsoLHLB/T1ZrukOrCGSN1wkhpiI6dNqzum2MuBHPG684pVpyk0brfxvIUAw==\"]],\"link\":null,\"link_same_type\":null,\"link_update_delete\":null,\"timestamp\":\"2020-02-03T05:19:00+00:00\"}]}", publish_ts: 1580707140 }] } }))
☮ DEBUG 2020-02-03 16:19:00 [holochain_metrics::logger] net_worker_thread/puid-4-30 crates/metrics/src/logger.rs:24 2020-02-03 05:19:00  METRIC sim2h_worker.tick.latency 0
☮ 
16:19:00 info: 
☉☉☉ {{{CONDUCTOR alice}}}
☉ DEBUG 2020-02-03 16:19:00 [holochain::txrx] ZomeFnCall { id: ProcessUniqueId { prefix: 7, offset: 35 }, zome_name: "txrx", cap: CapabilityRequest { cap_token: HashString("QmWC9f1twbikMhi1GvxtD4CfLNdSEueaiuNVgJXK8cykL6"), provenance: Provenance(HashString("HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra"), Signature("JORg2oDV1/ekK5rfyX14rQTKye7bKoULzNshc9eRH77KFVYp7j/r0DLAJKmY0EUiHB7kDh0ym9QuQOEtP3mcAQ==")) }, fn_name: "create_post", parameters: JsonString("{\"message\":\"Hello blog\",\"timestamp\":1580707140672}") } crates/core/src/workflows/author_entry.rs:55 workflow/authoring_entry/QmScKnjosuFdJgLUjWzGHWk8kXNTAKWTWCji18Kq8wy8PV: validating...
☉ DEBUG 2020-02-03 16:19:00 [holochain::txrx] ZomeFnCall { id: ProcessUniqueId { prefix: 7, offset: 35 }, zome_name: "txrx", cap: CapabilityRequest { cap_token: HashString("QmWC9f1twbikMhi1GvxtD4CfLNdSEueaiuNVgJXK8cykL6"), provenance: Provenance(HashString("HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra"), Signature("JORg2oDV1/ekK5rfyX14rQTKye7bKoULzNshc9eRH77KFVYp7j/r0DLAJKmY0EUiHB7kDh0ym9QuQOEtP3mcAQ==")) }, fn_name: "create_post", parameters: JsonString("{\"message\":\"Hello blog\",\"timestamp\":1580707140672}") } crates/core/src/nucleus/validation/mod.rs:81 workflow/validate_entry: LinkAdd(LinkData { action_kind: ADD, link: Link { base: HashString("HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra"), target: HashString("QmV3dVBMbo5FgqdN8CCbMX9mNcxZwhtRxgh799Sojpstyw"), link_type: "author_post", tag: "" }, top_chain_header: ChainHeader { entry_type: App(AppEntryType("post")), entry_address: HashString("QmV3dVBMbo5FgqdN8CCbMX9mNcxZwhtRxgh799Sojpstyw"), provenances: [Provenance(HashString("HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra"), Signature("9ytWLbiqVL7cbwqT1cFAMnxk024O3U83ZY3CL2JmcI0sWh8JhWs6feXPe//KJbGKBOq+152vdsrbHyOemK13Dg=="))], link: Some(HashString("QmS3qpXfEyM7znhfjDQKppC4iMGHV4RYUEqtDhdoS4bELu")), link_same_type: None, link_update_delete: None, timestamp: Iso8601(2020-02-03T05:19:00+00:00) }, agent_id: AgentId { nick: "alice::txrx::2ea86eb8-9551-4f12-9485-774a744c9ebc", pub_sign_key: "HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra" } })
☉ DEBUG 2020-02-03 16:19:00 [holochain_metrics::logger] ZomeFnCall { id: ProcessUniqueId { prefix: 7, offset: 35 }, zome_name: "txrx", cap: CapabilityRequest { cap_token: HashString("QmWC9f1twbikMhi1GvxtD4CfLNdSEueaiuNVgJXK8cykL6"), provenance: Provenance(HashString("HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra"), Signature("JORg2oDV1/ekK5rfyX14rQTKye7bKoULzNshc9eRH77KFVYp7j/r0DLAJKmY0EUiHB7kDh0ym9QuQOEtP3mcAQ==")) }, fn_name: "create_post", parameters: JsonString("{\"message\":\"Hello blog\",\"timestamp\":1580707140672}") } crates/metrics/src/logger.rs:24 2020-02-03 05:19:00  METRIC run_validation_callback.txrx.__hdk_validate_link.latency 20
☉ DEBUG 2020-02-03 16:19:00 [holochain::txrx] ZomeFnCall { id: ProcessUniqueId { prefix: 7, offset: 35 }, zome_name: "txrx", cap: CapabilityRequest { cap_token: HashString("QmWC9f1twbikMhi1GvxtD4CfLNdSEueaiuNVgJXK8cykL6"), provenance: Provenance(HashString("HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra"), Signature("JORg2oDV1/ekK5rfyX14rQTKye7bKoULzNshc9eRH77KFVYp7j/r0DLAJKmY0EUiHB7kDh0ym9QuQOEtP3mcAQ==")) }, fn_name: "create_post", parameters: JsonString("{\"message\":\"Hello blog\",\"timestamp\":1580707140672}") } crates/core/src/workflows/author_entry.rs:67 worflow/authoring_entry QmScKnjosuFdJgLUjWzGHWk8kXNTAKWTWCji18Kq8wy8PV: is valid!
☉ DEBUG 2020-02-03 16:19:00 [holochain::txrx] ZomeFnCall { id: ProcessUniqueId { prefix: 7, offset: 35 }, zome_name: "txrx", cap: CapabilityRequest { cap_token: HashString("QmWC9f1twbikMhi1GvxtD4CfLNdSEueaiuNVgJXK8cykL6"), provenance: Provenance(HashString("HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra"), Signature("JORg2oDV1/ekK5rfyX14rQTKye7bKoULzNshc9eRH77KFVYp7j/r0DLAJKmY0EUiHB7kDh0ym9QuQOEtP3mcAQ==")) }, fn_name: "create_post", parameters: JsonString("{\"message\":\"Hello blog\",\"timestamp\":1580707140672}") } crates/core/src/workflows/author_entry.rs:70 workflow/authoring_entry/QmScKnjosuFdJgLUjWzGHWk8kXNTAKWTWCji18Kq8wy8PV: committing...
☉ DEBUG 2020-02-03 16:19:00 [holochain::txrx] ZomeFnCall { id: ProcessUniqueId { prefix: 7, offset: 35 }, zome_name: "txrx", cap: CapabilityRequest { cap_token: HashString("QmWC9f1twbikMhi1GvxtD4CfLNdSEueaiuNVgJXK8cykL6"), provenance: Provenance(HashString("HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra"), Signature("JORg2oDV1/ekK5rfyX14rQTKye7bKoULzNshc9eRH77KFVYp7j/r0DLAJKmY0EUiHB7kDh0ym9QuQOEtP3mcAQ==")) }, fn_name: "create_post", parameters: JsonString("{\"message\":\"Hello blog\",\"timestamp\":1580707140672}") } crates/core/src/workflows/author_entry.rs:76 workflow/authoring_entry/QmScKnjosuFdJgLUjWzGHWk8kXNTAKWTWCji18Kq8wy8PV: committed
☉ DEBUG 2020-02-03 16:19:00 [holochain::txrx] ZomeFnCall { id: ProcessUniqueId { prefix: 7, offset: 35 }, zome_name: "txrx", cap: CapabilityRequest { cap_token: HashString("QmWC9f1twbikMhi1GvxtD4CfLNdSEueaiuNVgJXK8cykL6"), provenance: Provenance(HashString("HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra"), Signature("JORg2oDV1/ekK5rfyX14rQTKye7bKoULzNshc9eRH77KFVYp7j/r0DLAJKmY0EUiHB7kDh0ym9QuQOEtP3mcAQ==")) }, fn_name: "create_post", parameters: JsonString("{\"message\":\"Hello blog\",\"timestamp\":1580707140672}") } crates/core/src/workflows/author_entry.rs:80 workflow/authoring_entry/QmScKnjosuFdJgLUjWzGHWk8kXNTAKWTWCji18Kq8wy8PV: publishing...
☉ DEBUG 2020-02-03 16:19:00 [holochain::txrx] ZomeFnCall { id: ProcessUniqueId { prefix: 7, offset: 35 }, zome_name: "txrx", cap: CapabilityRequest { cap_token: HashString("QmWC9f1twbikMhi1GvxtD4CfLNdSEueaiuNVgJXK8cykL6"), provenance: Provenance(HashString("HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra"), Signature("JORg2oDV1/ekK5rfyX14rQTKye7bKoULzNshc9eRH77KFVYp7j/r0DLAJKmY0EUiHB7kDh0ym9QuQOEtP3mcAQ==")) }, fn_name: "create_post", parameters: JsonString("{\"message\":\"Hello blog\",\"timestamp\":1580707140672}") } crates/core/src/workflows/author_entry.rs:86 workflow/authoring_entry/QmScKnjosuFdJgLUjWzGHWk8kXNTAKWTWCji18Kq8wy8PV: published!
☉ DEBUG 2020-02-03 16:19:00 [holochain::txrx] ZomeFnCall { id: ProcessUniqueId { prefix: 7, offset: 35 }, zome_name: "txrx", cap: CapabilityRequest { cap_token: HashString("QmWC9f1twbikMhi1GvxtD4CfLNdSEueaiuNVgJXK8cykL6"), provenance: Provenance(HashString("HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra"), Signature("JORg2oDV1/ekK5rfyX14rQTKye7bKoULzNshc9eRH77KFVYp7j/r0DLAJKmY0EUiHB7kDh0ym9QuQOEtP3mcAQ==")) }, fn_name: "create_post", parameters: JsonString("{\"message\":\"Hello blog\",\"timestamp\":1580707140672}") } crates/core/src/workflows/author_entry.rs:96 debug/workflow/authoring_entry/QmScKnjosuFdJgLUjWzGHWk8kXNTAKWTWCji18Kq8wy8PV: publishing header...
☉ DEBUG 2020-02-03 16:19:00 [holochain::txrx] ZomeFnCall { id: ProcessUniqueId { prefix: 7, offset: 35 }, zome_name: "txrx", cap: CapabilityRequest { cap_token: HashString("QmWC9f1twbikMhi1GvxtD4CfLNdSEueaiuNVgJXK8cykL6"), provenance: Provenance(HashString("HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra"), Signature("JORg2oDV1/ekK5rfyX14rQTKye7bKoULzNshc9eRH77KFVYp7j/r0DLAJKmY0EUiHB7kDh0ym9QuQOEtP3mcAQ==")) }, fn_name: "create_post", parameters: JsonString("{\"message\":\"Hello blog\",\"timestamp\":1580707140672}") } crates/core/src/workflows/author_entry.rs:102 debug/workflow/authoring_entry/QmScKnjosuFdJgLUjWzGHWk8kXNTAKWTWCji18Kq8wy8PV: header published!
☉ 
16:19:00 [tryorama: tryorama conductor alice] debug: -> { Ok: 'QmV3dVBMbo5FgqdN8CCbMX9mNcxZwhtRxgh799Sojpstyw' }
ok 3 CREATE A POST WORKED
16:19:00 info: 
★★★ {{{CONDUCTOR alice}}}
★ DEBUG 2020-02-03 16:19:00 [holochain::txrx] ZomeFnCall { id: ProcessUniqueId { prefix: 7, offset: 35 }, zome_name: "txrx", cap: CapabilityRequest { cap_token: HashString("QmWC9f1twbikMhi1GvxtD4CfLNdSEueaiuNVgJXK8cykL6"), provenance: Provenance(HashString("HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra"), Signature("JORg2oDV1/ekK5rfyX14rQTKye7bKoULzNshc9eRH77KFVYp7j/r0DLAJKmY0EUiHB7kDh0ym9QuQOEtP3mcAQ==")) }, fn_name: "create_post", parameters: JsonString("{\"message\":\"Hello blog\",\"timestamp\":1580707140672}") } crates/core/src/nucleus/actions/call_zome_function.rs:288 actions/call_zome_fn: got call_result from ribosome::run_dna.
★ DEBUG 2020-02-03 16:19:00 [holochain::txrx] ZomeFnCall { id: ProcessUniqueId { prefix: 7, offset: 35 }, zome_name: "txrx", cap: CapabilityRequest { cap_token: HashString("QmWC9f1twbikMhi1GvxtD4CfLNdSEueaiuNVgJXK8cykL6"), provenance: Provenance(HashString("HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra"), Signature("JORg2oDV1/ekK5rfyX14rQTKye7bKoULzNshc9eRH77KFVYp7j/r0DLAJKmY0EUiHB7kDh0ym9QuQOEtP3mcAQ==")) }, fn_name: "create_post", parameters: JsonString("{\"message\":\"Hello blog\",\"timestamp\":1580707140672}") } crates/core/src/nucleus/actions/call_zome_function.rs:295 actions/call_zome_fn: sending ReturnZomeFunctionResult action.
★ DEBUG 2020-02-03 16:19:00 [holochain::txrx] ZomeFnCall { id: ProcessUniqueId { prefix: 7, offset: 35 }, zome_name: "txrx", cap: CapabilityRequest { cap_token: HashString("QmWC9f1twbikMhi1GvxtD4CfLNdSEueaiuNVgJXK8cykL6"), provenance: Provenance(HashString("HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra"), Signature("JORg2oDV1/ekK5rfyX14rQTKye7bKoULzNshc9eRH77KFVYp7j/r0DLAJKmY0EUiHB7kDh0ym9QuQOEtP3mcAQ==")) }, fn_name: "create_post", parameters: JsonString("{\"message\":\"Hello blog\",\"timestamp\":1580707140672}") } crates/core/src/nucleus/actions/call_zome_function.rs:304 actions/call_zome_fn: sent ReturnZomeFunctionResult action.
★ DEBUG 2020-02-03 16:19:00 [holochain_metrics::logger] event.loop0 crates/metrics/src/logger.rs:24 2020-02-03 05:19:00  METRIC call_zome_function.txrx.create_post.latency 116
★ DEBUG 2020-02-03 16:19:00 [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("QmRXwCKqhcdga3e2LwGwT4maYpwQMudJ9zvLFcsQv3asFU")), provider_agent_id: AgentPubKey(HashString("HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra")), entry: EntryData { entry_address: EntryHash(HashString("QmScKnjosuFdJgLUjWzGHWk8kXNTAKWTWCji18Kq8wy8PV")), aspect_list: [EntryAspectData { aspect_address: AspectHash(HashString("QmNY9k9RAwwWpEbp1WNk6nAmrXMWKqUbxmsAiLYJXEEkkU")), type_hint: "content", aspect: "{\"Content\":[{\"LinkAdd\":{\"action_kind\":\"ADD\",\"link\":{\"base\":\"HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra\",\"target\":\"QmV3dVBMbo5FgqdN8CCbMX9mNcxZwhtRxgh799Sojpstyw\",\"link_type\":\"author_post\",\"tag\":\"\"},\"top_chain_header\":{\"entry_type\":{\"App\":\"post\"},\"entry_address\":\"QmV3dVBMbo5FgqdN8CCbMX9mNcxZwhtRxgh799Sojpstyw\",\"provenances\":[[\"HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra\",\"9ytWLbiqVL7cbwqT1cFAMnxk024O3U83ZY3CL2JmcI0sWh8JhWs6feXPe//KJbGKBOq+152vdsrbHyOemK13Dg==\"]],\"link\":\"QmS3qpXfEyM7znhfjDQKppC4iMGHV4RYUEqtDhdoS4bELu\",\"link_same_type\":null,\"link_update_delete\":null,\"timestamp\":\"2020-02-03T05:19:00+00:00\"},\"agent_id\":{\"nick\":\"alice::txrx::2ea86eb8-9551-4f12-9485-774a744c9ebc\",\"pub_sign_key\":\"HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra\"}}},{\"entry_type\":\"LinkAdd\",\"entry_address\":\"QmScKnjosuFdJgLUjWzGHWk8kXNTAKWTWCji18Kq8wy8PV\",\"provenances\":[[\"HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra\",\"dcvVFdk5Z81126KOdCqt6BSkPm9WTnfY5+1gmmsawovQIn+yESeDhZgM16C+FLoZkmlfJo71SjJL/X7XItccDw==\"]],\"link\":\"QmcL9f1NnLv169nVBpoDJ7ndEeiuQqM8PYM6hmPT2bAn8Y\",\"link_same_type\":null,\"link_update_delete\":null,\"timestamp\":\"2020-02-03T05:19:00+00:00\"}]}", publish_ts: 1580707140 }] } })
★ DEBUG 2020-02-03 16:19:00 [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("QmRXwCKqhcdga3e2LwGwT4maYpwQMudJ9zvLFcsQv3asFU")), provider_agent_id: AgentPubKey(HashString("HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra")), entry: EntryData { entry_address: EntryHash(HashString("QmScKnjosuFdJgLUjWzGHWk8kXNTAKWTWCji18Kq8wy8PV")), aspect_list: [EntryAspectData { aspect_address: AspectHash(HashString("QmNY9k9RAwwWpEbp1WNk6nAmrXMWKqUbxmsAiLYJXEEkkU")), type_hint: "content", aspect: "{\"Content\":[{\"LinkAdd\":{\"action_kind\":\"ADD\",\"link\":{\"base\":\"HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra\",\"target\":\"QmV3dVBMbo5FgqdN8CCbMX9mNcxZwhtRxgh799Sojpstyw\",\"link_type\":\"author_post\",\"tag\":\"\"},\"top_chain_header\":{\"entry_type\":{\"App\":\"post\"},\"entry_address\":\"QmV3dVBMbo5FgqdN8CCbMX9mNcxZwhtRxgh799Sojpstyw\",\"provenances\":[[\"HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra\",\"9ytWLbiqVL7cbwqT1cFAMnxk024O3U83ZY3CL2JmcI0sWh8JhWs6feXPe//KJbGKBOq+152vdsrbHyOemK13Dg==\"]],\"link\":\"QmS3qpXfEyM7znhfjDQKppC4iMGHV4RYUEqtDhdoS4bELu\",\"link_same_type\":null,\"link_update_delete\":null,\"timestamp\":\"2020-02-03T05:19:00+00:00\"},\"agent_id\":{\"nick\":\"alice::txrx::2ea86eb8-9551-4f12-9485-774a744c9ebc\",\"pub_sign_key\":\"HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra\"}}},{\"entry_type\":\"LinkAdd\",\"entry_address\":\"QmScKnjosuFdJgLUjWzGHWk8kXNTAKWTWCji18Kq8wy8PV\",\"provenances\":[[\"HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra\",\"dcvVFdk5Z81126KOdCqt6BSkPm9WTnfY5+1gmmsawovQIn+yESeDhZgM16C+FLoZkmlfJo71SjJL/X7XItccDw==\"]],\"link\":\"QmcL9f1NnLv169nVBpoDJ7ndEeiuQqM8PYM6hmPT2bAn8Y\",\"link_same_type\":null,\"link_update_delete\":null,\"timestamp\":\"2020-02-03T05:19:00+00:00\"}]}", publish_ts: 1580707140 }] } }))
★ DEBUG 2020-02-03 16:19:00 [holochain_metrics::logger] net_worker_thread/puid-4-30 crates/metrics/src/logger.rs:24 2020-02-03 05:19:00  METRIC sim2h_worker.tick.latency 0
★ 
16:19:03 info: 
☯☯☯ {{{CONDUCTOR alice}}}
☯ DEBUG 2020-02-03 16:19:00 [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("QmRXwCKqhcdga3e2LwGwT4maYpwQMudJ9zvLFcsQv3asFU")), provider_agent_id: AgentPubKey(HashString("HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra")), entry: EntryData { entry_address: EntryHash(HashString("HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra")), aspect_list: [EntryAspectData { aspect_address: AspectHash(HashString("QmSngh91Eah9MgNFnPhRqaJF3pBLJhvksAGtrjcbtPGcU4")), type_hint: "link_add", aspect: "{\"LinkAdd\":[{\"action_kind\":\"ADD\",\"link\":{\"base\":\"HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra\",\"target\":\"QmV3dVBMbo5FgqdN8CCbMX9mNcxZwhtRxgh799Sojpstyw\",\"link_type\":\"author_post\",\"tag\":\"\"},\"top_chain_header\":{\"entry_type\":{\"App\":\"post\"},\"entry_address\":\"QmV3dVBMbo5FgqdN8CCbMX9mNcxZwhtRxgh799Sojpstyw\",\"provenances\":[[\"HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra\",\"9ytWLbiqVL7cbwqT1cFAMnxk024O3U83ZY3CL2JmcI0sWh8JhWs6feXPe//KJbGKBOq+152vdsrbHyOemK13Dg==\"]],\"link\":\"QmS3qpXfEyM7znhfjDQKppC4iMGHV4RYUEqtDhdoS4bELu\",\"link_same_type\":null,\"link_update_delete\":null,\"timestamp\":\"2020-02-03T05:19:00+00:00\"},\"agent_id\":{\"nick\":\"alice::txrx::2ea86eb8-9551-4f12-9485-774a744c9ebc\",\"pub_sign_key\":\"HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra\"}},{\"entry_type\":\"LinkAdd\",\"entry_address\":\"QmScKnjosuFdJgLUjWzGHWk8kXNTAKWTWCji18Kq8wy8PV\",\"provenances\":[[\"HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra\",\"dcvVFdk5Z81126KOdCqt6BSkPm9WTnfY5+1gmmsawovQIn+yESeDhZgM16C+FLoZkmlfJo71SjJL/X7XItccDw==\"]],\"link\":\"QmcL9f1NnLv169nVBpoDJ7ndEeiuQqM8PYM6hmPT2bAn8Y\",\"link_same_type\":null,\"link_update_delete\":null,\"timestamp\":\"2020-02-03T05:19:00+00:00\"}]}", publish_ts: 1580707140 }] } })
☯ DEBUG 2020-02-03 16:19:00 [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("QmRXwCKqhcdga3e2LwGwT4maYpwQMudJ9zvLFcsQv3asFU")), provider_agent_id: AgentPubKey(HashString("HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra")), entry: EntryData { entry_address: EntryHash(HashString("HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra")), aspect_list: [EntryAspectData { aspect_address: AspectHash(HashString("QmSngh91Eah9MgNFnPhRqaJF3pBLJhvksAGtrjcbtPGcU4")), type_hint: "link_add", aspect: "{\"LinkAdd\":[{\"action_kind\":\"ADD\",\"link\":{\"base\":\"HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra\",\"target\":\"QmV3dVBMbo5FgqdN8CCbMX9mNcxZwhtRxgh799Sojpstyw\",\"link_type\":\"author_post\",\"tag\":\"\"},\"top_chain_header\":{\"entry_type\":{\"App\":\"post\"},\"entry_address\":\"QmV3dVBMbo5FgqdN8CCbMX9mNcxZwhtRxgh799Sojpstyw\",\"provenances\":[[\"HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra\",\"9ytWLbiqVL7cbwqT1cFAMnxk024O3U83ZY3CL2JmcI0sWh8JhWs6feXPe//KJbGKBOq+152vdsrbHyOemK13Dg==\"]],\"link\":\"QmS3qpXfEyM7znhfjDQKppC4iMGHV4RYUEqtDhdoS4bELu\",\"link_same_type\":null,\"link_update_delete\":null,\"timestamp\":\"2020-02-03T05:19:00+00:00\"},\"agent_id\":{\"nick\":\"alice::txrx::2ea86eb8-9551-4f12-9485-774a744c9ebc\",\"pub_sign_key\":\"HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra\"}},{\"entry_type\":\"LinkAdd\",\"entry_address\":\"QmScKnjosuFdJgLUjWzGHWk8kXNTAKWTWCji18Kq8wy8PV\",\"provenances\":[[\"HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra\",\"dcvVFdk5Z81126KOdCqt6BSkPm9WTnfY5+1gmmsawovQIn+yESeDhZgM16C+FLoZkmlfJo71SjJL/X7XItccDw==\"]],\"link\":\"QmcL9f1NnLv169nVBpoDJ7ndEeiuQqM8PYM6hmPT2bAn8Y\",\"link_same_type\":null,\"link_update_delete\":null,\"timestamp\":\"2020-02-03T05:19:00+00:00\"}]}", publish_ts: 1580707140 }] } }))
☯ DEBUG 2020-02-03 16:19:00 [holochain_metrics::logger] net_worker_thread/puid-4-30 crates/metrics/src/logger.rs:24 2020-02-03 05:19:00  METRIC sim2h_worker.tick.latency 0
☯ DEBUG 2020-02-03 16:19:00 [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("QmRXwCKqhcdga3e2LwGwT4maYpwQMudJ9zvLFcsQv3asFU")), provider_agent_id: AgentPubKey(HashString("HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra")), entry: EntryData { entry_address: EntryHash(HashString("QmSatitzVY6YaZ2pASPsnEn8j1vo692CdNwrFnrifggFHy")), aspect_list: [EntryAspectData { aspect_address: AspectHash(HashString("QmerxQdkun1hDhneGUNhLyXmsZ2cj3xo9zbkQFVN6AxHGC")), type_hint: "content", aspect: "{\"Content\":[{\"ChainHeader\":{\"entry_type\":\"LinkAdd\",\"entry_address\":\"QmScKnjosuFdJgLUjWzGHWk8kXNTAKWTWCji18Kq8wy8PV\",\"provenances\":[[\"HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra\",\"dcvVFdk5Z81126KOdCqt6BSkPm9WTnfY5+1gmmsawovQIn+yESeDhZgM16C+FLoZkmlfJo71SjJL/X7XItccDw==\"]],\"link\":\"QmcL9f1NnLv169nVBpoDJ7ndEeiuQqM8PYM6hmPT2bAn8Y\",\"link_same_type\":null,\"link_update_delete\":null,\"timestamp\":\"2020-02-03T05:19:00+00:00\"}},{\"entry_type\":\"ChainHeader\",\"entry_address\":\"QmSatitzVY6YaZ2pASPsnEn8j1vo692CdNwrFnrifggFHy\",\"provenances\":[[\"HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra\",\"AP4xBavdkoV0p8o/JeC4LOQW+T3AoCbirwzk76dDsMH7KE062okkVahRvzKBSTicjeiuRsUOUdqMRWf+BX0yDg==\"]],\"link\":null,\"link_same_type\":null,\"link_update_delete\":null,\"timestamp\":\"2020-02-03T05:19:00+00:00\"}]}", publish_ts: 1580707140 }] } })
☯ DEBUG 2020-02-03 16:19:00 [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("QmRXwCKqhcdga3e2LwGwT4maYpwQMudJ9zvLFcsQv3asFU")), provider_agent_id: AgentPubKey(HashString("HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra")), entry: EntryData { entry_address: EntryHash(HashString("QmSatitzVY6YaZ2pASPsnEn8j1vo692CdNwrFnrifggFHy")), aspect_list: [EntryAspectData { aspect_address: AspectHash(HashString("QmerxQdkun1hDhneGUNhLyXmsZ2cj3xo9zbkQFVN6AxHGC")), type_hint: "content", aspect: "{\"Content\":[{\"ChainHeader\":{\"entry_type\":\"LinkAdd\",\"entry_address\":\"QmScKnjosuFdJgLUjWzGHWk8kXNTAKWTWCji18Kq8wy8PV\",\"provenances\":[[\"HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra\",\"dcvVFdk5Z81126KOdCqt6BSkPm9WTnfY5+1gmmsawovQIn+yESeDhZgM16C+FLoZkmlfJo71SjJL/X7XItccDw==\"]],\"link\":\"QmcL9f1NnLv169nVBpoDJ7ndEeiuQqM8PYM6hmPT2bAn8Y\",\"link_same_type\":null,\"link_update_delete\":null,\"timestamp\":\"2020-02-03T05:19:00+00:00\"}},{\"entry_type\":\"ChainHeader\",\"entry_address\":\"QmSatitzVY6YaZ2pASPsnEn8j1vo692CdNwrFnrifggFHy\",\"provenances\":[[\"HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra\",\"AP4xBavdkoV0p8o/JeC4LOQW+T3AoCbirwzk76dDsMH7KE062okkVahRvzKBSTicjeiuRsUOUdqMRWf+BX0yDg==\"]],\"link\":null,\"link_same_type\":null,\"link_update_delete\":null,\"timestamp\":\"2020-02-03T05:19:00+00:00\"}]}", publish_ts: 1580707140 }] } }))
☯ DEBUG 2020-02-03 16:19:00 [holochain_metrics::logger] net_worker_thread/puid-4-30 crates/metrics/src/logger.rs:24 2020-02-03 05:19:00  METRIC sim2h_worker.tick.latency 0
☯ WARN 2020-02-03 16:19:03 [in_stream::tcp] net_worker_thread/puid-4-30 crates/in_stream/src/tcp.rs:304 dropping tcp stream Url2 { url: "tcp://localhost:9000/" }
☯ 
vvvv    hachiko warning    vvvv
a hachiko callback has been waiting for 5 seconds with no change
Processed 7 signal(s) so far, but
still waiting on the following 8 signal(s):
{
  txrx: {
    '{"Hold":"HcSCIzV7HGwCraosnaGuHW3vI3Txxq3x6whKnBjIC794h9kpPcwPuH3n7Kd89bz"}': Set { 'alice', 'bob' },
    '{"Hold":"QmV3dVBMbo5FgqdN8CCbMX9mNcxZwhtRxgh799Sojpstyw"}': Set { 'alice', 'bob' },
    '{"Hold":"QmScKnjosuFdJgLUjWzGHWk8kXNTAKWTWCji18Kq8wy8PV"}': Set { 'alice', 'bob' },
    '{"AddLink":{"action_kind":"ADD","link":{"base":"HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra","target":"QmV3dVBMbo5FgqdN8CCbMX9mNcxZwhtRxgh799Sojpstyw","link_type":"author_post","tag":""},"top_chain_header":{"entry_type":{"App":"post"},"entry_address":"QmV3dVBMbo5FgqdN8CCbMX9mNcxZwhtRxgh799Sojpstyw","provenances":[["HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra","9ytWLbiqVL7cbwqT1cFAMnxk024O3U83ZY3CL2JmcI0sWh8JhWs6feXPe//KJbGKBOq+152vdsrbHyOemK13Dg=="]],"link":"QmS3qpXfEyM7znhfjDQKppC4iMGHV4RYUEqtDhdoS4bELu","link_same_type":null,"link_update_delete":null,"timestamp":"2020-02-03T05:19:00+00:00"},"agent_id":{"nick":"alice::txrx::2ea86eb8-9551-4f12-9485-774a744c9ebc","pub_sign_key":"HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra"}}}': Set { 'alice', 'bob' }
  }
}
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
16:19:12 info: 
☸☸☸ {{{CONDUCTOR bob}}}
☸ DEBUG 2020-02-03 16:19:00 [holochain::txrx] main crates/core/src/workflows/application.rs:51 dna/initialize: No DNA and agent in chain so assuming uninitialized: ErrorGeneric("Agent entry not found")
☸ DEBUG 2020-02-03 16:19:00 [holochain::txrx] main crates/core/src/nucleus/actions/initialize.rs:155 initialize: created public token: HashString("QmWC9f1twbikMhi1GvxtD4CfLNdSEueaiuNVgJXK8cykL6")
☸ DEBUG 2020-02-03 16:19:00 [holochain::txrx] main crates/core/src/workflows/application.rs:57 dna/initialize: Initializing new chain from given DNA...
☸ DEBUG 2020-02-03 16:19:00 [holochain::txrx] main crates/core/src/network/actions/initialize_network.rs:26 waiting for network
☸ DEBUG 2020-02-03 16:19:00 [holochain_net::sim2h_worker] net_worker_thread/puid-4-30 crates/net/src/sim2h_worker.rs:235 WireMessage: queueing Status
☸ WARN 2020-02-03 16:19:00 [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-02-03 16:19:00 [holochain_net::sim2h_worker] net_worker_thread/puid-4-30 crates/net/src/sim2h_worker.rs:127 BACKOFF setting reconnect interval to 4000
☸ DEBUG 2020-02-03 16:19:00 [holochain_net::sim2h_worker] net_worker_thread/puid-4-30 crates/net/src/sim2h_worker.rs:572 CORE >> Sim2h: JoinSpace(SpaceData { request_id: "puid-4-31", space_address: SpaceHash(HashString("QmRXwCKqhcdga3e2LwGwT4maYpwQMudJ9zvLFcsQv3asFU")), agent_id: AgentPubKey(HashString("HcSCIzV7HGwCraosnaGuHW3vI3Txxq3x6whKnBjIC794h9kpPcwPuH3n7Kd89bz")) })
☸ DEBUG 2020-02-03 16:19:00 [holochain_net::sim2h_worker] net_worker_thread/puid-4-30 crates/net/src/sim2h_worker.rs:235 WireMessage: queueing ClientToLib3h(JoinSpace(SpaceData { request_id: "puid-4-31", space_address: SpaceHash(HashString("QmRXwCKqhcdga3e2LwGwT4maYpwQMudJ9zvLFcsQv3asFU")), agent_id: AgentPubKey(HashString("HcSCIzV7HGwCraosnaGuHW3vI3Txxq3x6whKnBjIC794h9kpPcwPuH3n7Kd89bz")) }))
☸ DEBUG 2020-02-03 16:19:00 [holochain_metrics::logger] net_worker_thread/puid-4-30 crates/metrics/src/logger.rs:24 2020-02-03 05:19:00  METRIC sim2h_worker.tick.latency 0
☸ DEBUG 2020-02-03 16:19:00 [holochain::txrx] main crates/conductor_lib/src/holochain.rs:168 conductor: Holochain App Name instantiated
☸ INFO 2020-02-03 16:19:00 [ws] main /home/docker/project/.cargo/registry/src/github.com-1ecc6299db9ec823/ws-0.9.1/src/lib.rs:308 Listening for new connections on 0.0.0.0:33001.
☸ DEBUG 2020-02-03 16:19:00 [jsonrpc_ws_server::server] main /home/docker/project/.cargo/registry/src/github.com-1ecc6299db9ec823/jsonrpc-ws-server-14.0.5/src/server.rs:101 Bound to local address: 0.0.0.0:33001
☸ DEBUG 2020-02-03 16:19:00 [holochain_conductor_lib::conductor::base] main crates/conductor_lib/src/conductor/base.rs:1390 conductor: adding broadcaster to map Broadcaster::Ws
☸ DEBUG 2020-02-03 16:19:00 [holochain_conductor_lib::conductor::base] main crates/conductor_lib/src/conductor/base.rs:338 starting signal loop
☸ INFO 2020-02-03 16:19:00 [ws::io]  /home/docker/project/.cargo/registry/src/github.com-1ecc6299db9ec823/ws-0.9.1/src/io.rs:614 Accepted a new tcp connection from 127.0.0.1:34786.
☸ DEBUG 2020-02-03 16:19:00 [ws::handshake]  /home/docker/project/.cargo/registry/src/github.com-1ecc6299db9ec823/ws-0.9.1/src/handshake.rs:625 Built response from request:
☸ HTTP/1.1 101 Switching Protocols
☸ Connection: Upgrade
☸ Sec-WebSocket-Accept: z3OCaVe0w+t+SfarwtUjpu310aU=
☸ Upgrade: websocket
☸ 
☸ 
☸ DEBUG 2020-02-03 16:19:00 [ws::handler]  /home/docker/project/.cargo/registry/src/github.com-1ecc6299db9ec823/ws-0.9.1/src/handler.rs:35 Connection with 127.0.0.1 now open
☸ DEBUG 2020-02-03 16:19:00 [ws::connection]  /home/docker/project/.cargo/registry/src/github.com-1ecc6299db9ec823/ws-0.9.1/src/connection.rs:564 Connection to 127.0.0.1:34786 is now open.
☸ DEBUG 2020-02-03 16:19:00 [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: 66
☸ payload length: 64
☸ payload: 0x7b226a736f6e727063223a22322e30222c226d6574686f64223a2261646d696e2f6167656e742f6c697374222c22706172616d73223a7b7d2c226964223a317d
☸             
☸ DEBUG 2020-02-03 16:19:00 [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: 64
☸ payload length: 62
☸ payload: 0x7b226a736f6e727063223a22322e30222c226d6574686f64223a2261646d696e2f646e612f6c697374222c22706172616d73223a7b7d2c226964223a327d
☸             
☸ DEBUG 2020-02-03 16:19:00 [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: 69
☸ payload length: 67
☸ payload: 0x7b226a736f6e727063223a22322e30222c226d6574686f64223a2261646d696e2f696e7374616e63652f6c697374222c22706172616d73223a7b7d2c226964223a337d
☸             
☸ WARN 2020-02-03 16:19:04 [in_stream::tcp] net_worker_thread/puid-4-30 crates/in_stream/src/tcp.rs:304 dropping tcp stream Url2 { url: "tcp://localhost:9000/" }
☸ ERROR 2020-02-03 16:19:04 [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-02-03 16:19:04 [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-02-03 16:19:04 [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-02-03 16:19:09 [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-02-03 16:19:12 [in_stream::tcp] net_worker_thread/puid-4-30 crates/in_stream/src/tcp.rs:304 dropping tcp stream Url2 { url: "tcp://localhost:9000/" }
☸ ERROR 2020-02-03 16:19:12 [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-02-03 16:19:12 [holochain_net::sim2h_worker] net_worker_thread/puid-4-30 crates/net/src/sim2h_worker.rs:153 BACKOFF attempting reconnect, connection state: None
☸ 
vvvv  hachiko timed out!  vvvv
a hachiko callback has been waiting for 12 seconds with no change
Processed 7 signal(s) so far, but
still waiting on the following 8 signal(s):
{
  txrx: {
    '{"Hold":"HcSCIzV7HGwCraosnaGuHW3vI3Txxq3x6whKnBjIC794h9kpPcwPuH3n7Kd89bz"}': Set { 'alice', 'bob' },
    '{"Hold":"QmV3dVBMbo5FgqdN8CCbMX9mNcxZwhtRxgh799Sojpstyw"}': Set { 'alice', 'bob' },
    '{"Hold":"QmScKnjosuFdJgLUjWzGHWk8kXNTAKWTWCji18Kq8wy8PV"}': Set { 'alice', 'bob' },
    '{"AddLink":{"action_kind":"ADD","link":{"base":"HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra","target":"QmV3dVBMbo5FgqdN8CCbMX9mNcxZwhtRxgh799Sojpstyw","link_type":"author_post","tag":""},"top_chain_header":{"entry_type":{"App":"post"},"entry_address":"QmV3dVBMbo5FgqdN8CCbMX9mNcxZwhtRxgh799Sojpstyw","provenances":[["HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra","9ytWLbiqVL7cbwqT1cFAMnxk024O3U83ZY3CL2JmcI0sWh8JhWs6feXPe//KJbGKBOq+152vdsrbHyOemK13Dg=="]],"link":"QmS3qpXfEyM7znhfjDQKppC4iMGHV4RYUEqtDhdoS4bELu","link_same_type":null,"link_update_delete":null,"timestamp":"2020-02-03T05:19:00+00:00"},"agent_id":{"nick":"alice::txrx::2ea86eb8-9551-4f12-9485-774a744c9ebc","pub_sign_key":"HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra"}}}': Set { 'alice', 'bob' }
  }
}
------------------------------
Successfully handled 7 observations:
[
  {
    dna: 'txrx',
    node: 'bob',
    signal: {
      signal_type: 'Consistency',
      event: '"InitializeChain"',
      pending: [Array]
    }
  },
  {
    dna: 'txrx',
    node: 'alice',
    signal: {
      signal_type: 'Consistency',
      event: '{"SignalZomeFunctionCall":["txrx/hello_holo",{"prefix":7,"offset":10}]}',
      pending: [Array]
    }
  },
  {
    dna: 'txrx',
    node: 'alice',
    signal: {
      signal_type: 'Consistency',
      event: '{"ReturnZomeFunctionResult":["txrx/hello_holo",{"prefix":7,"offset":10}]}',
      pending: []
    }
  },
  {
    dna: 'txrx',
    node: 'alice',
    signal: {
      signal_type: 'Consistency',
      event: '{"SignalZomeFunctionCall":["txrx/create_post",{"prefix":7,"offset":35}]}',
      pending: [Array]
    }
  },
  {
    dna: 'txrx',
    node: 'alice',
    signal: {
      signal_type: 'Consistency',
      event: '{"Publish":"QmV3dVBMbo5FgqdN8CCbMX9mNcxZwhtRxgh799Sojpstyw"}',
      pending: [Array]
    }
  },
  {
    dna: 'txrx',
    node: 'alice',
    signal: {
      signal_type: 'Consistency',
      event: '{"Publish":"QmScKnjosuFdJgLUjWzGHWk8kXNTAKWTWCji18Kq8wy8PV"}',
      pending: [Array]
    }
  },
  {
    dna: 'txrx',
    node: 'alice',
    signal: {
      signal_type: 'Consistency',
      event: '{"ReturnZomeFunctionResult":["txrx/create_post",{"prefix":7,"offset":35}]}',
      pending: []
    }
  }
]
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
Since hachiko is not in strict mode, the test will resume now,
even though hachiko thinks it will fail. Good luck!
16:19:12 [tryorama: player alice] debug: instance(txrx)
16:19:12 [tryorama: player alice] debug: call(txrx, txrx, retrieve_posts, {"agent_address":"HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra"})
16:19:12 [tryorama: tryorama conductor alice] debug: zome call [alice]: {id: txrx, zome: txrx, fn: retrieve_posts}
16:19:12 [tryorama: tryorama conductor alice] debug: params: {
  "agent_address": "HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra"
}
16:19:27 info: 
☮☮☮ {{{CONDUCTOR alice}}}
☮ ERROR 2020-02-03 16:19:03 [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-02-03 16:19:03 [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-02-03 16:19:03 [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-02-03 16:19:08 [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-02-03 16:19:11 [in_stream::tcp] net_worker_thread/puid-4-30 crates/in_stream/src/tcp.rs:304 dropping tcp stream Url2 { url: "tcp://localhost:9000/" }
☮ ERROR 2020-02-03 16:19:11 [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-02-03 16:19:11 [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-02-03 16:19:11 [holochain_net::sim2h_worker] net_worker_thread/puid-4-30 crates/net/src/sim2h_worker.rs:127 BACKOFF setting reconnect interval to 16000
☮ DEBUG 2020-02-03 16:19:12 [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: 209
☮ payload length: 205
☮ payload: 0x7b226a736f6e727063223a22322e30222c226d6574686f64223a2263616c6c222c22706172616d73223a7b22696e7374616e63655f6964223a2274787278222c227a6f6d65223a2274787278222c2266756e6374696f6e223a2272657472696576655f706f737473222c2261726773223a7b226167656e745f61646472657373223a224863536349424a727a676f656976773879746752494f58687a5a6d676f706261333736506f724f6f51425875656236753765483671797556527135366b7261227d7d2c226964223a367d
☮             
☮ DEBUG 2020-02-03 16:19:12 [holochain::txrx] event.loop0 crates/core/src/nucleus/actions/call_zome_function.rs:72 actions/call_zome_fn: Validating call: ZomeFnCall { id: ProcessUniqueId { prefix: 7, offset: 133 }, zome_name: "txrx", cap: CapabilityRequest { cap_token: HashString("QmWC9f1twbikMhi1GvxtD4CfLNdSEueaiuNVgJXK8cykL6"), provenance: Provenance(HashString("HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra"), Signature("HHK7Wqzb2hWrVh7fTLLZUPrp6qLhKDcVscH6D0foElT6MOq2wtPp33/3ypL67Fp843+buyViLwxXA0sd4yY+CQ==")) }, fn_name: "retrieve_posts", parameters: JsonString("{\"agent_address\":\"HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra\"}") }
☮ DEBUG 2020-02-03 16:19:12 [holochain::txrx] event.loop0 crates/core/src/nucleus/actions/call_zome_function.rs:81 actions/call_zome_fn: executing call: ZomeFnCall { id: ProcessUniqueId { prefix: 7, offset: 133 }, zome_name: "txrx", cap: CapabilityRequest { cap_token: HashString("QmWC9f1twbikMhi1GvxtD4CfLNdSEueaiuNVgJXK8cykL6"), provenance: Provenance(HashString("HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra"), Signature("HHK7Wqzb2hWrVh7fTLLZUPrp6qLhKDcVscH6D0foElT6MOq2wtPp33/3ypL67Fp843+buyViLwxXA0sd4yY+CQ==")) }, fn_name: "retrieve_posts", parameters: JsonString("{\"agent_address\":\"HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra\"}") }
☮ DEBUG 2020-02-03 16:19:12 [holochain::txrx] 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: 133 }, zome_name: "txrx", cap: CapabilityRequest { cap_token: HashString("QmWC9f1twbikMhi1GvxtD4CfLNdSEueaiuNVgJXK8cykL6"), provenance: Provenance(HashString("HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra"), Signature("HHK7Wqzb2hWrVh7fTLLZUPrp6qLhKDcVscH6D0foElT6MOq2wtPp33/3ypL67Fp843+buyViLwxXA0sd4yY+CQ==")) }, fn_name: "retrieve_posts", parameters: JsonString("{\"agent_address\":\"HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra\"}") }
☮ DEBUG 2020-02-03 16:19:12 [holochain::txrx] ZomeFnCall { id: ProcessUniqueId { prefix: 7, offset: 133 }, zome_name: "txrx", cap: CapabilityRequest { cap_token: HashString("QmWC9f1twbikMhi1GvxtD4CfLNdSEueaiuNVgJXK8cykL6"), provenance: Provenance(HashString("HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra"), Signature("HHK7Wqzb2hWrVh7fTLLZUPrp6qLhKDcVscH6D0foElT6MOq2wtPp33/3ypL67Fp843+buyViLwxXA0sd4yY+CQ==")) }, fn_name: "retrieve_posts", parameters: JsonString("{\"agent_address\":\"HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra\"}") } crates/core/src/nucleus/ribosome/api/get_links.rs:19 zome/get_links: invoke_get_links called with GetLinksArgs { entry_address: HashString("HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra"), link_type: "^author_post$", tag: ".*", options: GetLinksOptions { status_request: Live, headers: false, timeout: Timeout(60000) } }
☮ DEBUG 2020-02-03 16:19:12 [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("QmRXwCKqhcdga3e2LwGwT4maYpwQMudJ9zvLFcsQv3asFU")), entry_address: EntryHash(HashString("HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra")), request_id: "puid-b-2", requester_agent_id: AgentPubKey(HashString("HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra")), query: "{\"GetLinks\":[\"^author_post$\",\".*\",\"live\",{\"Links\":{\"headers\":false}}]}" })
☮ DEBUG 2020-02-03 16:19:12 [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("QmRXwCKqhcdga3e2LwGwT4maYpwQMudJ9zvLFcsQv3asFU")), entry_address: EntryHash(HashString("HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra")), request_id: "puid-b-2", requester_agent_id: AgentPubKey(HashString("HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra")), query: "{\"GetLinks\":[\"^author_post$\",\".*\",\"live\",{\"Links\":{\"headers\":false}}]}" }))
☮ DEBUG 2020-02-03 16:19:12 [holochain_metrics::logger] net_worker_thread/puid-4-30 crates/metrics/src/logger.rs:24 2020-02-03 05:19:12  METRIC sim2h_worker.tick.latency 0
☮ DEBUG 2020-02-03 16:19: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-02-03 16:19:27 [in_stream::tcp] net_worker_thread/puid-4-30 crates/in_stream/src/tcp.rs:304 dropping tcp stream Url2 { url: "tcp://localhost:9000/" }
☮ ERROR 2020-02-03 16:19:27 [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)))" }
☮ 
16:19:57 [tryorama: tryorama conductor alice] warn: Zome call 'txrx/retrieve_posts' has been running for more than 45 seconds. Continuing to wait...
16:20:13 [tryorama: tryorama conductor alice] debug: -> {
  Err: {
    Internal: '{"kind":"Timeout","file":"crates/core/src/nucleus/ribosome/runtime.rs","line":"220"}'
  }
}
not ok 4 RETRIEVED A POST WORKED
  ---
    operator: ok
    expected: true
    actual:   undefined
    stack: |-
      Error: RETRIEVED A POST WORKED
          at Test.assert [as _assert] (/home/simwilso/Code/TestDemo/txrx/test/node_modules/tape/lib/test.js:228:54)
          at Test.bound [as _assert] (/home/simwilso/Code/TestDemo/txrx/test/node_modules/tape/lib/test.js:80:32)
          at Test.assert (/home/simwilso/Code/TestDemo/txrx/test/node_modules/tape/lib/test.js:347:10)
          at Test.bound [as ok] (/home/simwilso/Code/TestDemo/txrx/test/node_modules/tape/lib/test.js:80:32)
          at /home/simwilso/Code/TestDemo/txrx/test/index.js:75:5
          at processTicksAndRejections (internal/process/task_queues.js:93:5)
  ...
not ok 5 should be equivalent
  ---
    operator: deepEqual
    expected: |-
      [ { message: 'Hello blog', timestamp: 1580707140672, author_id: 'HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra' } ]
    actual: |-
      undefined
    stack: |-
      Error: should be equivalent
          at Test.assert [as _assert] (/home/simwilso/Code/TestDemo/txrx/test/node_modules/tape/lib/test.js:228:54)
          at Test.bound [as _assert] (/home/simwilso/Code/TestDemo/txrx/test/node_modules/tape/lib/test.js:80:32)
          at Test.tapeDeepEqual (/home/simwilso/Code/TestDemo/txrx/test/node_modules/tape/lib/test.js:426:10)
          at Test.bound [as deepEqual] (/home/simwilso/Code/TestDemo/txrx/test/node_modules/tape/lib/test.js:80:32)
          at /home/simwilso/Code/TestDemo/txrx/test/index.js:82:5
          at processTicksAndRejections (internal/process/task_queues.js:93:5)
  ...
vvvv    hachiko warning    vvvv
a hachiko callback has been waiting for 5 seconds with no change
Processed 9 signal(s) so far, but
still waiting on the following 8 signal(s):
{
  txrx: {
    '{"Hold":"HcSCIzV7HGwCraosnaGuHW3vI3Txxq3x6whKnBjIC794h9kpPcwPuH3n7Kd89bz"}': Set { 'alice', 'bob' },
    '{"Hold":"QmV3dVBMbo5FgqdN8CCbMX9mNcxZwhtRxgh799Sojpstyw"}': Set { 'alice', 'bob' },
    '{"Hold":"QmScKnjosuFdJgLUjWzGHWk8kXNTAKWTWCji18Kq8wy8PV"}': Set { 'alice', 'bob' },
    '{"AddLink":{"action_kind":"ADD","link":{"base":"HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra","target":"QmV3dVBMbo5FgqdN8CCbMX9mNcxZwhtRxgh799Sojpstyw","link_type":"author_post","tag":""},"top_chain_header":{"entry_type":{"App":"post"},"entry_address":"QmV3dVBMbo5FgqdN8CCbMX9mNcxZwhtRxgh799Sojpstyw","provenances":[["HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra","9ytWLbiqVL7cbwqT1cFAMnxk024O3U83ZY3CL2JmcI0sWh8JhWs6feXPe//KJbGKBOq+152vdsrbHyOemK13Dg=="]],"link":"QmS3qpXfEyM7znhfjDQKppC4iMGHV4RYUEqtDhdoS4bELu","link_same_type":null,"link_update_delete":null,"timestamp":"2020-02-03T05:19:00+00:00"},"agent_id":{"nick":"alice::txrx::2ea86eb8-9551-4f12-9485-774a744c9ebc","pub_sign_key":"HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra"}}}': Set { 'alice', 'bob' }
  }
}
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
vvvv  hachiko timed out!  vvvv
a hachiko callback has been waiting for 12 seconds with no change
Processed 9 signal(s) so far, but
still waiting on the following 8 signal(s):
{
  txrx: {
    '{"Hold":"HcSCIzV7HGwCraosnaGuHW3vI3Txxq3x6whKnBjIC794h9kpPcwPuH3n7Kd89bz"}': Set { 'alice', 'bob' },
    '{"Hold":"QmV3dVBMbo5FgqdN8CCbMX9mNcxZwhtRxgh799Sojpstyw"}': Set { 'alice', 'bob' },
    '{"Hold":"QmScKnjosuFdJgLUjWzGHWk8kXNTAKWTWCji18Kq8wy8PV"}': Set { 'alice', 'bob' },
    '{"AddLink":{"action_kind":"ADD","link":{"base":"HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra","target":"QmV3dVBMbo5FgqdN8CCbMX9mNcxZwhtRxgh799Sojpstyw","link_type":"author_post","tag":""},"top_chain_header":{"entry_type":{"App":"post"},"entry_address":"QmV3dVBMbo5FgqdN8CCbMX9mNcxZwhtRxgh799Sojpstyw","provenances":[["HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra","9ytWLbiqVL7cbwqT1cFAMnxk024O3U83ZY3CL2JmcI0sWh8JhWs6feXPe//KJbGKBOq+152vdsrbHyOemK13Dg=="]],"link":"QmS3qpXfEyM7znhfjDQKppC4iMGHV4RYUEqtDhdoS4bELu","link_same_type":null,"link_update_delete":null,"timestamp":"2020-02-03T05:19:00+00:00"},"agent_id":{"nick":"alice::txrx::2ea86eb8-9551-4f12-9485-774a744c9ebc","pub_sign_key":"HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra"}}}': Set { 'alice', 'bob' }
  }
}
------------------------------
Successfully handled 9 observations:
[
  {
    dna: 'txrx',
    node: 'bob',
    signal: {
      signal_type: 'Consistency',
      event: '"InitializeChain"',
      pending: [Array]
    }
  },
  {
    dna: 'txrx',
    node: 'alice',
    signal: {
      signal_type: 'Consistency',
      event: '{"SignalZomeFunctionCall":["txrx/hello_holo",{"prefix":7,"offset":10}]}',
      pending: [Array]
    }
  },
  {
    dna: 'txrx',
    node: 'alice',
    signal: {
      signal_type: 'Consistency',
      event: '{"ReturnZomeFunctionResult":["txrx/hello_holo",{"prefix":7,"offset":10}]}',
      pending: []
    }
  },
  {
    dna: 'txrx',
    node: 'alice',
    signal: {
      signal_type: 'Consistency',
      event: '{"SignalZomeFunctionCall":["txrx/create_post",{"prefix":7,"offset":35}]}',
      pending: [Array]
    }
  },
  {
    dna: 'txrx',
    node: 'alice',
    signal: {
      signal_type: 'Consistency',
      event: '{"Publish":"QmV3dVBMbo5FgqdN8CCbMX9mNcxZwhtRxgh799Sojpstyw"}',
      pending: [Array]
    }
  },
  {
    dna: 'txrx',
    node: 'alice',
    signal: {
      signal_type: 'Consistency',
      event: '{"Publish":"QmScKnjosuFdJgLUjWzGHWk8kXNTAKWTWCji18Kq8wy8PV"}',
      pending: [Array]
    }
  },
  {
    dna: 'txrx',
    node: 'alice',
    signal: {
      signal_type: 'Consistency',
      event: '{"ReturnZomeFunctionResult":["txrx/create_post",{"prefix":7,"offset":35}]}',
      pending: []
    }
  },
  {
    dna: 'txrx',
    node: 'alice',
    signal: {
      signal_type: 'Consistency',
      event: '{"SignalZomeFunctionCall":["txrx/retrieve_posts",{"prefix":7,"offset":133}]}',
      pending: [Array]
    }
  },
  {
    dna: 'txrx',
    node: 'alice',
    signal: {
      signal_type: 'Consistency',
      event: '{"ReturnZomeFunctionResult":["txrx/retrieve_posts",{"prefix":7,"offset":133}]}',
      pending: []
    }
  }
]
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
Since hachiko is not in strict mode, the test will resume now,
even though hachiko thinks it will fail. Good luck!
16:20:25 [tryorama: player bob] debug: call(txrx, txrx, retrieve_posts, {"agent_address":"HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra"})
16:20:25 [tryorama: tryorama conductor bob] debug: zome call [bob]: {id: txrx, zome: txrx, fn: retrieve_posts}
16:20:25 [tryorama: tryorama conductor bob] debug: params: {
  "agent_address": "HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra"
}
16:20:25 info: 
☉☉☉ {{{CONDUCTOR bob}}}
☉ DEBUG 2020-02-03 16:19:12 [holochain_net::sim2h_worker] net_worker_thread/puid-4-30 crates/net/src/sim2h_worker.rs:127 BACKOFF setting reconnect interval to 16000
☉ DEBUG 2020-02-03 16:19:20 [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-02-03 16:19:28 [in_stream::tcp] net_worker_thread/puid-4-30 crates/in_stream/src/tcp.rs:304 dropping tcp stream Url2 { url: "tcp://localhost:9000/" }
☉ ERROR 2020-02-03 16:19:28 [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-02-03 16:19:28 [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-02-03 16:19:28 [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-02-03 16:19:31 [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-02-03 16:19:42 [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-02-03 16:19:53 [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-02-03 16:20:00 [in_stream::tcp] net_worker_thread/puid-4-30 crates/in_stream/src/tcp.rs:304 dropping tcp stream Url2 { url: "tcp://localhost:9000/" }
☉ ERROR 2020-02-03 16:20:00 [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-02-03 16:20:00 [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-02-03 16:20:00 [holochain_net::sim2h_worker] net_worker_thread/puid-4-30 crates/net/src/sim2h_worker.rs:127 BACKOFF setting reconnect interval to 64000
☉ DEBUG 2020-02-03 16:20:04 [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-02-03 16:20:15 [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-02-03 16:20:25 [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: 209
☉ payload length: 205
☉ payload: 0x7b226a736f6e727063223a22322e30222c226d6574686f64223a2263616c6c222c22706172616d73223a7b22696e7374616e63655f6964223a2274787278222c227a6f6d65223a2274787278222c2266756e6374696f6e223a2272657472696576655f706f737473222c2261726773223a7b226167656e745f61646472657373223a224863536349424a727a676f656976773879746752494f58687a5a6d676f706261333736506f724f6f51425875656236753765483671797556527135366b7261227d7d2c226964223a347d
☉             
☉ DEBUG 2020-02-03 16:20:25 [holochain::txrx] event.loop0 crates/core/src/nucleus/actions/call_zome_function.rs:72 actions/call_zome_fn: Validating call: ZomeFnCall { id: ProcessUniqueId { prefix: 7, offset: 10 }, zome_name: "txrx", cap: CapabilityRequest { cap_token: HashString("QmWC9f1twbikMhi1GvxtD4CfLNdSEueaiuNVgJXK8cykL6"), provenance: Provenance(HashString("HcSCIzV7HGwCraosnaGuHW3vI3Txxq3x6whKnBjIC794h9kpPcwPuH3n7Kd89bz"), Signature("kWGTgUJjX3UiMYJluChKTKfAcQY9XX54/36yviF8ByNEnArGLTj+DYT+y5/SvwHOUpb0eSXqKmffaMrdxN6oCg==")) }, fn_name: "retrieve_posts", parameters: JsonString("{\"agent_address\":\"HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra\"}") }
☉ DEBUG 2020-02-03 16:20:25 [holochain::txrx] event.loop0 crates/core/src/nucleus/actions/call_zome_function.rs:81 actions/call_zome_fn: executing call: ZomeFnCall { id: ProcessUniqueId { prefix: 7, offset: 10 }, zome_name: "txrx", cap: CapabilityRequest { cap_token: HashString("QmWC9f1twbikMhi1GvxtD4CfLNdSEueaiuNVgJXK8cykL6"), provenance: Provenance(HashString("HcSCIzV7HGwCraosnaGuHW3vI3Txxq3x6whKnBjIC794h9kpPcwPuH3n7Kd89bz"), Signature("kWGTgUJjX3UiMYJluChKTKfAcQY9XX54/36yviF8ByNEnArGLTj+DYT+y5/SvwHOUpb0eSXqKmffaMrdxN6oCg==")) }, fn_name: "retrieve_posts", parameters: JsonString("{\"agent_address\":\"HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra\"}") }
☉ DEBUG 2020-02-03 16:20:25 [holochain::txrx] 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: 10 }, zome_name: "txrx", cap: CapabilityRequest { cap_token: HashString("QmWC9f1twbikMhi1GvxtD4CfLNdSEueaiuNVgJXK8cykL6"), provenance: Provenance(HashString("HcSCIzV7HGwCraosnaGuHW3vI3Txxq3x6whKnBjIC794h9kpPcwPuH3n7Kd89bz"), Signature("kWGTgUJjX3UiMYJluChKTKfAcQY9XX54/36yviF8ByNEnArGLTj+DYT+y5/SvwHOUpb0eSXqKmffaMrdxN6oCg==")) }, fn_name: "retrieve_posts", parameters: JsonString("{\"agent_address\":\"HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra\"}") }
☉ DEBUG 2020-02-03 16:20:25 [holochain::txrx] ZomeFnCall { id: ProcessUniqueId { prefix: 7, offset: 10 }, zome_name: "txrx", cap: CapabilityRequest { cap_token: HashString("QmWC9f1twbikMhi1GvxtD4CfLNdSEueaiuNVgJXK8cykL6"), provenance: Provenance(HashString("HcSCIzV7HGwCraosnaGuHW3vI3Txxq3x6whKnBjIC794h9kpPcwPuH3n7Kd89bz"), Signature("kWGTgUJjX3UiMYJluChKTKfAcQY9XX54/36yviF8ByNEnArGLTj+DYT+y5/SvwHOUpb0eSXqKmffaMrdxN6oCg==")) }, fn_name: "retrieve_posts", parameters: JsonString("{\"agent_address\":\"HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra\"}") } crates/core/src/nucleus/ribosome/api/get_links.rs:19 zome/get_links: invoke_get_links called with GetLinksArgs { entry_address: HashString("HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra"), link_type: "^author_post$", tag: ".*", options: GetLinksOptions { status_request: Live, headers: false, timeout: Timeout(60000) } }
☉ DEBUG 2020-02-03 16:20:25 [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("QmRXwCKqhcdga3e2LwGwT4maYpwQMudJ9zvLFcsQv3asFU")), entry_address: EntryHash(HashString("HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra")), request_id: "puid-9-2", requester_agent_id: AgentPubKey(HashString("HcSCIzV7HGwCraosnaGuHW3vI3Txxq3x6whKnBjIC794h9kpPcwPuH3n7Kd89bz")), query: "{\"GetLinks\":[\"^author_post$\",\".*\",\"live\",{\"Links\":{\"headers\":false}}]}" })
☉ 
16:21:10 [tryorama: tryorama conductor bob] warn: Zome call 'txrx/retrieve_posts' has been running for more than 45 seconds. Continuing to wait...
16:21:26 [tryorama: tryorama conductor bob] debug: -> {
  Err: {
    Internal: '{"kind":"Timeout","file":"crates/core/src/nucleus/ribosome/runtime.rs","line":"220"}'
  }
}
not ok 6 should be truthy
  ---
    operator: ok
    expected: true
    actual:   undefined
    stack: |-
      Error: should be truthy
          at Test.assert [as _assert] (/home/simwilso/Code/TestDemo/txrx/test/node_modules/tape/lib/test.js:228:54)
          at Test.bound [as _assert] (/home/simwilso/Code/TestDemo/txrx/test/node_modules/tape/lib/test.js:80:32)
          at Test.assert (/home/simwilso/Code/TestDemo/txrx/test/node_modules/tape/lib/test.js:347:10)
          at Test.bound [as ok] (/home/simwilso/Code/TestDemo/txrx/test/node_modules/tape/lib/test.js:80:32)
          at /home/simwilso/Code/TestDemo/txrx/test/index.js:92:5
          at processTicksAndRejections (internal/process/task_queues.js:93:5)
  ...
not ok 7 should be equivalent
  ---
    operator: deepEqual
    expected: |-
      [ { message: 'Hello blog', timestamp: 1580707140672, author_id: 'HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra' } ]
    actual: |-
      undefined
    stack: |-
      Error: should be equivalent
          at Test.assert [as _assert] (/home/simwilso/Code/TestDemo/txrx/test/node_modules/tape/lib/test.js:228:54)
          at Test.bound [as _assert] (/home/simwilso/Code/TestDemo/txrx/test/node_modules/tape/lib/test.js:80:32)
          at Test.tapeDeepEqual (/home/simwilso/Code/TestDemo/txrx/test/node_modules/tape/lib/test.js:426:10)
          at Test.bound [as deepEqual] (/home/simwilso/Code/TestDemo/txrx/test/node_modules/tape/lib/test.js:80:32)
          at /home/simwilso/Code/TestDemo/txrx/test/index.js:94:5
          at processTicksAndRejections (internal/process/task_queues.js:93:5)
  ...
success for  Test hello holo
16:21:26 [tryorama] debug: Done with test: Test hello holo
16:21:26 [tryorama: player alice] debug: Killing...
16:21:26 [tryorama: tryorama conductor alice] debug: Killing...
16:21:26 [tryorama: player bob] debug: Killing...
16:21:26 [tryorama: tryorama conductor bob] debug: Killing...
16:21:26 info: 
★★★ [[[CONDUCTOR alice]]]
★ Gracefully shutting down conductor...
★ Stopping interface tryorama-interface
★ Stopping instance "txrx"...
★ 
16:21:26 info: 
☯☯☯ [[[CONDUCTOR bob]]]
☯ Gracefully shutting down conductor...
☯ Stopping interface tryorama-interface
☯ Stopping instance "txrx"...
☯ 
16:21:26 [tryorama: player alice] debug: Killed.
16:21:26 info: 
☸☸☸ {{{CONDUCTOR alice}}}
☸ WARN 2020-02-03 16:19:27 [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-02-03 16:19:27 [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-02-03 16:19: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
☸ DEBUG 2020-02-03 16:19: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-02-03 16:19: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
☸ WARN 2020-02-03 16:19:59 [in_stream::tcp] net_worker_thread/puid-4-30 crates/in_stream/src/tcp.rs:304 dropping tcp stream Url2 { url: "tcp://localhost:9000/" }
☸ ERROR 2020-02-03 16:19:59 [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-02-03 16:19:59 [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-02-03 16:19:59 [holochain_net::sim2h_worker] net_worker_thread/puid-4-30 crates/net/src/sim2h_worker.rs:127 BACKOFF setting reconnect interval to 64000
☸ DEBUG 2020-02-03 16:20: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
☸ ERROR 2020-02-03 16:20:13 [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-02-03 16:20:13 [holochain::txrx] ZomeFnCall { id: ProcessUniqueId { prefix: 7, offset: 133 }, zome_name: "txrx", cap: CapabilityRequest { cap_token: HashString("QmWC9f1twbikMhi1GvxtD4CfLNdSEueaiuNVgJXK8cykL6"), provenance: Provenance(HashString("HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra"), Signature("HHK7Wqzb2hWrVh7fTLLZUPrp6qLhKDcVscH6D0foElT6MOq2wtPp33/3ypL67Fp843+buyViLwxXA0sd4yY+CQ==")) }, fn_name: "retrieve_posts", parameters: JsonString("{\"agent_address\":\"HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra\"}") } crates/core/src/nucleus/actions/call_zome_function.rs:288 actions/call_zome_fn: got call_result from ribosome::run_dna.
☸ DEBUG 2020-02-03 16:20:13 [holochain::txrx] ZomeFnCall { id: ProcessUniqueId { prefix: 7, offset: 133 }, zome_name: "txrx", cap: CapabilityRequest { cap_token: HashString("QmWC9f1twbikMhi1GvxtD4CfLNdSEueaiuNVgJXK8cykL6"), provenance: Provenance(HashString("HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra"), Signature("HHK7Wqzb2hWrVh7fTLLZUPrp6qLhKDcVscH6D0foElT6MOq2wtPp33/3ypL67Fp843+buyViLwxXA0sd4yY+CQ==")) }, fn_name: "retrieve_posts", parameters: JsonString("{\"agent_address\":\"HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra\"}") } crates/core/src/nucleus/actions/call_zome_function.rs:295 actions/call_zome_fn: sending ReturnZomeFunctionResult action.
☸ DEBUG 2020-02-03 16:20:13 [holochain::txrx] ZomeFnCall { id: ProcessUniqueId { prefix: 7, offset: 133 }, zome_name: "txrx", cap: CapabilityRequest { cap_token: HashString("QmWC9f1twbikMhi1GvxtD4CfLNdSEueaiuNVgJXK8cykL6"), provenance: Provenance(HashString("HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra"), Signature("HHK7Wqzb2hWrVh7fTLLZUPrp6qLhKDcVscH6D0foElT6MOq2wtPp33/3ypL67Fp843+buyViLwxXA0sd4yY+CQ==")) }, fn_name: "retrieve_posts", parameters: JsonString("{\"agent_address\":\"HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra\"}") } crates/core/src/nucleus/actions/call_zome_function.rs:304 actions/call_zome_fn: sent ReturnZomeFunctionResult action.
☸ DEBUG 2020-02-03 16:20:13 [holochain_metrics::logger] event.loop0 crates/metrics/src/logger.rs:24 2020-02-03 05:19:12  METRIC call_zome_function.txrx.retrieve_posts.latency 60863
☸ DEBUG 2020-02-03 16:20:14 [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-02-03 16:20:25 [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-02-03 16:20:36 [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-02-03 16:20:47 [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-02-03 16:20:58 [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-02-03 16:21:03 [in_stream::tcp] net_worker_thread/puid-4-30 crates/in_stream/src/tcp.rs:304 dropping tcp stream Url2 { url: "tcp://localhost:9000/" }
☸ ERROR 2020-02-03 16:21:03 [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-02-03 16:21:03 [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-02-03 16:21:03 [holochain_net::sim2h_worker] net_worker_thread/puid-4-30 crates/net/src/sim2h_worker.rs:127 BACKOFF setting reconnect interval to 128000
☸ DEBUG 2020-02-03 16:21:09 [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-02-03 16:21:20 [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-02-03 16:21:26 [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.
☸ 
16:21:26 [tryorama: player bob] debug: Killed.
16:21:27 info: 
☮☮☮ {{{CONDUCTOR bob}}}
☮ DEBUG 2020-02-03 16:20:25 [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("QmRXwCKqhcdga3e2LwGwT4maYpwQMudJ9zvLFcsQv3asFU")), entry_address: EntryHash(HashString("HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra")), request_id: "puid-9-2", requester_agent_id: AgentPubKey(HashString("HcSCIzV7HGwCraosnaGuHW3vI3Txxq3x6whKnBjIC794h9kpPcwPuH3n7Kd89bz")), query: "{\"GetLinks\":[\"^author_post$\",\".*\",\"live\",{\"Links\":{\"headers\":false}}]}" }))
☮ DEBUG 2020-02-03 16:20:25 [holochain_metrics::logger] net_worker_thread/puid-4-30 crates/metrics/src/logger.rs:24 2020-02-03 05:20:25  METRIC sim2h_worker.tick.latency 0
☮ DEBUG 2020-02-03 16:20:26 [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-02-03 16:20:37 [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-02-03 16:20:48 [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-02-03 16:20:59 [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-02-03 16:21:04 [in_stream::tcp] net_worker_thread/puid-4-30 crates/in_stream/src/tcp.rs:304 dropping tcp stream Url2 { url: "tcp://localhost:9000/" }
☮ ERROR 2020-02-03 16:21:04 [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-02-03 16:21:04 [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-02-03 16:21:04 [holochain_net::sim2h_worker] net_worker_thread/puid-4-30 crates/net/src/sim2h_worker.rs:127 BACKOFF setting reconnect interval to 128000
☮ DEBUG 2020-02-03 16:21:10 [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-02-03 16:21:21 [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
☮ ERROR 2020-02-03 16:21:26 [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-02-03 16:21:26 [holochain::txrx] ZomeFnCall { id: ProcessUniqueId { prefix: 7, offset: 10 }, zome_name: "txrx", cap: CapabilityRequest { cap_token: HashString("QmWC9f1twbikMhi1GvxtD4CfLNdSEueaiuNVgJXK8cykL6"), provenance: Provenance(HashString("HcSCIzV7HGwCraosnaGuHW3vI3Txxq3x6whKnBjIC794h9kpPcwPuH3n7Kd89bz"), Signature("kWGTgUJjX3UiMYJluChKTKfAcQY9XX54/36yviF8ByNEnArGLTj+DYT+y5/SvwHOUpb0eSXqKmffaMrdxN6oCg==")) }, fn_name: "retrieve_posts", parameters: JsonString("{\"agent_address\":\"HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra\"}") } crates/core/src/nucleus/actions/call_zome_function.rs:288 actions/call_zome_fn: got call_result from ribosome::run_dna.
☮ DEBUG 2020-02-03 16:21:26 [holochain::txrx] ZomeFnCall { id: ProcessUniqueId { prefix: 7, offset: 10 }, zome_name: "txrx", cap: CapabilityRequest { cap_token: HashString("QmWC9f1twbikMhi1GvxtD4CfLNdSEueaiuNVgJXK8cykL6"), provenance: Provenance(HashString("HcSCIzV7HGwCraosnaGuHW3vI3Txxq3x6whKnBjIC794h9kpPcwPuH3n7Kd89bz"), Signature("kWGTgUJjX3UiMYJluChKTKfAcQY9XX54/36yviF8ByNEnArGLTj+DYT+y5/SvwHOUpb0eSXqKmffaMrdxN6oCg==")) }, fn_name: "retrieve_posts", parameters: JsonString("{\"agent_address\":\"HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra\"}") } crates/core/src/nucleus/actions/call_zome_function.rs:295 actions/call_zome_fn: sending ReturnZomeFunctionResult action.
☮ DEBUG 2020-02-03 16:21:26 [holochain::txrx] ZomeFnCall { id: ProcessUniqueId { prefix: 7, offset: 10 }, zome_name: "txrx", cap: CapabilityRequest { cap_token: HashString("QmWC9f1twbikMhi1GvxtD4CfLNdSEueaiuNVgJXK8cykL6"), provenance: Provenance(HashString("HcSCIzV7HGwCraosnaGuHW3vI3Txxq3x6whKnBjIC794h9kpPcwPuH3n7Kd89bz"), Signature("kWGTgUJjX3UiMYJluChKTKfAcQY9XX54/36yviF8ByNEnArGLTj+DYT+y5/SvwHOUpb0eSXqKmffaMrdxN6oCg==")) }, fn_name: "retrieve_posts", parameters: JsonString("{\"agent_address\":\"HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra\"}") } crates/core/src/nucleus/actions/call_zome_function.rs:304 actions/call_zome_fn: sent ReturnZomeFunctionResult action.
☮ DEBUG 2020-02-03 16:21:26 [holochain_metrics::logger] event.loop0 crates/metrics/src/logger.rs:24 2020-02-03 05:20:25  METRIC call_zome_function.txrx.retrieve_posts.latency 60716
☮ DEBUG 2020-02-03 16:21:26 [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-02-03 16:21:26 [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-02-03 16:21:26 [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-02-03 16:21:26 [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-59", space_address: SpaceHash(HashString("QmRXwCKqhcdga3e2LwGwT4maYpwQMudJ9zvLFcsQv3asFU")), agent_id: AgentPubKey(HashString("HcSCIzV7HGwCraosnaGuHW3vI3Txxq3x6whKnBjIC794h9kpPcwPuH3n7Kd89bz")) })
☮ DEBUG 2020-02-03 16:21:26 [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-59", space_address: SpaceHash(HashString("QmRXwCKqhcdga3e2LwGwT4maYpwQMudJ9zvLFcsQv3asFU")), agent_id: AgentPubKey(HashString("HcSCIzV7HGwCraosnaGuHW3vI3Txxq3x6whKnBjIC794h9kpPcwPuH3n7Kd89bz")) }))
☮ DEBUG 2020-02-03 16:21:26 [holochain_metrics::logger] net_worker_thread/puid-4-30 crates/metrics/src/logger.rs:24 2020-02-03 05:21:26  METRIC sim2h_worker.tick.latency 0
☮ 
16:21:28 info: 
☉☉☉ {{{CONDUCTOR alice}}}
☉ DEBUG 2020-02-03 16:21:26 [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-02-03 16:21:26 [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-02-03 16:21:26 [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-d8", space_address: SpaceHash(HashString("QmRXwCKqhcdga3e2LwGwT4maYpwQMudJ9zvLFcsQv3asFU")), agent_id: AgentPubKey(HashString("HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra")) })
☉ DEBUG 2020-02-03 16:21:26 [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-d8", space_address: SpaceHash(HashString("QmRXwCKqhcdga3e2LwGwT4maYpwQMudJ9zvLFcsQv3asFU")), agent_id: AgentPubKey(HashString("HcScIBJrzgoeivw8ytgRIOXhzZmgopba376PorOoQBXueb6u7eH6qyuVRq56kra")) }))
☉ DEBUG 2020-02-03 16:21:26 [holochain_metrics::logger] net_worker_thread/puid-4-30 crates/metrics/src/logger.rs:24 2020-02-03 05:21:26  METRIC sim2h_worker.tick.latency 0
☉ DEBUG 2020-02-03 16:21:28 [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)
☉ Write  puid-0-8d         1991
☉ Write  puid-4-d7         1991
☉ Lock   puid-0-8c         1991
☉ DEBUG 2020-02-03 16:21:28 [holochain_net::connection::net_connection_thread] action_loop/puid-0-23 crates/net/src/connection/net_connection_thread.rs:154 Telling NetWorker to stop
☉ 
16:21:28 info: 
★★★ {{{CONDUCTOR bob}}}
★ DEBUG 2020-02-03 16:21:27 [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)
★ Write  puid-0-8e         1132
★ Write  puid-4-58         1132
★ Lock   puid-0-8d         1132
★ DEBUG 2020-02-03 16:21:28 [holochain_net::connection::net_connection_thread] action_loop/puid-0-23 crates/net/src/connection/net_connection_thread.rs:154 Telling NetWorker to stop
★ 
16:21:28 info: 
☯☯☯ {{{CONDUCTOR alice}}}
☯ thread 'holding_loop/puid-0-24' panicked at 'Tried to use dropped state', src/libcore/option.rs:1187:5
☯ stack backtrace:
☯ 
16:21:28 info: 
☸☸☸ {{{CONDUCTOR bob}}}
☸ thread 'holding_loop/puid-0-24' panicked at 'Tried to use dropped state', src/libcore/option.rs:1187:5
☸ stack backtrace:
☸ 
16:21:28 [tryorama] info: conductor 'alice' exited with code 0
16:21:28 [tryorama] info: conductor 'bob' exited with code 0

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