pejrich
Guardian generating an expired token because System.system_time != DateTime. Is this time warp?
I’m using Guardian to handle JWT tokens, and I noticed that after a given amount of time, the client app would not be able to refresh an refresh token into an access token. The request to refresh it would succeed, but the client app would say that the newly generated token was expired, which sure enough it was.
Digging into the Guardian source code, the timestamp is generated with System.system_time(:second), not DateTime.utc_now() |> DateTime.to_unix(), and sure enough, when I try both of those, they are different, by 97 minutes(my access token TTL is 60 minutes).
According to https://www.unixtimestamp.com/, the timestamp right now is roughly:
1685035696
iex(77)> System.system_time(:second)
1685029895
iex(78)> DateTime.to_unix(DateTime.utc_now())
1685035749
iex(79)> 1685035749 - 1685029895
5854
So my System.system_time is nearly 6000 seconds, ~100 minutes off the real time. I’ll admit I don’t have the clearest understanding of time warp, but this seems to happen consistently after about 6-8 hours of running the server. I have not changed timezone. I have not had daylight savings or a clock change. Any idea what could be causing this?
EDIT: In a new IEx console, they are equal again:
iex(1)> DateTime.to_unix(DateTime.utc_now()) - System.system_time(:second)
0
On the dev server that’s been running for 12 hours:
iex(96)> DateTime.to_unix(DateTime.utc_now()) - System.system_time(:second)
5831
Here are the specifics of the current uptime:
iex(107)> :erlang.statistics(:wall_clock)
{31386845, 9639}
iex(108)> :erlang.statistics(:runtime)
{471130, 23}
.tool-versions
elixir 1.14.4-otp-25
erlang 25.3
Most Liked
pejrich
I might also just start a plain IEx console and leave that running and see if the time drifts as that would point to it being M1/OS related. I wonder if when the laptop sleeps that could be causing the issue, that’s almost certainly the case each time I notice this. Of course I wasn’t taking detailed notes, but I can’t think of a time where i’ve started the server, and not had some reason that the laptop was sleeping for a few hours, and its usually after that that I notice it, but again this is just from vague recollection.
pejrich
Agreed. The underlying issue is almost certainly something in OTP rather than Guardian, but I still think there’s value in switching from system_time to os_time in Guardian, no?
Also, interestingly, my IEx session has drifted back to 0.
iex(1)> DateTime.to_unix(DateTime.utc_now()) - System.system_time(:second)
0
iex(2)> DateTime.to_unix(DateTime.utc_now()) - System.system_time(:second)
196
iex(3)> DateTime.to_unix(DateTime.utc_now()) - System.system_time(:second)
196
iex(4)> DateTime.to_unix(DateTime.utc_now()) - System.system_time(:second)
197
iex(5)> DateTime.to_unix(DateTime.utc_now()) - System.system_time(:second)
196
iex(6)> DateTime.to_unix(DateTime.utc_now()) - System.system_time(:second)
197
iex(7)> 197 / 60
3.283333333333333
iex(8)> DateTime.to_unix(DateTime.utc_now()) - System.system_time(:second)
195
iex(9)> DateTime.to_unix(DateTime.utc_now()) - System.system_time(:second)
17
iex(10)> DateTime.to_unix(DateTime.utc_now()) - System.system_time(:second)
17
iex(11)> DateTime.to_unix(DateTime.utc_now()) - System.system_time(:second)
0
adw632
Yeah it’s a thing in Erlang because most runtimes are relatively ignorant and are not trying to provide quite the same guarantees around scheduling.
I think in this case I think the original time abstraction was simply insufficient and maintaining that abstraction in the face of precision time and wall clock warping led to some slow syncing / unwanted consequences.
But things are good now with the new time API AFAIKT.
pejrich
I understand that there is some deeper cause. You may be right about the NIF claim. I do have some NIFs, and am running some ML models via Nx/EXLA, which uses a lot of NIFs, but I guess my other question still remains, if we have the following two options:
-
Timestamp 1, usually reliable, but sometimes for certain reasons can drift from the real time, maybe sometimes by a few seconds, but also sometimes by 97 minutes
-
Timestamp 2, reliable, doesn’t seem to drift from the real time
What would be the reason to ever use timestamp 1?
pejrich
I’ve only seen it on my M1, but as it’s still in development, it hasn’t had any real usage/runtime outside of the M1. I do have a server it’ll be running on, though it’s not running right now. I’ll start that up, and maybe start a task that trickles calls that would hit this nif and the ML models for 24 hours and see what the server reports. I’ve had this issue happen fairly consistently though locally. It seems to be related to time the server is running, rather than usage, e.g. if I start the server and then ~12 hours later try to make a request from the client, it’ll have the “expired JWT” issue(not because the JWT is 12 hours old, but rather because the newly created access token is expired), until I restart the server, but I won’t get that even after say 4-6 hours of development where the NIF would be getting called more often.
It is also a fairly different from typical setup, because the project relies on a few ML models, it’s running Bumblebee which starts up a couple models via some NIFs and EXLA, erlport which is running some python code, and the Rust NIF from above. Which certainly isn’t the most common use case, but still if a change from system_time to os_time can fix the issue for even a few people, it seems useful. I’ll start a issue on Github to see if there’s a reason for the use of one over the other.







