Skip to content

v0.10.0 — the report you can run before you integrate anything

Choose a tag to compare

@mrDlef mrDlef released this 20 Aug 22:44
· 40 commits to main since this release

the report you can run before you integrate anything

Fingerprints: q3:q4: — a range written the older way is now read
rather than shrugged at. Every hex is unchanged: a signature that did not
move kept its twelve characters, so q3:fe168406e702 and q4:fe168406e702
describe the same query, and a dashboard grouping by hash needs its stored
values re-prefixed, not recomputed.

os-query-digest slowlog

Everything else here asks you to log digests before you can find out whether
they tell you anything. This does not: index.search.slowlog is already on in
most clusters, so the CLI reads what is already on disk and ranks it.

$ os-query-digest slowlog /var/log/opensearch/*_index_search_slowlog.log
60 lines, 59 records, 3 shapes, 13,515 ms total

  count  total ms*  mean    p95    max  shape
     41      6,807   166    246    258  q4:fe168406e702
                                        logs-* | q=(@timestamp >= ? and @timestamp < ? and not status:? and service:?) | size=50 sort=@timestamp:desc
      6      5,978   996  1,325  1,325  q4:6b6fb17c6640
                                        orders-* | q=(sku:(? or ? or ?)) | aggs=date_histogram(created,day)

No application change, no index to create, nothing to deploy.

Ranked by total time rather than by the slowest record, because that is the
number a slow log cannot give you: it lists the 166 ms query forty-one times
without ever adding them up, and reading it top-down puts the one bad afternoon
above the shape that is the afternoon. --sort takes count, mean, p95
or max for the other readings — on the file above, --sort=p95 promotes that
date_histogram, which is a different and equally real answer.

The table prints the signature of each group, never one record's values.
Under a count of forty-one, a single sample's service and timestamps read as
the group's, and they are not. --json carries the slowest sample labelled as a
sample, beside the timestamps the group spans — which is how a shape that has
always been there is told from one that arrived with this morning's deploy.

Both appenders are read, the plain one and the JSON one beside it. A layout
that namespaces its keys — …slowlog.source rather than source — is read too,
which is tolerance rather than a promise: OpenSearch remains the only thing
certified here, as it has been since v0.7.0 dropped the elasticsearch keyword.
The root --help was still offering "an OpenSearch / Elasticsearch DSL query",
which that release had already stopped meaning; it says OpenSearch now.
Input is consumed a line at a time rather than slurped, because rotated slow
logs run to gigabytes and the whole premise is that you can point this at the
file you already have.

Two things a slow log does that a query file does not

A ] inside the query does not end the record. The plain appender writes
source[{…}] with nothing escaped, so a terms value of a[1], a regexp or a
field named a[0] all put brackets inside the body. Counting brackets is not
enough; the scan tracks where strings begin and end and stops at the first ]
outside one.

Noise and an unreadable record are told apart. Allocation notices, stack
traces and startup messages are skipped in silence — a tool that refused the
file over them would be useless exactly where it is pointed. A line that opened
source[ and never closed it, which is what rotation does to a record, is
reported instead: staying quiet about it would understate the shape it belonged
to. And a file with no records at all is an error rather than an empty table,
since pointing this at the wrong file should not look like a healthy cluster.

What the real nodes said

The formats above were first read from what the appenders are documented to
emit, which is only ever as right as the person writing it. Four files captured
from OpenSearch 2.19.6 and 3.8.0 — plain appender and JSON, verbatim — are
committed under tests/slowlog/ and read by SlowlogCaptureTest. Every one of
them ranks as the same four shapes, whichever version and whichever appender
wrote it. Three things they said that no amount of reading documentation would
have:

  • A search is logged once per phase, query and fetch, both records carrying
    the same body — so counting both doubled every number in the report. One phase
    is read at a time now, query by default, and the summary says how many
    records the other phase held. --phase=fetch|both for the rest.
  • The body in a record is the query the shard ran, not the one the client
    sent: boost and adjust_pure_negative appear, a term becomes
    {"value": …, "boost": 1.0}, a range matching nothing collapses to
    match_none, and a resolved range keeps its shape while losing its bounds.
    The consequence is worth stating plainly, and the guide states it: a slow
    log fingerprint and an application fingerprint of the same request are not the
    same hash
    . Each groups correctly against its own kind; the two sets do not
    join. Records are also per shard, so count is shards touched.
  • OpenSearch 3 escapes the body twice in the JSON layout, from the same
    configuration file 2.19.6 escapes it once with. Every 3.8.0 JSON record was
    unreadable until that layer was taken off — through the decoder rather than by
    stripping backslashes, so an escaped quote inside the query survives.

A range you could not read, in every slow log record

{"range": {"@timestamp": {"gte": "now-15m"}}} was rendered. The same range
as the shard rewrote it — {"from": …, "to": …, "include_lower": true} — was
not, and came out as range(?), which does not even name the field. Since every
record in a slow log carries the rewritten form, the report was unreadable
exactly where it mattered:

logs-* | q=(not status:? and range(?) and service:?)      before
logs-* | q=(@timestamp:* and not status:? and service:?)  after

Two rules, both reported by explain():

  • from/to with include_lower/include_upper are read as
    gte/gt/lte/lt.
    The two spellings are one query, and they now share a
    fingerprint: {"from": 20, "to": 150} and {"gte": 20, "lte": 150} hash
    identically, which is the same trade bool.filterand makes.
  • A range left with no bound at all becomes an exists. It matches every
    document that has the field, which is what @timestamp:* says — and says
    better than range(?) did. A shard rewrites a range every document satisfies
    into exactly that.

A payload naming no bound and no bound setting is still opaque: range(?) is
what "this library failed to read it" looks like, and it should keep meaning
that.

This is why the prefix moved. No committed fixture changed — none of them
used the older spelling — so make release-check had nothing to report, and the
decision could not be a mechanical one. The hashes that do move are those of
queries that read as range(?) until now.

tests/fixtures/18-rewritten-range is a record captured from a live 2.19.6 node,
kept as the fixture for exactly this, and it is a playground preset too.

The fingerprint flags now live in one place

Every sub-command has to accept all of them — a report grouped under different
rules than the application logging them is a report about nothing — so
FingerprintFlags holds the mapping and the help text both commands print.
Two copies of --max-values=none are two chances for one of them to quietly
mean something else.

The mutation job had a ceiling nobody had reached yet

Infection deletes its temporary directory by materialising every file in it into
a single array, so the image's 128 MB limit was a limit on how many mutants may
exist rather than on anything this library does. It was reached at the end of a
green run: the score printed, then a fatal error, then exit 255. The run is given
no memory ceiling now.

Covered MSI is 80%, up from 79, with nothing uncovered — the tests written
for the captured records killed escapes rather than adding any — so the ratchet
in infection.json5 moves 78 → 79.