Logger cause TC builds to hang indefinitely

[natemcmaster]

When using this logger to build large projects, such as https://github.com/aspnet/Universe, TeamCity appears to hang indefinitely even once the build has passed.

The build log shows that all build steps have completely, but the build is still hanging.

[NikolayPianikov]

Is it possible to share a Agent Thread Dump? See this page for details.

[natemcmaster]

Here's the agent thread dump: threadDump-2018-02-06_09.17.02.txt

[NikolayPianikov]

@natemcmaster how did you configure your build step? I mean a TeamCity build runner type and its parameters? And may be you could attach some screenshots? When I am running build.cmd build fails. I will attach the error later.

Did you use BuildInParallel = true for your msbuild projects?

[natemcmaster]

Here is a pruned example of the setup. projectSettings.zip

If you're trying to reproduce with https://github.com/aspnet/Universe, setup the build to run with build.cmd /p:CompileOnly=true. You can setup the logger with the KOREBUILD_TEAMCITY_LOGGER environment variables (see https://github.com/aspnet/BuildTools/blob/85ae1301d1a2ff19aab6837cc657699ccca719b5/docs/Logging.md#teamcity-logger). To get build to pass, you would also need VS 2017 with VC++ installed.

I am using the loggers I downloaded from the "Stable" link in this repo's README.

[NikolayPianikov]

Thanks for info, I will try

[natemcmaster]

Ok, let me know if you need any more info

[ryanbrandenburg]

When we restarted our TC server I noticed a bunch of possibly related warnings in the server log

[2018-02-06 13:50:38,087]   WARN -   jetbrains.buildServer.SERVER - Failed to parse status in service message for build with id 401210: ##teamcity[message text='No issues found with package Microsoft.AspNetCore.Http.Extensions (2.1.0-preview1-28241)' status='INFORMATION'] 

[NikolayPianikov]

@ryanbrandenburg I am not sure it is a reason

[NikolayPianikov]

I tried to reproduce, but failed. May be because my build was failed about 15 minutes after start with error: `

teamcity[message text=' ============ Done building KestrelHttpServer ============' status='NORMAL' tc:ta

teamcity[message text='←|[36;1m 1>Done Building Project "C:\Users\Nikol.dotnet\buildtools\korebuild\2.1.0-p

teamcity[message text='' status='NORMAL' tc:tags='tc:parseServiceMessagesInside' timestamp='2018-02-08T12:19:01.

teamcity[blockClosed name=' Project "KoreBuild.proj": _BuildRepository' timestamp='2018-02-08T12:19:01.572

teamcity[message text='←|[36;1m 1>Done Building Project "C:\Users\Nikol.dotnet\buildtools\korebuild\2.1.0-p

teamcity[message text='' status='NORMAL' tc:tags='tc:parseServiceMessagesInside' timestamp='2018-02-08T12:19:01.

teamcity[blockClosed name=' Project "KoreBuild.proj": GetArtifactInfo' timestamp='2018-02-08T12:19:01.573+

teamcity[flowFinished timestamp='2018-02-08T12:19:01.573+0000' flowId='8f3070c86cb649a5b29a438907ab376b']

teamcity[message text='' status='NORMAL' tc:tags='tc:parseServiceMessagesInside' timestamp='2018-02-08T12:19:01.

teamcity[message text='Build FAILED.' status='NORMAL' tc:tags='tc:parseServiceMessagesInside' timestamp='2018-02

teamcity[message text=' 0 Warning(s)' status='NORMAL' tc:tags='tc:parseServiceMessagesInside' timestamp='2018

teamcity[message text=' 1 Error(s)' status='ERROR' tc:tags='tc:parseServiceMessagesInside' timestamp='2018-02

teamcity[message text='' status='NORMAL' tc:tags='tc:parseServiceMessagesInside' timestamp='2018-02-08T12:19:01.

teamcity[message text='Time Elapsed 00:10:44.76' status='NORMAL' tc:tags='tc:parseServiceMessagesInside' timesta

dotnet.exe failed with exit code: 1 At C:\Users\Nikol.dotnet\buildtools\korebuild\2.1.0-preview2-15695\scripts\common.psm1:11 char:9

• throw "$cmdName failed with exit code: $exitCode"

• 
  + CategoryInfo          : OperationStopped: (dotnet.exe failed with exit code: 1:String) [], RuntimeException
  + FullyQualifiedErrorId : dotnet.exe failed with exit code: 1
  `

Have you any advises to fix a build?

PS Are you really needed this level of "verbosity" in logs by default?

[NikolayPianikov]

Another question is did you have a chance to reproduce this issue from the command line? Is it reproducible under TeamCity only?

[natemcmaster]

@NikolayPianikov I'm not quite sure what the error is. Was there more in the log output? All I can see is that dotnet.exe exited with a non-zero code.

This hang is consistently reproducing in TeamCity when we turn the logger on. It doesn't happen on command-line.

[NikolayPianikov]

When I am running this command build.cmd -Path C:\Projects\aspnet\Universe\modules\IISIntegration\ /t:CleanArtifacts /t:Build /p:SkipTests=true /p:AspNetUniverseBuildOffline=true /p:DotNetRestoreSourcePropsPath=C:\Projects\aspnet\Universe\obj\sources.g.props /p:DotNetPackageVersionPropsPath=C:\Projects\aspnet\Universe\obj\dependencies.g.props /p:BuildNumber=7 /p:Configuration=Debug /p:IsFinalBuild=false /noconsolelogger '/l:RepoTasks.FlowLogger,C:\Projects\aspnet\Universe\build\tasks\bin\publish\RepoTasks.dll;Summary;FlowId=IISIntegration'

I have this error: IISIntegration | C:\Users\Nikol\.dotnet\x64\sdk\2.1.300-preview2-008044\NuGet.targets(104,5): error : Central Directory corrupt. IISIntegration | C:\Users\Nikol\.dotnet\x64\sdk\2.1.300-preview2-008044\NuGet.targets(104,5): error : An attempt was made to move the file pointer before the beginning of the file

I've cleared NuGet caches and other things but it does not help. I have the same error on several computers.

@natemcmaster what am I doing wrong?

[natemcmaster]

Try also deleting C:\Users\Nikol.dotnet\x64\sdk\NuGetFallbackFolder and setting this variable: "DOTNET_SKIP_FIRST_TIME_EXPERIENCE=true".

I realized setting up our specific build code is a difficult way to repro the issue. Is there any other kind of dump or log I could send that would help you identify where the agent or server is hanging?

[NikolayPianikov]

Ok, I will try. Thank you. I would like to reproduce this issue

[NikolayPianikov]

@natemcmaster it helps and I have got an working build (except some modules). But still is not reproducing. May be there is a race condition or one of failed modules, that I still cannot build, has an influence. Is it possible to run build on your CI and to redirect stdOut (under the TeamCity logger) to some file and to send/share this file to me?

[NikolayPianikov]

@natemcmaster could you try this package, also you could add the plain switch to disallow nested TeamCity service messages, for example: dotnet build my.csproj /noconsolelogger /l:TeamCity.MSBuild.Logger.TeamCityMSBuildLogger,bin\publish\msbuild15\TeamCity.MSBuild.Logger.dll;teamcity;plain as workaround for #3

[natemcmaster]

Sure, I’ll give it a shot tomorrow.

[natemcmaster]

I re-ran a build with 1.0.1-beta70. I am still seeing the indefinite hang.

threadDump-2018-02-26_12.09.54.txt

Funny thing: this is in the agent log:

[2018-02-26 11:57:31,959]   INFO -    jetbrains.buildServer.AGENT - Build finished, build id 412869 
[2018-02-26 11:57:32,194]   INFO - nt.impl.BuildRunAgentStateImpl - Disposing build context 
[2018-02-26 11:57:32,194]   INFO - mpl$TeamCitySpringSubContainer - Closing SubContext: running build context id=412869: startup date [Mon Feb 26 11:20:25 PST 2018]; parent: jetbrains.buildServer.agent.AgentMain2$2@b8a058 
[2018-02-26 11:57:32,194]   INFO - ent.impl.BuildAgentStateHolder - Build data was released for buildId= 412869 

The agent status page does not show a running build, but the build results page still shows that the build is running. Is it possible the bug is not in the logger itself, but is in the TC server?

[NikolayPianikov]

@natemcmaster yes it is possible, as I see from the thread dump the TeamCity agent is ok. Is it possible to share a thread dump from your TeamCity server and a build log file if it is possible?

[natemcmaster]

@NikolayPianikov sorry this fell of my radar. At this point, I'm not pursuing using the logger anymore. Ran out of time to investigate it, and ended up just producing file logs instead. Sorry I wasn't more help in getting you logs and dumps.

[NikolayPianikov]

This issue was actually fixed in 1.0.7