search

fission-codes / go-car-mirror

Generic Go implementation of the CAR Mirror protocol
Apache License 2.0
4 stars 0 forks source link

Pull sessions intermittently don't close #77

Closed justindotpub closed 1 year ago

justindotpub commented 1 year ago

When initiating a pull from source to sink (i.e. calling http client's Receive on the sink node), intermittently the session won't close. In my testing I've seen SOURCE_CLOSING|SOURCE_WAITING on source and SINK_CLOSING|SINK_FLUSHING|SINK_SENDING on sink.

Sometimes this happens first try. Other times it happens after maybe 3 repeated pulls.

I haven't been able to reproduce the same with push yet (i.e. calling http client's Send on source node).

justindotpub commented 1 year ago

Another with sink SINK_CLOSING|SINK_CLOSED|SINK_FLUSHING|SINK_WAITING on sink and SOURCE_CLOSING|SOURCE_WAITING on source.

justindotpub commented 1 year ago

When calling http client's Receive it sometimes hangs and never returns, because sometimes its calls to Enqueue hang and never return, because it's waiting for SINK_FLUSHING to become 0 and it isn't.

Here are some debug statements leading up to the hang.

2023-01-31T11:26:17.280-0600    DEBUG   kubo-car-mirror carmirror/carmirror.go:219      before receive  {"object": "CarMirror", "method": "NewPullSessionHandler", "cid": "QmPk8QayuuF2VPYmuK2mZoY3wAdpvFvHwRcytm1VQg3YUx", "addr": "http://localhost:2503"}
2023-01-31T11:26:17.280-0600    DEBUG   go-car-mirror   http/client.go:174      enter   {"object": "Client", "method": "Receive", "url": "http://localhost:2503", "id": "QmPk8QayuuF2VPYmuK2mZoY3wAdpvFvHwRcytm1VQg3YUx"}
2023-01-31T11:26:17.280-0600    DEBUG   go-car-mirror   http/client.go:126      enter   {"object": "Client", "method": "GetSinkSession", "url": "http://localhost:2503"}
2023-01-31T11:26:17.280-0600    DEBUG   go-car-mirror   core/core.go:392        enter   {"object": "SinkSession", "method": "Enqueue"}
2023-01-31T11:26:17.280-0600    DEBUG   go-car-mirror   instrumented/instrument.go:30   enter   {"for": "http://localhost:2503", "for": "SinkOrchestrator", "method": "Notify", "event": "BEGIN_ENQUEUE", "state": "SINK_FLUSHING|SINK_SENDING|SINK_WAITING"}
justindotpub commented 1 year ago

Here's the smallest log I've been able to create so far with the hang. This is of a pull from node 0 to node 1.

==> /Users/justin/.iptb/testbeds/default/1/daemon.stderr <==
16:27:55.213-0600   kubo-car-mirror carmirror/carmirror.go:205      NewPullSessionHandler   {"params": {"Cid":"QmYhUdgqxnmxwmU3WKQutCLD1Qe5AVCZpkQp9AZQKNGKzW","Addr":"http://localhost:2503","Stream":false,"Background":false}}
16:27:55.215-0600   kubo-car-mirror carmirror/carmirror.go:214      before receive  {"object": "CarMirror", "method": "NewPullSessionHandler", "cid": "QmYhUdgqxnmxwmU3WKQutCLD1Qe5AVCZpkQp9AZQKNGKzW", "addr": "http://localhost:2503"}
16:27:55.216-0600   go-car-mirror   filter/filter.go:309    calculated parameters   {"object": "BloomFilter", "method": "NewBloomFilter", "bitCount": 16384, "hashCount": 12}
16:27:55.216-0600   go-car-mirror   instrumented/instrument.go:30   enter   {"for": "http://localhost:2503", "for": "SinkOrchestrator", "method": "Notify", "event": "BEGIN_ENQUEUE", "state": ""}
16:27:55.216-0600   go-car-mirror   http/client.go:109      starting sink session   {"object": "Client", "method": "startSinkSession", "url": "http://localhost:2503"}
16:27:55.216-0600   go-car-mirror   instrumented/instrument.go:30   enter   {"for": "http://localhost:2503", "for": "SinkOrchestrator", "method": "Notify", "event": "BEGIN_SESSION", "state": "SINK_ENQUEUING"}
16:27:55.216-0600   go-car-mirror   instrumented/instrument.go:33   exit    {"for": "http://localhost:2503", "for": "SinkOrchestrator", "method": "Notify", "event": "BEGIN_ENQUEUE", "error": null, "state": "SINK_ENQUEUING"}
16:27:55.216-0600   go-car-mirror   instrumented/instrument.go:67   enter   {"for": "http://localhost:2503", "for": "SinkStore", "method": "Get", "id": "QmYhUdgqxnmxwmU3WKQutCLD1Qe5AVCZpkQp9AZQKNGKzW"}
16:27:55.216-0600   go-car-mirror   instrumented/instrument.go:33   exit    {"for": "http://localhost:2503", "for": "SinkOrchestrator", "method": "Notify", "event": "BEGIN_SESSION", "error": null, "state": "SINK_ENQUEUING"}
16:27:55.216-0600   go-car-mirror   instrumented/instrument.go:47   exit    {"for": "http://localhost:2503", "for": "SinkOrchestrator", "method": "IsClosed", "state": "SINK_ENQUEUING", "result": false}
16:27:55.216-0600   go-car-mirror   instrumented/instrument.go:30   enter   {"for": "http://localhost:2503", "for": "SinkOrchestrator", "method": "Notify", "event": "BEGIN_PROCESSING", "state": "SINK_ENQUEUING"}
16:27:55.216-0600   go-car-mirror   instrumented/instrument.go:74   exit    {"for": "http://localhost:2503", "for": "SinkStore", "method": "Get", "error": "block not found"}
16:27:55.216-0600   go-car-mirror   instrumented/instrument.go:30   enter   {"for": "http://localhost:2503", "for": "SinkOrchestrator", "method": "Notify", "event": "END_ENQUEUE", "state": "SINK_ENQUEUING"}
16:27:55.216-0600   go-car-mirror   instrumented/instrument.go:33   exit    {"for": "http://localhost:2503", "for": "SinkOrchestrator", "method": "Notify", "event": "END_ENQUEUE", "error": null, "state": "SINK_PROCESSING|SINK_SENDING"}
16:27:55.216-0600   go-car-mirror   http/client.go:181      enter   {"object": "Client", "method": "CloseSink", "url": "http://localhost:2503"}
16:27:55.216-0600   go-car-mirror   instrumented/instrument.go:30   enter   {"for": "http://localhost:2503", "for": "SinkOrchestrator", "method": "Notify", "event": "BEGIN_CLOSE", "state": "SINK_PROCESSING|SINK_SENDING"}
16:27:55.216-0600   go-car-mirror   instrumented/instrument.go:33   exit    {"for": "http://localhost:2503", "for": "SinkOrchestrator", "method": "Notify", "event": "BEGIN_CLOSE", "error": null, "state": "SINK_CLOSING|SINK_PROCESSING|SINK_SENDING"}
16:27:55.216-0600   go-car-mirror   instrumented/instrument.go:30   enter   {"for": "http://localhost:2503", "for": "SinkOrchestrator", "method": "Notify", "event": "END_CLOSE", "state": "SINK_CLOSING|SINK_PROCESSING|SINK_SENDING"}
16:27:55.216-0600   go-car-mirror   instrumented/instrument.go:33   exit    {"for": "http://localhost:2503", "for": "SinkOrchestrator", "method": "Notify", "event": "END_CLOSE", "error": null, "state": "SINK_CLOSING|SINK_PROCESSING|SINK_SENDING"}
16:27:55.216-0600   go-car-mirror   http/client.go:184      exit    {"object": "Client", "method": "CloseSink", "err": null}
16:27:55.216-0600   go-car-mirror   instrumented/instrument.go:33   exit    {"for": "http://localhost:2503", "for": "SinkOrchestrator", "method": "Notify", "event": "BEGIN_PROCESSING", "error": null, "state": "SINK_PROCESSING|SINK_SENDING"}
16:27:55.216-0600   go-car-mirror   instrumented/instrument.go:30   enter   {"for": "http://localhost:2503", "for": "SinkOrchestrator", "method": "Notify", "event": "BEGIN_DRAINING", "state": "SINK_CLOSING|SINK_PROCESSING|SINK_SENDING"}
16:27:55.216-0600   go-car-mirror   instrumented/instrument.go:33   exit    {"for": "http://localhost:2503", "for": "SinkOrchestrator", "method": "Notify", "event": "BEGIN_DRAINING", "error": null, "state": "SINK_CLOSING|SINK_FLUSHING|SINK_SENDING"}
16:27:55.216-0600   go-car-mirror   filter/filter.go:309    calculated parameters   {"object": "BloomFilter", "method": "NewBloomFilter", "bitCount": 16384, "hashCount": 12}
16:27:55.216-0600   go-car-mirror   instrumented/instrument.go:40   exit    {"for": "http://localhost:2503", "for": "SinkOrchestrator", "method": "State", "result": "SINK_CLOSING|SINK_FLUSHING|SINK_SENDING"}
16:27:55.216-0600   go-car-mirror   http/connection.go:94   enter   {"object": "RequestStatusSender", "method": "SendStatus", "have": 0, "want": 1}
16:27:55.216-0600   go-car-mirror   http/connection.go:106  post    {"object": "RequestStatusSender", "method": "SendStatus", "url": "http://localhost:2503/dag/cm/status"}
16:27:55.216-0600   go-car-mirror   http/connection.go:103  finished writing batch to request       {"object": "RequestStatusSender", "method": "SendStatus"}

==> /Users/justin/.iptb/testbeds/default/0/daemon.stderr <==
16:27:55.216-0600   go-car-mirror   http/server.go:141      Server  {"method": "HandleStatus"}
16:27:55.216-0600   go-car-mirror   http/server.go:148      generating cookie       {"object": "Server", "method": "HandleStatus"}
16:27:55.216-0600   go-car-mirror   http/server.go:165      have session token      {"object": "Server", "method": "HandleStatus", "token": "SxOIUUo5lDj6wJ270mR1JQ=="}
16:27:55.216-0600   go-car-mirror   http/server.go:169      have session for token  {"object": "Server", "method": "HandleStatus", "session": "SxOIUUo5lDj6wJ270mR1JQ=="}
16:27:55.216-0600   go-car-mirror   http/server.go:112      starting source session {"object": "Server", "method": "startSourceSession", "token": "SxOIUUo5lDj6wJ270mR1JQ=="}
16:27:55.216-0600   go-car-mirror   instrumented/instrument.go:30   enter   {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "BEGIN_RECEIVE", "state": ""}
16:27:55.216-0600   go-car-mirror   instrumented/instrument.go:33   exit    {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "BEGIN_RECEIVE", "error": null, "state": ""}
16:27:55.216-0600   go-car-mirror   core/core.go:677        begin processing        {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "object": "SourceSession", "method": "HandleStatus", "pendingBlocks": 0, "filter": 0}
16:27:55.216-0600   go-car-mirror   instrumented/instrument.go:30   enter   {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "BEGIN_SESSION", "state": ""}
16:27:55.216-0600   go-car-mirror   instrumented/instrument.go:33   exit    {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "BEGIN_SESSION", "error": null, "state": ""}
16:27:55.216-0600   go-car-mirror   core/core.go:679        incoming have filter merged     {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "object": "SourceSession", "method": "HandleStatus", "filter": 0}
16:27:55.216-0600   go-car-mirror   core/core.go:684        incoming want list merged       {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "obect": "SourceSession", "method": "HandleStatus", "pendingBlocks": 1}
16:27:55.216-0600   go-car-mirror   instrumented/instrument.go:30   enter   {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "END_RECEIVE", "state": ""}
16:27:55.216-0600   go-car-mirror   instrumented/instrument.go:33   exit    {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "END_RECEIVE", "error": null, "state": "SOURCE_PROCESSING"}
16:27:55.216-0600   go-car-mirror   instrumented/instrument.go:47   exit    {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "IsClosed", "state": "", "result": false}
16:27:55.216-0600   go-car-mirror   instrumented/instrument.go:30   enter   {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "BEGIN_PROCESSING", "state": "SOURCE_PROCESSING"}
16:27:55.216-0600   go-car-mirror   instrumented/instrument.go:30   enter   {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "BEGIN_CLOSE", "state": "SOURCE_PROCESSING"}
16:27:55.216-0600   go-car-mirror   instrumented/instrument.go:33   exit    {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "BEGIN_CLOSE", "error": null, "state": "SOURCE_PROCESSING|SOURCE_CLOSING"}
16:27:55.216-0600   go-car-mirror   instrumented/instrument.go:33   exit    {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "BEGIN_PROCESSING", "error": null, "state": "SOURCE_PROCESSING"}
16:27:55.216-0600   go-car-mirror   instrumented/instrument.go:67   enter   {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceStore", "method": "Get", "id": "QmYhUdgqxnmxwmU3WKQutCLD1Qe5AVCZpkQp9AZQKNGKzW"}
16:27:55.216-0600   go-car-mirror   http/server.go:185      waiting on session      {"object": "Server", "method": "HandleStatus", "session": "SxOIUUo5lDj6wJ270mR1JQ=="}
16:27:55.216-0600   go-car-mirror   instrumented/instrument.go:30   enter   {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "BEGIN_SEND", "state": "SOURCE_PROCESSING|SOURCE_CLOSING"}
16:27:55.216-0600   go-car-mirror   instrumented/instrument.go:33   exit    {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "BEGIN_SEND", "error": null, "state": "SOURCE_PROCESSING|SOURCE_CLOSING|SOURCE_SENDING"}
16:27:55.216-0600   go-car-mirror   instrumented/instrument.go:30   enter   {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "END_SEND", "state": "SOURCE_PROCESSING|SOURCE_CLOSING|SOURCE_SENDING"}
16:27:55.216-0600   go-car-mirror   instrumented/instrument.go:33   exit    {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "END_SEND", "error": null, "state": "SOURCE_PROCESSING|SOURCE_CLOSING|SOURCE_SENDING"}
16:27:55.216-0600   go-car-mirror   instrumented/instrument.go:30   enter   {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "END_PROCESSING", "state": "SOURCE_PROCESSING|SOURCE_CLOSING|SOURCE_SENDING"}
16:27:55.216-0600   go-car-mirror   instrumented/instrument.go:33   exit    {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "END_PROCESSING", "error": null, "state": "SOURCE_PROCESSING|SOURCE_CLOSING|SOURCE_SENDING"}
16:27:55.216-0600   go-car-mirror   instrumented/instrument.go:47   exit    {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "IsClosed", "state": "SOURCE_PROCESSING|SOURCE_CLOSING|SOURCE_SENDING", "result": false}
16:27:55.216-0600   go-car-mirror   instrumented/instrument.go:30   enter   {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "BEGIN_PROCESSING", "state": "SOURCE_PROCESSING|SOURCE_CLOSING|SOURCE_SENDING"}
16:27:55.216-0600   go-car-mirror   instrumented/instrument.go:33   exit    {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "BEGIN_PROCESSING", "error": null, "state": "SOURCE_PROCESSING|SOURCE_CLOSING|SOURCE_SENDING"}
16:27:55.216-0600   go-car-mirror   instrumented/instrument.go:67   enter   {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceStore", "method": "Get", "id": "QmTnqf4gWyw9brRuYHixExHkX8VWudbcvq5i1icSXnebc2"}
16:27:55.216-0600   go-car-mirror   instrumented/instrument.go:30   enter   {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "BEGIN_SEND", "state": "SOURCE_PROCESSING|SOURCE_CLOSING|SOURCE_SENDING"}
16:27:55.216-0600   go-car-mirror   instrumented/instrument.go:33   exit    {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "BEGIN_SEND", "error": null, "state": "SOURCE_PROCESSING|SOURCE_CLOSING|SOURCE_SENDING"}
16:27:55.216-0600   go-car-mirror   instrumented/instrument.go:30   enter   {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "END_SEND", "state": "SOURCE_PROCESSING|SOURCE_CLOSING|SOURCE_SENDING"}
16:27:55.216-0600   go-car-mirror   instrumented/instrument.go:33   exit    {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "END_SEND", "error": null, "state": "SOURCE_PROCESSING|SOURCE_CLOSING|SOURCE_SENDING"}
16:27:55.216-0600   go-car-mirror   instrumented/instrument.go:30   enter   {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "END_PROCESSING", "state": "SOURCE_PROCESSING|SOURCE_CLOSING|SOURCE_SENDING"}
16:27:55.216-0600   go-car-mirror   instrumented/instrument.go:33   exit    {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "END_PROCESSING", "error": null, "state": "SOURCE_PROCESSING|SOURCE_CLOSING|SOURCE_SENDING"}
16:27:55.216-0600   go-car-mirror   instrumented/instrument.go:47   exit    {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "IsClosed", "state": "SOURCE_PROCESSING|SOURCE_CLOSING|SOURCE_SENDING", "result": false}
16:27:55.216-0600   go-car-mirror   instrumented/instrument.go:30   enter   {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "BEGIN_PROCESSING", "state": "SOURCE_PROCESSING|SOURCE_CLOSING|SOURCE_SENDING"}
16:27:55.216-0600   go-car-mirror   instrumented/instrument.go:33   exit    {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "BEGIN_PROCESSING", "error": null, "state": "SOURCE_PROCESSING|SOURCE_CLOSING|SOURCE_SENDING"}
16:27:55.216-0600   go-car-mirror   instrumented/instrument.go:30   enter   {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "BEGIN_DRAINING", "state": "SOURCE_PROCESSING|SOURCE_CLOSING|SOURCE_SENDING"}
16:27:55.216-0600   go-car-mirror   instrumented/instrument.go:33   exit    {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "BEGIN_DRAINING", "error": null, "state": "SOURCE_PROCESSING|SOURCE_CLOSING|SOURCE_SENDING"}
16:27:55.216-0600   go-car-mirror   instrumented/instrument.go:30   enter   {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "BEGIN_FLUSH", "state": "SOURCE_PROCESSING|SOURCE_CLOSING|SOURCE_SENDING"}
16:27:55.216-0600   go-car-mirror   instrumented/instrument.go:33   exit    {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "BEGIN_FLUSH", "error": null, "state": "SOURCE_CLOSING|SOURCE_SENDING|SOURCE_FLUSHING"}
16:27:55.216-0600   go-car-mirror   instrumented/instrument.go:40   exit    {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "State", "result": "SOURCE_CLOSING|SOURCE_SENDING|SOURCE_FLUSHING"}
16:27:55.216-0600   go-car-mirror   http/connection.go:76   ResponseBatchBlockSender - enter        {"method": "SendList", "state": "SOURCE_CLOSING|SOURCE_SENDING|SOURCE_FLUSHING", "blocks": 2}
16:27:55.216-0600   go-car-mirror   http/connection.go:78   ResponseBatchBlockSender - exit {"method": "SendList"}
16:27:55.216-0600   go-car-mirror   instrumented/instrument.go:30   enter   {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "END_FLUSH", "state": "SOURCE_CLOSING|SOURCE_SENDING|SOURCE_FLUSHING"}
16:27:55.216-0600   go-car-mirror   instrumented/instrument.go:33   exit    {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "END_FLUSH", "error": null, "state": "SOURCE_CLOSING|SOURCE_WAITING"}
16:27:55.216-0600   go-car-mirror   http/server.go:187      session returned blocks {"object": "Server", "method": "HandleStatus", "len": 2}
16:27:55.216-0600   go-car-mirror   instrumented/instrument.go:30   enter   {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "END_DRAINING", "state": "SOURCE_CLOSING|SOURCE_WAITING"}
16:27:55.217-0600   go-car-mirror   instrumented/instrument.go:33   exit    {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "END_DRAINING", "error": null, "state": "SOURCE_CLOSING|SOURCE_WAITING"}
16:27:55.217-0600   go-car-mirror   instrumented/instrument.go:30   enter   {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "END_PROCESSING", "state": "SOURCE_CLOSING|SOURCE_WAITING"}
16:27:55.217-0600   go-car-mirror   http/server.go:196      exit    {"object": "Server", "method": "HandleStatus"}
16:27:55.217-0600   go-car-mirror   instrumented/instrument.go:33   exit    {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "END_PROCESSING", "error": null, "state": "SOURCE_CLOSING|SOURCE_WAITING"}
16:27:55.217-0600   go-car-mirror   instrumented/instrument.go:47   exit    {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "IsClosed", "state": "SOURCE_CLOSING|SOURCE_WAITING", "result": false}
16:27:55.217-0600   go-car-mirror   instrumented/instrument.go:30   enter   {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "BEGIN_PROCESSING", "state": "SOURCE_CLOSING|SOURCE_WAITING"}

==> /Users/justin/.iptb/testbeds/default/1/daemon.stderr <==
16:27:55.217-0600   go-car-mirror   http/connection.go:112  post response   {"object": "RequestStatusSender", "method": "SendStatus", "url": "http://localhost:2503/dag/cm/status"}
16:27:55.217-0600   go-car-mirror   messages/messages.go:206        failed to read archive  {"error": "EOF"}
16:27:55.217-0600   go-car-mirror   instrumented/instrument.go:30   enter   {"for": "http://localhost:2503", "for": "SinkOrchestrator", "method": "Notify", "event": "BEGIN_BATCH", "state": "SINK_CLOSING|SINK_FLUSHING|SINK_SENDING"}
16:27:55.217-0600   go-car-mirror   instrumented/instrument.go:33   exit    {"for": "http://localhost:2503", "for": "SinkOrchestrator", "method": "Notify", "event": "BEGIN_BATCH", "error": null, "state": "SINK_CLOSING|SINK_FLUSHING|SINK_SENDING"}
16:27:55.217-0600   go-car-mirror   instrumented/instrument.go:30   enter   {"for": "http://localhost:2503", "for": "SinkOrchestrator", "method": "Notify", "event": "BEGIN_RECEIVE", "state": "SINK_CLOSING|SINK_FLUSHING|SINK_SENDING"}
16:27:55.217-0600   go-car-mirror   instrumented/instrument.go:33   exit    {"for": "http://localhost:2503", "for": "SinkOrchestrator", "method": "Notify", "event": "BEGIN_RECEIVE", "error": null, "state": "SINK_CLOSING|SINK_FLUSHING|SINK_SENDING"}
16:27:55.217-0600   go-car-mirror   instrumented/instrument.go:118  enter   {"for": "http://localhost:2503", "for": "SinkStore", "method": "Add", "id": "QmYhUdgqxnmxwmU3WKQutCLD1Qe5AVCZpkQp9AZQKNGKzW"}
16:27:55.233-0600   go-car-mirror   instrumented/instrument.go:30   enter   {"for": "http://localhost:2503", "for": "SinkOrchestrator", "method": "Notify", "event": "END_RECEIVE", "state": "SINK_CLOSING|SINK_FLUSHING|SINK_SENDING"}
16:27:55.233-0600   go-car-mirror   instrumented/instrument.go:33   exit    {"for": "http://localhost:2503", "for": "SinkOrchestrator", "method": "Notify", "event": "END_RECEIVE", "error": null, "state": "SINK_CLOSING|SINK_FLUSHING|SINK_SENDING"}
16:27:55.233-0600   go-car-mirror   instrumented/instrument.go:30   enter   {"for": "http://localhost:2503", "for": "SinkOrchestrator", "method": "Notify", "event": "BEGIN_RECEIVE", "state": "SINK_CLOSING|SINK_FLUSHING|SINK_SENDING"}
16:27:55.233-0600   go-car-mirror   instrumented/instrument.go:33   exit    {"for": "http://localhost:2503", "for": "SinkOrchestrator", "method": "Notify", "event": "BEGIN_RECEIVE", "error": null, "state": "SINK_CLOSING|SINK_FLUSHING|SINK_SENDING"}
16:27:55.233-0600   go-car-mirror   instrumented/instrument.go:118  enter   {"for": "http://localhost:2503", "for": "SinkStore", "method": "Add", "id": "QmTnqf4gWyw9brRuYHixExHkX8VWudbcvq5i1icSXnebc2"}
16:27:55.247-0600   go-car-mirror   instrumented/instrument.go:30   enter   {"for": "http://localhost:2503", "for": "SinkOrchestrator", "method": "Notify", "event": "END_RECEIVE", "state": "SINK_CLOSING|SINK_FLUSHING|SINK_SENDING"}
16:27:55.247-0600   go-car-mirror   instrumented/instrument.go:33   exit    {"for": "http://localhost:2503", "for": "SinkOrchestrator", "method": "Notify", "event": "END_RECEIVE", "error": null, "state": "SINK_CLOSING|SINK_FLUSHING|SINK_SENDING"}
16:27:55.247-0600   go-car-mirror   instrumented/instrument.go:30   enter   {"for": "http://localhost:2503", "for": "SinkOrchestrator", "method": "Notify", "event": "END_BATCH", "state": "SINK_CLOSING|SINK_FLUSHING|SINK_SENDING"}
16:27:55.247-0600   go-car-mirror   instrumented/instrument.go:33   exit    {"for": "http://localhost:2503", "for": "SinkOrchestrator", "method": "Notify", "event": "END_BATCH", "error": null, "state": "SINK_CLOSING|SINK_PROCESSING|SINK_FLUSHING|SINK_SENDING"}
16:27:55.247-0600   go-car-mirror   http/connection.go:124  exit    {"object": "RequestStatusSender", "method": "SendStatus", "error": null}
16:27:55.247-0600   go-car-mirror   instrumented/instrument.go:30   enter   {"for": "http://localhost:2503", "for": "SinkOrchestrator", "method": "Notify", "event": "END_DRAINING", "state": "SINK_CLOSING|SINK_PROCESSING|SINK_FLUSHING|SINK_SENDING"}
16:27:55.247-0600   go-car-mirror   instrumented/instrument.go:33   exit    {"for": "http://localhost:2503", "for": "SinkOrchestrator", "method": "Notify", "event": "END_DRAINING", "error": null, "state": "SINK_CLOSING|SINK_PROCESSING|SINK_WAITING"}
16:27:55.247-0600   go-car-mirror   instrumented/instrument.go:30   enter   {"for": "http://localhost:2503", "for": "SinkOrchestrator", "method": "Notify", "event": "END_PROCESSING", "state": "SINK_CLOSING|SINK_PROCESSING|SINK_WAITING"}
16:27:55.247-0600   go-car-mirror   instrumented/instrument.go:33   exit    {"for": "http://localhost:2503", "for": "SinkOrchestrator", "method": "Notify", "event": "END_PROCESSING", "error": null, "state": "SINK_CLOSING|SINK_PROCESSING|SINK_WAITING"}
16:27:55.247-0600   go-car-mirror   instrumented/instrument.go:47   exit    {"for": "http://localhost:2503", "for": "SinkOrchestrator", "method": "IsClosed", "state": "SINK_CLOSING|SINK_PROCESSING|SINK_WAITING", "result": false}
16:27:55.247-0600   go-car-mirror   instrumented/instrument.go:30   enter   {"for": "http://localhost:2503", "for": "SinkOrchestrator", "method": "Notify", "event": "BEGIN_PROCESSING", "state": "SINK_CLOSING|SINK_PROCESSING|SINK_WAITING"}
16:27:55.247-0600   go-car-mirror   instrumented/instrument.go:33   exit    {"for": "http://localhost:2503", "for": "SinkOrchestrator", "method": "Notify", "event": "BEGIN_PROCESSING", "error": null, "state": "SINK_CLOSING|SINK_PROCESSING|SINK_WAITING"}
16:27:55.247-0600   go-car-mirror   instrumented/instrument.go:30   enter   {"for": "http://localhost:2503", "for": "SinkOrchestrator", "method": "Notify", "event": "BEGIN_SEND", "state": "SINK_CLOSING|SINK_PROCESSING|SINK_WAITING"}
16:27:55.247-0600   go-car-mirror   instrumented/instrument.go:33   exit    {"for": "http://localhost:2503", "for": "SinkOrchestrator", "method": "Notify", "event": "BEGIN_SEND", "error": null, "state": "SINK_CLOSING|SINK_PROCESSING|SINK_SENDING|SINK_WAITING"}
16:27:55.247-0600   go-car-mirror   instrumented/instrument.go:67   enter   {"for": "http://localhost:2503", "for": "SinkStore", "method": "Get", "id": "QmTnqf4gWyw9brRuYHixExHkX8VWudbcvq5i1icSXnebc2"}
16:27:55.247-0600   go-car-mirror   instrumented/instrument.go:30   enter   {"for": "http://localhost:2503", "for": "SinkOrchestrator", "method": "Notify", "event": "END_SEND", "state": "SINK_CLOSING|SINK_PROCESSING|SINK_SENDING|SINK_WAITING"}
16:27:55.247-0600   go-car-mirror   instrumented/instrument.go:33   exit    {"for": "http://localhost:2503", "for": "SinkOrchestrator", "method": "Notify", "event": "END_SEND", "error": null, "state": "SINK_CLOSING|SINK_PROCESSING|SINK_SENDING|SINK_WAITING"}
16:27:55.247-0600   go-car-mirror   instrumented/instrument.go:30   enter   {"for": "http://localhost:2503", "for": "SinkOrchestrator", "method": "Notify", "event": "END_PROCESSING", "state": "SINK_CLOSING|SINK_PROCESSING|SINK_SENDING|SINK_WAITING"}
16:27:55.247-0600   go-car-mirror   instrumented/instrument.go:33   exit    {"for": "http://localhost:2503", "for": "SinkOrchestrator", "method": "Notify", "event": "END_PROCESSING", "error": null, "state": "SINK_CLOSING|SINK_PROCESSING|SINK_SENDING|SINK_WAITING"}
16:27:55.247-0600   go-car-mirror   instrumented/instrument.go:47   exit    {"for": "http://localhost:2503", "for": "SinkOrchestrator", "method": "IsClosed", "state": "SINK_CLOSING|SINK_PROCESSING|SINK_SENDING|SINK_WAITING", "result": false}
16:27:55.247-0600   go-car-mirror   instrumented/instrument.go:30   enter   {"for": "http://localhost:2503", "for": "SinkOrchestrator", "method": "Notify", "event": "BEGIN_PROCESSING", "state": "SINK_CLOSING|SINK_PROCESSING|SINK_SENDING|SINK_WAITING"}
16:27:55.247-0600   go-car-mirror   instrumented/instrument.go:33   exit    {"for": "http://localhost:2503", "for": "SinkOrchestrator", "method": "Notify", "event": "BEGIN_PROCESSING", "error": null, "state": "SINK_CLOSING|SINK_PROCESSING|SINK_SENDING|SINK_WAITING"}
16:27:55.247-0600   go-car-mirror   instrumented/instrument.go:30   enter   {"for": "http://localhost:2503", "for": "SinkOrchestrator", "method": "Notify", "event": "BEGIN_SEND", "state": "SINK_CLOSING|SINK_PROCESSING|SINK_SENDING|SINK_WAITING"}
16:27:55.247-0600   go-car-mirror   instrumented/instrument.go:33   exit    {"for": "http://localhost:2503", "for": "SinkOrchestrator", "method": "Notify", "event": "BEGIN_SEND", "error": null, "state": "SINK_CLOSING|SINK_PROCESSING|SINK_SENDING|SINK_WAITING"}
16:27:55.247-0600   go-car-mirror   instrumented/instrument.go:30   enter   {"for": "http://localhost:2503", "for": "SinkOrchestrator", "method": "Notify", "event": "END_SEND", "state": "SINK_CLOSING|SINK_PROCESSING|SINK_SENDING|SINK_WAITING"}
16:27:55.247-0600   go-car-mirror   instrumented/instrument.go:33   exit    {"for": "http://localhost:2503", "for": "SinkOrchestrator", "method": "Notify", "event": "END_SEND", "error": null, "state": "SINK_CLOSING|SINK_PROCESSING|SINK_SENDING|SINK_WAITING"}
16:27:55.247-0600   go-car-mirror   instrumented/instrument.go:30   enter   {"for": "http://localhost:2503", "for": "SinkOrchestrator", "method": "Notify", "event": "END_PROCESSING", "state": "SINK_CLOSING|SINK_PROCESSING|SINK_SENDING|SINK_WAITING"}
16:27:55.247-0600   go-car-mirror   instrumented/instrument.go:33   exit    {"for": "http://localhost:2503", "for": "SinkOrchestrator", "method": "Notify", "event": "END_PROCESSING", "error": null, "state": "SINK_CLOSING|SINK_PROCESSING|SINK_SENDING|SINK_WAITING"}
16:27:55.247-0600   go-car-mirror   instrumented/instrument.go:47   exit    {"for": "http://localhost:2503", "for": "SinkOrchestrator", "method": "IsClosed", "state": "SINK_CLOSING|SINK_PROCESSING|SINK_SENDING|SINK_WAITING", "result": false}
16:27:55.247-0600   go-car-mirror   instrumented/instrument.go:30   enter   {"for": "http://localhost:2503", "for": "SinkOrchestrator", "method": "Notify", "event": "BEGIN_PROCESSING", "state": "SINK_CLOSING|SINK_PROCESSING|SINK_SENDING|SINK_WAITING"}
16:27:55.247-0600   go-car-mirror   instrumented/instrument.go:33   exit    {"for": "http://localhost:2503", "for": "SinkOrchestrator", "method": "Notify", "event": "BEGIN_PROCESSING", "error": null, "state": "SINK_CLOSING|SINK_PROCESSING|SINK_SENDING|SINK_WAITING"}
16:27:55.247-0600   go-car-mirror   instrumented/instrument.go:30   enter   {"for": "http://localhost:2503", "for": "SinkOrchestrator", "method": "Notify", "event": "BEGIN_DRAINING", "state": "SINK_CLOSING|SINK_PROCESSING|SINK_SENDING|SINK_WAITING"}
16:27:55.247-0600   go-car-mirror   instrumented/instrument.go:33   exit    {"for": "http://localhost:2503", "for": "SinkOrchestrator", "method": "Notify", "event": "BEGIN_DRAINING", "error": null, "state": "SINK_CLOSING|SINK_FLUSHING|SINK_SENDING|SINK_WAITING"}
16:27:55.247-0600   go-car-mirror   filter/filter.go:309    calculated parameters   {"object": "BloomFilter", "method": "NewBloomFilter", "bitCount": 16384, "hashCount": 12}
16:27:55.247-0600   go-car-mirror   instrumented/instrument.go:40   exit    {"for": "http://localhost:2503", "for": "SinkOrchestrator", "method": "State", "result": "SINK_CLOSING|SINK_FLUSHING|SINK_SENDING|SINK_WAITING"}
16:27:55.247-0600   go-car-mirror   http/connection.go:94   enter   {"object": "RequestStatusSender", "method": "SendStatus", "have": 1, "want": 0}
16:27:55.247-0600   go-car-mirror   http/connection.go:106  post    {"object": "RequestStatusSender", "method": "SendStatus", "url": "http://localhost:2503/dag/cm/status"}
16:27:55.247-0600   go-car-mirror   http/connection.go:103  finished writing batch to request       {"object": "RequestStatusSender", "method": "SendStatus"}

==> /Users/justin/.iptb/testbeds/default/0/daemon.stderr <==
16:27:55.248-0600   go-car-mirror   http/server.go:141      Server  {"method": "HandleStatus"}
16:27:55.248-0600   go-car-mirror   http/server.go:165      have session token      {"object": "Server", "method": "HandleStatus", "token": "SxOIUUo5lDj6wJ270mR1JQ=="}
16:27:55.248-0600   go-car-mirror   http/server.go:169      have session for token  {"object": "Server", "method": "HandleStatus", "session": "SxOIUUo5lDj6wJ270mR1JQ=="}
16:27:55.248-0600   go-car-mirror   instrumented/instrument.go:30   enter   {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "BEGIN_RECEIVE", "state": "SOURCE_CLOSING|SOURCE_WAITING"}
16:27:55.248-0600   go-car-mirror   instrumented/instrument.go:33   exit    {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "BEGIN_RECEIVE", "error": null, "state": "SOURCE_CLOSING|SOURCE_WAITING"}
16:27:55.248-0600   go-car-mirror   core/core.go:677        begin processing        {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "object": "SourceSession", "method": "HandleStatus", "pendingBlocks": 0, "filter": 0}
16:27:55.248-0600   go-car-mirror   filter/filter.go:393    enter   {"object": "BloomFilter", "method": "TryAddAll", "other.bitCount": 16384, "hashCount": 12}
16:27:55.248-0600   go-car-mirror   filter/filter.go:416    exit    {"object": "BloomFilter", "method": "TryAddAll", "error": null}
16:27:55.248-0600   go-car-mirror   core/core.go:679        incoming have filter merged     {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "object": "SourceSession", "method": "HandleStatus", "filter": 1}
16:27:55.248-0600   go-car-mirror   core/core.go:684        incoming want list merged       {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "obect": "SourceSession", "method": "HandleStatus", "pendingBlocks": 0}
16:27:55.248-0600   go-car-mirror   instrumented/instrument.go:30   enter   {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "END_RECEIVE", "state": "SOURCE_CLOSING|SOURCE_WAITING"}
16:27:55.248-0600   go-car-mirror   instrumented/instrument.go:33   exit    {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "END_RECEIVE", "error": null, "state": "SOURCE_PROCESSING|SOURCE_CLOSING"}
16:27:55.248-0600   go-car-mirror   instrumented/instrument.go:30   enter   {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "BEGIN_CLOSE", "state": "SOURCE_PROCESSING|SOURCE_CLOSING"}
16:27:55.248-0600   go-car-mirror   instrumented/instrument.go:33   exit    {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "BEGIN_CLOSE", "error": null, "state": "SOURCE_PROCESSING|SOURCE_CLOSING"}
16:27:55.248-0600   go-car-mirror   http/server.go:185      waiting on session      {"object": "Server", "method": "HandleStatus", "session": "SxOIUUo5lDj6wJ270mR1JQ=="}
16:27:55.248-0600   go-car-mirror   instrumented/instrument.go:33   exit    {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "BEGIN_PROCESSING", "error": null, "state": "SOURCE_PROCESSING|SOURCE_CLOSING"}
16:27:55.248-0600   go-car-mirror   instrumented/instrument.go:30   enter   {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "BEGIN_DRAINING", "state": "SOURCE_PROCESSING|SOURCE_CLOSING"}
16:27:55.248-0600   go-car-mirror   instrumented/instrument.go:33   exit    {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "BEGIN_DRAINING", "error": null, "state": "SOURCE_PROCESSING|SOURCE_CLOSING|SOURCE_CLOSED"}
16:27:55.248-0600   go-car-mirror   instrumented/instrument.go:30   enter   {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "BEGIN_FLUSH", "state": "SOURCE_PROCESSING|SOURCE_CLOSING|SOURCE_CLOSED"}
16:27:55.248-0600   go-car-mirror   instrumented/instrument.go:33   exit    {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "BEGIN_FLUSH", "error": null, "state": "SOURCE_CLOSING|SOURCE_CLOSED|SOURCE_FLUSHING"}
16:27:55.248-0600   go-car-mirror   instrumented/instrument.go:40   exit    {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "State", "result": "SOURCE_CLOSING|SOURCE_CLOSED|SOURCE_FLUSHING"}
16:27:55.248-0600   go-car-mirror   http/connection.go:76   ResponseBatchBlockSender - enter        {"method": "SendList", "state": "SOURCE_CLOSING|SOURCE_CLOSED|SOURCE_FLUSHING", "blocks": 0}
16:27:55.248-0600   go-car-mirror   http/connection.go:78   ResponseBatchBlockSender - exit {"method": "SendList"}
16:27:55.248-0600   go-car-mirror   instrumented/instrument.go:30   enter   {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "END_FLUSH", "state": "SOURCE_CLOSING|SOURCE_CLOSED|SOURCE_FLUSHING"}
16:27:55.248-0600   go-car-mirror   instrumented/instrument.go:33   exit    {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "END_FLUSH", "error": null, "state": "SOURCE_CLOSING|SOURCE_CLOSED|SOURCE_WAITING"}
16:27:55.248-0600   go-car-mirror   instrumented/instrument.go:30   enter   {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "END_DRAINING", "state": "SOURCE_CLOSING|SOURCE_CLOSED|SOURCE_WAITING"}
16:27:55.248-0600   go-car-mirror   instrumented/instrument.go:33   exit    {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "END_DRAINING", "error": null, "state": "SOURCE_CLOSING|SOURCE_CLOSED|SOURCE_WAITING"}
16:27:55.248-0600   go-car-mirror   instrumented/instrument.go:30   enter   {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "END_PROCESSING", "state": "SOURCE_CLOSING|SOURCE_CLOSED|SOURCE_WAITING"}
16:27:55.248-0600   go-car-mirror   instrumented/instrument.go:33   exit    {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "END_PROCESSING", "error": null, "state": "SOURCE_CLOSING|SOURCE_CLOSED|SOURCE_WAITING"}
16:27:55.248-0600   go-car-mirror   http/server.go:187      session returned blocks {"object": "Server", "method": "HandleStatus", "len": 0}
16:27:55.248-0600   go-car-mirror   http/server.go:196      exit    {"object": "Server", "method": "HandleStatus"}
16:27:55.248-0600   go-car-mirror   instrumented/instrument.go:47   exit    {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "IsClosed", "state": "SOURCE_CLOSING|SOURCE_CLOSED|SOURCE_WAITING", "result": true}
16:27:55.248-0600   go-car-mirror   instrumented/instrument.go:30   enter   {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "END_SESSION", "state": "SOURCE_CLOSING|SOURCE_CLOSED|SOURCE_WAITING"}
16:27:55.248-0600   go-car-mirror   instrumented/instrument.go:33   exit    {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "END_SESSION", "error": null, "state": "SOURCE_CLOSED"}
16:27:55.248-0600   go-car-mirror   http/server.go:120      source session ended    {"object": "Server", "method": "startSourceSession", "token": "SxOIUUo5lDj6wJ270mR1JQ=="}

==> /Users/justin/.iptb/testbeds/default/1/daemon.stderr <==
16:27:55.248-0600   go-car-mirror   http/connection.go:112  post response   {"object": "RequestStatusSender", "method": "SendStatus", "url": "http://localhost:2503/dag/cm/status"}
16:27:55.248-0600   go-car-mirror   messages/messages.go:206        failed to read archive  {"error": "EOF"}
16:27:55.248-0600   go-car-mirror   instrumented/instrument.go:30   enter   {"for": "http://localhost:2503", "for": "SinkOrchestrator", "method": "Notify", "event": "BEGIN_BATCH", "state": "SINK_CLOSING|SINK_FLUSHING|SINK_SENDING|SINK_WAITING"}
16:27:55.248-0600   go-car-mirror   instrumented/instrument.go:33   exit    {"for": "http://localhost:2503", "for": "SinkOrchestrator", "method": "Notify", "event": "BEGIN_BATCH", "error": null, "state": "SINK_CLOSING|SINK_FLUSHING|SINK_SENDING|SINK_WAITING"}
16:27:55.248-0600   go-car-mirror   instrumented/instrument.go:30   enter   {"for": "http://localhost:2503", "for": "SinkOrchestrator", "method": "Notify", "event": "END_BATCH", "state": "SINK_CLOSING|SINK_FLUSHING|SINK_SENDING|SINK_WAITING"}
16:27:55.248-0600   go-car-mirror   instrumented/instrument.go:33   exit    {"for": "http://localhost:2503", "for": "SinkOrchestrator", "method": "Notify", "event": "END_BATCH", "error": null, "state": "SINK_CLOSING|SINK_PROCESSING|SINK_FLUSHING|SINK_SENDING"}
16:27:55.248-0600   go-car-mirror   http/connection.go:124  exit    {"object": "RequestStatusSender", "method": "SendStatus", "error": null}
16:27:55.248-0600   go-car-mirror   instrumented/instrument.go:30   enter   {"for": "http://localhost:2503", "for": "SinkOrchestrator", "method": "Notify", "event": "END_DRAINING", "state": "SINK_CLOSING|SINK_PROCESSING|SINK_FLUSHING|SINK_SENDING"}
16:27:55.248-0600   go-car-mirror   instrumented/instrument.go:33   exit    {"for": "http://localhost:2503", "for": "SinkOrchestrator", "method": "Notify", "event": "END_DRAINING", "error": null, "state": "SINK_CLOSING|SINK_PROCESSING|SINK_WAITING"}
16:27:55.248-0600   go-car-mirror   instrumented/instrument.go:30   enter   {"for": "http://localhost:2503", "for": "SinkOrchestrator", "method": "Notify", "event": "END_PROCESSING", "state": "SINK_CLOSING|SINK_PROCESSING|SINK_WAITING"}
16:27:55.248-0600   go-car-mirror   instrumented/instrument.go:33   exit    {"for": "http://localhost:2503", "for": "SinkOrchestrator", "method": "Notify", "event": "END_PROCESSING", "error": null, "state": "SINK_CLOSING|SINK_PROCESSING|SINK_WAITING"}
16:27:55.248-0600   go-car-mirror   instrumented/instrument.go:47   exit    {"for": "http://localhost:2503", "for": "SinkOrchestrator", "method": "IsClosed", "state": "SINK_CLOSING|SINK_PROCESSING|SINK_WAITING", "result": false}
16:27:55.248-0600   go-car-mirror   instrumented/instrument.go:30   enter   {"for": "http://localhost:2503", "for": "SinkOrchestrator", "method": "Notify", "event": "BEGIN_PROCESSING", "state": "SINK_CLOSING|SINK_PROCESSING|SINK_WAITING"}
16:27:55.248-0600   go-car-mirror   instrumented/instrument.go:33   exit    {"for": "http://localhost:2503", "for": "SinkOrchestrator", "method": "Notify", "event": "BEGIN_PROCESSING", "error": null, "state": "SINK_CLOSING|SINK_PROCESSING|SINK_WAITING"}
16:27:55.248-0600   go-car-mirror   instrumented/instrument.go:30   enter   {"for": "http://localhost:2503", "for": "SinkOrchestrator", "method": "Notify", "event": "BEGIN_DRAINING", "state": "SINK_CLOSING|SINK_PROCESSING|SINK_WAITING"}
16:27:55.248-0600   go-car-mirror   instrumented/instrument.go:33   exit    {"for": "http://localhost:2503", "for": "SinkOrchestrator", "method": "Notify", "event": "BEGIN_DRAINING", "error": null, "state": "SINK_CLOSING|SINK_CLOSED|SINK_FLUSHING|SINK_WAITING"}
16:27:55.248-0600   go-car-mirror   filter/filter.go:309    calculated parameters   {"object": "BloomFilter", "method": "NewBloomFilter", "bitCount": 16384, "hashCount": 12}
16:27:55.248-0600   go-car-mirror   instrumented/instrument.go:40   exit    {"for": "http://localhost:2503", "for": "SinkOrchestrator", "method": "State", "result": "SINK_CLOSING|SINK_CLOSED|SINK_FLUSHING|SINK_WAITING"}
16:27:55.248-0600   go-car-mirror   http/connection.go:94   enter   {"object": "RequestStatusSender", "method": "SendStatus", "have": 0, "want": 0}
16:27:55.248-0600   go-car-mirror   http/connection.go:106  post    {"object": "RequestStatusSender", "method": "SendStatus", "url": "http://localhost:2503/dag/cm/status"}
16:27:55.248-0600   go-car-mirror   http/connection.go:103  finished writing batch to request       {"object": "RequestStatusSender", "method": "SendStatus"}

==> /Users/justin/.iptb/testbeds/default/0/daemon.stderr <==
16:27:55.248-0600   go-car-mirror   http/server.go:141      Server  {"method": "HandleStatus"}
16:27:55.248-0600   go-car-mirror   http/server.go:165      have session token      {"object": "Server", "method": "HandleStatus", "token": "SxOIUUo5lDj6wJ270mR1JQ=="}
16:27:55.248-0600   go-car-mirror   http/server.go:169      have session for token  {"object": "Server", "method": "HandleStatus", "session": "SxOIUUo5lDj6wJ270mR1JQ=="}
16:27:55.248-0600   go-car-mirror   instrumented/instrument.go:30   enter   {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "BEGIN_RECEIVE", "state": ""}
16:27:55.248-0600   go-car-mirror   instrumented/instrument.go:33   exit    {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "BEGIN_RECEIVE", "error": null, "state": ""}
16:27:55.248-0600   go-car-mirror   core/core.go:677        begin processing        {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "object": "SourceSession", "method": "HandleStatus", "pendingBlocks": 0, "filter": 0}
16:27:55.248-0600   go-car-mirror   core/core.go:679        incoming have filter merged     {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "object": "SourceSession", "method": "HandleStatus", "filter": 0}
16:27:55.248-0600   go-car-mirror   core/core.go:684        incoming want list merged       {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "obect": "SourceSession", "method": "HandleStatus", "pendingBlocks": 0}
16:27:55.248-0600   go-car-mirror   instrumented/instrument.go:30   enter   {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "END_RECEIVE", "state": ""}
16:27:55.248-0600   go-car-mirror   instrumented/instrument.go:33   exit    {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "END_RECEIVE", "error": null, "state": "SOURCE_PROCESSING"}
16:27:55.248-0600   go-car-mirror   http/server.go:112      starting source session {"object": "Server", "method": "startSourceSession", "token": "SxOIUUo5lDj6wJ270mR1JQ=="}
16:27:55.248-0600   go-car-mirror   instrumented/instrument.go:30   enter   {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "BEGIN_SESSION", "state": "SOURCE_PROCESSING"}
16:27:55.248-0600   go-car-mirror   instrumented/instrument.go:33   exit    {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "BEGIN_SESSION", "error": null, "state": "SOURCE_PROCESSING"}
16:27:55.248-0600   go-car-mirror   instrumented/instrument.go:47   exit    {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "IsClosed", "state": "SOURCE_PROCESSING", "result": false}
16:27:55.248-0600   go-car-mirror   instrumented/instrument.go:30   enter   {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "BEGIN_PROCESSING", "state": "SOURCE_PROCESSING"}
16:27:55.248-0600   go-car-mirror   instrumented/instrument.go:33   exit    {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "BEGIN_PROCESSING", "error": null, "state": "SOURCE_PROCESSING"}
16:27:55.248-0600   go-car-mirror   instrumented/instrument.go:30   enter   {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "BEGIN_DRAINING", "state": "SOURCE_PROCESSING"}
16:27:55.248-0600   go-car-mirror   instrumented/instrument.go:33   exit    {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "BEGIN_DRAINING", "error": null, "state": "SOURCE_PROCESSING"}
16:27:55.248-0600   go-car-mirror   instrumented/instrument.go:30   enter   {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "BEGIN_FLUSH", "state": "SOURCE_PROCESSING"}
16:27:55.248-0600   go-car-mirror   instrumented/instrument.go:33   exit    {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "BEGIN_FLUSH", "error": null, "state": "SOURCE_FLUSHING"}
16:27:55.248-0600   go-car-mirror   instrumented/instrument.go:40   exit    {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "State", "result": "SOURCE_FLUSHING"}
16:27:55.248-0600   go-car-mirror   instrumented/instrument.go:30   enter   {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "BEGIN_CLOSE", "state": "SOURCE_PROCESSING"}
16:27:55.248-0600   go-car-mirror   instrumented/instrument.go:33   exit    {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "BEGIN_CLOSE", "error": null, "state": "SOURCE_CLOSING|SOURCE_FLUSHING"}
16:27:55.248-0600   go-car-mirror   http/server.go:185      waiting on session      {"object": "Server", "method": "HandleStatus", "session": "SxOIUUo5lDj6wJ270mR1JQ=="}
16:27:55.248-0600   go-car-mirror   instrumented/instrument.go:30   enter   {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "END_FLUSH", "state": "SOURCE_FLUSHING"}
16:27:55.248-0600   go-car-mirror   instrumented/instrument.go:33   exit    {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "END_FLUSH", "error": null, "state": "SOURCE_CLOSING|SOURCE_WAITING"}
16:27:55.248-0600   go-car-mirror   instrumented/instrument.go:30   enter   {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "END_DRAINING", "state": "SOURCE_CLOSING|SOURCE_WAITING"}
16:27:55.248-0600   go-car-mirror   instrumented/instrument.go:33   exit    {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "END_DRAINING", "error": null, "state": "SOURCE_CLOSING|SOURCE_WAITING"}
16:27:55.248-0600   go-car-mirror   instrumented/instrument.go:30   enter   {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "END_PROCESSING", "state": "SOURCE_CLOSING|SOURCE_WAITING"}
16:27:55.248-0600   go-car-mirror   instrumented/instrument.go:33   exit    {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "END_PROCESSING", "error": null, "state": "SOURCE_CLOSING|SOURCE_WAITING"}
16:27:55.248-0600   go-car-mirror   instrumented/instrument.go:47   exit    {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "IsClosed", "state": "SOURCE_CLOSING|SOURCE_WAITING", "result": false}
16:27:55.248-0600   go-car-mirror   instrumented/instrument.go:30   enter   {"for": "SxOIUUo5lDj6wJ270mR1JQ==", "for": "SourceOrchestrator", "method": "Notify", "event": "BEGIN_PROCESSING", "state": "SOURCE_CLOSING|SOURCE_WAITING"}
justindotpub commented 1 year ago

I've fixed quite a few issues that ultimately lead to this issue being closed. I have push and pull working, but not within the http specific code. I'll open a new issue for that.