WEBVTT

00:00:00.000 --> 00:00:02.400
Ninety point zero three seconds.

00:00:02.960 --> 00:00:05.440
That is how long my app waited for Chrome,

00:00:05.480 --> 00:00:07.800
in my rebuild of a February outage.

00:00:08.080 --> 00:00:10.320
On the right, the same Chrome and the same

00:00:10.400 --> 00:00:12.400
command line, started by hand.

00:00:12.880 --> 00:00:14.880
It lived for a tenth of a second.

00:00:15.280 --> 00:00:17.680
It printed why it was dying, and exited.

00:00:18.320 --> 00:00:21.280
My app waited out the whole timeout, then raised

00:00:21.360 --> 00:00:23.360
an error that mentions none of it.

00:00:23.680 --> 00:00:26.240
So the question was never why Chrome hung.

00:00:26.640 --> 00:00:29.200
It is what was waiting, and on whom.

00:00:34.734 --> 00:00:36.733
This is an invoicing app.

00:00:37.054 --> 00:00:39.773
Each invoice is a web page, and a headless

00:00:39.854 --> 00:00:42.973
Chrome prints it to PDF, through a small gem

00:00:43.054 --> 00:00:46.733
called ferrum_pdf, which sits on a browser library called

00:00:46.894 --> 00:00:50.173
Ferrum. On the seventh of February, I moved the

00:00:50.294 --> 00:00:52.333
app to a new deploy tool.

00:00:52.414 --> 00:00:55.533
From that week on, by my notes, every PDF

00:00:55.614 --> 00:00:58.573
took sixty to ninety seconds to fail, with an

00:00:58.734 --> 00:01:00.573
error that never said why.

00:01:00.654 --> 00:01:01.693
Not some of them.

00:01:01.854 --> 00:01:02.653
Every one.

00:01:02.934 --> 00:01:05.733
So I chased the plausible suspects, one at a

00:01:05.814 --> 00:01:09.333
time. The app's own IP rules, in case they

00:01:09.414 --> 00:01:12.253
blocked Chrome's request for the stylesheet.

00:01:12.294 --> 00:01:15.533
A base URL the new host did not set.

00:01:15.574 --> 00:01:19.053
A memory limit of five hundred and twelve megabytes.

00:01:19.094 --> 00:01:21.773
Then two rounds of pulling Chrome flags out of

00:01:21.814 --> 00:01:25.093
the config, betting each time that one had turned

00:01:25.174 --> 00:01:28.773
poisonous. Each one felt like the answer, until the

00:01:28.854 --> 00:01:30.293
next timeout.

00:01:30.500 --> 00:01:32.700
None of that config was new.

00:01:32.740 --> 00:01:35.180
I had been tuning it since August.

00:01:35.220 --> 00:01:38.393
The production flag list went from twenty one flags,

00:01:38.447 --> 00:01:42.580
to thirty six, to seventeen, to twenty eight.

00:01:42.740 --> 00:01:45.780
Along the way, the process_timeout went from the default

00:01:45.860 --> 00:01:48.300
ten seconds to ninety.

00:01:48.340 --> 00:01:51.940
Every rewrite was committed, and every rewrite felt like

00:01:52.020 --> 00:01:53.060
progress.

00:02:00.267 --> 00:02:03.066
A timeout that says nothing gives you nothing to

00:02:03.147 --> 00:02:06.746
grep. So I wrote a diagnostic task that walks

00:02:06.787 --> 00:02:08.906
the pipeline one layer at a time.

00:02:09.467 --> 00:02:11.826
System info. Launch the browser.

00:02:12.027 --> 00:02:13.506
Print a simple page.

00:02:13.707 --> 00:02:14.826
Reach the stylesheet.

00:02:15.147 --> 00:02:16.346
Print with styles.

00:02:16.507 --> 00:02:18.466
Then print a real invoice.

00:02:18.747 --> 00:02:20.466
Step two is the launch.

00:02:20.667 --> 00:02:23.106
If it fails, the task stops there.

00:02:23.387 --> 00:02:26.186
In my notes, that is exactly where it stopped.

00:02:26.467 --> 00:02:28.946
The first split was strange.

00:02:29.027 --> 00:02:32.546
Started by hand, with the sandbox switched off, the

00:02:32.627 --> 00:02:35.626
same Chrome printed its debugging address in under a

00:02:35.667 --> 00:02:37.546
tenth of a second.

00:02:37.587 --> 00:02:40.146
Started through the library, with a config that was

00:02:40.227 --> 00:02:42.786
meant to switch the sandbox off as well, it

00:02:42.867 --> 00:02:45.626
printed nothing for ninety seconds.

00:02:45.667 --> 00:02:48.946
So something on the library's path looked poisonous, and

00:02:49.027 --> 00:02:52.466
the obvious suspects were my own twenty eight flags.

00:02:52.667 --> 00:02:54.826
So I went flag hunting.

00:02:54.947 --> 00:02:57.826
Three essentials stayed in as a baseline.

00:02:57.867 --> 00:03:01.119
The other twenty five went in, in small groups,

00:03:01.254 --> 00:03:03.706
then one at a time inside any group that

00:03:04.227 --> 00:03:07.426
failed. In the rebuild, every group failed.

00:03:07.467 --> 00:03:10.506
Then every flag on its own failed, all twenty

00:03:10.627 --> 00:03:11.746
five of them.

00:03:11.787 --> 00:03:14.719
Even the baseline failed with nothing added.

00:03:14.774 --> 00:03:17.386
A poisonous flag breaks one group.

00:03:17.467 --> 00:03:19.226
This broke all of them.

00:03:19.434 --> 00:03:21.193
That is the clue.

00:03:21.274 --> 00:03:24.793
When taking any one thing away changes nothing, the

00:03:24.874 --> 00:03:27.873
thing you are taking away is not there.

00:03:27.914 --> 00:03:30.553
Here is the command line the library actually handed

00:03:30.634 --> 00:03:32.526
over, in my rebuild.

00:03:32.581 --> 00:03:36.206
With the fixed config, --no-sandbox is right there.

00:03:36.261 --> 00:03:39.513
With the config I had, thirty nine flags, all

00:03:39.554 --> 00:03:40.833
the library's own.

00:03:40.874 --> 00:03:43.353
Thirteen of mine are in there only as Ferrum

00:03:43.914 --> 00:03:47.593
defaults. Where --no-sandbox should be, there is nothing.

00:03:47.674 --> 00:03:50.793
One second later, that process is defunct.

00:03:58.000 --> 00:03:59.440
So, the wire.

00:04:00.160 --> 00:04:04.400
ferrum_pdf keeps its settings in one config object, an

00:04:04.480 --> 00:04:08.240
OrderedOptions object. It is a hash that answers to

00:04:08.360 --> 00:04:09.720
any name you give it.

00:04:10.080 --> 00:04:12.440
I wrote my flags to browser_args.

00:04:12.640 --> 00:04:15.720
It stored all twenty eight entries without a word.

00:04:15.760 --> 00:04:17.560
No error, no warning.

00:04:17.600 --> 00:04:18.480
Not a bug.

00:04:18.720 --> 00:04:20.920
It is exactly what a hash does.

00:04:21.200 --> 00:04:23.600
It cannot know a name is wrong, and nothing

00:04:23.680 --> 00:04:24.800
after it asks.

00:04:25.067 --> 00:04:28.826
The gem keeps three keys for itself, the page,

00:04:28.907 --> 00:04:32.906
PDF and screenshot options, and hands every other key

00:04:32.987 --> 00:04:35.173
to Ferrum, unchecked.

00:04:35.200 --> 00:04:39.666
Ferrum reads its flags from exactly one key, browser_options,

00:04:39.707 --> 00:04:42.346
with an empty hash as the default.

00:04:42.427 --> 00:04:45.146
My twenty eight flags went into a field nobody

00:04:45.627 --> 00:04:48.226
reads. So did two of my timeouts.

00:04:48.267 --> 00:04:50.906
Ferrum got an empty hash, and built the command

00:04:50.987 --> 00:04:53.066
line from its own defaults.

00:04:53.267 --> 00:04:56.626
Five revisions of flags, and my config delivered none

00:04:56.667 --> 00:04:59.826
of them. The fix was one word, in two

00:05:00.387 --> 00:05:05.186
places. browser_args became browser_options, once for the specs, and

00:05:05.267 --> 00:05:06.839
once for production.

00:05:06.894 --> 00:05:09.906
The same commit changed other things too, among them

00:05:09.987 --> 00:05:12.493
the memory limit and three flags.

00:05:12.520 --> 00:05:15.906
But in the rebuild, the word alone is enough.

00:05:15.987 --> 00:05:19.546
All twenty eight original flags, the old memory limit,

00:05:19.587 --> 00:05:22.546
and a PDF in about half a second.

00:05:22.734 --> 00:05:25.213
That word sat in the file from the sixteenth

00:05:25.294 --> 00:05:28.333
of August, a hundred and eighty one days before

00:05:28.414 --> 00:05:32.066
the fix. So what changed in February.

00:05:32.121 --> 00:05:34.573
The old deploy script ran the container with an

00:05:34.654 --> 00:05:39.693
extra Linux capability and an unconfined seccomp profile, put

00:05:39.774 --> 00:05:42.813
there, its comment says, for Chrome.

00:05:43.054 --> 00:05:46.386
Together they let Chrome build its sandbox anyway.

00:05:46.441 --> 00:05:49.053
The new deploy tool set a memory limit, and

00:05:49.214 --> 00:05:52.786
nothing else. The bug did not arrive in February.

00:05:52.841 --> 00:05:54.413
It lost its cover.

00:05:54.600 --> 00:05:57.280
A correction, and it is on me.

00:05:57.320 --> 00:06:00.360
My notes from February say Chrome hangs while it

00:06:00.480 --> 00:06:02.240
sets up its sandbox.

00:06:02.280 --> 00:06:05.240
Rebuilt with the same Chromium release, it does not

00:06:05.600 --> 00:06:08.640
hang. It aborts in a tenth of a second.

00:06:08.680 --> 00:06:11.453
Ferrum hands Chrome the write end of a pipe,

00:06:11.507 --> 00:06:13.800
and keeps its own copy open until it gives

00:06:13.960 --> 00:06:17.453
up. So the pipe never reports end of file,

00:06:17.507 --> 00:06:20.200
and the loop waits out all ninety seconds, for

00:06:20.240 --> 00:06:22.440
a line that is never coming.

00:06:22.634 --> 00:06:25.033
So, the receipts I kept.

00:06:25.194 --> 00:06:27.673
Three keys in that config were never read by

00:06:27.754 --> 00:06:30.713
anything, and a few lines at boot name all

00:06:31.274 --> 00:06:34.833
three. Check the command line your process actually got,

00:06:34.874 --> 00:06:36.713
not the one you configured.

00:06:36.794 --> 00:06:39.233
Print the output your errors carry.

00:06:39.274 --> 00:06:42.953
Where Ferrum reached its own timeout, Chrome's real error

00:06:43.114 --> 00:06:47.086
sat inside the exception, in a field nobody printed.

00:06:47.141 --> 00:06:50.233
And when something hangs, ask what is waiting, and

00:06:50.314 --> 00:06:51.273
on whom.