Investigate an Unfinished Order

A caller reports that A-1001 was accepted, but the receiving system has no visible notification. A successful HTTP response narrows the investigation: it does not identify the last durable transition.

The application already has three places to look: the accepted order and request result, its outbox record, and the controlled receiver’s event identity. Logs connect those states to an execution. They should describe the transition that actually occurred.

Open this checkpoint in ACB

Stop the previous local application, then use File → Open Folder to open book/checkpoints/26-order-investigation. Open src/main/mule/app.xml and use Flow List to select the named flow for each example. Start the controlled dependency in a separate terminal from the companion root with python3 book/stubs/server.py. Choose Run and Debug → Run Mule Application and wait for deployment. Save canvas edits and use Save and Hot-deploy to Local Runtime before repeating a request.

Run python3 book/run.py verify 26 from the companion root to exercise this running checkpoint with its synthetic fixtures. The verifier supplies requests and checks results; it does not start the ACB application. Keep the editor on this checkpoint while reading a failure so an old deployment cannot supply a misleading answer.

Log after the decision becomes durable

Logging every processor produces a long narrative that may still never record the decisive fact. What an investigation needs is a small number of meaningful transitions, each describing something the application actually knows — an attempted operation and an acknowledged one have very different evidential value. A line written just before a database insert can honestly claim only that a commit was attempted; calling it committed manufactures false evidence the moment that insert fails.

Example 068 — Log committed acceptance or replay

The complete source is in checkpoints/26-order-investigation/src/main/mule/app.xml.

Choose Flow List → create-order. The first Set Variable retains vars.principal.tenantId as tenant; Flow Reference calls accept-once. Select the Logger after that reference. Category is book.orders, Level is INFO, and Message is this expression:

write({event: if (vars.httpStatus == 201) 'order.accepted' else 'order.replayed',
       stage: 'committed', correlationId: correlationId,
       orderId: vars.result.orderId, tenantId: vars.tenant},
      'application/json', {indent: false})

The logger follows accept-once. A new successful commit returns 201 and produces order.accepted; a recorded repeat returns 200 and produces order.replayed. The event carries stage committed, correlation ID, order ID and tenant ID. It does not label validation as acceptance.

Correlation ID identifies an execution. Order ID identifies the business object within a tenant. Event ID identifies the notification that may be delivered several times. Keep all three meanings clear; replacing them with one generic id makes repeated requests difficult to explain. They also have different lifetimes — a caller that retries the same create-order operation produces two correlation IDs and one order.

Avoid full payloads and credentials in ordinary logs. An order log needs an internal identifier, a stage, an outcome and a correlation ID — it rarely needs a shipping address, a payment credential, an Authorization header or a full customer response. A controlled source/recovery store can retain sensitive evidence under appropriate access and retention, while logs carry the minimum identity needed to find it. A correlation value supplied by a caller also needs validation or controlled treatment before becoming trusted operational metadata.

Example 069 — Configure bounded local application logs

Source: checkpoints/26-order-investigation/src/main/resources/log4j2.xml.

Open src/main/resources/log4j2.xml in ACB Explorer. Log4j configuration is edited as text; it is not a flow on the canvas. Inspect this bounded rolling-file configuration:

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="WARN">
  <Appenders>
    <RollingFile name="Orders" fileName="${sys:mule.home}/logs/orders-learning.log"
        filePattern="${sys:mule.home}/logs/orders-learning-%i.log">
      <PatternLayout pattern="%d{ISO8601} %-5p [%t] %m%n"/>
      <Policies><SizeBasedTriggeringPolicy size="10 MB"/></Policies>
      <DefaultRolloverStrategy max="3"/>
    </RollingFile>
  </Appenders>
  <Loggers>
    <Logger name="book.orders" level="INFO" additivity="false"><AppenderRef ref="Orders"/></Logger>
    <Root level="INFO"><AppenderRef ref="Orders"/></Root>
  </Loggers>
</Configuration>

The dedicated category writes to orders-learning.log in the isolated runtime, rotates at 10 MB and retains three rolled files. Those are teaching defaults, not a retention policy for a regulated service. Platform collection and retention require their own configuration; a local rolling file does not automatically become an Anypoint Monitoring dashboard.

Logger records acceptance or replay after the acceptance flow returns.

Follow one failed publication

Run the checkpoint verification, or repeat the outbox lost-response scenario manually. Find the order’s committed record, then its pending event and the receiver row. A pending sender flag alongside a committed receiver effect is consistent with a lost acknowledgement. It is not evidence that the receiver did nothing.

Replay through the dispatcher with the same event identity. Then read sender and receiver state again. The recovery should explain both why another attempt was needed and why that attempt did not create another local effect.

If no accepted-order row exists, investigate the request before publication: contract rejection, principal failure, catalogue failure or rolled-back persistence. If the order exists but no outbox row exists in this edition’s transaction, investigate schema/version mismatch or an implementation defect. The transaction contract makes that combination unexpected. Throughout, treat a missing log line as ambiguous: the execution may have failed before it ever reached that logger.

Measure work as well as requests

Request latency, error rate and admitted volume explain the synchronous interface. Pending count and oldest age explain unfinished publication. Receiver failures, retries and duplicate recognitions explain delivery pressure. A mean can stay comfortable while a handful of orders wait forever, and ten events stuck for an hour are worse than ten thousand draining in a minute — a backlog count alone cannot tell those apart, which is why the oldest age and the relation between arrival and completion belong beside it. Retain distributions and identities for the oldest unresolved work.

Order and correlation identifiers create a new series for every execution, so they belong in logs and traces rather than in metric dimensions. Keep those dimensions bounded: environment, operation, outcome class and a short list of dependencies.

Runtime Manager answers deployment and process questions. Monitoring facilities, logs and dependency telemetry answer execution and service questions. Available features and retention depend on the account and target; design the operating procedure around what is actually collected, not a screenshot from another subscription.

Business counts need the same care, because a burst of client retries can look like a sudden increase in sales. Count completed orders after the durable commit boundary, and decide whether a replay that returns an existing order increments that count — the operational event counter and the unique-order counter answer different questions.

A service-level objective needs a start and finish. “Accepted within two seconds” starts at admitted request and ends at the durable acceptance decision. “Published within a minute” ends at the defined receiver/broker acknowledgement. Neither is a promise of final warehouse fulfillment unless that final state is measured too.

Give an alert a next action

An alert that says “CPU high” leaves the operator to invent its meaning at three in the morning. An alert for old pending events should name the service, environment, oldest age, failure category and owning runbook — a count with no owner is a notification without a recovery action.

For a replica failure, the first question is whether the order committed before the response was lost, and restarting the application again cannot answer it. Establish whether authoritative state is external and intact. Restore processing capacity, inspect unresolved events, then replay through the stable identity boundary. Do not reset the database to make the dashboard green. If the receiver outcome is uncertain, reconcile or repeat idempotently before clearing pending state.

For a policy failure, compare admission and rejection with a known good request. For a credential failure, establish a fresh connection after repair. For a bad release, use the recorded artifact/configuration pair rather than rebuilding a branch and guessing which values were active.

Try it

1. Name the event honestly. Why does order.accepted belong after accept-once rather than after request validation?

Show answer

Validation establishes eligibility, not durability. The acceptance event describes a committed order and recorded result. A replay receives its own event name so request count is not confused with newly accepted order count.

2. Investigate one old event. Sender state says pending; the receiver has the event row. What is a plausible failure and safe next step?

Show answer

The receiver may have committed before its acknowledgement was lost. Repeat or reconcile using the same event identity, then verify the sender flag and receiver effect count. Do not assume pending means no effect.

3. Interpret green process health. Which measure exposes a dispatcher that is alive but makes no progress?

Show answer

Oldest pending age and successful completion rate, considered with dependency failures and workload arrival. A process health endpoint can remain green while unfinished work ages indefinitely.

The local log and state checks are executable. Platform dashboards, alert delivery and an operator rehearsal remain deployment-specific work. The next chapter retains evidence of what was tested and which bytes were released.

Next: Release the Bytes You Tested