ラベル PostgreSQL の投稿を表示しています。 すべての投稿を表示
ラベル PostgreSQL の投稿を表示しています。 すべての投稿を表示

2016-05-31

Slony-I 2.0: `cleanupEvent' causes deadlock

Slony-I 2.0.6 + 同期復旧 patch を使うようになって以降、割と平穏な日々を過ごしてきた。

しかし実はまだ 1 つ、既知の問題が残っている。Slony-I 2.0 系は、deadlock を起こすことがある。

いつか直らないかと気に掛けていたものの、一向に直る気配もなく今に至る。そうこうしているうちに何年かぶりに再発したため、今更ながら調べることにした。

面倒なのでソースコード引用は省略。発生条件は、slon が 10 分毎に実行する clenaupEvent 処理と、slonik の実行が衝突すること。slonik を使わない、または slonik 実行時に slon が停止していれば発生することはない。(たぶん)

deadlock の原因は、当たり前だが、それぞれの処理でロックの取得順が異なることに因る。それぞれのロック取得順は次のようになる。

  • slonik コマンド: sl_config_lock → sl_event (一部の slonik コマンドを除く)
  • slon cleanupEvent: sl_event → sl_config_lock

分かってしまえば解決は難しくない。それぞれのロック取得順を合わせてやれば良い。今回の場合、cleanupEvent 処理の最初で sl_config_lock のロックを取得するのが簡単だろう。

--- slony1-2.0.6/src/backend/slony1_funcs.sql.orig	2010-12-08 01:44:09.000000000 +0900
+++ slony1-2.0.6/src/backend/slony1_funcs.sql	2016-05-31 17:35:22.000000000 +0900
@@ -4478,6 +4478,11 @@
 	v_rc            int8;
 begin
 	-- ----
+	-- Grab the central configuration lock
+	-- ----
+	lock table @NAMESPACE@.sl_config_lock;
+
+	-- ----
 	-- First remove all confirmations where origin/receiver no longer exist
 	-- ----
 	delete from @NAMESPACE@.sl_confirm

とは言っても、元々 deadlock が発生すること自体が稀なため、本当に直ったのか確認することは難しい。正直、「直ったらラッキー」程度に考えている。

ちなみに Slony-I 2.1 以降はロック機構がガラリと変わっており、以上のことは当てはまらない。(deadlock が起こらないかは知らない)

2015-11-30

RHEL7: Old PostgreSQL's initdb fails

下記の環境で PostgreSQL 8.4.17 をビルドすると、

# cat /etc/redhat-release
Red Hat Enterprise Linux Server release 7.1 (Maipo)

# rpm -q gcc
gcc-4.8.3-9.el7.x86_64

initdb コマンドでエラーが発生。

# su - postgres -c "/usr/local/pgsql-8.4.17/bin/initdb -E UTF8 --no-locale -D ./data" ; echo $?
The files belonging to this database system will be owned by user "postgres".
This user must also own the server process.

The database cluster will be initialized with locale C.
The default text search configuration will be set to "english".

creating directory ./data ... ok
creating subdirectories ... ok
selecting default max_connections ... 100
selecting default shared_buffers ... 32MB
creating configuration files ... ok
creating template1 database in ./data/base/1 ... ok
initializing pg_authid ... FATAL:  wrong number of index expressions
STATEMENT:  CREATE TRIGGER pg_sync_pg_database   AFTER INSERT OR UPDATE OR DELETE ON pg_database   FOR EACH STATEMENT EXECUTE PROCEDURE flatfile_update_trigger();

child process exited with exit code 1
initdb: removing data directory "./data"
1

調べると、GCC 4.8 で発生するらしい。

上記では、結局 GCC 4.7 でないと駄目だった模様。他のネット情報を見ても、大体「GCC 4.7 使え」的な感じ。しかし RHEL7 DVD には GCC 4.7 が入っていないので、解決策がそれだと(個人的に)非常に困る。:-(

という状況で、駄目元で 8.4 系の最新(8.4.22)を取ってきたら、何事もなく動いた。助かった! :-D

該当の部分は多分これ。PostgreSQL 8.4 系では、8.4.18 で入っている。一応、8.4.18 で initdb が動くことは確認した。

現時点で、8.2 / 8.3 の HEAD に対しても同様の修正が入っている。私のように困っている人は、HEAD を落としてくると幸せになれるかも。

2012-11-21

psycopg2: Can't mogrify `None' in a tuple to `NULL'

RHEL6 付属の psycopg2 で、

# rpm -qa | grep psycopg
python-psycopg2-2.0.13-2.el6_1.1.x86_64

tuple 中にある None を mogrify するとエラーになる。

test1.py:

#!/usr/bin/python

import psycopg2.extensions

def main():
    conn = psycopg2.connect('dbname=testdb user=testuser')
    cur = conn.cursor()
    for param in [0, [0], (0,), '', [''], ('',), None, [None], (None,)]:
        print '%s\t->' % repr(param), cur.mogrify('%s', [param])

if __name__ == '__main__':
    main()
$ python test1.py
0       -> 0
[0]     -> ARRAY[0]
(0,)    -> (0)
''      -> E''
['']    -> ARRAY[E'']
('',)   -> (E'')
None    -> NULL
[None]  -> ARRAY[NULL]
(None,) ->
Traceback (most recent call last):
  File "/root/tmp/test1.py", line 12, in <module>
    main()
  File "/root/tmp/test1.py", line 9, in main
    print '%s\t->' % repr(param), cur.mogrify('%s', [param])
  File "/usr/lib64/python2.6/site-packages/psycopg2/extensions.py", line 100, in getquoted
    qobjs = [str(o.getquoted()) for o in pobjs]
AttributeError: 'str' object has no attribute 'getquoted'

落ちている場所は、

/usr/lib64/python2.6/site-packages/psycopg2/extensions.py:

# The SQL_IN class is the official adapter for tuples starting from 2.0.6.
class SQL_IN(object):
    """Adapt any iterable to an SQL quotable object."""

    def __init__(self, seq):
        self._seq = seq

    def prepare(self, conn):
        self._conn = conn

    def getquoted(self):
        # this is the important line: note how every object in the
        # list is adapted and then how getquoted() is called on it
        pobjs = [adapt(o) for o in self._seq]
        for obj in pobjs:
            if hasattr(obj, 'prepare'):
                obj.prepare(self._conn)
        qobjs = [str(o.getquoted()) for o in pobjs]
        return '(' + ', '.join(qobjs) + ')'

    __str__ = getquoted

register_adapter(tuple, SQL_IN)

print デバッグすると直ぐに分かるが、このとき o には 'NULL' という文字列(str 型)が入っている。当然、単なる文字列に getquoted なんてメソッドがあるはずがない。そりゃ落ちるわ。

何がどうあるべきなのかは分からないが、「動かないシステムに価値はない」の持論に従い、ともかく動くようにする。

test2.py:

#!/usr/bin/python

import psycopg2.extensions

# Fix a bug that can't mogrify `None' in a tuple to `NULL'
class FIXED_SQL_IN(object):
    def __init__(self, seq):
        self._seq = seq

    def prepare(self, conn):
        self._conn = conn

    def getquoted(self):
        adapt = psycopg2.extensions.adapt
        pobjs = [adapt(o) for o in self._seq]
        for obj in pobjs:
            if hasattr(obj, 'prepare'):
                obj.prepare(self._conn)
        qobjs = [getattr(o, 'getquoted', o.__str__)() for o in pobjs]
        return '(' + ', '.join(qobjs) + ')'

    __str__ = getquoted

psycopg2.extensions.register_adapter(tuple, FIXED_SQL_IN)

def main():
    conn = psycopg2.connect('dbname=testdb user=testuser')
    cur = conn.cursor()
    for param in [0, [0], (0,), '', [''], ('',), None, [None], (None,)]:
        print '%s\t->' % repr(param), cur.mogrify('%s', [param])

if __name__ == '__main__':
    main()
$ python test2.py
0       -> 0
[0]     -> ARRAY[0]
(0,)    -> (0)
''      -> E''
['']    -> ARRAY[E'']
('',)   -> (E'')
None    -> NULL
[None]  -> ARRAY[NULL]
(None,) -> (NULL)

ということを、実は 2 年くらい前に RHEL5 + psycopg2-2.0.12 (from rpmforge)という組み合わせでやっていたのだが、最近になって検索すると次が出てきた。

本件は psycopg2-2.4 で直っている模様。しかし私が試した限り、この変更部分を 2.0 系に持ってきても動かない。None に対してアダプターを登録しても、全く動く気配がない。None に対するアダプターが動くようになる変更が 2.4 までの何処かに入ったのかも知れないが、私的にはもう上述の方法で解決しているのでこれ以上は調べる気なし。

2012-06-27

Slony-I: duplicate key value violates unique constraint "sl_nodelock-pkey", part 2

Slony-I (slon)が起動しなくなることがある。ログには、

2012-05-16 14:08:46.60711 FATAL  localListenThread: "select "_slony1".cleanupNodelock(); insert into "_slony1".sl_nodelock values (    1, 0, "pg_catalog".pg_backend_pid()); " - ERROR:  duplicate key value violates unique constraint "sl_nodelock-pkey"

こうなった時の復旧方法は、以前のエントリを参照。

以前から年に 1 回くらい起こっていて、サーバー再起動で復旧した後はパッタリ起こらなくなるため、そのうち(Slony-I 側で)直るだろうと気楽に考えていた。しかしいくら待っても一向に直る気配がなく、もういい加減に我慢ならなくなったので、ようやく重い腰を上げて調べることにした。

結果から先に言うと、Apache httpd, PostgreSQL での already running 現象と原因は同じ。これらの詳細については以前のエントリを参照。

Slony-I は、ファイルではなくデータベース(sl_nodelock テーブル)に PID を保存する。そして、slon 起動時にその cleanup 処理を行っている。ソースコードでは次の部分。(Slony-I 2.0.7 以降は使ってないので知らない)

slony1-2.0.6/src/backend/slony1_funcs.sql:

create or replace function @NAMESPACE@.cleanupNodelock ()
returns int4
as $$
declare
    v_row        record;
begin
    for v_row in select nl_nodeid, nl_conncnt, nl_backendpid
            from @NAMESPACE@.sl_nodelock
            for update
    loop
        if @NAMESPACE@.killBackend(v_row.nl_backendpid, 'NULL') < 0 then
            raise notice 'Slony-I: cleanup stale sl_nodelock entry for pid=%',
                    v_row.nl_backendpid;
            delete from @NAMESPACE@.sl_nodelock where
                    nl_nodeid = v_row.nl_nodeid and
                    nl_conncnt = v_row.nl_conncnt;
        end if;
    end loop;

    return 0;
end;
$$ language plpgsql;

killBackend(v_row.nl_backendpid, 'NULL') の結果が負になれば、行が delete される。killBackend の実装は C で書かれていて、

slony1-2.0.6/src/backend/slony1_funcs.c:

Datum
_Slony_I_killBackend(PG_FUNCTION_ARGS)
{
    int32        pid;
    int32        signo;
    text       *signame;

    if (!superuser())
        elog(ERROR, "Slony-I: insufficient privilege for killBackend");

    pid = PG_GETARG_INT32(0);
    signame = PG_GETARG_TEXT_P(1);

    if (VARSIZE(signame) == VARHDRSZ + 4 &&
        memcmp(VARDATA(signame), "NULL", 0) == 0)
    {
        signo = 0;
    }
    else if (VARSIZE(signame) == VARHDRSZ + 4 &&
             memcmp(VARDATA(signame), "TERM", 0) == 0)
    {
        signo = SIGTERM;
    }
    else
    {
        signo = 0;
        elog(ERROR, "Slony-I: unsupported signal");
    }

    if (kill(pid, signo) < 0)
        PG_RETURN_INT32(-1);

    PG_RETURN_INT32(0);
}

第 2 引数が "NULL" だと kill -0 が実行される。よってこの関数の返値は、プロセスが存在すれば 0、存在しなければ -1 となる。そのプロセスが slon であるかは関係ない。その結果、プロセスが存在すると sl_nodelock に行が残り、その後 slon が自身の PID を insert する際に duplicate error が発生することになる。

これは Apache httpd と同じロジックだ。しかし、Slony-I は httpd よりも 重大な問題 を抱えている。

  • slon は、例え正常終了であっても、終了時にロックを削除しない。
  • ロックはデータベース内にあるため、サーバー再起動では決して削除されない。

この合わせ技はかなり凶悪だ。想像してみよう。サーバーを再起動したとする。slon は正常終了するがロックは残ったままだ。次回 slon 起動時、ロックに残っている PID を持つプロセスが 存在しなければ slon は起動する。

怖すぎる。いくらサーバー起動時のプロセス起動順は滅多に変わらないと言っても、これでは「起動する方が運が良い」と言っていい。今まで知らずに slon を普通に起動していたかと思うと、背筋が寒くなる。

まさか Slony-I がこんなお粗末な二重起動チェックを行っているとは思わなかった。信じてたのに。せめてエラーログがもっと分かり易ければ早くに気付けたが、duplicate error でそれに気付けというのは難度が高過ぎだろう。

ということで、やはり起動スクリプトでロックを削除することになる。ロックの削除は、例えばこんな感じ。

DBHOST=localhost
DBUSER=postgres
DBNAME=testdb
CLUSTER=slony1

cleanup_local_nodelock() {
    echo 'cleanup sl_nodelock entry for local node'
    psql -h $DBHOST -U $DBUSER -d $DBNAME <<EOF
DELETE FROM _$CLUSTER.sl_nodelock
 WHERE nl_nodeid = (SELECT _$CLUSTER.getLocalNodeId('_$CLUSTER'))
   AND nl_conncnt = 0;
EOF
}

当然、ロックを削除する前には自力で二重起動をチェックする必要がある。この辺は起動スクリプトの内容にも依存するため、各自で頑張って実装して欲しい。私の知る限り Slony-I には 2 つの起動スクリプトが同梱(redhat/slony1.init, tools/start_slon.sh)されているし、起動スクリプトを自作していることも多いだろう。私の場合は、例によって runit なので(略)。

さて、今回の一連(Apache httpd, PostgreSQL, Slony-I)から得られた教訓は、

標準の二重起動チェックを信用するな。

PID ファイルを使って二重起動チェックを行うものは多いが、もし重要なサービスがあるなら、存在するプロセスの PID で PID ファイルを偽造してみて、サービスが起動するかどうか確認してみることをお勧めする。

2012-06-15

PostgreSQL: lock file "postmaster.pid" already exists

PostgreSQL が起動しなくなることがある。ログには、

2012-06-15 09:52:59 GMT  [6133]: FATAL:  lock file "postmaster.pid" already exists
2012-06-15 09:52:59 GMT  [6133]: HINT:  Is another postmaster (PID 2225) running in data directory "/var/lib/pgsql/data"?

原因は、Apache httpd の時と同じ。

ソースコードでは次の部分。(PostgreSQL 9.0 以降は使ってないので知らない)

postgresql-8.4.11/src/backend/utils/init/miscinit.c:

static void
CreateLockFile(const char *filename, bool amPostmaster,
               bool isDDLock, const char *refName)
{

    /* ...snip... */

        /*
         * Check to see if the other process still exists
         *
         * If the PID in the lockfile is our own PID or our parent's PID, then
         * the file must be stale (probably left over from a previous system
         * boot cycle).  We need this test because of the likelihood that a
         * reboot will assign exactly the same PID as we had in the previous
         * reboot.    Also, if there is just one more process launch in this
         * reboot than in the previous one, the lockfile might mention our
         * parent's PID.  We can reject that since we'd never be launched
         * directly by a competing postmaster.    We can't detect grandparent
         * processes unfortunately, but if the init script is written
         * carefully then all but the immediate parent shell will be
         * root-owned processes and so the kill test will fail with EPERM.
         *
         * We can treat the EPERM-error case as okay because that error
         * implies that the existing process has a different userid than we
         * do, which means it cannot be a competing postmaster.  A postmaster
         * cannot successfully attach to a data directory owned by a userid
         * other than its own.    (This is now checked directly in
         * checkDataDir(), but has been true for a long time because of the
         * restriction that the data directory isn't group- or
         * world-accessible.)  Also, since we create the lockfiles mode 600,
         * we'd have failed above if the lockfile belonged to another userid
         * --- which means that whatever process kill() is reporting about
         * isn't the one that made the lockfile.  (NOTE: this last
         * consideration is the only one that keeps us from blowing away a
         * Unix socket file belonging to an instance of Postgres being run by
         * someone else, at least on machines where /tmp hasn't got a
         * stickybit.)
         *
         * Windows hasn't got getppid(), but doesn't need it since it's not
         * using real kill() either...
         *
         * Normally kill() will fail with ESRCH if the given PID doesn't
         * exist.
         */
        if (other_pid != my_pid
#ifndef WIN32
            && other_pid != getppid()
#endif
            )
        {
            if (kill(other_pid, 0) == 0 ||
                (errno != ESRCH && errno != EPERM))
            {
                /* lockfile belongs to a live process */
                ereport(FATAL,
                        (errcode(ERRCODE_LOCK_FILE_EXISTS),
                         errmsg("lock file \"%s\" already exists",
                                filename),
                         isDDLock ?
                         (encoded_pid < 0 ?
                          errhint("Is another postgres (PID %d) running in data directory \"%s\"?",
                                  (int) other_pid, refName) :
                          errhint("Is another postmaster (PID %d) running in data directory \"%s\"?",
                                  (int) other_pid, refName)) :
                         (encoded_pid < 0 ?
                          errhint("Is another postgres (PID %d) using socket file \"%s\"?",
                                  (int) other_pid, refName) :
                          errhint("Is another postmaster (PID %d) using socket file \"%s\"?",
                                  (int) other_pid, refName))));
            }
        }

ちょっと長いが、全てはコメント部に書いてある。やはり PID ファイルにあるプロセスの存在をチェックしているが、httpd との違いはプロセスの所有者まで見ていること。プロセスの所有者が異なれば、二重起動とは見なさない。

PostgreSQL が postgres ユーザーで起動するようになっている場合、postgres ユーザーで起動するプロセスは基本的に PostgreSQL しかないはず。よって PostgreSQL を複数起動しているのでもない限り、この現象に遭遇することはまずない。私の場合、PostgreSQL を起動している runit の logger プロセス(svlogd)を postgres ユーザーで起動しており、運良く:-)この現象に遭遇した。

PostgreSQL を複数起動させたり、postgres ユーザーで他にプロセスを起動しているのであれば、httpd の時と同じく起動スクリプトで PID ファイルを削除した方が良いだろう。

その場合、やはり二重起動チェックを自力で行うことになるが、pg_ctl status はその用途には役に立たない(たぶん上記のコードを通るのだと思われる)。その代わり PostgreSQL は $PGDATA が一意となるので、プロセスのコマンドラインや環境変数を見る(/proc/<PID>/{cmdline,environ})と良いかも知れない。

例によって私は runit を使っていて二重起動チェックとは無縁なので、実際に動くコードは載せられない。

2012-02-27

Slony-I 2.0.7: EXECUTE SCRIPT is terribly slow

あるとき PostgreSQL が死ぬほど遅くなった。思えば PostgreSQL も Slony-I もアップグレードしたし、 VM の CPU 割り当て個数も変えた。そう言えばアンチウィルスもアップグレードした。もう心当たりがあり過ぎて、何が原因なのか切り分けるのも面倒臭え。

しかし観察していると、PostgreSQL が止まっている間、PostgreSQL が CPU を使い切っている。いったい何を?と pg_stat_activity を覗くと、

testdb=# select * from pg_stat_activity;
 datid  | datname | procpid | usesysid | usename  |                     current_query                      | waiting |          xact_start           |          query_start          |         backend_start         | client_addr | client_port
--------+---------+---------+----------+----------+--------------------------------------------------------+---------+-------------------------------+-------------------------------+-------------------------------+-------------+-------------
 415435 | testdb  |    5255 |    16389 | slony    | <IDLE>                                                 | f       |                               | 2012-02-24 19:48:07.394428+09 | 2012-02-24 19:22:35.865852+09 | 127.0.0.1   |       48965
 415435 | testdb  |    5260 |    16389 | slony    | <IDLE>                                                 | f       |                               | 2012-02-24 19:22:36.307407+09 | 2012-02-24 19:22:36.034956+09 | 127.0.0.1   |       48966
 415435 | testdb  |    5261 |    16389 | slony    | <IDLE>                                                 | f       |                               | 2012-02-24 19:45:36.396714+09 | 2012-02-24 19:22:36.03749+09  | 127.0.0.1   |       48968
 415435 | testdb  |    9887 |    16389 | slony    | select "_slony1".ddlScript_complete(1, $1::text, -1);  | f       | 2012-02-24 19:48:01.33087+09  | 2012-02-24 19:48:01.349439+09 | 2012-02-24 19:48:01.325438+09 | **.***.*.** |       43807
 415435 | testdb  |    5262 |    16389 | slony    | select "_slony1".createEvent('_slony1', 'SYNC', NULL); | t       | 2012-02-24 19:48:08.113728+09 | 2012-02-24 19:48:08.113921+09 | 2012-02-24 19:22:36.044133+09 | 127.0.0.1   |       48969
 415435 | testdb  |    4417 |       10 | postgres | select * from pg_stat_activity;                        | f       | 2012-02-24 19:48:08.321619+09 | 2012-02-24 19:48:08.321619+09 | 2012-02-24 19:17:32.972981+09 |             |          -1
(6 rows)

Slony-I が犯人っぽい。多分、2.0.6 -> 2.0.7 で入ったコレが原因。

この変更によって、EXECUTE SCRIPT の実行に最大 30 秒かかるようになった。連続で EXECUTE SCRIPT を流すと、2 回目以降の EXECUTE SCRIPT は確実に 30 秒かかる。

もちろん Slony-I に悪意はない。EXECUTE SCRIPT で主キーを変更すると同期が壊れる問題の対処として、EXECUTE SCRIPT を実行するタイミングを変更したのだろう。EXECUTE SCRIPT なんて滅多に実行しないはずだから、30 秒かかるくらいは大した問題ではない、と。しかし、

私には大問題だー! :-(

私のシステムは大量の DDL を使う。それも複数の DDL を纏めて流すのではなく、それぞれの DDL を個々に EXECUTE SCRIPT で流す。そうして、いつもなら 5 分で終わる処理が、1 時間かかるようになった。orz

そもそも 2.0.7 に上げたのには理由がある。2.0.6 には、一方のサーバーを再起動するだけで同期が停止する という、非同期レプリケーションとしてあるまじき致命的な不具合がある(slon 再起動で復旧する)。この問題だけは放置できない。しかし EXECUTE SCRIPT の問題も、私にとっては大問題だ。

ひとしきり悩んだ結果、2.0.7 から bug 217 の修正を除去するのは面倒そうなので、2.0.6 に同期復旧の patch だけを当てることにした。

さて、今後のアップグレードはどうしたもんか・・・。


2016-06-07 追記

今更の更新だが、この EXECUTE SCRIPT が遅い問題は、下記の patch で解決する。ddlScript_complete_int 中の 1 行をコメントアウトするだけで良い。

--- slony1-2.0.8/src/backend/slony1_funcs.sql.orig	2014-04-09 08:18:17.000000000 +0900
+++ slony1-2.0.8/src/backend/slony1_funcs.sql	2016-06-07 20:09:32.000000000 +0900
@@ -3800,7 +3800,7 @@
 	v_row				record;
 begin
 	perform @NAMESPACE@.updateRelname(p_set_id, p_only_on_node);
-	perform @NAMESPACE@.repair_log_triggers(true);
+	-- perform @NAMESPACE@.repair_log_triggers(true);
 	return p_set_id;
 end;
 $$ language plpgsql;

2.1.4 で動作することも確認している。2.2.x は未確認だが、たぶん問題ないと思う。

もちろん、これは「EXECUTE SCRIPT で主キーを変更しない」ことが条件となる。仮に主キーの変更が必要になったとしても、そのテーブルを一旦 Slony-I から外して主キーを変更し、Slony-I に再登録すれば良い。テーブルの再構築は発生してしまうが、EXUCUTE SCRIPT に 30 秒かかることに比べれば、私にとっては問題でない。そもそも主キーなんてそうそう変更しないし。

2012-02-22

Slony-I: duplicate key value violates unique constraint "sl_nodelock-pkey", part 1

Slony-I をアップグレードしたら、エラーが発生するようになった。

2012-02-22 12:15:13.37963 FATAL  localListenThread: "select "_slony1".cleanupNodelock(); insert into "_slony1".sl_nodelock values (    1, 0, "pg_catalog".pg_backend_pid()); " - ERROR:  duplicate key value violates unique constraint "sl_nodelock-pkey"

slon 再起動でも復旧しない。公式ドキュメントによると、

This error message is typically a sign that you have started up a second slon process for a given node. The slon asks the obvious question: "Do you already have a slon running against this node?"

Supposing you experience some sort of network outage, the connection between slon and database may fail, and the slon may figure this out long before the PostgreSQL instance it was connected to does. The result is that there will be some number of idle connections left on the database server, which won't be closed out until TCP/IP timeouts complete, which seems to normally take about two hours. For that two hour period, the slon will try to connect, over and over, and will get the above fatal message, over and over.

とのことだが、今回の場合には二重起動もネットワークエラーもあり得ない。サーバーを再起動しても直らないし。エラーになる前にやったことは、

  1. slave: stop slon
  2. slave: upgrade Slony-I 2.0.6 -> 2.0.7
  3. slave: reboot (start slon)
  4. master: stop slon
  5. master: upgrade Slony-I 2.0.6 -> 2.0.7
  6. master: reboot (start slon)

で、master 側がエラーになる。今まで 2 回起こったので、再現性はあるような気がする。いつか調べるハメになるかも知れないが、まずは復旧させないと。

# psql -U postgres testdb
testdb=# select * from _slony1.sl_nodelock;
 nl_nodeid | nl_conncnt | nl_backendpid
-----------+------------+---------------
         2 |        184 |          2608
         2 |        185 |          2593
         2 |        186 |         11678
         1 |          0 |          2583
         2 |        183 |          2606
(5 rows)

testdb=# delete from _slony1.sl_nodelock where nl_nodeid = 1 and nl_conncnt = 0;
DELETE 1
testdb=# \q

sl_nodelock から duplicate しているレコードを削除して、slon を再起動すれば復旧する。


2012-06-27 追記

いつか調べるハメになるかも知れないが、まずは復旧させないと。

調べた。