Runtime: ConfigurationSaveTest.* failed in CI
https://ci.dot.net/job/dotnet_corefx/job/master/job/ubuntu14.04_release_prtest/6288/consoleText
MonoTests.System.Configuration.ConfigurationSaveTest.AddDefaultListElement2 [FAIL]
System.Configuration.ConfigurationErrorsException : The configuration file has been changed by another program. (/tmp/ex0jeypp.umq/h1zeuqy5.xax)
Stack Trace:
at System.Configuration.BaseConfigurationRecord.EvaluateOne(String[] keys, SectionInput input, Boolean isTrusted, FactoryRecord factoryRecord, SectionRecord sectionRecord, Object parentResult)
at System.Configuration.BaseConfigurationRecord.Evaluate(FactoryRecord factoryRecord, SectionRecord sectionRecord, Object parentResult, Boolean getLkg, Boolean getRuntimeObject, Object& result, Object& resultRuntimeObject)
at System.Configuration.BaseConfigurationRecord.GetSectionRecursive(String configKey, Boolean getLkg, Boolean checkPermission, Boolean getRuntimeObject, Boolean requestIsHere, Object& result, Object& resultRuntimeObject)
at System.Configuration.BaseConfigurationRecord.GetSectionRecursive(String configKey, Boolean getLkg, Boolean checkPermission, Boolean getRuntimeObject, Boolean requestIsHere, Object& result, Object& resultRuntimeObject)
at System.Configuration.ConfigurationSectionCollection.Get(String name)
at MonoTests.System.Configuration.ConfigurationSaveTest.<>c.<AddDefaultListElement2>b__17_0(Configuration config, TestLabel label)
at MonoTests.System.Configuration.ConfigurationSaveTest.<>c__DisplayClass12_0`1.<Run>b__0(String parent, String filename)
at MonoTests.System.Configuration.Util.TestUtil.RunWithTempFiles(MyAction`2 action)
stephentoub
All 23 comments
Failed again here:
https://ci.dot.net/job/dotnet_corefx/job/master/job/ubuntu14.04_release_prtest/6304/
stephentoub
on 16 Apr 2017
Failed again here:
https://ci.dot.net/job/dotnet_corefx/job/master/job/ubuntu14.04_debug_prtest/6298/
stephentoub
on 16 Apr 2017
Failed again here:
https://ci.dot.net/job/dotnet_corefx/job/master/job/centos7.1_release_prtest/6291/
stephentoub
on 16 Apr 2017
Disabled both AddDefaultListElement2 and AddDefaultListElement, which also failed with the same error.
stephentoub
on 16 Apr 2017
MonoTests.System.Configuration.ConfigurationSaveTest.TestElementWithCollection2
Failed with same error:
https://ci.dot.net/job/dotnet_corefx/job/master/job/centos7.1_debug_prtest/6288/
safern
on 16 Apr 2017
@JeremyKuhne, @danmosemsft, did something change recently with how the configuration tests are configured / run / etc.? Seems like several of the tests in the suite are hitting this same error. I already disabled two tests, but it looks like more would need to be disabled as well.
stephentoub
on 16 Apr 2017
I will disable the one I pointed out. Submitting PR now.
safern
on 16 Apr 2017
Another failure of TestElementWithCollection2
This one was in a different OS:
https://ci.dot.net/job/dotnet_corefx/job/master/job/portablelinux_release_prtest/3570/
safern
on 17 Apr 2017
Another one: MonoTests.System.Configuration.ConfigurationSaveTest.ModifyListElement2
https://ci.dot.net/job/dotnet_corefx/job/master/job/portablelinux_debug_prtest/3590/consoleText
stephentoub
on 17 Apr 2017
Another one: MonoTests.System.Configuration.ConfigurationSaveTest.ModifyListElement2
https://ci.dot.net/job/dotnet_corefx/job/master/job/centos7.1_release/2116/testReport/MonoTests.System.Configuration/ConfigurationSaveTest/ModifyListElement2/
KristinXie1
on 17 Apr 2017
Another one: MonoTests.System.Configuration.ConfigurationSaveTest.NotModifiedAfterSave
https://ci.dot.net/job/dotnet_corefx/job/master/job/ubuntu14.04_debug_prtest/6352/
safern
on 17 Apr 2017
Another one: MonoTests.System.Configuration.ConfigurationSaveTest.TestElementWithCollection
https://ci.dot.net/job/dotnet_corefx/job/master/job/portablelinux_release_prtest/3621/
safern
on 17 Apr 2017
Another hit: MonoTests.System.Configuration.ConfigurationSaveTest.AddElement
https://ci.dot.net/job/dotnet_corefx/job/master/job/ubuntu14.04_release_prtest/6439/testReport/junit/MonoTests.System.Configuration/ConfigurationSaveTest/AddElement/
@safern This looks like a wide-spread issue, are you working on it?
karelz
on 18 Apr 2017
I just disabled the whole class of tests and I've been investigating the whole night but it is kinda slow cause it is flaky it failes once every 10th or 20th run. I have a pretty solid lead though. I'm getting closer and the failures start to make sense, I think tomorrow could be fixed.
safern
on 18 Apr 2017
Perfect, much faster than I expected. Thank you!
karelz
on 18 Apr 2017
This test still failed: MonoTests.System.Configuration.ConfigurationSaveTest.ModifyListElement2
Detail: https://ci.dot.net/job/dotnet_corefx/job/master/job/outerloop_netcoreapp_debian8.4_release/18/testReport/MonoTests.System.Configuration/ConfigurationSaveTest/ModifyListElement2/
Does it also need to be disabled?
KristinXie1
on 18 Apr 2017
JonHanna
on 18 Apr 2017
Thanks @JonHanna this failed yesterday at 7pm and we disabled the whole test class at around 11pm, so now we should not see failures.
safern
on 18 Apr 2017
That was just in the last hour or so. Maybe I'm mis-identifying, but it seems to be the same class.
JonHanna
on 18 Apr 2017
The test is not being even executed, so how come it can fail? Is this failure the one you are pointing out on https://github.com/dotnet/corefx/pull/18421?
safern
on 18 Apr 2017
After a long investigation and debugging session I found what was the change that introduced this failure. The failure of this tests is happening because of: dotnet/corefx#18343 which we moved from setting the File.CreationTime from being default time on Unix if the file doesn't have a BirthTime to be the Minimum in between last access, modification and change time.
Why was this causing a failure in ConfigurationManagerTests?
Well when trying to get a configuration section (xml tag section from the config file) configuration manager will get an XmlReader out of a stream, then get a SectionInfo which will check if the config file hasn't change from when we retrieved the XmlReader to read the sections. Here is where we get into the exception being thrown if the file version has changed:
https://github.com/dotnet/corefx/blob/master/src/System.Configuration.ConfigurationManager/src/System/Configuration/BaseConfigurationRecord.cs#L1370-L1376
How do we check for the file versions?
We will keep track of the XmlReader stream, which will eventually flush the stream or access the file somehow, but it will not modify it, so access doesn't always means the file was modified.
When we do the check if the stream has changed we do the following:
https://github.com/dotnet/corefx/blob/master/src/System.Configuration.ConfigurationManager/src/System/Configuration/BaseConfigurationRecord.cs#L3555-L3562
Which will compare lastVersion VS currentVersion (which somehow could register an access to the file since we are reading the sections out of it and reading will update access time). This comparison will check for CreationTime and LastWriteTime from both versions if any of them differ then it will say that the stream has changed (which is not true in this case since we just read from the file, never changed it):
https://github.com/dotnet/corefx/blob/master/src/System.Configuration.ConfigurationManager/src/System/Configuration/Internal/FileVersion.cs#L22-L33
Why is not a consistent failure and sometimes the exception is not thrown?
This is a timing thing, all the failures that I debugged are 1 second difference in between the creation time, this is because there could be a 1 second difference from when we read the file and when we wrote to it, but this depends on the miliseconds offset and when we start reading it from when we actually wrote the config file.
After talking offline with @tarekgh (who helped investigate this failure and debug in Linux) and @JeremyKuhne (who helped us understand how the filesystem in Linux works and helped to get to this conclusion) we investigated on how mono is calculating the creation time on linux and we saw that the don't take access time on count for this, they get the minimum on between modification and change time:
https://github.com/mono/mono/blob/9a21932f4326bcb1a6a03a3f355fb5eeea9e7fbc/mono/metadata/w32file-unix.c#L3827
The real fix here to have a creation time and not a default time on linux will be to only use Modify and Change times to calculate this. Why? Well because access time tracks only when the file was read and in multiple places we have to read it to interpret the contents of the file (in this case the config file), but that doesn't mean another process really changed the file, which is the exception we are getting:
System.Configuration.ConfigurationErrorsException : The configuration file has been changed by another program.
So I suggest we should do the following when calculating creation time when a file doesn't have a BirthTime:
DateTimeOffset IFileSystemObject.CreationTime
{
get
{
EnsureStatInitialized();
long rawTime = (_fileStatus.Flags & Interop.Sys.FileStatusFlags.HasBirthTime) != 0 ?
_fileStatus.BirthTime :
Math.Min(_fileStatus.CTime, _fileStatus.MTime);
return DateTimeOffset.FromUnixTimeSeconds(rawTime).ToLocalTime();
}
}
I've tested this locally, done a 1000 runs of this tests and I don't get any failures when I calculate CreationTime this way. With the way we have it now it failed every 10-20th run.
cc: @stephentoub @danmosemsft @ianhays @tarekgh @JeremyKuhne @karelz
safern
on 19 Apr 2017
Nice job tracking this down!
And I see how the access time could be problematic here. The Mono behavior is interesting, though, in that it's inconsistent from other Mono code here:
https://github.com/mono/mono/blob/8df83179b63e256bcd476d6d7ddbbd50015b81d6/mono/metadata/w32file-unix.c#L1690-L1702
which does factor in access time.
Regardless, your suggested fix makes sense. Let's do it.
If we still have problems with it after doing it, we should re-evaluate the CreationTime implementation and whether to revert back to default(DateTimeOffset), but for now min(ctime, mtime) makes sense.
stephentoub
on 19 Apr 2017
That is confusing and inconsistent.
Regardless, your suggested fix makes sense. Let's do it.
I'm sending a PR with the fix :)
safern
on 19 Apr 2017
Related issues
yahorsi
路
3Comments
EgorBo
路
3Comments
omajid
路
3Comments
sahithreddyk
路
3Comments
aggieben
路
3Comments
Most helpful comment
Nice job tracking this down!
And I see how the access time could be problematic here. The Mono behavior is interesting, though, in that it's inconsistent from other Mono code here:
https://github.com/mono/mono/blob/8df83179b63e256bcd476d6d7ddbbd50015b81d6/mono/metadata/w32file-unix.c#L1690-L1702
which does factor in access time.
Regardless, your suggested fix makes sense. Let's do it.
If we still have problems with it after doing it, we should re-evaluate the CreationTime implementation and whether to revert back to default(DateTimeOffset), but for now min(ctime, mtime) makes sense.