diff --git a/src/main/java/org/qora/controller/Synchronizer.java b/src/main/java/org/qora/controller/Synchronizer.java index 5a0841d0..e0a479bb 100644 --- a/src/main/java/org/qora/controller/Synchronizer.java +++ b/src/main/java/org/qora/controller/Synchronizer.java @@ -26,6 +26,7 @@ import org.qora.repository.DataException; import org.qora.repository.Repository; import org.qora.repository.RepositoryManager; import org.qora.transaction.Transaction; +import org.qora.utils.Base58; public class Synchronizer { @@ -108,10 +109,9 @@ public class Synchronizer { } byte[] ourLastBlockSignature = ourLatestBlockData.getSignature(); - if (peerHeight == ourHeight && (peersLastBlockSignature == null || !Arrays.equals(peersLastBlockSignature, ourLastBlockSignature))) - LOGGER.debug(String.format("Synchronizing with peer %s at height %d, our height %d, signatures differ", peer, peerHeight, ourHeight)); - else - LOGGER.debug(String.format("Synchronizing with peer %s at height %d, our height %d", peer, peerHeight, ourHeight)); + LOGGER.debug(String.format("Synchronizing with peer %s at height %d, sig %.8s, ts %d; our height %d, sig %.8s, ts %d", peer, + peerHeight, Base58.encode(peersLastBlockSignature), peer.getLastBlockTimestamp(), + ourHeight, Base58.encode(ourLastBlockSignature), ourLatestBlockData.getTimestamp())); List signatures = findSignaturesFromCommonBlock(peer, ourHeight); if (signatures == null) { @@ -126,7 +126,8 @@ public class Synchronizer { // First signature is common block BlockData commonBlockData = this.repository.getBlockRepository().fromSignature(signatures.get(0)); final int commonBlockHeight = commonBlockData.getHeight(); - LOGGER.debug(String.format("Common block with peer %s is at height %d", peer, commonBlockHeight)); + LOGGER.debug(String.format("Common block with peer %s is at height %d, sig %.8s, ts %d", peer, + commonBlockHeight, Base58.encode(commonBlockData.getSignature()), commonBlockData.getTimestamp())); signatures.remove(0); // If common block height is higher than peer's last reported height @@ -173,7 +174,8 @@ public class Synchronizer { byte[] previousSignature = sigIndex == 0 ? commonBlockData.getSignature() : signatures.get(sigIndex - 1); List moreSignatures = this.getBlockSignatures(peer, previousSignature, MAXIMUM_BLOCK_STEP); if (moreSignatures == null || moreSignatures.isEmpty()) { - LOGGER.info(String.format("Peer %s failed to respond with more block signatures after height %d", peer, height - 1)); + LOGGER.info(String.format("Peer %s failed to respond with more block signatures after height %d, sig %.8s", peer, + height - 1, Base58.encode(previousSignature))); return SynchronizationResult.NO_REPLY; } @@ -228,7 +230,8 @@ public class Synchronizer { signatures = this.getBlockSignatures(peer, signature, numberRequested); if (signatures == null || signatures.isEmpty()) { - LOGGER.info(String.format("Peer %s failed to respond with more block signatures after height %d", peer, ourHeight)); + LOGGER.info(String.format("Peer %s failed to respond with more block signatures after height %d, sig %.8s", peer, + ourHeight, Base58.encode(signature))); return SynchronizationResult.NO_REPLY; } @@ -242,12 +245,14 @@ public class Synchronizer { Block newBlock = this.fetchBlock(repository, peer, signature); if (newBlock == null) { - LOGGER.info(String.format("Peer %s failed to respond with block for height %d", peer, ourHeight)); + LOGGER.info(String.format("Peer %s failed to respond with block for height %d, sig %.8s", peer, + ourHeight, Base58.encode(signature))); return SynchronizationResult.NO_REPLY; } if (!newBlock.isSignatureValid()) { - LOGGER.info(String.format("Peer %s sent block with invalid signature for height %d", peer, ourHeight)); + LOGGER.info(String.format("Peer %s sent block with invalid signature for height %d, sig %.8s", peer, + ourHeight, Base58.encode(signature))); return SynchronizationResult.INVALID_DATA; } @@ -257,7 +262,8 @@ public class Synchronizer { ValidationResult blockResult = newBlock.isValid(); if (blockResult != ValidationResult.OK) { - LOGGER.info(String.format("Peer %s sent invalid block for height %d: %s", peer, ourHeight, blockResult.name())); + LOGGER.info(String.format("Peer %s sent invalid block for height %d, sig %.8s: %s", peer, + ourHeight, Base58.encode(signature), blockResult.name())); return SynchronizationResult.INVALID_DATA; } @@ -276,7 +282,11 @@ public class Synchronizer { // Commit repository.saveChanges(); - LOGGER.info(String.format("Synchronized with peer %s to height %d", peer, ourHeight)); + + final BlockData newLatestBlockData = this.repository.getBlockRepository().getLastBlock(); + LOGGER.info(String.format("Synchronized with peer %s to height %d, sig %.8s, ts: %d", peer, + newLatestBlockData.getHeight(), Base58.encode(newLatestBlockData.getSignature()), + newLatestBlockData.getTimestamp())); return SynchronizationResult.OK; } finally { diff --git a/src/test/java/org/qora/test/SyncReport.java b/src/test/java/org/qora/test/SyncReport.java new file mode 100644 index 00000000..0efe9cd6 --- /dev/null +++ b/src/test/java/org/qora/test/SyncReport.java @@ -0,0 +1,209 @@ +package org.qora.test; + +import java.io.IOException; +import java.io.InputStream; +import java.nio.file.Files; +import java.nio.file.Path; +import java.nio.file.Paths; +import java.text.ParseException; +import java.text.SimpleDateFormat; +import java.time.Instant; +import java.util.ArrayList; +import java.util.Date; +import java.util.HashMap; +import java.util.List; +import java.util.Map; +import java.util.Scanner; +import java.util.regex.Matcher; +import java.util.regex.Pattern; +import java.util.regex.PatternSyntaxException; + +/* + * We are expecting log entries like: + * + * 2019-07-24 11:31:25 DEBUG Synchronizer:121 - Synchronizing with peer 52.33.79.54:9889 at height 73139, sig 2cfqHyJ4, ts 1563964269587; our height 73140, sig 8hae8BLg, ts 1563964271060 + * + * 2019-07-24 11:31:26 DEBUG Synchronizer:138 - Common block with peer 52.33.79.54:9889 is at height 73138, sig 7LKMHZxU, ts 1563964148818 + * + * 2019-07-24 11:31:26 INFO Synchronizer:326 - Synchronized with peer 52.33.79.54:9889 to height 73139, sig 2cfqHyJ4, ts: 1563964269587 + * + */ +public class SyncReport { + + private static final Pattern START_PATTERN; + private static final Pattern COMMON_PATTERN; + private static final Pattern DONE_PATTERN; + private static final Pattern FAIL_PATTERN; + static { + try { + START_PATTERN = Pattern.compile("(\\d+-\\d+-\\d+ \\d+:\\d+:\\d+) .*? Synchronizing with peer (\\S+) at height (\\d+), sig (\\S+), ts (\\d+); our height (\\d+), sig (\\S+), ts (\\d+)"); + COMMON_PATTERN = Pattern.compile(".*? Common block with peer (\\S+) is at height (\\d+), sig (\\S+), ts (\\d+)"); + DONE_PATTERN = Pattern.compile(".*? Synchronized with peer (\\S+) to height (\\d+), sig (\\S+), ts:? (\\d+)"); + FAIL_PATTERN = Pattern.compile(".*? .ynchronized? with peer (\\S+) \\((\\S+)\\)"); + } catch (PatternSyntaxException e) { + throw new RuntimeException(e); + } + } + + private static final SimpleDateFormat LOG_DATE_FORMAT = new SimpleDateFormat("yyyy-MM-dd HH:mm:ss"); + + static class SyncEvent { + long timestamp; + String peer; + String fromBlockSig; + String commonBlockSig; + String tipBlockSig; + } + + public static void main(String args[]) { + if (args.length == 0) { + System.err.println("usage: SyncReport [ ...]"); + System.exit(1); + } + + List syncEvents = new ArrayList<>(); + Map blockHeights = new HashMap<>(); + + InputStream in = null; + Scanner scanner = null; + int argIndex = 0; + + Matcher matcher; + SyncEvent syncEvent = null; + + while (argIndex < args.length) { + if (in == null) { + // Open a log file + Path path = Paths.get(args[argIndex]); + + try { + in = Files.newInputStream(path); + } catch (IOException e) { + System.err.println(String.format("Unable to open '%s': %s", path.toString(), e.getMessage())); + System.exit(2); + } + + scanner = new Scanner(in, "UTF8"); + scanner.useDelimiter("\n"); + } + + if (!scanner.hasNext()) { + scanner.close(); + scanner = null; + + try { + in.close(); + } catch (IOException e) { + System.err.println(String.format("Unable to close InputStream: %s", e.getMessage())); + System.exit(2); + } + in = null; + + ++argIndex; + + continue; + } + + String line = scanner.next(); + + matcher = START_PATTERN.matcher(line); + if (matcher.matches()) { + long logTimestamp = 0; + try { + Date logDate = LOG_DATE_FORMAT.parse(matcher.group(1)); + logTimestamp = logDate.toInstant().toEpochMilli(); + } catch (ParseException e) { + System.err.println(String.format("Couldn't determine log entry timestamp from '%s'", matcher.group(1))); + System.exit(3); + } + + Integer tipHeight = Integer.valueOf(matcher.group(3)); + Integer ourHeight = Integer.valueOf(matcher.group(6)); + + if (syncEvent != null) { + // Salvageable? + + if (syncEvent.commonBlockSig != null && ourHeight > blockHeights.get(syncEvent.fromBlockSig)) { + syncEvent.tipBlockSig = matcher.group(7); + syncEvents.add(syncEvent); + } + } + + syncEvent = new SyncEvent(); + syncEvent.timestamp = logTimestamp; + syncEvent.peer = matcher.group(2); + syncEvent.fromBlockSig = matcher.group(7); + + blockHeights.put(matcher.group(4), tipHeight); + blockHeights.put(matcher.group(7), ourHeight); + continue; + } + + matcher = COMMON_PATTERN.matcher(line); + if (matcher.matches()) { + String peer = matcher.group(1); + + if (syncEvent == null || !peer.equals(syncEvent.peer)) { + System.err.println(String.format("No current synchronization with %s", peer)); + continue; + } + + if (syncEvent.commonBlockSig != null) { + System.err.println(String.format("We already have a common block: %s", syncEvent.commonBlockSig)); + continue; + } + + syncEvent.commonBlockSig = matcher.group(3); + blockHeights.put(matcher.group(3), Integer.valueOf(matcher.group(2))); + continue; + } + + matcher = DONE_PATTERN.matcher(line); + if (matcher.matches()) { + String peer = matcher.group(1); + + if (syncEvent == null || !peer.equals(syncEvent.peer)) { + System.err.println(String.format("No current synchronization with %s", peer)); + continue; + } + + syncEvent.tipBlockSig = matcher.group(3); + + // Add successful sync to list + syncEvents.add(syncEvent); + syncEvent = null; + continue; + } + + matcher = FAIL_PATTERN.matcher(line); + if (matcher.matches()) { + String result = matcher.group(2); + + if (result.equals("NO_REPLY")) + // Possibly salvageable + continue; + + // Sync went bad + syncEvent = null; + continue; + } + } + + for (SyncEvent se : syncEvents) { + if (se.commonBlockSig.equals(se.fromBlockSig)) + System.out.println(String.format("%s: %s (%d) ===> %s (%d) (peer %s)", + LOG_DATE_FORMAT.format(Date.from(Instant.ofEpochMilli(se.timestamp))), + se.fromBlockSig, blockHeights.get(se.fromBlockSig), + se.tipBlockSig, blockHeights.get(se.tipBlockSig), + se.peer)); + else + System.out.println(String.format("%s: %s (%d) ---> %s (%d) ===> %s (%d) (peer %s)", + LOG_DATE_FORMAT.format(Date.from(Instant.ofEpochMilli(se.timestamp))), + se.fromBlockSig, blockHeights.get(se.fromBlockSig), + se.commonBlockSig, blockHeights.get(se.commonBlockSig), + se.tipBlockSig, blockHeights.get(se.tipBlockSig), + se.peer)); + } + } + +}