1 // Licensed to the .NET Foundation under one or more agreements. 2 // The .NET Foundation licenses this file to you under the MIT license. 3 // See the LICENSE file in the project root for more information. 4 5 using System.Collections.Generic; 6 using System.Linq; 7 using System.Text; 8 using System.Threading; 9 using System.Threading.Tasks; 10 using Xunit; 11 12 namespace System.Diagnostics.Tests 13 { 14 public class ActivityTests 15 { 16 /// <summary> 17 /// Tests Activity constructor 18 /// </summary> 19 [Fact] DefaultActivity()20 public void DefaultActivity() 21 { 22 string activityName = "activity"; 23 var activity = new Activity(activityName); 24 Assert.Equal(activityName, activity.OperationName); 25 Assert.Null(activity.Id); 26 Assert.Null(activity.RootId); 27 Assert.Equal(TimeSpan.Zero, activity.Duration); 28 Assert.Null(activity.Parent); 29 Assert.Null(activity.ParentId); 30 Assert.Equal(0, activity.Baggage.ToList().Count); 31 Assert.Equal(0, activity.Tags.ToList().Count); 32 } 33 34 /// <summary> 35 /// Tests baggage operations 36 /// </summary> 37 [Fact] Baggage()38 public void Baggage() 39 { 40 var activity = new Activity("activity"); 41 Assert.Null(activity.GetBaggageItem("some baggage")); 42 43 Assert.Equal(activity, activity.AddBaggage("some baggage", "value")); 44 Assert.Equal("value", activity.GetBaggageItem("some baggage")); 45 46 var baggage = activity.Baggage.ToList(); 47 Assert.Equal(1, baggage.Count); 48 } 49 50 /// <summary> 51 /// Tests Tags operations 52 /// </summary> 53 [Fact] Tags()54 public void Tags() 55 { 56 var activity = new Activity("activity"); 57 58 Assert.Equal(activity, activity.AddTag("some tag", "value")); 59 60 var tags = activity.Tags.ToList(); 61 Assert.Equal(1, tags.Count); 62 Assert.Equal(tags[0].Key, "some tag"); 63 Assert.Equal(tags[0].Value, "value"); 64 } 65 66 /// <summary> 67 /// Tests activity SetParentId 68 /// </summary> 69 [Fact] SetParentId()70 public void SetParentId() 71 { 72 var parent = new Activity("parent"); 73 parent.SetParentId(null); // Error does nothing 74 Assert.Null(parent.ParentId); 75 76 parent.SetParentId(""); // Error does nothing 77 Assert.Null(parent.ParentId); 78 79 parent.SetParentId("1"); 80 Assert.Equal("1", parent.ParentId); 81 82 parent.SetParentId("2"); // Error does nothing 83 Assert.Equal("1", parent.ParentId); 84 85 Assert.Equal(parent.ParentId, parent.RootId); 86 parent.Start(); 87 88 var child = new Activity("child"); 89 child.Start(); 90 91 Assert.Equal(parent.Id, child.ParentId); 92 child.SetParentId("3"); // Error does nothing; 93 Assert.Equal(parent.Id, child.ParentId); 94 } 95 96 /// <summary> 97 /// Tests activity SetParentId 98 /// </summary> 99 [Fact] ActivityIdOverflow()100 public void ActivityIdOverflow() 101 { 102 //check parentId |abc.1.1...1.1.1.1.1. (1023 bytes) and check last .1.1.1.1 is replaced with #overflow_suffix 8 bytes long 103 var parentId = new StringBuilder("|abc."); 104 while (parentId.Length < 1022) 105 parentId.Append("1."); 106 107 var activity = new Activity("activity") 108 .SetParentId(parentId.ToString()) 109 .Start(); 110 111 Assert.Equal( 112 parentId.ToString().Substring(0, parentId.Length - 8), 113 activity.Id.Substring(0, activity.Id.Length - 9)); 114 Assert.Equal('#', activity.Id[activity.Id.Length - 1]); 115 116 //check parentId |abc.1.1...1.012345678 (128 bytes) and check last .012345678 is replaced with #overflow_suffix 8 bytes long 117 parentId = new StringBuilder("|abc."); 118 while (parentId.Length < 1013) 119 parentId.Append("1."); 120 parentId.Append("012345678."); 121 122 activity = new Activity("activity") 123 .SetParentId(parentId.ToString()) 124 .Start(); 125 126 //last .012345678 will be replaced with #overflow_suffix 8 bytes long 127 Assert.Equal( 128 parentId.ToString().Substring(0, parentId.Length - 10), 129 activity.Id.Substring(0, activity.Id.Length - 9)); 130 Assert.Equal('#', activity.Id[activity.Id.Length - 1]); 131 } 132 133 /// <summary> 134 /// Tests overflow in Id generation when parentId has a single (root) node 135 /// </summary> 136 [Fact] ActivityIdNonHierarchicalOverflow()137 public void ActivityIdNonHierarchicalOverflow() 138 { 139 // find out Activity Id length on this platform in this AppDomain 140 Activity testActivity = new Activity("activity") 141 .Start(); 142 var expectedIdLength = testActivity.Id.Length; 143 testActivity.Stop(); 144 145 // check that if parentId '|aaa...a' 1024 bytes long is set with single node (no dots or underscores in the Id) 146 // it causes overflow during Id generation, and new root Id is generated for the new Activity 147 var parentId = '|' + new string('a', 1022) + '.'; 148 149 var activity = new Activity("activity") 150 .SetParentId(parentId) 151 .Start(); 152 153 Assert.Equal(parentId, activity.ParentId); 154 155 // With probability 1/MaxLong, Activity.Id length may be expectedIdLength + 1 156 Assert.InRange(activity.Id.Length, expectedIdLength, expectedIdLength + 1); 157 Assert.False(activity.Id.Contains('#')); 158 } 159 160 /// <summary> 161 /// Tests activity start and stop 162 /// Checks Activity.Current correctness, Id generation 163 /// </summary> 164 [Fact] StartStop()165 public void StartStop() 166 { 167 var activity = new Activity("activity"); 168 Assert.Equal(null, Activity.Current); 169 activity.Start(); 170 Assert.Equal(activity, Activity.Current); 171 Assert.Null(activity.Parent); 172 Assert.NotNull(activity.Id); 173 Assert.NotNull(activity.RootId); 174 Assert.NotEqual(default(DateTime), activity.StartTimeUtc); 175 176 activity.Stop(); 177 Assert.Equal(null, Activity.Current); 178 } 179 180 /// <summary> 181 /// Tests Id generation 182 /// </summary> 183 [Fact] IdGenerationNoParent()184 public void IdGenerationNoParent() 185 { 186 var orphan1 = new Activity("orphan1"); 187 var orphan2 = new Activity("orphan2"); 188 189 Task.Run(() => orphan1.Start()).Wait(); 190 Task.Run(() => orphan2.Start()).Wait(); 191 192 Assert.NotEqual(orphan2.Id, orphan1.Id); 193 Assert.NotEqual(orphan2.RootId, orphan1.RootId); 194 } 195 196 /// <summary> 197 /// Tests Id generation 198 /// </summary> 199 [Fact] IdGenerationInternalParent()200 public void IdGenerationInternalParent() 201 { 202 var parent = new Activity("parent"); 203 parent.Start(); 204 var child1 = new Activity("child1"); 205 var child2 = new Activity("child2"); 206 //start 2 children in different execution contexts 207 Task.Run(() => child1.Start()).Wait(); 208 Task.Run(() => child2.Start()).Wait(); 209 #if DEBUG 210 Assert.Equal($"|{parent.RootId}.{child1.OperationName}-1.", child1.Id); 211 Assert.Equal($"|{parent.RootId}.{child2.OperationName}-2.", child2.Id); 212 #else 213 Assert.Equal($"|{parent.RootId}.1.", child1.Id); 214 Assert.Equal($"|{parent.RootId}.2.", child2.Id); 215 #endif 216 Assert.Equal(parent.RootId, child1.RootId); 217 Assert.Equal(parent.RootId, child2.RootId); 218 child1.Stop(); 219 child2.Stop(); 220 var child3 = new Activity("child3"); 221 child3.Start(); 222 #if DEBUG 223 Assert.Equal($"|{parent.RootId}.{child3.OperationName}-3.", child3.Id); 224 #else 225 Assert.Equal($"|{parent.RootId}.3.", child3.Id); 226 #endif 227 228 var grandChild = new Activity("grandChild"); 229 grandChild.Start(); 230 #if DEBUG 231 Assert.Equal($"{child3.Id}{grandChild.OperationName}-1.", grandChild.Id); 232 #else 233 Assert.Equal($"{child3.Id}1.", grandChild.Id); 234 #endif 235 236 } 237 238 /// <summary> 239 /// Tests Id generation 240 /// </summary> 241 [Fact] IdGenerationExternalParentId()242 public void IdGenerationExternalParentId() 243 { 244 var child1 = new Activity("child1"); 245 child1.SetParentId("123"); 246 child1.Start(); 247 Assert.Equal("123", child1.RootId); 248 Assert.Equal('|', child1.Id[0]); 249 Assert.Equal('_', child1.Id[child1.Id.Length - 1]); 250 child1.Stop(); 251 252 var child2 = new Activity("child2"); 253 child2.SetParentId("123"); 254 child2.Start(); 255 Assert.NotEqual(child2.Id, child1.Id); 256 Assert.Equal("123", child2.RootId); 257 } 258 259 /// <summary> 260 /// Tests Id generation 261 /// </summary> 262 [Fact] RootId()263 public void RootId() 264 { 265 266 var parentIds = new []{ 267 "123", //Parent does not start with '|' and does not contain '.' 268 "123.1", //Parent does not start with '|' but contains '.' 269 "|123", //Parent starts with '|' and does not contain '.' 270 "|123.1.1", //Parent starts with '|' and contains '.' 271 }; 272 foreach (var parentId in parentIds) 273 { 274 var activity = new Activity("activity"); 275 activity.SetParentId(parentId); 276 Assert.Equal("123", activity.RootId); 277 } 278 } 279 280 /// <summary> 281 /// Tests Activity Start and Stop with timestamp 282 /// </summary> 283 [Fact] StartStopWithTimestamp()284 public void StartStopWithTimestamp() 285 { 286 var activity = new Activity("activity"); 287 Assert.Equal(default(DateTime), activity.StartTimeUtc); 288 289 activity.SetStartTime(DateTime.Now); // Error Does nothing because it is not UTC 290 Assert.Equal(default(DateTime), activity.StartTimeUtc); 291 292 var startTime = DateTime.UtcNow.AddSeconds(-1); // A valid time in the past that we want to be our offical start time. 293 activity.SetStartTime(startTime); 294 295 activity.Start(); 296 Assert.Equal(startTime, activity.StartTimeUtc); // we use our offical start time not the time now. 297 Assert.Equal(TimeSpan.Zero, activity.Duration); 298 299 Thread.Sleep(35); 300 301 activity.SetEndTime(DateTime.Now); // Error does nothing because it is not UTC 302 Assert.Equal(TimeSpan.Zero, activity.Duration); 303 304 var stopTime = DateTime.UtcNow; 305 activity.SetEndTime(stopTime); 306 Assert.Equal(stopTime - startTime, activity.Duration); 307 } 308 309 /// <summary> 310 /// Tests Activity Stop without timestamp 311 /// </summary> 312 [Fact] StopWithoutTimestamp()313 public void StopWithoutTimestamp() 314 { 315 var startTime = DateTime.UtcNow.AddSeconds(-1); 316 var activity = new Activity("activity") 317 .SetStartTime(startTime); 318 319 activity.Start(); 320 Assert.Equal(startTime, activity.StartTimeUtc); 321 322 activity.Stop(); 323 324 // DateTime.UtcNow is not precise on some platforms, but Activity stop time is precise 325 // in this test we set start time, but not stop time and check duration. 326 // 327 // Let's check that duration is 1sec - 2 * maximum DateTime.UtcNow error or bigger. 328 // As both start and stop timestamps may have error. 329 // There is another test (ActivityDateTimeTests.StartStopReturnsPreciseDuration) 330 // that checks duration precision on netfx. 331 Assert.InRange(activity.Duration.TotalMilliseconds, 1000 - 2 * MaxClockErrorMSec, double.MaxValue); 332 } 333 334 /// <summary> 335 /// Tests Activity stack: creates a parent activity and child activity 336 /// Verifies 337 /// - Activity.Parent and ParentId correctness 338 /// - Baggage propagated from parent 339 /// - Tags are not propagated 340 /// Stops child and checks Activity,Current is set to parent 341 /// </summary> 342 [Fact] ParentChild()343 public void ParentChild() 344 { 345 var parent = new Activity("parent") 346 .AddBaggage("id1", "baggage from parent") 347 .AddTag("tag1", "tag from parent"); 348 349 parent.Start(); 350 351 Assert.Equal(parent, Activity.Current); 352 353 var child = new Activity("child"); 354 child.Start(); 355 Assert.Equal(parent, child.Parent); 356 Assert.Equal(parent.Id, child.ParentId); 357 358 //baggage from parent 359 Assert.Equal("baggage from parent", child.GetBaggageItem("id1")); 360 361 //no tags from parent 362 var childTags = child.Tags.ToList(); 363 Assert.Equal(0, childTags.Count); 364 365 child.Stop(); 366 Assert.Equal(parent, Activity.Current); 367 368 parent.Stop(); 369 Assert.Equal(null, Activity.Current); 370 } 371 372 /// <summary> 373 /// Tests wrong stop order, when parent is stopped before child 374 /// </summary> 375 [Fact] StopParent()376 public void StopParent() 377 { 378 var parent = new Activity("parent"); 379 parent.Start(); 380 var child = new Activity("child"); 381 child.Start(); 382 383 parent.Stop(); 384 Assert.Equal(null, Activity.Current); 385 } 386 387 /// <summary> 388 /// Tests that activity can not be stated twice 389 /// </summary> 390 [Fact] StartTwice()391 public void StartTwice() 392 { 393 var activity = new Activity("activity"); 394 activity.Start(); 395 var id = activity.Id; 396 397 activity.Start(); // Error already started. Does nothing. 398 Assert.Equal(id, activity.Id); 399 } 400 401 /// <summary> 402 /// Tests that activity that has not been started can not be stopped 403 /// </summary> 404 [Fact] StopNotStarted()405 public void StopNotStarted() 406 { 407 var activity = new Activity("activity"); 408 activity.Stop(); // Error Does Nothing 409 Assert.Equal(TimeSpan.Zero, activity.Duration); 410 } 411 412 /// <summary> 413 /// Tests that second activity stop does not update Activity.Current 414 /// </summary> 415 [Fact] StopTwice()416 public void StopTwice() 417 { 418 var parent = new Activity("parent"); 419 parent.Start(); 420 421 var child1 = new Activity("child1"); 422 child1.Start(); 423 child1.Stop(); 424 425 var child2 = new Activity("child2"); 426 child2.Start(); 427 428 child1.Stop(); 429 430 Assert.Equal(child2, Activity.Current); 431 } 432 433 [Fact] DiagnosticSourceStartStop()434 public void DiagnosticSourceStartStop() 435 { 436 using (DiagnosticListener listener = new DiagnosticListener("Testing")) 437 { 438 DiagnosticSource source = listener; 439 var observer = new TestObserver(); 440 441 using (listener.Subscribe(observer)) 442 { 443 var arguments = new { args = "arguments" }; 444 445 var activity = new Activity("activity"); 446 447 var stopWatch = Stopwatch.StartNew(); 448 // Test Activity.Start 449 source.StartActivity(activity, arguments); 450 451 Assert.Equal(activity.OperationName + ".Start", observer.EventName); 452 Assert.Equal(arguments, observer.EventObject); 453 Assert.NotNull(observer.Activity); 454 455 Assert.NotEqual(activity.StartTimeUtc, default(DateTime)); 456 Assert.Equal(TimeSpan.Zero, observer.Activity.Duration); 457 458 observer.Reset(); 459 460 Thread.Sleep(100); 461 462 // Test Activity.Stop 463 source.StopActivity(activity, arguments); 464 stopWatch.Stop(); 465 Assert.Equal(activity.OperationName + ".Stop", observer.EventName); 466 Assert.Equal(arguments, observer.EventObject); 467 468 // Confirm that duration is set. 469 Assert.NotNull(observer.Activity); 470 Assert.InRange(observer.Activity.Duration, TimeSpan.FromTicks(1), TimeSpan.MaxValue); 471 472 // let's only check that Duration is set in StopActivity, we do not intend to check precision here 473 Assert.InRange(observer.Activity.Duration, TimeSpan.FromTicks(1), stopWatch.Elapsed.Add(TimeSpan.FromMilliseconds(2 * MaxClockErrorMSec))); 474 } 475 } 476 } 477 478 /// <summary> 479 /// Tests that Activity.Current flows correctly within async methods 480 /// </summary> 481 [Fact] ActivityCurrentFlowsWithAsyncSimple()482 public async Task ActivityCurrentFlowsWithAsyncSimple() 483 { 484 Activity activity = new Activity("activity").Start(); 485 Assert.Same(activity, Activity.Current); 486 487 await Task.Run(() => 488 { 489 Assert.Same(activity, Activity.Current); 490 }); 491 492 Assert.Same(activity, Activity.Current); 493 } 494 495 /// <summary> 496 /// Tests that Activity.Current flows correctly within async methods 497 /// </summary> 498 [Fact] ActivityCurrentFlowsWithAsyncComplex()499 public async Task ActivityCurrentFlowsWithAsyncComplex() 500 { 501 Activity originalActivity = Activity.Current; 502 503 // Start an activity which spawns a task, but don't await it. 504 // While that's running, start another, nested activity. 505 Activity activity1 = new Activity("activity1").Start(); 506 Assert.Same(activity1, Activity.Current); 507 508 SemaphoreSlim semaphore = new SemaphoreSlim(initialCount: 0); 509 Task task = Task.Run(async () => 510 { 511 // Wait until the semaphore is signaled. 512 await semaphore.WaitAsync(); 513 Assert.Same(activity1, Activity.Current); 514 }); 515 516 Activity activity2 = new Activity("activity2").Start(); 517 Assert.Same(activity2, Activity.Current); 518 519 // Let task1 complete. 520 semaphore.Release(); 521 await task; 522 523 Assert.Same(activity2, Activity.Current); 524 525 activity2.Stop(); 526 527 Assert.Same(activity1, Activity.Current); 528 529 activity1.Stop(); 530 531 Assert.Same(originalActivity, Activity.Current); 532 } 533 534 private class TestObserver : IObserver<KeyValuePair<string, object>> 535 { 536 public string EventName { get; private set; } 537 public object EventObject { get; private set; } 538 539 public Activity Activity { get; private set; } 540 OnNext(KeyValuePair<string, object> value)541 public void OnNext(KeyValuePair<string, object> value) 542 { 543 EventName = value.Key; 544 EventObject = value.Value; 545 Activity = Activity.Current; 546 } 547 Reset()548 public void Reset() 549 { 550 EventName = null; 551 EventObject = null; 552 Activity = null; 553 } 554 OnCompleted()555 public void OnCompleted() { } 556 OnError(Exception error)557 public void OnError(Exception error) { } 558 } 559 560 private const int MaxClockErrorMSec = 20; 561 } 562 } 563