Merge pull request #159 from uswitch/feature/prom-and-zipkin-trace-in…

…tegration

Feature/prom and zipkin trace integration

.nvmrc

@@ -0,0 +1 @@
+10

README.md

@@ -72,13 +72,24 @@ updating dependencies and generating the documentation for `core` .
 
 This publishes to both the NPM and Github Packages Registries
 
+### Node Version
+
+<!-- FIXME: Node version 10 is very old and should be fixed -->
+`koa-core` was built using [Node v10](./nvmrc) so you should run the
+following when developing it.
+
+```sh
+nvm use
+```
+
+
 ## Packages
 
 #### `@uswitch` packages
 
 <!-- DO NOT REMOVE - This is generated documentation  -->
 <!-- [doc-list-packages-internal:start] -->
-<!-- Generated Fri Aug 06 2021 14:12:36 GMT+0100 (British Summer Time) -->
+<!-- Generated Wed Apr 13 2022 15:00:34 GMT+0100 (British Summer Time) -->
 | Package | Version | Dependencies | Description |
 |--|--|--|--|
 | [`@uswitch/koa-access`](https://www.npmjs.com/package/@uswitch/koa-access) | [![npm](https://img.shields.io/npm/v/@uswitch/koa-access.svg?maxAge=2592000)](https://www.npmjs.com/package/@uswitch/koa-access) | [![Dependency Status](https://david-dm.org/@uswitch/koa-access.svg?path=packages/@uswitch/koa-access)](https://david-dm.org/@uswitch/koa-access?path=packages/@uswitch/koa-access) | 👌 A Koa middleware for logging JSON access logs consistently, similar to morgan |
@@ -95,7 +106,7 @@ This publishes to both the NPM and Github Packages Registries
 #### `koa` packages
 <!-- DO NOT REMOVE - This is generated documentation  -->
 <!-- [doc-list-packages:start] -->
-<!-- Generated Fri Aug 06 2021 14:12:35 GMT+0100 (British Summer Time) -->
+<!-- Generated Wed May 04 2022 16:31:19 GMT+0100 (British Summer Time) -->
 | Package | Version | Latest |
 |--|--|--|
 | [`koa`](https://www.npmjs.com/package/koa) | `^2.6.2` | [![npm](https://img.shields.io/npm/v/koa.svg?maxAge=2592000)](https://www.npmjs.com/package/koa) |

__config__/prometheus-config.production.json

@@ -64,6 +64,13 @@
     "help": "Number of errors per second per request",
     "type": "Meter"
   },
+  {
+    "name": "trace_duration_seconds",
+    "help": "The time in seconds for traces to complete",
+    "type": "Histogram",
+    "labelNames": ["span"],
+    "buckets": [0.1, 0.2, 0.3, 0.4, 0.5, 0.6, 0.7, 0.8, 0.9, 1.0]
+  },
   {
     "name": "total_number_requests",
     "help": "The total number of requests served",

__example__/server-router.mjs

@@ -41,6 +41,22 @@ router.get('/trace/:timeout', async ctx => {
   ctx.body = `I waited ${ctx.params.timeout}ms`
 })
 
+router.get('/trace', async ctx => {
+  ctx.trace('wait', 'start')
+  await wait(Math.round(Math.random() * 100))
+  ctx.trace('wait', 'finish')
+  ctx.trace('process', 'start')
+  ctx.trace('sub process 1', 'start')
+  await wait(Math.round(Math.random() * 300))
+  ctx.trace('sub process 1', 'end')
+  ctx.trace('sub process 2', 'start')
+  await wait(Math.round(Math.random() * 200))
+  ctx.trace('sub process 2', 'end')
+  ctx.trace('process', 'end')
+
+  ctx.status = 200
+})
+
 router.get('/signal/all', async ctx => {
   /* Signal examples */
   signal.success('This is a success message!')
@@ -57,15 +73,24 @@ router.get('/zipkin', async ctx => {
   const method = 'GET'
 
   const body = await zipkinFetch({ remote }, { url, method })
-    .then(({ body, request }) => {
+    .then(async ({ body, request }) => {
       ctx.state.meters
         .totalUpstreamRequests
         .labels(method, remote, cacheHit(request))
         .inc(1)
 
+      ctx.trace('responsehandle', 'start')
+      await wait(100)
+      ctx.trace('responsehandle', 'hard process')
+      await wait(200)
+      ctx.trace('responsehandle', 'end')
       return body
     })
 
+  ctx.trace('postprocess', 'start')
+  await wait(450)
+  ctx.trace('postprocess', 'finish')
+
   ctx.body = body
   ctx.status = 200
 })

__example__/server.mjs

@@ -1,10 +1,12 @@
-import KoaCore from '../koa-core'
+import KoaCore from '../koa-core.js'
 import requestId from 'koa-requestid'
 
-import { zipkin } from './zipkin'
+import { zipkin, tracer } from './zipkin'
 import router from './server-router'
 
-const { app, signal } = KoaCore()
+const { app, signal } = KoaCore({
+  zipkinTracer: tracer
+})
 
 app.use(zipkin)
 app.use(requestId())

__example__/zipkin.mjs

@@ -4,7 +4,7 @@ import axios from 'axios'
 import cache from 'axios-cache-adapter'
 
 const { middleware, fetch, Logger, Tracer } = koaZipkin
-const { USE_CACHE = true, NODE_ENV, APP_NAME = 'example-uf-service' } = process.env
+const { USE_CACHE = true, ZIPKIN_HOST, APP_NAME = 'example-uf-service' } = process.env
 
 const { adapter } = cache.setupCache({ maxAge: USE_CACHE ? 10 * 1000 : 0 })
 const fetchClient = axios.create({ adapter })
@@ -18,7 +18,7 @@ fetchClient.interceptors.response.use(
   Promise.reject
 )
 
-const tracer = Tracer(APP_NAME, Logger({ local: NODE_ENV === 'development' }))
+export const tracer = Tracer(APP_NAME, Logger({ endpoint: ZIPKIN_HOST }))
 
 export const zipkin = middleware({ tracer })
 export const zipkinFetch = fetch({ local: APP_NAME, fetch: fetchClient, tracer })

docker-compose.yaml

@@ -0,0 +1,31 @@
+version: '2.0'
+services:
+  koa-core:
+    image: node:10-alpine
+    ports:
+      - "3000:3000"
+    networks:
+      - mesh
+    working_dir: /etc
+    command: |
+      node --experimental-modules /etc/server/server.mjs
+    environment:
+      - DEBUG_KOA=true
+      - ZIPKIN_HOST=http://zipkin:9411/api/v2/spans
+      - NODE_DEBUG=true
+      - NODE_ENV=development
+    volumes:
+      - ./__example__:/etc/server
+      - .:/etc
+
+  zipkin:
+    image: openzipkin/zipkin
+    networks:
+      mesh:
+        aliases:
+          - zipkin
+    ports:
+      - "9411:9411"
+
+networks:
+  mesh: {}

koa-core.js

@@ -1,5 +1,6 @@
 const Koa = require('koa')
 
+const zipkin = require('@uswitch/koa-zipkin')
 const { default: Meters } = require('@uswitch/koa-prometheus')
 const { default: Signal } = require('@uswitch/koa-signal')
 const { default: access, eventAccess } = require('@uswitch/koa-access')
@@ -13,7 +14,7 @@ module.exports = (config = {}) => {
   const app = new Koa()
 
   const { NODE_ENV } = process.env
-  const { dev = 'development', accessConf = [], signalConf = {}, prometheusConf } = config
+  const { zipkinTracer, dev = 'development', accessConf = [], signalConf = {}, prometheusConf } = config
 
   const signalConfig = NODE_ENV === dev ? signalConf : merge(signalConf, prodSignalConf)
   const signal = Signal(signalConfig)
@@ -26,13 +27,32 @@ module.exports = (config = {}) => {
 
   app.use(tracer())
   app.use(meters.middleware)
-  app.use(access([ 'id', 'trace', 'errors', ...accessConf ]))
+  app.use(access(['id', 'trace', 'errors', ...accessConf]))
 
   app.on(eventTrace, ({ ctx, key, trace }) => signal.trace({ ...ctx, ...trace, scope: key }))
   app.on(eventError, ({ ctx, original }) => signal.error(ctx, original))
-  app.on(eventError, () => meters.koaErrorsPerSecond.mark(1))
 
+  app.on(eventError, () => meters.koaErrorsPerSecond.mark(1))
   app.on(eventAccess, (ctx, extra) => meters.automark({ ...ctx, ...extra }))
+
+  // Marks each trace as a prometheus metric & zipkin trace
+  app.on(eventAccess, (ctx, { trace }) =>
+    Object
+      .entries(trace)
+      .forEach(([scope, trace], order) => {
+        if (zipkinTracer) // Only trace spans when a zipkin tracer is injected
+          zipkin.createTraceSpan(
+            ctx,
+            { scope, trace, tracer: zipkinTracer }
+          )
+
+        if (meters.traceDurationMilliseconds)
+          meters.traceDurationMilliseconds
+            .labels(scope)
+            .observe(trace.timeDiff / 1000) // Cast to seconds
+      })
+  )
+
   app.on(eventAccess, signal.access)
 
   return { app, meters, signal }