Merge pull request #407 from perceptron01/selectable-pretty-ts-format

Allowing users to customize timestamp format printed by pretty_ts() function

CHANGELOG.md

@@ -23,6 +23,7 @@
 - Add support for Kibana 7.14 for Kibana Discover - [#392](https://github.com/jertel/elastalert2/pull/392) - @nsano-rururu
 - Add metric_format_string optional configuration for Metric Aggregation to format aggregated value - [#399](https://github.com/jertel/elastalert2/pull/399) - @iamxeph
 - Make percentage_format_string support format() syntax in addition to old %-formatted syntax - [#403](https://github.com/jertel/elastalert2/pull/403) - @iamxeph
+- Add custom_pretty_ts_format option to provides a way to define custom format of timestamps printed by pretty_ts() function - [#407](https://github.com/jertel/elastalert2/pull/407) - @perceptron01
 
 ## Other changes
 - [Tests] Improve test code coverage - [#331](https://github.com/jertel/elastalert2/pull/331) - @nsano-rururu

docs/source/elastalert.rst

@@ -230,6 +230,15 @@ The default value is ``.raw`` for Elasticsearch 2 and ``.keyword`` for Elasticse
 
 ``jinja_template_path``: When using a Jinja template, specify filesystem path to template, this overrides the default behaviour of using alert_text as the template.
 
+``custom_pretty_ts_format``: This option provides a way to define custom format of timestamps printed in log messages and in alert messages.
+If this option is not set, default timestamp format ('%Y-%m-%d %H:%M %Z') will be used. (Optional, string, default None)
+
+Example usage and resulting formatted timestamps::
+
+    (not set; default)                               -> '2021-08-16 21:38 JST'
+    custom_pretty_ts_format: '%Y-%m-%d %H:%M %z'     -> '2021-08-16 21:38 +0900'
+    custom_pretty_ts_format: '%Y-%m-%d %H:%M'        -> '2021-08-16 21:38'
+
 Logging
 -------
 

elastalert/config.py

@@ -78,6 +78,7 @@ def load_conf(args, defaults=None, overwrites=None):
     conf.setdefault('disable_rules_on_error', True)
     conf.setdefault('scan_subdirectories', True)
     conf.setdefault('rules_loader', 'file')
+    conf.setdefault('custum_pretty_ts_format', None)
 
     # Convert run_every, buffer_time into a timedelta object
     try:

elastalert/elastalert.py

@@ -167,6 +167,7 @@ def __init__(self, args):
         self.add_metadata_alert = self.conf.get('add_metadata_alert', False)
         self.prometheus_port = self.args.prometheus_port
         self.show_disabled_rules = self.conf.get('show_disabled_rules', True)
+        self.pretty_ts_format = self.conf['custom_pretty_ts_format']
 
         self.writeback_es = elasticsearch_client(self.conf)
 
@@ -419,8 +420,8 @@ def get_hits(self, rule, starttime, endtime, index, scroll=False):
         lt = rule.get('use_local_time')
         status_log = "Queried rule %s from %s to %s: %s / %s hits" % (
             rule['name'],
-            pretty_ts(starttime, lt),
-            pretty_ts(endtime, lt),
+            pretty_ts(starttime, lt, self.pretty_ts_format),
+            pretty_ts(endtime, lt, self.pretty_ts_format),
             self.thread_data.num_hits,
             len(hits)
         )
@@ -482,7 +483,8 @@ def get_hits_count(self, rule, starttime, endtime, index):
         self.thread_data.num_hits += res['count']
         lt = rule.get('use_local_time')
         elastalert_logger.info(
-            "Queried rule %s from %s to %s: %s hits" % (rule['name'], pretty_ts(starttime, lt), pretty_ts(endtime, lt), res['count'])
+            "Queried rule %s from %s to %s: %s hits" % (rule['name'], pretty_ts(starttime, lt, self.pretty_ts_format),
+                                                        pretty_ts(endtime, lt, self.pretty_ts_format), res['count'])
         )
         return {endtime: res['count']}
 
@@ -552,7 +554,9 @@ def get_hits_terms(self, rule, starttime, endtime, index, key, qk=None, size=Non
         self.thread_data.num_hits += len(buckets)
         lt = rule.get('use_local_time')
         elastalert_logger.info(
-            'Queried rule %s from %s to %s: %s buckets' % (rule['name'], pretty_ts(starttime, lt), pretty_ts(endtime, lt), len(buckets))
+            'Queried rule %s from %s to %s: %s buckets' % (
+            rule['name'], pretty_ts(starttime, lt, self.pretty_ts_format),
+            pretty_ts(endtime, lt, self.pretty_ts_format), len(buckets))
         )
         return {endtime: buckets}
 
@@ -1299,13 +1303,14 @@ def run_all_rules(self):
     def handle_pending_alerts(self):
         self.thread_data.alerts_sent = 0
         self.send_pending_alerts()
-        elastalert_logger.info("Background alerts thread %s pending alerts sent at %s" % (self.thread_data.alerts_sent,
-                                                                                          pretty_ts(ts_now())))
+        elastalert_logger.info("Background alerts thread %s pending alerts sent at %s" % (
+            self.thread_data.alerts_sent, pretty_ts(ts_now(), ts_format=self.pretty_ts_format)))
 
     def handle_config_change(self):
         if not self.args.pin_rules:
             self.load_rule_changes()
-            elastalert_logger.info("Background configuration change check run at %s" % (pretty_ts(ts_now())))
+            elastalert_logger.info(
+                "Background configuration change check run at %s" % (pretty_ts(ts_now(), ts_format=self.pretty_ts_format)))
 
     def handle_rule_execution(self, rule):
         self.thread_data.alerts_sent = 0
@@ -1347,10 +1352,13 @@ def handle_rule_execution(self, rule):
         except Exception as e:
             self.handle_uncaught_exception(e, rule)
         else:
-            old_starttime = pretty_ts(rule.get('original_starttime'), rule.get('use_local_time'))
+            old_starttime = pretty_ts(rule.get('original_starttime'), rule.get('use_local_time'), self.pretty_ts_format)
             elastalert_logger.info("Ran %s from %s to %s: %s query hits (%s already seen), %s matches,"
-                                   " %s alerts sent" % (rule['name'], old_starttime, pretty_ts(endtime, rule.get('use_local_time')),
-                                                        self.thread_data.num_hits, self.thread_data.num_dupes, num_matches,
+                                   " %s alerts sent" % (rule['name'], old_starttime,
+                                                        pretty_ts(endtime, rule.get('use_local_time'),
+                                                                  self.pretty_ts_format),
+                                                        self.thread_data.num_hits, self.thread_data.num_dupes,
+                                                        num_matches,
                                                         self.thread_data.alerts_sent))
             rule_duration = seconds(endtime - rule.get('original_starttime'))
             elastalert_logger.info("%s range %s" % (rule['name'], rule_duration))
@@ -1364,7 +1372,7 @@ def handle_rule_execution(self, rule):
                 elastalert_logger.warning(
                     "Querying from %s to %s took longer than %s!" % (
                         old_starttime,
-                        pretty_ts(endtime, rule.get('use_local_time')),
+                        pretty_ts(endtime, rule.get('use_local_time'), self.pretty_ts_format),
                         self.run_every
                     )
                 )
@@ -1383,7 +1391,8 @@ def reset_rule_schedule(self, rule):
             if rule['next_min_starttime']:
                 rule['minimum_starttime'] = rule['next_min_starttime']
                 rule['previous_endtime'] = rule['next_min_starttime']
-            elastalert_logger.info('Pausing %s until next run at %s' % (rule['name'], pretty_ts(rule['next_starttime'])))
+            elastalert_logger.info('Pausing %s until next run at %s' % (
+            rule['name'], pretty_ts(rule['next_starttime'], ts_format=self.pretty_ts_format)))
 
     def stop(self):
         """ Stop an ElastAlert runner that's been started """

elastalert/ruletypes.py

@@ -272,9 +272,10 @@ def garbage_collect(self, timestamp):
 
     def get_match_str(self, match):
         lt = self.rules.get('use_local_time')
+        fmt = self.rules.get('custom_pretty_ts_format')
         match_ts = lookup_es_key(match, self.ts_field)
-        starttime = pretty_ts(dt_to_ts(ts_to_dt(match_ts) - self.rules['timeframe']), lt)
-        endtime = pretty_ts(match_ts, lt)
+        starttime = pretty_ts(dt_to_ts(ts_to_dt(match_ts) - self.rules['timeframe']), lt, fmt)
+        endtime = pretty_ts(match_ts, lt, fmt)
         message = 'At least %d events occurred between %s and %s\n\n' % (self.rules['num_events'],
                                                                          starttime,
                                                                          endtime)
@@ -543,15 +544,16 @@ def get_match_str(self, match):
         if self.field_value is None:
             message = 'An abnormal number (%d) of events occurred around %s.\n' % (
                 match['spike_count'],
-                pretty_ts(match[self.rules['timestamp_field']], self.rules.get('use_local_time'))
+                pretty_ts(match[self.rules['timestamp_field']], self.rules.get('use_local_time'), self.rules.get('custom_pretty_ts_format'))
             )
             message += 'Preceding that time, there were only %d events within %s\n\n' % (match['reference_count'], self.rules['timeframe'])
         else:
             message = 'An abnormal average value (%.2f) of field \'%s\' occurred around %s.\n' % (
                 match['spike_count'],
                 self.field_value,
                 pretty_ts(match[self.rules['timestamp_field']],
-                          self.rules.get('use_local_time'))
+                          self.rules.get('use_local_time'),
+                          self.rules.get('custom_pretty_ts_format'))
             )
             message += 'Preceding that time, the field had an average value of (%.2f) within %s\n\n' % (
                 match['reference_count'], self.rules['timeframe'])
@@ -621,10 +623,11 @@ def check_for_match(self, key, end=True):
     def get_match_str(self, match):
         ts = match[self.rules['timestamp_field']]
         lt = self.rules.get('use_local_time')
-        message = 'An abnormally low number of events occurred around %s.\n' % (pretty_ts(ts, lt))
+        fmt = self.rules.get('custom_pretty_ts_format')
+        message = 'An abnormally low number of events occurred around %s.\n' % (pretty_ts(ts, lt, fmt))
         message += 'Between %s and %s, there were less than %s events.\n\n' % (
-            pretty_ts(dt_to_ts(ts_to_dt(ts) - self.rules['timeframe']), lt),
-            pretty_ts(ts, lt),
+            pretty_ts(dt_to_ts(ts_to_dt(ts) - self.rules['timeframe']), lt, fmt),
+            pretty_ts(ts, lt, fmt),
             self.rules['threshold']
         )
         return message
@@ -980,8 +983,9 @@ def garbage_collect(self, timestamp):
 
     def get_match_str(self, match):
         lt = self.rules.get('use_local_time')
-        starttime = pretty_ts(dt_to_ts(ts_to_dt(lookup_es_key(match, self.ts_field)) - self.rules['timeframe']), lt)
-        endtime = pretty_ts(lookup_es_key(match, self.ts_field), lt)
+        fmt = self.rules.get('custom_pretty_ts_format')
+        starttime = pretty_ts(dt_to_ts(ts_to_dt(lookup_es_key(match, self.ts_field)) - self.rules['timeframe']), lt, fmt)
+        endtime = pretty_ts(lookup_es_key(match, self.ts_field), lt, fmt)
         if 'max_cardinality' in self.rules:
             message = ('A maximum of %d unique %s(s) occurred since last alert or between %s and %s\n\n' % (self.rules['max_cardinality'],
                                                                                                             self.rules['cardinality_field'],
@@ -1228,7 +1232,7 @@ def get_match_str(self, match):
         """
         message = 'An abnormal {0} of {1} ({2}) occurred around {3}.\n'.format(
             self.rules['metric_agg_type'], self.rules['metric_agg_key'], round(match['spike_count'], 2),
-            pretty_ts(match[self.rules['timestamp_field']], self.rules.get('use_local_time'))
+            pretty_ts(match[self.rules['timestamp_field']], self.rules.get('use_local_time'), self.rules.get('custom_pretty_ts_format'))
         )
         message += 'Preceding that time, there was a {0} of {1} of ({2}) within {3}\n\n'.format(
             self.rules['metric_agg_type'], self.rules['metric_agg_key'],
@@ -1301,4 +1305,4 @@ def percentage_violation(self, match_percentage):
             return True
         if 'min_percentage' in self.rules and match_percentage < self.rules['min_percentage']:
             return True
-        return False
+        return False

elastalert/schema.yaml

@@ -235,6 +235,7 @@ properties:
   kibana_dashboard: {type: string}
   use_kibana_dashboard: {type: string}
   use_local_time: {type: boolean}
+  custom_pretty_ts_format: {type: string}
   match_enhancements: {type: array, items: {type: string}}
   query_key: *arrayOfString
   replace_dots_in_field_names: {type: boolean}

elastalert/util.py

@@ -199,7 +199,7 @@ def inc_ts(timestamp, milliseconds=1):
     return dt_to_ts(dt)
 
 
-def pretty_ts(timestamp, tz=True):
+def pretty_ts(timestamp, tz=True, ts_format=None):
     """Pretty-format the given timestamp (to be printed or logged hereafter).
     If tz, the timestamp will be converted to local time.
     Format: YYYY-MM-DD HH:MM TZ"""
@@ -208,7 +208,10 @@ def pretty_ts(timestamp, tz=True):
         dt = ts_to_dt(timestamp)
     if tz:
         dt = dt.astimezone(dateutil.tz.tzlocal())
-    return dt.strftime('%Y-%m-%d %H:%M %z')
+    if ts_format is None:
+        return dt.strftime('%Y-%m-%d %H:%M %Z')
+    else:
+        return dt.strftime(ts_format)
 
 
 def ts_add(ts, td):

examples/config.yaml.example

@@ -72,6 +72,10 @@ writeback_index: elastalert_status
 alert_time_limit:
   days: 2
 
+# Optional timestamp format.
+# ElastAlert will print timestamps in alert messages and in log messages using this format.
+#custom_pretty_ts_format: '%Y-%m-%d %H:%M'
+
 # Custom logging configuration
 # If you want to setup your own logging configuration to log into
 # files as well or to Logstash and/or modify log levels, use

tests/base_test.py

@@ -1463,5 +1463,5 @@ def test_time_enhancement(ea):
         'somefield': 'foobarbaz'
     }
     te.process(match)
-    excepted = '2021-01-01 00:00 +0000'
+    excepted = '2021-01-01 00:00 UTC'
     assert match['@timestamp'] == excepted

tests/conftest.py

@@ -170,7 +170,8 @@ def ea():
             'max_query_size': 10000,
             'old_query_limit': datetime.timedelta(weeks=1),
             'disable_rules_on_error': False,
-            'scroll_keepalive': '30s'}
+            'scroll_keepalive': '30s',
+            'custom_pretty_ts_format': '%Y-%m-%d %H:%M'}
     elastalert.util.elasticsearch_client = mock_es_client
     conf['rules_loader'] = mock_rule_loader(conf)
     elastalert.elastalert.elasticsearch_client = mock_es_client
@@ -223,7 +224,8 @@ def ea_sixsix():
             'max_query_size': 10000,
             'old_query_limit': datetime.timedelta(weeks=1),
             'disable_rules_on_error': False,
-            'scroll_keepalive': '30s'}
+            'scroll_keepalive': '30s',
+            'custom_pretty_ts_format': '%Y-%m-%d %H:%M'}
     conf['rules_loader'] = mock_rule_loader(conf)
     elastalert.elastalert.elasticsearch_client = mock_es_sixsix_client
     elastalert.util.elasticsearch_client = mock_es_sixsix_client

tests/util_test.py

@@ -36,6 +36,7 @@
 from elastalert.util import expand_string_into_dict
 from elastalert.util import unixms_to_dt
 from elastalert.util import format_string
+from elastalert.util import pretty_ts
 
 
 @pytest.mark.parametrize('spec, expected_delta', [
@@ -511,3 +512,10 @@ def test_format_string():
     assert format_string('%.2f', target) == expected_percent_formatting
     expected_str_formatting = '96.67%'
     assert format_string('{:.2%}', target) == expected_str_formatting
+
+
+def test_pretty_ts():
+    ts = datetime(year=2021, month=8, day=16, hour=16, minute=35, second=5)
+    assert '2021-08-16 16:35 UTC' == pretty_ts(ts)
+    assert '2021-08-16 16:35 ' == pretty_ts(ts, False)
+    assert '2021-08-16 16:35 +0000' == pretty_ts(ts, ts_format='%Y-%m-%d %H:%M %z')