spin failure HEAD

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

RSS

still in 5.3.6

I'm seeing this problem in 5.3.6, but only when the remote is Debian stable. Both ends are running 5.3.6 built from source.

Comment by david — Fri Aug 24 02:12:44 2018

Remove comment

still in 5.4.1, but only on one machine

I updated to 5.4.1, and I still consistenly see this trying to spin my office computer from home. Weirdly a VM running Debian stretch on the same network does not repropduce. I'll have to try from a different machine on the office network to see if that makes a difference.

Comment by david — Fri Aug 24 10:11:16 2018

definitely network related

I can spin the same host from a different host on the office LAN (in fact they are connected to a cheapo hub, so that might not be much of a test), and from itself. So I guess it definitely has to do with networking. Does propellor need anything other than port 22 open?

Comment by david — Fri Aug 24 13:58:49 2018

comment 4

As far as I know, this was fixed in a series of commits, 01fc1375cece096ab2dec480b843ecdbc4f0d94e 1555c6f88a0446d3e29149eff8315817696731e1 53fe5ffaac4a243bb9fd3cf0e757128150a6a199

The problem was intermittent for me, I think based on network timing and different buffering behavior with different timings, which made it hard to debug, but I've not seen it since and I was seeing it frequently enough to be fairly sure I fixed it.

So I wonder if you might have some sort of version skew issue on the host being spun (eg, it could have an old version of propellor installed and be failing before spin can update it to the fixed version). The easy way to verify you have the fixed version is to run git config propellor.debug 1 in /usr/local/propellor/ on the host being spun, and look for "--upload-pack ./propellor --gitpush" in a debug message.

If you're confident the remote propellor has the above commits in it, you're going to need to do some debugging. Setting GIT_TRACE_PACKET=1 on the remote system was very helpful in understanding the problem, and should probably be your first step. Setting that environment inside Propellor.Spin.gitPullFromUpdateServer should work, of course you'll have to get the remote host to build propellor with that change somehow despite --spin to it not working.

diff --git a/src/Propellor/Spin.hs b/src/Propellor/Spin.hs
index 4a945e82..aa73e3b7 100644
--- a/src/Propellor/Spin.hs
+++ b/src/Propellor/Spin.hs
@@ -359,6 +359,7 @@ spinCommitMessage = "propellor spin"
 -- to receive the data.
 gitPullFromUpdateServer :: IO ()
 gitPullFromUpdateServer = req NeedGitPush gitPushMarker $ \_ -> do
+   setEnv "GIT_TRACE_PACKET" "1" True
    -- IO involving stdin can cause data to be buffered in the Handle
    -- (even when it's set NoBuffering), but we need to pass a FD to
    -- git fetch containing all of stdin after the gitPushMarker,

Comment by joey — Sun Aug 26 14:50:22 2018