intra-martで謎の起動失敗

概要

ある日突然それまで平和だったintra-martが死に、起動時に謎のjava.lang.RuntimeException: resource: iwp/platform/schema/exists_table.sql is not found.が発生するようになり、解決した記録です。

環境

intra-mart AccelPlatform 2015 Summer
Oracle 11g Release 2

調査

intra-mart

exception

intra-martを触っていると稀によくある起動時のexceptionです。
公式にも出るくらいメジャーなエラーですが、原因はDBです！としか分かりません。

11.15.4.1. Web Application Server 起動後にログインができない（データベースに接続できない）場合 — intra-mart Accel Platform セットアップガイド   第31版 2020-04-01

log.generating.time=Tue Jul 14 17:42:31 JST 2020
log.level=WARN
log.logger.name=com.caucho.server.webapp.WebApp
log.id=5iwjzz8cqc7mu
log.thread.id=resin-port-8080-76
log.thread.group=main
log.message=java.lang.RuntimeException: resource: iwp/platform/schema/exists_table.sql is not found.

java.lang.RuntimeException: resource: iwp/platform/schema/exists_table.sql is not found.
	at jp.co.intra_mart.mirage.SqlManagerImpl.prepareNode(SqlManagerImpl.java:143)
	at jp.co.intra_mart.mirage.SqlManagerImpl.getSingleResult(SqlManagerImpl.java:218)
	at jp.co.intra_mart.mirage.ext.IntramartSqlManager.getSingleResult(IntramartSqlManager.java:39)
	at jp.co.intra_mart.mirage.SqlManagerImpl.getSingleResult(SqlManagerImpl.java:214)
	at jp.co.intra_mart.system.service.provider.updater.dao.ImSchemaUpdateDAO.existsTable(ImSchemaUpdateDAO.java:34)
	at jp.co.intra_mart.system.service.provider.updater.AbstractSchemaUpdater.update(AbstractSchemaUpdater.java:67)
	at jp.co.intra_mart.system.service.provider.updater.SystemDatabaseUpdater.update(SystemDatabaseUpdater.java:21)
	at jp.co.intra_mart.system.service.impl.ServiceControllerImpl.startCoordinator(ServiceControllerImpl.java:185)
	at jp.co.intra_mart.system.service.impl.ServiceControllerImpl.accept(ServiceControllerImpl.java:654)
	at jp.co.intra_mart.system.service.impl.ServiceControllerImpl.start(ServiceControllerImpl.java:126)
	at jp.co.intra_mart.foundation.service.ServiceController.start(ServiceController.java:49)
	at jp.co.intra_mart.system.servlet.PlatformServletContextListener.contextInitialized(PlatformServletContextListener.java:124)
	at com.caucho.server.webapp.WebApp.addListenerObject(WebApp.java:2154)
	at com.caucho.server.webapp.WebApp.callInitializers(WebApp.java:3483)
	at com.caucho.server.webapp.WebApp.startImpl(WebApp.java:3788)
	at com.caucho.server.webapp.WebApp.access$700(WebApp.java:208)
	at com.caucho.server.webapp.WebApp$StartupTask.run(WebApp.java:5318)
	at com.caucho.env.thread2.ResinThread2.runTasks(ResinThread2.java:173)
	at com.caucho.env.thread2.ResinThread2.run(ResinThread2.java:118)

調べてみると、ある時を境に大量のジョブ実行時エラーが発生していることが発覚。内容的にもデータベースのコネクション取得時にネットワークアダプタでエラーが発生している。原因はこれっぽい。

log.generating.time=Sat Jul 11 20:54:29 JST 2020
log.level=ERROR
log.logger.name=jp.co.intra_mart.system.job_scheduler.quartz.JobStoreMirageSession
log.id=9861206c-c10c-4599-ab66-8d17ef060e0f
log.thread.id=QuartzScheduler_intra-mart-intra-martAPP:192.168.243.78:5200_ClusterManager
log.thread.group=main
log.message=ClusterManager: Error managing cluster: [E.IWP.DATABASE.00013] コネクション取得時に想定外のエラーが発生しました。

org.quartz.JobPersistenceException: [E.IWP.DATABASE.00013] コネクション取得時に想定外のエラーが発生しました。 [See nested exception: jp.co.intra_mart.foundation.database.exception.DatabaseException: [E.IWP.DATABASE.00013] コネクション取得時に想定外のエラーが発生しました。]
	at jp.co.intra_mart.system.job_scheduler.quartz.JobStoreMirageSession.getConnection(JobStoreMirageSession.java:82)
	at jp.co.intra_mart.system.job_scheduler.quartz.JobStoreMirageSession.getNonManagedTXConnection(JobStoreMirageSession.java:92)
	at org.quartz.impl.jdbcjobstore.JobStoreSupport.doCheckin(JobStoreSupport.java:3232)
	at org.quartz.impl.jdbcjobstore.JobStoreSupport$ClusterManager.manage(JobStoreSupport.java:3857)
	at org.quartz.impl.jdbcjobstore.JobStoreSupport$ClusterManager.run(JobStoreSupport.java:3894)
Caused by: jp.co.intra_mart.foundation.database.exception.DatabaseException: [E.IWP.DATABASE.00013] コネクション取得時に想定外のエラーが発生しました。
	at jp.co.intra_mart.system.database.SystemDatabase.getConnection(SystemDatabase.java:63)
	at jp.co.intra_mart.system.job_scheduler.quartz.JobStoreMirageSession.getConnection(JobStoreMirageSession.java:80)
	... 4 more
Caused by: java.sql.SQLRecoverableException: IOエラー: The Network Adapter could not establish the connection
	at oracle.jdbc.driver.T4CConnection.logon(T4CConnection.java:489)
	at oracle.jdbc.driver.PhysicalConnection.<init>(PhysicalConnection.java:553)
	at oracle.jdbc.driver.T4CConnection.<init>(T4CConnection.java:254)
	at oracle.jdbc.driver.T4CDriverExtension.getConnection(T4CDriverExtension.java:32)
	at oracle.jdbc.driver.OracleDriver.connect(OracleDriver.java:528)
	at com.caucho.sql.DriverConfig.createDriverConnection(DriverConfig.java:709)
	at com.caucho.sql.ManagedConnectionImpl.initDriverConnection(ManagedConnectionImpl.java:277)
	at com.caucho.sql.ManagedConnectionImpl.<init>(ManagedConnectionImpl.java:147)
	at com.caucho.sql.ManagedFactoryImpl.createManagedConnection(ManagedFactoryImpl.java:153)
	at com.caucho.env.dbpool.ConnectionPool.createConnection(ConnectionPool.java:1006)
	at com.caucho.env.dbpool.ConnectionPool.allocatePoolConnection(ConnectionPool.java:848)
	at com.caucho.env.dbpool.ConnectionPool.allocateConnection(ConnectionPool.java:740)
	at com.caucho.env.dbpool.ConnectionPool.allocateConnection(ConnectionPool.java:714)
	at com.caucho.sql.UserDataSource.getConnection(UserDataSource.java:75)
	at com.caucho.sql.DBPool.getConnection(DBPool.java:822)
	at jp.co.intra_mart.system.database.DatabaseAccessorImpl.getConnection(DatabaseAccessorImpl.java:56)
	at jp.co.intra_mart.system.database.SystemDatabase.getConnection(SystemDatabase.java:55)
	... 5 more
Caused by: oracle.net.ns.NetException: The Network Adapter could not establish the connection
	at oracle.net.nt.ConnStrategy.execute(ConnStrategy.java:439)
	at oracle.net.resolver.AddrResolution.resolveAndExecute(AddrResolution.java:454)
	at oracle.net.ns.NSProtocol.establishConnection(NSProtocol.java:693)
	at oracle.net.ns.NSProtocol.connect(NSProtocol.java:251)
	at oracle.jdbc.driver.T4CConnection.connect(T4CConnection.java:1140)
	at oracle.jdbc.driver.T4CConnection.logon(T4CConnection.java:340)
	... 21 more
Caused by: java.net.ConnectException: Connection refused: connect
	at java.net.DualStackPlainSocketImpl.waitForConnect(Native Method)
	at java.net.DualStackPlainSocketImpl.socketConnect(DualStackPlainSocketImpl.java:85)
	at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350)
	at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206)
	at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)
	at java.net.PlainSocketImpl.connect(PlainSocketImpl.java:172)
	at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
	at java.net.Socket.connect(Socket.java:589)
	at oracle.net.nt.TcpNTAdapter.connect(TcpNTAdapter.java:149)
	at oracle.net.nt.ConnOption.connect(ConnOption.java:133)
	at oracle.net.nt.ConnStrategy.execute(ConnStrategy.java:405)
	... 26 more

Oracle

ローカルからDBeaverでの接続もできなくなっていました。
エラー内容は、IOエラー: The Network Adapter could not establish the connection。
リスナーがうまく起動していないっぽい。

リスナー

サーバ上でlsnrctl statusを実行したところ、やたら待たされた挙句……

(DESCRIPTION=(ADDRESS=(PROTOCOL=IPC)(KEY=EXTPROC1521)))に接続中
TNS-01153: 文字列: PPの処理に失敗しました。

※PPの部分は文字化けしています。

！！！？？？
なんじゃこりゃ！？

リスナーの状態すら取得できないとはどういうこと？
tnsnames.oraやlistener.oraも調べましたが、特に問題なし。というかこないだまで普通に動いてたし。

ログ

本記事の環境はOracle 11gです。
各種ログの格納場所は11g以降変更になっています。

参考
リスナーログの格納場所が11gから異なる ｜ Oracle使いのネタ帳
[Oracle] listener.log、sqlnet.logはどこへ消えた？ | Archive Redo Blog

というか今更11g以前使っている方が珍しいか。

%diagnostic_dest%/diag/rdbms/%database%/%sid%/trace/alert_%sid%.log

***********************************************************************

Fatal NI connect error 12570, connecting to:
 (LOCAL=NO)

  VERSION INFORMATION:
	TNS for 64-bit Windows: Version 11.2.0.1.0 - Production
	Oracle Bequeath NT Protocol Adapter for 64-bit Windows: Version 11.2.0.1.0 - Production
	Windows NT TCP/IP NT Protocol Adapter for 64-bit Windows: Version 11.2.0.1.0 - Production
  Time: 14-7月 -2020 08:16:16
  Tracing not turned on.
  Tns error struct:
    ns main err code: 12570
    
TNS-12570: TNS: パケット・リーダーに障害が発生しました。
    ns secondary err code: 12560
    nt main err code: 0
    nt secondary err code: 0
    nt OS err code: 0
opiodr aborting process unknown ospid (3964) as a result of ORA-609
Tue Jul 14 08:16:36 2020


***********************************************************************

Fatal NI connect error 12537, connecting to:
 (LOCAL=NO)

  VERSION INFORMATION:
	TNS for 64-bit Windows: Version 11.2.0.1.0 - Production
	Oracle Bequeath NT Protocol Adapter for 64-bit Windows: Version 11.2.0.1.0 - Production
	Windows NT TCP/IP NT Protocol Adapter for 64-bit Windows: Version 11.2.0.1.0 - Production
  Time: 14-7月 -2020 08:16:36
  Tracing not turned on.
  Tns error struct:
    ns main err code: 12537
    
TNS-12537: TNS: 接続がクローズされました。
    ns secondary err code: 12560
    nt main err code: 0
    nt secondary err code: 0
    nt OS err code: 0
opiodr aborting process unknown ospid (5860) as a result of ORA-609
Tue Jul 14 08:17:06 2020

あとは接続が「クローズされました」を延々と繰り返すだけでした。

%dbhome%/NETWORK/log/sqlnet.log

***********************************************************************
Fatal NI connect error 12541, connecting to:
 (DESCRIPTION=(ADDRESS=(PROTOCOL=TCP)(HOST=NDSPC5145)(PORT=1521))(CONNECT_DATA=(SID=iaptst)(CID=(PROGRAM=C:\app\Administrator\product\11.2.0\dbhome_1\bin\emagent.exe)(HOST=NDSPC5145)(USER=SYSTEM))))

  VERSION INFORMATION:
	TNS for 64-bit Windows: Version 11.2.0.1.0 - Production
	Windows NT TCP/IP NT Protocol Adapter for 64-bit Windows: Version 11.2.0.1.0 - Production
  Time: 14-7月 -2020 17:01:51
  Tracing not turned on.
  Tns error struct:
    ns main err code: 12541
    TNS-12541: TNS: リスナーがありません。
    ns secondary err code: 12560
    nt main err code: 511
    TNS-00511: リスナーがありません。
    nt secondary err code: 61
    nt OS err code: 0

やっぱりリスナーがないって言われてますね。でもあるんですよ。。。

%dbhome%/log/%host%/client/clcs.log

2020-07-14 17:02:33.653: [ default][1520]ut_read_reg:2:ocr registry key SOFTWARE\Oracle\olr cannot be opened. error 2
[    CLSE][1520]clse_get_crs_home: Error retrieving OLR configuration [0] [Error opening olr registry key. 指定されたファイルが見つかりません。
]

レジストリキーが見つからない……何だこの謎のエラーは。
と思ってぐーぐる先生に聞いてみたところ、以下のページがヒット。

oracle11g - After working for years, all of a sudden TNS listener not working today

完全に状況が同じ。

結論

We were able to finally figure it out. The listener log file had gotten too large and the listener wouldn't start properly. Thanks Oracle for great error messages that don't help at all lol

訳

ようやくわかったよ。リスナーログファイルが大きくなりすぎて、リスナーが正しく起動してなかった。完全に糞の役にも立たない素晴らしいエラーメッセージについて、Oracleに感謝。lol

対処

サービスからOracleOraDb11g_home1TNSListenerを停止し、以下のファイルを.bakにリネーム。

%diagnostic_dest%/diag/tnslsnr/%host%/%listener%/trace/listener.log

ちなみに、サイズは4GBを超えていました。。。
サービスを再起動してlsnrctl statusを再実行すると、無事に結果が返ってきました。
もちろん、intra-martも無事に起動してめでたしめでたし。

余談

再起動が終わったintra-martに接続したところ、ライセンス切れのエラーが出ていました。
これが原因かどうかは、今のところ特定する手段がないので不明です。

参考

障害発生時の対処法など、フローチャートにまとまっていて分かりやすかったです。
今回は、おもくそ「リスナーログの肥大化」が原因だったというお話。

もっと早く見たかった。

Oracle Databaseのリスナーログ、接続障害発生時にどこを見るか：Oracleサポート出張所（5） - ＠IT