Crc: [BUG] Time skew caused by machine sleep

[rajivnathan]

Description

I had an issue with authentication due to a time difference between the token received from SSO and my local crc cluster.

What happened was the authentication was successful but the token validation resulted in the following error:

{error: "Token used before issued"}

It looks like the problem in my case was due to my local crc cluster. It appears when time.Now().Unix() (Go code) is run on my local system (not within crc) the time was correct but when run within the crc cluster the time was off by a large margin.

Attempt 1

{"level":"info","ts":1587483336.1436388,"logger":"registration-service","msg":"now: 1587483336","timestamp":"Tue, 21 Apr 2020 15:35:36 +0000","commit":"197d625"}
{"level":"info","ts":1587483336.143755,"logger":"registration-service","msg":"c.StandardClaims.IssuedAt: 1587587657","timestamp":"Tue, 21 Apr 2020 15:35:36 +0000","commit":"197d625"}

now: 1587483336 Tuesday, April 21, 2020 3:35:36 PM (GMT)
iat: 1587587657 Wednesday, April 22, 2020 8:34:17 PM

difference of 104321

Attempt 2

{"level":"info","ts":1587484357.7958674,"logger":"registration-service","msg":"now: 1587484357","timestamp":"Tue, 21 Apr 2020 15:52:37 +0000","commit":"197d625"}
{"level":"info","ts":1587484357.7959292,"logger":"registration-service","msg":"c.StandardClaims.IssuedAt: 1587588569","timestamp":"Tue, 21 Apr 2020 15:52:37 +0000","commit":"197d625"}

now: 1587484357 Tuesday, April 21, 2020 3:52:37 PM
iat: 1587588569 Wednesday, April 22, 2020 8:49:29 PM
difference of 104212

After stopping and starting crc

{"level":"info","ts":1587591117.3313382,"logger":"registration-service","msg":"now: 1587591117","timestamp":"Wed, 22 Apr 2020 21:31:57 +0000","commit":"197d625"}
{"level":"info","ts":1587591117.3313932,"logger":"registration-service","msg":"c.StandardClaims.IssuedAt: 1587591117","timestamp":"Wed, 22 Apr 2020 21:31:57 +0000","commit":"197d625"}

now: 1587591117
iat: 1587591117

No difference! And the authentication was successful this time. So my theory is when my laptop sleeps the crc VM is paused and when my laptop resumes the clock in the crc VM is not resynced.

General information

• OS: macOS
• Hypervisor: KVM / Hyper-V / hyperkit
• Did you run crc setup before starting it (Yes/No)?
  Yes

CRC version

crc version: 1.8.0+0a318dc
OpenShift version: 4.3.8 (embedded in binary)

CRC status

CRC VM:          Running
OpenShift:       Running (v4.3.8)
Disk Usage:      25.8GB of 32.72GB (Inside the CRC VM)
Cache Usage:     11.95GB
Cache Directory: ~/.crc/cache

CRC config

Host Operating System

ProductName:    Mac OS X
ProductVersion: 10.15.4
BuildVersion:   19E287

Steps to reproduce

1. Deploy a pod with an image build from the Dockerfile below
2. Allow the pod to continue running
3. Allow the crc host machine to sleep for a significant amount of time
4. When the machine resumes observe the container logs

Dockerfile

This Dockerfile simply prints a timestamp in unix epoch time every 10 seconds. You can verify the time using https://www.epochconverter.com/

FROM registry.access.redhat.com/ubi7/ubi-minimal:latest

ENV USER_UID=1001 \
    USER_NAME=test \
    LANG=en_US.utf8

ENTRYPOINT ["sh", "-c", "while sleep 10; do date +%s; done"]

USER ${USER_UID}

Expected

The time should be in sync with your crc host machine's time.

Actual

The timestamps from the container are lagging behind the host machine's time by a large margin.

Workaround

If you run crc stop and then crc start the time will be synced with the host machine's time.

[gbraad]

This is a known issue and duplicated

[gbraad]

@robin-owen Let's document this as part of the release notes (only happens on macOS). Not much we can do...

[robin-owen]

@gbraad Sure. We can also include this as a known issue for both the upcoming release and the current one.

[rajivnathan]

@gbraad @robin-owen Do you have a link to the duplicate issue please?

[gbraad]

https://github.com/code-ready/crc/issues/667#issuecomment-536305470

Note: this happens on hyperkit/macOS only (it also does for minishift and minikube). chronyd actually runs inside the vm.

[stale[bot]]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.