I should expect that there'd be more in the log than that.

What you are showing seems perfectly appropriate; what I imagine is missing
is that at the end, something is going wrong, the set is treated as NOT
having subscribed successfully, and it (correctly, generally speaking)
tries again a bit later.

Unfortunately, the "something going wrong" is some persistent problem, so
the subscriptions to tables never succeed.

There should surely be more in the log.

Here's what the logs commonly look like at subscription time:

DEBUG2 remoteWorkerThread_1: Received event #1 from 5000000017
type:ENABLE_SUBSCRIPTION
INFO   copy_set 1 - omit=f - bool=0
INFO   omit is FALSE
CONFIG version for "dbname=slonyregress1 host=localhost user=postgres
port=7099" is 90304
DEBUG1 copy_set_1 "dbname=slonyregress1 host=localhost user=postgres
port=7099": backend pid = 19464
CONFIG remoteWorkerThread_1: connected to provider DB
CONFIG remoteWorkerThread_1: prepare to copy table "public"."table1"
CONFIG remoteWorkerThread_1: prepare to copy table "public"."table2"
CONFIG remoteWorkerThread_1: prepare to copy table "public"."table4"
CONFIG remoteWorkerThread_1: prepare to copy table "public"."table5"
CONFIG remoteWorkerThread_1: all tables for set 1 found on subscriber
CONFIG remoteWorkerThread_1: copy table "public"."table1"
CONFIG remoteWorkerThread_1: Begin COPY of table "public"."table1"
NOTICE:  truncate of "public"."table1" failed - doing delete
CONFIG remoteWorkerThread_1: 32 bytes copied for table "public"."table1"
CONFIG remoteWorkerThread_1: 0.150 seconds to copy table "public"."table1"
CONFIG remoteWorkerThread_1: copy table "public"."table2"
CONFIG remoteWorkerThread_1: Begin COPY of table "public"."table2"
NOTICE:  truncate of "public"."table2" succeeded
CONFIG remoteWorkerThread_1: 36 bytes copied for table "public"."table2"
CONFIG remoteWorkerThread_1: 0.219 seconds to copy table "public"."table2"
CONFIG remoteWorkerThread_1: copy table "public"."table4"
CONFIG remoteWorkerThread_1: Begin COPY of table "public"."table4"
NOTICE:  truncate of "public"."table4" succeeded
CONFIG remoteWorkerThread_1: 253 bytes copied for table "public"."table4"
CONFIG remoteWorkerThread_1: 0.238 seconds to copy table "public"."table4"
CONFIG remoteWorkerThread_1: copy table "public"."table5"
CONFIG remoteWorkerThread_1: Begin COPY of table "public"."table5"
NOTICE:  truncate of "public"."table5" succeeded
CONFIG remoteWorkerThread_1: 0 bytes copied for table "public"."table5"
CONFIG remoteWorkerThread_1: 0.167 seconds to copy table "public"."table5"
INFO   remoteWorkerThread_1: copy_set SYNC found, use event seqno
5000000015.
INFO   remoteWorkerThread_1: 0.004 seconds to build initial setsync status
DEBUG1 remoteWorkerThread_1: disconnected from provider DB
INFO   copy_set 1 done in 0.798 seconds
CONFIG enableSubscription: sub_set=1
DEBUG2 sched_wakeup_node(): no_id=1 (0 threads + worker signaled)
CONFIG storeListen: li_origin=1 li_receiver=2 li_provider=1
DEBUG2 sched_wakeup_node(): no_id=1 (0 threads + worker signaled)
DEBUG2 sched_wakeup_node(): no_id=1 (0 threads + worker signaled)
CONFIG remoteWorkerThread_1: update provider configuration
CONFIG remoteWorkerThread_1: added active set 1 to provider 1

If you have logging turned way down so all you're seeing is CONFIG and
higher, you should nonetheless see the bulk of the above (and note the bits
*after* the last line indicating 0.167 seconds to copy table5).

If an error occurred, that should surely be logged, and that would be the
reason to not get the lines...

INFO   copy_set 1 done in 0.798 seconds
CONFIG enableSubscription: sub_set=1
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.slony.info/pipermail/slony1-general/attachments/20140801/e34caf4b/attachment.html