Skip to content

feat(client): improve logging #40

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 1 commit into from
Feb 21, 2025
Merged

feat(client): improve logging #40

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
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
76 changes: 54 additions & 22 deletions README.md
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -187,6 +187,59 @@ console.log(raw.headers.get('X-My-Header'));
console.log(response.organizationId);
```

### Logging

> [!IMPORTANT]
> All log messages are intended for debugging only. The format and content of log messages
> may change between releases.

#### Log levels

The log level can be configured in two ways:

1. Via the `GITPOD_LOG` environment variable
2. Using the `logLevel` client option (overrides the environment variable if set)

```ts
import Gitpod from '@gitpod/sdk';

const client = new Gitpod({
logLevel: 'debug', // Show all log messages
});
```

Available log levels, from most to least verbose:

- `'debug'` - Show debug messages, info, warnings, and errors
- `'info'` - Show info messages, warnings, and errors
- `'warn'` - Show warnings and errors (default)
- `'error'` - Show only errors
- `'off'` - Disable all logging

At the `'debug'` level, all HTTP requests and responses are logged, including headers and bodies.
Some authentication-related headers are redacted, but sensitive data in request and response bodies
may still be visible.

#### Custom logger

By default, this library logs to `globalThis.console`. You can also provide a custom logger.
Most logging libraries are supported, including [pino](https://www.npmjs.com/package/pino), [winston](https://www.npmjs.com/package/winston), [bunyan](https://www.npmjs.com/package/bunyan), [consola](https://www.npmjs.com/package/consola), [signale](https://www.npmjs.com/package/signale), and [@std/log](https://jsr.io/@std/log). If your logger doesn't work, please open an issue.

When providing a custom logger, the `logLevel` option still controls which messages are emitted, messages
below the configured level will not be sent to your logger.

```ts
import Gitpod from '@gitpod/sdk';
import pino from 'pino';

const logger = pino();

const client = new Gitpod({
logger: logger.child({ name: 'Gitpod' }),
logLevel: 'debug', // Send all messages to pino, allowing it to filter
});
```

### Making custom/undocumented requests

This library is typed for convenient access to the documented API. If you need to access undocumented
Expand Down Expand Up @@ -246,33 +299,12 @@ globalThis.fetch = fetch;
Or pass it to the client:

```ts
import Gitpod from '@gitpod/sdk';
import fetch from 'my-fetch';

const client = new Gitpod({ fetch });
```

### Logging and middleware

You may also provide a custom `fetch` function when instantiating the client,
which can be used to inspect or alter the `Request` or `Response` before/after each request:

```ts
import { fetch } from 'undici'; // as one example
import Gitpod from '@gitpod/sdk';

const client = new Gitpod({
fetch: async (url: RequestInfo, init?: RequestInit): Promise<Response> => {
console.log('About to make a request', url, init);
const response = await fetch(url, init);
console.log('Got response', response);
return response;
},
});
```

Note that if given a `GITPOD_LOG=debug` environment variable, this library will log all requests and responses automatically.
This is intended for debugging purposes only and may change in the future without notice.

### Fetch options

If you want to set custom `fetch` options without overriding the `fetch` function, you can provide a `fetchOptions` object when instantiating the client or making a request. (Request-specific options override client options.)
Expand Down
172 changes: 135 additions & 37 deletions src/client.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -3,7 +3,7 @@
import type { RequestInit, RequestInfo, BodyInit } from './internal/builtin-types';
import type { HTTPMethod, PromiseOrValue, MergedRequestInit } from './internal/types';
import { uuid4 } from './internal/utils/uuid';
import { validatePositiveInteger, isAbsoluteURL } from './internal/utils/values';
import { validatePositiveInteger, isAbsoluteURL, hasOwn } from './internal/utils/values';
import { sleep } from './internal/utils/sleep';
import { castToError, isAbortError } from './internal/errors';
import type { APIResponseProps } from './internal/parse';
Expand Down Expand Up @@ -122,7 +122,7 @@ import {
SecretsSecretsPage,
} from './resources/secrets';
import { readEnv } from './internal/utils/env';
import { logger } from './internal/utils/log';
import { formatRequestDetails, loggerFor } from './internal/utils/log';
import { isEmptyObj } from './internal/utils/values';
import {
AdmissionLevel,
Expand Down Expand Up @@ -251,15 +251,30 @@ export type Logger = {
debug: LogFn;
};
export type LogLevel = 'off' | 'error' | 'warn' | 'info' | 'debug';
const isLogLevel = (key: string | undefined): key is LogLevel => {
const parseLogLevel = (
maybeLevel: string | undefined,
sourceName: string,
client: Gitpod,
): LogLevel | undefined => {
if (!maybeLevel) {
return undefined;
}
const levels: Record<LogLevel, true> = {
off: true,
error: true,
warn: true,
info: true,
debug: true,
};
return key! in levels;
if (hasOwn(levels, maybeLevel)) {
return maybeLevel;
}
loggerFor(client).warn(
`${sourceName} was set to ${JSON.stringify(maybeLevel)}, expected one of ${JSON.stringify(
Object.keys(levels),
)}`,
);
return undefined;
};

export interface ClientOptions {
Expand Down Expand Up @@ -323,16 +338,16 @@ export interface ClientOptions {
/**
* Set the log level.
*
* Defaults to process.env['GITPOD_LOG'].
* Defaults to process.env['GITPOD_LOG'] or 'warn' if it isn't set.
*/
logLevel?: LogLevel | undefined | null;
logLevel?: LogLevel | undefined;

/**
* Set the logger.
*
* Defaults to globalThis.console.
*/
logger?: Logger | undefined | null;
logger?: Logger | undefined;
}

type FinalizedRequestInit = RequestInit & { headers: Headers };
Expand Down Expand Up @@ -387,14 +402,13 @@ export class Gitpod {
this.baseURL = options.baseURL!;
this.timeout = options.timeout ?? Gitpod.DEFAULT_TIMEOUT /* 1 minute */;
this.logger = options.logger ?? console;
if (options.logLevel != null) {
this.logLevel = options.logLevel;
} else {
const envLevel = readEnv('GITPOD_LOG');
if (isLogLevel(envLevel)) {
this.logLevel = envLevel;
}
}
const defaultLogLevel = 'warn';
// Set default logLevel early so that we can log a warning in parseLogLevel.
this.logLevel = defaultLogLevel;
this.logLevel =
parseLogLevel(options.logLevel, 'ClientOptions.logLevel', this) ??
parseLogLevel(readEnv('GITPOD_LOG'), "process.env['GITPOD_LOG']", this) ??
defaultLogLevel;
this.fetchOptions = options.fetchOptions;
this.maxRetries = options.maxRetries ?? 2;
this.fetch = options.fetch ?? Shims.getDefaultFetch();
Expand Down Expand Up @@ -524,12 +538,13 @@ export class Gitpod {
options: PromiseOrValue<FinalRequestOptions>,
remainingRetries: number | null = null,
): APIPromise<Rsp> {
return new APIPromise(this, this.makeRequest(options, remainingRetries));
return new APIPromise(this, this.makeRequest(options, remainingRetries, undefined));
}

private async makeRequest(
optionsInput: PromiseOrValue<FinalRequestOptions>,
retriesRemaining: number | null,
retryOfRequestLogID: string | undefined,
): Promise<APIResponseProps> {
const options = await optionsInput;
const maxRetries = options.maxRetries ?? this.maxRetries;
Expand All @@ -543,60 +558,142 @@ export class Gitpod {

await this.prepareRequest(req, { url, options });

logger(this).debug('request', url, options, req.headers);
/** Not an API request ID, just for correlating local log entries. */
const requestLogID = 'log_' + ((Math.random() * (1 << 24)) | 0).toString(16).padStart(6, '0');
const retryLogStr = retryOfRequestLogID === undefined ? '' : `, retryOf: ${retryOfRequestLogID}`;
const startTime = Date.now();

loggerFor(this).debug(
`[${requestLogID}] sending request`,
formatRequestDetails({
retryOfRequestLogID,
method: options.method,
url,
options,
headers: req.headers,
}),
);

if (options.signal?.aborted) {
throw new Errors.APIUserAbortError();
}

const controller = new AbortController();
const response = await this.fetchWithTimeout(url, req, timeout, controller).catch(castToError);
const headersTime = Date.now();

if (response instanceof Error) {
const retryMessage = `retrying, ${retriesRemaining} attempts remaining`;
if (options.signal?.aborted) {
throw new Errors.APIUserAbortError();
}
if (retriesRemaining) {
return this.retryRequest(options, retriesRemaining);
}
if (isAbortError(response)) {
throw new Errors.APIConnectionTimeoutError();
}
// detect native connection timeout errors
// deno throws "TypeError: error sending request for url (https://example/): client error (Connect): tcp connect error: Operation timed out (os error 60): Operation timed out (os error 60)"
// undici throws "TypeError: fetch failed" with cause "ConnectTimeoutError: Connect Timeout Error (attempted address: example:443, timeout: 1ms)"
// others do not provide enough information to distinguish timeouts from other connection errors
if (/timed? ?out/i.test(String(response) + ('cause' in response ? String(response.cause) : ''))) {
const isTimeout =
isAbortError(response) ||
/timed? ?out/i.test(String(response) + ('cause' in response ? String(response.cause) : ''));
if (retriesRemaining) {
loggerFor(this).info(
`[${requestLogID}] connection ${isTimeout ? 'timed out' : 'failed'} - ${retryMessage}`,
);
loggerFor(this).debug(
`[${requestLogID}] connection ${isTimeout ? 'timed out' : 'failed'} (${retryMessage})`,
formatRequestDetails({
retryOfRequestLogID,
url,
durationMs: headersTime - startTime,
message: response.message,
}),
);
return this.retryRequest(options, retriesRemaining, retryOfRequestLogID ?? requestLogID);
}
loggerFor(this).info(
`[${requestLogID}] connection ${isTimeout ? 'timed out' : 'failed'} - error; no more retries left`,
);
loggerFor(this).debug(
`[${requestLogID}] connection ${isTimeout ? 'timed out' : 'failed'} (error; no more retries left)`,
formatRequestDetails({
retryOfRequestLogID,
url,
durationMs: headersTime - startTime,
message: response.message,
}),
);
if (isTimeout) {
throw new Errors.APIConnectionTimeoutError();
}
throw new Errors.APIConnectionError({ cause: response });
}

const responseInfo = `[${requestLogID}${retryLogStr}] ${req.method} ${url} ${
response.ok ? 'succeeded' : 'failed'
} with status ${response.status} in ${headersTime - startTime}ms`;

if (!response.ok) {
if (retriesRemaining && this.shouldRetry(response)) {
const shouldRetry = this.shouldRetry(response);
if (retriesRemaining && shouldRetry) {
const retryMessage = `retrying, ${retriesRemaining} attempts remaining`;
logger(this).debug(`response (error; ${retryMessage})`, response.status, url, response.headers);
return this.retryRequest(options, retriesRemaining, response.headers);

// We don't need the body of this response.
await Shims.CancelReadableStream(response.body);
loggerFor(this).info(`${responseInfo} - ${retryMessage}`);
loggerFor(this).debug(
`[${requestLogID}] response error (${retryMessage})`,
formatRequestDetails({
retryOfRequestLogID,
url: response.url,
status: response.status,
headers: response.headers,
durationMs: headersTime - startTime,
}),
);
return this.retryRequest(
options,
retriesRemaining,
retryOfRequestLogID ?? requestLogID,
response.headers,
);
}

const retryMessage = shouldRetry ? `error; no more retries left` : `error; not retryable`;

loggerFor(this).info(`${responseInfo} - ${retryMessage}`);

const errText = await response.text().catch((err: any) => castToError(err).message);
const errJSON = safeJSON(errText);
const errMessage = errJSON ? undefined : errText;
const retryMessage = retriesRemaining ? `(error; no more retries left)` : `(error; not retryable)`;

logger(this).debug(
`response (error; ${retryMessage})`,
response.status,
url,
response.headers,
errMessage,
loggerFor(this).debug(
`[${requestLogID}] response error (${retryMessage})`,
formatRequestDetails({
retryOfRequestLogID,
url: response.url,
status: response.status,
headers: response.headers,
message: errMessage,
durationMs: Date.now() - startTime,
}),
);

const err = this.makeStatusError(response.status, errJSON, errMessage, response.headers);
throw err;
}

return { response, options, controller };
loggerFor(this).info(responseInfo);
loggerFor(this).debug(
`[${requestLogID}] response start`,
formatRequestDetails({
retryOfRequestLogID,
url: response.url,
status: response.status,
headers: response.headers,
durationMs: headersTime - startTime,
}),
);

return { response, options, controller, requestLogID, retryOfRequestLogID, startTime };
}

getAPIList<Item, PageClass extends Pagination.AbstractPage<Item> = Pagination.AbstractPage<Item>>(
Expand All @@ -614,7 +711,7 @@ export class Gitpod {
Page: new (...args: ConstructorParameters<typeof Pagination.AbstractPage>) => PageClass,
options: FinalRequestOptions,
): Pagination.PagePromise<PageClass, Item> {
const request = this.makeRequest(options, null);
const request = this.makeRequest(options, null, undefined);
return new Pagination.PagePromise<PageClass, Item>(this as any as Gitpod, request, Page);
}

Expand Down Expand Up @@ -677,6 +774,7 @@ export class Gitpod {
private async retryRequest(
options: FinalRequestOptions,
retriesRemaining: number,
requestLogID: string,
responseHeaders?: Headers | undefined,
): Promise<APIResponseProps> {
let timeoutMillis: number | undefined;
Expand Down Expand Up @@ -709,7 +807,7 @@ export class Gitpod {
}
await sleep(timeoutMillis);

return this.makeRequest(options, retriesRemaining - 1);
return this.makeRequest(options, retriesRemaining - 1, requestLogID);
}

private calculateDefaultRetryTimeoutMillis(retriesRemaining: number, maxRetries: number): number {
Expand Down
Loading