§ How-to · Maintain

Find out why a run fails

Read an evaluation error, ask pravo what it decided with -v, ask why a resource changes, check for drift and follow a run in a trace.

Time: 15 min
Level: intermediate
Needs: C1 for the shape of a CUE error. jq, and an empty directory.
Done when: You can name the file and line of an evaluation error, print the reason for a task from the debug log and follow a command in a trace.

View as Markdown

On this page

A run fails in one of four places. The specification does not evaluate, a task does something you did not expect, the real world differs from the state, or a provider reports an error. Each has a command that shows it.

Work in an empty directory.

main.cue

package debugging

import (
	rnd "pravo.dev/providers/hashicorp/random"
	loc "pravo.dev/providers/hashicorp/local"
)

$random: rnd.#Provider
$local:  loc.#Provider

$settings: refresh: "1h"

server: $random.#Resource.random_pet & {length: 2}

note: $local.#Resource.local_file & {
	filename: "note.txt"
	content:  "server \(server.id)\n"
}

terminal

$pravo init > /dev/null

$pravo apply -auto-approve | grep '^Apply complete'

Apply complete! Resources: 2 added, 0 changed, 0 destroyed. [txn <id>]

1. Read an evaluation error

An evaluation error has a path, the values that disagree, and a list of places. Add a second value for a field that already has one.

bad.cuerejected

package debugging

server: length: 3

terminalexit 6

$pravo validate

Error: evaluating .:
server.length: 2 errors in empty disjunction:
server.length: conflicting values 2 and 3:
    ./bad.cue:3:17
    ./main.cue:13:49
server.length: conflicting values 3 and null (mismatched types int and null):
    ./bad.cue:3:17
    ./cue.mod/gen/pravo.dev/providers/hashicorp/random/random_gen.cue:215:23
    ./main.cue:13:9

Path. server.length is the field that disagrees.
Values. 2 and 3 cannot both hold. 2 is in main.cue, 3 is in bad.cue.
Places. Each indented line is file:line:column. The first is the value you wrote, and the others are the values it met.
Alternatives. 2 errors in empty disjunction means that the schema offers two alternatives for the field, a number or null, and the value fits neither. Read the first error. The second compares 3 with null.

pravo validate, plan and apply print the same message and exit with 6 for an evaluation error. A misspelt field and an unknown name have shorter messages.

bad.cuerejected

package debugging

note: filenam: "x"

terminalexit 6

$pravo validate

Error: evaluating .:
note.filenam: field not allowed:
    ./bad.cue:3:7

field not allowed means that a definition is closed and the field is not in it. A resource is built from a closed definition, so a typo is an error before any provider starts. C3, Closed or open? explains it.

bad.cuerejected

package debugging

note: content: "\(servr.id)"

terminalexit 6

$pravo validate

Error: evaluating .:
note.content: reference "servr" not found:
    ./bad.cue:3:19

reference "servr" not found names the name that does not exist. Remove the file when you have read it.

terminal

$rm bad.cue

These messages come up most often.

Message	Meaning and fix
`conflicting values A and B`	Two files give a field two values. Read both places. C1
`N errors in empty disjunction`	A field has alternatives and the value fits none. Read the first error.
`field not allowed`	A closed definition does not have the field. Check the spelling.
`reference "x" not found`	A name does not exist in the scope.
`value depends on cfg, which is not concrete (is a -t tag missing?)`	A value still depends on a tag. Pass `-t`. C2
`$settings.state.path is not concrete`	The state path depends on a tag. Pass `-t env=...`.
`a provider schema package is missing`	Run `pravo init`.
`saved plan is stale`	The specification or the state changed after the plan. Plan again. Exit code 3.
`plan rejected: ... is reserved by`	Another actor holds the node. Exit code 4.

The error catalogue lists the rest, with causes and fixes.

2. Ask what pravo decided

-v writes pravo's own account of a run to standard error. It shows what was loaded, which state was opened, where each provider version came from, the graph, and for every task the action and the reason. Nothing is printed without it.

terminal

debug graph built tasks=2 took=0ms
debug plan refresh=age full=false destroy=false tasks=2
debug provider version from the lock file provider=local version=2.9.1 constraint=
debug provider version from the lock file provider=random version=3.9.1 constraint=
debug state opened backend=local location=./pravo.state nodes=2 took=0ms

Every line carries the time since the command began, which cut drops here. The task line carries the reason that pravo why prints.

terminal

$pravo plan -v 2>&1 | grep 'task addr=note' | cut -d' ' -f2-

debug task addr=note phase=plan outcome=ok took=0ms action=no-op skipped=true fresh=true unread=true why="skipped: nothing the provider saw has changed; not read: the plan did not reach it; the record is <age> old, its refresh age is 1h"

Seven lines carry took=: the time one phase of the command took and, on the last line, the time of the whole command. The phases follow one another.

Line	Phase	Its time follows
`loaded`	Loading and evaluating the specification, with the provider packages it imports.	The size of the specification and of the packages it imports.
`state opened`	Reading the records of the state.	The number of records.
`schemas ready`	Reading the schema of each provider from the cache.	The providers the specification uses.
`graph built`	Working out which task reads which, from the references in the body of each.	The number of tasks.
`tasks run`	Walking the graph: planning each task, or applying it. `phase` says which.	The tasks the run reaches and the calls it makes to providers. A task it does not reach costs a comparison of its configuration with its record.
`settled`	Unifying the values that the tasks computed into the configuration. `fills` counts the tasks that contributed.	The tasks whose values something reads.
`finished`	The whole command.

terminal

debug loaded dir=. managed=2 data=0 ephemeral=0 calls=0 outputs=0 providers=2 moves=0 imports=0 took=0ms
debug state opened backend=local location=./pravo.state nodes=2 took=0ms
debug schemas ready providers=2 took=0ms
debug graph built tasks=2 took=0ms
debug tasks run phase=plan tasks=2 took=0ms
debug settled phase=plan fills=0 took=0ms
debug finished command="pravo plan" exit=0 took=0ms

The first four phases do not depend on what changed. They are the floor of every command: a specification that imports a large provider, such as hashicorp/aws, spends most of its floor in loaded and schemas ready, and an estate of thousands of resources spends it in loaded, state opened and graph built. What a command does for the change is in tasks run.

-vv adds the finest detail, such as each task's dependencies, and turns on the providers' own log.

terminal

$pravo plan -vv 2>&1 | grep 'trace graph node' | cut -d' ' -f2- | sort

$pravo plan -vv -refresh=all 2>&1 | grep -c '\[DEBUG\] plugin: starting plugin'

trace graph node addr=note deps=server
trace graph node addr=server deps=
2

PRAVO_LOG=debug or trace does the same as -v or -vv for pravo, and shows the providers' log at that level. info, warn and error affect the providers only.

terminalexit 1

$PRAVO_LOG=warn pravo plan 2>&1 | grep -c debug

Values of attributes are never logged. The name of an environment variable is, and its value is not.

3. Ask why a task changes or is skipped

pravo why lists the reasons behind the action for each address. The plan does not reach note, and its record is within the refresh age of one hour, so pravo did not read it and trusts it. A node that the plan did not look at says so in a not read: reason, with the age of the record and its refresh age.

terminal

$pravo why note

note: no-op
  - skipped: nothing the provider saw has changed
  - not read: the plan did not reach it; the record is <age> old, its refresh age is 1h

Change the specification and ask about server.

main.cue

package debugging

import (
	rnd "pravo.dev/providers/hashicorp/random"
	loc "pravo.dev/providers/hashicorp/local"
)

$random: rnd.#Provider
$local:  loc.#Provider

$settings: refresh: "1h"

server: $random.#Resource.random_pet & {length: 3}

note: $local.#Resource.local_file & {
	filename: "note.txt"
	content:  "server \(server.id)\n"
}

terminal

$pravo why server note

server: replace
  - the specification changed since the last apply (hash f2caf74c767a7efa -> df0a9c7e3f0c3d57)
  - refresh skipped: the record is within its refresh age
  - the provider cannot change length in place; replacement required
  reaches: note
note: replace
  - inputs depend on values known only after apply: server
  - refresh skipped: the record is within its refresh age
  - the provider cannot change content in place; replacement required

The reasons name what changed in the specification, what the provider cannot change in place, and what the change reaches. Put length: 2 back before the next step.

terminal

$sed 's/length: 3/length: 2/' main.cue > main.tmp

$mv main.tmp main.cue

$pravo plan | grep -E '^(No changes|Graph)'

No changes. Your infrastructure matches the configuration.
Graph: planned 0 of 2, 2 unchanged and skipped, 2 within refresh age.

4. Check whether the real world agrees

Change the file behind pravo's back.

terminal

$echo changed > note.txt

$pravo plan | grep -E '^(No changes|Graph)'

No changes. Your infrastructure matches the configuration.
Graph: planned 0 of 2, 2 unchanged and skipped, 2 within refresh age.

The plan found nothing, because the record is within its refresh age and pravo did not read the file. pravo drift ignores refresh ages, reads every resource and exits 2 when something differs. -refresh=all does the same for a plan. A plan that finds nothing among a large estate may also not have looked: the Graph: line says how many records it did not read, and -refresh=expired reads every record that is past its refresh age.

terminalexit 2

$pravo drift

Drift. 1 of 2 resources changed outside pravo:
  note: create
    - refresh found the real state differs from the state (drift)

terminal

$pravo plan -refresh=all | grep -E '^(note|Plan|Graph)'

note: Refreshing state... [id=<id>]
note: no longer exists; it will be created again
Plan: 1 to add, 0 to change, 0 to destroy.
Graph: planned 1 of 2, 1 unchanged and skipped, 2 refreshed, 1 drifted.

-refresh takes age, the default, expired, false and all. The Graph: line counts what a plan read: refreshed and drifted, and what it did not: within refresh age and not read.

5. Follow a run in a trace

Every command can emit OpenTelemetry traces. They are off by default. OTEL_TRACES_EXPORTER=console writes one JSON object per span to standard error, which needs no collector.

terminal

$OTEL_TRACES_EXPORTER=console pravo plan 2> trace.jsonl > /dev/null

$jq -r '.Name' trace.jsonl | sort -u

engine plan
pravo plan
provider ConfigureProvider
provider PlanResourceChange
provider UpgradeResourceState
provider ValidateProviderConfig
provider ValidateResourceConfig
resource note
resource server

One trace per command. The command span is the root, and the run, the resources and the provider calls nest under it. A span records addresses, types, actions, counts and outcomes, and never attribute values.

terminal

$jq -c 'select(.Name == "resource server") | [.Attributes[] | {(.Key): .Value.Value}] | add' trace.jsonl

{"pravo.resource.address":"server","pravo.resource.type":"random_pet","pravo.mode":"managed","pravo.provider":"random","pravo.phase":"plan","pravo.action":"no-op","pravo.skipped":true,"pravo.refreshed":false,"pravo.drifted":false,"pravo.deferred":false}

When tracing is on, the trace id is stored where you already look. It is on every transaction in the state and on every plan document.

terminal

$OTEL_TRACES_EXPORTER=console pravo apply -auto-approve 2> /dev/null | grep -E '^(No changes|Apply complete)'

$pravo state log --json | jq -r '.[0].trace_id | length'

Apply complete! Resources: 1 added, 0 changed, 0 destroyed. [txn <id>]
32

A real collector takes the standard OTEL_EXPORTER_OTLP_ENDPOINT variable. TRACEPARENT in the environment makes the command a child of the caller's span, so a pipeline's trace shows pravo's work inside it.

What next

Run pravo in a pipeline lists the exit codes.
Global flags and why and drift are the reference for -v, pravo why and pravo drift.
Telemetry lists every span, attribute and metric.
C2, Why is my value incomplete? covers the errors about values that are not yet concrete.