[Bucardo-general] Problem with Bucardo tests
Giulio Harding
giulio.harding at mnetcorporation.com
Wed Feb 27 05:51:17 UTC 2008
Hmm, increasing those timeouts didn't help much (despite being an
order of magnitude greater) - the tests still fall over at various
different points. If anything, there's even less consistency - in
some cases, the tests are getting further along (up to the 500s) but
in other cases it's still failing early. I'm not yet at the point
where I understand what's going on in the tests (beyond some basic
aspects), so I'm not sure how to interpret some of the errors I'm
seeing, *but* the one thing that does seem to be possibly consistent
is a report of some mismatch between some data structures that are
being copied & compared, e.g.
(3519) [1204076947] CTL Created new kid 3521 for sync "copytest"
(3521) [1204076947] KID Nothing to do: no entry found in the q table
for this sync
(3422) [1204078944] MCP Found stopfile "/tmp/
bucardo_testing_giulio.harding/fullstopbucardo": exiting
and
(6252) [1204086541] CTL Created new kid 6256 for sync "copytest"
(6256) [1204086541] KID Nothing to do: no entry found in the q table
for this sync
(6233) [1204088538] MCP Found stopfile "/tmp/
bucardo_testing_giulio.harding/fullstopbucardo": exiting
and
# Failed test '(fullcopy) Second table bucardo_test2 got the
fullcopy row [line: 2600]'
# at t/01bc.t line 1188.
# Structures begin differing at:
# $got->[0] = Does not exist
# $expected->[0] = ARRAY(0x18c4ff0)
Are they related?
From the output + log.bucardo file that the tests generate, I have
attached some snippets below... any other ideas? I'm somewhat
reluctant to go ahead with testing Bucardo if I can't get the tests
to work :( What's the ETA on the new tests?
Thanks!
Test Run 1
----------
Output:
...
# Called bucardo_ctl with: kick copytest 0 --dbname=bucardo_test --
dbuser=bucardo_test --dbpass=pie --ctlquiet --debugstderr=0 --
debugstdout=0 --debugfile=1 --verbose=1 --sendmail=0 --cleandebugs=0
--debugdir=. --extraname=bctest_giulio.harding --dbport=5432
ok 409 - (fullcopy) Second table bucardo_test3 got the fullcopy rows
[line: 2663]
ok 410 - (fullcopy) End of basic_copy_testing for bucardo_test3
[line: 2666]
ok 411 - (fullcopy) Table bucardo_test4 is the same on both databases
[line: 2570]
ok 412 - (fullcopy) After insert, trigger and rule both populate
droptest table [line: 2584]
ok 413 - (fullcopy) Table droptest is empty on remote database
[line: 2588]
ok 414 - (fullcopy) Second table bucardo_test4 still empty before
kick [line: 2594]
# Called bucardo_ctl with: Kick copytest 0 --dbname=bucardo_test --
dbuser=bucardo_test --dbpass=pie --ctlquiet --debugstderr=0 --
debugstdout=0 --debugfile=1 --verbose=1 --sendmail=0 --cleandebugs=0
--debugdir=. --extraname=bctest_giulio.harding --dbport=5432
ok 415 - (fullcopy) Second table bucardo_test4 got the fullcopy row
[line: 2600]
ok 416 - (fullcopy) Triggers and rules did NOT fire on remote table
[line: 2604]
ok 417 - (fullcopy) After insert, trigger and rule both populate
droptest table [line: 2624]
ok 418 - (fullcopy) Table droptest is empty on remote database
[line: 2628]
# Called bucardo_ctl with: kick copytest 0 --dbname=bucardo_test --
dbuser=bucardo_test --dbpass=pie --ctlquiet --debugstderr=0 --
debugstdout=0 --debugfile=1 --verbose=1 --sendmail=0 --cleandebugs=0
--debugdir=. --extraname=bctest_giulio.harding --dbport=5432
Bailout called. Further testing stopped: bucardo_ctl was not
invoked: is the bucardo.test.helper file running? (command=kick
copytest 0)
bucardo_ctl was not invoked: is the bucardo.test.helper file running?
(command=kick copytest 0)
#
# Leaving, shutting down any running processes
# Called bucardo_ctl with: stop 'Stop the testing' --
dbname=bucardo_test --dbuser=bucardo_test --dbpass=pie --ctlquiet --
debugstderr=0 --debugstdout=0 --debugfile=1 --verbose=1 --sendmail=0
--cleandebugs=0 --debugdir=. --extraname=bctest_giulio.harding --
dbport=5432
make: *** [test_dynamic] Error 1
log.bucardo:
...
(3497) [1204076943] KID Analyzing bucardo_schema.bucardo_test2 on
bctest2
(3497) [1204076943] KID Emptying out target table
bucardo_schema.bucardo_test3 using delete
(3497) [1204076943] KID Rows deleted from
bucardo_schema.bucardo_test3: 6
(3497) [1204076943] KID Running on bctest1: COPY
bucardo_schema.bucardo_test3 TO STDOUT
(3497) [1204076943] KID Running on bctest2: COPY
bucardo_schema.bucardo_test3 FROM STDIN
(3497) [1204076943] KID End COPY of "bucardo_schema.bucardo_test3".
Rows inserted: 6
(3497) [1204076943] KID Analyzing bucardo_schema.bucardo_test3 on
bctest2
(3497) [1204076943] KID Emptying out target table
bucardo_schema.bucardo_test4 using delete
(3497) [1204076943] KID Rows deleted from
bucardo_schema.bucardo_test4: 1
(3497) [1204076943] KID Running on bctest1: COPY
bucardo_schema.bucardo_test4 TO STDOUT
(3497) [1204076943] KID Running on bctest2: COPY
bucardo_schema.bucardo_test4 FROM STDIN
(3497) [1204076943] KID End COPY of "bucardo_schema.bucardo_test4".
Rows inserted: 1
(3497) [1204076943] KID Analyzing bucardo_schema.bucardo_test4 on
bctest2
(3495) [1204076943] CTL Got notice
"bucardo_syncdone_copytest_bctest2" from 3504
(3497) [1204076943] KID Total target rows deleted: 25
(3497) [1204076943] KID Total target rows copied: 25
(3497) [1204076943] KID Enabling triggers and rules
(3495) [1204076943] CTL Sent notice "bucardo_syncdone_copytest"
(3497) [1204076943] KID Issuing final commit for source and target
(3497) [1204076944] KID Marking as done in the q table, notifying
controller
(3497) [1204076944] KID Finished syncing. Time: 2. Updates: 0+0
Inserts: 0+25 Deletes: 0+25 Sync: copytest. Keepalive: 1
(3422) [1204076944] MCP Got notice "bucardo_reload_sync_copytest"
from 3052 on main
(3422) [1204076944] MCP Deactivating sync copytest
(3422) [1204076944] MCP Sent kill 15 to CTL process 3495. Result: 1
(3495) [1204076944] CTL Warning! Controller for "copytest" was killed
at line 269: Caught a SIGTERM at /usr/lib/perl5/site_perl/5.8.8/
Bucardo.pm line 2751
(3495) [1204076944] CTL Asking kid process 3497 to terminate
(3495) [1204076944] CTL Controller exiting at cleanup_controller.
Reason: Killed (line 269): Caught a SIGTERM at /usr/lib/perl5/
site_perl/5.8.8/Bucardo.pm line 2751
(3497) [1204076944] KID Warning! Child for "copytest" was killed at
line 269: Caught a SIGTERM at /usr/lib/perl5/site_perl/5.8.8/
Bucardo.pm line 3670
(3422) [1204076946] MCP Reactivating sync copytest
(3422) [1204076946] MCP Validating source table
"bucardo_schema.bucardo_test0" on bctest1
(3422) [1204076946] MCP Comparing tables and columns on bctest2
(3422) [1204076946] MCP Validating source table
"bucardo_schema.bucardo_test1" on bctest1
(3422) [1204076946] MCP Comparing tables and columns on bctest2
(3422) [1204076946] MCP Validating source table
"bucardo_schema.bucardo_test2" on bctest1
(3422) [1204076946] MCP Comparing tables and columns on bctest2
(3422) [1204076946] MCP Validating source table
"bucardo_schema.bucardo_test3" on bctest1
(3422) [1204076946] MCP Comparing tables and columns on bctest2
(3422) [1204076946] MCP Validating source table
"bucardo_schema.bucardo_test4" on bctest1
(3422) [1204076946] MCP Comparing tables and columns on bctest2
(3422) [1204076946] MCP Listening on source server bctest1 for
"bucardo_kick_sync_copytest"
(3422) [1204076946] MCP Sent notice bucardo_reloaded_sync_copytest
(3422) [1204076946] MCP Checking for existing controllers for sync
"copytest"
(3519) [1204076947] CTL Controller starting for sync "copytest".
Source herd is "bctestherd1"
(3519) [1204076947] CTL database: bctest2 synctype:fullcopy
stayalive:1 checksecs:0
(3519) [1204076947] CTL limitdbs:0 kicked:0 kidsalive:1 triggers: SQL
(3422) [1204076947] MCP Created controller 3519 for sync "copytest".
Kick is 0
(3519) [1204076947] CTL Listening for "bucardo_ctl_kick_copytest"
(3422) [1204076947] MCP Got notice "bucardo_kick_sync_copytest" from
3518 on main
(3422) [1204076947] MCP Got notice "bucardo_kick_sync_copytest" from
3054 on db bctest1
(3422) [1204076947] MCP Sent a kick request to controller 3519 for
sync "copytest"
(3519) [1204076947] CTL Herd member 45671:
bucardo_schema.bucardo_test0
(3519) [1204076947] CTL Target oids: bctest2:45676
(3519) [1204076947] CTL Herd member 45692:
bucardo_schema.bucardo_test1
(3519) [1204076947] CTL Target oids: bctest2:45702
(3519) [1204076947] CTL Herd member 45728:
bucardo_schema.bucardo_test2
(3519) [1204076947] CTL Target oids: bctest2:45738
(3519) [1204076947] CTL Herd member 45764:
bucardo_schema.bucardo_test3
(3519) [1204076947] CTL Target oids: bctest2:45774
(3519) [1204076947] CTL Herd member 45800:
bucardo_schema.bucardo_test4
(3519) [1204076947] CTL Target oids: bctest2:45810
(3521) [1204076947] KID New kid, syncs "bctest1" to "bctest2" for
sync "copytest" alive=1 Parent=3519
(3519) [1204076947] CTL Created new kid 3521 for sync "copytest"
(3521) [1204076947] KID Nothing to do: no entry found in the q table
for this sync
(3422) [1204078944] MCP Found stopfile "/tmp/
bucardo_testing_giulio.harding/fullstopbucardo": exiting
(3422) [1204078944] MCP Removed file "/tmp/
bucardo_testing_giulio.harding/bucardo_testing.pid"
(3521) [1204078944] KID Found stopfile "/tmp/
bucardo_testing_giulio.harding/fullstopbucardo": exiting
(3422) [1204078945] MCP End of cleanup_mcp. Sys time: Wed Feb 27
13:22:25 2008. DB time: 2008-02-27 13:22:25.086911+11
(3422) [1204078945] MCP Exiting
(3521) [1204078945] KID Kid exiting
(3519) [1204078945] CTL Found stopfile "/tmp/
bucardo_testing_giulio.harding/fullstopbucardo": exiting
(3519) [1204078945] CTL Warning! Controller for "copytest" was killed
at line 2546: Found stopfile
(3519) [1204078945] CTL Controller exiting at cleanup_controller.
Reason: Killed (line 2546): Found stopfile
Test Run 2
----------
Output:
...
ok 347 - (makedelta) Insert to target bucardo_test4 with makedelta
created a source bucardo_track row [line: 2509]
ok 348 - (makedelta) Update to target bucardo_test4 populated target
bucardo_delta correctly [line: 2517]
ok 349 - (makedelta) Update to target bucardo_test4 with makedelta
created a source bucardo_delta row [line: 2525]
ok 350 - (makedelta) Update to target bucardo_test4 with makedelta
created a source bucardo_track row [line: 2530]
ok 351 - (makedelta) Delete to target bucardo_test4 populated target
bucardo_delta correctly [line: 2539]
ok 352 - (makedelta) Delete to target bucardo_test4 with makedelta
created a source bucardo_delta row [line: 2547]
ok 353 - (makedelta) Delete to target bucardo_test4 with makedelta
created a source bucardo_track row [line: 2552]
ok 354 - (makedelta) Finished with makedelta tests [line: 600]
ok 355 - (copy) Begin TEST_COPY section [line: 607]
ok 356 - (copy) Existing Bucardo asked to shut down [line: 897]
ok 357 - (copy) Finished clean_all_tables [line: 1006]
# Called bucardo_ctl with: start 'Start fullcopy testing' --
dbname=bucardo_test --dbuser=bucardo_test --dbpass=pie --ctlquiet --
debugstderr=0 --debugstdout=0 --debugfile=1 --verbose=1 --sendmail=0
--cleandebugs=0 --debugdir=. --extraname=bctest_giulio.harding --dbport=
5432
ok 358 - (copy) Bucardo was started [line: 627]
ok 359 - (fullcopy) Table bucardo_test0 is the same on both databases
[line: 2570]
ok 360 - (fullcopy) After insert, trigger and rule both populate
droptest table [line: 2584]
ok 361 - (fullcopy) Table droptest is empty on remote database
[line: 2588]
ok 362 - (fullcopy) Second table bucardo_test0 still empty before
kick [line: 2594]
# Called bucardo_ctl with: Kick copytest 0 --dbname=bucardo_test --
dbuser=bucardo_test --dbpass=pie --ctlquiet --debugstderr=0 --
debugstdout=0 --debugfile=1 --verbose=1 --sendmail=0 --cleandebugs=0
--debugdir=. --extraname=bctest_giulio.harding --dbport=5432
ok 363 - (fullcopy) Second table bucardo_test0 got the fullcopy row
[line: 2600]
ok 364 - (fullcopy) Triggers and rules did NOT fire on remote table
[line: 2604]
ok 365 - (fullcopy) After insert, trigger and rule both populate
droptest table [line: 2624]
ok 366 - (fullcopy) Table droptest is empty on remote database
[line: 2628]
# Called bucardo_ctl with: kick copytest 0 --dbname=bucardo_test --
dbuser=bucardo_test --dbpass=pie --ctlquiet --debugstderr=0 --
debugstdout=0 --debugfile=1 --verbose=1 --sendmail=0 --cleandebugs=0
--debugdir=. --extraname=bctest_giulio.harding --dbport=5432
Bailout called. Further testing stopped: bucardo_ctl was not
invoked: is the bucardo.test.helper file running? (command=kick
copytest 0)
bucardo_ctl was not invoked: is the bucardo.test.helper file running?
(command=kick copytest 0)
#
# Leaving, shutting down any running processes
# Called bucardo_ctl with: stop 'Stop the testing' --
dbname=bucardo_test --dbuser=bucardo_test --dbpass=pie --ctlquiet --
debugstderr=0 --debugstdout=0 --debugfile=1 --verbose=1 --sendmail=0
--cleandebugs=0 --debugdir=. --extraname=bctest_giulio.harding --
dbport=5432
(NOTE: the bucardo test process did not actually shut down in this
instance)
log.bucardo:
...
(6241) [1204086536] KID Analyzing bucardo_schema.bucardo_test3 on
bctest2
(6241) [1204086536] KID Emptying out target table
bucardo_schema.bucardo_test4 using delete
(6241) [1204086536] KID Rows deleted from
bucardo_schema.bucardo_test4: 0
(6241) [1204086536] KID Running on bctest1: COPY
bucardo_schema.bucardo_test4 TO STDOUT
(6241) [1204086536] KID Running on bctest2: COPY
bucardo_schema.bucardo_test4 FROM STDIN
(6241) [1204086536] KID End COPY of "bucardo_schema.bucardo_test4".
Rows inserted: 0
(6241) [1204086536] KID Analyzing bucardo_schema.bucardo_test4 on
bctest2
(6241) [1204086536] KID Total target rows deleted: 0
(6241) [1204086536] KID Total target rows copied: 1
(6241) [1204086536] KID Issuing final commit for source and target
(6241) [1204086536] KID Marking as done in the q table, notifying
controller
(6241) [1204086537] KID Finished syncing. Time: 2. Updates: 0+0
Inserts: 0+1 Deletes: 0+0 Sync: copytest. Keepalive: 1
(6239) [1204086537] CTL Got notice
"bucardo_syncdone_copytest_bctest2" from 6242
(6239) [1204086537] CTL Sent notice "bucardo_syncdone_copytest"
(6233) [1204086537] MCP Got notice "bucardo_reload_sync_copytest"
from 5861 on main
(6233) [1204086537] MCP Deactivating sync copytest
(6233) [1204086537] MCP Sent kill 15 to CTL process 6239. Result: 1
(6239) [1204086538] CTL Warning! Controller for "copytest" was killed
at line 269: Caught a SIGTERM at /usr/lib/perl5/site_perl/5.8.8/
Bucardo.pm line 2751
(6239) [1204086538] CTL Asking kid process 6241 to terminate
(6239) [1204086538] CTL Controller exiting at cleanup_controller.
Reason: Killed (line 269): Caught a SIGTERM at /usr/lib/perl5/
site_perl/5.8.8/Bucardo.pm line 2751
(6241) [1204086538] KID Warning! Child for "copytest" was killed at
line 269: Caught a SIGTERM at /usr/lib/perl5/site_perl/5.8.8/
Bucardo.pm line 3670
(6233) [1204086540] MCP Reactivating sync copytest
(6233) [1204086540] MCP Validating source table
"bucardo_schema.bucardo_test0" on bctest1
(6233) [1204086540] MCP Comparing tables and columns on bctest2
(6233) [1204086540] MCP Validating source table
"bucardo_schema.bucardo_test1" on bctest1
(6233) [1204086540] MCP Comparing tables and columns on bctest2
(6233) [1204086540] MCP Validating source table
"bucardo_schema.bucardo_test2" on bctest1
(6233) [1204086540] MCP Comparing tables and columns on bctest2
(6233) [1204086540] MCP Validating source table
"bucardo_schema.bucardo_test3" on bctest1
(6233) [1204086540] MCP Comparing tables and columns on bctest2
(6233) [1204086540] MCP Validating source table
"bucardo_schema.bucardo_test4" on bctest1
(6233) [1204086540] MCP Comparing tables and columns on bctest2
(6233) [1204086540] MCP Listening on source server bctest1 for
"bucardo_kick_sync_copytest"
(6233) [1204086540] MCP Sent notice bucardo_reloaded_sync_copytest
(6233) [1204086540] MCP Checking for existing controllers for sync
"copytest"
(6233) [1204086540] MCP Created controller 6252 for sync "copytest".
Kick is 0
(6252) [1204086540] CTL Controller starting for sync "copytest".
Source herd is "bctestherd1"
(6252) [1204086540] CTL database: bctest2 synctype:fullcopy
stayalive:1 checksecs:0
(6252) [1204086540] CTL limitdbs:0 kicked:0 kidsalive:1 triggers: SQL
(6252) [1204086540] CTL Listening for "bucardo_ctl_kick_copytest"
(6233) [1204086540] MCP Got notice "bucardo_kick_sync_copytest" from
6250 on main
(6233) [1204086540] MCP Got notice "bucardo_kick_sync_copytest" from
5866 on db bctest1
(6233) [1204086540] MCP Sent a kick request to controller 6252 for
sync "copytest"
(6252) [1204086541] CTL Herd member 47149:
bucardo_schema.bucardo_test0
(6252) [1204086541] CTL Target oids: bctest2:47154
(6252) [1204086541] CTL Herd member 47170:
bucardo_schema.bucardo_test1
(6252) [1204086541] CTL Target oids: bctest2:47180
(6252) [1204086541] CTL Herd member 47206:
bucardo_schema.bucardo_test2
(6252) [1204086541] CTL Target oids: bctest2:47216
(6252) [1204086541] CTL Herd member 47242:
bucardo_schema.bucardo_test3
(6252) [1204086541] CTL Target oids: bctest2:47252
(6252) [1204086541] CTL Herd member 47278:
bucardo_schema.bucardo_test4
(6252) [1204086541] CTL Target oids: bctest2:47288
(6256) [1204086541] KID New kid, syncs "bctest1" to "bctest2" for
sync "copytest" alive=1 Parent=6252
(6252) [1204086541] CTL Created new kid 6256 for sync "copytest"
(6256) [1204086541] KID Nothing to do: no entry found in the q table
for this sync
(6233) [1204088538] MCP Found stopfile "/tmp/
bucardo_testing_giulio.harding/fullstopbucardo": exiting
(6233) [1204088538] MCP Removed file "/tmp/
bucardo_testing_giulio.harding/bucardo_testing.pid"
(6256) [1204088538] KID Found stopfile "/tmp/
bucardo_testing_giulio.harding/fullstopbucardo": exiting
(6233) [1204088538] MCP End of cleanup_mcp. Sys time: Wed Feb 27
16:02:18 2008. DB time: 2008-02-27 16:02:18.435824+11
(6233) [1204088538] MCP Exiting
(6256) [1204088538] KID Kid exiting
(6252) [1204088539] CTL Found stopfile "/tmp/
bucardo_testing_giulio.harding/fullstopbucardo": exiting
(6252) [1204088539] CTL Warning! Controller for "copytest" was killed
at line 2546: Found stopfile
(6252) [1204088539] CTL Controller exiting at cleanup_controller.
Reason: Killed (line 2546): Found stopfile
Processes remaining:
[04:28 PM] nyx /tmp/Bucardo/Bucardo-3.0.8 -$ ps -ef | grep bucardo
1056 5849 1 0 15:19 pts/0 00:00:00 /usr/bin/perl t/
bucardo.test.helper
postgres 5861 9232 0 15:19 ? 00:00:00 postgres:
bucardo_test bucardo_test [local] idle
postgres 5866 9232 0 15:19 ? 00:00:00 postgres:
bucardo_test1 bucardo_test1 [local] idle
postgres 5868 9232 0 15:19 ? 00:00:00 postgres:
bucardo_test2 bucardo_test2 [local] idle
postgres 5870 9232 0 15:19 ? 00:00:00 postgres:
bucardo_test3 bucardo_test3 [local] idle
postgres 5873 9232 0 15:19 ? 00:00:00 postgres:
bucardo_test bucardo_test [local] idle
1056 6249 5849 0 15:28 pts/0 00:00:00 /usr/local/bin/perl
-- -*-cperl-*- ./bucardo_ctl kick copytest 0 --dbname=bucardo_test --
dbuser=bucardo_test --dbpass=pie --ctlquiet --debugstderr=0 --
debugstdout=0 --debugfile=1 --verbose=1 --sendmail=0 --cleandebugs=0
--debugdir=. --extraname=bctest_giulio.harding --dbport=5432
postgres 6250 9232 0 15:28 ? 00:00:00 postgres:
bucardo_test bucardo_test [local] idle
Test Run 3
----------
Output:
...
# Called bucardo_ctl with: kick copytest 0 --dbname=bucardo_test --
dbuser=bucardo_test --dbpass=pie --ctlquiet --debugstderr=0 --
debugstdout=0 --debugfile=1 --verbose=1 --sendmail=0 --cleandebugs=0
--debugdir=. --extraname=bctest_giulio.harding --dbport=5432
ok 383 - (fullcopy) Second table bucardo_test1 got the fullcopy rows
[line: 2663]
ok 384 - (fullcopy) End of basic_copy_testing for bucardo_test1
[line: 2666]
ok 385 - (fullcopy) Table bucardo_test2 is the same on both databases
[line: 2570]
ok 386 - (fullcopy) After insert, trigger and rule both populate
droptest table [line: 2584]
ok 387 - (fullcopy) Table droptest is empty on remote database
[line: 2588]
ok 388 - (fullcopy) Second table bucardo_test2 still empty before
kick [line: 2594]
# Called bucardo_ctl with: Kick copytest 0 --dbname=bucardo_test --
dbuser=bucardo_test --dbpass=pie --ctlquiet --debugstderr=0 --
debugstdout=0 --debugfile=1 --verbose=1 --sendmail=0 --cleandebugs=0
--debugdir=. --extraname=bctest_giulio.harding --dbport=5432
not ok 389 - (fullcopy) Second table bucardo_test2 got the fullcopy
row [line: 2600]
# Failed test '(fullcopy) Second table bucardo_test2 got the
fullcopy row [line: 2600]'
# at t/01bc.t line 1188.
# Structures begin differing at:
# $got->[0] = Does not exist
# $expected->[0] = ARRAY(0x18c4ff0)
# GOT: []
# EXPECTED: [[1]]
Bailout called. Further testing stopped: Stopping on a failed
'is_deeply' test from line 1265. Time: 1204090755
Stopping on a failed 'is_deeply' test from line 1265. Time: 1204090755
#
# Leaving, shutting down any running processes
# Called bucardo_ctl with: stop 'Stop the testing' --
dbname=bucardo_test --dbuser=bucardo_test --dbpass=pie --ctlquiet --
debugstderr=0 --debugstdout=0 --debugfile=1 --verbose=1 --sendmail=0
--cleandebugs=0 --debugdir=. --extraname=bctest_giulio.harding --
dbport=5432
make: *** [test_dynamic] Error 1
log.bucardo:
...
(7668) [1204090754] KID Analyzing bucardo_schema.bucardo_test4 on
bctest2
(7668) [1204090754] KID Total target rows deleted: 12
(7668) [1204090754] KID Total target rows copied: 12
(7668) [1204090754] KID Enabling triggers and rules
(7668) [1204090754] KID Issuing final commit for source and target
(7668) [1204090754] KID Marking as done in the q table, notifying
controller
(7668) [1204090754] KID Finished syncing. Time: 1. Updates: 0+0
Inserts: 0+12 Deletes: 0+12 Sync: copytest. Keepalive: 1
(7628) [1204090754] MCP Got notice "bucardo_kick_sync_copytest" from
7264 on db bctest1
(7628) [1204090754] MCP Sent a kick request to controller 7666 for
sync "copytest"
(7666) [1204090755] CTL Got notice
"bucardo_syncdone_copytest_bctest2" from 7669
(7666) [1204090755] CTL Sent notice "bucardo_syncdone_copytest"
(7666) [1204090755] CTL Got notice "bucardo_ctl_kick_copytest" from 7629
(7628) [1204090755] MCP Got notice "bucardo_kick_sync_copytest" from
7676 on main
(7628) [1204090755] MCP Sent a kick request to controller 7666 for
sync "copytest"
(7668) [1204090755] KID Got a notice for copytest: bctest1 -> bctest2
(7668) [1204090755] KID Disabling triggers and rules on bctest2
(7628) [1204090755] MCP Found stopfile "/tmp/
bucardo_testing_giulio.harding/fullstopbucardo": exiting
(7628) [1204090755] MCP Removed file "/tmp/
bucardo_testing_giulio.harding/bucardo_testing.pid"
(7668) [1204090755] KID Emptying out target table
bucardo_schema.bucardo_test0 using delete
(7668) [1204090755] KID Rows deleted from
bucardo_schema.bucardo_test0: 6
(7668) [1204090756] KID Running on bctest1: COPY
bucardo_schema.bucardo_test0 TO STDOUT
(7668) [1204090756] KID Running on bctest2: COPY
bucardo_schema.bucardo_test0 FROM STDIN
(7668) [1204090756] KID End COPY of "bucardo_schema.bucardo_test0".
Rows inserted: 6
(7668) [1204090756] KID Analyzing bucardo_schema.bucardo_test0 on
bctest2
(7668) [1204090756] KID Emptying out target table
bucardo_schema.bucardo_test1 using delete
(7668) [1204090756] KID Rows deleted from
bucardo_schema.bucardo_test1: 6
(7668) [1204090756] KID Running on bctest1: COPY
bucardo_schema.bucardo_test1 TO STDOUT
(7668) [1204090756] KID Running on bctest2: COPY
bucardo_schema.bucardo_test1 FROM STDIN
(7668) [1204090756] KID End COPY of "bucardo_schema.bucardo_test1".
Rows inserted: 6
(7666) [1204090756] CTL Found stopfile "/tmp/
bucardo_testing_giulio.harding/fullstopbucardo": exiting
(7668) [1204090756] KID Analyzing bucardo_schema.bucardo_test1 on
bctest2
(7666) [1204090756] CTL Warning! Controller for "copytest" was killed
at line 2546: Found stopfile: Stop the testing
(7668) [1204090756] KID Emptying out target table
bucardo_schema.bucardo_test2 using delete
(7668) [1204090756] KID Rows deleted from
bucardo_schema.bucardo_test2: 0
(7668) [1204090756] KID Running on bctest1: COPY
bucardo_schema.bucardo_test2 TO STDOUT
(7668) [1204090756] KID Running on bctest2: COPY
bucardo_schema.bucardo_test2 FROM STDIN
(7668) [1204090756] KID End COPY of "bucardo_schema.bucardo_test2".
Rows inserted: 1
(7668) [1204090756] KID Analyzing bucardo_schema.bucardo_test2 on
bctest2
(7668) [1204090756] KID Emptying out target table
bucardo_schema.bucardo_test3 using delete
(7628) [1204090756] MCP End of cleanup_mcp. Sys time: Wed Feb 27
16:39:16 2008. DB time: 2008-02-27 16:39:16.832289+11
(7668) [1204090756] KID Rows deleted from
bucardo_schema.bucardo_test3: 0
(7668) [1204090757] KID Running on bctest1: COPY
bucardo_schema.bucardo_test3 TO STDOUT
(7668) [1204090757] KID Running on bctest2: COPY
bucardo_schema.bucardo_test3 FROM STDIN
(7668) [1204090757] KID End COPY of "bucardo_schema.bucardo_test3".
Rows inserted: 0
(7668) [1204090757] KID Analyzing bucardo_schema.bucardo_test3 on
bctest2
(7628) [1204090757] MCP Exiting
(7666) [1204090757] CTL Asking kid process 7668 to terminate
(7668) [1204090757] KID Warning! Rows set to aborted in the q table
for this child: 1
(7666) [1204090757] CTL Controller exiting at cleanup_controller.
Reason: Killed (line 2546): Found stopfile: Stop the testing
(7668) [1204090757] KID Warning! Child for "copytest" was killed at
line 269: Caught a SIGTERM at /usr/lib/perl5/site_perl/5.8.8/
Bucardo.pm line 751
On 26/02/2008, at 1:31 AM, Greg Sabino Mullane wrote:
>
> On Thu, 2008-02-21 at 23:50 +1030, Giulio Harding wrote:
>> However, I'm having some trouble running the Bucardo tests. This is
>> on a Centos 4.6 x86-64 server with PostgreSQL 8.3 (PGDG rpms) and
>> Bucardo 3.0.8 fresh from the website. Each time I run the tests I get
>> a failure at a different location. For example, using 'time make test
>> TEST_VERBOSE=1 BUCARDO_KEEP_OLD_DEBUG=1 BUCARDO_TESTBAIL=1':
>
> The tests can be a little fragile at the moment (better ones are in
> the
> works). You can try increasing some of the timeouts (vars starting
> with
> $ALARM or $TIMEOUT in t/01bc.t) and see if that helps. At the very
> least, adjusting those might allow you to reproduce the problems
> reliably. It might also be a Bucardo issue itself - hard to tell
> unless
> the test is reproducible of course. Sorry I don't have any other
> specific information at the moment. You might also check the generated
> bucardo.log file to see if anything suspicious occurred around the
> times
> of the dropped communications.
>
> --
> Greg Sabino Mullane greg at endpoint.com
> End Point Corporation 610-983-9073
>
--
Giulio Harding
Systems Administrator
m.Net Corporation
Level 2, 8 Leigh Street
Adelaide SA 5000, Australia
Tel: +61 8 8210 2041
Fax: +61 8 8211 9620
Mobile: 0432 876 733
Yahoo: giulio.harding
MSN: giulio.harding at mnetcorporation.com
http://www.mnetcorporation.com
-------------- next part --------------
A non-text attachment was scrubbed...
Name: smime.p7s
Type: application/pkcs7-signature
Size: 2451 bytes
Desc: not available
Url : https://mail.endcrypt.com/pipermail/bucardo-general/attachments/20080227/ad1c146a/attachment.bin
More information about the Bucardo-general
mailing list