Misskeyのバックエンドプロセスが終了しない

noellabo commented 1 year ago

💡 Summary

Misskeyのバックエンドプロセスが終了しない、あるいは非常に時間がかかる

🥰 Expected Behavior

終了を指示したら、すぐにポートを閉じ、速やかに正常終了する

🤬 Actual Behavior

終了を指示しても、ポートが開いたままで内部エラーだけ繰り返し、終了しない（最終的に強制終了される）

📝 Steps to Reproduce

sudo systemctl stop misskey
（1分後にタイムアウトで強制Kill）

🛰 Backend (for server admin)

Installation Method or Hosting Service: systemd
Misskey: 13.13.1
Node: 18.16.0
PostgreSQL: 15.3
Redis: 7.0.11
OS and Architecture: Ubuntu 22.04.2 LTS (GNU/Linux 5.19.0-42-generic x86_64)

問題の発生はMisskey 13.13.0に更新して以降だと思われますが、Misskey以外の更新によるものである可能性もあり検証できていません。

ログ

 6月 12 09:09:31 cloud systemd[1]: Stopping Misskey daemon...
 6月 12 09:09:31 cloud misskey[3203131]: INFO 1        [chart]        activeUsers: Write skipped
 6月 12 09:09:31 cloud misskey[3203117]: INFO *        [chart]        federation: Write skipped
 6月 12 09:09:31 cloud misskey[3203117]: INFO *        [chart]        users: Write skipped
 6月 12 09:09:31 cloud misskey[3203117]: INFO *        [chart]        instance: Write skipped
 6月 12 09:09:31 cloud misskey[3203117]: INFO *        [chart]        drive: Write skipped
 6月 12 09:09:31 cloud misskey[3203117]: INFO *        [chart]        perUserFollowing: Write skipped
 6月 12 09:09:31 cloud misskey[3203117]: INFO *        [chart]        perUserDrive: Write skipped
 6月 12 09:09:31 cloud misskey[3203117]: INFO *        [chart]        apRequest: Write skipped
 6月 12 09:09:31 cloud misskey[3203117]: INFO *        [chart]        notes: Updated
 6月 12 09:09:31 cloud misskey[3203117]: INFO *        [chart]        perUserReaction:9faonpnovl: Updated
 6月 12 09:09:31 cloud misskey[3203117]: INFO *        [chart]        perUserReaction:912clqn4lh(hour): New commit created
 6月 12 09:09:31 cloud misskey[3203117]: INFO *        [chart]        perUserReaction:9arei1v1iz(hour): New commit created
 6月 12 09:09:31 cloud misskey[3203117]: INFO *        [chart]        perUserReaction:9fd83686a5(hour): New commit created
 6月 12 09:09:31 cloud misskey[3203117]: INFO *        [chart]        perUserReaction:912clqn4lh(day): New commit created
 6月 12 09:09:31 cloud misskey[3203117]: INFO *        [chart]        perUserReaction:9fd83686a5(day): New commit created
 6月 12 09:09:31 cloud misskey[3203117]: INFO *        [chart]        activeUsers: Updated
 6月 12 09:09:31 cloud misskey[3203117]: INFO *        [chart]        perUserReaction:9arei1v1iz(day): New commit created
 6月 12 09:09:31 cloud misskey[3203117]: INFO *        [chart]        perUserReaction:9arei1v1iz: Updated
 6月 12 09:09:31 cloud misskey[3203117]: INFO *        [chart]        perUserReaction:9fd83686a5: Updated
 6月 12 09:09:31 cloud misskey[3203117]: INFO *        [chart]        perUserReaction:912clqn4lh: Updated
 6月 12 09:09:31 cloud misskey[3203117]: INFO *        [chart]        perUserNotes:9fd5haou69(day): New commit created
 6月 12 09:09:31 cloud misskey[3203117]: INFO *        [chart]        perUserPv:9arei1v1iz(day): New commit created
 6月 12 09:09:31 cloud misskey[3203117]: INFO *        [chart]        perUserNotes:9fd5haou69(hour): New commit created
 6月 12 09:09:32 cloud misskey[3203117]: INFO *        [chart]        perUserNotes:9b20xql127(day): New commit created
 6月 12 09:09:32 cloud misskey[3203117]: INFO *        [chart]        perUserNotes:9fd5haou69: Updated
 6月 12 09:09:32 cloud misskey[3203117]: INFO *        [chart]        perUserNotes:9b20xql127(hour): New commit created
 6月 12 09:09:32 cloud misskey[3203117]: INFO *        [chart]        perUserNotes:9b20xql127: Updated
 6月 12 09:09:32 cloud misskey[3203131]: INFO 1        [chart]        perUserPv: Write skipped
 6月 12 09:09:32 cloud misskey[3203117]: Error: Connection is closed.
 6月 12 09:09:32 cloud misskey[3203117]:     at EventEmitter.sendCommand (/home/misskey/misskey/node_modules/.pnpm/ioredis@5.3.2/node_modules/ioredis/built/Redis.js:332:28)
 6月 12 09:09:32 cloud misskey[3203117]:     at Script.execute (/home/misskey/misskey/node_modules/.pnpm/ioredis@5.3.2/node_modules/ioredis/built/Script.js:59:26)
 6月 12 09:09:32 cloud misskey[3203117]:     at EventEmitter.addJob (/home/misskey/misskey/node_modules/.pnpm/ioredis@5.3.2/node_modules/ioredis/built/utils/Commander.js:111:27)
 6月 12 09:09:32 cloud misskey[3203117]:     at Scripts.addJob (/home/misskey/misskey/node_modules/.pnpm/bullmq@3.15.0/node_modules/bullmq/dist/cjs/classes/scripts.js:86:37)
 6月 12 09:09:32 cloud misskey[3203117]:     at Job.addJob (/home/misskey/misskey/node_modules/.pnpm/bullmq@3.15.0/node_modules/bullmq/dist/cjs/classes/job.js:726:29)
 6月 12 09:09:32 cloud misskey[3203117]:     at Job.create (/home/misskey/misskey/node_modules/.pnpm/bullmq@3.15.0/node_modules/bullmq/dist/cjs/classes/job.js:94:28)
 6月 12 09:09:32 cloud misskey[3203117]:     at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
 6月 12 09:09:32 cloud misskey[3203117]:     at async Queue.add (/home/misskey/misskey/node_modules/.pnpm/bullmq@3.15.0/node_modules/bullmq/dist/cjs/classes/queue.js:79:25)
 6月 12 09:09:32 cloud misskey[3203117]: INFO *        [chart]        perUserPv:9arei1v1iz(hour): New commit created
 6月 12 09:09:32 cloud misskey[3203131]: INFO 1        [chart]        perUserFollowing: Write skipped
 6月 12 09:09:32 cloud misskey[3203131]: INFO 1        [chart]        perUserDrive: Write skipped
 6月 12 09:09:32 cloud misskey[3203117]: INFO *        [chart]        perUserPv:9arei1v1iz: Updated
 6月 12 09:09:32 cloud misskey[3203131]: ERR  1        [core nest]        TypeORMError: Driver not Connected
 6月 12 09:09:32 cloud misskey[3203131]:     at PostgresDriver.obtainMasterConnection (/home/misskey/misskey/node_modules/.pnpm/typeorm@0.3.16_ioredis@5.3.2_pg@8.11.0/node_modules/typeorm/driver/postgres/PostgresDriver.js:>
 6月 12 09:09:32 cloud misskey[3203131]:     at PostgresQueryRunner.connect (/home/misskey/misskey/node_modules/.pnpm/typeorm@0.3.16_ioredis@5.3.2_pg@8.11.0/node_modules/typeorm/driver/postgres/PostgresQueryRunner.js:68:18)
 6月 12 09:09:32 cloud misskey[3203131]:     at PostgresQueryRunner.query (/home/misskey/misskey/node_modules/.pnpm/typeorm@0.3.16_ioredis@5.3.2_pg@8.11.0/node_modules/typeorm/driver/postgres/PostgresQueryRunner.js:174:47)
 6月 12 09:09:32 cloud misskey[3203131]:     at SelectQueryBuilder.loadRawResults (/home/misskey/misskey/node_modules/.pnpm/typeorm@0.3.16_ioredis@5.3.2_pg@8.11.0/node_modules/typeorm/query-builder/SelectQueryBuilder.js:21>
 6月 12 09:09:32 cloud misskey[3203131]:     at SelectQueryBuilder.executeEntitiesAndRawResults (/home/misskey/misskey/node_modules/.pnpm/typeorm@0.3.16_ioredis@5.3.2_pg@8.11.0/node_modules/typeorm/query-builder/SelectQuer>
 6月 12 09:09:32 cloud misskey[3203131]:     at SelectQueryBuilder.getRawAndEntities (/home/misskey/misskey/node_modules/.pnpm/typeorm@0.3.16_ioredis@5.3.2_pg@8.11.0/node_modules/typeorm/query-builder/SelectQueryBuilder.js>
 6月 12 09:09:32 cloud misskey[3203131]:     at SelectQueryBuilder.getOne (/home/misskey/misskey/node_modules/.pnpm/typeorm@0.3.16_ioredis@5.3.2_pg@8.11.0/node_modules/typeorm/query-builder/SelectQueryBuilder.js:711:36)
 6月 12 09:09:32 cloud misskey[3203131]:     at EntityManager.findOneBy (/home/misskey/misskey/node_modules/.pnpm/typeorm@0.3.16_ioredis@5.3.2_pg@8.11.0/node_modules/typeorm/entity-manager/EntityManager.js:610:14)
 6月 12 09:09:32 cloud misskey[3203131]:     at Repository.findOneBy (/home/misskey/misskey/node_modules/.pnpm/typeorm@0.3.16_ioredis@5.3.2_pg@8.11.0/node_modules/typeorm/repository/Repository.js:246:29)
 6月 12 09:09:32 cloud misskey[3203131]:     at FederationChart.claimCurrentLog (file:///home/misskey/misskey/packages/backend/built/core/chart/core.js:197:45)
 6月 12 09:09:32 cloud misskey[3203131]:     at file:///home/misskey/misskey/packages/backend/built/core/chart/core.js:380:22
 6月 12 09:09:32 cloud misskey[3203131]:     at Array.map (<anonymous>)
 6月 12 09:09:32 cloud misskey[3203131]:     at FederationChart.save (file:///home/misskey/misskey/packages/backend/built/core/chart/core.js:379:34)
 6月 12 09:09:32 cloud misskey[3203131]:     at file:///home/misskey/misskey/packages/backend/built/core/chart/ChartManagementService.js:49:62
 6月 12 09:09:32 cloud misskey[3203131]:     at Array.map (<anonymous>)
 6月 12 09:09:32 cloud misskey[3203131]:     at ChartManagementService.dispose (file:///home/misskey/misskey/packages/backend/built/core/chart/ChartManagementService.js:49:43)
 6月 12 09:09:32 cloud misskey[3203131]:     at ChartManagementService.onApplicationShutdown (file:///home/misskey/misskey/packages/backend/built/core/chart/ChartManagementService.js:53:20)
 6月 12 09:09:32 cloud misskey[3203131]:     at MapIterator.iteratee (/home/misskey/misskey/node_modules/.pnpm/@nestjs+core@9.4.2_@nestjs+common@9.4.2_reflect-metadata@0.1.13_rxjs@7.8.1/node_modules/@nestjs/core/hooks/on-a>
 6月 12 09:09:32 cloud misskey[3203131]:     at MapIterator.next (/home/misskey/misskey/node_modules/.pnpm/iterare@1.2.1/node_modules/iterare/lib/map.js:13:39)
 6月 12 09:09:32 cloud misskey[3203131]:     at IteratorWithOperators.next (/home/misskey/misskey/node_modules/.pnpm/iterare@1.2.1/node_modules/iterare/lib/iterate.js:21:28)
 6月 12 09:09:32 cloud misskey[3203131]:     at Function.from (<anonymous>)
 6月 12 09:09:32 cloud misskey[3203131]:     at IteratorWithOperators.toArray (/home/misskey/misskey/node_modules/.pnpm/iterare@1.2.1/node_modules/iterare/lib/iterate.js:180:22)
 6月 12 09:09:32 cloud misskey[3203131]:     at callOperator (/home/misskey/misskey/node_modules/.pnpm/@nestjs+core@9.4.2_@nestjs+common@9.4.2_reflect-metadata@0.1.13_rxjs@7.8.1/node_modules/@nestjs/core/hooks/on-app-shutd>
 6月 12 09:09:32 cloud misskey[3203131]:     at callAppShutdownHook (/home/misskey/misskey/node_modules/.pnpm/@nestjs+core@9.4.2_@nestjs+common@9.4.2_reflect-metadata@0.1.13_rxjs@7.8.1/node_modules/@nestjs/core/hooks/on-ap>
 6月 12 09:09:32 cloud misskey[3203131]:     at NestApplicationContext.callShutdownHook (/home/misskey/misskey/node_modules/.pnpm/@nestjs+core@9.4.2_@nestjs+common@9.4.2_reflect-metadata@0.1.13_rxjs@7.8.1/node_modules/@nes>
 6月 12 09:09:32 cloud misskey[3203131]:     at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
 6月 12 09:09:32 cloud misskey[3203131]:     at async process.cleanup (/home/misskey/misskey/node_modules/.pnpm/@nestjs+core@9.4.2_@nestjs+common@9.4.2_reflect-metadata@0.1.13_rxjs@7.8.1/node_modules/@nestjs/core/nest-appl>
 6月 12 09:09:32 cloud misskey[3203131]: INFO 1        [core]        The process is going to exit with code 1
 6月 12 09:09:32 cloud misskey[3203117]: ERR  *        [core cluster]        [1] died :(
 6月 12 09:09:33 cloud misskey[4134304]: (node:4134304) ExperimentalWarning: Import assertions are not a stable feature of the JavaScript language. Avoid relying on their current behavior and syntax as those might change i>
 6月 12 09:09:33 cloud misskey[4134304]: (Use `node --trace-warnings ...` to show where the warning was created)

（中略・redisのError: Connection is closed.繰り返し）

 6月 12 09:09:35 cloud misskey[3203117]: TypeORMError: Driver not Connected
 6月 12 09:09:35 cloud misskey[3203117]:     at PostgresDriver.obtainMasterConnection (/home/misskey/misskey/node_modules/.pnpm/typeorm@0.3.16_ioredis@5.3.2_pg@8.11.0/node_modules/typeorm/driver/postgres/PostgresDriver.js:>
 6月 12 09:09:35 cloud misskey[3203117]:     at PostgresQueryRunner.connect (/home/misskey/misskey/node_modules/.pnpm/typeorm@0.3.16_ioredis@5.3.2_pg@8.11.0/node_modules/typeorm/driver/postgres/PostgresQueryRunner.js:68:18)
 6月 12 09:09:35 cloud misskey[3203117]:     at PostgresQueryRunner.query (/home/misskey/misskey/node_modules/.pnpm/typeorm@0.3.16_ioredis@5.3.2_pg@8.11.0/node_modules/typeorm/driver/postgres/PostgresQueryRunner.js:174:47)
 6月 12 09:09:35 cloud misskey[3203117]:     at SelectQueryBuilder.loadRawResults (/home/misskey/misskey/node_modules/.pnpm/typeorm@0.3.16_ioredis@5.3.2_pg@8.11.0/node_modules/typeorm/query-builder/SelectQueryBuilder.js:21>
 6月 12 09:09:35 cloud misskey[3203117]:     at SelectQueryBuilder.executeEntitiesAndRawResults (/home/misskey/misskey/node_modules/.pnpm/typeorm@0.3.16_ioredis@5.3.2_pg@8.11.0/node_modules/typeorm/query-builder/SelectQuer>
 6月 12 09:09:35 cloud misskey[3203117]:     at SelectQueryBuilder.getRawAndEntities (/home/misskey/misskey/node_modules/.pnpm/typeorm@0.3.16_ioredis@5.3.2_pg@8.11.0/node_modules/typeorm/query-builder/SelectQueryBuilder.js>
 6月 12 09:09:35 cloud misskey[3203117]:     at SelectQueryBuilder.getMany (/home/misskey/misskey/node_modules/.pnpm/typeorm@0.3.16_ioredis@5.3.2_pg@8.11.0/node_modules/typeorm/query-builder/SelectQueryBuilder.js:750:36)
 6月 12 09:09:35 cloud misskey[3203117]:     at EntityManager.find (/home/misskey/misskey/node_modules/.pnpm/typeorm@0.3.16_ioredis@5.3.2_pg@8.11.0/node_modules/typeorm/entity-manager/EntityManager.js:523:14)
 6月 12 09:09:35 cloud misskey[3203117]:     at Repository.find (/home/misskey/misskey/node_modules/.pnpm/typeorm@0.3.16_ioredis@5.3.2_pg@8.11.0/node_modules/typeorm/repository/Repository.js:197:29)
 6月 12 09:09:35 cloud misskey[3203117]:     at UserListChannel.updateListUsers (file:///home/misskey/misskey/packages/backend/built/server/api/stream/channels/user-list.js:50:61)
 6月 12 09:09:35 cloud misskey[3203117]:     at listOnTimeout (node:internal/timers:569:17)
 6月 12 09:09:35 cloud misskey[3203117]:     at process.processTimers (node:internal/timers:512:7)

（中略・redisおよびTypeORMエラー繰り返し）

 6月 12 09:10:32 cloud systemd[1]: misskey.service: State 'final-sigterm' timed out. Killing.
 6月 12 09:10:32 cloud systemd[1]: misskey.service: Killing process 3203117 (Misskey (master) with signal SIGKILL.
 6月 12 09:10:32 cloud systemd[1]: misskey.service: Killing process 4134304 (Misskey (worker) with signal SIGKILL.
 6月 12 09:10:32 cloud systemd[1]: misskey.service: Killing process 3203119 (node) with signal SIGKILL.
 6月 12 09:10:32 cloud systemd[1]: misskey.service: Killing process 3203121 (node) with signal SIGKILL.
 6月 12 09:10:32 cloud systemd[1]: misskey.service: Killing process 4134306 (node) with signal SIGKILL.
 6月 12 09:10:32 cloud systemd[1]: misskey.service: Killing process 4134308 (node) with signal SIGKILL.
 6月 12 09:10:32 cloud systemd[1]: misskey.service: Killing process 4134310 (n/a) with signal SIGKILL.
 6月 12 09:10:32 cloud systemd[1]: misskey.service: Killing process 4134311 (node) with signal SIGKILL.
 6月 12 09:10:32 cloud systemd[1]: misskey.service: Killing process 4134313 (n/a) with signal SIGKILL.
 6月 12 09:10:32 cloud systemd[1]: misskey.service: Killing process 4134315 (n/a) with signal SIGKILL.
 6月 12 09:10:32 cloud systemd[1]: misskey.service: Failed with result 'timeout'.
 6月 12 09:10:32 cloud systemd[1]: Stopped Misskey daemon.

noellabo commented 1 year ago

misskey.cloud、のえすきーとも発生しています。

おそらくMisskey 13.13.0に更新して以降です。

定期再起動をかけて運用していたところ、13.13.0以降、利用者より再起動時にエラーが長く続くという報告があり、確認したところ、ポートを開いたままなかなかプロセスが終了しておらず、毎回、終了に1分＋起動後のアクセス受付までのあいだ、ユーザーにエラーを返す時間が生じていました。

Misskey 13.12.x までは終了は即座に終わっていたと思います。

fruitriin commented 1 year ago

うちも似たような現象が起きてたので報告 13.12.3 → 13.13.1 → 13.13.2 とマイグレートしてきたんだけど、13.13 では pnpm migrate systemctl restart misskey とすると起動しなくなる（なんかエラーはいてる）

どうもredis に繋がらないようで、 redis-serverを再起動すると起動プロセスが進みはじめるっぽい

yuriha-chan commented 1 year ago

https://github.com/misskey-dev/misskey/blob/f5dfb64a528d705970d606d3f84ec9de2ef55d84/packages/backend/src/server/ServerService.ts#L227-L228 これを両方コメントアウトすると終了するようになる

syuilo commented 1 year ago

tasukete

tamaina commented 1 year ago

https://github.com/misskey-dev/misskey/pull/10914 では治らなかった

fruitriin commented 1 year ago

https://github.com/fastify/fastify/issues/2571 https://github.com/fastify/fastify/issues/260 Fastify は通常の終了シグナルで終了しないので、Pluginを入れる必要がある

fruitriin commented 1 year ago

https://github.com/hemerajs/fastify-graceful-shutdown これ入れたらなおった

mei23 commented 1 year ago

究極的にはシャットダウンフックをしないを推すわ https://github.com/misskey-dev/misskey/blob/0e6cd577cc1e880f53492c3cb8b15f273e412897/packages/backend/src/boot/common.ts#L20

：

なぜ終わらないのか → ServerService.dispose() の Fastify 周りが終わらないから。(特にWebSocket繋がってると終わらない)

どうすれば終わるようになるのか → そこでawaitしないようにしたり、Fastifyがシグナルで閉じるようにしたりすると終わるようになる。 → でも、それ結局強制切断だから、今までのプロセスごと終了させられるのとあんまり変わらなくないかしら？ → 別にServerServiceのシャットダウンフックいらないのでは？

てゆうか他のシャットダウンフックもいらなくない？これから終了するプロセスのメモリキャッシュをクリアしたりハンドラを消したりするのリソースの無駄じゃないかしら？

なぜ、プロセスが再forkされ続けるのか？ → プロセスが終了したら理由を問わず再forkするようになってるから。 → プロセスの終了方法とかシャットダウン状態見るとかもあるけどなんかややこしいし、ちょっと挙動変わる。 → なお、シャットダウンフックが終わらない問題が解決すれば、メインプロセスもすぐ終わって、再forkするプロセスがいなくなるので事象は起きなくなる。

syuilo commented 1 year ago

一部メモリにデータを溜めておいて定期的にDBに書き込む処理があってシャットダウンされる時も書き込むようにしてるからシャットダウンフック使わないと困る場合があるかも

syuilo commented 1 year ago

まあそこまで重要なデータじゃないから失われてもそこまで問題にならないけど

mei23 commented 1 year ago

一部メモリにデータを溜めておいて定期的にDBに書き込む処理があってシャットダウンされる時も書き込むようにしてるからシャットダウンフック使わないと困る場合があるかも

チャートかしら https://github.com/misskey-dev/misskey/issues/8967

保存間隔短くして書ききれないのはあきらめるとか・・・

syuilo commented 1 year ago

RedisとかDBのコネクションって明示的に切断してやらないと相手側に残ったりしないのかしら？

mei23 commented 1 year ago

RedisとかDBのコネクションって明示的に切断してやらないと相手側に残ったりしないのかしら？

流石にプロセス終了→TCP接続終了→subscriber解除なんじゃないかしら

syuilo commented 1 year ago

なるほど

syuilo commented 1 year ago

あーでもあれだ Nestインスタンスはテスト中に何回も作成されたり廃棄されたりするからシャットダウン=プロセス終了とは限らない

u1-liquid commented 1 year ago

ちなみにioでは https://github.com/MisskeyIO/misskey/pull/156 と https://github.com/MisskeyIO/misskey/pull/159 で一応終了されないという問題は解消しています

mei23 commented 1 year ago

Nestインスタンスはテスト中に何回も作成されたり廃棄されたりするからシャットダウン=プロセス終了とは限らない

テスト環境だけHookするとか？

本番環境とかはズバッと終了してほしい気はするのだわ。(さっさと開放して復帰して欲しい)

fruitriin commented 1 year ago

ズバッと終了期待

syuilo commented 1 year ago

本番環境はズバッと終了させるか

misskey-dev / misskey