Skip to content

Commit 4b6ea2b

Browse files
murgatroid99murgatroid99
committed
Add channelz ID to trace logs, add a few trace log lines
1 parent d60c4ea commit 4b6ea2b

File tree

3 files changed

+59
-74
lines changed

3 files changed

+59
-74
lines changed

‎packages/grpc-js/src/channel.ts

Lines changed: 22 additions & 34 deletions
Original file line numberDiff line numberDiff line change
@@ -297,13 +297,7 @@ export class ChannelImplementation implements Channel {
297297
(status) => {
298298
this.channelzTrace.addTrace('CT_WARNING', 'Address resolution failed with code ' + status.code + ' and details "' + status.details + '"');
299299
if (this.configSelectionQueue.length > 0) {
300-
trace(
301-
LogVerbosity.DEBUG,
302-
'channel',
303-
'Name resolution failed for target ' +
304-
uriToString(this.target) +
305-
' with calls queued for config selection'
306-
);
300+
this.trace('Name resolution failed with calls queued for config selection');
307301
}
308302
const localQueue = this.configSelectionQueue;
309303
this.configSelectionQueue = [];
@@ -324,6 +318,7 @@ export class ChannelImplementation implements Channel {
324318
new MaxMessageSizeFilterFactory(this.options),
325319
new CompressionFilterFactory(this),
326320
]);
321+
this.trace('Constructed channel');
327322
}
328323

329324
private getChannelzInfo(): ChannelInfo {
@@ -336,12 +331,14 @@ export class ChannelImplementation implements Channel {
336331
};
337332
}
338333

334+
private trace(text: string, verbosityOverride?: LogVerbosity) {
335+
trace(verbosityOverride ?? LogVerbosity.DEBUG, 'channel', '(' + this.channelzRef.id + ') ' + uriToString(this.target) + ' ' + text);
336+
}
337+
339338
private callRefTimerRef() {
340339
// If the hasRef function does not exist, always run the code
341340
if (!this.callRefTimer.hasRef?.()) {
342-
trace(
343-
LogVerbosity.DEBUG,
344-
'channel',
341+
this.trace(
345342
'callRefTimer.ref | configSelectionQueue.length=' +
346343
this.configSelectionQueue.length +
347344
' pickQueue.length=' +
@@ -354,9 +351,7 @@ export class ChannelImplementation implements Channel {
354351
private callRefTimerUnref() {
355352
// If the hasRef function does not exist, always run the code
356353
if (!this.callRefTimer.hasRef || this.callRefTimer.hasRef()) {
357-
trace(
358-
LogVerbosity.DEBUG,
359-
'channel',
354+
this.trace(
360355
'callRefTimer.unref | configSelectionQueue.length=' +
361356
this.configSelectionQueue.length +
362357
' pickQueue.length=' +
@@ -391,9 +386,7 @@ export class ChannelImplementation implements Channel {
391386
metadata: callMetadata,
392387
extraPickInfo: callConfig.pickInformation,
393388
});
394-
trace(
395-
LogVerbosity.DEBUG,
396-
'channel',
389+
this.trace(
397390
'Pick result: ' +
398391
PickResultType[pickResult.pickResultType] +
399392
' subchannel: ' +
@@ -466,25 +459,23 @@ export class ChannelImplementation implements Channel {
466459
* the stream because the correct behavior may be
467460
* re-queueing instead, based on the logic in the rest of
468461
* tryPick */
469-
trace(
470-
LogVerbosity.INFO,
471-
'channel',
462+
this.trace(
472463
'Failed to start call on picked subchannel ' +
473464
pickResult.subchannel!.getAddress() +
474465
' with error ' +
475466
(error as Error).message +
476-
'. Retrying pick'
467+
'. Retrying pick',
468+
LogVerbosity.INFO
477469
);
478470
this.tryPick(callStream, callMetadata, callConfig);
479471
} else {
480-
trace(
481-
LogVerbosity.INFO,
482-
'channel',
472+
this.trace(
483473
'Failed to start call on picked subchanel ' +
484474
pickResult.subchannel!.getAddress() +
485475
' with error ' +
486476
(error as Error).message +
487-
'. Ending call'
477+
'. Ending call',
478+
LogVerbosity.INFO
488479
);
489480
callStream.cancelWithStatus(
490481
Status.INTERNAL,
@@ -497,14 +488,13 @@ export class ChannelImplementation implements Channel {
497488
} else {
498489
/* The logic for doing this here is the same as in the catch
499490
* block above */
500-
trace(
501-
LogVerbosity.INFO,
502-
'channel',
491+
this.trace(
503492
'Picked subchannel ' +
504493
pickResult.subchannel!.getAddress() +
505494
' has state ' +
506495
ConnectivityState[subchannelState] +
507-
' after metadata filters. Retrying pick'
496+
' after metadata filters. Retrying pick',
497+
LogVerbosity.INFO
508498
);
509499
this.tryPick(callStream, callMetadata, callConfig);
510500
}
@@ -560,7 +550,8 @@ export class ChannelImplementation implements Channel {
560550
trace(
561551
LogVerbosity.DEBUG,
562552
'connectivity_state',
563-
uriToString(this.target) +
553+
'(' + this.channelzRef.id + ') ' +
554+
uriToString(this.target) +
564555
' ' +
565556
ConnectivityState[this.connectivityState] +
566557
' -> ' +
@@ -706,11 +697,8 @@ export class ChannelImplementation implements Channel {
706697
throw new Error('Channel has been shut down');
707698
}
708699
const callNumber = getNewCallNumber();
709-
trace(
710-
LogVerbosity.DEBUG,
711-
'channel',
712-
uriToString(this.target) +
713-
' createCall [' +
700+
this.trace(
701+
'createCall [' +
714702
callNumber +
715703
'] method="' +
716704
method +

‎packages/grpc-js/src/server.ts

Lines changed: 11 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -64,10 +64,6 @@ import { CipherNameAndProtocol, TLSSocket } from 'tls';
6464

6565
const TRACER_NAME = 'server';
6666

67-
function trace(text: string): void {
68-
logging.trace(LogVerbosity.DEBUG, TRACER_NAME, text);
69-
}
70-
7167
interface BindResult {
7268
port: number;
7369
count: number;
@@ -163,6 +159,7 @@ export class Server {
163159
this.options = options ?? {};
164160
this.channelzRef = registerChannelzServer(() => this.getChannelzInfo());
165161
this.channelzTrace.addTrace('CT_INFO', 'Server created');
162+
this.trace('Server constructed');
166163
}
167164

168165
private getChannelzInfo(): ServerInfo {
@@ -217,6 +214,11 @@ export class Server {
217214
};
218215
}
219216

217+
private trace(text: string): void {
218+
logging.trace(LogVerbosity.DEBUG, TRACER_NAME, '(' + this.channelzRef.id + ') ' + text);
219+
}
220+
221+
220222
addProtoService(): void {
221223
throw new Error('Not implemented. Use addService() instead');
222224
}
@@ -372,7 +374,7 @@ export class Server {
372374
}
373375
return Promise.all(
374376
addressList.map((address) => {
375-
trace('Attempting to bind ' + subchannelAddressToString(address));
377+
this.trace('Attempting to bind ' + subchannelAddressToString(address));
376378
let addr: SubchannelAddress;
377379
if (isTcpSubchannelAddress(address)) {
378380
addr = {
@@ -426,7 +428,7 @@ export class Server {
426428
});
427429
this.listenerChildrenTracker.refChild(channelzRef);
428430
this.http2ServerList.push({server: http2Server, channelzRef: channelzRef});
429-
trace('Successfully bound ' + subchannelAddressToString(boundSubchannelAddress));
431+
this.trace('Successfully bound ' + subchannelAddressToString(boundSubchannelAddress));
430432
resolve('port' in boundSubchannelAddress ? boundSubchannelAddress.port : portNum);
431433
http2Server.removeListener('error', onError);
432434
});
@@ -494,7 +496,7 @@ export class Server {
494496
});
495497
this.listenerChildrenTracker.refChild(channelzRef);
496498
this.http2ServerList.push({server: http2Server, channelzRef: channelzRef});
497-
trace('Successfully bound ' + subchannelAddressToString(boundSubchannelAddress));
499+
this.trace('Successfully bound ' + subchannelAddressToString(boundSubchannelAddress));
498500
resolve(
499501
bindSpecificPort(
500502
addressList.slice(1),
@@ -727,7 +729,7 @@ export class Server {
727729
serverAddress.address + ':' + serverAddress.port;
728730
}
729731
}
730-
trace(
732+
this.trace(
731733
'Received call to method ' +
732734
path +
733735
' at address ' +
@@ -736,7 +738,7 @@ export class Server {
736738
const handler = this.handlers.get(path);
737739

738740
if (handler === undefined) {
739-
trace(
741+
this.trace(
740742
'No handler registered for method ' +
741743
path +
742744
'. Sending UNIMPLEMENTED status.'

‎packages/grpc-js/src/subchannel.ts

Lines changed: 26 additions & 31 deletions
Original file line numberDiff line numberDiff line change
@@ -42,14 +42,6 @@ const clientVersion = require('../../package.json').version;
4242

4343
const TRACER_NAME = 'subchannel';
4444

45-
function trace(text: string): void {
46-
logging.trace(LogVerbosity.DEBUG, TRACER_NAME, text);
47-
}
48-
49-
function refTrace(text: string): void {
50-
logging.trace(LogVerbosity.DEBUG, 'subchannel_refcount', text);
51-
}
52-
5345
const MIN_CONNECT_TIMEOUT_MS = 20000;
5446
const INITIAL_BACKOFF_MS = 1000;
5547
const BACKOFF_MULTIPLIER = 1.6;
@@ -237,6 +229,7 @@ export class Subchannel {
237229
this.channelzRef = registerChannelzSubchannel(this.subchannelAddressString, () => this.getChannelzInfo());
238230
this.channelzTrace = new ChannelzTrace();
239231
this.channelzTrace.addTrace('CT_INFO', 'Subchannel created');
232+
this.trace('Subchannel constructed');
240233
}
241234

242235
private getChannelzInfo(): SubchannelInfo {
@@ -307,6 +300,14 @@ export class Subchannel {
307300
this.lastMessageReceivedTimestamp = null;
308301
}
309302

303+
private trace(text: string): void {
304+
logging.trace(LogVerbosity.DEBUG, TRACER_NAME, '(' + this.channelzRef.id + ') ' + this.subchannelAddressString + ' ' + text);
305+
}
306+
307+
private refTrace(text: string): void {
308+
logging.trace(LogVerbosity.DEBUG, 'subchannel_refcount', '(' + this.channelzRef.id + ') ' + this.subchannelAddressString + ' ' + text);
309+
}
310+
310311
private handleBackoffTimer() {
311312
if (this.continueConnecting) {
312313
this.transitionToState(
@@ -338,7 +339,8 @@ export class Subchannel {
338339
logging.trace(
339340
LogVerbosity.DEBUG,
340341
'keepalive',
341-
'Sending ping to ' + this.subchannelAddressString
342+
'(' + this.channelzRef.id + ') ' + this.subchannelAddressString + ' ' +
343+
'Sending ping'
342344
);
343345
this.keepaliveTimeoutId = setTimeout(() => {
344346
this.transitionToState([ConnectivityState.READY], ConnectivityState.IDLE);
@@ -511,9 +513,8 @@ export class Subchannel {
511513
} ms`
512514
);
513515
}
514-
trace(
515-
this.subchannelAddressString +
516-
' connection closed by GOAWAY with code ' +
516+
this.trace(
517+
'connection closed by GOAWAY with code ' +
517518
errorCode
518519
);
519520
this.transitionToState(
@@ -526,9 +527,8 @@ export class Subchannel {
526527
session.once('error', (error) => {
527528
/* Do nothing here. Any error should also trigger a close event, which is
528529
* where we want to handle that. */
529-
trace(
530-
this.subchannelAddressString +
531-
' connection closed with error ' +
530+
this.trace(
531+
'connection closed with error ' +
532532
(error as Error).message
533533
);
534534
});
@@ -607,10 +607,8 @@ export class Subchannel {
607607
if (oldStates.indexOf(this.connectivityState) === -1) {
608608
return false;
609609
}
610-
trace(
611-
this.subchannelAddressString +
612-
' ' +
613-
ConnectivityState[this.connectivityState] +
610+
this.trace(
611+
ConnectivityState[this.connectivityState] +
614612
' -> ' +
615613
ConnectivityState[newState]
616614
);
@@ -687,9 +685,8 @@ export class Subchannel {
687685
}
688686

689687
callRef() {
690-
refTrace(
691-
this.subchannelAddressString +
692-
' callRefcount ' +
688+
this.refTrace(
689+
'callRefcount ' +
693690
this.callRefcount +
694691
' -> ' +
695692
(this.callRefcount + 1)
@@ -707,9 +704,8 @@ export class Subchannel {
707704
}
708705

709706
callUnref() {
710-
refTrace(
711-
this.subchannelAddressString +
712-
' callRefcount ' +
707+
this.refTrace(
708+
'callRefcount ' +
713709
this.callRefcount +
714710
' -> ' +
715711
(this.callRefcount - 1)
@@ -728,9 +724,8 @@ export class Subchannel {
728724
}
729725

730726
ref() {
731-
refTrace(
732-
this.subchannelAddressString +
733-
' refcount ' +
727+
this.refTrace(
728+
'refcount ' +
734729
this.refcount +
735730
' -> ' +
736731
(this.refcount + 1)
@@ -739,9 +734,8 @@ export class Subchannel {
739734
}
740735

741736
unref() {
742-
refTrace(
743-
this.subchannelAddressString +
744-
' refcount ' +
737+
this.refTrace(
738+
'refcount ' +
745739
this.refcount +
746740
' -> ' +
747741
(this.refcount - 1)
@@ -803,6 +797,7 @@ export class Subchannel {
803797
LogVerbosity.DEBUG,
804798
'call_stream',
805799
'Starting stream on subchannel ' +
800+
'(' + this.channelzRef.id + ') ' +
806801
this.subchannelAddressString +
807802
' with headers\n' +
808803
headersString

0 commit comments

Comments
 (0)