Msbuild: Unable to get any content from certain imported files embedded in binlog

Created on 11 Sep 2019 · 12Comments · Source: dotnet/msbuild

Steps to reproduce

Command line

mkdir repro
cd repro
dotnet new console
dotnet build /bl
start msbuild.binlog

Navigate to files tab on left, double click on each file

Expected behavior

You can see the content of all files.

Actual behavior

The files in C:\Program Files\dotnet\sdk\3.0.100-preview9-014004\Sdks\Microsoft.NET.Sdk are shown as empty

Environment data

16.3.0.42601

NET Core SDK (reflecting any global.json):
Version: 3.0.100-preview9-014004
Commit: 8e7ef240a5

Debuggability

Source

nguerrera

All 12 comments

cc @rainersigwald who is looking at this right next to me :)

nguerrera on 11 Sep 2019

Example of expanded zip contents, showing the 0 byte files only for some of the files. Pattern not at all clear to me.

 Volume in drive C is BOOTCAMP
 Volume Serial Number is FC56-66FC

 Directory of C:\play\lklkaejy\msbuild.ProjectImports

09/10/2019  05:22 PM    <DIR>          .
09/10/2019  05:22 PM    <DIR>          ..
09/10/2019  05:22 PM    <DIR>          C
               0 File(s)              0 bytes

 Directory of C:\play\lklkaejy\msbuild.ProjectImports\C

09/10/2019  05:22 PM    <DIR>          .
09/10/2019  05:22 PM    <DIR>          ..
09/10/2019  05:22 PM    <DIR>          play
09/10/2019  05:22 PM    <DIR>          Program Files
               0 File(s)              0 bytes

 Directory of C:\play\lklkaejy\msbuild.ProjectImports\C\play

09/10/2019  05:22 PM    <DIR>          .
09/10/2019  05:22 PM    <DIR>          ..
09/10/2019  05:22 PM    <DIR>          lklkaejy
               0 File(s)              0 bytes

 Directory of C:\play\lklkaejy\msbuild.ProjectImports\C\play\lklkaejy

09/10/2019  05:22 PM    <DIR>          .
09/10/2019  05:22 PM    <DIR>          ..
09/10/2019  05:18 PM               178 lklkaejy.csproj
09/10/2019  05:22 PM    <DIR>          obj
               1 File(s)            178 bytes

 Directory of C:\play\lklkaejy\msbuild.ProjectImports\C\play\lklkaejy\obj

09/10/2019  05:22 PM    <DIR>          .
09/10/2019  05:22 PM    <DIR>          ..
09/10/2019  05:18 PM             1,167 lklkaejy.csproj.nuget.g.props
09/10/2019  05:18 PM               294 lklkaejy.csproj.nuget.g.targets
               2 File(s)          1,461 bytes

 Directory of C:\play\lklkaejy\msbuild.ProjectImports\C\Program Files

09/10/2019  05:22 PM    <DIR>          .
09/10/2019  05:22 PM    <DIR>          ..
09/10/2019  05:22 PM    <DIR>          dotnet
               0 File(s)              0 bytes

 Directory of C:\play\lklkaejy\msbuild.ProjectImports\C\Program Files\dotnet

09/10/2019  05:22 PM    <DIR>          .
09/10/2019  05:22 PM    <DIR>          ..
09/10/2019  05:22 PM    <DIR>          sdk
               0 File(s)              0 bytes

 Directory of C:\play\lklkaejy\msbuild.ProjectImports\C\Program Files\dotnet\sdk

09/10/2019  05:22 PM    <DIR>          .
09/10/2019  05:22 PM    <DIR>          ..
09/10/2019  05:22 PM    <DIR>          3.0.100-preview9-014004
               0 File(s)              0 bytes

 Directory of C:\play\lklkaejy\msbuild.ProjectImports\C\Program Files\dotnet\sdk\3.0.100-preview9-014004

09/10/2019  05:22 PM    <DIR>          .
09/10/2019  05:22 PM    <DIR>          ..
09/10/2019  05:22 PM    <DIR>          Current
09/10/2019  05:22 PM    <DIR>          Microsoft
08/26/2019  03:01 PM           322,520 Microsoft.Common.CurrentVersion.targets
08/26/2019  03:01 PM            14,155 Microsoft.Common.targets
08/26/2019  03:01 PM            21,682 Microsoft.CSharp.CurrentVersion.targets
08/26/2019  03:01 PM            18,549 Microsoft.CSharp.targets
08/26/2019  03:01 PM             5,945 Microsoft.Managed.targets
08/27/2019  01:46 AM               615 Microsoft.NETCoreSdk.BundledCliTools.props
08/27/2019  01:46 AM             8,640 Microsoft.NETCoreSdk.BundledVersions.props
08/20/2019  06:12 AM             5,609 Microsoft.TestPlatform.targets
08/21/2019  02:50 PM            55,908 NuGet.targets
09/10/2019  05:22 PM    <DIR>          Roslyn
09/10/2019  05:22 PM    <DIR>          Sdks
               9 File(s)        453,623 bytes

 Directory of C:\play\lklkaejy\msbuild.ProjectImports\C\Program Files\dotnet\sdk\3.0.100-preview9-014004\Current

09/10/2019  05:22 PM    <DIR>          .
09/10/2019  05:22 PM    <DIR>          ..
08/26/2019  03:01 PM            13,606 Microsoft.Common.props
09/10/2019  05:22 PM    <DIR>          Microsoft.Common.targets
               1 File(s)         13,606 bytes

 Directory of C:\play\lklkaejy\msbuild.ProjectImports\C\Program Files\dotnet\sdk\3.0.100-preview9-014004\Current\Microsoft.Common.targets

09/10/2019  05:22 PM    <DIR>          .
09/10/2019  05:22 PM    <DIR>          ..
09/10/2019  05:22 PM    <DIR>          ImportAfter
               0 File(s)              0 bytes

 Directory of C:\play\lklkaejy\msbuild.ProjectImports\C\Program Files\dotnet\sdk\3.0.100-preview9-014004\Current\Microsoft.Common.targets\ImportAfter

09/10/2019  05:22 PM    <DIR>          .
09/10/2019  05:22 PM    <DIR>          ..
09/10/2019  05:20 PM                 0 Microsoft.NET.Build.Extensions.targets
08/27/2019  12:40 AM             1,054 Microsoft.TestPlatform.ImportAfter.targets
               2 File(s)          1,054 bytes

 Directory of C:\play\lklkaejy\msbuild.ProjectImports\C\Program Files\dotnet\sdk\3.0.100-preview9-014004\Microsoft

09/10/2019  05:22 PM    <DIR>          .
09/10/2019  05:22 PM    <DIR>          ..
09/10/2019  05:22 PM    <DIR>          Microsoft.NET.Build.Extensions
               0 File(s)              0 bytes

 Directory of C:\play\lklkaejy\msbuild.ProjectImports\C\Program Files\dotnet\sdk\3.0.100-preview9-014004\Microsoft\Microsoft.NET.Build.Extensions

09/10/2019  05:22 PM    <DIR>          .
09/10/2019  05:22 PM    <DIR>          ..
09/10/2019  05:20 PM                 0 Microsoft.NET.Build.Extensions.targets
               1 File(s)              0 bytes

 Directory of C:\play\lklkaejy\msbuild.ProjectImports\C\Program Files\dotnet\sdk\3.0.100-preview9-014004\Roslyn

09/10/2019  05:22 PM    <DIR>          .
09/10/2019  05:22 PM    <DIR>          ..
08/21/2019  08:52 PM             7,512 Microsoft.CSharp.Core.targets
08/21/2019  08:52 PM             8,095 Microsoft.Managed.Core.targets
08/21/2019  08:52 PM             1,011 Microsoft.Managed.EditorConfig.targets
               3 File(s)         16,618 bytes

 Directory of C:\play\lklkaejy\msbuild.ProjectImports\C\Program Files\dotnet\sdk\3.0.100-preview9-014004\Sdks

09/10/2019  05:22 PM    <DIR>          .
09/10/2019  05:22 PM    <DIR>          ..
09/10/2019  05:22 PM    <DIR>          ILLink.Tasks
09/10/2019  05:22 PM    <DIR>          Microsoft.NET.Sdk
09/10/2019  05:22 PM    <DIR>          NuGet.Build.Tasks.Pack
               0 File(s)              0 bytes

 Directory of C:\play\lklkaejy\msbuild.ProjectImports\C\Program Files\dotnet\sdk\3.0.100-preview9-014004\Sdks\ILLink.Tasks

09/10/2019  05:22 PM    <DIR>          .
09/10/2019  05:22 PM    <DIR>          ..
09/10/2019  05:22 PM    <DIR>          Sdk
               0 File(s)              0 bytes

 Directory of C:\play\lklkaejy\msbuild.ProjectImports\C\Program Files\dotnet\sdk\3.0.100-preview9-014004\Sdks\ILLink.Tasks\Sdk

09/10/2019  05:22 PM    <DIR>          .
09/10/2019  05:22 PM    <DIR>          ..
07/30/2019  10:57 AM             1,376 Sdk.props
               1 File(s)          1,376 bytes

 Directory of C:\play\lklkaejy\msbuild.ProjectImports\C\Program Files\dotnet\sdk\3.0.100-preview9-014004\Sdks\Microsoft.NET.Sdk

09/10/2019  05:22 PM    <DIR>          .
09/10/2019  05:22 PM    <DIR>          ..
09/10/2019  05:22 PM    <DIR>          Sdk
09/10/2019  05:22 PM    <DIR>          targets
               0 File(s)              0 bytes

 Directory of C:\play\lklkaejy\msbuild.ProjectImports\C\Program Files\dotnet\sdk\3.0.100-preview9-014004\Sdks\Microsoft.NET.Sdk\Sdk

09/10/2019  05:22 PM    <DIR>          .
09/10/2019  05:22 PM    <DIR>          ..
09/10/2019  05:20 PM                 0 Sdk.props
09/10/2019  05:20 PM                 0 Sdk.targets
               2 File(s)              0 bytes

 Directory of C:\play\lklkaejy\msbuild.ProjectImports\C\Program Files\dotnet\sdk\3.0.100-preview9-014004\Sdks\Microsoft.NET.Sdk\targets

09/10/2019  05:22 PM    <DIR>          .
09/10/2019  05:22 PM    <DIR>          ..
09/10/2019  05:20 PM                 0 Microsoft.NET.ComposeStore.targets
09/10/2019  05:20 PM                 0 Microsoft.NET.ConflictResolution.targets
09/10/2019  05:20 PM                 0 Microsoft.NET.CrossGen.targets
09/10/2019  05:20 PM                 0 Microsoft.NET.DefaultAssemblyInfo.targets
09/10/2019  05:20 PM                 0 Microsoft.NET.DefaultOutputPaths.targets
09/10/2019  05:20 PM                 0 Microsoft.NET.DefaultPackageConflictOverrides.targets
09/10/2019  05:20 PM                 0 Microsoft.NET.DesignerSupport.targets
09/10/2019  05:20 PM                 0 Microsoft.NET.DisableStandardFrameworkResolution.targets
09/10/2019  05:20 PM                 0 Microsoft.NET.GenerateAssemblyInfo.targets
09/10/2019  05:20 PM                 0 Microsoft.NET.GenerateSupportedRuntime.targets
09/10/2019  05:20 PM                 0 Microsoft.NET.ILLink.targets
09/10/2019  05:20 PM                 0 Microsoft.NET.NuGetOfflineCache.targets
09/10/2019  05:20 PM                 0 Microsoft.NET.ObsoleteReferences.targets
09/10/2019  05:20 PM                 0 Microsoft.NET.PackProjectTool.props
09/10/2019  05:20 PM                 0 Microsoft.NET.PackProjectTool.targets
09/10/2019  05:20 PM                 0 Microsoft.NET.PackTool.props
09/10/2019  05:20 PM                 0 Microsoft.NET.PackTool.targets
09/10/2019  05:20 PM                 0 Microsoft.NET.PreserveCompilationContext.targets
09/10/2019  05:20 PM                 0 Microsoft.NET.Publish.targets
09/10/2019  05:20 PM                 0 Microsoft.NET.RuntimeIdentifierInference.targets
09/10/2019  05:20 PM                 0 Microsoft.NET.Sdk.BeforeCommon.targets
09/10/2019  05:20 PM                 0 Microsoft.NET.Sdk.Common.targets
09/10/2019  05:20 PM                 0 Microsoft.NET.Sdk.CSharp.props
09/10/2019  05:20 PM                 0 Microsoft.NET.Sdk.CSharp.targets
09/10/2019  05:20 PM                 0 Microsoft.NET.Sdk.DefaultItems.props
09/10/2019  05:20 PM                 0 Microsoft.NET.Sdk.DefaultItems.targets
09/10/2019  05:20 PM                 0 Microsoft.NET.Sdk.FrameworkReferenceResolution.targets
09/10/2019  05:20 PM                 0 Microsoft.NET.Sdk.ImportPublishProfile.targets
09/10/2019  05:20 PM                 0 Microsoft.NET.Sdk.props
09/10/2019  05:20 PM                 0 Microsoft.NET.Sdk.targets
09/10/2019  05:20 PM                 0 Microsoft.NET.SupportedTargetFrameworks.props
09/10/2019  05:20 PM                 0 Microsoft.NET.TargetFrameworkInference.targets
09/10/2019  05:20 PM                 0 Microsoft.PackageDependencyResolution.targets
              33 File(s)              0 bytes

 Directory of C:\play\lklkaejy\msbuild.ProjectImports\C\Program Files\dotnet\sdk\3.0.100-preview9-014004\Sdks\NuGet.Build.Tasks.Pack

09/10/2019  05:22 PM    <DIR>          .
09/10/2019  05:22 PM    <DIR>          ..
09/10/2019  05:22 PM    <DIR>          build
               0 File(s)              0 bytes

 Directory of C:\play\lklkaejy\msbuild.ProjectImports\C\Program Files\dotnet\sdk\3.0.100-preview9-014004\Sdks\NuGet.Build.Tasks.Pack\build

09/10/2019  05:22 PM    <DIR>          .
09/10/2019  05:22 PM    <DIR>          ..
08/23/2019  07:00 AM            26,665 NuGet.Build.Tasks.Pack.targets
               1 File(s)         26,665 bytes

     Total Files Listed:
              56 File(s)        514,581 bytes
              68 Dir(s)   1,222,942,720 bytes free

rainersigwald on 11 Sep 2019

Skimming, the pattern appears to be things with "Microsoft.NET" in it are empty. ?!?

nguerrera on 11 Sep 2019

There's an exception being buried having to do with the timestamp on the file being invalid for a zip file, and somehow:

C:\Program Files\dotnet\sdk\3.0.100-preview9-014004\Sdks\Microsoft.NET.Sdk\Sdk\Sdk.props

nguerrera on 11 Sep 2019

👍1

"System.ArgumentOutOfRangeException: The DateTimeOffset specified cannot be converted into a Zip file timestamp.
Parameter name: value
   at System.IO.Compression.ZipArchiveEntry.set_LastWriteTime(DateTimeOffset value)
   at Microsoft.Build.Logging.ProjectImportsCollector.OpenArchiveEntry(String filePath, DateTime lastWriteTime) in C:\\src\\msbuild\\src\\Build\\Logging\\BinaryLogger\\ProjectImportsCollector.cs:line 158
   at Microsoft.Build.Logging.ProjectImportsCollector.AddFileCore(String filePath) in C:\\src\\msbuild\\src\\Build\\Logging\\BinaryLogger\\ProjectImportsCollector.cs:line 120
   at Microsoft.Build.Logging.ProjectImportsCollector.<>c__DisplayClass9_0.<AddFile>b__0(Task t) in C:\\src\\msbuild\\src\\Build\\Logging\\BinaryLogger\\ProjectImportsCollector.cs:line 61"

Thrown here:

https://github.com/dotnet/corefx/blob/b41b09eadd5eb3f5575845a982f2c177c37f7ce7/src/System.IO.Compression/src/System/IO/Compression/ZipArchiveEntry.cs#L231-L232

```C#
if (value.DateTime.Year < ZipHelper.ValidZipDate_YearMin || value.DateTime.Year > ZipHelper.ValidZipDate_YearMax)
throw new ArgumentOutOfRangeException(nameof(value), SR.DateTimeOutOfRange);


Where

```c#
internal const int ValidZipDate_YearMin = 1980;

rainersigwald on 11 Sep 2019

It appears that the difference is that dotnet/sdk is being packed with a very recent nuget. Running dotnet pack on dotnet new classlib and unzipping the files from the nupkg also creates file with last modification time in 1979.

nguerrera on 11 Sep 2019

One action item from here is to harden the BinaryLogger ProjectImportsCollector against files with a weird timestamp.
Another one is to figure out why those files have that timestamp in the first place ;)

KirillOsenkov on 11 Sep 2019

P.S. Excellent sleuthing guys! Great job figuring it out.

KirillOsenkov on 11 Sep 2019

So nuget made a change for determinism, and is packing with 1980 (minimum date), then it seems windows applies a time zone to that giving 1979 and then we try to rezip the file with < 1980, which is not valid. cc @nkolev92

Great bug!

nguerrera on 11 Sep 2019

I guess root cause is https://github.com/NuGet/NuGet.Client/pull/2989.

edit:
@nguerrera beat me to it.

nkolev92 on 11 Sep 2019

We're thinking about simply not preserving the timestamp when zipping the imports. We are taking a deliberate step to preserve it, but it doesn't seem like anyone would ever bother to look at this data in a binlog.

nguerrera on 11 Sep 2019

👍1

Yes let's just not include the timestamp when zipping.

KirillOsenkov on 11 Sep 2019

Was this page helpful?

0 / 5 - 0 ratings

Related issues

Understanding the Clean target

jaredpar · 4Comments

Publish Sdk package for Common props/targets

rainersigwald · 3Comments

Warning for leaked "private" variables

rainersigwald · 3Comments

Use of env variables leads to build failures with combination of multiple build systems [CMake/Xcode]

rokups · 3Comments

Exclude patterns behaving different in static evaluation and at runtime

dasMulli · 4Comments