How I found out the what is the issue?
While working on a new feature to the HGCommandParser and HGConfig, I have noticed that time to time a test HGTests>>#test_commit_03 would fail when running rake test:package:stx:libscm/mercurial which runs all the tests for the libscm.
After I have finished adding the new feature I have decided to debug this weird bug. I have found out that if I start the test after doing rake clobber (cleaning the compiled files) and then rake compile the test would pass. It would also pass if I did not do anything! For example, I would start it Monday as last thing before shutting the computer. Next day I would run the test first thing in the morning and it would pass.
Now I knew something is fishy and I have decided to debug the issue. First, I have noticed that the removed key 'username' magically appears again
during the commit which makes the test failed!
After some debugging later I have noticed that in HGConfig>>#mustReloadBecauseOf: a constant number 1000 (of something) is added to the modification time. The logic here is to check if the .hgrc or mercurial.ini file is not newer than the current timestamp. If it is, then reload the configuration file again! Now it occurred to me maybe that 1000 is counted in seconds, which is about 16.7 minutes, but it should have been in milliseconds!
The test has been failing because it considered the HGConfig config file too new for the next 1000 seconds. During the test commit it reloaded the whole HGConfig file. Thus the deleted key 'username' appeared again and failing the test.
Go through the source code to find out details
The original test
There was nothing suspicious about the test’s source and why it should fail:
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
test_commit_03
"
Commit without configured author should raise an error
"
| repo wc |
repo := self repositoryNamed:'test_repo_01'.
wc := repo workingCopy.
( wc / 'f1.txt' ) writingFileDo:[:s | s nextPutAll:'modified from test_commit_02 2' ].
"Now, fake missing ui.username config entry"
(repo config root includesKey: #ui) ifTrue:[
(repo config get:#ui) removeKey: 'username' ifAbsent:[nil]
].
"Try commit"
HGAuthorQuery answer: nil do:["See HGTestCase>>performTest"
self should:[
wc commit:'test_commit_03 commit 1'
] raise: HGCommitError
]
"
UserPreferences fileBrowserClass openOn: repo directory.
"
"Created: / 07-12-2012 / 15:42:52 / jv"
Smalltalk/X supports single line comments
"/comment, which is great feature! I don’t understand why the other Smalltalk flavors did not take over this great feature and support only the traditional"comment"syntax. Take advantage of the single line comments when it makes sense! Note: All single line comments in the code presented have been replaced, because the web page syntax highlighter does not work correctly with them.
Debugging
I have placed a debug on the line wc commit:'test_commit_03 commit 1' to see what is actually going on.
I have noticed that sometimes in the HGWorkingCopy>>#commit:files:author:date:amend: the HGAuthorQuery query gave me nil and sometimes my username details. I wondered how it is possible when I did not change anything.
The HGWorkingCopy>>#commit:files:author:date:amend: source code:
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
commit:message files:files author: authorOrNil date: dateSpecOrNil amend: amend
"Commit given files with given message, author and date
(if provided). If files is nil, all tracked modified files
are commited.
If `authorOrNil` is nil, then default author (as configured in .hgrc)
is used.
Date can be a Timestamp or a String
If `amend` is true, previous changeset is amended (by means of `hg commit --amend`)
instead creating a new changeset with current one as parent.
"
| author |
author := authorOrNil.
author isNil ifTrue:[
author := HGAuthorQuery query.
author isNil ifTrue:[
author := repository config get: #(ui username) default: nil.
author isNil ifTrue:[
HGCommitError newException
parameter: { repository . message . files };
messageText: 'Commit author not specified!';
raise
].
].
].
^self repository execute:
(HGCommand commit
workingDirectory:root pathName;
message:message;
files:files;
author: author;
date: dateSpecOrNil;
amend: amend;
yourself).
"Created: / 25-08-2015 / 16:02:03 / Jan Vrany <jan.vrany@fit.cvut.cz>"
I went deeper and I have noticed there is a HGConfig>>#mustReload which could indicate some condition is satisfied and the HGConfig gets reloaded:
1
2
3
4
5
6
7
8
9
10
11
12
mustReload
root isNil ifTrue:[ ^ true ].
repository notNil ifTrue:[
(self mustReloadBecauseOf: repository path / '.hg' / 'hgrc') ifTrue:[
^true
].
].
HGConfig userConfigFiles do:[:e|
(self mustReloadBecauseOf: e) ifTrue:[ ^ true ].
].
^false
The first two conditions were trivial, and not the reason why anything would get reloaded. I had to take a look of the #mustReloadBecauseOf: in the third condition.
This will takes us to HGConfig>>#mustReloadBecauseOf::
1
2
3
4
5
6
7
8
9
10
mustReloadBecauseOf: filenameOrString
"Return true, if config must be reloaded because file is newer"
| filename |
filename := filenameOrString asFilename.
"compensate for lack of milliseconds in OS time ---v"
^filename exists and:[(filename modificationTime + 1000) >= timestamp].
"Created: / 07-12-2012 / 16:26:38 / jv"
After trying to save the HGConfig file I have noticed that the 1000 what is added appears to be in seconds!
Is it really adding seconds?
Yes, it is:
1
2
3
4
+ aNumberOrTimeDuration
"Add aNumber (numberOfSeconds) or, if it's a timeDuration, add it's value"
^ aNumberOrTimeDuration sumFromTimestamp:self.
You may have noticed the comment that was there, I noticed it after I figured out the issue, but it helped in reaffirming that the solution was indeed a correct one. Placing meaningful comments which reveal the true intentions of the programmers is also really important!
The shortened Walkback:
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
[BreakPointInterrupt]: Breakpoint encountered at line 20 in HGTests >> #'test_commit_03' in process NewSystemBrowser [322]
(1000) SmallInteger(Integer) >> sumFromTimestamp: 2022-07-08 13:30:16 [1]
Timestamp(AbstractTime) >> + 1000 [4]
HGConfig >> mustReloadBecauseOf: UnixFilename('/home/tukan/.hgrc') [16]
[] in HGConfig>>mustReload >> value: UnixFilename('/home/tukan/.hgrc') [10]
Array >> do: [] in HGConfig>>mustReload [139]
HGConfig >> mustReload [9]
HGConfig >> root [6]
HGConfig >> get:default: #(#ui #username) nil [6]
HGWorkingCopy >> commit:files:author:date:amend: 'test_commit_03 commit 1' nil nil nil false [18]
HGWorkingCopy >> commit:files:author:date: 'test_commit_03 commit 1' nil nil nil [8]
HGWorkingCopy >> commit:files:author: 'test_commit_03 commit 1' nil nil [5]
HGWorkingCopy >> commit:files: 'test_commit_03 commit 1' nil [5]
HGWorkingCopy >> commit: 'test_commit_03 commit 1' [4]
[] in HGTests>>test_commit_03 >> value [20]
[] in TestCase>>executeShould:inScopeOf: >> value [11]
Block >> on:do: HGCommitError [] in TestCase>>executeShould:inScopeOf: [11]
HGTests(TestCase) >> executeShould:inScopeOf: [] in HGTests>>test_commit_03 HGCommitError [12]
HGTests(TestAsserter) >> should:raise: [] in HGTests>>test_commit_03 HGCommitError [6]
[] in HGTests>>test_commit_03 >> value [19]
HGAuthorQuery class(Notification class) >> answer:do: nil [] in HGTests>>test_commit_03 [10]
HGTests >> test_commit_03 [18]
HGTests(Object) >> perform: #'test_commit_03' [32]
HGTests(TestCase) >> performTest [2]
[] in HGTestCase>>performTest >> value [10]
Block >> ensure: [] in HGTestCase>>performTest [12]
[] in HGTestCase>>performTest >> value [11]
QuerySignal >> answer:do: false [] in HGTestCase>>performTest [10]
[] in HGTestCase>>performTest >> value [4]
HGAuthorQuery class(Notification class) >> answer:do: 'test_commit_03 <test_commit_03@HGTests>' [] in HGTestCase>>performTest [10]
HGTests(HGTestCase) >> performTest [3]
...
Now if correct message is sent to 1000, the #milliseconds now the test starts working. Now we are saying that the HGConfig file is considered fresh new only for the next 1000 milliseconds instead of 1000 seconds.
The fixed method
The fix is trivial, adding the #milliseconds message to the 1000 number. The fixed methods is:
1
2
3
4
5
6
7
8
9
10
mustReloadBecauseOf: filenameOrString
"Return true, if config must be reloaded because file is newer"
| filename |
filename := filenameOrString asFilename.
"compensate for lack of milliseconds in OS time ---v"
^filename exists and:[(filename modificationTime + 1000 milliseconds) >= timestamp].
"Created: / 07-12-2012 / 16:26:38 / jv"
The shortened Walkback of corrected method where we add milliseconds and not seconds:
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
[[BreakPointInterrupt]: Breakpoint encountered at line 20 in HGTests >> #'test_commit_03' in process NewSystemBrowser [237]
TimeDuration class >> fromMilliseconds: 1000 [1]
(1000) SmallInteger(Number) >> milliseconds [5]
HGConfig >> mustReloadBecauseOf: UnixFilename('/home/tukan/.hgrc') [630]
[] in HGConfig>>mustReload >> value: UnixFilename('/home/tukan/.hgrc') [10]
Array >> do: [] in HGConfig>>mustReload [139]
HGConfig >> mustReload [9]
HGConfig >> root [6]
HGConfig >> get:default: #(#ui #username) nil [6]
HGWorkingCopy >> commit:files:author:date:amend: 'test_commit_03 commit 1' nil nil nil false [18]
HGWorkingCopy >> commit:files:author:date: 'test_commit_03 commit 1' nil nil nil [8]
HGWorkingCopy >> commit:files:author: 'test_commit_03 commit 1' nil nil [5]
HGWorkingCopy >> commit:files: 'test_commit_03 commit 1' nil [5]
HGWorkingCopy >> commit: 'test_commit_03 commit 1' [4]
[] in HGTests>>test_commit_03 >> value [20]
[] in TestCase>>executeShould:inScopeOf: >> value [11]
Block >> on:do: HGCommitError [] in TestCase>>executeShould:inScopeOf: [11]
HGTests(TestCase) >> executeShould:inScopeOf: [] in HGTests>>test_commit_03 HGCommitError [12]
HGTests(TestAsserter) >> should:raise: [] in HGTests>>test_commit_03 HGCommitError [6]
[] in HGTests>>test_commit_03 >> value [19]
HGAuthorQuery class(Notification class) >> answer:do: nil [] in HGTests>>test_commit_03 [10]
HGTests >> test_commit_03 [18]
HGTests(Object) >> perform: #'test_commit_03' [32]
HGTests(TestCase) >> performTest [2]
[] in HGTestCase>>performTest >> value [10]
Block >> ensure: [] in HGTestCase>>performTest [12]
[] in HGTestCase>>performTest >> value [11]
QuerySignal >> answer:do: false [] in HGTestCase>>performTest [10]
[] in HGTestCase>>performTest >> value [4]
HGAuthorQuery class(Notification class) >> answer:do: 'test_commit_03 <test_commit_03@HGTests>' [] in HGTestCase>>performTest [10]
HGTests(HGTestCase) >> performTest [3]
...
Fix is create now we need to test it
To create a test which will test if the time when the HGConfig files is considered new and must reload. The tests uses linux touch or PowerShell’s .LastWriteTime to modify the HGconfig file modification time.
When the test fails it will probably fail directly in the commit. The subsequent assert is there for the programmer to see what to check for.
Here is the complete test of the too new HGConfig file:
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
test_reload_hgrc
"
Test if HGConfig userConfigFile does not get internally reloaded for being too new
(HGConfig>>mustReloadBecauseOf:)
"
| repo wc |
repo := self repositoryNamed:'test_repo_01'.
wc := repo workingCopy.
( wc / 'f1.txt' ) writingFileDo:[:s | s nextPutAll:'modified from test_commit_02 2' ].
"Check if ui.username is present"
self assert: ((repo config get:#ui) includesKey: 'username').
"Now, fake missing ui.username config entry"
(repo config root includesKey: #ui) ifTrue:[
(repo config get:#ui) removeKey: 'username' ifAbsent:[nil]
].
"Changing the HGConfig userConfigFile modification time to one minute into the past.
This is to see if the configuration file does not get internally reloaded, for being too new,
when performing commit."
OperatingSystem isMSWINDOWSlike ifTrue:[
OperatingSystem executeCommand:('Powershell.exe -Command "(Get-Item "%1").LastWriteTime = New-object DateTime(Get-Date.AddMinutes(-1))"'
bindWith: HGConfig userConfigFile pathName)
] ifFalse:[ "isUNIXlike (don't know if it will work on iOSXlike must contain touch)"
"-m change only the modification time
-t STAMP use [[CC]YY]MMDDhhmm[.ss] instead of current time"
OperatingSystem executeCommand:('touch -mt `date +"%y%m%d%H%M" --date="1 min ago"` %1' bindWith: HGConfig userConfigFile pathName)
].
"Try commit"
HGAuthorQuery answer: nil do:["See HGTestCase>>performTest"
self should:[
wc commit:'test_commit_03 commit 1'
] raise: HGCommitError
].
"The username is still missing -> no internal .hgrc reload
HGConfig >> mustReload (mustReloadBecauseOf:)"
self deny: ((repo config get:#ui) includesKey: 'username')
"
UserPreferences fileBrowserClass openOn: repo directory.
"
Conclusion
Today I showed how to debug failing test in Smalltalk/X. While this is not a tutorial for Smalltalk/X debugging it should give a reader an insight of the logic how an issue is debugged in Smalltalk/X.
If only one thing you should take from this article: you want to always specify units when working with constant time! It will bite you later if you don’t!
Note: In this blog I’m using Smalltalk/x-jv branch, which is maintained by Jan Vraný. The upstream Smalltalk/X was created and build by Claus Gittinger. It is used in products developed by the eXept company.