Buildbot infrastructure instability caused by time synchronization on latent workers

[pmisik]

Hi

I guess there is Buildbot infrastructure instability caused by time synchronization on latent workers.
On latent workers p12-pd-?? I'm seeing bizarre errors that seem to be time sync related.
It looks as if the time synchronization occurred during the execution of steps.
Reasons why I suspect time sync issue is that I randomly seeing these problems:

• Negative elapsed time: elapsedTime=-16489.823580
  see line 38 in https://buildbot.buildbot.net/#/builders/100/builds/3298/steps/1/logs/stdio

• Elapsed time much bigger than timeout 1200 seconds
  elapsedTime=16497.727639 see https://buildbot.buildbot.net/#/builders/108/builds/2120/steps/7/logs/stdio

• time related node assert
  node[2513]: ../src/env.cc:1288:v8::Local<v8::Value> node::Environment::GetNow(): Assertion (now) >= (timer_base())' failed.`
  https://buildbot.buildbot.net/#/builders/126/builds/92

• inconsistencies in the duration of the step reported in the master webUI and timeout in the workers

  • master webUI reports coverage tests run for 8:28 (508 seconds)
    command timed out: 1200 seconds without output running b'/tmp/bbvenv/bin/coverage run
    https://buildbot.buildbot.net/#/builders/83/builds/4711

  • master webUI reports set -e run for 5 seconds
    command timed out: 1200 seconds without output running
    https://buildbot.buildbot.net/#/builders/108/builds/2120
    ...

@p12tic what do you think?

[verm]

I just checked and it seems that ntpd was started incorrectly on service3 but I don't see anything in the logs about there being any time issues when I did restart it the adjustment was microseconds.

[pmisik]

I’m not sure if you use VM's for running worker machines.
Since the time offset was significant (16497 seconds=04:34:57), I wonder if this is one of the issues with time synchronization you can have on the VM infrastructure (at least I've encountered them).

• Booted VM with image with time sync disabled on VM machine startup
• It then starts the buildbot-worker and starts executing commands with the wrong time from image/snapshot.
• While the buildbot-worker is running, ntpd deamon/service runs and invokes time synchronization and shifts the time against the NTP server.
• During the run, the VM guest agent/daemon/service starts and again causes synchronization but against the host and shifts the time.
• In VM cluster with multiple nodes/hosts: During the running of the VM, the running VM will be relocated from one node to another. Subsequently, time synchronization will occur in the guest OS via VM guest agent/daemon/service, which will shift the time.

For example, here https://buildbot.buildbot.net/#/builders/108/builds/2120 is an interesting situation where there is probably a time shifted twice.

• Step 6 /tmp/bbvenv/bin/pip install -e master -e worker according to the webUI of master took 7 seconds but according to the log from the worker it took elapsedTime=-16486.171892 (negative duration)

• Step 7 set -e according to the webUI of master took 5 seconds but according to the log from the worker it took elapsedTime=16497.727639 (positive duration)

[p12tic]

Interesting. These workers are on a machine I boot up when I want faster test execution. Recently I migrated them to podman containers using gVisor container runtime. Probably gVisor doesn't fake syscalls well enough.

[verm]

Just checking in this isn't an issue with time on the master? Sounds like it's not but I want to make sure if there's anything I need to do let me know.

[p12tic]

@verm There's no issues with time on master. For any issues in p12-* workers the worker setup is the first suspect.

[verm]

@p12tic okay great!

[pmisik]

Now, it looks like p12-pd-? workers have run out of disk space for /home because errors like

error Error: ENOSPC: no space left on device, mkdir '/home/buildbot/...
https://buildbot.buildbot.net/#/builders/126/builds/128
https://buildbot.buildbot.net/#/builders/122/builds/1120

WARNING: Building wheel for buildbot failed: [Errno 28] No space left on device: '/home/buildbot/.cache/pip/wheels/62'
https://buildbot.buildbot.net/#/builders/127/builds/132

This applies at least to

• p12-pd-4
• p12-pd-5
• p12-pd-6
• p12-pd-14
• p12-pd-19
• p12-pd-33
• p12-pd-34
• p12-pd-37
• p12-pd-38
• p12-pd-39