Context:
I’ve been working on a simple Elixir application that runs cron-like jobs. I deployed it on my Macbook using launchd (it’s like systemd but for macos, although that’s a story for another day!). Basically, whenever my Mac wakes up, the app checks a SQLite database to see if a job has already run in the designated timeframe. If it hasn’t, the job gets executed.
The Problem:
One of my jobs used the elixir_google_spreadsheets library to fetch data from a Google Sheet. This library relies on Goth for Google authentication. Goth’s responsibility is to provide a valid authorization token for interacting with the Google Sheets API.
The problem? I kept getting 401 from the Google Sheets API at random times. Things would be fine when I’d just deployed, but some time later, the problem would start to happen. Upon further investigation, I discovered that Goth.fetch was returning a invalid token which was already expired.
Goth.fetch (link) is simple. It works by first checking the ETS cache for a token. If there’s one, it compares the current time with the token’s expiry to see if a new token is needed. It was using System.system_time to get the “current” time to make the comparison.
However, System.system_time was returning a old time that did not match the actual real time. This was happening after every few hours, for example when my macbook went to sleep for some time.
iex(..)11> :os.system_time(:second) - System.system_time(:second)96776Why was this happening?
System.system_time is the Erlang System Time, which is erlang’s view of the POSIX time.
Internally, the BEAM VM uses Erlang monotonic time as the main “time engine” that is used for more or less everything that has anything to do with time. By adding current Erlang monotonic time with current time offset, you get current Erlang system time, which is System.system_time. As per the docs, it might not match the “real” OS time in case of “time warps”.
What’s a time warp, you ask? A time warp is basically a jump forwards or backwards in time. Technically, it means that the difference of time values taken before and after the time warp does not correspond to the actual elapsed time. A time warp can happen due to many factors, such as host computer going to sleep for some time, and then waking up at a new time.
Before OTP 26, the default behaviour of the VM was that the time offset is chosen at VM start time, and it can never be modified. Due to this, when a time warp happens, System.system_time will now always lag behind the real time.
The Solution
The solution for this was simple, I updated Goth to use System.os_time instead of System.system_time. No more 401 errors after that. Here’s the PR if you’re interested.
Even though the solution was just a one liner, this problem was very helpful for me to understand how the BEAM VM handles time.
If you’re interested in reading more about how Time is handled in Elixir / Erlang, here’s a list of interesting links. I would highly recommend reading through at least the first two.
- https://learnyousomeerlang.com/time
- https://www.erlang.org/doc/apps/erts/time_correction.html
- https://adoptingerlang.org/docs/development/hard_to_get_right/#handling-time
- https://elixirforum.com/t/system-system-time-vs-system-os-time/48529
- https://elixirforum.com/t/guardian-generating-an-expired-token-because-system-system-time-datetime-is-this-time-warp/56110/19?page=2
What should I use while dealing with time related stuff?
- When working with “time” that also involves the real world, use
System.os_time, assuming that you can always trust the time that the operating system gives you is the “real world” time. This includes cases like checking if the token issued by an external system is expired, comparing timestamps from any external source with the current time, etc. - When you want to calculate duration, or measure time difference between two events, use
System.monotonic_time - To define an absolute order for two events on the same node, use
System.unique_integer(:monotonic)
Thanks for reading!
