恢复失败 - 可能是数据资源管理器问题

我有一个正常运行的论坛,想恢复几天前出现的一些问题。我使用的是 AWS,所以我为正常运行的论坛创建了一个 AMI 镜像,启动了一个新实例,并尝试从几天前的备份进行恢复。但恢复失败了,报错信息如下:

这不可能是版本或架构不匹配的问题,因为该服务器是基于正常运行的论坛的全新镜像构建的。

我已经尝试过重新构建。

我也尝试过从仅一天前的另一个备份进行恢复,结果相同。

我唯一做过异常操作的是删除了上传目录(…/uploads/original/1X/*.pdf)中的 PDF 文件以释放一些空间。我会尝试在不执行该步骤的情况下再次恢复,但这似乎不太可能是罪魁祸首。

> [2019-11-30 01:17:44] 'admin' 已开始恢复!
> [2019-11-30 01:17:44] 将恢复状态标记为运行中...
> [2019-11-30 01:17:44] 确保 /var/www/discourse/tmp/restores/default/2019-11-30-011744 存在...
> [2019-11-30 01:17:44] 正在将归档文件下载到临时目录...
> [2019-11-30 01:23:24] 正在解压缩归档文件,这可能需要一些时间...
> [2019-11-30 01:27:52] 没有可提取的元数据文件。
> [2019-11-30 01:27:52] 正在验证元数据...
> [2019-11-30 01:27:52]   当前版本:20191129144706
> [2019-11-30 01:27:52]   待恢复版本:20191120015344
> [2019-11-30 01:27:52] 正在提取转储文件...
> [2019-11-30 01:50:57] 无效命令 \N
> [2019-11-30 01:50:57] 无效命令 \N
> 
> 
> < 重复约 100 次 >
> 
> [2019-11-30 01:51:07] 无效命令 \N
> [2019-11-30 01:54:13] 无效命令 \N
> [2019-11-30 01:54:13] 异常:psql 执行失败
> [2019-11-30 01:54:14] /var/www/discourse/lib/backup_restore/restorer.rb:331:in `restore_dump'
> /var/www/discourse/lib/backup_restore/restorer.rb:75:in `run'
> /var/www/discourse/lib/backup_restore.rb:166:in `block in start!'
> /var/www/discourse/lib/backup_restore.rb:163:in `fork'
> /var/www/discourse/lib/backup_restore.rb:163:in `start!'
> /var/www/discourse/lib/backup_restore.rb:22:in `restore!'
> /var/www/discourse/app/controllers/admin/backups_controller.rb:119:in `restore'
> 等等...

尽管如此,invalid command \N 错误通常是 PostgreSQL 版本不匹配的典型表现……

root@example:/var/www/discourse# psql --version
psql (PostgreSQL) 10.10 (Debian 10.10-1.pgdg100+1)

新服务器上的版本相同,论坛运行正常。

我本想将这些错误与 PostgreSQL 版本匹配问题联系起来,但前几天我在一个磁盘空间耗尽的系统上看到了这些 \N 错误(当时我正在将备份恢复到生成该备份的同一系统)。我未能完成问题诊断(当时我正遇到另一个怪异的问题,而将备份恢复到另一台服务器解决了该问题;我在想,如果恢复到同一台服务器是否也能解决问题)。

你提到你的磁盘空间不足。我怀疑这就是问题所在。恢复过程需要大量空间,因为它会解压缩备份,因此需要同时保留两份完整的备份副本,再加上恢复所需的空间,以及在恢复失败时能够回滚所需的空间。

所以它花了 23 分钟才失败?

情况更糟了,但这可能更接近真正的问题……假设我需要更多磁盘空间,我这次用 100 GB(之前是 50 GB)从镜像创建了一个新实例。(每个备份为 5 GB,存储在 S3 上。)这次我得到了一个明确的错误:“设备上没有剩余空间”。然而,df 命令显示还有大量可用空间。

> [2019-11-29 22:42:58] 确保 /var/www/discourse/tmp/restores/default/2019-11-29-224258 存在...
> [2019-11-29 22:42:58] 正在将归档下载到临时目录...
> [2019-11-29 22:45:46] 正在解压缩归档,这可能需要一些时间...
> [2019-11-29 22:51:46] 没有要提取的元数据文件。
> [2019-11-29 22:51:46] 正在验证元数据...
> [2019-11-29 22:51:46]   当前版本:20191129144706
> [2019-11-29 22:51:46]   恢复版本:20191108000414
> [2019-11-29 22:51:46] 正在提取转储文件...
> [2019-11-29 22:53:47] 异常:设备上没有剩余空间 @ io_write - /shared/tmp/restores/default/2019-11-29-224258/dump.sql

> [ec2-user@ip-172-31-47-237 discourse]$ df / -h
> 文件系统       容量   已用   可用  已用% 挂载点
> /dev/xvda1      99G   28G   71G   28%  /

有趣的是,所引用的目录中没有任何内容:

> /var/www/discourse# ls /shared/tmp/*
> /shared/tmp/backups:
> < 空 >
> /shared/tmp/restores:
> < 空 >

这会不会是交换文件的问题?EC2 实例是 t2.small,拥有 2 GB 内存,因此我很久以前就在正常运行的论坛上 创建了交换文件。我假设交换文件会在新的实例上被复制。我不是专家,但我认为交换文件确实存在,因为它不允许我创建新的交换文件,而且:

> /var/www/discourse# swapon -s
> 文件名                                类型            大小       已用     优先级
> /swapfile                               文件            2097148  1024     -2

可能是 inode 问题。df -i 显示什么?

df -i
Filesystem Inodes IUsed IFree IUse% Mounted on
devtmpfs 252562 437 252125 1% /dev
tmpfs 255203 1 255202 1% /dev/shm
/dev/xvda1 6553600 737194 5816406 12% /

超出我的专业范围了,但我猜这应该不算严重吧?

不,没关系。

“设备上没有剩余空间”不仅会在设备没有剩余 GB 时出现,还会在文件系统没有剩余 inodes 时出现。但显然这里不是这个问题。(如果是这种情况,iUse% 会达到 100%)。

仍然没有进展。我原本打算尝试在 Lightsail 新实例上恢复,而不是启动我正常运行的 EC2 实例的 AMI。它仍然失败,但错误信息略有不同。

旧实例和新实例都已更新到最新版本,两者都是 标准 Docker 安装,并且都运行相同版本的 PostgreSQL:

psql --version
psql (PostgreSQL) 10.10 (Debian 10.10-1.pgdg100+1)

以下情况正常吗:

Creating missing functions in the discourse_functions schema
Cannot restore into different schema, restoring in-place

这是否与插件有关?我在“源”站点上安装了多个插件,包括官方支持的插件和自定义插件。其中一些使用了自定义用户字段。我尝试在干净(有或无插件)的“目标”站点上进行恢复。

有什么建议可以开始比较模式(schema)吗?

> [2019-12-07 04:51:36] 'admin' has started the restore!
> [2019-12-07 04:51:36] Marking restore as running...
> [2019-12-07 04:51:36] Making sure /var/www/discourse/tmp/restores/default/2019-12-07-045136 exists...
> [2019-12-07 04:51:36] Downloading archive to tmp directory...
> [2019-12-07 04:53:49] Unzipping archive, this may take a while...
> [2019-12-07 04:57:12] No metadata file to extract.
> [2019-12-07 04:57:12] Validating metadata...
> [2019-12-07 04:57:12]   Current version: 20191129144706
> [2019-12-07 04:57:12]   Restored version: 20191120015344
> [2019-12-07 04:57:12] Extracting dump file...
> [2019-12-07 04:59:10] Creating missing functions in the discourse_functions schema
> [2019-12-07 04:59:11] Cannot restore into different schema, restoring in-place
> [2019-12-07 05:05:02] ERROR:  current transaction is aborted, commands ignored until end of transaction block
> [2019-12-07 05:05:03] ERROR:  current transaction is aborted, commands ignored until end of transaction block
> < 重复约 100 次 >
> [2019-12-07 05:05:03] ERROR:  current transaction is aborted, commands ignored until end of transaction block
> [2019-12-07 05:05:03] EXCEPTION: psql failed
> [2019-12-07 05:05:03] /var/www/discourse/lib/backup_restore/restorer.rb:331:in `restore_dump'
> /var/www/discourse/lib/backup_restore/restorer.rb:75:in `run'
> /var/www/discourse/lib/backup_restore.rb:166:in `block in start!'
> /var/www/discourse/lib/backup_restore.rb:163:in `fork'
> /var/www/discourse/lib/backup_restore.rb:163:in `start!'
> /var/www/discourse/lib/backup_restore.rb:22:in `restore!'
> /var/www/discourse/app/controllers/admin/backups_controller.rb:119:in `restore'
> < 其余堆栈跟踪 >

是的,这是正常的。

PostgreSQL 内部显然出现了问题。您查看过它的日志吗?

一个不太可能的推测:这是否与内存有关?您能否在恢复过程中监控 free -m 的输出,看看是否耗尽了(虚拟)内存?

我知道这是个棘手的问题,因为我们还不清楚具体问题是什么。但一般来说,我是否应该在尝试恢复之前先在目标站点安装插件?还是说恢复过程会自动拉取并构建插件?

是的,你应该这样做——恢复功能不会自动为你完成这一步。

不过,我认为这并不是你的问题所在,因为恢复过程正确处理正确的数据库结构(包括插件特定的内容)。

我创建了一台新的 20 美元 Lightsail 实例,配备 4GB 内存。在恢复过程中,我观察了 free -m 的输出,发现始终有充足的空闲和可用内存。

具体的错误会根据是否安装了插件而有所不同,但可能源于同一个根本原因。在这种情况下,我在备份之前没有安装插件。错误主要分为两类:

  1. 在 PostgreSQL 日志中,我看到了大量此类错误,有时出现在第 34 个字符处,有时出现在第 41 个字符处。

discourse@discourse ERROR: relation “user_auth_tokens” does not exist at character 34

这些错误在 管理后台 > 备份 > 日志 页面中没有对应的输出,尽管出现这些错误,恢复过程仍继续进行了几分钟。

  1. 第二种错误取决于是否安装了插件。在这种情况下,我没有安装它们,因此收到了关于 Data Explorer 的错误,随后问题彻底爆发。

在 管理后台 > 备份 > 日志 中:

[2019-12-07 07:38:34] CREATE INDEX
[2019-12-07 07:38:34] CREATE INDEX
[2019-12-07 07:38:34] ERROR: could not create unique index “index_plugin_store_rows_on_plugin_name_and_key”
[2019-12-07 07:38:34] DETAIL: Key (plugin_name, key)=(discourse-data-explorer, q:-6) is duplicated.
[2019-12-07 07:38:34] ERROR: current transaction is aborted, commands ignored until end of transaction block
[2019-12-07 07:38:34] ERROR: current transaction is aborted, commands ignored until end of transaction block
< 重复 1000 次后退出 >

PostgreSQL 日志中的对应输出:

2019-12-07 07:38:34.718 UTC [8991] discourse@discourse LOG: duration: 165.427 ms statement: CREATE INDEX index_notifications_on_user_
id_and_topic_id_and_post_number ON public.notifications USING btree (user_id, topic_id, post_number);
2019-12-07 07:38:34.767 UTC [8991] discourse@discourse ERROR: could not create unique index “index_plugin_store_rows_on_plugin_name_an
d_key”
2019-12-07 07:38:34.767 UTC [8991] discourse@discourse DETAIL: Key (plugin_name, key)=(discourse-data-explorer, q:-6) is duplicated.
2019-12-07 07:38:34.767 UTC [8991] discourse@discourse STATEMENT: CREATE UNIQUE INDEX index_plugin_store_rows_on_plugin_name_and_key O
N public.plugin_store_rows USING btree (plugin_name, key);
2019-12-07 07:38:34.984 UTC [8991] discourse@discourse ERROR: current transaction is aborted, commands ignored until end of transactio
n block
2019-12-07 07:38:34.984 UTC [8991] discourse@discourse STATEMENT: CREATE INDEX index_policy_users_on_post_policy_id_and_user_id ON pub
lic.policy_users USING btree (post_policy_id, user_id);

我认为 #1 不是致命错误,只是原地恢复带来的副作用。

在创建备份之前,您可以考虑(导出并)删除所有数据探索器查询,并移除数据探索器插件。

或者,您能发布 plugin_store_rows 表中的相关内容吗?

确实存在具有重复 (plugin_name, key) 对的重复查询,例如 q:-11 和 q:-2,但它们的 id 是唯一的。我在这些重复项中没有发现任何模式,比如它们并不是我最喜欢的查询之类的。

因此,我的下一步将是删除重复项,进行备份,然后尝试从中恢复。

SELECT id, plugin_name, key from plugin_store_rows
WHERE plugin_name = ‘discourse-data-explorer’
ORDER BY key

id plugin_name key
1138 discourse-data-explorer q:-1
1136 discourse-data-explorer q:-10
813 discourse-data-explorer q:10
1142 discourse-data-explorer q:-11
1397 discourse-data-explorer q:-11
825 discourse-data-explorer q:11
889 discourse-data-explorer q:13
1004 discourse-data-explorer q:14
1005 discourse-data-explorer q:15
1043 discourse-data-explorer q:17
1044 discourse-data-explorer q:18
514 discourse-data-explorer q:-2
1249 discourse-data-explorer q:-2
764 discourse-data-explorer q:2
1053 discourse-data-explorer q:21
1066 discourse-data-explorer q:22
1082 discourse-data-explorer q:23
1097 discourse-data-explorer q:24
1131 discourse-data-explorer q:26
1132 discourse-data-explorer q:27
1134 discourse-data-explorer q:28
1135 discourse-data-explorer q:29
775 discourse-data-explorer q:3
1137 discourse-data-explorer q:30
1140 discourse-data-explorer q:31
1141 discourse-data-explorer q:32
1143 discourse-data-explorer q:33
1149 discourse-data-explorer q:34
1155 discourse-data-explorer q:35
1156 discourse-data-explorer q:36
1157 discourse-data-explorer q:37
1158 discourse-data-explorer q:38
1161 discourse-data-explorer q:39
513 discourse-data-explorer q:-4
777 discourse-data-explorer q:4
1211 discourse-data-explorer q:40
1215 discourse-data-explorer q:41
1223 discourse-data-explorer q:42
1224 discourse-data-explorer q:43
1225 discourse-data-explorer q:44
1226 discourse-data-explorer q:45
1269 discourse-data-explorer q:46
1272 discourse-data-explorer q:47
1273 discourse-data-explorer q:48
1274 discourse-data-explorer q:49
1279 discourse-data-explorer q:50
1281 discourse-data-explorer q:51
1282 discourse-data-explorer q:52
1301 discourse-data-explorer q:53
1349 discourse-data-explorer q:54
1369 discourse-data-explorer q:55
1373 discourse-data-explorer q:56
1384 discourse-data-explorer q:57
1387 discourse-data-explorer q:58
1396 discourse-data-explorer q:59
1222 discourse-data-explorer q:-6
1348 discourse-data-explorer q:-6
781 discourse-data-explorer q:6
763 discourse-data-explorer q:-7
782 discourse-data-explorer q:7
515 discourse-data-explorer q:-8
791 discourse-data-explorer q:8
1139 discourse-data-explorer q:-9
798 discourse-data-explorer q:9
507 discourse-data-explorer q:_id

实际上,我该如何删除重复项?这三项的所有者都是“system”,所以我无法编辑或删除它们。

找到规律了。当我运行由系统拥有的查询时,会创建一个重复项,这显然会导致恢复失败。

在干净的测试站点上我无法复现此问题,但在生产站点上它始终发生。我已在测试站点上安装了所有生产环境的插件,但仍无法复现。

  1. 我该如何排查生产站点的问题所在?

  2. 我该如何移除重复的查询?由于这些查询属于系统,我是否需要执行 sudo -u postgres psql discourse…?听起来有点吓人。

为了使备份可恢复,您可能需要从备份的 SQL 文件中删除重复的行。

开发数据库可能由于某种原因缺少该索引?