dvc: `lock` file ignored when command is run more than one time

[algomaster99]

Version

DVC version: 0.70.0
Python version: 3.7.3
Platform: Linux-5.0.0-36-generic-x86_64-with-Ubuntu-18.04-bionic
Binary: False
Package: pip
Cache: reflink - False, hardlink - True, symlink - True

Problem

.dvc/lock is ignored when a dvc command is run for the second time.

Expected behaviour

When dvc status is run for the second time, it should throw an error since .dvc/lock isn't deleted yet so it should have prevented the command from running.

Reproduce

1. Manually created lock file.

$ touch .dvc/lock

1. Run dvc status. (Throws error)

>>>
ERROR: failed to obtain data status - cannot perform the command because another DVC process seems to be running on this project. If that is not the case, manually remove `.dvc/lock` and try again.

1. Run ls .dvc to check if lock is still present.

$ ls .dvc
>>> cache  config  lock  state  tmp  updater

1. Run dvc status again.
   Runs successfully. It should not since lock is still present.

[shcheklein]

@mroutis could you triage this and see if it's an actual bug or expected?

[ghost]

@shcheklein , @algomaster99 , this is the expected behavior.
The lock is being broken because its lifetime expired already.
The lifetime of a flufl.lock is based on its mtime.
If you do instead: touch -mt 2001010000 .dvc/lock, the lock will be unbreakable until January 1st, 2020

Reading https://github.com/retinator/flufl.lock source code was a delightful experience (_read it with a British accent_); @algomaster99 , if you are interested to know how it works internally, I truly recommend you to grab a glass/cup of your favorite beverage and go through the code in one sit, it is short and well documented :ok_hand:

By the way, you can go to dvc/logger.py and turn down the level for flufl.lock logger to DEBUG and you'll get plenty of useful messages to understand what's happening :slightly_smiling_face:

I'll close this issue since the lock created by DVC doesn't get ignored:

dvc run sleep 1000 &
dvc status
dvc status

[efiop]

@mroutis That seems pretty weird. We set the lifetime to be over a year https://github.com/iterative/dvc/blob/master/dvc/lock.py#L62 so why does it break after one check? CC @Suor

[ghost]

@efiop , @algomaster99 was trying to emulate a _lockfile_ by using touch .dvc/lock directly.
DVC sets the time correctly to 1 year :slightly_smiling_face:

[efiop]

@mroutis Oh! Makes total sense! Sorry, didn't get that one right away. Great research! 🙏

To summarize, the way flufl sets a lifetime, is it sets mtime on the file to a 1 year from now on.

[algomaster99]

@mroutis @efiop Thanks for the explanation! How come its (lock created manually) expiry finishes just after the first run?

[Suor]

As far as I remember there is a grace period of several second built in, to compensate for time being not in sync across network. So if you touch it and then run status fast enough you'll get locked. Just a guess.