Changes for v2.10.4 release

CHANGELOG.rst

@@ -4,6 +4,27 @@ Changelog
 In development
 --------------
 
+Fixed
+~~~~~
+
+* Fix inadvertent regression in notifier service which would cause generic action trigger to only
+  be dispatched for completed states even if custom states were specified using
+  ``action_sensor.emit_when`` config option. (bug fix)
+  Reported by Shu Sugimoto (@shusugmt). #4591
+* Make sure we don't log auth token and api key inside st2api log file if those values are provided
+  via query parameter and not header (``?x-auth-token=foo``, ``?st2-api-key=bar``). (bug fix) #4592
+  #4589
+* Fix rendering of ``{{ config_context. }}`` in orquesta task that references action from a
+  different pack (bug fix) #4570 #4567
+* Add missing default config location (``/etc/st2/st2.conf``) to the following services:
+  ``st2actionrunner``, ``st2scheduler``, ``st2workflowengine``. (bug fix) #4596
+* Update statsd metrics driver so any exception thrown by statsd library is treated as non fatal.
+
+  Previously there was an edge case if user used a hostname instead of an IP address for metrics
+  backend server address. In such scenario, if hostname DNS resolution failed, statsd driver would
+  throw the exception which would propagate all the way up and break the application. (bug fix) #4597
+
+  Reported by Chris McKenzie.
 
 2.10.3 - March 06, 2019
 -----------------------

contrib/examples/actions/render_config_context.yaml

@@ -0,0 +1,8 @@
+---
+name: render_config_context
+pack: examples
+description: Run render config context workflow
+runner_type: orquesta
+entry_point: workflows/render_config_context.yaml
+enabled: true
+parameters: {}

contrib/examples/actions/workflows/render_config_context.yaml

@@ -0,0 +1,7 @@
+version: 1.0
+description: Testing config context render".
+tasks:
+  task1:
+    action: tests.render_config_context
+output:
+  - context_value: <% task(task1).result.result.context_value %>

st2actions/st2actions/config.py

@@ -22,12 +22,14 @@
 
 import st2common.config as common_config
 from st2common.constants.system import VERSION_STRING
+from st2common.constants.system import DEFAULT_CONFIG_FILE_PATH
 
 CONF = cfg.CONF
 
 
 def parse_args(args=None):
-    CONF(args=args, version=VERSION_STRING)
+    CONF(args=args, version=VERSION_STRING,
+         default_config_files=[DEFAULT_CONFIG_FILE_PATH])
 
 
 def register_opts():

st2actions/st2actions/notifier/notifier.py

@@ -97,10 +97,7 @@ def process(self, execution_db):
                     self._post_notify_triggers(liveaction_db=liveaction_db,
                                                execution_db=execution_db)
 
-            if cfg.CONF.action_sensor.enable:
-                with CounterWithTimer(key='notifier.generic_trigger.post'):
-                    self._post_generic_trigger(liveaction_db=liveaction_db,
-                                               execution_db=execution_db)
+        self._post_generic_trigger(liveaction_db=liveaction_db, execution_db=execution_db)
 
     def _get_execution_for_liveaction(self, liveaction):
         execution = ActionExecution.get(liveaction__id=str(liveaction.id))
@@ -252,25 +249,26 @@ def _post_generic_trigger(self, liveaction_db=None, execution_db=None):
             LOG.debug(msg % (execution_id, execution_db.status, target_statuses), extra=extra)
             return
 
-        payload = {'execution_id': execution_id,
-                   'status': liveaction_db.status,
-                   'start_timestamp': str(liveaction_db.start_timestamp),
-                   # deprecate 'action_name' at some point and switch to 'action_ref'
-                   'action_name': liveaction_db.action,
-                   'action_ref': liveaction_db.action,
-                   'runner_ref': self._get_runner_ref(liveaction_db.action),
-                   'parameters': liveaction_db.get_masked_parameters(),
-                   'result': liveaction_db.result}
-        # Use execution_id to extract trace rather than liveaction. execution_id
-        # will look-up an exact TraceDB while liveaction depending on context
-        # may not end up going to the DB.
-        trace_context = self._get_trace_context(execution_id=execution_id)
-        LOG.debug('POSTing %s for %s. Payload - %s. TraceContext - %s',
-                  ACTION_TRIGGER_TYPE['name'], liveaction_db.id, payload, trace_context)
-
-        with CounterWithTimer(key='notifier.generic_trigger.dispatch'):
-            self._trigger_dispatcher.dispatch(self._action_trigger, payload=payload,
-                                              trace_context=trace_context)
+        with CounterWithTimer(key='notifier.generic_trigger.post'):
+            payload = {'execution_id': execution_id,
+                       'status': liveaction_db.status,
+                       'start_timestamp': str(liveaction_db.start_timestamp),
+                       # deprecate 'action_name' at some point and switch to 'action_ref'
+                       'action_name': liveaction_db.action,
+                       'action_ref': liveaction_db.action,
+                       'runner_ref': self._get_runner_ref(liveaction_db.action),
+                       'parameters': liveaction_db.get_masked_parameters(),
+                       'result': liveaction_db.result}
+            # Use execution_id to extract trace rather than liveaction. execution_id
+            # will look-up an exact TraceDB while liveaction depending on context
+            # may not end up going to the DB.
+            trace_context = self._get_trace_context(execution_id=execution_id)
+            LOG.debug('POSTing %s for %s. Payload - %s. TraceContext - %s',
+                      ACTION_TRIGGER_TYPE['name'], liveaction_db.id, payload, trace_context)
+
+            with CounterWithTimer(key='notifier.generic_trigger.dispatch'):
+                self._trigger_dispatcher.dispatch(self._action_trigger, payload=payload,
+                                                  trace_context=trace_context)
 
     def _get_runner_ref(self, action_ref):
         """

st2actions/st2actions/scheduler/config.py

@@ -19,14 +19,16 @@
 
 from st2common import config as common_config
 from st2common.constants import system as sys_constants
+from st2common.constants.system import DEFAULT_CONFIG_FILE_PATH
 from st2common import log as logging
 
 
 LOG = logging.getLogger(__name__)
 
 
 def parse_args(args=None):
-    cfg.CONF(args=args, version=sys_constants.VERSION_STRING)
+    cfg.CONF(args=args, version=sys_constants.VERSION_STRING,
+             default_config_files=[DEFAULT_CONFIG_FILE_PATH])
 
 
 def register_opts():

st2actions/st2actions/workflows/config.py

@@ -19,10 +19,12 @@
 
 from st2common import config as common_config
 from st2common.constants import system as sys_constants
+from st2common.constants.system import DEFAULT_CONFIG_FILE_PATH
 
 
 def parse_args(args=None):
-    cfg.CONF(args=args, version=sys_constants.VERSION_STRING)
+    cfg.CONF(args=args, version=sys_constants.VERSION_STRING,
+             default_config_files=[DEFAULT_CONFIG_FILE_PATH])
 
 
 def register_opts():

st2actions/tests/unit/test_notifier.py

@@ -263,3 +263,83 @@ def test_post_generic_trigger_with_emit_condition(self, dispatch):
                                             payload=exp, trace_context={})
 
         self.assertEqual(dispatch.call_count, 3)
+
+    @mock.patch('oslo_config.cfg.CONF.action_sensor.enable', mock.MagicMock(
+        return_value=True))
+    @mock.patch.object(Notifier, '_get_runner_ref', mock.MagicMock(
+        return_value='local-shell-cmd'))
+    @mock.patch.object(Notifier, '_get_trace_context', mock.MagicMock(
+        return_value={}))
+    @mock.patch('st2common.transport.reactor.TriggerDispatcher.dispatch')
+    @mock.patch('st2actions.notifier.notifier.LiveAction')
+    @mock.patch('st2actions.notifier.notifier.policy_service.apply_post_run_policies', mock.Mock())
+    def test_process_post_generic_notify_trigger_on_completed_state_default(self,
+            mock_LiveAction, mock_dispatch):
+        # Verify that generic action trigger is posted on all completed states when action sensor
+        # is enabled
+        for status in LIVEACTION_STATUSES:
+            notifier = Notifier(connection=None, queues=[])
+
+            liveaction_db = LiveActionDB(id=bson.ObjectId(), action='core.local')
+            liveaction_db.status = status
+            execution = MOCK_EXECUTION
+            execution.liveaction = vars(LiveActionAPI.from_model(liveaction_db))
+            execution.status = liveaction_db.status
+
+            mock_LiveAction.get_by_id.return_value = liveaction_db
+
+            notifier = Notifier(connection=None, queues=[])
+            notifier.process(execution)
+
+            if status in LIVEACTION_COMPLETED_STATES:
+                exp = {'status': status,
+                       'start_timestamp': str(liveaction_db.start_timestamp),
+                       'result': {}, 'parameters': {},
+                       'action_ref': u'core.local',
+                       'runner_ref': 'local-shell-cmd',
+                       'execution_id': str(MOCK_EXECUTION.id),
+                       'action_name': u'core.local'}
+                mock_dispatch.assert_called_with('core.st2.generic.actiontrigger',
+                                                 payload=exp, trace_context={})
+
+        self.assertEqual(mock_dispatch.call_count, len(LIVEACTION_COMPLETED_STATES))
+
+    @mock.patch('oslo_config.cfg.CONF.action_sensor', mock.MagicMock(
+        enable=True, emit_when=['scheduled', 'pending', 'abandoned']))
+    @mock.patch.object(Notifier, '_get_runner_ref', mock.MagicMock(
+        return_value='local-shell-cmd'))
+    @mock.patch.object(Notifier, '_get_trace_context', mock.MagicMock(
+        return_value={}))
+    @mock.patch('st2common.transport.reactor.TriggerDispatcher.dispatch')
+    @mock.patch('st2actions.notifier.notifier.LiveAction')
+    @mock.patch('st2actions.notifier.notifier.policy_service.apply_post_run_policies', mock.Mock())
+    def test_process_post_generic_notify_trigger_on_custom_emit_when_states(self,
+            mock_LiveAction, mock_dispatch):
+        # Verify that generic action trigger is posted on all completed states when action sensor
+        # is enabled
+        for status in LIVEACTION_STATUSES:
+            notifier = Notifier(connection=None, queues=[])
+
+            liveaction_db = LiveActionDB(id=bson.ObjectId(), action='core.local')
+            liveaction_db.status = status
+            execution = MOCK_EXECUTION
+            execution.liveaction = vars(LiveActionAPI.from_model(liveaction_db))
+            execution.status = liveaction_db.status
+
+            mock_LiveAction.get_by_id.return_value = liveaction_db
+
+            notifier = Notifier(connection=None, queues=[])
+            notifier.process(execution)
+
+            if status in ['scheduled', 'pending', 'abandoned']:
+                exp = {'status': status,
+                       'start_timestamp': str(liveaction_db.start_timestamp),
+                       'result': {}, 'parameters': {},
+                       'action_ref': u'core.local',
+                       'runner_ref': 'local-shell-cmd',
+                       'execution_id': str(MOCK_EXECUTION.id),
+                       'action_name': u'core.local'}
+                mock_dispatch.assert_called_with('core.st2.generic.actiontrigger',
+                                                 payload=exp, trace_context={})
+
+        self.assertEqual(mock_dispatch.call_count, 3)

st2common/st2common/metrics/drivers/statsd_driver.py

@@ -13,14 +13,28 @@
 # See the License for the specific language governing permissions and
 # limitations under the License.
 
+import socket
+import logging as stdlib_logging
 from numbers import Number
 
 import statsd
 from oslo_config import cfg
 
+from st2common import log as logging
 from st2common.metrics.base import BaseMetricsDriver
 from st2common.metrics.utils import check_key
 from st2common.metrics.utils import get_full_key_name
+from st2common.util.misc import ignore_and_log_exception
+
+
+LOG = logging.getLogger(__name__)
+
+# Which exceptions thrown by statsd library should be considered as non-fatal
+NON_FATAL_EXC_CLASSES = [
+    socket.error,
+    IOError,
+    OSError
+]
 
 __all__ = [
     'StatsdDriver'
@@ -30,11 +44,22 @@
 class StatsdDriver(BaseMetricsDriver):
     """
     StatsD Implementation of the metrics driver
+
+    NOTE: Statsd uses UDP which is "fire and forget" and any kind of send error is not fatal. There
+    is an issue with python-statsd library though which doesn't ignore DNS resolution related errors
+    and bubbles them all the way up.
+
+    This of course breaks the application. Any kind of metric related errors should be considered
+    as non-fatal and not degrade application in any way if an error occurs. That's why we wrap all
+    the statsd library calls here to ignore the errors and just log them.
     """
+
     def __init__(self):
         statsd.Connection.set_defaults(host=cfg.CONF.metrics.host, port=cfg.CONF.metrics.port,
                                        sample_rate=cfg.CONF.metrics.sample_rate)
 
+    @ignore_and_log_exception(exc_classes=NON_FATAL_EXC_CLASSES, logger=LOG,
+                              level=stdlib_logging.WARNING)
     def time(self, key, time):
         """
         Timer metric
@@ -46,6 +71,8 @@ def time(self, key, time):
         timer = statsd.Timer('')
         timer.send(key, time)
 
+    @ignore_and_log_exception(exc_classes=NON_FATAL_EXC_CLASSES, logger=LOG,
+                              level=stdlib_logging.WARNING)
     def inc_counter(self, key, amount=1):
         """
         Increment counter
@@ -57,6 +84,8 @@ def inc_counter(self, key, amount=1):
         counter = statsd.Counter(key)
         counter.increment(delta=amount)
 
+    @ignore_and_log_exception(exc_classes=NON_FATAL_EXC_CLASSES, logger=LOG,
+                              level=stdlib_logging.WARNING)
     def dec_counter(self, key, amount=1):
         """
         Decrement metric
@@ -68,6 +97,8 @@ def dec_counter(self, key, amount=1):
         counter = statsd.Counter(key)
         counter.decrement(delta=amount)
 
+    @ignore_and_log_exception(exc_classes=NON_FATAL_EXC_CLASSES, logger=LOG,
+                              level=stdlib_logging.WARNING)
     def set_gauge(self, key, value):
         """
         Set gauge value.
@@ -79,6 +110,8 @@ def set_gauge(self, key, value):
         gauge = statsd.Gauge(key)
         gauge.send(None, value)
 
+    @ignore_and_log_exception(exc_classes=NON_FATAL_EXC_CLASSES, logger=LOG,
+                              level=stdlib_logging.WARNING)
     def inc_gauge(self, key, amount=1):
         """
         Increment gauge value.
@@ -90,6 +123,8 @@ def inc_gauge(self, key, amount=1):
         gauge = statsd.Gauge(key)
         gauge.increment(None, amount)
 
+    @ignore_and_log_exception(exc_classes=NON_FATAL_EXC_CLASSES, logger=LOG,
+                              level=stdlib_logging.WARNING)
     def dec_gauge(self, key, amount=1):
         """
         Decrement gauge value.

st2common/st2common/middleware/logging.py

@@ -14,16 +14,28 @@
 # limitations under the License.
 
 from __future__ import absolute_import
+
 import time
 import types
 import itertools
 
+from oslo_config import cfg
+
 from st2common.constants.api import REQUEST_ID_HEADER
+from st2common.constants.auth import QUERY_PARAM_ATTRIBUTE_NAME
+from st2common.constants.auth import QUERY_PARAM_API_KEY_ATTRIBUTE_NAME
+from st2common.constants.secrets import MASKED_ATTRIBUTE_VALUE
+from st2common.constants.secrets import MASKED_ATTRIBUTES_BLACKLIST
 from st2common import log as logging
 from st2common.router import Request, NotFoundException
 
 LOG = logging.getLogger(__name__)
 
+SECRET_QUERY_PARAMS = [
+    QUERY_PARAM_ATTRIBUTE_NAME,
+    QUERY_PARAM_API_KEY_ATTRIBUTE_NAME
+] + MASKED_ATTRIBUTES_BLACKLIST
+
 try:
     clock = time.perf_counter
 except AttributeError:
@@ -46,12 +58,20 @@ def __call__(self, environ, start_response):
 
         request = Request(environ)
 
+        query_params = request.GET.dict_of_lists()
+
+        # Mask secret / sensitive query params
+        secret_query_params = SECRET_QUERY_PARAMS + cfg.CONF.log.mask_secrets_blacklist
+        for param_name in secret_query_params:
+            if param_name in query_params:
+                query_params[param_name] = MASKED_ATTRIBUTE_VALUE
+
         # Log the incoming request
         values = {
             'method': request.method,
             'path': request.path,
             'remote_addr': request.remote_addr,
-            'query': request.GET.dict_of_lists(),
+            'query': query_params,
             'request_id': request.headers.get(REQUEST_ID_HEADER, None)
         }