はじめに

この記事はNew Relic Advent Calendar 2021の25日目の記事です。
「ミイダス」という転職支援・採用支援サービスで、New Relic Goエージェントを導入した際に踏んだ地雷について、いくつかご紹介したいと思います。

New RelicのGoエージェントはまだ新しいサービスで資料が少ないこともあり、いくつかの地雷を踏むことになるかと思いますが、それを乗り越えるととても幸せな世界が待っています。
弊社のサービスでは、New Relicを活用して、より良いサービスになるよう数々の処理の改善や障害の早期発見などに役立てています。

APIの応答性能やエラー率を監視するダッシュボード作成例

この記事が少しでも参考になって、読者皆様のNew Relic導入の一助になれば幸いです。

1.Goエージェントについて
 2.地雷その1 - ライセンスキー丸見え問題
 3.地雷その2 - 非同期処理でのエラー頻発問題①
4.地雷その3 - 非同期処理でのエラー頻発問題②
5.地雷その4 - バッチのメトリクスが取れない問題
 6.地雷その5 - レビュー辛い問題
 7.あとがき

1. Goエージェントについて

New Relicを使用してGoアプリケーションを監視するには、Goエージェントのパッケージを使用します。
https://github.com/newrelic/go-agent

トランザクション、データベース呼び出し、およびGoアプリケーションの動作の他の部分を追跡することが可能になります。
また、GoroutineやCPU、メモリなどの状態も監視することができます。

Goはランタイムに計測のための機能がないため、GoアプリにNew Relicを設定するには、GoエージェントAPIを使用し、ソースコードにNew Relicメソッドを手動で追加する必要があります。

弊社では以下のような感じでGoエージェントAPIをラップして使用しています。
また、WebフレームワークとしてEchoを使用しているので、Echoのインスタンスを作成した時にGoエージェントのnrecho ミドルウェアを追加しています。

apm.go

// New Relicアプリケーションを初期化
func NewAPMApplication(additional ...newrelic.ConfigOption) (*newrelic.Application, error) {
	options := []newrelic.ConfigOption{
		newrelic.ConfigLicense("__YOUR_NEW_RELIC_LICENSE_KEY__"),
	}

	if len(additional) > 0 {
		options = append(options, additional...)
	}

	app, err := newrelic.NewApplication(options...)

	if err != nil {
		return nil, err
	}

	if err = app.WaitForConnection(5 * time.Second); nil != err {
		return nil, err
	}

	return app, nil
}

// New Relicのアプリ名を設定
func SetAppName(appName string) newrelic.ConfigOption {
	return newrelic.ConfigAppName(appName)
}

main.go

// Echoフレームワークを使用する場合
func main() {
	e := echo.New()
	app, err := apm.NewAPMApplication(
		apm.SetAppName("Your Application Name")
		// 任意のnewrelic.ConfigOption追加
		}
	if err != nil {
		// New Relic初期化でエラー
	} else if app != nil {
		//nrecho ミドルウェアを追加
		e.Use(nrecho.Middleware(app))
	}
	// ~ 処理 ~
}

2. 地雷その1 - ライセンスキー丸見え問題

Goエージェントで集めたデータをNew Relicに送信するには、「1.Goエージェントについて」で紹介したようにNew Relicのライセンスキーの設定が必要です。
ここで、ライセンスキーの管理をどうするかということが問題になります。
というのも、開発のコード上でライセンスキーを直書等していると、ライセンスキーがログに出力されたり、コード上に書かれているので権限がない人達にまでライセンスキーが丸見えとなってしまいます。

ライセンスキーが丸見えとなった一部のログの具体例を以下に掲載します。

Error Api messaage: harvest failure, error: Post "https://collector-005.newrelic.com/agent_listener/invoke_raw_method?license_key=~ここで丸見え~&marshal_format=json&method=...": context deadline exceeded (Client.Timeout exceeded while awaiting headers), retain_data: true, cmd: metric_data

これはデータをNew Relicに送信する際に問題が発生した場合のエラーログですが、Post先のURLにlicense_keyがGetパラメータでガッツリ表示されてしまっています。
当然ユーザーには見えませんので、すぐ問題になることはありませんが、組織内とはいえ権限がない人達にまでライセンスキーが見えてしまうのはあまり望ましい状況ではありません。

対策

弊社ではライセンスキー丸見えの地雷に対して以下の2つの対応を行いました。

① AWS Secrets Managerでライセンスキーを管理

AWS Secrets Managerはライセンスキーやパスワード等のシークレット情報をAPIで呼び出すことで取得できるAWSのサービスです。
これを利用してNew Relicのライセンスキーをコード上にプレーンテキストで書き込むことを脱却しました。

② ログに書き込まれるライセンスキーを正規表現で検知して置換する

次にログ上でライセンスキーが丸見えになる問題への対処ですが、これはログが出力される前にコード上で書き込まれるログにライセンスキーを正規表現で検出して、別の文字列に置き換える処置を行いました。

コードは下記のような感じです。

// mask license_key
var rx = regexp.MustCompile("(license_key=[^&]*)(&|$)")
if strings.Contains(str, "license_key=") {
	str = rx.ReplaceAllString(str, "license_key=masked$2")
}

置換後のログ

Error Api messaage: harvest failure, error: Post "https://collector-005.newrelic.com/agent_listener/invoke_raw_method?license_key=masked&marshal_format=json&method=...": context deadline exceeded (Client.Timeout exceeded while awaiting headers), retain_data: true, cmd: metric_data

3. 地雷その2 - 非同期処理でのエラー頻発問題①

Go言語のGoroutineを活用した非同期処理においてNew Relicでデータを取得する場合、同期処理のTransactionをそのまま使用すると以下のようなエラーが出力されます。

Error Api message: unable to end segment, reason: transaction has already ended, ~

このログでは非同期処理内のセグメントが終了しようとしたところ、既にセグメントが終了されており、エラーとなっています。
これは以下の図のように親のSeg1から子となるSeg2を開始させた場合、本来であればSeg2の処理が終わってからSeg1が終了されるべきですが、Seg2が非同期の場合、順序が守られないので、先にSeg1が終了してしまい、Seg2も処理が途中にも関わらず同時に終了してしまうということになっています。

自分は寄りにも寄って夜中に回るバッチでこのエラーを出してしまい、ずっとSlackのエラー通知が鳴り止まない眠れぬ夜を過ごしました。

対策

GoroutineでNew Relicのデータを取得するにはTransaction.NewGoroutine() Transactionメソッドを使用します。

公式ドキュメント : https://docs.newrelic.com/jp/docs/apm/agents/go-agent/features/trace-asynchronous-applications/

これはGoroutine用に新しいTransactionの参照を返す処理で、他のセグメントに左右されず、完全に新しいセグメントの開始と終了を行うことが可能になります。

4. 地雷その3 - 非同期処理でのエラー頻発問題②

Webリクエスト~レスポンスという一連の処理の事後に走る非同期処理（Goroutine）でNew Relicのデータを取得したい場合、[3.地雷その2](#3-地雷その2 - 同期処理でのエラー頻発問題①)と同様にunable to end segment~のエラーが頻発する事象に見舞われました。
これはWebトランザクションを終了させてしまうと、Goroutineで起動した処理が終わる前にトランザクションのデータが確定されてしまうことが原因です。
特にnrecho等のミドルウェアを使っている場合は、通常トランザクションに対応したメソッドが完了した時点で自動的に終了されてしまうため、コントロールがよりシビアになります。

対策

New Relicのサポートに泣きつきました。
New Relicのサポートは日本語でも可能で、とても丁寧に相談に乗ってもらえます。

結果、nrecho等のミドルウェアを使っている場合にトランザクションが自動的に終了してしまうことを止めるAPIがあればよさそうですが、現時点のGoエージェントではそのようなAPIは存在しないため、機能リクエストを作成してもらいました。

作成してもらった機能リクエスト（GitHub）

New Relicのサポートは素晴らしいので、まだ利用されていない方は何か困ったらぜひ利用してみてください。

5. 地雷その4 - バッチのメトリクスが取れない問題

New RelicのトランザクションにはWebトランザクションとNon-webトランザクションの2種類のカテゴリがあります。
Webトランザクションは、Webリクエストによって開始される一般的なタイプのトランザクションです。
一方、Non-webトランザクションはWeb伴わないタイプで、バッチ等のバックグラウンドタスクの場合はこちらのカテゴリに分類されます。
ここで弊社で使用しているバッチ群にNon-webトランザクションとしてNew Relicのデータを取得しようとした際に、バッチ処理が完遂してもNew RelicのAPMメトリクスにまったく反映されない事象に会いました。
調査したところ、トランザクション終了時にデータがNew Relicに送信されていないことが判明しました。
これはバッチの終了でGo処理も即時終了されるため、データ送信処理が間に合っていないことが原因として考えられます。

対策

Goエージェントのメソッドでfunc (*Application) Shutdownというものがあるので、これをトランザクション完了時に使用します。
このメソッドは　、すべてのデータがNew Relicに送信されるか、タイムアウトが経過するまで待つという処理になっています。

実装は、以下のようにNewRelicのトランザクションを終了するタイミングでShutdownメソッドを呼ぶようにします。

app, err := newrelic.NewApplication(
    newrelic.ConfigAppName("Your Application Name"),
    newrelic.ConfigLicense("__YOUR_NEW_RELIC_LICENSE_KEY__"),
)
tx := app.StartTransaction("usecase")

// ~ 処理 ~

tx.End()
app.Shutdown(10 * time.Second)

これによって、バッチのAPMメトリクスも無事見られるようになりました。

Non-webのトランザクションタイプでAPMメトリクスが見れるようになっています。

6. 地雷その5 - レビュー辛い問題

New RelicのGoエージェントは上記で挙げたような地雷のように独自のロジックが多く存在しています。
このようなNew Relicの特有のコードを埋め込んで、コードレビューに出すのですが、いくつかつらみなポイントがあるので、ここでは2点紹介しようと思います。

①New Relicのコードが散りばめられるので敬遠されがち

New RelicのGoエージェントは監視したい処理にセグメントの開始と終了の処理を都度記述していく必要があるので、どうしても各処理でNew Relicのロジックが記述される箇所が多くなります。
また、New RelicのトランザクションにアクセスするためのContextを引数として伝搬する必要もあるので、メソッドの引数が一つ増えていくことになります。
すると、New Relicが組織に浸透していないうちはレビューで、「これなんとかなりませんか?」⇒「なんともなりません🙇‍♂️」の流れが発生するので、ここ辛いポイントです。
オブザーバビリティするんだという強い心をもってレビューに臨みましょう。

②コードを見ただけでは処理がうまく実行されるのかイメージが難しい

レビュワー視点の意見ですが、New Relicのコードは見ただけではその処理が間違っていても気づきにくいという問題があります。
例えば、以下のような処理の場合、s2より先にs1が終了していますからunable to end segmentのエラーになりますが、処理が複雑になってくるとセグメントの終了がどの順番で行われるのかきちんと把握していないと、わりと見逃してしまいます。

s1 := txn.StartSegment("outerSegment")
// ~　処理 ~
s2 := txn.StartSegment("innerSegment")
// ~　処理 ~
s1.End()
// ~　処理 ~
s2.End() // ここでエラー

New RelicのGoエージェントは出来てから日が浅いこともあり、しっかりとレビューできる人は限られてきますが、着眼点などを整理して組織内で共有することでNew Relicのナレッジを組織に浸透させるような活動も大切になってくるのかなと思います。
他にNew Relicのレビューで良いやり方やアイデアをお持ちの方がいましたらぜひ教えてください。

7. あとがき

サービスにNew Relicを導入してから半年程経ちましたが、最初はなにこれ？という組織内のムードから随分変わって利用する開発メンバーも増えてきました。
やはり最初はNew Relicのエラーもよく出しますし、APMメトリクスの見方もよくわからないので、組織に浸透するためのハードルが結構あるかもしれないですが、時間が経つにつれナレッジが溜まり、New Relicのオブザーバビリティの効力がサービスをより良いものに導いてくれるはずです。
Goエージェントに関しては、まだQiitaの記事も少ないみたいですので、これからも何かネタがあれば記事にしていきたいと思います。
それでは、ここまで読んでくださりありがとうございました。
良いお年をお迎えください！