From c63dc3a1ea8d4b339f970738ad773d37d13f79a7 Mon Sep 17 00:00:00 2001 From: Asher Date: Thu, 29 Oct 2020 14:48:01 -0500 Subject: [PATCH 1/4] Add more logging around connections --- ci/build/build-release.sh | 2 +- ci/dev/vscode.patch | 99 +++++++++++++++++++++++++-------------- 2 files changed, 64 insertions(+), 37 deletions(-) diff --git a/ci/build/build-release.sh b/ci/build/build-release.sh index 95579eb8..3b88ed7e 100755 --- a/ci/build/build-release.sh +++ b/ci/build/build-release.sh @@ -67,7 +67,7 @@ EOF bundle_vscode() { mkdir -p "$VSCODE_OUT_PATH" rsync "$VSCODE_SRC_PATH/yarn.lock" "$VSCODE_OUT_PATH" - rsync "$VSCODE_SRC_PATH/out-vscode${MINIFY+-min}/" "$VSCODE_OUT_PATH/out" + rsync "$VSCODE_SRC_PATH/out-vscode${MINIFY:+-min}/" "$VSCODE_OUT_PATH/out" rsync "$VSCODE_SRC_PATH/.build/extensions/" "$VSCODE_OUT_PATH/extensions" if [ "$KEEP_MODULES" = 0 ]; then diff --git a/ci/dev/vscode.patch b/ci/dev/vscode.patch index b205aa83..f1eaef04 100644 --- a/ci/dev/vscode.patch +++ b/ci/dev/vscode.patch @@ -1225,10 +1225,10 @@ index 0000000000000000000000000000000000000000..4ea6d95d36aaac07dbd4d0e16ab3c1bb +} diff --git a/src/vs/server/entry.ts b/src/vs/server/entry.ts new file mode 100644 -index 0000000000000000000000000000000000000000..ab020fbb4e4ab3748cc807765ff9c362389faafa +index 0000000000000000000000000000000000000000..8482c48bae007ed6b39183001ae2cc6d140fcd50 --- /dev/null +++ b/src/vs/server/entry.ts -@@ -0,0 +1,78 @@ +@@ -0,0 +1,79 @@ +import { field } from '@coder/logger'; +import { setUnexpectedErrorHandler } from 'vs/base/common/errors'; +import { CodeServerMessage, VscodeMessage } from 'vs/server/ipc'; @@ -1273,7 +1273,8 @@ index 0000000000000000000000000000000000000000..ab020fbb4e4ab3748cc807765ff9c362 +// Wait for the init message then start up VS Code. Subsequent messages will +// return new workbench options without starting a new instance. +process.on('message', async (message: CodeServerMessage, socket) => { -+ logger.debug('got message from code-server', field('message', message)); ++ logger.debug('got message from code-server', field('type', message.type)); ++ logger.trace('code-server message content', field('message', message)); + switch (message.type) { + case 'init': + try { @@ -1821,10 +1822,11 @@ index 0000000000000000000000000000000000000000..609c4d1cb43f52f92906b901c14c790f +} diff --git a/src/vs/server/node/connection.ts b/src/vs/server/node/connection.ts new file mode 100644 -index 0000000000000000000000000000000000000000..eec198c948d48b1539ff46510016f759f396be18 +index 0000000000000000000000000000000000000000..93062cadc627c61e0829c27a72894b81e6a0e039 --- /dev/null +++ b/src/vs/server/node/connection.ts -@@ -0,0 +1,157 @@ +@@ -0,0 +1,171 @@ ++import { field, Logger, logger } from '@coder/logger'; +import * as cp from 'child_process'; +import { VSBuffer } from 'vs/base/common/buffer'; +import { Emitter } from 'vs/base/common/event'; @@ -1832,10 +1834,8 @@ index 0000000000000000000000000000000000000000..eec198c948d48b1539ff46510016f759 +import { ISocket } from 'vs/base/parts/ipc/common/ipc.net'; +import { NodeSocket } from 'vs/base/parts/ipc/node/ipc.net'; +import { INativeEnvironmentService } from 'vs/platform/environment/common/environment'; -+import { ILogService } from 'vs/platform/log/common/log'; +import { getNlsConfiguration } from 'vs/server/node/nls'; +import { Protocol } from 'vs/server/node/protocol'; -+import { IExtHostReadyMessage } from 'vs/workbench/services/extensions/common/extensionHostProtocol'; + +export abstract class Connection { + private readonly _onClose = new Emitter(); @@ -1899,13 +1899,14 @@ index 0000000000000000000000000000000000000000..eec198c948d48b1539ff46510016f759 + +export class ExtensionHostConnection extends Connection { + private process?: cp.ChildProcess; ++ private readonly logger: Logger; + + public constructor( + locale:string, protocol: Protocol, buffer: VSBuffer, token: string, -+ private readonly log: ILogService, + private readonly environment: INativeEnvironmentService, + ) { + super(protocol, token); ++ this.logger = logger.named("exthost", field("token", token)); + this.protocol.dispose(); + this.spawn(locale, buffer).then((p) => this.process = p); + this.protocol.getUnderlyingSocket().pause(); @@ -1928,6 +1929,7 @@ index 0000000000000000000000000000000000000000..eec198c948d48b1539ff46510016f759 + private sendInitMessage(buffer: VSBuffer): void { + const socket = this.protocol.getUnderlyingSocket(); + socket.pause(); ++ this.logger.trace('Sending socket'); + this.process!.send({ // Process must be set at this point. + type: 'VSCODE_EXTHOST_IPC_SOCKET', + initialDataChunk: (buffer.buffer as Buffer).toString('base64'), @@ -1936,7 +1938,9 @@ index 0000000000000000000000000000000000000000..eec198c948d48b1539ff46510016f759 + } + + private async spawn(locale: string, buffer: VSBuffer): Promise { ++ this.logger.trace('Getting NLS configuration...'); + const config = await getNlsConfiguration(locale, this.environment.userDataPath); ++ this.logger.trace('Spawning extension host...'); + const proc = cp.fork( + FileAccess.asFileUri('bootstrap-fork', require).fsPath, + [ '--type=extensionHost' ], @@ -1956,30 +1960,41 @@ index 0000000000000000000000000000000000000000..eec198c948d48b1539ff46510016f759 + }, + ); + -+ proc.on('error', () => this.dispose()); -+ proc.on('exit', () => this.dispose()); ++ proc.on('error', (error) => { ++ this.logger.error('Exited unexpectedly', field('error', error)); ++ this.dispose(); ++ }); ++ proc.on('exit', (code) => { ++ this.logger.trace('Exited', field('code', code)); ++ this.dispose(); ++ }); + if (proc.stdout && proc.stderr) { -+ proc.stdout.setEncoding('utf8').on('data', (d) => this.log.info('Extension host stdout', d)); -+ proc.stderr.setEncoding('utf8').on('data', (d) => this.log.error('Extension host stderr', d)); ++ proc.stdout.setEncoding('utf8').on('data', (d) => this.logger.info(d)); ++ proc.stderr.setEncoding('utf8').on('data', (d) => this.logger.error(d)); + } ++ + proc.on('message', (event) => { -+ if (event && event.type === '__$console') { -+ const severity = (this.log)[event.severity] ? event.severity : 'info'; -+ (this.log)[severity]('Extension host', event.arguments); -+ } -+ if (event && event.type === 'VSCODE_EXTHOST_DISCONNECTED') { -+ this.setOffline(); ++ switch (event && event.type) { ++ case '__$console': ++ const severity = (this.logger)[event.severity] || 'info'; ++ (this.logger)[severity]('console', field('arguments', event.arguments)); ++ break; ++ case 'VSCODE_EXTHOST_DISCONNECTED': ++ this.logger.trace('Going offline'); ++ this.setOffline(); ++ break; ++ case 'VSCODE_EXTHOST_IPC_READY': ++ this.logger.trace('Got ready message'); ++ this.sendInitMessage(buffer); ++ break; ++ default: ++ this.logger.error('Unexpected message', field("event", event)); ++ break; + } + }); + -+ const listen = (message: IExtHostReadyMessage) => { -+ if (message.type === 'VSCODE_EXTHOST_IPC_READY') { -+ proc.removeListener('message', listen); -+ this.sendInitMessage(buffer); -+ } -+ }; -+ -+ return proc.on('message', listen); ++ this.logger.trace('Waiting for handshake...'); ++ return proc; + } +} diff --git a/src/vs/server/node/insights.ts b/src/vs/server/node/insights.ts @@ -2463,15 +2478,17 @@ index 0000000000000000000000000000000000000000..3d428a57d31f29c40f9c3ce45f715b44 +}; diff --git a/src/vs/server/node/protocol.ts b/src/vs/server/node/protocol.ts new file mode 100644 -index 0000000000000000000000000000000000000000..3c74512192aec6220216bc8563b3127b9cfd5fbf +index 0000000000000000000000000000000000000000..523fcd3186d92799bc50e33a72832bd443b2945b --- /dev/null +++ b/src/vs/server/node/protocol.ts -@@ -0,0 +1,73 @@ +@@ -0,0 +1,80 @@ ++import { field } from '@coder/logger'; +import * as net from 'net'; +import { VSBuffer } from 'vs/base/common/buffer'; +import { PersistentProtocol } from 'vs/base/parts/ipc/common/ipc.net'; +import { NodeSocket, WebSocketNodeSocket } from 'vs/base/parts/ipc/node/ipc.net'; +import { AuthRequest, ConnectionTypeRequest, HandshakeMessage } from 'vs/platform/remote/common/remoteAgentConnection'; ++import { logger } from 'vs/server/node/logger'; + +export interface SocketOptions { + readonly reconnectionToken: string; @@ -2499,16 +2516,21 @@ index 0000000000000000000000000000000000000000..3c74512192aec6220216bc8563b3127b + * Perform a handshake to get a connection request. + */ + public handshake(): Promise { ++ logger.trace('Protocol handshake', field('token', this.options.reconnectionToken)); + return new Promise((resolve, reject) => { + const handler = this.onControlMessage((rawMessage) => { + try { -+ const message = JSON.parse(rawMessage.toString()); ++ const raw = rawMessage.toString(); ++ logger.trace('Protocol message', field('token', this.options.reconnectionToken), field('message', raw)); ++ const message = JSON.parse(raw); + switch (message.type) { -+ case 'auth': return this.authenticate(message); ++ case 'auth': ++ return this.authenticate(message); + case 'connectionType': + handler.dispose(); + return resolve(message); -+ default: throw new Error('Unrecognized message type'); ++ default: ++ throw new Error('Unrecognized message type'); + } + } catch (error) { + handler.dispose(); @@ -2521,7 +2543,7 @@ index 0000000000000000000000000000000000000000..3c74512192aec6220216bc8563b3127b + /** + * TODO: This ignores the authentication process entirely for now. + */ -+ private authenticate(_message: AuthRequest): void { ++ private authenticate(_?: AuthRequest): void { + this.sendMessage({ type: 'sign', data: '' }); + } + @@ -2542,10 +2564,11 @@ index 0000000000000000000000000000000000000000..3c74512192aec6220216bc8563b3127b +} diff --git a/src/vs/server/node/server.ts b/src/vs/server/node/server.ts new file mode 100644 -index 0000000000000000000000000000000000000000..a1289865858f405f93d3d396f41c6a0aadffd5e5 +index 0000000000000000000000000000000000000000..45a7bf62a6c07d8771b0257e7c98fae095109eb1 --- /dev/null +++ b/src/vs/server/node/server.ts -@@ -0,0 +1,286 @@ +@@ -0,0 +1,291 @@ ++import { field } from '@coder/logger'; +import * as fs from 'fs'; +import * as net from 'net'; +import * as path from 'path'; @@ -2709,6 +2732,7 @@ index 0000000000000000000000000000000000000000..a1289865858f405f93d3d396f41c6a0a + ); + } + ++ logger.debug('New connection', field('token', token)); + protocol.sendMessage(await ok()); + + let connection: Connection; @@ -2727,12 +2751,14 @@ index 0000000000000000000000000000000000000000..a1289865858f405f93d3d396f41c6a0a + connection = new ExtensionHostConnection( + message.args ? message.args.language : 'en', + protocol, buffer, token, -+ this.services.get(ILogService) as ILogService, + this.services.get(IEnvironmentService) as INativeEnvironmentService, + ); + } + connections.set(token, connection); -+ connection.onClose(() => connections.delete(token)); ++ connection.onClose(() => { ++ logger.debug('Connection closed', field('token', token)); ++ connections.delete(token); ++ }); + this.disposeOldOfflineConnections(connections); + break; + case ConnectionType.Tunnel: return protocol.tunnel(); @@ -2744,6 +2770,7 @@ index 0000000000000000000000000000000000000000..a1289865858f405f93d3d396f41c6a0a + const offline = Array.from(connections.values()) + .filter((connection) => typeof connection.offline !== 'undefined'); + for (let i = 0, max = offline.length - this.maxExtraOfflineConnections; i < max; ++i) { ++ logger.debug('Disposing offline connection', field("token", offline[i].token)); + offline[i].dispose(); + } + } From 0b9af6ef67253e4db7eb128a78d6676097a59cb8 Mon Sep 17 00:00:00 2001 From: Asher Date: Thu, 29 Oct 2020 18:54:18 -0500 Subject: [PATCH 2/4] Initiate connection handshake from server This way the connection can be initiated by either side. It looks like sometimes the initial message from the client is lost (it never makes it into the onControlMessage callback) but I'm still not sure why or if that is preventable. Also added a timeout on the server end to clean things up in case the client never responds. --- ci/dev/vscode.patch | 15 +++++++++++++-- 1 file changed, 13 insertions(+), 2 deletions(-) diff --git a/ci/dev/vscode.patch b/ci/dev/vscode.patch index f1eaef04..531bffe2 100644 --- a/ci/dev/vscode.patch +++ b/ci/dev/vscode.patch @@ -2478,10 +2478,10 @@ index 0000000000000000000000000000000000000000..3d428a57d31f29c40f9c3ce45f715b44 +}; diff --git a/src/vs/server/node/protocol.ts b/src/vs/server/node/protocol.ts new file mode 100644 -index 0000000000000000000000000000000000000000..523fcd3186d92799bc50e33a72832bd443b2945b +index 0000000000000000000000000000000000000000..0d9310038c0ca378579652d89bc8ac84924213db --- /dev/null +++ b/src/vs/server/node/protocol.ts -@@ -0,0 +1,80 @@ +@@ -0,0 +1,91 @@ +import { field } from '@coder/logger'; +import * as net from 'net'; +import { VSBuffer } from 'vs/base/common/buffer'; @@ -2518,6 +2518,11 @@ index 0000000000000000000000000000000000000000..523fcd3186d92799bc50e33a72832bd4 + public handshake(): Promise { + logger.trace('Protocol handshake', field('token', this.options.reconnectionToken)); + return new Promise((resolve, reject) => { ++ const timeout = setTimeout(() => { ++ logger.error('Handshake timed out', field('token', this.options.reconnectionToken)); ++ reject(new Error("timed out")); ++ }, 10000); // Matches the client timeout. ++ + const handler = this.onControlMessage((rawMessage) => { + try { + const raw = rawMessage.toString(); @@ -2528,15 +2533,21 @@ index 0000000000000000000000000000000000000000..523fcd3186d92799bc50e33a72832bd4 + return this.authenticate(message); + case 'connectionType': + handler.dispose(); ++ clearTimeout(timeout); + return resolve(message); + default: + throw new Error('Unrecognized message type'); + } + } catch (error) { + handler.dispose(); ++ clearTimeout(timeout); + reject(error); + } + }); ++ ++ // Kick off the handshake in case we missed the client's opening shot. ++ // TODO: Investigate why that message seems to get lost. ++ this.authenticate(); + }); + } + From 07e7c38ea2ba601c11d1c4f40380e00e629855e3 Mon Sep 17 00:00:00 2001 From: Asher Date: Fri, 30 Oct 2020 13:38:13 -0500 Subject: [PATCH 3/4] Immediately pause web socket This will buffer any data sent to it until something is ready to listen on it. --- src/node/http.ts | 2 ++ 1 file changed, 2 insertions(+) diff --git a/src/node/http.ts b/src/node/http.ts index c616c883..c3635e07 100644 --- a/src/node/http.ts +++ b/src/node/http.ts @@ -738,6 +738,8 @@ export class HttpServer { } private onUpgrade = async (request: http.IncomingMessage, socket: net.Socket, head: Buffer): Promise => { + socket.pause() + try { this.heart.beat() socket.on("error", () => socket.destroy()) From 9ad7d0b7a3e78ff6cb111a263f20e078da140ef3 Mon Sep 17 00:00:00 2001 From: Asher Date: Fri, 30 Oct 2020 14:50:06 -0500 Subject: [PATCH 4/4] Fix potential 500 when loading in parallel --- src/node/app/vscode.ts | 17 ++++++++++------- 1 file changed, 10 insertions(+), 7 deletions(-) diff --git a/src/node/app/vscode.ts b/src/node/app/vscode.ts index ed4f714e..18c9d8a9 100644 --- a/src/node/app/vscode.ts +++ b/src/node/app/vscode.ts @@ -50,12 +50,15 @@ export class VscodeHttpProvider extends HttpProvider { logger.debug("setting up vs code...") return new Promise((resolve, reject) => { - vscode.once("message", (message: VscodeMessage) => { - logger.debug("got message from vs code", field("message", message)) - return message.type === "options" && message.id === id - ? resolve(message.options) - : reject(new Error("Unexpected response during initialization")) - }) + const onMessage = (message: VscodeMessage) => { + // There can be parallel initializations so wait for the right ID. + if (message.type === "options" && message.id === id) { + logger.trace("got message from vs code", field("message", message)) + vscode.off("message", onMessage) + resolve(message.options) + } + } + vscode.on("message", onMessage) vscode.once("error", reject) vscode.once("exit", (code) => reject(new Error(`VS Code exited unexpectedly with code ${code}`))) this.send({ type: "init", id, options }, vscode) @@ -77,7 +80,7 @@ export class VscodeHttpProvider extends HttpProvider { this._vscode = new Promise((resolve, reject) => { vscode.once("message", (message: VscodeMessage) => { - logger.debug("got message from vs code", field("message", message)) + logger.trace("got message from vs code", field("message", message)) return message.type === "ready" ? resolve(vscode) : reject(new Error("Unexpected response waiting for ready response"))