{"thread":{"id":"45973","subject":"t5400 failure on Windows","startedAt":"2017-05-15T20:05:39Z","lastAt":"2017-05-18T05:02:19Z","messageCount":6,"participants":["Johannes Sixt","Jeff King"],"isPatch":false,"patchVersion":null,"patchTotal":null},"messages":[{"id":"319831","messageId":"50f6d8b7-383b-7673-22ad-9a9b80bec2d1@kdbg.org","threadId":"45973","inReplyTo":null,"subject":"t5400 failure on Windows","fromName":"Johannes Sixt","fromEmail":"j6t@kdbg.org","sentAt":"2017-05-15T20:05:29Z","receivedAt":"2017-05-15T20:05:39Z","isPatch":false,"sender":{"key":"j6t@kdbg.org","avatar":"https://avatars.githubusercontent.com/u/14810926?v=4"},"body":"I observe the following failure on Windws with origin/next, in\nt5400-send-pack.sh\n\n+++ diff -u expect refs\n--- expect Mon May 15 06:54:59 2017\n+++ refs Mon May 15 06:54:59 2017\n@@ -1,4 +1,3 @@\n 5285e1710002a06a379056b0d21357a999f3c642 refs/heads/master\n-5285e1710002a06a379056b0d21357a999f3c642 refs/remotes/origin/HEAD\n 5285e1710002a06a379056b0d21357a999f3c642 refs/remotes/origin/master\n 53d9066ca10f2e103b33caf3a16a723553c33b00 .have\nerror: last command exited with $?=1\nnot ok 16 - receive-pack de-dupes .have lines\n\n\nThe trace file looks like this:\n\n-------- trace --------\npacket: receive-pack> 5285e1710002a06a379056b0d21357a999f3c642 refs/heads/master\\0report-status delete-refs side-band-64k quiet atomic ofs-delta agent=git/2.13.0.497.g5af12421b0\npacket: receive-pack> 5285e1710002a06a379056b0d21357a999f3c642 refs/remotes/origin/HEAD\npacket: push< 5285e1710002a06a379056b0d21357a999f3c642 refs/heads/master\\0report-status delete-refs side-band-64k quiet atomic ofs-delta agent=git/2.13.0.497.g5af12421b0\npacket: receive-pack> 5285e1710002a06a379056b0d21357a999f3c642 refs/remotes/origin/master\npacket: push< 5285e1710002a06a379056b0d21357a999f3c642 refs/remotes/origin/master\npacket: receive-pack> 53d9066ca10f2e103b33caf3a16a723553c33b00 .have\npacket: push< 53d9066ca10f2e103b33caf3a16a723553c33b00 .have\npacket: receive-pack> 0000\npacket: push< 0000\npacket: push> 0000000000000000000000000000000000000000 b1a1c97e94b6388c108e195d28a3e89f00c81698 refs/heads/foo\\0 report-status agent=git/2.13.0.497.g5af12421b0\npacket: push> 0000\npacket: receive-pack< 0000000000000000000000000000000000000000 b1a1c97e94b6388c108e195d28a3e89f00c81698 refs/heads/foo\\0 report-status agent=git/2.13.0.497.g5af12421b0\npacket: receive-pack< 0000\npacket: receive-pack> unpack ok\npacket: receive-pack> ok refs/heads/foo\npacket: receive-pack> 0000\npacket: push< unpack ok\npacket: push< ok refs/heads/foo\npacket: push< 0000\n-------- end of trace --------\n\nWhere should I start looking? On a Linux box, the test case does\nproduce an additional line\n\npacket: push< 5285e1710002a06a379056b0d21357a999f3c642 refs/remotes/origin/HEAD\n\nin the trace file. I also do not see that any tests would be skipped\non Windows. (But I forgot to check whether refs/remotes/origin/HEAD\nis present in any of the repositories.)\n\n-- Hannes\n"},{"id":"319843","messageId":"20170515222406.hxab2wrapv75ybmj@sigill.intra.peff.net","threadId":"45973","inReplyTo":"50f6d8b7-383b-7673-22ad-9a9b80bec2d1@kdbg.org","subject":"Re: t5400 failure on Windows","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2017-05-15T22:24:07Z","receivedAt":"2017-05-15T22:24:18Z","isPatch":false,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Mon, May 15, 2017 at 10:05:29PM +0200, Johannes Sixt wrote:\n\n> I observe the following failure on Windws with origin/next, in\n> t5400-send-pack.sh\n> \n> +++ diff -u expect refs\n> --- expect Mon May 15 06:54:59 2017\n> +++ refs Mon May 15 06:54:59 2017\n> @@ -1,4 +1,3 @@\n> 5285e1710002a06a379056b0d21357a999f3c642 refs/heads/master\n> -5285e1710002a06a379056b0d21357a999f3c642 refs/remotes/origin/HEAD\n> 5285e1710002a06a379056b0d21357a999f3c642 refs/remotes/origin/master\n> 53d9066ca10f2e103b33caf3a16a723553c33b00 .have\n> error: last command exited with $?=1\n> not ok 16 - receive-pack de-dupes .have lines\n\nInteresting that it's the symref. I wonder if that is important (though\nthey should always be implemented as a real symref file and not a\nsymlink, so I don't think FS limitations would come into play).\n\nFor sanity, you might want to double-check that the \"shared-fork\"\nrepository has that symref on disk, and that for-each-ref reports it.\nBut...\n\n> The trace file looks like this:\n> \n> -------- trace --------\n> packet: receive-pack> 5285e1710002a06a379056b0d21357a999f3c642 refs/heads/master\\0report-status delete-refs side-band-64k quiet atomic ofs-delta agent=git/2.13.0.497.g5af12421b0\n> packet: receive-pack> 5285e1710002a06a379056b0d21357a999f3c642 refs/remotes/origin/HEAD\n\nWait, there it is in the receive-pack output. But if we look at what\n\"push\" receives:\n\n> packet: push< 5285e1710002a06a379056b0d21357a999f3c642 refs/heads/master\\0report-status delete-refs side-band-64k quiet atomic ofs-delta agent=git/2.13.0.497.g5af12421b0\n> packet: receive-pack> 5285e1710002a06a379056b0d21357a999f3c642 refs/remotes/origin/master\n> packet: push< 5285e1710002a06a379056b0d21357a999f3c642 refs/remotes/origin/master\n\nIt's skipped! So either:\n\n 1. receive-pack wrote the trace line without sending it (which seems\n an unlikely bug to differ between platforms)\n\n 2. push some didn't receive it (which makes no sense; this is a stream\n socket and it was able to parse the next pktline)\n\n 3. push did get it but for some reason didn't write the trace (also\n unlikely as with option 1)\n\n 4. There is something racy and unportable about both programs writing\n to the same trace file. It's opened with O_APPEND, which means that\n each write should atomically position the pointer at the end of the\n file. Is it possible there's a problem with that in the way\n O_APPEND works on Windows?\n\n If that was the case, though, I'd generally expect a sheared write\n or a partial overwrite. The two origin/HEAD lines from the two\n programs are the exact same length, but I'd find it more likely for\n the overwrite to happen with one of the follow-on lines.\n\nSo all of those sound kind of implausible. If you run the test over and\nover, does it happen consistently, and is it always the same line?\n\n-Peff\n"},{"id":"319950","messageId":"afca6bf5-472e-dda4-2c16-a2256080ac51@kdbg.org","threadId":"45973","inReplyTo":"20170515222406.hxab2wrapv75ybmj@sigill.intra.peff.net","subject":"Re: t5400 failure on Windows","fromName":"Johannes Sixt","fromEmail":"j6t@kdbg.org","sentAt":"2017-05-16T18:35:46Z","receivedAt":"2017-05-16T18:35:55Z","isPatch":false,"sender":{"key":"j6t@kdbg.org","avatar":"https://avatars.githubusercontent.com/u/14810926?v=4"},"body":"Am 16.05.2017 um 00:24 schrieb Jeff King:\n> 4. There is something racy and unportable about both programs writing\n> to the same trace file. It's opened with O_APPEND, which means that\n> each write should atomically position the pointer at the end of the\n> file. Is it possible there's a problem with that in the way\n> O_APPEND works on Windows?\n> \n> If that was the case, though, I'd generally expect a sheared write\n> or a partial overwrite. The two origin/HEAD lines from the two\n> programs are the exact same length, but I'd find it more likely for\n> the overwrite to happen with one of the follow-on lines.\n\nGood guesswork! O_APPEND is not atomic on Windows, in particular, it is \nemulated as lseek(SEEK_END) followed by write().\n\nI ran the test a few more times, and it fails in different ways \n(different missing lines) and also succeeds in a minority of the cases.\n\nWindows is capable of writing atomically in the way O_APPEND requires \n(keyword: FILE_APPEND_DATA), but I do not see a way to wedge this into \nthe emulation layer. For the time being, I think I have to skip the test \ncase.\n\nThe question remains how endangered our uses of O_APPEND are when the \nPOSIX semantics are not obeyed precisely:\n\n* trace.c: It is about debugging. Not critical.\n\n* sequencer.c: It writes the \"done\" file. No concurrent accesses are \nexpected: Not critial.\n\n* refs/files-backend.c: There are uses in functions \nopen_or_create_logfile() and log_ref_setup(). Sounds like it is in \nreflogs. Sounds like this is about reflogs. If there are concurrent \naccesses, there is a danger that a reflog is not recorded correctly. \nThen reflogs may be missing and objects may be pruned earlier than \nexpected. That's something to worry about, but I would not count it as \nmission critical.\n\n-- Hannes\n"},{"id":"320023","messageId":"20170517054424.cq66cl5ukvhsz34y@sigill.intra.peff.net","threadId":"45973","inReplyTo":"afca6bf5-472e-dda4-2c16-a2256080ac51@kdbg.org","subject":"Re: t5400 failure on Windows","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2017-05-17T05:44:25Z","receivedAt":"2017-05-17T05:44:33Z","isPatch":false,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Tue, May 16, 2017 at 08:35:46PM +0200, Johannes Sixt wrote:\n\n> Am 16.05.2017 um 00:24 schrieb Jeff King:\n> > 4. There is something racy and unportable about both programs writing\n> > to the same trace file. It's opened with O_APPEND, which means that\n> > each write should atomically position the pointer at the end of the\n> > file. Is it possible there's a problem with that in the way\n> > O_APPEND works on Windows?\n> > \n> > If that was the case, though, I'd generally expect a sheared write\n> > or a partial overwrite. The two origin/HEAD lines from the two\n> > programs are the exact same length, but I'd find it more likely for\n> > the overwrite to happen with one of the follow-on lines.\n> \n> Good guesswork! O_APPEND is not atomic on Windows, in particular, it is\n> emulated as lseek(SEEK_END) followed by write().\n> \n> I ran the test a few more times, and it fails in different ways (different\n> missing lines) and also succeeds in a minority of the cases.\n\nOK, that definitely explains it, then.\n\n> Windows is capable of writing atomically in the way O_APPEND requires\n> (keyword: FILE_APPEND_DATA), but I do not see a way to wedge this into the\n> emulation layer. For the time being, I think I have to skip the test case.\n\nI wonder if there's a way we could convince the trace for the two\nprograms to go to separate locations. We don't care about receive-pack's\ntrace at all. So maybe:\n\ndiff --git a/t/t5400-send-pack.sh b/t/t5400-send-pack.sh\nindex 3331e0f53..d375d7110 100755\n--- a/t/t5400-send-pack.sh\n+++ b/t/t5400-send-pack.sh\n@@ -288,7 +288,10 @@ test_expect_success 'receive-pack de-dupes .have lines' '\n \t$shared .have\n \tEOF\n \n-\tGIT_TRACE_PACKET=$(pwd)/trace git push fork HEAD:foo &&\n+\tGIT_TRACE_PACKET=$(pwd)/trace \\\n+\t git push \\\n+\t\t--receive-pack=\"unset GIT_TRACE_PACKET; git-receive-pack\" \\\n+\t\tfork HEAD:foo &&\n \textract_ref_advertisement refs &&\n \ttest_cmp expect refs\n '\n\n> The question remains how endangered our uses of O_APPEND are when the POSIX\n> semantics are not obeyed precisely:\n> \n> * trace.c: It is about debugging. Not critical.\n\nAgreed.\n\n> * sequencer.c: It writes the \"done\" file. No concurrent accesses are\n> expected: Not critial.\n\nAgreed.\n\n> * refs/files-backend.c: There are uses in functions open_or_create_logfile()\n> and log_ref_setup(). Sounds like it is in reflogs. Sounds like this is about\n> reflogs. If there are concurrent accesses, there is a danger that a reflog\n> is not recorded correctly. Then reflogs may be missing and objects may be\n> pruned earlier than expected. That's something to worry about, but I would\n> not count it as mission critical.\n\nWe should always hold the matching ref lock already when modifying a\nreflog. I seem to recall there was a case that missed this (I think\nmaybe modifying the HEAD reflog without holding HEAD.lock), but it was\nfixed in the last few versions.\n\nSo I think we're probably OK, but I agree it's an interesting gotcha\nthat may bite us in the future.\n\n-Peff\n"},{"id":"320098","messageId":"83b6c8d3-2787-995a-a4e5-e6a437c53e89@kdbg.org","threadId":"45973","inReplyTo":"20170517054424.cq66cl5ukvhsz34y@sigill.intra.peff.net","subject":"Re: t5400 failure on Windows","fromName":"Johannes Sixt","fromEmail":"j6t@kdbg.org","sentAt":"2017-05-17T18:41:01Z","receivedAt":"2017-05-17T18:41:08Z","isPatch":false,"sender":{"key":"j6t@kdbg.org","avatar":"https://avatars.githubusercontent.com/u/14810926?v=4"},"body":"Am 17.05.2017 um 07:44 schrieb Jeff King:\n> I wonder if there's a way we could convince the trace for the two\n> programs to go to separate locations. We don't care about receive-pack's\n> trace at all. So maybe:\n\nThis works. Below it is with a commit message. I'm unsure about the\nsign-off procedure, though.\n\n>> * refs/files-backend.c: There are uses in functions open_or_create_logfile()\n>> and log_ref_setup(). Sounds like it is in reflogs. Sounds like this is about\n>> reflogs. If there are concurrent accesses, there is a danger that a reflog\n>> is not recorded correctly. Then reflogs may be missing and objects may be\n>> pruned earlier than expected. That's something to worry about, but I would\n>> not count it as mission critical.\n\nOf course, the reflog can also be corrupted, but:\n\n> We should always hold the matching ref lock already when modifying a\n> reflog. I seem to recall there was a case that missed this (I think\n> maybe modifying the HEAD reflog without holding HEAD.lock), but it was\n> fixed in the last few versions.\n\nwe should be fairly safe then.\n\n---- 8< ----\nFrom: Jeff King \nSubject: [PATCH jk/alternate-ref-optim] t5400: avoid concurrent writes into a trace file\n\nOne test in t5400 examines the packet exchange between git-push and\ngit-receive-pack. The latter inherits the GIT_TRACE_PACKET environment\nvariable, so that both processes dump trace data into the same file\nconcurrently. This should not be a problem because the trace file is\nopened with O_APPEND.\n\nOn Windows, however, O_APPEND is not atomic as it should be: it is\nemulated as lseek(SEEK_END) followed by write(). For this reason, the\ntest is unreliable: it can happen that one process overwrites a line\nthat was just written by the other process. As a consequence, the test\nsometimes does not find one or another line that is expected (and it is\nalso successful occasionally).\n\nThe test case is actually only interested in the output of git-push.\nTo ensure that only git-push writes to the trace file, override the\nreceive-pack command such that it does not even open the trace file.\n\nSigned-off-by: Johannes Sixt \n---\n t/t5400-send-pack.sh | 5 ++++-\n 1 file changed, 4 insertions(+), 1 deletion(-)\n\ndiff --git a/t/t5400-send-pack.sh b/t/t5400-send-pack.sh\nindex 3331e0f534..d375d7110d 100755\n--- a/t/t5400-send-pack.sh\n+++ b/t/t5400-send-pack.sh\n@@ -288,7 +288,10 @@ test_expect_success 'receive-pack de-dupes .have lines' '\n \t$shared .have\n \tEOF\n \n-\tGIT_TRACE_PACKET=$(pwd)/trace git push fork HEAD:foo &&\n+\tGIT_TRACE_PACKET=$(pwd)/trace \\\n+\t git push \\\n+\t\t--receive-pack=\"unset GIT_TRACE_PACKET; git-receive-pack\" \\\n+\t\tfork HEAD:foo &&\n \textract_ref_advertisement refs &&\n \ttest_cmp expect refs\n '\n-- \n2.13.0.55.g17b7d13330\n"},{"id":"320138","messageId":"20170518050209.dezna5tillvlbwgw@sigill.intra.peff.net","threadId":"45973","inReplyTo":"83b6c8d3-2787-995a-a4e5-e6a437c53e89@kdbg.org","subject":"[PATCH] t5400: avoid concurrent writes into a trace file","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2017-05-18T05:02:09Z","receivedAt":"2017-05-18T05:02:19Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Wed, May 17, 2017 at 08:41:01PM +0200, Johannes Sixt wrote:\n\n> Am 17.05.2017 um 07:44 schrieb Jeff King:\n> > I wonder if there's a way we could convince the trace for the two\n> > programs to go to separate locations. We don't care about receive-pack's\n> > trace at all. So maybe:\n> \n> This works. Below it is with a commit message. I'm unsure about the\n> sign-off procedure, though.\n\nThanks for testing. I actually wrote one in preparation, but I like\nyours a little better.\n\nI'll repost here with my signoff and a cc to Junio, since the earlier\nsubject line was less likely to grab attention. This goes on top of\njk/alternate-ref-optim.\n\n-- >8 --\nSubject: t5400: avoid concurrent writes into a trace file\n\nOne test in t5400 examines the packet exchange between git-push and\ngit-receive-pack. The latter inherits the GIT_TRACE_PACKET environment\nvariable, so that both processes dump trace data into the same file\nconcurrently. This should not be a problem because the trace file is\nopened with O_APPEND.\n\nOn Windows, however, O_APPEND is not atomic as it should be: it is\nemulated as lseek(SEEK_END) followed by write(). For this reason, the\ntest is unreliable: it can happen that one process overwrites a line\nthat was just written by the other process. As a consequence, the test\nsometimes does not find one or another line that is expected (and it is\nalso successful occasionally).\n\nThe test case is actually only interested in the output of git-push.\nTo ensure that only git-push writes to the trace file, override the\nreceive-pack command such that it does not even open the trace file.\n\nReported-by: Johannes Sixt \nSigned-off-by: Jeff King \n---\n t/t5400-send-pack.sh | 5 ++++-\n 1 file changed, 4 insertions(+), 1 deletion(-)\n\ndiff --git a/t/t5400-send-pack.sh b/t/t5400-send-pack.sh\nindex 3331e0f53..d375d7110 100755\n--- a/t/t5400-send-pack.sh\n+++ b/t/t5400-send-pack.sh\n@@ -288,7 +288,10 @@ test_expect_success 'receive-pack de-dupes .have lines' '\n \t$shared .have\n \tEOF\n \n-\tGIT_TRACE_PACKET=$(pwd)/trace git push fork HEAD:foo &&\n+\tGIT_TRACE_PACKET=$(pwd)/trace \\\n+\t git push \\\n+\t\t--receive-pack=\"unset GIT_TRACE_PACKET; git-receive-pack\" \\\n+\t\tfork HEAD:foo &&\n \textract_ref_advertisement refs &&\n \ttest_cmp expect refs\n '\n-- \n2.13.0.219.g63f6bc368\n\n"}]}