クラスタ構成の kengine ログ調査
INS-CK1: kengine ログに「Is the server running on that host and accepting TCP/IP connections? Host is unreachable」というエラーが記録されている
KE2 APP とデータベースサーバー間でネットワーク接続の問題が発生している場合、kengine のログを確認すると、「ログのサンプルエントリ」のようなログが表示される可能性があります。
ログのサンプルエントリ
Node: ke2-rhel89-swarm-1
Traceback (most recent call last):
File "/usr/local/lib/python3.11/site-packages/django_dbconn_retry/apps.py", line 51, in ensure_connection_with_retries
self.connect()
File "/usr/local/lib/python3.11/site-packages/django/utils/asyncio.py", line 26, in inner
return func(*args, **kwargs)
^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.11/site-packages/django/db/backends/base/base.py", line 270, in connect
self.connection = self.get_new_connection(conn_params)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.11/site-packages/django/utils/asyncio.py", line 26, in inner
return func(*args, **kwargs)
^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.11/site-packages/django/db/backends/postgresql/base.py", line 275, in get_new_connection
connection = self.Database.connect(**conn_params)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.11/site-packages/psycopg2/__init__.py", line 122, in connect
conn = _connect(dsn, connection_factory=connection_factory, **kwasync)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
psycopg2.OperationalError: connection to server at "10.20.47.20", port 9999 failed: Host is unreachable
Is the server running on that host and accepting TCP/IP connections?
解決策
KE2 APP から外部 DB ホストサーバに ping して答えがない原因でこのような状況発生されます。この場合、以下の調査してください。
- 外部 DB ホストサーバの正常性をご確認ください。
- 外部 DB ホストサーバのネットワークインターフェイスの状態を確認してください。
- 外部 DB ホストサーバの Network 設定を確認してください。
外部 DB ホストサーバやネットワークなどの保守手順については、本マニュアルの範囲外になります。
INS-CK2: kengine ログに「ERROR: unable to read message kind DETAIL: kind does not match between main(4e) slot[1] (53)」というエラーが記録されている
DB クラスタ(pgpool)利用すると、DB ノード間のネットワーク遅延・DB サーバリソース使用率が高い場合、kengine のログを確認すると、「ログのサンプルエントリ」のようなログが表示される可能性があります。
ログのサンプルエントリ
Node: ke2-rhel89-swarm-3
[2024-09-11 08:57:54:ke-ke2-rhel89-swarm-3:docker-entrypoint.sh] INFO: Starting docker-entrypoint(kompirad) [KOMPIRA_VERSION=2.0.0, LANGUAGE_CODE=ja]
[2024-09-11 08:57:54:ke-ke2-rhel89-swarm-3:docker-entrypoint.sh] INFO: Wait for Cache: redis:6379 -t 15
wait-for-it.sh: waiting 15 seconds for redis:6379
wait-for-it.sh: redis:6379 is available after 0 seconds
[2024-09-11 08:57:54:ke-ke2-rhel89-swarm-3:docker-entrypoint.sh] INFO: Cache is ready
[2024-09-11 08:57:54:ke-ke2-rhel89-swarm-3:docker-entrypoint.sh] INFO: Wait for Database: 10.20.47.20:9999 -t 30
wait-for-it.sh: waiting 30 seconds for 10.20.47.20:9999
wait-for-it.sh: 10.20.47.20:9999 is available after 0 seconds
[2024-09-11 08:57:54:ke-ke2-rhel89-swarm-3:docker-entrypoint.sh] INFO: Database is ready
[2024-09-11 08:57:54:ke-ke2-rhel89-swarm-3:docker-entrypoint.sh] INFO: Wait for flock: /var/opt/kompira/.flock_init_data
[2024-09-11 08:57:54:ke-ke2-rhel89-swarm-3:docker-entrypoint.sh] INFO: flock is acquired
[2024-09-11 08:57:55,634:ke-ke2-rhel89-swarm-3:MainProcess:MainThread] INFO: AXES: BEGIN version 6.0.5, blocking by combination of username and ip_address
Reconnecting to the database didn't help connection to server at "10.20.47.20", port 9999 failed: ERROR: unable to read message kind
DETAIL: kind does not match between main(4e) slot[1] (53)
Traceback (most recent call last):
File "/usr/local/lib/python3.11/site-packages/django_dbconn_retry/apps.py", line 51, in ensure_connection_with_retries
self.connect()
File "/usr/local/lib/python3.11/site-packages/django/utils/asyncio.py", line 26, in inner
return func(*args, **kwargs)
^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.11/site-packages/django/db/backends/base/base.py", line 270, in connect
self.connection = self.get_new_connection(conn_params)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.11/site-packages/django/utils/asyncio.py", line 26, in inner
return func(*args, **kwargs)
^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.11/site-packages/django/db/backends/postgresql/base.py", line 275, in get_new_connection
connection = self.Database.connect(**conn_params)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.11/site-packages/psycopg2/__init__.py", line 122, in connect
conn = _connect(dsn, connection_factory=connection_factory, **kwasync)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
psycopg2.OperationalError: connection to server at "10.20.47.20", port 9999 failed: ERROR: unable to read message kind
DETAIL: kind does not match between main(4e) slot[1] (53)
解決策
-
pgpoolノード間の通信問題
ネットワークの問題により、pgpoolノード間で適切な調整ができず、ノード間でデータは同期が取れない場合があります。
-
pgpoolノードのリソース使用率が高い
pgpool VMでCPU、メモリ、I/Oの使用率が高い場合、データベース操作が遅くなり、DB ノード間でデータは同期が取れない場合があります。
外部 DB ホストサーバやネットワークなどの保守手順については、本マニュアルの範囲外になります。
INS-CK3: kengine ログに「database error: cannot execute UPDATE in a read-only transaction」というエラーが記録されている
データベースの不整合やDB クラスタなら、DB クラスタ(pgpool)がフェイルオーバーを実行し、アプリケーションが依然として古いプライマリノード（現在は読み取り専用モード）に接続されている可能性もあります。この状況で kengine のログを確認すると、「ログのサンプルエントリ」のようなログが表示される可能性があります。
ログのサンプルエントリ
Node: ke-ke2-rhel89-swarm-2
[2024-09-25 10:48:17,034:ke-ke2-rhel89-swarm-2:kompirad:MainThread] ERROR: Failed to start due to database error: cannot execute UPDATE in a read-only transaction
解決策
- 以下のコマンドで外部 DB 操作をご確認ください。
# ベーシックコマンド: psql -h <DB IP> -p <DB PORT> -U <USER> -d <DATABASE>
# pgpool場合、DB IP は Virtual IP です。DB PORT は defaultでは 9999 です。
# postgres場合、DB IP は DB サーバ IP です。DB PORT は defaultでは 5432 です。
# USER は postgres です。
# DATABASE は kompira です。
# 例：
$ psql -h 10.20.47.20 -p 9999 -U postgres -d kompira -c "CREATE TEMP TABLE pg_temp.test_table (value TEXT); INSERT INTO pg_temp.test_table (value) VALUES ('Dummy Test Value'); SELECT * FROM pg_temp.test_table;"
Password for user postgres: *****
value
------------------
Dummy Test Value
(1 row)
上のコマンドで問題があれば、外部 DB 管理者に連絡してください。
psql コマンドが利用できない場合は、CentOS/RHEL: postgresql、Debian/Ubuntu: postgresql-client をインストールしてください。
- 外部 DB 操作に問題がなければ、KE2 APP 側での DB 接続セッションの問題の可能性があります。この場合、kengine サービスを再起動してください。
$ docker service update --force $(docker service ls | grep kengine | awk '{print $2}')
INS-CK4: kengine ログに「Error -2 connecting to redis:6379. Name does not resolve」というエラーが記録されている
クラスタ構成場合、redis は3台ノードのいずれかのノードで実行中の可能です。実行中ノードで以下ような問題が発生すると redis が別のノードに切り替えて起動します。
- 実行中ノードがダウン・再起動
- 実行中ノードのリソース利用率が高い
- swarm ノード間のネットワーク導通の問題
- 実行中ノードの docker 停止・再起動
切り替えると kengine で「ログのサンプルエントリ」のようなログが表示される可能性があります。
主なエラーメッセージ
redis.exceptions.ConnectionError: Error -2 connecting to redis:6379. Name does not resolve.
ログのサンプルエントリ
Node: ke2-rhel89-swarm-1
File "/usr/local/lib/python3.11/site-packages/kompira/core/cache.py", line 55, in get_object
cache.touch(key)
File "/usr/local/lib/python3.11/site-packages/django/core/cache/backends/redis.py", line 195, in touch
return self._cache.touch(key, self.get_backend_timeout(timeout))
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.11/site-packages/django/core/cache/backends/redis.py", line 115, in touch
return bool(client.expire(key, timeout))
^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.11/site-packages/redis/commands/core.py", line 1762, in expire
return self.execute_command("EXPIRE", name, time, *exp_option)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.11/site-packages/redis/client.py", line 1266, in execute_command
conn = self.connection or pool.get_connection(command_name, **options)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.11/site-packages/redis/connection.py", line 1461, in get_connection
connection.connect()
File "/usr/local/lib/python3.11/site-packages/redis/connection.py", line 713, in connect
raise ConnectionError(self._error_message(e))
redis.exceptions.ConnectionError: Error -2 connecting to redis:6379. Name does not resolve.
解決策
redis が不安定かどうか確認してください。
以下のコマンドでを実行します。
$ docker service ls
ID NAME MODE REPLICAS IMAGE PORTS
j82svpetkj10 ke2_jobmngrd replicated 3/3 (max 1 per node) kompira.azurecr.io/kompira-enterprise:latest
8nmuory1g71d ke2_kengine replicated 3/3 (max 1 per node) kompira.azurecr.io/kompira-enterprise:latest
nfjkex57y4il ke2_kompira replicated 3/3 (max 1 per node) kompira.azurecr.io/kompira-enterprise:latest
jgfdapwajjat ke2_nginx replicated 3/3 (max 1 per node) registry.hub.docker.com/library/nginx:1.27-alpine *:80->80/tcp, *:443->443/tcp
qf169f0k9idj ke2_rabbitmq replicated 3/3 (max 1 per node) registry.hub.docker.com/library/rabbitmq:3.13-alpine *:5671->5671/tcp
l76bm4t1wf6n ke2_redis replicated 1/1 registry.hub.docker.com/library/redis:7.2-alpine
上の結果見ると ke2_redis は replicated 1/1 なるべきです。でも不安定場合、上ののコマンド数回実行すると replicated 0/1, 1/1, 0/1 に変わってしまいます。以下のコマンドで詳細も見ることができます。
$ docker service ps ke2_redis
ID NAME IMAGE NODE DESIRED STATE CURRENT STATE ERROR PORTS
k5oa1w93z9me ke2_redis.1 registry.hub.docker.com/library/redis:7.2-alpine ke2-rhel89-swarm-3 Running Running about a minute ago
jyc5pxewoedb \_ ke2_redis.1 registry.hub.docker.com/library/redis:7.2-alpine ke2-rhel89-swarm-1 Shutdown Complete about a minute ago
g2eryw4fug4f \_ ke2_redis.1 registry.hub.docker.com/library/redis:7.2-alpine ke2-rhel89-swarm-1 Shutdown Complete about a minute ago
redis がよく再起度を繰り返すと上の通り結果項目が多くなります。そして CURRENT STATE 見ると短い期間で Shutdown になっていることがわかります。
redis が不安定場合、以下の手順を進んでください。
-
swarm ノードのステータスをご確認ください。
swarm ノードの状況が異常場合、解決してください。
-
swarm ノードのステータスは正常の場合、 redis を再起動してください。 redis サービス名で再起動してください。
$ docker service --force update ke2_redis ke2_redis overall progress: 1 out of 1 tasks 1/1: running [==================================================>] verify: Service ke2_redis converged
INS-CK5: kengine ログに「Is the server running on that host and accepting TCP/IP connections? Connection refused」というエラーが記録されている
データベースが停止されてしまった場合、kengine のログを確認すると、「ログのサンプルエントリ」のようなログが表示される可能性があります。
ログのサンプルエントリ
Reconnecting to the database didn't help connection to server at "10.20.47.20", port 9999 failed: Connection refused
Is the server running on that host and accepting TCP/IP connections?
解決策
- 外部データベースへのアクセスを確認してみてください。