I've been working on an export job on OpenVMS. A DCL procedure walks a list of about two hundred tables, runs a Python exporter for each one, and turns RMS files into SQL. It started out sequential, and last week I turned it into a pool of batch workers so the tables export in parallel.

The workers write a results file, and a re-run of the procedure shows progress: how many tables are done, which ones failed, how long each took. The first real run was humming along nicely.

Then I opened one of the worker logs.

The log that skipped a line

Here's a piece of it, with the table names changed:

  OK    customers.sql (2s, 4 records)
  RUN   order_history.sql alias=order_history --key 1 --param 1
Traceback (most recent call last):
  ...
  File "/python$root/lib/python3.10/vms/indexedfile.py", line 62, in usekey
    self._file.usekey(keynum)
vms.rms.error: [Errno 4042] %SYSTEM-E-INVARG, invalid argument
  RUN   order_lines.sql alias=order_lines --key 1 --param 4

Python crashes, and the very next line is DCL starting the next table. There's no FAIL line in between, and the subroutine that runs each export definitely prints one. This is the shape it had since the first version:

$ SET NOON
...
$ KEXPORT: SUBROUTINE
$   ...
$   'PYCMD'
$   IF $STATUS
$   THEN
$     SAY "  OK    ''FILE'"
$   ELSE
$     SAY "  FAIL  ''FILE' (status=''$STATUS')"
$   ENDIF
$ ENDSUBROUTINE

SET NOON is right there at the top. Errors shouldn't stop anything. And yet the code after the failing command never ran.

SET NOON has a scope

It's in the docs, just not where you'd look when you're staring at a log. The DCL Dictionary entry for SET ON:

The SET ON or SET NOON command applies only at the current command level. If you use the SET NOON command in a command procedure that executes another procedure, the default, SET ON, is established while the second procedure executes.

And the User's Manual, on CALL:

The CALL command transfers control to a labeled subroutine in a command procedure and creates a new procedure level.

Put the two together. Every CALL is a new level, every new level starts with error checking on, and the default action is ON ERROR THEN EXIT. My SET NOON at the top protected the main procedure and nothing it called.

So Python exits with an error status, DCL checks it, and the subroutine exits on the spot. The IF $STATUS never gets evaluated. Control goes back to the caller, the caller has NOON, and it happily moves on to the next table.

The failure wasn't swallowed. It was skipped.

And then the report lied

In the sequential version that only meant a missing FAIL line and a wrong count. The parallel version made it worse.

Each worker calls the export subroutine, and the subroutine leaves its outcome in a global symbol. After the CALL the worker appends that symbol to its results file. Except the subroutine never got far enough to set it, so the symbol still held the result of the previous table. Which was OK.

Every crashed table got recorded as a success, and the progress report would have counted it as done.

The saving grace was a completion marker: the exporter only writes a .done file after the output is safely on disk, and the next run skips only tables that have one. The crashed tables had no marker, so a re-run would have retried them. The data was fine. Only the report lied.

I checked git afterwards. The original sequential script had the same bug from its very first commit in April. Every failure since then had been silent.

The fix

Three small changes:

$ RUN_EXPORT: SUBROUTINE
$   SET NOON
$   ...
$   'PYCMD'
$   PYSTAT = $STATUS
$   IF .NOT. PYSTAT
$   THEN
$     SAY "  FAIL  ''FILE' (status=''PYSTAT')"
$     EXP_RESULT == "FAIL"
$     EXIT 1
$   ENDIF
$   ...
$   EXIT 1
$ ENDSUBROUTINE
  • SET NOON as the first line of every subroutine. Not just the ones that run images: an error anywhere in a subroutine ends it the same way.
  • Save $STATUS right after the image, before anything else overwrites it, and end with an explicit EXIT 1. The outcome lives in a global, and the caller never sees Python's error status. Otherwise a caller without NOON gets ended by it too, one level up.
  • The worker sets EXP_RESULT == "FAIL" before every CALL. If the subroutine ever ends early again, for whatever reason, the table shows up as failed instead of inheriting the last result.

The smallest version of the trap, if you want to see it on your own box:

$ SET NOON
$ CALL SUB
$ WRITE SYS$OUTPUT "main: back"
$ EXIT
$
$ FAILS: SUBROUTINE
$   EXIT 44          ! SS$_ABORT, standing in for the failing image
$ ENDSUBROUTINE
$
$ SUB: SUBROUTINE
$   CALL FAILS
$   WRITE SYS$OUTPUT "sub: after the failure"   ! never runs
$ ENDSUBROUTINE

Add SET NOON as the first line of SUB and the second message shows up.

Bonus: the counters that were always zero

While I was in there, I found a second one by reading the code. The original script counted results like this:

$ OK = 0
$ FAIL = 0
...
$ KEXPORT: SUBROUTINE
$   ...
$     OK == OK + 1

OK = 0 at the top is a local symbol. Inside the subroutine, OK == OK + 1 assigns a global, but the OK on the right-hand side gets looked up first. DCL searches the current level's locals, then the locals of the levels above it, then the globals. It finds the caller's local OK, which is still 0, every single time. The global gets set to 1, again and again.

And the summary at the end, back at the top level, reads ''OK'. That's the local again, so it prints 0.

The fix is boring: no locals with those names at all. The counters are globals from the start, with a prefix so they don't collide with anything in the user's session:

$ EXP_OK   == 0
$ EXP_FAIL == 0

Both bugs come down to the same thing. A CALL doesn't just jump to a label. It opens a new level with its own error handling and its own local symbols, and anything you set up at the top stays at the top.

The bug the bug was hiding

Once failures showed up as failures, the INVARG from the log above got some attention. That's the error the VSI Python RMS module gives you for usekey() on a key the file doesn't have.

The config describing the files declared alternate keys. ANALYZE/RMS_FILE/FDL on the actual files said otherwise: one had only its primary key, another had keys 0 and 1 but not the key 2 the config promised. Every export that read by one of those keys had been crashing before it read a single record, probably since the day those keys were added to the config. The silent subroutine had been covering for it.

Those tables now get exported with a filtered full scan instead. That's a story for another day.

Takeaway

If a DCL procedure has SET NOON at the top and does real work inside CALL subroutines, that work runs with error checking on. Put SET NOON in every subroutine, or decide on purpose that you want the default. And if you've got a summary line that has never once said something failed, it's worth finding out whether that's because nothing ever did.

If you've got an OpenVMS system that needs this kind of attention, that's something I do.