Refactor Logger to SafeLogger, part 1 #5619

unneon · 2021-09-02T13:53:24Z

Goals (and why): Replace most Logger usage in favor of SafeLogger, to unblock #5597.

Implementation Description (bullets): Each SafeArg vs UnsafeArg decision was made manually, quite conservatively in favor of UnsafeArg due to the large number of changes. For now, only log instances with simple logger declarations were processed.

Testing (What was existing testing like? What have you done to improve it?): Very few places in code test log messages. Nothing was done to improve this.

Concerns (what feedback would you like?): Thoroughly check that all SafeArg instances are actually safe.

Where should we start reviewing?: Wherever.

Priority (whenever / two weeks / yesterday): Not urgent, but blocks baseline upgrade.

changelog-app · 2021-09-02T14:25:29Z

Generate changelog in `changelog/@unreleased`

Type

Description

Refactor Logger to SafeLogger, part 1

Check the box to generate changelog(s)

Generate changelog entry

gmaretic

This must have been enjoyable to write!

gmaretic · 2021-09-09T14:55:59Z

atlasdb-cassandra/src/main/java/com/palantir/atlasdb/keyvalue/cassandra/CqlExecutorImpl.java

@@ -151,7 +151,7 @@ private void scheduleSweepRowTask(
            // RejectedExecutionException are expected.
            // The executor is shutdown when we already fetched all the values we were interested
            // for the current iteration.
-            log.trace("Rejecting row {} because executor is closed", rows.get(rowIndex), e);
+            log.trace("Rejecting row {} because executor is closed", UnsafeArg.of("row", rows.get(rowIndex)), e);


These kind of args are crap anyway because we are logging a reference only. I guess therefore it could be also logged as safe, even though the intention was almost certainly to log the hex representation of the byte array (and therefore unsafe). So this is not wrong, but I would drive by fix it and log the actual array

gmaretic · 2021-09-09T14:57:31Z

...b-cassandra/src/main/java/com/palantir/atlasdb/keyvalue/cassandra/pool/CassandraService.java

@@ -341,7 +342,7 @@ public void debugLogStateOfPool() {
                        activeCheckouts > 0 ? Integer.toString(activeCheckouts) : "(unknown)",
                        totalAllowed > 0 ? Integer.toString(totalAllowed) : "(not bounded)"));
            }
-            log.debug("Current pool state: {}", currentState.toString());
+            log.debug("Current pool state: {}", UnsafeArg.of("currentState", currentState.toString()));


Why unsafe?

gmaretic · 2021-09-09T14:58:44Z

atlasdb-client/src/main/java/com/palantir/atlasdb/keyvalue/impl/SweepStatsKeyValueService.java

@@ -262,7 +263,7 @@ private void flushTask() {
            }
        } catch (Throwable t) {
            if (!Thread.interrupted()) {
-                log.warn("Error occurred while flushing sweep stats: {}", t, t);
+                log.warn("Error occurred while flushing sweep stats: {}", UnsafeArg.of("throwable", t), t);


Is there a benefit to attaching the throwable also as an arg?

gmaretic · 2021-09-09T15:00:47Z

atlasdb-client/src/main/java/com/palantir/atlasdb/keyvalue/impl/SweepStatsKeyValueService.java

@@ -331,7 +336,11 @@ private void flushWrites(Multiset<TableReference> writes, Set<TableReference> cl
                // ignore problems when sweep or transaction tables don't exist
                log.warn("Ignoring failed sweep stats flush due to ", e);
            }
-            log.warn("Unable to flush sweep stats for writes {} and clears {}: ", writes, clears, e);
+            log.warn(


We could add a method to convert these in LoggingArgs?

gmaretic · 2021-09-09T15:01:34Z

atlasdb-client/src/main/java/com/palantir/atlasdb/schema/KvsRangeMigrator.java

+                        SafeArg.of("numRangeBoundaries", numRangeBoundaries),
+                        LoggingArgs.tableRef("srcTable", srcTable),
+                        LoggingArgs.tableRef("destTable", destTable),
+                        UnsafeArg.of("checkpoint", PtBytes.encodeHexString(checkpoint)));


(this is how you encode the hex string)

gmaretic · 2021-09-09T15:05:22Z

atlasdb-client/src/main/java/com/palantir/atlasdb/stream/AbstractGenericStreamStore.java

@@ -190,7 +195,7 @@ private void writeStreamToFile(Transaction transaction, T id, StreamMetadata met
        try {
            tryWriteStreamToFile(transaction, id, metadata, fos);
        } catch (IOException e) {
-            log.error("Could not finish streaming blocks to file for stream {}", id, e);
+            log.error("Could not finish streaming blocks to file for stream {}", UnsafeArg.of("stream", id), e);


Stream ids are probably safe, but no need to change

gmaretic · 2021-09-09T15:07:06Z

atlasdb-client/src/main/java/com/palantir/atlasdb/table/description/Schema.java

@@ -248,7 +249,7 @@ public void validate() {
            try {
                entry.getValue().validate();
            } catch (Exception e) {
-                log.error("Failed to validate table {}.", entry.getKey(), e);
+                log.error("Failed to validate table {}.", UnsafeArg.of("tableName", entry.getKey()), e);


These are table names from schemas, probably should be safe to log? Again, fine to leave as is

gmaretic · 2021-09-09T15:29:16Z

...-dbkvs/src/main/java/com/palantir/atlasdb/keyvalue/dbkvs/impl/postgres/PostgresDdlTable.java

@@ -128,7 +135,7 @@ public void truncate() {
    public void checkDatabaseVersion() {
        AgnosticResultSet result = conns.get().selectResultSetUnregisteredQuery("SHOW server_version");
        String version = result.get(0).getString("server_version");
-        PostgresVersionCheck.checkDatabaseVersion(version, log);


Why not modify the method to take a SafeLogger instead? If you're worried about public API, you can always keep the old version of the method

gmaretic · 2021-09-09T15:31:38Z

atlasdb-impl-shared/src/main/java/com/palantir/atlasdb/cleaner/Scrubber.java

+                    SafeArg.of("tableCount", scrubTimestampToTableNameToCell.size()),
+                    SafeArg.of("minTimestamp", minTimestamp),
+                    SafeArg.of("maxTimestamp", maxTimestamp),
+                    UnsafeArg.of("tables", tables));


Also maybe use LoggingArgs

gmaretic · 2021-09-09T15:38:41Z

lock-impl/src/main/java/com/palantir/lock/impl/LockServiceImpl.java

        }
    }

-    private Object[] constructSlowLockLogParams(String lockId, LockClient currentHolder, long durationMillis) {


Refactor Logger to SafeLogger, part 1

a992a37

unneon added no changelog merge when ready labels Sep 2, 2021

unneon added 2 commits September 2, 2021 15:11

Style silence warnings CompileTimeConstant

ecef0db

Fix PostgresVersionCheckTest

690aeb8

unneon removed the no changelog label Sep 2, 2021

svc-changelog and others added 7 commits September 2, 2021 14:25

Add generated changelog entries

3a5b08b

Revert PostgresVersionCheck refactor

ab3b45a

Revert IterablePartitioner refactor

b2918ff

Fix using new logger

2fd8b72

Style silence warning

f354950

Style autoformatter

e436b8d

Merge branch 'develop' into mcegielka/safelogger

0b7b339

gmaretic approved these changes Sep 9, 2021

View reviewed changes

Merge branch 'develop' into mcegielka/safelogger

6ca3e3c

bulldozer-bot bot merged commit 0b57644 into develop Sep 13, 2021

bulldozer-bot bot deleted the mcegielka/safelogger branch September 13, 2021 17:12

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Refactor Logger to SafeLogger, part 1 #5619

Refactor Logger to SafeLogger, part 1 #5619

unneon commented Sep 2, 2021

changelog-app bot commented Sep 2, 2021 •

edited by unneon

Loading

gmaretic left a comment

gmaretic Sep 9, 2021

gmaretic Sep 9, 2021

gmaretic Sep 9, 2021

gmaretic Sep 9, 2021

gmaretic Sep 9, 2021

gmaretic Sep 9, 2021

gmaretic Sep 9, 2021

gmaretic Sep 9, 2021

gmaretic Sep 9, 2021

gmaretic Sep 9, 2021

Refactor Logger to SafeLogger, part 1 #5619

Refactor Logger to SafeLogger, part 1 #5619

Conversation

unneon commented Sep 2, 2021

changelog-app bot commented Sep 2, 2021 • edited by unneon Loading

Generate changelog in changelog/@unreleased

gmaretic left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

changelog-app bot commented Sep 2, 2021 •

edited by unneon

Loading

Generate changelog in `changelog/@unreleased`