仕事中の問題と解決メモ。

最近はPythonとGoogle Cloud Platformがメイン。株式会社ビズオーシャンで企画と開発運用、データ活用とか。https://github.com/uyamazak/

GKE上の Django + ManifestStaticFilesStorage + Google Cloud Storage でValueError無限ループが起きてハマった話

Templyでは、Djangoのアプリが入ったDockerコンテナをGoogle Kubernetes Engine(GKE)で動かし、ファイルはGoogle Cloud Storage(GCS)で管理している。
temply.bizocean.jp

本番公開してからデプロイ時にcss、jsなどの静的ファイルが更新されず困ったので、よくあるファイル名にハッシュを付ける形にして解決しようとしたところ、下記のようなエラーが連発して、止まってしまうことがあった。

ValueError at /favicon.ico
The file 'send/img/favicon.png' could not be found with <mysite.storage.MyManifestStaticFilesStorage object at 0x7f5fbae7d320>.

問題と解決方法を3行まとめ。

  • staticファイルはGCS上に置くので.dockerignoreで/static/以下をDockerイメージに含めないようにしていた
  • staticfiles.jsonは、STATIC_URL上ではなく、ローカルファイルシステム上STATIC_ROOT直下から読み込もうとする
  • GCSを使う場合でもSTATIC_ROOT/staticfiles.jsonだけはイメージに含めるなどdjango側がローカルで読める必要がある

以下詳細。

ファイル名にハッシュをつけるのはDjangoの標準で入っているManifestStaticFilesStorageを使った。

The staticfiles app | Django documentation | Django

これはsettings.pyに下記のような設定を追加するだけでおk。

STATICFILES_STORAGE = 'django.contrib.staticfiles.storage.ManifestStaticFilesStorage'

あとはテンプレートでちゃんとstaticを使ってパスを書いていれば、自動的に変換してくれるので導入は簡単。

{% static 'app/css/style.css' %}

仕組みとしては、collectstaticコマンド実行時に元のファイル名と、ハッシュ付きのファイル名のペアが書かれたstaticfiles.jsonを書き出し、それを使ってパスを変換してくれる。

で、開発環境では問題なく動いているのに、本番環境ではエラーが連発しまくってValueErrorのメールがきまくる現象になった。

faviconでエラーが出る原因は、ブラウザが裏で勝手にアクセスし、まずfavicon.icoがないのでエラーを出そうとするんだけど、そのエラーページでもfavicon.icoを呼び出すのでさらにエラーの無限ループだった。

静的ファイルはGCS上に別途アップし配信しているので、staticfiles.jsonもそっちから取ってきてるだろうと思っていたのだが違った。

開発環境ではアプリのディレクトリをまるごとマウントし、開発しやすくしており、/static/以下も入っていたので問題にならなかった。

下記のようにSTATIC_ROOTに指定したパス+staticfiles.jsonを.dockerignoreに追加すればおk。
.dockerignore

!app/django/static/staticfiles.json

いくらDockerといえども、こういった外部ストレージ周りは本番と開発で差異が出てしまうので注意が必要そう。

vimのPython環境を再構築した

基本的にPythonの開発は社内のLinuxサーバー上でVimを使い行っている。

Pythonを使うからには、やっぱりPEP8を守り、見た目も統一されたソースコードにしたいので、Vimに下記のプラグインを入れ、
github.com

さらに.vimrcに下記を追加して保存時走るようにして文法などのチェックを行っている。

autocmd BufWritePost *.py call Flake8()

インストール時にはたしかNeoBundleなどのパッケージ管理を使ったが、いまだに理解できず、何とか動いている感じで、消していいかわからないゴミもたくさん残っていた。

そんな風に感じている中、下記記事に出会った。

プラグインはフォルダでgit cloneするだけでいいらしい。

すてき。

tyru.hatenablog.com

でもvim8が必要。サーバーはUbuntu16.10でまだvim7だったので、下記記事通りにVim8にアップデートする。

Vim 8.0 Released! How to install it in Ubuntu 16.04 - Tips on Ubuntu

あっけなく動いて、.vimrcや、.vimディレクトリがかなりすっきりした。

残る問題としては、まだ社内サーバーはUbuntu16.10のためPython3.5で、Dockerでは3.6を使っているのでtype hintingがエラーになってしまうなど。これはおそらくUbuntu17.10にすればpythonも3.6になるので解決しそう。

Vimテクニックバイブル ?作業効率をカイゼンする150の技

Vimテクニックバイブル ?作業効率をカイゼンする150の技

DjangoのAdminsにメールが送られない時のチェックリスト

Djangoではsettings.pyのADMINSにメールアドレスを指定しておくと、エラー時に通知を送ってくれるので便利。

でもこれまでの開発でもよくなぜか届かない問題があり、最近Templyの開発でも起きたので備忘録。

temply.bizocean.jp


まず、メールサーバーの設定が済んでいて、django.core.mail.send_mailで送れることは前提として話を進める。

ADMINSの設定

名前、メールアドレスのタプルのリストを設定
https://docs.djangoproject.com/en/2.0/ref/settings/#admins

DEBUG=False

これは本番では間違えないと思うし当たり前だけど一応。

LOGGINGの設定

今回の原因1つ目
ログを受け取ってメールにしているので設定に追加が必要。

下記抜粋

LOGGING = {
    'version': 1,
    'disable_existing_loggers': True,
    'formatters': {
        'standard': {
            'format': '%(asctime)s [%(levelname)s] %(name)s: %(message)s'
        },
    },
    'filters': {
        'require_debug_false': {
            '()': 'django.utils.log.RequireDebugFalse',
        },
        'require_debug_true': {
            '()': 'django.utils.log.RequireDebugTrue',
        },
    },
    'handlers': {
        'mail_admins': {
            'level': 'ERROR',
            'class': 'django.utils.log.AdminEmailHandler',
            'include_html': True,
            'filters': ['require_debug_false'],
        },
    },
    'loggers': {
        'django.request': {
            'handlers': ['mail_admins'],
            'level': os.environ.get('DJANGO_LOG_LEVEL', 'INFO'),
            'propagate': True,
        },
    },
}

SERVER_EMAILの設定

今回の原因2つ目

似たようなメールの送信元としてDEFAULT_FROM_EMAILがあるが、ADMINSとMANAGERSはこれを使わない。
代わりにSERVER_EMAILを使っており、設定しないとroot@localhostが使われてしまう。

自前のメールサーバーであれば問題ないかもしれないが、今回メールのbackendに使っていたsendgridでは問題があるようで、スパムにも入らず消えてしまっていた。

https://docs.djangoproject.com/en/2.0/ref/settings/#server-email

SERVER_EMAIL = 'admins@sample.jp'

1日で理解するDjango超基礎入門

1日で理解するDjango超基礎入門

Django1.10 QUICKSTART-BOOK with Python3: 作りながら学ぶDjangoアプリケーション開発

Django1.10 QUICKSTART-BOOK with Python3: 作りながら学ぶDjangoアプリケーション開発

GCPのバグでGoogleのIssue Trackerに投稿して直してもらうまでの流れ

oceanusで使っているGCPのプロジェクトで、Cloud Functionsの関数の作成時、削除時にエラーが出て何もできない状況になった。

Googleで検索しても解決策は見つからず、他のプロジェクトでは問題なくできる操作なので、明らかにバグだと判断して、Stack Overflowなどの質問サイトではなく、公開バグトラッカーに投稿することにした。

コミュニティサポートの詳細はこれ。まずはこれで解決するかどうか読んで調べる。
Community Support Overview  |  Support  |  Google Cloud Platform

issue trackerについてはここ。読んで検索してそれでもだめだったら投稿する。
Report Bugs and Request Features with Issue Trackers  |  Support  |  Google Cloud Platform

当該のスレッドはこれ。Googleのアカウントが必要かもしれない。
https://issuetracker.google.com/issues/67027944

当時も検索したつもりだったけど、今改めて検索してみると、自分が投稿する3週間ほど前に同じような投稿が1件見つかった。
やりとりが多く、若干おこの模様。ここにコメントできればよかったかもしれない。
https://issuetracker.google.com/issues/65368380

原因としては、1年以上前に作ったプロジェクトで、Cloud Functionsのalpha時に使ってたのが原因だったらしい。裏で直してくれたようで無事消すことができた。

Marked as Fixed
Hi,
Your project turned out to be very old, used during alpha testing, so some setup was incorrect. Please try deleting the functions now.
I'm closing the issue now, but please reopen if it still fails.

英語を読むのには慣れたけど、質問などには慣れていないので、Google翻訳そのままか中学レベルの英語しか使えなかった。

こういったやりとりをよく読むようにして、かっこいい慣用句なんかを使っていきたい。


今回のバグは、特定のプロジェクトでcloud functionsが使えないという結構状況によってはまずいバグだったけど、9月末に投稿して直ったのが12月初旬なのでこういったバグでも2か月以上かかった。

今後投稿する人は、よく検索してから投稿し、気長に待った方がいいと思う。

BigQueryに入れたアクセスログを調べたい時によく使うスニペットまとめ

よく忘れてDatalabの中を捜索するはめになるので、まとめておく

レガシーSQL

TABLE_DATE_RANGE

昔ながらの日付別テーブルに格納しているとき

FROM TABLE_DATE_RANGE(
  [project_name:dataset_name.table_name_],
  TIMESTAMP("2017-11-27"), 
  TIMESTAMP("2017-11-28")
)

JSON

SELECT
  JSON_EXTRACT(jsn, "$$.text") as string,
  JSON_EXTRACT_SCALAR(jsn, "$$.text") as scalar,

URLからID(数字)を取り出す

SELECT
  INTEGER(REGEXP_EXTRACT(url, r'/doc/detail/([0-9]+)/')) as product_id,

日時の文字列を9時間プラス(日本時間)して、日付だけを返す

dtには「2017-11-26 14:41:27.407015」な感じの日付が文字列で入っている

SELECT
  DATE(DATE_ADD(TIMESTAMP(dt), 9, "HOUR")) 

gitでテストpushをたくさんしたいときのワンライナー

リモートレポジトリのWebHookとGoogle Cloud Functionsを使って、slack通知を作るときに使ったもの。

今の日付(date)が入ったpush.testという名前のファイルを作って、コミットして、remote-nameのbranch-nameにプッシュして削除まで行う。
履歴はたくさん残る。

date > push.test && git add push.test && git commit -m "`cat push.test`" && git push remote-name branch-name && git rm push.test

gunicornの [CRITICAL] WORKER TIMEOUT で本当の原因がわからなくなる問題

GKE上で動かしているgunicornアプリケーションで、特に負荷が高いわけでもないのに、突然

 [CRITICAL] WORKER TIMEOUT (pid:667)

というログを出しまくって止まってしまうことが発生していた。

いつなるかわからないのでしばらく見守っていたけど、原因を調べることにした。

gunicornのタイムアウトはconfファイルで設定している。

gunicorn_conf.py

worker_class = "gevent"
proxy_protocol = True
x_forwarded_for_header = "X-Real-IP"
bind = ":80"
# reload = True
timeout = 5
graceful_timeout = 5
# loglevel="debug"

Dockefileでは下記のように実行

CMD ["gunicorn", "-c", "gunicorn_conf.py", "arms:app"]

エラーが発生したときには、ログには上記の [CRITICAL] WORKER TIMEOUT が連発するだけで、エラーの原因がわからないなーと思っていたけど考えれば当たり前で、アプリ内の処理は特に時間がかかっているだけなので、エラーとは認識できない。

そのため、これから下記の対策を行う。

  1. タイムアウトが発生しそうなところ(DBとかRedis等外部への接続する関数) にすべて短めのタイムアウトをつける
  2. gunicornのタイムアウトは1でエラーが発生できるようにちょっと長めにする

タイムアウトは以前記事にも書いたtimeout-decoratorを使う。

uyamazak.hatenablog.com

そして、本番公開を行ったけど、いつ起こるかわからないのでしばらく様子見。

現時点の仮説としてはおそらくRedisへの接続でたまに時間がかかってしまうのと予想している。

アクセスの負荷とはあまり関係ないので、GKEでRedisのpodが移動したりでネットワークがつながらなくなっている可能性も。

その際は待っても解決しないので、PODごと落として、再起動させる必要があるかも。