Skip to content

Commit

Permalink
[DPC-3785] Mask Postgres details in application logs (#2318)
Browse files Browse the repository at this point in the history
## 🎫 Ticket
[DPC-3875](https://jira.cms.gov/browse/DPC-3785)

## 🛠 Changes
- adds additional masking method for stripping out PSQL details to
existing DPCJsonLayout logging layout class
- this requires changes to both "exception" and "message" fields of
incoming log messages.

<!-- What was added, updated, or removed in this PR? -->

## ℹ️ Context
Even when database entities (i.e.
[OrganizationEntity](https://github.com/CMSgov/dpc-app/blob/99f63fd7ccbdf603c246f6c062eb874f4053cd0f/dpc-common/src/main/java/gov/cms/dpc/common/entities/OrganizationEntity.java))
are not explicitly logged, if an exception is raised, information from
the database may show up in system logs. (See validation section below
for example)

<!-- Why were these changes made? Add background context suitable for a
non-technical audience. -->

<!-- If any of the following security implications apply, this PR must
not be merged without Stephen Walter's approval. Explain in this section
and add @SJWalter11 as a reviewer.
  - Adds a new software dependency or dependencies.
  - Modifies or invalidates one or more of our security controls.
  - Stores or transmits data that was not stored or transmitted before.
- Requires additional review of security implications for other reasons.
-->

## 🧪 Validation

<!-- How were the changes verified? Did you fully test the acceptance
criteria in the ticket? Provide reproducible testing instructions and
screenshots if applicable. -->
 - manual testing done with the Organization `$submit` endpoint
- making this API call multiple times raises a unique constraint
violation
- see also automated unit test added to
`dpc-common/src/test/java/gov/cms/dpc/common/logging/DPCJsonLayoutUnitTest.java`
  • Loading branch information
lukey-luke authored Nov 7, 2024
1 parent b22e19d commit 63b9e29
Show file tree
Hide file tree
Showing 2 changed files with 86 additions and 6 deletions.
Original file line number Diff line number Diff line change
Expand Up @@ -17,10 +17,14 @@
public class DPCJsonLayout extends EventJsonLayout {

private static final String MESSAGE = "message";
private static final String EXCEPTION = "exception";
private static final String KEY_VALUE_SEPARATOR = "=";
private static final String ENTRY_SEPARATOR = ",";
private static final Pattern MBI_PATTERN = Pattern.compile("\\d[a-zA-Z][a-zA-Z0-9]\\d[a-zA-Z][a-zA-Z0-9]\\d[a-zA-Z]{2}\\d{2}");
private static final String MBI_MASK = "***MBI?***";
private static final String DATABASE_INFO_MASK = "**********";
private static final Pattern PSQL_BATCH_ENTRY_EXCEPTION_PATTERN = Pattern.compile("Batch entry \\d+.*?was aborted");
private static final Pattern PSQL_DETAIL_EXCEPTION_PATTERN = Pattern.compile("Detail:.*");

public DPCJsonLayout(JsonFormatter jsonFormatter, TimestampFormatter timestampFormatter, ThrowableHandlingConverter throwableProxyConverter, Set<EventAttribute> includes, Map<String, String> customFieldNames, Map<String, Object> additionalFields, Set<String> includesMdcKeys, boolean flattenMdc) {
super(jsonFormatter, timestampFormatter, throwableProxyConverter, includes, customFieldNames, additionalFields, includesMdcKeys, flattenMdc);
Expand All @@ -29,11 +33,16 @@ public DPCJsonLayout(JsonFormatter jsonFormatter, TimestampFormatter timestampFo
@Override
protected Map<String, Object> toJsonMap(ILoggingEvent event) {
Map<String, Object> map = super.toJsonMap(event);
if(map.containsKey(MESSAGE)){
if(map.get(MESSAGE) != null){
String maskedMessage = maskMBI(event.getFormattedMessage());
maskedMessage = maskPSQLData(maskedMessage);
map.put(MESSAGE, maskedMessage);
parseJsonMessageIfPossible(map, maskedMessage);
}
if(map.get(EXCEPTION) != null){
String maskedExceptionDetails = maskPSQLData(map.get(EXCEPTION).toString());
map.put(EXCEPTION, maskedExceptionDetails);
}
return map;
}

Expand Down Expand Up @@ -63,4 +72,14 @@ private String maskMBI(String unMaskedMessage) {
return unMaskedMessage;
}
}

private String maskPSQLData(String unMaskedMessage) {
try {
String newMessage = PSQL_DETAIL_EXCEPTION_PATTERN.matcher(unMaskedMessage).replaceAll(DATABASE_INFO_MASK);
newMessage = PSQL_BATCH_ENTRY_EXCEPTION_PATTERN.matcher(newMessage).replaceAll(DATABASE_INFO_MASK);
return newMessage;
} catch (Exception e) {
return unMaskedMessage;
}
}
}
Original file line number Diff line number Diff line change
@@ -1,8 +1,10 @@
package gov.cms.dpc.common.logging;

import ch.qos.logback.classic.Logger;
import ch.qos.logback.classic.pattern.ThrowableHandlingConverter;
import ch.qos.logback.classic.spi.ILoggingEvent;
import ch.qos.logback.classic.spi.LoggerContextVO;
import ch.qos.logback.core.read.ListAppender;
import com.google.common.collect.Maps;
import io.dropwizard.logging.json.EventAttribute;
import io.dropwizard.logging.json.layout.JsonFormatter;
Expand All @@ -11,14 +13,15 @@
import org.junit.jupiter.api.Test;
import org.mockito.Mock;
import org.mockito.MockitoAnnotations;
import org.slf4j.LoggerFactory;
import org.hibernate.exception.ConstraintViolationException;
import java.sql.SQLException;

import java.util.HashMap;
import java.util.HashSet;
import java.util.Map;
import java.util.Set;
import java.util.*;

import static org.junit.jupiter.api.Assertions.assertEquals;
import static org.junit.jupiter.api.Assertions.assertFalse;
import static org.mockito.ArgumentMatchers.any;
import static org.mockito.Mockito.when;


Expand Down Expand Up @@ -47,7 +50,7 @@ public void setup() {
dpcJsonLayout = new DPCJsonLayout(jsonFormatter,
timestampFormatter,
throwableHandlingConverter,
Set.of(EventAttribute.MESSAGE),
Set.of(EventAttribute.MESSAGE, EventAttribute.EXCEPTION),
new HashMap<>(),
new HashMap<>(),
new HashSet<>(),
Expand Down Expand Up @@ -125,4 +128,62 @@ public void testMBIMaskingWhenMessageIsParsableAsMap() {
assertEquals("***MBI?***", map.get("key2"));
assertEquals("value3", map.get("key3"));
}

@Test
public void testPostgresMasking() {
String badLogMessage = "[ERROR] org.postgresql.util.PSQLException: ERROR: duplicate key value violates unique constraint \"organization_idx\"\n" +
" Detail: Key (id_system, id_value)=(1, 1111111112) already exists.\n" +
"\tat org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2725)\n" +
"\tat org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2412)\n";
String expectedLogMessage = "[ERROR] org.postgresql.util.PSQLException: ERROR: duplicate key value violates unique constraint \"organization_idx\"\n" +
" **********\n" +
"\tat org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2725)\n" +
"\tat org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2412)\n";
when(loggingEvent.getFormattedMessage()).thenReturn(badLogMessage);
Map<String, Object> map = dpcJsonLayout.toJsonMap(loggingEvent);
assertEquals(expectedLogMessage, map.get("message"));
}

@Test
public void testBatchMessageMasking() {
String reallyLongLogMessage = "Wrapped by: java.sql.BatchUpdateException: Batch entry 0 /* insert gov.cms.dpc.common.entities.OrganizationEntity */ insert into organizations (city, country, district, line1, line2, postal_code, state, address_type, address_use, id_system, id_value, organization_name, id) values (('Akron'), ('US'), (NULL), ('111 Main ST'), ('STE 5'), ('22222'), ('OH'), ('2'::int4), ('1'::int4), ('1'::int4), ('1111111112'), ('Org'), ('d2fcd068-a818-4874-9fc2-fd9633b073a2'::uuid)) was aborted: ERROR: duplicate key value violates unique constraint \\\"organization_idx\\\"\\n Detail: some bad info here";
String expectedLogMessage = "Wrapped by: java.sql.BatchUpdateException: **********: ERROR: duplicate key value violates unique constraint \\\"organization_idx\\\"\\n **********";
when(loggingEvent.getFormattedMessage()).thenReturn(reallyLongLogMessage);
Map<String, Object> map = dpcJsonLayout.toJsonMap(loggingEvent);
assertEquals(expectedLogMessage, map.get("message"));
}

@Test
public void testPostgresMaskingOnException() {
String badLogOnException = "2024-11-01 12:23:25 {\"timestamp\":\"2024-11-01T19:23:25.359+0000\"," +
"\"level\":\"ERROR\",\"thread\":\"pool-3-thread-6\"," +
"\"logger\":\"io.dropwizard.jersey.errors.LoggingExceptionMapper\"," +
"\"message\":\"Error handling a request: 33abf771288c609f\"," +
"\"exception\":\"org.postgresql.util.PSQLException: ERROR: duplicate key value violates unique constraint \\\"organization_idx\\\"\\n Detail: Key (id_system, id_value)=(1, 1111111112) already exists.\\n\\tat org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2725)\\n\\tat ";
String expectedLogMessage = "2024-11-01 12:23:25 {\"timestamp\":\"2024-11-01T19:23:25.359+0000\"," +
"\"level\":\"ERROR\",\"thread\":\"pool-3-thread-6\"," +
"\"logger\":\"io.dropwizard.jersey.errors.LoggingExceptionMapper\"," +
"\"message\":\"Error handling a request: 33abf771288c609f\"," +
"\"exception\":\"org.postgresql.util.PSQLException: ERROR: duplicate key value violates unique constraint \\\"organization_idx\\\"\\n **********";

when(throwableHandlingConverter.convert(any())).thenReturn(badLogOnException);
Logger logger = (Logger) LoggerFactory.getLogger("justtesting");
ListAppender<ILoggingEvent> listAppender = new ListAppender<>();
listAppender.start();
logger.addAppender(listAppender);

// log exception with nested database info
SQLException sqlException = new SQLException("/* insert gov.cms.dpc.common.entities.OrganizationEntity */ insert into organizations (city, country, district, line1, line2, postal_code, state, address_type, address_use, id_system, id_value, organization_name, id) values (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)");
ConstraintViolationException exception = new ConstraintViolationException("could not execute batch", sqlException, "organization_idx");
logger.error("Error handling a request: 33211570adcaad95", exception);

// Retrieve the LoggingEvent object
ILoggingEvent loggingEvent = listAppender.list.stream()
.filter(event -> event.getFormattedMessage().contains("Error handling a request: 33211570adcaad95"))
.findFirst()
.orElse(null);

Map<String, Object> map = dpcJsonLayout.toJsonMap(loggingEvent);
assertEquals(expectedLogMessage, map.get("exception"));
}
}

0 comments on commit 63b9e29

Please sign in to comment.