カテゴリー別アーカイブ: トラブルシューティング

mysqlのネクストキーロックと挿入インテンションギャップロックのデッドロックを確認する

概要

先日mysqlを利用したアプリケーションにおいてデッドロックが発生しました。
あちゃぱーと思いつつもせっかくなので自分の中で消化しきれいなかった部分をこれを機に再確認してみることに。

この記事ではmysqlのデフォルトの分離レベル(Repeatable Read)においての レコードロック / ネクストキーロック / ギャップロック / 挿入インテンションギャップロック というハイカラな単語と結びつけながら自分なりに解釈したものを解説します。
と、赤字で書きましたが、始めに詫びを入れておきます。
ロックの解釈はドキュメントを読むだけで詳細に把握するのは非常に難しく、もしかしたら間違っていることを言っているかもしれません。そしたら本当に申し訳ありません。

解決したい問題

はじめに問題を共有したほうがやる気もでるしわかりやすい。
というわけで具体的に問題をものすごく単純にしたテーブルを用意しました。
こちらをつかって問題を再確認したいと思います。

テーブル

はい。めちゃくちゃ単純化しました。主キーとさらにインデックスを付けた属性だけが存在するテーブルです。わかりやすい。

CREATE TABLE test (
  id bigint(20) unsigned NOT NULL AUTO_INCREMENT,
  secondaryId bigint(20) unsigned NOT NULL,
  PRIMARY KEY (id),
  KEY idxSecondaryId (secondaryId)
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4;

データ

データを用意します。一応ギャップロックとかいう話も出てくるのでギャップが存在するように飛び飛びのデータを入れてみます。これまたわかりやすい。

INSERT INTO test (id, secondaryId) VALUES (10, 10), (20, 20), (30, 30), (40, 40);

デッドロック

さてここで用意ができましたので、問題を再現してみたいと思います。
ここでトランザクション1(Trx1)とトランザクション2(Trx2)という二人のお友達に協力してもらおうと思います。
上から順に時系列で記載します。左側にどちらのトランザクションが実施したかという情報を記載します。

Trx1: begin;
Trx2: begin;
Trx1: DELETE FROM test WHERE secondaryId = 80;
Trx2: DELETE FROM test WHERE secondaryId = 90;
Trx1: INSERT INTO test VALUES (80, 80); // ここでTrx1がロックが取得できずに待ち状態になります
Trx2: INSERT INTO test VALUES (90, 90); // ここでTrx2もロックを取得できずに待ち状態となり、Trx1とのデッドロック状態となります

ということで

これがどういう仕組でデッドロックするか理解している方、これ以上この記事を見る必要はないです。

さておき、問題が確認できました。
実際にはアプリケーションで特定のキーによって管理されたデータを一回削除して再度データを入れ直す、というような処理を実装していました。
データ構造は全く違いますが、問題の本質はこれと一緒になります。
さて、この状況で中で一体何が起こっているのか見ていきましょう。

基本

まずここに上げる公式マニュアルを合わせてくまなく目を通しましょう。
合わせてよくまとまっているサイトなどもあると思うので、嘘か本当か見極めつつ検索して参考にしましょう。
なお本記事では各種ロックがどういうものかという基本的なことは一切説明しません。

さらに言葉の定義をちゃんとイメージできた方がいいと思うのでいくつかここで補足します。

トランザクションとロック

「ロックした」とかいう表現が意外と通じるのであるのであたかも「ロック」というのが動作とか状態のように解釈されがちだと感じますが、自分なりに解釈した結果ですと「ロック」とはアクセスする権利とイメージするとしっくり来ると思います。

例えばあるトランザクションのsql実行が別のトランザクションによって待ち状態になったとしましょう。
この時まさに「ロックした」といってもいいんですが、もっと正確に言うと「ロックを取得しようとしたが取得できずに待ち状態になった」というのが正しいです。

つまりロックというのは単なるアクセス権なのです。
ものすごく単純にいうと、この辺の話はトランザクションという登場人物がいて、レコードを操作する際にロック(アクセス権)を確保したり開放したりして自分の作業の影響範囲を定義しているのです。
でロックが先に取得されていたら、ロックが解放されるまで終わるまで待つ。ロックが開放されたら自分がロックを取得してレコードを操作する。シンプルにそれだけの話です。

ロックとは

でロックにも3つほど種類が存在します。冒頭にも挙げた レコードロック / ギャップロック / ネクストキーロック です。
マニュアルを読むとなるほどこれらの性質はなんとなくわかります。ですが どういうときにどのロックが使用されるのか というところがいまいちマニュアルだけだと分からない。
というわけでここが本記事の肝になります。

調査

というわけでじゃあ具体的にどういうことが起こっているの?という調査をします。

調査環境は osx で MariaDB を使用します。バージョンは下記。

MariaDB [test]> select version();
+-----------------+
| version()       |
+-----------------+
| 10.1.21-MariaDB |
+-----------------+

そして状態を確認するために下記のコマンドを実施しておきます。
これによってトランザクションの状態を出力する際にロックの詳細も一緒に出力してくれるようになります。

set global innodb_status_output_locks = ON;

どういうロックがかかっているのか

では先の例に沿って実行していきます。下記のdelete文を発行した時点で各トランザクションがどういうロックの取得を行っているのか確認してみます。

Trx1: begin;
Trx1: DELETE FROM test WHERE secondaryId = 80;

この時点で下記のコマンドによってトランザクションの状態を確認します。
モニターテーブルを作成してそちらを参照しても良いです。

show engine innodb status\G

するといろいろ出力されるのですが、トランザクションのロック取得状況を表す箇所を抜粋します。

---TRANSACTION 82897, ACTIVE 101 sec
2 lock struct(s), heap size 360, 1 row lock(s)
MySQL thread id 899, OS thread handle 0x700010b45000, query id 4569881 localhost root cleaning up
Trx #rec lock waits 7 #table lock waits 0
Trx total rec lock wait time 28 SEC
Trx total table lock wait time 0 SEC
TABLE LOCK table test.test trx id 82897 lock mode IX lock hold time 101 wait time before grant 0
RECORD LOCKS space id 5931 page no 4 n bits 72 index idxSecondaryId of table test.test trx table locks 1 total table locks 1  trx id 82897 lock_mode X lock hold time 101 wait time before grant 0

確認すると

  1. テーブルに対するインテンション排他ロック
  2. idxSecondaryIdインデックスに対する排他ネクストキーロック

が取得されているようです。テーブルに対するインテンションなロックはこの場合にはデッドロックを引き起こさないので無視します。
では続いてトランザクション2にも同じ手順に沿って実施してもらいましょう。

Trx2: begin;
Trx2: DELETE FROM test WHERE secondaryId = 90;

どうように show engin innodb status を実施すると

---TRANSACTION 82898, ACTIVE 1 sec
2 lock struct(s), heap size 360, 1 row lock(s)
MySQL thread id 945, OS thread handle 0x700010e57000, query id 4569884 localhost root cleaning up
Trx #rec lock waits 2 #table lock waits 0
Trx total rec lock wait time 0 SEC
Trx total table lock wait time 0 SEC
TABLE LOCK table test.test trx id 82898 lock mode IX lock hold time 1 wait time before grant 0
RECORD LOCKS space id 5931 page no 4 n bits 72 index idxSecondaryId of table test.test trx table locks 1 total table locks 2  trx id 82898 lock_mode X lock hold time 1 wait time before grant 0

トランザクション1と同様のロックを取得していることが確認できます。

ここで一つ注目したいのはこれら2つのステートメントの実施はロック待ち状態が発生することなく実施することができました。
つまり delete文によって取得した2つの異なるインデックス値に対するネクストキーロックの範囲は重なっていない ということがわかりました。

ネクストキーロックとは何なのだろう

これに気づいた時結構驚きました。
だってネクストキーロックって、指定の値に対してレコードロックとさらにその前のインデックスとのギャップを含むと説明があるではありませんか。
テストデータの末尾の idxSeconaryId は 40 になっています。
すなわち Trx1 の delete文は (40, 80] の範囲のネクストキーロックを取得し、 Trx2 の delete文は (40, 90] の範囲のネクストキーロックを取得するのではないかと考えました。

わかりやすいように図を用意しましょう。力作です。
横軸が idxSecondaryId のインデックスの並びで、ボックスが取得しようとしているロックの範囲を表しています。

fig1

しかしながら双方のロックが取得しているということは、この仮定が誤っているという結論になります。
この解釈は後で述べることにして、とりあえず先に進みます。

デッドロックの確認

ではロック取得待ちを引き起こすトランザクション1のステートメントを実施してみましょう

Trx1: INSERT INTO test VALUES (80, 80); // ここでTrx1がロックが取得できずに待ち状態になります

ここでロック取得待ちが発生します。トランザクション1のロック取得状態を確認してみましょう。

---TRANSACTION 82897, ACTIVE 2059 sec inserting
mysql tables in use 1, locked 1
LOCK WAIT 3 lock struct(s), heap size 1184, 2 row lock(s), undo log entries 1
MySQL thread id 899, OS thread handle 0x700010b45000, query id 4569893 localhost root update
INSERT INTO test VALUES (80, 80)
Trx #rec lock waits 8 #table lock waits 0
Trx total rec lock wait time 28 SEC
Trx total table lock wait time 0 SEC
------- TRX HAS BEEN WAITING 2 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 5931 page no 4 n bits 72 index idxSecondaryId of table test.test trx table locks 1 total table locks 2  trx id 82897 lock_mode X insert intention waiting lock hold time 2 wait time before grant 0
------------------
TABLE LOCK table test.test trx id 82897 lock mode IX lock hold time 2059 wait time before grant 0
RECORD LOCKS space id 5931 page no 4 n bits 72 index idxSecondaryId of table test.test trx table locks 1 total table locks 2  trx id 82897 lock_mode X lock hold time 2059 wait time before grant 0
RECORD LOCKS space id 5931 page no 4 n bits 72 index idxSecondaryId of table test.test trx table locks 1 total table locks 2  trx id 82897 lock_mode X insert intention waiting lock hold time 2 wait time before grant 0

一つロックが増えていますね。これは挿入インテンションギャップロックというやつです。
そしてこれがトランザクション2の取得している idxSecondaryId = 90 に対するネクストキーロックによりブロックされているという状況になります。

そして最後にトランザクション2の方でも insert を実行してみましょう。

Trx2: INSERT INTO test VALUES (90, 90); // ここでTrx2もロックを取得できずに待ち状態となり、Trx1とのデッドロック状態となります
ERROR 1213 (40001): Deadlock found when trying to get lock; try restarting transaction

デッドロックが起こったことが確認できました。

考察

状況を整理して客観的に見たときに、下記のような条件が成り立っています。

  1. 2つのトランザクションがはじめにdelete文により取得したネクストキーロックはお互いのロック領域に重なっていない
  2. その後発行するinsert文が取得しようとする挿入インテンションギャップロックはお互いのネクストキーロックに重なっている

逆にこれが成り立つような状況を想像できればネクストキーロック、挿入インテンションギャップロックが取得しようとするロックの範囲を推測できます。

で自分なりに解釈した結論が下記のようになります

ネクストキーロックについて

ネクストキーロックはインデックス値の前のギャップも取得することもあるが、ギャップを取得しないこともある。つまりこの場合はレコードロックの範囲と等しい
これは具体的には Trx1 の発行する delete文は idxSecondaryId = 80 のレコードロックの範囲に等しく、 Trx2 の発行する delete文は idxSecondaryId = 90 のレコードロックの範囲に等しい

挿入インテンションギャップロックについて

挿入インテンションギャップロックが取得しようとするギャップは、挿入するレコードが該当するギャップに等しい範囲が対象となる。つまりこの場合は末尾のレコードである idxSecondaryId = 40 以降に存在する無限のギャップが対象となる
これは具体的には Trx1, Trx2 の発行する insert文の idxSecondaryId がそれぞれ 80, 90であり、Trx1, Trx2ともに idxSecondaryId = 40 以降のギャップロックを取得しようとする

わかりにくいと思うので図にします。これまた会心の出来です。
矢印はレコードロックを表しています。

fig2

こんな形になるんではなかろうかと。
記事に記載されていること以外にも色々試行錯誤したのですが、すべての結果を説明できるので自分としてはこんな形であろうと解釈しました。
(本当は実装レベルで把握できれば良いんだろうけれども。)

対応

今回の対応としては削除時に主キーのレコードロックのみを取得して削除するような実装に変更しました。

参考

InnoDB のレコード、ギャップ、およびネクストキーロック
InnoDB のロックモード
InnoDB のさまざまな SQL ステートメントで設定されたロック


時間が立つとGoogle APIのOAuth認証に失敗する

概要

Googleが提供するツール。便利ですよね。
公式ではよくG Suitesと呼ばれているスプレッドシートや、ドキュメントなどなどのことを指します。
アプリケーションからG Suitesを操作するためにはOauth認証を利用するのですが、今回はその際時間が立つと認証時にエラーが出てアプリケーションからの操作ができなくなる問題に遭遇したのでまとめておきます。

エラー詳細

今回のアプリケーションはG Suitesの操作をアプリケーションで実行しています。
挙動としてはまずOAuthクライアントを作成したユーザで 認証を行い、アクセストークンを取得します。
その後アクセストークンを用いてG Suitesの操作を行うようなごくごくシンプルなものです。

当初はアプリケーションが正常に動作するのですが、一定時間が経過した上で再度実行するとG Suitesの操作を行う際にトークンが正常でないエラーが発生するような現象が起こりました。

もう少し細かい実装について述べましょう。
今回はgoogle側で用意してくれているjavaのライブラリを使用しています。
かなりライブラリが充実しているので普通に考えてこれを使わない手はありません。

認証には公式ガイドに沿った典型的な実装だと思います。

GoogleAuthorizationCodeFlow を利用して認証しアクセストークンを取得します。
また認証した情報は FileDataStoreFactory を用いてローカルディスクに保存します。
一度認証した後はセッションを発行して、二度目以降は保存したトークンを用いてアプリケーションの処理を行います。

原因

一定時間が経過すると再度実行できなくなるということから、おそらくトークンが期限切れになった際にトークンのリフレッシュができていないんじゃないかと当たりをつけました。
ちょうどはじめに返却されるアクセストークンの生存期間が1時間でしたので、期限が切れたタイミングで実施するとやはり、エラーが再現することが確認できました。
更に認証時に返却される情報をよくよく確認してみると、リフレッシュトークンが返却されていません。
なのでFileDataStoreにはアクセストークンなどは保存はされているんですが、当然リフレッシュトークンがないのでアクセストークンの期限が切れた瞬間に再発行ができずにエラーとなっているようです。

今回はリフレッシュトークンが空っぽいという点に気づくのに時間がかかりました。
あとはデバッグする際にはアプリケーションを再起動して確認していたので、初回のアクセストークンが切れる前に再度アクセストークンが新しいものに変わるんですよね。なのでエラーが出るまでに時間がかかるので気づきにくかったです。

調べてみますとこちらに情報があり、リフレッシュトークンは初回の認証した時点でしか返却されないそうです。
なんですが approval_promt=force を指定することで毎回認可ダイアログに飛び、それによってリフレッシュトークンが返却されるようになります。

いろいろ試してみたところ、途中から認可ダイアログが表示されなくなるユーザ(この場合リフレッシュトークンが帰ってこなくなります)もいれば、ずっと認可ダイアログが開くユーザもおり、正直なところ何を基準にそうなっているのかわかりませんでした。

参考URLのようにパラメータを指定することで強制的に認証ダイアログを表示するなり、シークレットをリセットするなりするのが対応としては良さそうです。

参考

https://stackoverflow.com/questions/10827920/not-receiving-google-oauth-refresh-token


javaアプリケーションのcron起動時の文字化けに対応する

概要

javaアプリケーションの起動を行った際に、ある部分で文字化けが起こったので対応について調査する。

具体的には不具合が起こった箇所はjavaアプリケーションから外部プロセスを起動する部分や、メールを送信する機能の本文にVelocityのテンプレート機能を利用しており、これらを利用する箇所でそれぞれ日本語箇所が文字化けしていた。

原因

まず注目したいのは文字化けが起こっているケースがcronによるバッチからの起動に限定されることである。
バッチとは別にwebプロセスも動作しており、これはfat jarを作成してjavaコマンド経由でbashインタプリタ経由で起動している。が、こちらのwebプロセスは特に問題はない。

また先程メールが文字化けすると述べたが、実は文字化けするのは本文だけで、タイトルに関しては文字化けしていなかった。両者の違いは本文は外部テンプレートファイルから読み込んでいるのに対して、タイトルはソースコードに日本語をハードコーディングしている。

このことから大きく予想できるのはcron経由で外部ファイルを読み込むときに何らかの不具合が生じていることである。
cronはenvなどが特殊なんだろうかと当たりをつけて軽くウェブを検索するとこちらの記事を発見

どうやらcron経由でのコマンドはユーザの環境変数は一切適用されない模様。

解決

わかってしまえばなんてことはない。今回は参考サイトに則ってcrontabの記述の上にenv設定を行うことにします。
今回の場合はjavaがおそらく外部ファイルの文字コードを認識できていないのでcrontabの上部に下記のようにファイルエンコーディングを追記しました。

_JAVA_OPTIONS=-Dfile.encoding=UTF-8

無事にアプリケーションが動きましたとさ


mariadbのcollationをutf8mb4 に対応させる

概要

アプリケーション開発を行っていたところ下記のようなエラーが出た。
この現象について調査する。

Caused by: java.sql.SQLException: Illegal mix of collations (utf8mb4_bin,IMPLICIT) and (utf8_general_ci,COERCIBLE) for operation '='

原因

これは utf8mb8 で作成したテーブル内部に varchar binary のカラムに対して where 条件を指定したときに発現しているようである。

collation の設定を確認したところ下記のようになっている。

MariaDB [(none)]> show variables like '%collation%';
+----------------------+--------------------+
| Variable_name        | Value              |
+----------------------+--------------------+
| collation_connection | utf8_general_ci    |
| collation_database   | utf8_general_ci    |
| collation_server     | utf8_general_ci    |
+----------------------+--------------------+

どうやら mysqld の持っている collation が色々存在して
それとテーブルの照合順序が食い違っているということが原因のようである。
というわけで collation を一致させることで不具合の修正を図る。

対応

この辺を参考にしながら文字コードを設定する。

[client]
default-character-set = utf8mb4

[mysql]
default-character-set = utf8mb4

[mysqld]
character-set-server = utf8mb4
collation-server = utf8mb4_bin

あまりMariaDBの設定には詳しくないが、どうやらMySQLのそれとは多少なり異なるようである。
修正して再度 collation を表示してみると無事に修正された。

MariaDB [(none)]> show variables like '%collation%';
+----------------------+--------------------+
| Variable_name        | Value              |
+----------------------+--------------------+
| collation_connection | utf8mb4_general_ci |
| collation_database   | utf8mb4_bin        |
| collation_server     | utf8mb4_bin        |
+----------------------+--------------------+

アプリケーションの方も無事に動作した。


osx brew で easy_install が正常にインストールされない

概要

python を使用する機会があり、brew経由でインストールを行った。
ついで pip をインストールしようとしたところ下記のようなエラーがでてしまって pip のインストールができない。
これについて対応してみる。

$ easy_install
Traceback (most recent call last):
  File "/usr/local/bin/easy_install", line 9, in <module>
    load_entry_point('setuptools==29.0.1', 'console_scripts', 'easy_install')()
  File "/System/Library/Frameworks/Python.framework/Versions/2.7/Extras/lib/python/pkg_resources.py", line 357, in load_entry_point
    return get_distribution(dist).load_entry_point(group, name)
  File "/System/Library/Frameworks/Python.framework/Versions/2.7/Extras/lib/python/pkg_resources.py", line 2394, in load_entry_point
    return ep.load()
  File "/System/Library/Frameworks/Python.framework/Versions/2.7/Extras/lib/python/pkg_resources.py", line 2108, in load
    entry = __import__(self.module_name, globals(),globals(), ['__name__'])
  File "build/bdist.macosx-10.11-intel/egg/setuptools/__init__.py", line 10, in <module>
  File "build/bdist.macosx-10.11-intel/egg/setuptools/extern/__init__.py", line 1, in <module>
ImportError: No module named extern

調査する

brew を用いてインストールしたのだが、一度消してまた入れてみる

$ brew install python
==&gt; Downloading https://homebrew.bintray.com/bottles/python-2.7.12_2.el_capitan.bottle.tar.gz
Already downloaded: .../Caches/Homebrew/python-2.7.12_2.el_capitan.bottle.tar.gz
==&gt; Pouring python-2.7.12_2.el_capitan.bottle.tar.gz
==&gt; Using the sandbox
Warning: The post-install step did not complete successfully
You can try again using <code>brew postinstall python</code>
==&gt; Caveats
Pip and setuptools have been installed. To update them
  pip install --upgrade pip setuptools

You can install Python packages with
  pip install &lt;package&gt;

They will install into the site-package directory
  /usr/local/lib/python2.7/site-packages

See: https://github.com/Homebrew/brew/blob/master/docs/Homebrew-and-Python.md

.app bundles were installed.
Run <code>brew linkapps python</code> to symlink these to /Applications.
==&gt; Summary
🍺  /usr/local/Cellar/python/2.7.12_2: 2,948 files, 39.8M

すると読み飛ばしていたのだがインストール後の処理が正常に完了していないようなことが表示されていた。

手動で実行してみると

$ brew postinstall python
==> Using the sandbox
Error: Permission denied - /usr/local/lib/python2.7/site-packages/sitecustomize.py20161201-35997-9nuclf

すると権限がないようなことを言われる。これが原因か?

対応

brew は sudo で実行することはできないので(詳しくないができるかも。できても推奨していないが。)
権限で文句を言われている lib/python2.7 に直接一般ユーザでの権限を与える

$ sudo chown -R <user>:<group> /usr/local/lib/python2.7

そして再度後処理を実行してみる

$ brew postinstall python
==> Using the sandbox
==> /usr/local/Cellar/python/2.7.12_2/bin/python -s setup.py --no-user-cfg install --force --verbose
==> /usr/local/Cellar/python/2.7.12_2/bin/python -s setup.py --no-user-cfg install --force --verbose
==> /usr/local/Cellar/python/2.7.12_2/bin/python -s setup.py --no-user-cfg install --force --verbose

原因はよくわからないが動いた。easy_installも動作することが確認できました。
なんてことはありませんでした。


SeleniumのStaleElementReferenceExceptionに対応する

概要

Selenium (javaAPI) を用いてスクレイピングを実施しするような仕組みを作っていたところタイトルにもあるエラーに遭遇した
(そうでなくてもSeleniumはなれるまでなかなかピーキーな動きをするときもあるが)

厄介なことに毎回必ず同じタイミングで発生するわけでもなく、その発生はかなり不定期である。
実施しているスクレピング処理においては、条件を引き起こすページすら一致せずにどのページでもまんべんなく発生する可能性が存在するようである。

今回はその解決方法について調査して実装までを検討する。

調査

まずはスタックトレースを見てみる、関連部分だけを抽出すると概ね下記のようなメッセージが出ている。

Caused by: org.openqa.selenium.StaleElementReferenceException: Element not found in the cache - perhaps the page has changed since it was looked up
Command duration or timeout: 7.64 seconds
For documentation on this error, please visit: http://seleniumhq.org/exceptions/stale_element_reference.html
Build info: version: 'unknown', revision: 'unknown', time: 'unknown'
System info: host: 'something host', ip: 'xxx.xxx.xxx.xxx', os.name: 'Linux', os.arch: 'amd64', os.version: 'something os', java.version: '1.8.0_91'
Driver info: org.openqa.selenium.firefox.FirefoxDriver
Capabilities [{applicationCacheEnabled=true, rotatable=false, pageLoadStrategy=unstable, handlesAlerts=true, databaseEnabled=true, version=42.0, platform=LINUX, nativeEvents=false, acceptSslCerts=true, webStorageEnabled=true, locationContextEnabled=true, browserName=firefox, takesScreenshot=true, javascriptEnabled=true, pageLoadingStrategy=unstable, cssSelectorsEnabled=true}]
Session ID: xxxxxxxxxx

ご丁寧にドキュメントのURLがエラーメッセージに含まれているので、公式ページへアクセスしてみる。

読んでみるとこの例外が発生するパターンは大きく分けて2つ存在するようだ。


参照しているエレメントが削除された場合

大概はこちらのケースに該当するようである。
例えばエレメントの参照を取得した時点から、別ページに移動、その後さらに保持していた参照を引き続き利用しようとした場合や、はたまた何らかのjsライブラリによって保持していたエレメントの参照が別の参照に置き換えられてしまった場合などがある。

この場合例えばid属性などは同じものを保持しているのにもかかわらず、内部的には別のDOMインスタンスとして管理されているため、例えば同じ属性を用いてセレクタを作成し、参照を引っ張ってきたとしても以前参照していたものはなくなってしまったためこのような例外を引き起こす。

エレメントがDOMにアタッチされていない場合

例えばtabを表現するテクニックにDivを予め用意しておいて、実際に表示されるDomは一つだけで他のDomは単純に値を保持するためだけに使用されているような場合、場合によっては他のDivはDOMから参照が保持されていない場合があるようである。
こんなケースは非常にまれでしょう。


その他jsによってエレメントタイプが変更された場合などもこの例外を引き起こす可能性があるようです。
が、どれにしても今回のケースに当てはまっていないように思う。

そのためweb上を検索しほかのサイトを調査していたところ、ページが読み込まれる際に間髪入れずにDOMを検索する際にうまくいかないことがあるようである。
またリトライすることでうまくDOMを検索できるケースもあるようであった。

これらを踏まえて対応を考える。

対応

はっきりとした原因はわからなかったが、おそらく今回のケースはページを移動した直後にDOMを検索することが原因だと予想する。

そのためページを移動した後にwait処理を導入する。またそれと同時にリトライ機構を導入する。

実装

下記の用に実装を行った。概念的なものしか示していないがなんとなくイメージは掴めると思います。
もともとの処理としてはループで色々なページを探索していたので、forの概形だけ残してあります。

変更前

    for( someCondition ) {
        driver.get(url);

        // スクレイピング処理
        someScrape();
    }

変更後

    for ( someCondition ) {
        driver.get(url);

        // StaleElementReferenceException を回避するため、ここで明示的にDOMの読み込みを待つ
        _sleepSec(5);

        for(int count=1; count<=RETRY_COUNT; count++) {
            try {

                // スクレイピング処理
                someScrape();

                break;
            } catch (StaleElementReferenceException e) {
                // StaleElementReferenceException が発生した場合は規定回数内であればリトライを行う
                if (count >= RETRY_COUNT) {
                    throw e;
                }
                _sleepSec(5);
            }
        }
    }

対応したところ、今のところ問題なさそうである。

参考ページ

http://www.software-testing-tutorials-automation.com/2015/02/how-to-handle-stale-element-reference.html
http://blog.afnf.net/blog/69


osxでsshにて公開鍵認証を行っていてkeychainにパスワードを毎回聞かれる際の対応

なんてことはない小ネタですが、備忘録として

対応としては秘密鍵に対応する公開鍵が存在していないことが原因のようです。

keychainの仕様と言ってしまえばそれまでですが、公開鍵を ~/.ssh ディレクトリ内部に保存することで対応できました。

~/.ssh/configを確認したりssh-addを明示的に実行したりといろいろ試しましたがやはり公開鍵がなければ駄目なようです。

公開鍵がないという場合も対向サーバから scp などで持ってきましょう。置くだけで対応できました。


scalikejdbcでmysqlとの通信時のCommunicationsExceptionに対処する

概要

scalaアプリケーションを作成している際に下記のような例外が発生しているケースがありました。

[CommunicationsException: Communications link failure

The last packet successfully received from the server was 15,048 milliseconds ago.  The last packet sent successfully to the server was 10 milliseconds ago.]

今回はこのエラーの原因とその対処についてまとめたいと思います。
ちなみにタイトルにはscalikejdbcと記述してありますが、原因分析についてはmysqlを使用していれば例外なくほぼ同じことが原因であることが多いです。
またアプリケーションについてもscalaといわず、javaを用いていれば同じような対応で解決できます。
(言わずともscalaってjavaのラッパーみたいなものなので)

また私の環境ではscalikejdbcというライブラリを使用したコネクションプールを使っており、検証にそれを用いることとしますし、特にその点については詳しく述べます。

原因

初めに原因だけ端的に記述しておきましょう。
原因としてはアプリケーションが確立したmysqlとの接続、いわゆる「コネクション」が途切れているにもかかわらずアプリケーションではその使えなくなったコネクションを利用してmysqlとの通信をしようとしているからである。

ネットなどで検索するとよくあるのが、一日立ってからアプリケーションが動き出そうとしたタイミングで一回だけ発生する。などの記述が少なくない。

これはアプリケーション(クライアント)が認識しているコネクションの有効性と、mysql(サーバ)が認識しているコネクションの有効性が食い違っているからである。

クライアントでは通常一度作成したコネクションに関してそのまま使い回す。
サーバでは一度作成されたコネクションをいつまでも有効にしていると、新しいクライアントとのコネションを作成する際の邪魔になってしまう。
そのため一定時間アイドル状態(通信が発生していない)であったコネクションをクローズする仕組みが存在する。

そのためサーバ側では閉じたはずのコネクションに対して、クライアントから通信が行われ、結果通信ができずエラーとなるのである。

コネクションプール

さて更にここで掘り下げてコネクションプールを用いている場合にはどうなっているのかということについてより詳しく記述する。
私の環境ではscalikejdbcというライブラリのコネクションプール機能を利用しているが、まあ他のアプリケーションでもコネクションプールを利用している場合はそんなに変わらないでしょう。

コネクションプールとはコネクションを確立する際のコストを減らすため、予め確立しておいたコネクションをすぐに使えるように準備する(プールする、という)仕組みである。

コネクションプールを用いた場合にも先の原因で説明したように全く同じことが言える。
プールされたコネクションは特に読み取り専用のコネクションであれば、一回使用した後もコネクションはクローズされずに何度も使いまわされる。
そして通信がしばらく行われなかった場合、プールされていたコネクションはサーバ側のタイムアウト設定により、使えなくなってしまうのである。

コネクションプールの設定にもよるが、プールされていたコネクションはサーバ側でコネクションが破棄されていたとしてもずっとプールされ続けることがある(というか特に設定しないかぎりは通常だとそうなる)
そのため同様にしばらく(サーバのタイムアウト設定以上)に通信が行われなかった後、再び実行しようとすると同じエラーを引き起こす。

対応

対応としてはいくつかあるが、適切なものとしては通信を行う前にコネクションの検証を行うsqlを発行することで回避できる。
scalikejdbcのような内部でDBCPを利用しているようなコネクションプールであれば、公式にサポートされている機能がある。

設定パラメータに存在するvalidationQueryという項目に適当なsqlを設定する。
例えばselect 1 as oneなど。
そうすることでコネクションを利用する前にその検証クエリを毎回発行するようになり、コネクションが切れていた場合は自動的に再接続を行なってくれるようになる。
コネクションプールを利用していない場合については、自身で実装を工夫する必要がある。

検証

ここまでの話を実装レベルで検証してみよう。

mysqlのタイムアウト値

mysqlの実装におけるコネクションのタイムアウト値はwait_timeoutという項目により設定される。
その項目を確認してみよう

show variables like 'wait_timeout';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| wait_timeout  | 28800 |
+---------------+-------+
1 row in set (0.00 sec)

デフォルトでは28800秒である。これは8時間に値する。
すなわちよくあるケースではアプリケーションが最後にデータベースと通信をおこない、その8時間以上経過してから再度データベースと通信を行うような処理を実行しようとしたところでエラーが発生する、というケースである。

検証する上で流石に8時間も待てないので、この時間を変更する

/etc/my.cnfを編集してタイムアウト時間を更新する
今回は下記のように設定することで10秒に指定した

wait_timeout=10

アプリケーションでエラーが発生することの確認

さて、ここでscalikejdbcを用いたplay scalaアプリケーションにて同エラーが発生することを確認する。
テスト用に作成したアプリケーションを用いることとする。
同じ状況が再現できれば、別にアプリケーションはなんでもよい。

application.conf

コネクションプールを利用するためdefaultという接続子を用いて下記のような設定を行う。

db {
  default.driver=com.mysql.jdbc.Driver
  default.url="jdbc:mysql://localhost/test"
  default.username=user
  default.password=password

  default.poolInitialSize = 10
  default.poolMaxSize = 10
}

アプリケーション

検証のため適当なコントローラに下記のような記述をする。
純粋にループしながらselectを行う。ループ中では15秒のwaitを入れる。

def index = Action {
  scalikejdbc.config.DBs.setupAll()

  var name: Option[String] = None

  (0 to 10).foreach(_ => {
    println("try read")
    name = DB readOnly { implicit session =>
      sql"select name from t order by id desc limit 1".map(rs => rs.string("name")).single().apply()
    }
    println(name)
    Thread.sleep(15000)
  })

  Ok("ok")
}

このアプリケーションを実行すると先のエラーが発生した。
予測はあっているようである。

さらに対応としてvalidationQueryを設定してみる。
scalikejdbcにおけるvalidationQueryの設定は下記のようになる。

db {
  default.driver=com.mysql.jdbc.Driver
  default.url="jdbc:mysql://localhost/test"
  default.username=user
  default.password=password

  default.poolValidationQuery="select 1 as one"
  default.poolInitialSize = 10
  default.poolMaxSize = 10
}

この設定を用いてアプリケーションを実行してみると、今度は無事にエラーが発生しないで実行できる。

またこの際のquery.logを確認してみる

...
2016-05-15T23:36:57.488754Z   71 Query	select 1 as one
2016-05-15T23:36:57.489167Z   71 Query	set session transaction read only
2016-05-15T23:36:57.489512Z   71 Query	SET autocommit=1
2016-05-15T23:36:57.490026Z   71 Query	select name from t order by id desc limit 1
...

目的のsqlの直前にvalidationQueryが存在していることが確認できる。
これによって無事に対応することができた。


mac osx におけるファイルディスクリプタの上限

概要

mac osxでmysql5.7.11を用いてアプリケーション開発を行ったところ、特定の動作をした時点でアプリケーションが動作しなくなる現象に直面した。

mysqlのエラーログを確認してみると下記のようなエラーが出ていることが確認できた。

[Warning] File Descriptor 2032 exceedeed FD_SETSIZE=1024

開発にともなって行った「特定の動作」とはmysqlにおいて、あるテーブルにpartitioningを適用したことである。それも結構な数の。
なるほどmysqlエラーログと合わせてみてみるとその状況は察することができる。
partitioningを切ったことで、物理的に異なるファイルとしてその実態データファイル(InnoDBでいうところのibdファイル)が分離された。
mysql上でそれら実体ファイルをオープンしているfile descriptorがosの上限を上回ったのであろう。

この点について原因の調査と、対応方法をまとめる。

検証

さて、ここでアプリケーション上で起こった問題を再現して、再度その問題が憶測と合っているか検証してみよう。

ここで、sqlを作成する簡単なphpプログラムを用意する。
余談だがやっぱ私の年代となるとスクリプトももっぱらphpだな。

テーブルを作成するsqlを生成するphpコード

下記のコードを実行することで、3000個のパーティショニングを日付で切ったテーブルを作成する
ちなみに、paritioningの最後のところでカンマが一つ多くなるので注意されたし。
そのまま実行する場合は構文エラーになるので手動で削除してください。

<?php
date_default_timezone_set('Asia/Tokyo');

$pivot = strtotime('2010-01-01 00:00:00');
create_partition($pivot);

// create partition ddl
function create_partition($date){
	echo "CREATE TABLE t (id BIGINT auto_increment, name VARCHAR(50), purchased DATE, primary key(id, purchased)) ENGINE=InnoDB DEFAULT charset=utf8 PARTITION BY RANGE COLUMNS(purchased) (";
	for($i=0; $i<3000; $i++) {
		echo "PARTITION p{$i} VALUES LESS THAN ('" . date('Y-m-d', $date) . "')," . PHP_EOL;
		$date = strtotime(date('Y-m-d H:i:s', $date) . " +1 days");
	}
	echo ");";
}

データを挿入するsqlを生成するphpコード

続いて各パーティションにデータを挿入してみる。
下記のコードを実行する。

<?php
date_default_timezone_set('Asia/Tokyo');

$pivot = strtotime('2010-01-01 00:00:00');
create_data($pivot);

// insert data
function create_data($date){
	for($i=0; $i<2999; $i++) {
		echo "INSERT INTO t(name, purchased) VALUES('name{$i}', '" . date('Y-m-d H:i:s', $date) . "');" . PHP_EOL;
		$date = strtotime(date('Y-m-d H:i:s', $date) . " +1 days");
	}
}

そしてその状態で再度mysqlへ接続し、use文を用いてデータベースを選択すると

[Warning] File Descriptor 2032 exceedeed FD_SETSIZE=1024

再現した。

調査

原因は概ね特定できたので、この件について対応方法がないかweb上で検索する。

するとピタリ。こちらのmysqlのバグレポートに全く同じ事象が報告されている。

詳しくは上記のリンクに目を通していただけるとよい。
要約すると osx 固有のバグであり、予想していたように FD_SETSIZE が os の規定値を上回っているためである。
また、するとこの os が持っているファイルディスクリプタの上限値を変更できないのか?
ということを想像するが、残念ながらこれは mac osx で動作している現在の mysql5.7.11 では不可能である。

というのもこちらの github コードを参照してもらうとわかるように osx では FD_SETSIZE 決め打ちで上限を規定している。
これを回避するためには自分でソースコードを改修し、リビルドするしかない。

対応

では、この問題に対応できないのか?というと、そういうわけでもない。
別のアプローチで対処する事が可能である。

問題は mysql がテーブルを参照する際にオープンしている file descriptor の数が多すぎることである。
mysql アプリケーションのパラメータを変更することである程度コントロールすることができる。
具体的には一番大きな影響を与えている、テーブルのキャッシュを数を減らすことである

テーブルエントリのキャッシュ数を変更するには下記の項目を my.cnf に付け加える
数値は上限(osxでは1024)に達しないように調整する。

table_open_cache=400

すると一度オープンしたテーブルの file descriptor を保持しないようになるため、問題を解決できる。
なお、この対応方法はパフォーマンスに大きく影響をあたえる場合もあるので十分注意するべきである。
通常の linux ベースのサーバなどでは file descriptor の上限を上げるなどの対応を合わせて検討するべきである。


mysqlにおけるvarcharのindex使用時の注意

概要

みなさんmysqlを使用していてvarcharのカラムにindexをつけることってないだろうか?
selectする際にindexが付いているカラムを対象にwhereをつけているのにindexが有効になっていない機会があり得る。
今回はそんな時に認識しておかないと、はまるかもしれない挙動について取り上げる。
(そもそもvarcharにindexつけることについてはまた別の機会にでも)

準備

  • テーブル
  • varcharのカラムにindex付いているテーブルを用意

  • 確認方法
  • 確認方法としてはmysqldの設定としてINDEXの効いていないクエリがslowlogに出力されるように設定し、slowlogの出力を確認しながら進める。

    事前確認

    まずは普通にqueryを発行してみる

  • 数値として検索した場合
  • mysql> select count(*) from t1 where column1 = 7395584;
    +----------+
    | count(*) |
    +----------+
    |       37 |
    +----------+
    1 row in set (0.63 sec)
    
    # Time: 150129  5:47:34
    # User@Host: mysql[mysql] @ localhost []
    # Query_time: 0.633334  Lock_time: 0.000088 Rows_sent: 1  Rows_examined: 1264725
    SET timestamp=1422510454;
    select count(*) from t1 where column1 = 7395584;
    
  • 文字列として検索した場合
  • mysql> select count(*) from t1 where column1 = '7395584';
    +----------+
    | count(*) |
    +----------+
    |       37 |
    +----------+
    1 row in set (0.01 sec)
    

    早い。slowlogの出力はなし。

  • explain
  • explainすると数値として検索した場合はいわゆるフルスキャンとなっていることがわかる

    mysql> explain select count(*) from t1 where column1 = 7395584;
    +----+-------------+--------+-------+---------------+------+---------+------+---------+--------------------------+
    | id | select_type | table  | type  | possible_keys | key  | key_len | ref  | rows    | Extra                    |
    +----+-------------+--------+-------+---------------+------+---------+------+---------+--------------------------+
    |  1 | SIMPLE      | t1     | index | idx1          | idx1 | 396     | NULL | 1265625 | Using where; Using index |
    +----+-------------+--------+-------+---------------+------+---------+------+---------+--------------------------+
    1 row in set (0.00 sec)
    
    mysql> explain select count(*) from t1 where column1 = '7395584';
    +----+-------------+--------+------+---------------+------+---------+-------+------+--------------------------+
    | id | select_type | table  | type | possible_keys | key  | key_len | ref   | rows | Extra                    |
    +----+-------------+--------+------+---------------+------+---------+-------+------+--------------------------+
    |  1 | SIMPLE      | t1     | ref  | idx1          | idx1 | 386     | const |   37 | Using where; Using index |
    +----+-------------+--------+------+---------------+------+---------+-------+------+--------------------------+
    1 row in set (0.00 sec)
    

    と、生のmysqlクライアントからの検索は分かった。
    アプリケーションからの実行はどうなるんだろうか。
    使用する機会の多いpdoについて検証してみる。

    アプリケーションレイヤからの検証

  • 生のquery
  • 簡単なphpアプリケーションを作成して、slowlogの出力を見る。

    <?php
    $dns = "mysql:host=localhost;dbname=testdb;charset=utf8";
    $user = "mysql";
    $pass = "pass";
    $pdo = new PDO($dns, $user, $pass);
    
    $stmt = $pdo->query("SELECT count(*) AS cnt FROM t1 WHERE column1 = 7395584");
    $row = $stmt->fetch(PDO::FETCH_ASSOC);
    
    var_dump($row);
    

    出力は下記のようになった。きちんと動作はしている。

    [vagrant@local tmp]$ php select.php 
    array(1) {
      ["cnt"]=>
      string(2) "37"
    }
    

    さてslowlog出力は?

    # Time: 150129  5:55:12
    # User@Host: mysql[mysql] @ localhost []
    # Query_time: 0.242804  Lock_time: 0.000055 Rows_sent: 1  Rows_examined: 1264725
    SET timestamp=1422510912;
    SELECT count(*) AS cnt FROM t1 WHERE column1 = 7395584;
    

    でた!
    これに関してはpdoは特に何もしない。mysqlクライアントから直接クエリを入力した時と同じような結果となった。
    結果は割愛するが、シングルクォートで文字列を囲った時にはslowlogの出力はされなくなった。したがってindexによる検索が有効になっているようである。

    ここで勘の良い人は気になっているかもしれないが、では逆に数値のカラムにINDEXがはられている場合、where句に記述したデータをシングルクォートでくくり文字列として検索した場合どうなるのか。
    ということで気になっているであろうが、これに関して検証した結果どちらでも適切にindexが効くことが確認できた。

  • prepared statement
  • さてprepared statementを利用した場合はどのようになるのか、検証したいと思う。
    pdoにはbindを行うために二種類のインタフェースが存在するが、今回はbindValueを取り上げる。
    マニュアルを確認すると第三引数にバインドするパラメータの方が指定できる。なんとなく今検証していることをの結果を匂わせるようなインタフェースをしている。

    まずは第三引数のことはおいておき、純粋にPHPの型推論による挙動の変化を観察しようではないか。

    初めに数値としてbindValueを実行してアプリケーションを叩いてみる。
    アプリケーションは下記のようになる。

    <?php
    $dns = "mysql:host=localhost;dbname=testdb;charset=utf8";
    $user = "mysql";
    $pass = "pass";
    $pdo = new PDO($dns, $user, $pass);
    
    $sql = "SELECT count(*) AS cnt FROM t1 WHERE column1 = :column1";
    $stmt = $pdo->prepare($sql);
    $stmt->execute(array('column1' => 7395584));
    $row = $stmt->fetch(PDO::FETCH_ASSOC);
    
    var_dump($row);
    

    動作を確認し、結果も正常に取得できている。

    [vagrant@local tmp]$ php select2.php 
    array(1) {
      ["cnt"]=>
      string(2) "37"
    }
    

    さて、肝心なslowlogはどうなっているかというと。
    出ていない!
    prepared statementとbindを利用すると、数値文字列などのギャップはpdo側で吸収してくれるようだ。

    また当然bindの引数の型を文字列に加工したとしてもslowlogは出力されずに、indexが有効になっていることが確認できた。

    これについて思うことは、phpの場合に限って言うとなるべくprepared statementを使用したほうがお馬鹿なミスが減るだろうということだ。
    生のsqlは思ったよりもずっとデリケートなのかもしれない。

    他のアプリケーションに関してもアプリケーションが提供してくれる機能を用いるほうが良いだろう。