<div dir="ltr">I should expect that there'd be more in the log than that.<div><br></div><div>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.</div>
<div><br></div><div>Unfortunately, the "something going wrong" is some persistent problem, so the subscriptions to tables never succeed.</div><div><br></div><div>There should surely be more in the log.</div><div>
<br></div><div>Here's what the logs commonly look like at subscription time:</div><div><br></div><div><div>DEBUG2 remoteWorkerThread_1: Received event #1 from 5000000017 type:ENABLE_SUBSCRIPTION</div><div>INFO copy_set 1 - omit=f - bool=0</div>
<div>INFO omit is FALSE</div><div>CONFIG version for "dbname=slonyregress1 host=localhost user=postgres port=7099" is 90304</div><div>DEBUG1 copy_set_1 "dbname=slonyregress1 host=localhost user=postgres port=7099": backend pid = 19464</div>
<div>CONFIG remoteWorkerThread_1: connected to provider DB</div><div>CONFIG remoteWorkerThread_1: prepare to copy table "public"."table1"</div><div>CONFIG remoteWorkerThread_1: prepare to copy table "public"."table2"</div>
<div>CONFIG remoteWorkerThread_1: prepare to copy table "public"."table4"</div><div>CONFIG remoteWorkerThread_1: prepare to copy table "public"."table5"</div><div>CONFIG remoteWorkerThread_1: all tables for set 1 found on subscriber</div>
<div>CONFIG remoteWorkerThread_1: copy table "public"."table1"</div><div>CONFIG remoteWorkerThread_1: Begin COPY of table "public"."table1"</div><div>NOTICE: truncate of "public"."table1" failed - doing delete</div>
<div>CONFIG remoteWorkerThread_1: 32 bytes copied for table "public"."table1"</div><div>CONFIG remoteWorkerThread_1: 0.150 seconds to copy table "public"."table1"</div><div>CONFIG remoteWorkerThread_1: copy table "public"."table2"</div>
<div>CONFIG remoteWorkerThread_1: Begin COPY of table "public"."table2"</div><div>NOTICE: truncate of "public"."table2" succeeded</div><div>CONFIG remoteWorkerThread_1: 36 bytes copied for table "public"."table2"</div>
<div>CONFIG remoteWorkerThread_1: 0.219 seconds to copy table "public"."table2"</div><div>CONFIG remoteWorkerThread_1: copy table "public"."table4"</div><div>CONFIG remoteWorkerThread_1: Begin COPY of table "public"."table4"</div>
<div>NOTICE: truncate of "public"."table4" succeeded</div><div>CONFIG remoteWorkerThread_1: 253 bytes copied for table "public"."table4"</div><div>CONFIG remoteWorkerThread_1: 0.238 seconds to copy table "public"."table4"</div>
<div>CONFIG remoteWorkerThread_1: copy table "public"."table5"</div><div>CONFIG remoteWorkerThread_1: Begin COPY of table "public"."table5"</div><div>NOTICE: truncate of "public"."table5" succeeded</div>
<div>CONFIG remoteWorkerThread_1: 0 bytes copied for table "public"."table5"</div><div>CONFIG remoteWorkerThread_1: 0.167 seconds to copy table "public"."table5"</div><div>INFO remoteWorkerThread_1: copy_set SYNC found, use event seqno 5000000015.</div>
<div>INFO remoteWorkerThread_1: 0.004 seconds to build initial setsync status</div><div>DEBUG1 remoteWorkerThread_1: disconnected from provider DB</div><div>INFO copy_set 1 done in 0.798 seconds</div><div>CONFIG enableSubscription: sub_set=1</div>
<div>DEBUG2 sched_wakeup_node(): no_id=1 (0 threads + worker signaled)</div><div>CONFIG storeListen: li_origin=1 li_receiver=2 li_provider=1</div><div>DEBUG2 sched_wakeup_node(): no_id=1 (0 threads + worker signaled)</div>
<div>DEBUG2 sched_wakeup_node(): no_id=1 (0 threads + worker signaled)</div><div>CONFIG remoteWorkerThread_1: update provider configuration</div><div>CONFIG remoteWorkerThread_1: added active set 1 to provider 1</div></div>
<div><br></div><div>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).</div>
<div><br></div><div>If an error occurred, that should surely be logged, and that would be the reason to not get the lines...</div><div><br></div><div><div>INFO copy_set 1 done in 0.798 seconds</div><div>CONFIG enableSubscription: sub_set=1</div>
</div><div><br></div></div>