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

Missing email notifications in spite of email subscription settings #2549

Closed
david17123 opened this issue Jan 14, 2016 · 28 comments
Closed

Missing email notifications in spite of email subscription settings #2549

david17123 opened this issue Jan 14, 2016 · 28 comments

Comments

@david17123
Copy link

This is a continuation of issue 2528 where email notifications are not received. However, this time the user is already properly subscribed to the projects and yet still no email (or digest) is coming. To begin with, here's the situation:

  • I created a new team (called "Test team") and a new project for the team (called "Test project")
  • I then sent an event (of level "error") to the project
  • I double-checked that I am subscribed to the project (via url: http://[sentry.domain]/organizations/sentry/members/1/; screenshot attached)
  • I also double checked that I have the right rules applied that should create the notification (screenshot attached)
  • I can see that the task sentry.tasks.digests.deliver_digest is fired and handled by celery worker (screenshot attached)

This is the notification rules being applied. It is the default one created by Sentry, and it should create notification when a new event is seen.
notification rules

This is a snippet of celery flower right after the event is received by sentry. It is clear that a deliver_digest task is fired at that moment. Also, it is shown in the kwargs column that the event is a new event.
celery flower

Just to confirm that the user is subscribed for notifications for the project, the correct checkboxes are ticked.
Members settings

I wonder what information did deliver_digest process when it was executed on my sentry instance but I'm not too sure how to go that deep into the code to figure it out. As previously, I'm not even sure if this is actually a bug or merely a config issue. Any help would be appreciated! Thanks

@tkaemming
Copy link
Contributor

Since the delivery task is returning without an error, I'm having trouble coming up with any ideas here except a continuation of the previous thread where the digest is not being addressed to the intended users. You can check via the mail plugin with sentry shell like so:

from sentry.models import Project
from sentry.plugins import plugins

project = Project.objects.get(slug='internal')  # Replace `internal` with your project.
print plugins.get('mail').get_send_to(project)

This should return a sequence of user IDs that will be sent to. If this is empty, that's your problem. If not, let me know and we can try and dig in further. In the future, we'll probably end up adding more debug logging to this path to improve observability here.

There are a few less likely cases, which all should end up logging if they occur, such as these ones (among others):

  • if 'no such key' in str(error):
    logger.debug('Could not move timeline for digestion (likely has no contents.)')
    else:
    raise
  • for (record_key, timestamp), value in zip(records, pipeline.execute()):
    # We have to handle failures if the key does not exist --
    # this could happen due to evictions or race conditions
    # where the record was added to a timeline while it was
    # already being digested.
    if value is None:
    logger.warning('Could not retrieve event for timeline.')
    else:
    yield Record(record_key, self.codec.decode(value), timestamp)

@sul4bh
Copy link

sul4bh commented Jan 15, 2016

I have a similar issue.

I (the first/super user) never get any email notifications. But other project members are getting the emails.

@tkaemming
Copy link
Contributor

@sul4bh: This was addressed in #2528 (specifically this comment.)

@david17123
Copy link
Author

@tkaemming I've just tried running your code and here's what it returns:

Python 2.7.6 (default, Jun 22 2015, 17:58:13)
[GCC 4.8.2] on linux2
Type "help", "copyright", "credits" or "license" for more information.
(InteractiveConsole)
>>> from sentry.models import Project
>>> from sentry.plugins import plugins
>>> project = Project.objects.get(slug='test-project')
>>> print plugins.get('mail').get_send_to(project)
[1L]
>>>

I think that 1L is the user ID? I tried with another project as well and, just like this one, it returned a list of integers. And just to be sure that I'm still not receiving the digest email I created a new event and I can see it in Celery Flower both the event processing tasks and deliver_digest task. (The deliver_digest has this in its args: ('mail:p:8', 1453073005.13117) and the project I'm observing has ID 8).

@david17123
Copy link
Author

By the way, was just wondering if this could be of any use. This is the Celery Flower screenshot for the deliver_digest task I mentioned. There seems to be no error there.

deliver_digest

@tkaemming
Copy link
Contributor

Do you get a non-empty result back running this snippet?

from sentry.models import Project
from sentry.utils.email import MessageBuilder

project = Project.objects.get(slug='test-project')
message = MessageBuilder('test')
message.add_users((1,), project)
print message._send_to

@david17123
Copy link
Author

Yes, I've got a set of email addresses. In this case there's only 1 entry in the returned set because there's only 1 user subscribing to the project.

@dcramer
Copy link
Member

dcramer commented Jan 19, 2016

@david17123 did you confirm there were no debug log messages? i.e. with celery worker -l DEBUG

@david17123
Copy link
Author

I haven't tried running with DEBUG level logging before. I just did and there are tons of things printed out, which I tried to copy and paste the tasks around receiving the event:

[2016-01-19 01:43:46,174: INFO/MainProcess] Received task: sentry.tasks.store.preprocess_event[87d38d2c-a4a5-4e8e-baf6-9e394224d8f0]
[2016-01-19 01:43:46,175: DEBUG/MainProcess] TaskPool: Apply <function _fast_trace_task at 0x7fb9e2ef2488> (args:('sentry.tasks.store.preprocess_event', '87d38d2c-a4a5-4e8e-baf6-9e394224d8f0', [], {'start_time': 1453167826.171991, 'cache_key': 'e:556cb3094e8b4bbbbe584be7119a530b:8'}, {'utc': True, u'is_eager': False, 'chord': None, u'group': None, 'args': [], 'retries': 0, u'delivery_info': {u'priority': 0, u'redelivered': None, u'routing_key': 'events', u'exchange': 'default'}, 'expires': None, u'hostname': 'celery@queue', 'task': 'sentry.tasks.store.preprocess_event', 'callbacks': None, u'correlation_id': '87d38d2c-a4a5-4e8e-baf6-9e394224d8f0', 'errbacks': None, 'timelimit': (65, 60), 'taskset': None, 'kwargs': {'start_time': 1453167826.171991, 'cache_key': 'e:556cb3094e8b4bbbbe584be7119a530b:8'}, 'eta': None, u'reply_to': 'c2f325fe-257a-3dac-aeda-6d36f0b25f99', 'id': '87d38d2c-a4a5-4e8e-baf6-9e394224d8f0', u'headers': {}}) kwargs:{})
[2016-01-19 01:43:46,193: DEBUG/MainProcess] Task accepted: sentry.tasks.store.preprocess_event[87d38d2c-a4a5-4e8e-baf6-9e394224d8f0] pid:22130
[2016-01-19 01:43:46,202: INFO/MainProcess] Received task: sentry.tasks.store.save_event[e01a51c2-d50b-496c-ae15-940a3818a79b]
[2016-01-19 01:43:46,206: DEBUG/MainProcess] TaskPool: Apply <function _fast_trace_task at 0x7fb9e2ef2488> (args:('sentry.tasks.store.save_event', 'e01a51c2-d50b-496c-ae15-940a3818a79b', [], {'start_time': 1453167826.171991, 'cache_key': 'e:556cb3094e8b4bbbbe584be7119a530b:8', 'data': None}, {'utc': True, u'is_eager': False, 'chord': None, u'group': None, 'args': [], 'retries': 0, u'delivery_info': {u'priority': 0, u'redelivered': None, u'routing_key': 'events', u'exchange': 'default'}, 'expires': None, u'hostname': 'celery@queue', 'task': 'sentry.tasks.store.save_event', 'callbacks': None, u'correlation_id': 'e01a51c2-d50b-496c-ae15-940a3818a79b', 'errbacks': None, 'timelimit': (None, None), 'taskset': None, 'kwargs': {'start_time': 1453167826.171991, 'cache_key': 'e:556cb3094e8b4bbbbe584be7119a530b:8', 'data': None}, 'eta': None, u'reply_to': 'dd9c3be4-d210-3700-bd29-2ba428f90b34', 'id': 'e01a51c2-d50b-496c-ae15-940a3818a79b', u'headers': {}}) kwargs:{})
[2016-01-19 01:43:46,208: INFO/MainProcess] Task sentry.tasks.store.preprocess_event[87d38d2c-a4a5-4e8e-baf6-9e394224d8f0] succeeded in 0.0300511529204s: None
[2016-01-19 01:43:46,211: DEBUG/MainProcess] Task accepted: sentry.tasks.store.save_event[e01a51c2-d50b-496c-ae15-940a3818a79b] pid:22130
[2016-01-19 01:43:46,300: INFO/MainProcess] Received task: sentry.tasks.post_process.post_process_group[699d3ab6-be7e-4665-97d6-58900c096014]
[2016-01-19 01:43:46,305: DEBUG/MainProcess] TaskPool: Apply <function _fast_trace_task at 0x7fb9e2ef2488> (args:('sentry.tasks.post_process.post_process_group', '699d3ab6-be7e-4665-97d6-58900c096014', [], {'is_new': True, 'group': <Group at 0x7fb9e9531e50: id=1881L, project_id=8L>, 'is_sample': False, 'is_regression': False, 'event': <Event at 0x7fb9de9e3410: id=3838L, project_id=8L, group_id=1881L>}, {'utc': True, u'is_eager': False, 'chord': None, u'group': None, 'args': [], 'retries': 0, u'delivery_info': {u'priority': 0, u'redelivered': None, u'routing_key': u'', u'exchange': 'triggers'}, 'expires': None, u'hostname': 'celery@queue', 'task': 'sentry.tasks.post_process.post_process_group', 'callbacks': None, u'correlation_id': '699d3ab6-be7e-4665-97d6-58900c096014', 'errbacks': None, 'timelimit': (None, None), 'taskset': None, 'kwargs': {'is_new': True, 'group': <Group at 0x7fb9e9531e50: id=1881L, project_id=8L>, 'is_sample': False, 'is_regression': False, 'event': <Event at 0x7fb9de9e3410: id=3838L, project_id=8L, group_id=1881L>}, 'eta': None, u'reply_to': 'dd9c3be4-d210-3700-bd29-2ba428f90b34', 'id':... kwargs:{})
[2016-01-19 01:43:46,307: INFO/MainProcess] Task sentry.tasks.store.save_event[e01a51c2-d50b-496c-ae15-940a3818a79b] succeeded in 0.0977017190307s: None
[2016-01-19 01:43:46,315: DEBUG/MainProcess] Task accepted: sentry.tasks.post_process.post_process_group[699d3ab6-be7e-4665-97d6-58900c096014] pid:22130
[2016-01-19 01:43:46,474: INFO/MainProcess] Received task: sentry.tasks.digests.deliver_digest[627dddda-3337-4fb6-9413-07e25cb5c42a]
[2016-01-19 01:43:46,483: DEBUG/MainProcess] TaskPool: Apply <function _fast_trace_task at 0x7fb9e2ef2488> (args:('sentry.tasks.digests.deliver_digest', '627dddda-3337-4fb6-9413-07e25cb5c42a', ('mail:p:8',), {}, {'utc': True, u'is_eager': False, 'chord': None, u'group': None, 'args': ('mail:p:8',), 'retries': 0, u'delivery_info': {u'priority': 0, u'redelivered': None, u'routing_key': 'digests.delivery', u'exchange': 'default'}, 'expires': None, u'hostname': 'celery@queue', 'task': 'sentry.tasks.digests.deliver_digest', 'callbacks': None, u'correlation_id': '627dddda-3337-4fb6-9413-07e25cb5c42a', 'errbacks': None, 'timelimit': (None, None), 'taskset': None, 'kwargs': {}, 'eta': None, u'reply_to': 'dd9c3be4-d210-3700-bd29-2ba428f90b34', 'id': '627dddda-3337-4fb6-9413-07e25cb5c42a', u'headers': {}}) kwargs:{})
[2016-01-19 01:43:46,485: INFO/MainProcess] Task sentry.tasks.post_process.post_process_group[699d3ab6-be7e-4665-97d6-58900c096014] succeeded in 0.175404203008s: None
[2016-01-19 01:43:46,488: DEBUG/MainProcess] Task accepted: sentry.tasks.digests.deliver_digest[627dddda-3337-4fb6-9413-07e25cb5c42a] pid:22130
[2016-01-19 01:43:46,505: INFO/MainProcess] Task sentry.tasks.digests.deliver_digest[627dddda-3337-4fb6-9413-07e25cb5c42a] succeeded in 0.0175451060059s: None

@dcramer
Copy link
Member

dcramer commented Jan 19, 2016

@david17123 its possible this is getting evicted in Redis -- do you know what maxmemory is set to? I'm assuming Redis is being used for everything (broker included).

@david17123
Copy link
Author

Yes, redis is used for everything including the broker. I've checked the redis configuration file and I don't see maxmemory is explicitly set anywhere. When I checked via redis-cli it says that maxmemory is set to 0, which I assume means no limit. Furthermore, the stats also says that evicted_keys is 0. Is this the stats that you're after?

@tkaemming
Copy link
Contributor

We added some additional debug logging with #2569 (on master as of dd51c16) which could provide some visibility into what's going on here if you're up for deploying a git revision.

I don't think this is part of the digest building process, but somewhere between when the digest data is handed off to to be rendered into and email message and delivered to you — this would at least confirm that. The key line here would be something like this:

2016-01-19 22:31:41,560 7639  DEBUG    sentry.digests <function sort_rule_groups at 0x103caf848> applied to 2 items.

As long as sort_rule_groups is applied to > 0 items when there are expected events, it's passing through the digest subsystem correctly. If the email doesn't get sent because the there aren't any recipients, one of the log statements in ed7c3ef should be triggered.

@joedborg
Copy link
Contributor

I get a similar issue where the test email works from the Admin page, as does:

project = Project.objects.get(slug='django')
message = MessageBuilder('test')
message.add_users((1,), project)
message.send()

But I get no notification emails (all are turned on). Should I raise a new ticket for this, or do we think they're related?

@dcramer
Copy link
Member

dcramer commented Jan 20, 2016

@joedborg can you confirm:

  • SENTRY_DIGESTS
  • The user is a member of the team (this is more clear in 8.0.1)
  • The user has notification settings enabled
  • The email isn't failing to send via smtp logs

@joedborg
Copy link
Contributor

@dcramer
How do I check SENTRY_DIGESTS? It's not something I've overwritten.

>>> settings.SENTRY_DIGESTS
'sentry.digests.backends.redis.RedisBackend'

I checked the membership as of issue 2528, which is fine (returns a populated object).
I'm pretty certain I have that enabled, is there a way to check via the sentry shell?
Is that something that sentry will kick out into its logs? I use a dedicated SMTP server, rather than local.

@dcramer
Copy link
Member

dcramer commented Jan 20, 2016

As a simple temporary solution (until we can figure out what's going on here), you can put this in sentry.conf.py:

SENTRY_DIGESTS = 'sentry.digests.backends.dummy.DummyBackend'

@joedborg
Copy link
Contributor

Done that and reloaded Sentry, but still not getting emails unfortunately.

@joedborg
Copy link
Contributor

The only thing I can pick out of the logs is

celery-worker_1 | [2016-01-20 10:58:14,330: WARNING/Worker-11] No handlers could be found for logger "toronado.cssutils"

...I don't think it's related though

After which, just cycle through

celery-beat_1   | [2016-01-20 10:58:16,221: INFO/MainProcess] Scheduler: Sending due task schedule-digests (sentry.tasks.digests.schedule_digests)
celery-beat_1   | [2016-01-20 10:58:16,263: INFO/MainProcess] Scheduler: Sending due task flush-buffers (sentry.tasks.process_buffer.process_pending)
celery-beat_1   | [2016-01-20 10:58:16,268: INFO/MainProcess] Scheduler: Sending due task sync-options (sentry.tasks.options.sync_options)

@joedborg
Copy link
Contributor

This looks more like it:

sentry_1        | 192.168.204.53 - - [20/Jan/2016:11:01:24 +0000] "POST /api/2/store/ HTTP/1.1" 200 41 "-" "raven-python/5.9.0"
postgres_1      | ERROR:  duplicate key value violates unique constraint "sentry_eventuser_project_id_1a96e3b719e55f9a_uniq"
postgres_1      | DETAIL:  Key (project_id, hash)=(2, c4ca4238a0b923820dcc509a6f75849b) already exists.
postgres_1      | STATEMENT:  INSERT INTO "sentry_eventuser" ("project_id", "hash", "ident", "email", "username", "ip_address", "date_added") VALUES (2, 'c4ca4238a0b923820dcc509a6f75849b', '1', '*EMAIL*', '*USER*', NULL, '2016-01-20 11:01:24.406495+00:00') RETURNING "sentry_eventuser"."id"

I've obviously replaced my email and user

@dcramer
Copy link
Member

dcramer commented Jan 20, 2016

When digests are disabled it doesnt even hit any of that code (which is what the Dummy backend does). The toronado log message is something that would show up when rendering an email. It really does sound like it's getting into the email pipeline:

from sentry.models import Project
from sentry.plugins import plugin
project = Project.objects.get(slug='django')
mail = plugins.get('mail')
mail.get_send_to(project)

Can you confirm that this is returning members? I can't possible see how this would break, especially since we're not having any issues in prod and most of the standard mail path has not changed.

@dcramer
Copy link
Member

dcramer commented Jan 21, 2016

@joedborg that is unrelated -- we use try insert pattern everywhere in Sentry so you'll commonly see that in SQL logs. In general, SQL logs are useless.

@joedborg
Copy link
Contributor

@dcramer Ah ok, makes sense.
It seems to be fine:

>>> mail.get_send_to(project)
[1]

@dcramer
Copy link
Member

dcramer commented Jan 21, 2016

@joedborg I find it very unlikely email would be breaking here, so can you also please confirm that a notification should be generated. That is, does the event match a rule to which it would even try to send something?

@joedborg
Copy link
Contributor

screenshot from 2016-01-22 09-56-43

@dcramer What else needs checking in the settings? I think it's all set to send (I've tried removing the events to trigger the new event email).

@tkaemming
Copy link
Contributor

We believe this was fixed with #2587.

From the merge commit (8a7c726):

In some unknown cases, it's possible that the result of record.value.event.group.get_status() is a long rather than an integer. This results in the check 0L is 0 which is False (and not the correct answer to the intended check.)

This resulted in every issue being filtered from the digest since each issue appeared as it was not in the unresolved state. (We don't send notifications for issues that are resolved or muted for reasons that are hopefully obvious.)

tkaemming pushed a commit that referenced this issue Jan 23, 2016
mattrobenolt pushed a commit that referenced this issue Jan 23, 2016
Don't use unreliable identity check in digest pipeline.

In some unknown cases, it's possible that the result of `record.value.event.group.get_status()` is a long rather than an integer. This results in the check `0L is 0` which is `False` (and not the correct answer to the intended check.)

This will likely fix GH-2549.
mattrobenolt pushed a commit that referenced this issue Jan 23, 2016
ehfeng pushed a commit that referenced this issue Jan 23, 2016
@tkaemming
Copy link
Contributor

The fix mentioned above is now available on PyPI as Sentry 8.0.4. If you continue to have issues after upgrading, please let us know.

@david17123
Copy link
Author

Sorry I haven't been able to follow this up for quite a while. Just want to confirm that the problem I had is now fixed (i.e. I can now receive emails) after upgrading to 8.0.4. Thanks for your very responsive and helpful support!

@sul4bh
Copy link

sul4bh commented Jan 26, 2016

8.0.4 fixed the problem for me as well. Thank you guys.

@github-actions github-actions bot locked and limited conversation to collaborators Dec 18, 2020
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
None yet
Projects
None yet
Development

No branches or pull requests

5 participants