cvs checkout is racy, it wasn't in the past

[Robert Collins]

cvs checkout returns within the same second that the Entries files contain, this
leads to missed commits, when scripts are performing operations on fast machines.

** See below for a test case. (Bug triagers especially: run the test before changing status. This bug has had enough attention of inattentive bug triagers.)

[Robert Collins (lifeless)]

Created an attachment (id=1142)
a test case to trigger the problem

this shows the problem, often. being a race condition it doesn't always occur.

[Matt Zimmerman (mdz)]

(In reply to comment #0)
> cvs checkout returns within the same second that the Entries files contain, this
> leads to missed commits, when scripts are performing operations on fast machines.

I think I understand the issue, but could you explain in complete sentences to
confirm?

[Robert Collins (lifeless)]

There is a race condition when using cvs, where cvs returns to the caller within
the same second as one or more entries within its created Entries files, this
combined with its ignoring files with mtimes the same as that recorded within
the Entries files results in cvs ignoring changes to said files that occur
within the same second.

[Matt Zimmerman (mdz)]

Are you sure it wasn't racy before? It seems like a design flaw. Did something
change in your test environment which has allowed the bug to surface? There
have been no relevant code changes since Warty that I see (and likely much
longer than that).

Is this blocking one of your projects? We could implement a (very slow)
workaround to bypass this optimization. Fixing it properly would seem to mean
breaking compatibility, and that needs to go through upstream.

[Colin Watson (cjwatson)]

I haven't looked at the code, but I'm sure I remember that cvs traditionally did
a sleep(1) before exit to avoid this problem.

[Matt Zimmerman (mdz)]

It does that after some operations, but checkout is not one of them as far as I
see. We can certainly add one there if necessary; the calling code could also
do the same as a workaround.

[Robert Collins (lifeless)]

the supplied test script demonstrates checkout with the race.

Yes the calling code does wait but it shouldn't have to - it adds an
unconditional delay, where CVS has enough information to /conditionally/ decide
if a delay is needed. In prior CVS versions, this race did not occur, which is
why I've open the bug rather than going 'cvs sucks more' ;)

[Robert Collins (lifeless)]

sorry about, this I'm replying to the bugzilla emails in reverse-chrono order ...

yes, I'm sure, same hardware, new cvs version, race suddenly appears.

Yes something did change : CVS got upgraded when I moved to Warty back in Oxford
(which is when my test suite started failing randomly - I've only just had time
to track down the cause).

I've put workarounds in cscvs for this, which has pushed the test suite run time
up hugely. So its not blocking.

Fixing it shouldn't require any compatability changes : just record the latest
timestamp written during the checkout process, and usleep to the start of the
next second before exiting.

[Matt Zimmerman (mdz)]

Not a high priority, but should be fixed for Hoary so that Robert can remove the
workaround and get better throughput

[Dennis Kaarsemaker (dennis)]

I see no evidence of such a patch in Breezy - did I miss something or was it
fixed in another way?

[Tor Harald Thorland (linux-strigen)]

Hi, Is this still an issue? Looks like it has been quiet for a while... If it's not, then we can maby close it :-)

[Robert Collins (lifeless)]

Theres an automatic test case at the very start of the bug: you can trivially see if its still an issue or not.

[Tor Harald Thorland (linux-strigen)]

I'm not a real bug buster, I'm just trying to help by closing/taking the dust away on old bugs, like looks like they are forgotten.

By heres my output on this one. about 70% success, 30%fail if i understand correct.

tortho@inspiron:~$ ./test-cvs-co.sh
N missing_commit/file1

No conflicts created by this import

cvs checkout: Updating missing_commit
U missing_commit/file1
cvs commit: Examining .
/home/tortho/working/cvs/missing_commit/file1,v <-- file1
new revision: 1.2; previous revision: 1.1
revision 1.2

tortho@inspiron:~$ ./test-cvs-co.sh
N missing_commit/file1

No conflicts created by this import

cvs checkout: Updating missing_commit
U missing_commit/file1
cvs commit: Examining .
revision 1.2 not present in the log

tortho@inspiron:~$

[Robert Collins (lifeless)]

On Wed, 2006-04-26 at 05:49 +0000, Tor Harald Thorland wrote:
> I'm not a real bug buster, I'm just trying to help by closing/taking the dust away on old bugs, like looks like they are forgotten.
>
> By heres my output on this one. about 70% success, 30%fail if i understand correct.

Thus this bug is still present.

Cheers,
Rob
--
GPG key available at: <http://www.robertcollins.net/keys.txt>.

[KarlGoetz (kgoetz)]

Seeing as Tor had the same issue in Dapper, i'm marking confirmed, not having a cvs server i cant test on current edgy.

[Robert Collins (lifeless)]

On Fri, 2006-07-28 at 08:08 +0000, KarlGoetz wrote:
> Seeing as Tor had the same issue in Dapper, i'm marking confirmed, not
> having a cvs server i cant test on current edgy.

Sure you can test - run the test sh script I provided way back. Its in
the bug report!

Rob
--
GPG key available at: <http://www.robertcollins.net/keys.txt>.

[KarlGoetz (kgoetz)]

Still happens :/, at
$ apt-cache policy cvs
cvs:
  Installed: 1:1.12.13-3
  Candidate: 1:1.12.13-3
  Version table:
 *** 1:1.12.13-3 0

[Dimitrios Symeonidis (azimout)]

Thank you for taking the time to report this bug and helping to make Ubuntu better. You reported this bug a while ago and there hasn't been any activity in it recently. We were wondering if this is still an issue for you. Can you try with the latest Ubuntu release? Thanks in advance.

[Robert Collins (lifeless)]

On Thu, 2009-04-16 at 23:38 +0000, Dimitrios Symeonidis wrote:
> Thank you for taking the time to report this bug and helping to make
> Ubuntu better. You reported this bug a while ago and there hasn't been
> any activity in it recently. We were wondering if this is still an issue
> for you. Can you try with the latest Ubuntu release? Thanks in advance.
>
> ** Changed in: cvs (Ubuntu)
> Status: Confirmed => Incomplete

status confirmed

If you took even 2 seconds to read the report you would fine included a
test script letting you reproduce it, and plenty of details which mean a
round trip to the reporter is a waste of time.

Thanks.

[Dimitrios Symeonidis (azimout)]

I was going to ignore this, but seeing the change in description, I can't resist:

Before my comment, the bug was last touched in 2006-07-29, i.e. 2.5 years ago.
The original bug reporter, with all due respect to your high karma, never bothered to come back every 6 months to just post a 1-line comment saying "this is still present in Gutsy/Hardy/Intrepid" etc.

I realize that reproducing one specific bug might seem trivial. However, you're making one wrong assumption here:
The reporter's time is scarce and valuable. The triager's time is infinite and cheap. Triagers should install ALL packages and reproduce all 45k bugs in launchpad, instead of asking reporters if the issue is still there.

It's just my opinion, that the above assumption is wrong. From experience (just yesterday I touched ~100 bugs like this) most people will just respond "No, it was fixed some time last year, you can close it", or they will never respond.

However, if you feel that Bugsquad has lots of triagers, and too few reporters, so we should leave the reporters alone and load the triagers with work, feel free to continue this strategy.

Goodnight, and good luck

[Thorsten Glaser (mirabilos)]

Please retry with cvs (2:1.12.13-4) once it has reached *buntu.
There are sleep calls in there.

[Thorsten Glaser (mirabilos)]

Actually, it became cvs 2:1.12.13+real-4 due to a need to replace the .orig.tar.gz…

[Thorsten Glaser (mirabilos)]

(changing status: waiting for you to retry)

[Thorsten Glaser (mirabilos)]

This doesn’t happen for me with cvs 2:1.12.13+real-5 and https://bugs.launchpad.net/ubuntu/+source/cvs/+bug/12230/+attachment/1831/+files/test-cvs-co.test

[Robert Collins (lifeless)]

I'll be able to retry this once I upgrade to oneiric.

[Dave Walker (davewalker)]

@Thorsten, thanks for looking into this. I'm not certain it is resolved. :(

@Robert, can you confirm a subset of my output please to confirm I have interpreted it correctly please?

Thanks

$ apt-cache policy cvs
cvs:
  Installed: 2:1.12.13+real-5ubuntu1
  Candidate: 2:1.12.13+real-5ubuntu1
  Version table:
 *** 2:1.12.13+real-5ubuntu1 0
        500 http://gb.archive.ubuntu.com/ubuntu/ oneiric/main amd64 Packages
        100 /var/lib/dpkg/status

dave@voodoo:~/tmp/scratch$ ./test-cvs-co.test
N missing_commit/file1

No conflicts created by this import

cvs checkout: Updating missing_commit
U missing_commit/file1
cvs commit: Examining .
revision 1.2 not present in the log
dave@voodoo:~/tmp/scratch$ ./test-cvs-co.test
N missing_commit/file1

No conflicts created by this import

cvs checkout: Updating missing_commit
U missing_commit/file1
cvs commit: Examining .
/home/dave/tmp/scratch/working/cvs/missing_commit/file1,v <-- file1
new revision: 1.2; previous revision: 1.1
revision 1.2
dave@voodoo:~/tmp/scratch$ ./test-cvs-co.test
N missing_commit/file1

No conflicts created by this import

cvs checkout: Updating missing_commit
U missing_commit/file1
cvs commit: Examining .
revision 1.2 not present in the log

[Robert Collins (lifeless)]

Looks like it worked on one run out of 3. So, not fixed.

[Thorsten Glaser (mirabilos)]

OK, confirm on a Xen domU on a decently fast amd64 system (zigo’s Debian machine),
no confirm on a slower Celeron 2G4Hz bare iron. This indeed seems to be a timing
issue; fix would be to sleep past checkout?

[Thorsten Glaser (mirabilos)]

This is very interesting.

Your script executes the following commands in order:

  cvs -d ${REPOSITORY} co missing_commit
  cd missing_commit
  echo "dead1" > file1

There’s nothing in between it.

In one of the “racy” cases, the following happens:
I put in a debug fprintf(stderr, …) with the result of time()

cvs co ⇒ time() returns 1311862167

tg@zigo:~/X $ date -d @1311862167
Thu Jul 28 14:09:27 UTC 2011

tg@zigo:~/X $ stat working/missing_commit/file1
  File: `working/missing_commit/file1'
  Size: 6 Blocks: 8 IO Block: 4096 regular file
Device: ca00h/51712d Inode: 667057 Links: 1
Access: (0644/-rw-r--r--) Uid: ( 1000/ tg) Gid: ( 1000/ tg)
Access: 2011-07-28 14:09:26.000000000 +0000
Modify: 2011-07-28 14:09:26.000000000 +0000
Change: 2011-07-28 14:09:26.000000000 +0000

So the question is rather: why is the file changed with an atime/mtime/ctime
that lies in the past?

[Thorsten Glaser (mirabilos)]

It gets funnier: I changed the script now:

echo = co
  cvs -d ${REPOSITORY} co missing_commit
date +%s
  cd missing_commit
  echo "dead1" > file1
echo = ci
  cvs ci -m "dead1"

This is the output I get:

[…]
= co
cvs checkout: Updating missing_commit
U missing_commit/file1
{sleep:1311862405<1311862405=0}
{slept:1311862406<1311862405=-1}
1311862406
= ci
cvs commit: Examining .
= log
revision 1.2 not present in the log

This is the dates:

tg@zigo:~/X $ date -d @1311862406
Thu Jul 28 14:13:26 UTC 2011
tg@zigo:~/X $ stat working/missing_commit/file1
  File: `working/missing_commit/file1'
  Size: 6 Blocks: 8 IO Block: 4096 regular file
Device: ca00h/51712d Inode: 667057 Links: 1
Access: (0644/-rw-r--r--) Uid: ( 1000/ tg) Gid: ( 1000/ tg)
Access: 2011-07-28 14:13:25.000000000 +0000
Modify: 2011-07-28 14:13:25.000000000 +0000
Change: 2011-07-28 14:13:25.000000000 +0000

WAAH?! Definitively not a bug in CVS.

[Thorsten Glaser (mirabilos)]

Short question: does that “race” happen on bare iron too, or just on virtualised environments?

[Thorsten Glaser (mirabilos)]

Got a workaround: just sleep 20ms more unless we’re already more than a second past the time.

Even cjwatson had no idea about this…

[Robert Collins (lifeless)]

See comment 3.

[Thorsten Glaser (mirabilos)]

No because CVS returns *one second later* (see in the example I pasted
it’s 14:13:26 when CVS returns).

Then, the file1 gets created with an mtime of 14:13:25 *although* it’s
already been 14:13:26 before it, according to date(1).

So Comment #3 is untrue at least for the versions of CVS I maintain.

(Anyway, you got a workaround, and cjwatson said he’ll initiate a sync
as soon as it’s available – the benefit of sitting across each other
during Debconf ☺)

[Thorsten Glaser (mirabilos)]

Actually, the fix you suggested in comment #8 is part of stock GNU CVS 1.12.13

[Robert Collins (lifeless)]

Ah, so that suggests the issue goes deeper, if its still reproducable :(.

[Thorsten Glaser (mirabilos)]

Yes, but stracing it wasn’t, and a 20-ms additional sleep (2 HZ, after all)
seems to help as well. The -6 upload _should_ work now.

Of course, if anyone finds the real problem, do tell…

[Launchpad Janitor (janitor)]

This bug was fixed in the package cvs - 2:1.12.13+real-6

---------------
cvs (2:1.12.13+real-6) unstable; urgency=low

  * d/watch: mangle the +real away until 1.12.14 is out,
    as this is an artefact from the old (epoch 1) packaging
  * Demote mksh to Suggests, recommended (hah!) by many
    (Closes: #631110) (merges back 2:1.12.13+real-5ubuntu1)
  * Honour Policy §11.4; fix by YOSHINO Yoshihito (Closes: #631936)
  * Use upstream-source-in-CVS packaging, clean up
  * d/rules: Add build-{arch,indep} targets as aliases to build
  * Bring d/copyright more in sync with this distfile’s reality
  * d/control: Reword package description. (Closes: #631826)
  * If sleeping at exit, sleep another 20 ms (2 HZ), to avoid
    possible race conditions. (Should work around LP: #12230)
  * Update in sync with MirPorts 1.12.13-12 = MirOS BSD 0AAF.1
  * Stop installing cvsbug(8), use reportbug instead
 -- Thorsten Glaser <email address hidden> Fri, 29 Jul 2011 08:58:16 +0000