😊

一日一処: npm installとかでピロピロ動いてるあれがなにか突き止める(番外編)

2024/02/14に公開

JavaScript

ピロピロ動くあれ

前編と後編にて送ってきた、ピロピロのあれ。
正体がgaugeというパッケージであることを突き止める事ができた。ただし、実際の処理の中で、どの道筋を通って実行されているかを完璧に明らかにしたわけではない。
そのため、この番外編では、プログラムを実際にいじって、どの経路で動作したのか探る。

ソースコードだけで追えない

Catch me if you canなんて、ある人は言っていましたが、実行せずにプログラムのソースコードを読んで、それぞれの関係性を始め、順序や終端など、すべてを把握するには、かなりの時間がかかってしまいます。だったら、ソースコードを直接変更すればいい。
実際のところ、これから紹介する方法は、あまり推奨されておらず、やり直しが可能な環境でなければ、行うべきではない。よって、今回私は、Docker上にてNode環境を作り、そこで実行した。実際に触れてみたい人は、そのように、インスタントな環境で対応してほしい。

経路を把握

npmが使用できる環境下にて、npmコマンドを引数なしで実行すると、Usageが表示される。そして、非常に親切なことに、このnpmコマンドの場所まで丁寧に教えてくれる。

npm <command>

Usage:

npm install        install all the dependencies in your project
npm install <foo>  add the <foo> dependency to your project
npm test           run this project's tests

// 中略

npm@10.2.4 /usr/local/lib/node_modules/npm

末尾を見ると、npmのパスが記述されている。ひとまず、ここへ向かうのだが、今回、ターゲットとなっているのは、ピロピロを表示しているgaugeパッケージだ。npmは、それぞれのパッケージが必要となるそれぞれのパッケージをインストールしているので、npmのnode_modulesを見に行けば、gaugeがインストールされているのも確認できる。
gaugeのパッケージのファイル一覧を見たが、さて、どいつの中身を変更してやろうか、とじっくりファイル名を観察していると、lib/progress-bar.jsというなんともそれらしいファイルを見つけた。手始めに、このファイルにて例外を返却してみる。

lib/progress-bar.js

  'use strict'
  var validate = require('aproba')
  var renderTemplate = require('./render-template.js')
  var wideTruncate = require('./wide-truncate')
  var stringWidth = require('string-width')

  module.exports = function (theme, width, completed) {
+   throw new Error('test')
    validate('ONN', [theme, width, completed])

関数の先頭で、例外を投げるように追記した。適当にinstallコマンドを実行すると、この様に表示された。

npm ERR! test

大成功の様だ。しっかりとここを通過していることがわかった。
次にしたいことは、ここまで、どのような経路を辿って、ピロピロへ到達しているのかということだ。installのプログラムの流れは、なんとなく前編にて把握した。それと同じような、流れであれば、嬉しい限りだ。
この流れを知るために、以下を更に追記した。

lib/progress-bar.js

  'use strict'
  var validate = require('aproba')
  var renderTemplate = require('./render-template.js')
  var wideTruncate = require('./wide-truncate')
  var stringWidth = require('string-width')

  module.exports = function (theme, width, completed) {
+   console.trace()
+   throw new Error('test')
    validate('ONN', [theme, width, completed])

保存して、また適当にnpm installを実行すると、今度は以下の出力となった。

Trace
    at module.exports (/usr/local/lib/node_modules/npm/node_modules/gauge/lib/progress-bar.js:8:11)
    at TemplateItem.progressbar [as value] (/usr/local/lib/node_modules/npm/node_modules/gauge/lib/base-theme.js:16:12)
    at renderFunction (/usr/local/lib/node_modules/npm/node_modules/gauge/lib/render-template.js:204:17)
    at renderValue (/usr/local/lib/node_modules/npm/node_modules/gauge/lib/render-template.js:212:50)
    at /usr/local/lib/node_modules/npm/node_modules/gauge/lib/render-template.js:10:12
    at Array.map (<anonymous>)
    at module.exports (/usr/local/lib/node_modules/npm/node_modules/gauge/lib/render-template.js:16:24)
    at TemplateItem.value (/usr/local/lib/node_modules/npm/node_modules/gauge/lib/render-template.js:57:12)
    at renderFunction (/usr/local/lib/node_modules/npm/node_modules/gauge/lib/render-template.js:204:17)
    at renderValue (/usr/local/lib/node_modules/npm/node_modules/gauge/lib/render-template.js:212:50)
npm ERR! test

例外の処理の前に多くの文字が現れてくれた。これが、console.traceの結果だ。そして、当然ながら、スタックトレースの順序は、末尾にかけて、呼び出し元に戻っていくため、当然npm.jsになるのだが、この結果を見ると、少し異なる。
最後に表示されている箇所は、gaugeのrenderValue関数だ。そして、これはこの一覧の中で２回登場する。２回登場するが、その間にあるのは、at Array.map (<anonymous>)というログだ。何を意味するかというと、ある配列が、mapメソッドを用いて、同様の処理を複数回実行しているということだ。実行回数が多くなると、必然的に、一部のログしか表示されなくなってしまう。
このmapメソッドの実行は、関数の実行を遡れば、すぐに見つけ出すことができる。
発見したmapメソッドの実行手前で、先程と同様にスタックトレースを表示する。

lib/render-template.js

  var renderTemplate = module.exports = function (width, template, values) {
+   console.trace()
+   throw new Error('test')
    var items = prepareItems(width, template, values)
    var rendered = items.map(renderValueWithValues(values)).join('')
    return align.left(wideTruncate(rendered, width), width)
  }

新しく表示されたログは以下の内容だ。前回より短い件数となった。

Trace
    at module.exports (/usr/local/lib/node_modules/npm/node_modules/gauge/lib/render-template.js:15:11)
    at Plumbing.show (/usr/local/lib/node_modules/npm/node_modules/gauge/lib/plumbing.js:47:10)
    at Gauge._doRedraw (/usr/local/lib/node_modules/npm/node_modules/gauge/lib/index.js:282:40)
    at Timeout._onTimeout (/usr/local/lib/node_modules/npm/node_modules/gauge/lib/index.js:15:19)
    at listOnTimeout (node:internal/timers:573:17)
    at process.processTimers (node:internal/timers:514:7)
npm ERR! test

内容の末尾を見ると、npm.jsではない。件数が少ないため、これ以上の表示はないだろう。末尾の項目を見ると、process.processTimersとある。これは、非同期処理を行った際のエントリーポイントとなるため、この時点で、gauge側からのスタックトレースで呼び出し元を知るすべはなくなった。

諦められないその先へ

前述のログには、まだ読み解いていない部分がある。それがGauge._doRedrawだ。これは、外部から直接呼び出すことを想定していないメソッドであることが命名からわかるため、このクラス内のみで使用されているはずだ。そして、注意深く遡っていくと、callWith関数(lib/index.js:15:19)の到達する。これは、単純に指定されたメソッドを呼び出すための関数を生成するもので、なにかに任意で呼び出したい関数を設定する場合に使用するパターンだった。
そして、さらにこれを遡ると、callWith関数で生成された関数は、以下で実行されていた。

非同期処理としても使われるsetInterval関数がここで登場している。これが、先程のログのprocess.processTimersの正体だ。前に習い、ここも同様にスタックトレースを表示させると、以下のような出力となる。

Trace
    at Gauge._enableEvents (/usr/local/lib/node_modules/npm/node_modules/gauge/lib/index.js:184:13)
    at Gauge.enable (/usr/local/lib/node_modules/npm/node_modules/gauge/lib/index.js:155:10)
    at log.enableProgress (/usr/local/lib/node_modules/npm/node_modules/npmlog/lib/log.js:88:14)
    at Arborist.addTracker (/usr/local/lib/node_modules/npm/node_modules/@npmcli/arborist/lib/tracker.js:33:16)
    at Arborist.reify (/usr/local/lib/node_modules/npm/node_modules/@npmcli/arborist/lib/arborist/reify.js:156:10)
    at Install.exec (/usr/local/lib/node_modules/npm/lib/commands/install.js:152:15)
    at Install.cmdExec (/usr/local/lib/node_modules/npm/lib/base-command.js:142:17)
    at Npm.exec (/usr/local/lib/node_modules/npm/lib/npm.js:136:20)
    at module.exports (/usr/local/lib/node_modules/npm/lib/cli-entry.js:61:15)
npm ERR! test

皆の衆、これで満足だろう。末尾の方を見ると、しっかりとnpm.jsの呼び出しも、さらにcliとしての呼び出しも確認できる。末尾４つの項目は、前編で確認した内容だ。おそらく、コード上で確認した流れとほぼ同程度に動いているだろう。
ただ、前編でInstall.execを確認していたにも関わらず@npmcli/arboristの読み込みをスルーしてしまったことが悔しい。冷静になっていれば、npm installコマンドでreifyという文字は常に表示されていたため、@npmcli/arboristのパッケージにも目線を落とすべきだった。
ちなみに、以下の処理で、arboristからnpmlogに処理が移り、gaugeに到達する。

最後に

この３回に綴った内容は、npmの中身に迫るということだけではなく、プログラムとにらめっこしても、わからないときはわからないので、スタックトレースや例外の出力をしてみるということを伝えたかったことも目的のひとつだった。
ただやはり思うのは、この様にソースコードを遡るのは楽しい。