Trace mutex locks in otel and fix tracing issues (#5471)

graphql-hive · Aug 21, 2024 · ce20e3d · ce20e3d
1 parent 7707b73
commit ce20e3d
Show file tree

Hide file tree

Showing 10 changed files with 106 additions and 31 deletions.
diff --git a/deployment/grafana-dashboards/Container-Logs.json b/deployment/grafana-dashboards/Container-Logs.json
@@ -26,7 +26,6 @@
   "graphTooltip": 0,
   "id": 54,
   "links": [],
-  "liveNow": false,
   "panels": [
     {
       "datasource": {
@@ -39,12 +38,14 @@
             "mode": "palette-classic"
           },
           "custom": {
+            "axisBorderShow": false,
             "axisCenteredZero": false,
             "axisColorMode": "text",
             "axisLabel": "",
             "axisPlacement": "auto",
             "axisSoftMin": 0,
             "barAlignment": 0,
+            "barWidthFactor": 0.6,
             "drawStyle": "line",
             "fillOpacity": 0,
             "gradientMode": "none",
@@ -53,6 +54,7 @@
               "tooltip": false,
               "viz": false
             },
+            "insertNulls": false,
             "lineInterpolation": "linear",
             "lineStyle": {
               "fill": "solid"
@@ -107,6 +109,7 @@
           "sort": "none"
         }
       },
+      "pluginVersion": "11.2.0-74515",
       "targets": [
         {
           "datasource": {
@@ -135,7 +138,6 @@
       "id": 4,
       "panels": [],
       "repeat": "service",
-      "repeatDirection": "h",
       "title": "$service",
       "type": "row"
     },
@@ -144,6 +146,10 @@
         "type": "loki",
         "uid": "grafanacloud-logs"
       },
+      "fieldConfig": {
+        "defaults": {},
+        "overrides": []
+      },
       "gridPos": {
         "h": 13,
         "w": 24,
@@ -154,21 +160,22 @@
       "options": {
         "dedupStrategy": "none",
         "enableLogDetails": true,
-        "prettifyLogMessage": true,
+        "prettifyLogMessage": false,
         "showCommonLabels": false,
         "showLabels": false,
         "showTime": true,
         "sortOrder": "Descending",
         "wrapLogMessage": false
       },
+      "pluginVersion": "11.2.0-74515",
       "targets": [
         {
           "datasource": {
             "type": "loki",
             "uid": "grafanacloud-logs"
           },
           "editorMode": "code",
-          "expr": "{container_name=\"$service\"} | json | __error__!=\"JSONParserErr\" | level>30 ",
+          "expr": "{container_name=\"$service\"} | json | regexp `(?P<requestId>[a-f0-9-]{36})`| line_format \"{{ .msg }}\" | __error__ != `JSONParserErr` | level > 30",
           "hide": false,
           "key": "Q-4f74f5b0-5837-415a-b726-56138193c25e-0",
           "queryType": "range",
@@ -183,6 +190,10 @@
         "type": "loki",
         "uid": "grafanacloud-logs"
       },
+      "fieldConfig": {
+        "defaults": {},
+        "overrides": []
+      },
       "gridPos": {
         "h": 11,
         "w": 24,
@@ -200,14 +211,15 @@
         "sortOrder": "Descending",
         "wrapLogMessage": false
       },
+      "pluginVersion": "11.2.0-74515",
       "targets": [
         {
           "datasource": {
             "type": "loki",
             "uid": "grafanacloud-logs"
           },
           "editorMode": "code",
-          "expr": "{container_name=\"$service\"} | json | __error__!=\"JSONParserErr\" ",
+          "expr": "{container_name=\"$service\"} | json | __error__ != `JSONParserErr` | regexp `(?P<requestId>[a-f0-9-]{36})` | line_format `{{ .msg }}`",
           "queryType": "range",
           "refId": "A"
         }
@@ -216,28 +228,24 @@
       "type": "logs"
     }
   ],
+  "preload": false,
   "refresh": "30s",
-  "revision": 1,
-  "schemaVersion": 38,
-  "style": "dark",
+  "schemaVersion": 39,
   "tags": ["kubernetes", "logs"],
   "templating": {
     "list": [
       {
         "current": {
-          "selected": false,
-          "text": "rate-limiter",
-          "value": "rate-limiter"
+          "text": "graphql-api",
+          "value": "graphql-api"
         },
         "datasource": {
           "type": "loki",
           "uid": "grafanacloud-logs"
         },
         "definition": "",
-        "hide": 0,
         "includeAll": false,
         "label": "Service:",
-        "multi": false,
         "name": "service",
         "options": [],
         "query": {
@@ -248,9 +256,16 @@
         },
         "refresh": 1,
         "regex": "",
-        "skipUrlSync": false,
-        "sort": 0,
         "type": "query"
+      },
+      {
+        "datasource": {
+          "type": "loki",
+          "uid": "grafanacloud-logs"
+        },
+        "filters": [],
+        "name": "Filters",
+        "type": "adhoc"
       }
     ]
   },
@@ -262,6 +277,6 @@
   "timezone": "",
   "title": "Container Logs",
   "uid": "ih6KH0aVz",
-  "version": 8,
+  "version": 9,
   "weekStart": ""
 }
diff --git a/deployment/utils/contour.types.ts b/deployment/utils/contour.types.ts
@@ -787,6 +787,7 @@ export interface ContourValues {
       };
       [k: string]: unknown;
     };
+    defaultStorageClass?: string;
     imagePullSecrets?: unknown[];
     imageRegistry?: string;
     storageClass?: string;

diff --git a/deployment/utils/observability.ts b/deployment/utils/observability.ts
@@ -55,6 +55,8 @@ export class Observability {
         },
       },
       podAnnotations: {
+        // This is done because open-telemetry collector doesn't always update the deployment
+        // when the config file changes. This will force-restart it.
         'pulumi.com/update-timestamp': Date.now().toString(),
       },
       clusterRole: {
@@ -133,21 +135,30 @@ export class Observability {
             limit_mib: 409,
             spike_limit_mib: 128,
           },
+          // Filter OpenTelemetry traces that are not needed for debugging.
           'filter/traces': {
             error_mode: 'ignore',
             traces: {
               span: [
+                // Ignore all HEAD/OPTIONS requests
                 'attributes["component"] == "proxy" and attributes["http.method"] == "HEAD"',
                 'attributes["component"] == "proxy" and attributes["http.method"] == "OPTIONS"',
+                // Ignore health checks
+                'attributes["component"] == "proxy" and attributes["http.method"] == "GET" and attributes["http.url"] == "/_readiness"',
+                'attributes["component"] == "proxy" and attributes["http.method"] == "GET" and attributes["http.url"] == "/_health"',
                 'attributes["component"] == "proxy" and attributes["http.method"] == "GET" and IsMatch(attributes["http.url"], ".*/_health") == true',
+                // Ignore Contour/Envoy traces for /usage requests
                 'attributes["component"] == "proxy" and attributes["http.method"] == "POST" and attributes["http.url"] == "/usage"',
+                'attributes["component"] == "proxy" and attributes["http.method"] == "POST" and IsMatch(attributes["upstream_cluster.name"], "default_usage-service-.*") == true',
+                'attributes["component"] == "proxy" and attributes["http.method"] == "POST" and IsMatch(attributes["upstream_cluster.name"], "default_app-.*") == true',
+                // Ignore metrics scraping
                 'attributes["component"] == "proxy" and attributes["http.method"] == "GET" and attributes["http.url"] == "/metrics"',
-                'attributes["component"] == "proxy" and attributes["http.method"] == "GET" and attributes["http.url"] == "/_readiness"',
-                'attributes["component"] == "proxy" and attributes["http.method"] == "GET" and attributes["http.url"] == "/_health"',
+                // Ignore webapp HTTP calls
                 'attributes["component"] == "proxy" and attributes["http.method"] == "GET" and IsMatch(attributes["upstream_cluster.name"], "default_app-.*") == true',
               ],
             },
           },
+          // Remove raw trace information that we don't really need and exposed by default.
           'attributes/trace_filter': {
             actions: [
               'downstream_cluster',
@@ -156,12 +167,12 @@ export class Observability {
               'zone',
               'upstream_cluster',
               'peer.address',
-              'response_flags',
             ].map(key => ({
               key,
               action: 'delete',
             })),
           },
+          // Remove attributes that are not needed for debugging.
           'resource/trace_cleanup': {
             attributes: [
               'host.arch',
@@ -182,6 +193,10 @@ export class Observability {
               action: 'delete',
             })),
           },
+          // Contour spans are not very human-readable by default, so we are transforming them
+          // into a format that is easier to understand.
+          // First, we modify the span URL to be relative, and remove the hostname and full path,
+          // Then, we rename to be "METHOD /path"
           'transform/patch_envoy_spans': {
             error_mode: 'ignore',
             trace_statements: [

diff --git a/packages/services/api/src/modules/schema/providers/models/composite.ts b/packages/services/api/src/modules/schema/providers/models/composite.ts
@@ -1,4 +1,5 @@
 import { Injectable, Scope } from 'graphql-modules';
+import { traceFn } from '@hive/service-common';
 import { SchemaChangeType } from '@hive/storage';
 import { FederationOrchestrator } from '../orchestrators/federation';
 import { StitchingOrchestrator } from '../orchestrators/stitching';
@@ -14,6 +15,7 @@ import type {
   Target,
 } from './../../../../shared/entities';
 import { ProjectType } from './../../../../shared/entities';
+import { Logger } from './../../../shared/providers/logger';
 import {
   buildSchemaCheckFailureState,
   ContractCheckInput,
@@ -40,6 +42,7 @@ export class CompositeModel {
     private federationOrchestrator: FederationOrchestrator,
     private stitchingOrchestrator: StitchingOrchestrator,
     private checks: RegistryChecks,
+    private logger: Logger,
   ) {}
 
   private async getContractChecks(args: {
@@ -83,6 +86,13 @@ export class CompositeModel {
     );
   }
 
+  @traceFn('Composite modern: check', {
+    initAttributes: args => ({
+      'hive.project.id': args.selector.project,
+      'hive.target.id': args.selector.target,
+      'hive.organization.id': args.selector.organization,
+    }),
+  })
   async check({
     input,
     selector,
@@ -166,6 +176,7 @@ export class CompositeModel {
     });
 
     if (checksumCheck === 'unchanged') {
+      this.logger.info('No changes detected, skipping schema check');
       return {
         conclusion: SchemaCheckConclusion.Skip,
       };
@@ -175,6 +186,7 @@ export class CompositeModel {
       project.type === ProjectType.FEDERATION
         ? this.federationOrchestrator
         : this.stitchingOrchestrator;
+    this.logger.debug('Orchestrator: %s', orchestrator);
 
     const compositionCheck = await this.checks.composition({
       orchestrator,
@@ -208,6 +220,7 @@ export class CompositeModel {
       compositionCheck,
       conditionalBreakingChangeDiffConfig,
     });
+    this.logger.info('Contract checks: %o', contractChecks);
 
     const [diffCheck, policyCheck] = await Promise.all([
       this.checks.diff({
@@ -225,6 +238,8 @@ export class CompositeModel {
         modifiedSdl: incoming.sdl,
       }),
     ]);
+    this.logger.info('diff check status: %o', diffCheck);
+    this.logger.info('policy check status: %o', policyCheck);
 
     if (
       compositionCheck.status === 'failed' ||
@@ -233,6 +248,7 @@ export class CompositeModel {
       // if any of the contract compositions failed, the schema check failed.
       (contractChecks?.length && contractChecks.some(check => !isContractChecksSuccessful(check)))
     ) {
+      this.logger.debug('Schema check failed');
       return {
         conclusion: SchemaCheckConclusion.Failure,
         state: buildSchemaCheckFailureState({
@@ -244,6 +260,7 @@ export class CompositeModel {
       };
     }
 
+    this.logger.debug('Schema check successful');
     return {
       conclusion: SchemaCheckConclusion.Success,
       state: {

diff --git a/packages/services/api/src/modules/schema/providers/models/single.ts b/packages/services/api/src/modules/schema/providers/models/single.ts
@@ -1,4 +1,5 @@
 import { Injectable, Scope } from 'graphql-modules';
+import { traceFn } from '@hive/service-common';
 import { SchemaChangeType } from '@hive/storage';
 import { SingleOrchestrator } from '../orchestrators/single';
 import { ConditionalBreakingChangeDiffConfig, RegistryChecks } from '../registry-checks';
@@ -26,6 +27,13 @@ export class SingleModel {
     private logger: Logger,
   ) {}
 
+  @traceFn('Single modern: check', {
+    initAttributes: args => ({
+      'hive.project.id': args.selector.project,
+      'hive.target.id': args.selector.target,
+      'hive.organization.id': args.selector.organization,
+    }),
+  })
   async check({
     input,
     selector,

diff --git a/packages/services/api/src/modules/schema/providers/registry-checks.ts b/packages/services/api/src/modules/schema/providers/registry-checks.ts
@@ -5,6 +5,7 @@ import hashObject from 'object-hash';
 import { CriticalityLevel } from '@graphql-inspector/core';
 import type { CheckPolicyResponse } from '@hive/policy';
 import type { CompositionFailureError, ContractsInputType } from '@hive/schema';
+import { traceFn } from '@hive/service-common';
 import {
   HiveSchemaChangeModel,
   type RegistryServiceUrlChangeSerializableChange,
@@ -346,6 +347,7 @@ export class RegistryChecks {
     return existingSchemaResult.sdl ?? null;
   }
 
+  @traceFn('RegistryChecks.policyCheck')
   async policyCheck({
     selector,
     modifiedSdl,
@@ -397,6 +399,7 @@ export class RegistryChecks {
    * Diff incoming and existing SDL and generate a list of changes.
    * Uses usage stats to determine whether a change is safe or not (if available).
    */
+  @traceFn('RegistryChecks.diff')
   async diff(args: {
     /** The existing SDL */
     existingSdl: string | null;