Skip to content

Introduce Traceformat to allow JSON format log #366

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 6 commits into from
Aug 28, 2018
Merged

Introduce Traceformat to allow JSON format log #366

Show file tree
Hide file tree
Changes from 4 commits
Commits
Show all changes
6 commits
Select commit Hold shift + click to select a range
631cbd1
Introduce Traceformat to allow JSON format log
octref Jun 22, 2018
fa968d7
Address feedback
octref Aug 23, 2018
299f725
Don't break existing API
octref Aug 24, 2018
8e3a1c8
Fix whitespace
octref Aug 24, 2018
78cfde6
Minor type fix
octref Aug 24, 2018
fa28e47
Add TraceOptions and address feedback
octref Aug 24, 2018
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
45 changes: 36 additions & 9 deletions client/src/client.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -22,7 +22,7 @@ import {
RequestType, RequestType0, RequestHandler, RequestHandler0, GenericRequestHandler,
NotificationType, NotificationType0,
NotificationHandler, NotificationHandler0, GenericNotificationHandler,
MessageReader, MessageWriter, Trace, Tracer, Event, Emitter,
MessageReader, MessageWriter, Trace, TraceFormat, Tracer, Event, Emitter,
createProtocolConnection,
ClientCapabilities, WorkspaceEdit,
RegistrationRequest, RegistrationParams, UnregistrationRequest, UnregistrationParams, TextDocumentRegistrationOptions,
Expand Down Expand Up @@ -100,7 +100,7 @@ interface IConnection {
onNotification(method: string, handler: GenericNotificationHandler): void;
onNotification(method: string | RPCMessageType, handler: GenericNotificationHandler): void;

trace(value: Trace, tracer: Tracer, sendNotification?: boolean): void;
trace(value: Trace, tracer: Tracer, sendNotification?: boolean, traceFormat?: TraceFormat): void;

initialize(params: InitializeParams): Thenable<InitializeResult>;
shutdown(): Thenable<void>;
Expand Down Expand Up @@ -161,7 +161,7 @@ function createConnection(input: any, output: any, errorHandler: ConnectionError
sendNotification: (type: string | RPCMessageType, params?: any): void => connection.sendNotification(Is.string(type) ? type : type.method, params),
onNotification: (type: string | RPCMessageType, handler: GenericNotificationHandler): void => connection.onNotification(Is.string(type) ? type : type.method, handler),

trace: (value: Trace, tracer: Tracer, sendNotification: boolean = false): void => connection.trace(value, tracer, sendNotification),
trace: (value: Trace, tracer: Tracer, sendNotification: boolean = false, traceFormat: TraceFormat = TraceFormat.Text): void => connection.trace(value, tracer, sendNotification, traceFormat),
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I know it is easier to implement if we simply add an optional arg at the endd but I would prefer to have to signatures like this:

trace: (value: Trace, tracer: Tracer, sendNotification: boolean = false)
trace: (value: Trace, traceFormat: TraceFormat, tracer: Tracer, sendNotification: boolean = false)

to keep the args together and may be deprecate the old signature.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@dbaeumer Decided to have this:

trace(value: Trace, tracer: Tracer, sendNotification?: boolean): void;
trace(value: Trace, tracer: Tracer, traceOptions?: TraceOptions): void;

// In json-rpc

export interface TraceOptions {
	sendNotification?: boolean;
	traceFormat?: TraceFormat;
}

I initially had what you suggested, but later abandoned it in favor of traceFormat? at the end, as

  • I'd prefer to keep traceFormat optional
  • A call with three args can be of either signature.

With this new one it's easier to detect the params of the overloaded functions, and in the future it's easier to add more options without breaking backward compatibility.

Copy link
Member

@dbaeumer dbaeumer Aug 27, 2018 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

No, this is not what I meant. I was suggesting to have this:

trace: (value: Trace, tracer: Tracer, sendNotification: boolean = false)
trace: (value: Trace, traceFormat: TraceFormat, tracer: Tracer, sendNotification: boolean = false)

with one implementation overload like this:

function trace(arg0: Trace, arg1: Tracer | TraceFormat, arg2?: Tracer | boolean, arg3?: boolean)

There is enough information in the signatures to decide which on is meant.


initialize: (params: InitializeParams) => connection.sendRequest(InitializeRequest.type, params),
shutdown: () => connection.sendRequest(ShutdownRequest.type, undefined),
Expand Down Expand Up @@ -2249,6 +2249,7 @@ export abstract class BaseLanguageClient {
private _stateChangeEmitter: Emitter<StateChangeEvent>;

private _trace: Trace;
private _traceFormat: TraceFormat = TraceFormat.Text;
private _tracer: Tracer;

private _c2p: c2p.Converter;
Expand Down Expand Up @@ -2300,9 +2301,15 @@ export abstract class BaseLanguageClient {
this._telemetryEmitter = new Emitter<any>();
this._stateChangeEmitter = new Emitter<StateChangeEvent>();
this._tracer = {
log: (message: string, data?: string) => {
this.logTrace(message, data);
}
log: (...params: any[]) => {
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Can this not still be message & data and message can be string | any. ...params makes it harder to understand what data can actually come.

if (typeof params[0] === 'string') {
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

There is a Is.string() helper I consistently use.

const [message, data] = params;
this.logTrace(message, data);
} else {
const [data] = params;
this.logObjectTrace(data);
}
},
};
this._c2p = c2p.createConverter(clientOptions.uriConverters ? clientOptions.uriConverters.code2Protocol : undefined);
this._p2c = p2c.createConverter(clientOptions.uriConverters ? clientOptions.uriConverters.protocol2Code : undefined);
Expand Down Expand Up @@ -2438,7 +2445,7 @@ export abstract class BaseLanguageClient {
this._trace = value;
this.onReady().then(() => {
this.resolveConnection().then((connection) => {
connection.trace(value, this._tracer);
connection.trace(this._trace, this._tracer, false, this._traceFormat);
})
}, () => {
});
Expand Down Expand Up @@ -2498,6 +2505,17 @@ export abstract class BaseLanguageClient {
}
}

private logObjectTrace(data: any): void {
if (data.isLSPMessage && data.type) {
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@dbaeumer Not sure if this is what you meant by "if the data is an object then log it by JSON stringify here". Also not sure if that isLSPMessage is the best way to go. If you have better suggestions, let me know!

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

No, in this case I would simply do

this.outputChannel.append(`[LSP   - ${(new Date().toLocaleTimeString())}] `);
this.outputChannel.appendLine(`${JSON.stringify(data)}`);

this.outputChannel.append(`[LSP - ${(new Date().toLocaleTimeString())}] `);
} else {
this.outputChannel.append(`[Trace - ${(new Date().toLocaleTimeString())}] `);
}
if (data) {
this.outputChannel.appendLine(`${JSON.stringify(data)}`);
}
}

public needsStart(): boolean {
return this.state === ClientState.Initial || this.state === ClientState.Stopping || this.state === ClientState.Stopped;
}
Expand Down Expand Up @@ -2846,11 +2864,20 @@ export abstract class BaseLanguageClient {
private refreshTrace(connection: IConnection, sendNotification: boolean = false): void {
let config = Workspace.getConfiguration(this._id);
let trace: Trace = Trace.Off;
let traceFormat: TraceFormat = TraceFormat.Text;
if (config) {
trace = Trace.fromString(config.get('trace.server', 'off'));
const traceConfig = config.get('trace.server', 'off');

if (typeof traceConfig === 'string') {
trace = Trace.fromString(traceConfig);
} else {
trace = Trace.fromString(config.get('trace.server.verbosity', 'off'));
traceFormat = TraceFormat.fromString(config.get('trace.server.format', 'text'));
}
}
this._trace = trace;
connection.trace(this._trace, this._tracer, sendNotification);
this._traceFormat = traceFormat;
connection.trace(this._trace, this._tracer, sendNotification, this._traceFormat);
}


Expand Down
170 changes: 118 additions & 52 deletions jsonrpc/src/main.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -15,7 +15,8 @@ import {
ResponseMessage, isResponseMessage, ResponseError, ErrorCodes,
NotificationMessage, isNotificationMessage,
NotificationType, NotificationType0, NotificationType1, NotificationType2, NotificationType3, NotificationType4,
NotificationType5, NotificationType6, NotificationType7, NotificationType8, NotificationType9
NotificationType5, NotificationType6, NotificationType7, NotificationType8, NotificationType9,
LSPMessageType
} from './messages';

import { MessageReader, DataCallback, StreamMessageReader, IPCMessageReader, SocketMessageReader } from './messageReader';
Expand Down Expand Up @@ -205,6 +206,21 @@ export namespace Trace {
}
}

export enum TraceFormat {
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Instead of having a number enum and a TraceFormatValues would it make sense to use a string Enum which is now supported by TS?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Was aligning to TraceValues, string enum makes sense.

Text = 'text',
JSON = 'json'
}
export namespace TraceFormat {
export function fromString(value: string): TraceFormat {
value = value.toLowerCase();
if (value === 'json') {
return TraceFormat.JSON;
} else {
return TraceFormat.Text;
}
}
}

export interface SetTraceParams {
value: TraceValues;
}
Expand All @@ -223,6 +239,7 @@ export namespace LogTraceNotification {
}

export interface Tracer {
log(data: Object): void;
log(message: string, data?: string): void;
}

Expand Down Expand Up @@ -321,6 +338,7 @@ export interface MessageConnection {
onNotification(handler: StarNotificationHandler): void;

trace(value: Trace, tracer: Tracer, sendNotification?: boolean): void;
trace(value: Trace, tracer: Tracer, sendNotification?: boolean, traceFormat?: TraceFormat): void;

onError: Event<[Error, Message | undefined, number | undefined]>;
onClose: Event<void>;
Expand Down Expand Up @@ -365,12 +383,13 @@ function _createMessageConnection(messageReader: MessageReader, messageWriter: M
let starNotificationHandler: StarNotificationHandler | undefined = undefined;
let notificationHandlers: { [name: string]: NotificationHandlerElement | undefined } = Object.create(null);

let timer: NodeJS.Timer | undefined;
let timer: NodeJS.Timer | undefined;
let messageQueue: MessageQueue = new LinkedMap<string, Message>();
let responsePromises: { [name: string]: ResponsePromise } = Object.create(null);
let requestTokens: { [id: string]: CancellationTokenSource } = Object.create(null);

let trace: Trace = Trace.Off;
let traceFormat: TraceFormat = TraceFormat.Text;
let tracer: Tracer | undefined;

let state: ConnectionState = ConnectionState.New;
Expand Down Expand Up @@ -713,95 +732,140 @@ function _createMessageConnection(messageReader: MessageReader, messageWriter: M
if (trace === Trace.Off || !tracer) {
return;
}
let data: string | undefined = undefined;
if (trace === Trace.Verbose && message.params) {
data = `Params: ${JSON.stringify(message.params, null, 4)}\n\n`;

if (traceFormat === TraceFormat.Text) {
let data: string | undefined = undefined;
if (trace === Trace.Verbose && message.params) {
data = `Params: ${JSON.stringify(message.params, null, 4)}\n\n`;
}
tracer.log(`Sending request '${message.method} - (${message.id})'.`, data);
} else {
logLSPMessage('send-request', message);
}
tracer.log(`Sending request '${message.method} - (${message.id})'.`, data);
}

function traceSendNotification(message: NotificationMessage): void {
function traceSendingNotification(message: NotificationMessage): void {
if (trace === Trace.Off || !tracer) {
return;
}
let data: string | undefined = undefined;
if (trace === Trace.Verbose) {
if (message.params) {
data = `Params: ${JSON.stringify(message.params, null, 4)}\n\n`;
} else {
data = 'No parameters provided.\n\n';

if (traceFormat === TraceFormat.Text) {
let data: string | undefined = undefined;
if (trace === Trace.Verbose) {
if (message.params) {
data = `Params: ${JSON.stringify(message.params, null, 4)}\n\n`;
} else {
data = 'No parameters provided.\n\n';
}
}
tracer.log(`Sending notification '${message.method}'.`, data);
} else {
logLSPMessage('send-notification', message);
}
tracer.log(`Sending notification '${message.method}'.`, data);
}

function traceSendingResponse(message: ResponseMessage, method: string, startTime: number): void {
if (trace === Trace.Off || !tracer) {
return;
}
let data: string | undefined = undefined;
if (trace === Trace.Verbose) {
if (message.error && message.error.data) {
data = `Error data: ${JSON.stringify(message.error.data, null, 4)}\n\n`;
} else {
if (message.result) {
data = `Result: ${JSON.stringify(message.result, null, 4)}\n\n`;
} else if (message.error === void 0) {
data = 'No result returned.\n\n';

if (traceFormat === TraceFormat.Text) {
let data: string | undefined = undefined;
if (trace === Trace.Verbose) {
if (message.error && message.error.data) {
data = `Error data: ${JSON.stringify(message.error.data, null, 4)}\n\n`;
} else {
if (message.result) {
data = `Result: ${JSON.stringify(message.result, null, 4)}\n\n`;
} else if (message.error === void 0) {
data = 'No result returned.\n\n';
}
}
}
tracer.log(`Sending response '${method} - (${message.id})'. Processing request took ${Date.now() - startTime}ms`, data)
} else {
logLSPMessage('send-response', message);
}
tracer.log(`Sending response '${method} - (${message.id})'. Processing request took ${Date.now() - startTime}ms`, data)
}

function traceReceivedRequest(message: RequestMessage): void {
if (trace === Trace.Off || !tracer) {
return;
}
let data: string | undefined = undefined;
if (trace === Trace.Verbose && message.params) {
data = `Params: ${JSON.stringify(message.params, null, 4)}\n\n`;

if (traceFormat === TraceFormat.Text) {
let data: string | undefined = undefined;
if (trace === Trace.Verbose && message.params) {
data = `Params: ${JSON.stringify(message.params, null, 4)}\n\n`;
}
tracer.log(`Received request '${message.method} - (${message.id})'.`, data);
} else {
logLSPMessage('receive-request', message);
}
tracer.log(`Received request '${message.method} - (${message.id})'.`, data);
}

function traceReceivedNotification(message: NotificationMessage): void {
if (trace === Trace.Off || !tracer || message.method === LogTraceNotification.type.method) {
return;
}
let data: string | undefined = undefined;
if (trace === Trace.Verbose) {
if (message.params) {
data = `Params: ${JSON.stringify(message.params, null, 4)}\n\n`;
} else {
data = 'No parameters provided.\n\n';

if (traceFormat === TraceFormat.Text) {
let data: string | undefined = undefined;
if (trace === Trace.Verbose) {
if (message.params) {
data = `Params: ${JSON.stringify(message.params, null, 4)}\n\n`;
} else {
data = 'No parameters provided.\n\n';
}
}
tracer.log(`Received notification '${message.method}'.`, data);
} else {
logLSPMessage('receive-notification', message);
}
tracer.log(`Received notification '${message.method}'.`, data);
}

function traceReceivedResponse(message: ResponseMessage, responsePromise: ResponsePromise): void {
if (trace === Trace.Off || !tracer) {
return;
}
let data: string | undefined = undefined;
if (trace === Trace.Verbose) {
if (message.error && message.error.data) {
data = `Error data: ${JSON.stringify(message.error.data, null, 4)}\n\n`;
} else {
if (message.result) {
data = `Result: ${JSON.stringify(message.result, null, 4)}\n\n`;
} else if (message.error === void 0) {
data = 'No result returned.\n\n';

if (traceFormat === TraceFormat.Text) {
let data: string | undefined = undefined;
if (trace === Trace.Verbose) {
if (message.error && message.error.data) {
data = `Error data: ${JSON.stringify(message.error.data, null, 4)}\n\n`;
} else {
if (message.result) {
data = `Result: ${JSON.stringify(message.result, null, 4)}\n\n`;
} else if (message.error === void 0) {
data = 'No result returned.\n\n';
}
}
}
}
if (responsePromise) {
let error = message.error ? ` Request failed: ${message.error.message} (${message.error.code}).` : '';
tracer.log(`Received response '${responsePromise.method} - (${message.id})' in ${Date.now() - responsePromise.timerStart}ms.${error}`, data);
if (responsePromise) {
let error = message.error ? ` Request failed: ${message.error.message} (${message.error.code}).` : '';
tracer.log(`Received response '${responsePromise.method} - (${message.id})' in ${Date.now() - responsePromise.timerStart}ms.${error}`, data);
} else {
tracer.log(`Received response ${message.id} without active response promise.`, data);
}
} else {
tracer.log(`Received response ${message.id} without active response promise.`, data);
logLSPMessage('receive-response', message);
}
}

function logLSPMessage(type: LSPMessageType, message: RequestMessage | ResponseMessage | NotificationMessage): void {
if (!tracer || trace === Trace.Off) {
return;
}

const lspMessage = {
isLSPMessage: true,
type,
message,
timestamp: Date.now()
}

tracer.log(lspMessage);
}

function throwIfClosedOrDisposed() {
Expand Down Expand Up @@ -886,7 +950,7 @@ function _createMessageConnection(messageReader: MessageReader, messageWriter: M
method: method,
params: messageParams
}
traceSendNotification(notificationMessage);
traceSendingNotification(notificationMessage);
messageWriter.write(notificationMessage);
},
onNotification: (type: string | MessageType | StarNotificationHandler, handler?: GenericNotificationHandler): void => {
Expand Down Expand Up @@ -985,14 +1049,16 @@ function _createMessageConnection(messageReader: MessageReader, messageWriter: M
}
}
},
trace: (_value: Trace, _tracer: Tracer, sendNotification: boolean = false) => {
trace: (_value: Trace, _tracer: Tracer, _sendNotification: boolean = false, _traceFormat: TraceFormat = TraceFormat.Text) => {
trace = _value;

traceFormat = _traceFormat;
if (trace === Trace.Off) {
tracer = undefined;
} else {
tracer = _tracer;
}
if (sendNotification && !isClosed() && !isDisposed()) {
if (_sendNotification && !isClosed() && !isDisposed()) {
connection.sendNotification(SetTraceNotification.type, { value: Trace.toString(_value) });
}
},
Expand Down
Loading