Centralise logging

Summary:
Centralise connectivity logging into a single place. By having all logs go through a single interface, then it becomes trivial to manipulate them as needed.

In this change, this is not done.

In subsequent diffs, logs will be dispatched via an event and will be visualised in the Connectivity Hub.

Reviewed By: passy

Differential Revision: D47185054

fbshipit-source-id: fb5eab98895be0c8f61fb9a77d3e66d6a8dbcb27
This commit is contained in:
Lorenzo Blasa
2023-07-10 04:14:14 -07:00
committed by Facebook GitHub Bot
parent 49d1a8b0fa
commit fc38355eee
22 changed files with 351 additions and 258 deletions

View File

@@ -18,6 +18,7 @@ import {
import WebSocketClientConnection from './WebSocketClientConnection';
import {serializeError} from 'serialize-error';
import {WSCloseCode} from '../utils/WSCloseCode';
import {recorder} from '../recorder';
export interface SecureConnectionCtx extends ConnectionCtx {
clientQuery?: SecureClientQuery;
@@ -39,15 +40,15 @@ class SecureServerWebSocket extends ServerWebSocket {
const {clientQuery, ws} = ctx;
assertNotNull(clientQuery);
console.info(
`[conn] Secure websocket connection attempt: ${clientQuery.app} on ${clientQuery.device_id}. Medium ${clientQuery.medium}. CSR: ${clientQuery.csr_path}`,
recorder.log(
clientQuery,
`Secure websocket connection attempt: ${clientQuery.app} on ${clientQuery.device}.`,
);
this.listener.onSecureConnectionAttempt(clientQuery);
const clientConnection = new WebSocketClientConnection(ws);
// TODO: Could we just await it here? How much time could it be, potentially?
// DRI: @aigoncharov
const clientPromise: Promise<ClientDescription> = this.listener
.onConnectionCreated(clientQuery, clientConnection)
.then((client) => {
@@ -96,7 +97,6 @@ class SecureServerWebSocket extends ServerWebSocket {
}
// Received an "execute" message
if (client) {
this.listener.onClientMessage(client.id, rawMessage);
} else {

View File

@@ -23,11 +23,7 @@ import {ClientConnection, ConnectionStatus} from './ClientConnection';
import {EventEmitter} from 'events';
import invariant from 'invariant';
import DummyDevice from '../devices/DummyDevice';
import {
appNameWithUpdateHint,
assertNotNull,
cloneClientQuerySafeForLogging,
} from './Utilities';
import {appNameWithUpdateHint, assertNotNull} from './Utilities';
import ServerWebSocketBase, {ServerEventsListener} from './ServerWebSocketBase';
import {
createBrowserServer,
@@ -40,12 +36,13 @@ import {
getFlipperServerConfig,
} from '../FlipperServerConfig';
import {
extractAppNameFromCSR,
extractBundleIdFromCSR,
loadSecureServerConfig,
} from './certificate-exchange/certificate-utils';
import DesktopCertificateProvider from '../devices/desktop/DesktopCertificateProvider';
import WWWCertificateProvider from '../fb-stubs/WWWCertificateProvider';
import {tracker} from '../utils/tracker';
import {tracker} from '../tracker';
import {recorder} from '../recorder';
type ClientTimestampTracker = {
insecureStart?: number;
@@ -114,10 +111,10 @@ export class ServerController
const options = await loadSecureServerConfig();
console.info('[conn] secure server listening at port: ', secure);
console.info('[ws] secure server listening at port: ', secure);
this.secureServer = await createServer(secure, this, options);
const {secure: altSecure} = getServerPortsConfig().altServerPorts;
console.info('[conn] secure server (ws) listening at port: ', altSecure);
console.info('[ws] secure server listening at port: ', altSecure);
this.altSecureServer = await createServer(
altSecure,
this,
@@ -125,13 +122,10 @@ export class ServerController
TransportType.WebSocket,
);
console.info('[conn] insecure server listening at port: ', insecure);
console.info('[ws] insecure server listening at port: ', insecure);
this.insecureServer = await createServer(insecure, this);
const {insecure: altInsecure} = getServerPortsConfig().altServerPorts;
console.info(
'[conn] insecure server (ws) listening at port: ',
altInsecure,
);
console.info('[ws] insecure server listening at port: ', altInsecure);
this.altInsecureServer = await createServer(
altInsecure,
this,
@@ -140,7 +134,7 @@ export class ServerController
);
const browserPort = getServerPortsConfig().browserPort;
console.info('[conn] Browser server (ws) listening at port: ', browserPort);
console.info('[ws] Browser server listening at port: ', browserPort);
this.browserServer = await createBrowserServer(browserPort, this);
}
@@ -174,11 +168,7 @@ export class ServerController
rsocket,
} = clientQuery;
console.info(
`[conn] Connection established: ${app} on ${device_id}. Medium ${medium}. CSR: ${csr_path}`,
cloneClientQuerySafeForLogging(clientQuery),
);
recorder.log(clientQuery, 'Connection established');
tracker.track('app-connection-created', {
app,
os,
@@ -233,17 +223,25 @@ export class ServerController
medium: clientQuery.medium,
});
const {os, app, device_id} = clientQuery;
// without these checks, the user might see a connection timeout error instead, which would be much harder to track down
if (os === 'iOS' && !getFlipperServerConfig().settings.enableIOS) {
console.error(
`Refusing connection from ${app} on ${device_id}, since iOS support is disabled in settings`,
// Without these checks, the user might see a connection timeout error instead,
// which would be much harder to track down
if (
clientQuery.os === 'iOS' &&
!getFlipperServerConfig().settings.enableIOS
) {
recorder.error(
clientQuery,
`Refusing connection since iOS support is disabled in settings`,
);
return;
}
if (os === 'Android' && !getFlipperServerConfig().settings.enableAndroid) {
console.error(
`Refusing connection from ${app} on ${device_id}, since Android support is disabled in settings`,
if (
clientQuery.os === 'Android' &&
!getFlipperServerConfig().settings.enableAndroid
) {
recorder.error(
clientQuery,
`Refusing connection since Android support is disabled in settings`,
);
return;
}
@@ -268,14 +266,24 @@ export class ServerController
}
}
/**
* A connection has been established between a running app and Flipper Desktop.
* The connection sole purpose is to perform the certificate exchange.
* @param clientQuery Client query defines the arguments passed down from the app
* to Flipper Desktop.
*/
onConnectionAttempt(clientQuery: ClientQuery): void {
// Remove the device id from the query, if found.
// Instead, set the device id as 'unknown'.
const strippedClientQuery = (({device_id, ...o}) => o)(clientQuery);
const id = buildClientId({device_id: 'unknown', ...strippedClientQuery});
this.timestamps.set(id, {
insecureStart: Date.now(),
});
tracker.track('app-connection-insecure-attempt', clientQuery);
recorder.log(clientQuery, 'Insecure connection attempt');
this.connectionTracker.logConnectionAttempt(clientQuery);
@@ -325,23 +333,30 @@ export class ServerController
}
default: {
throw new Error(
`ServerController.onProcessCSR -> os ${clientQuery.os} does not support certificate exchange.`,
`OS '${clientQuery.os}' does not support certificate exchange.`,
);
}
}
certificateProvider.verifyMedium(clientQuery.medium);
recorder.log(clientQuery, 'Certificate Signing Request being processed');
return new Promise((resolve, reject) => {
reportPlatformFailures(
certificateProvider.processCertificateSigningRequest(
clientQuery,
unsanitizedCSR,
clientQuery.os,
appDirectory,
),
'processCertificateSigningRequest',
)
.then((response) => {
recorder.log(
clientQuery,
'Certificate Signing Request successfully processed',
);
const client: UninitializedClient = {
os: clientQuery.os,
deviceName: clientQuery.device,
@@ -392,12 +407,7 @@ export class ServerController
}
onClientSetupError(clientQuery: ClientQuery, e: any) {
console.warn(
`[conn] Failed to exchange certificate with ${clientQuery.app} on ${
clientQuery.device || clientQuery.device_id
}`,
e,
);
recorder.error(clientQuery, 'Failed to exchange certificate', e);
const client: UninitializedClient = {
os: clientQuery.os,
deviceName: clientQuery.device,
@@ -405,58 +415,56 @@ export class ServerController
};
this.emit('client-setup-error', {
client,
error: `[conn] Failed to exchange certificate with ${
clientQuery.app
} on ${clientQuery.device || clientQuery.device_id}: ${e}`,
error: `Failed to exchange certificate with ${clientQuery.app} on ${
clientQuery.device || clientQuery.device_id
}: ${e}`,
});
}
/**
* Creates a Client and sets the underlying connection.
* @param connection A client connection to communicate between server and client.
* @param query The client query created from the initial handshake.
* @param clientQuery The client query created from the initial handshake.
* @param csrQuery The CSR query which contains CSR related information.
*/
async addConnection(
connection: ClientConnection,
query: SecureClientQuery,
clientQuery: SecureClientQuery,
silentReplace?: boolean,
): Promise<ClientDescription> {
invariant(query, 'expected query');
invariant(clientQuery, 'expected query');
// try to get id by comparing giving `csr` to file from `csr_path`
// otherwise, use given device_id
const {csr_path, csr} = query;
// otherwise, use given device_id.
const {csr_path, csr} = clientQuery;
// For Android, device id might change
if (csr_path && csr && query.os === 'Android') {
const app_name = await extractAppNameFromCSR(csr);
if (csr_path && csr && clientQuery.os === 'Android') {
const bundleId = await extractBundleIdFromCSR(csr);
assertNotNull(this.flipperServer.android);
// TODO: allocate new object, kept now as is to keep changes minimal
(query as any).device_id =
(clientQuery as any).device_id =
await this.flipperServer.android.certificateProvider.getTargetDeviceId(
app_name,
bundleId,
csr_path,
csr,
);
console.info(
`[conn] Detected ${app_name} on ${query.device_id} in certificate`,
query,
recorder.log(
clientQuery,
`Detected ${bundleId} on ${clientQuery.device_id} in certificate`,
);
}
// TODO: allocate new object, kept now as is to keep changes minimal
(query as any).app = appNameWithUpdateHint(query);
(clientQuery as any).app = appNameWithUpdateHint(clientQuery);
const id = buildClientId(query);
console.info(
`[conn] Matching device for ${query.app} on ${query.device_id}...`,
query,
const id = buildClientId(clientQuery);
recorder.log(
clientQuery,
`Matching device for ${clientQuery.app} on ${clientQuery.device_id}`,
);
const client: ClientDescription = {
id,
query,
query: clientQuery,
};
const info = {
@@ -464,9 +472,9 @@ export class ServerController
connection: connection,
};
console.info(
`[conn] Initializing client ${query.app} on ${query.device_id}...`,
query,
recorder.log(
clientQuery,
`Initializing client ${clientQuery.app} on ${clientQuery.device_id}`,
);
connection.subscribeToEvents((status: ConnectionStatus) => {
@@ -478,7 +486,7 @@ export class ServerController
}
});
console.debug(`[conn] Device client initialized: ${id}.`, 'server', query);
recorder.log(clientQuery, `Device client initialized: ${id}`);
/* If a device gets disconnected without being cleaned up properly,
* Flipper won't be aware until it attempts to reconnect.
@@ -508,12 +516,15 @@ export class ServerController
const start = tracker.insecureStart
? tracker.insecureStart
: tracker.secureStart;
const elapsed = Math.round(end - start!);
this.logger.track('performance', 'client-connection-tracker', {
'time-to-connection': elapsed,
...query,
});
this.timestamps.delete(id);
if (start) {
const elapsed = Math.round(end - start);
this.logger.track('performance', 'client-connection-tracker', {
'time-to-connection': elapsed,
...clientQuery,
});
this.timestamps.delete(id);
}
}
return client;
@@ -534,9 +545,9 @@ export class ServerController
removeConnection(id: string) {
const info = this.connections.get(id);
if (info) {
console.info(
`[conn] Disconnected: ${info.client.query.app} on ${info.client.query.device_id}.`,
recorder.log(
info.client.query,
`Disconnected: ${info.client.query.app} on ${info.client.query.device_id}.`,
);
this.flipperServer.emit('client-disconnected', {id});
this.connections.delete(id);
@@ -566,21 +577,21 @@ class ConnectionTracker {
this.logger = logger;
}
logConnectionAttempt(client: ClientQuery) {
const key = `${client.os}-${client.device}-${client.app}`;
logConnectionAttempt(clientQuery: ClientQuery) {
const key = `${clientQuery.os}-${clientQuery.device}-${clientQuery.app}`;
const time = Date.now();
let entry = this.connectionAttempts.get(key) || [];
entry.push(time);
entry = entry.filter((t) => t >= time - this.timeWindowMillis);
this.connectionAttempts.set(key, entry);
if (entry.length >= this.connectionProblemThreshold) {
console.warn(
`[conn] Connection loop detected with ${key}. Connected ${
recorder.error(
clientQuery,
`Connection loop detected with ${key}. Connected ${
this.connectionProblemThreshold
} times within ${this.timeWindowMillis / 1000}s.`,
'server',
client,
);
}
}

View File

@@ -28,6 +28,7 @@ import {SecureServerConfig} from './certificate-exchange/certificate-utils';
import {Server} from 'net';
import {serializeError} from 'serialize-error';
import {WSCloseCode} from '../utils/WSCloseCode';
import {recorder} from '../recorder';
export interface ConnectionCtx {
clientQuery?: ClientQuery;
@@ -73,7 +74,9 @@ class ServerWebSocket extends ServerWebSocketBase {
wsServer.once('error', onConnectionError);
server.listen(port, () => {
console.debug(
`${sslConfig ? 'Secure' : 'Insecure'} server started on port ${port}`,
`[ws] ${
sslConfig ? 'Secure' : 'Insecure'
} server started on port ${port}`,
'server',
);
@@ -96,7 +99,7 @@ class ServerWebSocket extends ServerWebSocketBase {
'connection',
(ws: WebSocket, request: IncomingMessage) => {
ws.on('error', (error) => {
console.error('[conn] WS connection error:', error);
console.error('[ws] Connection error:', error);
this.listener.onError(error);
});
@@ -123,7 +126,7 @@ class ServerWebSocket extends ServerWebSocketBase {
},
);
this.wsServer.on('error', (error) => {
console.error('[conn] WS server error:', error);
console.error('[ws] Server error:', error);
this.listener.onError(error);
});
@@ -136,7 +139,7 @@ class ServerWebSocket extends ServerWebSocketBase {
}
await new Promise<void>((resolve, reject) => {
console.info('[conn] Stopping WS server');
console.info('[ws] Stopping server');
assertNotNull(this.wsServer);
this.wsServer.close((err) => {
if (err) {
@@ -147,7 +150,7 @@ class ServerWebSocket extends ServerWebSocketBase {
});
});
await new Promise<void>((resolve, reject) => {
console.info('[conn] Stopping HTTP server');
console.info('[ws] Stopping HTTP server');
assertNotNull(this.httpServer);
this.httpServer.close((err) => {
if (err) {
@@ -175,7 +178,10 @@ class ServerWebSocket extends ServerWebSocketBase {
ws.on('message', async (message: WebSocket.RawData) => {
const messageString = message.toString();
try {
const parsedMessage = this.handleMessageDeserialization(messageString);
const parsedMessage = this.handleMessageDeserialization(
ctx,
messageString,
);
// Successful deserialization is a proof that the message is a string
this.handleMessage(ctx, parsedMessage, messageString);
} catch (error) {
@@ -183,7 +189,7 @@ class ServerWebSocket extends ServerWebSocketBase {
// all other plugins might still be working correctly. So let's just report it.
// This avoids ping-ponging connections if an individual plugin sends garbage (e.g. T129428800)
// or throws an error when handling messages
console.error('[conn] Failed to handle message', messageString, error);
console.error('[ws] Failed to handle message', messageString, error);
}
});
}
@@ -205,11 +211,11 @@ class ServerWebSocket extends ServerWebSocketBase {
if (!clientQuery) {
console.warn(
'[conn] Unable to extract the client query from the request URL.',
'[ws] Unable to extract the client query from the request URL.',
request.url,
);
throw new UnableToExtractClientQueryError(
'[conn] Unable to extract the client query from the request URL.',
'Unable to extract the client query from the request URL.',
);
}
@@ -220,17 +226,24 @@ class ServerWebSocket extends ServerWebSocketBase {
const {clientQuery} = ctx;
assertNotNull(clientQuery);
console.info(
`[conn] Insecure websocket connection attempt: ${clientQuery.app} on ${clientQuery.device_id}.`,
recorder.log(
clientQuery,
`Insecure websocket connection attempt: ${clientQuery.app} on ${clientQuery.device_id}.`,
);
this.listener.onConnectionAttempt(clientQuery);
}
protected handleMessageDeserialization(message: unknown): object {
protected handleMessageDeserialization(
ctx: ConnectionCtx,
message: unknown,
): object {
const {clientQuery} = ctx;
assertNotNull(clientQuery);
const parsedMessage = parseMessageToJson(message);
if (!parsedMessage) {
console.error('[conn] Failed to parse message', message);
throw new Error(`[conn] Failed to parse message`);
recorder.error(clientQuery, 'Failed to parse message', message);
throw new Error(`Failed to parse message`);
}
return parsedMessage;
}

View File

@@ -71,7 +71,7 @@ export function isWsResponseMessage(
return typeof (message as ResponseMessage).id === 'number';
}
const certExchangeSupportedOSes = new Set<DeviceOS>([
const supportedOSForCertificateExchange = new Set<DeviceOS>([
'Android',
'iOS',
'MacOS',
@@ -85,7 +85,7 @@ const certExchangeSupportedOSes = new Set<DeviceOS>([
export function verifyClientQueryComesFromCertExchangeSupportedOS(
query: ClientQuery | undefined,
): ClientQuery | undefined {
if (!query || !certExchangeSupportedOSes.has(query.os)) {
if (!query || !supportedOSForCertificateExchange.has(query.os)) {
return;
}
return query;
@@ -141,22 +141,22 @@ export function parseClientQuery(
throw new Error('Unsupported exchange medium: ' + medium);
}
let sdk_version: number | undefined;
if (typeof query.sdk_version === 'string') {
sdk_version = parseInt(query.sdk_version, 10);
} else if (typeof query.sdk_version === 'number') {
sdk_version = query.sdk_version;
}
const clientQuery: ClientQuery = {
device_id,
device,
app,
os,
medium: transformCertificateExchangeMediumToType(medium),
sdk_version,
};
if (typeof query.sdk_version === 'string') {
const sdk_version = parseInt(query.sdk_version, 10);
if (sdk_version) {
// TODO: allocate new object, kept now as is to keep changes minimal
(clientQuery as any).sdk_version = sdk_version;
}
}
return clientQuery;
}
@@ -213,7 +213,6 @@ export function cloneClientQuerySafeForLogging(clientQuery: SecureClientQuery) {
return {...clientQuery, csr: !clientQuery.csr ? clientQuery.csr : '<hidden>'};
}
// TODO: Merge with the same fn in desktop/app/src/utils
export function assertNotNull<T extends any>(
value: T,
message: string = 'Unexpected null/undefined value found',

View File

@@ -41,9 +41,11 @@ export default class WebSocketClientConnection implements ClientConnection {
const callbacks = this.pendingRequests.get(id);
if (!callbacks) {
console.debug(`[conn] Pending request ${id} is not found. Ignore.`);
console.debug(`[ws] Pending request ${id} is not found. Ignore.`);
// It must be a response for a message from the older connection. Ignore.
// TODO: When we decide to bump sdk_version, make `id` a string equal to `connectionId:messageId`. Ignore messages only from other conections. Raise an error for missing mesages from this connection.
// TODO: When we decide to bump sdk_version, make `id` a string equal to `connectionId:messageId`.
// Ignore messages only from other conections.
// Raise an error for missing mesages from this connection.
return;
}

View File

@@ -7,12 +7,13 @@
* @format
*/
import {CertificateExchangeMedium} from 'flipper-common';
import {CertificateExchangeMedium, ClientQuery} from 'flipper-common';
import {recorder} from '../../recorder';
import {
deviceCAcertFile,
deviceClientCertFile,
ensureOpenSSLIsAvailable,
extractAppNameFromCSR,
extractBundleIdFromCSR,
generateClientCertificate,
getCACertificate,
} from './certificate-utils';
@@ -28,48 +29,37 @@ export default abstract class CertificateProvider {
}
async processCertificateSigningRequest(
clientQuery: ClientQuery,
unsanitizedCsr: string,
os: string,
appDirectory: string,
): Promise<{deviceId: string}> {
console.debug(
`${this.constructor.name}.processCertificateSigningRequest`,
unsanitizedCsr,
os,
appDirectory,
);
const csr = this.santitizeString(unsanitizedCsr);
if (csr === '') {
return Promise.reject(new Error(`Received empty CSR from ${os} device`));
const msg = `Received empty CSR from ${clientQuery.os} device`;
recorder.error(clientQuery, msg);
return Promise.reject(new Error(msg));
}
console.debug(
`${this.constructor.name}.processCertificateSigningRequest -> ensureOpenSSLIsAvailable`,
os,
appDirectory,
);
recorder.log(clientQuery, 'Ensure OpenSSL is available');
await ensureOpenSSLIsAvailable();
recorder.log(clientQuery, 'Obtain CA certificate');
const caCert = await getCACertificate();
console.debug(
`${this.constructor.name}.processCertificateSigningRequest -> deploy caCert`,
os,
appDirectory,
);
recorder.log(clientQuery, 'Deploy CA certificate to application sandbox');
await this.deployOrStageFileForDevice(
appDirectory,
deviceCAcertFile,
caCert,
csr,
);
console.debug(
`${this.constructor.name}.processCertificateSigningRequest -> generateClientCertificate`,
os,
appDirectory,
);
recorder.log(clientQuery, 'Generate client certificate');
const clientCert = await generateClientCertificate(csr);
console.debug(
`${this.constructor.name}.processCertificateSigningRequest -> deploy clientCert`,
os,
appDirectory,
recorder.log(
clientQuery,
'Deploy client certificate to application sandbox',
);
await this.deployOrStageFileForDevice(
appDirectory,
@@ -77,20 +67,19 @@ export default abstract class CertificateProvider {
clientCert,
csr,
);
const appName = await extractAppNameFromCSR(csr);
console.debug(
`${this.constructor.name}.processCertificateSigningRequest -> getTargetDeviceId`,
os,
appDirectory,
appName,
recorder.log(clientQuery, 'Extract application name from CSR');
const bundleId = await extractBundleIdFromCSR(csr);
recorder.log(
clientQuery,
'Get target device from CSR and application name',
);
const deviceId = await this.getTargetDeviceId(appName, appDirectory, csr);
console.debug(
`${this.constructor.name}.processCertificateSigningRequest -> done`,
os,
appDirectory,
appName,
deviceId,
const deviceId = await this.getTargetDeviceId(bundleId, appDirectory, csr);
recorder.log(
clientQuery,
`Finished processing CSR, device identifier is '${deviceId}'`,
);
return {
deviceId,
@@ -98,9 +87,9 @@ export default abstract class CertificateProvider {
}
abstract getTargetDeviceId(
_appName: string,
_appDirectory: string,
_csr: string,
bundleId: string,
appDirectory: string,
csr: string,
): Promise<string>;
protected abstract deployOrStageFileForDevice(

View File

@@ -92,7 +92,7 @@ export const loadSecureServerConfig = async (): Promise<SecureServerConfig> => {
return serverConfig;
};
export const extractAppNameFromCSR = async (csr: string): Promise<string> => {
export const extractBundleIdFromCSR = async (csr: string): Promise<string> => {
const path = await writeToTempFile(csr);
const subject = await openssl('req', {
in: path,