Merge pull request #2764 from lucas-clemente/fix-local-key-update-logging

fix logging of locally initiated key updates
This commit is contained in:
Marten Seemann 2020-09-09 23:52:52 +07:00 committed by GitHub
commit 9e1d65f4c9
No known key found for this signature in database
GPG key ID: 4AEE18F83AFDEB23
11 changed files with 51 additions and 41 deletions

View file

@ -9,15 +9,15 @@ import (
"os"
"time"
"github.com/lucas-clemente/quic-go/logging"
"github.com/golang/mock/gomock"
"github.com/lucas-clemente/quic-go/internal/mocks"
mocklogging "github.com/lucas-clemente/quic-go/internal/mocks/logging"
"github.com/lucas-clemente/quic-go/internal/protocol"
"github.com/lucas-clemente/quic-go/internal/utils"
"github.com/lucas-clemente/quic-go/internal/wire"
"github.com/lucas-clemente/quic-go/logging"
"github.com/lucas-clemente/quic-go/quictrace"
"github.com/golang/mock/gomock"
. "github.com/onsi/ginkgo"
. "github.com/onsi/gomega"
)
@ -31,7 +31,7 @@ var _ = Describe("Client", func() {
mockMultiplexer *MockMultiplexer
origMultiplexer multiplexer
tlsConf *tls.Config
tracer *mocks.MockConnectionTracer
tracer *mocklogging.MockConnectionTracer
config *Config
originalClientSessConstructor func(
@ -66,8 +66,8 @@ var _ = Describe("Client", func() {
tlsConf = &tls.Config{NextProtos: []string{"proto1"}}
connID = protocol.ConnectionID{0, 0, 0, 0, 0, 0, 0x13, 0x37}
originalClientSessConstructor = newClientSession
tracer = mocks.NewMockConnectionTracer(mockCtrl)
tr := mocks.NewMockTracer(mockCtrl)
tracer = mocklogging.NewMockConnectionTracer(mockCtrl)
tr := mocklogging.NewMockTracer(mockCtrl)
tr.EXPECT().TracerForConnection(protocol.PerspectiveClient, gomock.Any()).Return(tracer).MaxTimes(1)
config = &Config{Tracer: tr}
Eventually(areSessionsRunning).Should(BeFalse())

View file

@ -6,7 +6,7 @@ import (
"reflect"
"time"
"github.com/lucas-clemente/quic-go/internal/mocks"
mocklogging "github.com/lucas-clemente/quic-go/internal/mocks/logging"
"github.com/lucas-clemente/quic-go/internal/protocol"
"github.com/lucas-clemente/quic-go/quictrace"
@ -73,7 +73,7 @@ var _ = Describe("Config", func() {
case "QuicTracer":
f.Set(reflect.ValueOf(quictrace.NewTracer()))
case "Tracer":
f.Set(reflect.ValueOf(mocks.NewMockTracer(mockCtrl)))
f.Set(reflect.ValueOf(mocklogging.NewMockTracer(mockCtrl)))
default:
Fail(fmt.Sprintf("all fields must be accounted for, but saw unknown field %q", fn))
}

View file

@ -242,10 +242,11 @@ func (a *updatableAEAD) shouldInitiateKeyUpdate() bool {
func (a *updatableAEAD) KeyPhase() protocol.KeyPhaseBit {
if a.shouldInitiateKeyUpdate() {
a.rollKeys(time.Now())
a.logger.Debugf("Initiating key update to key phase %s", a.keyPhase)
if a.tracer != nil {
a.tracer.UpdatedKey(a.keyPhase, false)
}
a.rollKeys(time.Now())
}
return a.keyPhase.Bit()
}

View file

@ -7,6 +7,7 @@ import (
"os"
"time"
mocklogging "github.com/lucas-clemente/quic-go/internal/mocks/logging"
"github.com/lucas-clemente/quic-go/internal/protocol"
"github.com/lucas-clemente/quic-go/internal/qtls"
"github.com/lucas-clemente/quic-go/internal/utils"
@ -37,24 +38,31 @@ var _ = Describe("Updatable AEAD", func() {
cs := cipherSuites[i]
Context(fmt.Sprintf("using %s", qtls.CipherSuiteName(cs.ID)), func() {
getPeers := func(rttStats *utils.RTTStats) (client, server *updatableAEAD) {
var (
client, server *updatableAEAD
clientTracer, serverTracer *mocklogging.MockConnectionTracer
rttStats *utils.RTTStats
)
BeforeEach(func() {
clientTracer = mocklogging.NewMockConnectionTracer(mockCtrl)
serverTracer = mocklogging.NewMockConnectionTracer(mockCtrl)
trafficSecret1 := make([]byte, 16)
trafficSecret2 := make([]byte, 16)
rand.Read(trafficSecret1)
rand.Read(trafficSecret2)
client = newUpdatableAEAD(rttStats, nil, utils.DefaultLogger)
server = newUpdatableAEAD(rttStats, nil, utils.DefaultLogger)
rttStats = utils.NewRTTStats()
client = newUpdatableAEAD(rttStats, clientTracer, utils.DefaultLogger)
server = newUpdatableAEAD(rttStats, serverTracer, utils.DefaultLogger)
client.SetReadKey(cs, trafficSecret2)
client.SetWriteKey(cs, trafficSecret1)
server.SetReadKey(cs, trafficSecret1)
server.SetWriteKey(cs, trafficSecret2)
return
}
})
Context("header protection", func() {
It("encrypts and decrypts the header", func() {
server, client := getPeers(&utils.RTTStats{})
var lastFiveBitsDifferent int
for i := 0; i < 100; i++ {
sample := make([]byte, 16)
@ -76,12 +84,8 @@ var _ = Describe("Updatable AEAD", func() {
Context("message encryption", func() {
var msg, ad []byte
var server, client *updatableAEAD
var rttStats *utils.RTTStats
BeforeEach(func() {
rttStats = &utils.RTTStats{}
server, client = getPeers(rttStats)
msg = []byte("Lorem ipsum dolor sit amet, consectetur adipiscing elit, sed do eiusmod tempor incididunt ut labore et dolore magna aliqua.")
ad = []byte("Donec in velit neque.")
})
@ -144,6 +148,7 @@ var _ = Describe("Updatable AEAD", func() {
// now received a message at key phase one
client.rollKeys(now)
encrypted1 := client.Seal(nil, msg, 0x43, ad)
serverTracer.EXPECT().UpdatedKey(protocol.KeyPhase(1), true)
decrypted, err = server.Open(nil, encrypted1, now, 0x43, protocol.KeyPhaseOne, ad)
Expect(err).ToNot(HaveOccurred())
Expect(decrypted).To(Equal(msg))
@ -163,6 +168,7 @@ var _ = Describe("Updatable AEAD", func() {
client.rollKeys(now)
encrypted1 := client.Seal(nil, msg, 0x44, ad)
Expect(server.KeyPhase()).To(Equal(protocol.KeyPhaseZero))
serverTracer.EXPECT().UpdatedKey(protocol.KeyPhase(1), true)
_, err = server.Open(nil, encrypted1, now, 0x44, protocol.KeyPhaseOne, ad)
Expect(err).ToNot(HaveOccurred())
Expect(server.KeyPhase()).To(Equal(protocol.KeyPhaseOne))
@ -188,6 +194,7 @@ var _ = Describe("Updatable AEAD", func() {
client.rollKeys(now)
encrypted1 := client.Seal(nil, msg, 0x44, ad)
Expect(server.KeyPhase()).To(Equal(protocol.KeyPhaseZero))
serverTracer.EXPECT().UpdatedKey(protocol.KeyPhase(1), true)
_, err = server.Open(nil, encrypted1, now, 0x44, protocol.KeyPhaseOne, ad)
Expect(err).ToNot(HaveOccurred())
Expect(server.KeyPhase()).To(Equal(protocol.KeyPhaseOne))
@ -233,6 +240,7 @@ var _ = Describe("Updatable AEAD", func() {
// no update allowed before receiving an acknowledgement for the current key phase
Expect(server.KeyPhase()).To(Equal(protocol.KeyPhaseZero))
server.SetLargestAcked(0)
serverTracer.EXPECT().UpdatedKey(protocol.KeyPhase(1), false)
Expect(server.KeyPhase()).To(Equal(protocol.KeyPhaseOne))
})
@ -248,6 +256,7 @@ var _ = Describe("Updatable AEAD", func() {
Expect(server.KeyPhase()).To(Equal(protocol.KeyPhaseZero))
server.Seal(nil, msg, 1, ad)
server.SetLargestAcked(1)
serverTracer.EXPECT().UpdatedKey(protocol.KeyPhase(1), false)
Expect(server.KeyPhase()).To(Equal(protocol.KeyPhaseOne))
})
})

View file

@ -1,8 +1,8 @@
// Code generated by MockGen. DO NOT EDIT.
// Source: github.com/lucas-clemente/quic-go/logging (interfaces: ConnectionTracer)
// Package mocks is a generated GoMock package.
package mocks
// Package mocklogging is a generated GoMock package.
package mocklogging
import (
net "net"

View file

@ -1,8 +1,8 @@
// Code generated by MockGen. DO NOT EDIT.
// Source: github.com/lucas-clemente/quic-go/logging (interfaces: Tracer)
// Package mocks is a generated GoMock package.
package mocks
// Package mocklogging is a generated GoMock package.
package mocklogging
import (
net "net"

View file

@ -3,8 +3,8 @@ package mocks
//go:generate sh -c "mockgen -package mockquic -destination quic/stream.go github.com/lucas-clemente/quic-go Stream && goimports -w quic/stream.go"
//go:generate sh -c "mockgen -package mockquic -destination quic/early_session_tmp.go github.com/lucas-clemente/quic-go EarlySession && sed 's/qtls.ConnectionState/quic.ConnectionState/g' quic/early_session_tmp.go > quic/early_session.go && rm quic/early_session_tmp.go && goimports -w quic/early_session.go"
//go:generate sh -c "mockgen -package mockquic -destination quic/early_listener.go github.com/lucas-clemente/quic-go EarlyListener && goimports -w quic/early_listener.go"
//go:generate sh -c "mockgen -package mocks -destination tracer.go github.com/lucas-clemente/quic-go/logging Tracer && goimports -w tracer.go"
//go:generate sh -c "mockgen -package mocks -destination connection_tracer.go github.com/lucas-clemente/quic-go/logging ConnectionTracer && goimports -w connection_tracer.go"
//go:generate sh -c "mockgen -package mocklogging -destination logging/tracer.go github.com/lucas-clemente/quic-go/logging Tracer && goimports -w logging/tracer.go"
//go:generate sh -c "mockgen -package mocklogging -destination logging/connection_tracer.go github.com/lucas-clemente/quic-go/logging ConnectionTracer && goimports -w logging/connection_tracer.go"
//go:generate sh -c "mockgen -package mocks -destination short_header_sealer.go github.com/lucas-clemente/quic-go/internal/handshake ShortHeaderSealer && goimports -w short_header_sealer.go"
//go:generate sh -c "mockgen -package mocks -destination short_header_opener.go github.com/lucas-clemente/quic-go/internal/handshake ShortHeaderOpener && goimports -w short_header_opener.go"
//go:generate sh -c "mockgen -package mocks -destination long_header_opener.go github.com/lucas-clemente/quic-go/internal/handshake LongHeaderOpener && goimports -w long_header_opener.go"

View file

@ -3,7 +3,7 @@ package quic
import (
"net"
"github.com/lucas-clemente/quic-go/internal/mocks"
mocklogging "github.com/lucas-clemente/quic-go/internal/mocks/logging"
. "github.com/onsi/ginkgo"
. "github.com/onsi/gomega"
@ -25,7 +25,7 @@ var _ = Describe("Client Multiplexer", func() {
pconn := newMockPacketConn()
pconn.addr = &net.UDPAddr{IP: net.IPv4(1, 2, 3, 4), Port: 4321}
conn := testConn{PacketConn: pconn}
tracer := mocks.NewMockTracer(mockCtrl)
tracer := mocklogging.NewMockTracer(mockCtrl)
_, err := getMultiplexer().AddConn(conn, 8, []byte("foobar"), tracer)
Expect(err).ToNot(HaveOccurred())
conn.counter++
@ -52,9 +52,9 @@ var _ = Describe("Client Multiplexer", func() {
It("errors when adding an existing conn with different tracers", func() {
conn := newMockPacketConn()
_, err := getMultiplexer().AddConn(conn, 7, nil, mocks.NewMockTracer(mockCtrl))
_, err := getMultiplexer().AddConn(conn, 7, nil, mocklogging.NewMockTracer(mockCtrl))
Expect(err).ToNot(HaveOccurred())
_, err = getMultiplexer().AddConn(conn, 7, nil, mocks.NewMockTracer(mockCtrl))
_, err = getMultiplexer().AddConn(conn, 7, nil, mocklogging.NewMockTracer(mockCtrl))
Expect(err).To(MatchError("cannot use different tracers on the same packet conn"))
})
})

View file

@ -7,7 +7,7 @@ import (
"net"
"time"
"github.com/lucas-clemente/quic-go/internal/mocks"
mocklogging "github.com/lucas-clemente/quic-go/internal/mocks/logging"
"github.com/lucas-clemente/quic-go/internal/protocol"
"github.com/lucas-clemente/quic-go/internal/utils"
"github.com/lucas-clemente/quic-go/internal/wire"
@ -23,7 +23,7 @@ var _ = Describe("Packet Handler Map", func() {
var (
handler *packetHandlerMap
conn *mockPacketConn
tracer *mocks.MockTracer
tracer *mocklogging.MockTracer
connIDLen int
statelessResetKey []byte
@ -51,7 +51,7 @@ var _ = Describe("Packet Handler Map", func() {
BeforeEach(func() {
statelessResetKey = nil
connIDLen = 0
tracer = mocks.NewMockTracer(mockCtrl)
tracer = mocklogging.NewMockTracer(mockCtrl)
})
JustBeforeEach(func() {

View file

@ -14,9 +14,8 @@ import (
"sync/atomic"
"time"
"github.com/lucas-clemente/quic-go/internal/mocks"
"github.com/lucas-clemente/quic-go/internal/handshake"
mocklogging "github.com/lucas-clemente/quic-go/internal/mocks/logging"
"github.com/lucas-clemente/quic-go/internal/protocol"
"github.com/lucas-clemente/quic-go/internal/qerr"
"github.com/lucas-clemente/quic-go/internal/testdata"
@ -186,11 +185,11 @@ var _ = Describe("Server", func() {
var (
serv *baseServer
phm *MockPacketHandlerManager
tracer *mocks.MockTracer
tracer *mocklogging.MockTracer
)
BeforeEach(func() {
tracer = mocks.NewMockTracer(mockCtrl)
tracer = mocklogging.NewMockTracer(mockCtrl)
ln, err := Listen(conn, tlsConf, &Config{Tracer: tracer})
Expect(err).ToNot(HaveOccurred())
serv = ln.(*baseServer)

View file

@ -17,6 +17,7 @@ import (
"github.com/lucas-clemente/quic-go/internal/handshake"
"github.com/lucas-clemente/quic-go/internal/mocks"
mockackhandler "github.com/lucas-clemente/quic-go/internal/mocks/ackhandler"
mocklogging "github.com/lucas-clemente/quic-go/internal/mocks/logging"
"github.com/lucas-clemente/quic-go/internal/protocol"
"github.com/lucas-clemente/quic-go/internal/qerr"
"github.com/lucas-clemente/quic-go/internal/testutils"
@ -50,7 +51,7 @@ var _ = Describe("Session", func() {
streamManager *MockStreamManager
packer *MockPacker
cryptoSetup *mocks.MockCryptoSetup
tracer *mocks.MockConnectionTracer
tracer *mocklogging.MockConnectionTracer
)
remoteAddr := &net.UDPAddr{IP: net.IPv4(127, 0, 0, 1), Port: 1337}
localAddr := &net.UDPAddr{IP: net.IPv4(127, 0, 0, 1), Port: 7331}
@ -88,7 +89,7 @@ var _ = Describe("Session", func() {
mconn.EXPECT().LocalAddr().Return(localAddr).AnyTimes()
tokenGenerator, err := handshake.NewTokenGenerator(rand.Reader)
Expect(err).ToNot(HaveOccurred())
tracer = mocks.NewMockConnectionTracer(mockCtrl)
tracer = mocklogging.NewMockConnectionTracer(mockCtrl)
tracer.EXPECT().SentTransportParameters(gomock.Any())
tracer.EXPECT().UpdatedKeyFromTLS(gomock.Any(), gomock.Any()).AnyTimes()
tracer.EXPECT().UpdatedCongestionState(gomock.Any())
@ -2109,7 +2110,7 @@ var _ = Describe("Client Session", func() {
packer *MockPacker
mconn *MockSendConn
cryptoSetup *mocks.MockCryptoSetup
tracer *mocks.MockConnectionTracer
tracer *mocklogging.MockConnectionTracer
tlsConf *tls.Config
quicConf *Config
)
@ -2148,7 +2149,7 @@ var _ = Describe("Client Session", func() {
tlsConf = &tls.Config{}
}
sessionRunner = NewMockSessionRunner(mockCtrl)
tracer = mocks.NewMockConnectionTracer(mockCtrl)
tracer = mocklogging.NewMockConnectionTracer(mockCtrl)
tracer.EXPECT().SentTransportParameters(gomock.Any())
tracer.EXPECT().UpdatedKeyFromTLS(gomock.Any(), gomock.Any()).AnyTimes()
tracer.EXPECT().UpdatedCongestionState(gomock.Any())