GAE/Goでハマった制約: invalid security ticket (context expired) #Go

~~「Google App Engineではレスポンスだけ速攻で返して別プロセスで重い処理を実行する、みたいなAPIは作れない」という学びがありました。~~
2018/12/1追記: コメントで「Task Queueを使えば10分までの処理は実行できる」とご指摘いただきました。試してみます！
2018/12/14追記：TaskQueueによる実装を記事にしました
GAE/GoでTaskQueueを使ったAPIを実装する - Qiita

よく考えれば当たり前のことですが、ググっても上手く情報を見つけられなかったので書き残しておきます。

環境

macOS High Sierra 10.13.6
go version go1.11.2 darwin/amd64
Python 2.7.13 :: Anaconda 4.4.0 (x86_64
Google Cloud SDK 226.0.0

やろうとしたこと

GAE/GoでAPIを作る
特定のリクエストを受け取ったら速攻でレスポンスを返して、goroutineで外部のAPIを叩いたりDatastoreに書き込んだりする

これなら「60秒以内にレスポンスを返さないといけない」という制限をクリアして好きな処理ができるのでは？という淡い希望がありました。

`Call error 3: invalid security ticket (context expired)`

そして、私たちが行き着く結末はこれです。

2018/11/29 02:16:25 appengine_internal.flushLog: failed Flush RPC: Call error 3: invalid security ticket (context expired)

「contextが期限切れだぞ。セキュリティだめだぞ」と。

実装

何がこのエラーを起こすのかを検証してみました。結論は「レスポンスを返した時点でそのリクエストに対応するcontextは期限切れになってしまう」なのですが、OKパターンとNGパターンを比較してみましょう。

ということで、こんなAPIを実装しました。

OKパターン `helloForeground`関数

https://www.google.comにアクセス
Googleから返ってきたステータスコードをログに残す
okのレスポンスを返す

とくに変わったことはしていません。公式の手順を参考に、GCP外部にHTTPリクエストしています。

ref. Issuing HTTP(S) Requests | App Engine standard environment for Go | Google Cloud

const url = "https://www.google.com/"

// OKパターン
func helloForeground(w http.ResponseWriter, r *http.Request) {
  // URLにリクエストして返ってきたステータスをログに残す
  ctx := appengine.NewContext(r) // App Engineのcontext作成
  client := urlfetch.Client(ctx) // contextを使ってhttp.Clientを作成
  resp, err := client.Get(url)
  if err != nil {
    log.Errorf(ctx, "TEST: helloForeground: %s", err)
    return
  }
  log.Infof(ctx, "'%s' returns %s", url, resp.Status)

  // レスポンス
  json.NewEncoder(w).Encode(Response{
    Status: "ok",
    Message: fmt.Sprintf("'%s' returns %s", url, resp.Status),
  })
}

NGパターン `helloBackground`関数

↓の処理をするgoroutineを作成
1. https://www.google.comにアクセス
2. Googleから返ってきたステータスコードをログに残す
okのレスポンスを返す

こちらは、先ほどのHTTPリクエスト & ログ送信をgoroutineのなかで行うパターンです。goroutineを作成したらさっさとokのレスポンスを返しています。

「60秒制限に引っかからないようになるはやでレスポンスを返して、あとの重たい処理はgoroutineのなかに放り込んでしまえ」という発想です。

// NGパターン
const url = "https://www.google.com/"

func helloBackground(w http.ResponseWriter, r *http.Request) {
  // URLにリクエストして返ってきたステータスをログに残すgoroutine
  go func() {
    ctx := appengine.NewContext(r) // App Engineのcontext作成
    client := urlfetch.Client(ctx) // contextを使ってhttp.Clientを作成
    resp, err := client.Get(url)
    if err != nil {
      log.Errorf(ctx, "TEST: helloBackground: %s", err)
      return
    }
    log.Infof(ctx, "'%s' returns %s", url, resp.Status)
  }()

  // レスポンス
  json.NewEncoder(w).Encode(Response{
    Status: "ok",
    Message: "processing in background.",
  })
}

コード全体

その他必要な記述を追加したコード全体がこちらです。

package main

import (
  "fmt"
  "net/http"
  "encoding/json"

  "google.golang.org/appengine"
  "google.golang.org/appengine/log"
  "google.golang.org/appengine/urlfetch"
)

const url = "https://www.google.com/"

type Response struct {
  Status string `json:"status"`
  Message string `json:"message"`
}

func main() {
  http.HandleFunc("/fore", helloForeground)
  http.HandleFunc("/back", helloBackground)
  appengine.Main()
}

// OKパターン
func helloForeground(w http.ResponseWriter, r *http.Request) {
  // URLにリクエストして返ってきたステータスをログに残す
  ctx := appengine.NewContext(r) // App Engineのcontext作成
  client := urlfetch.Client(ctx) // contextを使ってhttp.Clientを作成
  resp, err := client.Get(url)
  if err != nil {
    log.Errorf(ctx, "TEST: helloForeground: %s", err)
    return
  }
  log.Infof(ctx, "'%s' returns %s", url, resp.Status)

  // レスポンス
  json.NewEncoder(w).Encode(Response{
    Status: "ok",
    Message: fmt.Sprintf("'%s' returns %s", url, resp.Status),
  })
}

// NGパターン
func helloBackground(w http.ResponseWriter, r *http.Request) {
  // URLにリクエストして返ってきたステータスをログに残すgoroutine
  go func() {
    ctx := appengine.NewContext(r) // App Engineのcontext作成
    client := urlfetch.Client(ctx) // contextを使ってhttp.Clientを作成
    resp, err := client.Get(url)
    if err != nil {
      log.Errorf(ctx, "TEST: helloBackground: %s", err)
      return
    }
    log.Infof(ctx, "'%s' returns %s", url, resp.Status)
  }()

  // レスポンス
  json.NewEncoder(w).Encode(Response{
    Status: "ok",
    Message: "processing in background.",
  })
}

APIを叩いてみる

これを、ローカルでデプロイしてAPIサーバーを起動します。

$ dev_appserver.py app.yaml --port 8080 --admin_port 8000
INFO     2018-11-29 02:49:15,235 devappserver2.py:278] Skipping SDK update check.
INFO     2018-11-29 02:49:15,495 api_server.py:275] Starting API server at: http://localhost:56998
INFO     2018-11-29 02:49:15,503 instance_factory.py:170] Building with dependencies from GOPATH.
INFO     2018-11-29 02:49:15,510 dispatcher.py:256] Starting module "default" running at: http://localhost:8080
INFO     2018-11-29 02:49:15,515 admin_server.py:150] Starting admin server at: http://localhost:8000
INFO     2018-11-29 02:49:19,624 instance.py:294] Instance PID: 49458

OKパターン

別のコマンドラインか、ブラウザを起動してhttp://localhost:8080/foreを叩きます。

$ curl http://localhost:8080/fore
{"status":"ok","message":"'https://www.google.com/' returns 200 OK"}

普通に返ってきました。

サーバー側のコマンドラインを確認すると、こちら側でも正常に処理されているのが分かります。

2018/11/29 03:19:50 INFO: 'https://www.google.com/' returns 200 OK
INFO     2018-11-29 03:19:50,065 module.py:861] default: "GET /fore HTTP/1.1" 200 69

NGパターン

今度はhttp://localhost:8080/backを叩きます。

$ curl http://localhost:8080/back
{"status":"ok","message":"processing in background."}

クライアント側は上手くいっているように見えます。しかし、サーバー側を確認すると、

2018/11/29 03:21:40 ERROR: context expired before API call urlfetch/Fetch completed
request URL: /back
2018/11/29 03:21:40 ERROR: TEST: helloBackground: Get https://www.google.com/: Call error 3: invalid security ticket (context expired)
2018/11/29 03:21:40 ERROR: context expired before API call logservice/Flush completed
request URL: /back
2018/11/29 03:21:40 appengine_internal.flushLog: failed Flush RPC: Call error 3: invalid security ticket (context expired)
INFO     2018-11-29 03:21:40,239 module.py:861] default: "GET /back HTTP/1.1" 200 54

予定通りこの結末を迎えました。

TEST: helloBackground:... の部分は、google.comからのレスポンスを受け取るときのエラーハンドリングで書いたログなので、そのときに発生しているエラーだと分かります。

やっぱりそんなうまい話はないよなあ、おとなしくGCEに切り替えよう…。

GAE/Goでハマった制約: invalid security ticket (context expired)

環境