GELF logs do not properly render short_message

SUMMARY

The short_message for GelfFormat logs does not properly render variables. It logs things like Validating rule %s for %s - i.e. it literally uses %s. full_message is logged correctly.

ISSUE TYPE

• Bug Report

STACKSTORM VERSION

st2 2.9.1, on Python 2.7.12

OS / ENVIRONMENT / INSTALL METHOD

Ansible install, on Ubuntu 16.04.

STEPS TO REPRODUCE

Change the log configuration for ST2 services as documented here. Configure Fluentd to read those GELF-format logs, and send them to Elastic Stack. View the results in Kibana.

EXPECTED RESULTS

I expected to see properly formatted logs, with variables correctly rendered.

ACTUAL RESULTS

The short_message is not properly rendered. For example, when a rule is validated (https://github.com/StackStorm/st2/blob/master/st2reactor/st2reactor/rules/filter.py#L72), it calls the logger:

        LOG.info('Validating rule %s for %s.', self.rule.ref, self.trigger['name'],
                 extra=self._base_logger_context)

This result in a log message like this

Note these fields:

"short_message": "Validating rule %s for %s."
"full_message": "Validating rule mypack.myrule for webhook.",

I expect that short_message should also be rendering %s as the actual variable.

Start at st2reactor/st2reactor/rules/filter.py around line 72, then trace the GelfFormat logging path that produces short_message and full_message. Reproduce the documented GELF configuration and verify that short_message renders the rule reference and trigger name instead of retaining the %s placeholders.