Add some console logs to print network times for each API request

Author: isaacroldan

packages/cli-kit/src/private/node/api.ts

@@ -1,5 +1,6 @@
 import {sanitizedHeadersOutput} from './api/headers.js'
 import {sanitizeURL} from './api/urls.js'
+import {startHRTime} from '@shopify/cli-kit/node/hrtime'
 import {outputDebug} from '@shopify/cli-kit/node/output'
 import {Headers} from 'form-data'
 import {ClientError} from 'graphql-request'
@@ -53,7 +54,9 @@ async function makeVerboseRequest<T extends {headers: Headers; status: number}>(
   const sanitizedUrl = sanitizeURL(url)
   let response: T = {} as T
   try {
+    const start = startHRTime()
     response = await request()
+    // console.log(`${endHRTimeInMs(start)}ms - Network: ${outputContent`${outputToken.magenta(url)}`.value}`)
     // eslint-disable-next-line @typescript-eslint/no-explicit-any
     response.headers.forEach((value: any, key: any) => {
       if (responseHeaderIsInteresting(key)) responseHeaders[key] = value

packages/cli-kit/src/private/node/session/validate.ts

@@ -6,6 +6,7 @@ import {sessionConstants} from '../constants.js'
 import {outputDebug} from '../../../public/node/output.js'
 import {firstPartyDev} from '../../../public/node/context/local.js'
 import {OAuthApplications} from '../session.js'
+import {endHRTimeInMs, startHRTime} from '@shopify/cli-kit/node/hrtime'
 
 type ValidationResult = 'needs_refresh' | 'needs_full_auth' | 'ok'
 
@@ -35,7 +36,9 @@ export async function validateSession(
 ): Promise<ValidationResult> {
   if (!session) return 'needs_full_auth'
   const scopesAreValid = validateScopes(scopes, session.identity)
+  const start = startHRTime()
   const identityIsValid = await validateIdentityToken(session.identity.accessToken)
+  console.log(`${endHRTimeInMs(start)}ms - Auth: Identity token introspection (${identityIsValid ? 'OK' : 'FAILED'})`)
   if (!scopesAreValid) return 'needs_full_auth'
   let tokensAreExpired = isTokenExpired(session.identity)
 

packages/cli-kit/src/public/node/analytics.ts

@@ -49,6 +49,7 @@ export async function reportAnalyticsEvent(options: ReportAnalyticsEventOptions)
         withinRateLimit = true
       },
     })
+    console.log('All network time:', payload.public.cmd_all_timing_network_ms)
     if (!withinRateLimit) {
       outputDebug(outputContent`Skipping command analytics due to rate limiting, payload: ${outputToken.json(payload)}`)
       return

packages/cli-kit/src/public/node/api/graphql.ts

@@ -3,6 +3,8 @@ import {debugLogRequestInfo, errorHandler} from '../../../private/node/api/graph
 import {addPublicMetadata, runWithTimer} from '../metadata.js'
 import {retryAwareRequest} from '../../../private/node/api.js'
 import {requestIdsCollection} from '../../../private/node/request-ids.js'
+import {endHRTimeInMs, startHRTime} from '../hrtime.js'
+import {outputContent, outputToken} from '../output.js'
 import {
   GraphQLClient,
   rawRequest,
@@ -75,8 +77,13 @@ async function performGraphQLRequest<TResult>(options: PerformGraphQLRequestOpti
     // there is a errorPolicy option which returns rather than throwing on errors, but we _do_ ultimately want to
     // throw.
     try {
+      const time = startHRTime()
       fullResponse = await client.rawRequest<TResult>(queryAsString, variables)
       await logLastRequestIdFromResponse(fullResponse)
+      const firstLine = queryAsString.split('\n')[0] ?? ''
+      const secondLine = queryAsString.split('\n')[1] ?? ''
+      const validLine = firstLine.includes('query') ? firstLine : secondLine
+      console.log(`${endHRTimeInMs(time)}ms - Network: ${outputContent`${outputToken.yellow(validLine)}`.value}`)
       return fullResponse
     } catch (error) {
       if (error instanceof ClientError) {