Hi Nuno,
I did the same test again this morning, your right, there is nearly
nothing in the log, that indicates an error, but my Application got the
following exception from the controller:
Inititialize: test_big_36_C on test_big_36_Bbeqv377w
Enable: test_big_36_C on test_big_36_Bbeqv377w
createDump: test_big_36_C on test_big_36_Bbeqv377w init_dump_test_big_36_C
transferDump: test_big_36_C on init_dump_test_big_36_C xxx.234.68.194:1090
2007-06-01 08:32:28,376 FATAL [main] ClusterAdminLogger:
org.continuent.sequoia.controller.virtualdatabase.DistributedVirtualDatabase.getControllerByName(DistributedVirtualDatabase.java:1280)
FATAL -
org.continuent.sequoia.controller.virtualdatabase.DistributedVirtualDatabase.getControllerByName(DistributedVirtualDatabase.java:1280)
2007-06-01 08:32:28,376 FATAL [main] ClusterAdminLogger:
org.continuent.sequoia.controller.virtualdatabase.DistributedVirtualDatabase.sendMessageToController(DistributedVirtualDatabase.java:2713)
FATAL -
org.continuent.sequoia.controller.virtualdatabase.DistributedVirtualDatabase.sendMessageToController(DistributedVirtualDatabase.java:2713)
2007-06-01 08:32:28,376 FATAL [main] ClusterAdminLogger:
org.continuent.sequoia.controller.virtualdatabase.DistributedVirtualDatabase.transferDump(DistributedVirtualDatabase.java:2941)
FATAL -
org.continuent.sequoia.controller.virtualdatabase.DistributedVirtualDatabase.transferDump(DistributedVirtualDatabase.java:2941)
2007-06-01 08:32:28,376 FATAL [main] ClusterAdminLogger:
org.continuent.sequoia.controller.virtualdatabase.management.VirtualDatabase.transferDump(VirtualDatabase.java:514)
FATAL -
org.continuent.sequoia.controller.virtualdatabase.management.VirtualDatabase.transferDump(VirtualDatabase.java:514)
2007-06-01 08:32:28,376 FATAL [main] ClusterAdminLogger:
sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
FATAL - sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
2007-06-01 08:32:28,376 FATAL [main] ClusterAdminLogger:
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
FATAL -
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
2007-06-01 08:32:28,376 FATAL [main] ClusterAdminLogger:
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
FATAL -
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
2007-06-01 08:32:28,376 FATAL [main] ClusterAdminLogger:
java.lang.reflect.Method.invoke(Method.java:585)
FATAL - java.lang.reflect.Method.invoke(Method.java:585)
2007-06-01 08:32:28,376 FATAL [main] ClusterAdminLogger:
com.sun.jmx.mbeanserver.StandardMetaDataImpl.invoke(StandardMetaDataImpl.java:414)
FATAL -
com.sun.jmx.mbeanserver.StandardMetaDataImpl.invoke(StandardMetaDataImpl.java:414)
2007-06-01 08:32:28,376 FATAL [main] ClusterAdminLogger:
javax.management.StandardMBean.invoke(StandardMBean.java:323)
FATAL - javax.management.StandardMBean.invoke(StandardMBean.java:323)
2007-06-01 08:32:28,376 FATAL [main] ClusterAdminLogger:
com.sun.jmx.mbeanserver.DynamicMetaDataImpl.invoke(DynamicMetaDataImpl.java:213)
FATAL -
com.sun.jmx.mbeanserver.DynamicMetaDataImpl.invoke(DynamicMetaDataImpl.java:213)
2007-06-01 08:32:28,376 FATAL [main] ClusterAdminLogger:
com.sun.jmx.mbeanserver.MetaDataImpl.invoke(MetaDataImpl.java:220)
FATAL - com.sun.jmx.mbeanserver.MetaDataImpl.invoke(MetaDataImpl.java:220)
2007-06-01 08:32:28,376 FATAL [main] ClusterAdminLogger:
com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.invoke(DefaultMBeanServerInterceptor.java:815)
FATAL -
com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.invoke(DefaultMBeanServerInterceptor.java:815)
2007-06-01 08:32:28,376 FATAL [main] ClusterAdminLogger:
com.sun.jmx.mbeanserver.JmxMBeanServer.invoke(JmxMBeanServer.java:784)
FATAL -
com.sun.jmx.mbeanserver.JmxMBeanServer.invoke(JmxMBeanServer.java:784)
2007-06-01 08:32:28,376 FATAL [main] ClusterAdminLogger:
org.continuent.sequoia.controller.jmx.ChainedMBeanServer.invoke(ChainedMBeanServer.java:318)
FATAL -
org.continuent.sequoia.controller.jmx.ChainedMBeanServer.invoke(ChainedMBeanServer.java:318)
2007-06-01 08:32:28,376 FATAL [main] ClusterAdminLogger:
org.continuent.sequoia.controller.jmx.AuthenticatingMBeanServer.invoke(AuthenticatingMBeanServer.java:127)
FATAL -
org.continuent.sequoia.controller.jmx.AuthenticatingMBeanServer.invoke(AuthenticatingMBeanServer.java:127)
2007-06-01 08:32:28,376 FATAL [main] ClusterAdminLogger:
javax.management.remote.rmi.RMIConnectionImpl.doOperation(RMIConnectionImpl.java:1408)
FATAL -
javax.management.remote.rmi.RMIConnectionImpl.doOperation(RMIConnectionImpl.java:1408)
2007-06-01 08:32:28,376 FATAL [main] ClusterAdminLogger:
javax.management.remote.rmi.RMIConnectionImpl.access$100(RMIConnectionImpl.java:81)
FATAL -
javax.management.remote.rmi.RMIConnectionImpl.access$100(RMIConnectionImpl.java:81)
2007-06-01 08:32:28,376 FATAL [main] ClusterAdminLogger:
javax.management.remote.rmi.RMIConnectionImpl$PrivilegedOperation.run(RMIConnectionImpl.java:1245)
FATAL -
javax.management.remote.rmi.RMIConnectionImpl$PrivilegedOperation.run(RMIConnectionImpl.java:1245)
2007-06-01 08:32:28,376 FATAL [main] ClusterAdminLogger:
java.security.AccessController.doPrivileged(Native Method)
FATAL - java.security.AccessController.doPrivileged(Native Method)
2007-06-01 08:32:28,376 FATAL [main] ClusterAdminLogger:
javax.management.remote.rmi.RMIConnectionImpl.doPrivilegedOperation(RMIConnectionImpl.java:1348)
FATAL -
javax.management.remote.rmi.RMIConnectionImpl.doPrivilegedOperation(RMIConnectionImpl.java:1348)
2007-06-01 08:32:28,376 FATAL [main] ClusterAdminLogger:
javax.management.remote.rmi.RMIConnectionImpl.invoke(RMIConnectionImpl.java:782)
FATAL -
javax.management.remote.rmi.RMIConnectionImpl.invoke(RMIConnectionImpl.java:782)
2007-06-01 08:32:28,376 FATAL [main] ClusterAdminLogger:
sun.reflect.GeneratedMethodAccessor177.invoke(Unknown Source)
FATAL - sun.reflect.GeneratedMethodAccessor177.invoke(Unknown Source)
2007-06-01 08:32:28,376 FATAL [main] ClusterAdminLogger:
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
FATAL -
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
2007-06-01 08:32:28,376 FATAL [main] ClusterAdminLogger:
java.lang.reflect.Method.invoke(Method.java:585)
FATAL - java.lang.reflect.Method.invoke(Method.java:585)
2007-06-01 08:32:28,376 FATAL [main] ClusterAdminLogger:
sun.rmi.server.UnicastServerRef.dispatch(UnicastServerRef.java:294)
FATAL - sun.rmi.server.UnicastServerRef.dispatch(UnicastServerRef.java:294)
2007-06-01 08:32:28,392 FATAL [main] ClusterAdminLogger:
sun.rmi.transport.Transport$1.run(Transport.java:153)
FATAL - sun.rmi.transport.Transport$1.run(Transport.java:153)
2007-06-01 08:32:28,392 FATAL [main] ClusterAdminLogger:
java.security.AccessController.doPrivileged(Native Method)
FATAL - java.security.AccessController.doPrivileged(Native Method)
2007-06-01 08:32:28,392 FATAL [main] ClusterAdminLogger:
sun.rmi.transport.Transport.serviceCall(Transport.java:149)
FATAL - sun.rmi.transport.Transport.serviceCall(Transport.java:149)
2007-06-01 08:32:28,392 FATAL [main] ClusterAdminLogger:
sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:466)
FATAL -
sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:466)
2007-06-01 08:32:28,392 FATAL [main] ClusterAdminLogger:
sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:707)
FATAL -
sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:707)
2007-06-01 08:32:28,392 FATAL [main] ClusterAdminLogger:
java.lang.Thread.run(Thread.java:595)
FATAL - java.lang.Thread.run(Thread.java:595)
2007-06-01 08:32:28,392 FATAL [main] ClusterAdminLogger: Caused by:
FATAL - Caused by:
2007-06-01 08:32:28,392 FATAL [main] ClusterAdminLogger: Cannot find
controller 149.234.68.194:1090 in group
FATAL - Cannot find controller 149.234.68.194:1090 in group
2007-06-01 08:32:28,392 ERROR [main] ClusterAdminLogger: Unable to
Initilize VirtualDatabase test_big_36_C
ERROR - Unable to Initilize VirtualDatabase test_big_36_C
Here the content of the logfile during this operations:
2007-06-01 08:32:11,829 INFO controller.backup.BackupManager Using
provided dump-server address: xxx.234.68.193
2007-06-01 08:32:11,841 INFO controller.backup.BackupManager Dump server
started @ 0.0.0.0/0.0.0.0:42995
2007-06-01 08:32:12,947 INFO controller.backup.BackupManager Registering
backuper MySQL to handle format MySQL raw dump
2007-06-01 08:32:12,950 INFO
backend.DatabaseBackend.test_big_36_Bbeqv377w Adding connection manager
for virtual user "mySQLSimpleUser"
2007-06-01 08:32:12,976 INFO sequoia.controller.recoverylog Creating
recovery log table: RECOVERY_TEST_BIG_36_C
2007-06-01 08:32:12,979 INFO sequoia.controller.recoverylog Creating
checkpoint table: CHECKPOINT_TEST_BIG_36_C
2007-06-01 08:32:12,982 INFO sequoia.controller.recoverylog Creating
backend table: BACKEND_TEST_BIG_36_C
2007-06-01 08:32:12,993 INFO sequoia.controller.recoverylog Creating dump
table: DUMP_TEST_BIG_36_C
2007-06-01 08:32:13,008 INFO controller.RequestManager.test_big_36_C
Request manager will parse requests with the following granularity: TABLE
2007-06-01 08:32:13,018 INFO controller.virtualdatabase.test_big_36_C
Using Hedera properties file: /hedera_appia.properties
2007-06-01 08:32:13,035 INFO appia.xml.AppiaXML Loading XML configuration
from file: /opt/sequoia-2.10.6-bin/config/appia.xml
2007-06-01 08:32:13,084 INFO continuent.hedera.appia AppiaThread:
Starting Appia.
2007-06-01 08:32:13,117 DEBUG continuent.hedera.appia Received new view:
version: 1
group: [Group:test_big_36_C]
id: [ViewID:0;[AppiaHedera@/xxx.234.68.193:42996]]
previous: []
view: [[AppiaHedera@/xxx.234.68.193:42996],]
addresses: [/xxx.234.68.193:42996,]
2007-06-01 08:32:13,120 DEBUG continuent.hedera.gms Appia reported new view:
version: 1
group: [Group:test_big_36_C]
id: [ViewID:0;[AppiaHedera@/xxx.234.68.193:42996]]
previous: []
view: [[AppiaHedera@/xxx.234.68.193:42996],]
addresses: [/xxx.234.68.193:42996,]
2007-06-01 08:32:15,126 INFO controller.virtualdatabase.test_big_36_C
Group test_big_36_C connected to Member(address=/xxx.234.68.193:42996,
uid=xxx.234.68.193:42996)
2007-06-01 08:32:15,129 INFO controller.virtualdatabase.test_big_36_C
First controller in group test_big_36_C
2007-06-01 08:32:15,136 INFO sequoia.controller.recoverylog Checking
recovery log consistency
2007-06-01 08:32:15,188 INFO controller.core.Controller Adding
VirtualDatabase test_big_36_C
2007-06-01 08:32:16,964 DEBUG continuent.hedera.gms Appia reported block()
2007-06-01 08:32:18,400 DEBUG continuent.hedera.appia Received new view:
version: 1
group: [Group:test_big_36_C]
id: [ViewID:1;[AppiaHedera@/xxx.234.68.193:42996]]
previous:
[[ViewID:0;[AppiaHedera@/xxx.234.68.193:42996]],[ViewID:0;[AppiaHedera@/xxx.234.68.194:37299]],]
view:
[[AppiaHedera@/xxx.234.68.193:42996],[AppiaHedera@/xxx.234.68.194:37299],]
addresses: [/xxx.234.68.193:42996,/xxx.234.68.194:37299,]
2007-06-01 08:32:18,404 DEBUG continuent.hedera.gms Appia reported new view:
version: 1
group: [Group:test_big_36_C]
id: [ViewID:1;[AppiaHedera@/xxx.234.68.193:42996]]
previous:
[[ViewID:0;[AppiaHedera@/xxx.234.68.193:42996]],[ViewID:0;[AppiaHedera@/xxx.234.68.194:37299]],]
view:
[[AppiaHedera@/xxx.234.68.193:42996],[AppiaHedera@/xxx.234.68.194:37299],]
addresses: [/xxx.234.68.193:42996,/xxx.234.68.194:37299,]
2007-06-01 08:32:18,403 DEBUG continuent.hedera.gms
Member(address=/xxx.234.68.194:37299, uid=xxx.234.68.194:37299) joins
Group(gid=test_big_36_C).
2007-06-01 08:32:19,260 INFO
backend.DatabaseBackend.test_big_36_Bbeqv377w Detected backend as: MySQL
2007-06-01 08:32:19,348 INFO controller.RequestManager.test_big_36_C
Setting new virtual database schema.
2007-06-01 08:32:19,414 INFO controller.recoverylog.RecoverThread
Starting recovery
2007-06-01 08:32:19,448 INFO controller.RequestManager.test_big_36_C All
activity is suspended for test_big_36_C
2007-06-01 08:32:19,454 INFO controller.recoverylog.RecoverThread
Recovery completed
2007-06-01 08:32:19,540 INFO controller.recoverylog.RecoverThread
Database backend test_big_36_Bbeqv377w is now enabled
2007-06-01 08:32:19,543 WARN controller.virtualdatabase.test_big_36_C No
response while getting static metadata from remote controller
2007-06-01 08:32:19,622 INFO controller.RequestManager.test_big_36_C All
activity is suspended for test_big_36_C
2007-06-01 08:32:19,638 INFO controller.virtualdatabase.test_big_36_C
Checkpoint backup
init_dump_test_big_36_C-xxx.234.68.193:25322-20070601083219574+0200 was
stored
2007-06-01 08:32:19,644 INFO controller.virtualdatabase.test_big_36_C
Disabling backend test_big_36_Bbeqv377w, waiting for current transaction
to complete on this backend
2007-06-01 08:32:19,655 INFO controller.RequestManager.test_big_36_C
Setting new virtual database schema.
2007-06-01 08:32:19,668 INFO sequoia.controller.connection 2 connections
freed on "jdbc:mysql://beqv377w/test_big_36"
2007-06-01 08:32:21,330 INFO controller.virtualdatabase.test_big_36_C
Backend test_big_36_Bbeqv377w is now disabled
2007-06-01 08:32:21,332 WARN controller.virtualdatabase.test_big_36_C No
information has been found for remote controller
Member(address=/xxx.234.68.193:42996, uid=xxx.234.68.193:42996)
2007-06-01 08:32:21,333 WARN controller.virtualdatabase.test_big_36_C
Updating backend list with unknown backend test_big_36_Bbeqv377w disabled
on controller Member(address=/xxx.234.68.193:42996,
uid=xxx.234.68.193:42996)
2007-06-01 08:32:22,117 INFO controller.RequestManager.test_big_36_C
Backend test_big_36_Bbeqv377w is now disabled
2007-06-01 08:32:22,119 INFO controller.RequestManager.test_big_36_C
Starting backup of backend test_big_36_Bbeqv377w
2007-06-01 08:32:24,252 INFO backup.backupers.NativeCommandExec Starting
execution of "mysqldump --routines --add-drop-database -h beqv377w
--port=3306 -uuser1 --password=pass1 --databases test_big_36"
2007-06-01 08:32:24,523 INFO backup.backupers.NativeCommandExec Command
"mysqldump --routines --add-drop-database -h beqv377w --port=3306 -uuser1
--password=pass1 --databases test_big_36" logged 0 errors and terminated
with exitcode 0
2007-06-01 08:32:24,627 INFO controller.RequestManager.test_big_36_C
Backup has completed.
2007-06-01 08:32:24,924 INFO controller.recoverylog.RecoverThread
Starting recovery
2007-06-01 08:32:27,163 INFO controller.RequestManager.test_big_36_C All
activity is suspended for test_big_36_C
2007-06-01 08:32:27,167 INFO controller.recoverylog.RecoverThread
Recovery completed
Nothing spectacular, I think...
But look at this (using CLC):
Ready to administrate virtual database test_big_35_C
test_big_35_C(root) > show controllers
test_big_35_C is hosted by 1 controller(s):
xxx.234.68.193:1090
test_big_35_C(root) > show controllers
test_big_35_C is hosted by 1 controller(s):
xxx.234.68.193:1090
test_big_35_C(root) >
And in the logfile[full_cluster.log] (same time):
2007-06-01 08:40:57,327 INFO controller.virtualdatabase.test_big_35_C
Member(address=/xxx.234.68.193:42981, uid=xxx.234.68.193:42981) see
members:[Member(address=/xxx.234.68.193:42981, uid=xxx.234.68.193:42981),
Member(address=/xxx.234.68.194:37298, uid=xxx.234.68.194:37298)] and has
mapping:{Member(address=/xxx.234.68.193:42981,
uid=xxx.234.68.193:42981)=xxx.234.68.193:1090}
2007-06-01 08:41:25,381 INFO controller.virtualdatabase.test_big_35_C
Member(address=/xxx.234.68.193:42981, uid=xxx.234.68.193:42981) see
members:[Member(address=/xxx.234.68.193:42981, uid=xxx.234.68.193:42981),
Member(address=/xxx.234.68.194:37298, uid=xxx.234.68.194:37298)] and has
mapping:{Member(address=/xxx.234.68.193:42981,
uid=xxx.234.68.193:42981)=xxx.234.68.193:1090}
Later I took a look in the cluster.log and, *surprise, surprise*, I found:
2007-06-01 08:32:12,838 INFO Loading virtual databases configuration file
2007-06-01 08:32:15,191 INFO The virtual database test_big_36_C has been
successfully added to the controller.
2007-06-01 08:32:15,191 INFO Loading of virtual databases configuration
file has been successful
2007-06-01 08:32:19,073 INFO Virtual database test_big_36_C is
initializing from database backend test_big_36_Bbeqv377w
2007-06-01 08:32:19,084 INFO Database backend test_big_36_Bbeqv377w is
now in state disabled
2007-06-01 08:32:19,095 INFO Virtual database test_big_36_C
initialization from database backend test_big_36_Bbeqv377w completed
2007-06-01 08:32:19,118 INFO Virtual database test_big_36_C is enabling
database backend test_big_36_Bbeqv377w from checkpoint
2007-06-01 08:32:19,351 INFO Database backend test_big_36_Bbeqv377w is
now in state replaying
2007-06-01 08:32:19,479 INFO Database backend test_big_36_Bbeqv377w is
now in state write-only enabled
2007-06-01 08:32:19,483 INFO Database backend test_big_36_Bbeqv377w is
now in state enabled
2007-06-01 08:32:19,555 INFO Virtual database test_big_36_C successfully
enabled from checkpoint on database backend test_big_36_Bbeqv377w
2007-06-01 08:32:19,572 INFO Virtual database test_big_36_C is backuping
database backend test_big_36_Bbeqv377w with dump name
init_dump_test_big_36_C
2007-06-01 08:32:19,640 INFO Database backend test_big_36_Bbeqv377w is
now in state disabling
2007-06-01 08:32:19,645 INFO Database backend test_big_36_Bbeqv377w is
now in state disabled
2007-06-01 08:32:22,120 INFO Database backend test_big_36_Bbeqv377w is
now in state backing up
2007-06-01 08:32:24,597 INFO Database backend test_big_36_Bbeqv377w is
now in state disabled
2007-06-01 08:32:24,632 INFO Database backend test_big_36_Bbeqv377w is
now in state replaying
2007-06-01 08:32:27,201 INFO Database backend test_big_36_Bbeqv377w is
now in state write-only enabled
2007-06-01 08:32:27,204 INFO Database backend test_big_36_Bbeqv377w is
now in state enabled
2007-06-01 08:32:28,239 INFO Virtual database test_big_36_C successfully
backuped database backend test_big_36_Bbeqv377w with dump name
init_dump_test_big_36_C
2007-06-01 08:32:28,315 INFO Dump init_dump_test_big_36_C for virtual
database test_big_36_C is being transferred on remote controller
xxx.234.68.194:1090
2007-06-01 08:32:28,324 ERROR Failed to transfer dump
init_dump_test_big_36_C for virtual database test_big_36_C (because of :
Cannot find controller xxx.234.68.194:1090 in group)
A Few more details to the scenario, my app created and initilized
test_big_0_C...test_big_36_C automaticly and the first instances (around
30) worked fine, but the last failed with the described error / exception.
Any suggestions?
_______________________________________________
Sequoia mailing list
[email protected]
https://forge.continuent.org/mailman/listinfo/sequoia
