[sentry-worker] sentry.errors.events: process.failed.empty

On-Premise
1

I see our sentry-worker instance (v9.1.2) log boat loads of sentry.errors.events: process.failed.empty and entry.errors.events: preprocess.failed.empty issues right after start and it does not end:

16:01:35 [WARNING] sentry.utils.geo: settings.GEOIP_PATH_MMDB not configured.
16:02:13 [INFO] sentry.plugins.github: apps-not-configured
16:02:14 [INFO] sentry.bgtasks: bgtask.spawn (task_name=u'sentry.bgtasks.clean_dsymcache:clean_dsymcache')
 
 -------------- celery@sentry-worker-8-xgjxv v3.1.18 (Cipater)
---- **** ----- 
--- * ***  * -- Linux-3.10.0-957.1.3.el7.x86_64-x86_64-with-debian-9.9
-- * - **** --- 
- ** ---------- [config]
- ** ---------- .> app:         sentry:0x7fd7c01b0390
- ** ---------- .> transport:   redis://sentry-redis.infra.svc.cluster.local:6379/0
- ** ---------- .> results:     disabled
- *** --- * --- .> concurrency: 4 (prefork)
-- ******* ---- 
--- ***** ----- [queues]
 -------------- .> activity.notify  exchange=default(direct) key=activity.notify
                .> alerts           exchange=default(direct) key=alerts
                .> app_platform     exchange=default(direct) key=app_platform
                .> assemble         exchange=default(direct) key=assemble
                .> auth             exchange=default(direct) key=auth
                .> buffers.process_pending exchange=default(direct) key=buffers.process_pending
                .> cleanup          exchange=default(direct) key=cleanup
                .> commits          exchange=default(direct) key=commits
                .> counters-0       exchange=counters(direct) key=
                .> default          exchange=default(direct) key=default
                .> digests.delivery exchange=default(direct) key=digests.delivery
                .> digests.scheduling exchange=default(direct) key=digests.scheduling
                .> email            exchange=default(direct) key=email
                .> events.index_event_tags exchange=default(direct) key=events.index_event_tags
                .> events.preprocess_event exchange=default(direct) key=events.preprocess_event
                .> events.process_event exchange=default(direct) key=events.process_event
                .> events.reprocess_events exchange=default(direct) key=events.reprocess_events
                .> events.reprocessing.preprocess_event exchange=default(direct) key=events.reprocessing.preprocess_event
                .> events.reprocessing.process_event exchange=default(direct) key=events.reprocessing.process_event
                .> events.save_event exchange=default(direct) key=events.save_event
                .> files.delete     exchange=default(direct) key=files.delete
                .> integrations     exchange=default(direct) key=integrations
                .> merge            exchange=default(direct) key=merge
                .> options          exchange=default(direct) key=options
                .> reports.deliver  exchange=default(direct) key=reports.deliver
                .> reports.prepare  exchange=default(direct) key=reports.prepare
                .> search           exchange=default(direct) key=search
                .> sleep            exchange=default(direct) key=sleep
                .> stats            exchange=default(direct) key=stats
                .> triggers-0       exchange=triggers(direct) key=
                .> unmerge          exchange=default(direct) key=unmerge
                .> update           exchange=default(direct) key=update

16:02:19 [ERROR] sentry.errors.events: preprocess.failed.empty (cache_key=u'e:eb2547f4d6be4f1f88cb2eb66e749b45:12')
16:02:19 [ERROR] sentry.errors.events: process.failed.empty (cache_key=u'e:f9e814d361eb4074a644c7bbf7c06b0c:12')
16:02:20 [ERROR] sentry.errors.events: preprocess.failed.empty (cache_key=u'e:3ea07657dde64561aeb63f1c220070c4:12')
16:02:20 [ERROR] sentry.errors.events: process.failed.empty (cache_key=u'e:83e57546dd5747b7ad4ea6a3cb4b226d:7')
16:02:20 [ERROR] sentry.errors.events: preprocess.failed.empty (cache_key=u'e:451fbb85680348c39390614082ec3397:12')
16:02:21 [ERROR] sentry.errors.events: preprocess.failed.empty (cache_key=u'e:05402c16cc064521942821bd044abaa6:12')
…

Once in a while I get killed worker notices:

celery@sentry-worker-8-xgjxv ready.
16:09:33 [ERROR] multiprocessing: Process 'Worker-4' pid:16 exited with 'signal 9 (SIGKILL)'
Traceback (most recent call last):
  File "/usr/local/lib/python2.7/site-packages/billiard/pool.py", line 1175, in mark_as_worker_lost
    human_status(exitcode)),
WorkerLostError: Worker exited prematurely: signal 9 (SIGKILL).
16:09:33 [ERROR] celery.worker.job: Task sentry.tasks.store.process_event[a740d584-15c6-40ba-805d-37c9959f010a] raised unexpected: WorkerLostError('Worker exited prematurely: signal 9 (SIGKILL).',) (data={u'hostname': 'celery@sentry-worker-8-xgjxv', u'name': 'sentry.tasks.store.process_event', u'args': '[]', u'internal': False, u'kwargs': "{'event_id': u'eb22c38f89d04c1f9b90af328168597e', 'start_time': 1565276970.349995, 'cache_key': u'e:eb22c38f89d04c1f9b90af328168597e:3'}", u'id': 'a740d584-15c6-40ba-805d-37c9959f010a'})

Any pointers how to figure out what’s going on here are highly appreciated.

2

This indicates something wrong with Redis. Events are stored by a key/value pair in Redis, and this key is put into the event processing queue. When the processing task is pulled, it tries to in turn pull the blob out of Redis. When this blob is missing, you get this error.

The other side of this is that the blobs are set to TTL in 1 hour, so if your queue is backlogged and you’re more than an hour behind, they will start to disappear on their own.

1 Like
3

@matt thanks for clarifying! <3

we did have a “downtime” where events weren’t processed. I understandt this is just the worker pulling all the evicted events and this will recover eventually.

1 Like
4

Is there a way to configure the TTL to be > 1 hour?

5

Not without forking and modifying code. There’s not really a practical reason to have this configurable.

6

Any solutions guide for it?