Improve logging

[Karql]

1. Fix reporting warning as error from elastalert PytzUsageWarning alarm #41
2. Fix multiline logs from elastalert
3. Improve logging requeset to elastalert2-server
4. Add possibility to configure bunyan output

[KevinLiangX]

@Karql

hello Karql

About the nodejs log，We have one more scene. we also use the es to store log and index , however ,the nodejs log is not continuous , blank lines and lines break in the log

it also will be showed black lines in es , like below

is any possible make the log continuous ? like below as other component log format

[Karql]

Hi @519859716

Thank you for sugestions.
I will try to find some time to work on it.

[Karql]

Hi @519859716 again!

I found some time and worked over this during the weekend 😉

Done 1 and 2 from issue.

I added parsing logs from elastalert and using dedicaded logger for them.

So now instead:

07:46:27.565Z ERROR elastalert-server:

ProcessService: WARNING:py.warnings:/usr/lib/python3.9/site-packages/APScheduler-3.8.1-...

will be:

07:46:27.565Z WARNING elastalert: elastalert:  ProcessService: WARNING:py.warnings:/usr/lib/python3.9/site-packages/APScheduler-3.8.1-...

Some logs example:

17:42:49.207Z  INFO elastalert-server: Config:  No config.dev.json file was found in /opt/elastalert-server/config/config.dev.json.
17:42:49.210Z  INFO elastalert-server: Config:  A config file was found in /opt/elastalert-server/config/config.json. Using that config.
17:42:49.210Z  INFO elastalert-server: Config:  Found config file.
17:42:49.236Z  INFO elastalert-server: ProcessService:  Starting ElastAlert
17:42:49.237Z  INFO elastalert-server: ProcessService:  Creating index
17:42:50.070Z  INFO elastalert: create_index:  Reading Elastic 6 index mappings: Reading index mapping 'es_mappings/6/silence.json' Reading index mapping 'es_mappings/6/elastalert_status.json' Reading index mapping 'es_mappings/6/elastalert.json' Reading index mapping 'es_mappings/6/past_elastalert.json' Reading index mapping 'es_mappings/6/elastalert_error.json' Index elastalert_status already exists. Skipping index creation.
17:42:50.070Z  INFO elastalert-server: ProcessService:  Index create exited with code 0
17:42:50.070Z  INFO elastalert-server: ProcessService:  Setting ElastAlert debug mode. This will increase the logging verboseness, change all alerts to DebugAlerter, which prints alerts and suppresses their normal action, and skips writing search and alert metadata back to Elasticsearch.
17:42:50.070Z  INFO elastalert-server: ProcessService:  Setting ElastAlert verbose mode. This will increase the logging verboseness, which allows you to see information about the state of queries.
17:42:50.070Z  INFO elastalert-server: ProcessService:  Setting ElastAlert es_debug mode. This will enable logging for all queries made to Elasticsearch.
17:42:50.070Z  INFO elastalert-server: ProcessService:  Starting elastalert with arguments --debug --verbose --es_debug
17:42:50.077Z  INFO elastalert-server: ProcessService:  Started Elastalert (PID: 38)
17:42:50.079Z  INFO elastalert-server: Server:  Server started
17:42:50.080Z  INFO elastalert-server: Server:  Server listening on port 3030
17:42:50.081Z  INFO elastalert-server: Server:  Websocket listening on port 3333
17:42:51.799Z  INFO elastalert: elastalert:  Note: In debug mode, alerts will be logged to console but NOT actually sent.  To send them but remain verbose, use --verbose instead.
17:42:51.805Z  INFO elastalert: elastalert:  Note: --debug and --verbose flags are set. --debug takes precedent.
17:42:51.805Z  INFO elastalert: elastalert:  Note: In debug mode, alerts will be logged to console but NOT actually sent.  To send them but remain verbose, use --verbose instead.
17:42:52.066Z  INFO elastalert: elastalert:  Starting up
17:42:52.067Z  INFO elastalert: elastalert:  Disabled rules are: []
17:42:52.067Z  INFO elastalert: elastalert:  Sleeping for 59.999849 seconds
17:42:52.087Z  INFO elastalert: elastalert:  Queried rule Spike in attacks on server from 2022-01-08 06:25 UTC to 2022-01-08 06:30 UTC: 0 / 0 hits
17:42:52.092Z  INFO elastalert: elastalert:  Queried rule Spike in attacks on server from 2022-01-08 06:30 UTC to 2022-01-08 06:35 UTC: 0 / 0 hits
17:42:52.097Z  INFO elastalert: elastalert:  Queried rule Spike in attacks on server from 2022-01-08 06:35 UTC to 2022-01-08 06:40 UTC: 0 / 0 hits

After level (INFO, ERROR etc.) there is logger type: elastalert-server or elastalert.
After logger type is service like ProcessService, RulesService etc. for elastalert-server or elastalert, elasticsearch, elasticsearch.trace etc. form here: https://github.com/jertel/elastalert2/blob/b8e52e91efc7db147a36b965eb6645d25b03487e/examples/config.yaml.example#L106

Please try new version: karql/elastalert2-server:5.0.0-next.2 and let me know what do you think.

btw. you can replace scritps/start.sh (e.g. by docker volume) and remove | ./node_modules/.bin/bunyan -o short to get logs in structured form:

Point 4 is about that. I will add possibility to configure it.

I don't close this issue becasue 3 and 4 remain to be done.

[nsano-rururu]

I think you should check what the log looks like when an exception occurs as shown below.

Below is an example of an error that occurred in elastalert 0.2.4

root@Lab-ELK:/etc/elastalert# python3.8 -m elastalert.elastalert --verbose --rule sshtele.yaml
Traceback (most recent call last):
  File "/usr/lib/python3.8/runpy.py", line 194, in _run_module_as_main
    return _run_code(code, main_globals, None,
  File "/usr/lib/python3.8/runpy.py", line 87, in _run_code
    exec(code, run_globals)
  File "/etc/elastalert/elastalert/elastalert.py", line 30, in <module>
    from .alerts import DebugAlerter
  File "/etc/elastalert/elastalert/alerts.py", line 26, in <module>
    from jira.client import JIRA
  File "/usr/local/lib/python3.8/dist-packages/jira/__init__.py", line 10, in <module>
    from jira.client import Comment  # noqa: E402
  File "/usr/local/lib/python3.8/dist-packages/jira/client.py", line 225
    validate=False, get_server_info=True, async=False, logging=True, max_retries=3, proxies=None,
                                          ^
SyntaxError: invalid syntax

[nsano-rururu]

I tried setting the value of slack_timeout to a string instead of a number

[CORP\sano@a-ngft53r34ong elastalert2-server]$ docker run -d -p 3030:3030 -p 3333:3333 \
>     -v `pwd`/config/elastalert.yaml:/opt/elastalert/config.yaml \
>     -v `pwd`/config/elastalert-test.yaml:/opt/elastalert/config-test.yaml \
>     -v `pwd`/config/config.json:/opt/elastalert-server/config/config.json \
>     -v `pwd`/rules:/opt/elastalert/rules \
>     -v `pwd`/rule_templates:/opt/elastalert/rule_templates \
>     --net="host" \
>     --name elastalert2-server karql/elastalert2-server:latest
WARNING: Published ports are discarded when using host network mode
af4e306b5095972305ef36420d43392e9cd9af61fdc661f68caedacf100df11b
[CORP\sano@a-ngft53r34ong elastalert2-server]$ docker logs -f elastalert2-server

> elastalert2-server@5.0.0-next.2 start /opt/elastalert-server
> sh ./scripts/start.sh

04:05:57.244Z  INFO elastalert-server: Config:  No config.dev.json file was found in /opt/elastalert-server/config/config.dev.json.
04:05:57.246Z  INFO elastalert-server: Config:  A config file was found in /opt/elastalert-server/config/config.json. Using that config.
04:05:57.246Z  INFO elastalert-server: Config:  Found config file.
04:05:57.262Z  INFO elastalert-server: ProcessService:  Starting ElastAlert
04:05:57.262Z  INFO elastalert-server: ProcessService:  Creating index
04:05:58.365Z  INFO elastalert: create_index:  Reading Elastic 6 index mappings: Reading index mapping 'es_mappings/6/silence.json' Reading index mapping 'es_mappings/6/elastalert_status.json' Reading index mapping 'es_mappings/6/elastalert.json' Reading index mapping 'es_mappings/6/past_elastalert.json' Reading index mapping 'es_mappings/6/elastalert_error.json' Index elastalert_status already exists. Skipping index creation.
04:05:58.365Z  INFO elastalert-server: ProcessService:  Index create exited with code 0
04:05:58.365Z  INFO elastalert-server: ProcessService:  Starting elastalert with arguments [none]
04:05:58.373Z  INFO elastalert-server: ProcessService:  Started Elastalert (PID: 40)
04:05:58.375Z  INFO elastalert-server: Server:  Server started
04:05:58.376Z  INFO elastalert-server: Server:  Server listening on port 3030
04:05:58.378Z  INFO elastalert-server: Server:  Websocket listening on port 3333
04:06:01.062Z  WARN elastalert-server:
    ProcessService:  No matches while process elastalert log: Traceback (most recent call last):
      File "/opt/elastalert/elastalert/loaders.py", line 277, in load_options
    
04:06:01.064Z  WARN elastalert-server:
    ProcessService:  No matches while process elastalert log:     self.rule_schema.validate(rule)
      File "/usr/lib/python3.9/site-packages/jsonschema-4.3.3-py3.9.egg/jsonschema/validators.py", line 251, in validate
        raise error
    jsonschema.exceptions.ValidationError: '10' is not of type 'integer'
    
    Failed validating 'type' in schema['properties']['slack_timeout']:
        {'type': 'integer'}
    
    On instance['slack_timeout']:
        '10'
    
    During handling of the above exception, another exception occurred:
    
    Traceback (most recent call last):
      File "/opt/elastalert/elastalert/loaders.py", line 162, in load
        rule = self.load_configuration(rule_file, conf, args)
      File "/opt/elastalert/elastalert/loaders.py", line 224, in load_configuration
        self.load_options(rule, conf, filename, args)
      File "/opt/elastalert/elastalert/loaders.py", line 279, in load_options
        raise EAException("Invalid Rule file: %s\n%s" % (filename, e))
    elastalert.util.EAException: Invalid Rule file: rules/a.yaml
    '10' is not of type 'integer'
    
    Failed validating 'type' in schema['properties']['slack_timeout']:
        {'type': 'integer'}
    
    On instance['slack_timeout']:
        '10'
    
    During handling of the above exception, another exception occurred:
    
    Traceback (most recent call last):
      File "/usr/lib/python3.9/runpy.py", line 197, in _run_module_as_main
        return _run_code(code, main_globals, None,
      File "/usr/lib/python3.9/runpy.py", line 87, in _run_code
        exec(code, run_globals)
      File "/opt/elastalert/elastalert/elastalert.py", line 2166, in <module>
        sys.exit(main(sys.argv[1:]))
      File "/opt/elastalert/elastalert/elastalert.py", line 2155, in main
        client = ElastAlerter(args)
      File "/opt/elastalert/elastalert/elastalert.py", line 128, in __init__
        self.rules = self.rules_loader.load(self.conf, self.args)
      File "/opt/elastalert/elastalert/loaders.py", line 170, in load
        raise EAException('Error loading file %s: %s' % (rule_file, e))
    elastalert.util.EAException: Error loading file rules/a.yaml: Invalid Rule file: rules/a.yaml
    '10' is not of type 'integer'
    
    Failed validating 'type' in schema['properties']['slack_timeout']:
        {'type': 'integer'}
    
    On instance['slack_timeout']:
        '10'
    
04:06:01.242Z ERROR elastalert-server: ProcessService:  ElastAlert exited with code 1
04:06:01.242Z  INFO elastalert-server: Server:  Stopping server
04:06:01.242Z  INFO elastalert-server: ProcessService:  ElastAlert is not running
04:06:01.243Z  INFO elastalert-server: Server:  Server stopped. Bye!
[CORP\sano@a-ngft53r34ong elastalert2-server]$