Log non-fatal errors during service bootstrap phase under DEBUG instead of ERROR #4630

Kami · 2019-04-10T11:53:31Z

This pull request updates the code to log non-fatal errors under DEBUG log level instead of ERROR.

Previously we logged those under ERROR which caused a lot of unnecessary confusion.

Background, Context

During service bootstrap phase and when running register content script we register internal trigger types (among other things).

This operation is idempotent and as such, some of the possible errors (not unique and object already exists error) are non-fatal. An error represents a non-fatal race which just means that a particular trigger has already been registered by a different service / process.

NOTE: Adding tests for that would be hard. We would need to replicate the race which means spawning multiple processes (using multiple eventlets won't work here, we need real parallelism to replicate it) and ensure tests run on multi core / CPU server...

Resolves #3933.

Output

Before:

$ sudo st2ctl reload --register-rules
Registering content...[flags = --config-file /etc/st2/st2.conf --register-rules]
2019-04-10 11:23:21,171 INFO [-] Connecting to database "st2" @ "127.0.0.1:27017" as user "None".
2019-04-10 11:23:21,174 INFO [-] Successfully connected to database "st2" @ "127.0.0.1:27017" as user "None".
2019-04-10 11:23:21,329 ERROR [-] Conflict while trying to save in DB.
Traceback (most recent call last):
  File "/opt/stackstorm/st2/local/lib/python2.7/site-packages/st2common/persistence/base.py", line 174, in add_or_update
    model_object = cls._get_impl().add_or_update(model_object, validate=True)
  File "/opt/stackstorm/st2/local/lib/python2.7/site-packages/st2common/models/db/__init__.py", line 452, in add_or_update
    instance.save(validate=validate)
  File "/opt/stackstorm/st2/local/lib/python2.7/site-packages/mongoengine/document.py", line 405, in save
    raise NotUniqueError(message % six.text_type(err))
NotUniqueError: Tried to save duplicate unique keys (E11000 duplicate key error collection: st2.trigger_type_d_b index: uid_1 dup key: { : "trigger_type:core:st2.generic.actiontrigger" })
2019-04-10 11:23:21,379 ERROR [-] Conflict while trying to save in DB.
Traceback (most recent call last):
  File "/opt/stackstorm/st2/local/lib/python2.7/site-packages/st2common/persistence/base.py", line 174, in add_or_update
    model_object = cls._get_impl().add_or_update(model_object, validate=True)
  File "/opt/stackstorm/st2/local/lib/python2.7/site-packages/st2common/models/db/__init__.py", line 452, in add_or_update
    instance.save(validate=validate)
  File "/opt/stackstorm/st2/local/lib/python2.7/site-packages/mongoengine/document.py", line 405, in save
    raise NotUniqueError(message % six.text_type(err))
NotUniqueError: Tried to save duplicate unique keys (E11000 duplicate key error collection: st2.trigger_type_d_b index: uid_1 dup key: { : "trigger_type:core:st2.generic.notifytrigger" })
2019-04-10 11:23:21,391 ERROR [-] Conflict while trying to save in DB.
Traceback (most recent call last):
  File "/opt/stackstorm/st2/local/lib/python2.7/site-packages/st2common/persistence/base.py", line 174, in add_or_update
    model_object = cls._get_impl().add_or_update(model_object, validate=True)
  File "/opt/stackstorm/st2/local/lib/python2.7/site-packages/st2common/models/db/__init__.py", line 452, in add_or_update
    instance.save(validate=validate)
  File "/opt/stackstorm/st2/local/lib/python2.7/site-packages/mongoengine/document.py", line 405, in save
    raise NotUniqueError(message % six.text_type(err))
NotUniqueError: Tried to save duplicate unique keys (E11000 duplicate key error collection: st2.trigger_type_d_b index: uid_1 dup key: { : "trigger_type:core:st2.action.file_writen" })
2019-04-10 11:23:21,404 ERROR [-] Conflict while trying to save in DB.
Traceback (most recent call last):
  File "/opt/stackstorm/st2/local/lib/python2.7/site-packages/st2common/persistence/base.py", line 174, in add_or_update
    model_object = cls._get_impl().add_or_update(model_object, validate=True)
  File "/opt/stackstorm/st2/local/lib/python2.7/site-packages/st2common/models/db/__init__.py", line 452, in add_or_update
    instance.save(validate=validate)
  File "/opt/stackstorm/st2/local/lib/python2.7/site-packages/mongoengine/document.py", line 405, in save
    raise NotUniqueError(message % six.text_type(err))
NotUniqueError: Tried to save duplicate unique keys (E11000 duplicate key error collection: st2.trigger_type_d_b index: uid_1 dup key: { : "trigger_type:core:st2.generic.inquiry" })
2019-04-10 11:23:21,417 ERROR [-] Conflict while trying to save in DB.
Traceback (most recent call last):
  File "/opt/stackstorm/st2/local/lib/python2.7/site-packages/st2common/persistence/base.py", line 174, in add_or_update
    model_object = cls._get_impl().add_or_update(model_object, validate=True)
  File "/opt/stackstorm/st2/local/lib/python2.7/site-packages/st2common/models/db/__init__.py", line 452, in add_or_update
    instance.save(validate=validate)
  File "/opt/stackstorm/st2/local/lib/python2.7/site-packages/mongoengine/document.py", line 405, in save
    raise NotUniqueError(message % six.text_type(err))
NotUniqueError: Tried to save duplicate unique keys (E11000 duplicate key error collection: st2.trigger_type_d_b index: uid_1 dup key: { : "trigger_type:core:st2.key_value_pair.create" })
2019-04-10 11:23:21,429 ERROR [-] Conflict while trying to save in DB.
Traceback (most recent call last):
  File "/opt/stackstorm/st2/local/lib/python2.7/site-packages/st2common/persistence/base.py", line 174, in add_or_update
    model_object = cls._get_impl().add_or_update(model_object, validate=True)
  File "/opt/stackstorm/st2/local/lib/python2.7/site-packages/st2common/models/db/__init__.py", line 452, in add_or_update
    instance.save(validate=validate)
  File "/opt/stackstorm/st2/local/lib/python2.7/site-packages/mongoengine/document.py", line 405, in save
    raise NotUniqueError(message % six.text_type(err))
NotUniqueError: Tried to save duplicate unique keys (E11000 duplicate key error collection: st2.trigger_type_d_b index: uid_1 dup key: { : "trigger_type:core:st2.key_value_pair.update" })
2019-04-10 11:23:21,441 ERROR [-] Conflict while trying to save in DB.
Traceback (most recent call last):
  File "/opt/stackstorm/st2/local/lib/python2.7/site-packages/st2common/persistence/base.py", line 174, in add_or_update
    model_object = cls._get_impl().add_or_update(model_object, validate=True)
  File "/opt/stackstorm/st2/local/lib/python2.7/site-packages/st2common/models/db/__init__.py", line 452, in add_or_update
    instance.save(validate=validate)
  File "/opt/stackstorm/st2/local/lib/python2.7/site-packages/mongoengine/document.py", line 405, in save
    raise NotUniqueError(message % six.text_type(err))
NotUniqueError: Tried to save duplicate unique keys (E11000 duplicate key error collection: st2.trigger_type_d_b index: uid_1 dup key: { : "trigger_type:core:st2.key_value_pair.value_change" })
2019-04-10 11:23:21,453 ERROR [-] Conflict while trying to save in DB.
Traceback (most recent call last):
  File "/opt/stackstorm/st2/local/lib/python2.7/site-packages/st2common/persistence/base.py", line 174, in add_or_update
    model_object = cls._get_impl().add_or_update(model_object, validate=True)
  File "/opt/stackstorm/st2/local/lib/python2.7/site-packages/st2common/models/db/__init__.py", line 452, in add_or_update
    instance.save(validate=validate)
  File "/opt/stackstorm/st2/local/lib/python2.7/site-packages/mongoengine/document.py", line 405, in save
    raise NotUniqueError(message % six.text_type(err))
NotUniqueError: Tried to save duplicate unique keys (E11000 duplicate key error collection: st2.trigger_type_d_b index: uid_1 dup key: { : "trigger_type:core:st2.key_value_pair.delete" })
2019-04-10 11:23:21,465 ERROR [-] Conflict while trying to save in DB.
Traceback (most recent call last):
  File "/opt/stackstorm/st2/local/lib/python2.7/site-packages/st2common/persistence/base.py", line 174, in add_or_update
    model_object = cls._get_impl().add_or_update(model_object, validate=True)
  File "/opt/stackstorm/st2/local/lib/python2.7/site-packages/st2common/models/db/__init__.py", line 452, in add_or_update
    instance.save(validate=validate)
  File "/opt/stackstorm/st2/local/lib/python2.7/site-packages/mongoengine/document.py", line 405, in save
    raise NotUniqueError(message % six.text_type(err))
NotUniqueError: Tried to save duplicate unique keys (E11000 duplicate key error collection: st2.trigger_type_d_b index: uid_1 dup key: { : "trigger_type:core:st2.sensor.process_spawn" })
2019-04-10 11:23:21,478 ERROR [-] Conflict while trying to save in DB.
Traceback (most recent call last):
  File "/opt/stackstorm/st2/local/lib/python2.7/site-packages/st2common/persistence/base.py", line 174, in add_or_update
    model_object = cls._get_impl().add_or_update(model_object, validate=True)
  File "/opt/stackstorm/st2/local/lib/python2.7/site-packages/st2common/models/db/__init__.py", line 452, in add_or_update
    instance.save(validate=validate)
  File "/opt/stackstorm/st2/local/lib/python2.7/site-packages/mongoengine/document.py", line 405, in save
    raise NotUniqueError(message % six.text_type(err))
NotUniqueError: Tried to save duplicate unique keys (E11000 duplicate key error collection: st2.trigger_type_d_b index: uid_1 dup key: { : "trigger_type:core:st2.sensor.process_exit" })
2019-04-10 11:23:21,486 INFO [-] =========================================================
2019-04-10 11:23:21,486 INFO [-] ############## Registering rules ########################
2019-04-10 11:23:21,486 INFO [-] =========================================================
2019-04-10 11:23:23,165 INFO [-] Registered 76 rules.

After (as you can see, the error is only logged under debug when --verbose flag is used):

$ sudo st2ctl reload --register-rules
Registering content...[flags = --config-file /etc/st2/st2.conf --register-rules]
2019-04-10 11:40:56,815 INFO [-] Connecting to database "st2" @ "127.0.0.1:27017" as user "None".
2019-04-10 11:40:56,818 INFO [-] Successfully connected to database "st2" @ "127.0.0.1:27017" as user "None".
2019-04-10 11:40:57,000 INFO [-] =========================================================
2019-04-10 11:40:57,000 INFO [-] ############## Registering rules ########################
2019-04-10 11:40:57,000 INFO [-] =========================================================
2019-04-10 11:40:58,634 INFO [-] Registered 76 rules.

$ sudo st2ctl reload --register-rules --verbose
Registering content...[flags = --config-file /etc/st2/st2.conf --register-rules --verbose]
2019-04-10 11:46:46,135 INFO [-] Connecting to database "st2" @ "127.0.0.1:27017" as user "None".
2019-04-10 11:46:46,139 INFO [-] Successfully connected to database "st2" @ "127.0.0.1:27017" as user "None".
2019-04-10 11:46:46,139 DEBUG [-] Ensuring database indexes...
....
2019-04-10 11:46:46,239 DEBUG [-] Registering internal trigger: st2.generic.actiontrigger
2019-04-10 11:46:46,242 DEBUG [-] verified trigger and formulated TriggerDB=TriggerTypeDB(description="Trigger encapsulating the completion of an action execution.", id=None, metadata_file=None, name="st2.generic.actiontrigger", pack="core", parameters_schema={}, payload_schema={'type': 'object', 'properties': {'status': {}, 'start_timestamp': {}, 'parameters': {}, 'runner_ref': {}, 'action_name': {}, 'result': {}, 'action_ref': {}, 'execution_id': {}}}, ref="core.st2.generic.actiontrigger", tags=[], uid="trigger_type:core:st2.generic.actiontrigger")
2019-04-10 11:46:46,244 DEBUG [-] Conflict while trying to save in DB: Tried to save duplicate unique keys (E11000 duplicate key error collection: st2.trigger_type_d_b index: uid_1 dup key: { : "trigger_type:core:st2.generic.actiontrigger" }).
2019-04-10 11:46:46,246 DEBUG [-] Internal trigger type "st2.generic.actiontrigger" already exists, ignoring...
Traceback (most recent call last):
  File "/opt/stackstorm/st2/local/lib/python2.7/site-packages/st2common/triggers.py", line 42, in _register_internal_trigger_type
    log_not_unique_error_as_debug=True)
  File "/opt/stackstorm/st2/local/lib/python2.7/site-packages/st2common/services/triggers.py", line 362, in create_trigger_type_db
    log_not_unique_error_as_debug=log_not_unique_error_as_debug)
  File "/opt/stackstorm/st2/local/lib/python2.7/site-packages/st2common/persistence/base.py", line 186, in add_or_update
    model_object=model_object)
StackStormDBObjectConflictError: Tried to save duplicate unique keys (E11000 duplicate key error collection: st2.trigger_type_d_b index: uid_1 dup key: { : "trigger_type:core:st2.generic.actiontrigger" })
2019-04-10 11:46:46,247 DEBUG [-] Registered internal trigger: st2.generic.actiontrigger.
....

TODO

Changelog entry

registration) as debug since they are non-fatal. Previously they were logged under error which caused a lot of confusion.

Kami · 2019-04-10T11:53:55Z

st2common/st2common/services/triggers.py


-def create_or_update_trigger_db(trigger):
+def create_or_update_trigger_db(trigger, log_not_unique_error_as_debug=False):
    """


Note: We want to default this to False everywhere because in other context, this error would indeed be fatal.

arm4b

LGTM, thanks for catching this!

arm4b · 2019-04-10T13:16:12Z

st2common/st2common/triggers.py

            LOG.audit('Trigger created for parameter-less internal TriggerType. Trigger.id=%s' %
                      (trigger_db.id), extra=extra)
-        except StackStormDBObjectConflictError:
+        except (NotUniqueError, StackStormDBObjectConflictError):


Kami · 2019-04-10T13:42:36Z

Overall, I would be much more happy if we could add a consistent test for it, but as mentioned above - this would be hard and there are a lot of edge cases.

…_error_log_level

Log non-fatal errors during service startup phase (internal trigger type

bfbd06a

registration) as debug since they are non-fatal. Previously they were logged under error which caused a lot of confusion.

Kami added the bug label Apr 10, 2019

Kami added this to the 3.0.0 milestone Apr 10, 2019

Kami commented Apr 10, 2019

View reviewed changes

Kami requested a review from arm4b April 10, 2019 11:54

Don't include traceback on non fatal error.

9e46cbd

arm4b approved these changes Apr 10, 2019

View reviewed changes

Kami added 2 commits April 11, 2019 10:14

Merge branch 'master' of github.com:StackStorm/st2 into fix_non_fatal…

1462533

…_error_log_level

Add changelog entry.

39ae2d7

Kami merged commit 0ae2a62 into master Apr 11, 2019

Kami deleted the fix_non_fatal_error_log_level branch April 11, 2019 15:36

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

Uh oh!

Log non-fatal errors during service bootstrap phase under DEBUG instead of ERROR #4630

Log non-fatal errors during service bootstrap phase under DEBUG instead of ERROR #4630

Uh oh!

Kami commented Apr 10, 2019 •

edited

Loading

Uh oh!

Kami Apr 10, 2019

Uh oh!

arm4b left a comment

Uh oh!

arm4b Apr 10, 2019

Uh oh!

Kami commented Apr 10, 2019

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants

Uh oh!

Log non-fatal errors during service bootstrap phase under DEBUG instead of ERROR #4630

Log non-fatal errors during service bootstrap phase under DEBUG instead of ERROR #4630

Uh oh!

Conversation

Kami commented Apr 10, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Background, Context

Output

TODO

Uh oh!

Kami Apr 10, 2019

Choose a reason for hiding this comment

Uh oh!

arm4b left a comment

Choose a reason for hiding this comment

Uh oh!

arm4b Apr 10, 2019

Choose a reason for hiding this comment

Uh oh!

Kami commented Apr 10, 2019

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants

Kami commented Apr 10, 2019 •

edited

Loading