On 12-01-03 12:31 PM, Martijn van Oosterhout wrote:
> Hoi,
>
>> What version of Slony are you using?
>> What version of Postgresql are you using?
>
> Sorry, I should have mentioned: slony-I 2.0.7, PostgreSQL 9.0.3
>
>
>>
>> What do you base this statement on?   I do not see anything in the logs you
>> pasted showing me that slon2 has received the SUBSCRIBE_SET or
>> ENABLE_SUBSCRIPTION event.
>
> Well, I'm basing it on that the logs repeated this for two days:
>
> 2012-01-02 12:31:47 CETINFO   cleanupThread:    0.004 seconds for cleanupEvent()
> NOTICE:  Slony-I: log switch to sl_log_2 complete - truncate sl_log_1
> CONTEXT:  PL/pgSQL function "cleanupevent" line 99 at assignment
> 2012-01-02 12:43:15 CETINFO   cleanupThread:    0.079 seconds for cleanupEvent()
> 2012-01-02 12:43:15 CETINFO   cleanupThread:    0.006 seconds for vacuuming
> NOTICE:  Slony-I: Logswitch to sl_log_1 initiated
> CONTEXT:  SQL statement "SELECT "_pp_config_rep".logswitch_start()"
> PL/pgSQL function "cleanupevent" line 101 at PERFORM
> 2012-01-02 12:54:30 CETINFO   cleanupThread:    0.004 seconds for cleanupEvent()
> NOTICE:  Slony-I: log switch to sl_log_1 complete - truncate sl_log_2
> CONTEXT:  PL/pgSQL function "cleanupevent" line 99 at assignment
> 2012-01-02 13:05:14 CETINFO   cleanupThread:    0.096 seconds for cleanupEvent()
> NOTICE:  Slony-I: Logswitch to sl_log_2 initiated
> CONTEXT:  SQL statement "SELECT "_pp_config_rep".logswitch_start()"
>


The above log messages are normal activities for the cleanup thread. 
They don't indicate a problem.


> So it was doing something, but now you mention it, there are no SYNCs,
> so perhaps it wasn't subscribed.

If you had a set subscribed you would see messages like

CETINFO remoteWorkerThread_1 syncing set %d with %d table(s) from 
provider %d

on each sync.

If you are not subscribed to any sets but are processing SYNC events 
(slon should still be processing SYNC events even if it isn't subscribed 
to anything)
You would see

CETDEBUG1 no sets need syncing for this event\n

in the log.  However that message is at the DEBUG level, and if you are 
running slon at the INFO level you will need to bump up the verbosity of 
slon to see it.

 From your log snippet I would say either

1) You are not subscribed to the set, and node 2 has not processed the 
ENABLE_SUBSCRIPTION event.

2) You are subscribed to the set but are not receiving or processing any 
events from node 1 (for some unknown reason)

Querying sl_status on the master would have told you how far behind the 
slave is.




>
> This is the log for the slave, and it says there "storeSubscribe".
> doesn't that mean it received a SUBSCRIBE_SET?
>

The message

CETCONFIG storeSubscribe: sub_set=%d sub_provider=%d sub_forward='%s

comes from the function rtcfg_storeSubscribe which gets called both on 
startup and when a SUBSCRIBE_SET event is processed.

If the ENABLE_SUBSCRIPTION command was processed then it should have 
called rtcfg_enableSubscription and would have seen

CETCONFIG enableSubscription: sub_set=%d\n"

which I didn't see in the log.

The data copy takes place in response to the ENABLE_SUBSCRIPTION event.




>> What is sl_subscribe on node 2 at this point in time?
>> Does node 2 have a record in sl_event of it having processed those two
>> events?
>
> Unfortunately I don't have that information available, but it looks
> like pilot error (the user claimed there were no errors) after all:
> the subscribe didn't work.
>

The subscribe event gets submitted to the origin (or the provider, 
depending on the version of slony, but in this case I think they are the 
same).   The SUBSCRIBE_SET and ENABLE_SUBSCRIPTION events then need to 
get replicated to the receiver that will start the copy_set.




> Have a nice day,