Correction to resolve the event tag once per exported event #5185

[kev365]

Fixes #5185.

Resolves the event tag once per exported event instead of twice.

Where to look

The two call sites on main, both storage_reader.GetEventTagByEventIdentifer:

• plaso/multi_process/output_engine.py:256, in _ExportEvents, used for the event
  filter and only consumed when one is set;
• plaso/multi_process/output_engine.py:371, in _FlushExportBuffer, used for the
  output module.

Both were introduced together in 65fb698, "Removed event tag index #3714 (#4154)",
which replaced EventTagIndex.GetEventTagByIdentifier with
reader.GetEventTagByEventIdentifer at each site. In the removed
plaso/storage/event_tag_index.py a lookup was a dict hit followed by
GetAttributeContainerByIdentifier, and returned None without touching the database
when the storage file had no event tags, so calling it twice was close to free.

Change

The event tag is now resolved in one of two places, depending on whether the event
filter needs it:

• with an event filter, in the read loop, since a filter can match on labels, and
  carried through PsortEventHeap to the flush the same way event_data and
  event_data_stream already are;
• without one, when the export buffer is flushed, after duplicate events have been
  discarded, so deduplicated events no longer resolve a tag at all.

Events released from the time slice buffer are resolved at the point they are
exported, since they do not pass through the read loop.

Output is unchanged in both cases. The second point is a behaviour change in that a
deduplicated event no longer causes a lookup, but such events are never written, so
nothing reaches an output module that did not before.

Effect

Measured against a storage file of 1,296,316 events extracted from a disk image, of
which 1,293,801 are exported and 2,515 are discarded as duplicates. Both versions were
run alternately on the same idle machine, twice each, so that run to run variation is
visible rather than assumed:

run	lookups per exported event	wall clock
before	2.00	328.9 s, 355.0 s
after	1.00	285.8 s, 295.1 s

That is 342.0 s against 290.4 s on average, or about 15 percent of export, for 1.30
million lookups removed.

The proportion depends on what is being exported. The measurement in the issue, over
134,499 events extracted from /var/log where the event data is cheaper to
deserialise and the lookup is therefore a larger share of the total, came out closer
to 10 percent. The number of lookups removed per exported event is one in either case.

Note that these storage files contain no event tags, so each removed lookup is the
inexpensive path: the filter expression is still built and parsed, but
_GetAttributeContainersWithFilter returns without querying when there are no
containers of that type. On a storage file that has been tagged the removed lookup
also avoids a query and the deserialisation of a container.

Tests

tests/multi_process/output_engine.py passes unmodified. Giving PushEvent an
event_tag=None default keeps existing callers working.

psort.py -o dynamic output is byte identical before and after against
test_data/psort_test.plaso, with no filter, with a filter on timestamp_desc, and
with a filter on tag, the last of which exercises resolving the tag before the
filter is applied.

Full end-to-end suite on Ubuntu 26.04, exit 0.

[kev365]

Haven't dug into it much, but the failing check here (testProcessSource, 5 != 15) looks unrelated to this change — it passes with dfdatetime 20260411 and fails with 20260730.

A quick look points at ConvertDateTimeValuesToJSON now going via CopyToSerializableDict (#309) — dfVFS's TSKTime doesn't implement it, so a TSK modification_time comes back null after the task store round trip. I could well be missing something, that's as far as I took it.

[joachimmetz]

I opt to change the path spec type form TSK to EXT for now. Will take a closer look at the TSK timestamp when time permits #5189

[joachimmetz]

Changes in #5190 to address the pre-release compatibility issue

[codecov]

Codecov Report

❌ Patch coverage is 64.70588% with 6 lines in your changes missing coverage. Please review.
✅ Project coverage is 85.09%. Comparing base (6fadae7) to head (2da553f).
⚠️ Report is 2 commits behind head on main.

Files with missing lines	Patch %	Lines
plaso/multi_process/output_engine.py	64.70%	6 Missing ⚠️

Additional details and impacted files

@@            Coverage Diff             @@
##             main    #5187      +/-   ##
==========================================
- Coverage   85.10%   85.09%   -0.01%     
==========================================
  Files         456      456              
  Lines       41089    41103      +14     
==========================================
+ Hits        34967    34977      +10     
- Misses       6122     6126       +4     

☔ View full report in Codecov by Harness.
📢 Have feedback on the report? Share it here.

🚀 New features to boost your workflow:

• ❄️ Test Analytics: Detect flaky tests, report on failures, and find test suite problems.

[joachimmetz]

Instead of tracking this state at the object level, I opt to pass this as an argument to _FlushExportBuffer e.g. resolve_event_tag = True/False

[kev365]

Done.

One choice worth flagging: resolve_event_tag defaults to True on both _ExportEvent and _FlushExportBuffer. _ExportEvents always passes it explicitly so the default only affects other callers, but True costs at most a redundant lookup where False would leave the event tag unresolved. Happy to flip it if you prefer False.

psort -o dynamic output is byte identical before and after, without a filter and with filters on timestamp_desc and tag.

[joachimmetz]

Thanks,. It does the safe thing by default, that is fine.

[joachimmetz]

Thanks for the proposed changes, one suggestion

[joachimmetz]

LGTM