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

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

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


## 環境
* 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

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

これなら「[60秒以内にレスポンスを返さないといけない](https://cloud.google.com/appengine/docs/standard/go/how-requests-are-handled)」という制限をクリアして好きな処理ができるのでは？という淡い希望がありました。

## `Call error 3: invalid security ticket (context expired)`
そして、私たちが行き着く結末はこれです。

```bash
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`関数
  1. `https://www.google.com`にアクセス
  2. Googleから返ってきたステータスコードをログに残す
  3. okのレスポンスを返す

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

ref. [Issuing HTTP(S) Requests  |  App Engine standard environment for Go  |  Google Cloud](https://cloud.google.com/appengine/docs/standard/go/issue-requests)

```golang
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`関数
  1. ↓の処理をするgoroutineを作成
      1. `https://www.google.com`にアクセス
      2. Googleから返ってきたステータスコードをログに残す
  2. okのレスポンスを返す

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

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

```golang
// 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.",
  })
}
```

### コード全体

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

```golang
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サーバーを起動します。

```bash
$ 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`を叩きます。

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

普通に返ってきました。

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

```bash
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`を叩きます。

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

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

```bash
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に切り替えよう…。