Hello,
I'm trying to set up archiveopteryx, for the first time. (I'm using the git version, because using the 3.2.0 release, the server would not start properly, giving the same error message as mentioned in <http://archives.aox.org/archives/mailstore-users/4786/thread>.) Installation seemed to go OK. However, the server halts, after only a few seconds uptime. I can just manage to log in (using telnet) before that time, but after that, "aox show status" reports stopped logd and archive daemons, and I can no longer log in. There does not seem to be anything relevant in the log, but I attach it anyway. Hoping to get this to work, it seems like a nice program. Regards, Arie
info: 2/31503: 2014-08-07 16:28:12.373 Process 31507 started debug: 2/31503/6: 2014-08-07 16:28:12.384 Connecting to PostgreSQL server at 127.0.0.1:5432 (backend 1, fd 10, user aox) debug: 2/31503/7: 2014-08-07 16:28:12.411 Connecting to PostgreSQL server at 127.0.0.1:5432 (backend 2, fd 11, user aox) debug: 2/31503/8: 2014-08-07 16:28:12.412 Connecting to PostgreSQL server at 127.0.0.1:5432 (backend 3, fd 12, user aox) info: 2/31503/11/1: 2014-08-07 16:28:12.413 Listening for database signal mailboxes_updated info: 2/31503/13: 2014-08-07 16:28:12.414 Listening for database signal deliveries_updated info: 2/31503/15: 2014-08-07 16:28:12.414 Listening for database signal database_retuned info: 2/31503/17: 2014-08-07 16:28:12.414 Listening for database signal flag_names_extended debug: 2/31503/18: 2014-08-07 16:28:12.427 Using configuration file /usr/local/archiveopteryx/archiveopteryx.conf info: 2/31503/18: 2014-08-07 16:28:12.428 Setting default use-ipv6=off debug: 2/31503: 2014-08-07 16:28:12.428 Starting event loop debug: 2/31503/8: 2014-08-07 16:28:12.428 Connected: Database client 127.0.0.1:34599 connected to server 127.0.0.1:5432, on fd 12 (9 connections) debug: 2/31503/7: 2014-08-07 16:28:12.429 Connected: Database client 127.0.0.1:34598 connected to server 127.0.0.1:5432, on fd 11 (9 connections) debug: 2/31503/6: 2014-08-07 16:28:12.435 Connected: Database client 127.0.0.1:34595 connected to server 127.0.0.1:5432, on fd 10 (9 connections) debug: 2/31503: 2014-08-07 16:28:12.450 Connected: Log client 127.0.0.1:49471 connected to server 127.0.0.1:2054, on fd 4 (9 connections) info: 3/31503: 2014-08-07 16:28:12.375 Process 31508 started debug: 3/31503/6: 2014-08-07 16:28:12.387 Connecting to PostgreSQL server at 127.0.0.1:5432 (backend 1, fd 10, user aox) debug: 3/31503/7: 2014-08-07 16:28:12.389 Connecting to PostgreSQL server at 127.0.0.1:5432 (backend 2, fd 11, user aox) debug: 3/31503/8: 2014-08-07 16:28:12.390 Connecting to PostgreSQL server at 127.0.0.1:5432 (backend 3, fd 12, user aox) info: 3/31503/11/1: 2014-08-07 16:28:12.391 Listening for database signal mailboxes_updated info: 3/31503/13: 2014-08-07 16:28:12.391 Listening for database signal deliveries_updated info: 3/31503/15: 2014-08-07 16:28:12.392 Listening for database signal database_retuned info: 3/31503/17: 2014-08-07 16:28:12.392 Listening for database signal flag_names_extended debug: 3/31503/18: 2014-08-07 16:28:12.392 Using configuration file /usr/local/archiveopteryx/archiveopteryx.conf info: 3/31503/18: 2014-08-07 16:28:12.392 Setting default use-ipv6=off debug: 3/31503: 2014-08-07 16:28:12.393 Starting event loop debug: 3/31503/8: 2014-08-07 16:28:12.393 Connected: Database client 127.0.0.1:34597 connected to server 127.0.0.1:5432, on fd 12 (9 connections) debug: 3/31503/7: 2014-08-07 16:28:12.394 Connected: Database client 127.0.0.1:34596 connected to server 127.0.0.1:5432, on fd 11 (9 connections) debug: 3/31503/6: 2014-08-07 16:28:12.430 Connected: Database client 127.0.0.1:34594 connected to server 127.0.0.1:5432, on fd 10 (9 connections) debug: 3/31503: 2014-08-07 16:28:12.464 Connected: Log client 127.0.0.1:49472 connected to server 127.0.0.1:2054, on fd 4 (9 connections) debug: 3/31503/8: 2014-08-07 16:28:12.536 PostgreSQL server: SET application_name="" debug: 3/31503/8: 2014-08-07 16:28:12.536 PostgreSQL server: SET IntervalStyle="postgres" debug: 3/31503/8: 2014-08-07 16:28:12.536 Postgres backend 3 has pid 31512 debug: 3/31503/8: 2014-08-07 16:28:12.536 Sent parse/execute for "select oid::int4 from pg_catalog.pg_type where typname='citext'" on backend 3 debug: 2/31503/7: 2014-08-07 16:28:12.549 PostgreSQL server: SET application_name="" debug: 2/31503/7: 2014-08-07 16:28:12.549 PostgreSQL server: SET IntervalStyle="postgres" debug: 2/31503/7: 2014-08-07 16:28:12.549 Postgres backend 2 has pid 31513 debug: 2/31503/7: 2014-08-07 16:28:12.549 Sent parse/execute for "select oid::int4 from pg_catalog.pg_type where typname='citext'" on backend 2 debug: 2/31503/8: 2014-08-07 16:28:12.556 PostgreSQL server: SET application_name="" debug: 2/31503/8: 2014-08-07 16:28:12.556 PostgreSQL server: SET IntervalStyle="postgres" debug: 2/31503/8: 2014-08-07 16:28:12.556 Postgres backend 3 has pid 31514 debug: 2/31503/8: 2014-08-07 16:28:12.556 Sent parse/execute for "listen "mailboxes_updated"" on backend 3 debug: 2/31503/8: 2014-08-07 16:28:12.556 Sent parse/execute for "listen "deliveries_updated"" on backend 3 debug: 2/31503/8: 2014-08-07 16:28:12.557 Sent parse/execute for "listen "database_retuned"" on backend 3 debug: 2/31503/8: 2014-08-07 16:28:12.557 Sent parse/execute for "listen "flag_names_extended"" on backend 3 debug: 2/31503: 2014-08-07 16:28:12.557 Sent parse/execute for "select version() as version, revision from mailstore" on backend 3 debug: 3/31503/6: 2014-08-07 16:28:12.564 PostgreSQL server: SET application_name="" debug: 3/31503/6: 2014-08-07 16:28:12.564 PostgreSQL server: SET IntervalStyle="postgres" debug: 3/31503/6: 2014-08-07 16:28:12.565 Postgres backend 1 has pid 31509 debug: 3/31503/6: 2014-08-07 16:28:12.565 Sent parse/execute for "listen "mailboxes_updated"" on backend 1 debug: 3/31503/6: 2014-08-07 16:28:12.565 Sent parse/execute for "listen "deliveries_updated"" on backend 1 debug: 3/31503/6: 2014-08-07 16:28:12.565 Sent parse/execute for "listen "database_retuned"" on backend 1 debug: 3/31503/6: 2014-08-07 16:28:12.566 Sent parse/execute for "listen "flag_names_extended"" on backend 1 debug: 3/31503: 2014-08-07 16:28:12.566 Sent parse/execute for "select version() as version, revision from mailstore" on backend 1 info: 2/31503/8: 2014-08-07 16:28:12.591 Dequeueing query "listen "mailboxes_updated"" on backend 3 info: 2/31503/8: 2014-08-07 16:28:12.592 Dequeueing query "listen "deliveries_updated"" on backend 3 info: 2/31503/8: 2014-08-07 16:28:12.592 Dequeueing query "listen "database_retuned"" on backend 3 info: 2/31503/8: 2014-08-07 16:28:12.592 Dequeueing query "listen "flag_names_extended"" on backend 3 debug: 2/31503/6: 2014-08-07 16:28:12.592 PostgreSQL server: SET application_name="" debug: 2/31503/6: 2014-08-07 16:28:12.592 PostgreSQL server: SET IntervalStyle="postgres" debug: 2/31503/6: 2014-08-07 16:28:12.593 Postgres backend 1 has pid 31510 debug: 2/31503: 2014-08-07 16:28:12.593 Sent parse/execute for "select not exists (select * from information_schema.table_privileges where privilege_type='DELETE' and table_name='messages' and grantee=$1) and not exists (select u.usename from pg_catalog.pg_class c left join pg_catalog.pg_user u on (u.usesysid=c.relowner) where c.relname='messages' and u.usename=$1) as allowed" ($1='aox') on backend 1 info: 3/31503/8: 2014-08-07 16:28:12.613 Dequeueing query "select oid::int4 from pg_catalog.pg_type where typname='citext'" on backend 3 (with 1 rows) debug: 3/31503: 2014-08-07 16:28:12.613 Sent parse/execute for "select not exists (select * from information_schema.table_privileges where privilege_type='DELETE' and table_name='messages' and grantee=$1) and not exists (select u.usename from pg_catalog.pg_class c left join pg_catalog.pg_user u on (u.usesysid=c.relowner) where c.relname='messages' and u.usename=$1) as allowed" ($1='aox') on backend 3 debug: 3/31503/7: 2014-08-07 16:28:12.614 PostgreSQL server: SET application_name="" debug: 3/31503/7: 2014-08-07 16:28:12.614 PostgreSQL server: SET IntervalStyle="postgres" debug: 3/31503/7: 2014-08-07 16:28:12.614 Postgres backend 2 has pid 31511 debug: 3/31503/11: 2014-08-07 16:28:12.614 Sent parse/execute for "select m.id, m.name, m.deleted, m.owner, m.uidnext, m.nextmodseq, m.uidvalidity from mailboxes m " on backend 2 info: 3/31503/6: 2014-08-07 16:28:12.647 Dequeueing query "listen "mailboxes_updated"" on backend 1 info: 3/31503/6: 2014-08-07 16:28:12.647 Dequeueing query "listen "deliveries_updated"" on backend 1 info: 3/31503/6: 2014-08-07 16:28:12.647 Dequeueing query "listen "database_retuned"" on backend 1 info: 3/31503/6: 2014-08-07 16:28:12.647 Dequeueing query "listen "flag_names_extended"" on backend 1 info: 2/31503/7: 2014-08-07 16:28:12.650 Dequeueing query "select oid::int4 from pg_catalog.pg_type where typname='citext'" on backend 2 (with 1 rows) debug: 2/31503/11: 2014-08-07 16:28:12.650 Sent parse/execute for "select m.id, m.name, m.deleted, m.owner, m.uidnext, m.nextmodseq, m.uidvalidity from mailboxes m " on backend 2 info: 3/31503: 2014-08-07 16:28:12.654 Dequeueing query "select version() as version, revision from mailstore" on backend 1 (with 1 rows) debug: 3/31503/6: 2014-08-07 16:28:12.654 Sent parse/execute for "update deliveries set expires_at=current_timestamp+interval '900 s' where expires_at<current_timestamp+interval '900 s' and id in (select delivery from delivery_recipients where action=$1 or action=$2)" ($1='0',$2='2') on backend 1 info: 2/31503: 2014-08-07 16:28:12.682 Dequeueing query "select version() as version, revision from mailstore" on backend 3 (with 1 rows) debug: 2/31503/8: 2014-08-07 16:28:12.682 Sent parse/execute for "update deliveries set expires_at=current_timestamp+interval '900 s' where expires_at<current_timestamp+interval '900 s' and id in (select delivery from delivery_recipients where action=$1 or action=$2)" ($1='0',$2='2') on backend 3 info: 3/31503/11: 2014-08-07 16:28:12.709 Dequeueing query "select m.id, m.name, m.deleted, m.owner, m.uidnext, m.nextmodseq, m.uidvalidity from mailboxes m " on backend 2 (with 4 rows) debug: 3/31503: 2014-08-07 16:28:12.710 Sent parse/execute for "select indexdef from pg_indexes where indexdef ilike '% USING gin (to_tsvector%'and tablename='bodyparts' and schemaname=$1" ($1='public') on backend 2 significant: 3/31503: 2014-08-07 16:28:12.716 archiveopteryx: Server startup complete info: 2/31503/11: 2014-08-07 16:28:12.721 Dequeueing query "select m.id, m.name, m.deleted, m.owner, m.uidnext, m.nextmodseq, m.uidvalidity from mailboxes m " on backend 2 (with 4 rows) debug: 2/31503: 2014-08-07 16:28:12.722 Sent parse/execute for "select indexdef from pg_indexes where indexdef ilike '% USING gin (to_tsvector%'and tablename='bodyparts' and schemaname=$1" ($1='public') on backend 2 significant: 2/31503: 2014-08-07 16:28:12.745 archiveopteryx: Server startup complete info: 2/31503/8: 2014-08-07 16:28:12.793 Dequeueing query "update deliveries set expires_at=current_timestamp+interval '900 s' where expires_at<current_timestamp+interval '900 s' and id in (select delivery from delivery_recipients where action=$1 or action=$2)" ($1='0',$2='2') on backend 3 (with 0 rows) debug: 2/31503/16: 2014-08-07 16:28:12.794 Sent parse/execute for "select id, name from flag_names where id > $1" ($1='0') on backend 3 info: 3/31503/6: 2014-08-07 16:28:12.796 Dequeueing query "update deliveries set expires_at=current_timestamp+interval '900 s' where expires_at<current_timestamp+interval '900 s' and id in (select delivery from delivery_recipients where action=$1 or action=$2)" ($1='0',$2='2') on backend 1 (with 0 rows) debug: 3/31503/16: 2014-08-07 16:28:12.797 Sent parse/execute for "select id, name from flag_names where id > $1" ($1='0') on backend 1 info: 3/31503/16: 2014-08-07 16:28:12.823 Dequeueing query "select id, name from flag_names where id > $1" ($1='0') on backend 1 (with 5 rows) info: 2/31503/16: 2014-08-07 16:28:12.861 Dequeueing query "select id, name from flag_names where id > $1" ($1='0') on backend 3 (with 5 rows) info: 2/31503: 2014-08-07 16:28:12.999 Dequeueing query "select indexdef from pg_indexes where indexdef ilike '% USING gin (to_tsvector%'and tablename='bodyparts' and schemaname=$1" ($1='public') on backend 2 (with 0 rows) info: 3/31503: 2014-08-07 16:28:13.004 Dequeueing query "select indexdef from pg_indexes where indexdef ilike '% USING gin (to_tsvector%'and tablename='bodyparts' and schemaname=$1" ($1='public') on backend 2 (with 0 rows) info: 3/31503: 2014-08-07 16:28:13.011 Dequeueing query "select not exists (select * from information_schema.table_privileges where privilege_type='DELETE' and table_name='messages' and grantee=$1) and not exists (select u.usename from pg_catalog.pg_class c left join pg_catalog.pg_user u on (u.usesysid=c.relowner) where c.relname='messages' and u.usename=$1) as allowed" ($1='aox') on backend 3 (with 1 rows) info: 3/31503/12: 2014-08-07 16:28:13.011 Starting queue run debug: 3/31503/12: 2014-08-07 16:28:13.012 Sent parse/execute for "select d.message, extract(epoch from min(coalesce(dr.last_attempt+interval '900 s', d.deliver_after, current_timestamp)))::bigint-extract(epoch from current_timestamp)::bigint as delay from deliveries d join delivery_recipients dr on (d.id=dr.delivery) where (dr.action=$1 or dr.action=$2) group by d.message order by delay" ($1='0',$2='2') on backend 3 info: 2/31503: 2014-08-07 16:28:13.019 Dequeueing query "select not exists (select * from information_schema.table_privileges where privilege_type='DELETE' and table_name='messages' and grantee=$1) and not exists (select u.usename from pg_catalog.pg_class c left join pg_catalog.pg_user u on (u.usesysid=c.relowner) where c.relname='messages' and u.usename=$1) as allowed" ($1='aox') on backend 1 (with 1 rows) info: 2/31503/12: 2014-08-07 16:28:13.020 Starting queue run debug: 2/31503/12: 2014-08-07 16:28:13.020 Sent parse/execute for "select d.message, extract(epoch from min(coalesce(dr.last_attempt+interval '900 s', d.deliver_after, current_timestamp)))::bigint-extract(epoch from current_timestamp)::bigint as delay from deliveries d join delivery_recipients dr on (d.id=dr.delivery) where (dr.action=$1 or dr.action=$2) group by d.message order by delay" ($1='0',$2='2') on backend 2 info: 2/31503/12: 2014-08-07 16:28:13.081 Dequeueing query "select d.message, extract(epoch from min(coalesce(dr.last_attempt+interval '900 s', d.deliver_after, current_timestamp)))::bigint-extract(epoch from current_timestamp)::bigint as delay from deliveries d join delivery_recipients dr on (d.id=dr.delivery) where (dr.action=$1 or dr.action=$2) group by d.message order by delay" ($1='0',$2='2') on backend 2 (with 0 rows) info: 2/31503/12: 2014-08-07 16:28:13.081 Ending queue run info: 3/31503/12: 2014-08-07 16:28:13.089 Dequeueing query "select d.message, extract(epoch from min(coalesce(dr.last_attempt+interval '900 s', d.deliver_after, current_timestamp)))::bigint-extract(epoch from current_timestamp)::bigint as delay from deliveries d join delivery_recipients dr on (d.id=dr.delivery) where (dr.action=$1 or dr.action=$2) group by d.message order by delay" ($1='0',$2='2') on backend 3 (with 0 rows) info: 3/31503/12: 2014-08-07 16:28:13.089 Ending queue run significant: 3/31503/2/1: 2014-08-07 16:28:19.892 Connected: IMAP server 127.0.0.1:143 connected to client 127.0.0.1:39436, on fd 13 (10 connections) info: 3/31503/2/1/1: 2014-08-07 16:28:24.979 IMAP Command: 1 LOGIN debug: 3/31503/2/1: 2014-08-07 16:28:24.979 IMAP::runCommands, 1 commands debug: 3/31503/2/1/1: 2014-08-07 16:28:24.979 Executing debug: 3/31503/2/1: 2014-08-07 16:28:24.979 IMAP::runCommands, 1 commands debug: 3/31503/2/1/1/1: 2014-08-07 16:28:24.980 Verifying client response debug: 3/31503/2/1/1/1: 2014-08-07 16:28:24.985 Sent parse/execute for "select u.id, u.login, u.secret, u.ldapdn, a.name, a.localpart::text, a.domain::text, u.quota, al.mailbox as inbox, n.name as parentspace from users u join namespaces n on (u.parentspace=n.id) left join aliases al on (u.alias=al.id) left join addresses a on (al.address=a.id) where lower(u.login)=lower($1)" ($1='arie') on backend 3 info: 3/31503/2/1/1/1: 2014-08-07 16:28:25.020 Dequeueing query "select u.id, u.login, u.secret, u.ldapdn, a.name, a.localpart::text, a.domain::text, u.quota, al.mailbox as inbox, n.name as parentspace from users u join namespaces n on (u.parentspace=n.id) left join aliases al on (u.alias=al.id) left join addresses a on (al.address=a.id) where lower(u.login)=lower($1)" ($1='arie') on backend 3 (with 1 rows) debug: 3/31503/2/1/1/1: 2014-08-07 16:28:25.032 Authenticated: "arie" significant: 3/31503/2/1: 2014-08-07 16:28:25.033 Authenticated as arie using IMAP login debug: 3/31503/2/1: 2014-08-07 16:28:25.033 Changed to authenticated state info: 3/31503/2/1/1: 2014-08-07 16:28:25.033 Execution time 54ms debug: 3/31503/2/1/1: 2014-08-07 16:28:25.034 Finished debug: 3/31503/2/1: 2014-08-07 16:28:25.034 IMAP::runCommands, 1 commands debug: 3/31503/2/1/1: 2014-08-07 16:28:25.034 Retired info: 3/31503/2/1/1: 2014-08-07 16:28:25.034 1 OK [CAPABILITY IMAP4rev1 ACL ANNOTATE-EXPERIMENT-1 BINARY CATENATE CHILDREN CONDSTORE ENABLE ESEARCH I18NLEVEL=1 ID IDLE LIST-EXTENDED LITERAL+ MOVE MULTIAPPEND NAMESPACE QUOTA QRESYNC RIGHTS=ekntx SORT SORT=DISPLAY STARTTLS THREAD=ORDEREDSUBJECT THREAD=REFS THREAD=REFERENCES UIDPLUS UNSELECT URLAUTH UTF8=ACCEPT WITHIN X-AOX-GM-1] done debug: 3/31503/2/1: 2014-08-07 16:28:25.034 IMAP::runCommands, 0 commands info: 3/31503/7: 2014-08-07 16:28:33.054 Closing idle database backend 2 (2 remaining) debug: 3/31503/7: 2014-08-07 16:28:33.064 Closing: Database client 127.0.0.1:34596 connected to server 127.0.0.1:5432, on fd 11 (10 connections) info: 2/31503/7: 2014-08-07 16:28:33.125 Closing idle database backend 2 (2 remaining) debug: 2/31503/7: 2014-08-07 16:28:33.135 Closing: Database client 127.0.0.1:34598 connected to server 127.0.0.1:5432, on fd 11 (9 connections) info: 3/31503/2/1/2: 2014-08-07 16:28:35.575 IMAP Command: 1 LOGOUT debug: 3/31503/2/1/2: 2014-08-07 16:28:35.576 First line: 1 LOGOUT debug: 3/31503/2/1: 2014-08-07 16:28:35.576 IMAP::runCommands, 1 commands debug: 3/31503/2/1/2: 2014-08-07 16:28:35.576 Executing debug: 3/31503/2/1: 2014-08-07 16:28:35.576 IMAP::runCommands, 1 commands debug: 3/31503/2/1: 2014-08-07 16:28:35.576 Changed to logout state debug: 3/31503/2/1/2: 2014-08-07 16:28:35.576 Execution time 0ms debug: 3/31503/2/1/2: 2014-08-07 16:28:35.576 Finished debug: 3/31503/2/1/2: 2014-08-07 16:28:35.576 Retired info: 3/31503/2/1/2: 2014-08-07 16:28:35.576 1 OK done debug: 3/31503/2/1: 2014-08-07 16:28:35.576 IMAP::runCommands, 0 commands debug: 3/31503/2/1: 2014-08-07 16:28:36.181 IMAP::runCommands, 0 commands info: 3/31503/2/1: 2014-08-07 16:28:36.181 Closing: IMAP server 127.0.0.1:143 connected to client 127.0.0.1:39436, on fd 13 (9 connections) debug: 3/31503: 2014-08-07 16:28:36.182 Sent parse/execute for "insert into connections (username,address,port,mechanism,authfailures,syntaxerrors,started_at,ended_at,userid) values ($1,$2,$3,$4,$5,$6,$7::interval + 'epoch'::timestamptz,$8::interval + 'epoch'::timestamptz,$9)" ($1='arie',$2='127.0.0.1',$3='39436',$4='IMAP login',$5='0',$6='0',$7='1407428905',$8='1407428916',$9='1') on backend 3 info: 3/31503/8: 2014-08-07 16:28:36.248 Dequeueing query "insert into connections (username,address,port,mechanism,authfailures,syntaxerrors,started_at,ended_at,userid) values ($1,$2,$3,$4,$5,$6,$7::interval + 'epoch'::timestamptz,$8::interval + 'epoch'::timestamptz,$9)" ($1='arie',$2='127.0.0.1',$3='39436',$4='IMAP login',$5='0',$6='0',$7='1407428905',$8='1407428916',$9='1') on backend 3 (with 1 rows)
