Seeing every event of a journey

What you want to do

The log stopped at Pat's charge, so no record says how Pat's journey ended. You want to see every event of a journey as it happens, without writing a reporter of your own.

The code

The shop is chapter 31's, with one more reporter. DebugReporter, from itinera::report, comes with itinera, and prints every event of a journey on a line of its own. The workflow lists it first:

Rust, from the program ch32_seeing_every_event_of_a_journey

#[workflow(name = "orders", reporters = [DebugReporter, Log, Desk], policies = [Notify])]

Rust, the same in its asynchronous form, from the program ch32_seeing_every_event_of_a_journey_async

#[workflow(
    name = "orders",
    reporters = [DebugReporter, Desk],
    async_reporters = [Log],
    policies = [Notify]
)]

The log is chapter 31's, the desk is chapter 11's and notify is chapter 19's.

In the asynchronous form, DebugReporter stays under reporters too, since printing waits for nothing, and the reporters under reporters receive each event before those under async_reporters. main runs Pat's order alone, and prints:

What ch32_seeing_every_event_of_a_journey prints, recorded in ch32_seeing_every_event_of_a_journey.txt

Pat's order:
Event { sequence: 1, timestamp: Timestamp { instant: SystemTime { tv_sec: 1791996170, tv_nsec: 358384048 } }, journey_id: JourneyId("A-15"), workflow: WorkflowName("orders"), body: JourneyStarted { initial_keys: ["card", "customer", "gift_card", "order", "parcel", "price"] } }
log orders A-15 #1 journey_started card, customer, gift_card, order, parcel, price
Event { sequence: 2, timestamp: Timestamp { instant: SystemTime { tv_sec: 1791996170, tv_nsec: 358494850 } }, journey_id: JourneyId("A-15"), workflow: WorkflowName("orders"), body: AttemptStarted { step: StepAttempt { step: StepName { name: "lookup" }, attempt: 1 } } }
log orders A-15 #2 attempt_started lookup, attempt 1
Event { sequence: 3, timestamp: Timestamp { instant: SystemTime { tv_sec: 1791996170, tv_nsec: 358534694 } }, journey_id: JourneyId("A-15"), workflow: WorkflowName("orders"), body: ServiceProvided { step: StepAttempt { step: StepName { name: "lookup" }, attempt: 1 }, key: "order_book", provider: ProviderName("ledger"), implementation: Implementation { name: "ch32_seeing_every_event_of_a_journey::Ledger" }, data: None } }
log orders A-15 #3 service_provided lookup gets order_book from ledger, a ch32_seeing_every_event_of_a_journey::Ledger
the order book has no order A-15 yet
Event { sequence: 4, timestamp: Timestamp { instant: SystemTime { tv_sec: 1791996170, tv_nsec: 358597163 } }, journey_id: JourneyId("A-15"), workflow: WorkflowName("orders"), body: StepSucceeded { step: StepAttempt { step: StepName { name: "lookup" }, attempt: 1 } } }
log orders A-15 #4 step_succeeded lookup
Event { sequence: 5, timestamp: Timestamp { instant: SystemTime { tv_sec: 1791996170, tv_nsec: 358638290 } }, journey_id: JourneyId("A-15"), workflow: WorkflowName("orders"), body: ContributionCommitted { key: "completed", source: Step(StepAttempt { step: StepName { name: "lookup" }, attempt: 1 }) } }
log orders A-15 #5 contribution_committed completed
Event { sequence: 6, timestamp: Timestamp { instant: SystemTime { tv_sec: 1791996170, tv_nsec: 358705836 } }, journey_id: JourneyId("A-15"), workflow: WorkflowName("orders"), body: HookCalled { hook: Step { policy: PolicyName("already_completed"), hook: OnStepSuccess, step: StepAttempt { step: StepName { name: "lookup" }, attempt: 1 } }, lifecycle: None } }
log orders A-15 #6 hook_called already_completed: on step success of lookup
Event { sequence: 7, timestamp: Timestamp { instant: SystemTime { tv_sec: 1791996170, tv_nsec: 358741056 } }, journey_id: JourneyId("A-15"), workflow: WorkflowName("orders"), body: AttemptStarted { step: StepAttempt { step: StepName { name: "price" }, attempt: 1 } } }
log orders A-15 #7 attempt_started price, attempt 1
Event { sequence: 8, timestamp: Timestamp { instant: SystemTime { tv_sec: 1791996170, tv_nsec: 358777468 } }, journey_id: JourneyId("A-15"), workflow: WorkflowName("orders"), body: OptionalInputAbsent { key: "discount", requester: Step(StepAttempt { step: StepName { name: "price" }, attempt: 1 }) } }
log orders A-15 #8 optional_input_absent discount
Event { sequence: 9, timestamp: Timestamp { instant: SystemTime { tv_sec: 1791996170, tv_nsec: 358818731 } }, journey_id: JourneyId("A-15"), workflow: WorkflowName("orders"), body: StepSucceeded { step: StepAttempt { step: StepName { name: "price" }, attempt: 1 } } }
log orders A-15 #9 step_succeeded price
Event { sequence: 10, timestamp: Timestamp { instant: SystemTime { tv_sec: 1791996170, tv_nsec: 358852815 } }, journey_id: JourneyId("A-15"), workflow: WorkflowName("orders"), body: ContributionCommitted { key: "amount", source: Step(StepAttempt { step: StepName { name: "price" }, attempt: 1 }) } }
log orders A-15 #10 contribution_committed amount
Event { sequence: 11, timestamp: Timestamp { instant: SystemTime { tv_sec: 1791996170, tv_nsec: 358888211 } }, journey_id: JourneyId("A-15"), workflow: WorkflowName("orders"), body: AttemptStarted { step: StepAttempt { step: StepName { name: "charge" }, attempt: 1 } } }
log orders A-15 #11 attempt_started charge, attempt 1
Event { sequence: 12, timestamp: Timestamp { instant: SystemTime { tv_sec: 1791996170, tv_nsec: 358932113 } }, journey_id: JourneyId("A-15"), workflow: WorkflowName("orders"), body: ServiceProvided { step: StepAttempt { step: StepName { name: "charge" }, attempt: 1 }, key: "payments", provider: ProviderName("bank"), implementation: Implementation { name: "ch32_seeing_every_event_of_a_journey::Bank" }, data: None } }
log orders A-15 #12 service_provided charge gets payments from bank, a ch32_seeing_every_event_of_a_journey::Bank
the bank charges 50 for order A-15
Event { sequence: 13, timestamp: Timestamp { instant: SystemTime { tv_sec: 1791996170, tv_nsec: 358993910 } }, journey_id: JourneyId("A-15"), workflow: WorkflowName("orders"), body: StepSucceeded { step: StepAttempt { step: StepName { name: "charge" }, attempt: 1 } } }
Event { sequence: 14, timestamp: Timestamp { instant: SystemTime { tv_sec: 1791996170, tv_nsec: 359022110 } }, journey_id: JourneyId("A-15"), workflow: WorkflowName("orders"), body: JourneyAborted { abort: ReporterFailed { step: Some(StepName { name: "charge" }), error: "the logging service is down" } } }
the journey was aborted (reporter failed: the logging service is down)

What the asynchronous form ch32_seeing_every_event_of_a_journey_async prints, recorded in ch32_seeing_every_event_of_a_journey_async.txt

Event { sequence: 1, timestamp: Timestamp { instant: SystemTime { tv_sec: 1791996170, tv_nsec: 362243087 } }, journey_id: JourneyId("A-15"), workflow: WorkflowName("orders"), body: JourneyStarted { initial_keys: ["card", "customer", "gift_card", "order", "parcel", "price"] } }
log orders A-15 #1 journey_started card, customer, gift_card, order, parcel, price
Event { sequence: 2, timestamp: Timestamp { instant: SystemTime { tv_sec: 1791996170, tv_nsec: 362336101 } }, journey_id: JourneyId("A-15"), workflow: WorkflowName("orders"), body: AttemptStarted { step: StepAttempt { step: StepName { name: "lookup" }, attempt: 1 } } }
log orders A-15 #2 attempt_started lookup, attempt 1
Event { sequence: 3, timestamp: Timestamp { instant: SystemTime { tv_sec: 1791996170, tv_nsec: 362375427 } }, journey_id: JourneyId("A-15"), workflow: WorkflowName("orders"), body: ServiceProvided { step: StepAttempt { step: StepName { name: "lookup" }, attempt: 1 }, key: "order_book", provider: ProviderName("ledger"), implementation: Implementation { name: "ch32_seeing_every_event_of_a_journey_async::Ledger" }, data: None } }
log orders A-15 #3 service_provided lookup gets order_book from ledger, a ch32_seeing_every_event_of_a_journey_async::Ledger
the order book has no order A-15 yet
Event { sequence: 4, timestamp: Timestamp { instant: SystemTime { tv_sec: 1791996170, tv_nsec: 362437154 } }, journey_id: JourneyId("A-15"), workflow: WorkflowName("orders"), body: StepSucceeded { step: StepAttempt { step: StepName { name: "lookup" }, attempt: 1 } } }
log orders A-15 #4 step_succeeded lookup
Event { sequence: 5, timestamp: Timestamp { instant: SystemTime { tv_sec: 1791996170, tv_nsec: 362568875 } }, journey_id: JourneyId("A-15"), workflow: WorkflowName("orders"), body: ContributionCommitted { key: "completed", source: Step(StepAttempt { step: StepName { name: "lookup" }, attempt: 1 }) } }
log orders A-15 #5 contribution_committed completed
Event { sequence: 6, timestamp: Timestamp { instant: SystemTime { tv_sec: 1791996170, tv_nsec: 362608040 } }, journey_id: JourneyId("A-15"), workflow: WorkflowName("orders"), body: HookCalled { hook: Step { policy: PolicyName("already_completed"), hook: OnStepSuccess, step: StepAttempt { step: StepName { name: "lookup" }, attempt: 1 } }, lifecycle: None } }
log orders A-15 #6 hook_called already_completed: on step success of lookup
Event { sequence: 7, timestamp: Timestamp { instant: SystemTime { tv_sec: 1791996170, tv_nsec: 362648116 } }, journey_id: JourneyId("A-15"), workflow: WorkflowName("orders"), body: AttemptStarted { step: StepAttempt { step: StepName { name: "price" }, attempt: 1 } } }
log orders A-15 #7 attempt_started price, attempt 1
Event { sequence: 8, timestamp: Timestamp { instant: SystemTime { tv_sec: 1791996170, tv_nsec: 362689539 } }, journey_id: JourneyId("A-15"), workflow: WorkflowName("orders"), body: OptionalInputAbsent { key: "discount", requester: Step(StepAttempt { step: StepName { name: "price" }, attempt: 1 }) } }
log orders A-15 #8 optional_input_absent discount
Event { sequence: 9, timestamp: Timestamp { instant: SystemTime { tv_sec: 1791996170, tv_nsec: 362729420 } }, journey_id: JourneyId("A-15"), workflow: WorkflowName("orders"), body: StepSucceeded { step: StepAttempt { step: StepName { name: "price" }, attempt: 1 } } }
log orders A-15 #9 step_succeeded price
Event { sequence: 10, timestamp: Timestamp { instant: SystemTime { tv_sec: 1791996170, tv_nsec: 362761457 } }, journey_id: JourneyId("A-15"), workflow: WorkflowName("orders"), body: ContributionCommitted { key: "amount", source: Step(StepAttempt { step: StepName { name: "price" }, attempt: 1 }) } }
log orders A-15 #10 contribution_committed amount
Event { sequence: 11, timestamp: Timestamp { instant: SystemTime { tv_sec: 1791996170, tv_nsec: 362793989 } }, journey_id: JourneyId("A-15"), workflow: WorkflowName("orders"), body: AttemptStarted { step: StepAttempt { step: StepName { name: "charge" }, attempt: 1 } } }
log orders A-15 #11 attempt_started charge, attempt 1
Event { sequence: 12, timestamp: Timestamp { instant: SystemTime { tv_sec: 1791996170, tv_nsec: 362834176 } }, journey_id: JourneyId("A-15"), workflow: WorkflowName("orders"), body: ServiceProvided { step: StepAttempt { step: StepName { name: "charge" }, attempt: 1 }, key: "payments", provider: ProviderName("bank"), implementation: Implementation { name: "ch32_seeing_every_event_of_a_journey_async::Bank" }, data: None } }
log orders A-15 #12 service_provided charge gets payments from bank, a ch32_seeing_every_event_of_a_journey_async::Bank
the bank charges 50 for order A-15
Event { sequence: 13, timestamp: Timestamp { instant: SystemTime { tv_sec: 1791996170, tv_nsec: 362904217 } }, journey_id: JourneyId("A-15"), workflow: WorkflowName("orders"), body: StepSucceeded { step: StepAttempt { step: StepName { name: "charge" }, attempt: 1 } } }
Event { sequence: 14, timestamp: Timestamp { instant: SystemTime { tv_sec: 1791996170, tv_nsec: 362928182 } }, journey_id: JourneyId("A-15"), workflow: WorkflowName("orders"), body: JourneyAborted { abort: ReporterFailed { step: Some(StepName { name: "charge" }), error: "the logging service is down" } } }
order A-15 aborted

How it works

A ready-made reporter prints every event. DebugReporter prints each event as Rust's Debug shows it: its sequence number, its timestamp, the journey's ID, the workflow and the body, with everything the body carries. It suits trying a workflow out, debugging one and watching a test run. A reporter for the shop's real log still formats its own lines, as the log does.
It never fails. So DebugReporter never costs a journey, as chapter 31 said every reporter should.
Reporters receive each event in the order the workflow lists them. DebugReporter comes first, so it printed event 13, the charge's step_succeeded, before the log failed on it.
journey_aborted reaches every reporter but the one that failed. Event 14 reached DebugReporter, and not the log. It names the abort's reason, ReporterFailed, the step the journey was in, charge, and the log's error.

Pat's journey is now on record to its end. But the shop still has to refund Pat, and no line holds the receipt the bank gave: the charge never got to commit it. Nor does any line name Pat: they name the journey, A-15.

Outcomes

We have shown how a ready-made reporter shows every event of a journey, up to its end.

The usual way	With Itinera
Seeing what a request did means adding print statements, then taking them out.	A reporter that comes with Itinera prints every event, listed once on the workflow.
A crash in one part of the logging often hides what happened next.	`journey_aborted` reaches every reporter but the one that failed, with the reason and the error.