Skip to content

Commit

Permalink
fix: use trace logging for happy paths (#35)
Browse files Browse the repository at this point in the history 
* fix: use trace logging for happy paths

Updates logging to use `.trace` where the code is on the happy path.

Being able to debug behaviour is useful but the logs are very noisy
for when you're not debugging yamux.

* chore: use error log for errors
  • Loading branch information
@achingbrain
achingbrain authored Apr 16, 2023
1 parent f16b2ae commit 2c64584
Show file tree
Hide file tree
Showing 2 changed files with 35 additions and 22 deletions.
28 changes: 16 additions & 12 deletions src/muxer.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -90,7 +90,7 @@ export class YamuxMuxer implements StreamMuxer {

this.source = pushable({
onEnd: (err?: Error): void => {
this.log?.('muxer source ended')
this.log?.trace('muxer source ended')
this.close(err)
}
})
Expand Down Expand Up @@ -139,7 +139,7 @@ export class YamuxMuxer implements StreamMuxer {
}
}

this.log?.('muxer sink ended')
this.log?.trace('muxer sink ended')

this.close(error, reason)
}
Expand All @@ -153,7 +153,7 @@ export class YamuxMuxer implements StreamMuxer {
this.nextPingID = 0
this.rtt = 0

this.log?.('muxer created')
this.log?.trace('muxer created')

if (this.config.enableKeepAlive) {
this.keepAliveLoop().catch(e => this.log?.error('keepalive error: %s', e))
Expand All @@ -180,7 +180,7 @@ export class YamuxMuxer implements StreamMuxer {
throw new CodeError('max outbound streams exceeded', ERR_MAX_OUTBOUND_STREAMS_EXCEEDED)
}

this.log?.('new outgoing stream id=%s', id)
this.log?.trace('new outgoing stream id=%s', id)

const stream = this._newStream(id, name, StreamState.Init, 'outbound')
this._streams.set(id, stream)
Expand Down Expand Up @@ -274,7 +274,11 @@ export class YamuxMuxer implements StreamMuxer {
// If reason was provided, use that, otherwise use the presence of `err` to determine the reason
reason = reason ?? (err === undefined ? GoAwayCode.InternalError : GoAwayCode.NormalTermination)

this.log?.('muxer close reason=%s error=%s', GoAwayCode[reason], err)
if (err != null) {
this.log?.error('muxer close reason=%s error=%s', GoAwayCode[reason], err)
} else {
this.log?.trace('muxer close reason=%s', GoAwayCode[reason])
}

// If err is provided, abort all underlying streams, else close all underlying streams
if (err === undefined) {
Expand Down Expand Up @@ -347,7 +351,7 @@ export class YamuxMuxer implements StreamMuxer {

private async keepAliveLoop (): Promise<void> {
const abortPromise = new Promise((_resolve, reject) => { this.closeController.signal.addEventListener('abort', reject, { once: true }) })
this.log?.('muxer keepalive enabled interval=%s', this.config.keepAliveInterval)
this.log?.trace('muxer keepalive enabled interval=%s', this.config.keepAliveInterval)
while (true) {
let timeoutId
try {
Expand Down Expand Up @@ -399,10 +403,10 @@ export class YamuxMuxer implements StreamMuxer {
private handlePing (header: FrameHeader): void {
// If the ping is initiated by the sender, send a response
if (header.flag === Flag.SYN) {
this.log?.('received ping request pingId=%s', header.length)
this.log?.trace('received ping request pingId=%s', header.length)
this.sendPing(header.length, Flag.ACK)
} else if (header.flag === Flag.ACK) {
this.log?.('received ping response pingId=%s', header.length)
this.log?.trace('received ping response pingId=%s', header.length)
this.handlePingResponse(header.length)
} else {
// Invalid state
Expand All @@ -425,7 +429,7 @@ export class YamuxMuxer implements StreamMuxer {
}

private handleGoAway (reason: GoAwayCode): void {
this.log?.('received GoAway reason=%s', GoAwayCode[reason] ?? 'unknown')
this.log?.trace('received GoAway reason=%s', GoAwayCode[reason] ?? 'unknown')
this.remoteGoAway = reason

// If the other side is friendly, they would have already closed all streams before sending a GoAway
Expand Down Expand Up @@ -482,7 +486,7 @@ export class YamuxMuxer implements StreamMuxer {
return
}

this.log?.('new incoming stream id=%s', id)
this.log?.trace('new incoming stream id=%s', id)

if (this.localGoAway !== undefined) {
// reject (reset) immediately if we are doing a go away
Expand Down Expand Up @@ -530,9 +534,9 @@ export class YamuxMuxer implements StreamMuxer {

private sendPing (pingId: number, flag: Flag = Flag.SYN): void {
if (flag === Flag.SYN) {
this.log?.('sending ping request pingId=%s', pingId)
this.log?.trace('sending ping request pingId=%s', pingId)
} else {
this.log?.('sending ping response pingId=%s', pingId)
this.log?.trace('sending ping response pingId=%s', pingId)
}
this.sendFrame({
type: FrameType.Ping,
Expand Down
29 changes: 19 additions & 10 deletions src/stream.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -114,7 +114,12 @@ export class YamuxStream implements Stream {

this.sourceInput = pushable({
onEnd: (err?: Error) => {
this.log?.('stream source ended id=%s', this._id, err)
if (err != null) {
this.log?.error('stream source ended id=%s', this._id, err)
} else {
this.log?.trace('stream source ended id=%s', this._id)
}

this.closeRead()
}
})
Expand Down Expand Up @@ -145,7 +150,7 @@ export class YamuxStream implements Stream {
} catch (e) {
this.log?.error('stream sink error id=%s', this._id, e)
} finally {
this.log?.('stream sink ended id=%s', this._id)
this.log?.trace('stream sink ended id=%s', this._id)
this.closeWrite()
}
}
Expand All @@ -167,7 +172,7 @@ export class YamuxStream implements Stream {
}

close (): void {
this.log?.('stream close id=%s', this._id)
this.log?.trace('stream close id=%s', this._id)
this.closeRead()
this.closeWrite()
}
Expand All @@ -181,7 +186,7 @@ export class YamuxStream implements Stream {
return
}

this.log?.('stream close read id=%s', this._id)
this.log?.trace('stream close read id=%s', this._id)

this.readState = HalfStreamState.Closed

Expand All @@ -203,7 +208,7 @@ export class YamuxStream implements Stream {
return
}

this.log?.('stream close write id=%s', this._id)
this.log?.trace('stream close write id=%s', this._id)

this.writeState = HalfStreamState.Closed

Expand Down Expand Up @@ -235,7 +240,11 @@ export class YamuxStream implements Stream {
throw new Error('unreachable')
}

this.log?.('stream abort id=%s error=%s', this._id, err)
if (err != null) {
this.log?.error('stream abort id=%s error=%s', this._id, err)
} else {
this.log?.trace('stream abort id=%s', this._id)
}

this.onReset(new CodeError(String(err) ?? 'stream aborted', ERR_STREAM_ABORT))
}
Expand All @@ -245,7 +254,7 @@ export class YamuxStream implements Stream {
return
}

this.log?.('stream reset id=%s', this._id)
this.log?.trace('stream reset id=%s', this._id)

this.onReset(new CodeError('stream reset', ERR_STREAM_RESET))
}
Expand Down Expand Up @@ -301,7 +310,7 @@ export class YamuxStream implements Stream {
* handleWindowUpdate is called when the stream receives a window update frame
*/
handleWindowUpdate (header: FrameHeader): void {
this.log?.('stream received window update id=%s', this._id)
this.log?.trace('stream received window update id=%s', this._id)
this.processFlags(header.flag)

// increase send window
Expand All @@ -317,7 +326,7 @@ export class YamuxStream implements Stream {
* handleData is called when the stream receives a data frame
*/
async handleData (header: FrameHeader, readData: () => Promise<Uint8ArrayList>): Promise<void> {
this.log?.('stream received data id=%s', this._id)
this.log?.trace('stream received data id=%s', this._id)
this.processFlags(header.flag)

// check that our recv window is not exceeded
Expand Down Expand Up @@ -351,7 +360,7 @@ export class YamuxStream implements Stream {
* finish sets the state and triggers eventual garbage collection of the stream
*/
private finish (): void {
this.log?.('stream finished id=%s', this._id)
this.log?.trace('stream finished id=%s', this._id)
this.state = StreamState.Finished
this.stat.timeline.close = Date.now()
this.onStreamEnd()
Expand Down

0 comments on commit 2c64584

Please sign in to comment.