portal shit!

Rails のログファイルを tail -f で見たいんだけど余計なものはフィルタリングして表示されないようにしたかった。最初は以下のようにしてみた。

⚡ tail -f log/development.log | grep -v -e ‘asset|Cache|Rendered’

これだと条件にマッチする行は表示されなくなるけど改行が削除されずに空行がたくさん表示される。これでは見やすいとは言えない。以下のように sed で空行を削除するようにしてみた。

⚡ tail -f log/development.log | grep -v -e ‘asset|Cache|Rendered’ | sed -e ‘/^$/d’

しかしこうすると必要な情報まで表示されなくなってしまう。 tail ではなく cat とかでやると望んだ通りになる。 tail -> grep -> sed の流れだとうまくいかないぽかった。

“tail grep sed” でググったら以下のような記事を発見したので試しに grep に —line-buffered オプションを渡してみた。

grep, awk, sed でバッファしない方法 | TECHSCORE BLOG

こんにちは、TechscoreBlogのログ閲覧が日課になっている河野です。ログをtailでリアルタイムに見ているときに、grep, awk, sedと組み合わせることがあります。ところが、特にオプシ...

www.techscore.com

⚡ tail -f log/development.log | grep -v -e 'asset|Cache|Rendered' --line-buffered | sed -e '/^$/d'

これで望んだ通りの出力になった。便利。

Rails で public_activity.gem を使っていて、 activities テーブルにレコードが追加されたタイミングで callback を仕掛けたい衝動に駆られた。ちょっと調べてみたけどやり方が見つからなかったので、チームの人と相談して以下のようにした。 public_activity は PublicActivity::Activity というモデルを gem の中に持っていて、こいつが belongs_to :model になる。

なのでこのモデルクラスを open して以下のように記述した。

# RAILS_ROOT/lib/public_activity/activity.rb

module PublicActivity
  class Activity
    after_create do
      HogeHogeMailer.send_mail(self.trackable).deliver
    end
  end
end

ただしこのファイルを config/initializers/ とかで require してやらないと Rails がファイルを読み込んでくれない。 Rails.application.config.autoload_paths に lib/**.rb とかを追加しとけば自動的に読み込まれるんじゃないかなと思ったけどそうじゃなかった。 Rails の autoload は、 ConstMissing という例外が発生したときに定数の名前からファイル名を推測して require するらしい。名前が既に定義済みだと ConstMissing 例外が発生せず autoload では読み込まれないので明示的に読み込む必要があるということらしい。

読み込みされていないクラスを使用すると ConstMissing という例外が発生します。 この部分に介入して autoload_paths の中に規約に合うファイルがあるか確認します。 存在する場合は読み込みします。 存在しない場合は ConstMissing を発生させます。

Rails の自動読み込みの話 - そんなこと覚えてない

ナルホディウスですぞ〜！！！

そのうち忘れそうなのでここに書き記しておきます。

このブログを Capistrano 3 でデプロイするようにした。こちらを参考にした。

unicorn + rails 用 Capistrano 3 の設定ファイル #Rails - Qiita

動くところまでできたので共有します。 Gemfile group :development, :test do gem 'capistrano', :require => false gem 'capistrano-rails', :require => fals...

qiita.com

一点、 deploy:restart 内で、 invoke メソッドで他の namespace の task を呼び出すところで

The deploy has failed with an error: #<NoMethodError: undefined method `verbosity' for "/usr/bin/env unicorn:restart\n":String>

というエラーが出てた。調べたらどうも sshkit のバグっぽかった。

Fix "undefined method `verbosity'" error by nikita-v · Pull Request #58 · capistrano/sshkit

Fix "undefined method `verbosity'" error in the Pretty formatter

github.com

最新版では Pull Request マージされてて治ってるぽかったので Gemfile で

gem 'sshkit', github: 'capistrano/sshkit'

と書いておいた。

Capistrano 3、他の gem いれなくても色付いたりマルチステージになってたり rbenv 対応しててモダンになってると思った。あとシンボリックリンク作ってくれる task が便利。

フッターのキャッシュとかフラグメントキャッシュはできたので、サイトのなかで一番重いアーカイブページのキャッシュを考えてみることにした。

当初はアーカイブページも、一番重い記事一覧表示部分をフラグメントキャッシュしてみていた。しかしあまり効果がなかった。Sinatra は仕組み上、コントローラーにいろいろ書いてしまいがちになり、アーカイブページのコントローラーが Fat になっていた。そのためフラグメントキャッシュをしたところでコントローラーの重い処理はビューがレンダリングされる前に走ってしまい、キャッシュの意味があまりない状態だった。

Rails だったらアクションキャッシュとかあるけど、先日から Folk して改造を進めている sinatra-cache でできるのはページキャッシュとフラグメントキャッシュだけなため、ページキャッシュをしてみることにした。

ページキャッシュの残念な点は Nginx 側の設定も必要なことだ。せっかく Lokka は Heroku や Sqale など Rack アプリケーション置ける PaaS にならどこにでも置けるのに、Nginx の設定変更を前提とした変更を行うと CMS for Cloud ではなくなってしまう。しかしこのブログは自分の勉強の場でもあるのでえいやっとやてみた。

sinatra-cache は Lokka + Nginx + Unicorn という環境であれば、LOKKA_ROOT/lib/lokka/app.rb を開いて以下のようにしてやれば使えるようになります。

require 'lokka'
require 'sinatra/cache'        # <= 追加

module Lokka
  class App < Sinatra::Base
    configure do
      # ...
      register Sinatra::Cache  # <= 追加
      set :cache_enabled, true # <= 追加
      # ...
    end
    # ...
  end
end

とかやってやれば、勝手に LOKKA_ROOT/public にキャッシュファイルを作るようになります。Nginx 側でキャッシュファイルがあれば Unicorn に proxy せずキャッシュファイルを返すようにすればページキャッシングで爆速になる。sinatra-cache は {$request_filename}.html という名前でキャッシュファイルを作るので Nginx の設定は以下のような感じになる。

server {
    location {
        root /var/wwww/portalshit/public;
        # ...
        if (!-f $request_filename.html) {
            add_header Cache-Control public;
            rewrite (.*) $1.html;
            break;
        }
        # ...
    }
}

ポータルシットはトップページも重いのでトップページもページキャッシュしようかなと思ったけど、ページングとかあるのでいろいろ面倒くさいことになることに気がついた（キャッシュファイルがない状態で Google のクローラーが 35 ページ目とかをクローリングしてたら 35 ページ目の html が index.html としてキャッシュされてトップページに来た人が全員 35 ページ目を見ることになってしまう）のでやめた。

キャッシュ、レスポンスを速くしてくれるけど何でもキャッシュすれば良いわけではないし奥が深い。

Lokka がすごく遅い

EC2 の micro で Lokka を運用してたけど、Unicorn が CPU 100% 近く使う状態が続き、リクエスト送ってレスポンスが返ってくるまでに 30 秒近くかかる状態になってて、AWS での運用を諦めざるを得なかった。さくら VPS に戻したところ、CPU 使用率もロードアベレージも落ち着いた。しかしレスポンスは遅くて、HTML が返ってくるまでに 5 秒くらいかかってる。

原因調べた

Newrelic を入れて調べてみた。Application が一番遅い。MySQL も遅いけど気になるレベルではないみたいだった。

• EC2 に Application
• さくら VPS に MySQL

という構成で運用していたのが遅い原因だったかも。App も DB も同じサーバーに置いたら Newrelic 上で Database が遅いと表示されなくなった。つまり Application をどうにかするしかない。

やろうとしてること

Lokka で動いててもそんなに遅くないページもある。komagata さんのブログは遅くない（heroku に置いてあるっぽいので heroku 側でキャッシュとかいろいろやってあるのもあると思う）。自分のブログに関してはテンプレートで最近の過去数ヶ月の月ごとの記事数表示したりタグクラウド出したりしてるところが遅そう。なので重い処理のところをフラグメントキャッシュしたい。

試したこと

sinatra-cache

導入できて動いた。勝手にページキャッシュする。フラグメントキャッシュできるけど、キャッシュのキーが URL のディレクトリベースのため、効率が悪い。

padrino-cache

導入できなかった。Padrino::Routing に依存してるっぽくて素の Sinatra で使いづらい。

落っこちてた gist (Simple fragment caching in sinatra)

これも Sinatra が前提。view から使うフラグメントキャッシュ専用ヘルパーメソッド。なんか Sinatra が内部的に使ってるインスタンス変数を上書きするというやり方みたい そのままでは Lokka で使えず <- ｲﾏｺｺ。

最後のやつが一番導入に近いところまで来てるっぽいけど、断片の部分だけ haml のコードを実行させて結果を取得させる、というところがなかなか難しい。Rails の ActionController::Caching のコードを見て参考にしようとしてみたけどちょっとよく分からなかった。

実は最近、仕事で Ruby 書かないおじさんになってしまったので週末に Ruby のコード見てもすんなり頭に入ってこない。ダメだなぁ。

一月くらい前から Lokka の master ブランチを自分のブログ用のブランチに merge してサイトをデプロイすると謎の白画面が出るようになっていて困っていた。現象は極めて謎で、ローカルの開発環境（RACK_ENV='development'）では見られず、本番（RACK_ENV='production'）だけで発生した。HTTP ステータスコードは 1054 が返ってきたりする。なんか変な gem でも入れてしまったかなと休みの日に動作検証したりしていたんだけどついぞ分からなかった。

SQL 弱者なので気がついてなかったんだけど、2月15日の commit で Site モデルに新しいフィールドが追加されていた（Add default markup in admin/site/edit · 2243dc5 · lokka/lokka ※この機能便利すね）。なので bundle exec rake db:migrate しないといけなかったわけだった。ローカルで動いている開発環境（データベースは SQLite）では Migration なんて行ってないんだけどエラーは出なかった。本番は MySQL で動いていて、こちらでだけエラーが出るようだった。

しかしいざ migrate しようとすると失敗する。

bundle exec rake db:migrate
Upgrading Database...
rake aborted!
Invalid default value for 'updated_at'

のようなエラーが出る。updated_at のデフォルト値がおかしいらしい。このときのテーブルの構造を見てみると以下のような感じだった。

mysql> desc entries;
+-----------------+--------------+------+-----+---------------------+-----------------------------+
| Field           | Type         | Null | Key | Default             | Extra                       |
+-----------------+--------------+------+-----+---------------------+-----------------------------+
| id              | int(11)      | NO   | PRI | NULL                | auto_increment              |
| user_id         | int(11)      | YES  |     | NULL                |                             |
| category_id     | int(11)      | YES  |     | NULL                |                             |
| slug            | varchar(255) | YES  |     | NULL                |                             |
| title           | varchar(255) | YES  |     | NULL                |                             |
| body            | text         | YES  |     | NULL                |                             |
| type            | text         | NO   |     | NULL                |                             |
| draft           | tinyint(1)   | YES  |     | 0                   |                             |
| created_at      | timestamp    | NO   |     | 0000-00-00 00:00:00 |                             |
| updated_at      | timestamp    | NO   |     | CURRENT_TIMESTAMP   | on update CURRENT_TIMESTAMP |
| frozen_tag_list | text         | YES  |     | NULL                |                             |
| markup          | varchar(255) | YES  |     | NULL                |                             |
+-----------------+--------------+------+-----+---------------------+-----------------------------+

調べてみたところ MySQL の Mode が NO_ZERO_DATE になっている場合、MySQL は timestamp 型のフィールドのデフォルト値に 0000-00-00 00:00:00 みたいな値を設定することを許さないらしい。 mysql - Invalid default value for 'create_date' timestamp field - Stack Overflow

検証用に別にテーブルを用意して bundle exec rake db:setup してみたところ、以下のような構造のテーブルができた。

mysql> desc entries;
+-----------------+------------------+------+-----+---------+----------------+
| Field           | Type             | Null | Key | Default | Extra          |
+-----------------+------------------+------+-----+---------+----------------+
| id              | int(10) unsigned | NO   | PRI | NULL    | auto_increment |
| user_id         | int(11)          | YES  |     | NULL    |                |
| category_id     | int(11)          | YES  |     | NULL    |                |
| slug            | varchar(255)     | YES  |     | NULL    |                |
| title           | varchar(255)     | YES  |     | NULL    |                |
| body            | text             | YES  |     | NULL    |                |
| markup          | varchar(255)     | YES  |     | NULL    |                |
| type            | varchar(50)      | NO   |     | NULL    |                |
| draft           | tinyint(1)       | YES  |     | 0       |                |
| created_at      | datetime         | YES  |     | NULL    |                |
| updated_at      | datetime         | YES  |     | NULL    |                |
| frozen_tag_list | text             | YES  |     | NULL    |                |
+-----------------+------------------+------+-----+---------+----------------+

created_at と updated_at は datetime 型になるらしい。なので以下のような ALTER 文を実行した。

mysql> alter table entries modify column created_at datetime, modify column updated_at datetime;
mysql> desc entries;
+-----------------+--------------+------+-----+---------+----------------+
| Field           | Type         | Null | Key | Default | Extra          |
+-----------------+--------------+------+-----+---------+----------------+
| id              | int(11)      | NO   | PRI | NULL    | auto_increment |
| user_id         | int(11)      | YES  |     | NULL    |                |
| category_id     | int(11)      | YES  |     | NULL    |                |
| slug            | varchar(255) | YES  |     | NULL    |                |
| title           | varchar(255) | YES  |     | NULL    |                |
| body            | text         | YES  |     | NULL    |                |
| type            | text         | NO   |     | NULL    |                |
| draft           | tinyint(1)   | YES  |     | 0       |                |
| created_at      | datetime     | YES  |     | NULL    |                |
| updated_at      | datetime     | YES  |     | NULL    |                |
| frozen_tag_list | text         | YES  |     | NULL    |                |
| markup          | varchar(255) | YES  |     | NULL    |                |
+-----------------+--------------+------+-----+---------+----------------+

これで最新のコードをデプロイしても真っ白画面になることはなくなった。以前遭遇した更新時に created_at の値が更新されてしまう問題 もフィールドの型が timestamp だったのが原因なのだと思う。SQLite から MySQL への移行は一筋縄では行かないことが分かった。

DataMapper はソースコード内の記述内容から動的に Migration を行えるけど、ActiveRecord みたいに $APP_ROOT/db/ ディレクトリに Migration ファイルを作ってくれたりしないので DB スキーマの変更が必要なことに気がつきにくい。便利だけど不便な感じがする。Rails で $APP_ROOT/db/ 以下にアホみたいにファイルが出来ていくの嫌だと思っていたけど、スキーマ変更に気がつかずコードをデプロイしてウェブアプリケーション停止みたいな自体は防げると思った。

ブログ書こうと思ってパソコン開いて「ついでに最新版の変更を取り込むか」とかやるとデプロイできなくなったりして書きたかった記事が書けず残念な感じになる。はてなブログでブログ書いてて画面が真っ白になったらひとでくんさんに不具合報告して直してもらえば良いので楽だと思う。

Lokka で Syntax Highlight するプラグイン（morygonzalez/lokka-pygmentize · GitHub）、これまで Ajax で Syntax Highlight させてたんだけど、HTTP リクエストが増えていけてないと感じたのでサーバーサイドでハイライトが完結するように変更した。Railscasts の #272 Markdown with Redcarpet - RailsCasts を参考にして、プラグインの中で Entry クラスを再オープンした。こんな感じ。

class Entry
  def body
    doc  = Nokogiri::HTML(self.long_body)
    doc.search("//pre").each do |pre|
      code = pre.css("code")[0]
      pre.replace Pygments.highlight(
        code.text.rstrip,
        :lexer   => code[:class],
        :options => { :encoding => 'utf-8' }
      )
    end
    doc.to_s
  end
end

前の実装はだいぶいけてなかったと思うので随分マシになったと思う。あと この Pull Request でレンダリングエンジンに Redcarpet が追加されたので、GitHub と同じように

```ruby

```

みたいな感じの書き方でコードがハイライトされるようになった。便利。

追記1

ちゃんと動いてなかった…。夜直します…

追記2 2013/02/04 0:45

最終的にオープンした Entry クラスのコードは以下のようになった。

class Entry
  alias_method :original_long_body, :body
  def highlighted_long_body
    syntax_highlight(self.original_long_body)
  end
  alias_method :body, :highlighted_long_body

  alias_method :original_short_body, :short_body
  def highlighted_short_body
    syntax_highlight(self.original_short_body)
  end
  alias_method :short_body, :highlighted_short_body

  def syntax_highlight(body)
    doc = Nokogiri::HTML(body)
    doc.search("//pre").each do |pre|
      code  = pre.css("code")[0]
      lexer = if pre[:class].present?
                pre[:class]
              elsif code.present? && code[:class].present?
                code[:class]
              else
                nil
              end
      begin
        pre.replace Pygments.highlight(
          code.text.rstrip,
          :lexer   => lexer,
          :options => { :encoding => 'utf-8' }
        ) if code
      rescue MentosError
        next
      end
    end
    doc.to_s
  end
end

Lokka、結構メタプログラミングが多くて、Entry クラスのインスタンスの body メソッドは単なるゲッターではなく、 index アクションのときと show アクションのときで別々にエイリアスが設定されていて、index アクションのときは Entry#short_body 、show アクションのときは Entry#long_body が呼ばれるようになっていた。アラウンドエイリアス使って力業で解決したけど他のプラグインが同じように振る舞ったら破滅を招きそうな気がする…。それにしても『メタプログラミング Ruby』読んでなかったらどうすればいいか皆目検討付かなかっただろうなー。