Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Merged
merged 4 commits into from
Apr 11, 2019

Conversation

Kami
Copy link
Member

@Kami Kami commented Apr 10, 2019

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 Kami added the bug label Apr 10, 2019
@Kami Kami added this to the 3.0.0 milestone Apr 10, 2019
@@ -245,7 +245,7 @@ def create_trigger_db(trigger_api):
return trigger_db


def create_or_update_trigger_db(trigger):
def create_or_update_trigger_db(trigger, log_not_unique_error_as_debug=False):
"""
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

@Kami Kami requested a review from arm4b April 10, 2019 11:54
Copy link
Member

@arm4b arm4b left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM, thanks for catching this!


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

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

👍

@Kami
Copy link
Member Author

Kami commented Apr 10, 2019

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.

@Kami Kami merged commit 0ae2a62 into master Apr 11, 2019
@Kami Kami deleted the fix_non_fatal_error_log_level branch April 11, 2019 15:36
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants