[jwrosewell]

The problem

Node's release build failed its performance gate on Ubuntu_ARM_Node_24 at
25,484 detections a second, against a ten result history average of 33,358
and the gate's floor of 27,413.

The cause is #58,
merge commit
efbea083,
which made LicenseKeys.mask the first line of Pipeline.log. FlowData
logs on every process and on every element read, so the mask ran for every
detection whether or not anything was listening for the message.

Measured on one ubuntu-22.04-arm runner, every tree built whole in its own
folder, five rounds each with the order rotating, run
43182592963:

Tree	Detections a second, median of five
fdc2a3dd, the only parent of #58's merge	33,641
efbea083, #58 as merged	27,446
efbea083 with that one line removed	32,263

The two trees in the first two rows are one commit apart, so 18.4 per cent is
the cost of #58 and nothing else. Removing the one line gives 17.6 per cent
of it back and lands within the spread of the tree before #58, whose rounds
ran 32,851 to 34,547 against 31,423 to 34,304. So the line is effectively all
of the cost and there is no residue to hunt.

The new test counts how often the mask actually runs, and it is 575 calls
over 25 detections, which is 23 a detection rather than the two the file's
shape suggests. FlowData logs on process, on stop and on every read,
Evidence.add logs for each key, and PipelineBuilder puts the sequence,
JavaScript and HTTP elements alongside the element under test, so each of
them logs too.

What the specification says

pipeline-specification/features/logging.md,
pinned at a0a7008a, sets the guarantee at lines 20 and 21:

A license key MUST NOT appear in full in a log entry or in an error
message, at any log level.

and names the one message that matters most here, at lines 32 to 36:

Some URLs carry a license key in their query, such as the URL a
data update
request is sent to. A message that names such a URL MUST name it with the
key masked in the same way. The same applies to the message of an error
raised by an HTTP library, which often includes the URL it requested.

and asks, at lines 15 and 16, for the cost this draft is about:

Testing will be needed to ensure that detailed (e.g. debug level) logging
does not impact performance when it is not enabled.

The specification says a key must not reach a log entry. It does not say
where the masking has to happen, so masking where a key can enter a message
satisfies it, and it is what
.NET #119,
Java #85,
PHP #52 did on
10 November, and Go #79
on 9 November. Not one of them touched its Pipeline or Flow Data logging. Node
was the only language that put the mask on the generic path.

What changed

Two production files, 17 lines added and 5 removed, most of which is the
documentation of why. The rest of the diff is three test files and the
matching JSDoc carried into types/pipeline.d.ts, which mirrors the source
verbatim.

pipeline/fiftyone.pipeline.core/pipeline.js

log no longer masks the message it emits. It still masks the one it writes
to the console, which is the branch taken for an 'error' that has no error
listener, because the console is the end of the line and nothing else would
mask it.

A detection's own messages are 'info' and 'debug', and a cloud
detection also logs 'warn' (cloudRequestEngine.js lines 528 and
702), none of which takes that branch. Two kinds of detection
do take it. A failed one masks a message FlowData.setError has already
masked, which LicenseKeys.mask returns unchanged. A cloud detection that
carries on with a missing or null element logs 'error' from
cloudEngine.js lines 139 and 147, not through
setError, and with no error listener that message is masked there too. The
missing element message is logged once for the life of the engine, and the
null element one on each request that has a null element, so a successful
detection with every element present never pays the mask.

pipeline/fiftyone.pipeline.engines/dataFileUpdateService.js

This file's own log wrapper now masks, which covers all of its roughly
twenty messages in one place and is never on the detection path. The file
already imported LicenseKeys for its console branch.

This part is not optional. #58 masked at the cloud request engine, at the
51Did client and in FlowData.setError, and it never touched the data update
service, whose messages name the update URL that carries the licence keys.
Those were covered only by the generic mask, which is why
tests/dataUpdateKeyMasking.test.js passed with no change to that file.
Taking the mask off Pipeline.log and stopping there would have published
licence keys in update log entries, against the specification lines quoted
above.

Which places a key can reach, and how I satisfied myself there are no others

I listed every .log(, ._log( and eventEmitter.emit( in production code
across the repository, leaving out tests, examples and console.log. That
is 48 call sites in 10 files, every one of them under pipeline/ and none
in device-detection, ip-intelligence or location. I then read each
one's message.

Place	Where it is masked
cloudRequestEngine.js lines 315 to 344, every error built from a cloud answer	At the call site, by #58, using the engine's own key
didClient.js lines 702 and 706, the body and the errors of a redeem answer	At the call site, by #58, with its own maskLicence at line 1047, because the package depends on nothing in the Pipeline
flowData.js line 143, setError	At the call site, by #58, before the message is built, so the errors list the JSON Builder sends to the browser is masked too
dataFileUpdateService.js, every message	New in this draft, in that file's own log wrapper
Pipeline.log's console branch	Kept, and free

The places I read and left alone, with the reason, because a reviewer should
weigh these rather than take my word:

• flowData.js lines 121, 164 and
  189, evidence.js lines
  202 and
  208, setHeadersElement.js
  lines 173 and
  208 and
  pipeline.js line 124 name
  element data keys, property names and evidence key names, never a
  value. These are the messages a detection produces.
• shareUsage.js logs gzip and network errors from
  https://devices-v4.51degrees.com/new.ashx, which carries no licence key.
• cloudEngine.js lines 139 and 147 name element keys, a product hint and
  the cloud's own nullreason text.
• cloudRequestEngine.js line 528 names property names, and
  line 702 names
  an evidence key, its value and the keys it conflicts with.
• javascriptbuilder.js line 333 names the callback URL the application
  configured, and line 400 an object name.

The last three are the ones I was unsure about, so I will say plainly what
the change does to them. Each is built from text a caller or the cloud
supplies, so a 51Degrees licence key does not reach them through our own
code, but a caller could in principle put one in a JavaScript builder
endpoint or in evidence. Today's generic mask would catch such a case only
where the text literally reads license= or licence=, because
Pipeline.log calls LicenseKeys.mask(message) with no keys, and with
no keys maskText skips its key loop and only runs the KeyParameter
replacement. So the generic path was already far narrower than it looks, and
what it covered that these call sites do not is the caller's own text with a
licence parameter in it. I judged that not worth 13 per cent of every
detection. If a reviewer disagrees, the cheapest answer is a mask at
javascriptbuilder.js line 333, which is behind a log-once flag and would
cost nothing.

The test #58 wrote that this draft changes

The first full build,
43186177965,
failed on two tests in
tests/licenseKeys.test.js
that #58 wrote, both pinning that Pipeline.log masks. They needed two
different answers.

1. a pipeline error entry with no listener is masked on the console is
   kept and passes unchanged, because the mask stayed in that branch.
2. a pipeline log entry is masked asserted the behaviour this draft
   deliberately changes, so it is now a pipeline log entry is passed on as it is, with a comment above it naming where the guarantee lives instead.

A reviewer should look hard at the second one. It is a test of a security
property being changed rather than fixed, and I would rather it were
challenged than waved through. The guarantee it used to carry is now carried
by cloudLicenseKeyMasking.test.js, didClient.test.js,
dataUpdateKeyMasking.test.js and the an error kept on the flow data is masked test beside it, all of which pass untouched.

What the draft is worth

Run
43189086425,
five arms built whole on one ubuntu-22.04-arm runner, five rounds each with
the order rotating, the same 109,324,901 byte TAC Enterprise data file and
2,726,867 byte 20,000 User-Agent evidence the gate uses. The log prints each
arm's Pipeline.log and dataFileUpdateService.js lines, so which tree ran
is checked rather than assumed.

The arms ran on b1bc4e9d. This head,
629ae019,
differs from it in three comments and one JSDoc block carried into
types/pipeline.d.ts, with no change to any code, so the figures stand.

Arm	Tree	Detections a second, median of five
b0	fdc2a3dd, before #58	32,567
b1	rc head 74cdc781	24,928
b2	this draft	28,190
b3	rc head, with an info and a debug listener attached	24,679
b4	this draft, with those listeners	28,294

The draft is 13.1 per cent faster than rc with nothing listening and 14.7
per cent faster with a logger attached, which is the condition an application
is actually in. It clears the gate floor of 27,413 by 2.8 per cent.

It does not get back to the tree before #58, and it will not. The draft
sits 13.4 per cent below b0. That gap is not masking, and here is the
evidence. In run
43182592963
the same change was applied to two different trees. On efbea083 it measured
32,263 and on today's rc head it measured 29,154, a difference of 9.6 per
cent between the same code on trees three days apart. So the rest of the gap
is the cost of what merged into rc between
efbea083
on 10 November and
74cdc781
today, it is a separate fault, and nobody is on it. On a slow runner Node
could still miss the gate with this draft merged.

Why not make the masking lazy instead

The other shape was to keep the mask on Pipeline.log and skip it when
nothing is listening for the message, which would have kept Node's broader
guarantee. It was measured in the same run and it loses on the figures, not
on taste.

Arm	Tree	Detections a second, median of five
a1	rc head	25,647
a2	head, lazy, nothing listening	28,720
a3	head, mask taken off	29,154
a6	head, listeners attached	25,212
a4	head, lazy, listeners attached	24,661
a5	head, mask taken off, listeners attached	29,021

With a logger attached the lazy shape is worse than doing nothing, 24,661
against 25,212, because it still masks every message it delivers and pays a
listenerCount call on top. It only helps where nothing listens, which is
the performance gate's case and not a customer's. Taking the mask off is 15.1
per cent better in the same condition.

Runs

• Red
  43188579949
  on 95d34ef, which is today's rc with the three test files and no
  production change. 4 failed, 36 passed. The four are the two new cost
  tests, each counting 575 calls where 0 is asked, the new data update
  service test and the rewritten pipeline log test.
• Green
  43189007832
  on 43f1842, the same branch with the two production files added. 40
  passed, 40 total. ESLint reports 0 errors and 1 warning, and that warning
  is on pipeline.js line 57 and is identical on rc.
• Measurements as above, runs
  43182592963
  and
  43189086425.
• Full build
  43199280160,
  green. All 7 Setting 'PullRequestSha' lines read
  9fd11ad5b227ae528e78a7d02038d0afe654b28e, the head before the last commit, Configure
  printed "Left out 2 macOS entries", and each of the 6 jobs ran two suites,
  being 1,237 passed with 2 skipped and 132 passed with 4 skipped. The build
  before it,
  43189129810,
  was green on b1bc4e9d, which is this head less the two documentation
  commits. The earlier build
  43186177965
  on f18dd1c failed, for the reason in "The test Mask license keys in log entries and error messages #58 wrote that this draft
  changes" above.

The last commit,
629ae019,
changes only the comment in Pipeline.log on which detections reach its
console branch, and no code, so it merges on its quick checks and a review,
without a new full build.

macOS was left out of this draft's full build under the 9 November decision.
The rc head is built with macOS before it merges into main.

What remains

1. The 9.6 per cent that merged into rc between 10 and 12 November has no
   owner. It is named by the two arms above and it is not this draft's
   business, but Node will not return to 33,000 detections a second until
   someone bisects it. It should be an issue of its own before the release
   is judged.
2. The three caller-data messages listed above are not masked, and
   javascriptbuilder.js line 333 is the cheapest to add if a reviewer wants
   it.
3. pipeline.js line 124 emits 'info' straight onto the event emitter
   rather than through log. Its message is 'processing ' and an element's
   data key, so no key can reach it and this draft leaves it alone, but it is
   a piece of per request work that nothing can switch off.