To reproduce: 

darcs init --hashed --repodir=u2
cd darcs-unstable-repo
time -p darcs push -a --no-set ../u2
Resolving conflicts 5/27
Apply failed!
real 862.99
user 731.10
sys 3.98

###

Darcs takes a very long time and then results in "apply failed". Another minor
bug was expected in the process: The count of conflicts being resolved jumped
around, rather than only increasing. The total count of conflicts to resolve
went up to 600 at one point, and then back down to 27. I would have expected
that the total would only increase. 

Perhaps this issue is considered "resolved in unstable" because it wouldn't
happen on projects starting from scratch with Darcs 2, even though it happens
this repo which created earlier. 

I was somewhat surprised that pushing to an empty repo didn't approach the
efficiency of a "darcs put".

    Mark

I re-tested this tonight. Besides that it still fails with "hashed" repo, I
tested again after first converting the darcs-unstable repo to the --darc-2 format. 

It fails like this when I do the push with --debug-verbose:

Beginning reading pristine
darcs apply --all --repodir ../u2
Disabling progress reports...
Reenabling progress reports.
Apply failed!

Maybe I can try again by creating a giant patch with "send" and they applying
with it "apply --debug-verbose".

Well, I had a breakthrough of sorts with this issue. 

I used darcs send -O to generate the patch, and "darcs apply --debug-verbose" to
apply it. Using that method, the patch applied cleanly, when a direct "push"
failed! I'm not sure that means, but I imagine it should help narrow down the
issue.

That's encouraging! I've reproduced this myself now.

FWIW I spent quite a while today trying to debug this effect with little
success.  We're having runProcess return ExitFailure 127, which supposedly (from
a google search) is the exit code for "command not found", which would explain
why the darcs apply never gives any output.  What I'm at a loss to explain is
why this is triggered.

It doesn't help that I can't figure out any way to trigger this bug in less than
six or so minutes.  :(

I've confirmed what Mark said, that if I use darcs send and then apply to do the
same work, I don't see any failure.  I haven't yet tried grabbing the temporary
file that darcs push generates and feeding that file to darcs apply manually,
but I should should do that.

In the meantime, I'm wondering if Simon (who I think wrote System.Process?)
could give me any hints as to how to go about debugging a call to runProcess
that seems to exit without any trace of having actually called darcs.  :(

David (who is most puzzled)

> In the meantime, I'm wondering if Simon (who I think wrote
> System.Process?)
> could give me any hints as to how to go about debugging a call to
> runProcess
> that seems to exit without any trace of having actually called darcs.  :(

The problem is that after the fork, there's no way to return an error to the parent other than via the exit code, which is why you get exit(127) for "file not found" (this is the same as C's system(), IIRC).

The way to debug it is by using strace -f.

Cheers,
        Simon

Is there any possibility that the environment isn't passed along 
properly, particularly the PATH variable?

Having a reality check that the darcs binary is present and executable 
before calling it would address this, but you may already be doing that 
kind of check.

<thinks>

Of course, in my case that check would not have been enough, because I 
have darcs-1 in /usr/bin, but was using a "private" darcs 2. So the 
reality check of the binary would need to involve testing the version 
(or some other feature) to determine if it is capable of this operation. 
Perhaps testing that there is a "--hashed" flag for "darcs --init"?

OTOH, perhaps you have a way to say to "call exactly the binary we are 
already using", which seems the most reliable of all. (And again, 
perhaps you already do that).

I'm just brainstorming...this seems mysterious to me too.

    Mark

Simon, thanks for the suggestion (and explanation).  Unfortunately, when I call
push with strace -f, I get failure well before it gets to the fork, with the
following:

stat("_darcs", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
stat("_darcs/prefs/defaults", {st_mode=S_IFREG|0644, st_size=23, ...}) = 0
open("_darcs/prefs/defaults", O_RDONLY|O_NONBLOCK|O_NOCTTY) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=23, ...}) = 0
fcntl(3, F_GETFL)                       = 0x8800 (flags
O_RDONLY|O_NONBLOCK|O_LARGEFILE)
fcntl(3, F_SETFL, O_RDONLY|O_NONBLOCK|O_LARGEFILE) = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=23, ...}) = 0
ioctl(3, SNDCTL_TMR_TIMEBASE or TCGETS, 0x7fffe3bdf120) = -1 ENOTTY
(Inappropriate ioctl for device)
fstat(3, {st_mode=S_IFREG|0644, st_size=23, ...}) = 0
read(3, "apply --mark-conflicts\n", 8192) = 23
close(3)                                = 0

Any idea what this ioctl is, or why it's failing when running under strace?

David

David Roundy wrote:
> 
> Simon, thanks for the suggestion (and explanation).  Unfortunately, when I call
> push with strace -f, I get failure well before it gets to the fork, with the
> following:
> 
> stat("_darcs", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
> stat("_darcs/prefs/defaults", {st_mode=S_IFREG|0644, st_size=23, ...}) = 0
> open("_darcs/prefs/defaults", O_RDONLY|O_NONBLOCK|O_NOCTTY) = 3
> fstat(3, {st_mode=S_IFREG|0644, st_size=23, ...}) = 0
> fcntl(3, F_GETFL)                       = 0x8800 (flags
> O_RDONLY|O_NONBLOCK|O_LARGEFILE)
> fcntl(3, F_SETFL, O_RDONLY|O_NONBLOCK|O_LARGEFILE) = 0
> fstat(3, {st_mode=S_IFREG|0644, st_size=23, ...}) = 0
> ioctl(3, SNDCTL_TMR_TIMEBASE or TCGETS, 0x7fffe3bdf120) = -1 ENOTTY
> (Inappropriate ioctl for device)
> fstat(3, {st_mode=S_IFREG|0644, st_size=23, ...}) = 0
> read(3, "apply --mark-conflicts\n", 8192) = 23
> close(3)                                = 0
> 
> Any idea what this ioctl is, or why it's failing when running under strace?

That's just GHC testing whether the file descriptor is a TTY or not, the 
failure is not fatal.

Cheers,
	Simon

I've confirmed that this error has nothing to do with calling darcs, by changing
the push code to call "echo" rather than "darcs".  In this case, when pushing
just a few patches, I get:

$ time darcs push
Pushing to "../darcs-central"...
Wed Feb 20 12:19:20 EST 2008  David Roundy <droundy@darcs.net>
  * give better error message when we get "command not found" == ExitFailure 127.
Shall I push this patch? (1/1)  [ynWsfvpxdaqjk], or ? for help: y
apply --all --repodir ../darcs-central
Push successful.

In other words, echo works fine.  When pushing the entire darcs repository, I get:

$ darcs push /tmp/foo -a --no-set-default
Command not found:
   ["echo","apply","--all","--repodir","/tmp/foo"]
Apply failed!

Where the "Command not found" message is now printed when waitForProcess returns
ExitFailure 127.

In other words, for some reason runProcess is failing after the fork, and is
returning an exit code of 127, and it's highly unlikely that it's actually
failing to execute the command.  Perhaps the problem involves the file handle
that's used to provide input to the runProcess?

David (thoroughly perplexed, and hoping Simon can help)

Okay, I've finally tracked this down.  The problem was the environment variables
defined for the posthook, which turned out in this case to be so big as to cause
an E2BIG error when passing them to darcs apply.  I've chosen the solution of
restricting these env vars to 1k max size.

David Roundy wrote:
> 
> Okay, I've finally tracked this down.  The problem was the environment variables
> defined for the posthook, which turned out in this case to be so big as to cause
> an E2BIG error when passing them to darcs apply.  I've chosen the solution of
> restricting these env vars to 1k max size.

Great work, David!

While the XML still be valid, or just truncated?

It seems like a little bit of a tricky problem to solve well.

    Mark

On Thu, Feb 21, 2008 at 04:34:33PM -0000, Mark Stosberg wrote:
> David Roundy wrote:
> > Okay, I've finally tracked this down.  The problem was the environment variables
> > defined for the posthook, which turned out in this case to be so big as to cause
> > an E2BIG error when passing them to darcs apply.  I've chosen the solution of
> > restricting these env vars to 1k max size.
> 
> Great work, David!
> 
> While the XML still be valid, or just truncated?
> 
> It seems like a little bit of a tricky problem to solve well.

Actually, it'll be set to a single space " " if there are either no
changes, or if the set of changes is too large.  We could implement a
special message, but that didn't seem worthwhile at this stage.
-- 
David Roundy
Department of Physics
Oregon State University

David Roundy wrote:
>>
>> While the XML still be valid, or just truncated?
>>
>> It seems like a little bit of a tricky problem to solve well.
> 
> Actually, it'll be set to a single space " " if there are either no
> changes, or if the set of changes is too large.  We could implement a
> special message, but that didn't seem worthwhile at this stage.

I agree something simple seems reasonable now.

I would advocate when plain text is expected, the message would provide 
a clue, like

"ERROR: Environment variables larger than 1k were detected and have been 
discarded to avoid problems."

The XML could also be something simple and well-formed and convey that 
message.

Still, what you've already was the key hurdle to get over.

Thanks!

      Mark

The following patch updated the status of issue672 to be resolved in the unstable branch:

* resolve issue672: defining environment variables for the posthook caused E2BIG error. 
The solution chosen for this was simply to restrict environment variables
passed to posthooks to a maximum value of 1k.

You can view the patch details online here: 
http://darcs.net/cgi-bin/darcs.cgi/unstable/?c=annotate&p=20080221161733-72aca-b97b6bdbe9c2da19a1edad51fd32821e133cd840.gz