kmuto’s blog

はてな社でMackerel CREをやっています。料理と旅行といろんなIT技術

OpenTelemetryのzero-code計装を試している〜その6。JavaScript

tech

zero-code計装シリーズ、いよいよ対応言語最後のJavaScriptとなった。

kmuto.hatenablog.com kmuto.hatenablog.com kmuto.hatenablog.com kmuto.hatenablog.com kmuto.hatenablog.com

JavaScriptというかNode.jsへの計装。実行時に計装ライブラリを注入してテレメトリーを取り出す仕組みになっている。

いつもの雑なWebサーバーを立てる。Expressフレームワークを利用することにした。

npm init --yes
npm install express

index.jsを書く。

const express = require("express");
const app = express();

app.get("/", (req, res) => {
  res.send("Hello, World\n");
});

app.get("/error", (req, res) => {
  throw new Error("Internal Server Error");
});

app.get("/500", (req, res) => {
  res.status(500).send("Internal Server Error");
});

app.listen(5000, () => {
  console.log("Server running at http://localhost:5000/");
});

node index.jsを実行し、curlで結果が返ってくることを確認。

$ curl http://localhost:5000
Hello, World
$ curl http://localhost:5000/error
<!DOCTYPE html>
<html lang="en">
<head>
<meta charset="utf-8">
<title>Error</title>
</head>
<body>
<pre>Error: Internal Server Error<br> &nbsp; &nbsp;at /home/kmuto/nodejs-zerocode/index.js:9:9<br> &nbsp; &nbsp;at Layer.handle [as handle_request] (/home/kmuto/nodejs-zerocode/node_modules/express/lib/router/layer.js:95:5)<br> &nbsp; &nbsp;at next (/home/kmuto/nodejs-zerocode/node_modules/express/lib/router/route.js:149:13)<br> &nbsp; &nbsp;at Route.dispatch (/home/kmuto/nodejs-zerocode/node_modules/express/lib/router/route.js:119:3)<br> &nbsp; &nbsp;at Layer.handle [as handle_request] (/home/kmuto/nodejs-zerocode/node_modules/express/lib/router/layer.js:95:5)<br> &nbsp; &nbsp;at /home/kmuto/nodejs-zerocode/node_modules/express/lib/router/index.js:284:15<br> &nbsp; &nbsp;at Function.process_params (/home/kmuto/nodejs-zerocode/node_modules/express/lib/router/index.js:346:12)<br> &nbsp; &nbsp;at next (/home/kmuto/nodejs-zerocode/node_modules/express/lib/router/index.js:280:10)<br> &nbsp; &nbsp;at expressInit (/home/kmuto/nodejs-zerocode/node_modules/express/lib/middleware/init.js:40:5)<br> &nbsp; &nbsp;at Layer.handle [as handle_request] (/home/kmuto/nodejs-zerocode/node_modules/express/lib/router/layer.js:95:5)</pre>
</body>
</html>
$ curl http://localhost:5000/500
Internal Server Error

ドキュメントに従い、計装パッケージをインストールする。

npm install --save @opentelemetry/api
npm install --save @opentelemetry/auto-instrumentations-node

OpenTelemetry Collectorをいつものとおり実行しておく。

receivers:
  otlp:
    protocols:
      http:

exporters:
  debug:
    verbosity: detailed

service:
  pipelines:
    metrics:
      receivers: [otlp]
      exporters: [debug]
    logs:
      receivers: [otlp]
      exporters: [debug]
    traces:
      receivers: [otlp]
      exporters: [debug]

では、zero-code計装付きで実行。--require @opentelemetry/auto-instrumentations-node/registerで注入させている。

OTEL_SERVICE_NAME=nodejs-zerocode node --require @opentelemetry/auto-instrumentations-node/register index.js

curlしながらトレースの様子を見てみよう。

2025-02-01T21:32:38.791+0900    info    Traces  {"kind": "exporter", "data_type": "traces", "name": "debug", "resource spans": 1, "spans": 4}
2025-02-01T21:32:38.791+0900    info    ResourceSpans #0
Resource SchemaURL: 
Resource attributes:
     -> service.name: Str(nodejs-zerocode)
     -> telemetry.sdk.language: Str(nodejs)
     -> telemetry.sdk.name: Str(opentelemetry)
     -> telemetry.sdk.version: Str(1.30.1)
     -> host.name: Str(...)
     -> host.arch: Str(amd64)
     -> os.type: Str(linux)
     -> os.version: Str(6.1.0-30-amd64)
     -> service.instance.id: Str(76577b3b-41ff-4a0a-b383-499c13cb9a7e)
     -> process.pid: Int(1250110)
     -> process.executable.name: Str(node)
     -> process.executable.path: Str(/usr/bin/node)
     -> process.command_args: Slice(["/usr/bin/node","--require","@opentelemetry/auto-instrumentations-node/register","/home/kmuto/nodejs-zerocode/index.js"])
     -> process.runtime.version: Str(20.18.1)
     -> process.runtime.name: Str(nodejs)
     -> process.runtime.description: Str(Node.js)
     -> process.command: Str(/home/kmuto/nodejs-zerocode/index.js)
     -> process.owner: Str(kmuto)
     -> host.id: Str(86fdb17091114232ba104aea4bc5250d)
ScopeSpans #0
ScopeSpans SchemaURL: 
InstrumentationScope @opentelemetry/instrumentation-net 0.43.0
Span #0
    Trace ID       : caa5bd201ff9f307aebce2f7e2ec2aa7
    Parent ID      : 0c738bec56d427a2
    ID             : 1e3edea415bc59d2
    Name           : tcp.connect
    Kind           : Internal
    Start time     : 2025-02-01 12:32:33.775 +0000 UTC
    End time       : 2025-02-01 12:32:33.78085516 +0000 UTC
    Status code    : Error
    Status message : getaddrinfo ENOTFOUND metadata.google.internal.
Attributes:
     -> net.transport: Str(ip_tcp)
     -> net.peer.name: Str(metadata.google.internal.)
     -> net.peer.port: Int(80)
Span #1
    Trace ID       : 7c0859294fc05427999ea55420b5c5ed
    Parent ID      : c8f98b03201b8700
    ID             : 71ece3918be021b5
    Name           : tcp.connect
    Kind           : Internal
    Start time     : 2025-02-01 12:32:33.771 +0000 UTC
    End time       : 2025-02-01 12:32:36.777999004 +0000 UTC
    Status code    : Unset
    Status message : 
Attributes:
     -> net.transport: Str(ip_tcp)
     -> net.peer.name: Str(169.254.169.254)
     -> net.peer.port: Int(80)
ScopeSpans #1
ScopeSpans SchemaURL: 
InstrumentationScope @opentelemetry/instrumentation-http 0.57.1
Span #0
    Trace ID       : caa5bd201ff9f307aebce2f7e2ec2aa7
    Parent ID      : 
    ID             : 0c738bec56d427a2
    Name           : GET
    Kind           : Client
    Start time     : 2025-02-01 12:32:33.772 +0000 UTC
    End time       : 2025-02-01 12:32:33.781158297 +0000 UTC
    Status code    : Error
    Status message : getaddrinfo ENOTFOUND metadata.google.internal.
Attributes:
     -> http.url: Str(http://metadata.google.internal./computeMetadata/v1/instance)
     -> http.method: Str(GET)
     -> http.target: Str(/computeMetadata/v1/instance)
     -> net.peer.name: Str(metadata.google.internal.)
     -> http.host: Str(metadata.google.internal.:80)
     -> http.error_name: Str(Error)
     -> http.error_message: Str(getaddrinfo ENOTFOUND metadata.google.internal.)
Events:
SpanEvent #0
     -> Name: exception
     -> Timestamp: 2025-02-01 12:32:33.781121043 +0000 UTC
     -> DroppedAttributesCount: 0
     -> Attributes::
          -> exception.type: Str(ENOTFOUND)
          -> exception.message: Str(getaddrinfo ENOTFOUND metadata.google.internal.)
          -> exception.stacktrace: Str(Error: getaddrinfo ENOTFOUND metadata.google.internal.
    at GetAddrInfoReqWrap.onlookupall [as oncomplete] (node:dns:120:26)
    at GetAddrInfoReqWrap.callbackTrampoline (node:internal/async_hooks:130:17))
Span #1
    Trace ID       : 7c0859294fc05427999ea55420b5c5ed
    Parent ID      : 
    ID             : c8f98b03201b8700
    Name           : GET
    Kind           : Client
    Start time     : 2025-02-01 12:32:33.769 +0000 UTC
    End time       : 2025-02-01 12:32:36.777554317 +0000 UTC
    Status code    : Error
    Status message : socket hang up
Attributes:
     -> http.url: Str(http://169.254.169.254/computeMetadata/v1/instance)
     -> http.method: Str(GET)
     -> http.target: Str(/computeMetadata/v1/instance)
     -> net.peer.name: Str(169.254.169.254)
     -> http.host: Str(169.254.169.254:80)
     -> http.error_name: Str(Error)
     -> http.error_message: Str(socket hang up)
Events:
SpanEvent #0
     -> Name: exception
     -> Timestamp: 2025-02-01 12:32:36.77754689 +0000 UTC
     -> DroppedAttributesCount: 0
     -> Attributes::
          -> exception.type: Str(ECONNRESET)
          -> exception.message: Str(socket hang up)
          -> exception.stacktrace: Str(Error: socket hang up
    at Socket.socketCloseListener (node:_http_client:477:27)
    at Socket.emit (node:events:530:35)
    at TCP.<anonymous> (node:net:343:12)
    at TCP.callbackTrampoline (node:internal/async_hooks:130:17))
        {"kind": "exporter", "data_type": "traces", "name": "debug"}
2025-02-01T21:33:13.387+0900    info    Traces  {"kind": "exporter", "data_type": "traces", "name": "debug", "resource spans": 1, "spans": 8}
2025-02-01T21:33:13.387+0900    info    ResourceSpans #0
Resource SchemaURL: 
Resource attributes:
     -> service.name: Str(nodejs-zerocode)
     -> telemetry.sdk.language: Str(nodejs)
     -> telemetry.sdk.name: Str(opentelemetry)
     -> telemetry.sdk.version: Str(1.30.1)
     -> host.name: Str(elemental)
     -> host.arch: Str(amd64)
     -> os.type: Str(linux)
     -> os.version: Str(6.1.0-30-amd64)
     -> service.instance.id: Str(76577b3b-41ff-4a0a-b383-499c13cb9a7e)
     -> process.pid: Int(1250110)
     -> process.executable.name: Str(node)
     -> process.executable.path: Str(/usr/bin/node)
     -> process.command_args: Slice(["/usr/bin/node","--require","@opentelemetry/auto-instrumentations-node/register","/home/kmuto/nodejs-zerocode/index.js"])
     -> process.runtime.version: Str(20.18.1)
     -> process.runtime.name: Str(nodejs)
     -> process.runtime.description: Str(Node.js)
     -> process.command: Str(/home/kmuto/nodejs-zerocode/index.js)
     -> process.owner: Str(kmuto)
     -> host.id: Str(86fdb17091114232ba104aea4bc5250d)
ScopeSpans #0
ScopeSpans SchemaURL: 
InstrumentationScope @opentelemetry/instrumentation-express 0.47.0
Span #0
    Trace ID       : 9572efd867249b59cbb376732a820d0c
    Parent ID      : 27c4c6585ef4a6d9
    ID             : b0247ca292ec8610
    Name           : middleware - query
    Kind           : Internal
    Start time     : 2025-02-01 12:33:08.384 +0000 UTC
    End time       : 2025-02-01 12:33:08.384331017 +0000 UTC
    Status code    : Unset
    Status message : 
Attributes:
     -> http.route: Str(/)
     -> express.name: Str(query)
     -> express.type: Str(middleware)
Span #1
    Trace ID       : 9572efd867249b59cbb376732a820d0c
    Parent ID      : 27c4c6585ef4a6d9
    ID             : 33e78a22a5b79809
    Name           : middleware - expressInit
    Kind           : Internal
    Start time     : 2025-02-01 12:33:08.384 +0000 UTC
    End time       : 2025-02-01 12:33:08.384114406 +0000 UTC
    Status code    : Unset
    Status message : 
Attributes:
     -> http.route: Str(/)
     -> express.name: Str(expressInit)
     -> express.type: Str(middleware)
Span #2
    Trace ID       : 9572efd867249b59cbb376732a820d0c
    Parent ID      : 27c4c6585ef4a6d9
    ID             : 7e56c5d076b97d5a
    Name           : request handler - /
    Kind           : Internal
    Start time     : 2025-02-01 12:33:08.384 +0000 UTC
    End time       : 2025-02-01 12:33:08.384017304 +0000 UTC
    Status code    : Unset
    Status message : 
Attributes:
     -> http.route: Str(/)
     -> express.name: Str(/)
     -> express.type: Str(request_handler)
Span #3
    Trace ID       : 906fcf5a00e00da4750ce5cbc9597179
    Parent ID      : 7fc2baee42bada97
    ID             : e2b782bd9eb7ff6a
    Name           : middleware - query
    Kind           : Internal
    Start time     : 2025-02-01 12:33:13.3 +0000 UTC
    End time       : 2025-02-01 12:33:13.300063332 +0000 UTC
    Status code    : Unset
    Status message : 
Attributes:
     -> http.route: Str(/)
     -> express.name: Str(query)
     -> express.type: Str(middleware)
Span #4
    Trace ID       : 906fcf5a00e00da4750ce5cbc9597179
    Parent ID      : 7fc2baee42bada97
    ID             : d6ee11556a6e8a44
    Name           : middleware - expressInit
    Kind           : Internal
    Start time     : 2025-02-01 12:33:13.301 +0000 UTC
    End time       : 2025-02-01 12:33:13.301048907 +0000 UTC
    Status code    : Unset
    Status message : 
Attributes:
     -> http.route: Str(/)
     -> express.name: Str(expressInit)
     -> express.type: Str(middleware)
Span #5
    Trace ID       : 906fcf5a00e00da4750ce5cbc9597179
    Parent ID      : 7fc2baee42bada97
    ID             : b7bb9416e075767b
    Name           : request handler - /error
    Kind           : Internal
    Start time     : 2025-02-01 12:33:13.301 +0000 UTC
    End time       : 2025-02-01 12:33:13.301092888 +0000 UTC
    Status code    : Unset
    Status message : 
Attributes:
     -> http.route: Str(/error)
     -> express.name: Str(/error)
     -> express.type: Str(request_handler)
ScopeSpans #1
ScopeSpans SchemaURL: 
InstrumentationScope @opentelemetry/instrumentation-http 0.57.1
Span #0
    Trace ID       : 9572efd867249b59cbb376732a820d0c
    Parent ID      : 
    ID             : 27c4c6585ef4a6d9
    Name           : GET /
    Kind           : Server
    Start time     : 2025-02-01 12:33:08.382 +0000 UTC
    End time       : 2025-02-01 12:33:08.387360158 +0000 UTC
    Status code    : Unset
    Status message : 
Attributes:
     -> http.url: Str(http://localhost:5000/)
     -> http.host: Str(localhost:5000)
     -> net.host.name: Str(localhost)
     -> http.method: Str(GET)
     -> http.scheme: Str(http)
     -> http.target: Str(/)
     -> http.user_agent: Str(curl/7.88.1)
     -> http.flavor: Str(1.1)
     -> net.transport: Str(ip_tcp)
     -> net.host.ip: Str(::ffff:127.0.0.1)
     -> net.host.port: Int(5000)
     -> net.peer.ip: Str(::ffff:127.0.0.1)
     -> net.peer.port: Int(57458)
     -> http.status_code: Int(200)
     -> http.status_text: Str(OK)
     -> http.route: Str(/)
Span #1
    Trace ID       : 906fcf5a00e00da4750ce5cbc9597179
    Parent ID      : 
    ID             : 7fc2baee42bada97
    Name           : GET /error
    Kind           : Server
    Start time     : 2025-02-01 12:33:13.3 +0000 UTC
    End time       : 2025-02-01 12:33:13.30250585 +0000 UTC
    Status code    : Error
    Status message : 
Attributes:
     -> http.url: Str(http://localhost:5000/error)
     -> http.host: Str(localhost:5000)
     -> net.host.name: Str(localhost)
     -> http.method: Str(GET)
     -> http.scheme: Str(http)
     -> http.target: Str(/error)
     -> http.user_agent: Str(curl/7.88.1)
     -> http.flavor: Str(1.1)
     -> net.transport: Str(ip_tcp)
     -> net.host.ip: Str(::ffff:127.0.0.1)
     -> net.host.port: Int(5000)
     -> net.peer.ip: Str(::ffff:127.0.0.1)
     -> net.peer.port: Int(34950)
     -> http.status_code: Int(500)
     -> http.status_text: Str(INTERNAL SERVER ERROR)
     -> http.route: Str(/error)
        {"kind": "exporter", "data_type": "traces", "name": "debug"}
2025-02-01T21:33:21.147+0900    info    Traces  {"kind": "exporter", "data_type": "traces", "name": "debug", "resource spans": 1, "spans": 4}
2025-02-01T21:33:21.147+0900    info    ResourceSpans #0
Resource SchemaURL: 
Resource attributes:
     -> service.name: Str(nodejs-zerocode)
     -> telemetry.sdk.language: Str(nodejs)
     -> telemetry.sdk.name: Str(opentelemetry)
     -> telemetry.sdk.version: Str(1.30.1)
     -> host.name: Str(elemental)
     -> host.arch: Str(amd64)
     -> os.type: Str(linux)
     -> os.version: Str(6.1.0-30-amd64)
     -> service.instance.id: Str(76577b3b-41ff-4a0a-b383-499c13cb9a7e)
     -> process.pid: Int(1250110)
     -> process.executable.name: Str(node)
     -> process.executable.path: Str(/usr/bin/node)
     -> process.command_args: Slice(["/usr/bin/node","--require","@opentelemetry/auto-instrumentations-node/register","/home/kmuto/nodejs-zerocode/index.js"])
     -> process.runtime.version: Str(20.18.1)
     -> process.runtime.name: Str(nodejs)
     -> process.runtime.description: Str(Node.js)
     -> process.command: Str(/home/kmuto/nodejs-zerocode/index.js)
     -> process.owner: Str(kmuto)
     -> host.id: Str(86fdb17091114232ba104aea4bc5250d)
ScopeSpans #0
ScopeSpans SchemaURL: 
InstrumentationScope @opentelemetry/instrumentation-express 0.47.0
Span #0
    Trace ID       : daf7b2cca043477e1ca19acc3225cb1d
    Parent ID      : 79219c5dc5b522b9
    ID             : 5bb002eafa0cfb27
    Name           : middleware - query
    Kind           : Internal
    Start time     : 2025-02-01 12:33:16.145 +0000 UTC
    End time       : 2025-02-01 12:33:16.145034154 +0000 UTC
    Status code    : Unset
    Status message : 
Attributes:
     -> http.route: Str(/)
     -> express.name: Str(query)
     -> express.type: Str(middleware)
Span #1
    Trace ID       : daf7b2cca043477e1ca19acc3225cb1d
    Parent ID      : 79219c5dc5b522b9
    ID             : 087cbf534f01297a
    Name           : middleware - expressInit
    Kind           : Internal
    Start time     : 2025-02-01 12:33:16.145 +0000 UTC
    End time       : 2025-02-01 12:33:16.145031246 +0000 UTC
    Status code    : Unset
    Status message : 
Attributes:
     -> http.route: Str(/)
     -> express.name: Str(expressInit)
     -> express.type: Str(middleware)
Span #2
    Trace ID       : daf7b2cca043477e1ca19acc3225cb1d
    Parent ID      : 79219c5dc5b522b9
    ID             : b8d033ff29b225bc
    Name           : request handler - /500
    Kind           : Internal
    Start time     : 2025-02-01 12:33:16.145 +0000 UTC
    End time       : 2025-02-01 12:33:16.145006133 +0000 UTC
    Status code    : Unset
    Status message : 
Attributes:
     -> http.route: Str(/500)
     -> express.name: Str(/500)
     -> express.type: Str(request_handler)
ScopeSpans #1
ScopeSpans SchemaURL: 
InstrumentationScope @opentelemetry/instrumentation-http 0.57.1
Span #0
    Trace ID       : daf7b2cca043477e1ca19acc3225cb1d
    Parent ID      : 
    ID             : 79219c5dc5b522b9
    Name           : GET /500
    Kind           : Server
    Start time     : 2025-02-01 12:33:16.145 +0000 UTC
    End time       : 2025-02-01 12:33:16.145981532 +0000 UTC
    Status code    : Error
    Status message : 
Attributes:
     -> http.url: Str(http://localhost:5000/500)
     -> http.host: Str(localhost:5000)
     -> net.host.name: Str(localhost)
     -> http.method: Str(GET)
     -> http.scheme: Str(http)
     -> http.target: Str(/500)
     -> http.user_agent: Str(curl/7.88.1)
     -> http.flavor: Str(1.1)
     -> net.transport: Str(ip_tcp)
     -> net.host.ip: Str(::ffff:127.0.0.1)
     -> net.host.port: Int(5000)
     -> net.peer.ip: Str(::ffff:127.0.0.1)
     -> net.peer.port: Int(34958)
     -> http.status_code: Int(500)
     -> http.status_text: Str(INTERNAL SERVER ERROR)
     -> http.route: Str(/500)
        {"kind": "exporter", "data_type": "traces", "name": "debug"}

予想外にドバドバ出てきた。

curlの実行前に、metadata.google.internalにアクセスする接続が出てエラーになっていた。常にDNS解決にもアクセスにも失敗しそうなものだが、なんでこんなリクエストを実行しているんだろう。

本題のほうについては、フレームワーク内の「middleware - query」と「middleware - expressInit」という初期化系スパンが生まれている。属性的にはそんなに面白いものはない感じだった。

ハンドラは「request handler」というごく短いスパンになっている。/errorリクエストで直接内部例外起こしたところでは、特に何も属性は付かなかった。

Mackerelにも送ってみた。

だいぶ大雑把ではあったけれども、これでひととおりzero-code計装として公式に言及されている6言語を試し終えた。次回記事で、総評や今後試してみたいことなどを書き連ねてみることにしよう。