355 369 | }
|
356 370 |
|
357 371 | /// Returns the final protocol and ownership close classification.
|
358 372 | pub fn reason(&self) -> CloseReason {
|
359 373 | self.reason
|
360 374 | }
|
361 375 | }
|
362 376 |
|
363 377 | /// Pool-owned connection event source.
|
364 378 | ///
|
365 - | /// This owner retains callback delivery, lifecycle timing, and establishment
|
366 - | /// identity allocation. Starting an establishment performs no timing or
|
367 - | /// identity work when no listener is configured.
|
379 + | /// This owner retains callback delivery, establishment timing, and public
|
380 + | /// establishment identity allocation. Timing is collected for successful
|
381 + | /// connection metadata even when callback delivery is disabled.
|
368 382 | #[derive(Debug)]
|
369 383 | pub(super) struct ConnectionEvents {
|
370 384 | listener: Option<SharedConnectionEventListener>,
|
371 385 | time_source: SharedTimeSource,
|
372 386 | next_establishment_id: AtomicU64,
|
373 387 | }
|
374 388 |
|
375 389 | impl ConnectionEvents {
|
376 390 | /// Creates the event source retained by one connection pool.
|
377 391 | pub(super) fn new(
|
378 392 | listener: Option<SharedConnectionEventListener>,
|
379 393 | time_source: SharedTimeSource,
|
380 394 | ) -> Self {
|
381 395 | Self {
|
382 396 | listener,
|
383 397 | time_source,
|
384 398 | next_establishment_id: AtomicU64::new(0),
|
385 399 | }
|
386 400 | }
|
387 401 |
|
388 - | /// Records the start of an establishment when observation is enabled.
|
402 + | /// Records the start of one connection establishment.
|
389 403 | pub(super) fn establishment_started(
|
390 404 | &self,
|
391 405 | origin: &OriginKey,
|
392 406 | partition: PartitionId,
|
393 407 | connection_stats: PoolArc<CellConnectionStats>,
|
394 408 | ) -> ConnectionEstablishment {
|
395 409 | connection_stats.establishment_started();
|
410 + | let timing = EstablishmentTiming {
|
411 + | time_source: self.time_source.clone(),
|
412 + | started_at: self.time_source.now(),
|
413 + | protocol_handshake_started_at: None,
|
414 + | transport_duration: None,
|
415 + | protocol_handshake_duration: None,
|
416 + | };
|
396 417 | let observation = self
|
397 418 | .listener
|
398 419 | .as_ref()
|
399 420 | .map(|listener| EstablishmentObservation {
|
400 421 | listener: listener.clone(),
|
401 422 | info: ConnectionEstablishmentInfo {
|
402 423 | id: ConnectionEstablishmentId(
|
403 424 | self.next_establishment_id.fetch_add(1, Ordering::Relaxed),
|
404 425 | ),
|
405 426 | origin: origin.clone(),
|
406 427 | partition,
|
407 428 | },
|
408 - | time_source: self.time_source.clone(),
|
409 - | started_at: self.time_source.now(),
|
410 - | protocol_handshake_started_at: None,
|
411 - | transport_duration: None,
|
412 - | protocol_handshake_duration: None,
|
413 429 | stage: ConnectionEstablishmentStage::Transport,
|
414 430 | remote_addr: None,
|
415 431 | protocol: None,
|
416 432 | });
|
417 433 | ConnectionEstablishment {
|
434 + | timing,
|
418 435 | observation,
|
436 + | successful_stats: None,
|
419 437 | connection_stats: Some(connection_stats),
|
420 438 | }
|
421 439 | }
|
422 440 | }
|
423 441 |
|
424 - | /// Tracks observations collected during one connection establishment.
|
442 + | /// Tracks measurements and optional callback state for one establishment.
|
425 443 | pub(super) struct ConnectionEstablishment {
|
444 + | timing: EstablishmentTiming,
|
426 445 | observation: Option<EstablishmentObservation>,
|
446 + | successful_stats: Option<ConnectionEstablishmentStats>,
|
427 447 | connection_stats: Option<PoolArc<CellConnectionStats>>,
|
428 448 | }
|
429 449 |
|
430 - | /// Data collected while one observed establishment is active.
|
431 - | struct EstablishmentObservation {
|
432 - | listener: SharedConnectionEventListener,
|
433 - | info: ConnectionEstablishmentInfo,
|
450 + | /// Timing collected for every connection establishment.
|
451 + | struct EstablishmentTiming {
|
434 452 | time_source: SharedTimeSource,
|
435 453 | started_at: SystemTime,
|
436 454 | protocol_handshake_started_at: Option<SystemTime>,
|
437 455 | transport_duration: Option<Duration>,
|
438 456 | protocol_handshake_duration: Option<Duration>,
|
457 + | }
|
458 + |
|
459 + | /// Callback state retained only when a listener is configured.
|
460 + | struct EstablishmentObservation {
|
461 + | listener: SharedConnectionEventListener,
|
462 + | info: ConnectionEstablishmentInfo,
|
439 463 | stage: ConnectionEstablishmentStage,
|
440 464 | remote_addr: Option<SocketAddr>,
|
441 465 | protocol: Option<ConnectionProtocol>,
|
442 466 | }
|
443 467 |
|
444 468 | impl ConnectionEstablishment {
|
445 469 | /// Records completion of the transport stage.
|
446 470 | pub(super) fn transport_completed(&mut self, remote_addr: Option<SocketAddr>) {
|
471 + | self.timing.transport_duration = Some(self.timing.elapsed_since(self.timing.started_at));
|
447 472 | if let Some(observation) = &mut self.observation {
|
448 - | observation.transport_duration =
|
449 - | Some(observation.elapsed_since(observation.started_at));
|
450 473 | observation.remote_addr = remote_addr;
|
451 474 | observation.stage = ConnectionEstablishmentStage::ProtocolSelection;
|
452 475 | }
|
453 476 | }
|
454 477 |
|
455 478 | /// Records the protocol selected from connector metadata.
|
456 479 | pub(super) fn protocol_selected(&mut self, protocol: ConnectionProtocol) {
|
457 480 | if let Some(observation) = &mut self.observation {
|
458 481 | observation.protocol = Some(protocol);
|
459 482 | }
|
460 483 | }
|
461 484 |
|
462 485 | /// Records entry into Hyper's protocol handshake.
|
463 486 | pub(super) fn protocol_handshake_started(&mut self) {
|
487 + | self.timing.protocol_handshake_started_at = Some(self.timing.time_source.now());
|
464 488 | if let Some(observation) = &mut self.observation {
|
465 - | observation.protocol_handshake_started_at = Some(observation.time_source.now());
|
466 489 | observation.stage = ConnectionEstablishmentStage::ProtocolHandshake;
|
467 490 | }
|
468 491 | }
|
469 492 |
|
470 493 | /// Records a failed Hyper handshake before emitting its terminal event.
|
471 494 | pub(super) fn protocol_handshake_failed(&mut self) {
|
472 - | if let Some(observation) = &mut self.observation {
|
473 - | observation.finish_protocol_handshake();
|
474 - | }
|
495 + | self.timing.finish_protocol_handshake();
|
475 496 | }
|
476 497 |
|
477 498 | /// Records successful Hyper handshake before pool installation.
|
478 499 | pub(super) fn protocol_handshake_completed(&mut self) {
|
500 + | self.timing.finish_protocol_handshake();
|
479 501 | if let Some(observation) = &mut self.observation {
|
480 - | observation.finish_protocol_handshake();
|
481 502 | observation.stage = ConnectionEstablishmentStage::PoolInstallation;
|
482 503 | }
|
483 504 | }
|
484 505 |
|
506 + | /// Freezes successful measurements before the connection becomes visible.
|
507 + | pub(super) fn installed(&mut self, connection: &PoolArc<ConnectionState>) {
|
508 + | let stats = self.timing.stats();
|
509 + | connection
|
510 + | .info()
|
511 + | .set_establishment(stats.connection_metadata());
|
512 + | assert!(
|
513 + | self.successful_stats.replace(stats).is_none(),
|
514 + | "connection establishment was installed more than once"
|
515 + | );
|
516 + | }
|
517 + |
|
485 518 | /// Emits the terminal failure for this establishment.
|
486 519 | pub(super) fn failed(mut self, error: &ConnectorError) {
|
520 + | let stats = self.timing.stats();
|
487 521 | self.finish_connection_stats();
|
488 522 | let Some(observation) = self.observation.take() else {
|
489 523 | return;
|
490 524 | };
|
491 - | observation.notify_failure(error);
|
525 + | observation.notify_failure(error, &stats);
|
492 526 | }
|
493 527 |
|
494 528 | /// Reports successful installation and enables ordered close observations.
|
495 529 | pub(super) fn opened(mut self, connection: &PoolArc<ConnectionState>) {
|
530 + | let stats = self.successful_stats.take().unwrap_or_else(|| {
|
531 + | let stats = self.timing.stats();
|
532 + | connection
|
533 + | .info()
|
534 + | .set_establishment(stats.connection_metadata());
|
535 + | stats
|
536 + | });
|
496 537 | self.finish_connection_stats();
|
497 538 | let listener = self.observation.take().map(|observation| {
|
498 - | let stats = observation.stats();
|
499 539 | observation
|
500 540 | .listener
|
501 541 | .notify(&ConnectionEvent::Opened(ConnectionOpened {
|
502 542 | establishment: &observation.info,
|
503 543 | stats: &stats,
|
504 544 | connection: connection.info(),
|
505 545 | }));
|
506 546 | observation.listener
|
507 547 | });
|
508 548 | connection.complete_opened_event(listener.as_ref());
|
509 549 | }
|
510 550 |
|
511 551 | /// Ends an establishment whose transport lost to existing HTTP/2 supply.
|
512 552 | pub(super) fn superseded(mut self) {
|
513 553 | self.finish_connection_stats();
|
514 554 | self.observation.take();
|
515 555 | }
|
516 556 |
|
517 557 | fn finish_connection_stats(&mut self) {
|
518 558 | if let Some(stats) = self.connection_stats.take() {
|
519 559 | stats.establishment_finished();
|
520 560 | }
|
521 561 | }
|
522 562 | }
|
523 563 |
|
524 564 | impl Drop for ConnectionEstablishment {
|
525 565 | fn drop(&mut self) {
|
566 + | let stats = self.successful_stats.unwrap_or_else(|| self.timing.stats());
|
526 567 | self.finish_connection_stats();
|
527 568 | let Some(observation) = self.observation.take() else {
|
528 569 | return;
|
529 570 | };
|
530 571 | let error = ConnectorError::io("connection establishment task was dropped".into());
|
531 - | observation.notify_failure(&error);
|
572 + | observation.notify_failure(&error, &stats);
|
532 573 | }
|
533 574 | }
|
534 575 |
|
535 576 | impl EstablishmentObservation {
|
536 - | fn notify_failure(&self, error: &ConnectorError) {
|
537 - | let stats = self.stats();
|
577 + | fn notify_failure(&self, error: &ConnectorError, stats: &ConnectionEstablishmentStats) {
|
538 578 | self.listener.notify(&ConnectionEvent::EstablishmentFailed(
|
539 579 | ConnectionEstablishmentFailed {
|
540 580 | establishment: &self.info,
|
541 - | stats: &stats,
|
581 + | stats,
|
542 582 | stage: self.stage,
|
543 583 | remote_addr: self.remote_addr,
|
544 584 | protocol: self.protocol,
|
545 585 | error,
|
546 586 | },
|
547 587 | ));
|
548 588 | }
|
589 + | }
|
549 590 |
|
591 + | impl EstablishmentTiming {
|
550 592 | fn stats(&self) -> ConnectionEstablishmentStats {
|
551 593 | let total_duration = self.elapsed_since(self.started_at);
|
552 594 | ConnectionEstablishmentStats {
|
553 595 | total_duration,
|
554 596 | transport_duration: self.transport_duration.unwrap_or(total_duration),
|
555 597 | protocol_handshake_duration: self.protocol_handshake_duration.or_else(|| {
|
556 598 | self.protocol_handshake_started_at
|
557 599 | .map(|started_at| self.elapsed_since(started_at))
|
558 600 | }),
|
559 601 | }
|
560 602 | }
|
561 603 |
|
562 604 | fn finish_protocol_handshake(&mut self) {
|
563 605 | self.protocol_handshake_duration = self
|
564 606 | .protocol_handshake_started_at
|
565 607 | .take()
|
566 608 | .map(|started_at| self.elapsed_since(started_at));
|
567 609 | }
|
568 610 |
|
569 611 | fn elapsed_since(&self, started_at: SystemTime) -> Duration {
|
570 612 | self.time_source
|
571 613 | .now()
|
572 614 | .duration_since(started_at)
|
573 615 | .unwrap_or_default()
|
574 616 | }
|
575 617 | }
|
576 618 |
|
577 619 | #[cfg(all(test, not(smithy_http_client_loom)))]
|
578 620 | mod tests {
|
579 621 | use super::*;
|
622 + | use aws_smithy_async::test_util::ManualTimeSource;
|
580 623 | use std::sync::atomic::AtomicUsize;
|
581 624 | use std::sync::Mutex;
|
625 + | use std::time::UNIX_EPOCH;
|
582 626 |
|
583 627 | fn origin() -> OriginKey {
|
584 628 | OriginKey::from_parts(http_1x::uri::Scheme::HTTPS, "example.com", None).unwrap()
|
585 629 | }
|
586 630 |
|
587 631 | fn events(listener: Option<SharedConnectionEventListener>) -> ConnectionEvents {
|
588 632 | ConnectionEvents::new(listener, SharedTimeSource::default())
|
589 633 | }
|
590 634 |
|
591 635 | fn establishment(events: &ConnectionEvents) -> ConnectionEstablishment {
|
695 739 | Some((
|
696 740 | ConnectionEstablishmentId(0),
|
697 741 | ConnectionEstablishmentStage::ProtocolHandshake,
|
698 742 | Some(ConnectionProtocol::Http2),
|
699 743 | true,
|
700 744 | )),
|
701 745 | *observed.lock().unwrap()
|
702 746 | );
|
703 747 | }
|
704 748 |
|
749 + | #[test]
|
750 + | fn establishment_stats_measure_recorded_phases() {
|
751 + | let time = ManualTimeSource::new(UNIX_EPOCH);
|
752 + | let observed = Arc::new(Mutex::new(None));
|
753 + | let events = ConnectionEvents::new(
|
754 + | Some(SharedConnectionEventListener::new({
|
755 + | let observed = observed.clone();
|
756 + | move |event: &ConnectionEvent<'_>| {
|
757 + | let ConnectionEvent::EstablishmentFailed(failed) = event else {
|
758 + | panic!("unexpected event: {event:?}");
|
759 + | };
|
760 + | *observed.lock().unwrap() = Some(*failed.stats());
|
761 + | }
|
762 + | })),
|
763 + | SharedTimeSource::new(time.clone()),
|
764 + | );
|
765 + | let mut establishment = establishment(&events);
|
766 + |
|
767 + | time.advance(Duration::from_secs(2));
|
768 + | establishment.transport_completed(None);
|
769 + | establishment.protocol_selected(ConnectionProtocol::Http2);
|
770 + | establishment.protocol_handshake_started();
|
771 + | time.advance(Duration::from_secs(3));
|
772 + | establishment.protocol_handshake_completed();
|
773 + | time.advance(Duration::from_secs(2));
|
774 + | establishment.failed(&ConnectorError::io("synthetic installation failure".into()));
|
775 + |
|
776 + | let stats = observed.lock().unwrap().expect("establishment stats");
|
777 + | assert_eq!(stats.total_duration(), Duration::from_secs(7));
|
778 + | assert_eq!(stats.transport_duration(), Duration::from_secs(2));
|
779 + | assert_eq!(
|
780 + | stats.protocol_handshake_duration(),
|
781 + | Some(Duration::from_secs(3))
|
782 + | );
|
783 + | let metadata = stats.connection_metadata();
|
784 + | assert_eq!(metadata.total_duration(), Duration::from_secs(7));
|
785 + | assert_eq!(metadata.transport_duration(), Duration::from_secs(2));
|
786 + | assert_eq!(
|
787 + | metadata.protocol_handshake_duration(),
|
788 + | Some(Duration::from_secs(3))
|
789 + | );
|
790 + | }
|
791 + |
|
705 792 | #[test]
|
706 793 | fn superseded_establishment_emits_no_public_event() {
|
707 794 | let observed = Arc::new(AtomicUsize::new(0));
|
708 795 | let events = events(Some(SharedConnectionEventListener::new({
|
709 796 | let observed = observed.clone();
|
710 797 | move |_: &ConnectionEvent<'_>| {
|
711 798 | observed.fetch_add(1, Ordering::Relaxed);
|
712 799 | }
|
713 800 | })));
|
714 801 |
|