serposcopeのエラー

2018年10月17日

serposcopeについての全投稿は/tag/serposcopeにあるので参照されたい

問題発生

なぜか突然、ブラウザ上に以下のようなエラーを表示して動作しなくなってしまった。バージョンは2.8.0である。

Oops. An error occurred.

Please contact support if error persists.

/var/log/serposcopeの中のログを見てみると、以下の表示

[2018-10-16 22:40:56,515] [qtp1720435669-10] WARN  o.e.j.s.ServletHandler - /
java.lang.RuntimeException: javax.crypto.BadPaddingException: Given final block not properly padded. Such issues can arise if a bad key is used during decryption.
    at ninja.utils.CookieEncryption.decrypt(CookieEncryption.java:139) ~[serposcope-2.8.0.jar:na]
    at ninja.session.SessionImpl.init(SessionImpl.java:117) ~[serposcope-2.8.0.jar:na]
    at ninja.utils.AbstractContext.init(AbstractContext.java:95) ~[serposcope-2.8.0.jar:na]
    at ninja.servlet.NinjaServletContext.init(NinjaServletContext.java:128) ~[serposcope-2.8.0.jar:na]
    at ninja.servlet.NinjaServletDispatcher.service(NinjaServletDispatcher.java:82) ~[serposcope-2.8.0.jar:na]
    at com.google.inject.servlet.ServletDefinition.doServiceImpl(ServletDefinition.java:287) ~[serposcope-2.8.0.jar:na]
    at com.google.inject.servlet.ServletDefinition.doService(ServletDefinition.java:277) ~[serposcope-2.8.0.jar:na]
    at com.google.inject.servlet.ServletDefinition.service(ServletDefinition.java:182) ~[serposcope-2.8.0.jar:na]
    at com.google.inject.servlet.ManagedServletPipeline.service(ManagedServletPipeline.java:91) ~[serposcope-2.8.0.jar:na]
    at com.google.inject.servlet.ManagedFilterPipeline.dispatch(ManagedFilterPipeline.java:119) ~[serposcope-2.8.0.jar:na]
    at com.google.inject.servlet.GuiceFilter$1.call(GuiceFilter.java:133) ~[serposcope-2.8.0.jar:na]
    at com.google.inject.servlet.GuiceFilter$1.call(GuiceFilter.java:130) ~[serposcope-2.8.0.jar:na]
    at com.google.inject.servlet.GuiceFilter$Context.call(GuiceFilter.java:203) ~[serposcope-2.8.0.jar:na]
    at com.google.inject.servlet.GuiceFilter.doFilter(GuiceFilter.java:130) ~[serposcope-2.8.0.jar:na]
    at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1652) ~[serposcope-2.8.0.jar:na]
    at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:585) [serposcope-2.8.0.jar:na]
    at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1127) [serposcope-2.8.0.jar:na]
    at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:515) [serposcope-2.8.0.jar:na]
    at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1061) [serposcope-2.8.0.jar:na]
    at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) [serposcope-2.8.0.jar:na]
    at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97) [serposcope-2.8.0.jar:na]
    at org.eclipse.jetty.server.Server.handle(Server.java:497) [serposcope-2.8.0.jar:na]
    at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:310) [serposcope-2.8.0.jar:na]
    at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:257) [serposcope-2.8.0.jar:na]
    at org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:540) [serposcope-2.8.0.jar:na]
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:635) [serposcope-2.8.0.jar:na]
    at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:555) [serposcope-2.8.0.jar:na]
    at java.lang.Thread.run(Unknown Source) [na:1.8.0_181]
Caused by: javax.crypto.BadPaddingException: Given final block not properly padded. Such issues can arise if a bad key is used during decryption.
    at com.sun.crypto.provider.CipherCore.doFinal(CipherCore.java:991) ~[sunjce_provider.jar:1.8.0_171]
    at com.sun.crypto.provider.CipherCore.doFinal(CipherCore.java:847) ~[sunjce_provider.jar:1.8.0_171]
    at com.sun.crypto.provider.AESCipher.engineDoFinal(AESCipher.java:446) ~[sunjce_provider.jar:1.8.0_171]
    at javax.crypto.Cipher.doFinal(Cipher.java:2164) ~[na:1.8.0_171]
    at ninja.utils.CookieEncryption.decrypt(CookieEncryption.java:129) ~[serposcope-2.8.0.jar:na]
    ... 27 common frames omitted
[2018-10-16 22:40:56,523] [qtp1720435669-10] ERROR n.s.NinjaJetty$SilentErrorHandler - An error occurred that cannot be handled by Ninja null. Responsing with default error page.

何やら暗号解除にてエラーが発生しているらしいのだが、当然何がおかしいかは不明。

最新版にする

とりあえず、2.10.0の最新版にしてみる–>全く同じエラー

データベースを新たにする

別のmysqlデータベースを作成し、それを使わせるようにすると正常に動作する。

原因らしきもの

おそらくこれが原因だろう。https://github.com/ninjaframework/ninja/issues/605およびhttps://github.com/ninjaframework/ninja/issues/532

Javaのバージョンを変更したことがいけなかったらしい。何かしらセッションクッキーの暗号化が変わってしまうらしい。

ではセッションクッキーを削除してしまえば問題は解決するのだろうか？

データベースを元に戻し、セッションクッキーを削除する

と思い、データベーステーブルを調べてみるが、それらしきフィールドが無し。

設定ファイルに「serposcope.db.debug=true」を追加し、以前のデータベースに戻して起動してみると、何事もなかったように起動する。

再度、「serposcope.db.debug=true」を削除して再度起動してみても問題無し。

結局どこが悪いのか不明。

技術メモserposcope

Posted by ysugimura