Skip to content

Commit

Permalink
[server] improved logging (#18697)
Browse files Browse the repository at this point in the history
  • Loading branch information
@svenefftinge
svenefftinge authored Sep 12, 2023
1 parent c23f106 commit e2ae3e3
Show file tree
Hide file tree
Showing 6 changed files with 97 additions and 65 deletions.
49 changes: 26 additions & 23 deletions components/server/src/jobs/runner.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -18,6 +18,7 @@ import { WebhookEventGarbageCollector } from "./webhook-gc";
import { WorkspaceGarbageCollector } from "./workspace-gc";
import { SnapshotsJob } from "./snapshots";
import { RelationshipUpdateJob } from "../authorization/relationship-updater-job";
import { runWithContext } from "../util/log-context";

export const Job = Symbol("Job");

Expand Down Expand Up @@ -78,29 +79,31 @@ export class JobRunner {

try {
await this.mutex.using([job.name, ...(job.lockedResources || [])], job.frequencyMs, async (signal) => {
log.info(`Acquired lock for job ${job.name}.`, logCtx);
// we want to hold the lock for the entire duration of the job, so we return earliest after frequencyMs
const timeout = new Promise<void>((resolve) => setTimeout(resolve, job.frequencyMs));
const timer = jobsDurationSeconds.startTimer({ name: job.name });
reportJobStarted(job.name);
const now = new Date().getTime();
try {
await job.run();
log.info(`Successfully finished job ${job.name}`, {
...logCtx,
jobTookSec: `${(new Date().getTime() - now) / 1000}s`,
});
reportJobCompleted(job.name, true);
} catch (err) {
log.error(`Error while running job ${job.name}`, err, {
...logCtx,
jobTookSec: `${(new Date().getTime() - now) / 1000}s`,
});
reportJobCompleted(job.name, false);
} finally {
jobsDurationSeconds.observe(timer());
await timeout;
}
await runWithContext(job.name, {}, async () => {
log.info(`Acquired lock for job ${job.name}.`, logCtx);
// we want to hold the lock for the entire duration of the job, so we return earliest after frequencyMs
const timeout = new Promise<void>((resolve) => setTimeout(resolve, job.frequencyMs));
const timer = jobsDurationSeconds.startTimer({ name: job.name });
reportJobStarted(job.name);
const now = new Date().getTime();
try {
await job.run();
log.info(`Successfully finished job ${job.name}`, {
...logCtx,
jobTookSec: `${(new Date().getTime() - now) / 1000}s`,
});
reportJobCompleted(job.name, true);
} catch (err) {
log.error(`Error while running job ${job.name}`, err, {
...logCtx,
jobTookSec: `${(new Date().getTime() - now) / 1000}s`,
});
reportJobCompleted(job.name, false);
} finally {
jobsDurationSeconds.observe(timer());
await timeout;
}
});
});
} catch (err) {
if (err instanceof ResourceLockedError || err instanceof ExecutionError) {
Expand Down
27 changes: 15 additions & 12 deletions components/server/src/messaging/redis-subscriber.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -29,6 +29,7 @@ import {
} from "../prometheus-metrics";
import { Redis } from "ioredis";
import { WorkspaceDB } from "@gitpod/gitpod-db/lib";
import { runWithContext } from "../util/log-context";

const UNDEFINED_KEY = "undefined";

Expand All @@ -54,18 +55,20 @@ export class RedisSubscriber {
}

this.redis.on("message", async (channel: string, message: string) => {
reportRedisUpdateReceived(channel);

let err: Error | undefined;
try {
await this.onMessage(channel, message);
log.debug("[redis] Succesfully handled update", { channel, message });
} catch (e) {
err = e;
log.error("[redis] Failed to handle message from Pub/Sub", e, { channel, message });
} finally {
reportRedisUpdateCompleted(channel, err);
}
await runWithContext("redis-subscriber", {}, async () => {
reportRedisUpdateReceived(channel);

let err: Error | undefined;
try {
await this.onMessage(channel, message);
log.debug("[redis] Succesfully handled update", { channel, message });
} catch (e) {
err = e;
log.error("[redis] Failed to handle message from Pub/Sub", e, { channel, message });
} finally {
reportRedisUpdateCompleted(channel, err);
}
});
});
}

Expand Down
11 changes: 11 additions & 0 deletions components/server/src/server.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -47,6 +47,7 @@ import { GitHubEnterpriseApp } from "./prebuilds/github-enterprise-app";
import { JobRunner } from "./jobs/runner";
import { RedisSubscriber } from "./messaging/redis-subscriber";
import { HEADLESS_LOGS_PATH_PREFIX, HEADLESS_LOG_DOWNLOAD_PATH_PREFIX } from "./workspace/headless-log-service";
import { runWithContext } from "./util/log-context";

@injectable()
export class Server {
Expand Down Expand Up @@ -138,6 +139,16 @@ export class Server {
// Install passport
await this.authenticator.init(app);

// log context
app.use(async (req: express.Request, res: express.Response, next: express.NextFunction) => {
try {
const userId = req.user ? req.user.id : undefined;
await runWithContext("http", { userId }, () => next());
} catch (err) {
next(err);
}
});

// Ensure that host contexts of dynamic auth providers are initialized.
await this.hostCtxProvider.init();

Expand Down
19 changes: 14 additions & 5 deletions components/server/src/util/log-context.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -13,24 +13,33 @@ import { v4 } from "uuid";
type EnhancedLogContext = LogContext & {
contextId?: string;
contextTimeMs: number;
contextKind: string;
};

const asyncLocalStorage = new AsyncLocalStorage<EnhancedLogContext>();
const augmenter: LogContext.Augmenter = (ctx) => {
const globalContext = asyncLocalStorage.getStore();
const contextTime = globalContext?.contextTimeMs ? Date.now() - globalContext.contextTimeMs : undefined;
return {
const contextTimeMs = globalContext?.contextTimeMs ? Date.now() - globalContext.contextTimeMs : undefined;
const result = {
...globalContext,
contextTime,
contextTimeMs,
...ctx,
};
// if its an empty object return undefined
return Object.keys(result).length === 0 ? undefined : result;
};
LogContext.setAugmenter(augmenter);

export async function runWithContext<T>(context: LogContext, fun: () => T): Promise<T> {
export async function runWithContext<T>(
contextKind: string,
context: LogContext & { contextId?: string },
fun: () => T,
): Promise<T> {
return asyncLocalStorage.run(
{
...context,
contextId: v4(),
contextKind,
contextId: context.contextId || v4(),
contextTimeMs: Date.now(),
},
fun,
Expand Down
28 changes: 19 additions & 9 deletions components/server/src/websocket/websocket-connection-manager.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -374,21 +374,33 @@ class GitpodJsonRpcProxyFactory<T extends object> extends JsonRpcProxyFactory<T>
}

protected async onRequest(method: string, ...args: any[]): Promise<any> {
const span = TraceContext.startSpan(method, undefined);
const userId = this.clientMetadata.userId;
const requestId = span.context().toTraceId();
return runWithContext(
"request",
{
userId,
contextId: requestId,
},
() => {
return this.internalOnRequest(method, ...args);
try {
return this.internalOnRequest(span, requestId, method, ...args);
} finally {
span.finish();
}
},
);
}

private async internalOnRequest(method: string, ...args: any[]): Promise<any> {
const span = TraceContext.startSpan(method, undefined);
const ctx = { span };
private async internalOnRequest(
span: opentracing.Span,
requestId: string,
method: string,
...args: any[]
): Promise<any> {
const userId = this.clientMetadata.userId;
const ctx = { span };
const timer = apiCallDurationHistogram.startTimer();
try {
// generic tracing data
Expand Down Expand Up @@ -432,7 +444,7 @@ class GitpodJsonRpcProxyFactory<T extends object> extends JsonRpcProxyFactory<T>
observeAPICallsDuration(method, 200, timer());
return result;
} catch (e) {
const traceID = span.context().toTraceId();
const requestIdMessage = ` If this error is unexpected, please quote the request ID '${requestId}' when reaching out to Gitpod Support.`;
if (ApplicationError.hasErrorCode(e)) {
increaseApiCallCounter(method, e.code);
observeAPICallsDuration(method, e.code, timer());
Expand All @@ -449,13 +461,13 @@ class GitpodJsonRpcProxyFactory<T extends object> extends JsonRpcProxyFactory<T>
message: e.message,
},
);
throw new ResponseError(e.code, e.message, e.data);
throw new ResponseError(e.code, e.message + requestIdMessage, e.data);
} else {
TraceContext.setError(ctx, e); // this is a "real" error

const err = new ApplicationError(
ErrorCodes.INTERNAL_SERVER_ERROR,
`Internal server error. Please quote trace ID: '${traceID}' when reaching to Gitpod Support`,
`Internal server error: '${e.message}'` + requestIdMessage,
);
increaseApiCallCounter(method, err.code);
observeAPICallsDuration(method, err.code, timer());
Expand All @@ -464,8 +476,6 @@ class GitpodJsonRpcProxyFactory<T extends object> extends JsonRpcProxyFactory<T>
log.error({ userId }, `Request ${method} failed with internal server error`, e, { method, args });
throw new ResponseError(ErrorCodes.INTERNAL_SERVER_ERROR, e.message);
}
} finally {
span.finish();
}
}

Expand Down
28 changes: 12 additions & 16 deletions components/server/src/workspace/workspace-starter.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -484,9 +484,13 @@ export class WorkspaceStarter {
const span = TraceContext.startSpan("actuallyStartWorkspace", ctx);
const region = instance.configuration.regionPreference;
span.setTag("region_preference", region);
log.info("Attempting to start workspace", {
instanceID: instance.id,
userID: user.id,
const logCtx: LogContext = {
instanceId: instance.id,
userId: user.id,
organizationId: workspace.organizationId,
workspaceId: workspace.id,
};
log.info(logCtx, "Attempting to start workspace", {
forceRebuild: forceRebuild,
});

Expand Down Expand Up @@ -524,18 +528,10 @@ export class WorkspaceStarter {
const ideUrlPromise = new Deferred<string>();
const before = Date.now();
const logSuccess = (fromWsManager: boolean) => {
log.info(
{
instanceId: instance.id,
userId: workspace.ownerId,
workspaceId: workspace.id,
},
"Received ideURL",
{
tookMs: Date.now() - before,
fromWsManager,
},
);
log.info(logCtx, "Received ideURL", {
tookMs: Date.now() - before,
fromWsManager,
});
};

const doStartWorkspace = async () => {
Expand Down Expand Up @@ -623,7 +619,7 @@ export class WorkspaceStarter {
intervalHandle.dispose();
}
} catch (err) {
this.logAndTraceStartWorkspaceError({ span }, { userId: user.id, instanceId: instance.id }, err);
this.logAndTraceStartWorkspaceError({ span }, logCtx, err);

return { instanceID: instance.id };
} finally {
Expand Down

0 comments on commit e2ae3e3

Please sign in to comment.