[18.0] auditlog: write_fast logs raw o2m/m2m Command tuples verbatim, causing downstream TypeError: unhashable type: 'list' under load

[nolifelover]

Module / version

• auditlog (OCA server-tools), version 18.0.2.0.9
• Odoo 18.0 (Community + Enterprise)
• File: auditlog/models/rule.py

Summary

AuditlogRule's log_type='fast' write hook (_make_write's write_fast
closure) logs the raw write() vals dict verbatim, before Odoo's ORM
normalizes it:

def write_fast(self, vals, **kwargs):
    self = self.with_context(auditlog_disabled=True)
    rule_model = self.env["auditlog.rule"]
    vals2 = dict(vals)
    old_vals2 = dict.fromkeys(list(vals2.keys()), False)
    old_values = {id_: old_vals2 for id_ in self.ids}
    new_values = {id_: vals2 for id_ in self.ids}
    result = write_fast.origin(self, vals, **kwargs)
    ...
    rule_model.sudo().create_logs(
        self.env.uid, self._name, self.ids, "write",
        old_values, new_values, {"log_type": log_type},
    )
    return result

For a One2many/Many2many field, vals2[field_name] is the raw Command
tuple list the caller passed — e.g. [Command.clear(), Command.create({...})]
or [(6, 0, [id1, id2])] — not the field's real (converted, .read()-able)
value. That raw structure then flows unmodified into
create_logs → _create_log_line_on_write →
_prepare_log_line_vals_on_write, and gets stored directly as
old_value/new_value on auditlog.log.line (both plain fields.Text()).

In our deployment this pattern — writing an o2m field with
[Command.clear(), Command.create({...})] on a model tracked by a fast
rule — was the write shape in production code that immediately preceded a
TypeError: unhashable type: 'list' raised from around rule.py:488
(the write_fast closure itself, in the old_values = {id_: old_vals2 for id_ in self.ids} / create_logs call region) during a live dev session.
The exception left the DB connection in a bad state; connections piled up
until the pool was exhausted and took the whole environment down (not a
clean 500 — a hung env), which is why we're reporting rather than shrugging
it off as "just install-time noise".

Environment / model shape that triggered it

• Model: loyalty.program (core loyalty module), tracked by a fast
auditlog.rule (log_create/log_write/log_unlink all True).

• Trigger: a write() on the tracked model setting two O2M fields in the
  same call, each with a Command.clear() + Command.create({...}) pair:

  program.write({
      "rule_ids": [Command.clear(), Command.create({
          "reward_point_mode": "unit", "reward_point_amount": 1,
          "minimum_qty": 1, "minimum_amount": 0, "mode": "auto",
          "product_ids": [Command.set(product.ids)],
      })],
      "reward_ids": [Command.clear(), Command.create({
          "reward_type": "product", "reward_product_id": product.id,
          "reward_product_qty": 1, "required_points": 1,
          "description": "...",
      })],
  })

  i.e. two nested o2m fields, each carrying a Command list whose create
  command's own dict ALSO contains a nested m2m Command (product_ids).

Expected vs actual

• Expected: write() on an audited model with o2m/m2m Command-tuple
  values in vals logs successfully (or, if raw Command tuples genuinely
  can't be logged safely in fast mode, fails with a clear, contained
  error — not a TypeError that leaves the connection/pool in a bad
  state).
• Actual (observed in our environment): TypeError: unhashable type: 'list' surfaced from the write_fast region of rule.py (~line 488)
  when the write above ran against a model under a fast audit rule,
  hanging the connection and eventually exhausting the pool.

What we could NOT reproduce (please treat this report as "real incident,

unconfirmed minimal repro")

We tried hard to build a minimal, deterministic repro against the
currently-vendored copy of auditlog/models/rule.py (unmodified since we
vendored it — single commit, no local patches) in a disposable clone
database, and could not trigger the crash again, across ~16 write
shapes:

• program.write({'reward_ids': [(4, id)]}), (6, 0, [ids]),
  (0, 0, {...}), (2, id), (5, 0, 0), and mixes of the above;
• the same shapes on rule_ids;
• rule_ids and reward_ids written together in one call;
• the exact production shape quoted above (Command.clear() +
  Command.create() on both fields at once), including running it through
  the real production method that generates it end-to-end;
• direct m2m writes on the child models themselves
  (loyalty.reward.write({'discount_product_ids': [(6, 0, ids)]}),
  loyalty.rule.write({'product_ids': [(6, 0, ids)]}));
• all of the above under both log_type='fast' and log_type='full'.

Code review explains part of why: we found only 3 set() calls in the
whole file. Two operate on dict keys (always field-name strings, never
unhashable). The third (rule.py ~758, inside
_prepare_log_line_vals_on_write's many-to-many branch) is gated to
log_type == 'full' and reads its operands from .read()-converted values
(hashable id lists), not from raw vals. None of the three should be
reachable with an unhashable operand under the write shapes we tried against
this version of the file.

We're filing anyway because: (a) the incident was real and reproducible
enough in the live environment to take the whole dev stack down via pool
exhaustion — first-hand, not secondhand — and (b) storing a raw,
un-normalized Command-tuple list as old_value/new_value on
fields.Text() is a genuine correctness/robustness gap in write_fast
regardless of whether we can currently force the exact TypeError: the
"old value" it records is always a False placeholder rather than the real
prior state, and the "new value" is an internal ORM protocol object
(Command tuples) rather than the actual data — neither is useful for an
audit trail, and storing internal protocol objects verbatim seems like the
root of the exposure even if the specific crash needs a timing/version
condition we didn't hit.

Our mitigation

We switched the affected rule to log_type='full', which never puts raw
Command tuples into old_values/new_values in the first place (write_full
always calls .read() before and after the write), at the cost of two extra
reads per audited write. Given this model is written rarely (admin edits +
one upgrade-time sync, not a write-heavy model like stock.*), that's an
acceptable trade for us, but it doesn't fix the underlying write_fast
Text-field storage of un-normalized Command tuples for other models/setups
that can't afford full.

Suggested fix direction

write_fast (and _prepare_log_line_vals_on_write's fast branch) could
normalize x2many vals entries before storing them — e.g. resolve Command
tuples to a plain summary (added/removed/updated id lists, or a JSON-safe
structure) instead of persisting the raw tuple/Command objects — which would
both fix whatever surfaces the TypeError under the right timing/version
and make the "new value" column actually legible for an o2m/m2m field
change.