mirrors/uquic
1
0
Fork 0
mirror of https://github.com/refraction-networking/uquic.git synced 2025-04-03 20:27:35 +03:00
Code Issues Projects Releases Packages Wiki Activity

use decimal number for logging stream offsets and byte counts

Browse source
This commit is contained in:
Marten Seemann 2020-04-15 15:42:54 +07:00
parent 140b90449b
commit e116e2f4cc
6 changed files with 77 additions and 33 deletions
Download patch file Download diff file Expand all files Collapse all files

8
internal/flowcontrol/stream_flow_controller.go
View file

@ -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)
}

16
internal/flowcontrol/stream_flow_controller_test.go
View file

@ -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() {

14
internal/wire/log.go
View file

@ -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:

50
internal/wire/log_test.go
View file

@ -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,

20
internal/wire/transport_parameter_test.go
View file

@ -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() {

2
internal/wire/transport_parameters.go
View file

@ -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"