Chromium Code Reviews
chromiumcodereview-hr@appspot.gserviceaccount.com (chromiumcodereview-hr) | Please choose your nickname with Settings | Help | Chromium Project | Gerrit Changes | Sign out
(331)

Side by Side Diff: net/quic/core/quic_connection.cc

Issue 2611613003: Add quic_logging (Closed)
Patch Set: fix failed test? Created 3 years, 11 months ago
Use n/p to move between diff chunks; N/P to move between comments. Draft comments are only viewable by you.
Jump to:
View unified diff | Download patch
« no previous file with comments | « net/quic/core/quic_connection.h ('k') | net/quic/core/quic_connection_test.cc » ('j') | no next file with comments »
Toggle Intra-line Diffs ('i') | Expand Comments ('e') | Collapse Comments ('c') | Show Comments Hide Comments ('s')
OLDNEW
1 // Copyright (c) 2012 The Chromium Authors. All rights reserved. 1 // Copyright (c) 2012 The Chromium Authors. All rights reserved.
2 // Use of this source code is governed by a BSD-style license that can be 2 // Use of this source code is governed by a BSD-style license that can be
3 // found in the LICENSE file. 3 // found in the LICENSE file.
4 4
5 #include "net/quic/core/quic_connection.h" 5 #include "net/quic/core/quic_connection.h"
6 6
7 #include <string.h> 7 #include <string.h>
8 #include <sys/types.h> 8 #include <sys/types.h>
9 9
10 #include <algorithm> 10 #include <algorithm>
11 #include <iterator> 11 #include <iterator>
12 #include <limits> 12 #include <limits>
13 #include <memory> 13 #include <memory>
14 #include <set> 14 #include <set>
15 #include <utility> 15 #include <utility>
16 16
17 #include "base/format_macros.h" 17 #include "base/format_macros.h"
18 #include "base/logging.h"
19 #include "base/macros.h" 18 #include "base/macros.h"
20 #include "base/metrics/histogram_macros.h" 19 #include "base/metrics/histogram_macros.h"
21 #include "base/stl_util.h" 20 #include "base/stl_util.h"
22 #include "net/base/address_family.h" 21 #include "net/base/address_family.h"
23 #include "net/base/ip_address.h" 22 #include "net/base/ip_address.h"
24 #include "net/base/net_errors.h" 23 #include "net/base/net_errors.h"
25 #include "net/quic/core/crypto/crypto_protocol.h" 24 #include "net/quic/core/crypto/crypto_protocol.h"
26 #include "net/quic/core/crypto/quic_decrypter.h" 25 #include "net/quic/core/crypto/quic_decrypter.h"
27 #include "net/quic/core/crypto/quic_encrypter.h" 26 #include "net/quic/core/crypto/quic_encrypter.h"
28 #include "net/quic/core/proto/cached_network_parameters.pb.h" 27 #include "net/quic/core/proto/cached_network_parameters.pb.h"
29 #include "net/quic/core/quic_bandwidth.h" 28 #include "net/quic/core/quic_bandwidth.h"
30 #include "net/quic/core/quic_config.h" 29 #include "net/quic/core/quic_config.h"
31 #include "net/quic/core/quic_flags.h" 30 #include "net/quic/core/quic_flags.h"
32 #include "net/quic/core/quic_packet_generator.h" 31 #include "net/quic/core/quic_packet_generator.h"
33 #include "net/quic/core/quic_pending_retransmission.h" 32 #include "net/quic/core/quic_pending_retransmission.h"
34 #include "net/quic/core/quic_sent_packet_manager.h" 33 #include "net/quic/core/quic_sent_packet_manager.h"
35 #include "net/quic/core/quic_utils.h" 34 #include "net/quic/core/quic_utils.h"
36 #include "net/quic/platform/api/quic_bug_tracker.h" 35 #include "net/quic/platform/api/quic_bug_tracker.h"
36 #include "net/quic/platform/api/quic_logging.h"
37 #include "net/quic/platform/api/quic_str_cat.h" 37 #include "net/quic/platform/api/quic_str_cat.h"
38 #include "net/quic/platform/api/quic_text_utils.h" 38 #include "net/quic/platform/api/quic_text_utils.h"
39 39
40 using base::StringPiece; 40 using base::StringPiece;
41 using std::string; 41 using std::string;
42 42
43 namespace net { 43 namespace net {
44 44
45 class QuicDecrypter; 45 class QuicDecrypter;
46 class QuicEncrypter; 46 class QuicEncrypter;
(...skipping 217 matching lines...) Expand 10 before | Expand all | Expand 10 after
264 can_truncate_connection_ids_(true), 264 can_truncate_connection_ids_(true),
265 mtu_discovery_target_(0), 265 mtu_discovery_target_(0),
266 mtu_probe_count_(0), 266 mtu_probe_count_(0),
267 packets_between_mtu_probes_(kPacketsBetweenMtuProbesBase), 267 packets_between_mtu_probes_(kPacketsBetweenMtuProbesBase),
268 next_mtu_probe_at_(kPacketsBetweenMtuProbesBase), 268 next_mtu_probe_at_(kPacketsBetweenMtuProbesBase),
269 largest_received_packet_size_(0), 269 largest_received_packet_size_(0),
270 goaway_sent_(false), 270 goaway_sent_(false),
271 goaway_received_(false), 271 goaway_received_(false),
272 multipath_enabled_(false), 272 multipath_enabled_(false),
273 write_error_occured_(false) { 273 write_error_occured_(false) {
274 DVLOG(1) << ENDPOINT 274 QUIC_DLOG(INFO) << ENDPOINT
275 << "Created connection with connection_id: " << connection_id; 275 << "Created connection with connection_id: " << connection_id;
276 framer_.set_visitor(this); 276 framer_.set_visitor(this);
277 if (!FLAGS_quic_reloadable_flag_quic_receive_packet_once_decrypted) { 277 if (!FLAGS_quic_reloadable_flag_quic_receive_packet_once_decrypted) {
278 last_stop_waiting_frame_.least_unacked = 0; 278 last_stop_waiting_frame_.least_unacked = 0;
279 } 279 }
280 stats_.connection_creation_time = clock_->ApproximateNow(); 280 stats_.connection_creation_time = clock_->ApproximateNow();
281 if (FLAGS_quic_reloadable_flag_quic_enable_multipath) { 281 if (FLAGS_quic_reloadable_flag_quic_enable_multipath) {
282 sent_packet_manager_.reset(new QuicMultipathSentPacketManager( 282 sent_packet_manager_.reset(new QuicMultipathSentPacketManager(
283 sent_packet_manager_.release(), this)); 283 sent_packet_manager_.release(), this));
284 } 284 }
285 // TODO(ianswett): Supply the NetworkChangeVisitor as a constructor argument 285 // TODO(ianswett): Supply the NetworkChangeVisitor as a constructor argument
(...skipping 143 matching lines...) Expand 10 before | Expand all | Expand 10 after
429 429
430 void QuicConnection::OnPublicResetPacket(const QuicPublicResetPacket& packet) { 430 void QuicConnection::OnPublicResetPacket(const QuicPublicResetPacket& packet) {
431 // Check that any public reset packet with a different connection ID that was 431 // Check that any public reset packet with a different connection ID that was
432 // routed to this QuicConnection has been redirected before control reaches 432 // routed to this QuicConnection has been redirected before control reaches
433 // here. (Check for a bug regression.) 433 // here. (Check for a bug regression.)
434 DCHECK_EQ(connection_id_, packet.public_header.connection_id); 434 DCHECK_EQ(connection_id_, packet.public_header.connection_id);
435 if (debug_visitor_ != nullptr) { 435 if (debug_visitor_ != nullptr) {
436 debug_visitor_->OnPublicResetPacket(packet); 436 debug_visitor_->OnPublicResetPacket(packet);
437 } 437 }
438 const string error_details = "Received public reset."; 438 const string error_details = "Received public reset.";
439 DVLOG(1) << ENDPOINT << error_details; 439 QUIC_DLOG(INFO) << ENDPOINT << error_details;
440 TearDownLocalConnectionState(QUIC_PUBLIC_RESET, error_details, 440 TearDownLocalConnectionState(QUIC_PUBLIC_RESET, error_details,
441 ConnectionCloseSource::FROM_PEER); 441 ConnectionCloseSource::FROM_PEER);
442 } 442 }
443 443
444 bool QuicConnection::OnProtocolVersionMismatch(QuicVersion received_version) { 444 bool QuicConnection::OnProtocolVersionMismatch(QuicVersion received_version) {
445 DVLOG(1) << ENDPOINT << "Received packet with mismatched version " 445 QUIC_DLOG(INFO) << ENDPOINT << "Received packet with mismatched version "
446 << received_version; 446 << received_version;
447 // TODO(satyamshekhar): Implement no server state in this mode. 447 // TODO(satyamshekhar): Implement no server state in this mode.
448 if (perspective_ == Perspective::IS_CLIENT) { 448 if (perspective_ == Perspective::IS_CLIENT) {
449 const string error_details = "Protocol version mismatch."; 449 const string error_details = "Protocol version mismatch.";
450 QUIC_BUG << ENDPOINT << error_details; 450 QUIC_BUG << ENDPOINT << error_details;
451 TearDownLocalConnectionState(QUIC_INTERNAL_ERROR, error_details, 451 TearDownLocalConnectionState(QUIC_INTERNAL_ERROR, error_details,
452 ConnectionCloseSource::FROM_SELF); 452 ConnectionCloseSource::FROM_SELF);
453 return false; 453 return false;
454 } 454 }
455 DCHECK_NE(version(), received_version); 455 DCHECK_NE(version(), received_version);
456 456
(...skipping 24 matching lines...) Expand all
481 481
482 default: 482 default:
483 DCHECK(false); 483 DCHECK(false);
484 } 484 }
485 485
486 version_negotiation_state_ = NEGOTIATED_VERSION; 486 version_negotiation_state_ = NEGOTIATED_VERSION;
487 visitor_->OnSuccessfulVersionNegotiation(received_version); 487 visitor_->OnSuccessfulVersionNegotiation(received_version);
488 if (debug_visitor_ != nullptr) { 488 if (debug_visitor_ != nullptr) {
489 debug_visitor_->OnSuccessfulVersionNegotiation(received_version); 489 debug_visitor_->OnSuccessfulVersionNegotiation(received_version);
490 } 490 }
491 DVLOG(1) << ENDPOINT << "version negotiated " << received_version; 491 QUIC_DLOG(INFO) << ENDPOINT << "version negotiated " << received_version;
492 492
493 // Store the new version. 493 // Store the new version.
494 framer_.set_version(received_version); 494 framer_.set_version(received_version);
495 495
496 // TODO(satyamshekhar): Store the packet number of this packet and close the 496 // TODO(satyamshekhar): Store the packet number of this packet and close the
497 // connection if we ever received a packet with incorrect version and whose 497 // connection if we ever received a packet with incorrect version and whose
498 // packet number is greater. 498 // packet number is greater.
499 return true; 499 return true;
500 } 500 }
501 501
(...skipping 17 matching lines...) Expand all
519 519
520 if (version_negotiation_state_ != START_NEGOTIATION) { 520 if (version_negotiation_state_ != START_NEGOTIATION) {
521 // Possibly a duplicate version negotiation packet. 521 // Possibly a duplicate version negotiation packet.
522 return; 522 return;
523 } 523 }
524 524
525 if (base::ContainsValue(packet.versions, version())) { 525 if (base::ContainsValue(packet.versions, version())) {
526 const string error_details = 526 const string error_details =
527 "Server already supports client's version and should have accepted the " 527 "Server already supports client's version and should have accepted the "
528 "connection."; 528 "connection.";
529 DLOG(WARNING) << error_details; 529 QUIC_DLOG(WARNING) << error_details;
530 TearDownLocalConnectionState(QUIC_INVALID_VERSION_NEGOTIATION_PACKET, 530 TearDownLocalConnectionState(QUIC_INVALID_VERSION_NEGOTIATION_PACKET,
531 error_details, 531 error_details,
532 ConnectionCloseSource::FROM_SELF); 532 ConnectionCloseSource::FROM_SELF);
533 return; 533 return;
534 } 534 }
535 535
536 if (!SelectMutualVersion(packet.versions)) { 536 if (!SelectMutualVersion(packet.versions)) {
537 CloseConnection( 537 CloseConnection(
538 QUIC_INVALID_VERSION, 538 QUIC_INVALID_VERSION,
539 QuicStrCat("No common version found. Supported versions: {", 539 QuicStrCat("No common version found. Supported versions: {",
540 QuicVersionVectorToString(framer_.supported_versions()), 540 QuicVersionVectorToString(framer_.supported_versions()),
541 "}, peer supported versions: {", 541 "}, peer supported versions: {",
542 QuicVersionVectorToString(packet.versions), "}"), 542 QuicVersionVectorToString(packet.versions), "}"),
543 ConnectionCloseBehavior::SEND_CONNECTION_CLOSE_PACKET); 543 ConnectionCloseBehavior::SEND_CONNECTION_CLOSE_PACKET);
544 return; 544 return;
545 } 545 }
546 546
547 DVLOG(1) << ENDPOINT 547 QUIC_DLOG(INFO) << ENDPOINT
548 << "Negotiated version: " << QuicVersionToString(version()); 548 << "Negotiated version: " << QuicVersionToString(version());
549 server_supported_versions_ = packet.versions; 549 server_supported_versions_ = packet.versions;
550 version_negotiation_state_ = NEGOTIATION_IN_PROGRESS; 550 version_negotiation_state_ = NEGOTIATION_IN_PROGRESS;
551 RetransmitUnackedPackets(ALL_UNACKED_RETRANSMISSION); 551 RetransmitUnackedPackets(ALL_UNACKED_RETRANSMISSION);
552 } 552 }
553 553
554 bool QuicConnection::OnUnauthenticatedPublicHeader( 554 bool QuicConnection::OnUnauthenticatedPublicHeader(
555 const QuicPacketPublicHeader& header) { 555 const QuicPacketPublicHeader& header) {
556 if (header.connection_id == connection_id_) { 556 if (header.connection_id == connection_id_) {
557 return true; 557 return true;
558 } 558 }
559 559
560 ++stats_.packets_dropped; 560 ++stats_.packets_dropped;
561 DVLOG(1) << ENDPOINT << "Ignoring packet from unexpected ConnectionId: " 561 QUIC_DLOG(INFO) << ENDPOINT
562 << header.connection_id << " instead of " << connection_id_; 562 << "Ignoring packet from unexpected ConnectionId: "
563 << header.connection_id << " instead of " << connection_id_;
563 if (debug_visitor_ != nullptr) { 564 if (debug_visitor_ != nullptr) {
564 debug_visitor_->OnIncorrectConnectionId(header.connection_id); 565 debug_visitor_->OnIncorrectConnectionId(header.connection_id);
565 } 566 }
566 // If this is a server, the dispatcher routes each packet to the 567 // If this is a server, the dispatcher routes each packet to the
567 // QuicConnection responsible for the packet's connection ID. So if control 568 // QuicConnection responsible for the packet's connection ID. So if control
568 // arrives here and this is a server, the dispatcher must be malfunctioning. 569 // arrives here and this is a server, the dispatcher must be malfunctioning.
569 DCHECK_NE(Perspective::IS_SERVER, perspective_); 570 DCHECK_NE(Perspective::IS_SERVER, perspective_);
570 return false; 571 return false;
571 } 572 }
572 573
(...skipping 14 matching lines...) Expand all
587 "processed."; 588 "processed.";
588 QUIC_BUG << error_details; 589 QUIC_BUG << error_details;
589 CloseConnection(QUIC_INTERNAL_ERROR, error_details, 590 CloseConnection(QUIC_INTERNAL_ERROR, error_details,
590 ConnectionCloseBehavior::SEND_CONNECTION_CLOSE_PACKET); 591 ConnectionCloseBehavior::SEND_CONNECTION_CLOSE_PACKET);
591 return false; 592 return false;
592 } 593 }
593 594
594 // If this packet has already been seen, or the sender has told us that it 595 // If this packet has already been seen, or the sender has told us that it
595 // will not be retransmitted, then stop processing the packet. 596 // will not be retransmitted, then stop processing the packet.
596 if (!received_packet_manager_.IsAwaitingPacket(header.packet_number)) { 597 if (!received_packet_manager_.IsAwaitingPacket(header.packet_number)) {
597 DVLOG(1) << ENDPOINT << "Packet " << header.packet_number 598 QUIC_DLOG(INFO) << ENDPOINT << "Packet " << header.packet_number
598 << " no longer being waited for. Discarding."; 599 << " no longer being waited for. Discarding.";
599 if (debug_visitor_ != nullptr) { 600 if (debug_visitor_ != nullptr) {
600 debug_visitor_->OnDuplicatePacket(header.packet_number); 601 debug_visitor_->OnDuplicatePacket(header.packet_number);
601 } 602 }
602 ++stats_.packets_dropped; 603 ++stats_.packets_dropped;
603 return false; 604 return false;
604 } 605 }
605 606
606 return true; 607 return true;
607 } 608 }
608 609
(...skipping 27 matching lines...) Expand all
636 last_packet_source_address_); 637 last_packet_source_address_);
637 // Do not migrate connection if the changed address packet is a reordered 638 // Do not migrate connection if the changed address packet is a reordered
638 // packet. 639 // packet.
639 if (active_peer_migration_type_ == NO_CHANGE && 640 if (active_peer_migration_type_ == NO_CHANGE &&
640 peer_migration_type != NO_CHANGE && 641 peer_migration_type != NO_CHANGE &&
641 header.packet_number > received_packet_manager_.GetLargestObserved()) { 642 header.packet_number > received_packet_manager_.GetLargestObserved()) {
642 StartPeerMigration(header.path_id, peer_migration_type); 643 StartPeerMigration(header.path_id, peer_migration_type);
643 } 644 }
644 645
645 --stats_.packets_dropped; 646 --stats_.packets_dropped;
646 DVLOG(1) << ENDPOINT << "Received packet header: " << header; 647 QUIC_DVLOG(1) << ENDPOINT << "Received packet header: " << header;
647 last_header_ = header; 648 last_header_ = header;
648 if (FLAGS_quic_reloadable_flag_quic_receive_packet_once_decrypted) { 649 if (FLAGS_quic_reloadable_flag_quic_receive_packet_once_decrypted) {
649 // An ack will be sent if a missing retransmittable packet was received; 650 // An ack will be sent if a missing retransmittable packet was received;
650 was_last_packet_missing_ = 651 was_last_packet_missing_ =
651 received_packet_manager_.IsMissing(last_header_.packet_number); 652 received_packet_manager_.IsMissing(last_header_.packet_number);
652 653
653 // Record received to populate ack info correctly before processing stream 654 // Record received to populate ack info correctly before processing stream
654 // frames, since the processing may result in a response packet with a 655 // frames, since the processing may result in a response packet with a
655 // bundled ack. 656 // bundled ack.
656 received_packet_manager_.RecordPacketReceived( 657 received_packet_manager_.RecordPacketReceived(
(...skipping 32 matching lines...) Expand 10 before | Expand all | Expand 10 after
689 stats_.stream_bytes_received += frame.data_length; 690 stats_.stream_bytes_received += frame.data_length;
690 should_last_packet_instigate_acks_ = true; 691 should_last_packet_instigate_acks_ = true;
691 return connected_; 692 return connected_;
692 } 693 }
693 694
694 bool QuicConnection::OnAckFrame(const QuicAckFrame& incoming_ack) { 695 bool QuicConnection::OnAckFrame(const QuicAckFrame& incoming_ack) {
695 DCHECK(connected_); 696 DCHECK(connected_);
696 if (debug_visitor_ != nullptr) { 697 if (debug_visitor_ != nullptr) {
697 debug_visitor_->OnAckFrame(incoming_ack); 698 debug_visitor_->OnAckFrame(incoming_ack);
698 } 699 }
699 DVLOG(1) << ENDPOINT << "OnAckFrame: " << incoming_ack; 700 QUIC_DVLOG(1) << ENDPOINT << "OnAckFrame: " << incoming_ack;
700 701
701 if (last_header_.packet_number <= largest_seen_packet_with_ack_) { 702 if (last_header_.packet_number <= largest_seen_packet_with_ack_) {
702 DVLOG(1) << ENDPOINT << "Received an old ack frame: ignoring"; 703 QUIC_DLOG(INFO) << ENDPOINT << "Received an old ack frame: ignoring";
703 return true; 704 return true;
704 } 705 }
705 706
706 const char* error = ValidateAckFrame(incoming_ack); 707 const char* error = ValidateAckFrame(incoming_ack);
707 if (error != nullptr) { 708 if (error != nullptr) {
708 CloseConnection(QUIC_INVALID_ACK_DATA, error, 709 CloseConnection(QUIC_INVALID_ACK_DATA, error,
709 ConnectionCloseBehavior::SEND_CONNECTION_CLOSE_PACKET); 710 ConnectionCloseBehavior::SEND_CONNECTION_CLOSE_PACKET);
710 return false; 711 return false;
711 } 712 }
712 713
(...skipping 29 matching lines...) Expand all
742 void QuicConnection::ProcessStopWaitingFrame( 743 void QuicConnection::ProcessStopWaitingFrame(
743 const QuicStopWaitingFrame& stop_waiting) { 744 const QuicStopWaitingFrame& stop_waiting) {
744 largest_seen_packet_with_stop_waiting_ = last_header_.packet_number; 745 largest_seen_packet_with_stop_waiting_ = last_header_.packet_number;
745 received_packet_manager_.UpdatePacketInformationSentByPeer(stop_waiting); 746 received_packet_manager_.UpdatePacketInformationSentByPeer(stop_waiting);
746 } 747 }
747 748
748 bool QuicConnection::OnStopWaitingFrame(const QuicStopWaitingFrame& frame) { 749 bool QuicConnection::OnStopWaitingFrame(const QuicStopWaitingFrame& frame) {
749 DCHECK(connected_); 750 DCHECK(connected_);
750 751
751 if (last_header_.packet_number <= largest_seen_packet_with_stop_waiting_) { 752 if (last_header_.packet_number <= largest_seen_packet_with_stop_waiting_) {
752 DVLOG(1) << ENDPOINT << "Received an old stop waiting frame: ignoring"; 753 QUIC_DLOG(INFO) << ENDPOINT
754 << "Received an old stop waiting frame: ignoring";
753 return true; 755 return true;
754 } 756 }
755 757
756 const char* error = ValidateStopWaitingFrame(frame); 758 const char* error = ValidateStopWaitingFrame(frame);
757 if (error != nullptr) { 759 if (error != nullptr) {
758 CloseConnection(QUIC_INVALID_STOP_WAITING_DATA, error, 760 CloseConnection(QUIC_INVALID_STOP_WAITING_DATA, error,
759 ConnectionCloseBehavior::SEND_CONNECTION_CLOSE_PACKET); 761 ConnectionCloseBehavior::SEND_CONNECTION_CLOSE_PACKET);
760 return false; 762 return false;
761 } 763 }
762 764
(...skipping 21 matching lines...) Expand all
784 DCHECK(connected_); 786 DCHECK(connected_);
785 if (debug_visitor_ != nullptr) { 787 if (debug_visitor_ != nullptr) {
786 debug_visitor_->OnPingFrame(frame); 788 debug_visitor_->OnPingFrame(frame);
787 } 789 }
788 should_last_packet_instigate_acks_ = true; 790 should_last_packet_instigate_acks_ = true;
789 return true; 791 return true;
790 } 792 }
791 793
792 const char* QuicConnection::ValidateAckFrame(const QuicAckFrame& incoming_ack) { 794 const char* QuicConnection::ValidateAckFrame(const QuicAckFrame& incoming_ack) {
793 if (incoming_ack.largest_observed > packet_generator_.packet_number()) { 795 if (incoming_ack.largest_observed > packet_generator_.packet_number()) {
794 DLOG(WARNING) << ENDPOINT << "Peer's observed unsent packet:" 796 QUIC_DLOG(WARNING) << ENDPOINT << "Peer's observed unsent packet:"
795 << incoming_ack.largest_observed << " vs " 797 << incoming_ack.largest_observed << " vs "
796 << packet_generator_.packet_number(); 798 << packet_generator_.packet_number();
797 // We got an error for data we have not sent. Error out. 799 // We got an error for data we have not sent. Error out.
798 return "Largest observed too high."; 800 return "Largest observed too high.";
799 } 801 }
800 802
801 if (incoming_ack.largest_observed < 803 if (incoming_ack.largest_observed <
802 sent_packet_manager_->GetLargestObserved(incoming_ack.path_id)) { 804 sent_packet_manager_->GetLargestObserved(incoming_ack.path_id)) {
803 VLOG(1) << ENDPOINT << "Peer's largest_observed packet decreased:" 805 QUIC_LOG(INFO) << ENDPOINT << "Peer's largest_observed packet decreased:"
804 << incoming_ack.largest_observed << " vs " 806 << incoming_ack.largest_observed << " vs "
805 << sent_packet_manager_->GetLargestObserved(incoming_ack.path_id) 807 << sent_packet_manager_->GetLargestObserved(
806 << " packet_number:" << last_header_.packet_number 808 incoming_ack.path_id)
807 << " largest seen with ack:" << largest_seen_packet_with_ack_ 809 << " packet_number:" << last_header_.packet_number
808 << " connection_id: " << connection_id_; 810 << " largest seen with ack:" << largest_seen_packet_with_ack_
811 << " connection_id: " << connection_id_;
809 // A new ack has a diminished largest_observed value. Error out. 812 // A new ack has a diminished largest_observed value. Error out.
810 // If this was an old packet, we wouldn't even have checked. 813 // If this was an old packet, we wouldn't even have checked.
811 return "Largest observed too low."; 814 return "Largest observed too low.";
812 } 815 }
813 816
814 if (!incoming_ack.packets.Empty() && 817 if (!incoming_ack.packets.Empty() &&
815 incoming_ack.packets.Max() != incoming_ack.largest_observed) { 818 incoming_ack.packets.Max() != incoming_ack.largest_observed) {
816 QUIC_BUG << ENDPOINT 819 QUIC_BUG << ENDPOINT
817 << "Peer last received packet: " << incoming_ack.packets.Max() 820 << "Peer last received packet: " << incoming_ack.packets.Max()
818 << " which is not equal to largest observed: " 821 << " which is not equal to largest observed: "
819 << incoming_ack.largest_observed; 822 << incoming_ack.largest_observed;
820 return "Last received packet not equal to largest observed."; 823 return "Last received packet not equal to largest observed.";
821 } 824 }
822 825
823 return nullptr; 826 return nullptr;
824 } 827 }
825 828
826 const char* QuicConnection::ValidateStopWaitingFrame( 829 const char* QuicConnection::ValidateStopWaitingFrame(
827 const QuicStopWaitingFrame& stop_waiting) { 830 const QuicStopWaitingFrame& stop_waiting) {
828 if (stop_waiting.least_unacked < 831 if (stop_waiting.least_unacked <
829 received_packet_manager_.peer_least_packet_awaiting_ack()) { 832 received_packet_manager_.peer_least_packet_awaiting_ack()) {
830 DLOG(ERROR) << ENDPOINT << "Peer's sent low least_unacked: " 833 QUIC_DLOG(ERROR)
831 << stop_waiting.least_unacked << " vs " 834 << ENDPOINT
832 << received_packet_manager_.peer_least_packet_awaiting_ack(); 835 << "Peer's sent low least_unacked: " << stop_waiting.least_unacked
836 << " vs " << received_packet_manager_.peer_least_packet_awaiting_ack();
833 // We never process old ack frames, so this number should only increase. 837 // We never process old ack frames, so this number should only increase.
834 return "Least unacked too small."; 838 return "Least unacked too small.";
835 } 839 }
836 840
837 if (stop_waiting.least_unacked > last_header_.packet_number) { 841 if (stop_waiting.least_unacked > last_header_.packet_number) {
838 DLOG(ERROR) << ENDPOINT 842 QUIC_DLOG(ERROR) << ENDPOINT
839 << "Peer sent least_unacked:" << stop_waiting.least_unacked 843 << "Peer sent least_unacked:" << stop_waiting.least_unacked
840 << " greater than the enclosing packet number:" 844 << " greater than the enclosing packet number:"
841 << last_header_.packet_number; 845 << last_header_.packet_number;
842 return "Least unacked too large."; 846 return "Least unacked too large.";
843 } 847 }
844 848
845 return nullptr; 849 return nullptr;
846 } 850 }
847 851
848 bool QuicConnection::OnRstStreamFrame(const QuicRstStreamFrame& frame) { 852 bool QuicConnection::OnRstStreamFrame(const QuicRstStreamFrame& frame) {
849 DCHECK(connected_); 853 DCHECK(connected_);
850 if (debug_visitor_ != nullptr) { 854 if (debug_visitor_ != nullptr) {
851 debug_visitor_->OnRstStreamFrame(frame); 855 debug_visitor_->OnRstStreamFrame(frame);
852 } 856 }
853 DVLOG(1) << ENDPOINT 857 QUIC_DLOG(INFO) << ENDPOINT
854 << "RST_STREAM_FRAME received for stream: " << frame.stream_id 858 << "RST_STREAM_FRAME received for stream: " << frame.stream_id
855 << " with error: " 859 << " with error: "
856 << QuicRstStreamErrorCodeToString(frame.error_code); 860 << QuicRstStreamErrorCodeToString(frame.error_code);
857 visitor_->OnRstStream(frame); 861 visitor_->OnRstStream(frame);
858 visitor_->PostProcessAfterData(); 862 visitor_->PostProcessAfterData();
859 should_last_packet_instigate_acks_ = true; 863 should_last_packet_instigate_acks_ = true;
860 return connected_; 864 return connected_;
861 } 865 }
862 866
863 bool QuicConnection::OnConnectionCloseFrame( 867 bool QuicConnection::OnConnectionCloseFrame(
864 const QuicConnectionCloseFrame& frame) { 868 const QuicConnectionCloseFrame& frame) {
865 DCHECK(connected_); 869 DCHECK(connected_);
866 if (debug_visitor_ != nullptr) { 870 if (debug_visitor_ != nullptr) {
867 debug_visitor_->OnConnectionCloseFrame(frame); 871 debug_visitor_->OnConnectionCloseFrame(frame);
868 } 872 }
869 DVLOG(1) << ENDPOINT 873 QUIC_DLOG(INFO) << ENDPOINT << "Received ConnectionClose for connection: "
870 << "Received ConnectionClose for connection: " << connection_id() 874 << connection_id()
871 << ", with error: " << QuicErrorCodeToString(frame.error_code) 875 << ", with error: " << QuicErrorCodeToString(frame.error_code)
872 << " (" << frame.error_details << ")"; 876 << " (" << frame.error_details << ")";
873 if (frame.error_code == QUIC_BAD_MULTIPATH_FLAG) { 877 if (frame.error_code == QUIC_BAD_MULTIPATH_FLAG) {
874 LOG(ERROR) << "Unexpected QUIC_BAD_MULTIPATH_FLAG error." 878 QUIC_LOG_FIRST_N(ERROR, 10) << "Unexpected QUIC_BAD_MULTIPATH_FLAG error."
875 << " last_received_header: " << last_header_ 879 << " last_received_header: " << last_header_
876 << " encryption_level: " << encryption_level_; 880 << " encryption_level: " << encryption_level_;
877 } 881 }
878 TearDownLocalConnectionState(frame.error_code, frame.error_details, 882 TearDownLocalConnectionState(frame.error_code, frame.error_details,
879 ConnectionCloseSource::FROM_PEER); 883 ConnectionCloseSource::FROM_PEER);
880 return connected_; 884 return connected_;
881 } 885 }
882 886
883 bool QuicConnection::OnGoAwayFrame(const QuicGoAwayFrame& frame) { 887 bool QuicConnection::OnGoAwayFrame(const QuicGoAwayFrame& frame) {
884 DCHECK(connected_); 888 DCHECK(connected_);
885 if (debug_visitor_ != nullptr) { 889 if (debug_visitor_ != nullptr) {
886 debug_visitor_->OnGoAwayFrame(frame); 890 debug_visitor_->OnGoAwayFrame(frame);
887 } 891 }
888 DVLOG(1) << ENDPOINT << "GOAWAY_FRAME received with last good stream: " 892 QUIC_DLOG(INFO) << ENDPOINT << "GOAWAY_FRAME received with last good stream: "
889 << frame.last_good_stream_id 893 << frame.last_good_stream_id
890 << " and error: " << QuicErrorCodeToString(frame.error_code) 894 << " and error: " << QuicErrorCodeToString(frame.error_code)
891 << " and reason: " << frame.reason_phrase; 895 << " and reason: " << frame.reason_phrase;
892 896
893 goaway_received_ = true; 897 goaway_received_ = true;
894 visitor_->OnGoAway(frame); 898 visitor_->OnGoAway(frame);
895 visitor_->PostProcessAfterData(); 899 visitor_->PostProcessAfterData();
896 should_last_packet_instigate_acks_ = true; 900 should_last_packet_instigate_acks_ = true;
897 return connected_; 901 return connected_;
898 } 902 }
899 903
900 bool QuicConnection::OnWindowUpdateFrame(const QuicWindowUpdateFrame& frame) { 904 bool QuicConnection::OnWindowUpdateFrame(const QuicWindowUpdateFrame& frame) {
901 DCHECK(connected_); 905 DCHECK(connected_);
902 if (debug_visitor_ != nullptr) { 906 if (debug_visitor_ != nullptr) {
903 debug_visitor_->OnWindowUpdateFrame(frame); 907 debug_visitor_->OnWindowUpdateFrame(frame);
904 } 908 }
905 DVLOG(1) << ENDPOINT 909 QUIC_DLOG(INFO) << ENDPOINT << "WINDOW_UPDATE_FRAME received for stream: "
906 << "WINDOW_UPDATE_FRAME received for stream: " << frame.stream_id 910 << frame.stream_id
907 << " with byte offset: " << frame.byte_offset; 911 << " with byte offset: " << frame.byte_offset;
908 visitor_->OnWindowUpdateFrame(frame); 912 visitor_->OnWindowUpdateFrame(frame);
909 visitor_->PostProcessAfterData(); 913 visitor_->PostProcessAfterData();
910 should_last_packet_instigate_acks_ = true; 914 should_last_packet_instigate_acks_ = true;
911 return connected_; 915 return connected_;
912 } 916 }
913 917
914 bool QuicConnection::OnBlockedFrame(const QuicBlockedFrame& frame) { 918 bool QuicConnection::OnBlockedFrame(const QuicBlockedFrame& frame) {
915 DCHECK(connected_); 919 DCHECK(connected_);
916 if (debug_visitor_ != nullptr) { 920 if (debug_visitor_ != nullptr) {
917 debug_visitor_->OnBlockedFrame(frame); 921 debug_visitor_->OnBlockedFrame(frame);
918 } 922 }
919 DVLOG(1) << ENDPOINT 923 QUIC_DLOG(INFO) << ENDPOINT
920 << "BLOCKED_FRAME received for stream: " << frame.stream_id; 924 << "BLOCKED_FRAME received for stream: " << frame.stream_id;
921 visitor_->OnBlockedFrame(frame); 925 visitor_->OnBlockedFrame(frame);
922 visitor_->PostProcessAfterData(); 926 visitor_->PostProcessAfterData();
923 stats_.blocked_frames_received++; 927 stats_.blocked_frames_received++;
924 should_last_packet_instigate_acks_ = true; 928 should_last_packet_instigate_acks_ = true;
925 return connected_; 929 return connected_;
926 } 930 }
927 931
928 bool QuicConnection::OnPathCloseFrame(const QuicPathCloseFrame& frame) { 932 bool QuicConnection::OnPathCloseFrame(const QuicPathCloseFrame& frame) {
929 DCHECK(connected_); 933 DCHECK(connected_);
930 if (debug_visitor_ != nullptr) { 934 if (debug_visitor_ != nullptr) {
931 debug_visitor_->OnPathCloseFrame(frame); 935 debug_visitor_->OnPathCloseFrame(frame);
932 } 936 }
933 DVLOG(1) << ENDPOINT 937 QUIC_DLOG(INFO) << ENDPOINT
934 << "PATH_CLOSE_FRAME received for path: " << frame.path_id; 938 << "PATH_CLOSE_FRAME received for path: " << frame.path_id;
935 OnPathClosed(frame.path_id); 939 OnPathClosed(frame.path_id);
936 return connected_; 940 return connected_;
937 } 941 }
938 942
939 void QuicConnection::OnPacketComplete() { 943 void QuicConnection::OnPacketComplete() {
940 // Don't do anything if this packet closed the connection. 944 // Don't do anything if this packet closed the connection.
941 if (!connected_) { 945 if (!connected_) {
942 ClearLastFrames(); 946 ClearLastFrames();
943 return; 947 return;
944 } 948 }
945 949
946 DVLOG(1) << ENDPOINT << "Got packet " << last_header_.packet_number << " for " 950 QUIC_DVLOG(1) << ENDPOINT << "Got packet " << last_header_.packet_number
947 << last_header_.public_header.connection_id; 951 << " for " << last_header_.public_header.connection_id;
948 952
949 if (FLAGS_quic_reloadable_flag_quic_receive_packet_once_decrypted) { 953 if (FLAGS_quic_reloadable_flag_quic_receive_packet_once_decrypted) {
950 // An ack will be sent if a missing retransmittable packet was received; 954 // An ack will be sent if a missing retransmittable packet was received;
951 const bool was_missing = 955 const bool was_missing =
952 should_last_packet_instigate_acks_ && was_last_packet_missing_; 956 should_last_packet_instigate_acks_ && was_last_packet_missing_;
953 957
954 // It's possible the ack frame was sent along with response data, so it 958 // It's possible the ack frame was sent along with response data, so it
955 // no longer needs to be sent. 959 // no longer needs to be sent.
956 if (ack_frame_updated()) { 960 if (ack_frame_updated()) {
957 MaybeQueueAck(was_missing); 961 MaybeQueueAck(was_missing);
(...skipping 122 matching lines...) Expand 10 before | Expand all | Expand 10 after
1080 WriteAndBundleAcksIfNotBlocked(); 1084 WriteAndBundleAcksIfNotBlocked();
1081 } 1085 }
1082 } 1086 }
1083 1087
1084 void QuicConnection::SendVersionNegotiationPacket() { 1088 void QuicConnection::SendVersionNegotiationPacket() {
1085 pending_version_negotiation_packet_ = true; 1089 pending_version_negotiation_packet_ = true;
1086 if (writer_->IsWriteBlocked()) { 1090 if (writer_->IsWriteBlocked()) {
1087 visitor_->OnWriteBlocked(); 1091 visitor_->OnWriteBlocked();
1088 return; 1092 return;
1089 } 1093 }
1090 DVLOG(1) << ENDPOINT << "Sending version negotiation packet: {" 1094 QUIC_DLOG(INFO) << ENDPOINT << "Sending version negotiation packet: {"
1091 << QuicVersionVectorToString(framer_.supported_versions()) << "}"; 1095 << QuicVersionVectorToString(framer_.supported_versions())
1096 << "}";
1092 std::unique_ptr<QuicEncryptedPacket> version_packet( 1097 std::unique_ptr<QuicEncryptedPacket> version_packet(
1093 packet_generator_.SerializeVersionNegotiationPacket( 1098 packet_generator_.SerializeVersionNegotiationPacket(
1094 framer_.supported_versions())); 1099 framer_.supported_versions()));
1095 WriteResult result = writer_->WritePacket( 1100 WriteResult result = writer_->WritePacket(
1096 version_packet->data(), version_packet->length(), self_address().host(), 1101 version_packet->data(), version_packet->length(), self_address().host(),
1097 peer_address(), per_packet_options_); 1102 peer_address(), per_packet_options_);
1098 1103
1099 if (result.status == WRITE_STATUS_ERROR) { 1104 if (result.status == WRITE_STATUS_ERROR) {
1100 OnWriteError(result.error_code); 1105 OnWriteError(result.error_code);
1101 return; 1106 return;
(...skipping 147 matching lines...) Expand 10 before | Expand all | Expand 10 after
1249 // Ensure the time coming from the packet reader is within a minute of now. 1254 // Ensure the time coming from the packet reader is within a minute of now.
1250 if (FLAGS_quic_reloadable_flag_quic_allow_large_send_deltas && 1255 if (FLAGS_quic_reloadable_flag_quic_allow_large_send_deltas &&
1251 std::abs((packet.receipt_time() - clock_->ApproximateNow()).ToSeconds()) > 1256 std::abs((packet.receipt_time() - clock_->ApproximateNow()).ToSeconds()) >
1252 60) { 1257 60) {
1253 QUIC_BUG << "Packet receipt time:" 1258 QUIC_BUG << "Packet receipt time:"
1254 << packet.receipt_time().ToDebuggingValue() 1259 << packet.receipt_time().ToDebuggingValue()
1255 << " too far from current time:" 1260 << " too far from current time:"
1256 << clock_->ApproximateNow().ToDebuggingValue(); 1261 << clock_->ApproximateNow().ToDebuggingValue();
1257 } 1262 }
1258 time_of_last_received_packet_ = packet.receipt_time(); 1263 time_of_last_received_packet_ = packet.receipt_time();
1259 DVLOG(1) << ENDPOINT << "time of last received packet: " 1264 QUIC_DVLOG(1) << ENDPOINT << "time of last received packet: "
1260 << time_of_last_received_packet_.ToDebuggingValue(); 1265 << time_of_last_received_packet_.ToDebuggingValue();
1261 1266
1262 ScopedRetransmissionScheduler alarm_delayer(this); 1267 ScopedRetransmissionScheduler alarm_delayer(this);
1263 if (!framer_.ProcessPacket(packet)) { 1268 if (!framer_.ProcessPacket(packet)) {
1264 // If we are unable to decrypt this packet, it might be 1269 // If we are unable to decrypt this packet, it might be
1265 // because the CHLO or SHLO packet was lost. 1270 // because the CHLO or SHLO packet was lost.
1266 if (framer_.error() == QUIC_DECRYPTION_FAILURE) { 1271 if (framer_.error() == QUIC_DECRYPTION_FAILURE) {
1267 if (encryption_level_ != ENCRYPTION_FORWARD_SECURE && 1272 if (encryption_level_ != ENCRYPTION_FORWARD_SECURE &&
1268 undecryptable_packets_.size() < max_undecryptable_packets_) { 1273 undecryptable_packets_.size() < max_undecryptable_packets_) {
1269 QueueUndecryptablePacket(packet); 1274 QueueUndecryptablePacket(packet);
1270 } else if (debug_visitor_ != nullptr) { 1275 } else if (debug_visitor_ != nullptr) {
1271 debug_visitor_->OnUndecryptablePacket(); 1276 debug_visitor_->OnUndecryptablePacket();
1272 } 1277 }
1273 } 1278 }
1274 DVLOG(1) << ENDPOINT << "Unable to process packet. Last packet processed: " 1279 QUIC_DVLOG(1) << ENDPOINT
1275 << last_header_.packet_number; 1280 << "Unable to process packet. Last packet processed: "
1281 << last_header_.packet_number;
1276 current_packet_data_ = nullptr; 1282 current_packet_data_ = nullptr;
1277 return; 1283 return;
1278 } 1284 }
1279 1285
1280 ++stats_.packets_processed; 1286 ++stats_.packets_processed;
1281 if (active_peer_migration_type_ != NO_CHANGE && 1287 if (active_peer_migration_type_ != NO_CHANGE &&
1282 sent_packet_manager_->GetLargestObserved(last_header_.path_id) > 1288 sent_packet_manager_->GetLargestObserved(last_header_.path_id) >
1283 highest_packet_sent_before_peer_migration_) { 1289 highest_packet_sent_before_peer_migration_) {
1284 OnPeerMigrationValidated(last_header_.path_id); 1290 OnPeerMigrationValidated(last_header_.path_id);
1285 } 1291 }
(...skipping 57 matching lines...) Expand 10 before | Expand all | Expand 10 after
1343 last_packet_destination_address_.host().Normalized()) { 1349 last_packet_destination_address_.host().Normalized()) {
1344 CloseConnection(QUIC_ERROR_MIGRATING_ADDRESS, 1350 CloseConnection(QUIC_ERROR_MIGRATING_ADDRESS,
1345 "Self address migration is not supported at the server.", 1351 "Self address migration is not supported at the server.",
1346 ConnectionCloseBehavior::SEND_CONNECTION_CLOSE_PACKET); 1352 ConnectionCloseBehavior::SEND_CONNECTION_CLOSE_PACKET);
1347 return false; 1353 return false;
1348 } 1354 }
1349 self_address_ = last_packet_destination_address_; 1355 self_address_ = last_packet_destination_address_;
1350 } 1356 }
1351 1357
1352 if (!Near(header.packet_number, last_header_.packet_number)) { 1358 if (!Near(header.packet_number, last_header_.packet_number)) {
1353 DVLOG(1) << ENDPOINT << "Packet " << header.packet_number 1359 QUIC_DLOG(INFO) << ENDPOINT << "Packet " << header.packet_number
1354 << " out of bounds. Discarding"; 1360 << " out of bounds. Discarding";
1355 CloseConnection(QUIC_INVALID_PACKET_HEADER, "packet number out of bounds.", 1361 CloseConnection(QUIC_INVALID_PACKET_HEADER, "packet number out of bounds.",
1356 ConnectionCloseBehavior::SEND_CONNECTION_CLOSE_PACKET); 1362 ConnectionCloseBehavior::SEND_CONNECTION_CLOSE_PACKET);
1357 return false; 1363 return false;
1358 } 1364 }
1359 1365
1360 // Multipath is not enabled, but a packet with multipath flag on is 1366 // Multipath is not enabled, but a packet with multipath flag on is
1361 // received. 1367 // received.
1362 if (!multipath_enabled_ && header.public_header.multipath_flag) { 1368 if (!multipath_enabled_ && header.public_header.multipath_flag) {
1363 const string error_details = 1369 const string error_details =
1364 "Received a packet with multipath flag but multipath is not enabled."; 1370 "Received a packet with multipath flag but multipath is not enabled.";
1365 QUIC_BUG << error_details; 1371 QUIC_BUG << error_details;
1366 CloseConnection(QUIC_BAD_MULTIPATH_FLAG, error_details, 1372 CloseConnection(QUIC_BAD_MULTIPATH_FLAG, error_details,
1367 ConnectionCloseBehavior::SEND_CONNECTION_CLOSE_PACKET); 1373 ConnectionCloseBehavior::SEND_CONNECTION_CLOSE_PACKET);
1368 return false; 1374 return false;
1369 } 1375 }
1370 1376
1371 if (version_negotiation_state_ != NEGOTIATED_VERSION) { 1377 if (version_negotiation_state_ != NEGOTIATED_VERSION) {
1372 if (perspective_ == Perspective::IS_SERVER) { 1378 if (perspective_ == Perspective::IS_SERVER) {
1373 if (!header.public_header.version_flag) { 1379 if (!header.public_header.version_flag) {
1374 // Packets should have the version flag till version negotiation is 1380 // Packets should have the version flag till version negotiation is
1375 // done. 1381 // done.
1376 string error_details = 1382 string error_details =
1377 QuicStrCat(ENDPOINT, "Packet ", header.packet_number, 1383 QuicStrCat(ENDPOINT, "Packet ", header.packet_number,
1378 " without version flag before version negotiated."); 1384 " without version flag before version negotiated.");
1379 DLOG(WARNING) << error_details; 1385 QUIC_DLOG(WARNING) << error_details;
1380 CloseConnection(QUIC_INVALID_VERSION, error_details, 1386 CloseConnection(QUIC_INVALID_VERSION, error_details,
1381 ConnectionCloseBehavior::SEND_CONNECTION_CLOSE_PACKET); 1387 ConnectionCloseBehavior::SEND_CONNECTION_CLOSE_PACKET);
1382 return false; 1388 return false;
1383 } else { 1389 } else {
1384 DCHECK_EQ(1u, header.public_header.versions.size()); 1390 DCHECK_EQ(1u, header.public_header.versions.size());
1385 DCHECK_EQ(header.public_header.versions[0], version()); 1391 DCHECK_EQ(header.public_header.versions[0], version());
1386 version_negotiation_state_ = NEGOTIATED_VERSION; 1392 version_negotiation_state_ = NEGOTIATED_VERSION;
1387 visitor_->OnSuccessfulVersionNegotiation(version()); 1393 visitor_->OnSuccessfulVersionNegotiation(version());
1388 if (debug_visitor_ != nullptr) { 1394 if (debug_visitor_ != nullptr) {
1389 debug_visitor_->OnSuccessfulVersionNegotiation(version()); 1395 debug_visitor_->OnSuccessfulVersionNegotiation(version());
(...skipping 116 matching lines...) Expand 10 before | Expand all | Expand 10 after
1506 if (delay.IsInfinite()) { 1512 if (delay.IsInfinite()) {
1507 DCHECK_EQ(kInvalidPathId, path_id); 1513 DCHECK_EQ(kInvalidPathId, path_id);
1508 send_alarm_->Cancel(); 1514 send_alarm_->Cancel();
1509 return false; 1515 return false;
1510 } 1516 }
1511 1517
1512 DCHECK_NE(kInvalidPathId, path_id); 1518 DCHECK_NE(kInvalidPathId, path_id);
1513 // If the scheduler requires a delay, then we can not send this packet now. 1519 // If the scheduler requires a delay, then we can not send this packet now.
1514 if (!delay.IsZero()) { 1520 if (!delay.IsZero()) {
1515 send_alarm_->Update(now + delay, QuicTime::Delta::FromMilliseconds(1)); 1521 send_alarm_->Update(now + delay, QuicTime::Delta::FromMilliseconds(1));
1516 DVLOG(1) << ENDPOINT << "Delaying sending " << delay.ToMilliseconds() 1522 QUIC_DVLOG(1) << ENDPOINT << "Delaying sending " << delay.ToMilliseconds()
1517 << "ms"; 1523 << "ms";
1518 return false; 1524 return false;
1519 } 1525 }
1520 return true; 1526 return true;
1521 } 1527 }
1522 1528
1523 bool QuicConnection::WritePacket(SerializedPacket* packet) { 1529 bool QuicConnection::WritePacket(SerializedPacket* packet) {
1524 if (packet->packet_number < 1530 if (packet->packet_number <
1525 sent_packet_manager_->GetLargestSentPacket(packet->path_id)) { 1531 sent_packet_manager_->GetLargestSentPacket(packet->path_id)) {
1526 QUIC_BUG << "Attempt to write packet:" << packet->packet_number << " after:" 1532 QUIC_BUG << "Attempt to write packet:" << packet->packet_number << " after:"
1527 << sent_packet_manager_->GetLargestSentPacket(packet->path_id); 1533 << sent_packet_manager_->GetLargestSentPacket(packet->path_id);
(...skipping 33 matching lines...) Expand 10 before | Expand all | Expand 10 after
1561 // This assures we won't try to write *forced* packets when blocked. 1567 // This assures we won't try to write *forced* packets when blocked.
1562 // Return true to stop processing. 1568 // Return true to stop processing.
1563 if (writer_->IsWriteBlocked()) { 1569 if (writer_->IsWriteBlocked()) {
1564 visitor_->OnWriteBlocked(); 1570 visitor_->OnWriteBlocked();
1565 return true; 1571 return true;
1566 } 1572 }
1567 } 1573 }
1568 1574
1569 DCHECK_LE(encrypted_length, kMaxPacketSize); 1575 DCHECK_LE(encrypted_length, kMaxPacketSize);
1570 DCHECK_LE(encrypted_length, packet_generator_.GetCurrentMaxPacketLength()); 1576 DCHECK_LE(encrypted_length, packet_generator_.GetCurrentMaxPacketLength());
1571 DVLOG(1) << ENDPOINT << "Sending packet " << packet_number << " : " 1577 QUIC_DVLOG(1) << ENDPOINT << "Sending packet " << packet_number << " : "
1572 << (IsRetransmittable(*packet) == HAS_RETRANSMITTABLE_DATA 1578 << (IsRetransmittable(*packet) == HAS_RETRANSMITTABLE_DATA
1573 ? "data bearing " 1579 ? "data bearing "
1574 : " ack only ") 1580 : " ack only ")
1575 << ", encryption level: " 1581 << ", encryption level: "
1576 << QuicUtils::EncryptionLevelToString(packet->encryption_level) 1582 << QuicUtils::EncryptionLevelToString(packet->encryption_level)
1577 << ", encrypted length:" << encrypted_length; 1583 << ", encrypted length:" << encrypted_length;
1578 DVLOG(2) << ENDPOINT << "packet(" << packet_number << "): " << std::endl 1584 QUIC_DVLOG(2) << ENDPOINT << "packet(" << packet_number << "): " << std::endl
1579 << QuicTextUtils::HexDump( 1585 << QuicTextUtils::HexDump(
1580 StringPiece(packet->encrypted_buffer, encrypted_length)); 1586 StringPiece(packet->encrypted_buffer, encrypted_length));
1581 1587
1582 // Measure the RTT from before the write begins to avoid underestimating the 1588 // Measure the RTT from before the write begins to avoid underestimating the
1583 // min_rtt_, especially in cases where the thread blocks or gets swapped out 1589 // min_rtt_, especially in cases where the thread blocks or gets swapped out
1584 // during the WritePacket below. 1590 // during the WritePacket below.
1585 QuicTime packet_send_time = clock_->Now(); 1591 QuicTime packet_send_time = clock_->Now();
1586 WriteResult result = writer_->WritePacket( 1592 WriteResult result = writer_->WritePacket(
1587 packet->encrypted_buffer, encrypted_length, self_address().host(), 1593 packet->encrypted_buffer, encrypted_length, self_address().host(),
1588 peer_address(), per_packet_options_); 1594 peer_address(), per_packet_options_);
1589 if (result.error_code == ERR_IO_PENDING) { 1595 if (result.error_code == ERR_IO_PENDING) {
1590 DCHECK_EQ(WRITE_STATUS_BLOCKED, result.status); 1596 DCHECK_EQ(WRITE_STATUS_BLOCKED, result.status);
(...skipping 17 matching lines...) Expand all
1608 packet->retransmittable_frames.empty() && 1614 packet->retransmittable_frames.empty() &&
1609 packet->encrypted_length > long_term_mtu_) { 1615 packet->encrypted_length > long_term_mtu_) {
1610 mtu_discovery_target_ = 0; 1616 mtu_discovery_target_ = 0;
1611 mtu_discovery_alarm_->Cancel(); 1617 mtu_discovery_alarm_->Cancel();
1612 // The write failed, but the writer is not blocked, so return true. 1618 // The write failed, but the writer is not blocked, so return true.
1613 return true; 1619 return true;
1614 } 1620 }
1615 1621
1616 if (result.status == WRITE_STATUS_ERROR) { 1622 if (result.status == WRITE_STATUS_ERROR) {
1617 OnWriteError(result.error_code); 1623 OnWriteError(result.error_code);
1618 DLOG(ERROR) << ENDPOINT << "failed writing " << encrypted_length 1624 QUIC_LOG_FIRST_N(ERROR, 10)
1619 << " from host " << self_address().host().ToString() 1625 << ENDPOINT << "failed writing " << encrypted_length
1620 << " to address " << peer_address().ToString() 1626 << " bytes from host " << self_address().host().ToString()
1621 << " with error code " << result.error_code; 1627 << " to address " << peer_address().ToString() << " with error code "
1628 << result.error_code;
1622 return false; 1629 return false;
1623 } 1630 }
1624 1631
1625 if (result.status != WRITE_STATUS_ERROR && debug_visitor_ != nullptr) { 1632 if (result.status != WRITE_STATUS_ERROR && debug_visitor_ != nullptr) {
1626 // Pass the write result to the visitor. 1633 // Pass the write result to the visitor.
1627 debug_visitor_->OnPacketSent(*packet, packet->original_path_id, 1634 debug_visitor_->OnPacketSent(*packet, packet->original_path_id,
1628 packet->original_packet_number, 1635 packet->original_packet_number,
1629 packet->transmission_type, packet_send_time); 1636 packet->transmission_type, packet_send_time);
1630 } 1637 }
1631 if (packet->transmission_type == NOT_RETRANSMISSION) { 1638 if (packet->transmission_type == NOT_RETRANSMISSION) {
1632 time_of_last_sent_new_packet_ = packet_send_time; 1639 time_of_last_sent_new_packet_ = packet_send_time;
1633 } 1640 }
1634 // Only adjust the last sent time (for the purpose of tracking the idle 1641 // Only adjust the last sent time (for the purpose of tracking the idle
1635 // timeout) if this is the first retransmittable packet sent after a 1642 // timeout) if this is the first retransmittable packet sent after a
1636 // packet is received. If it were updated on every sent packet, then 1643 // packet is received. If it were updated on every sent packet, then
1637 // sending into a black hole might never timeout. 1644 // sending into a black hole might never timeout.
1638 if (IsRetransmittable(*packet) == HAS_RETRANSMITTABLE_DATA && 1645 if (IsRetransmittable(*packet) == HAS_RETRANSMITTABLE_DATA &&
1639 last_send_for_timeout_ <= time_of_last_received_packet_) { 1646 last_send_for_timeout_ <= time_of_last_received_packet_) {
1640 last_send_for_timeout_ = packet_send_time; 1647 last_send_for_timeout_ = packet_send_time;
1641 } 1648 }
1642 SetPingAlarm(); 1649 SetPingAlarm();
1643 MaybeSetMtuAlarm(); 1650 MaybeSetMtuAlarm();
1644 DVLOG(1) << ENDPOINT << "time we began writing last sent packet: " 1651 QUIC_DVLOG(1) << ENDPOINT << "time we began writing last sent packet: "
1645 << packet_send_time.ToDebuggingValue(); 1652 << packet_send_time.ToDebuggingValue();
1646 1653
1647 bool reset_retransmission_alarm = sent_packet_manager_->OnPacketSent( 1654 bool reset_retransmission_alarm = sent_packet_manager_->OnPacketSent(
1648 packet, packet->original_path_id, packet->original_packet_number, 1655 packet, packet->original_path_id, packet->original_packet_number,
1649 packet_send_time, packet->transmission_type, IsRetransmittable(*packet)); 1656 packet_send_time, packet->transmission_type, IsRetransmittable(*packet));
1650 1657
1651 if (reset_retransmission_alarm || !retransmission_alarm_->IsSet()) { 1658 if (reset_retransmission_alarm || !retransmission_alarm_->IsSet()) {
1652 SetRetransmissionAlarm(); 1659 SetRetransmissionAlarm();
1653 } 1660 }
1654 1661
1655 // The packet number length must be updated after OnPacketSent, because it 1662 // The packet number length must be updated after OnPacketSent, because it
1656 // may change the packet number length in packet. 1663 // may change the packet number length in packet.
1657 packet_generator_.UpdateSequenceNumberLength( 1664 packet_generator_.UpdateSequenceNumberLength(
1658 sent_packet_manager_->GetLeastUnacked(packet->path_id), 1665 sent_packet_manager_->GetLeastUnacked(packet->path_id),
1659 sent_packet_manager_->EstimateMaxPacketsInFlight(max_packet_length())); 1666 sent_packet_manager_->EstimateMaxPacketsInFlight(max_packet_length()));
1660 1667
1661 stats_.bytes_sent += result.bytes_written; 1668 stats_.bytes_sent += result.bytes_written;
1662 ++stats_.packets_sent; 1669 ++stats_.packets_sent;
1663 if (packet->transmission_type != NOT_RETRANSMISSION) { 1670 if (packet->transmission_type != NOT_RETRANSMISSION) {
1664 stats_.bytes_retransmitted += result.bytes_written; 1671 stats_.bytes_retransmitted += result.bytes_written;
1665 ++stats_.packets_retransmitted; 1672 ++stats_.packets_retransmitted;
1666 } 1673 }
1667 1674
1668 return true; 1675 return true;
1669 } 1676 }
1670 1677
1671 bool QuicConnection::ShouldDiscardPacket(const SerializedPacket& packet) { 1678 bool QuicConnection::ShouldDiscardPacket(const SerializedPacket& packet) {
1672 if (!connected_) { 1679 if (!connected_) {
1673 DVLOG(1) << ENDPOINT << "Not sending packet as connection is disconnected."; 1680 QUIC_DLOG(INFO) << ENDPOINT
1681 << "Not sending packet as connection is disconnected.";
1674 return true; 1682 return true;
1675 } 1683 }
1676 1684
1677 QuicPacketNumber packet_number = packet.packet_number; 1685 QuicPacketNumber packet_number = packet.packet_number;
1678 if (encryption_level_ == ENCRYPTION_FORWARD_SECURE && 1686 if (encryption_level_ == ENCRYPTION_FORWARD_SECURE &&
1679 packet.encryption_level == ENCRYPTION_NONE) { 1687 packet.encryption_level == ENCRYPTION_NONE) {
1680 // Drop packets that are NULL encrypted since the peer won't accept them 1688 // Drop packets that are NULL encrypted since the peer won't accept them
1681 // anymore. 1689 // anymore.
1682 DVLOG(1) << ENDPOINT << "Dropping NULL encrypted packet: " << packet_number 1690 QUIC_DLOG(INFO) << ENDPOINT
1683 << " since the connection is forward secure."; 1691 << "Dropping NULL encrypted packet: " << packet_number
1692 << " since the connection is forward secure.";
1684 return true; 1693 return true;
1685 } 1694 }
1686 1695
1687 return false; 1696 return false;
1688 } 1697 }
1689 1698
1690 void QuicConnection::OnWriteError(int error_code) { 1699 void QuicConnection::OnWriteError(int error_code) {
1691 if (write_error_occured_) { 1700 if (write_error_occured_) {
1692 // A write error already occurred. The connection is being closed. 1701 // A write error already occurred. The connection is being closed.
1693 return; 1702 return;
1694 } 1703 }
1695 write_error_occured_ = true; 1704 write_error_occured_ = true;
1696 1705
1697 const string error_details = QuicStrCat( 1706 const string error_details = QuicStrCat(
1698 "Write failed with error: ", error_code, " (", strerror(error_code), ")"); 1707 "Write failed with error: ", error_code, " (", strerror(error_code), ")");
1699 DVLOG(1) << ENDPOINT << error_details; 1708 QUIC_LOG_FIRST_N(ERROR, 2) << ENDPOINT << error_details;
1700 // We can't send an error as the socket is presumably borked. 1709 // We can't send an error as the socket is presumably borked.
1701 switch (error_code) { 1710 switch (error_code) {
1702 case kMessageTooBigErrorCode: 1711 case kMessageTooBigErrorCode:
1703 CloseConnection( 1712 CloseConnection(
1704 QUIC_PACKET_WRITE_ERROR, error_details, 1713 QUIC_PACKET_WRITE_ERROR, error_details,
1705 ConnectionCloseBehavior::SEND_CONNECTION_CLOSE_PACKET_WITH_NO_ACK); 1714 ConnectionCloseBehavior::SEND_CONNECTION_CLOSE_PACKET_WITH_NO_ACK);
1706 break; 1715 break;
1707 default: 1716 default:
1708 // We can't send an error as the socket is presumably borked. 1717 // We can't send an error as the socket is presumably borked.
1709 TearDownLocalConnectionState(QUIC_PACKET_WRITE_ERROR, error_details, 1718 TearDownLocalConnectionState(QUIC_PACKET_WRITE_ERROR, error_details,
(...skipping 171 matching lines...) Expand 10 before | Expand all | Expand 10 after
1881 const QuicDecrypter* QuicConnection::decrypter() const { 1890 const QuicDecrypter* QuicConnection::decrypter() const {
1882 return framer_.decrypter(); 1891 return framer_.decrypter();
1883 } 1892 }
1884 1893
1885 const QuicDecrypter* QuicConnection::alternative_decrypter() const { 1894 const QuicDecrypter* QuicConnection::alternative_decrypter() const {
1886 return framer_.alternative_decrypter(); 1895 return framer_.alternative_decrypter();
1887 } 1896 }
1888 1897
1889 void QuicConnection::QueueUndecryptablePacket( 1898 void QuicConnection::QueueUndecryptablePacket(
1890 const QuicEncryptedPacket& packet) { 1899 const QuicEncryptedPacket& packet) {
1891 DVLOG(1) << ENDPOINT << "Queueing undecryptable packet."; 1900 QUIC_DVLOG(1) << ENDPOINT << "Queueing undecryptable packet.";
1892 undecryptable_packets_.push_back(packet.Clone()); 1901 undecryptable_packets_.push_back(packet.Clone());
1893 } 1902 }
1894 1903
1895 void QuicConnection::MaybeProcessUndecryptablePackets() { 1904 void QuicConnection::MaybeProcessUndecryptablePackets() {
1896 if (undecryptable_packets_.empty() || encryption_level_ == ENCRYPTION_NONE) { 1905 if (undecryptable_packets_.empty() || encryption_level_ == ENCRYPTION_NONE) {
1897 return; 1906 return;
1898 } 1907 }
1899 1908
1900 while (connected_ && !undecryptable_packets_.empty()) { 1909 while (connected_ && !undecryptable_packets_.empty()) {
1901 DVLOG(1) << ENDPOINT << "Attempting to process undecryptable packet"; 1910 QUIC_DVLOG(1) << ENDPOINT << "Attempting to process undecryptable packet";
1902 QuicEncryptedPacket* packet = undecryptable_packets_.front().get(); 1911 QuicEncryptedPacket* packet = undecryptable_packets_.front().get();
1903 if (!framer_.ProcessPacket(*packet) && 1912 if (!framer_.ProcessPacket(*packet) &&
1904 framer_.error() == QUIC_DECRYPTION_FAILURE) { 1913 framer_.error() == QUIC_DECRYPTION_FAILURE) {
1905 DVLOG(1) << ENDPOINT << "Unable to process undecryptable packet..."; 1914 QUIC_DVLOG(1) << ENDPOINT << "Unable to process undecryptable packet...";
1906 break; 1915 break;
1907 } 1916 }
1908 DVLOG(1) << ENDPOINT << "Processed undecryptable packet!"; 1917 QUIC_DVLOG(1) << ENDPOINT << "Processed undecryptable packet!";
1909 ++stats_.packets_processed; 1918 ++stats_.packets_processed;
1910 undecryptable_packets_.pop_front(); 1919 undecryptable_packets_.pop_front();
1911 } 1920 }
1912 1921
1913 // Once forward secure encryption is in use, there will be no 1922 // Once forward secure encryption is in use, there will be no
1914 // new keys installed and hence any undecryptable packets will 1923 // new keys installed and hence any undecryptable packets will
1915 // never be able to be decrypted. 1924 // never be able to be decrypted.
1916 if (encryption_level_ == ENCRYPTION_FORWARD_SECURE) { 1925 if (encryption_level_ == ENCRYPTION_FORWARD_SECURE) {
1917 if (debug_visitor_ != nullptr) { 1926 if (debug_visitor_ != nullptr) {
1918 // TODO(rtenneti): perhaps more efficient to pass the number of 1927 // TODO(rtenneti): perhaps more efficient to pass the number of
1919 // undecryptable packets as the argument to OnUndecryptablePacket so that 1928 // undecryptable packets as the argument to OnUndecryptablePacket so that
1920 // we just need to call OnUndecryptablePacket once? 1929 // we just need to call OnUndecryptablePacket once?
1921 for (size_t i = 0; i < undecryptable_packets_.size(); ++i) { 1930 for (size_t i = 0; i < undecryptable_packets_.size(); ++i) {
1922 debug_visitor_->OnUndecryptablePacket(); 1931 debug_visitor_->OnUndecryptablePacket();
1923 } 1932 }
1924 } 1933 }
1925 undecryptable_packets_.clear(); 1934 undecryptable_packets_.clear();
1926 } 1935 }
1927 } 1936 }
1928 1937
1929 void QuicConnection::CloseConnection( 1938 void QuicConnection::CloseConnection(
1930 QuicErrorCode error, 1939 QuicErrorCode error,
1931 const string& error_details, 1940 const string& error_details,
1932 ConnectionCloseBehavior connection_close_behavior) { 1941 ConnectionCloseBehavior connection_close_behavior) {
1933 DCHECK(!error_details.empty()); 1942 DCHECK(!error_details.empty());
1934 if (!connected_) { 1943 if (!connected_) {
1935 DVLOG(1) << "Connection is already closed."; 1944 QUIC_DLOG(INFO) << "Connection is already closed.";
1936 return; 1945 return;
1937 } 1946 }
1938 1947
1939 DVLOG(1) << ENDPOINT << "Closing connection: " << connection_id() 1948 QUIC_DLOG(INFO) << ENDPOINT << "Closing connection: " << connection_id()
1940 << ", with error: " << QuicErrorCodeToString(error) << " (" << error 1949 << ", with error: " << QuicErrorCodeToString(error) << " ("
1941 << "), and details: " << error_details; 1950 << error << "), and details: " << error_details;
1942 1951
1943 if (connection_close_behavior == 1952 if (connection_close_behavior ==
1944 ConnectionCloseBehavior::SEND_CONNECTION_CLOSE_PACKET) { 1953 ConnectionCloseBehavior::SEND_CONNECTION_CLOSE_PACKET) {
1945 SendConnectionClosePacket(error, error_details, SEND_ACK); 1954 SendConnectionClosePacket(error, error_details, SEND_ACK);
1946 } else if (connection_close_behavior == 1955 } else if (connection_close_behavior ==
1947 ConnectionCloseBehavior:: 1956 ConnectionCloseBehavior::
1948 SEND_CONNECTION_CLOSE_PACKET_WITH_NO_ACK) { 1957 SEND_CONNECTION_CLOSE_PACKET_WITH_NO_ACK) {
1949 SendConnectionClosePacket(error, error_details, NO_ACK); 1958 SendConnectionClosePacket(error, error_details, NO_ACK);
1950 } 1959 }
1951 1960
1952 ConnectionCloseSource source = ConnectionCloseSource::FROM_SELF; 1961 ConnectionCloseSource source = ConnectionCloseSource::FROM_SELF;
1953 if (perspective_ == Perspective::IS_CLIENT && 1962 if (perspective_ == Perspective::IS_CLIENT &&
1954 error == QUIC_CRYPTO_HANDSHAKE_STATELESS_REJECT) { 1963 error == QUIC_CRYPTO_HANDSHAKE_STATELESS_REJECT) {
1955 // Regard stateless rejected connection as closed by server. 1964 // Regard stateless rejected connection as closed by server.
1956 source = ConnectionCloseSource::FROM_PEER; 1965 source = ConnectionCloseSource::FROM_PEER;
1957 } 1966 }
1958 TearDownLocalConnectionState(error, error_details, source); 1967 TearDownLocalConnectionState(error, error_details, source);
1959 } 1968 }
1960 1969
1961 void QuicConnection::SendConnectionClosePacket(QuicErrorCode error, 1970 void QuicConnection::SendConnectionClosePacket(QuicErrorCode error,
1962 const string& details, 1971 const string& details,
1963 AckBundling ack_mode) { 1972 AckBundling ack_mode) {
1964 DVLOG(1) << ENDPOINT << "Sending connection close packet."; 1973 QUIC_DLOG(INFO) << ENDPOINT << "Sending connection close packet.";
1965 ClearQueuedPackets(); 1974 ClearQueuedPackets();
1966 ScopedPacketBundler ack_bundler(this, ack_mode); 1975 ScopedPacketBundler ack_bundler(this, ack_mode);
1967 QuicConnectionCloseFrame* frame = new QuicConnectionCloseFrame(); 1976 QuicConnectionCloseFrame* frame = new QuicConnectionCloseFrame();
1968 frame->error_code = error; 1977 frame->error_code = error;
1969 frame->error_details = details; 1978 frame->error_details = details;
1970 packet_generator_.AddControlFrame(QuicFrame(frame)); 1979 packet_generator_.AddControlFrame(QuicFrame(frame));
1971 packet_generator_.FlushAllQueuedFrames(); 1980 packet_generator_.FlushAllQueuedFrames();
1972 } 1981 }
1973 1982
1974 void QuicConnection::TearDownLocalConnectionState( 1983 void QuicConnection::TearDownLocalConnectionState(
1975 QuicErrorCode error, 1984 QuicErrorCode error,
1976 const string& error_details, 1985 const string& error_details,
1977 ConnectionCloseSource source) { 1986 ConnectionCloseSource source) {
1978 if (!connected_) { 1987 if (!connected_) {
1979 DVLOG(1) << "Connection is already closed."; 1988 QUIC_DLOG(INFO) << "Connection is already closed.";
1980 return; 1989 return;
1981 } 1990 }
1982 connected_ = false; 1991 connected_ = false;
1983 DCHECK(visitor_ != nullptr); 1992 DCHECK(visitor_ != nullptr);
1984 // TODO(rtenneti): crbug.com/546668. A temporary fix. Added a check for null 1993 // TODO(rtenneti): crbug.com/546668. A temporary fix. Added a check for null
1985 // |visitor_| to fix crash bug. Delete |visitor_| check and histogram after 1994 // |visitor_| to fix crash bug. Delete |visitor_| check and histogram after
1986 // fix is merged. 1995 // fix is merged.
1987 if (visitor_ != nullptr) { 1996 if (visitor_ != nullptr) {
1988 visitor_->OnConnectionClosed(error, error_details, source); 1997 visitor_->OnConnectionClosed(error, error_details, source);
1989 } else { 1998 } else {
1990 UMA_HISTOGRAM_BOOLEAN("Net.QuicCloseConnection.NullVisitor", true); 1999 UMA_HISTOGRAM_BOOLEAN("Net.QuicCloseConnection.NullVisitor", true);
1991 } 2000 }
1992 if (debug_visitor_ != nullptr) { 2001 if (debug_visitor_ != nullptr) {
1993 debug_visitor_->OnConnectionClosed(error, error_details, source); 2002 debug_visitor_->OnConnectionClosed(error, error_details, source);
1994 } 2003 }
1995 // Cancel the alarms so they don't trigger any action now that the 2004 // Cancel the alarms so they don't trigger any action now that the
1996 // connection is closed. 2005 // connection is closed.
1997 CancelAllAlarms(); 2006 CancelAllAlarms();
1998 } 2007 }
1999 2008
2000 void QuicConnection::CancelAllAlarms() { 2009 void QuicConnection::CancelAllAlarms() {
2001 DVLOG(1) << "Cancelling all QuicConnection alarms."; 2010 QUIC_DVLOG(1) << "Cancelling all QuicConnection alarms.";
2002 2011
2003 ack_alarm_->Cancel(); 2012 ack_alarm_->Cancel();
2004 ping_alarm_->Cancel(); 2013 ping_alarm_->Cancel();
2005 resume_writes_alarm_->Cancel(); 2014 resume_writes_alarm_->Cancel();
2006 retransmission_alarm_->Cancel(); 2015 retransmission_alarm_->Cancel();
2007 send_alarm_->Cancel(); 2016 send_alarm_->Cancel();
2008 timeout_alarm_->Cancel(); 2017 timeout_alarm_->Cancel();
2009 mtu_discovery_alarm_->Cancel(); 2018 mtu_discovery_alarm_->Cancel();
2010 } 2019 }
2011 2020
2012 void QuicConnection::SendGoAway(QuicErrorCode error, 2021 void QuicConnection::SendGoAway(QuicErrorCode error,
2013 QuicStreamId last_good_stream_id, 2022 QuicStreamId last_good_stream_id,
2014 const string& reason) { 2023 const string& reason) {
2015 if (goaway_sent_) { 2024 if (goaway_sent_) {
2016 return; 2025 return;
2017 } 2026 }
2018 goaway_sent_ = true; 2027 goaway_sent_ = true;
2019 2028
2020 DVLOG(1) << ENDPOINT << "Going away with error " 2029 QUIC_DLOG(INFO) << ENDPOINT << "Going away with error "
2021 << QuicErrorCodeToString(error) << " (" << error << ")"; 2030 << QuicErrorCodeToString(error) << " (" << error << ")";
2022 2031
2023 // Opportunistically bundle an ack with this outgoing packet. 2032 // Opportunistically bundle an ack with this outgoing packet.
2024 ScopedPacketBundler ack_bundler(this, SEND_ACK_IF_PENDING); 2033 ScopedPacketBundler ack_bundler(this, SEND_ACK_IF_PENDING);
2025 packet_generator_.AddControlFrame( 2034 packet_generator_.AddControlFrame(
2026 QuicFrame(new QuicGoAwayFrame(error, last_good_stream_id, reason))); 2035 QuicFrame(new QuicGoAwayFrame(error, last_good_stream_id, reason)));
2027 } 2036 }
2028 2037
2029 QuicByteCount QuicConnection::max_packet_length() const { 2038 QuicByteCount QuicConnection::max_packet_length() const {
2030 return packet_generator_.GetCurrentMaxPacketLength(); 2039 return packet_generator_.GetCurrentMaxPacketLength();
2031 } 2040 }
(...skipping 48 matching lines...) Expand 10 before | Expand all | Expand 10 after
2080 2089
2081 void QuicConnection::CheckForTimeout() { 2090 void QuicConnection::CheckForTimeout() {
2082 QuicTime now = clock_->ApproximateNow(); 2091 QuicTime now = clock_->ApproximateNow();
2083 QuicTime time_of_last_packet = 2092 QuicTime time_of_last_packet =
2084 std::max(time_of_last_received_packet_, last_send_for_timeout_); 2093 std::max(time_of_last_received_packet_, last_send_for_timeout_);
2085 2094
2086 // |delta| can be < 0 as |now| is approximate time but |time_of_last_packet| 2095 // |delta| can be < 0 as |now| is approximate time but |time_of_last_packet|
2087 // is accurate time. However, this should not change the behavior of 2096 // is accurate time. However, this should not change the behavior of
2088 // timeout handling. 2097 // timeout handling.
2089 QuicTime::Delta idle_duration = now - time_of_last_packet; 2098 QuicTime::Delta idle_duration = now - time_of_last_packet;
2090 DVLOG(1) << ENDPOINT << "last packet " 2099 QUIC_DVLOG(1) << ENDPOINT << "last packet "
2091 << time_of_last_packet.ToDebuggingValue() 2100 << time_of_last_packet.ToDebuggingValue()
2092 << " now:" << now.ToDebuggingValue() 2101 << " now:" << now.ToDebuggingValue()
2093 << " idle_duration:" << idle_duration.ToMicroseconds() 2102 << " idle_duration:" << idle_duration.ToMicroseconds()
2094 << " idle_network_timeout: " 2103 << " idle_network_timeout: "
2095 << idle_network_timeout_.ToMicroseconds(); 2104 << idle_network_timeout_.ToMicroseconds();
2096 if (idle_duration >= idle_network_timeout_) { 2105 if (idle_duration >= idle_network_timeout_) {
2097 const string error_details = "No recent network activity."; 2106 const string error_details = "No recent network activity.";
2098 DVLOG(1) << ENDPOINT << error_details; 2107 QUIC_DVLOG(1) << ENDPOINT << error_details;
2099 CloseConnection(QUIC_NETWORK_IDLE_TIMEOUT, error_details, 2108 CloseConnection(QUIC_NETWORK_IDLE_TIMEOUT, error_details,
2100 idle_timeout_connection_close_behavior_); 2109 idle_timeout_connection_close_behavior_);
2101 return; 2110 return;
2102 } 2111 }
2103 2112
2104 if (!handshake_timeout_.IsInfinite()) { 2113 if (!handshake_timeout_.IsInfinite()) {
2105 QuicTime::Delta connected_duration = now - stats_.connection_creation_time; 2114 QuicTime::Delta connected_duration = now - stats_.connection_creation_time;
2106 DVLOG(1) << ENDPOINT 2115 QUIC_DVLOG(1) << ENDPOINT
2107 << "connection time: " << connected_duration.ToMicroseconds() 2116 << "connection time: " << connected_duration.ToMicroseconds()
2108 << " handshake timeout: " << handshake_timeout_.ToMicroseconds(); 2117 << " handshake timeout: "
2118 << handshake_timeout_.ToMicroseconds();
2109 if (connected_duration >= handshake_timeout_) { 2119 if (connected_duration >= handshake_timeout_) {
2110 const string error_details = "Handshake timeout expired."; 2120 const string error_details = "Handshake timeout expired.";
2111 DVLOG(1) << ENDPOINT << error_details; 2121 QUIC_DVLOG(1) << ENDPOINT << error_details;
2112 CloseConnection(QUIC_HANDSHAKE_TIMEOUT, error_details, 2122 CloseConnection(QUIC_HANDSHAKE_TIMEOUT, error_details,
2113 ConnectionCloseBehavior::SEND_CONNECTION_CLOSE_PACKET); 2123 ConnectionCloseBehavior::SEND_CONNECTION_CLOSE_PACKET);
2114 return; 2124 return;
2115 } 2125 }
2116 } 2126 }
2117 2127
2118 SetTimeoutAlarm(); 2128 SetTimeoutAlarm();
2119 } 2129 }
2120 2130
2121 void QuicConnection::SetTimeoutAlarm() { 2131 void QuicConnection::SetTimeoutAlarm() {
(...skipping 63 matching lines...) Expand 10 before | Expand all | Expand 10 after
2185 AckBundling ack_mode) 2195 AckBundling ack_mode)
2186 : connection_(connection), 2196 : connection_(connection),
2187 already_in_batch_mode_(connection != nullptr && 2197 already_in_batch_mode_(connection != nullptr &&
2188 connection->packet_generator_.InBatchMode()) { 2198 connection->packet_generator_.InBatchMode()) {
2189 if (connection_ == nullptr) { 2199 if (connection_ == nullptr) {
2190 return; 2200 return;
2191 } 2201 }
2192 // Move generator into batch mode. If caller wants us to include an ack, 2202 // Move generator into batch mode. If caller wants us to include an ack,
2193 // check the delayed-ack timer to see if there's ack info to be sent. 2203 // check the delayed-ack timer to see if there's ack info to be sent.
2194 if (!already_in_batch_mode_) { 2204 if (!already_in_batch_mode_) {
2195 DVLOG(2) << "Entering Batch Mode."; 2205 QUIC_DVLOG(2) << "Entering Batch Mode.";
2196 connection_->packet_generator_.StartBatchOperations(); 2206 connection_->packet_generator_.StartBatchOperations();
2197 } 2207 }
2198 if (ShouldSendAck(ack_mode)) { 2208 if (ShouldSendAck(ack_mode)) {
2199 DVLOG(1) << "Bundling ack with outgoing packet."; 2209 QUIC_DVLOG(1) << "Bundling ack with outgoing packet.";
2200 DCHECK(ack_mode == SEND_ACK || connection_->ack_frame_updated() || 2210 DCHECK(ack_mode == SEND_ACK || connection_->ack_frame_updated() ||
2201 connection_->stop_waiting_count_ > 1); 2211 connection_->stop_waiting_count_ > 1);
2202 connection_->SendAck(); 2212 connection_->SendAck();
2203 } 2213 }
2204 } 2214 }
2205 2215
2206 bool QuicConnection::ScopedPacketBundler::ShouldSendAck( 2216 bool QuicConnection::ScopedPacketBundler::ShouldSendAck(
2207 AckBundling ack_mode) const { 2217 AckBundling ack_mode) const {
2208 switch (ack_mode) { 2218 switch (ack_mode) {
2209 case SEND_ACK: 2219 case SEND_ACK:
(...skipping 10 matching lines...) Expand all
2220 return true; 2230 return true;
2221 } 2231 }
2222 } 2232 }
2223 2233
2224 QuicConnection::ScopedPacketBundler::~ScopedPacketBundler() { 2234 QuicConnection::ScopedPacketBundler::~ScopedPacketBundler() {
2225 if (connection_ == nullptr) { 2235 if (connection_ == nullptr) {
2226 return; 2236 return;
2227 } 2237 }
2228 // If we changed the generator's batch state, restore original batch state. 2238 // If we changed the generator's batch state, restore original batch state.
2229 if (!already_in_batch_mode_) { 2239 if (!already_in_batch_mode_) {
2230 DVLOG(2) << "Leaving Batch Mode."; 2240 QUIC_DVLOG(2) << "Leaving Batch Mode.";
2231 connection_->packet_generator_.FinishBatchOperations(); 2241 connection_->packet_generator_.FinishBatchOperations();
2232 2242
2233 // Once all transmissions are done, check if there is any outstanding data 2243 // Once all transmissions are done, check if there is any outstanding data
2234 // to send and notify the congestion controller if not. 2244 // to send and notify the congestion controller if not.
2235 // 2245 //
2236 // Note that this means that the application limited check will happen as 2246 // Note that this means that the application limited check will happen as
2237 // soon as the last bundler gets destroyed, which is typically after a 2247 // soon as the last bundler gets destroyed, which is typically after a
2238 // single stream write is finished. This means that if all the data from a 2248 // single stream write is finished. This means that if all the data from a
2239 // single write goes through the connection, the application-limited signal 2249 // single write goes through the connection, the application-limited signal
2240 // will fire even if the caller does a write operation immediately after. 2250 // will fire even if the caller does a write operation immediately after.
(...skipping 102 matching lines...) Expand 10 before | Expand all | Expand 10 after
2343 2353
2344 // Calculate the packet number of the next probe *before* sending the current 2354 // Calculate the packet number of the next probe *before* sending the current
2345 // one. Otherwise, when SendMtuDiscoveryPacket() is called, 2355 // one. Otherwise, when SendMtuDiscoveryPacket() is called,
2346 // MaybeSetMtuAlarm() will not realize that the probe has been just sent, and 2356 // MaybeSetMtuAlarm() will not realize that the probe has been just sent, and
2347 // will reschedule this probe again. 2357 // will reschedule this probe again.
2348 packets_between_mtu_probes_ *= 2; 2358 packets_between_mtu_probes_ *= 2;
2349 next_mtu_probe_at_ = 2359 next_mtu_probe_at_ =
2350 packet_number_of_last_sent_packet_ + packets_between_mtu_probes_ + 1; 2360 packet_number_of_last_sent_packet_ + packets_between_mtu_probes_ + 1;
2351 ++mtu_probe_count_; 2361 ++mtu_probe_count_;
2352 2362
2353 DVLOG(2) << "Sending a path MTU discovery packet #" << mtu_probe_count_; 2363 QUIC_DVLOG(2) << "Sending a path MTU discovery packet #" << mtu_probe_count_;
2354 SendMtuDiscoveryPacket(mtu_discovery_target_); 2364 SendMtuDiscoveryPacket(mtu_discovery_target_);
2355 2365
2356 DCHECK(!mtu_discovery_alarm_->IsSet()); 2366 DCHECK(!mtu_discovery_alarm_->IsSet());
2357 } 2367 }
2358 2368
2359 void QuicConnection::OnPeerMigrationValidated(QuicPathId path_id) { 2369 void QuicConnection::OnPeerMigrationValidated(QuicPathId path_id) {
2360 if (active_peer_migration_type_ == NO_CHANGE) { 2370 if (active_peer_migration_type_ == NO_CHANGE) {
2361 QUIC_BUG << "No migration underway."; 2371 QUIC_BUG << "No migration underway.";
2362 return; 2372 return;
2363 } 2373 }
2364 highest_packet_sent_before_peer_migration_ = 0; 2374 highest_packet_sent_before_peer_migration_ = 0;
2365 active_peer_migration_type_ = NO_CHANGE; 2375 active_peer_migration_type_ = NO_CHANGE;
2366 } 2376 }
2367 2377
2368 // TODO(jri): Modify method to start migration whenever a new IP address is seen 2378 // TODO(jri): Modify method to start migration whenever a new IP address is seen
2369 // from a packet with sequence number > the one that triggered the previous 2379 // from a packet with sequence number > the one that triggered the previous
2370 // migration. This should happen even if a migration is underway, since the 2380 // migration. This should happen even if a migration is underway, since the
2371 // most recent migration is the one that we should pay attention to. 2381 // most recent migration is the one that we should pay attention to.
2372 void QuicConnection::StartPeerMigration( 2382 void QuicConnection::StartPeerMigration(
2373 QuicPathId path_id, 2383 QuicPathId path_id,
2374 PeerAddressChangeType peer_migration_type) { 2384 PeerAddressChangeType peer_migration_type) {
2375 // TODO(fayang): Currently, all peer address change type are allowed. Need to 2385 // TODO(fayang): Currently, all peer address change type are allowed. Need to
2376 // add a method ShouldAllowPeerAddressChange(PeerAddressChangeType type) to 2386 // add a method ShouldAllowPeerAddressChange(PeerAddressChangeType type) to
2377 // determine whether |type| is allowed. 2387 // determine whether |type| is allowed.
2378 if (active_peer_migration_type_ != NO_CHANGE || 2388 if (active_peer_migration_type_ != NO_CHANGE ||
2379 peer_migration_type == NO_CHANGE) { 2389 peer_migration_type == NO_CHANGE) {
2380 QUIC_BUG << "Migration underway or no new migration started."; 2390 QUIC_BUG << "Migration underway or no new migration started.";
2381 return; 2391 return;
2382 } 2392 }
2383 DVLOG(1) << ENDPOINT << "Peer's ip:port changed from " 2393 QUIC_DLOG(INFO) << ENDPOINT << "Peer's ip:port changed from "
2384 << peer_address_.ToString() << " to " 2394 << peer_address_.ToString() << " to "
2385 << last_packet_source_address_.ToString() 2395 << last_packet_source_address_.ToString()
2386 << ", migrating connection."; 2396 << ", migrating connection.";
2387 2397
2388 highest_packet_sent_before_peer_migration_ = 2398 highest_packet_sent_before_peer_migration_ =
2389 packet_number_of_last_sent_packet_; 2399 packet_number_of_last_sent_packet_;
2390 peer_address_ = last_packet_source_address_; 2400 peer_address_ = last_packet_source_address_;
2391 active_peer_migration_type_ = peer_migration_type; 2401 active_peer_migration_type_ = peer_migration_type;
2392 2402
2393 // TODO(jri): Move these calls to OnPeerMigrationValidated. Rename 2403 // TODO(jri): Move these calls to OnPeerMigrationValidated. Rename
2394 // OnConnectionMigration methods to OnPeerMigration. 2404 // OnConnectionMigration methods to OnPeerMigration.
2395 visitor_->OnConnectionMigration(peer_migration_type); 2405 visitor_->OnConnectionMigration(peer_migration_type);
2396 sent_packet_manager_->OnConnectionMigration(path_id, peer_migration_type); 2406 sent_packet_manager_->OnConnectionMigration(path_id, peer_migration_type);
(...skipping 60 matching lines...) Expand 10 before | Expand all | Expand 10 after
2457 2467
2458 void QuicConnection::CheckIfApplicationLimited() { 2468 void QuicConnection::CheckIfApplicationLimited() {
2459 if (queued_packets_.empty() && 2469 if (queued_packets_.empty() &&
2460 !sent_packet_manager_->HasPendingRetransmissions() && 2470 !sent_packet_manager_->HasPendingRetransmissions() &&
2461 !visitor_->WillingAndAbleToWrite()) { 2471 !visitor_->WillingAndAbleToWrite()) {
2462 sent_packet_manager_->OnApplicationLimited(); 2472 sent_packet_manager_->OnApplicationLimited();
2463 } 2473 }
2464 } 2474 }
2465 2475
2466 } // namespace net 2476 } // namespace net
OLDNEW
« no previous file with comments | « net/quic/core/quic_connection.h ('k') | net/quic/core/quic_connection_test.cc » ('j') | no next file with comments »

Powered by Google App Engine
This is Rietveld 408576698