Formatting anti-pattern in log messages leave % placeholders unresolved

Bug #1439762 reported by Csaba Henk on 2015-04-02
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
OpenStack Shared File Systems Service (Manila)
Low
Ramana Raja

Bug Description

The following anti-pattern is frequent across Manila source:

msg = ("The number of %(bar)ses found is %(quux)d that exceeds limit %(lim)d.", {"bar": "wooz", "quux": 14, "lim": 9})
LOG.error(msg)
raise exception.BarQuuxException(message=msg)

This results in actual messages like:

ERROR <component> (u'The number of %(bar)ses found is %(quux)d that exceeds limit %(lim)d.', {'bar': 'wooz', 'quux': 14, 'lim': 9})
...
TRACE <component> BarQuuxException: ("The number of %(bar)ses found is %(quux)d that exceeds limit %(lim)d.", {"bar": "wooz", "quux": 14, "lim": 9})

While a properly formatted message would be:

The number of woozes found is 14 that exceeds limit 9.

For a real life example please see the attachment of https://bugs.launchpad.net/manila/+bug/1417352,
https://launchpadlibrarian.net/198010156/manila-bug-1417352-stacktrace.txt

Csaba Henk (chenk) on 2015-04-02
summary: - Formatting errors in log messages leave % placeholders unresolved
+ Formatting anti-pattern in log messages leave % placeholders unresolved
Changed in manila:
assignee: nobody → Csaba Henk (chenk)
importance: Undecided → Low
milestone: none → kilo-rc1
status: New → Triaged
Changed in manila:
assignee: Csaba Henk (chenk) → Ramana Raja (rraja)

Fix proposed to branch: master
Review: https://review.openstack.org/171201

Changed in manila:
status: Triaged → In Progress
Csaba Henk (chenk) on 2015-04-07
description: updated

Reviewed: https://review.openstack.org/171201
Committed: https://git.openstack.org/cgit/openstack/manila/commit/?id=a992aa00130a56ce5c0a513553a1fe563b705972
Submitter: Jenkins
Branch: master

commit a992aa00130a56ce5c0a513553a1fe563b705972
Author: Ramana Raja <email address hidden>
Date: Tue Apr 7 18:38:07 2015 +0530

    Fix log/error message formatting

    - Use '%' for variable substitution in the message used for logging a
      call and throwing an exception.

    - Use log marker functions(_LI(), _LW(), _LE(), and _LC()) to send
      message directly to the log.

    - Use ',' for variable subsitution in the message in a log marker
      function.

    Change-Id: Ib925014e79d2c380954d952f5dbc835971a0b320
    Closes-Bug: #1439762

Changed in manila:
status: In Progress → Fix Committed
Thierry Carrez (ttx) on 2015-04-13
Changed in manila:
status: Fix Committed → Fix Released
Csaba Henk (chenk) wrote :

We provide the meval.py script that can be used to dump occurrences of this anti-pattern.

The output is JSON.

Usage: use from the root of the git tree.

$ meval.py stats
# gives the listing of files with number of suspicious cases
$ meval.py select --kind=ambiguous
# gives the listing of cases where the program could not judge
# whether it's an occurrence
$ meval.py select --kind=suspicious
# gives the listing of cases which are found suspicious

Thierry Carrez (ttx) on 2015-04-30
Changed in manila:
milestone: kilo-rc1 → 2015.1.0
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers