ぶ！ログ
MisskeyのDBをダンプしたい(その3)
Error message from server: server closed the connection unexpectedly
前回に引き続きPostgreSQLをダンプするための試行錯誤の話
次はuser_profileテーブルがぶっ壊れていたというやつです。エラーは以下の通り。
$ docker exec [container] pg_dump -c -U misskey -t user_profile > dump.sql
pg_dump: error: Dumping the contents of table "user_profile" failed: PQgetCopyData() failed.
pg_dump: detail: Error message from server: server closed the connection unexpectedly
This probably means the server terminated abnormally
before or while processing the request.
pg_dump: detail: Command was: COPY public.user_profile ("userId", location, birthday, description, fields, url, email, "emailVerifyCode", "emailVerified", "twoFactorTempSecret", "twoFactorSecret", "twoFactorEnabled", password, "clientData", "autoAcceptFollowed", "alwaysMarkNsfw", "carefulBot", "userHost", "securityKeysAvailable", "usePasswordLessLogin", "pinnedPageId", room, "injectFeaturedNote", "enableWordMute", "mutedWords", "noCrawle", "receiveAnnouncementEmail", "emailNotificationTypes", lang, "mutedInstances", "publicReactions", "autoSensitive", "moderationNote", achievements, "loggedInDates", "preventAiLearning", "twoFactorBackupSecret", "verifiedLinks", "notificationRecieveConfig", "hardMutedWords", "followingVisibility", "followersVisibility") TO stdout;
$
user_profileテーブルをダンプするときにDBからの接続が切られているということしかわかりません。
db-1 | 2024-08-06 00:52:36.242 UTC [1] LOG: server process (PID 2281320) was terminated by signal 11: Segmentation fault
db-1 | 2024-08-06 00:52:36.242 UTC [1] DETAIL: Failed process was running: COPY public.user_profile ("userId", location, birthday, description, fields, url, email, "emailVerifyCode", "emailVerified", "twoFactorTempSecret", "twoFactorSecret", "twoFactorEnabled", password, "clientData", "autoAcceptFollowed", "alwaysMarkNsfw", "carefulBot", "userHost", "securityKeysAvailable", "usePasswordLessLogin", "pinnedPageId", room, "injectFeaturedNote", "enableWordMute", "mutedWords", "noCrawle", "receiveAnnouncementEmail", "emailNotificationTypes", lang, "mutedInstances", "publicReactions", "autoSensitive", "moderationNote", achievements, "loggedInDates", "preventAiLearning", "twoFactorBackupSecret", "verifiedLinks", "notificationRecieveConfig", "hardMutedWords", "followingVisibility", "followersVisibility") TO stdout;
DB側のログでもSEGVってダンプが中断されていること以外はわかりませんでした。
ログレベル上げるべきなんだろうけど、めんどくさいんだよなあ。
虱潰し
秘技虱潰し。
現状なんの問題なしにMisskeyが稼働していることを考えると、テーブルが完全にぶっ壊れているのではなく、
一部のデータだけが壊れているということが推測されます。
大量にあるレコードを一つ一つ確認していくのは非現実的なため、ダメそうなデータを絞り込んでいきましょう。
とりあえず、特定のカラムの情報が取得できないんじゃあないかなということで、ダメそうなカラムを絞っていきます。
Misskeyのuser_profileテーブルには以下のカラムが存在します。
userId
location
birthday
description
fields
url
email
emailVerifyCode
emailVerified
twoFactorTempSecret
twoFactorSecret
twoFactorEnabled
password
clientData
autoAcc eptFollowed
alwaysMarkNsfw
carefulBot
userHost
securityKeysAvailable
usePasswordLessLogin
pinnedPageId
room
injectFeaturedNote
enableWordMute
mutedWords
noCrawle
receiveAnnouncementEmail
emailNotificationTypes
lang
mutedInstances
publicReactions
autoSensitive
moderationNote
achievements
loggedInDates
preventAiLearning
twoFactorBackupSecret
verifiedLinks
notificationRecieveConfig
hardMutedWords
followingVisibility
followersVisibility
例のごとく、SELECT "カラム名" FROM user_profile;で適当にエラーが出るものを探していきます。
$ docker exec [container] psql -c 'SELECT "hardMutedWords" FROM user_profile;' -U misskey misskey > dump.txt
server closed the connection unexpectedly
This probably means the server terminated abnormally
before or while processing the request.
connection to server was lost
$
頭から順に試したところ、hardMutedWordsのカラムで失敗するようです。
レコードを特定
user_profileテーブルのhardMutedWordsは名前の通りハードミュートの単語を配列で持っています。
初期値は[]で空配列が代入されています。
問題があると考えられるレコードはその値が参照できないはずなので、[]以外の値を持つレコードを探してやれば原因特定が楽そうです。まあまあ無理やりな方法ですが・・・。
$ docker exec [container] psql -c 'SELECT "userId" FROM user_profile WHERE "hardMutedWords" = '\''[]'\'';' -U misskey misskey | sort > nonMute_users.txt
$ wc -l nonMute_users.txt
322854 nonMute_users.txt
$ docker exec [container] psql -c 'SELECT "userId" FROM user_profile;' -U misskey misskey | sort > all_users.txt
$ wc -l all_users.txt
322855 all_users.txt
$ diff nonMute_users.txt all_users.txt
240367a240368
> 9nwdtwqmmd
322853c322854
< (322850 rows)
---
> (322851 rows)
$
ということで、全userIdと空配列を持つレコードのuserIdを抽出し、diffを取ってみると9nwdtwqmmdが引っかかりました。
対応
当該レコードは現在もサービスを提供しているインスタンスのユーザーのようです。
例によって初期値を代入することで解決を試みようと思いましたが、どうやらUPDATEするだけでもSEGVってしまうようです。
misskey=# UPDATE user_profile SET "hardMutedWords" = '[]' WHERE "userId" = '9nwdtwqmmd';
WARNING: terminating connection because of crash of another server process
DETAIL: The postmaster has commanded this server process to roll back the current transaction and exit, because another server process exited abnormally and possibly corrupted shared memory.
HINT: In a moment you should be able to reconnect to the database and repeat your command.
server closed the connection unexpectedly
This probably means the server terminated abnormally
before or while processing the request.
misskey=?#
仕方がないので、DELETEします。
misskey=# DELETE FROM user_profile WHERE "userId" = '9nwdtwqmmd';
DELETE 1
misskey=#
misskey=# SELECT "userId", "userHost", "url" FROM user_profile WHERE "userId" = '9nwdtwqmmd';
userId | userHost | url
--------+----------+-----
(0 rows)
misskey=#
対応2
これで一応ダンプはできるように放ったのですが、当該ユーザーの情報をうちのサーバーからは参照できなくなっています。(中途半端に情報が残っているので)
当該ユーザーを参照できないのはまあまあまずそうなので参照できるようにしておきます。
ユーザーはuserテーブルを参照していますが、詳細なプロフィールはuser_profileを参照しているようで、
user_profileテーブルのレコードだけをDELETEするのはよく無さそうです。
ということで当該ユーザーのuserテーブルのレコードも消してしまいます。
misskey=# SELECT * FROM "user" WHERE "username" = 'ユーザーID';
id | updatedAt | lastFetchedAt | username | usernameLower | name | followersCount | followingCount | notesCount | avatarId | bannerId | tags | isSuspended | isLocked | isBot | isCat | isRoot | emojis | host | inbox | sharedInbox | featured | uri | token | isExplorable | followersUri | lastActiveDate | hideOnlineStatus | isDeleted | avatarUrl | bannerUrl | avatarBlurhash | bannerBlurhash | movedToUri | alsoKnownAs | movedAt | isHibernated | avatarDecorations
------------+----------------------------+---------------------------+---------------+---------------+----------+----------------+----------------+------------+------------+----------+------+-------------+----------+-------+-------+--------+--------+--------------+---------------------------------------------+----------------------------+------------------------------------------------------------+---------------------------------------+-------+--------------+-------------------------------------------------+----------------+------------------+-----------+----------------------------------------------------------------------------------------------------------------------------------------------+-----------+--------------------------------------------------------+----------------+------------+-------------+---------+--------------+-------------------
9nwdtwqmmd | 2023-12-31 04:10:57.833+00 | 2024-08-16 14:29:44.73+00 | ユーザーID | ユーザーID | ユーザー名 | 0 | 0 | 9 | 9nwdv06go4 | | {} | f | f | f | f | f | {} | example.com | https://example.com/users/userid/inbox | https://example.com/inbox | https://example.com/users/userid/collections/featured | https://example.com/users/userid | | t | https://example.com/users/userid/followers | | f | f | https://sns.copi.pe/proxy/avatar.webp?url=https%3A%2F%2Fexample.com%2Fstorage%2Fwebpublic-4c24b55a-d6f2-46bb-92ea-db25b531d21f.jpg&avatar=1 | | eGO:w%xa~M-;tmxwM|IWof%3%LRit7WAs:%fRmxVt6R-$~R*NLRini | | | | | f | []
(1 row)
misskey=# DELETE FROM "user" WHERE "id" = '9nwdtwqmmd';
DELETE 1
misskey=# SELECT * FROM "user" WHERE "username" = 'Pikainti_7171';
id | updatedAt | lastFetchedAt | username | usernameLower | name | followersCount | followingCount | notesCount | avatarId | bannerId | tags | isSuspended | isLocked | isBot | isCat | isRoot | emojis | host | inbox | sharedInbox | featured | uri | token | isExplorable | followersUri | lastActiveDate | hideOnlineStatus | isDeleted | avatarUrl | bannerUrl | avatarBlurhash | bannerBlurhash | movedToUri | alsoKnownAs | movedAt | isHibernated | avatarDecorations
----+-----------+---------------+----------+---------------+------+----------------+----------------+------------+----------+----------+------+-------------+----------+-------+-------+--------+--------+------+-------+-------------+----------+-----+-------+--------------+--------------+----------------+------------------+-----------+-----------+-----------+----------------+----------------+------------+-------------+---------+--------------+-------------------
(0 rows)
misskey=#
これで当該ユーザーの情報は消えましたので、再度参照し再取得することでとりあえずは適切にプロフィールを開けるようになりました。
当該ユーザーが過去に投稿したノートとかは違うユーザー扱い受けるので参照できませんが、今回はここまでにしておきます。
おわり
とりあえずダンプはできるようになりましたのでめでたしめでたし。
$ time docker exec [container] pg_dumpall -c -U misskey > dump.sql
real 5m11.371s
user 0m11.514s
sys 0m35.777s
$ du -h dump.sql
13G dump.sql
$
今のところダンプには6分程度時間がかかり、13GBのサイズらしいです。
次はバックアップ計画を考えなければなりませんね。
それはまたおいおい・・・。
おわり2
こういうDBの破損、本来ならば破損した時点でロールバックするべきなんだろうし、
修復するのも適当にレコード削除や初期値代入ではなく過去のデーターから値を再代入するべきなんだろうか・・・？
DBのレプリケーション組んでたらこういう1ノードだけ破損したって場合どういう挙動するんだろうか。