Correlating Compile, Elaboration and Runtime Logs

Part II · Module 29 · Chapter 29.7 · Correlating Compile, Elaboration and Runtime Logs

Chapter 27.1 separated the three stages and gave each its own log, with the argument that a merged stream buries the originating error. This chapter is the other half: given three logs, which one do you read?

1. One Root Cause, Three Logs

A port is widened from two bits to three, and the case arms inside still use two-element literals. One edit, one mistake:

-- the entity's port, widened
req   : in  std_logic_vector(2 downto 0);
…
-- and the architecture still says
when "00" => gnt <= "00";

Three stages, three logs:

$ nvc --work=work -a vhdl/arb_wide.vhd vhdl/tb_arb.vhd > analyse.log 2>&1   ; echo "rc=$?"
rc=1
$ nvc --work=work -e tb_arb                             > elaborate.log 2>&1 ; echo "rc=$?"
rc=1
$ nvc --work=work -r tb_arb                             > run.log 2>&1       ; echo "rc=$?"
rc=1

All three failed. Now ask which of them says what is wrong:

$ printf '  %-14s %-7s %-14s %-18s %s\n' LOG lines "mentions req" "mentions element" "first line"
$ for s in analyse elaborate run; do
>   printf '  %-14s %-7s %-14s %-18s %s\n' "$s.log" "$(grep -c . $s.log)" \
>     "$(grep -ci 'req' $s.log)" "$(grep -ci 'element' $s.log)" "$(head -1 $s.log | cut -c1-44)"
> done
  LOG            lines   mentions req   mentions element   first line
  analyse.log    20      1              3                  ** Error: expected 3 elements in string lite
  elaborate.log  1       0              0                  ** Fatal: cannot find unit WORK.TB_ARB in li
  run.log        1       0              0                  ** Fatal: WORK.TB_ARB not elaborated

The root cause appears in exactly one log. The other two are one line each and mention neither the signal nor the problem. What they say is true and useless:

$ tail -1 run.log
** Fatal: WORK.TB_ARB not elaborated

That is what a flow showing "the most recent log" presents to the engineer. It is a correct statement about a consequence three steps removed from the cause, and it sends the reader to look for an elaboration problem that does not exist.

What they needed was in analyse.log:

$ grep -m1 -A4 -e 'Error' analyse.log
** Error: expected 3 elements in string literal but have 2
    |
 21 |         when "00" => gnt <= "00";
    |              ^^^^

File, line, the offending text, and a caret under it.

2. The Rule

Read the first stage that failed, never the last.

$ for s in analyse elaborate run; do
>   if grep -qE '\*\* (Error|Fatal)' "$s.log"; then
>     echo "first failing stage: $s -> read $s.log"; break
>   fi
> done
first failing stage: analyse -> read analyse.log

Four lines, and they are worth more than any amount of pattern-matching on the last log. The reason is structural rather than a convention: a stage consumes the previous stage's output, so a failure upstream guarantees a failure downstream, and the downstream message describes the missing input rather than the original mistake.

Two corollaries follow, and both matter.

The downstream messages should be suppressed, not improved. There is no wording for WORK.TB_ARB not elaborated that would be more helpful, because the run stage genuinely does not know why its input is missing. The fix is for the wrapper to stop at the first failure — which Chapter 27.1's stage runner does, with exit "$rc" after a failed stage — so the later logs are never produced and never read.

The later stages should not be run at all. Running them wastes time, fills disk, and — worse — produces logs that will be read. The three logs above exist because I ran all three deliberately to measure them; a correct flow would have one.

3. The Inverse Shape: All Three Succeed and the Design Is Wrong

The rule in §2 assumes the stages report their failures. Chapter 27.1 measured the case where they do not, and it belongs here because it is the other half of the correlation problem.

A VHDL component instantiation whose entity was never analysed:

$ nvc --work=work_u -a faults/tb_e2.vhd ; echo "rc=$?"
rc=0
$ nvc --work=work_u -e tb_arb
** Warning: (init): cannot find entity for component ARB without binding indication
$ echo "rc=$?"
rc=0
$ nvc --work=work_u -r tb_arb
** Warning: 45ns+1: ERROR gnt mismatch
** Warning: 65ns+1: ERROR gnt mismatch
** Warning: 85ns+1: ERROR gnt mismatch
** Note:    85ns+1: TEST FAILED errors=3
$ echo "rc=$?"
rc=0

Three zeros, and the design under test was never in the design. The only evidence at the point where it mattered was a warning in a stage that reported success.

So the "first failing stage" search in §2 has a blind spot: it looks for Error or Fatal, and this failure announced itself as Warning. Which gives the third rule:

A stage's warnings are part of its verdict. Not all of them — Chapter 29.6 is about selecting — but for elaboration specifically, a warning about an unresolved binding is a failure wearing the wrong severity, and it is worth promoting explicitly:

# elaboration warnings that mean the design is not what you think it is
if grep -qE 'cannot find entity|unbound|without binding indication' "$rundir/elaborate.log"; then
  echo "elaborate: unresolved binding -- the design is incomplete" >&2
  exit 1
fi

That is a narrow, named list rather than "treat warnings as errors", because the broad version fails immediately on the hundreds of legitimate warnings a real elaboration produces.

4. And the Stage That Fails While Reporting Success

One more hazard, from Chapter 29.2: a compile can report 256 errors and exit 0, because iverilog's status is its own error count truncated to a byte.

That breaks the §2 search in a different way. The search greps the logs, so it still works — but a wrapper that decides which logs exist by checking exit statuses will run every stage:

# this runs the run stage on a compile that produced nothing
iverilog -o sim.vvp -f filelists/sim.f > compile.log 2>&1 || exit 1
vvp sim.vvp > run.log 2>&1

With 256 errors the || exit 1 does not fire, sim.vvp does not exist, and vvp fails with a message about a missing file. Three stages' worth of confusion from a compile that said what was wrong perfectly clearly.

Combining the three hazards gives the complete gate, and it is not symmetric — each stage needs a different check:

Three stages, three reasons the status is insufficient, three different log checks. That table is the practical content of this chapter.

5. A Stage Correlator

#!/bin/bash
# stagecheck RUNDIR — find the first stage that failed, by log and by artifact.
set -u
rundir=${1:?usage: stagecheck RUNDIR}
[ -d "$rundir" ] || { echo "stagecheck: no such directory: $rundir" >&2; exit 2; }

# the stage order of this flow, earliest first
stages="compile analyse elaborate run"

first=""
printf '%-12s %-7s %-9s %s\n' STAGE LINES STATE 'FIRST MESSAGE'
for s in $stages; do
  log="$rundir/$s.log"
  [ -r "$log" ] || continue
  n=$(grep -c . "$log")

  state=ok
  msg=""
  if m=$(grep -m1 -e '\*\* Error' -e '\*\* Fatal' -e 'error:' -e '^ERROR' "$log" 2>/dev/null); then
    state=FAILED; msg=$m
  elif grep -qE 'cannot find entity|unbound|without binding indication' "$log" 2>/dev/null; then
    # 29.7 §3: an unresolved binding is a failure wearing a warning's severity
    state=UNBOUND; msg=$(grep -m1 -E 'cannot find entity|unbound|without binding' "$log")
  elif c=$(grep -oE '[0-9]+ error\(s\)' "$log" 2>/dev/null | tail -1); [ -n "${c:-}" ]; then
    # 29.2: the status may have wrapped to 0; the log's own count has not
    state=COUNTED; msg="the tool reported $c"
  fi

  printf '%-12s %-7s %-9s %s\n' "$s" "$n" "$state" "$(printf '%s' "$msg" | cut -c1-46)"
  [ "$state" != ok ] && [ -z "$first" ] && first=$s
done

# the run stage needs a verdict, not merely an absence of errors
if [ -r "$rundir/run.log" ] && [ -z "$first" ]; then
  grep -qE 'TEST (PASSED|FAILED)|Report Summary' "$rundir/run.log" \
    || { printf '\nrun produced no verdict -- see Chapter 29.5\n'; first=run; }
fi

if [ -n "$first" ]; then
  printf '\nfirst failing stage: %s -> read %s/%s.log\n' "$first" "$rundir" "$first"
  exit 1
fi
printf '\nall stages clean\n'

$ stagecheck logs/stages
STAGE        LINES   STATE     FIRST MESSAGE
analyse      20      FAILED    ** Error: expected 3 elements in string litera
elaborate    1       FAILED    ** Fatal: cannot find unit WORK.TB_ARB in libr
run          1       FAILED    ** Fatal: WORK.TB_ARB not elaborated

first failing stage: analyse -> read logs/stages/analyse.log
$ echo $?
1

On a clean run it says so and exits 0, with the compile log at zero lines per Chapter 29.1 §4:

$ stagecheck logs/clean
STAGE        LINES   STATE     FIRST MESSAGE
compile      0       ok
run          2       ok

all stages clean
$ echo $?
0

And on §4's wrapping compile — the one iverilog reported as success:

$ iverilog -g2012 -o /tmp/w.vvp /tmp/w.sv > logs/wrapped/compile.log 2>&1
$ echo "iverilog rc=$?"
iverilog rc=0
$ stagecheck logs/wrapped
STAGE        LINES   STATE     FIRST MESSAGE
compile      259     FAILED    /tmp/w.sv:2: error: Unknown module type: missi

first failing stage: compile -> read logs/wrapped/compile.log
$ echo $?
1

The tool exited 0 and stagecheck reported FAILED, because it read the log rather than the status. That single contrast is the argument for the whole chapter.

Four decisions.

The stage order is declared, not discovered. compile analyse elaborate run — because the filesystem has no notion of which log came first, and sorting by mtime is wrong the moment two stages finish in the same second or a log is copied.

UNBOUND and COUNTED are distinct states. §3 and §4 are two different ways a stage fails while looking clean, and giving each its own name means the output says why it is suspicious rather than just flagging it.

The run stage is checked for a verdict, and only when nothing earlier failed — because a run with no verdict after a failed compile is expected, and reporting it would bury the real cause under a second complaint.

It names the log to read. That one line is the whole purpose: not "the flow failed" but "read analyse.log".

6. Correlating a Run-Time Problem Backwards

The chapter so far runs forwards: an early failure explains a later one. The harder direction is a run-time failure that an earlier stage predicted, quietly.

The useful habit is to check the earlier logs for mentions of whatever the run complained about:

# the run failed on a signal; did anything earlier mention it?
sig=$(sed -n 's/.*\[MISMATCH\].*/gnt/p' "$rundir/run.log" | head -1)
for s in compile analyse elaborate; do
  [ -r "$rundir/$s.log" ] && grep -Hn -e "$sig" "$rundir/$s.log"
done

On a clean flow that finds nothing, which is the expected answer and still worth the two seconds. When it finds something — a width-truncation warning at compile time naming the signal that later mismatched — it has saved the entire investigation, because an earlier stage noticed and was not listened to.

That is the same asymmetry as §3 in a different place: a stage's warnings are evidence about the stages that follow it, and the only way to use them is to go back and look after the later stage fails.

Practice

1. Introduce one width mistake in a design and run all three stages. Record the line count and first line of each log.
2. Count how many of the three mention the real cause.
3. Read the last log's message and say what investigation it would send you on.
4. Find the first failing stage with a four-line loop.
5. Explain structurally why the downstream messages cannot be improved.
6. Make the wrapper stop at the first failed stage and confirm the later logs are never created.
7. Build the unbound-component case and record the status of all three stages.
8. Find the single piece of evidence that the design was incomplete, and note its severity.
9. Add a named unresolved-binding check and explain why a blanket warnings-as-errors rule is worse.
10. Build a compile with 256 errors and confirm a || exit 1 wrapper proceeds to the run stage.
11. Fill in the three-stage gate table for your own flow.
12. Write stagecheck and confirm it names analyse on the cascade and exits 1.
13. Sort the stages by mtime instead of declaring the order, and find an input where that is wrong.
14. Grep the earlier logs for a signal the run complained about, on a clean flow and on one with a compile-time warning about the same signal.

Check Your Understanding

1. One mistake produced three failing logs. How many named the cause?
2. What did the two later logs say, and why is that useless?
3. What does a flow showing "the most recent log" present?
4. State the rule in one sentence.
5. Why is the rule structural rather than a convention?
6. Why can the downstream messages not be improved by better wording?
7. What should a wrapper do instead of improving them?
8. In the unbound-component case, what were the three exit statuses?
9. What severity did the only real evidence carry, and which stage emitted it?
10. Why is a named unresolved-binding check better than warnings-as-errors?
11. How does a wrapping exit status break a || exit 1 wrapper?
12. Give the three stages and the reason each one's status is insufficient.
13. Why is the stage order declared rather than derived from mtimes?
14. Why is the run-stage verdict check done only when nothing earlier failed?
15. What is the point of grepping earlier logs after a run-time failure?

7. Remember

• One root cause, three failing logs, and the cause appeared in exactly one — 20 lines against 1 and 1.
• The later messages are true and useless, because a stage can only report that its input is missing.
• Read the first stage that failed, never the last, and stop the flow there so the later logs are never written.
• The inverse shape exists: three stages all exited 0 with no DUT in the design, and the only evidence was a warning during a successful elaboration.
• A stage's warnings are part of its verdict — for elaboration, a named unresolved-binding check, not warnings-as-errors.
• A wrapping exit status defeats || exit 1, so the run stage executes against an artifact that was never produced.
• Three stages, three different insufficiencies: require the artifact, check for a binding message, require a verdict.
• Declare the stage order. Mtimes are not it.
• Check the run verdict only when nothing earlier failed.
• After a run-time failure, grep the earlier logs for the signal — sometimes a stage already told you.

8. What Is Next

Every individual question about a log has an answer. Chapter 29.8 closes the module by producing the thing a team actually reads: one screen, built from the raw logs with the Part I text pipeline, that answers whether things got worse.