Nov 14

symfonyでアプリケーションを作成していた際に、文字コード絡みで面白い事象に遭遇したので記事にすることにしたw

携帯用のWebアプリケーションを作っていたのだが、
Webサーバ側での出力データの文字コードをShift_JISに統一するため、
以下のように全ての文字コードをShift_JIS/cp932に統一して実験してみた。
MySQL(my.cnf)

[client]
default-character-set=cp932
[mysqld]
default-character-set=cp932

現在の設定状況を確認。

mysql> show variables like 'character_set%';
+--------------------------+----------------------------+
| Variable_name            | Value                      |
+--------------------------+----------------------------+
| character_set_client     | cp932                      |
| character_set_connection | cp932                      |
| character_set_database   | cp932                      |
| character_set_filesystem | binary                     |
| character_set_results    | cp932                      |
| character_set_server     | cp932                      |
| character_set_system     | utf8                       |
| character_sets_dir       | /usr/share/mysql/charsets/ |
+--------------------------+----------------------------+

とここで、、、DBドライバmysqliはmy.cnfを読み込む設定が可能だが、DBドライバmysqlは無理ぽい。。。
要するに、クライアント側(symfony/phpアプリケーション)からはmy.cnfは読み込まれない。

php(php.ini)

[mbstring]
mbstring.language = Japanese
mbstring.internal_encoding = SJIS-WIN
mbstring.http_output = SJIS-WIN

symfony

# config/settings.yml(symfony本体、アプリケーション共に)
charset: Shift_JIS
# databases.yml
encoding: cp932

以上の設定を施したが、0×5c問題が気になったので以下のテストを行った。

symfonyで作成したテスト用アプリケーションで「ソ」一文字を登録。
結果は失敗。
ということでsymfonyが使用しているO/Rマッパや
データベースドライバについて調べてみた。
symfonyはデフォルトではPropelというO/Rマッパを用い、
CreoleというDB接続モジュールでDBドライバに”mysql”を利用している。
ということで、CreoleのDBドライバ:mysqlにおける MySQL接続クラス(MySQLConnection.php)を確認してみた。

if ($encoding) {
    $this->executeUpdate("SET NAMES " . $encoding);
}

むむ、発見。
ここでdatabases.ymlに設定した文字コードを指定している。
SET NAMESクエリを発行している。
試しにここをphpの標準関数mysql_set_charset()に置き換えてみた。

if ($encoding) {
    mysql_set_charset($encoding);
}

再度「ソ」一文字登録テスト。
お!成功!!
しかし何故??
ということでMySQLのクエリログを確認

# 失敗: $this->executeUpdate("SET NAMES " . $encoding);
081114 19:30:21      22 Connect     db_test@localhost on
                     22 Init DB     db_test
                     22 Init DB     db_test
                     22 Query       SET NAMES cp932
                     22 Query       SET AUTOCOMMIT=0
                     22 Query       BEGIN
                     22 Init DB     db_test
                     22 Query       INSERT INTO table_test (TITLE,CREATED_AT,UPDATED_AT) VALUES ('ソ\','2008-11-14 20:27:42','2008-11-14 20:27:42')
                     22 Init DB     db_test
                     22 Query       ROLLBACK
                     22 Query       SET AUTOCOMMIT=1
                     22 Quit

# 成功: mysql_set_charset($encoding);
081114 19:30:48      23 Connect     db_test@localhost on
                     23 Init DB     db_test
                     23 Query       SET NAMES cp932
                     23 Query       SET AUTOCOMMIT=0
                     23 Query       BEGIN
                     23 Init DB     db_test
                     23 Query       INSERT INTO table_test (TITLE,CREATED_AT,UPDATED_AT) VALUES ('ソ','2008-11-14 20:28:09','2008-11-14 20:28:09')
                     23 Init DB     db_test
                     23 Query       COMMIT
                     23 Query       SET AUTOCOMMIT=1

# 失敗: mysql_query("SET NAMES " . $encoding);
081114 19:39:12      27 Connect     db_test@localhost on
                     27 Init DB     db_test
                     27 Query       SET NAMES cp932
                     27 Query       SET AUTOCOMMIT=0
                     27 Query       BEGIN
                     27 Init DB     db_test
                     27 Query       INSERT INTO table_test (TITLE,CREATED_AT,UPDATED_AT) VALUES ('ソ\','2008-11-14 20:36:33','2008-11-14 20:36:33')
                     27 Init DB     db_test
                     27 Query       ROLLBACK
                     27 Query       SET AUTOCOMMIT=1

ン?
成功/失敗時のクエリを確認すると、文字コード指定部分は全く同じである。
なんと、違いはMySQLサーバがデータを受け取った時点で異なることがわかった。
では、php標準関数mysql_set_charset()では何をしているのか?
phpのソースコード(php_mysql.c)を追ってみた。

PHP_FUNCTION(mysql_set_charset)
{
	zval *mysql_link = NULL;
	char *csname;
	int id = -1, csname_len;
	php_mysql_conn *mysql;

	if (zend_parse_parameters(ZEND_NUM_ARGS() TSRMLS_CC, "s|r", &csname, &csname_len, &mysql_link) == FAILURE) {
		return;
	}

	if (ZEND_NUM_ARGS() == 1) {
		id = php_mysql_get_default_link(INTERNAL_FUNCTION_PARAM_PASSTHRU);
		CHECK_LINK(id);
	}

	ZEND_FETCH_RESOURCE2(mysql, php_mysql_conn *, &mysql_link, id, "MySQL-Link", le_link, le_plink);

	if (!mysql_set_character_set(&mysql->conn, csname)) {
		RETURN_TRUE;
	} else {
		RETURN_FALSE;
	}
}

おっと、mysql_set_character_set()関数を使用している。
これはMySQLモジュール、libmysqlの関数である。
では、このmysql_set_character_set()では何をしているのか?
MySQLのソースコードに内包されているlibmysqldのclient.cを確認

int STDCALL mysql_set_character_set(MYSQL *mysql, const char *cs_name)
{
  struct charset_info_st *cs;
  const char *save_csdir= charsets_dir;

  if (mysql->options.charset_dir)
    charsets_dir= mysql->options.charset_dir;

  if (strlen(cs_name) < MY_CS_NAME_SIZE &&
     (cs= get_charset_by_csname(cs_name, MY_CS_PRIMARY, MYF(0))))
  {
    char buff[MY_CS_NAME_SIZE + 10];
    charsets_dir= save_csdir;
    /* Skip execution of "SET NAMES" for pre-4.1 servers */
    if (mysql_get_server_version(mysql) < 40100)
      return 0;
    sprintf(buff, "SET NAMES %s", cs_name);
    if (!mysql_real_query(mysql, buff, strlen(buff)))
    {
      mysql->charset= cs;
    }
  }
  else
  {
    char cs_dir_name[FN_REFLEN];
    get_charsets_dir(cs_dir_name);
    mysql->net.last_errno= CR_CANT_READ_CHARSET;
    strmov(mysql->net.sqlstate, unknown_sqlstate);
    my_snprintf(mysql->net.last_error, sizeof(mysql->net.last_error) - 1,
		ER(mysql->net.last_errno), cs_name, cs_dir_name);

  }
  charsets_dir= save_csdir;
  return mysql->net.last_errno;
}

ぉお!

sprintf(buff, "SET NAMES %s", cs_name);
if (!mysql_real_query(mysql, buff, strlen(buff)))
{
    mysql->charset= cs;
}

これだ!
SET NAMESクエリを発行した後で
クライアント側のmysqlコネクションオブジェクトに文字コードをセットしている。

ただ単にSET NAMESクエリを発行するのとphpのmysql_set_charset()にて文字コードを指定するのとでは
この違いがあった。

いくらsymfonyやphpの設定をShift_JISにしても、MySQLクライアント(DBドライバmysql)がShift_JISで無ければ0×5cの2バイト目の5c(\)を2バイト目の5cと認識できず、単にエスケープ文字としてエスケープしてしまう。しかし、MySQLサーバ側はShift_JIS(cp932)で設定されているため2バイト目の5cを2バイト目と認識し、クライアントが付加した5cが余分なエスケープとなってクエリがシンタックスエラーとなる。
Shift_JISの「ソ」を「835c」と表現して以下に当問題の一連の流れを書く。

■ symfony/php
insert into table values '835c';
■ mysql(MySQLクライアント)
# 835cの2バイト目をエスケープ(5c付加)してしまう
# 83 + ここに5cを付加 + 5c ⇒ 835c5c
insert into table values '835c5c';
■ MySQLサーバ
# 835cまでを「ソ」と認識し、残りの5cが余計なエスケープとなり、
# 閉じクオートがエスケープされる。('ソ\')
insert into table values '835c5c';

mysqliなら、my.cnfを読み込むことも可能なのでこの様な事象に遭遇することは少ないのかもしれない。

ん~phpでDBドライバにmysqlを使用する、またはそのような環境においてShift_JISを利用したい場合は
mysql_set_charset()で文字コードを設定するべきですね。

Oct 31

先輩のamo-kさんから、「Symfonyのトランザクション処理時の動作について調べてみて」と言われたので、Symfonyの勉強がてら調べてみました。

Synfony のログからわかること

まず Symfony のログを見てみると、begin -> begin -> category テーブルの update -> commit -> begin -> begin -> bookmark テーブルの update -> commit -> commit という処理の流れになっています。

アクションで明示的に記述したトランザクションとは別に、$category->save では1重、$bookmark->save では2重のトランザクションが走っているように見えます。

モデルクラスの中身を見てみる

$bookmark と $category はそれぞれ Symfony のスクリプトによって自動生成されたモデルクラスである BookMark と Category のインスタンスです。

Bookmark と Category はそれぞれ BaseBookmark と BaseCategory を継承しており、実際の更新処理はこれらのベースクラスに記述されています。

save関数の中でもトランザクションが使われています。

BaseBookmark と BaseCategory の save 関数内に以下のような記述があります。

// BaseBookmark::save 関数の一部(BaseBookmark.php)、BaseCategory::save (BaseCategory.php)も同様
$con->begin();
$affectedRows = $this->doSave($con);
$con->commit();
return $affectedRows;

これを見てわかるとおり、 save 関数内でも $con->begin() ~ $con->commit() によって、トランザクション処理を行っています。

doSave 関数の中では、このインスタンスが新規のレコードなのか、レコードの更新なのかを判定し、新規であれば Peer クラスの doInsert を、更新であれば doUpdate を呼び出すようになっています。

以下、該当部分のソースコード。

// BaseBookmark::doSave 関数の一部(BaseBookmark.php)
  if ($this->isNew()) {
    $pk = BookmarkPeer::doInsert($this, $con);
    $affectedRows += 1;
    $this->setId($pk);
    $this->setNew(false);
  } else {
    $affectedRows += CategoryPeer::doUpdate($this, $con);
  }

doInsert 関数と doUpdate 関数は BookmarkPeer の親クラスである BaseBookmarkPeer クラスで定義されていています。

doInsert関数の中では、以下のように $con->begin() でトランザクションを開始したあと、BasePeer クラスの doInsert 関数を呼び出しています。これが、 $bookmark->save() を実行したときの、最も深い begin ~ commit の正体です。

// BaseBookmarkPeer::doInsert 関数の一部(BaseBookmark.php)
  try {
    $con->begin();
    $pk = BasePeer::doInsert($criteria, $con);
    $con->commit();
  } catch(PropelException $e) {
    $con->rollback();
    throw $e;
  }

なお、doUpdate 関数内ではトランザクションをかけていません。アクション内で記述していた $category->save() はすでにあるレコードの更新操作なので doUpdate が実行され、該当部分のトランザクションは2重までになります。

コネクションオブジェクトに対する関数呼び出しのログ出力処理

アプリケーションをデバッグモードで実行しているときは $con は sfDebugConnection というクラスのインスタンスになっていて、各モデルクラスはこのインスタンスを通して、DB操作を行うようになっています。

このクラスはsymfonyで提供されているもので、コネクションオブジェクトに対して実行された処理のログをとっています。例えば、commit 関数なら以下のようになっています。

 // sfDebugConnection.php から抜粋
  public function commit()
  {
    $this->log("{sfCreole} committing transaction.");
    return $this->childConnection->commit();
  }

関数が呼び出されると無条件にログ出力が行われます。そのため、今回のようにコネクションオブジェクトに対して最大で3重のトランザクションをかけている場合は、ログにもそのように出力されるわけです。

その次に $this->childConnection の同名の関数を呼び出すという処理になっています。
$this->childConnection は実際に使われているDBに応じた、Connectionインタフェースを実装したドライバになります。今回はMySQLを使用しているので、MySQLConnectionというクラスになっています。

MySQLConnection は ConnectionCommon というクラスを継承しています。DBの実装に関係なくコネクションで共通の処理が ConnectionCommon に記述されています。

begin関数、commit関数はConnectionCommonで以下のように定義されています。

// sfConnectionCommon.php から抜粋
    public function begin()
    {
        if ($this->transactionOpcount === 0 || $this->supportsNestedTrans()) {
            $this->beginTrans();
        }
        $this->transactionOpcount++;
    }

    public function commit()
    {
        if ($this->transactionOpcount > 0) {
            if ($this->transactionOpcount == 1 || $this->supportsNestedTrans()) {
                $this->commitTrans();
            }
            $this->transactionOpcount--;
        }
    }

begin関数で transactionOpcount を +1 し、commit関数で -1 するようになっています。

ここで supportNestedTrans 関数はDBがトランザクションの入れ子をサポートしている場合にtrueを返します。今回使用しているMySQLはトランザクションの入れ子をサポートしないので、この関数は false を返します。

ConnectionCommon のサブクラスで beginTrans および commitTrans 関数がオーバーライドされ、実際のトランザクション開始~コミット処理を行っています。

この部分の処理で、MySQLのようにトランザクションの入れ子をサポートしていないDBを使用している場合は最も外側のトランザクションのみが有効になることがわかります。

以上の処理をシーケンス図にすると、以下のようになります。



トランザクション処理時のシーケンス(拡大画像へリンク)

と、ここまでわかったところで、この記事を発見。まさに知りたかったことが書いてあるじゃないか・・・。

まあ、もう少し詳細にコードを追っているので、本記事も参考になるのではないでしょうか。

Oct 31

Symfony(phpのフレームワーク)にて気になる部分があったので若手ホープのhonda-hに調査してもらった。
※データベースはMySQL5、InnoDBを利用。

気になった部分
以下のコードサンプルのように
明示的にトランザクション処理を行ったとする。
Symfonyのログを見ると何故か4回づつbeginやcommitが行われたように
sfCreoleのログが出力されている。
これでは、以下のコードサンプルの更新2の部分で
エラーとなった場合に更新1も含めてロールバックしてほしいのに
更新1はコミットされたように見える。
しかし、SQLログを見るとサンプルコードで期待する結果となっている。
(begin ⇒ 更新1⇒ 更新2 ⇒ commit)

コードサンプル:

    // 実際はもう少し処理をしているがコアな部分以外は割愛する
...
    $bookmark = new Bookmark();
    $bookmark->setTitle($this->getRequestParameter('title'));
    $bookmark->setUrl($this->getRequestParameter('url'));

    if ($this->getRequestParameter('category_id'))
    {
        $bookmark->setCategoryId($this->getRequestParameter('category_id'));
        $category = CategoryPeer::retrieveByPk($this->getRequestParameter('category_id'));
        $category->incrementSize();
    }

    $con = Propel::getConnection();  // DBコネクションオブジェクト取得

    try
    {
        $con->begin();  // トランザクション開始
        if ($this->getRequestParameter('category_id'))
        {
            $this->logMessage('{sfAction} save category.', 'info');
            $category->save($con);  // 更新1
        }

        $this->logMessage('{sfAction} save bookmark.', 'info');
        $bookmark->save($con);  // 更新2

        $this->logMessage('{sfAction} commit transaction.', 'info');
        $con->commit();  // コミット
    }
    catch (Exception $e)
    {
        $con->rollback();  // ロールバック
...

Symfonyログサンプル

Oct 28 11:29:51 symfony [info] {sfCreole} prepareStatement(): SELECT category.ID, category.TITLE, category.SIZE FROM category WHERE category.ID=?
Oct 28 11:29:51 symfony [info] {sfCreole} executeQuery(): [0.47 ms] SELECT category.ID, category.TITLE, category.SIZE FROM category WHERE category.ID=5
Oct 28 11:29:51 symfony [info] {sfCreole} connect(): DSN: array (   'compat_assoc_lower' => NULL,   'compat_rtrim_string' => NULL,   'database' => 'criteria_test',   'encoding' => 'cp932',   'hostspec' => 'localhost',   'password' => 'criteria_test',   'persistent' => NULL,   'phptype' => 'mysql',   'port' => NULL,   'protocol' => NULL,   'socket' => NULL,   'username' => 'criteria_test', ), FLAGS: 0
Oct 28 11:29:51 symfony [info] {sfCreole} beginning transaction.
Oct 28 11:29:51 symfony [info] {sfAction} save category.
Oct 28 11:29:51 symfony [info] {sfCreole} beginning transaction.
Oct 28 11:29:51 symfony [info] {sfCreole} prepareStatement(): UPDATE category SET SIZE = ? WHERE category.ID=?
Oct 28 11:29:51 symfony [info] {sfCreole} executeUpdate(): UPDATE category SET SIZE = 5 WHERE category.ID=5
Oct 28 11:29:51 symfony [info] {sfCreole} committing transaction.
Oct 28 11:29:51 symfony [info] {sfAction} save bookmark.
Oct 28 11:29:51 symfony [info] {sfCreole} beginning transaction.
Oct 28 11:29:51 symfony [info] {sfCreole} beginning transaction.
Oct 28 11:29:51 symfony [info] {sfCreole} prepareStatement(): INSERT INTO bookmark (CATEGORY_ID,TITLE,URL,CREATED_AT,UPDATED_AT) VALUES (?,?,?,?,?)
Oct 28 11:29:51 symfony [info] {sfCreole} executeUpdate(): INSERT INTO bookmark (CATEGORY_ID,TITLE,URL,CREATED_AT,UPDATED_AT) VALUES (5,'koreha hidoi','http://korea.hidoi/','2008-10-28 11:29:51','2008-10-28 11:29:51')
Oct 28 11:29:51 symfony [info] {sfCreole} committing transaction.
Oct 28 11:29:51 symfony [info] {sfCreole} committing transaction.
Oct 28 11:29:51 symfony [info] {sfAction} commit transaction.
Oct 28 11:29:51 symfony [info] {sfCreole} committing transaction.

SQLログサンプル:

# at 3946
#081028 11:29:51 server id 1  end_log_pos 4023 	Query	thread_id=47	exec_time=0	error_code=0
SET TIMESTAMP=1225160991/*!*/;
BEGIN
/*!*/;
# at 4023
#081028 11:29:51 server id 1  end_log_pos 4143 	Query	thread_id=47	exec_time=0	error_code=0
SET TIMESTAMP=1225160991/*!*/;
UPDATE category SET SIZE = 5 WHERE category.ID=5
/*!*/;
# at 4143
#081028 11:29:51 server id 1  end_log_pos 4171 	Intvar
SET INSERT_ID=40/*!*/;
# at 4171
#081028 11:29:51 server id 1  end_log_pos 4401 	Query	thread_id=47	exec_time=0	error_code=0
SET TIMESTAMP=1225160991/*!*/;
INSERT INTO bookmark (CATEGORY_ID,TITLE,URL,CREATED_AT,UPDATED_AT) VALUES (5,'koreha hidoi','http://koreha.hidoi/','2008-10-28 11:29:51','2008-10-28 11:29:51')
/*!*/;
# at 4401
#081028 11:29:51 server id 1  end_log_pos 4428 	Xid = 334
COMMIT/*!*/;
DELIMITER ;

ということで、honda-hの調査結果を次に書きます。
ではhonnda-h、あとはよろしく~
調査結果