From 7fc0af2b1f1e3e91e008d065da0c40f87f5fe57c Mon Sep 17 00:00:00 2001 From: Vladimir Eliezer Tokarev Date: Fri, 15 Apr 2016 06:51:36 -0700 Subject: [PATCH] Added logging to Voter-Registry --- .../src/main/java/meerkat/AsyncRegistry.java | 25 ++-- .../GetGroupsCallback.java | 18 ++- .../HasVotedCallback.java | 15 ++- .../getVoterCallback.java | 17 ++- .../registry/MessageCollectionUtils.java | 11 +- .../src/test/java/SimpleRegistryTest.java | 107 ++++++++++++++++-- 6 files changed, 168 insertions(+), 25 deletions(-) diff --git a/voter-registry/src/main/java/meerkat/AsyncRegistry.java b/voter-registry/src/main/java/meerkat/AsyncRegistry.java index 6792539..990c254 100644 --- a/voter-registry/src/main/java/meerkat/AsyncRegistry.java +++ b/voter-registry/src/main/java/meerkat/AsyncRegistry.java @@ -24,7 +24,7 @@ import java.util.List; import static meerkat.util.BulletinBoardUtils.signBulletinBoardMessage; -// TODO : add ability to use DB of certificates and add logging +// TODO : add ability to use DB of certificates /** * Created by Vladimir Eliezer Tokarev on 1/8/2016. @@ -39,14 +39,13 @@ public class AsyncRegistry implements VoterRegistry{ @Override public void init(DigitalSignature signer, SubscriptionAsyncBulletinBoardClient communicator) { - logger.debug("Initialized the AsyncRegistry"); + logger.debug("Initialized AsyncRegistry: ", new java.util.Date().getTime()); this.signer = signer; this.cachedBulletinBoardClient = communicator; } @Override public void addVoter(VoterInfo voterInfo, FutureCallback callback) throws SignatureException { - logger.info("Adding voter : {0}", RegistryTags.ID_TAG); UnsignedBulletinBoardMessage basicMessage = UnsignedBulletinBoardMessage.newBuilder() .addTag(RegistryTags.ID_TAG + voterInfo.getId().getId()) @@ -55,8 +54,8 @@ public class AsyncRegistry implements VoterRegistry{ .setTimestamp(BulletinBoardUtils.getCurrentTimestampProto()) .build(); - cachedBulletinBoardClient.postMessage(signBulletinBoardMessage(basicMessage, signer), callback); + logger.debug("Added voter : ", RegistryTags.ID_TAG, new java.util.Date().getTime()); } @Override @@ -69,6 +68,8 @@ public class AsyncRegistry implements VoterRegistry{ .setTimestamp(BulletinBoardUtils.getCurrentTimestampProto()); cachedBulletinBoardClient.postMessage(signBulletinBoardMessage(basicMessage.build(), signer), callback); + + logger.debug("Set voter groups to be : ", new java.util.Date().getTime()); } @Override @@ -81,6 +82,8 @@ public class AsyncRegistry implements VoterRegistry{ .build(); cachedBulletinBoardClient.postMessage(signBulletinBoardMessage(basicMessage, signer), callback); + + logger.debug("Next voter has voted : ", voterId.getId(), new java.util.Date().getTime()); } @Override @@ -90,8 +93,12 @@ public class AsyncRegistry implements VoterRegistry{ add(RegistryTags.ID_TAG + voterID.getId()); }}; - cachedBulletinBoardClient.readMessages(MessageCollectionUtils.generateFiltersFromTags(GroupsActionsTags), + cachedBulletinBoardClient.readMessages(MessageCollectionUtils.generateFiltersFromTags(GroupsActionsTags, logger), new GetGroupsCallback(callback)); + + logger.debug("Trying to retrieve next user groups : ", + voterID.getId(), + new java.util.Date().getTime()); } @Override @@ -101,8 +108,10 @@ public class AsyncRegistry implements VoterRegistry{ add(RegistryTags.VOTER_ENTRY_TAG); }}; - cachedBulletinBoardClient.readMessages(MessageCollectionUtils.generateFiltersFromTags(addVoterTags), + cachedBulletinBoardClient.readMessages(MessageCollectionUtils.generateFiltersFromTags(addVoterTags, logger), new GetVoterCallback(callback)); + + logger.debug("Trying to retrieve next user information : ", voterID.getId(), new java.util.Date().getTime()); } @Override @@ -112,7 +121,9 @@ public class AsyncRegistry implements VoterRegistry{ add(RegistryTags.VOTE_ACTION_TAG); }}; - cachedBulletinBoardClient.readMessages(MessageCollectionUtils.generateFiltersFromTags(setVotedTags), + cachedBulletinBoardClient.readMessages(MessageCollectionUtils.generateFiltersFromTags(setVotedTags, logger), new HasVotedCallback(callBack)); + + logger.debug("Trying to check if next has voted : ", voterId.getId(), new java.util.Date().getTime()); } } diff --git a/voter-registry/src/main/java/meerkat/registry/AsyncRegistryCallbacks/GetGroupsCallback.java b/voter-registry/src/main/java/meerkat/registry/AsyncRegistryCallbacks/GetGroupsCallback.java index 9f279db..af8c72d 100644 --- a/voter-registry/src/main/java/meerkat/registry/AsyncRegistryCallbacks/GetGroupsCallback.java +++ b/voter-registry/src/main/java/meerkat/registry/AsyncRegistryCallbacks/GetGroupsCallback.java @@ -4,13 +4,16 @@ import com.google.common.util.concurrent.FutureCallback; import javassist.NotFoundException; import meerkat.protobuf.BulletinBoardAPI.BulletinBoardMessage; import meerkat.protobuf.VoterRegistry; +import meerkat.registry.RegistryTags; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; import java.io.IOException; import java.util.List; +import static meerkat.util.BulletinBoardUtils.findTagWithPrefix; import static meerkat.util.BulletinBoardUtils.getLatestMessage; -// TODO : add logging /** * Created by Vladimir Eliezer on 3/12/2016. @@ -18,6 +21,7 @@ import static meerkat.util.BulletinBoardUtils.getLatestMessage; */ public class GetGroupsCallback implements FutureCallback> { protected FutureCallback> callback; + final Logger logger = LoggerFactory.getLogger(getClass()); public GetGroupsCallback(FutureCallback> callback){ this.callback = callback; @@ -31,6 +35,7 @@ public class GetGroupsCallback implements FutureCallback getVoterGroups(BulletinBoardMessage message) throws IOException, ClassNotFoundException { + logger.debug("Initialized GetGroupsCallback : ", new java.util.Date().getTime()); VoterRegistry.VoterRegistryMessage voterRegistryMessage = VoterRegistry.VoterRegistryMessage.parseFrom(message.getMsg().getData()); @@ -47,14 +52,25 @@ public class GetGroupsCallback implements FutureCallback>{ protected FutureCallback callback; + final Logger logger = LoggerFactory.getLogger(getClass()); public HasVotedCallback(FutureCallback callback){ + logger.debug("Initialized HasVotedCallback : ", new java.util.Date().getTime()); this.callback = callback; } @@ -24,11 +30,18 @@ public class HasVotedCallback implements FutureCallback> { protected FutureCallback callback; + final Logger logger = LoggerFactory.getLogger(getClass()); public GetVoterCallback(FutureCallback callback){ + logger.debug("Initialized GetVoterCallback : ", new java.util.Date().getTime()); this.callback = callback; } @@ -34,14 +37,24 @@ public class GetVoterCallback implements FutureCallback tags) { + public static MessageFilterList generateFiltersFromTags(List tags, Logger logger) { if (tags == null){ return MessageFilterList.getDefaultInstance(); } @@ -32,6 +32,9 @@ public abstract class MessageCollectionUtils { MessageFilter filter = MessageFilter.newBuilder().setTag(tag).setType(FilterType.TAG).build(); filters.addFilter(filter); } + + logger.debug("Converted next strings to filters", StringUtils.join(tags, " ")); + return filters.build(); } } diff --git a/voter-registry/src/test/java/SimpleRegistryTest.java b/voter-registry/src/test/java/SimpleRegistryTest.java index dd73836..23cc0f4 100644 --- a/voter-registry/src/test/java/SimpleRegistryTest.java +++ b/voter-registry/src/test/java/SimpleRegistryTest.java @@ -2,8 +2,8 @@ import com.google.common.util.concurrent.FutureCallback; import meerkat.AsyncRegistry; import meerkat.bulletinboard.BulletinBoardServer; import meerkat.bulletinboard.LocalBulletinBoardClient; -import meerkat.bulletinboard.sqlserver.*; - +import meerkat.bulletinboard.sqlserver.BulletinBoardSQLServer; +import meerkat.bulletinboard.sqlserver.H2QueryProvider; import meerkat.comm.CommunicationException; import meerkat.crypto.DigitalSignature; import meerkat.crypto.concrete.ECDSASignature; @@ -17,6 +17,8 @@ import meerkat.registry.MessageCollectionUtils; import meerkat.registry.RegistryTags; import org.junit.Before; import org.junit.Test; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; import java.io.IOException; import java.io.InputStream; @@ -28,13 +30,13 @@ import java.sql.Connection; import java.sql.SQLException; import java.sql.Statement; import java.util.ArrayList; +import java.util.Date; import java.util.List; import java.util.concurrent.Semaphore; import static junit.framework.TestCase.assertEquals; import static junit.framework.TestCase.assertTrue; -import static meerkat.util.BulletinBoardUtils.findTagWithPrefix; -import static meerkat.util.BulletinBoardUtils.getLatestMessage; +import static meerkat.util.BulletinBoardUtils.*; /** * TODO: add logs prints for the tests to be clear what they are @@ -49,7 +51,7 @@ import static meerkat.util.BulletinBoardUtils.getLatestMessage; public class SimpleRegistryTest { private DigitalSignature signer; - private LocalBulletinBoardClient cachedBulletinBoardClient; + private LocalBulletinBoardClient localBulletinBoardClient; private SecureRandom random = new SecureRandom(); Semaphore jobSemaphore; @@ -59,6 +61,7 @@ public class SimpleRegistryTest { private static final String DB_NAME = "TestDB"; private static final int SUBSCRIPTION_DELAY = 3000; private static final int THREAD_NUM = 3; + final Logger logger = LoggerFactory.getLogger(getClass()); class DummyRegistryCallBackHandler implements FutureCallback{ public int counter; @@ -119,6 +122,8 @@ public class SimpleRegistryTest { BulletinBoardServer server = new BulletinBoardSQLServer(queryProvider); server.init(DB_NAME); + logger.debug("Created new LocalBulletinBoardClient: {}", new Date()); + return new LocalBulletinBoardClient(server, THREAD_NUM, SUBSCRIPTION_DELAY); } @@ -130,7 +135,7 @@ public class SimpleRegistryTest { * @throws SQLException */ private void CommunicatorSetup() throws InstantiationException, IllegalAccessException, CommunicationException, SQLException { - cachedBulletinBoardClient = CreateLocalBulletinBoardClient(); + localBulletinBoardClient = CreateLocalBulletinBoardClient(); } /** @@ -148,6 +153,7 @@ public class SimpleRegistryTest { keyStream.close(); this.signer = signer; + logger.info("Have set new signer: {}", new Date()); } catch (Exception e){ assert false : "The signers creation failed "; @@ -166,12 +172,14 @@ public class SimpleRegistryTest { SetSigner(); CommunicatorSetup(); jobSemaphore = new Semaphore(0); + logger.info("Ended the setup preparations: {}", new Date()); } private AsyncRegistry GetRegistry() { AsyncRegistry registry = new AsyncRegistry(); - registry.init(signer, cachedBulletinBoardClient); + registry.init(signer, localBulletinBoardClient); + logger.info("Created new AsyncRegistry: {}", new Date()); return registry; } @@ -190,7 +198,9 @@ public class SimpleRegistryTest { @Test public void simpleRegistryCreation() { try { + logger.info("Testing registry creation: {}", new Date()); GetRegistry(); + logger.info("Registry creation succeed: {} \n\n", new Date()); } catch (Exception e) { assert false : "While creating the registry exception have been thrown " + e; } @@ -220,11 +230,15 @@ public class SimpleRegistryTest { counter++; } } + logger.info("Counted {} messages with all wanted tags from {} given messages: {}", + counter, + messages.size(), + new Date()); return counter; } /** - * Reads messages from cachedBulletinBoardClient by given tags and return the callback handler + * Reads messages from localBulletinBoardClient by given tags and return the callback handler * object * * @param tags list of strings that represents tags @@ -232,9 +246,9 @@ public class SimpleRegistryTest { */ private DummyBulletinBoardCallBackHandler readMessagesByTags(List tags) { - MessageFilterList filters = MessageCollectionUtils.generateFiltersFromTags(tags); + MessageFilterList filters = MessageCollectionUtils.generateFiltersFromTags(tags, logger); DummyBulletinBoardCallBackHandler bulletinHandler = new DummyBulletinBoardCallBackHandler(); - cachedBulletinBoardClient.readMessages(filters, bulletinHandler); + localBulletinBoardClient.readMessages(filters, bulletinHandler); return bulletinHandler; } @@ -243,6 +257,8 @@ public class SimpleRegistryTest { */ @Test public void testAddVoter() throws InterruptedException, SignatureException { + logger.info("Testing registry adding voter functionality: {}", new Date()); + DummyRegistryCallBackHandler handler = new DummyRegistryCallBackHandler<>(); String id = generateString(); @@ -251,6 +267,9 @@ public class SimpleRegistryTest { AsyncRegistry registry = GetRegistry(); registry.addVoter(voterInfo, handler); + logger.info("Tried to add next voter to registry: id: {} {}", + voterInfo.getId().getId(), + new Date()); jobSemaphore.acquire(); assertEquals(1, handler.counter ); @@ -258,13 +277,19 @@ public class SimpleRegistryTest { List tags = new ArrayList(){{ add(RegistryTags.VOTER_ENTRY_TAG);}}; DummyBulletinBoardCallBackHandler bulletinHandler = readMessagesByTags(tags); + jobSemaphore.acquire(); + logger.info("Got add voter messages that have been added lately to the server: {} {}", + GetListOfTags(bulletinHandler.messages, RegistryTags.ID_TAG), + new Date()); tags.clear(); tags.add(RegistryTags.ID_TAG + id); int counter = countMessagesWithTags(bulletinHandler.messages, tags); assert counter == 1 : "The server don't have the new user data."; + logger.info("The server had a message with voter data: id: {} data: {} {}", id, data, new Date()); + logger.info("Ended testing registry adding voter functionality: {}\n\n", new Date()); } /** @@ -272,6 +297,7 @@ public class SimpleRegistryTest { */ @Test public void testSetVoted() throws InterruptedException, SignatureException { + logger.info("Testing registry set voted functionality: {}", new Date()); DummyRegistryCallBackHandler handler = new DummyRegistryCallBackHandler<>(); String id = generateString(); @@ -279,6 +305,9 @@ public class SimpleRegistryTest { AsyncRegistry registry = GetRegistry(); registry.setVoted(voterInfo, handler); + logger.info("Tried to set that next voter voted : id: {} {}", + voterInfo.getId(), + new Date()); jobSemaphore.acquire(); assertEquals(1, handler.counter ); @@ -287,12 +316,17 @@ public class SimpleRegistryTest { DummyBulletinBoardCallBackHandler bulletinHandler = readMessagesByTags(tags); jobSemaphore.acquire(); + logger.info("Got set voted messages that have been added lately to the server: {} {} ", + GetListOfTags(bulletinHandler.messages, RegistryTags.ID_TAG), + new Date()); tags.clear(); tags.add(RegistryTags.ID_TAG + id); int counter = countMessagesWithTags(bulletinHandler.messages, tags); assert counter == 1 : "The server don't have the new user id."; + logger.info("The server had a message with voter data: id: {} {}", id, new Date()); + logger.info("Ended testing registry set voted functionality: {}\n\n", new Date()); } /** @@ -300,6 +334,8 @@ public class SimpleRegistryTest { */ @Test public void testSetVoterGroups() throws InterruptedException, SignatureException, IOException, ClassNotFoundException { + logger.info("Testing registry set voter groups functionality: {}", new Date()); + DummyRegistryCallBackHandler handler = new DummyRegistryCallBackHandler<>(); String voterId = generateString(); @@ -310,6 +346,10 @@ public class SimpleRegistryTest { AsyncRegistry registry = GetRegistry(); registry.setVoterGroups(voterInfo, handler); + logger.info("Tried to set voter groups : id: {} groupId: {} {}", + voterId, + groupId1, + new Date()); jobSemaphore.acquire(); assertEquals("The callback handler hasn't been called yet", 1, handler.counter); @@ -319,18 +359,27 @@ public class SimpleRegistryTest { DummyBulletinBoardCallBackHandler bulletinHandler = readMessagesByTags(tags); jobSemaphore.acquire(); + logger.info("Got set voter groups messages that have been added lately to the server: {} {} ", + GetListOfTags(bulletinHandler.messages, RegistryTags.ID_TAG), + new Date()); BulletinBoardMessage latestMessage = getLatestMessage(bulletinHandler.messages); assert findTagWithPrefix(latestMessage, RegistryTags.ID_TAG).equals(voterId) : "The latest message recieved is not of our voter"; + logger.info("The server had a message of our voter, data: id: {} {}", + findTagWithPrefix(latestMessage, RegistryTags.ID_TAG), new Date()); + VoterRegistry.VoterRegistryMessage voterRegistryMessage = VoterRegistry.VoterRegistryMessage.parseFrom(latestMessage.getMsg().getData()); List groupsIds = voterRegistryMessage.getGroupIDList(); assert groupsIds.get(0).getId().equals(groupId1) : "The latest message doesn't have the voter group"; + logger.info("The server had a message with voter data: groupId: {} {}", + groupsIds.get(0).getId(), new Date()); + logger.info("Ended testing registry set voter groups functionality: {}\n\n", new Date()); } /** @@ -338,6 +387,7 @@ public class SimpleRegistryTest { */ @Test public void testGetGroups() throws InterruptedException, SignatureException, IOException { + logger.info("Testing registry get voter groups functionality: {}", new Date()); DummyRegistryCallBackHandler handler = new DummyRegistryCallBackHandler<>(); @@ -351,6 +401,11 @@ public class SimpleRegistryTest { AsyncRegistry registry = GetRegistry(); registry.setVoterGroups(voterInfo, handler); + logger.info("Tried to set voter groups : id: {} groupId 1: {} groupId 2: {} {}", + voterId, + groupId1, + groupId2, + new Date()); jobSemaphore.acquire(); assertEquals("The callback handler hasn't been called yet", 1, handler.counter ); @@ -361,11 +416,18 @@ public class SimpleRegistryTest { jobSemaphore.acquire(1); List userGroups = groupsHandler.data; + logger.info("Got get voter groups messages that have been added lately to the server: {}", + new Date()); + assert userGroups.contains(GroupID.newBuilder().setId(groupId1).build()) : "The simple voter registry object does not retrieved the first user groups"; assert userGroups.contains(GroupID.newBuilder().setId(groupId2).build()) : "The simple voter registry object does not retrieved the second user groups"; + + logger.info("The server had a message with wanted data: groupId 1: {} groupId 2: {} {}", + groupId1, groupId2, new Date()); + logger.info("Ended testing registry get voter groups functionality: {}\n\n", new Date()); } /** @@ -373,6 +435,7 @@ public class SimpleRegistryTest { */ @Test public void testGetVoter() throws InterruptedException, SignatureException { + logger.info("Testing registry get voter groups functionality: {}", new Date()); DummyRegistryCallBackHandler handler = new DummyRegistryCallBackHandler<>(); @@ -384,6 +447,9 @@ public class SimpleRegistryTest { AsyncRegistry registry = GetRegistry(); registry.addVoter(voterInfo, handler); + logger.info("Tried to get voter with data: id: {} groupId 1: {} groupId 2: {} {}", + id, data, new Date()); + jobSemaphore.acquire(); assertEquals("The callback handler hasn't been called yet", 1, handler.counter ); @@ -391,10 +457,19 @@ public class SimpleRegistryTest { registry.getVoter(VoterID.newBuilder().setId(id).build(), personalHandler); jobSemaphore.acquire(1); + + logger.info("Got get voter messages that have been added lately to the server: {} {}", + personalHandler.data.getId(), + new Date()); + assertEquals("The voter id doesn't match the created on ", id, personalHandler.data.getId().getId()); String personalData = personalHandler.data.getInfo(); assertTrue("The voter personal data can't be found.", data.equals(personalData)); + + logger.info("The server had a message with wanted data: if: {} personal data: {} {}", + personalHandler.data.getId().getId(), personalData, new Date()); + logger.info("Ended testing registry get voter functionality: {}\n\n", new Date()); } /** @@ -403,19 +478,31 @@ public class SimpleRegistryTest { */ @Test public void testHasVoted () throws InterruptedException, SignatureException { + logger.info("Testing registry has voted functionality: {}", new Date()); + DummyRegistryCallBackHandler handler = new DummyRegistryCallBackHandler<>(); String id = generateString(); VoterID voterInfo = VoterID.newBuilder().setId(id).build(); AsyncRegistry registry = GetRegistry(); registry.setVoted(voterInfo, handler); + + logger.info("Tried to set voted with data: id: {} groupId 1: {} {}", + id, new Date()); + jobSemaphore.acquire(); assertEquals("The callback handler hasn't been called yet", 1, handler.counter); DummyRegistryCallBackHandler personalHandler = new DummyRegistryCallBackHandler<>(); registry.hasVoted(VoterID.newBuilder().setId(id).build(), personalHandler); jobSemaphore.acquire(1); + + logger.info("Got has voted messages that have been added lately to the server: {} {}", + personalHandler.data, + new Date()); assertTrue("The voter hasn't voted yet.", personalHandler.data); + + logger.info("Ended testing registry has voted functionality: {}\n\n", new Date()); } }