Merge pull request #12 from RIPE-NCC/better-logging

Better logging and metrics for broken objects

src/main/java/net/ripe/rpki/rsyncit/rrdp/RRDPFetcherMetrics.java

@@ -11,11 +11,16 @@ public final class RRDPFetcherMetrics {
     private final Counter successfulUpdates;
     private final Counter failedUpdates;
     private final Counter timeoutUpdates;
+    private final Counter objectFailures;
 
     public RRDPFetcherMetrics(MeterRegistry meterRegistry) {
         successfulUpdates = buildCounter("success", meterRegistry);
         failedUpdates = buildCounter("failed", meterRegistry);
         timeoutUpdates = buildCounter("timeout", meterRegistry);
+        objectFailures = Counter.builder("rsyncit.fetcher.objects")
+            .description("Metrics on objects")
+            .tag("status", "failure")
+            .register(meterRegistry);
 
         Gauge.builder("rsyncit.fetcher.rrdp.serial", rrdpSerial::get)
             .description("Serial of the RRDP notification.xml at the given URL")
@@ -35,6 +40,10 @@ public void timeout() {
         this.timeoutUpdates.increment();
     }
 
+    public void badObject() {
+        this.objectFailures.increment();
+    }
+
     private static Counter buildCounter(String statusTag, MeterRegistry registry) {
         return Counter.builder("rsyncit.fetcher.updated")
             .description("Number of fetches")

src/main/java/net/ripe/rpki/rsyncit/rrdp/RrdpFetcher.java

@@ -3,6 +3,7 @@
 import lombok.Getter;
 import lombok.extern.slf4j.Slf4j;
 import net.ripe.rpki.commons.crypto.cms.RpkiSignedObject;
+import net.ripe.rpki.commons.crypto.cms.RpkiSignedObjectParser;
 import net.ripe.rpki.commons.crypto.cms.aspa.AspaCmsParser;
 import net.ripe.rpki.commons.crypto.cms.ghostbuster.GhostbustersCmsParser;
 import net.ripe.rpki.commons.crypto.cms.manifest.ManifestCmsParser;
@@ -43,7 +44,6 @@
 import java.util.Optional;
 import java.util.concurrent.atomic.AtomicInteger;
 import java.util.concurrent.atomic.AtomicReference;
-import java.util.function.BiFunction;
 import java.util.function.Function;
 import java.util.stream.Collectors;
 import java.util.stream.IntStream;
@@ -55,11 +55,13 @@ public class RrdpFetcher {
     private final Config config;
     private final WebClient httpClient;
     private final State state;
+    private final RRDPFetcherMetrics metrics;
 
-    public RrdpFetcher(Config config, WebClient httpClient, State state) {
+    public RrdpFetcher(Config config, WebClient httpClient, State state, RRDPFetcherMetrics metrics) {
         this.config = config;
         this.httpClient = httpClient;
         this.state = state;
+        this.metrics = metrics;
         log.info("RrdpFetcher for {}", config.rrdpUrl());
     }
 
@@ -226,7 +228,6 @@ private ProcessPublishElementResult processPublishElements(Element doc, Instant
             .map(item -> {
                 var objectUri = item.getAttributes().getNamedItem("uri").getNodeValue();
                 var content = item.getTextContent();
-
                 try {
                     // Surrounding whitespace is allowed by xsd:base64Binary. Trim that
                     // off before decoding. See also:
@@ -245,6 +246,7 @@ private ProcessPublishElementResult processPublishElements(Element doc, Instant
 
                     return new RpkiObject(URI.create(objectUri), decoded, createAt);
                 } catch (RuntimeException e) {
+                    metrics.badObject();
                     log.error("Cannot decode object data for URI {}\n{}", objectUri, content);
                     throw e;
                 }
@@ -281,44 +283,50 @@ private Instant getTimestampForObject(final String objectUri, final byte[] decod
         final RepositoryObjectType objectType = RepositoryObjectType.parse(objectUri);
         try {
             return switch (objectType) {
-                case Manifest -> {
-                    ManifestCmsParser manifestCmsParser = new ManifestCmsParser();
-                    manifestCmsParser.parse(ValidationResult.withLocation(objectUri), decoded);
-                    yield extractSigningTime(manifestCmsParser.getManifestCms());
-                }
-                case Aspa -> {
-                    var aspaCmsParser = new AspaCmsParser();
-                    aspaCmsParser.parse(ValidationResult.withLocation(objectUri), decoded);
-                    yield extractSigningTime(aspaCmsParser.getAspa());
-                }
-                case Roa -> {
-                    RoaCmsParser roaCmsParser = new RoaCmsParser();
-                    roaCmsParser.parse(ValidationResult.withLocation(objectUri), decoded);
-                    yield extractSigningTime(roaCmsParser.getRoaCms());
-                }
                 case Certificate -> {
                     X509ResourceCertificateParser x509CertificateParser = new X509ResourceCertificateParser();
                     x509CertificateParser.parse(ValidationResult.withLocation(objectUri), decoded);
                     final var cert = x509CertificateParser.getCertificate().getCertificate();
                     yield Instant.ofEpochMilli(cert.getNotBefore().getTime());
                 }
                 case Crl -> {
-                    final X509Crl x509Crl = X509Crl.parseDerEncoded(decoded, ValidationResult.withLocation(objectUri));
-                    final var crl = x509Crl.getCrl();
-                    yield Instant.ofEpochMilli(crl.getThisUpdate().getTime());
-                }
-                case Gbr -> {
-                    GhostbustersCmsParser ghostbustersCmsParser = new GhostbustersCmsParser();
-                    ghostbustersCmsParser.parse(ValidationResult.withLocation(objectUri), decoded);
-                    yield extractSigningTime(ghostbustersCmsParser.getGhostbustersCms());
+                    final ValidationResult result = ValidationResult.withLocation(objectUri);
+                    final X509Crl x509Crl = X509Crl.parseDerEncoded(decoded, result);
+                    checkResult(objectUri, result);
+                    yield Instant.ofEpochMilli(x509Crl.getCrl().getThisUpdate().getTime());
                 }
-                case Unknown -> lastModified;
+                case Manifest ->
+                    extractSigningTime(tryParse(new ManifestCmsParser(), objectUri, decoded).getManifestCms());
+                case Aspa ->
+                    extractSigningTime(tryParse(new AspaCmsParser(), objectUri, decoded).getAspa());
+                case Roa ->
+                    extractSigningTime(tryParse(new RoaCmsParser(), objectUri, decoded).getRoaCms());
+                case Gbr ->
+                    extractSigningTime(tryParse(new GhostbustersCmsParser(), objectUri, decoded).getGhostbustersCms());
+                case Unknown ->
+                    lastModified;
             };
         } catch (Exception e) {
+            metrics.badObject();
+            var encoder = Base64.getEncoder();
+            log.error("Could not parse the object url = {}, body = {} :", objectUri, encoder.encodeToString(decoded), e);
             return lastModified;
         }
     }
 
+    private static <T extends RpkiSignedObjectParser> T tryParse(T parser, final String objectUri, final byte[] decoded) {
+        final ValidationResult result = ValidationResult.withLocation(objectUri);
+        parser.parse(result, decoded);
+        checkResult(objectUri, result);
+        return parser;
+    }
+
+    private static void checkResult(String objectUri, ValidationResult result) {
+        if (result.hasFailures()) {
+            throw new RuntimeException(String.format("Object %s, error %s", objectUri, result.getFailuresForAllLocations()));
+        }
+    }
+
     /**
      * Add artificial millisecond offset to the timestamp based on hash of the object.
      * This MAY help for the corner case of objects having second-accuracy timestamps

src/main/java/net/ripe/rpki/rsyncit/service/SyncService.java

@@ -38,7 +38,7 @@ public SyncService(WebClient webClient,
 
     public void sync() {
         var config = appConfig.getConfig();
-        var rrdpFetcher = new RrdpFetcher(config, webClient, state);
+        var rrdpFetcher = new RrdpFetcher(config, webClient, state, metrics);
 
         var t = Time.timed(rrdpFetcher::fetchObjects);
         final RrdpFetcher.FetchResult fetchResult = t.getResult();

src/test/java/net/ripe/rpki/rsyncit/rrdp/RrdpFetcherTest.java

@@ -1,7 +1,9 @@
 package net.ripe.rpki.rsyncit.rrdp;
 
+import io.micrometer.core.instrument.simple.SimpleMeterRegistry;
 import net.ripe.rpki.TestDefaults;
 import net.ripe.rpki.rsyncit.util.Sha256;
+import org.junit.jupiter.api.DisplayNameGenerator;
 import org.junit.jupiter.api.Test;
 import org.xml.sax.SAXException;
 import org.xml.sax.SAXParseException;
@@ -122,7 +124,7 @@ public void testBrokenSnapshot()  {
     }
 
     private RrdpFetcher.FetchResult tryFetch(String notificationXml, String snapshotXml) throws NotificationStructureException, XPathExpressionException, IOException, ParserConfigurationException, SAXException {
-        var fetcher = new RrdpFetcher(TestDefaults.defaultConfig(), TestDefaults.defaultWebClient(), new State());
+        var fetcher = new RrdpFetcher(TestDefaults.defaultConfig(), TestDefaults.defaultWebClient(), new State(), new RRDPFetcherMetrics(new SimpleMeterRegistry()));
         return fetcher.processNotificationXml(notificationXml.getBytes(StandardCharsets.UTF_8),
             url -> new RrdpFetcher.Downloaded(snapshotXml.getBytes(StandardCharsets.UTF_8), Instant.now()));
     }