diff --git a/packages/gateway/README.md b/packages/gateway/README.md index 92d7cdfe4a..cbbe627439 100644 --- a/packages/gateway/README.md +++ b/packages/gateway/README.md @@ -25,6 +25,7 @@ One time set up of your cloudflare worker subdomain for dev: ```sh wrangler secret put SENTRY_DSN --env $(whoami) # Get from Sentry (not required for dev) + wrangler secret put LOGTAIL_TOKEN --env $(whoami) # Get from Logtail ``` - `npm run publish` - Publish the worker under your env. An alias for `wrangler publish --env $(whoami)` diff --git a/packages/gateway/package.json b/packages/gateway/package.json index 5fde78036c..6228280dcf 100644 --- a/packages/gateway/package.json +++ b/packages/gateway/package.json @@ -18,6 +18,7 @@ "dependencies": { "itty-router": "^2.4.5", "multiformats": "^9.5.2", + "nanoid": "^3.1.30", "p-any": "^4.0.0", "p-settle": "^5.0.0", "toucan-js": "^2.5.0" diff --git a/packages/gateway/src/env.js b/packages/gateway/src/env.js index 40d8646c1e..2d345f2606 100644 --- a/packages/gateway/src/env.js +++ b/packages/gateway/src/env.js @@ -1,13 +1,18 @@ import Toucan from 'toucan-js' import pkg from '../package.json' +import { Logging } from './logs.js' // TODO: Get Durable object typedef /** * @typedef {Object} EnvInput * @property {string} IPFS_GATEWAYS * @property {string} VERSION + * @property {string} COMMITHASH + * @property {string} BRANCH + * @property {string} DEBUG * @property {string} ENV * @property {string} [SENTRY_DSN] + * @property {string} [LOGTAIL_TOKEN] * @property {number} [REQUEST_TIMEOUT] * @property {Object} METRICS * @property {Object} CIDSTRACKER @@ -18,6 +23,7 @@ import pkg from '../package.json' * @property {Object} cidsTrackerDurable * @property {number} REQUEST_TIMEOUT * @property {Toucan} [sentry] + * @property {Logging} [log] * * @typedef {EnvInput & EnvTransformed} Env */ @@ -25,13 +31,15 @@ import pkg from '../package.json' /** * @param {Request} request * @param {Env} env + * @param {import('./').Ctx} ctx */ -export function envAll(request, env) { +export function envAll(request, env, ctx) { env.sentry = getSentry(request, env) env.ipfsGateways = JSON.parse(env.IPFS_GATEWAYS) env.metricsDurable = env.METRICS env.cidsTrackerDurable = env.CIDSTRACKER env.REQUEST_TIMEOUT = env.REQUEST_TIMEOUT || 20000 + env.log = new Logging(request, env, ctx) } /** diff --git a/packages/gateway/src/error-handler.js b/packages/gateway/src/error-handler.js index 1756b97caa..0723e5135f 100644 --- a/packages/gateway/src/error-handler.js +++ b/packages/gateway/src/error-handler.js @@ -8,7 +8,7 @@ export function errorHandler(err, env) { const status = err.status || 500 if (env.sentry && status >= 500) { - env.sentry.captureException(err) + env.log.error(err) } return new Response(err.message || 'Server Error', { status }) diff --git a/packages/gateway/src/logs.js b/packages/gateway/src/logs.js new file mode 100644 index 0000000000..5bd39e343c --- /dev/null +++ b/packages/gateway/src/logs.js @@ -0,0 +1,267 @@ +import { nanoid } from 'nanoid/non-secure' + +const logtailApiURL = 'https://in.logtail.com/' + +const buildMetadataFromHeaders = (/** @type {Headers} */ headers) => { + /** @type {Record} */ + const responseMetadata = {} + Array.from(headers).forEach(([key, value]) => { + responseMetadata[key.replace(/-/g, '_')] = value + }) + return responseMetadata +} + +export class Logging { + /** + * @param {Request} request + * @param {import('./env').Env} env + * @param {import('./').Ctx} ctx + */ + constructor(request, env, ctx) { + this.request = request + this.env = env + this.ctx = ctx + + this._times = new Map() + /** + * @type {string[]} + */ + this._timesOrder = [] + /** + * @type {any[]} + */ + this.logEventsBatch = [] + this.startTs = Date.now() + this.currentTs = this.startTs + + const cf = request.cf // TODO? + let rCf + if (cf) { + const { tlsClientAuth, tlsExportedAuthenticator, ...rest } = cf + rCf = rest + } + this.metadata = { + user: { + id: 0, + }, + request: { + url: request.url, + method: request.method, + headers: buildMetadataFromHeaders(request.headers), + cf: rCf, + }, + cloudflare_worker: { + version: env.VERSION, + commit: env.COMMITHASH, + branch: env.BRANCH, + worker_id: nanoid(10), + worker_started: this.startTs, + }, + } + } + + _date() { + const now = Date.now() + if (now === this.currentTs) { + const dt = new Date().toISOString() + /** + * Fake increment the datetime string to order the logs entries + * It won't leap seconds but for most cases it will increment by 1 the datetime milliseconds + */ + const newDt = dt.replace(/\.(\d*)Z/, (s, p1, p2) => { + return `.${String(Number(p1) + this.logEventsBatch.length)}Z` + }) + return new Date(newDt).toISOString() + } else { + this.currentTs = now + return new Date().toISOString() + } + } + + /** + * Add log entry to batch + * + * @param {any} body + */ + _add(body) { + this.logEventsBatch.push(body) + } + + async postBatch() { + if (this.logEventsBatch.length > 0) { + const batchInFlight = [...this.logEventsBatch] + this.logEventsBatch = [] + const rHost = batchInFlight[0].metadata.request.headers.host + const body = JSON.stringify(batchInFlight) + const request = { + method: 'POST', + headers: { + Authorization: `Bearer ${this.env.LOGTAIL_TOKEN}`, + 'Content-Type': 'application/json', + 'User-Agent': `Cloudflare Worker via ${rHost}`, + }, + body, + } + const resp = await fetch(logtailApiURL, request) + if (this.env.DEBUG) { + console.info( + `[${this._date()}] `, + `${batchInFlight.length} Logs pushed with status ${resp.status}.` + ) + } + } + } + + /** + * End instance, push logs and servers timings + * + * @param {Response} response + */ + async end(response) { + if (this.env.DEBUG) { + response.headers.set('Server-Timing', this._timersString()) + } + const run = async () => { + const dt = this._date() + const duration = Date.now() - this.startTs + const log = { + message: '', + dt, + level: 'info', + metadata: { + ...this.metadata, + response: { + headers: buildMetadataFromHeaders(response.headers), + status_code: response.status, + duration, + }, + }, + } + this._add(log) + await this.postBatch() + } + this.ctx.waitUntil(run()) + + return response + } + + /** + * Log + * + * @param {string | Error} message + * @param {'debug' | 'info' | 'warn' | 'error'} level + * @param {any} [context] + * @param {any} [metadata] + */ + log(message, level, context, metadata) { + const dt = this._date() + let log = { + dt, + level, + metadata: { ...this.metadata, ...metadata }, + ...context, + } + + if (message instanceof Error) { + log = { + ...log, + stack: message.stack, + message: message.message, + } + this.env.sentry && this.env.sentry.captureException(message) + } else { + log = { + ...log, + message, + } + } + + if (this.env.DEBUG) { + console[level](`[${dt}] `, log.message, context) + } + this._add(log) + } + + /** + * @param {string} message + * @param {any} [context] + */ + debug(message, context) { + return this.log(message, 'debug', context) + } + + /** + * @param {string} message + * @param {any} [context] + */ + info(message, context) { + return this.log(message, 'info', context) + } + + /** + * @param {string} message + * @param {any} [context] + */ + warn(message, context) { + return this.log(message, 'warn', context) + } + /** + * @param {string | Error} message + * @param {any} [context] + */ + error(message, context) { + return this.log(message, 'error', context) + } + + /** + * @param {string} name + * @param {any} [description] + */ + time(name, description) { + this._times.set(name, { + name: name, + description: description, + start: Date.now(), + }) + this._timesOrder.push(name) + } + + /** + * @param {string} name + */ + timeEnd(name) { + const timeObj = this._times.get(name) + if (!timeObj) { + return console.warn(`No such name ${name}`) + } + + const end = Date.now() + const duration = end - timeObj.start + const value = duration + timeObj.value = value + this._times.set(name, { + ...timeObj, + end, + duration, + }) + + if (this.env.DEBUG) { + console.log(`[${this._date()}] `, `name: ${duration} ms`) + } + return timeObj + } + + _timersString() { + const result = [] + for (const key of this._timesOrder) { + const { name, duration, description } = this._times.get(key) + result.push( + description + ? `${name};desc="${description}";dur=${duration}` + : `${name};dur=${duration}` + ) + } + + return result.join(',') + } +} diff --git a/packages/gateway/wrangler.toml b/packages/gateway/wrangler.toml index 6c80321791..7b95c5b540 100644 --- a/packages/gateway/wrangler.toml +++ b/packages/gateway/wrangler.toml @@ -16,38 +16,55 @@ format = "modules" dir = "dist" main = "index.mjs" -[durable_objects] -bindings = [{name = "METRICS", class_name = "Metrics13"}, {name = "CIDSTRACKER", class_name = "CidsTracker0"}] - # PROD! [env.production] # name = "gateway-nft-storage-production" account_id = "fffa4b4363a7e5250af8357087263b3a" # Protocol Labs CF account zone_id = "fc6cb51dbc2d0b9a729eae6a302a49c9" # nft.storage zone route = "*gateway.nft.storage/*" -vars = { IPFS_GATEWAYS = "[\"https://ipfs.io\", \"https://cf-ipfs.com\", \"https://nft-storage.mypinata.cloud/\"]", ENV = "production" } +[env.production.vars] +IPFS_GATEWAYS = "[\"https://ipfs.io\", \"https://cf-ipfs.com\", \"https://nft-storage.mypinata.cloud/\"]" +DEBUG = "false" +ENV = "production" + +[env.production.durable_objects] +bindings = [{name = "METRICS", class_name = "Metrics13"}, {name = "CIDSTRACKER", class_name = "CidsTracker0"}] + +# Staging! [env.staging] # name = "gateway-nft-storage-staging" account_id = "fffa4b4363a7e5250af8357087263b3a" # Protocol Labs CF account zone_id = "fc6cb51dbc2d0b9a729eae6a302a49c9" # nft.storage zone route = "*gateway-staging.nft.storage/*" -vars = { IPFS_GATEWAYS = "[\"https://ipfs.io\", \"https://cf-ipfs.com\", \"https://nft-storage.mypinata.cloud/\"]", ENV = "staging" } + +[env.staging.vars] +IPFS_GATEWAYS = "[\"https://ipfs.io\", \"https://cf-ipfs.com\", \"https://nft-storage.mypinata.cloud/\"]" +DEBUG = "true" +ENV = "staging" [env.staging.durable_objects] bindings = [{name = "METRICS", class_name = "Metrics13"}, {name = "CIDSTRACKER", class_name = "CidsTracker0"}] +# Test! [env.test] workers_dev = true -vars = { IPFS_GATEWAYS = "[\"http://localhost:9081\", \"http://localhost:9082\"]", ENV = "test" } + +[env.test.vars] +IPFS_GATEWAYS = "[\"http://localhost:9081\", \"http://localhost:9082\"]" +DEBUG = "true" +ENV = "test" [env.test.durable_objects] bindings = [{name = "METRICS", class_name = "Metrics13"}, {name = "CIDSTRACKER", class_name = "CidsTracker0"}] +# Dev! [env.vsantos] workers_dev = true account_id = "7ec0b7cf2ec201b2580374e53ba5f37b" -vars = { IPFS_GATEWAYS = "[\"https://ipfs.io\"]" } + +[env.vsantos.vars] +IPFS_GATEWAYS = "[\"https://ipfs.io\"]" [env.vsantos.durable_objects] bindings = [{name = "METRICS", class_name = "Metrics13"}, {name = "CIDSTRACKER", class_name = "CidsTracker0"}]