Improve on-demand logging

appender/src/main/java/no/entur/logging/cloud/appender/scope/DefaultLoggingScope.java

@@ -11,47 +11,48 @@
  */
 public class DefaultLoggingScope implements LoggingScope {
 
-    private final Predicate<ILoggingEvent> queuePredicate;
-    private final Predicate<ILoggingEvent> ignorePredicate;
+    protected final Predicate<ILoggingEvent> queuePredicate;
+    protected final Predicate<ILoggingEvent> ignorePredicate;
 
-    private final Predicate<ILoggingEvent> logLevelFailurePredicate;
+    protected boolean failure = false;
 
-    private boolean logLevelFailure = false;
+    protected ConcurrentLinkedQueue<ILoggingEvent> queue = new ConcurrentLinkedQueue<ILoggingEvent>();
 
-    private ConcurrentLinkedQueue<ILoggingEvent> queue = new ConcurrentLinkedQueue<ILoggingEvent>();
-
-    public DefaultLoggingScope(Predicate<ILoggingEvent> queuePredicate, Predicate<ILoggingEvent> ignorePredicate, Predicate<ILoggingEvent> logLevelFailurePredicate) {
+    public DefaultLoggingScope(Predicate<ILoggingEvent> queuePredicate, Predicate<ILoggingEvent> ignorePredicate) {
         this.queuePredicate = queuePredicate;
         this.ignorePredicate = ignorePredicate;
-        this.logLevelFailurePredicate = logLevelFailurePredicate;
     }
 
+    @Override
     public ConcurrentLinkedQueue<ILoggingEvent> getEvents() {
         return queue;
     }
 
+    @Override
     public boolean append(ILoggingEvent eventObject) {
         if(ignorePredicate.test(eventObject)) {
             return true;
         }
 
-        if(!logLevelFailure && logLevelFailurePredicate.test(eventObject)) {
-            logLevelFailure = true;
-        }
-
-        if(queuePredicate.test(eventObject)) {
-            if(logLevelFailure) {
-                // log now, no point in buffering this
-                return false;
+        if(!failure) {
+            if(queuePredicate.test(eventObject)) {
+                // log this event later or not at all
+                queue.add(eventObject);
+                return true;
             }
-            queue.add(eventObject);
-
-            return true;
         }
+        // log this event now
         return false;
     }
 
-    public boolean isLogLevelFailure() {
-        return logLevelFailure;
+    @Override
+    public boolean isFailure() {
+        return failure;
+    }
+
+    @Override
+    public void failure() {
+        // TODO flush buffer here?
+        this.failure = true;
     }
 }

appender/src/main/java/no/entur/logging/cloud/appender/scope/LogLevelLoggingScope.java

@@ -0,0 +1,43 @@
+package no.entur.logging.cloud.appender.scope;
+
+import ch.qos.logback.classic.spi.ILoggingEvent;
+
+import java.util.concurrent.ConcurrentLinkedQueue;
+import java.util.function.Predicate;
+
+/**
+ * Logging scope for temporarily adjusting what gets logged, caching the log skipped-over log statements in the process.
+ *
+ */
+public class LogLevelLoggingScope extends DefaultLoggingScope {
+
+    private final Predicate<ILoggingEvent> logLevelFailurePredicate;
+
+    public LogLevelLoggingScope(Predicate<ILoggingEvent> queuePredicate, Predicate<ILoggingEvent> ignorePredicate, Predicate<ILoggingEvent> logLevelFailurePredicate) {
+        super(queuePredicate, ignorePredicate);
+        this.logLevelFailurePredicate = logLevelFailurePredicate;
+    }
+
+    public boolean append(ILoggingEvent eventObject) {
+        if(ignorePredicate.test(eventObject)) {
+            return true;
+        }
+
+        if(!failure) {
+            if(logLevelFailurePredicate.test(eventObject)) {
+                failure();
+
+                // log this event now
+                return false;
+            }
+            if(queuePredicate.test(eventObject)) {
+                // log this event later or not at all
+                queue.add(eventObject);
+                return true;
+            }
+        }
+        // log this event now
+        return false;
+    }
+
+}

appender/src/main/java/no/entur/logging/cloud/appender/scope/LoggingScope.java

@@ -3,18 +3,25 @@
 import ch.qos.logback.classic.spi.ILoggingEvent;
 
 import java.util.concurrent.ConcurrentLinkedQueue;
-import java.util.function.Predicate;
 
 /**
  * Logging scope for temporarily adjusting what gets logged, caching the log skipped-over log statements in the process.
  *
+ *  Logging scopes are thread safe.
  */
 public interface LoggingScope {
 
     ConcurrentLinkedQueue<ILoggingEvent> getEvents();
 
     boolean append(ILoggingEvent eventObject);
 
-    boolean isLogLevelFailure();
+    boolean isFailure();
 
+    /**
+     *
+     * Manually trigger failure condition for this scope.
+     *
+     */
+
+    void failure();
 }

examples/gcp-async-web-example/README.md

@@ -0,0 +1,2 @@
+# gcp-async-web-example
+Simple async Spring REST service example with a few unit tests.

examples/gcp-async-web-example/build.gradle

@@ -0,0 +1,39 @@
+plugins {
+    id 'org.springframework.boot' version '3.3.7'
+}
+
+test {
+    useJUnitPlatform {
+        includeEngines 'junit-jupiter', 'junit-vintage'
+    }
+}
+
+dependencies {
+    implementation project(':on-demand:on-demand-spring-boot-starter-web')
+    implementation project(":gcp:spring-boot-starter-gcp-web");
+    implementation project(":gcp:request-response-spring-boot-starter-gcp-web");
+
+    implementation("org.springframework.boot:spring-boot-starter-security:${springBootVersion}")
+    implementation("org.springframework.boot:spring-boot-starter-web:${springBootVersion}")
+    implementation("org.springframework.boot:spring-boot-starter-actuator:${springBootVersion}")
+
+    testImplementation project(":gcp:spring-boot-starter-gcp-web-test");
+    testImplementation project(":gcp:request-response-spring-boot-starter-gcp-web-test");
+
+    testImplementation("org.springframework.boot:spring-boot-starter-test:${springBootVersion}")
+
+    // JUnit Jupiter API and TestEngine implementation
+    testImplementation("org.junit.jupiter:junit-jupiter-api:${junitJupiterVersion}")
+    testImplementation("org.junit.jupiter:junit-jupiter-engine:${junitJupiterVersion}")
+
+    testImplementation ("com.google.truth:truth:${googleTruthVersion}")
+    testImplementation ("com.google.truth.extensions:truth-java8-extension:${googleTruthVersion}")
+}
+
+bootRun {
+    // example for running locally with one-line logging
+    dependencies {
+        implementation project(":gcp:spring-boot-starter-gcp-web-test");
+        implementation project(":gcp:request-response-spring-boot-starter-gcp-web-test");
+    }
+}

examples/gcp-async-web-example/dependencycheck-base-suppression.xml

@@ -0,0 +1,9 @@
+<?xml version="1.0" encoding="UTF-8"?>
+<suppressions
+		xmlns="https://jeremylong.github.io/DependencyCheck/dependency-suppression.1.2.xsd">
+
+	<suppress>
+		<cve>CVE-2022-25857</cve>
+	</suppress>
+
+</suppressions>

examples/gcp-async-web-example/src/main/java/org/entur/example/web/DemoApplication.java

@@ -0,0 +1,13 @@
+package org.entur.example.web;
+
+import org.springframework.boot.SpringApplication;
+import org.springframework.boot.autoconfigure.SpringBootApplication;
+
+@SpringBootApplication
+public class DemoApplication {
+    public static void main(String[] args) {
+        SpringApplication.run(DemoApplication.class, args);
+    }
+}
+
+

examples/gcp-async-web-example/src/main/java/org/entur/example/web/config/LogConfiguration.java

@@ -0,0 +1,21 @@
+package org.entur.example.web.config;
+
+import java.util.HashSet;
+import java.util.Set;
+
+import org.springframework.context.annotation.Bean;
+import org.springframework.context.annotation.Configuration;
+import org.zalando.logbook.BodyFilter;
+import org.zalando.logbook.json.JsonBodyFilters;
+
+@Configuration
+public class LogConfiguration {
+
+	@Bean
+	public BodyFilter filterBody() {
+        final Set<String> properties = new HashSet<>();
+        properties.add("secret");
+        return JsonBodyFilters.replaceJsonStringProperty(properties, "hidden");
+	}
+
+}

examples/gcp-async-web-example/src/main/java/org/entur/example/web/config/WebSecurityConfig.java

@@ -0,0 +1,20 @@
+package org.entur.example.web.config;
+import org.springframework.context.annotation.Bean;
+import org.springframework.context.annotation.Configuration;
+import org.springframework.security.config.annotation.web.builders.HttpSecurity;
+import org.springframework.security.config.annotation.web.configuration.EnableWebSecurity;
+import org.springframework.security.web.SecurityFilterChain;
+
+@Configuration
+@EnableWebSecurity
+public class WebSecurityConfig {
+
+	@Bean
+	public SecurityFilterChain filterChain(HttpSecurity http) throws Exception {
+		http
+				.csrf().disable()
+				.authorizeHttpRequests((authz) -> authz
+						.anyRequest().permitAll());
+		return http.build();
+	}
+}

examples/gcp-async-web-example/src/main/java/org/entur/example/web/rest/AsyncDocumentEndpoint.java

@@ -0,0 +1,108 @@
+package org.entur.example.web.rest;
+
+import com.fasterxml.jackson.core.JsonFactory;
+import com.fasterxml.jackson.core.JsonGenerator;
+import no.entur.logging.cloud.spring.ondemand.web.scope.LoggingScopeThreadUtils;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
+import org.springframework.beans.factory.annotation.Autowired;
+import org.springframework.http.HttpStatus;
+import org.springframework.http.ResponseEntity;
+import org.springframework.web.bind.annotation.GetMapping;
+import org.springframework.web.bind.annotation.PostMapping;
+import org.springframework.web.bind.annotation.RequestBody;
+import org.springframework.web.bind.annotation.RequestMapping;
+import org.springframework.web.bind.annotation.RestController;
+
+import java.io.CharArrayWriter;
+import java.io.IOException;
+import java.util.concurrent.CompletableFuture;
+
+@RestController
+@RequestMapping("/api/document")
+public class AsyncDocumentEndpoint {
+
+    private final static Logger logger = LoggerFactory.getLogger(AsyncDocumentEndpoint.class);
+
+	@Autowired
+	private LoggingScopeThreadUtils utils;
+
+	@PostMapping("/some/method")
+	public CompletableFuture<MyEntity> someMessage(@RequestBody MyEntity entity) {
+		logger.trace("Hello entity with secret / trace");
+		logger.debug("Hello entity with secret / debug");
+		logger.info("Hello entity with secret / info");
+		logger.warn("Hello entity with secret / warn");
+		logger.error("Hello entity with secret / error");
+
+		entity.setName("Entur response");
+
+		return CompletableFuture.supplyAsync(utils.with(() -> entity));
+	}
+
+	@PostMapping("/some/error")
+	public CompletableFuture<ResponseEntity> errorMethod(@RequestBody MyEntity entity) throws InterruptedException {
+		System.out.flush();
+		System.out.println("System out before endpoint logging");
+
+		logger.trace("This message should be ignored / trace");
+		logger.debug("This message should be ignored / debug");
+		logger.info("This message should be delayed / info");
+		logger.warn("This message should be logged / warn");
+		logger.error("This message should be logged / error");
+
+		Thread.sleep(1000);
+		System.out.println("System out after endpoint logging + 1000ms");
+
+
+		return CompletableFuture.supplyAsync(utils.with(() -> new ResponseEntity(HttpStatus.NOT_FOUND)));
+	}
+
+	@GetMapping(value = "/some/newlines", produces = "application/json")
+	public CompletableFuture<ResponseEntity<String>> age() {
+		String json = "{\n}\n";
+
+		return CompletableFuture.supplyAsync(utils.with(() -> new ResponseEntity<>(json, HttpStatus.OK)));
+	}
+
+	@GetMapping(value = "/some/bigResponse", produces = "application/json")
+	public CompletableFuture<ResponseEntity<String>> bigResponse() throws IOException {
+		JsonFactory factory = new JsonFactory();
+
+		CharArrayWriter writer = new CharArrayWriter();
+
+		JsonGenerator generator = factory.createGenerator(writer);
+
+		generator.writeStartObject();
+		generator.writeStringField("start", "here");
+		generator.writeStringField("longValue", generateLongString(64*1024));
+		generator.writeStringField("end", "here");
+		generator.writeEndObject();
+
+		generator.flush();
+
+		return CompletableFuture.supplyAsync(utils.with(() -> new ResponseEntity<>(writer.toString(), HttpStatus.OK)));
+	}
+
+	private String generateLongString(int length) {
+		StringBuilder builder = new StringBuilder(length);
+
+		int mod = 'z' - 'a';
+
+		for(int i = 0; i < length; i++) {
+			char c = (char) ('a' + i % mod);
+			builder.append(c);
+		}
+		return builder.toString();
+	}
+
+	@PostMapping("/some/method/infoLoggingOnly")
+	public CompletableFuture<MyEntity> infoLoggingOnly(@RequestBody MyEntity entity) {
+		logger.info("Hello entity with secret / info");
+
+		entity.setName("Entur response");
+		return CompletableFuture.supplyAsync(utils.with(() -> entity));
+	}
+
+
+}

examples/gcp-async-web-example/src/main/java/org/entur/example/web/rest/MyEntity.java

@@ -0,0 +1,28 @@
+package org.entur.example.web.rest;
+
+import org.codehaus.commons.nullanalysis.NotNull;
+
+public class MyEntity {
+
+	@NotNull
+	private String secret;
+
+	@NotNull
+	private String name;
+
+	public String getSecret() {
+		return secret;
+	}
+	public void setSecret(String secret) {
+		this.secret = secret;
+	}
+	public String getName() {
+		return name;
+	}
+	public void setName(String key) {
+		this.name = key;
+	}
+
+
+
+}