From 25d9208064980ed3f32ac6642d43fd2b5215e275 Mon Sep 17 00:00:00 2001 From: Joey Hess Date: Sun, 18 Jun 2017 16:23:32 -0400 Subject: propellor spin --- doc/todo/spin_failure_HEAD.mdwn | 25 +++++++++++++++++++++++++ 1 file changed, 25 insertions(+) (limited to 'doc') diff --git a/doc/todo/spin_failure_HEAD.mdwn b/doc/todo/spin_failure_HEAD.mdwn index f693b4a4..7c4976ab 100644 --- a/doc/todo/spin_failure_HEAD.mdwn +++ b/doc/todo/spin_failure_HEAD.mdwn @@ -15,3 +15,28 @@ but the rest of the propellor runs doesn't happen. --[[Joey]] > 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: : 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. +> > +> > -- cgit v1.2.3 From bdbc4155ee1c39e5baac58e95980d50cf2fb897a Mon Sep 17 00:00:00 2001 From: Joey Hess Date: Sun, 18 Jun 2017 16:30:57 -0400 Subject: propellor spin --- doc/todo/spin_failure_HEAD.mdwn | 20 +++++++++++++++++++- 1 file changed, 19 insertions(+), 1 deletion(-) (limited to 'doc') diff --git a/doc/todo/spin_failure_HEAD.mdwn b/doc/todo/spin_failure_HEAD.mdwn index 7c4976ab..39b64cbd 100644 --- a/doc/todo/spin_failure_HEAD.mdwn +++ b/doc/todo/spin_failure_HEAD.mdwn @@ -39,4 +39,22 @@ but the rest of the propellor runs doesn't happen. --[[Joey]] > > 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. +> > 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
+(omitted 364 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
+
-- cgit v1.2.3 From 49ff9d547070bc644f0ece2a1f5de8d70699b4c0 Mon Sep 17 00:00:00 2001 From: Joey Hess Date: Sun, 18 Jun 2017 16:43:48 -0400 Subject: propellor spin --- doc/todo/spin_failure_HEAD.mdwn | 36 +++++++++++++++++++++++++++++++++--- 1 file changed, 33 insertions(+), 3 deletions(-) (limited to 'doc') diff --git a/doc/todo/spin_failure_HEAD.mdwn b/doc/todo/spin_failure_HEAD.mdwn index 39b64cbd..6013db62 100644 --- a/doc/todo/spin_failure_HEAD.mdwn +++ b/doc/todo/spin_failure_HEAD.mdwn @@ -39,8 +39,8 @@ but the rest of the propellor runs doesn't happen. --[[Joey]] > > 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. -> > I did so on kite, but then propellor --spin succeeded. +> > 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. @@ -51,10 +51,40 @@ Sending privdata (73139 bytes) to kite.kitenet.net ... done [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 -(omitted 364 lines of refs) +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?
-- 
cgit v1.2.3


From 5f50c9ee767156b44b34e40eaa2a887e7878be63 Mon Sep 17 00:00:00 2001
From: Joey Hess
Date: Sun, 18 Jun 2017 16:49:14 -0400
Subject: propellor spin

---
 doc/todo/spin_failure_HEAD.mdwn | 7 +++++++
 1 file changed, 7 insertions(+)

(limited to 'doc')

diff --git a/doc/todo/spin_failure_HEAD.mdwn b/doc/todo/spin_failure_HEAD.mdwn
index 6013db62..b1ec4de3 100644
--- a/doc/todo/spin_failure_HEAD.mdwn
+++ b/doc/todo/spin_failure_HEAD.mdwn
@@ -88,3 +88,10 @@ Sending privdata (73139 bytes) to kite.kitenet.net ... done
 > > 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 truncating
+> >   data somehow?
+> > * Could be something on the remote side is consuming stdin
+> >   that is not supposed to, and eats some of the protocol.
-- 
cgit v1.2.3


From 6acb52f5f9696bfa549fec827420f1672cd7a52b Mon Sep 17 00:00:00 2001
From: Joey Hess
Date: Sun, 18 Jun 2017 16:56:27 -0400
Subject: propellor spin

---
 doc/todo/spin_failure_HEAD.mdwn | 9 ++++++---
 1 file changed, 6 insertions(+), 3 deletions(-)

(limited to 'doc')

diff --git a/doc/todo/spin_failure_HEAD.mdwn b/doc/todo/spin_failure_HEAD.mdwn
index b1ec4de3..af525f61 100644
--- a/doc/todo/spin_failure_HEAD.mdwn
+++ b/doc/todo/spin_failure_HEAD.mdwn
@@ -91,7 +91,10 @@ Sending privdata (73139 bytes) to kite.kitenet.net ... done
 > > 
 > > * 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 truncating
-> >   data somehow?
+> > * 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.
+> >   that is not supposed to, and eats some of the protocol.a
+> > 
+> > I added debug dumping to gitPushHelper, and it seems to be
+> > reading the same truncated data.
-- 
cgit v1.2.3


From 01fc1375cece096ab2dec480b843ecdbc4f0d94e Mon Sep 17 00:00:00 2001
From: Joey Hess
Date: Sun, 18 Jun 2017 18:24:05 -0400
Subject: Fix bug that sometimes made --spin fail with "fatal: Couldn't find
 remote ref HEAD"

Tricky stdin buffering problem.

An easier fix would have been:

	hSetBuffering stdin NoBuffering

But that approach is less robust; even with NoBuffering, anything that
uses hLookAhead causes 1 byte of buffering. And, any reads from stdin
before hSetBuffering would still cause the problem. Instead, I used a
bigger hammer that will always work. It involves a bit more CPU work,
but this is data that is already being fed through ssh; copying it one
more time won't cause a measurable performance impact.

This commit was sponsored by Jack Hill on Patreon.
---
 debian/changelog                |   2 +
 doc/todo/spin_failure_HEAD.mdwn |  33 +++++++++++--
 src/Propellor/Spin.hs           | 102 +++++++++++++++++++++++-----------------
 3 files changed, 92 insertions(+), 45 deletions(-)

(limited to 'doc')

diff --git a/debian/changelog b/debian/changelog
index d26e007c..086c82c0 100644
--- a/debian/changelog
+++ b/debian/changelog
@@ -1,5 +1,7 @@
 propellor (4.0.6) UNRELEASED; urgency=medium
 
+  * Fix bug that sometimes made --spin fail with 
+    "fatal: Couldn't find remote ref HEAD"
   * Display error and warning messages to stderr, not stdout.
 
  -- Joey Hess   Sun, 18 Jun 2017 16:19:41 -0400
diff --git a/doc/todo/spin_failure_HEAD.mdwn b/doc/todo/spin_failure_HEAD.mdwn
index af525f61..f838e469 100644
--- a/doc/todo/spin_failure_HEAD.mdwn
+++ b/doc/todo/spin_failure_HEAD.mdwn
@@ -51,7 +51,6 @@ Sending privdata (73139 bytes) to kite.kitenet.net ... done
 [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.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
@@ -94,7 +93,35 @@ Sending privdata (73139 bytes) to kite.kitenet.net ... done
 > > * 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.a
+> >   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.
+> > 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
+
+> > [[fixed|done]] --[[Joey]]
diff --git a/src/Propellor/Spin.hs b/src/Propellor/Spin.hs
index d0ce4d03..cc5fa0e8 100644
--- a/src/Propellor/Spin.hs
+++ b/src/Propellor/Spin.hs
@@ -186,26 +186,8 @@ update forhost = do
 		writeFileProtected privfile
 
 	whenM hasGitRepo $
-		req NeedGitPush gitPushMarker $ \_ -> do
-			hin <- dup stdInput
-			hout <- dup stdOutput
-			hClose stdin
-			hClose stdout
-			-- Not using git pull because git 2.5.0 badly
-			-- broke its option parser.
-			unlessM (boolSystemNonConcurrent "git" (pullparams hin hout)) $
-				errorMessage "git fetch from client failed"
-			unlessM (boolSystemNonConcurrent "git" [Param "merge", Param "FETCH_HEAD"]) $
-				errorMessage "git merge from client failed"
+		gitPullFromUpdateServer
   where
-	pullparams hin hout =
-		[ Param "fetch"
-		, Param "--progress"
-		, Param "--upload-pack"
-		, Param $ "./propellor --gitpush " ++ show hin ++ " " ++ show hout
-		, Param "."
-		]
-
 	-- When --spin --relay is run, get a privdata file
 	-- to be relayed to the target host.
 	privfile = maybe privDataLocal privDataRelay forhost
@@ -336,29 +318,6 @@ sendPrecompiled hn = void $ actionMessage "Uploading locally compiled propellor
 		, "rm -f " ++ remotetarball
 		]
 
--- Shim for git push over the propellor ssh channel.
--- Reads from stdin and sends it to hout;
--- reads from hin and sends it to stdout.
-gitPushHelper :: Fd -> Fd -> IO ()
-gitPushHelper hin hout = void $ fromstdin `concurrently` tostdout
-  where
-	fromstdin = do
-		h <- fdToHandle hout
-		connect stdin h
-	tostdout = do
-		h <- fdToHandle hin
-		connect h stdout
-	connect fromh toh = do
-		b <- B.hGetSome fromh 40960
-		if B.null b
-			then do
-				hClose fromh
-				hClose toh
-			else do
-				B.hPut toh b
-				hFlush toh
-				connect fromh toh
-
 mergeSpin :: IO ()
 mergeSpin = do
 	branch <- getCurrentBranch
@@ -386,3 +345,62 @@ findLastNonSpinCommit = do
 
 spinCommitMessage :: String
 spinCommitMessage = "propellor spin"
+
+-- Stdin and stdout are connected to the updateServer over ssh.
+-- Request that it run git upload-pack, and connect that up to a git fetch
+-- to receive the data.
+gitPullFromUpdateServer :: IO ()
+gitPullFromUpdateServer = req NeedGitPush gitPushMarker $ \_ -> do
+	-- 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,
+	-- including any that has been buffered.
+	--
+	-- To do so, create a pipe, and forward stdin, including any
+	-- buffered part, through it.
+	(pread, pwrite) <- System.Posix.IO.createPipe
+	hwrite <- fdToHandle pwrite
+	_ <- async $ stdin *>* hwrite
+	let hin = pread
+	hout <- dup stdOutput
+	hClose stdout
+	-- Not using git pull because git 2.5.0 badly
+	-- broke its option parser.
+	unlessM (boolSystemNonConcurrent "git" (fetchparams hin hout)) $
+		errorMessage "git fetch from client failed"
+	unlessM (boolSystemNonConcurrent "git" [Param "merge", Param "FETCH_HEAD"]) $
+		errorMessage "git merge from client failed"
+  where
+	fetchparams hin hout =
+		[ Param "fetch"
+		, Param "--progress"
+		, Param "--upload-pack"
+		, Param $ "./propellor --gitpush " ++ show hin ++ " " ++ show hout
+		, Param "."
+		]
+
+-- Shim for git push over the propellor ssh channel.
+-- Reads from stdin and sends it to hout;
+-- reads from hin and sends it to stdout.
+gitPushHelper :: Fd -> Fd -> IO ()
+gitPushHelper hin hout = void $ fromstdin `concurrently` tostdout
+  where
+	fromstdin = do
+		h <- fdToHandle hout
+		stdin *>* h
+	tostdout = do
+		h <- fdToHandle hin
+		h *>* stdout
+
+-- Forward data from one handle to another.
+(*>*) :: Handle -> Handle -> IO ()
+fromh *>* toh = do
+	b <- B.hGetSome fromh 40960
+	if B.null b
+		then do
+			hClose fromh
+			hClose toh
+		else do
+			B.hPut toh b
+			hFlush toh
+			fromh *>* toh
-- 
cgit v1.2.3