* test failure
@ 2016-12-16 20:32 Ramsay Jones
2016-12-17 14:28 ` Lars Schneider
0 siblings, 1 reply; 6+ messages in thread
From: Ramsay Jones @ 2016-12-16 20:32 UTC (permalink / raw)
To: Lars Schneider; +Cc: Junio C Hamano, GIT Mailing-list
Hi Lars,
For the last two days, I've noticed t0021.15 on the 'pu' branch has been failing intermittently (well it fails with: 'make test >ptest-out', but
when run by hand, it fails only say 1-in-6, 1-in-18, etc.).
[yes, it's a bit strange; this hasn't changed in a couple of weeks!]
I don't have time to investigate further tonight and, since I had not
heard anyone else complain, I thought I should let you know.
See below for the output from a failing run. [Note: this is on Linux
Mint 18, tonight's pu branch @7c7984401].
ATB,
Ramsay Jones
$ ./t0021-conversion.sh -i -v
...
ok 14 - diff does not reuse worktree files that need cleaning
expecting success:
test_config_global filter.protocol.process "rot13-filter.pl clean smudge" &&
test_config_global filter.protocol.required true &&
rm -rf repo &&
mkdir repo &&
(
cd repo &&
git init &&
echo "*.r filter=protocol" >.gitattributes &&
git add . &&
git commit -m "test commit 1" &&
git branch empty-branch &&
cp "$TEST_ROOT/test.o" test.r &&
cp "$TEST_ROOT/test2.o" test2.r &&
mkdir testsubdir &&
cp "$TEST_ROOT/test3 'sq',\$x=.o" "testsubdir/test3 'sq',\$x=.r" &&
>test4-empty.r &&
S=$(file_size test.r) &&
S2=$(file_size test2.r) &&
S3=$(file_size "testsubdir/test3 'sq',\$x=.r") &&
filter_git add . &&
cat >expected.log <<-EOF &&
START
init handshake complete
IN: clean test.r $S [OK] -- OUT: $S . [OK]
IN: clean test2.r $S2 [OK] -- OUT: $S2 . [OK]
IN: clean test4-empty.r 0 [OK] -- OUT: 0 [OK]
IN: clean testsubdir/test3 'sq',\$x=.r $S3 [OK] -- OUT: $S3 . [OK]
STOP
EOF
test_cmp_count expected.log rot13-filter.log &&
filter_git commit -m "test commit 2" &&
cat >expected.log <<-EOF &&
START
init handshake complete
IN: clean test.r $S [OK] -- OUT: $S . [OK]
IN: clean test2.r $S2 [OK] -- OUT: $S2 . [OK]
IN: clean test4-empty.r 0 [OK] -- OUT: 0 [OK]
IN: clean testsubdir/test3 'sq',\$x=.r $S3 [OK] -- OUT: $S3 . [OK]
IN: clean test.r $S [OK] -- OUT: $S . [OK]
IN: clean test2.r $S2 [OK] -- OUT: $S2 . [OK]
IN: clean test4-empty.r 0 [OK] -- OUT: 0 [OK]
IN: clean testsubdir/test3 'sq',\$x=.r $S3 [OK] -- OUT: $S3 . [OK]
STOP
EOF
test_cmp_count expected.log rot13-filter.log &&
rm -f test2.r "testsubdir/test3 'sq',\$x=.r" &&
filter_git checkout --quiet --no-progress . &&
cat >expected.log <<-EOF &&
START
init handshake complete
IN: smudge test2.r $S2 [OK] -- OUT: $S2 . [OK]
IN: smudge testsubdir/test3 'sq',\$x=.r $S3 [OK] -- OUT: $S3 . [OK]
STOP
EOF
test_cmp_exclude_clean expected.log rot13-filter.log &&
filter_git checkout --quiet --no-progress empty-branch &&
cat >expected.log <<-EOF &&
START
init handshake complete
IN: clean test.r $S [OK] -- OUT: $S . [OK]
STOP
EOF
test_cmp_exclude_clean expected.log rot13-filter.log &&
filter_git checkout --quiet --no-progress master &&
cat >expected.log <<-EOF &&
START
init handshake complete
IN: smudge test.r $S [OK] -- OUT: $S . [OK]
IN: smudge test2.r $S2 [OK] -- OUT: $S2 . [OK]
IN: smudge test4-empty.r 0 [OK] -- OUT: 0 [OK]
IN: smudge testsubdir/test3 'sq',\$x=.r $S3 [OK] -- OUT: $S3 . [OK]
STOP
EOF
test_cmp_exclude_clean expected.log rot13-filter.log &&
test_cmp_committed_rot13 "$TEST_ROOT/test.o" test.r &&
test_cmp_committed_rot13 "$TEST_ROOT/test2.o" test2.r &&
test_cmp_committed_rot13 "$TEST_ROOT/test3 'sq',\$x=.o" "testsubdir/test3 'sq',\$x=.r"
)
Initialized empty Git repository in /home/ramsay/git/t/trash directory.t0021-conversion/repo/.git/
[master (root-commit) 56d459b] test commit 1
Author: A U Thor <author@example.com>
1 file changed, 1 insertion(+)
create mode 100644 .gitattributes
[master 9ea74df] test commit 2
Author: A U Thor <author@example.com>
4 files changed, 5 insertions(+)
create mode 100644 test.r
create mode 100644 test2.r
create mode 100644 test4-empty.r
create mode 100644 testsubdir/test3 'sq',$x=.r
sort: cannot read: rot13-filter.log: No such file or directory
--- expected.log 2016-12-16 20:14:29.037426091 +0000
+++ rot13-filter.log 2016-12-16 20:14:29.041426091 +0000
@@ -1,7 +0,0 @@
-x IN: clean test.r 57 [OK] -- OUT: 57 . [OK]
-x IN: clean test2.r 14 [OK] -- OUT: 14 . [OK]
-x IN: clean test4-empty.r 0 [OK] -- OUT: 0 [OK]
-x IN: clean testsubdir/test3 'sq',$x=.r 49 [OK] -- OUT: 49 . [OK]
- 1 START
- 1 STOP
- 1 init handshake complete
not ok 15 - required process filter should filter data
#
# test_config_global filter.protocol.process "rot13-filter.pl clean smudge" &&
# test_config_global filter.protocol.required true &&
# rm -rf repo &&
# mkdir repo &&
# (
# cd repo &&
# git init &&
#
# echo "*.r filter=protocol" >.gitattributes &&
# git add . &&
# git commit -m "test commit 1" &&
# git branch empty-branch &&
#
# cp "$TEST_ROOT/test.o" test.r &&
# cp "$TEST_ROOT/test2.o" test2.r &&
# mkdir testsubdir &&
# cp "$TEST_ROOT/test3 'sq',\$x=.o" "testsubdir/test3 'sq',\$x=.r" &&
# >test4-empty.r &&
#
# S=$(file_size test.r) &&
# S2=$(file_size test2.r) &&
# S3=$(file_size "testsubdir/test3 'sq',\$x=.r") &&
#
# filter_git add . &&
# cat >expected.log <<-EOF &&
# START
# init handshake complete
# IN: clean test.r $S [OK] -- OUT: $S . [OK]
# IN: clean test2.r $S2 [OK] -- OUT: $S2 . [OK]
# IN: clean test4-empty.r 0 [OK] -- OUT: 0 [OK]
# IN: clean testsubdir/test3 'sq',\$x=.r $S3 [OK] -- OUT: $S3 . [OK]
# STOP
# EOF
# test_cmp_count expected.log rot13-filter.log &&
#
# filter_git commit -m "test commit 2" &&
# cat >expected.log <<-EOF &&
# START
# init handshake complete
# IN: clean test.r $S [OK] -- OUT: $S . [OK]
# IN: clean test2.r $S2 [OK] -- OUT: $S2 . [OK]
# IN: clean test4-empty.r 0 [OK] -- OUT: 0 [OK]
# IN: clean testsubdir/test3 'sq',\$x=.r $S3 [OK] -- OUT: $S3 . [OK]
# IN: clean test.r $S [OK] -- OUT: $S . [OK]
# IN: clean test2.r $S2 [OK] -- OUT: $S2 . [OK]
# IN: clean test4-empty.r 0 [OK] -- OUT: 0 [OK]
# IN: clean testsubdir/test3 'sq',\$x=.r $S3 [OK] -- OUT: $S3 . [OK]
# STOP
# EOF
# test_cmp_count expected.log rot13-filter.log &&
#
# rm -f test2.r "testsubdir/test3 'sq',\$x=.r" &&
#
# filter_git checkout --quiet --no-progress . &&
# cat >expected.log <<-EOF &&
# START
# init handshake complete
# IN: smudge test2.r $S2 [OK] -- OUT: $S2 . [OK]
# IN: smudge testsubdir/test3 'sq',\$x=.r $S3 [OK] -- OUT: $S3 . [OK]
# STOP
# EOF
# test_cmp_exclude_clean expected.log rot13-filter.log &&
#
# filter_git checkout --quiet --no-progress empty-branch &&
# cat >expected.log <<-EOF &&
# START
# init handshake complete
# IN: clean test.r $S [OK] -- OUT: $S . [OK]
# STOP
# EOF
# test_cmp_exclude_clean expected.log rot13-filter.log &&
#
# filter_git checkout --quiet --no-progress master &&
# cat >expected.log <<-EOF &&
# START
# init handshake complete
# IN: smudge test.r $S [OK] -- OUT: $S . [OK]
# IN: smudge test2.r $S2 [OK] -- OUT: $S2 . [OK]
# IN: smudge test4-empty.r 0 [OK] -- OUT: 0 [OK]
# IN: smudge testsubdir/test3 'sq',\$x=.r $S3 [OK] -- OUT: $S3 . [OK]
# STOP
# EOF
# test_cmp_exclude_clean expected.log rot13-filter.log &&
#
# test_cmp_committed_rot13 "$TEST_ROOT/test.o" test.r &&
# test_cmp_committed_rot13 "$TEST_ROOT/test2.o" test2.r &&
# test_cmp_committed_rot13 "$TEST_ROOT/test3 'sq',\$x=.o" "testsubdir/test3 'sq',\$x=.r"
# )
#
$
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: test failure
2016-12-16 20:32 test failure Ramsay Jones
@ 2016-12-17 14:28 ` Lars Schneider
2016-12-17 16:11 ` Lars Schneider
0 siblings, 1 reply; 6+ messages in thread
From: Lars Schneider @ 2016-12-17 14:28 UTC (permalink / raw)
To: Ramsay Jones, Jeff King; +Cc: Junio C Hamano, GIT Mailing-list
> On 16 Dec 2016, at 21:32, Ramsay Jones <ramsay@ramsayjones.plus.com> wrote:
>
> Hi Lars,
>
> For the last two days, I've noticed t0021.15 on the 'pu' branch has been failing intermittently (well it fails with: 'make test >ptest-out', but
> when run by hand, it fails only say 1-in-6, 1-in-18, etc.).
>
> [yes, it's a bit strange; this hasn't changed in a couple of weeks!]
>
> I don't have time to investigate further tonight and, since I had not
> heard anyone else complain, I thought I should let you know.
>
> See below for the output from a failing run. [Note: this is on Linux
> Mint 18, tonight's pu branch @7c7984401].
Thanks Ramsay!
I was able to reproduce the problem with this test:
test_expect_success 'ramsay-report' '
test_config_global filter.protocol.clean cat &&
git init &&
echo "*.r filter=protocol" >.gitattributes &&
echo "bla" >test.r &&
git add . &&
GIT_TRACE=1 git commit -m "test commit 2" > trace 2>&1 &&
grep "run_command" trace
'
It looks like as if Git occasionally forgets to run the clean filter.
I bisected the problem and I think the problem starts with "diff: do not
reuse worktree files that need "clean" conversion" (06dec439a3) which
definitively sounds related.
Back in June I reported that Git invokes the clean process 4 times if a
single file is added. Peff took a closer look and suggested the patch
mentioned above to remove one unnecessary invocation. I re-read his comments
and everything sounds still reasonable to me:
http://public-inbox.org/git/1469134747-26785-1-git-send-email-larsxschneider@gmail.com/#t
Does anyone have a clue what is going on?
I keep digging...
Thanks,
Lars
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: test failure
2016-12-17 14:28 ` Lars Schneider
@ 2016-12-17 16:11 ` Lars Schneider
2016-12-18 12:37 ` [PATCH v1] t0021: fix flaky test larsxschneider
0 siblings, 1 reply; 6+ messages in thread
From: Lars Schneider @ 2016-12-17 16:11 UTC (permalink / raw)
To: Ramsay Jones, Jeff King; +Cc: Junio C Hamano, GIT Mailing-list
> On 17 Dec 2016, at 15:28, Lars Schneider <larsxschneider@gmail.com> wrote:
>
>
>> On 16 Dec 2016, at 21:32, Ramsay Jones <ramsay@ramsayjones.plus.com> wrote:
>>
>> Hi Lars,
>>
>> For the last two days, I've noticed t0021.15 on the 'pu' branch has been failing intermittently (well it fails with: 'make test >ptest-out', but
>> when run by hand, it fails only say 1-in-6, 1-in-18, etc.).
>>
>> [yes, it's a bit strange; this hasn't changed in a couple of weeks!]
>>
>> I don't have time to investigate further tonight and, since I had not
>> heard anyone else complain, I thought I should let you know.
>>
>> See below for the output from a failing run. [Note: this is on Linux
>> Mint 18, tonight's pu branch @7c7984401].
>
> Thanks Ramsay!
>
> I was able to reproduce the problem with this test:
>
> test_expect_success 'ramsay-report' '
> test_config_global filter.protocol.clean cat &&
> git init &&
> echo "*.r filter=protocol" >.gitattributes &&
> echo "bla" >test.r &&
> git add . &&
> GIT_TRACE=1 git commit -m "test commit 2" > trace 2>&1 &&
> grep "run_command" trace
> '
>
> It looks like as if Git occasionally forgets to run the clean filter.
> I bisected the problem and I think the problem starts with "diff: do not
> reuse worktree files that need "clean" conversion" (06dec439a3) which
> definitively sounds related.
>
> Back in June I reported that Git invokes the clean process 4 times if a
> single file is added. Peff took a closer look and suggested the patch
> mentioned above to remove one unnecessary invocation. I re-read his comments
> and everything sounds still reasonable to me:
> http://public-inbox.org/git/1469134747-26785-1-git-send-email-larsxschneider@gmail.com/#t
>
> Does anyone have a clue what is going on?
> I keep digging...
Ugh. I stopped coding, started cleaning the house, and it hit me:
"git commit" shouldn't call the filter anyways. I suspect it is called in
my tests because I add and commit the file to the index right after its
creation. All this usually happens within 1 second and therefore Git cannot
know if the file was modified between "add" and "commit". That's why it needs
to run "clean" again.
I will adjust the tests.
Cheers,
Lars
^ permalink raw reply [flat|nested] 6+ messages in thread
* [PATCH v1] t0021: fix flaky test
2016-12-17 16:11 ` Lars Schneider
@ 2016-12-18 12:37 ` larsxschneider
2016-12-19 17:24 ` Ramsay Jones
0 siblings, 1 reply; 6+ messages in thread
From: larsxschneider @ 2016-12-18 12:37 UTC (permalink / raw)
To: git; +Cc: ramsay, peff, gitster, Lars Schneider
From: Lars Schneider <larsxschneider@gmail.com>
t0021.15 creates files, adds them to the index, and commits them. All
this usually happens in a test run within the same second and Git cannot
know if the files have been changed between `add` and `commit`. Thus,
Git has to run the clean filter in both operations. Sometimes these
invocations spread over two different seconds and Git can infer that the
files were not changed between `add` and `commit` based on their
modification timestamp. The test would fail as it expects the filter
invocation. Remove this expectation to make the test stable.
Signed-off-by: Lars Schneider <larsxschneider@gmail.com>
---
Notes:
Base Commit: f8bf8f2a7b (next)
Diff on Web: https://github.com/git/git/compare/f8bf8f2a7b...larsxschneider:9d88b66e03
Checkout: git fetch https://github.com/larsxschneider/git filter-process/fix-flaky-test-v1 && git checkout 9d88b66e03
t/t0021-conversion.sh | 17 +----------------
1 file changed, 1 insertion(+), 16 deletions(-)
diff --git a/t/t0021-conversion.sh b/t/t0021-conversion.sh
index 6f16983d3e..161f560446 100755
--- a/t/t0021-conversion.sh
+++ b/t/t0021-conversion.sh
@@ -377,22 +377,7 @@ test_expect_success PERL 'required process filter should filter data' '
EOF
test_cmp_count expected.log rot13-filter.log &&
- filter_git commit -m "test commit 2" &&
- cat >expected.log <<-EOF &&
- START
- init handshake complete
- IN: clean test.r $S [OK] -- OUT: $S . [OK]
- IN: clean test2.r $S2 [OK] -- OUT: $S2 . [OK]
- IN: clean test4-empty.r 0 [OK] -- OUT: 0 [OK]
- IN: clean testsubdir/test3 '\''sq'\'',\$x=.r $S3 [OK] -- OUT: $S3 . [OK]
- IN: clean test.r $S [OK] -- OUT: $S . [OK]
- IN: clean test2.r $S2 [OK] -- OUT: $S2 . [OK]
- IN: clean test4-empty.r 0 [OK] -- OUT: 0 [OK]
- IN: clean testsubdir/test3 '\''sq'\'',\$x=.r $S3 [OK] -- OUT: $S3 . [OK]
- STOP
- EOF
- test_cmp_count expected.log rot13-filter.log &&
-
+ git commit -m "test commit 2" &&
rm -f test2.r "testsubdir/test3 '\''sq'\'',\$x=.r" &&
filter_git checkout --quiet --no-progress . &&
--
2.11.0
^ permalink raw reply related [flat|nested] 6+ messages in thread
* Re: [PATCH v1] t0021: fix flaky test
2016-12-18 12:37 ` [PATCH v1] t0021: fix flaky test larsxschneider
@ 2016-12-19 17:24 ` Ramsay Jones
2016-12-19 20:00 ` Jeff King
0 siblings, 1 reply; 6+ messages in thread
From: Ramsay Jones @ 2016-12-19 17:24 UTC (permalink / raw)
To: larsxschneider, git; +Cc: peff, gitster
On 18/12/16 12:37, larsxschneider@gmail.com wrote:
> From: Lars Schneider <larsxschneider@gmail.com>
>
> t0021.15 creates files, adds them to the index, and commits them. All
> this usually happens in a test run within the same second and Git cannot
> know if the files have been changed between `add` and `commit`. Thus,
> Git has to run the clean filter in both operations. Sometimes these
> invocations spread over two different seconds and Git can infer that the
> files were not changed between `add` and `commit` based on their
> modification timestamp. The test would fail as it expects the filter
> invocation. Remove this expectation to make the test stable.
>
> Signed-off-by: Lars Schneider <larsxschneider@gmail.com>
> ---
>
> Notes:
> Base Commit: f8bf8f2a7b (next)
> Diff on Web: https://github.com/git/git/compare/f8bf8f2a7b...larsxschneider:9d88b66e03
> Checkout: git fetch https://github.com/larsxschneider/git filter-process/fix-flaky-test-v1 && git checkout 9d88b66e03
>
> t/t0021-conversion.sh | 17 +----------------
> 1 file changed, 1 insertion(+), 16 deletions(-)
>
> diff --git a/t/t0021-conversion.sh b/t/t0021-conversion.sh
> index 6f16983d3e..161f560446 100755
> --- a/t/t0021-conversion.sh
> +++ b/t/t0021-conversion.sh
> @@ -377,22 +377,7 @@ test_expect_success PERL 'required process filter should filter data' '
> EOF
> test_cmp_count expected.log rot13-filter.log &&
>
> - filter_git commit -m "test commit 2" &&
> - cat >expected.log <<-EOF &&
> - START
> - init handshake complete
> - IN: clean test.r $S [OK] -- OUT: $S . [OK]
> - IN: clean test2.r $S2 [OK] -- OUT: $S2 . [OK]
> - IN: clean test4-empty.r 0 [OK] -- OUT: 0 [OK]
> - IN: clean testsubdir/test3 '\''sq'\'',\$x=.r $S3 [OK] -- OUT: $S3 . [OK]
> - IN: clean test.r $S [OK] -- OUT: $S . [OK]
> - IN: clean test2.r $S2 [OK] -- OUT: $S2 . [OK]
> - IN: clean test4-empty.r 0 [OK] -- OUT: 0 [OK]
> - IN: clean testsubdir/test3 '\''sq'\'',\$x=.r $S3 [OK] -- OUT: $S3 . [OK]
> - STOP
> - EOF
> - test_cmp_count expected.log rot13-filter.log &&
> -
> + git commit -m "test commit 2" &&
> rm -f test2.r "testsubdir/test3 '\''sq'\'',\$x=.r" &&
>
> filter_git checkout --quiet --no-progress . &&
>
I applied this to the pu branch and ran the test by hand
48 times in a row without failure. (the most trials without
error beforehand was 24).
Thanks.
ATB,
Ramsay Jones
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: [PATCH v1] t0021: fix flaky test
2016-12-19 17:24 ` Ramsay Jones
@ 2016-12-19 20:00 ` Jeff King
0 siblings, 0 replies; 6+ messages in thread
From: Jeff King @ 2016-12-19 20:00 UTC (permalink / raw)
To: Ramsay Jones; +Cc: larsxschneider, git, gitster
On Mon, Dec 19, 2016 at 05:24:32PM +0000, Ramsay Jones wrote:
> > t0021.15 creates files, adds them to the index, and commits them. All
> > this usually happens in a test run within the same second and Git cannot
> > know if the files have been changed between `add` and `commit`. Thus,
> > Git has to run the clean filter in both operations. Sometimes these
> > invocations spread over two different seconds and Git can infer that the
> > files were not changed between `add` and `commit` based on their
> > modification timestamp. The test would fail as it expects the filter
> > invocation. Remove this expectation to make the test stable.
> [...]
> I applied this to the pu branch and ran the test by hand
> 48 times in a row without failure. (the most trials without
> error beforehand was 24).
The original also fails nearly-instantly under my stress script[1], and
it runs for several minutes with this patch.
It might be instructive to try all of the tests under that script, but
it would require a fair bit of patience (and to some degree, people
running "make -j32 test" accomplishes the same thing over time).
-Peff
[1] https://github.com/peff/git/blob/meta/stress
^ permalink raw reply [flat|nested] 6+ messages in thread
end of thread, other threads:[~2016-12-19 20:01 UTC | newest]
Thread overview: 6+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2016-12-16 20:32 test failure Ramsay Jones
2016-12-17 14:28 ` Lars Schneider
2016-12-17 16:11 ` Lars Schneider
2016-12-18 12:37 ` [PATCH v1] t0021: fix flaky test larsxschneider
2016-12-19 17:24 ` Ramsay Jones
2016-12-19 20:00 ` Jeff King
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.