diff --git a/internal/flowcontrol/stream_flow_controller.go b/internal/flowcontrol/stream_flow_controller.go index 5a11929f..26460e8c 100644 --- a/internal/flowcontrol/stream_flow_controller.go +++ b/internal/flowcontrol/stream_flow_controller.go @@ -58,11 +58,11 @@ func (c *streamFlowController) UpdateHighestReceived(offset protocol.ByteCount, if c.receivedFinalOffset { // If we receive another final offset, check that it's the same. if final && offset != c.highestReceived { - return qerr.NewError(qerr.FinalSizeError, fmt.Sprintf("Received inconsistent final offset for stream %d (old: %#x, new: %#x bytes)", c.streamID, c.highestReceived, offset)) + return qerr.NewError(qerr.FinalSizeError, fmt.Sprintf("Received inconsistent final offset for stream %d (old: %d, new: %d bytes)", c.streamID, c.highestReceived, offset)) } // Check that the offset is below the final offset. if offset > c.highestReceived { - return qerr.NewError(qerr.FinalSizeError, fmt.Sprintf("Received offset %#x for stream %d. Final offset was already received at %#x", offset, c.streamID, c.highestReceived)) + return qerr.NewError(qerr.FinalSizeError, fmt.Sprintf("Received offset %d for stream %d. Final offset was already received at %d", offset, c.streamID, c.highestReceived)) } } @@ -76,7 +76,7 @@ func (c *streamFlowController) UpdateHighestReceived(offset protocol.ByteCount, // This can happen due to reordering. if offset <= c.highestReceived { if final { - return qerr.NewError(qerr.FinalSizeError, fmt.Sprintf("Received final offset %#x for stream %d, but already received offset %#x before", offset, c.streamID, c.highestReceived)) + return qerr.NewError(qerr.FinalSizeError, fmt.Sprintf("Received final offset %d for stream %d, but already received offset %d before", offset, c.streamID, c.highestReceived)) } return nil } @@ -84,7 +84,7 @@ func (c *streamFlowController) UpdateHighestReceived(offset protocol.ByteCount, increment := offset - c.highestReceived c.highestReceived = offset if c.checkFlowControlViolation() { - return qerr.NewError(qerr.FlowControlError, fmt.Sprintf("Received %#x bytes on stream %d, allowed %#x bytes", offset, c.streamID, c.receiveWindow)) + return qerr.NewError(qerr.FlowControlError, fmt.Sprintf("Received %d bytes on stream %d, allowed %d bytes", offset, c.streamID, c.receiveWindow)) } return c.connection.IncrementHighestReceived(increment) } diff --git a/internal/flowcontrol/stream_flow_controller_test.go b/internal/flowcontrol/stream_flow_controller_test.go index ac2dea67..cfb26655 100644 --- a/internal/flowcontrol/stream_flow_controller_test.go +++ b/internal/flowcontrol/stream_flow_controller_test.go @@ -60,7 +60,7 @@ var _ = Describe("Stream Flow controller", func() { Context("receiving data", func() { Context("registering received offsets", func() { - var receiveWindow protocol.ByteCount = 0x10000 + var receiveWindow protocol.ByteCount = 10000 var receiveWindowSize protocol.ByteCount = 600 BeforeEach(func() { @@ -98,7 +98,7 @@ var _ = Describe("Stream Flow controller", func() { }) It("detects a flow control violation", func() { - Expect(controller.UpdateHighestReceived(receiveWindow+1, false)).To(MatchError("FLOW_CONTROL_ERROR: Received 0x10001 bytes on stream 10, allowed 0x10000 bytes")) + Expect(controller.UpdateHighestReceived(receiveWindow+1, false)).To(MatchError("FLOW_CONTROL_ERROR: Received 10001 bytes on stream 10, allowed 10000 bytes")) }) It("accepts a final offset higher than the highest received", func() { @@ -108,8 +108,8 @@ var _ = Describe("Stream Flow controller", func() { }) It("errors when receiving a final offset smaller than the highest offset received so far", func() { - controller.UpdateHighestReceived(0x100, false) - Expect(controller.UpdateHighestReceived(0xff, true)).To(MatchError("FINAL_SIZE_ERROR: Received final offset 0xff for stream 10, but already received offset 0x100 before")) + controller.UpdateHighestReceived(100, false) + Expect(controller.UpdateHighestReceived(50, true)).To(MatchError("FINAL_SIZE_ERROR: Received final offset 50 for stream 10, but already received offset 100 before")) }) It("accepts delayed data after receiving a final offset", func() { @@ -118,8 +118,8 @@ var _ = Describe("Stream Flow controller", func() { }) It("errors when receiving a higher offset after receiving a final offset", func() { - Expect(controller.UpdateHighestReceived(0x200, true)).To(Succeed()) - Expect(controller.UpdateHighestReceived(0x250, false)).To(MatchError("FINAL_SIZE_ERROR: Received offset 0x250 for stream 10. Final offset was already received at 0x200")) + Expect(controller.UpdateHighestReceived(200, true)).To(Succeed()) + Expect(controller.UpdateHighestReceived(250, false)).To(MatchError("FINAL_SIZE_ERROR: Received offset 250 for stream 10. Final offset was already received at 200")) }) It("accepts duplicate final offsets", func() { @@ -129,8 +129,8 @@ var _ = Describe("Stream Flow controller", func() { }) It("errors when receiving inconsistent final offsets", func() { - Expect(controller.UpdateHighestReceived(0x200, true)).To(Succeed()) - Expect(controller.UpdateHighestReceived(0x201, true)).To(MatchError("FINAL_SIZE_ERROR: Received inconsistent final offset for stream 10 (old: 0x200, new: 0x201 bytes)")) + Expect(controller.UpdateHighestReceived(200, true)).To(Succeed()) + Expect(controller.UpdateHighestReceived(201, true)).To(MatchError("FINAL_SIZE_ERROR: Received inconsistent final offset for stream 10 (old: 200, new: 201 bytes)")) }) It("tells the connection flow controller when a stream is abandoned", func() { diff --git a/internal/wire/log.go b/internal/wire/log.go index c2792161..34617822 100644 --- a/internal/wire/log.go +++ b/internal/wire/log.go @@ -20,9 +20,11 @@ func LogFrame(logger utils.Logger, frame Frame, sent bool) { switch f := frame.(type) { case *CryptoFrame: dataLen := protocol.ByteCount(len(f.Data)) - logger.Debugf("\t%s &wire.CryptoFrame{Offset: 0x%x, Data length: 0x%x, Offset + Data length: 0x%x}", dir, f.Offset, dataLen, f.Offset+dataLen) + logger.Debugf("\t%s &wire.CryptoFrame{Offset: %d, Data length: %d, Offset + Data length: %d}", dir, f.Offset, dataLen, f.Offset+dataLen) case *StreamFrame: - logger.Debugf("\t%s &wire.StreamFrame{StreamID: %d, FinBit: %t, Offset: 0x%x, Data length: 0x%x, Offset + Data length: 0x%x}", dir, f.StreamID, f.FinBit, f.Offset, f.DataLen(), f.Offset+f.DataLen()) + logger.Debugf("\t%s &wire.StreamFrame{StreamID: %d, FinBit: %t, Offset: %d, Data length: %d, Offset + Data length: %d}", dir, f.StreamID, f.FinBit, f.Offset, f.DataLen(), f.Offset+f.DataLen()) + case *ResetStreamFrame: + logger.Debugf("\t%s &wire.ResetStreamFrame{StreamID: %d, ErrorCode: %#x, ByteOffset: %d}", dir, f.StreamID, f.ErrorCode, f.ByteOffset) case *AckFrame: if len(f.AckRanges) > 1 { ackRanges := make([]string, len(f.AckRanges)) @@ -33,6 +35,14 @@ func LogFrame(logger utils.Logger, frame Frame, sent bool) { } else { logger.Debugf("\t%s &wire.AckFrame{LargestAcked: %d, LowestAcked: %d, DelayTime: %s}", dir, f.LargestAcked(), f.LowestAcked(), f.DelayTime.String()) } + case *MaxDataFrame: + logger.Debugf("\t%s &wire.MaxDataFrame{ByteOffset: %d}", dir, f.ByteOffset) + case *MaxStreamDataFrame: + logger.Debugf("\t%s &wire.MaxStreamDataFrame{StreamID: %d, ByteOffset: %d}", dir, f.StreamID, f.ByteOffset) + case *DataBlockedFrame: + logger.Debugf("\t%s &wire.DataBlockedFrame{DataLimit: %d}", dir, f.DataLimit) + case *StreamDataBlockedFrame: + logger.Debugf("\t%s &wire.StreamDataBlockedFrame{StreamID: %d, DataLimit: %d}", dir, f.StreamID, f.DataLimit) case *MaxStreamsFrame: switch f.Type { case protocol.StreamTypeUni: diff --git a/internal/wire/log_test.go b/internal/wire/log_test.go index 9cfdeb27..c8e5f694 100644 --- a/internal/wire/log_test.go +++ b/internal/wire/log_test.go @@ -38,32 +38,32 @@ var _ = Describe("Frame logging", func() { It("logs sent frames", func() { LogFrame(logger, &ResetStreamFrame{}, true) - Expect(buf.Bytes()).To(ContainSubstring("\t-> &wire.ResetStreamFrame{StreamID:0, ErrorCode:0x0, ByteOffset:0x0}\n")) + Expect(buf.String()).To(ContainSubstring("\t-> &wire.ResetStreamFrame{StreamID: 0, ErrorCode: 0x0, ByteOffset: 0}\n")) }) It("logs received frames", func() { LogFrame(logger, &ResetStreamFrame{}, false) - Expect(buf.Bytes()).To(ContainSubstring("\t<- &wire.ResetStreamFrame{StreamID:0, ErrorCode:0x0, ByteOffset:0x0}\n")) + Expect(buf.String()).To(ContainSubstring("\t<- &wire.ResetStreamFrame{StreamID: 0, ErrorCode: 0x0, ByteOffset: 0}\n")) }) It("logs CRYPTO frames", func() { frame := &CryptoFrame{ - Offset: 0x42, - Data: make([]byte, 0x123), + Offset: 42, + Data: make([]byte, 123), } LogFrame(logger, frame, false) - Expect(buf.Bytes()).To(ContainSubstring("\t<- &wire.CryptoFrame{Offset: 0x42, Data length: 0x123, Offset + Data length: 0x165}\n")) + Expect(buf.String()).To(ContainSubstring("\t<- &wire.CryptoFrame{Offset: 42, Data length: 123, Offset + Data length: 165}\n")) }) It("logs STREAM frames", func() { frame := &StreamFrame{ StreamID: 42, - Offset: 0x1337, - Data: bytes.Repeat([]byte{'f'}, 0x100), + Offset: 1337, + Data: bytes.Repeat([]byte{'f'}, 100), } LogFrame(logger, frame, false) - Expect(buf.Bytes()).To(ContainSubstring("\t<- &wire.StreamFrame{StreamID: 42, FinBit: false, Offset: 0x1337, Data length: 0x100, Offset + Data length: 0x1437}\n")) + Expect(buf.String()).To(ContainSubstring("\t<- &wire.StreamFrame{StreamID: 42, FinBit: false, Offset: 1337, Data length: 100, Offset + Data length: 1437}\n")) }) It("logs ACK frames without missing packets", func() { @@ -96,6 +96,40 @@ var _ = Describe("Frame logging", func() { Expect(buf.String()).To(ContainSubstring("\t<- &wire.MaxStreamsFrame{Type: bidi, MaxStreamNum: 42}\n")) }) + It("logs MAX_DATA frames", func() { + frame := &MaxDataFrame{ + ByteOffset: 42, + } + LogFrame(logger, frame, false) + Expect(buf.String()).To(ContainSubstring("\t<- &wire.MaxDataFrame{ByteOffset: 42}\n")) + }) + + It("logs MAX_STREAM_DATA frames", func() { + frame := &MaxStreamDataFrame{ + StreamID: 10, + ByteOffset: 42, + } + LogFrame(logger, frame, false) + Expect(buf.String()).To(ContainSubstring("\t<- &wire.MaxStreamDataFrame{StreamID: 10, ByteOffset: 42}\n")) + }) + + It("logs DATA_BLOCKED frames", func() { + frame := &DataBlockedFrame{ + DataLimit: 1000, + } + LogFrame(logger, frame, false) + Expect(buf.String()).To(ContainSubstring("\t<- &wire.DataBlockedFrame{DataLimit: 1000}\n")) + }) + + It("logs STREAM_DATA_BLOCKED frames", func() { + frame := &StreamDataBlockedFrame{ + StreamID: 42, + DataLimit: 1000, + } + LogFrame(logger, frame, false) + Expect(buf.String()).To(ContainSubstring("\t<- &wire.StreamDataBlockedFrame{StreamID: 42, DataLimit: 1000}\n")) + }) + It("logs STREAMS_BLOCKED frames", func() { frame := &StreamsBlockedFrame{ Type: protocol.StreamTypeBidi, diff --git a/internal/wire/transport_parameter_test.go b/internal/wire/transport_parameter_test.go index 56bb8011..ecd0c298 100644 --- a/internal/wire/transport_parameter_test.go +++ b/internal/wire/transport_parameter_test.go @@ -26,10 +26,10 @@ var _ = Describe("Transport Parameters", func() { It("has a string representation", func() { p := &TransportParameters{ - InitialMaxStreamDataBidiLocal: 0x1234, - InitialMaxStreamDataBidiRemote: 0x2345, - InitialMaxStreamDataUni: 0x3456, - InitialMaxData: 0x4567, + InitialMaxStreamDataBidiLocal: 1234, + InitialMaxStreamDataBidiRemote: 2345, + InitialMaxStreamDataUni: 3456, + InitialMaxData: 4567, MaxBidiStreamNum: 1337, MaxUniStreamNum: 7331, MaxIdleTimeout: 42 * time.Second, @@ -39,15 +39,15 @@ var _ = Describe("Transport Parameters", func() { StatelessResetToken: &[16]byte{0x11, 0x22, 0x33, 0x44, 0x55, 0x66, 0x77, 0x88, 0x99, 0xaa, 0xbb, 0xcc, 0xdd, 0xee, 0xff, 0x00}, ActiveConnectionIDLimit: 123, } - Expect(p.String()).To(Equal("&wire.TransportParameters{OriginalConnectionID: 0xdeadbeef, InitialMaxStreamDataBidiLocal: 0x1234, InitialMaxStreamDataBidiRemote: 0x2345, InitialMaxStreamDataUni: 0x3456, InitialMaxData: 0x4567, MaxBidiStreamNum: 1337, MaxUniStreamNum: 7331, MaxIdleTimeout: 42s, AckDelayExponent: 14, MaxAckDelay: 37ms, ActiveConnectionIDLimit: 123, StatelessResetToken: 0x112233445566778899aabbccddeeff00}")) + Expect(p.String()).To(Equal("&wire.TransportParameters{OriginalConnectionID: 0xdeadbeef, InitialMaxStreamDataBidiLocal: 1234, InitialMaxStreamDataBidiRemote: 2345, InitialMaxStreamDataUni: 3456, InitialMaxData: 4567, MaxBidiStreamNum: 1337, MaxUniStreamNum: 7331, MaxIdleTimeout: 42s, AckDelayExponent: 14, MaxAckDelay: 37ms, ActiveConnectionIDLimit: 123, StatelessResetToken: 0x112233445566778899aabbccddeeff00}")) }) It("has a string representation, if there's no stateless reset token", func() { p := &TransportParameters{ - InitialMaxStreamDataBidiLocal: 0x1234, - InitialMaxStreamDataBidiRemote: 0x2345, - InitialMaxStreamDataUni: 0x3456, - InitialMaxData: 0x4567, + InitialMaxStreamDataBidiLocal: 1234, + InitialMaxStreamDataBidiRemote: 2345, + InitialMaxStreamDataUni: 3456, + InitialMaxData: 4567, MaxBidiStreamNum: 1337, MaxUniStreamNum: 7331, MaxIdleTimeout: 42 * time.Second, @@ -56,7 +56,7 @@ var _ = Describe("Transport Parameters", func() { MaxAckDelay: 37 * time.Second, ActiveConnectionIDLimit: 89, } - Expect(p.String()).To(Equal("&wire.TransportParameters{OriginalConnectionID: 0xdeadbeef, InitialMaxStreamDataBidiLocal: 0x1234, InitialMaxStreamDataBidiRemote: 0x2345, InitialMaxStreamDataUni: 0x3456, InitialMaxData: 0x4567, MaxBidiStreamNum: 1337, MaxUniStreamNum: 7331, MaxIdleTimeout: 42s, AckDelayExponent: 14, MaxAckDelay: 37s, ActiveConnectionIDLimit: 89}")) + Expect(p.String()).To(Equal("&wire.TransportParameters{OriginalConnectionID: 0xdeadbeef, InitialMaxStreamDataBidiLocal: 1234, InitialMaxStreamDataBidiRemote: 2345, InitialMaxStreamDataUni: 3456, InitialMaxData: 4567, MaxBidiStreamNum: 1337, MaxUniStreamNum: 7331, MaxIdleTimeout: 42s, AckDelayExponent: 14, MaxAckDelay: 37s, ActiveConnectionIDLimit: 89}")) }) It("marshals and unmarshals", func() { diff --git a/internal/wire/transport_parameters.go b/internal/wire/transport_parameters.go index dd51cf34..2d02f399 100644 --- a/internal/wire/transport_parameters.go +++ b/internal/wire/transport_parameters.go @@ -416,7 +416,7 @@ func (p *TransportParameters) ValidFor0RTT(tp *TransportParameters) bool { // String returns a string representation, intended for logging. func (p *TransportParameters) String() string { - logString := "&wire.TransportParameters{OriginalConnectionID: %s, InitialMaxStreamDataBidiLocal: %#x, InitialMaxStreamDataBidiRemote: %#x, InitialMaxStreamDataUni: %#x, InitialMaxData: %#x, MaxBidiStreamNum: %d, MaxUniStreamNum: %d, MaxIdleTimeout: %s, AckDelayExponent: %d, MaxAckDelay: %s, ActiveConnectionIDLimit: %d" + logString := "&wire.TransportParameters{OriginalConnectionID: %s, InitialMaxStreamDataBidiLocal: %d, InitialMaxStreamDataBidiRemote: %d, InitialMaxStreamDataUni: %d, InitialMaxData: %d, MaxBidiStreamNum: %d, MaxUniStreamNum: %d, MaxIdleTimeout: %s, AckDelayExponent: %d, MaxAckDelay: %s, ActiveConnectionIDLimit: %d" logParams := []interface{}{p.OriginalConnectionID, p.InitialMaxStreamDataBidiLocal, p.InitialMaxStreamDataBidiRemote, p.InitialMaxStreamDataUni, p.InitialMaxData, p.MaxBidiStreamNum, p.MaxUniStreamNum, p.MaxIdleTimeout, p.AckDelayExponent, p.MaxAckDelay, p.ActiveConnectionIDLimit} if p.StatelessResetToken != nil { // the client never sends a stateless reset token logString += ", StatelessResetToken: %#x"