Skip to content

Commit 033b82a

Browse files
GoodforGodGoodforGod
authored
Logging improvements (#141)
1 parent f536f82 commit 033b82a

File tree

40 files changed

+475
-286
lines changed

40 files changed

+475
-286
lines changed

‎application-graph/src/main/java/ru/tinkoff/kora/application/graph/GraphImpl.java‎

Lines changed: 14 additions & 14 deletions
Original file line numberDiff line numberDiff line change
@@ -95,7 +95,7 @@ public Mono<Void> refresh(Node<?> fromNode) {
9595
}
9696
case ON_COMPLETE -> {
9797
this.semaphore.release();
98-
log.debug("Refreshing Graph completed took {}", Duration.ofNanos(System.nanoTime() - started));
98+
log.debug("Refreshing Graph completed in {}", Duration.ofNanos(System.nanoTime() - started).toString().substring(2).toLowerCase());
9999
}
100100
default -> {}
101101
}
@@ -110,22 +110,22 @@ public Mono<Void> init() {
110110
root.set(0, this.objects.length());
111111
this.semaphore.acquireUninterruptibly();
112112

113-
log.debug("Initializing Graph...");
113+
log.debug("Graph Initializing...");
114114
final long started = System.nanoTime();
115115
return this.initializeSubgraph(root)
116116
.doOnEach(s -> {
117117
switch (s.getType()) {
118118
case CANCEL -> {
119119
this.semaphore.release();
120-
log.debug("Initializing Graph cancelled");
120+
log.debug("Graph Initializing cancelled");
121121
}
122122
case ON_ERROR -> {
123123
this.semaphore.release();
124-
log.debug("Initializing Graph error", s.getThrowable());
124+
log.debug("Graph Initializing error", s.getThrowable());
125125
}
126126
case ON_COMPLETE -> {
127127
this.semaphore.release();
128-
log.debug("Initializing Graph completed took {}", Duration.ofNanos(System.nanoTime() - started));
128+
log.debug("Graph Initializing completed in {}", Duration.ofNanos(System.nanoTime() - started).toString().substring(2).toLowerCase());
129129
}
130130
default -> {}
131131
}
@@ -139,22 +139,22 @@ public Mono<Void> release() {
139139
var root = new BitSet(this.objects.length());
140140
root.set(0, this.objects.length());
141141
this.semaphore.acquireUninterruptibly();
142-
log.debug("Releasing Graph...");
142+
log.debug("Graph Releasing...");
143143
final long started = System.nanoTime();
144144
return this.releaseNodes(this.objects, root)
145145
.doOnEach(s -> {
146146
switch (s.getType()) {
147147
case CANCEL -> {
148148
this.semaphore.release();
149-
log.debug("Releasing graph cancelled");
149+
log.debug("Graph Releasing cancelled");
150150
}
151151
case ON_ERROR -> {
152152
this.semaphore.release();
153-
log.debug("Releasing graph error", s.getThrowable());
153+
log.debug("Graph Releasing error", s.getThrowable());
154154
}
155155
case ON_COMPLETE -> {
156156
this.semaphore.release();
157-
log.debug("Releasing graph completed took {}", Duration.ofNanos(System.nanoTime() - started));
157+
log.debug("Graph Releasing completed in {}", Duration.ofNanos(System.nanoTime() - started).toString().substring(2).toLowerCase());
158158
}
159159
default -> {}
160160
}
@@ -175,7 +175,7 @@ private Mono<Void> initializeSubgraph(BitSet root) {
175175
for (var newPromise : tmpGraph.newPromises) {
176176
newPromise.graph = GraphImpl.this;
177177
}
178-
log.trace("Graph refreshed, calling interceptors");
178+
log.trace("Graph refreshed, calling interceptors...");
179179
for (var refreshListenerNode : this.refreshListenerNodes) {
180180
if (this.objects.get(refreshListenerNode) instanceof RefreshListener refreshListener) {
181181
try {
@@ -386,14 +386,14 @@ private Mono<Void> initializeNode(Node<?> node, Lifecycle lifecycle) {
386386
return lifecycle.init().then()
387387
.doOnEach(s -> {
388388
switch (s.getType()) {
389-
case CANCEL -> this.rootGraph.log.trace("Initializing node {} of class {} cancelled", index, lifecycle.getClass());
390-
case ON_SUBSCRIBE -> this.rootGraph.log.trace("Initializing node {} of class {}", index, lifecycle.getClass());
391-
case ON_ERROR -> this.rootGraph.log.trace("Initializing node {} of class {} error", index, lifecycle.getClass(), s.getThrowable());
389+
case CANCEL -> this.rootGraph.log.trace("Node Initializing {} of class {} cancelled", index, lifecycle.getClass());
390+
case ON_SUBSCRIBE -> this.rootGraph.log.trace("Node Initializing {} of class {}", index, lifecycle.getClass());
391+
case ON_ERROR -> this.rootGraph.log.trace("Node Initializing {} of class {} error", index, lifecycle.getClass(), s.getThrowable());
392392
case ON_COMPLETE -> {
393393
synchronized (TmpGraph.this) {
394394
this.initialized.set(node.index);
395395
}
396-
this.rootGraph.log.trace("Initializing node {} of class {} complete", index, lifecycle.getClass());
396+
this.rootGraph.log.trace("Node Initializing {} of class {} complete", index, lifecycle.getClass());
397397
}
398398
default -> {}
399399
}

‎application-graph/src/main/java/ru/tinkoff/kora/application/graph/KoraApplication.java‎

Lines changed: 4 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -11,22 +11,22 @@ public static RefreshableGraph run(Supplier<ApplicationGraphDraw> supplier) {
1111
var start = System.currentTimeMillis();
1212
var graphDraw = supplier.get();
1313
var log = LoggerFactory.getLogger(graphDraw.getRoot());
14-
log.debug("Initializing Application...");
14+
log.debug("Application initializing...");
1515
try {
1616
var graph = graphDraw.init().block();
1717
var end = System.currentTimeMillis();
1818
try {
1919
var uptime = ManagementFactory.getRuntimeMXBean().getUptime() / 1000.0;
20-
log.info("Initialized Application in {} ms (JVM running for {} s)", end - start, uptime);
20+
log.info("Application initialized in {} ms (JVM running for {} s)", end - start, uptime);
2121
} catch (Throwable ex) {
22-
log.info("Initialized Application in {}ms", end - start);
22+
log.info("Application initialized in {}ms", end - start);
2323
}
2424
var thread = new Thread(() -> graph.release().block());
2525
thread.setName("kora-shutdown");
2626
Runtime.getRuntime().addShutdownHook(thread);
2727
return graph;
2828
} catch (Exception e) {
29-
log.error("Initializing Application failed with error", e);
29+
log.error("Application initializing failed with error", e);
3030
e.printStackTrace();
3131
try {
3232
Thread.sleep(100);// so async logger is able to write exception to log

‎cache/cache-caffeine/src/main/java/ru/tinkoff/kora/cache/caffeine/CaffeineCache.java‎

Lines changed: 6 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -29,15 +29,15 @@ String origin() {
2929

3030
@Override
3131
public V get(@Nonnull K key) {
32-
logger.trace("Looking for value in cache '{}' for key: {}", name, key);
32+
logger.trace("Cache '{}' looking for value for key: {}", name, key);
3333
final CacheTelemetry.TelemetryContext telemetryContext = telemetry.create(CacheTelemetry.Operation.Type.GET, name, origin());
3434
telemetryContext.startRecording();
3535

3636
final V v = caffeine.getIfPresent(key);
3737
if (v == null) {
38-
logger.trace("Value NOT found in cache '{}' for key: {}", name, key);
38+
logger.trace("Cache '{}' no value found for key: {}", name, key);
3939
} else {
40-
logger.debug("Value found in cache '{}' for key: {}", name, key);
40+
logger.debug("Cache '{}' found value for key: {}", name, key);
4141
}
4242

4343
telemetryContext.recordSuccess(v);
@@ -46,7 +46,7 @@ public V get(@Nonnull K key) {
4646

4747
@Nonnull
4848
public V put(@Nonnull K key, @Nonnull V value) {
49-
logger.trace("Putting value in cache '{}' for key: {}", name, key);
49+
logger.trace("Cache '{}' storing for key: {}", name, key);
5050
final CacheTelemetry.TelemetryContext telemetryContext = telemetry.create(CacheTelemetry.Operation.Type.PUT, name, origin());
5151
telemetryContext.startRecording();
5252

@@ -58,7 +58,7 @@ public V put(@Nonnull K key, @Nonnull V value) {
5858

5959
@Override
6060
public void invalidate(@Nonnull K key) {
61-
logger.trace("Invalidating value in cache '{}' for key: {}", name, key);
61+
logger.trace("Cache '{}' invalidating for key: {}", name, key);
6262
final CacheTelemetry.TelemetryContext telemetryContext = telemetry.create(CacheTelemetry.Operation.Type.INVALIDATE, name, origin());
6363
telemetryContext.startRecording();
6464

@@ -69,7 +69,7 @@ public void invalidate(@Nonnull K key) {
6969

7070
@Override
7171
public void invalidateAll() {
72-
logger.trace("Invalidating all values in cache '{}'", name);
72+
logger.trace("Cache '{}' invalidating all values", name);
7373
final CacheTelemetry.TelemetryContext telemetryContext = telemetry.create(CacheTelemetry.Operation.Type.INVALIDATE_ALL, name, origin());
7474
telemetryContext.startRecording();
7575

‎cache/cache-redis/src/main/java/ru/tinkoff/kora/cache/redis/RedisCache.java‎

Lines changed: 24 additions & 18 deletions
Original file line numberDiff line numberDiff line change
@@ -53,7 +53,7 @@ String origin() {
5353

5454
@Override
5555
public V get(@Nonnull K key) {
56-
logger.trace("Looking for value in cache '{}' for key: {}", name, key);
56+
logger.trace("Cache '{}' looking for value for key: {}", name, key);
5757
final byte[] keyAsBytes = keyMapper.apply(key);
5858
final CacheTelemetry.TelemetryContext telemetryContext = telemetry.create(CacheTelemetry.Operation.Type.GET, name, origin());
5959

@@ -64,9 +64,9 @@ public V get(@Nonnull K key) {
6464
: syncClient.getExpire(keyAsBytes, expireAfterAccessMillis);
6565

6666
if (jsonAsBytes != null) {
67-
logger.trace("Value NOT found in cache '{}' for key: {}", name, key);
67+
logger.trace("Cache '{}' no value found for key: {}", name, key);
6868
} else {
69-
logger.debug("Value found in cache '{}' for key: {}", name, key);
69+
logger.debug("Cache '{}' found value for key: {}", name, key);
7070
}
7171

7272
final V v = valueMapper.read(jsonAsBytes);
@@ -82,7 +82,7 @@ public V get(@Nonnull K key) {
8282
@Nonnull
8383
@Override
8484
public V put(@Nonnull K key, @Nonnull V value) {
85-
logger.trace("Putting value in cache '{}' for key: {}", name, key);
85+
logger.trace("Cache '{}' storing for key: {}", name, key);
8686
final byte[] keyAsBytes = keyMapper.apply(key);
8787
final byte[] valueAsBytes = valueMapper.write(value);
8888
final CacheTelemetry.TelemetryContext telemetryContext = telemetry.create(CacheTelemetry.Operation.Type.PUT, name, origin());
@@ -95,7 +95,7 @@ public V put(@Nonnull K key, @Nonnull V value) {
9595
syncClient.setExpire(keyAsBytes, valueAsBytes, expireAfterWriteMillis);
9696
}
9797
telemetryContext.recordSuccess();
98-
logger.trace("Putted value in cache '{}' for key: {}", name, key);
98+
logger.debug("Cache '{}' stored for key: {}", name, key);
9999
return value;
100100
} catch (Exception e) {
101101
telemetryContext.recordFailure(e);
@@ -106,15 +106,15 @@ public V put(@Nonnull K key, @Nonnull V value) {
106106

107107
@Override
108108
public void invalidate(@Nonnull K key) {
109-
logger.trace("Invalidating value in cache '{}' for key: {}", name, key);
109+
logger.trace("Cache '{}' invalidating for key: {}", name, key);
110110
final byte[] keyAsBytes = keyMapper.apply(key);
111111
final CacheTelemetry.TelemetryContext telemetryContext = telemetry.create(CacheTelemetry.Operation.Type.INVALIDATE, name, origin());
112112

113113
try {
114114
telemetryContext.startRecording();
115115
syncClient.del(keyAsBytes);
116116
telemetryContext.recordSuccess();
117-
logger.trace("Invalidated value in cache '{}' for key: {}", name, key);
117+
logger.debug("Cache '{}' invalidated for key: {}", name, key);
118118
} catch (Exception e) {
119119
telemetryContext.recordFailure(e);
120120
logger.warn(e.getMessage(), e);
@@ -123,14 +123,14 @@ public void invalidate(@Nonnull K key) {
123123

124124
@Override
125125
public void invalidateAll() {
126-
logger.trace("Invalidating all values in cache '{}'", name);
126+
logger.trace("Cache '{}' invalidating all", name);
127127
final CacheTelemetry.TelemetryContext telemetryContext = telemetry.create(CacheTelemetry.Operation.Type.INVALIDATE_ALL, name, origin());
128128

129129
try {
130130
telemetryContext.startRecording();
131131
syncClient.flushAll();
132132
telemetryContext.recordSuccess();
133-
logger.trace("Invalidated all values in cache '{}'", name);
133+
logger.debug("Cache '{}' invalidated all", name);
134134
} catch (Exception e) {
135135
telemetryContext.recordFailure(e);
136136
logger.warn(e.getMessage(), e);
@@ -143,17 +143,17 @@ public Mono<V> getAsync(@Nonnull K key) {
143143
final CacheTelemetry.TelemetryContext telemetryContext = telemetry.create(CacheTelemetry.Operation.Type.GET, name, origin());
144144
return Mono.fromCallable(() -> keyMapper.apply(key))
145145
.flatMap(keyAsBytes -> {
146-
logger.trace("Looking for value in cache '{}' for key: {}", name, key);
146+
logger.trace("Cache '{}' looking for value for key: {}", name, key);
147147
telemetryContext.startRecording();
148148
return (expireAfterAccessMillis == null)
149149
? reactiveClient.get(keyAsBytes)
150150
: reactiveClient.getExpire(keyAsBytes, expireAfterAccessMillis);
151151
})
152152
.map(jsonAsBytes -> {
153153
if (jsonAsBytes != null) {
154-
logger.trace("Value NOT found in cache '{}' for key: {}", name, key);
154+
logger.trace("Cache '{}' no value found for key: {}", name, key);
155155
} else {
156-
logger.debug("Value found in cache '{}' for key: {}", name, key);
156+
logger.debug("Cache '{}' found value for key: {}", name, key);
157157
}
158158
final V v = valueMapper.read(jsonAsBytes);
159159
telemetryContext.recordSuccess(jsonAsBytes);
@@ -172,7 +172,7 @@ public Mono<V> putAsync(@Nonnull K key, @Nonnull V value) {
172172
final CacheTelemetry.TelemetryContext telemetryContext = telemetry.create(CacheTelemetry.Operation.Type.PUT, name, origin());
173173
return Mono.fromCallable(() -> keyMapper.apply(key))
174174
.flatMap(keyAsBytes -> {
175-
logger.trace("Putting value in cache '{}' for key: {}", name, key);
175+
logger.trace("Cache '{}' storing for key: {}", name, key);
176176
final byte[] valueAsBytes = valueMapper.write(value);
177177
telemetryContext.startRecording();
178178
return (expireAfterWriteMillis == null)
@@ -182,7 +182,7 @@ public Mono<V> putAsync(@Nonnull K key, @Nonnull V value) {
182182
.map(r -> value)
183183
.switchIfEmpty(Mono.fromCallable(() -> {
184184
telemetryContext.recordSuccess();
185-
logger.trace("Putted value in cache '{}' for key: {}", name, key);
185+
logger.debug("Cache '{}' stored for key: {}", name, key);
186186
return value;
187187
}))
188188
.onErrorResume(e -> {
@@ -197,11 +197,14 @@ public Mono<V> putAsync(@Nonnull K key, @Nonnull V value) {
197197
public Mono<Void> invalidateAsync(@Nonnull K key) {
198198
final CacheTelemetry.TelemetryContext telemetryContext = telemetry.create(CacheTelemetry.Operation.Type.INVALIDATE, name, origin());
199199
return Mono.fromCallable(() -> {
200-
logger.trace("Invalidating value in cache '{}' for key: {}", name, key);
200+
logger.trace("Cache '{}' invalidating for key: {}", name, key);
201201
return keyMapper.apply(key);
202202
})
203203
.flatMap(reactiveClient::del)
204-
.doOnSuccess(r -> telemetryContext.recordSuccess())
204+
.doOnSuccess(r -> {
205+
telemetryContext.recordSuccess();
206+
logger.debug("Cache '{}' invalidated for key: {}", name, key);
207+
})
205208
.onErrorResume(e -> {
206209
telemetryContext.recordFailure(e);
207210
logger.warn(e.getMessage(), e);
@@ -213,9 +216,12 @@ public Mono<Void> invalidateAsync(@Nonnull K key) {
213216
@Override
214217
public Mono<Void> invalidateAllAsync() {
215218
final CacheTelemetry.TelemetryContext telemetryContext = telemetry.create(CacheTelemetry.Operation.Type.INVALIDATE_ALL, name, origin());
216-
logger.trace("Invalidating all values in cache '{}'", name);
219+
logger.trace("Cache '{}' invalidating all", name);
217220
return reactiveClient.flushAll()
218-
.doOnSuccess(r -> telemetryContext.recordSuccess())
221+
.doOnSuccess(r -> {
222+
telemetryContext.recordSuccess();
223+
logger.debug("Cache '{}' invalidated all", name);
224+
})
219225
.onErrorResume(e -> {
220226
telemetryContext.recordFailure(e);
221227
logger.warn(e.getMessage(), e);

‎cache/cache-redis/src/main/java/ru/tinkoff/kora/cache/redis/client/DefaultLettuceCommander.java‎

Lines changed: 4 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -31,7 +31,7 @@ public DefaultLettuceCommander(AbstractRedisClient redisClient) {
3131
@Override
3232
public Mono<?> init() {
3333
return ReactorUtils.ioMono(() -> {
34-
logger.debug("Starting Redis Client (Lettuce)...");
34+
logger.debug("Redis Client (Lettuce) starting...");
3535
final long started = System.nanoTime();
3636

3737
try {
@@ -56,18 +56,18 @@ public Mono<?> init() {
5656
throw Exceptions.propagate(e);
5757
}
5858

59-
logger.info("Started Redis Client (Lettuce) took {}", Duration.ofNanos(System.nanoTime() - started));
59+
logger.info("Redis Client (Lettuce) started in {}", Duration.ofNanos(System.nanoTime() - started).toString().substring(2).toLowerCase());
6060
});
6161
}
6262

6363
@Override
6464
public Mono<?> release() {
6565
return ReactorUtils.ioMono(() -> {
6666
try {
67-
logger.debug("Stopping Redis Client (Lettuce)...");
67+
logger.debug("Redis Client (Lettuce) stopping...");
6868
final long started = System.nanoTime();
6969
connection.close();
70-
logger.info("Stopping Redis Client (Lettuce) took {}", Duration.ofNanos(System.nanoTime() - started));
70+
logger.info("Redis Client (Lettuce) stopped in {}", Duration.ofNanos(System.nanoTime() - started).toString().substring(2).toLowerCase());
7171
} catch (Exception e) {
7272
throw Exceptions.propagate(e);
7373
}

‎database/database-cassandra/src/main/java/ru/tinkoff/kora/database/cassandra/CassandraDatabase.java‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -21,6 +21,7 @@ public CassandraDatabase(CassandraConfig config, DataBaseTelemetryFactory teleme
2121
this.telemetry = telemetryFactory.get(
2222
Objects.requireNonNullElse(config.basic().sessionName(), "cassandra"),
2323
"cassandra",
24+
"cassandra",
2425
Optional.ofNullable(config.auth()).map(CassandraConfig.CassandraCredentials::login).orElse("anonymous")
2526
);
2627
}

‎database/database-common/src/main/java/ru/tinkoff/kora/database/common/telemetry/DataBaseLogger.java‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -9,5 +9,5 @@ public interface DataBaseLogger {
99

1010
void logQueryBegin(QueryContext queryContext);
1111

12-
void logQueryEnd(long duration, QueryContext queryContext, @Nullable Throwable ex);
12+
void logQueryEnd(long processingTime, QueryContext queryContext, @Nullable Throwable ex);
1313
}

‎database/database-common/src/main/java/ru/tinkoff/kora/database/common/telemetry/DataBaseLoggerFactory.java‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1,6 +1,7 @@
11
package ru.tinkoff.kora.database.common.telemetry;
22

33
public interface DataBaseLoggerFactory {
4+
45
DataBaseLogger get(String poolName);
56

67
final class DefaultDataBaseLoggerFactory implements DataBaseLoggerFactory {

‎database/database-common/src/main/java/ru/tinkoff/kora/database/common/telemetry/DataBaseTelemetryFactory.java‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,5 @@
11
package ru.tinkoff.kora.database.common.telemetry;
22

33
public interface DataBaseTelemetryFactory {
4-
DataBaseTelemetry get(String name, String dbType, String username);
4+
DataBaseTelemetry get(String name, String driverType, String dbType, String username);
55
}

0 commit comments

Comments
 (0)