Skip to content

Commit

Permalink
Demote PHI logging to debug or lower (#4430)
Browse files Browse the repository at this point in the history 
Ensure resource bodies are only logged at debug or lower.

* Drop possible-phi logs to debug.
* Demote request/response log bodies to debug since they may contain PHI.
* Demote job-param logging to debug.
* Add startup hook to App for test injection.
* Change terminology cli logging to avoid logging whole resource.
  • Loading branch information
@michaelabuckley
michaelabuckley authored Jan 13, 2023
1 parent a9ecc18 commit 21b1820
Show file tree
Hide file tree
Showing 162 changed files with 1,275 additions and 1,112 deletions.
12 changes: 12 additions & 0 deletions hapi-fhir-cli/hapi-fhir-cli-api/src/main/java/ca/uhn/fhir/cli/BaseApp.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -23,6 +23,7 @@
import ca.uhn.fhir.i18n.Msg;
import ca.uhn.fhir.system.HapiSystemProperties;
import ca.uhn.fhir.util.VersionUtil;
import com.google.common.annotations.VisibleForTesting;
import com.helger.commons.io.file.FileHelper;
import org.apache.commons.cli.CommandLine;
import org.apache.commons.cli.DefaultParser;
Expand All @@ -43,6 +44,7 @@
import java.util.Collections;
import java.util.List;
import java.util.Optional;
import java.util.function.Consumer;

import static org.apache.commons.lang3.StringUtils.isNotBlank;
import static org.fusesource.jansi.Ansi.ansi;
Expand All @@ -63,6 +65,7 @@ public abstract class BaseApp {
ourLog = LoggerFactory.getLogger(App.class);
}

private Consumer<BaseApp> myStartupHook = noop->{};
private MyShutdownHook myShutdownHook;
private boolean myShutdownHookHasNotRun;

Expand Down Expand Up @@ -256,6 +259,8 @@ public void run(String[] theArgs) {
ourDebugMode = true;
}

myStartupHook.accept(this);

// Actually execute the command
command.run(parsedOptions);

Expand Down Expand Up @@ -331,6 +336,8 @@ private void exitDueToProblem(String theDescription) {

private void exitDueToException(Throwable e) {
if (HapiSystemProperties.isTestModeEnabled()) {
ourLog.error("In test-mode - block exit with error status.");
ourLog.error("FAILURE: {}", e.getMessage());
if (e instanceof CommandFailureException) {
throw (CommandFailureException) e;
}
Expand Down Expand Up @@ -358,6 +365,11 @@ private void validateJavaVersion() {
}
}

@VisibleForTesting
public void setStartupHook(Consumer<BaseApp> theStartupHook) {
myStartupHook = theStartupHook;
}

private class MyShutdownHook extends Thread {
private final BaseCommand myFinalCommand;

Expand Down
2 changes: 1 addition & 1 deletion hapi-fhir-cli/hapi-fhir-cli-api/src/main/java/ca/uhn/fhir/cli/BulkImportCommand.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -144,7 +144,7 @@ public void run(CommandLine theCommandLine) throws ParseException, ExecutionExce
.withAdditionalHeader(Constants.HEADER_PREFER, Constants.HEADER_PREFER_RESPOND_ASYNC)
.execute();

ourLog.info("Got response: {}", myFhirCtx.newJsonParser().setPrettyPrint(true).encodeResourceToString(outcome));
ourLog.debug("Got response: {}", myFhirCtx.newJsonParser().setPrettyPrint(true).encodeResourceToString(outcome));
ourLog.info("Bulk import is now running. Do not terminate this command until all files have been uploaded.");

checkJobComplete(outcome.getIdElement().toString(), client);
Expand Down
48 changes: 31 additions & 17 deletions hapi-fhir-cli/hapi-fhir-cli-api/src/main/java/ca/uhn/fhir/cli/ReindexTerminologyCommand.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -20,21 +20,25 @@
* #L%
*/

import ca.uhn.fhir.i18n.Msg;
import ca.uhn.fhir.rest.client.api.IGenericClient;
import ca.uhn.fhir.rest.client.interceptor.LoggingInterceptor;
import ca.uhn.fhir.rest.server.exceptions.BaseServerResponseException;
import ca.uhn.fhir.util.ParametersUtil;
import joptsimple.internal.Strings;
import org.apache.commons.cli.CommandLine;
import org.apache.commons.cli.ParseException;
import org.hl7.fhir.instance.model.api.IBaseParameters;
import org.hl7.fhir.r4.model.Parameters;

import javax.annotation.Nonnull;
import java.util.List;
import java.util.Optional;

import static ca.uhn.fhir.jpa.provider.BaseJpaSystemProvider.RESP_PARAM_SUCCESS;

public class ReindexTerminologyCommand extends BaseRequestGeneratingCommand {
private static final org.slf4j.Logger ourLog = org.slf4j.LoggerFactory.getLogger(ReindexTerminologyCommand.class);
public static final org.slf4j.Logger ourLog = org.slf4j.LoggerFactory.getLogger(ReindexTerminologyCommand.class);

static final String REINDEX_TERMINOLOGY = "reindex-terminology";

Expand Down Expand Up @@ -65,11 +69,11 @@ public void run(CommandLine theCommandLine) throws ParseException {


private void invokeOperation(IGenericClient theClient) {
IBaseParameters inputParameters = ParametersUtil.newInstance(myFhirCtx);

ourLog.info("Beginning freetext indexing - This may take a while...");

IBaseParameters response;
// non-null errorMessage means failure
String errorMessage = null;
try {
response = theClient
.operation()
Expand All @@ -79,30 +83,40 @@ private void invokeOperation(IGenericClient theClient) {
.execute();

} catch (BaseServerResponseException e) {
int statusCode = e.getStatusCode();
errorMessage = e.getMessage();

if (e.getOperationOutcome() != null) {
ourLog.error("Received the following response: {}{}", NL,
myFhirCtx.newJsonParser().setPrettyPrint(true).encodeResourceToString(e.getOperationOutcome()));
errorMessage += " : " + e.getOperationOutcome().getFormatCommentsPre();
}
throw e;
throw new CommandFailureException(Msg.code(2228) + "FAILURE: Received HTTP " + statusCode + ": " + errorMessage);

}


Optional<String> isSuccessResponse = ParametersUtil.getNamedParameterValueAsString(myFhirCtx, response, RESP_PARAM_SUCCESS);
if ( ! isSuccessResponse.isPresent() ) {
ParametersUtil.addParameterToParametersBoolean(myFhirCtx, response, RESP_PARAM_SUCCESS, false);
ParametersUtil.addParameterToParametersString(myFhirCtx, response, "message",
"Internal error. Command result unknown. Check system logs for details");
ourLog.error("Response:{}{}", NL, myFhirCtx.newXmlParser().setPrettyPrint(true).encodeResourceToString(response));
return;
errorMessage = "Internal error. Command result unknown. Check system logs for details.";
} else {
boolean succeeded = Boolean.parseBoolean( isSuccessResponse.get() );
if ( ! succeeded) {
errorMessage = getResponseMessage(response);
}
}

boolean succeeded = Boolean.parseBoolean( isSuccessResponse.get() );
if ( ! succeeded) {
ourLog.info("Response:{}{}", NL, myFhirCtx.newXmlParser().setPrettyPrint(true).encodeResourceToString(response));
return;
if (errorMessage != null) {
throw new CommandFailureException(Msg.code(2229) + "FAILURE: " + errorMessage);
} else {
ourLog.info("Recreation of terminology freetext indexes complete!");
ourLog.info("Response:{}{}", NL, getResponseMessage(response));
}

ourLog.info("Recreation of terminology freetext indexes complete!");
ourLog.info("Response:{}{}", NL, myFhirCtx.newXmlParser().setPrettyPrint(true).encodeResourceToString(response));
}

@Nonnull
private String getResponseMessage(IBaseParameters response) {
List<String> message = ParametersUtil.getNamedParameterValuesAsString(myFhirCtx, response, "message");
return Strings.join(message, NL);
}


Expand Down
4 changes: 2 additions & 2 deletions hapi-fhir-cli/hapi-fhir-cli-api/src/main/java/ca/uhn/fhir/cli/UploadTerminologyCommand.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -217,7 +217,7 @@ private void invokeOperation(String theTermUrl, String[] theDatafile, IGenericCl
ourLog.info("Beginning upload - This may take a while...");

if (ourLog.isDebugEnabled() || HapiSystemProperties.isTestModeEnabled()) {
ourLog.info("Submitting parameters: {}", myFhirCtx.newJsonParser().setPrettyPrint(true).encodeResourceToString(inputParameters));
ourLog.debug("Submitting parameters: {}", myFhirCtx.newJsonParser().setPrettyPrint(true).encodeResourceToString(inputParameters));
}

IBaseParameters response;
Expand All @@ -237,7 +237,7 @@ private void invokeOperation(String theTermUrl, String[] theDatafile, IGenericCl


ourLog.info("Upload complete!");
ourLog.info("Response:\n{}", myFhirCtx.newXmlParser().setPrettyPrint(true).encodeResourceToString(response));
ourLog.debug("Response:\n{}", myFhirCtx.newXmlParser().setPrettyPrint(true).encodeResourceToString(response));
}

private void addFileToRequestBundle(IBaseParameters theInputParameters, String theFileName, byte[] theBytes) {
Expand Down
2 changes: 1 addition & 1 deletion ...i/hapi-fhir-cli-api/src/test/java/ca/uhn/fhir/cli/ExportConceptMapToCsvCommandR4Test.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -66,7 +66,7 @@ public static void afterAll(){
@ParameterizedTest
@ValueSource(booleans = {true, false})
public void testExportConceptMapToCsvCommand(boolean theIncludeTls) throws IOException {
ourLog.info("ConceptMap:\n" + myCtx.newJsonParser().setPrettyPrint(true).encodeResourceToString(createConceptMap()));
ourLog.debug("ConceptMap:\n" + myCtx.newJsonParser().setPrettyPrint(true).encodeResourceToString(createConceptMap()));

App.main(myTlsAuthenticationTestHelper.createBaseRequestGeneratingCommandArgs(
new String[]{
Expand Down
2 changes: 1 addition & 1 deletion ...api-fhir-cli-api/src/test/java/ca/uhn/fhir/cli/ImportCsvToConceptMapCommandDstu3Test.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -145,7 +145,7 @@ public void testImportCsvToConceptMapCommandNoTls(boolean theIncludeTls) throws

ConceptMap conceptMap = (ConceptMap) response.getEntryFirstRep().getResource();

ourLog.info(myCtx.newJsonParser().setPrettyPrint(true).encodeResourceToString(conceptMap));
ourLog.debug(myCtx.newJsonParser().setPrettyPrint(true).encodeResourceToString(conceptMap));

assertEquals(myRestServerDstu3Helper.getBase() + "/ConceptMap/1/_history/1", conceptMap.getId());

Expand Down
4 changes: 2 additions & 2 deletions ...i/hapi-fhir-cli-api/src/test/java/ca/uhn/fhir/cli/ImportCsvToConceptMapCommandR4Test.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -155,7 +155,7 @@ public void testImportCsvToConceptMapCommand(boolean theIncludeTls) throws Excep

ConceptMap conceptMap = (ConceptMap) response.getEntryFirstRep().getResource();

ourLog.info(myFhirContext.newJsonParser().setPrettyPrint(true).encodeResourceToString(conceptMap));
ourLog.debug(myFhirContext.newJsonParser().setPrettyPrint(true).encodeResourceToString(conceptMap));

assertEquals(myRestServerR4Helper.getBase() + "/ConceptMap/1/_history/1", conceptMap.getId());

Expand Down Expand Up @@ -390,7 +390,7 @@ public void testImportCsvToConceptMapCommandWithByteOrderMark(boolean theInclude

ConceptMap conceptMap = (ConceptMap) response.getEntryFirstRep().getResource();

ourLog.info(myFhirContext.newJsonParser().setPrettyPrint(true).encodeResourceToString(conceptMap));
ourLog.debug(myFhirContext.newJsonParser().setPrettyPrint(true).encodeResourceToString(conceptMap));

assertEquals(myRestServerR4Helper.getBase() + "/ConceptMap/1/_history/1", conceptMap.getId());

Expand Down
84 changes: 51 additions & 33 deletions ...ir-cli/hapi-fhir-cli-api/src/test/java/ca/uhn/fhir/cli/ReindexTerminologyCommandTest.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -6,6 +6,9 @@
import ca.uhn.fhir.test.utilities.RestServerR4Helper;
import ca.uhn.fhir.test.utilities.TlsAuthenticationTestHelper;
import ca.uhn.fhir.util.ParametersUtil;
import ca.uhn.test.util.LogbackCaptureTestExtension;
import ch.qos.logback.classic.Logger;
import org.hamcrest.Matchers;
import org.hl7.fhir.instance.model.api.IBaseParameters;
import org.junit.jupiter.api.BeforeEach;
import org.junit.jupiter.api.extension.ExtendWith;
Expand All @@ -15,12 +18,13 @@
import org.mockito.Spy;
import org.mockito.junit.jupiter.MockitoExtension;

import java.io.ByteArrayOutputStream;
import java.io.PrintStream;
import java.util.function.Consumer;

import static ca.uhn.fhir.jpa.provider.BaseJpaSystemProvider.RESP_PARAM_SUCCESS;
import static ca.uhn.test.util.LogbackCaptureTestExtension.eventWithMessageContains;
import static org.hamcrest.CoreMatchers.containsString;
import static org.hamcrest.MatcherAssert.assertThat;
import static org.hamcrest.Matchers.hasItem;
import static org.junit.jupiter.api.Assertions.fail;
import static org.mockito.ArgumentMatchers.any;
import static org.mockito.Mockito.doReturn;
Expand All @@ -39,8 +43,8 @@ class ReindexTerminologyCommandTest {
@RegisterExtension
public TlsAuthenticationTestHelper myTlsAuthenticationTestHelper = new TlsAuthenticationTestHelper();


private final ByteArrayOutputStream outputStreamCaptor = new ByteArrayOutputStream();
// Deliberately not registered - we manually run this later because App startup resets the logging.
LogbackCaptureTestExtension myAppLogCapture;

static {
HapiSystemProperties.enableTestMode();
Expand All @@ -54,21 +58,20 @@ public void beforeEach(){
@ParameterizedTest
@ValueSource(booleans = {true, false})
public void testProviderMethodInvoked(boolean theIncludeTls) {
System.setOut(new PrintStream(outputStreamCaptor));
IBaseParameters retVal = ParametersUtil.newInstance(myContext);
ParametersUtil.addParameterToParametersBoolean(myContext, retVal, RESP_PARAM_SUCCESS, true);
doReturn(retVal).when(myProvider).reindexTerminology(any());

App.main(myTlsAuthenticationTestHelper.createBaseRequestGeneratingCommandArgs(
String[] args = myTlsAuthenticationTestHelper.createBaseRequestGeneratingCommandArgs(
new String[]{
ReindexTerminologyCommand.REINDEX_TERMINOLOGY,
"-v", "r4"
},
"-t", theIncludeTls, myRestServerR4Helper
));
);
runAppWithStartupHook(args, getLoggingStartupHook());

assertThat(outputStreamCaptor.toString().trim(),
outputStreamCaptor.toString().trim(), containsString("<valueBoolean value=\"true\"/>"));
assertThat(myAppLogCapture.getLogEvents(), Matchers.not(hasItem(eventWithMessageContains("FAILURE"))));
}


Expand All @@ -79,13 +82,14 @@ public void testNoVersionThrows(boolean theIncludeTls) {
ParametersUtil.addParameterToParametersBoolean(myContext, retVal, RESP_PARAM_SUCCESS, true);
doReturn(retVal).when(myProvider).reindexTerminology(any());

String[] args = myTlsAuthenticationTestHelper.createBaseRequestGeneratingCommandArgs(
new String[]{
ReindexTerminologyCommand.REINDEX_TERMINOLOGY
},
"-t", theIncludeTls, myRestServerR4Helper
);
try {
App.main(myTlsAuthenticationTestHelper.createBaseRequestGeneratingCommandArgs(
new String[]{
ReindexTerminologyCommand.REINDEX_TERMINOLOGY
},
"-t", theIncludeTls, myRestServerR4Helper
));
App.main(args);
fail();
} catch (Error e) {
assertThat(e.getMessage(), containsString("Missing required option: v"));
Expand Down Expand Up @@ -118,49 +122,63 @@ public void testNoTargetThrows(boolean theIncludeTls) {
@ParameterizedTest
@ValueSource(booleans = {true, false})
public void testHandleUnexpectedResponse(boolean theIncludeTls) {
System.setOut(new PrintStream(outputStreamCaptor));
IBaseParameters retVal = ParametersUtil.newInstance(myContext);
doReturn(retVal).when(myProvider).reindexTerminology(any());

App.main(myTlsAuthenticationTestHelper.createBaseRequestGeneratingCommandArgs(
String[] args = myTlsAuthenticationTestHelper.createBaseRequestGeneratingCommandArgs(
new String[]{
ReindexTerminologyCommand.REINDEX_TERMINOLOGY,
"-v", "r4"
},
"-t", theIncludeTls, myRestServerR4Helper
));

assertThat(outputStreamCaptor.toString().trim(),
outputStreamCaptor.toString().trim(), containsString("<valueBoolean value=\"false\"/>"));
assertThat(outputStreamCaptor.toString().trim(),
outputStreamCaptor.toString().trim(), containsString("<valueString value=\"Internal error. " +
"Command result unknown. Check system logs for details\"/>"));
);
runAppWithStartupHook(args, getLoggingStartupHook());

assertThat(myAppLogCapture.getLogEvents(), hasItem(eventWithMessageContains("FAILURE")));
assertThat(myAppLogCapture.getLogEvents(), hasItem(eventWithMessageContains("Internal error. Command result unknown. Check system logs for details")));
}


@ParameterizedTest
@ValueSource(booleans = {true, false})
public void testHandleServiceError(boolean theIncludeTls) {
System.setOut(new PrintStream(outputStreamCaptor));
IBaseParameters retVal = ParametersUtil.newInstance(myContext);
ParametersUtil.addParameterToParametersBoolean(myContext, retVal, RESP_PARAM_SUCCESS, false);
ParametersUtil.addParameterToParametersString(myContext, retVal, "message",
"Freetext service is not configured. Operation didn't run.");
doReturn(retVal).when(myProvider).reindexTerminology(any());

App.main(myTlsAuthenticationTestHelper.createBaseRequestGeneratingCommandArgs(
// to keep logging verbose.
String[] args = myTlsAuthenticationTestHelper.createBaseRequestGeneratingCommandArgs(
new String[]{
ReindexTerminologyCommand.REINDEX_TERMINOLOGY,
"-v", "r4"
"-v", "r4",
"--debug" // to keep logging verbose.
},
"-t", theIncludeTls, myRestServerR4Helper
));
);
runAppWithStartupHook(args, getLoggingStartupHook());

assertThat(myAppLogCapture.getLogEvents(), hasItem(eventWithMessageContains("FAILURE")));
assertThat(myAppLogCapture.getLogEvents(), hasItem(eventWithMessageContains("Freetext service is not configured. Operation didn't run.")));
}

assertThat(outputStreamCaptor.toString().trim(),
outputStreamCaptor.toString().trim(), containsString("<valueBoolean value=\"false\"/>"));
assertThat(outputStreamCaptor.toString().trim(),
outputStreamCaptor.toString().trim(), containsString("<valueString value=\"Freetext service is not configured. Operation didn't run.\"/>"));
static void runAppWithStartupHook(String[] args, Consumer<BaseApp> startupHook) {
App app = new App();
app.setStartupHook(startupHook);
try {
app.run(args);
} catch (CommandFailureException e) {
// expected
}
}

/**
* The CLI resets Logback logging, so our log hook needs to run inside the app.
*/
Consumer<BaseApp> getLoggingStartupHook() {
return (unused) -> {
myAppLogCapture = new LogbackCaptureTestExtension((Logger) BaseApp.ourLog);
myAppLogCapture.setUp();
};
}
}
4 changes: 2 additions & 2 deletions hapi-fhir-client/src/main/java/ca/uhn/fhir/rest/client/interceptor/LoggingInterceptor.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -92,7 +92,7 @@ public void interceptRequest(IHttpRequest theRequest) {
try {
String content = theRequest.getRequestBodyFromStream();
if (content != null) {
myLog.info("Client request body:\n{}", content);
myLog.debug("Client request body:\n{}", content);
}
} catch (IllegalStateException | IOException e) {
myLog.warn("Failed to replay request contents (during logging attempt, actual FHIR call did not fail)", e);
Expand Down Expand Up @@ -154,7 +154,7 @@ public void interceptResponse(IHttpResponse theResponse) throws IOException {
} catch (IllegalStateException e) {
throw new InternalErrorException(Msg.code(1405) + e);
}
myLog.info("Client response body:\n{}", new String(bytes, StandardCharsets.UTF_8));
myLog.debug("Client response body:\n{}", new String(bytes, StandardCharsets.UTF_8));
} else {
myLog.info("Client response body: (none)");
}
Expand Down
Loading

0 comments on commit 21b1820

Please sign in to comment.