From 02a73af386a52498e4c171627b33013a97dfffd9 Mon Sep 17 00:00:00 2001 From: Alex Vandiver Date: Thu, 9 Feb 2023 18:55:06 +0000 Subject: [PATCH] deferred_work: Log at start of the work. This is helpful for debugging -- generally these tasks are in a worker queue because they take a long time to run, so knowing what long task is about to start before it does, rather than just after, is useful. --- zerver/worker/queue_processors.py | 29 ++++++++++++++++++++++++++++- 1 file changed, 28 insertions(+), 1 deletion(-) diff --git a/zerver/worker/queue_processors.py b/zerver/worker/queue_processors.py index f006f4492b..47e8f85c5f 100644 --- a/zerver/worker/queue_processors.py +++ b/zerver/worker/queue_processors.py @@ -958,6 +958,11 @@ class DeferredWorker(QueueProcessingWorker): start = time.time() if event["type"] == "mark_stream_messages_as_read": user_profile = get_user_profile_by_id(event["user_profile_id"]) + logger.info( + "Marking messages as read for user %s, stream_recipient_ids %s", + user_profile.id, + event["stream_recipient_ids"], + ) for recipient_id in event["stream_recipient_ids"]: count = do_mark_stream_messages_as_read(user_profile, recipient_id) @@ -968,6 +973,10 @@ class DeferredWorker(QueueProcessingWorker): recipient_id, ) elif event["type"] == "mark_stream_messages_as_read_for_everyone": + logger.info( + "Marking messages as read for all users, stream_recipient_id %s", + event["stream_recipient_id"], + ) # This event is generated by the stream deactivation code path. batch_size = 100 offset = 0 @@ -989,6 +998,10 @@ class DeferredWorker(QueueProcessingWorker): event["stream_recipient_id"], ) elif event["type"] == "clear_push_device_tokens": + logger.info( + "Clearing push device tokens for user_profile_id %s", + event["user_profile_id"], + ) try: clear_push_device_tokens(event["user_profile_id"]) except PushNotificationBouncerRetryLaterError: @@ -1005,6 +1018,12 @@ class DeferredWorker(QueueProcessingWorker): output_dir = tempfile.mkdtemp(prefix="zulip-export-") export_event = RealmAuditLog.objects.get(id=event["id"]) user_profile = get_user_profile_by_id(event["user_profile_id"]) + logger.info( + "Starting realm export for realm %s into %s, initiated by user_profile_id %s", + realm.string_id, + output_dir, + event["user_profile_id"], + ) try: public_url = export_realm_wrapper( @@ -1068,11 +1087,19 @@ class DeferredWorker(QueueProcessingWorker): logger.info("Processing reupload_realm_emoji event for realm %s", realm.id) handle_reupload_emojis_event(realm, logger) elif event["type"] == "soft_reactivate": + logger.info( + "Starting soft reactivation for user_profile_id %s", + event["user_profile_id"], + ) user_profile = get_user_profile_by_id(event["user_profile_id"]) reactivate_user_if_soft_deactivated(user_profile) end = time.time() - logger.info("deferred_work processed %s event (%dms)", event["type"], (end - start) * 1000) + logger.info( + "deferred_work processed %s event (%dms)", + event["type"], + (end - start) * 1000, + ) @assign_queue("test", is_test_queue=True)