No master node succeeded problem

[James Pirz]

Hi,

I am trying to put values, with sizes around 200k ~ 300K, in a cluster
of 6 nodes.
Persistence storage is mysql, but I am getting an error as:

Exception in thread "main"
voldemort.store.InsufficientOperationalNodesException: No master node
succeeded!
at voldemort.store.routed.RoutedStore.put(RoutedStore.java:703)
...
.
.
.
Caused by: voldemort.store.PersistenceFailureException: Fix me!
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native
Method)
...



I know this kind of exception occurs because of routing/connection
time-out or buffer size in sockets, but I have increased all of them,
here is my ClientConfig setting in the code:

ClientConfig cc = new ClientConfig();
cc.setBootstrapUrls("tcp://localhost:6666");
cc.setMaxThreads(10);
cc.setMaxQueuedRequests(500);
cc.setMaxConnectionsPerNode(10);
cc.setMaxTotalConnections(5000);
cc.setSocketTimeout(50000, TimeUnit.MILLISECONDS);
cc.setConnectionTimeout(15000, TimeUnit.MILLISECONDS);
cc.setRoutingTimeout(15000, TimeUnit.MILLISECONDS);
cc.setSocketBufferSize(3000000);


Any suggestion or idea to solve this problem ?

Thnx

-James

[Kirk True]

Hi James,

What sort of errors (if any) are being logged on the Voldemort storage
nodes?

Thanks,
Kirk

[James Pirz]

Kirk

No specific error is being logged in the nodes, after start log, I
just of a bunch of connected/disconnected logs for my attempts

[2010-08-13 11:16:51,275 voldemort.server.socket.SocketServerSession]
INFO Client /127.0.0.1:34478 connected successfully with protocol vp1
[2010-08-13 11:16:55,732 voldemort.server.socket.SocketServerSession]
INFO Client /127.0.0.1:34478 disconnected.
[2010-08-13 11:17:09,174 voldemort.server.socket.SocketServerSession]
INFO Client /127.0.0.1:34480 connected successfully with protocol vp1
[2010-08-13 11:17:13,054 voldemort.server.socket.SocketServerSession]
INFO Client /127.0.0.1:34480 disconnected.
[2010-08-13 11:41:33,776 voldemort.server.socket.SocketServerSession]
INFO Client /127.0.0.1:49884 connected successfully with protocol vp1
[2010-08-13 11:41:38,410 voldemort.server.socket.SocketServerSession]
INFO Client /127.0.0.1:49884 disconnected.
[2010-08-13 11:45:15,813 voldemort.server.socket.SocketServerSession]
INFO Client /127.0.0.1:37195 connected successfully with protocol vp1
[2010-08-13 11:45:19,571 voldemort.server.socket.SocketServerSession]
INFO Client /127.0.0.1:37195 disconnected.


Another fact is:

I even tried http store, instead of the socket one (based on a
previous topic in this group), but I got the exact same error,
I tried the previous ClientConfig setting, but this time with:

StoreClientFactory scf = new HttpStoreClientFactory(cc);
StoreClient<String, byte[]> client = scf.getStoreClient(storeName);

and no success ....

James

[Kirk True]

Hi James,

Is this something that occurs with just a few requests, or do you have
to inundate the cluster with tons of simultaneous client requests?

Perhaps you could post the relevant logs for us to check out?

Thanks,
Kirk

[James Pirz]

Kirk,

Thanks for the help,

There is no massive put or multi-thread kinds of stuff, my code is a
simple, single-thread code, which tries to put values (as byte[]) in
Voldemort,
and I get the error at the very first put,
There is no replication, and required R/W is set to be 1,

In fact I was gradually increasing the size of the values, I was
putting in Voldemort, and mysql has been the storage,
The code was just working fine up to some certain level, and I was
getting reasonable results, but as soon as the value size goes beyond
some threshold (which is around 200k ~ 300k), I started getting the
error at the beginning ...
(I even checked the databases on the nodes, and nothing is inserted
there),
Here is the complete copy of the log, from the node application is
being run:

[2010-08-13 12:17:15,430 voldemort.store.metadata.MetadataStore] INFO
metadata init().
[2010-08-13 12:17:15,536 voldemort.cluster.Node] WARN admin-port not
defined for node:0 using default value(socket_port + 1):6667
[2010-08-13 12:17:15,537 voldemort.cluster.Node] WARN admin-port not
defined for node:1 using default value(socket_port + 1):6667
[2010-08-13 12:17:15,537 voldemort.cluster.Node] WARN admin-port not
defined for node:2 using default value(socket_port + 1):6667
[2010-08-13 12:17:15,537 voldemort.cluster.Node] WARN admin-port not
defined for node:3 using default value(socket_port + 1):6667
[2010-08-13 12:17:15,537 voldemort.cluster.Node] WARN admin-port not
defined for node:4 using default value(socket_port + 1):6667
[2010-08-13 12:17:15,537 voldemort.cluster.Node] WARN admin-port not
defined for node:5 using default value(socket_port + 1):6667
[2010-08-13 12:17:15,667 voldemort.server.VoldemortServer] INFO Using
BIO Connector.
[2010-08-13 12:17:15,672 voldemort.server.VoldemortServer] INFO Using
BIO Connector for Admin Service.
[2010-08-13 12:17:15,673 voldemort.server.VoldemortService] INFO
Starting voldemort-server
[2010-08-13 12:17:15,673 voldemort.server.VoldemortServer] INFO
Starting 8 services.
[2010-08-13 12:17:15,673 voldemort.server.VoldemortService] INFO
Starting storage-service
[2010-08-13 12:17:15,721 voldemort.server.storage.StorageService] INFO
Initializing bdb storage engine.
[2010-08-13 12:17:15,811 voldemort.server.storage.StorageService] INFO
Initializing mysql storage engine.
[2010-08-13 12:17:15,812 voldemort.server.storage.StorageService] INFO
Initializing memory storage engine.
[2010-08-13 12:17:15,813 voldemort.server.storage.StorageService] INFO
Initializing cache storage engine.
[2010-08-13 12:17:15,814 voldemort.server.storage.StorageService] INFO
Initializing read-only storage engine.
[2010-08-13 12:17:15,815 voldemort.store.bdb.BdbStorageConfiguration]
INFO Creating BDB data directory '/data/voldemort-0.81/config/
xen_cluster/data/bdb.
[2010-08-13 12:17:16,050 voldemort.store.bdb.BdbStorageConfiguration]
INFO Creating shared BDB environment:
[2010-08-13 12:17:16,050 voldemort.store.bdb.BdbStorageConfiguration]
INFO BDB cache size = 1073741824
[2010-08-13 12:17:16,050 voldemort.store.bdb.BdbStorageConfiguration]
INFO BDB je.cleaner.threads = 1
[2010-08-13 12:17:16,050 voldemort.store.bdb.BdbStorageConfiguration]
INFO BDB je.cleaner.minUtilization = 50
[2010-08-13 12:17:16,050 voldemort.store.bdb.BdbStorageConfiguration]
INFO BDB je.cleaner.minFileUtilization = 5
[2010-08-13 12:17:16,050 voldemort.store.bdb.BdbStorageConfiguration]
INFO BDB je.log.fileMax = 62914560
[2010-08-13 12:17:16,091 voldemort.server.storage.StorageService] INFO
Initializing stores:
[2010-08-13 12:17:16,091 voldemort.server.storage.StorageService] INFO
Opening store 'mysqlPIX' (mysql).
[2010-08-13 12:17:16,389 voldemort.server.storage.StorageService] INFO
Opening store 'mysqlTest' (mysql).
[2010-08-13 12:17:16,398 voldemort.server.storage.StorageService] INFO
Opening store 'rawByteValue' (bdb).
[2010-08-13 12:17:16,406 voldemort.server.storage.StorageService] INFO
Opening store 'RawByteTest' (bdb).
[2010-08-13 12:17:16,436 voldemort.server.storage.StorageService] INFO
Opening store 'test' (bdb).
[2010-08-13 12:17:16,445 voldemort.server.storage.StorageService] INFO
Opening store 'SecondaryIndex' (bdb).
[2010-08-13 12:17:16,465 voldemort.server.storage.StorageService] INFO
Opening store 'SecondaryTable' (bdb).
[2010-08-13 12:17:16,478 voldemort.server.storage.StorageService] INFO
All stores initialized.
[2010-08-13 12:17:16,478 voldemort.server.VoldemortService] INFO
Starting scheduler-service
[2010-08-13 12:17:16,478 voldemort.server.VoldemortService] INFO
Starting async-scheduler
[2010-08-13 12:17:16,478
voldemort.server.protocol.admin.AsyncOperationService] INFO Starting
asyncOperationRunner
[2010-08-13 12:17:16,478 voldemort.server.VoldemortService] INFO
Starting http-service
[2010-08-13 12:17:16,584 voldemort.server.http.HttpService] INFO HTTP
service started on port 8081
[2010-08-13 12:17:16,584 voldemort.server.VoldemortService] INFO
Starting socket-service
[2010-08-13 12:17:16,585 voldemort.server.socket.SocketServer[socket-
server]] INFO Starting voldemort socket server (socket-server) on port
6666
[2010-08-13 12:17:16,591 voldemort.server.VoldemortService] INFO
Starting rebalance-service
[2010-08-13 12:17:16,592 voldemort.server.VoldemortService] INFO
Starting socket-service
[2010-08-13 12:17:16,592 voldemort.server.socket.SocketServer[admin-
server]] INFO Starting voldemort socket server (admin-server) on port
6667
[2010-08-13 12:17:16,596 voldemort.server.VoldemortService] INFO
Starting jmx-service
[2010-08-13 12:17:16,626 voldemort.server.jmx.JmxService] WARN
Overwriting mbean voldemort.server.socket:type=SocketService
[2010-08-13 12:17:16,634 voldemort.server.VoldemortServer] INFO
Startup completed in 961 ms.
[2010-08-13 12:18:17,036 voldemort.server.socket.SocketServerSession]
INFO Client /127.0.0.1:52806 connected successfully with protocol vp1

[2010-08-13 12:18:21,530 voldemort.server.socket.SocketServerSession]

INFO Client /127.0.0.1:52806 disconnected.

[Kirk True]

Hi James,

I should have asked before: can you turn up the logging level and
include both the client and server node logs? It's not possible to see
from the logs if the server's even receiving the request.

Also, have you tried another storage engine (e.g. BDB, in-memory, etc.)?

Thanks,
Kirk

[James Pirz]

Kirk,

Thanks for the time and your attention,

I changed the logging level (in log4j properties) and I set it to all,
So what I am getting on the screen is a bunch of attempts as:

[2010-08-13 13:44:05,063 voldemort.store.routed.RoutedStore] TRACE
Attempting get operation on node 5 for key '6d79526f6f74'.
[2010-08-13 13:44:05,064 voldemort.store.routed.RoutedStore] TRACE GET
retrieved the following node values: {GetResult(nodeId=5, key=[109,
121, 82, 111, 111, 116], retrieved= []), }
[2010-08-13 13:44:05,070 voldemort.store.routed.RoutedStore] TRACE
Attempting get operation on node 5 for key '6d79526f6f74'.
[2010-08-13 13:44:05,072 voldemort.store.routed.RoutedStore] TRACE GET
retrieved the following node values: {GetResult(nodeId=5, key=[109,
121, 82, 111, 111, 116], retrieved= [[[B@28c5ea2, version(5:1)]]), }

Where this couple of lines keeps on repeating, up to the failure
point,

I had tested the code with bdb, working fine there, and when I changed
the storage to mysql, I started getting errors ....

James

> ...
>
> read more »