WEBVTT

00:00:00.000 --> 00:00:03.200
Every so often, every tab in my terminal lost

00:00:03.320 --> 00:00:04.680
my Documents folder.

00:00:04.960 --> 00:00:06.480
Operation not permitted.

00:00:06.960 --> 00:00:09.600
Git, ruby, even plain ls.

00:00:10.080 --> 00:00:11.360
The Desktop was fine.

00:00:11.520 --> 00:00:12.840
Downloads was fine.

00:00:13.120 --> 00:00:15.680
A reset command cleared it, and later it came

00:00:15.760 --> 00:00:18.240
back. I wrote two explanations.

00:00:18.560 --> 00:00:19.680
I shipped the first one.

00:00:20.080 --> 00:00:22.000
The second came out of the log.

00:00:27.534 --> 00:00:29.773
The obvious suspect was a browser.

00:00:30.334 --> 00:00:33.053
The video platform I work on renders through headless

00:00:33.134 --> 00:00:36.733
Chrome, and when a render dies badly, its browser

00:00:36.854 --> 00:00:38.973
is orphaned and lives on.

00:00:39.054 --> 00:00:42.253
I found 41 of them, some from July.

00:00:42.334 --> 00:00:44.373
I killed them, moved the browser out of the

00:00:44.414 --> 00:00:47.293
Documents folder, and wrote a reaper that only kills

00:00:47.374 --> 00:00:50.573
a browser whose parent is PID 1.

00:00:50.654 --> 00:00:53.533
Good code. It just wasn't the cure.

00:00:53.800 --> 00:00:55.440
I wrote down why.

00:00:55.480 --> 00:00:58.760
A headless browser asks for the Documents folder, and

00:00:58.840 --> 00:01:02.800
macOS shows a permission prompt that nobody can see.

00:01:02.840 --> 00:01:05.880
It times out, and writes a persistent deny that

00:01:05.960 --> 00:01:08.320
overrides Full Disk Access.

00:01:08.360 --> 00:01:11.040
It went into the docs that same day.

00:01:11.080 --> 00:01:14.720
Nobody had ever seen that prompt, or that deny.

00:01:14.760 --> 00:01:17.240
The log had shown a burst of folder requests

00:01:17.320 --> 00:01:18.960
from the headless binary.

00:01:19.000 --> 00:01:21.160
The story filled in the rest.

00:01:21.367 --> 00:01:23.606
By the tenth, it was back.

00:01:23.687 --> 00:01:26.406
No leaked browser this time, though a batch of

00:01:26.487 --> 00:01:28.926
still renders had just finished.

00:01:28.967 --> 00:01:32.966
A reset took 30 to 60 seconds to hold, and it came

00:01:33.127 --> 00:01:35.086
back once more that night.

00:01:35.127 --> 00:01:37.806
And the question I hadn't asked.

00:01:37.847 --> 00:01:40.086
If a deny row were the cause, there would

00:01:40.127 --> 00:01:41.846
be a row to find.

00:01:42.034 --> 00:01:43.873
That theory was wrong.

00:01:43.954 --> 00:01:46.273
I found out on the eleventh, reading the log

00:01:46.354 --> 00:01:50.273
properly. My first query came back empty.

00:01:50.314 --> 00:01:53.953
In the non-interactive zsh that scripts and coding agents

00:01:54.034 --> 00:01:57.233
run, log is a shell builtin, not the log

00:01:57.674 --> 00:02:00.806
tool. Hide its error and you get 0 lines,

00:02:00.861 --> 00:02:03.433
which looks exactly like nothing happened.

00:02:03.474 --> 00:02:06.806
Apple switches it off for interactive tabs.

00:02:06.861 --> 00:02:12.913
The full path, /usr/bin/log, returned over 1,500 lines when I counted.

00:02:20.100 --> 00:02:25.060
The privacy daemon, tccd, logs one request across several

00:02:25.140 --> 00:02:27.460
lines, and three of them matter.

00:02:27.780 --> 00:02:29.380
One names the permission.

00:02:29.620 --> 00:02:31.500
One names who is asking.

00:02:31.780 --> 00:02:33.340
One gives the verdict.

00:02:33.620 --> 00:02:35.580
They share a message ID.

00:02:36.020 --> 00:02:38.340
Read any one alone and you get the permission

00:02:38.420 --> 00:02:41.940
without the process, or the process without the verdict.

00:02:42.260 --> 00:02:44.900
Join them on the message ID, and one request

00:02:44.980 --> 00:02:46.500
becomes one row.

00:02:46.900 --> 00:02:50.060
Terminal, running git, full disk access.

00:02:50.260 --> 00:02:50.900
Allowed.

00:02:51.167 --> 00:02:54.126
Read that way, the failure was plain.

00:02:54.207 --> 00:02:58.366
proc_pidpath, audit token, failed.

00:02:58.487 --> 00:03:01.966
(#2), no such file or directory.

00:03:02.047 --> 00:03:05.526
Then, failed to build the accessing process.

00:03:05.567 --> 00:03:09.726
Then sandboxd failed to create the attribution chain, for

00:03:09.807 --> 00:03:11.926
the Documents-folder service.

00:03:11.967 --> 00:03:15.566
macOS could not find the program that was asking.

00:03:15.647 --> 00:03:17.806
These lines are as I recorded them on the

00:03:17.927 --> 00:03:21.166
eleventh. A month later, the log no longer held

00:03:21.607 --> 00:03:22.126
them.

00:03:22.334 --> 00:03:25.186
I could reproduce half of that safely.

00:03:25.241 --> 00:03:28.733
I compiled a tiny program that only sleeps, because

00:03:28.814 --> 00:03:32.253
a copied system binary gets killed on this Mac.

00:03:32.334 --> 00:03:34.573
I ran it, and deleted its file while it

00:03:34.654 --> 00:03:38.693
slept. ps still shows the old path.

00:03:38.734 --> 00:03:41.853
Asking the kernel for that process's path fails with

00:03:41.934 --> 00:03:43.333
the same words.

00:03:43.374 --> 00:03:46.693
(#2), no such file or directory.

00:03:46.734 --> 00:03:49.106
That reproduces the failed lookup.

00:03:49.161 --> 00:03:50.573
Not the lockout.

00:03:50.767 --> 00:03:53.086
Here is the chain, as far as the evidence

00:03:53.167 --> 00:03:56.846
goes. A process whose file is gone touches the

00:03:57.087 --> 00:04:02.206
Documents folder. tccd asks which program that is, and

00:04:02.327 --> 00:04:05.859
gets no answer, so the request is refused.

00:04:05.914 --> 00:04:08.926
And the refusal behaves like a verdict cached against

00:04:08.967 --> 00:04:11.446
the responsible app, Terminal.

00:04:11.487 --> 00:04:13.966
Every tab is locked out, not just the stale

00:04:14.047 --> 00:04:17.566
one. That last step I inferred from behaviour.

00:04:17.647 --> 00:04:19.726
I couldn't find it documented.

00:04:19.934 --> 00:04:23.253
And the persistent deny from my first theory.

00:04:23.294 --> 00:04:26.573
On the eleventh, before any reset, there was no

00:04:26.814 --> 00:04:29.173
Documents row for Terminal at all.

00:04:29.214 --> 00:04:31.653
Later I found a better witness.

00:04:31.694 --> 00:04:34.173
Terminal had held a real deny row for the

00:04:34.254 --> 00:04:37.000
Desktop since the previous November.

00:04:37.027 --> 00:04:41.333
The Desktop opened anyway, because Full Disk Access wins.

00:04:41.374 --> 00:04:44.333
A persistent deny doesn't override it.

00:04:44.534 --> 00:04:47.653
Who was running on a deleted program.

00:04:47.734 --> 00:04:51.533
On the eleventh, my AI coding-agent sessions.

00:04:51.574 --> 00:04:54.333
Five of them had been open for days.

00:04:54.374 --> 00:04:58.693
Their command-line tool updated itself daily and kept 3 versions on

00:04:59.214 --> 00:05:03.093
disk. When the 3rd new release landed, the version all five were

00:05:03.294 --> 00:05:06.080
running was pruned, in one go.

00:05:06.187 --> 00:05:09.053
Five processes, one missing file.

00:05:09.094 --> 00:05:12.293
A renderer that re-downloads its browser under a running

00:05:12.374 --> 00:05:14.173
shell does the same.

00:05:14.214 --> 00:05:17.093
So the browser was not entirely innocent.

00:05:24.367 --> 00:05:27.646
While I was writing this, one coding-agent process had

00:05:27.727 --> 00:05:31.806
been up for 3 days, and npm had replaced its package that

00:05:31.887 --> 00:05:35.726
morning. ps shows a path that exists, because the

00:05:35.807 --> 00:05:37.566
new version sits there.

00:05:37.647 --> 00:05:41.726
lsof shows where the old binary was renamed to.

00:05:41.847 --> 00:05:43.246
That path is gone.

00:05:43.287 --> 00:05:45.646
The kernel can't name the process.

00:05:45.727 --> 00:05:47.326
(#2), again.

00:05:47.600 --> 00:05:52.160
So the detector asks lsof instead.

00:05:52.240 --> 00:05:56.360
One pass over my own processes, text mappings only.

00:05:56.400 --> 00:05:59.040
The first text mapping of each process is its

00:05:59.120 --> 00:06:02.800
program. If that file doesn't exist, the process is

00:06:02.880 --> 00:06:07.720
stale. One flag matters more than the rest, -a,

00:06:07.760 --> 00:06:10.240
and the comment above it says why.

00:06:10.434 --> 00:06:16.113
Without -a, lsof joins its filters with or, not

00:06:16.274 --> 00:06:20.193
and. The listing balloons with every kind of open

00:06:20.274 --> 00:06:24.033
file. The first record for each process becomes its

00:06:24.114 --> 00:06:27.873
working directory, which almost always exists.

00:06:27.954 --> 00:06:33.073
In one run, the same pipeline found 2 stale processes with -a,

00:06:33.154 --> 00:06:37.713
and 0 without it. The manual says so in one line.

00:06:37.900 --> 00:06:41.780
For whatever slips through, I run a small watchdog.

00:06:41.820 --> 00:06:45.820
It streams tccd's error log and runs the reset

00:06:45.860 --> 00:06:51.140
when an attribution failure shows up, and every 10 minutes regardless.

00:06:51.180 --> 00:06:54.220
Its first run fired on its own startup, because

00:06:54.300 --> 00:06:57.527
the stream's banner contains the search text.

00:06:57.553 --> 00:07:01.060
In a month it reacted over 900 times.

00:07:01.100 --> 00:07:03.580
Most of those were not my stale sessions, and

00:07:03.820 --> 00:07:06.060
I hadn't pinned down what they were.

00:07:06.267 --> 00:07:08.186
Then I stopped making them.

00:07:08.307 --> 00:07:13.066
Mostly. Auto-updates are off, I update on purpose, then

00:07:13.347 --> 00:07:14.959
restart the sessions.

00:07:15.014 --> 00:07:18.426
My provisioning script refuses to replace the browser while

00:07:18.507 --> 00:07:20.146
anything runs from it.

00:07:20.187 --> 00:07:23.106
Here is the doctor on that live process.

00:07:23.147 --> 00:07:25.826
Stale-binary processes, one.

00:07:25.867 --> 00:07:28.226
Orphaned browsers, 0.

00:07:28.267 --> 00:07:29.839
About a second.

00:07:29.894 --> 00:07:32.506
The theory I shipped first was one nobody had

00:07:32.587 --> 00:07:35.866
observed. The log had the answer, once I asked

00:07:35.947 --> 00:07:36.826
it properly.