darcs

Issue 2424 First push fails, second succeeds

Title First push fails, second succeeds
Priority Status resolved
Milestone 2.8.5 Resolved in 2.8.5
Superseder Nosy List ganesh, lelf, steffenfritz
Assigned To
Topics

Created on 2014-12-01.06:35:17 by steffenfritz, last changed 2015-01-28.23:59:59 by ganesh.

Files
File name Uploaded Type Edit Remove
darcs_local_apply_fails.txt amp, 2014-12-05.07:44:07 text/plain
darcs_local_apply_succ.txt amp, 2014-12-05.07:44:51 text/plain
Messages
msg17870 (view) Author: steffenfritz Date: 2014-12-01.06:35:15
Description:
=========

When a patch is pushed to a remote repository via ssh or applied locally, the 
first try fails.

Output of 'darcs push'
------------------------------------

<snip>

darcs failed:  Couldn't fetch 
0000000369b60776b9ae996a253f8a5a296927293faab87036846b34b0e710c9fc0f58429b'
in subdir inventories from sources:

thisrepo:/usr/home/me/darcs_repos/ar_report
cache:/home/me/.darcs/cache


HINT: I could not reach the following repositories:
    /home/me/.darcs/cache
    /usr/home/me/darcs_repos/ar_report
  If you're not using them, you should probably delete
  the corresponding entries from _darcs/prefs/sources.
Apply failed!

</snip>

A second attempt works without problems.

First push also fails when a patch is created with 'darcs send -O', copied to 
the remote machine and applied there. Second attempt succeeds.


Output of 'darcs apply --debug'
-------------------------------------------------

Beginning identifying repository .
Done identifying repository .
Identified darcs-2 repo: /usr/home/steffen/darcs_repos/ar_report
Beginning defining set of chosen patches
Done defining set of chosen patches
Checking for conflicts...
Announcing conflicts...
Checking for unrecorded conflicts...
Beginning identifying repository .
Done identifying repository .
Reading working directory...
Working out conflicts in actual working directory...
Applying patches to the local directories...
Adding patches to inventory...
Writing hash file to patches
No sources from which to fetch file 
`0000002770-17c73051a32c92fb5a4419e16683cfc8bee8fed14fbec71a0abea1c8ca3d2b7e'
thisrepo:/usr/home/steffen/darcs_repos/ar_report
cache:/home/steffen/.darcs/cache

Couldn't fetch 
`0000002770-17c73051a32c92fb5a4419e16683cfc8bee8fed14fbec71a0abea1c8ca3d2b7e'
in subdir patches from sources:

thisrepo:/usr/home/steffen/darcs_repos/ar_report
cache:/home/steffen/.darcs/cache

Applying patches to pristine...
Considering whether to test...
Considering whether to test...
Considering whether to test...
Finalizing changes...
Optimizing the inventory...
in writeEitherInventory...
Beginning writing inventory
Beginning optimizing inventory
Done optimizing inventory
Writing hash file to inventories
No sources from which to fetch file 
`0000001154-72ca51033edf2df83010de796d0ea255b8171b6a6ceb7470ee027b50b5538c5f'
thisrepo:/usr/home/steffen/darcs_repos/ar_report
cache:/home/steffen/.darcs/cache

Couldn't fetch 
`0000001154-72ca51033edf2df83010de796d0ea255b8171b6a6ceb7470ee027b50b5538c5f'
in subdir inventories from sources:

thisrepo:/usr/home/steffen/darcs_repos/ar_report
cache:/home/steffen/.darcs/cache

Done writing inventory
still in writeEitherInventory...
I'm doing copyFileUsingCache on 
inventories/0000001154-72ca51033edf2df83010de796d0ea255b8171b6a6ceb7470ee027b50b5538c5f
No sources from which to fetch file 
`0000001154-72ca51033edf2df83010de796d0ea255b8171b6a6ceb7470ee027b50b5538c5f'
thisrepo:/usr/home/steffen/darcs_repos/ar_report
cache:/home/steffen/.darcs/cache

Couldn't fetch 
`0000001154-72ca51033edf2df83010de796d0ea255b8171b6a6ceb7470ee027b50b5538c5f'
in subdir inventories from sources:

thisrepo:/usr/home/steffen/darcs_repos/ar_report
cache:/home/steffen/.darcs/cache


darcs failed:  Couldn't fetch 
`0000001154-72ca51033edf2df83010de796d0ea255b8171b6a6ceb7470ee027b50b5538c5f'
in subdir inventories from sources:

thisrepo:/usr/home/steffen/darcs_repos/ar_report
cache:/home/steffen/.darcs/cache


HINT: I could not reach the following repositories:
        /home/steffen/.darcs/cache
        /usr/home/steffen/darcs_repos/ar_report
      If you're not using them, you should probably delete
      the corresponding entries from _darcs/prefs/sources.



Reproduction
=========
1) darcs get $URL
2) modify local copy
3) darcs record -m "some text"
4) darcs push
--fails--
5) darcs push
--succeeds-- 



Additional Info:
==========

Used systems:

Server / gets patch:
FreeBSD 10.0-RELEASE-p12 amd64
darcs version: 2.8.4 (+ 1 patch)

Client / pushs patch:
Arch Linux 3.17.3-1-ARCH x86_64
darcs version: 2.8.0 (release)
msg17874 (view) Author: ganesh Date: 2014-12-04.06:33:55
For other people's background, this bug report originated here: 
http://stackoverflow.com/questions/26972799/darcs-first-push-fails

I've looked through the source and I think this must be some kind of glitch 
in the underlying filesystem. The file that triggers the error is one that 
should just have been written to disk. Is the repository on a network 
filesystem or subject to some kind of virus scanning?

Some kind of problem with immediately reading a file after it's been written 
would explain why it works the second time, because then the same file would 
already be there.

If you can strace the execution that might validate my belief - I'd expect 
to see a write to the file that causes the 'darcs failed' error immediately 
followed by a failed read.
msg17875 (view) Author: ganesh Date: 2014-12-04.12:12:01
Another interesting (and cheap) experiment would be to try to reproduce 
in a shell one-liner:

echo foo > somenewfilename ; cat somenewfilename
msg17876 (view) Author: steffenfritz Date: 2014-12-04.15:06:10
echo foo > somenewfilename ; cat somenewfilename

gives the expected output "foo".

On FreeBSD is no strace available, but I did some truss'ing. 

I created a patch with darcs send -O, copied it to the repo and run

truss darcs apply test_patch.dpatch

Output:

<snip>

mmap(0x0,4194304,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANON,-1,0x0) = 34556870656 (0x80bc00000)
clock_gettime(4,{344609.006372268 })             = 0 (0x0)
_umtx_op(0x800f91e90,0xf,0x0,0x0,0x0,0x0)        = 0 (0x0)
_umtx_op(0x80b006e58,0x15,0x1,0x0,0x0,0x1)       = 0 (0x0) SIGNAL 14 (SIGALRM)
_umtx_op(0x800b76038,0xf,0x0,0x0,0x0,0x0)        ERR#4 'Interrupted 
system callsigreturn(0x7fffffff8f40,0xd,0x800d83d60,0x0,0xffffffff0fffffff,0x7fffffff98b8)
sigreturn(0x7fffffff8f40,0xd,0x800d83d60,0x0,0xffffffff0fffffff,0x7fffffff98b8) ERR#87 'Attribute not found'
getcontext(0x7fffffff9450,0x800d7c65b,0x178bfbff,0x802009,0x0,0x7fffffff98b8) = 0 (0x0)

</snip>

It is a local UFS filesystem, no antivirus software running.
msg17877 (view) Author: ganesh Date: 2014-12-04.17:32:30
Could you send the entire truss log? If you're entering messages 
directly in the roundup UI you can use "Choose file" at the top of the 
ticket, or just attach it to an email you send to the tracker.
msg17878 (view) Author: amp Date: 2014-12-05.07:28:58
Here comes an update:

I ssh'd into the FreeBSD box, created a directory in my homedir,
initialized a darcs repo, added the file "test.txt", tried to record the
changes and this last step fails. 

mkdir test
cd test
darcs init
touch test.txt
darcs add test.txt
darcs record -m "test record"


addfile ./test.txt
Shall I record this change? (1/1)  [ynW...], or ? for more options: a

darcs failed:  Couldn't fetch
`0000000179-41f0246d2d4ff11c659813eafe61381c4ca8a33d1d1d6b8150935c3fbece39ce'
in subdir inventories from sources:

thisrepo:/usr/home/me/darcs_repos/test
cache:/home/me/.darcs/cache

Failed to record patch 'test record'


HINT: I could not reach the following repositories:
        /home/me/.darcs/cache
        /usr/home/me/darcs_repos/test
      If you're not using them, you should probably delete
      the corresponding entries from _darcs/prefs/sources.


A second attempt does NOT succeed, it keeps failing. Is this related?
However, I will submit the truss report in the following message.
msg17879 (view) Author: amp Date: 2014-12-05.07:44:07
This is the truss report when the applying fails. In the following
message you find the report of the successful try.
Attachments
msg17880 (view) Author: amp Date: 2014-12-05.07:44:51
This is the truss report when the applying succeeds.
Attachments
msg17881 (view) Author: ganesh Date: 2014-12-05.08:35:35
The behaviour of 'darcs record' you describe is consistent with what 
we're seeing with 'darcs apply'.

The difference is that 'record' creates new metadata (timestamp and a 
random salt) each time you run it, so darcs won't be trying to write an 
identical file the second time round, so will still fail.

I'll dig through the truss files as soon as I have time. Are you able to 
build Haskell programs from source on this machine? One avenue for 
debugging further may be for you to run either a custom darcs or a 
custom Haskell program to test out the theory about writes/reads.
msg17890 (view) Author: ganesh Date: 2014-12-10.07:45:19
The truss log tends to contradict my theory about immediately re-
reading the file, as it successfully stats the file and then 
immediately fails without trying to open it.

Can you build darcs for yourself for the server? If so could you try 
the version at http://hub.darcs.net/ganesh/darcs-2.8-issue2424 which 
should include the underlying error message when it fails to read 
the file causing the failure. If you can run this then please 
provide the 'darcs apply --debug' output again.
msg17948 (view) Author: lelf Date: 2015-01-24.18:24:23
FYI I see the bug in 2.8.4, but 2.8.5 is ok
msg17955 (view) Author: steffenfritz Date: 2015-01-26.07:43:44
I confirm.

Am Samstag, 24. Januar 2015, 18:24:24 schrieb Antonio Nikishaev:
> Antonio Nikishaev <anton.nik@gmail.com> added the comment:
> 
> FYI I see the bug in 2.8.4, but 2.8.5 is ok
> 
> __________________________________
> Darcs bug tracker <bugs@darcs.net>
> <http://bugs.darcs.net/issue2424>
> __________________________________
msg17960 (view) Author: bfrk Date: 2015-01-28.20:59:11
Can you try the HEAD (current screened)? If that works, we should close
it as "fixed in 2.8.5"... only that this option does not yet exist in
the tracker, hmmm.
msg17964 (view) Author: ganesh Date: 2015-01-28.23:59:57
If it's fixed in 2.8.5 then I suspect it's to do with issue2364 
which was fixed between 2.8.4 and 2.8.5, and was also fixed on HEAD. 
The symptoms didn't match very well which was why I didn't think of 
that before.

I've added 2.8.5 to the list and resolved this.
History
Date User Action Args
2014-12-01 06:35:17steffenfritzcreate
2014-12-04 06:33:57ganeshsetmessages: + msg17874
2014-12-04 12:12:03ganeshsetmessages: + msg17875
2014-12-04 15:06:11steffenfritzsetmessages: + msg17876
2014-12-04 17:32:32ganeshsetmessages: + msg17877
2014-12-05 07:29:00ampsetmessages: + msg17878
2014-12-05 07:44:12ampsetfiles: + darcs_local_apply_fails.txt
messages: + msg17879
2014-12-05 07:44:54ampsetfiles: + darcs_local_apply_succ.txt
messages: + msg17880
2014-12-05 08:35:37ganeshsetmessages: + msg17881
2014-12-10 07:45:21ganeshsetstatus: unknown -> needs-diagnosis/design
messages: + msg17890
2015-01-24 17:49:18lelfsetnosy: + lelf
2015-01-24 18:24:24lelfsetmessages: + msg17948
2015-01-26 07:43:46steffenfritzsetmessages: + msg17955
2015-01-28 20:59:13bfrksetmessages: + msg17960
2015-01-28 23:59:59ganeshsetstatus: needs-diagnosis/design -> resolved
resolvedin: 2.8.5
messages: + msg17964
milestone: 2.8.5