2.6.0 Beta4のアップデートがdbエラーのようなもので失敗しました

サポート インストール
1

Hi,

I just tried doing a command line ‘launcher rebuild app’ to update from 2.6.0.beta3 (7afb5be5f9), which has been running fine for a while, to 2.6.0.beta4 (as of 20 minutes ago). This is how I usually do my updates.

The update failed, please see output below. I tried running launcher rebuild once more, but it failed with the same error. Next I ran discourse-doctor, which also errored out on the rebuild, but which managed to start Discourse back up on 2.6.0.beta3.

Just to recap that last bit: I’m back up on 2.6.0.beta3 and the site is functioning. But I’m not about to try an update to 2.6.0.beta4 again until I understand what happened.

The launcher output says “database system was interrupted”, but Discourse was up and running fine when I started the launcher rebuild command.

Discourse resides on AWS EFS, so has virtually unlimited space. The server has 32 GB of memory, which is plenty for this site (about 1.3 million pageviews/month).

Appreciate any help and pointers in figuring this out.

Here’s the full output log from running rebuild:

gunnar@dewis:/var/discourse$ sudo ./launcher rebuild app

WARNING: We are about to start downloading the Discourse base image
This process may take anywhere between a few minutes to an hour, depending on your network speed

Please be patient

2.0.20201004-2310: Pulling from discourse/base
Digest: sha256:076ad6f035d7f38e08a2d4fdd4f429ad7a40a9cc72d9958445261cdb9e743d26
Status: Downloaded newer image for discourse/base:2.0.20201004-2310
docker.io/discourse/base:2.0.20201004-2310
Ensuring launcher is up to date
Fetching origin
remote: Enumerating objects: 15, done.
remote: Counting objects: 100% (15/15), done.
remote: Compressing objects: 100% (12/12), done.
remote: Total 15 (delta 5), reused 9 (delta 3), pack-reused 0
Unpacking objects: 100% (15/15), done.
From https://github.com/discourse/discourse_docker
   1b97cb1..468f1f9  master                 -> origin/master
 * [new branch]      imagemagick-policy-xml -> origin/imagemagick-policy-xml
Updating Launcher...
Updating 1b97cb1..468f1f9
Fast-forward
 samples/mail-receiver.yml | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)
Launcher updated, restarting...
Ensuring launcher is up to date
Fetching origin
Launcher is up-to-date
Stopping old container
+ /usr/bin/docker stop -t 60 app
app
cd /pups && git pull && /pups/bin/pups --stdin
Already up to date.
I, [2020-10-19T18:46:41.157056 #1]  INFO -- : Loading --stdin
I, [2020-10-19T18:46:41.162007 #1]  INFO -- : > locale-gen $LANG && update-locale
I, [2020-10-19T18:46:41.197444 #1]  INFO -- : Generating locales (this might take a while)...
Generation complete.

I, [2020-10-19T18:46:41.197650 #1]  INFO -- : > mkdir -p /shared/postgres_run
I, [2020-10-19T18:46:41.202176 #1]  INFO -- : 
I, [2020-10-19T18:46:41.202375 #1]  INFO -- : > chown postgres:postgres /shared/postgres_run
I, [2020-10-19T18:46:41.208709 #1]  INFO -- : 
I, [2020-10-19T18:46:41.208877 #1]  INFO -- : > chmod 775 /shared/postgres_run
I, [2020-10-19T18:46:41.215819 #1]  INFO -- : 
I, [2020-10-19T18:46:41.215957 #1]  INFO -- : > rm -fr /var/run/postgresql
I, [2020-10-19T18:46:41.219629 #1]  INFO -- : 
I, [2020-10-19T18:46:41.219800 #1]  INFO -- : > ln -s /shared/postgres_run /var/run/postgresql
I, [2020-10-19T18:46:41.222805 #1]  INFO -- : 
I, [2020-10-19T18:46:41.222936 #1]  INFO -- : > socat /dev/null UNIX-CONNECT:/shared/postgres_run/.s.PGSQL.5432 || exit 0 && echo postgres already running stop container ; exit 1
2020/10/19 18:46:41 socat[27] E connect(6, AF=1 "/shared/postgres_run/.s.PGSQL.5432", 36): Connection refused
I, [2020-10-19T18:46:41.237039 #1]  INFO -- : 
I, [2020-10-19T18:46:41.237173 #1]  INFO -- : > rm -fr /shared/postgres_run/.s*
I, [2020-10-19T18:46:41.292499 #1]  INFO -- : 
I, [2020-10-19T18:46:41.292674 #1]  INFO -- : > rm -fr /shared/postgres_run/*.pid
I, [2020-10-19T18:46:41.304292 #1]  INFO -- : 
I, [2020-10-19T18:46:41.304434 #1]  INFO -- : > mkdir -p /shared/postgres_run/12-main.pg_stat_tmp
I, [2020-10-19T18:46:41.310575 #1]  INFO -- : 
I, [2020-10-19T18:46:41.310782 #1]  INFO -- : > chown postgres:postgres /shared/postgres_run/12-main.pg_stat_tmp
I, [2020-10-19T18:46:41.317554 #1]  INFO -- : 
I, [2020-10-19T18:46:41.322287 #1]  INFO -- : File > /etc/service/postgres/run  chmod: +x  chown: 
I, [2020-10-19T18:46:41.326660 #1]  INFO -- : File > /etc/service/postgres/log/run  chmod: +x  chown: 
I, [2020-10-19T18:46:41.330737 #1]  INFO -- : File > /etc/runit/3.d/99-postgres  chmod: +x  chown: 
I, [2020-10-19T18:46:41.334906 #1]  INFO -- : File > /root/upgrade_postgres  chmod: +x  chown: 
I, [2020-10-19T18:46:41.335100 #1]  INFO -- : > chown -R root /var/lib/postgresql/12/main
I, [2020-10-19T18:46:42.155381 #1]  INFO -- : 
I, [2020-10-19T18:46:42.155536 #1]  INFO -- : > [ ! -e /shared/postgres_data ] && install -d -m 0755 -o postgres -g postgres /shared/postgres_data && sudo -E -u postgres /usr/lib/postgresql/12/bin/initdb -D /shared/postgres_data || exit 0
I, [2020-10-19T18:46:42.157629 #1]  INFO -- : 
I, [2020-10-19T18:46:42.157703 #1]  INFO -- : > chown -R postgres:postgres /shared/postgres_data
I, [2020-10-19T18:47:06.520719 #1]  INFO -- : 
I, [2020-10-19T18:47:06.520876 #1]  INFO -- : > chown -R postgres:postgres /var/run/postgresql
I, [2020-10-19T18:47:06.523564 #1]  INFO -- : 
I, [2020-10-19T18:47:06.523706 #1]  INFO -- : > /root/upgrade_postgres
I, [2020-10-19T18:47:06.540126 #1]  INFO -- : 
I, [2020-10-19T18:47:06.540286 #1]  INFO -- : > rm /root/upgrade_postgres
I, [2020-10-19T18:47:06.542555 #1]  INFO -- : 
I, [2020-10-19T18:47:06.543828 #1]  INFO -- : Replacing data_directory = '/var/lib/postgresql/12/main' with data_directory = '/shared/postgres_data' in /etc/postgresql/12/main/postgresql.conf
I, [2020-10-19T18:47:06.544330 #1]  INFO -- : Replacing (?-mix:#?listen_addresses *=.*) with listen_addresses = '*' in /etc/postgresql/12/main/postgresql.conf
I, [2020-10-19T18:47:06.545027 #1]  INFO -- : Replacing (?-mix:#?synchronous_commit *=.*) with synchronous_commit = $db_synchronous_commit in /etc/postgresql/12/main/postgresql.conf
I, [2020-10-19T18:47:06.545814 #1]  INFO -- : Replacing (?-mix:#?shared_buffers *=.*) with shared_buffers = $db_shared_buffers in /etc/postgresql/12/main/postgresql.conf
I, [2020-10-19T18:47:06.546523 #1]  INFO -- : Replacing (?-mix:#?work_mem *=.*) with work_mem = $db_work_mem in /etc/postgresql/12/main/postgresql.conf
I, [2020-10-19T18:47:06.547230 #1]  INFO -- : Replacing (?-mix:#?default_text_search_config *=.*) with default_text_search_config = '$db_default_text_search_config' in /etc/postgresql/12/main/postgresql.conf
I, [2020-10-19T18:47:06.547896 #1]  INFO -- : > install -d -m 0755 -o postgres -g postgres /shared/postgres_backup
I, [2020-10-19T18:47:06.561717 #1]  INFO -- : 
I, [2020-10-19T18:47:06.562046 #1]  INFO -- : Replacing (?-mix:#?checkpoint_segments *=.*) with checkpoint_segments = $db_checkpoint_segments in /etc/postgresql/12/main/postgresql.conf
I, [2020-10-19T18:47:06.562327 #1]  INFO -- : Replacing (?-mix:#?logging_collector *=.*) with logging_collector = $db_logging_collector in /etc/postgresql/12/main/postgresql.conf
I, [2020-10-19T18:47:06.563080 #1]  INFO -- : Replacing (?-mix:#?log_min_duration_statement *=.*) with log_min_duration_statement = $db_log_min_duration_statement in /etc/postgresql/12/main/postgresql.conf
I, [2020-10-19T18:47:06.564238 #1]  INFO -- : Replacing (?-mix:^#local +replication +postgres +peer$) with local replication postgres  peer in /etc/postgresql/12/main/pg_hba.conf
I, [2020-10-19T18:47:06.564505 #1]  INFO -- : Replacing (?-mix:^host.*all.*all.*127.*$) with host all all 0.0.0.0/0 md5 in /etc/postgresql/12/main/pg_hba.conf
I, [2020-10-19T18:47:06.565039 #1]  INFO -- : > HOME=/var/lib/postgresql USER=postgres exec chpst -u postgres:postgres:ssl-cert -U postgres:postgres:ssl-cert /usr/lib/postgresql/12/bin/postmaster -D /etc/postgresql/12/main
I, [2020-10-19T18:47:06.566806 #1]  INFO -- : > sleep 5
2020-10-19 18:47:06.629 UTC [50] LOG:  starting PostgreSQL 12.4 (Debian 12.4-1.pgdg100+1) on x86_64-pc-linux-gnu, compiled by gcc (Debian 8.3.0-6) 8.3.0, 64-bit
2020-10-19 18:47:06.629 UTC [50] LOG:  listening on IPv4 address "0.0.0.0", port 5432
2020-10-19 18:47:06.629 UTC [50] LOG:  listening on IPv6 address "::", port 5432
2020-10-19 18:47:06.665 UTC [50] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
2020-10-19 18:47:07.211 UTC [53] LOG:  database system was interrupted; last known up at 2020-10-19 18:40:46 UTC
I, [2020-10-19T18:47:11.568937 #1]  INFO -- : 
I, [2020-10-19T18:47:11.569207 #1]  INFO -- : > su postgres -c 'createdb discourse' || true
2020-10-19 18:47:11.636 UTC [57] postgres@postgres FATAL:  the database system is starting up
2020-10-19 18:47:11.638 UTC [58] postgres@template1 FATAL:  the database system is starting up
createdb: error: could not connect to database template1: FATAL:  the database system is starting up
I, [2020-10-19T18:47:11.640042 #1]  INFO -- : 
I, [2020-10-19T18:47:11.640270 #1]  INFO -- : > su postgres -c 'psql discourse -c "create user discourse;"' || true
2020-10-19 18:47:11.704 UTC [69] postgres@discourse FATAL:  the database system is starting up
psql: error: could not connect to server: FATAL:  the database system is starting up
I, [2020-10-19T18:47:11.706232 #1]  INFO -- : 
I, [2020-10-19T18:47:11.706429 #1]  INFO -- : > su postgres -c 'psql discourse -c "grant all privileges on database discourse to discourse;"' || true
2020-10-19 18:47:11.761 UTC [80] postgres@discourse FATAL:  the database system is starting up
psql: error: could not connect to server: FATAL:  the database system is starting up
I, [2020-10-19T18:47:11.763159 #1]  INFO -- : 
I, [2020-10-19T18:47:11.763357 #1]  INFO -- : > su postgres -c 'psql discourse -c "alter schema public owner to discourse;"'
2020-10-19 18:47:11.818 UTC [91] postgres@discourse FATAL:  the database system is starting up
psql: error: could not connect to server: FATAL:  the database system is starting up
I, [2020-10-19T18:47:11.819734 #1]  INFO -- : 
I, [2020-10-19T18:47:11.819998 #1]  INFO -- : Terminating async processes
I, [2020-10-19T18:47:11.820025 #1]  INFO -- : Sending INT to HOME=/var/lib/postgresql USER=postgres exec chpst -u postgres:postgres:ssl-cert -U postgres:postgres:ssl-cert /usr/lib/postgresql/12/bin/postmaster -D /etc/postgresql/12/main pid: 50
2020-10-19 18:47:11.820 UTC [50] LOG:  received fast shutdown request
I, [2020-10-19T18:47:21.820568 #1]  INFO -- : HOME=/var/lib/postgresql USER=postgres exec chpst -u postgres:postgres:ssl-cert -U postgres:postgres:ssl-cert /usr/lib/postgresql/12/bin/postmaster -D /etc/postgresql/12/main pid:50 did not terminate cleanly, forcing termination!


FAILED
--------------------
Pups::ExecError: su postgres -c 'psql discourse -c "alter schema public owner to discourse;"' failed with return #<Process::Status: pid 81 exit 2>
Location of failure: /pups/lib/pups/exec_command.rb:112:in `spawn'
exec failed with the params "su postgres -c 'psql $db_name -c \"alter schema public owner to $db_user;\"'"
809e00dc988196b9a3c0bfe215ff0ba30fa00056e1d2ad92818bc6b9d911df62
** FAILED TO BOOTSTRAP ** please scroll up and look for earlier error messages, there may be more than one.
./discourse-doctor may help diagnose the problem.
gunnar@dewis:/var/discourse$
「いいね！」 1
2

それは非常に特異な選択ですね。なぜ RDS を使わないのですか？

これはコンテナが正常にシャットダウンされなかった場合に発生します。そのため、PostgreSQL は次回起動時にリカバリ処理を実行する必要があります。

通常、この処理は非常に高速に行われますが、データベースが大きい場合（今回のケース）やディスクの速度が遅い場合（まさに今回のケース）は、処理に時間がかかりすぎて、再構築スクリプトが適切に対応できないことがあります。

簡単なリカバリ方法は、./launcher start appでコンテナを再度起動し、ある程度（例えば 1 時間程度）正常に動作させてから、後で再構築を試みるというものです。

「いいね！」 5
3

なぜなら、それをどう実装し始めてよいのか、全く見当がつかないからです。とはいえ、面白いアイデアだとは思います。

EFS は単なるファイルシステムなので、実装が簡単です。そして、少なくとも私たちの用途においては、通常の操作には十分な速度があります。少なくとも、私はそう思っていました。

はい、私もそう思っていました。興味深いのは、ランチャーを起動した際、Discourse はすでにしばらく実行されていたことです。つまり、PostgreSQL をシャットダウンしたのは、ランチャー・スクリプト自体だったのです。

わかりました、試してみます。ありがとうございます！

「いいね！」 2
4

最後のビルド（リビルド）はいつでしたか？

wait a bit more if necessary for container stop · discourse/discourse_docker@49ed141 · GitHub で、データベースが正常にシャットダウンするのを待つ時間を延長しました。そのため、そのコミットより前の状態だった場合は、この問題がよく発生していました。

「いいね！」 2
5

正確にはわかりませんが、その変更がコミットされた5月以降であることは確かです。おそらく1ヶ月前くらいでしょう。上記の出力には「-t 60」も表示されています。

さっきもう一度再構築を試してみたところ、今回は正常に完了しました。今後は再構築を実行する前に、PostgreSQL がアイドル状態、あるいはほぼアイドル状態であることを確認する必要があるようです。

ご支援いただき、ありがとうございました！

「いいね！」 2
6

なぜそれに気づかなかったのか、自分でも不思議です :man_facepalming:。
そのステップは60秒間完全に費やされ、その後継続したかどうか覚えていらっしゃいますか？

やった！

「いいね！」 1
7

確実には言えませんが、60秒ほどはかからなかったと思います。今後、再構築する際にはその点により注意を払います。

「いいね！」 2
8

This topic was automatically closed 30 days after the last reply. New replies are no longer allowed.