FMG API From Scratch Part 7: Stage and Inspect, or Was Anything Actually Written?

Part 6 ended with stage returning a task id. This part is about what you do next, because there are three separate questions and it is easy to answer only the first:

QuestionWhere the answer is
Did the task finish, and how?The task, at /task/task/<id>
What does FortiManager say it ran?The script execution log
Did anything change?The Device Database, before and after

Only the third one matters. The first two can both say “success” while the third says nothing happened, which is exactly what the Jinja trap in Part 6 does.

The code for this part is in the fmg-api-from-scratch repo at tag part-07.

The task

exec on the script endpoint doesn’t run anything synchronously. It queues work and returns a task id, and you poll:

GET /task/task/<id>

The record has a numeric state. On my 7.6.6 box, 4 is success and 5 is failure. Those are the two terminal states I have seen; other values appear while the task runs, and I have not confirmed what they all mean, so the code treats only 4 and 5 as final.

TASK_OK, TASK_FAILED = 4, 5      # the two terminal states seen on 7.6.6; others are unconfirmed


def wait_for_task(fmg, task: int, *, timeout: float = 180, interval: float = 2,
                  sleep: Callable[[float], None] = time.sleep) -> dict:
    """Poll until the task reaches a terminal state; raise TimeoutError if it doesn't."""
    waited = 0.0
    while True:
        status = task_state(fmg, task)
        if status.get("state") in (TASK_OK, TASK_FAILED):
            return status
        if waited >= timeout:
            raise TimeoutError(f"task {task} still in state {status.get('state')!r} after {timeout}s")
        sleep(interval)
        waited += interval

Two design points. It raises on timeout rather than returning whatever it last saw, because a caller who forgets to check would treat “still running” as an answer. And sleep is a parameter, so the tests run instantly and can prove the polling logic without waiting.

A task in state 4 means FortiManager finished what it was asked to do. It does not mean what you meant it to do was done.

The execution log

FortiManager keeps a record of every script run. The log is a plain-text transcript. A run of a small DNS script looks like this (device name and addresses replaced):

Starting log (Run on database)

 config system dns
 set primary 192.0.2.53
 set secondary 198.51.100.53
 set domain "lab.local"
 end
Running script(system_dns__<device>) on DB success

Note what it contains: the CLI that was sent, after variables were substituted. That is the same secret-handling point as Part 6. If a template sets a pre-shared key, the log holds it. So the tool prints a log for a human to read on purpose (log --show), and nothing else prints or stores one.

Finding the right log

This is the part that cost me the most time, because there are several endpoints that look interchangeable and every wrong answer looked plausible. They do not cover the same things:

EndpointWhat it actually covers
/dvmdb/adom/<adom>/script/log/summaryRuns at ADOM level (policy package and ADOM database runs). It did not list my device runs at all.
/dvmdb/adom/<adom>/script/log/latestThe newest of those ADOM-level runs. It returned log_id 181, from July.
/dvmdb/adom/<adom>/script/log/latest/device/<device>Supposed to be the newest run for one device. It returned log_id 801, from 1 October, when I had run scripts against that device that afternoon.
/dvmdb/adom/<adom>/script/log/summary/device/<device>Every run recorded for one device. This one was right.
/dvmdb/adom/<adom>/script/log/output/device/<device>/logid/<id>One device run in full: content, exec_time, log_id, script_name. Right.
/dvmdb/adom/<adom>/script/log/output/logid/<id>One run in full, but only for ADOM-level runs. For a device run it returned -3.

The per-device summary, sorted newest first by log_id, looked like this on the day I tested it. The top entry is the run I had just made, at 15:58 that afternoon:

1271   Oct 18 15:58:13
1121
1081
1051
831
811
801    (the one latest/device kept returning)
791
501
471

So latest/device did not fail. It returned a real record. It just wasn’t the newest, and nothing in the reply says so.

Two things I believed here were wrong, and both were easy to believe. The ADOM summary is not a capped or lossy list of device runs; it answers a different question, so it never lists them. And the per-device latest endpoint, which I trusted because it returned a value for three of my four devices, returned a stale run. A value that exists is not a value that is current.

The id is the task id

The way out of guessing is that the community How-To for the FortiManager API documents how log ids are built: the log_id is the task id followed by a 1 for a run against the Device Database, or followed by a 0 for a run on the real device. I have only run the first kind.

So the run for a task is a calculation, not a search. These are my own runs:

Stage taskLog id read back
1271271
1371371
1381381
def log_id_for_task(task: int, *, real_device: bool = False) -> int:
    """The documented rule: log_id is the task id followed by 1 for a run
    against the Device Database, or 0 for a run on the real device."""
    return int(f"{task}{0 if real_device else 1}")

stage waits for the task, and log --log-id 1381 reads exactly that run. With no --log-id, log takes the highest log_id from the per-device summary:

def latest_log(fmg, adom: str, device: str, log_id: int | None = None) -> dict | None:
    if log_id is None:
        runs = device_summary(fmg, adom, device)
        if not runs:
            return None
        log_id = max(r["log_id"] for r in runs)
    try:
        return log_output(fmg, adom, device, log_id)
    except FMGShapeError:
        return None

Which field says “newest”?

The summary has both seq and log_id. seq looks like the natural sort key and it is not chronological: in my data, entries appeared with seq values out of order relative to their exec_time. log_id rose with execution time throughout, so it’s the one to sort on.

A control question for “OK, no data”

FortiManager answers a URL that doesn’t exist and a URL with nothing to return in the same way: status 0 and no data. At one point I concluded an endpoint didn’t exist because it came back like that, and it did exist. The test that would have caught it is to ask the same endpoint about something that must have an answer. One control question separates “no such endpoint” from “nothing to show”.

Did anything change?

Now the question that matters. The method is the one from Part 5’s rule about writes, applied to staging: read the state the operation changes, before and after.

  1. Read the device’s Device Database for the object the script touches, for example /pm/config/device/<device>/global/system/dns.
  2. Stage the script and wait for the task.
  3. Read the same object again.
  4. Compare.

The comparison reports field names and never values, because a value could be a secret:

def changed_keys(before: Any, after: Any) -> list[str]:
    """Names of the top-level fields that differ. Names only: values may be secrets."""
    if not isinstance(before, dict) or not isinstance(after, dict):
        return [] if before == after else ["(whole value)"]
    return sorted(k for k in set(before) | set(after) if before.get(k) != after.get(k))

Then interpret the result carefully, because there are four outcomes and only one is clearly good:

TaskLogFields changedWhat it means
SucceededsuccessThe ones the script setsThe stage worked
SucceededsuccessNoneEither the script set what was already there, or nothing was written (the Jinja trap, or a wrong target)
SucceededsuccessFields the script doesn’t mentionSomething else changed the database while you were looking
Failederror textNoneA normal failure, and the log says why

The second row is the dangerous one, and it has an innocent cause: if the device already had the value, nothing changes, correctly. That is why a test stage should change something on purpose, then confirm the change, and put the value back. A test that sets a value to what it already is proves nothing.

The test on a lab device

I changed the DNS domain on one spoke from lab.local to lab.test, because it is harmless and easy to see:

$ python fmg_push.py stage --script dns__<spoke-1> --device <spoke-1> \
    --watch /pm/config/device/<spoke-1>/global/system/dns --apply
Task 138 finished, state 4 (success).
Fields changed in the Device Database: domain

The log for that run was 1381, and its content was the five lines of CLI with lab.test in them. Three independent things agree: the task, the log, and the changed field. That is what a stage that worked looks like.

Staging the revert to lab.local (task 144) reported the same single field, domain, changing back.

A second record: FortiManager’s own Event Log

The Event Log in the GUI recorded these runs too. The entries are for the API account, show the source address of the jumpbox, and show the old value in brackets next to the new one:

type=sys_dns,domain=lab.local(lab.test)    userfrom=JSON(192.0.2.6)

That is useful as an independent cross-check, because it was written by FortiManager and not by my tool. It was there even though I have the JSON API logging setting disabled. That setting has request and response modes that capture what the client sent, and I leave it off because a request mode would capture the login credentials.

The GUI’s “Modified” is not the install diff

One thing that misled me during this: after staging, the device’s Config Status in the GUI said Modified, but the Install Preview showed nothing to install. They are measuring different things. The status comes from the Device Database compared with the last saved revision; the preview compares the Device Database with the device. In my case the Device Database and the device agreed, so there was nothing to preview, yet the database differed from its last saved revision, so the status said Modified.

What cleared it was Retrieve Config from the device’s revision history in the GUI. It pulls the configuration from the device, saves a new revision and pushes nothing. The status went to Synchronized. If your device shows Modified and an empty preview, check the diff before assuming something is pending.

The tests

The tests cover the reasoning above, not just the happy path:

  • Polling continues through non-terminal states and stops at 4 or 5.
  • A failed task is terminal and is not counted as success.
  • A task that never finishes raises TimeoutError instead of hanging.
  • The log id is the task id followed by 1, or 0 for a real-device run.
  • The newest run is the highest log_id, not the first entry and not the highest seq.
  • latest_log never calls the latest endpoints.
  • A device with no recorded runs gives None.
  • The change check reports field names and never the values that changed.

Checklist

  • A finished task is not a result. Read the state before and after
  • Poll the task with a timeout that raises, and treat only confirmed terminal states as final
  • Read the log by the id the task gives you: the task id followed by 1
  • Use the per-device summary and the per-device output. The latest endpoints returned stale runs on my box
  • A value that exists is not a value that is current
  • “OK, no data” is ambiguous. Ask the same endpoint about something that must have an answer
  • Sort log entries by log_id, never seq
  • A test stage must change something on purpose, or it proves nothing
  • Compare field names, not values
  • Logs contain the rendered CLI, secrets included
  • The GUI’s Modified status is not the install diff

What comes next

Staging has changed the Device Database and nothing else. Part 8 is the step that reaches the live unit: install, which is a preview followed by a commit, using numeric IDs, and which is where the permission mistakes in Part 4 came from.