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.
This commit is contained in:
Alex Vandiver 2023-02-09 18:55:06 +00:00 committed by Tim Abbott
parent 7ab4fdf250
commit 02a73af386
1 changed files with 28 additions and 1 deletions

View File

@ -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)