Property function regression from MSBuild 15

[dfederm]

Steps to reproduce

Project file (eg. named "SomeProject.csproj")

<?xml version="1.0" encoding="utf-8"?>
<Project ToolsVersion="4.0" DefaultTargets="Build" xmlns="http://schemas.microsoft.com/developer/msbuild/2003">
  <ItemGroup>
    <Foo Include="foo.xml" />
  </ItemGroup>
  <PropertyGroup>
    <_FileNamePrefixLength>$([MSBuild]::Add($(MsBuildProjectName.Length),1))</_FileNamePrefixLength>
  </PropertyGroup>
  <ItemGroup>
    <Bar Include="@(Foo-> 'Output\$(MsBuildProjectName)-%(FileName)%(Extension)')">
      <TargetPath>$([System.String]::new(%(FileName)).Substring($(_FileNamePrefixLength)))%(Extension)</TargetPath>
    </Bar>
  </ItemGroup>
  <Target Name="Build">
    <Message Text="%(Bar.Identity) -> %(Bar.TargetPath)" Importance="High" />
  </Target>
</Project>

Directory contents:
N/A

Command line

msbuild

Expected behavior

Build passes with output (this is msbuild 14):

Microsoft (R) Build Engine version 14.0.25123.0
Copyright (C) Microsoft Corporation. All rights reserved.

Build started 6/28/2018 9:38:58 AM.
Project "<removed>\SomeProject.csproj" on node 1 (default targets).
Build:
  Output\SomeProject-foo.xml -> foo.xml
Done Building Project "<removed>\SomeProject.csproj" (default targets).

Actual behavior

Build errors with evaluation error (msbuild 15):

Microsoft (R) Build Engine version 15.8.86-preview+g4ef6bb1fb2 for .NET Framework
Copyright (C) Microsoft Corporation. All rights reserved.

Build started 6/28/2018 9:39:02 AM.
Project "<removed>\SomeProject.csproj" on node 1 (default targets).
<removed>\SomeProject.csproj(11,7): error MSB4184: The expression ""%(FileName)".Substring(12)" cannot be evaluated. star
tIndex cannot be larger than length of string. Parameter name: startIndex
Done Building Project "<removed>\SomeProject.csproj" (default targets) -- FAILED.


Build FAILED.

"<removed>\SomeProject.csproj" (default target) (1) ->
  <removed>\SomeProject.csproj(11,7): error MSB4184: The expression ""%(FileName)".Substring(12)" cannot be evaluated. st
artIndex cannot be larger than length of string. Parameter name: startIndex

    0 Warning(s)
    1 Error(s)

Time Elapsed 00:00:00.07

Environment data

msbuild /version output:

Microsoft (R) Build Engine version 15.8.86-preview+g4ef6bb1fb2 for .NET Framework
Copyright (C) Microsoft Corporation. All rights reserved.

15.8.86.63054

OS info: Win 10

[dfederm]

After debugging, it looks to be checking the length of %(FileName).

IE, this does not repro:

  <ItemGroup>
    <Bar Include="A-foo.xml">
      <TargetPath>$([System.String]::new(%(FileName)).Substring(2))</TargetPath>
    </Bar>
  </ItemGroup>

But this does:

  <ItemGroup>
    <Bar Include="SomeProject-foo.xml">
      <TargetPath>$([System.String]::new(%(FileName)).Substring(12))</TargetPath>
    </Bar>
  </ItemGroup>

And if I change the number to 11:

  <ItemGroup>
    <Bar Include="SomeProject-foo.xml">
      <TargetPath>$([System.String]::new(%(FileName)).Substring(11))</TargetPath>
    </Bar>
  </ItemGroup>

It works and produces "-foo" (leading dash since I took off one character)

[dfederm]

Found an easy unit test for this.

In ItemEvaluation_Tests.cs, add:

        // see https://github.com/Microsoft/msbuild/issues/3460
        [Fact]
        public void MetadataPropertyFunctionBug()
        {
            const string prefix = "SomeLongPrefix-"; // Needs to be longer than "%(FileName)"
            var projectContent = $@"
<Project>
  <ItemGroup>
    <Bar Include=`{prefix}foo`>
      <Baz>$([System.String]::new(%(FileName)).Substring({prefix.Length}))</Baz>
    </Bar>
  </ItemGroup>
</Project>
".Cleanup();

            var items = ObjectModelHelpers.GetItems(projectContent, allItems: true);

            var expectedMetadata = new[]
            {
                new Dictionary<string, string>
                {
                    {"Baz", "foo"},
                },
            };

            ObjectModelHelpers.AssertItems(new[] { $"{prefix}foo" }, items, expectedMetadata);
        }

[dfederm]

I've done a little debugging, so I'll leave some notes for my findings here.

This seems to happen as part of a "first pass" at metadata evaluation. Specifically, it seems to attempt to evaluate the metadata only expanding properties and not other metadata (LazyItemEvaluator.ProcessMetadataElements) so that it can gather referenced items. It doesn't actually use the result (obviously, since it's be incorrect), but if the evaluation leads to an exception like it does here, it fails the evaluation completely despite this being a discovery-based operation and not critical. A couple options I can think of:

1. Ignore exceptions during this phase? If anything bad happens during the property-only expansion, just ignore it. If anything bad happens later during full evaluation, that's when it can really error.

2. Detect the metadata reference (%(...)) and stop trying to expand the value during this property-only phase.

3. Special-case this substring case somehow? Some of the other well-known functions don't seem to have error conditions which are similarly easily triggerable by unexpanded metadata. This seems like whack-a-mole though.

I haven't tried it yet, but this seems to imply weird behavior if property expansion happens first. For example, what if I had something like $([System.String]::new(%(FileName)).Replace('%', '@')). This initial pass seems like it would expand to @(FileName) which may actually be defined as an item group. This would lead to @(FileName) being seen as a referenced item, but maybe that doesn't really matter anyway.