tasks.loop running twice when a specific time is given

s0hv commented 2 years ago

Summary

The task is running two times instead of one on the given time.

Reproduction Steps

Have a task with a time specified @tasks.loop(time=time(tzinfo=timezone.utc)). The second time the task runs it will run twice instead of once. I managed to pinpoint the culprit to the _get_next_sleep_time function https://github.com/DisnakeDev/disnake/blob/d76c09fca5d50d3fbf1522890f668a6ed8812c21/disnake/ext/tasks/__init__.py#L556 Specifically these lines https://github.com/DisnakeDev/disnake/blob/d76c09fca5d50d3fbf1522890f668a6ed8812c21/disnake/ext/tasks/__init__.py#L581-L583

The first time the task runs fine as it does not reach this point in the code but returns earlier. After the task has successfully run once, the problem begins since the problematic code is reached. The reason for this is that after the first successful run, _last_iteration is set to the last return value of _get_next_sleep_time. This is problematic, since the time part of _get_next_sleep_time is the time argument of the task. This causes next_time == next_date.timetz() to be true, which in turn makes the if condition false which prevents a day being added to the sleep time.

Minimal Reproducible Code

No response

Expected Results

The task to run once each day on the specified time.

Actual Results

The task starts running twice after the first time.

Intents

irrelevant here

System Information

- Python v3.10.1-final              
- disnake v2.5.1-final              
    - disnake pkg_resources: v2.5.1 
- aiohttp v3.8.1                    
- system info: Windows 10 10.0.19042

Checklist

[X] I have searched the open issues for duplicates.
[X] I have shown the entire traceback, if possible.
[X] I have removed my token from display, if visible.

Additional Context

Link to the discord message where I brought this up just in case it's necessary https://discord.com/channels/808030843078836254/913779868985090089/991012140947222538

s0hv commented 2 years ago

I've done some more logging and I've come to the conclusion that the explanation I gave above is not quite exactly right. When the current time is checked after sleeping on this line https://github.com/DisnakeDev/disnake/blob/d76c09fca5d50d3fbf1522890f668a6ed8812c21/disnake/ext/tasks/__init__.py#L170 The returned value is sometimes before self._next_iteration. With this code snippet placed after the utcnow

logger.info(f'Now after sleep {now} next iteration {self._next_iteration}')

I managed to get this log Now after sleep 2022-07-05 23:59:59.999240+00:00 next iteration 2022-07-06 00:00:00+00:00. So now I believe this bug is caused by the fact that sleeping operations are not guaranteed to wait at least the given amount of time. The time can be more or less by an amount that depends on the clock resolution. When the loop works correctly utcnow returned a datetime after self._next_iteration. The instant utcnow was before self._next_iteration the task ran twice.

solumath commented 2 years ago

I got similar problem. With this code everything that runs after the midnight to 1 am is constantly looped. Other times i detected no problem with my zone. The problem would be propably with time drift because with "UTC" time zone I didn't have problem.

local_tz = datetime.now().astimezone().tzinfo

@tasks.loop(time=time(0, 1, tzinfo=local_tz))
async def send_names(self):
    nameday_cz = await self._nameday_cz()
    nameday_sk = await self._nameday_sk()
    channel = self.bot.get_channel(config.name_day_room)
    await channel.send(f"{nameday_cz}\n{nameday_sk}")

solumath commented 3 months ago

Is this WIP? I still have the same problem even today. Would be grateful for an update on where it stands.

DisnakeDev / disnake