St2: Jinja templating broken in action notify section
When I run an action and try to reference any of its output values in jinja template format, the literal string of the template itself is used. For example, the message output is "@channel: Action run by {{action_context.user}} succeeded. Cmd run was {{cmd}}."
The documentation demonstrates this feature here: https://docs.stackstorm.com/chatops/notifications.html#jinja-templating-in-message-and-data
cwkatzmann
All 9 comments
@cwkatzmann When referring to the output and parameters, are you using {{ action_parameters.cmd }} and {{ action_parameters.output }}. The context "action_parameters" is required.
lakshmi-kannan
on 16 Jun 2017
lakshmi-kannan
on 16 Jun 2017
@lakshmi-kannan i've been doing some digging on this and noticed the same thing.
@cwkatzmann original problem came from the following action yaml:
---
name: "guest_wifi"
runner_type: "local-shell-cmd"
parameters:
cmd:
type: "string"
default: "cat /home/stanley/guest_wifi.txt"
notify:
on-complete:
routes:
- chatops_override
message: "{{action_results.stdout}}"
I did some digging and printed out the Jinja context before rendering the message and noticed that action_results is empty:
st2notifier.log:2017-06-16 16:00:24,003 44250928 INFO notifier [-] nmaludy: context = {'action_context': {u'user': u'st2admin'}, 'action_results': {}, 'action_parameters': {u'cmd': u'cat /etc/hosts'}, 'st2kv': {'system': <st2common.services.keyvalues.KeyValueLookup object at 0x2b0e250>}}
I'm guessing his jinja is failing to render because he's trying to reference action_results.stdout which should exist, but isn't being populated
nmaludy
on 16 Jun 2017
It looks like execution.result is being used to populate the action_result context and, in my case, that result is empty in the execution object on the line of code i linked to above.
ActionExecutionDB(action={u'runner_type': u'local-shell-cmd', u'name': u'local-notify', u'parameters': {u'cmd': {u'required': True, u'type': u'string', u'description': u'Arbitrary Linux command to be executed on the remote host(s).'}, u'sudo': {u'immutable': True}}, u'tags': [], u'enabled': True, u'entry_point': u'', u'notify': {u'on-complete': {u'routes': [u'slack'], u'message': u'"@channel: Action run by {{ action_context.user }} succeeded. Cmd run was {{ action_parameters.cmd }}."'}}, u'uid': u'action:examples:local-notify', u'pack': u'examples', u'ref': u'examples.local-notify', u'id': u'58c9debda814c063ec6296d7', u'description': u'Action that executes an arbitrary Linux command on the localhost.'},
children=[],
context={u'user': u'st2admin'},
end_timestamp=None,
id=5944415da814c0293f8ffe43,
liveaction={u'callback': {}, u'runner_info': {u'hostname': u'stackstorm.maludy.home', u'pid': 10412}, u'notify': {u'on-complete': {u'routes': [u'slack'], u'message': u'"@channel: Action run by {{ action_context.user }} succeeded. Cmd run was {{ action_parameters.cmd }}."'}}, u'parameters': {u'cmd': u'cat /etc/hosts'}, u'action': u'examples.local-notify', u'action_is_workflow': False, u'id': u'5944415da814c0293f8ffe42'},
log=[{u'status': u'requested', u'timestamp': datetime.datetime(2017, 6, 16, 20, 36, 45, 929000, tzinfo= < bson.tz_util.FixedOffset object at 0x2c88250 > )},
{u'status': u'scheduled', u'timestamp': datetime.datetime(2017, 6, 16, 20, 36, 45, 999000, tzinfo= < bson.tz_util.FixedOffset object at 0x2c88250 > )},
{u'status': u'running', u'timestamp': datetime.datetime(2017, 6, 16, 20, 36, 46, 60000, tzinfo= < bson.tz_util.FixedOffset object at 0x2c88250 > )}],
parameters={u'cmd': u'cat /etc/hosts'},
parent=None,
result={},
rule={},
runner={u'runner_module': u'local_runner', u'uid': u'runner_type:local-shell-cmd', u'name': u'local-shell-cmd', u'runner_parameters': {u'kwarg_op': {u'default': u'--', u'type': u'string', u'description': u'Operator to use in front of keyword args i.e. "--" or "-".'}, u'cmd': {u'type': u'string', u'description': u'Arbitrary Linux command to be executed on the host.'}, u'timeout': {u'default': 60, u'type': u'integer', u'description': u"Action timeout in seconds. Action will get killed if it doesn't finish in timeout seconds."}, u'env': {u'type': u'object', u'description': u'Environment variables which will be available to the command(e.g. key1=val1,key2=val2)'}, u'sudo': {u'default': False, u'type': u'boolean', u'description': u'The command will be executed with sudo.'}, u'cwd': {u'type': u'string', u'description': u'Working directory where the command will be executed in'}}, u'enabled': True, u'id': u'58c9c9a1a814c00df78edaa9', u'description': u'A runner to execute local actions as a fixed user.'},
start_timestamp="2017-06-16 20:36:45.918003+00:00",
status="running",
trigger={},
trigger_instance={},
trigger_type={},
web_url="https://xxx/#/history/5944415da814c0293f8ffe43/general")
@lakshmi-kannan this appears to be related to a race-condition on startup.
About 50% of the time if i st2ctl restart the action's result is populated, the other 50% of the time it is not.
During the failure mode the only way i can get it to recover is to st2ctl restart and hope that it initializes correctly.
Example of the result being populated in the context properly:
st2notifier.log:2017-06-16 16:48:49,806 63852048 INFO notifier [-] nmaludy: context = {'action_context': {u'user': u'st2admin'}, 'action_results': {u'failed': False, u'stderr': u'', u'return_code': 0, u'succeeded': True, u'stdout': u'127.0.0.1 localhost localhost.localdomain localhost4 localhost4.localdomain4\n::1 localhost localhost.localdomain localhost6 localhost6.localdomain6'}, 'action_parameters': {u'cmd': u'cat /etc/hosts'}, 'st2kv': {'system': <st2common.services.keyvalues.KeyValueLookup object at 0x3b9df50>}}
Then after a restart:
st2notifier.log:2017-06-16 16:50:01,252 63850128 INFO notifier [-] nmaludy: context = {'action_context': {u'user': u'st2admin'}, 'action_results': {}, 'action_parameters': {u'cmd': u'cat /etc/hosts'}, 'st2kv': {'system': <st2common.services.keyvalues.KeyValueLookup object at 0x3ad1610>}}
Another interesting note (thanks to @Mierdin )
The st2 trigger-instance command shows the result's stdout properly, even though the context given to jinja is empty:
[root@stackstorm st2]# st2 trigger-instance get 59444a59a814c043a52eda5e
+-----------------+--------------------------------------------------------------+
| Property | Value |
+-----------------+--------------------------------------------------------------+
| id | 59444a59a814c043a52eda5e |
| trigger | core.st2.generic.notifytrigger |
| occurrence_time | 2017-06-16T21:15:05.582000Z |
| payload | { |
| | "status": "succeeded", |
| | "start_timestamp": "2017-06-16T21:15:05.295975+00:00", |
| | "route": "slack", |
| | "runner_ref": "local-shell-cmd", |
| | "channel": "slack", |
| | "action_ref": "examples.local-notify", |
| | "data": { |
| | "result": "{"failed": false, "stderr": "", |
| | "return_code": 0, "succeeded": true, "stdout": "127.0.0.1 |
| | localhost localhost.localdomain localhost4 |
| | localhost4.localdomain4\n::1 localhost |
| | localhost.localdomain localhost6 localhost6.localdomain6"}" |
| | }, |
| | "message": ""@channel: Action run by st2admin succeeded. |
| | Cmd run was cat /etc/hosts."", |
| | "execution_id": "59444a59a814c043a7402e2b", |
| | "end_timestamp": "2017-06-16T21:15:05.528862+00:00" |
| | } |
| status | processed |
+-----------------+--------------------------------------------------------------+
2017-06-16 17:15:05,562 62465840 INFO jinja [-] Rendering string "@channel: Action run by {{ action_context.user }} succeeded. Cmd run was {{ action_parameters.cmd }}.". Super context={'action_parameters': {u'cmd': u'cat /etc/hosts'}, '__context': {'action_context': {u'user': u'st2admin'}, 'action_results': {}, 'action_parameters': {u'cmd': u'cat /etc/hosts'}, 'st2kv': {'system': <st2common.services.keyvalues.KeyValueLookup object at 0x3c6d350>}}, 'action_results': {}, 'action_context': {u'user': u'st2admin'}, 'st2kv': {'system': <st2common.services.keyvalues.KeyValueLookup object at 0x3c6d350>}}
2017-06-16 17:15:05,566 62465840 INFO jinja [-] Mapping: {'message': u'"@channel: Action run by {{ action_context.user }} succeeded. Cmd run was {{ action_parameters.cmd }}."'}, rendered_mapping: {'message': u'"@channel: Action run by st2admin succeeded. Cmd run was cat /etc/hosts."'}, context: {'action_context': {u'user': u'st2admin'}, 'action_results': {}, 'action_parameters': {u'cmd': u'cat /etc/hosts'}, 'st2kv': {'system': <st2common.services.keyvalues.KeyValueLookup object at 0x3c6d350>}}
@nmaludy Thanks for digging in and posting a simple action to repro. From your logs here https://github.com/StackStorm/st2/issues/3487#issuecomment-309129240, it looks like the action execution status is pending and we shouldn't even hit the code to build the jinja context etc. See https://github.com/StackStorm/st2/blob/3a615564218323be52d6a541a4eb249b7a0590cd/st2actions/st2actions/notifier/notifier.py#L83. So something goofy is going on. I'll use your action and try to repro.
lakshmi-kannan
on 19 Jun 2017
I reproed the issue and I figured out the root cause. We have two data models - LiveAction and Execution. When an action goes through various stages, LiveAction and Execution both get updated. LiveAction is a shorter "control" data model and "Execution" pretty much contains more information about the trigger and other contextual information. The commits to the models are async. Whenever a model gets updated, a new message is also posted in rabbitmq which is what the st2 components consume. Notifier consumes the LiveAction queue as well. The funny thing is LiveAction turns to "succeeded" state and we lookup the execution model but it hasn't been updated yet for whatever reason. So we are looking up a stale object which has no results populated yet and hence the bug. We initially discussed changing the notifier to consume the executions topic in rabbitmq as opposed to liveaction. I'll look into these changes but be forewarned that this is an invasive change and needs to tested carefully. I hope to fix this in the next release. (ETA: 3-4 weeks).
lakshmi-kannan
on 19 Jun 2017
@cwkatzmann @nmaludy Can you please test these changes? It should be in unstable repos in a few hours if our promotion workflows succeed. You can validate the SHA by checking /opt/stackstorm/st2/package.meta and comparing against https://github.com/StackStorm/st2/commits/master.
lakshmi-kannan
on 26 Jun 2017
Related issues
trstruth
路
3Comments
Kami
路
8Comments
armab
路
6Comments
makandre
路
8Comments
nmaludy
路
7Comments
Most helpful comment
I reproed the issue and I figured out the root cause. We have two data models - LiveAction and Execution. When an action goes through various stages, LiveAction and Execution both get updated. LiveAction is a shorter "control" data model and "Execution" pretty much contains more information about the trigger and other contextual information. The commits to the models are async. Whenever a model gets updated, a new message is also posted in rabbitmq which is what the st2 components consume. Notifier consumes the LiveAction queue as well. The funny thing is LiveAction turns to "succeeded" state and we lookup the execution model but it hasn't been updated yet for whatever reason. So we are looking up a stale object which has no results populated yet and hence the bug. We initially discussed changing the notifier to consume the executions topic in rabbitmq as opposed to liveaction. I'll look into these changes but be forewarned that this is an invasive change and needs to tested carefully. I hope to fix this in the next release. (ETA: 3-4 weeks).