Skip to content

Commit c093d27

Browse files
simbo1905simbo1905
committed
logging
1 parent 0227fbd commit c093d27

File tree

10 files changed

+87
-61
lines changed

10 files changed

+87
-61
lines changed

‎json-java21-schema/src/main/java/io/github/simbo1905/json/schema/JsonSchema.java‎

Lines changed: 22 additions & 20 deletions
Original file line numberDiff line numberDiff line change
@@ -14,8 +14,8 @@
1414
import java.net.URI;
1515
import java.util.*;
1616
import java.util.logging.Level;
17-
import java.util.logging.Logger;
1817
import java.util.regex.Pattern;
18+
import static io.github.simbo1905.json.schema.SchemaLogging.LOG;
1919

2020
/// JSON Schema public API entry point
2121
///
@@ -55,9 +55,9 @@ public sealed interface JsonSchema
5555
JsonSchema.RootRef,
5656
JsonSchema.EnumSchema {
5757

58-
Logger LOG = Logger.getLogger(JsonSchema.class.getName());
58+
/// Shared logger is provided by SchemaLogging.LOG
5959

60-
/** Adapter that normalizes URI keys (strip fragment + normalize) for map access. */
60+
/// Adapter that normalizes URI keys (strip fragment + normalize) for map access.
6161
final class NormalizedUriMap implements java.util.Map<java.net.URI, CompiledRoot> {
6262
private final java.util.Map<java.net.URI, CompiledRoot> delegate;
6363
NormalizedUriMap(java.util.Map<java.net.URI, CompiledRoot> delegate) { this.delegate = delegate; }
@@ -101,11 +101,10 @@ public ValidationResult validateAt(String path, JsonValue json, Deque<Validation
101101
}
102102

103103
/// Options for schema compilation
104-
///
105-
/// @param assertFormats whether to enable format assertion validation
106104
record Options(boolean assertFormats) {
107105
/// Default options with format assertion disabled
108106
static final Options DEFAULT = new Options(false);
107+
String summary() { return "assertFormats=" + assertFormats; }
109108
}
110109

111110
/// Compile-time options controlling remote resolution and caching
@@ -317,7 +316,7 @@ static JsonSchema compile(JsonValue schemaJson, Options options, CompileOptions
317316
Objects.requireNonNull(schemaJson, "schemaJson");
318317
Objects.requireNonNull(options, "options");
319318
Objects.requireNonNull(compileOptions, "compileOptions");
320-
LOG.fine(() -> "compile: Starting schema compilation with initial URI: " + java.net.URI.create("urn:inmemory:root"));
319+
LOG.info(() -> "json-schema.compile start doc=" + java.net.URI.create("urn:inmemory:root") + " options=" + options.summary());
321320
LOG.fine(() -> "compile: Starting schema compilation with full options, schema type: " + schemaJson.getClass().getSimpleName() +
322321
", options.assertFormats=" + options.assertFormats() + ", compileOptions.remoteFetcher=" + compileOptions.remoteFetcher().getClass().getSimpleName());
323322
LOG.fine(() -> "compile: fetch policy allowedSchemes=" + compileOptions.fetchPolicy().allowedSchemes());
@@ -374,8 +373,7 @@ static JsonSchema compile(JsonValue schemaJson, Options options, CompileOptions
374373
}
375374
}
376375

377-
LOG.fine(() -> "compile: Completed schema compilation, total roots compiled: " + rootCount);
378-
LOG.fine(() -> "compile: Completed schema compilation with full options, result type: " + result.getClass().getSimpleName());
376+
LOG.info(() -> "json-schema.compile done roots=" + rootCount);
379377
return result;
380378
}
381379

@@ -393,7 +391,7 @@ static java.net.URI normalizeUri(java.net.URI baseUri, String refString) {
393391
LOG.finest(() -> "normalizeUri: final normalized URI=" + normalized + ", scheme=" + normalized.getScheme() + ", host=" + normalized.getHost() + ", path=" + normalized.getPath());
394392
return normalized;
395393
} catch (IllegalArgumentException e) {
396-
LOG.severe(() -> "ERROR: normalizeUri failed for refString=" + refString + ", baseUri=" + baseUri);
394+
LOG.severe(() -> "ERROR: SCHEMA: normalizeUri failed ref=" + refString + " base=" + baseUri);
397395
throw new IllegalArgumentException("Invalid URI reference: " + refString);
398396
}
399397
}
@@ -571,7 +569,7 @@ static JsonValue fetchIfNeeded(java.net.URI docUri,
571569
return fetchedDocument;
572570

573571
} catch (Exception e) {
574-
LOG.severe(() -> "ERROR: fetchIfNeeded failed to fetch remote document: " + docUri + ", error: " + e.getMessage());
572+
// Network failures are logged by the fetcher; suppress here to avoid duplication
575573
throw new RemoteResolutionException(docUri, RemoteResolutionException.Reason.NETWORK_ERROR,
576574
"Failed to fetch remote document: " + docUri, e);
577575
}
@@ -681,7 +679,7 @@ static void detectAndThrowCycle(Set<java.net.URI> active, java.net.URI docUri, S
681679
LOG.finest(() -> "detectAndThrowCycle: active set=" + active + ", docUri=" + docUri + ", pathTrail='" + pathTrail + "'");
682680
LOG.finest(() -> "detectAndThrowCycle: docUri object=" + docUri + ", scheme=" + docUri.getScheme() + ", host=" + docUri.getHost() + ", path=" + docUri.getPath());
683681
if (active.contains(docUri)) {
684-
String cycleMessage = "ERROR: CYCLE: " + pathTrail + " -> " + docUri + " (compile-time remote ref cycle)";
682+
String cycleMessage = "ERROR: CYCLE: " + pathTrail + "; doc=" + docUri;
685683
LOG.severe(() -> cycleMessage);
686684
throw new IllegalArgumentException(cycleMessage);
687685
}
@@ -730,20 +728,24 @@ static CompiledRegistry freezeRoots(Map<java.net.URI, CompiledRoot> built, java.
730728
/// @return ValidationResult with success/failure information
731729
default ValidationResult validate(JsonValue json) {
732730
Objects.requireNonNull(json, "json");
731+
LOG.info(() -> "json-schema.validate start frames=0 doc=unknown");
733732
List<ValidationError> errors = new ArrayList<>();
734733
Deque<ValidationFrame> stack = new ArrayDeque<>();
735734
Set<ValidationKey> visited = new HashSet<>();
736735
stack.push(new ValidationFrame("", this, json));
737736

738737
int iterationCount = 0;
739-
final int WARNING_THRESHOLD = 1000; // Warn after 1000 iterations
738+
int maxDepthObserved = 0;
739+
final int WARNING_THRESHOLD = 10_000;
740740

741741
while (!stack.isEmpty()) {
742742
iterationCount++;
743+
if (stack.size() > maxDepthObserved) maxDepthObserved = stack.size();
743744
if (iterationCount % WARNING_THRESHOLD == 0) {
744-
final int count = iterationCount;
745-
LOG.warning(() -> "PERFORMANCE WARNING: Validation stack processing " + count +
746-
" iterations - possible infinite recursion or deeply nested schema");
745+
final int processed = iterationCount;
746+
final int pending = stack.size();
747+
final int maxDepth = maxDepthObserved;
748+
LOG.fine(() -> "PERFORMANCE WARNING: Validation stack processed=" + processed + " pending=" + pending + " maxDepth=" + maxDepth);
747749
}
748750

749751
ValidationFrame frame = stack.pop();
@@ -1457,7 +1459,7 @@ private static String escapeJsonString(String s) {
14571459

14581460
/// Internal schema compiler
14591461
final class SchemaCompiler {
1460-
/** Per-compilation session state (no static mutable fields). */
1462+
/// Per-compilation session state (no static mutable fields).
14611463
private static final class Session {
14621464
final Map<String, JsonSchema> definitions = new LinkedHashMap<>();
14631465
final Map<String, JsonSchema> compiledByPointer = new LinkedHashMap<>();
@@ -1467,7 +1469,7 @@ private static final class Session {
14671469
long totalFetchedBytes;
14681470
int fetchedDocs;
14691471
}
1470-
/** Strip any fragment from a URI, returning the base document URI. */
1472+
/// Strip any fragment from a URI, returning the base document URI.
14711473
private static java.net.URI stripFragment(java.net.URI uri) {
14721474
String s = uri.toString();
14731475
int i = s.indexOf('#');
@@ -1482,7 +1484,7 @@ private static void trace(String stage, JsonValue fragment) {
14821484
}
14831485
}
14841486

1485-
/** Per-compile carrier for resolver-related state. */
1487+
/// Per-compile carrier for resolver-related state.
14861488
private static final class CompileContext {
14871489
final Session session;
14881490
final Map<java.net.URI, CompiledRoot> sharedRoots;
@@ -1504,7 +1506,7 @@ private static final class CompileContext {
15041506
}
15051507
}
15061508

1507-
/** Immutable context frame capturing current document/base/pointer/anchors. */
1509+
/// Immutable context frame capturing current document/base/pointer/anchors.
15081510
private static final class ContextFrame {
15091511
final java.net.URI docUri;
15101512
final java.net.URI baseUri;
@@ -1783,7 +1785,7 @@ static CompilationBundle compileBundle(JsonValue schemaJson, Options options, Co
17831785
final java.net.URI normUri = first;
17841786
LOG.fine(() -> "compileBundle: Successfully fetched document (normalized): " + normUri + ", document type: " + normType);
17851787
} catch (RemoteResolutionException e) {
1786-
LOG.severe(() -> "ERROR: compileBundle failed to fetch remote document: " + docUri + ", reason: " + e.reason());
1788+
// Network outcomes are logged by the fetcher; rethrow to surface to caller
17871789
throw e;
17881790
}
17891791
}

‎json-java21-schema/src/main/java/io/github/simbo1905/json/schema/SchemaLogging.java‎

Lines changed: 11 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,11 @@
1+
package io.github.simbo1905.json.schema;
2+
3+
import java.util.logging.Logger;
4+
5+
/// Centralized logger for the JSON Schema subsystem.
6+
/// All classes must use this logger via:
7+
/// import static io.github.simbo1905.json.schema.SchemaLogging.LOG;
8+
final class SchemaLogging {
9+
public static final Logger LOG = Logger.getLogger("io.github.simbo1905.json.schema");
10+
private SchemaLogging() {}
11+
}

‎json-java21-schema/src/main/java/io/github/simbo1905/json/schema/StructuredLog.java‎

Lines changed: 13 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -4,6 +4,7 @@
44
import java.util.Objects;
55
import java.util.concurrent.ConcurrentHashMap;
66
import java.util.concurrent.atomic.AtomicLong;
7+
import java.util.function.Supplier;
78
import java.util.logging.Level;
89
import java.util.logging.Logger;
910

@@ -24,6 +25,18 @@ static void finest(Logger log, String event, Object... kv) {
2425
if (log.isLoggable(Level.FINEST)) log.finest(() -> ev(event, kv));
2526
}
2627

28+
static void finest(Logger log, String event, Supplier<Map<String, Object>> supplier) {
29+
if (!log.isLoggable(Level.FINEST)) return;
30+
Map<String, Object> m = supplier.get();
31+
Object[] kv = new Object[m.size() * 2];
32+
int i = 0;
33+
for (var e : m.entrySet()) {
34+
kv[i++] = e.getKey();
35+
kv[i++] = e.getValue();
36+
}
37+
log.finest(() -> ev(event, kv));
38+
}
39+
2740
/// Log at FINEST but only every Nth occurrence per event key.
2841
static void finestSampled(Logger log, String event, int everyN, Object... kv) {
2942
if (!log.isLoggable(Level.FINEST)) return;
@@ -78,4 +91,3 @@ private static String sanitize(String s) {
7891
return trimmed.replace('\n', ' ').replace('\r', ' ').replace('\t', ' ');
7992
}
8093
}
81-

‎json-java21-schema/src/main/java/io/github/simbo1905/json/schema/VirtualThreadHttpFetcher.java‎

Lines changed: 13 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -21,13 +21,12 @@
2121
import java.util.concurrent.Future;
2222
import java.util.concurrent.atomic.AtomicInteger;
2323
import java.util.concurrent.atomic.AtomicLong;
24-
import java.util.logging.Logger;
24+
import static io.github.simbo1905.json.schema.SchemaLogging.LOG;
2525

2626
/// `RemoteFetcher` implementation that performs blocking HTTP requests
2727
/// on Java 21 virtual threads. Reuses responses via an in-memory cache
2828
/// so repeated `$ref` lookups avoid re-fetching during the same run.
2929
final class VirtualThreadHttpFetcher implements JsonSchema.RemoteFetcher {
30-
static final Logger LOG = Logger.getLogger(VirtualThreadHttpFetcher.class.getName());
3130

3231
private final HttpClient client;
3332
private final ConcurrentMap<URI, FetchResult> cache = new ConcurrentHashMap<>();
@@ -36,6 +35,8 @@ final class VirtualThreadHttpFetcher implements JsonSchema.RemoteFetcher {
3635

3736
VirtualThreadHttpFetcher() {
3837
this(HttpClient.newBuilder().build());
38+
// Centralized network logging banner
39+
LOG.config(() -> "http.fetcher init redirectPolicy=default timeout=" + 0 + "ms");
3940
}
4041

4142
VirtualThreadHttpFetcher(HttpClient client) {
@@ -65,18 +66,21 @@ private FetchResult fetchOnVirtualThread(URI uri, JsonSchema.FetchPolicy policy)
6566
return future.get();
6667
} catch (InterruptedException e) {
6768
Thread.currentThread().interrupt();
69+
LOG.severe(() -> "ERROR: FETCH: " + uri + " - interrupted TIMEOUT");
6870
throw new JsonSchema.RemoteResolutionException(uri, JsonSchema.RemoteResolutionException.Reason.TIMEOUT, "Interrupted while fetching " + uri, e);
6971
} catch (java.util.concurrent.ExecutionException e) {
7072
Throwable cause = e.getCause();
7173
if (cause instanceof JsonSchema.RemoteResolutionException ex) {
7274
throw ex;
7375
}
76+
LOG.severe(() -> "ERROR: FETCH: " + uri + " - exec NETWORK_ERROR");
7477
throw new JsonSchema.RemoteResolutionException(uri, JsonSchema.RemoteResolutionException.Reason.NETWORK_ERROR, "Failed fetching " + uri, cause);
7578
}
7679
}
7780

7881
private FetchResult performFetch(URI uri, JsonSchema.FetchPolicy policy) {
7982
enforceDocumentLimits(uri, policy);
83+
LOG.finer(() -> "http.fetch start method=GET uri=" + uri);
8084

8185
long start = System.nanoTime();
8286
HttpRequest request = HttpRequest.newBuilder(uri)
@@ -89,6 +93,7 @@ private FetchResult performFetch(URI uri, JsonSchema.FetchPolicy policy) {
8993
HttpResponse<java.io.InputStream> response = client.send(request, HttpResponse.BodyHandlers.ofInputStream());
9094
int status = response.statusCode();
9195
if (status / 100 != 2) {
96+
LOG.severe(() -> "ERROR: FETCH: " + uri + " - " + status + " NOT_FOUND");
9297
throw new JsonSchema.RemoteResolutionException(uri, JsonSchema.RemoteResolutionException.Reason.NOT_FOUND, "HTTP " + status + " fetching " + uri);
9398
}
9499

@@ -104,6 +109,7 @@ private FetchResult performFetch(URI uri, JsonSchema.FetchPolicy policy) {
104109
if (n == -1) break;
105110
readTotal += n;
106111
if (readTotal > cap) {
112+
LOG.severe(() -> "ERROR: FETCH: " + uri + " - 413 PAYLOAD_TOO_LARGE");
107113
throw new JsonSchema.RemoteResolutionException(uri, JsonSchema.RemoteResolutionException.Reason.PAYLOAD_TOO_LARGE, "Payload too large for " + uri);
108114
}
109115
out.write(buf, 0, n);
@@ -113,19 +119,24 @@ private FetchResult performFetch(URI uri, JsonSchema.FetchPolicy policy) {
113119

114120
long total = totalBytes.addAndGet(bytes.length);
115121
if (total > policy.maxTotalBytes()) {
122+
LOG.severe(() -> "ERROR: FETCH: " + uri + " - policy TOTAL_BYTES_EXCEEDED");
116123
throw new JsonSchema.RemoteResolutionException(uri, JsonSchema.RemoteResolutionException.Reason.POLICY_DENIED, "Total fetched bytes exceeded policy for " + uri);
117124
}
118125

119126
String body = new String(bytes, StandardCharsets.UTF_8);
120127
JsonValue json = Json.parse(body);
121128
Duration elapsed = Duration.ofNanos(System.nanoTime() - start);
129+
LOG.finer(() -> "http.fetch done status=" + status + " bytes=" + bytes.length + " uri=" + uri);
122130
return new FetchResult(json, bytes.length, Optional.of(elapsed));
123131
} catch (HttpTimeoutException e) {
132+
LOG.severe(() -> "ERROR: FETCH: " + uri + " - timeout TIMEOUT");
124133
throw new JsonSchema.RemoteResolutionException(uri, JsonSchema.RemoteResolutionException.Reason.TIMEOUT, "Fetch timeout for " + uri, e);
125134
} catch (IOException e) {
135+
LOG.severe(() -> "ERROR: FETCH: " + uri + " - io NETWORK_ERROR");
126136
throw new JsonSchema.RemoteResolutionException(uri, JsonSchema.RemoteResolutionException.Reason.NETWORK_ERROR, "I/O error fetching " + uri, e);
127137
} catch (InterruptedException e) {
128138
Thread.currentThread().interrupt();
139+
LOG.severe(() -> "ERROR: FETCH: " + uri + " - interrupted TIMEOUT");
129140
throw new JsonSchema.RemoteResolutionException(uri, JsonSchema.RemoteResolutionException.Reason.TIMEOUT, "Interrupted fetching " + uri, e);
130141
}
131142
}

‎json-java21-schema/src/test/java/io/github/simbo1905/json/schema/JsonSchemaCheckIT.java‎

Lines changed: 2 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -273,9 +273,7 @@ private static String buildCsvSummary(boolean strict, String timestamp) {
273273
}
274274
}
275275

276-
/**
277-
* Thread-safe metrics container for the JSON Schema Test Suite run.
278-
*/
276+
/// Thread-safe metrics container for the JSON Schema Test Suite run.
279277
/// Thread-safe strict metrics container for the JSON Schema Test Suite run
280278
final class StrictMetrics {
281279
final java.util.concurrent.atomic.LongAdder total = new java.util.concurrent.atomic.LongAdder();
@@ -303,4 +301,4 @@ static final class FileCounters {
303301
final java.util.concurrent.atomic.LongAdder skipException = new java.util.concurrent.atomic.LongAdder();
304302
final java.util.concurrent.atomic.LongAdder skipMismatch = new java.util.concurrent.atomic.LongAdder();
305303
}
306-
}
304+
}

‎json-java21-schema/src/test/java/io/github/simbo1905/json/schema/JsonSchemaRefLocalTest.java‎

Lines changed: 12 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -65,9 +65,9 @@ void testDefsByName() {
6565
@Test
6666
void testNestedPointer() {
6767
/// Schema with nested pointer #/properties/...
68-
JsonSchema.LOG.fine("testNestedPointer: Starting detailed logging");
69-
JsonSchema.LOG.finer("testNestedPointer: About to parse schema JSON");
70-
JsonSchema.LOG.info("Starting test: testNestedPointer XXX");
68+
io.github.simbo1905.json.schema.SchemaLogging.LOG.fine("testNestedPointer: Starting detailed logging");
69+
io.github.simbo1905.json.schema.SchemaLogging.LOG.finer("testNestedPointer: About to parse schema JSON");
70+
io.github.simbo1905.json.schema.SchemaLogging.LOG.info("TEST: JsonSchemaRefLocalTest#testNestedPointer");
7171

7272
var schemaJson = Json.parse("""
7373
{
@@ -83,23 +83,23 @@ void testNestedPointer() {
8383
}
8484
}
8585
""");
86-
JsonSchema.LOG.finer("testNestedPointer: Schema JSON parsed successfully");
87-
JsonSchema.LOG.fine("testNestedPointer: Schema JSON parsed: " + schemaJson);
88-
JsonSchema.LOG.finer("testNestedPointer: About to compile schema");
86+
io.github.simbo1905.json.schema.SchemaLogging.LOG.finer("testNestedPointer: Schema JSON parsed successfully");
87+
io.github.simbo1905.json.schema.SchemaLogging.LOG.fine("testNestedPointer: Schema JSON parsed: " + schemaJson);
88+
io.github.simbo1905.json.schema.SchemaLogging.LOG.finer("testNestedPointer: About to compile schema");
8989
var schema = JsonSchema.compile(schemaJson);
90-
JsonSchema.LOG.finer("testNestedPointer: Schema compiled successfully");
91-
JsonSchema.LOG.fine("testNestedPointer: Compiled schema: " + schema);
90+
io.github.simbo1905.json.schema.SchemaLogging.LOG.finer("testNestedPointer: Schema compiled successfully");
91+
io.github.simbo1905.json.schema.SchemaLogging.LOG.fine("testNestedPointer: Compiled schema: " + schema);
9292

9393
// { "refUser": { "id":"aa" } } valid
94-
JsonSchema.LOG.fine("testNestedPointer: Validating first case - should pass");
94+
io.github.simbo1905.json.schema.SchemaLogging.LOG.fine("testNestedPointer: Validating first case - should pass");
9595
var result1 = schema.validate(Json.parse("{ \"refUser\": { \"id\":\"aa\" } }"));
96-
JsonSchema.LOG.finest("testNestedPointer: First validation result: " + result1);
96+
io.github.simbo1905.json.schema.SchemaLogging.LOG.finest("testNestedPointer: First validation result: " + result1);
9797
assertThat(result1.valid()).isTrue();
9898

9999
// { "refUser": { "id":"a" } } invalid (minLength)
100-
JsonSchema.LOG.fine("testNestedPointer: Validating second case - should fail");
100+
io.github.simbo1905.json.schema.SchemaLogging.LOG.fine("testNestedPointer: Validating second case - should fail");
101101
var result2 = schema.validate(Json.parse("{ \"refUser\": { \"id\":\"a\" } }"));
102-
JsonSchema.LOG.finest("testNestedPointer: Second validation result: " + result2);
102+
io.github.simbo1905.json.schema.SchemaLogging.LOG.finest("testNestedPointer: Second validation result: " + result2);
103103
assertThat(result2.valid()).isFalse();
104104
assertThat(result2.errors()).hasSize(1);
105105
assertThat(result2.errors().get(0).message()).contains("String too short");

‎json-java21-schema/src/test/java/io/github/simbo1905/json/schema/JsonSchemaRemoteRefTest.java‎

Lines changed: 1 addition & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -11,15 +11,13 @@
1111
import java.util.Optional;
1212
import java.util.Set;
1313
import java.util.concurrent.atomic.AtomicInteger;
14-
import java.util.logging.Logger;
14+
import static io.github.simbo1905.json.schema.SchemaLogging.LOG;
1515

1616
import static org.assertj.core.api.Assertions.assertThat;
1717
import static org.assertj.core.api.Assertions.assertThatThrownBy;
1818

1919
final class JsonSchemaRemoteRefTest extends JsonSchemaLoggingConfig {
2020

21-
private static final Logger LOG = Logger.getLogger(JsonSchemaRemoteRefTest.class.getName());
22-
2321
@Test
2422
void resolves_http_ref_to_pointer_inside_remote_doc() {
2523
LOG.info(() -> "START resolves_http_ref_to_pointer_inside_remote_doc");

0 commit comments

Comments
 (0)