Servlet3.0+RequestDumpFilterでMergedWebXMLの大量のログ出力

Java Tomcat SAStruts

Tomcat7+SAStrutsでJava Webアプリケーション構築をしています。
主にセキュリティ関連のパラメータ追加の兼ね合いでweb.xmlをServlet2.4からServlet3.0にしてみました。
すると、SAStrutsでの入出力パラメータをログ出力するRequestDumpFilterで、mergedWebXMLのコンテキスト設定値が大量にログ出力されるようになってしまいました。

あまりにも大量過ぎてログを追うのが出来ないレベルだったので対処法を探してみました。

調べたところ、以下のツイートを見つけました。

ただし、これ以外の有効な情報が見つからず。

そんなわけで、リプで聞いてみました。

web-appタグにmetadata-complete="true"を付けることでweb.xmlのマージを抑止、ログ出力もなくなる、、とのことでしたが、相変わらずログが出てしまいます。

諦めてRequestDumpFilterを独自拡張しよう…とRequestDumpFilterのソース()を眺めたところ、beforeContextAttribute/afterContextAttribute初期化パラメータでコンテキストのログ出力有無を制御できることがわかりました。
とりあえずこれにfalseにすることで対処。

S2JDBC-GenでSQLServerのvarbinary(max)の扱いにはまった

S2JDBC MSSQL

遅ればせながら、S2JDBC-Genをお試ししてみました。
gen-ddlでDDLやdumpとれる！便利！とかやってたらmigrateでエラー発生。
db/migrate/0001/010-table配下のDDLファイルの、varbinary(max)の列がvarbinary(2147483647)で出力されてました。

gen-entityで生成されたEntityの対象カラムにBlobアノテーションをつけたら解決。

ちなみに、SQLServer 2008R2の場合、dialectはmssqlDialectとmssql2005Dialectどっちがいいんだろう。とりあえずmssql2005Dialect使ってます。

コマンドラインでメール送信

tips

メール送信失敗の障害解析で、Windowsコマンドプロンプトからメール送信する機会があったのでメモ。
下記の記事を参考にやってみました。

コマンドプロンプトだけでメールを送信する | WindowsServer管理者への道

参考記事では、こちらで打つコマンドとサーバからの応答がごっちゃになっていたので、コマンドだけを抜き出してみました。

telnet SMTPサーバIPアドレス 25

helo 自ホスト名

mail from:<送信元メールアドレス>

rcpt to:<送信先メールアドレス>

data
From:送信元メールアドレス
To:送信先メールアドレス
Subject:件名

メール本文
.

quit

なお、「quit」まで実行するとメール送信される。
「data」~「.」までを入力したところで「メール送信されない！」と一瞬騒いでしまったのはココだけの話。

play! framework 1.2.5のTwitter-OAuthサンプルでエラー

playframework

play! framework 1.2.5のtwitter-oauthサンプルを動かしてみたが、以下のエラーが発生した。

Error connecting to twitter: OAuth.Error: NOT_AUTHORIZED - Authorization failed (server replied with a 401). This can happen if the consumer key was not correct or the signatures did not match.

エラー内容を基にconsumer keyとconsumer secretを確認したが、どちらもTwitter Applicationで生成したものと同じ値を設定していた。

原因その1: OAuthのURL誤り

サンプルソースのTwitter OAuth URLに古いもの？が設定されていた。
なお、play!2系のサンプルでは修正されていた。


Application.java
変更前

    private static final ServiceInfo TWITTER = new ServiceInfo(
            "http://twitter.com/oauth/request_token",
            "http://twitter.com/oauth/access_token",
            "http://twitter.com/oauth/authorize",
            "consumer key",
            "consumer secret"
    );

変更後

    private static final ServiceInfo TWITTER = new ServiceInfo(
            "https://api.twitter.com/oauth/request_token",
            "https://api.twitter.com/oauth/access_token",
            "https://api.twitter.com/oauth/authorize",
            "consumer key",
            "consumer secret"
    );

原因その2: Callback URLの設定漏れ

こちらは私の設定漏れ。Twitter ApplicationのCallback URLに、「http://<自IPアドレス>:9000/auth」を設定する必要がある。

以下のページを参考に設定した。
Playframework2とScalaでTwitter APIを操作する - えんたつの記録

logbackでJavaシステムプロパティを利用する

Java logback

logbackでJavaシステムプロパティを参照するには、「${propname}」といった表記を使用する。同様の表記で環境変数も参照できる。

コマンドライン

java -Dlog.home=/path/to/log ClassName

logback.xml

<property name="LOG_HOME" value="${log.home}" />

なお、Javaシステムプロパティが存在しなかった場合、「propname_IS_UNDEFINED」をいう値が設定される。

変数のデフォルト値設定

Javaシステムプロパティが設定されていなかった時のデフォルト値を定義するためには、「${propname:-defaultValue}」といった表記を使用する。

logback.xml

<property name="LOG_HOME" value="${log.home:-/default/log}" />


なお、デフォルト値を変数にする場合、${propname:-${defaultpropname}}のように書くらしいのだがデフォルト値の変数がうまく展開されない…

参考

logback Configuration default Values For Variables

LinuxサーバからOracle JDBC接続するとEnd of TNS data channelやConnection resetが発生する場合の対処法

Linux Java Oracle

事象

LinuxのAPサーバ上に配置したJavaバッチプログラムからOracle DBへJDBC接続しようとするとDBコネクション取得時にエラーが出ることがあった。
体感的には、何度かバッチ起動終了を繰り返すとDBコネクション取得にかかる時間がどんどん遅くなっていき、最終的に繋がらなくなる。

DB接続部分はいつもどおりのやり方。

Class.forName("oracle.jdbc.driver.OracleDriver");
 Connection con = DriverManager.getConnection("jdbc:oracle:thin:@host:1521:sid", user, pass);

共有サーバ接続だと以下のエラー

java.sql.SQLException: IO Error: End of TNS data channel
at oracle.jdbc.driver.T4CConnection.logon(T4CConnection.java:458)
at oracle.jdbc.driver.PhysicalConnection.(PhysicalConnection.java:546)
at oracle.jdbc.driver.T4CConnection.(T4CConnection.java:236)
at oracle.jdbc.driver.T4CDriverExtension.getConnection(T4CDriverExtension.java:32)
at oracle.jdbc.driver.OracleDriver.connect(OracleDriver.java:521)
at java.sql.DriverManager.getConnection(DriverManager.java:525)
at java.sql.DriverManager.getConnection(DriverManager.java:171)
at ...
Caused by: oracle.net.ns.NetException: End of TNS data channel
at oracle.net.ns.NetInputStream.getNextPacket(NetInputStream.java:308)
at oracle.net.ns.NetInputStream.read(NetInputStream.java:260)
at oracle.net.ns.NetInputStream.read(NetInputStream.java:185)
at oracle.net.ns.NetInputStream.read(NetInputStream.java:102)
at oracle.jdbc.driver.T4CSocketInputStreamWrapper.readNextPacket(T4CSocketInputStreamWrapper.java:124)
at oracle.jdbc.driver.T4CSocketInputStreamWrapper.read(T4CSocketInputStreamWrapper.java:80)
at oracle.jdbc.driver.T4CMAREngine.unmarshalUB1(T4CMAREngine.java:1137)
at oracle.jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:290)
at oracle.jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:192)
at oracle.jdbc.driver.T4CTTIoauthenticate.doOSESSKEY(T4CTTIoauthenticate.java:404)
at oracle.jdbc.driver.T4CConnection.logon(T4CConnection.java:385)
... 9 more

専用サーバ接続だと以下のエラー

java.sql.SQLException: IO Error: Connection reset
at oracle.jdbc.driver.T4CConnection.logon(T4CConnection.java:467)
at oracle.jdbc.driver.PhysicalConnection.(PhysicalConnection.java:546)
at oracle.jdbc.driver.T4CConnection.(T4CConnection.java:236)
at oracle.jdbc.driver.T4CDriverExtension.getConnection(T4CDriverExtension.java:32)
at oracle.jdbc.driver.OracleDriver.connect(OracleDriver.java:521)
at java.sql.DriverManager.getConnection(DriverManager.java:525)
at java.sql.DriverManager.getConnection(DriverManager.java:171)
at ...
Caused by: java.net.SocketException: Connection reset
at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:96)
at java.net.SocketOutputStream.write(SocketOutputStream.java:136)
at oracle.net.ns.DataPacket.send(DataPacket.java:210)
at oracle.net.ns.NetOutputStream.flush(NetOutputStream.java:230)
at oracle.net.ns.NetInputStream.getNextPacket(NetInputStream.java:312)
at oracle.net.ns.NetInputStream.read(NetInputStream.java:260)
at oracle.net.ns.NetInputStream.read(NetInputStream.java:185)
at oracle.net.ns.NetInputStream.read(NetInputStream.java:102)
at oracle.jdbc.driver.T4CSocketInputStreamWrapper.readNextPacket(T4CSocketInputStreamWrapper.java:124)
at oracle.jdbc.driver.T4CSocketInputStreamWrapper.read(T4CSocketInputStreamWrapper.java:80)
at oracle.jdbc.driver.T4CMAREngine.unmarshalUB1(T4CMAREngine.java:1137)
at oracle.jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:290)
at oracle.jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:192)
at oracle.jdbc.driver.T4CTTIoauthenticate.doOSESSKEY(T4CTTIoauthenticate.java:404)
at oracle.jdbc.driver.T4CConnection.logon(T4CConnection.java:385)
... 9 more

sqlplusでのDB接続は問題なし。
End of TNS data channelで調べたところ「OracleDBとOracle JDBCドライバのバージョンが不一致の場合に発生」といった情報はあったが、バージョンを一致させても改善せず。

バッチが固まったときにスレッドダンプを取得。その内容がこちら。

kill -3
...
"main" prio=1 tid=0x00000000599cadd0 nid=0x31a8 runnable [0x00007fff03644000..0x00007fff03645c60]
at java.io.FileInputStream.readBytes(Native Method)
at java.io.FileInputStream.read(FileInputStream.java:194)
at java.io.BufferedInputStream.read1(BufferedInputStream.java:254)
at java.io.BufferedInputStream.read(BufferedInputStream.java:313)
- locked <0x00002abece792fd0> (a java.io.BufferedInputStream)
at java.io.BufferedInputStream.fill(BufferedInputStream.java:218)
at java.io.BufferedInputStream.read1(BufferedInputStream.java:256)
at java.io.BufferedInputStream.read(BufferedInputStream.java:313)
- locked <0x00002abece792ce8> (a java.io.BufferedInputStream)
at sun.security.provider.SeedGenerator$URLSeedGenerator.getSeedByte(SeedGenerator.java:452)
at sun.security.provider.SeedGenerator.getSeedBytes(SeedGenerator.java:122)
at sun.security.provider.SeedGenerator.generateSeed(SeedGenerator.java:117)
at sun.security.provider.SecureRandom.engineGenerateSeed(SecureRandom.java:114)
at sun.security.provider.SecureRandom.engineNextBytes(SecureRandom.java:171)
- locked <0x00002abece792778> (a sun.security.provider.SecureRandom)
at java.security.SecureRandom.nextBytes(SecureRandom.java:413)
- locked <0x00002abece792b08> (a java.security.SecureRandom)
at oracle.security.o5logon.O5Logon.a(Unknown Source)
at oracle.security.o5logon.O5Logon.(Unknown Source)
at oracle.jdbc.driver.T4CTTIoauthenticate.(T4CTTIoauthenticate.java:566)
at oracle.jdbc.driver.T4CConnection.logon(T4CConnection.java:370)
at oracle.jdbc.driver.PhysicalConnection.(PhysicalConnection.java:546)
at oracle.jdbc.driver.T4CConnection.(T4CConnection.java:236)
at oracle.jdbc.driver.T4CDriverExtension.getConnection(T4CDriverExtension.java:32)
at oracle.jdbc.driver.OracleDriver.connect(OracleDriver.java:521)
at java.sql.DriverManager.getConnection(DriverManager.java:525)
- locked <0x00002abe9df21a10> (a java.lang.Class)
at java.sql.DriverManager.getConnection(DriverManager.java:171)
- locked <0x00002abe9df21a10> (a java.lang.Class)
at ...

原因

DBコネクション取得時にOracleJDBCドライバ内から呼び出しているSecureRandomでのシード生成で時間がかかることがあり、一定時間以上かかるとOracleDBサーバはクライアントの操作タイムアウトとして通信を切断してしまう。

シード生成で時間がかかるのはLinuxサーバの場合のみ発生、Windowsでは発生しない。

上記のスレッドダンプを基に、SecureRandomでのシード生成の関連で調べてみると、以下のサイトがヒットした。

SecureRandom で処理が約20秒停止 - QA@IT
Bug ID: JDK-6202721 SHA1PRNG reads from /dev/random even if /dev/urandom selected

対処

Bug ID: JDK-6202721 SHA1PRNG reads from /dev/random even if /dev/urandom selected の、ワークアラウンドにあった方法で試したところ改善した。

Javaの実行時引数に「-Djava.security.egd=file:/dev/./urandom」を追加。

ちなみに、「-Djava.security.egd=file:/dev/urandom」ではうまくいかない。
サイトを見ればわかるのだが、明らかにJavaのバグなのに、「ワークアラウンドがあるので問題ではない」という回答でクローズしている。かなり強引(笑

終わりに

問題発見からこの対処に行き着くまで2週間かかった。他の仕事が立て込んでたというのもあるけど。
スレッドダンプ取ってからはするすると解決の方向に向かっていったので、固まる事象にはスレッドダンプさまさまだなあと思った。

ORA-01502: 索引'string.string'またはそのパーティションが使用不可の状態です。

Oracle

あるメンバが、「間違ってSQL*Loaderで同じデータを2回入れちゃってPKが壊れちゃった！」とすがりついてきたので調べてみた。

DELETE FROM <TABLE_NAME> WHERE PK_COLUMN1 = 'XX'; 
ORA-01502: 索引'TABLE_PK'またはそのパーティションが使用不可の状態です。

早速調べてみると、以下の参考ページに行き着いた。
[Oracle] 再作成したテーブルにアクセスするとORA-01502エラーが発生する。｜Archive Redo Blog

確かに対象のインデックスはUNUSABLEになっているが、既にPK重複のデータが入ってしまっているのでインデックス再構築は失敗する。
従って、PK削除、問題データ削除、PK追加で復旧させた。

ALTER TABLE <TABLE_NAME> DROP CONSTRAINT <TABLE_PK>;
DELETE FROM <TABLE_NAME> WHERE PK_COLUMN1 = 'XX';
ALTER TABLE <TABLE_NAME> ADD CONSTRAINT <TABLE_PK> PRIMARY KEY (<PK_COLUMN1>, <PK_COLUMN2>);