Heroku CLIの動きを観察する

HerokuはCLIでもちゃんと利用できます。でも、CLIがうまく動かなかったり、同様の動作を、直接Platform APIを叩いて、プログラムから実行したくなることもありますよね。そんな時は、CLIの動作を眺めてみるといろいろとヒントが得られるかもしれません。

この記事はHeroku Advent Calendar 2019の8日目の記事です。7日目はさえきさんによる「見積から開発・運用まで！Herokuの基本とTips」でした。9日目は、「Herokuのdynoは何コアか」です。すみません！連投になっちゃった。

この記事の内容は2019年12月時点のものです。Heroku CLIの内部構成や非公開のAPIなどは予告なく変更になる可能性があります。

Heroku CLIとプラグイン

現在のHeroku CLIはNode.JSで書かれたCLIフレームワークであるoclifで構築されていて、プラグインを書きやすく、配布しやすくなっています。逆に言うと、CLIのそれぞれの動作がどのファイルで定義されているのか、コードを読むだけではわかりづらく、実際に動作する様子を観察して見たほうがわかりやすい場合があります。(ご指摘いただいて追記) プラグインを書いてみたくなったら、Dev Center記事Developing CLI Pluginsを読んでみてください！

うまく動かない例

今回はone-off dynoに接続できない問題を例にして、Heroku CLIのどこで何が起きているのか観察してみましょう。

$ heroku run bash
Running bash on ⬢ app-name... !
 ▸    ETIMEDOUT: connect ETIMEDOUT 50.19.103.36:5000

環境変数を設定して動作を観察する

上記の例では、エラーメッセージから、Herokuのエンドポイントのポート5000に接続できないことが原因とわかりますが、Heroku CLIはどのようにこの接続先を認識してるのかな？

そんな時には、環境変数DEBUGを設定して、Heroku CLIを起動してみましょう。下記のように、実行ファイルの場所、プラグインのパス、クレデンシャルのパス、プラットフォームAPIとのやりとり、さらには、one-off dynoとセッションを接続するために必要なURLが表示されます。(ご指摘いただいて追記) Dev Center記事Developing CLI Pluginsより、HEROKU_DEBUG=1でプラットフォームAPIとのやりとりの概略、HEROKU_DEBUG_HEADERS=1でプラットフォームAPIとのリクエスト・レスポンスヘッダを表示させることもできます。

$ DEBUG=* heroku run bash
/usr/local/Cellar/heroku/7.24.1/lib/client/bin/heroku run bash
HEROKU_BINPATH=/usr/local/Cellar/heroku/7.24.1/lib/client/bin/heroku /usr/local/Cellar/heroku/7.24.1/lib/client/7.35.0/bin/node /usr/local/Cellar/heroku/7.24.1/lib/client/7.35.0/bin/run run bash
  @oclif/config reading core plugin /usr/local/Cellar/heroku/7.24.1/lib/client/7.35.0 +0ms
  @oclif/config loadJSON /usr/local/Cellar/heroku/7.24.1/lib/client/7.35.0/package.json +0ms
  @oclif/config loadJSON /usr/local/Cellar/heroku/7.24.1/lib/client/7.35.0/oclif.manifest.json +3ms
  @oclif/config:heroku using manifest from /usr/local/Cellar/heroku/7.24.1/lib/client/7.35.0/oclif.manifest.json +0ms
  @oclif/config reading user plugins pjson /Users/zunda/.local/share/heroku/package.json +0ms
  @oclif/config loadJSON /Users/zunda/.local/share/heroku/package.json +3ms
  @oclif/config loading plugins [
  { name: 'heroku-repo', tag: 'latest', type: 'user' },
  { name: 'heroku-pg-extras', tag: 'latest', type: 'user' },
  { name: 'heroku-builds', tag: 'latest', type: 'user' },
  { name: 'heroku-slugs', tag: 'latest', type: 'user' },
  { 中略 }
] +1ms
  @oclif/config loadJSON /Users/zunda/.local/share/heroku/package.json/package.json +5ms
  :
  @oclif/config reading user plugin /Users/zunda/.local/share/heroku/node_modules/heroku-repo +0ms
  @oclif/config loadJSON /Users/zunda/.local/share/heroku/node_modules/heroku-repo/package.json +1ms
  :
  @oclif/config loading plugins [
  '@oclif/plugin-legacy',
  '@heroku-cli/plugin-addons-v5',
  中略
] +25ms
  @oclif/config reading core plugin /usr/local/Cellar/heroku/7.24.1/lib/client/7.35.0/node_modules/@oclif/plugin-legacy +0ms
  @oclif/config loadJSON /usr/local/Cellar/heroku/7.24.1/lib/client/7.35.0/node_modules/@oclif/plugin-legacy/package.json +4ms
  :
  @oclif/config init hook done +1s
  heroku init version: @oclif/command@1.5.18 argv: [ 'run', 'bash' ] +0ms
  @oclif/config runCommand run [ 'bash' ] +5ms
  @oclif/config:@heroku-cli/plugin-run-v5 require /usr/local/Cellar/heroku/7.24.1/lib/client/7.35.0/node_modules/@heroku-cli/plugin-run-v5/commands/run.js +7ms
  @oclif/config start prerun hook +27ms
  heroku:heroku:hooks:prerun start /usr/local/Cellar/heroku/7.24.1/lib/client/7.35.0/lib/hooks/prerun/analytics +0ms
  netrc-parser load /Users/zunda/.netrc +0ms
  http --> POST /apps/app-name/dynos +0ms
--> POST /apps/app-name/dynos
  http
  http     accept=application/vnd.heroku+json; version=3
  http     content-type=application/json
  http     user-agent=heroku/7.35.0 darwin-x64 node-v12.13.0
  http     range=id ..; max=1000
  http     host=api.heroku.com
  http     authorization=REDACTED +0ms
--> {"command":"bash","attach":true,"env":{"TERM":"xterm-256color","COLUMNS":80,"LINES":25}}
Running bash on ⬢ app-name... ⣽
<-- 201 Created
  http <-- POST /apps/app-name/dynos
  http {"attach_url":"rendezvous://rendezvous.runtime.heroku.com:5000/省略","command":"bash","created_at":"2019-12-07T19:33:22Z","id":"省略","name":"run.8399","app":{"id":"省略","name":"app-name"},"release":{"id":"省略","version":123},"size":"Hobby","state":"starting","type":"run","updated_at":"2019-12-07T19:33:22Z"} +780ms
  http
  http     cache-control=private, no-cache
  http     content-length=474
  http     content-type=application/json
  http     date=Sat, 07 Dec 2019 19:33:22 GMT
  http     oauth-scope=global
  http     oauth-scope-accepted=global write write-protected
  http     ratelimit-multiplier=1
  http     ratelimit-remaining=4499
  http     request-id=省略
  http     vary=Accept-Encoding
  http     via=1.1 spaces-router (d458a6f05c96), 1.1 spaces-router (d458a6f05c96)
  http     x-content-type-options=nosniff
  http     x-runtime=0.194371404 +779ms
<-- {"attach_url":"rendezvous://rendezvous.runtime.heroku.com:5000/省略","command":"bash","created_at":"2019-12-07T19:33:22Z","id":"6f38da4c-bb1d-4053-9c11-0ef19cedb4ee","name":"run.8399","app":{"id":"省略","name":"app-name"},"release":{"id":"省略","version":123},"sizeRunning bash on ⬢ app-name... !
  heroku:run Error: connect ETIMEDOUT 50.19.103.36:5000
  heroku:run     at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1128:14) +0ms
 ▸    ETIMEDOUT: connect ETIMEDOUT 50.19.103.36:5000
Error: connect ETIMEDOUT 50.19.103.36:5000
    at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1128:14)

それでは、Heroku CLIで/を、Happy Hacking!