From 383ee9e7b75cdc14023cfdaaba0b505761bd0055 Mon Sep 17 00:00:00 2001 From: Ariel Caplan Date: Fri, 23 Dec 2022 10:16:15 +0200 Subject: [PATCH 1/4] Log request times for partners API and other HTTP fetch --- packages/cli-kit/src/api/partners.ts | 4 ++++ packages/cli-kit/src/http/fetch.ts | 3 +++ 2 files changed, 7 insertions(+) diff --git a/packages/cli-kit/src/api/partners.ts b/packages/cli-kit/src/api/partners.ts index 59f5dc9662..377b5a5f67 100644 --- a/packages/cli-kit/src/api/partners.ts +++ b/packages/cli-kit/src/api/partners.ts @@ -2,6 +2,7 @@ import {buildHeaders, debugLogRequest, handlingErrors} from './common.js' import {ScriptServiceProxyQuery} from './graphql/index.js' import {partners as partnersFqdn} from '../environment/fqdn.js' import {graphqlClient} from '../http/graphql.js' +import {debug} from '../output.js' import {Variables, RequestDocument} from 'graphql-request' export async function request(query: RequestDocument, token: string, variables?: Variables): Promise { @@ -12,7 +13,10 @@ export async function request(query: RequestDocument, token: string, variable const headers = await buildHeaders(token) debugLogRequest(api, query, variables, headers) const client = await graphqlClient({headers, url}) + const t0 = performance.now() const response = await client.request(query, variables) + const t1 = performance.now() + debug(`Request to ${url.toString()} completed in ${Math.round(t1 - t0)} ms`) return response }) } diff --git a/packages/cli-kit/src/http/fetch.ts b/packages/cli-kit/src/http/fetch.ts index 8fe45fa85b..e6a500487e 100644 --- a/packages/cli-kit/src/http/fetch.ts +++ b/packages/cli-kit/src/http/fetch.ts @@ -39,6 +39,9 @@ export async function shopifyFetch(url: RequestInfo, init?: RequestInit): Respon Sending ${options.method ?? 'GET'} request to URL ${url.toString()} and headers: ${sanitizedHeadersOutput((options?.headers ?? {}) as {[header: string]: string})} `) + const t0 = performance.now() const response = await nodeFetch(url, {...init, agent: await httpsAgent()}) + const t1 = performance.now() + debug(`Request to ${url.toString()} completed with status ${response.status} in ${Math.round(t1 - t0)} ms`) return response } From 888c69e70e45bd4b77db6441cc33301dc7fa4bfa Mon Sep 17 00:00:00 2001 From: Gonzalo Riestra Date: Fri, 23 Dec 2022 14:03:10 +0100 Subject: [PATCH 2/4] Add performance import (required for Node < 16) --- packages/cli-kit/src/api/partners.ts | 1 + packages/cli-kit/src/http/fetch.ts | 1 + 2 files changed, 2 insertions(+) diff --git a/packages/cli-kit/src/api/partners.ts b/packages/cli-kit/src/api/partners.ts index 377b5a5f67..914f065a4e 100644 --- a/packages/cli-kit/src/api/partners.ts +++ b/packages/cli-kit/src/api/partners.ts @@ -4,6 +4,7 @@ import {partners as partnersFqdn} from '../environment/fqdn.js' import {graphqlClient} from '../http/graphql.js' import {debug} from '../output.js' import {Variables, RequestDocument} from 'graphql-request' +import {performance} from 'perf_hooks' export async function request(query: RequestDocument, token: string, variables?: Variables): Promise { const api = 'Partners' diff --git a/packages/cli-kit/src/http/fetch.ts b/packages/cli-kit/src/http/fetch.ts index e6a500487e..5009b5d70a 100644 --- a/packages/cli-kit/src/http/fetch.ts +++ b/packages/cli-kit/src/http/fetch.ts @@ -2,6 +2,7 @@ import {httpsAgent} from '../http.js' import {buildHeaders, sanitizedHeadersOutput} from '../api/common.js' import {content, debug} from '../output.js' import nodeFetch from 'node-fetch' +import {performance} from 'perf_hooks' import type {RequestInfo, RequestInit} from 'node-fetch' type Response = ReturnType From 36fa6d1d1f046171550dad758c2cfb0f8a3d2910 Mon Sep 17 00:00:00 2001 From: Gonzalo Riestra Date: Fri, 23 Dec 2022 14:04:28 +0100 Subject: [PATCH 3/4] Add time to debug messages --- packages/cli-kit/src/output.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/packages/cli-kit/src/output.ts b/packages/cli-kit/src/output.ts index 3edbcc1be8..efe4e9fbf3 100644 --- a/packages/cli-kit/src/output.ts +++ b/packages/cli-kit/src/output.ts @@ -257,7 +257,7 @@ export const completed = (content: Message, logger: Logger = consoleLog) => { export const debug = (content: Message, logger: Logger = consoleLog) => { if (isUnitTest()) collectLog('debug', content) const message = colors.gray(stringifyMessage(content)) - outputWhereAppropriate('debug', logger, message) + outputWhereAppropriate('debug', logger, `${new Date().toISOString()}: ${message}`) } /** From 23b1cc84e504133a0baa74700aa9eb27c33ef0d9 Mon Sep 17 00:00:00 2001 From: Gonzalo Riestra Date: Fri, 23 Dec 2022 14:42:30 +0100 Subject: [PATCH 4/4] Create stupid-games-type.md --- .changeset/stupid-games-type.md | 5 +++++ 1 file changed, 5 insertions(+) create mode 100644 .changeset/stupid-games-type.md diff --git a/.changeset/stupid-games-type.md b/.changeset/stupid-games-type.md new file mode 100644 index 0000000000..dcb46acb20 --- /dev/null +++ b/.changeset/stupid-games-type.md @@ -0,0 +1,5 @@ +--- +'@shopify/cli-kit': patch +--- + +Add timing information to verbose logs