Skip to content
This repository was archived by the owner on Dec 5, 2024. It is now read-only.

Commit 8ad212e

Browse files
shanashana
committed
More logging, also making sure httpserver closes connections so things don't timeout
1 parent 7575e79 commit 8ad212e

File tree

3 files changed

+113
-30
lines changed

3 files changed

+113
-30
lines changed

‎src/GitHub.Api/IO/Utils.cs

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -14,6 +14,7 @@ public static bool Copy(Stream source, Stream destination,
1414
Func<long, long, bool> progress = null,
1515
int progressUpdateRate = 100)
1616
{
17+
var logger = Logging.GetLogger("Copy");
1718
byte[] buffer = new byte[chunkSize];
1819
int bytesRead = 0;
1920
long totalRead = 0;
@@ -61,7 +62,7 @@ public static bool Copy(Stream source, Stream destination,
6162
timeToFinish = Math.Max(1L,
6263
(long)((totalSize - totalRead) / (averageSpeed / progressUpdateRate)));
6364

64-
Logging.Debug($"totalRead: {totalRead} of {totalSize}");
65+
logger.Trace($"totalRead: {totalRead} of {totalSize}");
6566
success = progress(totalRead, timeToFinish);
6667
if (!success)
6768
break;

‎src/tests/IntegrationTests/Download/DownloadTaskTests.cs

Lines changed: 86 additions & 24 deletions
Original file line numberDiff line numberDiff line change
@@ -6,12 +6,16 @@
66
using GitHub.Unity;
77
using NUnit.Framework;
88
using System.Diagnostics;
9+
using GitHub.Unity.Logs;
10+
using System.Runtime.CompilerServices;
911

1012
namespace IntegrationTests.Download
1113
{
1214
[TestFixture]
1315
class DownloadTaskTests : BaseTaskManagerTest
1416
{
17+
const int Timeout = 30000;
18+
1519
public override void OnSetup()
1620
{
1721
base.OnSetup();
@@ -34,10 +38,33 @@ public override void TestFixtureTearDown()
3438
ApplicationConfiguration.WebTimeout = ApplicationConfiguration.DefaultWebTimeout;
3539
}
3640

41+
private void StartTest(out Stopwatch watch, out ILogging logger, [CallerMemberName] string testName = "test")
42+
{
43+
watch = new Stopwatch();
44+
logger = Logging.GetLogger(testName);
45+
logger.Trace("Starting test");
46+
}
47+
48+
private void StartTrackTime(Stopwatch watch, ILogging logger = null, string message = "")
49+
{
50+
if (!String.IsNullOrEmpty(message))
51+
logger.Trace(message);
52+
watch.Reset();
53+
watch.Start();
54+
}
55+
56+
private void StopTrackTimeAndLog(Stopwatch watch, ILogging logger)
57+
{
58+
watch.Stop();
59+
logger.Trace($"Time: {watch.ElapsedMilliseconds}");
60+
}
61+
3762
[Test]
3863
public void TestDownloadTask()
3964
{
40-
Logger.Info("Starting Test: TestDownloadTask");
65+
Stopwatch watch;
66+
ILogging logger;
67+
StartTest(out watch, out logger);
4168

4269
var fileSystem = Environment.FileSystem;
4370

@@ -47,26 +74,33 @@ public void TestDownloadTask()
4774
var evtDone = new ManualResetEventSlim(false);
4875

4976
string md5 = null;
77+
78+
StartTrackTime(watch, logger, gitLfsMd5);
5079
new DownloadTextTask(TaskManager.Token, fileSystem, gitLfsMd5, TestBasePath)
5180
.Finally(r => {
5281
md5 = r;
5382
evtDone.Set();
5483
})
5584
.Start();
5685

57-
evtDone.Wait(10000);
86+
evtDone.Wait(Timeout).Should().BeTrue("Finally raised the signal");
87+
StopTrackTimeAndLog(watch, logger);
88+
5889
evtDone.Reset();
5990
Assert.NotNull(md5);
6091

6192
string downloadPath = null;
93+
StartTrackTime(watch, logger, gitLfs);
6294
new DownloadTask(TaskManager.Token, fileSystem, gitLfs, TestBasePath)
6395
.Finally(r => {
6496
downloadPath = r;
6597
evtDone.Set();
6698
})
6799
.Start();
68100

69-
evtDone.Wait(10000);
101+
evtDone.Wait(Timeout).Should().BeTrue("Finally raised the signal");;
102+
StopTrackTimeAndLog(watch, logger);
103+
70104
evtDone.Reset();
71105

72106
Assert.NotNull(downloadPath);
@@ -81,14 +115,17 @@ public void TestDownloadTask()
81115
fileSystem.FileDelete(downloadPath);
82116
fileSystem.WriteAllBytes(downloadPath, cutDownloadPathBytes);
83117

118+
StartTrackTime(watch, logger, "resuming download");
84119
new DownloadTask(TaskManager.Token, fileSystem, gitLfs, TestBasePath)
85120
.Finally(r => {
86121
downloadPath = r;
87122
evtDone.Set();
88123
})
89124
.Start();
90125

91-
evtDone.Wait(10000);
126+
evtDone.Wait(Timeout).Should().BeTrue("Finally raised the signal");;
127+
StopTrackTimeAndLog(watch, logger);
128+
92129
evtDone.Reset();
93130

94131
var downloadHalfPathBytes = fileSystem.ReadAllBytes(downloadPath);
@@ -101,7 +138,9 @@ public void TestDownloadTask()
101138
[Test]
102139
public void TestDownloadFailure()
103140
{
104-
Logger.Info("Starting Test: TestDownloadFailure");
141+
Stopwatch watch;
142+
ILogging logger;
143+
StartTest(out watch, out logger);
105144

106145
var fileSystem = Environment.FileSystem;
107146

@@ -110,17 +149,21 @@ public void TestDownloadFailure()
110149

111150
var autoResetEvent = new AutoResetEvent(false);
112151

113-
var downloadTask = new DownloadTask(TaskManager.Token, fileSystem,
114-
$"http://localhost:{server.Port}/nope", TestBasePath)
152+
var downloadTask = new DownloadTask(TaskManager.Token, fileSystem, $"http://localhost:{server.Port}/nope", TestBasePath);
153+
154+
StartTrackTime(watch);
155+
downloadTask
115156
.Finally((b, exception) => {
116157
taskFailed = !b;
117158
exceptionThrown = exception;
118159
autoResetEvent.Set();
119-
});
160+
})
161+
.Start();
120162

121-
downloadTask.Start();
163+
var ret = autoResetEvent.WaitOne(Timeout);
164+
StopTrackTimeAndLog(watch, logger);
122165

123-
autoResetEvent.WaitOne(10000);
166+
ret.Should().BeTrue("Finally raised the signal");
124167

125168
taskFailed.Should().BeTrue();
126169
exceptionThrown.Should().NotBeNull();
@@ -129,7 +172,9 @@ public void TestDownloadFailure()
129172
[Test]
130173
public void TestDownloadTextTask()
131174
{
132-
Logger.Info("Starting Test: TestDownloadTextTask");
175+
Stopwatch watch;
176+
ILogging logger;
177+
StartTest(out watch, out logger);
133178

134179
var fileSystem = Environment.FileSystem;
135180

@@ -139,43 +184,55 @@ public void TestDownloadTextTask()
139184

140185
var autoResetEvent = new AutoResetEvent(false);
141186
string result = null;
187+
188+
StartTrackTime(watch);
142189
downloadTask
143190
.Finally(r => {
144191
result = r;
145192
autoResetEvent.Set();
146193
})
147194
.Start();
148195

149-
autoResetEvent.WaitOne(10000);
196+
autoResetEvent.WaitOne(Timeout).Should().BeTrue("Finally raised the signal");;
197+
StopTrackTimeAndLog(watch, logger);
198+
150199
result.Should().Be("105DF1302560C5F6AA64D1930284C126");
151200
}
152201

153202
[Test]
154203
public void TestDownloadTextFailure()
155204
{
156-
Logger.Info("Starting Test: TestDownloadTextFailure");
205+
Stopwatch watch;
206+
ILogging logger;
207+
StartTest(out watch, out logger);
157208

158209
var fileSystem = Environment.FileSystem;
159210

160211
var downloadTask = new DownloadTextTask(TaskManager.Token, fileSystem, "https://ggggithub.com/robots.txt");
161212
var exceptionThrown = false;
162213

163214
var autoResetEvent = new AutoResetEvent(false);
215+
216+
StartTrackTime(watch);
164217
downloadTask
165218
.Finally((b, exception) => {
166219
exceptionThrown = exception != null;
167220
autoResetEvent.Set();
168221
})
169222
.Start();
170223

171-
autoResetEvent.WaitOne(10000);
224+
autoResetEvent.WaitOne(Timeout).Should().BeTrue("Finally raised the signal");;
225+
StopTrackTimeAndLog(watch, logger);
226+
172227
exceptionThrown.Should().BeTrue();
173228
}
174229

175230
[Test]
176231
public void TestDownloadFileAndHash()
177232
{
178-
Logger.Info("Starting Test: TestDownloadFileAndHash");
233+
Stopwatch watch;
234+
ILogging logger;
235+
StartTest(out watch, out logger);
179236

180237
var fileSystem = Environment.FileSystem;
181238

@@ -190,6 +247,7 @@ public void TestDownloadFileAndHash()
190247

191248
var autoResetEvent = new AutoResetEvent(false);
192249

250+
StartTrackTime(watch);
193251
downloadGitLfsMd5Task
194252
.Then((b, s) =>
195253
{
@@ -203,7 +261,8 @@ public void TestDownloadFileAndHash()
203261
})
204262
.Start();
205263

206-
autoResetEvent.WaitOne(10000);
264+
autoResetEvent.WaitOne(Timeout).Should().BeTrue("Finally raised the signal");;
265+
StopTrackTimeAndLog(watch, logger);
207266

208267
result.Should().BeTrue();
209268
exception.Should().BeNull();
@@ -212,7 +271,9 @@ public void TestDownloadFileAndHash()
212271
[Test]
213272
public void TestDownloadShutdownTimeWhenInterrupted()
214273
{
215-
Logger.Info("Starting Test: TestDownloadShutdownTimeWhenInterrupted");
274+
Stopwatch watch;
275+
ILogging logger;
276+
StartTest(out watch, out logger);
216277

217278
server.Delay = 100;
218279

@@ -222,9 +283,9 @@ public void TestDownloadShutdownTimeWhenInterrupted()
222283
var evtFinally = new AutoResetEvent(false);
223284
Exception exception = null;
224285

225-
var watch = new Stopwatch();
226-
227286
var gitLfs = new UriString($"http://localhost:{server.Port}/git-lfs.zip");
287+
288+
StartTrackTime(watch, logger, gitLfs);
228289
var downloadGitTask = new DownloadTask(TaskManager.Token, fileSystem, gitLfs, TestBasePath)
229290

230291
// An exception is thrown when we stop the task manager
@@ -243,19 +304,20 @@ public void TestDownloadShutdownTimeWhenInterrupted()
243304

244305
downloadGitTask.Start();
245306

246-
evtStop.WaitOne(10000);
307+
evtStop.WaitOne(Timeout).Should().BeTrue("Progress raised the signal");
308+
StopTrackTimeAndLog(watch, logger);
247309

248-
watch.Start();
310+
311+
StartTrackTime(watch, logger, "TaskManager.Dispose()");
249312
TaskManager.Dispose();
250-
evtFinally.WaitOne(10000);
251-
watch.Stop();
313+
evtFinally.WaitOne(Timeout).Should().BeTrue("Catch raised the signal");
314+
StopTrackTimeAndLog(watch, logger);
252315

253316
server.Delay = 0;
254317
server.Abort();
255318

256319
exception.Should().NotBeNull();
257320
watch.ElapsedMilliseconds.Should().BeLessThan(250);
258-
259321
}
260322
}
261323
}

‎src/tests/TestWebServer/HttpServer.cs

Lines changed: 25 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -24,6 +24,8 @@ public class HttpServer
2424
private readonly HttpListener listener;
2525
private readonly string rootDirectory;
2626
private bool abort;
27+
private static ILogging Logger = Logging.GetLogger<HttpServer>();
28+
private ManualResetEvent delay = new ManualResetEvent(false);
2729

2830
/// <summary>
2931
/// Construct server with given port.
@@ -65,30 +67,34 @@ public void Start()
6567
{
6668
try
6769
{
70+
Logger.Info($"Starting http server on port {Port}");
6871
listener.Start();
6972
while (true)
7073
{
7174
try
7275
{
7376
abort = false;
77+
Logger.Info($"Waiting for a request...");
7478
var context = listener.GetContext();
7579
Process(context);
7680
}
77-
catch
81+
catch (Exception ex)
7882
{
83+
Logger.Error(ex);
7984
break;
8085
}
8186
}
8287
}
8388
catch (Exception ex)
8489
{
85-
Logging.GetLogger(GetType()).Error(ex);
90+
Logger.Error(ex);
8691
}
8792
}
8893

8994
public void Abort()
9095
{
9196
abort = true;
97+
delay.Set();
9298
}
9399

94100
private void Process(HttpListenerContext context)
@@ -100,6 +106,7 @@ private void Process(HttpListenerContext context)
100106
if (!File.Exists(filename))
101107
{
102108
context.Response.StatusCode = (int)HttpStatusCode.NotFound;
109+
context.Response.Close();
103110
return;
104111
}
105112

@@ -154,12 +161,16 @@ private void Process(HttpListenerContext context)
154161
{
155162
context.Response.ContentLength64 = length;
156163

157-
var delay = new ManualResetEvent(false);
164+
Logger.Info($"Writing {length} bytes");
165+
166+
delay.Reset();
158167
Utils.Copy(input, context.Response.OutputStream, length,
159-
progress: (_, __) =>
168+
progress: (total, __) =>
160169
{
161170
if (Delay > 0)
162171
delay.WaitOne(Delay);
172+
if (abort)
173+
Logger.Info($"aborting after {total} bytes");
163174
return !abort;
164175
},
165176
progressUpdateRate: 0
@@ -168,10 +179,19 @@ private void Process(HttpListenerContext context)
168179
}
169180
}
170181
}
171-
catch
182+
catch (Exception ex)
172183
{
184+
Logging.GetLogger<HttpServer>().Error(ex);
173185
context.Response.StatusCode = (int)HttpStatusCode.InternalServerError;
174186
}
187+
finally
188+
{
189+
try
190+
{
191+
context.Response.Close();
192+
}
193+
catch { }
194+
}
175195
}
176196

177197
public int Delay { get; set; }

0 commit comments

Comments
 (0)