はじめに
この記事では、REST APIを実行するサービス接続の実行時に連携先システムで障害が発生した際にどのような動作なるかを確認した結果をまとめてみました。
この記事は次の記事の内容を理解していることを前提としています。
なお、この記事ではシステム障害を意図的に発生させるために、JSON Serverを利用します。JSON Serverとは、簡単にモックAPI（モックサーバー）を構築できるオープンソースのNode.jsツールで、主にフロントエンド開発やAPIのプロトタイピング、テスト用途で使われています。
光の速さでJSON Serverを導入する
次のようにコマンドを実行してJSON Serverを起動します。
$ curl -fsSL https://rpm.nodesource.com/setup_lts.x | sudo bash -
$ sudo yum install -y nodejs
$ sudo npm install -g json-server
$ cat << ___EOF___ > db.json
> {
> "posts": [
> { "id": 1, "title": "Hello World" }
> ],
> "comments": [
> { "id": 1, "body": "Nice post!" }
> ]
> }
> ___EOF___
$ json-server --watch db.json
--watch/-w can be omitted, JSON Server 1+ watches for file changes by default
JSON Server started on PORT :3000
Press CTRL-C to stop
Watching db.json...
♡( ◡‿◡ )
Index:
http://localhost:3000/
Static files:
Serving ./public directory if it exists
Endpoints:
http://localhost:3000/posts
http://localhost:3000/comments
コマンド json-server 実行時の出力にあるように次のエンドポイントが作成されています。
何ということでしょう、ホスト名の部分を適当に変えてブラウザからアクセスすると、光の速さでJSONのレスポンスが得られる動作を確認できます(参照できるデータはdb.jsonにて定義した内容、そしてJSON ServerはGETだけでなくPOSTもできたりと優れもの)。
今回は、このJSON Serverをハングさせたり、Killしたりした時の動作を見てゆきます。
動作確認用のCAIプロセスを作成して実行する
詳細な手順の紹介は割愛しますが、次の手順にて動作確認用のCAIプロセスを作成します。
- JSON Serverにアクセスするサービス接続を作成する
- 作成したサービス接続より、アプリケーション接続を作成する
- CAIプロセスにて作成したアプリケーション接続を利用する
作成したCAIプロセスをcurlコマンドで実行してエラーが発生しない動作を確認します。
(実行結果が正常に取得できずとも、エラーが発生していなければ今回はOKです！)
curlコマンドと実行結果
// curl コマンド
curl https://localhost:7443/process-engine/public/rt/recipe-psa-svcConnJsonServer
// 実行結果
{"out":{"id":1,"title":"Hello World"}}
JSON Serverをハングさせた場合の動作を確認する
REST APIのエンドポイントをハングさせる
コマンド kill -s SIGSTOP `pgrep -f json-server`を実行してREST APIのエンドポイントであるJSON Serverをハング状態にしてCAIプロセスを実行します。この状態で10分程放置して、どのような動作が起こるのかを確認してみましょう。
なお、ハングさせたJSON Serverは kill -s SIGCONT `pgrep -f json-server` により処理を再開できます。
ハング中にコマンドラインで観察する
10分待っている間、時間がもったいないですのでLinuxコマンドやJDKのコマンドラインツールで色々確認してみることにします。
netstatコマンドで通信先ポート(3000)を利用しているプロセスを確認する
$ netstat -lanput | grep 3000
(Not all processes could be identified, non-owned process info
will not be shown, you would have to be root to see it all.)
tcp6 0 0 10.65.133.33:58928 10.65.133.34:3000 ESTABLISHED 1745211/java
netstatコマンドからは、Javaのプロセス(PID=1745211)が、JSON Serverと接続している様子が見えました。
PID=1745211 を対象にpsコマンドで起動時のコマンドラインを確認する
$ ps aux | grep 1745211
infaUSW5 1745211 1.0 4.2 7429604 1382920 ? Sl Dec04 8:41 /opt/infaUSW5/infaagent/apps/jdk/zulu8.86.0.26-sa-fx-jdk8.0.452/jre/bin/java -Dnop -Dnop -ea -esa -showversion -Dorg.apache.el.parser.SKIP_IDENTIFIER_CHECK=true -Djava.security.auth.login.config=/opt/infaUSW5/infaagent/apps/process-engine/15124581.26.2/conf/login.config -Djavax.xml.transform.TransformerFactory=org.activebpel.rt.util.AeTransformerFactory -Ddtm.path=/opt/infaUSW5/infaagent/apps/process-engine/15124581.26.2/plugins -DUseExplicitClassLoaderJDBC=true -Xms516M -Xmx1536M -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/opt/infaUSW5/infaagent/apps/process-engine/15124581.26.2/../logs/ -Xloggc:/opt/infaUSW5/infaagent/apps/process-engine/15124581.26.2/../logs/gc.log -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=10 -XX:GCLogFileSize=5M -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps -Dfile.encoding=UTF-8 -Dcom.sun.org.apache.xml.internal.security.resource.config=/com/sun/org/apache/xml/internal/security/resource/config.xml -Dwebapp.context.allowLinking=true -Dhost.name=invgcsjcsa01.informatica.com -Dkey.alias=invgcsjcsa01.informatica.com -Dmaster.url=https://dm-us.informaticacloud.com -Dapp.server.security.config.file=/opt/infaUSW5/infaagent/apps/process-engine/15124581.26.2/conf/security.properties -Dshutdown.port=7005 -Djdk.tls.ephemeralDHKeySize=2048 -Djdk.tls.client.protocols=TLSv1.2 -Dmail.smtps.ssl.protocols=TLSv1.3 TLSv1.2 -Dmail.smtp.ssl.protocols=TLSv1.3 TLSv1.2 -Dpe.db.username=bpeluser -Dpe.db.password=MKKqH3ijSJBGDyekE+VMDg== -Dpe.db.port=5432 -Dpe.db.embedded.mode=true -Dpe.db.logUsername=bpeluser -Dpe.db.logPassword=MKKqH3ijSJBGDyekE+VMDg== -Dpe.ldap.password=mh8d/khcffn+vZQ+b3GdMw== -Dsecure.channel.port=14801 -Dsecure.channel.connectionTimeout=120000 -Dsecure.channel.maxThreads=600 -Dapp.keystore.path=/opt/infaUSW5/infaagent/apps/process-engine/15124581.26.2/.lcm/app-keystore.jks -Dapp.keystore.pass=SIqYbngr57UyyvhowF9k8dm2g2VoWReBXoBLuNOX3Gg= -Dapp.truststore.path=/opt/infaUSW5/infaagent/apps/process-engine/15124581.26.2/.lcm/app-truststore.jks -Dapp.truststore.pass=fQmeMQnqYG+0pmFUY/9RA4dc9LyCtRCTDVojBfPj1Ko= -Dhttp.port=7080 -Dhttp.connectionTimeout=120000 -Dhttp.maxThreads=600 -Dhttps.port=7443 -Dhttps.connectionTimeout=120000 -Dhttps.maxThreads=600 -Dcom.amazonaws.services.s3.enableV4=true -DINFA_PLUGINS_HOME=/opt/infaUSW5/infaagent/apps/process-engine/15124581.26.2/cci-connectors/plugins -DCCI_HOME=/opt/infaUSW5/infaagent/apps/process-engine/15124581.26.2/cci-connectors -DCCI_NEXT_HOME=/opt/infaUSW5/infaagent/apps/process-engine/15124581.26.2/cci-connectors -DADAPTER_HOME=/opt/infaUSW5/infaagent/apps/process-engine/15124581.26.2/cci-connectors/connectors -Dlog4j2.formatMsgNoLookups=true -Dlog4j.configurationFile=/opt/infaUSW5/infaagent/apps/process-engine/15124581.26.2/conf/log4j2.xml -Djava.util.logging.manager=org.apache.logging.log4j.jul.LogManager -javaagent:/opt/infaUSW5/infaagent/apps/process-engine/15124581.26.2/aspectj-weaver/aspectjweaver-1.9.9.1.jar -Dae.saxon.access.allow.env.var=true -Dae.saxon.access.allow.filesystem=true -Dcamel.repo.dir=/opt/infaUSW5/infaagent/apps/process-engine/15124581.26.2/../data/camel -Dlib.XMLTransformerFactory=/opt/infaUSW5/infaagent/apps/process-engine/15124581.26.2/shared/xq1.0/*.jar -Dlib.xq1.0=/opt/infaUSW5/infaagent/apps/process-engine/15124581.26.2/shared/xq1.0/*.jar -Dlib.xq3.1=/opt/infaUSW5/infaagent/apps/process-engine/15124581.26.2/shared/xq3.1/*.jar -Dlib.xq3.1_10=/opt/infaUSW5/infaagent/apps/process-engine/15124581.26.2/shared/xq3.1_10/*.jar -Djdk.tls.ephemeralDHKeySize=2048 -Djava.protocol.handler.pkgs=org.apache.catalina.webresources -Dsun.io.useCanonCaches=false -Dorg.apache.catalina.security.SecurityListener.UMASK=0027 -Dignore.endorsed.dirs= -classpath :/opt/infaUSW5/infaagent/apps/process-engine/15124581.26.2/lib/log4j-jul-2.17.1.jar:/opt/infaUSW5/infaagent/apps/process-engine/15124581.26.2/lib/log4j-api-2.17.1.jar:/opt/infaUSW5/infaagent/apps/process-engine/15124581.26.2/lib/log4j-core-2.17.1.jar:/opt/infaUSW5/infaagent/apps/process-engine/15124581.26.2/apache-tomcat-9.0.108/bin/bootstrap.jar:/opt/infaUSW5/infaagent/apps/process-engine/15124581.26.2/apache-tomcat-9.0.108/bin/tomcat-juli.jar -Dcatalina.base=/opt/infaUSW5/infaagent/apps/process-engine/15124581.26.2 -Dcatalina.home=/opt/infaUSW5/infaagent/apps/process-engine/15124581.26.2/apache-tomcat-9.0.108 -Djava.io.tmpdir=/opt/infaUSW5/infaagent/apps/process-engine/15124581.26.2/temp org.apache.catalina.startup.Bootstrap start
psコマンドからはprocess engineのサービスを実行しているjavaのプロセスがbootstrapというjarファイルを利用している様子が見えました。
PID=1745211 を対象にjpsコマンドにより起動しているjavaのプロセスを確認する
$ jps | grep 1745211
1745211 Bootstrap
jpsコマンドではprocess engineのサービスを実行しているjavaのプセスがBootstrapと名付けられている様子が見えました。
PID=1745211 を対象にjstackを実行して眺めてみる
$ jstack -l `pgrep -f bootstrap`
2025-12-05 10:35:31
Full thread dump OpenJDK 64-Bit Server VM (25.452-b09 mixed mode):
...略
"QueueManagerWorkManager-WorkerThread-10" #52 prio=5 os_prio=0 tid=0x00007fe5a1e3a000 nid=0x1aa219 runnable [0x00007fe52923c000]
java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
at java.net.SocketInputStream.read(SocketInputStream.java:171)
at java.net.SocketInputStream.read(SocketInputStream.java:141)
at org.apache.http.impl.io.SessionInputBufferImpl.streamRead(SessionInputBufferImpl.java:137)
at org.apache.http.impl.io.SessionInputBufferImpl.fillBuffer(SessionInputBufferImpl.java:153)
at org.apache.http.impl.io.SessionInputBufferImpl.readLine(SessionInputBufferImpl.java:280)
at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:138)
at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:56)
at org.apache.http.impl.io.AbstractMessageParser.parse(AbstractMessageParser.java:259)
at org.apache.http.impl.DefaultBHttpClientConnection.receiveResponseHeader(DefaultBHttpClientConnection.java:163)
at org.apache.http.impl.conn.CPoolProxy.receiveResponseHeader(CPoolProxy.java:157)
at org.apache.http.protocol.HttpRequestExecutor.doReceiveResponse(HttpRequestExecutor.java:273)
at org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:125)
at org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:272)
at org.apache.http.impl.execchain.ProtocolExec.execute(ProtocolExec.java:186)
at org.apache.http.impl.execchain.RetryExec.execute(RetryExec.java:89)
at org.apache.http.impl.execchain.RedirectExec.execute(RedirectExec.java:110)
at org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:185)
at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:83)
at org.activebpel.rt.http.AeHttpClient.execute(AeHttpClient.java:107)
at org.activebpel.rt.http.AeHttpSendHandlerBase.deliver(AeHttpSendHandlerBase.java:98)
at org.activebpel.rt.http.handler.AeHttpGetHandler.handle(AeHttpGetHandler.java:34)
at org.activebpel.rt.http.AeHttpServiceManager.send(AeHttpServiceManager.java:169)
...略
非常に多くのスレッド情報が出力されますが、ネットワーク待ちとみられるスレッドは上記の出力のみでした。ソケット読み込みで待っている状況です。Apache HTTP Clientを使って通信をしている様子がみえました。
という確認をしているうちに、ちょうど10分にて実行していたCAIプロセスがエラー Read timed out で終了している動作を確認できました。
curlコマンドと実行結果
// curl コマンド
curl https://localhost:7443/process-engine/public/rt/recipe-psa-svcConnJsonServer
// 実行結果
{"error":{"code":500,"detail":{"reason":"Read timed out","code":"HTTP_500"},"message":"Read timed out"}}
どうやら、10分でタイムアウトする動作設定の様です。
タイムアウトするまでの設定を変更する
タイムアウトのような動作は アプリケーション統合コンソール の画面から設定を変更できる場合があります。10分(=600秒)の設定がされているプロパティは2つあるようです。
各プロパティの値を変更しながら確認したところ Webサービス呼び出しタイムアウト の設定により Read timed out が発生するまでの時間を制御できることを確認できました。
process engineのログを確認する
ディレクトリ SAインストール先/apps/process-engine/logs に出力されているカタリナログを確認するとjstackで確認していたstackと同じstackでCAIプロセス(ID=21011)においてRead timed outが発生している動作を確認できました。
catalina.2025-12-04.log
05-Dec-2025 10:38:49.803 IST ERROR [QueueManagerWorkManager-WorkerThread-10] [AeException] [{X_INFA_LOG_CTX=req_id=f233fc7589504e82b270aea293135be8, mdc.process.id=21011, mdc.process.initiator=anonymous, mdc.process.name={http://com.activevos.socrates.repository.services/businessConnection}businessConnectionAutomatedStep, mdc.tenant.id=$public}] - Error delivering request targeted for URI: http://invgcsjcsa02.informatica.com:3000/posts/1
java.net.SocketTimeoutException: Read timed out
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
at java.net.SocketInputStream.read(SocketInputStream.java:171)
at java.net.SocketInputStream.read(SocketInputStream.java:141)
at org.apache.http.impl.io.SessionInputBufferImpl.streamRead(SessionInputBufferImpl.java:137)
at org.apache.http.impl.io.SessionInputBufferImpl.fillBuffer(SessionInputBufferImpl.java:153)
at org.apache.http.impl.io.SessionInputBufferImpl.readLine(SessionInputBufferImpl.java:280)
at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:138)
at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:56)
at org.apache.http.impl.io.AbstractMessageParser.parse(AbstractMessageParser.java:259)
at org.apache.http.impl.DefaultBHttpClientConnection.receiveResponseHeader(DefaultBHttpClientConnection.java:163)
at org.apache.http.impl.conn.CPoolProxy.receiveResponseHeader(CPoolProxy.java:157)
at org.apache.http.protocol.HttpRequestExecutor.doReceiveResponse(HttpRequestExecutor.java:273)
at org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:125)
at org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:272)
at org.apache.http.impl.execchain.ProtocolExec.execute(ProtocolExec.java:186)
at org.apache.http.impl.execchain.RetryExec.execute(RetryExec.java:89)
at org.apache.http.impl.execchain.RedirectExec.execute(RedirectExec.java:110)
at org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:185)
at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:83)
at org.activebpel.rt.http.AeHttpClient.execute(AeHttpClient.java:107)
at org.activebpel.rt.http.AeHttpSendHandlerBase.deliver(AeHttpSendHandlerBase.java:98)
at org.activebpel.rt.http.handler.AeHttpGetHandler.handle(AeHttpGetHandler.java:34)
at org.activebpel.rt.http.AeHttpServiceManager.send(AeHttpServiceManager.java:169)
JSON Serverをハング⇒KILLした時の動作を確認する
JSON Serverをハング中にKILLする
JSON Serverを kill -s SIGSTOP `pgrep -f json-server`でハングさせて、CAIプロセスがソケット読み込みで待っている状況下にて JSON Serverに kill -9 `pgrep -f json-server` を実行して強制停止した時の動作を確認してみたいと思います。
なお、コマンド kill -9 は特定のプロセスを強制終了する際に使用します。kill -s SIGKILL も kill -9 と同じ動作ですが、後者の方が市民権を得ている、そんな気がしています。
コマンド kill -9 にてJSON Serverを停止すると、次のような結果になりました。
curlコマンドと実行結果
// curl コマンド
curl https://localhost:7443/process-engine/public/rt/recipe-psa-svcConnJsonServer
// 実行結果
{"error":{"code":500,"detail":{"reason":"Connect to invgcsjcsa02.informatica.com:3000 [invgcsjcsa02.informatica.com\/10.65.133.34] failed: Connection refused (Connection refused)","code":"HTTP_500"},"message":"Connect to invgcsjcsa02.informatica.com:3000 [invgcsjcsa02.informatica.com\/10.65.133.34] failed: Connection refused (Connection refused)"}}
正直に言うと、あまりうれしいログは出てこないかな？と思っていたのですが、上記のメッセージだけでも invgcsjcsa02.informatica.com というホストに接続しているときに、接続が切断された(Connection refused) といったように、トラブルシューティングには十分な情報が得られました。
process engineのログを確認する
ディレクトリ SAインストール先/apps/process-engine/logs に出力されているカタリナログを確認するとハング時にjstackで確認していたstackとは少し異なるstackでCAIプロセス(ID=21017)においてConnection refusedが発生している動作を確認できました。
catalina.2025-12-04.log
05-Dec-2025 11:21:23.352 IST ERROR [QueueManagerWorkManager-WorkerThread-16] [AeException] [{X_INFA_LOG_CTX=req_id=5f4a4c74ed8642f1b683b72a3b694e06, mdc.process.id=21017, mdc.process.initiator=anonymous, mdc.process.name={http://com.activevos.socrates.repository.services/businessConnection}businessConnectionAutomatedStep, mdc.tenant.id=$public}] - Error delivering request targeted for URI: http://invgcsjcsa02.informatica.com:3000/posts/1
org.apache.http.conn.HttpHostConnectException: Connect to invgcsjcsa02.informatica.com:3000 [invgcsjcsa02.informatica.com/10.65.133.34] failed: Connection refused (Connection refused)
at org.apache.http.impl.conn.DefaultHttpClientConnectionOperator.connect(DefaultHttpClientConnectionOperator.java:156)
at org.apache.http.impl.conn.PoolingHttpClientConnectionManager.connect(PoolingHttpClientConnectionManager.java:376)
at org.apache.http.impl.execchain.MainClientExec.establishRoute(MainClientExec.java:393)
at org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:236)
at org.apache.http.impl.execchain.ProtocolExec.execute(ProtocolExec.java:186)
at org.apache.http.impl.execchain.RetryExec.execute(RetryExec.java:89)
at org.apache.http.impl.execchain.RedirectExec.execute(RedirectExec.java:110)
at org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:185)
at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:83)
at org.activebpel.rt.http.AeHttpClient.execute(AeHttpClient.java:107)
at org.activebpel.rt.http.AeHttpSendHandlerBase.deliver(AeHttpSendHandlerBase.java:98)
at org.activebpel.rt.http.handler.AeHttpGetHandler.handle(AeHttpGetHandler.java:34)
at org.activebpel.rt.http.AeHttpServiceManager.send(AeHttpServiceManager.java:169)
おわりに
実はこの記事では、コマンドラインツールで様子を見て言えることを取り留めもなく書いて終わりかな？と思っていたのですが、手を動かして動作確認を進めることで、色々な気づきや、この記事作成時には想定していなかったタイムアウトが発生するまでの設定変更まで言及できました。改めて手を動かして動作確認することは製品の理解を深めるうえで重要だなと感じました。