t1450-fsck (sometimes/often) failes on Mac OS X

t1450-fsck (sometimes/often) failes on Mac OS X

[Torsten Bögershausen]

I saw the problem first on pu, some time ago, 
but it dissappeared after cloning git.git into another directory.

Now it appeared on next as well, so it's time to look a little bit deeper.

This test case of t1450 fails:
test_expect_success 'tag pointing to something else than its type' '

To debug more, I added an exit 0 here to inspect the file named out:
diff --git a/t/t1450-fsck.sh b/t/t1450-fsck.sh
index 5b79c51..f1f45c9 100755
--- a/t/t1450-fsck.sh
+++ b/t/t1450-fsck.sh
@@ -179,6 +179,7 @@ test_expect_success 'tag pointing to something else than its type' '
        test_when_finished "git update-ref -d refs/tags/wrong" &&
        test_must_fail git fsck --tags 2>out &&
        cat out &&
+       exit 0
        grep "error in tag.*broken links" out
 '

Linux:
error: Object 63499e4ea8e096b831515ceb1d5a7593e4d87ae5 is a blob, not a commit
error in tag 66f6581d549f70e05ca586bc2df5c15a95662c36: broken links
error in tag 66f6581d549f70e05ca586bc2df5c15a95662c36: could not load tagged object

Mac OS X:
error: Object 63499e4ea8e096b831515ceb1d5a7593e4d87ae5 is a commit, not a blob
error: 63499e4ea8e096b831515ceb1d5a7593e4d87ae5: object corrupt or missing

I reverted the last change in fsck.c (Use the streaming interface), but that doesn't help

Looking into the trash directory and looking at the files, we can see that the .git/index is different
between Linux and Mac OS X.

Is there a good way to debug the index file?

BTW:  git bisect pointed out: 
 [76759c7dff53e8c84e975b88cb8245587c14c7ba] git on Mac OS and precomposed unicode
But re-running t1450 makes it pass, so that bisect went into the wrong direction
somewhere.

It seems that t1450 is timing depending, sometimes it passes, sometimes not.
And once it went into the state "non passed", it stays there.

It feels that I got stuck, any hints how to debug this further, please ?

/Torsten

Re: t1450-fsck (sometimes/often) failes on Mac OS X

[Jeff King]

On Sat, Jul 14, 2012 at 02:21:35PM +0200, Torsten Bögershausen wrote:

> I saw the problem first on pu, some time ago, 
> but it dissappeared after cloning git.git into another directory.
> 
> Now it appeared on next as well, so it's time to look a little bit deeper.
> 
> This test case of t1450 fails:
> test_expect_success 'tag pointing to something else than its type' '

I can't reproduce this failure; I tried both pu or next, on Linux and OS
X (10.7).

> Linux:
> error: Object 63499e4ea8e096b831515ceb1d5a7593e4d87ae5 is a blob, not a commit
> error in tag 66f6581d549f70e05ca586bc2df5c15a95662c36: broken links
> error in tag 66f6581d549f70e05ca586bc2df5c15a95662c36: could not load tagged object
> 
> Mac OS X:
> error: Object 63499e4ea8e096b831515ceb1d5a7593e4d87ae5 is a commit, not a blob
> error: 63499e4ea8e096b831515ceb1d5a7593e4d87ae5: object corrupt or missing

That seems very broken. That sha1 can have only one type, so OS X is
actually mis-parsing the object type? Weird. I would suggest a memory
error or race condition, but the test is valgrind-clean, and fsck should
not be threaded at all.

What does "git show 63499e4" show when the test has failed? If you
re-run "git fsck --tags", does it reproduce reliably (i.e., is it bogus
data that something wrote to the object db, or is it good data being
ruined during the reading process)?

> I reverted the last change in fsck.c (Use the streaming interface), but that doesn't help
> 
> Looking into the trash directory and looking at the files, we can see that the .git/index is different
> between Linux and Mac OS X.
> 
> Is there a good way to debug the index file?

git ls-files -s will dump the entries. But I'd expect them not to be
byte-equivalent, because the index will contain things like mtimes for
each entry, which will vary from run to run. Plus the error message
above indicates something much more broken.

-Peff

Re: t1450-fsck (sometimes/often) failes on Mac OS X

[Torsten Bögershausen]

Peff, thanks for looking into this.

My answers are inline and at the end.

On 15.07.12 11:08, Jeff King wrote:
> On Sat, Jul 14, 2012 at 02:21:35PM +0200, Torsten Bögershausen wrote:
> 
>> I saw the problem first on pu, some time ago, 
>> but it dissappeared after cloning git.git into another directory.
>>
>> Now it appeared on next as well, so it's time to look a little bit deeper.
>>
>> This test case of t1450 fails:
>> test_expect_success 'tag pointing to something else than its type' '
> 
> I can't reproduce this failure; I tried both pu or next, on Linux and OS
> X (10.7).
> 
>> Linux:
>> error: Object 63499e4ea8e096b831515ceb1d5a7593e4d87ae5 is a blob, not a commit
>> error in tag 66f6581d549f70e05ca586bc2df5c15a95662c36: broken links
>> error in tag 66f6581d549f70e05ca586bc2df5c15a95662c36: could not load tagged object
>>
>> Mac OS X:
>> error: Object 63499e4ea8e096b831515ceb1d5a7593e4d87ae5 is a commit, not a blob
>> error: 63499e4ea8e096b831515ceb1d5a7593e4d87ae5: object corrupt or missing
> 
> That seems very broken. That sha1 can have only one type, so OS X is
> actually mis-parsing the object type? Weird. I would suggest a memory
> error or race condition, but the test is valgrind-clean, and fsck should
> not be threaded at all.
> 
> What does "git show 63499e4" show when the test has failed? 
 ../../git show 63499e4
blob


> If you re-run "git fsck --tags", does it reproduce reliably (i.e., is it bogus
> data that something wrote to the object db, or is it good data being
> ruined during the reading process)?

 ../../git fsck --tags
Checking object directories: 100% (256/256), done.
error: Object 63499e4ea8e096b831515ceb1d5a7593e4d87ae5 is a blob, not a commit
error in tag 66f6581d549f70e05ca586bc2df5c15a95662c36: broken links
error in tag 66f6581d549f70e05ca586bc2df5c15a95662c36: could not load tagged object
broken link from     tag 66f6581d549f70e05ca586bc2df5c15a95662c36
broken link from unknown unknown
dangling blob 63499e4ea8e096b831515ceb1d5a7593e4d87ae5

> 
>> I reverted the last change in fsck.c (Use the streaming interface), but that doesn't help
>>
>> Looking into the trash directory and looking at the files, we can see that the .git/index is different
>> between Linux and Mac OS X.
>>
>> Is there a good way to debug the index file?
> 
> git ls-files -s will dump the entries. But I'd expect them not to be
> byte-equivalent, because the index will contain things like mtimes for
> each entry, which will vary from run to run. Plus the error message
> above indicates something much more broken.
 ../../git ls-files -s
100644 5626abf0f72e58d7a153368ba57db4c673c0e171 0       fileA
100644 f719efd430d52bcfc8566a43b2eb655688d38871 0       fileB


I did some bisecting, and it didn't lead to a bad commit.
The problem goes away after another clone into a fresh directory.

Once it comes up, it seems to stay within that working tree.
Or it has something to do with the uptime of the machine (?)

Checking out v1.7.10 seems to make the problem go away, and
stepping up to e.g.
>commit d30ef5144cee3e9ed01a2a3f3b96d47c5322b20d
>    Merge branch 'jc/sha1-name-more' into next

brings the failure back.

This is probably not related to this very 2 commits, so may be a
"reverse bisect" would help, ("When does the problem go away?")

Thanks for helping

/Torsten












> 
> -Peff

Re: t1450-fsck (sometimes/often) failes on Mac OS X

[Torsten Bögershausen]

On 07/15/2012 11:08 AM, Jeff King wrote:
> On Sat, Jul 14, 2012 at 02:21:35PM +0200, Torsten Bögershausen wrote:
>
>> I saw the problem first on pu, some time ago,
>> but it dissappeared after cloning git.git into another directory.
>>
>> Now it appeared on next as well, so it's time to look a little bit deeper.
>>
>> This test case of t1450 fails:
>> test_expect_success 'tag pointing to something else than its type' '
>
> I can't reproduce this failure; I tried both pu or next, on Linux and OS
> X (10.7).
>
>> Linux:
>> error: Object 63499e4ea8e096b831515ceb1d5a7593e4d87ae5 is a blob, not a commit
>> error in tag 66f6581d549f70e05ca586bc2df5c15a95662c36: broken links
>> error in tag 66f6581d549f70e05ca586bc2df5c15a95662c36: could not load tagged object
>>
>> Mac OS X:
>> error: Object 63499e4ea8e096b831515ceb1d5a7593e4d87ae5 is a commit, not a blob
>> error: 63499e4ea8e096b831515ceb1d5a7593e4d87ae5: object corrupt or missing
>
> That seems very broken. That sha1 can have only one type, so OS X is
> actually mis-parsing the object type? Weird. I would suggest a memory
> error or race condition, but the test is valgrind-clean, and fsck should
> not be threaded at all.
>
> What does "git show 63499e4" show when the test has failed? If you
> re-run "git fsck --tags", does it reproduce reliably (i.e., is it bogus
> data that something wrote to the object db, or is it good data being
> ruined during the reading process)?
>
>> I reverted the last change in fsck.c (Use the streaming interface), but that doesn't help
>>
>> Looking into the trash directory and looking at the files, we can see that the .git/index is different
>> between Linux and Mac OS X.
>>
>> Is there a good way to debug the index file?
>
> git ls-files -s will dump the entries. But I'd expect them not to be
> byte-equivalent, because the index will contain things like mtimes for
> each entry, which will vary from run to run. Plus the error message
> above indicates something much more broken.
>
After some time, the problem is still there

When I make a fresh clone of git.git under Mac OS, 1450 passes.
After a while, running things like "git fetch && git checkout 
origin/next && make clean && make test", it starts to fail.

(currently I have a couple of git repo-copies, t1450 fails in git.pu 
and passes in git.next.
But that has nothing to do with next or pu)

When I run ssh into the Mac OS X machine, the test case passes even in pu.
Very strange, but reproducable.

Now things become more puzzled:
I managed to re-produce it on a Linux machine as well.
Using v1.7.12 and applying my i18.pathencoding patch,
t1450 fails on Linux, regardless if I use ssh or sit locally at the machine.

I make a new version of t1450-fsck.sh, called t1450-fsck2.sh
That uses git fsck --verbose, I add the log file here.
The short version:
- I can re-run the "git fsck", all files on disk have the same md5.
- The 63499e4ea8e096b831515ceb1d5a7593e4d87ae5 has the same md5 as well
I added lots of printouts in git code, according to my understanding 
63499  is checked/fsck'ed after being loaded into RAM, is that right?

For some reasons it is classified as "is a blob, not a commit" when it 
passes and "is a commit, not a blob" when it fails.

I want to debug when it is loaded into RAM, so that code is in 
read-cache.c, isn't it?

Does anybody have a tool to debug the contents of the index file?
Even offline could help, I can send a bunch of files ;-)

And why doesn't fsck find the broken link?

Other ideas are welcome,
thanks everybody for reading/helping.
/Torsten

"out" after running git fsck --verbose --tags, t1450 failed
(no broken link)
============
Checking HEAD link
Checking object directory
Checking directory .git/objects/13
Checking directory .git/objects/15
Checking directory .git/objects/1b
Checking directory .git/objects/30
Checking directory .git/objects/35
Checking directory .git/objects/44
Checking directory .git/objects/56
Checking directory .git/objects/63
Checking directory .git/objects/66
Checking directory .git/objects/af
Checking directory .git/objects/b6
Checking directory .git/objects/bd
Checking directory .git/objects/c4
Checking directory .git/objects/c9
Checking directory .git/objects/f7
Checking tag 66f6581d549f70e05ca586bc2df5c15a95662c36
Checking commit 134756353796a5439d93586be27999eea3807a34
Checking blob 5626abf0f72e58d7a153368ba57db4c673c0e171
error: Object 63499e4ea8e096b831515ceb1d5a7593e4d87ae5 is a commit, not 
a blob
error: 63499e4ea8e096b831515ceb1d5a7593e4d87ae5: object corrupt or missing
Checking tree bd04fbdc74c1ad468ee1cc86d49860490ab3e6c7
Checking commit c9145d6720f85544cc4bb6009a2e541660aa156b
Checking tree c9176b0dd1a95c80ad8de21784b1eeffd3681f49
Checking blob f719efd430d52bcfc8566a43b2eb655688d38871
Checking cache tree
Checking connectivity (32 objects)
Checking 63499e4ea8e096b831515ceb1d5a7593e4d87ae5
Checking 66f6581d549f70e05ca586bc2df5c15a95662c36
Checking c9145d6720f85544cc4bb6009a2e541660aa156b
Checking c9176b0dd1a95c80ad8de21784b1eeffd3681f49
Checking 134756353796a5439d93586be27999eea3807a34
Checking 5626abf0f72e58d7a153368ba57db4c673c0e171
Checking f719efd430d52bcfc8566a43b2eb655688d38871
Checking bd04fbdc74c1ad468ee1cc86d49860490ab3e6c7
===========


diff failed passed
diff out ../../../git.next/t/trash_directory.t1450-fsck2_120912_205305/out
17a18,20
 > Checking blob 5626abf0f72e58d7a153368ba57db4c673c0e171
 > Checking blob 63499e4ea8e096b831515ceb1d5a7593e4d87ae5
 > error: Object 63499e4ea8e096b831515ceb1d5a7593e4d87ae5 is a blob, not 
a commit
18a22,23
 > error in tag 66f6581d549f70e05ca586bc2df5c15a95662c36: broken links
 > error in tag 66f6581d549f70e05ca586bc2df5c15a95662c36: could not load 
tagged object
20,22d24
< Checking blob 5626abf0f72e58d7a153368ba57db4c673c0e171
< error: Object 63499e4ea8e096b831515ceb1d5a7593e4d87ae5 is a commit, 
not a blob
< error: 63499e4ea8e096b831515ceb1d5a7593e4d87ae5: object corrupt or missing

Re: t1450-fsck (sometimes/often) failes on Mac OS X

[Junio C Hamano]

Torsten Bögershausen <tboegi@web.de> writes:

>>> Linux:
>>> error: Object 63499e4ea8e096b831515ceb1d5a7593e4d87ae5 is a blob, not a commit
>>> error in tag 66f6581d549f70e05ca586bc2df5c15a95662c36: broken links
>>> error in tag 66f6581d549f70e05ca586bc2df5c15a95662c36: could not load tagged object
>>>
>>> Mac OS X:
>>> error: Object 63499e4ea8e096b831515ceb1d5a7593e4d87ae5 is a commit, not a blob
>>> error: 63499e4ea8e096b831515ceb1d5a7593e4d87ae5: object corrupt or missing

Interesting difference.

>> That seems very broken. That sha1 can have only one type, so OS X is
>> actually mis-parsing the object type? Weird. I would suggest a memory
>> error or race condition, but the test is valgrind-clean, and fsck should
>> not be threaded at all.

"is a blob, not a commit" is likely to come from validating of the
tag 66f6581d that presumably point at 63499e4; it reads the tag,
learns the name of the object that is tagged and the type of it,
remembers that the object pointed at (which it hasn't and is going
to validate next) _must_ be a commit (because tag says so) and then
realizes when it reads 63499e4 it is a blob and barfs.

And that is what _should_ happen in that test.  It crafts a
malformed tag that points at a blob and claims that it is a commit.
The test makes sure fsck catches that, and it does.

On the other hand, "is a commit, not a blob", unless you have a tag
that directly points at a blob, is more likely to come from
validating some tree object.  It reads the tree, learns the name of
the object contained in the tree and infers the type of that object
from the mode bits in the tree (100644 or 100755 would mean the
object must be a blob), goes on to validate that object and realizes
it is a commit and barfs.

It is veriy unusual to get, even on two different platforms, both
messages for the same object.

Could it be that you have i18n on "Object %s is a %s, not a %s" with
a wrong .po file that swaps the latter two parameters in the output?

>> What does "git show 63499e4" show when the test has failed?

Was this question ever answered (I would prever "cat-file -t"
followed by "cat-file <type>" instead of "show" for things like
this)?  It should show that it is a blob whose contents is "blob\n".

> Checking tag 66f6581d549f70e05ca586bc2df5c15a95662c36
> Checking commit 134756353796a5439d93586be27999eea3807a34
> Checking blob 5626abf0f72e58d7a153368ba57db4c673c0e171
> error: Object 63499e4ea8e096b831515ceb1d5a7593e4d87ae5 is a commit,
> not a blob
> error: 63499e4ea8e096b831515ceb1d5a7593e4d87ae5: object corrupt or missing
> Checking tree bd04fbdc74c1ad468ee1cc86d49860490ab3e6c7
> Checking commit c9145d6720f85544cc4bb6009a2e541660aa156b
> Checking tree c9176b0dd1a95c80ad8de21784b1eeffd3681f49
> Checking blob f719efd430d52bcfc8566a43b2eb655688d38871
> Checking cache tree
> Checking connectivity (32 objects)
> Checking 63499e4ea8e096b831515ceb1d5a7593e4d87ae5
> Checking 66f6581d549f70e05ca586bc2df5c15a95662c36
> Checking c9145d6720f85544cc4bb6009a2e541660aa156b
> Checking c9176b0dd1a95c80ad8de21784b1eeffd3681f49
> Checking 134756353796a5439d93586be27999eea3807a34
> Checking 5626abf0f72e58d7a153368ba57db4c673c0e171
> Checking f719efd430d52bcfc8566a43b2eb655688d38871
> Checking bd04fbdc74c1ad468ee1cc86d49860490ab3e6c7
> ===========
>
>
> diff failed passed
> diff out ../../../git.next/t/trash_directory.t1450-fsck2_120912_205305/out
> 17a18,20
>> Checking blob 5626abf0f72e58d7a153368ba57db4c673c0e171
>> Checking blob 63499e4ea8e096b831515ceb1d5a7593e4d87ae5
>> error: Object 63499e4ea8e096b831515ceb1d5a7593e4d87ae5 is a blob, not a commit

This is the correct behaviour.

> 18a22,23
>> error in tag 66f6581d549f70e05ca586bc2df5c15a95662c36: broken links
>> error in tag 66f6581d549f70e05ca586bc2df5c15a95662c36: could not load tagged object

This too.

> 20,22d24
> < Checking blob 5626abf0f72e58d7a153368ba57db4c673c0e171
> < error: Object 63499e4ea8e096b831515ceb1d5a7593e4d87ae5 is a commit, not a blob
> < error: 63499e4ea8e096b831515ceb1d5a7593e4d87ae5: object corrupt or missing

Re: t1450-fsck (sometimes/often) failes on Mac OS X

[Torsten Bögershausen]

Thanks Junio,
and all readers
commenst and answers are inline

On 19.09.12 20:30, Junio C Hamano wrote:
> Torsten Bögershausen <tboegi@web.de> writes:
> 
>>>> Linux:
>>>> error: Object 63499e4ea8e096b831515ceb1d5a7593e4d87ae5 is a blob, not a commit
>>>> error in tag 66f6581d549f70e05ca586bc2df5c15a95662c36: broken links
>>>> error in tag 66f6581d549f70e05ca586bc2df5c15a95662c36: could not load tagged object
>>>>
>>>> Mac OS X:
>>>> error: Object 63499e4ea8e096b831515ceb1d5a7593e4d87ae5 is a commit, not a blob
>>>> error: 63499e4ea8e096b831515ceb1d5a7593e4d87ae5: object corrupt or missing
> 
> Interesting difference.
> 
>>> That seems very broken. That sha1 can have only one type, so OS X is
>>> actually mis-parsing the object type? Weird. I would suggest a memory
>>> error or race condition, but the test is valgrind-clean, and fsck should
>>> not be threaded at all.
> 
> "is a blob, not a commit" is likely to come from validating of the
> tag 66f6581d that presumably point at 63499e4; it reads the tag,
> learns the name of the object that is tagged and the type of it,
> remembers that the object pointed at (which it hasn't and is going
> to validate next) _must_ be a commit (because tag says so) and then
> realizes when it reads 63499e4 it is a blob and barfs.
> 
> And that is what _should_ happen in that test.  It crafts a
> malformed tag that points at a blob and claims that it is a commit.
> The test makes sure fsck catches that, and it does.
> 
> On the other hand, "is a commit, not a blob", unless you have a tag
> that directly points at a blob, is more likely to come from
> validating some tree object.  It reads the tree, learns the name of
> the object contained in the tree and infers the type of that object
> from the mode bits in the tree (100644 or 100755 would mean the
> object must be a blob), goes on to validate that object and realizes
> it is a commit and barfs.
Sorry for not knowing better and asking stupid questions.
"Reads the tree", does it mean "read the index file" and put all objects into memory
or does it mean "scan the file system using readdir()"
Or is both done?

It looks as if there is a different execution order (wild speculation)

> 
> It is veriy unusual to get, even on two different platforms, both
> messages for the same object.
> 
> Could it be that you have i18n on "Object %s is a %s, not a %s" with
> a wrong .po file that swaps the latter two parameters in the output?
I'm using 
LANG=en_US.UTF-8

> 
>>> What does "git show 63499e4" show when the test has failed?
> 
> Was this question ever answered (I would prever "cat-file -t"
> followed by "cat-file <type>" instead of "show" for things like
> this)?  It should show that it is a blob whose contents is "blob\n".

The question was never answered - I recently learnt that 63499e4 has been removed by this line: 
	test_when_finished "remove_object $sha" &&
And when I remove that line in the modified test case, I get:
=====================
Mac OS X, failed
--------------
find . -name "499e4*" 
./.git/objects/63/499e4ea8e096b831515ceb1d5a7593e4d87ae5

find . -name "499e4*" | xargs xxd
0000000: 7801 4bca c94f 5230 6548 0252 5c00 1938  x.K..OR0eH.R\..8
0000010: 039e                                     ..

git show 63499e4
blob

git cat-file -t 63499e4
blob

git cat-file blob 63499e4
blob
=========================
Mac OS X passed
---------------
~/projects/git/git.next/t/trash_directory.t1450-fsck2_120919_214913> ../../../errors_on_master/1450/junio.sh
find . -name "499e4*" 
./.git/objects/63/499e4ea8e096b831515ceb1d5a7593e4d87ae5

find . -name "499e4*" | xargs xxd
0000000: 7801 4bca c94f 5230 6548 0252 5c00 1938  x.K..OR0eH.R\..8
0000010: 039e                                     ..

git show 63499e4
blob

git cat-file -t 63499e4
blob

git cat-file blob 63499e4
blob

==============
Linux failed
----------
find . -name "499e4*" 
./.git/objects/63/499e4ea8e096b831515ceb1d5a7593e4d87ae5

find . -name "499e4*" | xargs xxd
0000000: 7801 4bca c94f 5230 6548 0252 5c00 1938  x.K..OR0eH.R\..8
0000010: 039e                                     ..

git show 63499e4
blob

git cat-file -t 63499e4
blob

git cat-file blob 63499e4
blob
==========================
So unless I'm too tired to see, there doesn't seem to be a difference
[snip]
>>
>> diff failed passed
>> diff out ../../../git.next/t/trash_directory.t1450-fsck2_120912_205305/out
>> 17a18,20
>>> Checking blob 5626abf0f72e58d7a153368ba57db4c673c0e171
>>> Checking blob 63499e4ea8e096b831515ceb1d5a7593e4d87ae5
>>> error: Object 63499e4ea8e096b831515ceb1d5a7593e4d87ae5 is a blob, not a commit
> 
> This is the correct behaviour.
> 
>> 18a22,23
>>> error in tag 66f6581d549f70e05ca586bc2df5c15a95662c36: broken links
>>> error in tag 66f6581d549f70e05ca586bc2df5c15a95662c36: could not load tagged object
> 
> This too.
> 
>> 20,22d24
>> < Checking blob 5626abf0f72e58d7a153368ba57db4c673c0e171
>> < error: Object 63499e4ea8e096b831515ceb1d5a7593e4d87ae5 is a commit, not a blob
>> < error: 63499e4ea8e096b831515ceb1d5a7593e4d87ae5: object corrupt or missing

OK, both are correct. But why isn't the "broken links" not detected?
Does fsck stop in one case, but continue in the other?

/Torsten

Re: t1450-fsck (sometimes/often) failes on Mac OS X

[Torsten Bögershausen]

On 09/19/2012 08:30 PM, Junio C Hamano wrote:
> Torsten Bögershausen <tboegi@web.de> writes:
>
> "is a blob, not a commit" is likely to come from validating of the
> tag 66f6581d that presumably point at 63499e4; it reads the tag,
> learns the name of the object that is tagged and the type of it,
> remembers that the object pointed at (which it hasn't and is going
> to validate next) _must_ be a commit (because tag says so) and then
> realizes when it reads 63499e4 it is a blob and barfs.
>
> And that is what _should_ happen in that test.  It crafts a
> malformed tag that points at a blob and claims that it is a commit.
> The test makes sure fsck catches that, and it does.
>
> On the other hand, "is a commit, not a blob", unless you have a tag
> that directly points at a blob, is more likely to come from
> validating some tree object.  It reads the tree, learns the name of
> the object contained in the tree and infers the type of that object
> from the mode bits in the tree (100644 or 100755 would mean the
> object must be a blob), goes on to validate that object and realizes
> it is a commit and barfs.
>


The good news:
With help of Junio's comments I probably found the reason why the test 
behaves differently:

The objects are checked in a certain order, based on the inode number.

Which seems to be the same on most machines: when files are created
in a certain order, then the inode numbers are in the same order.

When the inode numbering changes for reasons known to the file system, 
the order changes and fsck takes a different code path.

To provoke the error, the following helped at my Linux box:

diff --git a/builtin/fsck.c b/builtin/fsck.c
index a710227..bba8082 100644
--- a/builtin/fsck.c
+++ b/builtin/fsck.c
@@ -373,7 +373,7 @@ static struct {

  static int ino_compare(const void *_a, const void *_b)
  {
-       const struct sha1_entry *a = _a, *b = _b;
+       const struct sha1_entry *a = _b, *b = _a;
         unsigned long ino1 = a->ino, ino2 = b->ino;
         return ino1 < ino2 ? -1 : ino1 > ino2 ? 1 : 0;
  }

The bad news: I haven't found the time to prepare a fix.

/Torsten

Re: t1450-fsck (sometimes/often) failes on Mac OS X

[Junio C Hamano]

Torsten Bögershausen <tboegi@web.de> writes:

> With help of Junio's comments I probably found the reason why the test
> behaves differently:
>
> The objects are checked in a certain order, based on the inode number.
>
> Which seems to be the same on most machines: when files are created
> in a certain order, then the inode numbers are in the same order.
>
> When the inode numbering changes for reasons known to the file system,
> the order changes and fsck takes a different code path.
>
> To provoke the error, the following helped at my Linux box:
>
> diff --git a/builtin/fsck.c b/builtin/fsck.c
> index a710227..bba8082 100644
> --- a/builtin/fsck.c
> +++ b/builtin/fsck.c
> @@ -373,7 +373,7 @@ static struct {
>
>  static int ino_compare(const void *_a, const void *_b)
>  {
> -       const struct sha1_entry *a = _a, *b = _b;
> +       const struct sha1_entry *a = _b, *b = _a;
>         unsigned long ino1 = a->ino, ino2 = b->ino;
>         return ino1 < ino2 ? -1 : ino1 > ino2 ? 1 : 0;
>  }
>
> The bad news: I haven't found the time to prepare a fix.

Thanks for a reproduction. Yes, the test t1450.13 is expecting too
much.

If it finds the $sha blob first and then looks at $tag tag, then it
will notice that the tag is pointing at a blob but claims it must be
a commit.  If it finds the $tag tag first, it will remember that the
tag claimed $sha must be a commit, and when later it sees $sha, it
finds that it is not of the type it is expecting (namely, a commit),
and says "the object called $sha is broken".

So "test_must_fail git fsck --tags" is correct.  The fsck must find
the breakage either way.

The last piece to expect "error in tag.*broken links" in the output
is wrong.  Probably we should remove the misguided check and end
it with "test_must_fail git fsck --tags".

Re: t1450-fsck (sometimes/often) failes on Mac OS X

[Junio C Hamano]

Junio C Hamano <gitster@pobox.com> writes:

> The last piece to expect "error in tag.*broken links" in the output
> is wrong.  Probably we should remove the misguided check and end
> it with "test_must_fail git fsck --tags".

I think this should suffice.

When we check tag T first, we make a mental note on X that is
referred by T that X must be of a certain type, but we do not bother
recording _why_ we decided X must be of the type (e.g. "because tag
T asks it to be").  So when we check T and later check X, the only
thing we know is that we expected X to be commit but it actually is
blob.  Exactly the same type of issue can arise for a blob that is
pointed by a tree or a tree that is pointed by a commit.  If a tree
records a reference to a commit but with 100644 mode bits, we may
either say tree is broken (when we have already seen the referent
and know it is a commit), or the referent is broken (when we saw the
tree first and expect the referent to be a blob).

-- >8 --
Subject: [PATCH] t1450: the order the objects are checked is undefined

When a tag T points at an object X that is of a type that is
different from what the tag records as, fsck should report it as an
error.

However, depending on the order X and T are checked individually,
the actual error message can be different.  If X is checked first,
fsck remembers X's type and then when it checks T, it notices that T
records X as a wrong type (i.e. the complaint is about a broken tag
T).  If T is checked first, on the other hand, fsck remembers that we
need to verify X is of the type tag records, and when it later
checks X, it notices that X is of a wrong type (i.e. the complaint
is about a broken object X).

The important thing is that fsck notices such an error and diagnoses
the issue on object X, but the test was expecting that we happen to
check objects in the order to make us detect issues with tag T, not
with object X.  Remove this unwarranted assumption.

Signed-off-by: Junio C Hamano <gitster@pobox.com>
---
 t/t1450-fsck.sh | 4 +---
 1 file changed, 1 insertion(+), 3 deletions(-)

diff --git a/t/t1450-fsck.sh b/t/t1450-fsck.sh
index 5b79c51..9c64eef 100755
--- a/t/t1450-fsck.sh
+++ b/t/t1450-fsck.sh
@@ -177,9 +177,7 @@ test_expect_success 'tag pointing to something else than its type' '
 	test_when_finished "remove_object $tag" &&
 	echo $tag >.git/refs/tags/wrong &&
 	test_when_finished "git update-ref -d refs/tags/wrong" &&
-	test_must_fail git fsck --tags 2>out &&
-	cat out &&
-	grep "error in tag.*broken links" out
+	test_must_fail git fsck --tags
 '
 
 test_expect_success 'cleaned up' '
-- 
1.8.0.rc0.54.g771a61b

Re: t1450-fsck (sometimes/often) failes on Mac OS X

[Torsten Bögershausen]

On 03.10.12 00:21, Junio C Hamano wrote:
> I think this should suffice.
> [snip]
> -	test_must_fail git fsck --tags 2>out &&
> -	cat out &&
> -	grep "error in tag.*broken links" out
> +	test_must_fail git fsck --tags
[snip]

Thanks, and all TC passed in pu.
/Torsten

Re: t1450-fsck (sometimes/often) failes on Mac OS X

[Thomas Rast]

Torsten Bögershausen <tboegi@web.de> writes:

> Now it appeared on next as well, so it's time to look a little bit deeper.
>
> This test case of t1450 fails:
> test_expect_success 'tag pointing to something else than its type' '
>
> To debug more, I added an exit 0 here to inspect the file named out:
> diff --git a/t/t1450-fsck.sh b/t/t1450-fsck.sh
> index 5b79c51..f1f45c9 100755
> --- a/t/t1450-fsck.sh
> +++ b/t/t1450-fsck.sh
> @@ -179,6 +179,7 @@ test_expect_success 'tag pointing to something else than its type' '
>         test_when_finished "git update-ref -d refs/tags/wrong" &&
>         test_must_fail git fsck --tags 2>out &&
>         cat out &&
> +       exit 0
>         grep "error in tag.*broken links" out
>  '
>
> Linux:
> error: Object 63499e4ea8e096b831515ceb1d5a7593e4d87ae5 is a blob, not a commit
> error in tag 66f6581d549f70e05ca586bc2df5c15a95662c36: broken links
> error in tag 66f6581d549f70e05ca586bc2df5c15a95662c36: could not load tagged object
>
> Mac OS X:
> error: Object 63499e4ea8e096b831515ceb1d5a7593e4d87ae5 is a commit, not a blob
> error: 63499e4ea8e096b831515ceb1d5a7593e4d87ae5: object corrupt or missing

What OS X are you running?  I started a loop

  while : ; do ./t1450-fsck.sh || break; done

and it hasn't failed yet.  It is

  $ uname -a
  Darwin mackeller.inf.ethz.ch 11.4.0 Darwin Kernel Version 11.4.0: Mon Apr  9 19:32:15 PDT 2012; root:xnu-1699.26.8~1/RELEASE_X86_64 x86_64

> I reverted the last change in fsck.c (Use the streaming interface), but that doesn't help
>
> Looking into the trash directory and looking at the files, we can see that the .git/index is different
> between Linux and Mac OS X.
>
> Is there a good way to debug the index file?

You can run 'git ls-files --debug' which should give you all the data in
the index, and then perhaps run diff over that to determine the
differences...

-- 
Thomas Rast
trast@{inf,student}.ethz.ch

Re: t1450-fsck (sometimes/often) failes on Mac OS X

[Torsten Bögershausen]

Am 16.07.2012 um 09:57 schrieb Thomas Rast:

> Torsten Bögershausen <tboegi@web.de> writes:
> 
>> Now it appeared on next as well, so it's time to look a little bit deeper.
>> 
>> This test case of t1450 fails:
>> test_expect_success 'tag pointing to something else than its type' '
>> 
>> To debug more, I added an exit 0 here to inspect the file named out:
>> diff --git a/t/t1450-fsck.sh b/t/t1450-fsck.sh
>> index 5b79c51..f1f45c9 100755
>> --- a/t/t1450-fsck.sh
>> +++ b/t/t1450-fsck.sh
>> @@ -179,6 +179,7 @@ test_expect_success 'tag pointing to something else than its type' '
>>        test_when_finished "git update-ref -d refs/tags/wrong" &&
>>        test_must_fail git fsck --tags 2>out &&
>>        cat out &&
>> +       exit 0
>>        grep "error in tag.*broken links" out
>> '
>> 
>> Linux:
>> error: Object 63499e4ea8e096b831515ceb1d5a7593e4d87ae5 is a blob, not a commit
>> error in tag 66f6581d549f70e05ca586bc2df5c15a95662c36: broken links
>> error in tag 66f6581d549f70e05ca586bc2df5c15a95662c36: could not load tagged object
>> 
>> Mac OS X:
>> error: Object 63499e4ea8e096b831515ceb1d5a7593e4d87ae5 is a commit, not a blob
>> error: 63499e4ea8e096b831515ceb1d5a7593e4d87ae5: object corrupt or missing
> 
> What OS X are you running?  I started a loop
> 
>  while : ; do ./t1450-fsck.sh || break; done
> 
> and it hasn't failed yet.  It is
> 
>  $ uname -a
>  Darwin mackeller.inf.ethz.ch 11.4.0 Darwin Kernel Version 11.4.0: Mon Apr  9 19:32:15 PDT 2012; root:xnu-1699.26.8~1/RELEASE_X86_64 x86_64
> 
 uname -a
Darwin birne.lan 10.8.0 Darwin Kernel Version 10.8.0: Tue Jun  7 16:33:36 PDT 2011; root:xnu-1504.15.3~1/RELEASE_I386 i386
> 
> You can run 'git ls-files --debug' which should give you all the data in
> the index, and then perhaps run diff over that to determine the
> differences...
> 

That lloks like this:

fileA
  ctime: 1342453768:0
  mtime: 1342453768:0
  dev: 234881026        ino: 92698027
  uid: 1500     gid: 20
  size: 4       flags: 5
fileB
  ctime: 1342453768:0
  mtime: 1342453768:0
  dev: 234881026        ino: 92698053
  uid: 1500     gid: 20
  size: 4       flags: 5

==================
But what is interesting, is that 
a) When I clone a fresh copy from git.git, it works OK. After some activity with the working dir,
  suddenly t1450 fails. Switching back to e.g. v1.7.11 makes t1450  pass again.
  Switching to origin/next , running make brings back the problem, t1450 fails

b) The failure seems to be time critical. When I run the test yesterday evening,
   being logged in via ssh makes the test pass.
   Sitting at the machine makes it fail.

c) It seems as if there is a problem when writing to disk.
   Could be the index file
   (git ls-files --debug does not dump the whole index, does it?)

d) As Peff pointed out, the fsck itself is not time critical.
  
Thanks for looking into it

Re: t1450-fsck (sometimes/often) failes on Mac OS X

[Heiko Voigt]

Hi,

just to verify that this is unlikely just a hardware issue on one machine. I
today experienced this failure on master as well.

On Mon, Jul 16, 2012 at 06:06:26PM +0200, Torsten B?gershausen wrote:
> 
> Am 16.07.2012 um 09:57 schrieb Thomas Rast:
> 
> > Torsten Bögershausen <tboegi@web.de> writes:
> > What OS X are you running?  I started a loop
> > 
> >  while : ; do ./t1450-fsck.sh || break; done
> > 
> > and it hasn't failed yet.  It is
> > 
> >  $ uname -a
> >  Darwin mackeller.inf.ethz.ch 11.4.0 Darwin Kernel Version 11.4.0: Mon Apr  9 19:32:15 PDT 2012; root:xnu-1699.26.8~1/RELEASE_X86_64 x86_64
> > 
>  uname -a
> Darwin birne.lan 10.8.0 Darwin Kernel Version 10.8.0: Tue Jun  7 16:33:36 PDT 2011; root:xnu-1504.15.3~1/RELEASE_I386 i386

$ uname -a
Darwin book.hvoigt.net 10.8.0 Darwin Kernel Version 10.8.0: Tue Jun  7 16:33:36 PDT 2011; root:xnu-1504.15.3~1/RELEASE_I386 i386

My bisect run did also not reveal anything useful. I tried to use valgrind.
Interestingly just by prepending my valgrind directory to the PATH the test
passes. When changing PATH further it sometimes passes and sometimes not.
Reopening a new shell it reliably fails.

The commit I am experiencing this with is cdd159b. This one reliably fails for
me with the correct path setting :-)

To me this smells a little bit like using a dangling pointer or uninitialized
memory since threading seems to be out of the game. A dangling pointer only
available on a certain OS X version?

If I modify the PATH after adding the valgrind bin folder so that it matches
the same amount of characters as before I get the failure again.

It seems the error only occurs if my PATH is exactly 280 characters long. E.g.:

export PATH=/usr/local/valgrind/bin:/Users/hvoigt/.local/bin:/usr/bin:/bin:/usr/local/bin:/sw/bin/:/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa

When running under valgrind test 13 (the original one) passes but 2 fails. Not
sure if this is a false positive[1].

If I add those eight bytes here the tests pass for me without valgrind:

diff --git a/environment.c b/environment.c
index 85edd7f..988f836 100644
--- a/environment.c
+++ b/environment.c
@@ -131,7 +131,7 @@ static void setup_git_env(void)
        }
        git_index_file = getenv(INDEX_ENVIRONMENT);
        if (!git_index_file) {
-               git_index_file = xmalloc(strlen(git_dir) + 7);
+               git_index_file = xmalloc(strlen(git_dir) + 7 + 8);
                sprintf(git_index_file, "%s/index", git_dir);
        }
        git_graft_file = getenv(GRAFT_ENVIRONMENT);

But maybe thats just a coincidence and totally unrelated.

The valgrind error can be fixed by this change:

diff --git a/sha1_file.c b/sha1_file.c
index 4ccaf7a..631d0dd 100644
--- a/sha1_file.c
+++ b/sha1_file.c
@@ -251,7 +251,7 @@ static int link_alt_odb_entry(const char * entry, int len, const char * relative
        const char *objdir = get_object_directory();
        struct alternate_object_database *ent;
        struct alternate_object_database *alt;
-       int pfxlen, entlen;
+       int pfxlen, entlen, objdirlen;
        struct strbuf pathbuf = STRBUF_INIT;
 
        if (!is_absolute_path(entry) && relative_base) {
@@ -298,7 +298,8 @@ static int link_alt_odb_entry(const char * entry, int len, const char * relative
                        return -1;
                }
        }
-       if (!memcmp(ent->base, objdir, pfxlen)) {
+       objdirlen = strlen(objdir);
+       if (!memcmp(ent->base, objdir, pfxlen > objdirlen ? objdirlen : pfxlen)) {
                free(ent);
                return -1;
        }

I will format this into a proper patch independent from this mail.

These are my observations.

Cheers Heiko

[1]
$ ./t1450-fsck.sh --valgrind
[...]
expecting success: 
	mkdir another &&
	(
		cd another &&
		git init &&
		echo ../../../.git/objects >.git/objects/info/alternates &&
		test_commit C fileC one &&
		git fsck --no-dangling >../actual 2>&1
	) &&
	test_cmp empty actual

Initialized empty Git repository in /Users/hvoigt/Repository/git/t/trash directory.t1450-fsck/another/.git/
==42686== Invalid read of size 8
==42686==    at 0x100625064: bcmp (in /usr/lib/libSystem.B.dylib)
==42686==    by 0x100112846: link_alt_odb_entries (in /Users/hvoigt/Repository/git/t/valgrind/../../git)
==42686==    by 0x1001129C0: read_info_alternates (in /Users/hvoigt/Repository/git/t/valgrind/../../git)
==42686==    by 0x100112B8C: prepare_alt_odb (in /Users/hvoigt/Repository/git/t/valgrind/../../git)
==42686==    by 0x1001148B7: prepare_packed_git (in /Users/hvoigt/Repository/git/t/valgrind/../../git)
==42686==    by 0x100116A8B: find_pack_entry (in /Users/hvoigt/Repository/git/t/valgrind/../../git)
==42686==    by 0x100118008: has_sha1_file (in /Users/hvoigt/Repository/git/t/valgrind/../../git)
==42686==    by 0x100117DFA: write_sha1_file (in /Users/hvoigt/Repository/git/t/valgrind/../../git)
==42686==    by 0x100118268: index_mem (in /Users/hvoigt/Repository/git/t/valgrind/../../git)
==42686==    by 0x1001183DC: index_core (in /Users/hvoigt/Repository/git/t/valgrind/../../git)
==42686==    by 0x100118586: index_fd (in /Users/hvoigt/Repository/git/t/valgrind/../../git)
==42686==    by 0x1001186DA: index_path (in /Users/hvoigt/Repository/git/t/valgrind/../../git)
==42686==  Address 0x100faca78 is 8 bytes inside a block of size 13 alloc'd
==42686==    at 0x10029C679: malloc (vg_replace_malloc.c:266)
==42686==    by 0x1001349CD: xmalloc (in /Users/hvoigt/Repository/git/t/valgrind/../../git)
==42686==    by 0x1000C23F5: setup_git_env (in /Users/hvoigt/Repository/git/t/valgrind/../../git)
==42686==    by 0x1000C286B: set_git_dir (in /Users/hvoigt/Repository/git/t/valgrind/../../git)
==42686==    by 0x100110128: setup_work_tree (in /Users/hvoigt/Repository/git/t/valgrind/../../git)
==42686==    by 0x1000022F2: run_builtin (in /Users/hvoigt/Repository/git/t/valgrind/../../git)
==42686==    by 0x1000024DA: handle_internal_command (in /Users/hvoigt/Repository/git/t/valgrind/../../git)
==42686==    by 0x1000025E8: run_argv (in /Users/hvoigt/Repository/git/t/valgrind/../../git)
==42686==    by 0x10000275F: main (in /Users/hvoigt/Repository/git/t/valgrind/../../git)
==42686== 
{
   <insert_a_suppression_name_here>
   Memcheck:Addr8
   fun:bcmp
   fun:link_alt_odb_entries
   fun:read_info_alternates
   fun:prepare_alt_odb
   fun:prepare_packed_git
   fun:find_pack_entry
   fun:has_sha1_file
   fun:write_sha1_file
   fun:index_mem
   fun:index_core
   fun:index_fd
   fun:index_path
}
not ok - 2 loose objects borrowed from alternate are not missing

Re: t1450-fsck (sometimes/often) failes on Mac OS X

[Thomas Rast]

Heiko Voigt <hvoigt@hvoigt.net> writes:

>         if (!git_index_file) {
> -               git_index_file = xmalloc(strlen(git_dir) + 7);
> +               git_index_file = xmalloc(strlen(git_dir) + 7 + 8);
>                 sprintf(git_index_file, "%s/index", git_dir);
>         }
[...]
> -       if (!memcmp(ent->base, objdir, pfxlen)) {
> +       objdirlen = strlen(objdir);
> +       if (!memcmp(ent->base, objdir, pfxlen > objdirlen ? objdirlen : pfxlen)) {
[...]
> Initialized empty Git repository in /Users/hvoigt/Repository/git/t/trash directory.t1450-fsck/another/.git/
> ==42686== Invalid read of size 8
> ==42686==    at 0x100625064: bcmp (in /usr/lib/libSystem.B.dylib)
> ==42686==    by 0x100112846: link_alt_odb_entries (in /Users/hvoigt/Repository/git/t/valgrind/../../git)
> ==42686==    by 0x1001129C0: read_info_alternates (in /Users/hvoigt/Repository/git/t/valgrind/../../git)
[...]
> ==42686==  Address 0x100faca78 is 8 bytes inside a block of size 13 alloc'd
> ==42686==    at 0x10029C679: malloc (vg_replace_malloc.c:266)
> ==42686==    by 0x1001349CD: xmalloc (in /Users/hvoigt/Repository/git/t/valgrind/../../git)
> ==42686==    by 0x1000C23F5: setup_git_env (in /Users/hvoigt/Repository/git/t/valgrind/../../git)

To me that looks just like a false positive.  memcmp (which seems to be
the same as bcmp) can load 8 bytes from an aligned address even if these
are only partially within the block being compared, since an aligned
load can never partially fault (it must all be within the same page).
Valgrind normally substitutes its own routines for memcmp etc. to
correctly handle this, but this does not seem to happen in your case for
some reason.

Then again I am not entirely sure how you could verify that this theory
is correct :-)

-- 
Thomas Rast
trast@{inf,student}.ethz.ch