[Bucardo-general] Replication won't start.

Donald StDenis donald.stdenis at goodsearch.com
Thu Jan 12 18:36:00 UTC 2017


The strange value indicated below is just and automatically created dbgroup - so this is not a problem.  I have created a manual name for this and hit same wall.

So I was able to make it start replication by allowing Postgres user bucardo to have "trust"ed access on the local socket.

This is slowing me to make progress right now but is not a recommended solution for production.

Thanks.


> On Jan 12, 2017, at 6:50 AM, Donald StDenis <donald.stdenis at goodsearch.com> wrote:
> 
> Hi,
> 
> debugging shows a strange value - perhaps that is causing the issue?
> 
> bucardo at ale-pg1:~$ bucardo add sync the_sync --verbose --debug relgroup=copying_herd dbs=source_db:source,dest_db:target onetimecopy=2
> SQL: INSERT INTO bucardo.sync (dbs,onetimecopy,herd,name) VALUES (?,?,?,?)
> $VAR1 = 'the_sync';
> $VAR2 = '2';
> $VAR3 = 'copying_herd';
> $VAR4 = 'the_sync';
> WARNING:  Issuing rollback() due to DESTROY without explicit disconnect() of DBD::Pg::db handle dbname=good_rails_production at -e line 56.
> Failed to add sync: DBD::Pg::st execute failed: ERROR:  DBD::Pg::db do failed: ERROR:  role "bucardo" already exists at line 186. at line 30.
> CONTEXT:  PL/Perl function "validate_sync" at /usr/local/bin/bucardo line 4633.
> 
> Should the ‘dbs' field of the bacardi.sync table be set to ‘the_sync’ as the above it trying to do?  It looks like I tried to specify on the command line: dbs=source_db:source,dest_db:target
> 
> If someone could show a debugging outpost of a successful “add sync” command that would be very helpful.
> 
> Thanks.
> 
> Don. 
> 
> 
>> On Jan 11, 2017, at 1:33 PM, Don St. Denis <donald.stdenis at goodsearch.com <mailto:donald.stdenis at goodsearch.com>> wrote:
>> 
>> Hi,
>> 
>> OK, I got past the table addition problem by specifying the relgroup and I have added all the Primary Keys required but I am running into an error that doesn't appear to have much online for:
>> 
>> bucardo at pg1:~$ DBUSER=bucardo DBPASS=*** bucardo add sync the_sync relgroup=copying_herd dbs=source_db:source,dest_db:target onetimecopy=2
>> WARNING:  Issuing rollback() due to DESTROY without explicit disconnect() of DBD::Pg::db handle dbname=good_rails_production at -e line 56.
>> Failed to add sync: DBD::Pg::st execute failed: ERROR:  DBD::Pg::db do failed: ERROR:  role "bucardo" already exists at line 186. at line 30.
>> CONTEXT:  PL/Perl function "validate_sync" at /usr/local/bin/bucardo line 4633.
>> 
>> 
>> In the Log file I see this:
>> 2017-01-11 21:00:55.653 UTC [00000] [29258]: [1] db=[unknown],user=[unknown],host=[local] LOG:  connection received: host=[local]
>> 2017-01-11 21:00:55.654 UTC [00000] [29258]: [2] db=bucardo,user=bucardo,host=[local] LOG:  connection authorized: user=bucardo database=bucardo
>> 2017-01-11 21:00:55.724 UTC [00000] [29258]: [3] db=bucardo,user=bucardo,host=[local] LOG:  Starting validate_sync for the_sync
>> 2017-01-11 21:00:55.724 UTC [00000] [29258]: [4] db=bucardo,user=bucardo,host=[local] CONTEXT:  PL/Perl function "validate_sync"
>>         SQL statement "SELECT validate_sync('the_sync')"
>>         PL/Perl function "validate_sync"
>> 2017-01-11 21:00:55.724 UTC [00000] [29258]: [5] db=bucardo,user=bucardo,host=[local] STATEMENT:  INSERT INTO bucardo.sync (name,dbs,herd,onetimecopy) VALUES ($1,$2,$3,$4)
>> 2017-01-11 21:00:56.319 UTC [00000] [29259]: [1] db=[unknown],user=[unknown],host=[local] LOG:  connection received: host=[local]
>> 2017-01-11 21:00:56.320 UTC [00000] [29259]: [2] db=good_rails_production,user=bucardo,host=[local] LOG:  provided user name (bucardo) and authenticated user name (postgres) do not match
>> 2017-01-11 21:00:56.320 UTC [28000] [29259]: [3] db=good_rails_production,user=bucardo,host=[local] FATAL:  Peer authentication failed for user "bucardo"
>> 2017-01-11 21:00:56.320 UTC [28000] [29259]: [4] db=good_rails_production,user=bucardo,host=[local] DETAIL:  Connection matched pg_hba.conf line 29: "local   all           bucardo                  ident"
>> 2017-01-11 21:00:56.321 UTC [00000] [29260]: [1] db=[unknown],user=[unknown],host=[local] LOG:  connection received: host=[local]
>> 2017-01-11 21:00:56.322 UTC [00000] [29260]: [2] db=good_rails_production,user=postgres,host=[local] LOG:  connection authorized: user=postgres database=good_rails_production
>> 2017-01-11 21:00:56.323 UTC [00000] [29260]: [3] db=good_rails_production,user=postgres,host=[local] LOG:  statement: CREATE USER bucardo SUPERUSER
>> 2017-01-11 21:00:56.323 UTC [42710] [29260]: [4] db=good_rails_production,user=postgres,host=[local] ERROR:  role "bucardo" already exists
>> 2017-01-11 21:00:56.323 UTC [42710] [29260]: [5] db=good_rails_production,user=postgres,host=[local] STATEMENT:  CREATE USER bucardo SUPERUSER
>> 2017-01-11 21:00:56.323 UTC [01000] [29258]: [6] db=bucardo,user=bucardo,host=[local] WARNING:  Issuing rollback() due to DESTROY without explicit disconnect() of DBD::Pg::db handle dbname=good_rails_production at -e line 56.
>> 2017-01-11 21:00:56.323 UTC [01000] [29258]: [7] db=bucardo,user=bucardo,host=[local] CONTEXT:  PL/Perl function "validate_sync"
>>         SQL statement "SELECT validate_sync('the_sync')"
>>         PL/Perl function "validate_sync"
>> 2017-01-11 21:00:56.323 UTC [00000] [29260]: [6] db=good_rails_production,user=postgres,host=[local] LOG:  disconnection: session time: 0:00:00.002 user=postgres database=good_rails_production host=[local]
>> 2017-01-11 21:00:56.325 UTC [38000] [29258]: [8] db=bucardo,user=bucardo,host=[local] ERROR:  DBD::Pg::db do failed: ERROR:  role "bucardo" already exists at line 186. at line 30.
>> 2017-01-11 21:00:56.325 UTC [38000] [29258]: [9] db=bucardo,user=bucardo,host=[local] CONTEXT:  PL/Perl function "validate_sync"
>> 2017-01-11 21:00:56.325 UTC [38000] [29258]: [10] db=bucardo,user=bucardo,host=[local] STATEMENT:  INSERT INTO bucardo.sync (name,dbs,herd,onetimecopy) VALUES ($1,$2,$3,$4)
>> 2017-01-11 21:00:56.326 UTC [00000] [29258]: [11] db=bucardo,user=bucardo,host=[local] LOG:  disconnection: session time: 0:00:00.673 user=bucardo database=bucardo host=[local]
>> 
>> Specifically this is weird: "
>> LOG:  provided user name (bucardo) and authenticated user name (postgres) do not match
>> "
>> 
>> But it clearly matches line 29 authentication below it?
>> 
>> Why does the system try to recreate user bucardo?
>> 
>> Any ideas?
>> 
>> Don.
>> 
>> On 01/10/2017 11:35 AM, Donald StDenis wrote:
>>> Hi,
>>> 
>>> I finally got back to this project...  Used github to get latest from master, ran the perl make, make, and make test (almost all succeeded, couple of them failed) then installed it.  Then ran through the above installation again.  Fails same way.
>>> 
>>> Its been a while since I debugged PERL but the PERL does not seem to be the issue here...  
>>> 
>>> I have never debugged Postgres stored procedures/functions BEFORE - but I see quite a few in the schema file.  Which one would be the most interesting to add logging lines to to debug?
>>> 
>>> I checked the master database carefully there are no entries put into the Postgres log file when the sync is added.  
>>> 
>>> Nothing appears to STDOUT or STDERR.
>>> 
>>> Is there a suggested debugging process I can follow to move forward here?
>>>  
>>> 
>>> On Mon, Dec 19, 2016 at 2:00 PM, Donald StDenis <donald.stdenis at goodsearch.com <mailto:donald.stdenis at goodsearch.com>> wrote:
>>> Here’s the output from the command lines, I don’t see any errors or warnings in the database log file.  Earlier I tried the —debug options on the start and saw no differences.  Also previously (about 6 months ago while testing with 9.2->9.2 replication) I always got errors for trying to add tables without any UNIQUE or PRIMARY KEYS but there is none now.
>>> 
>>> Current output:
>>> 
>>> bucardo at ale-pg1:~$ echo "DROP DATABASE good_rails_production" | psql bucardo
>>> bucardo at ale-pg1:~$ pg_dump --host=10.223.160.229 --dbname=good_rails_production --user=bucardo --schema-only --create --format=plain  > schema-all.sql
>>> bucardo at ale-pg1:~$ echo "
>>>   CREATE USER conn*** WITH LOGIN SUPERUSER ENCRYPTED PASSWORD '***';
>>>   CREATE USER repo*** WITH LOGIN ENCRYPTED PASSWORD '***';
>>> " | psql bucardo
>>> ERROR:  role "conn***" already exists
>>> ERROR:  role "repo***" already exists
>>> bucardo at ale-pg1:~$ psql --dbname=postgres --user=bucardo -f schema-all.sql
>>> <completes without error... very long>
>>> 
>>> bucardo at ale-pg1:~$ bucardo add db source_db dbhost=10.223.160.229 dbport=5432 dbname=good_rails_production dbuser=bucardo dbpass=****
>>> Added database "source_db"
>>> bucardo at ale-pg1:~$ bucardo add db dest_db dbname=good_rails_production dbuser=bucardo
>>> Added database "dest_db"
>>> bucardo at ale-pg1:~$ bucardo add all tables
>>> New tables added: 275
>>> bucardo at ale-pg1:~$ bucardo add all sequences
>>> New sequences added: 99
>>> bucardo at ale-pg1:~$ bucardo add herd copying_herd
>>> Created relgroup "copying_herd"
>>> bucardo at ale-pg1:~$ bucardo add sync the_sync relgroup=copying_herd dbs=source_db:source,dest_db:target onetimecopy=2
>>> WARNING:  Relgroup has no members: copying_herd
>>> Added sync "the_sync"
>>> Created a new dbgroup named "the_sync"
>>> 
>>> bucardo at ale-pg1:~$ bucardo start
>>> Checking for existing processes
>>> Removing file "/var/run/bucardo/fullstopbucardo"
>>> Starting Bucardo
>>> bucardo at ale-pg1:~$ bucardo status
>>> PID of Bucardo MCP: 28741
>>>  Name       State    Last good    Time    Last I/D    Last bad    Time
>>> ==========+========+============+=======+===========+===========+=======
>>>  the_sync | Bad    | none       |       |           | 16:48:44  | 3s
>>> bucardo at ale-pg1:~$ bucardo status the_sync
>>> ======================================================================
>>> Use of uninitialized value $sourcedb in concatenation (.) or string at /usr/bin/bucardo line 6013.
>>> Last bad                 : Dec 19, 2016 16:48:44 (time until fail: 1s)
>>> Sync name                : the_sync
>>> Current state            : Bad
>>> Source relgroup/database : copying_herd /
>>> Tables in sync           : 0
>>> Status                   : Active
>>> Check time               : None
>>> Overdue time             : 00:00:00
>>> Expired time             : 00:00:00
>>> Stayalive/Kidsalive      : Yes / Yes
>>> Rebuild index            : No
>>> Autokick                 : Yes
>>> Onetimecopy              : No
>>> Post-copy analyze        : Yes
>>> Last error:              : Failed : DBD::Pg::st execute failed: ERROR:  schema "bucardo" does not exist LINE 1: ...ident(tname), MAX(EXTRACT(epoch FROM cdate)) FROM bucardo.bu...                                                              ^ at /usr/sh\
>>> are/perl5/Bucardo.pm line 3299. Line: 5041 Main DB state: ? Error: none DB dest_db state: ? Error: none DB source_db state: 3F000 Error: 7  (KID 28752)
>>> ======================================================================
>>> bucardo at ale-pg1:~$ bucardo stop
>>> Creating /var/run/bucardo/fullstopbucardo ... Done
>>> 
>>> 
>>> 
>>>> On Dec 19, 2016, at 1:49 PM, David Christensen <david at endpoint.com <mailto:david at endpoint.com>> wrote:
>>>> 
>>>> 
>>>>> On Dec 19, 2016, at 11:06 AM, Donald StDenis < <mailto:donald.stdenis at goodsearch.com>donald.stdenis at goodsearch.com <mailto:donald.stdenis at goodsearch.com>> wrote:
>>>>> 
>>>>> Hi,
>>>>> 
>>>>> I’ve been trying to set up Bucardo replication from Pg9.2 to Pg9.6 and I can’t seem to make the replication start.
>>>>> 
>>>>> I did this from 9.2->9.2 about 6 months ago with almost no problems as I recall.
>>>>> 
>>>>> The bucardo status error on the slave is: 
>>>>> 
>>>>> bacardi:~$ bucardo status
>>>> 
>>>> [snip]
>>>> 
>>>> Hi Donald,
>>>> 
>>>> If it’s not finding the “bucardo” schema, that would indicate that the “validate_sync()” step did not complete successfully when you did an `bucardo add sync …`.  Do you have logs of the steps for setting this up and any errors encountered in that process?
>>>> 
>>>> Best,
>>>> 
>>>> David
>>>> --
>>>> David Christensen
>>>> End Point Corporation
>>>> david at endpoint.com <mailto:david at endpoint.com>
>>>> 785-727-1171 <tel:%28785%29%20727-1171>
>>>> 
>>>> 
>>>> 
>>> 
>>> 
>>> 
>>> 
>>> -- 
>>> --
>>> Donald St. Denis
>>> DevOps Engineer
>>> donald.stdenis at goodsearch.com <mailto:donald.stdenis at goodsearch.com>
>>> 707-331-9624
>> 
> 

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://mail.endcrypt.com/pipermail/bucardo-general/attachments/20170112/3766694f/attachment-0001.html>


More information about the Bucardo-general mailing list