Seen recently on 2 hosts:

Sending privdata (73139 bytes) to kite.kitenet.net ... done
fatal: Couldn't find remote ref HEAD
propellor: <stdout>: hPutStr: illegal operation (handle is closed)
fatal: The remote end hung up unexpectedly
Sending git update to kite.kitenet.net ... failed

Despite the error, HEAD seems to be updated to the commit that is being spun, but the rest of the propellor runs doesn't happen. --Joey

This was happening spinning kite at my Mom's, but not from home.

Earlier, it was happening spinning clam from home, when clam had debian oldstable on it (new install).

So, transient and/or network-related.. --Joey

Happening again spinning kite over satelite, but not other hosts. I enabled propellor.debug, and here's what it showed on kite:

Sending privdata (73139 bytes) to kite.kitenet.net ... done
[2017-06-18 16:01:08 EDT] received marked PRIVDATA 
[2017-06-18 16:01:08 EDT] requested marked GITPUSH
[2017-06-18 16:01:11 EDT] received marked GITPUSH
[2017-06-18 16:01:11 EDT] command line:  GitPush 11 12
fatal: Couldn't find remote ref HEAD
propellor: <stdout>: hPutStr: illegal operation (handle is closed)
fatal: The remote end hung up unexpectedly
Sending git update to kite.kitenet.net ... failed

Seem that what's failing is "git fetch" when propellor runs it with --upload-pack used to run propellor --gitpush.

The "fatal: Couldn't find remote ref HEAD" comes from git fetch, I think when no HEAD is in the list of remote refs.

The hPutStr error was a red herring; errorMessage was using outputConcurrent. After I fixed it to use errorConcurrent, it displayed the "git fetch from client failed" error message instead.

Next step is probably to enable GIT_TRACE_PACKET debugging of the git fetch. I did so on kite, but then propellor --spin succeeded. Here's the debug output I got when it worked, for later comparison next time it fails. Note the HEAD ref is given first thing.

Sending privdata (73139 bytes) to kite.kitenet.net ... done
[2017-06-18 16:27:12 EDT] received marked PRIVDATA 
[2017-06-18 16:27:12 EDT] requested marked GITPUSH
[2017-06-18 16:27:13 EDT] received marked GITPUSH
[2017-06-18 16:27:13 EDT] command line:  GitPush 11 12
16:27:13.953638 pkt-line.c:80           packet:        fetch< 3a3c8a731d169a2768dd243581803dcb7b275049 HEAD\0multi_ack thin-pack side-band side-band-64k ofs-delta shallow deepen-since deepen-not deepen-relative no-progress include-tag multi_ack_detailed symref=HEAD:refs/heads/joeyconfig agent=git/2.11.0
16:27:13.953781 pkt-line.c:80           packet:        fetch< 86b077b7a21efd5484dfaeee3c31fc5f3c151f6c refs/heads/confpairs
16:27:13.953789 pkt-line.c:80           packet:        fetch< e03e4bf0f1e557f87d1fe7e01a6de7866296fce6 refs/heads/d-i
16:27:13.953795 pkt-line.c:80           packet:        fetch< 3a3c8a731d169a2768dd243581803dcb7b275049 refs/heads/joeyconfig
16:27:13.953801 pkt-line.c:80           packet:        fetch< ee56d3793be3a8c0c268d8afdc642ef92b879269 refs/heads/master
16:27:13.953807 pkt-line.c:80           packet:        fetch< 51be061c90ca7539d7f8b804007cd9942f316860 refs/heads/precompiled
16:27:13.953812 pkt-line.c:80           packet:        fetch< 48c0e1107ea4a89a22e71c1cba0bdc238d119a9f refs/heads/resourceconflict
16:27:13.953818 pkt-line.c:80           packet:        fetch< dbfac89a85485f8ca2107792a3ce964c06adefbf refs/heads/typed-os-requirements
16:27:13.953823 pkt-line.c:80           packet:        fetch< 96a4fcf180885788959d7dc136dbef544270fa81 refs/heads/wip-bytestring-privdata
16:27:13.953829 pkt-line.c:80           packet:        fetch< ee35c58303221ddb4c83c33eb12a52c59cd482c2 refs/remotes/abailly/master
16:27:13.953834 pkt-line.c:80           packet:        fetch< baf65fa9fff4b8451ba7f1ee129484723a8deb9b refs/remotes/db48x/fstab-swap
16:27:13.953839 pkt-line.c:80           packet:        fetch< 7d8f9dbf60f8ab345a75c4ee4f8c457d0fde5b43 refs/remotes/db48x/git-in-emtpy-directory
16:27:13.953844 pkt-line.c:80           packet:        fetch< 17abde8439d17d49676f549f357f45eb2adce868 refs/remotes/db48x/master
16:27:13.953849 pkt-line.c:80           packet:        fetch< de50503e4dbdea853e899f01e8828cf4f454dd57 refs/remotes/dgit/dgit/sid
(omitted 300+ lines of refs)
16:27:14.352945 pkt-line.c:80           packet:        fetch< 0000
From .
 * branch              HEAD       -> FETCH_HEAD
16:27:14.379922 pkt-line.c:80           packet:        fetch> 0000
Sending git update to kite.kitenet.net ... done

Aha! My next spin failed again, with this debug:

Sending privdata (73139 bytes) to kite.kitenet.net ... done
[2017-06-18 16:31:15 EDT] received marked PRIVDATA 
[2017-06-18 16:31:15 EDT] requested marked GITPUSH
[2017-06-18 16:31:16 EDT] received marked GITPUSH
[2017-06-18 16:31:16 EDT] command line:  GitPush 11 12
16:31:16.361717 pkt-line.c:80           packet:        fetch< 17abde8439d17d49676f549f357f45eb2adce868 refs/remotes/db48x/master

So there's an actual protocol error here; the first 13 lines of git protocol were not sent.

Question now is, where is the mangling happening?

  • Fairly sure it's not on the local side's sendGitUpdate, where "git upload-pack ." is simply run and fed over ssh.
  • Could be in gitPushHelper, perhaps it's failing to write some of the first lines somehow?
  • Could be something on the remote side is consuming stdin that is not supposed to, and eats some of the protocol.

I added debug dumping to gitPushHelper, and it seems to be reading the same truncated data, so it seems the problem is not there.

Aha! The problem comes from stdin/stdInput confusion here:

    req NeedGitPush gitPushMarker $ \_ -> do
        hin <- dup stdInput
        hout <- dup stdOutput
        hClose stdin
        hClose stdout

A line read from stdin just before the dup gets the first line of the protocol as expected. But reading from stdInput starts with a later line. Apparently data is being buffered in the stdin Handle, so gitPushHelper, which reads from the Fd, does not see it.

Here's a simple test case. Feeding this 2 lines on stdin will print the first and then fail with "hGetLine: end of file". The second line is lost in the buffer. This test case behaves like that reliably, so I'm surprised propellor only fails sometimes.

main = do
        l <- hGetLine stdin
        print l
        bob <- fdToHandle stdInput
        l2 <- hGetLine bob
        print l2

I thought I'd fixed this by disabling buffering of stdin, but it seems not.

Seems really done at last! --Joey