Skip to content

Commit 7ffb903

Browse files
committed
Temp graceful shutdown disabled investigation
- Invocations fail about 1% of the time when graceful shutdown is disabled, i.e both retries consumed, once from process getting killed and the other for an obscure HttpRequestException. - Can't reproduce on dev machine.
1 parent 8a5e953 commit 7ffb903

File tree

5 files changed

+207
-11
lines changed

5 files changed

+207
-11
lines changed

Jering.Javascript.NodeJS.sln

+6
Original file line numberDiff line numberDiff line change
@@ -25,6 +25,8 @@ Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "Jering.Javascript.NodeJS.Te
2525
EndProject
2626
Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "Jering.Javascript.NodeJS.Performance", "perf\NodeJS\Jering.Javascript.NodeJS.Performance.csproj", "{248EFBD7-AD1B-4543-8FFC-4C1E5D13F8FD}"
2727
EndProject
28+
Project("{FAE04EC0-301F-11D3-BF4B-00C04F79EFBC}") = "Temp.GracefulShutdownDisabledIntermittentIssue", "Temp.GracefulShutdownDisabledIntermittentIssue\Temp.GracefulShutdownDisabledIntermittentIssue.csproj", "{0BC8B09B-F3DB-4BE8-913A-7F61064A1790}"
29+
EndProject
2830
Global
2931
GlobalSection(SolutionConfigurationPlatforms) = preSolution
3032
Debug|Any CPU = Debug|Any CPU
@@ -43,6 +45,10 @@ Global
4345
{248EFBD7-AD1B-4543-8FFC-4C1E5D13F8FD}.Debug|Any CPU.Build.0 = Debug|Any CPU
4446
{248EFBD7-AD1B-4543-8FFC-4C1E5D13F8FD}.Release|Any CPU.ActiveCfg = Release|Any CPU
4547
{248EFBD7-AD1B-4543-8FFC-4C1E5D13F8FD}.Release|Any CPU.Build.0 = Release|Any CPU
48+
{0BC8B09B-F3DB-4BE8-913A-7F61064A1790}.Debug|Any CPU.ActiveCfg = Debug|Any CPU
49+
{0BC8B09B-F3DB-4BE8-913A-7F61064A1790}.Debug|Any CPU.Build.0 = Debug|Any CPU
50+
{0BC8B09B-F3DB-4BE8-913A-7F61064A1790}.Release|Any CPU.ActiveCfg = Release|Any CPU
51+
{0BC8B09B-F3DB-4BE8-913A-7F61064A1790}.Release|Any CPU.Build.0 = Release|Any CPU
4652
EndGlobalSection
4753
GlobalSection(SolutionProperties) = preSolution
4854
HideSolutionNode = FALSE
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,161 @@
1+
using Jering.Javascript.NodeJS;
2+
using Jering.Javascript.NodeJS.Tests;
3+
using Microsoft.Extensions.DependencyInjection;
4+
using Microsoft.Extensions.Logging;
5+
using System;
6+
using System.Collections.Generic;
7+
using System.Diagnostics;
8+
using System.IO;
9+
using System.Linq;
10+
using System.Text;
11+
using System.Text.RegularExpressions;
12+
using System.Threading.Tasks;
13+
using Xunit;
14+
15+
namespace Temp.GracefulShutdownDisabledIntermittentIssue
16+
{
17+
class Program
18+
{
19+
private static readonly string _tempWatchDirectory = Path.Combine(Path.GetTempPath(), nameof(GracefulShutdownDisabledIntermittentIssue) + "/");
20+
private static IServiceProvider _serviceProvider;
21+
private static Uri _tempWatchDirectoryUri;
22+
23+
static async Task Main(string[] args)
24+
{
25+
for (int i = 0; ; i++)
26+
{
27+
Console.WriteLine($"***** Starting run number: {i} *****");
28+
29+
RecreateWatchDirectory();
30+
await Run();
31+
Cleanup();
32+
33+
Console.WriteLine($"***** Successful run: {i} *****");
34+
}
35+
}
36+
37+
private static async Task Run()
38+
{
39+
const int dummyNumProcesses = 12;
40+
RecreateWatchDirectory();
41+
// Create initial module
42+
const string dummyInitialModule = @"module.exports = {
43+
getPid: (callback) => callback(null, process.pid),
44+
longRunning: (callback) => setInterval(() => { /* Do nothing */ }, 1000)
45+
}";
46+
string dummyModuleFilePath = new Uri(_tempWatchDirectoryUri, "dummyModule.js").AbsolutePath;
47+
File.WriteAllText(dummyModuleFilePath, dummyInitialModule);
48+
var dummyServices = new ServiceCollection();
49+
dummyServices.Configure<OutOfProcessNodeJSServiceOptions>(options =>
50+
{
51+
options.EnableFileWatching = true;
52+
options.WatchPath = _tempWatchDirectory;
53+
options.WatchGracefulShutdown = false;
54+
});
55+
var resultStringBuilder = new StringBuilder();
56+
HttpNodeJSPoolService testSubject = CreateHttpNodeJSPoolService(dummyNumProcesses, dummyServices, resultStringBuilder);
57+
58+
// Act
59+
var getPidTasks = new Task<int>[dummyNumProcesses];
60+
for (int i = 0; i < dummyNumProcesses; i++)
61+
{
62+
getPidTasks[i] = testSubject.InvokeFromFileAsync<int>(dummyModuleFilePath, "getPid");
63+
}
64+
Task.WaitAll(getPidTasks);
65+
int[] intialProcessIDs = getPidTasks.Select(task => task.Result).ToArray();
66+
var initialProcesses = new Process[dummyNumProcesses];
67+
for (int i = 0; i < dummyNumProcesses; i++)
68+
{
69+
// Create Process instances for initial processes so we can verify that they get killed
70+
initialProcesses[i] = Process.GetProcessById(intialProcessIDs[i]);
71+
}
72+
var longRunningTasks = new Task<int>[dummyNumProcesses];
73+
for (int i = 0; i < dummyNumProcesses; i++)
74+
{
75+
longRunningTasks[i] = testSubject.InvokeFromFileAsync<int>(dummyModuleFilePath, "longRunning");
76+
}
77+
// Trigger shifts to new processes
78+
const string dummyNewModule = @"module.exports = {
79+
getPid: (callback) => callback(null, process.pid),
80+
longRunning: (callback) => callback(null, process.pid)
81+
}";
82+
File.WriteAllText(dummyModuleFilePath, dummyNewModule);
83+
// Wait for initial processes to exit
84+
foreach (Process initialProcess in initialProcesses)
85+
{
86+
initialProcess.WaitForExit();
87+
}
88+
// Wait for all processes to shift
89+
var newProcessID1s = new List<int>(dummyNumProcesses);
90+
do
91+
{
92+
int newProcessID = await testSubject.InvokeFromFileAsync<int>(dummyModuleFilePath, "getPid").ConfigureAwait(false);
93+
if (!intialProcessIDs.Contains(newProcessID) && !newProcessID1s.Contains(newProcessID))
94+
{
95+
newProcessID1s.Add(newProcessID);
96+
}
97+
}
98+
while (newProcessID1s.Count != dummyNumProcesses); // Poll until we've shifted to new processes. If we don't successfully shift to new processes, test will timeout.
99+
// Because graceful shutdown is disabled, long running invocations should fail in initial processes and retry successfully in new processes
100+
Task.WaitAll(longRunningTasks);
101+
int[] newProcessID2s = longRunningTasks.Select(task => task.Result).ToArray();
102+
103+
// Assert
104+
string resultLog = resultStringBuilder.ToString();
105+
Assert.Equal(dummyNumProcesses, Regex.Matches(resultLog, nameof(IOException)).Count); // IOExceptions thrown when initial processes are killed
106+
foreach (int newProcessID1 in newProcessID1s)
107+
{
108+
Assert.Contains(newProcessID1, newProcessID2s); // Long running invocations should complete in new processes
109+
}
110+
}
111+
112+
private static void RecreateWatchDirectory()
113+
{
114+
TryDeleteWatchDirectory();
115+
Directory.CreateDirectory(_tempWatchDirectory);
116+
_tempWatchDirectoryUri = new Uri(_tempWatchDirectory);
117+
}
118+
119+
private static void TryDeleteWatchDirectory()
120+
{
121+
try
122+
{
123+
Directory.Delete(_tempWatchDirectory, true);
124+
}
125+
catch
126+
{
127+
// Do nothing
128+
}
129+
}
130+
131+
private static HttpNodeJSPoolService CreateHttpNodeJSPoolService(int numProcesses, ServiceCollection services = default, StringBuilder loggerStringBuilder = default)
132+
{
133+
services = services ?? new ServiceCollection();
134+
services.AddNodeJS();
135+
services.Configure<OutOfProcessNodeJSServiceOptions>(options =>
136+
{
137+
options.Concurrency = Concurrency.MultiProcess;
138+
options.ConcurrencyDegree = numProcesses;
139+
});
140+
141+
services.AddLogging(lb =>
142+
{
143+
lb.
144+
AddConsole().
145+
AddProvider(new StringBuilderProvider(loggerStringBuilder)).
146+
AddFilter<StringBuilderProvider>((LogLevel logLevel) => logLevel >= LogLevel.Debug);
147+
});
148+
149+
_serviceProvider = services.BuildServiceProvider();
150+
151+
return _serviceProvider.GetRequiredService<INodeJSService>() as HttpNodeJSPoolService;
152+
}
153+
154+
public static void Cleanup()
155+
{
156+
((IDisposable)_serviceProvider).Dispose();
157+
TryDeleteWatchDirectory();
158+
}
159+
160+
}
161+
}
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,18 @@
1+
<Project Sdk="Microsoft.NET.Sdk">
2+
3+
<PropertyGroup>
4+
<OutputType>Exe</OutputType>
5+
<TargetFramework>netcoreapp2.1</TargetFramework>
6+
</PropertyGroup>
7+
8+
<ItemGroup>
9+
<PackageReference Include="Microsoft.Extensions.Logging.Console" Version="3.1.2" />
10+
<PackageReference Include="xunit.assert" Version="2.4.1" />
11+
</ItemGroup>
12+
13+
<ItemGroup>
14+
<ProjectReference Include="..\src\NodeJS\Jering.Javascript.NodeJS.csproj" />
15+
<ProjectReference Include="..\test\NodeJS\Jering.Javascript.NodeJS.Tests.csproj" />
16+
</ItemGroup>
17+
18+
</Project>

azure-pipelines.yml

+20-11
Original file line numberDiff line numberDiff line change
@@ -9,14 +9,23 @@ resources:
99
endpoint: JeringTech
1010

1111
jobs:
12-
- template: templates/nuget/stress-test.yml@templates
13-
# - template: templates/nuget/main.yml@templates
14-
# parameters:
15-
# nugetUnreleasedPrereleasePushEndpoint: "https://www.myget.org/F/jering/api/v3/index.json"
16-
# outOfProcessBuildDependencies: ["nodejs"]
17-
# codecovKey: "e5de9f48-fb06-43c6-8368-44de5cf7e5d4"
18-
# cacheYarnPackages: true
19-
# - template: templates/docs/main.yml@templates
20-
# parameters:
21-
# nugetRestoreEndpoints: "https://pkgs.dev.azure.com/JeremyTCD/_packaging/Main/nuget/v2"
22-
# nugetRestorePats: "$(nugetRestorePats)"
12+
- job: "GracefulShutdownDisabledIntermittentIssue"
13+
pool:
14+
vmImage: "windows-2019"
15+
variables:
16+
NUGET_PACKAGES: $(Pipeline.Workspace)/.nuget/packages
17+
YARN_CACHE_FOLDER: $(Pipeline.Workspace)/.yarn
18+
steps:
19+
- task: UseDotNet@2
20+
displayName: 'Install .NET Core SDK'
21+
inputs:
22+
version: "3.0.100"
23+
- task: UseDotNet@2
24+
displayName: 'Install .NET Core Runtime'
25+
inputs:
26+
packageType: runtime
27+
version: "2.1.13"
28+
- pwsh: |
29+
dotnet build -c Release
30+
dotnet run -p ./Temp.GracefulShutdownDisabledIntermittentIssue/Temp.GracefulShutdownDisabledIntermittentIssue.csproj -c Release
31+
displayName: "Investigation"

src/NodeJS/NodeJSServiceImplementations/OutOfProcess/Http/HttpNodeJSService.cs

+2
Original file line numberDiff line numberDiff line change
@@ -106,6 +106,8 @@ public HttpNodeJSService(IOptions<OutOfProcessNodeJSServiceOptions> outOfProcess
106106
using (HttpContent httpContent = _httpContentFactory.Create(invocationRequest))
107107
using (var httpRequestMessage = new HttpRequestMessage(HttpMethod.Post, _endpoint))
108108
{
109+
Logger.LogInformation("Sending invocation to: " + _endpoint.AbsoluteUri);
110+
109111
httpRequestMessage.Content = httpContent;
110112

111113
// Some notes on disposal:

0 commit comments

Comments
 (0)