Document how to debug REST request/response

[planetf1]

When debugging, it can be useful to log both requests/response made to the server (within the client, 3rd party app, or chassis) as well as the server chassis's inbound requests & response sent.

From a client perspective there are options such as using RestTemplate logging ( spring property logging.level.org.springframework.web.client.RestTemplate=DEBUG )

For the server, we run tomcat, and access logs can be enabled as per https://howtodoinjava.com/spring-boot2/logging/embedded-server-logging-config . There are also other options such as enabling the spring logging actuator, or a logging filter that may be clearer.

As a first step we should document suggested current logging mechanisms, and if insufficient look to enhance that capability in the code

(Originated from a user's query)

[mandy-chessell]

Logging debug messages server-side is a requirement for Egeria modules. Most use the RESTCallLogger for this which also logs the time of the call.

We need an issue for which components are not logging server side.

All client-side requests go through the REST connector and so enabling debug logging just requires log.debug calls.

[planetf1]

Also add info on debugging ssl -- for example can run the chassis, or a client with

-Djavax.net.debug=ssl:handshake:verbose:keymanager:trustmanager 

This enables the logging built into the standard java ssl modules (not in our code -- so we need to do it this way)

The spring logging actuator/config above also caters for debugging all inbound http requests, including those that don't reach our code - bad structure in the request body, invalid endpoint etc - again this is referring to system capabilities since our code is not reached.

So this is more about debugging the setup of the environment itself, rather than trying to understand what Egeria itself is doing once it's involved where as you say, we'd use the Audit Log.

Good tip on the rest call logger for egeria clients

[planetf1]

(Am happy to make these updates - just collating some content and ensuring it's not lost)

[planetf1]

-Dlogging.level.org.springframework.web.client.RestTemplate=DEBUG
-Dserver.tomcat.basedir=/tmp
-Dserver.tomcat.accesslog.enabled=true
-Dserver.tomcat.accesslog.buffered=false

is an example which will produce a simple access log under /tmp/logs ie

tail -f access_log.2021-11-29.log                                                                                               [17:53:06]
0:0:0:0:0:0:0:1 - - [29/Nov/2021:17:52:54 +0000] "GET / HTTP/1.1" 404 100

for the inbound requests - so at least we can see what is being called, in case it is malformed & never reaches Egeria

(as well as add debug for the client)

[planetf1]

Some further hints at https://stackoverflow.com/questions/7952154/spring-resttemplate-how-to-enable-full-debugging-logging-of-requests-responses - but note that by default we are using the jdk http client rather than apache. Enhanced logging may be one reason to move to the latter

For jdk http client see https://stackoverflow.com/questions/53215038/how-to-log-request-response-using-java-net-http-httpclient

-Djdk.httpclient.HttpClient.log=requests

is an option. Needs some further investigation

[planetf1]

Another good suggestion to debug spring request/response - -Ddebug

With this added I was able to determine why a particular REST call was failing. Without this only a 400 was returned, with nothing in the audit log, since the error is swallowed by spring when parsing the request -- we would need to add more handlers to manage this better.

With the debug we see:

2022-02-02 15:07:21.103 DEBUG 49120 --- [io-9443-exec-10] o.s.web.servlet.DispatcherServlet        : POST "/open-metadata/admin-services/users/garygeeke/servers/intsrv/integration-services/database-integrator", parameters={}
2022-02-02 15:07:21.105 DEBUG 49120 --- [io-9443-exec-10] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped to org.odpi.openmetadata.adminservices.spring.ConfigIntegrationServicesResource#configureIntegrationService(String, String, String, IntegrationServiceRequestBody)
2022-02-02 15:07:21.121 DEBUG 49120 --- [io-9443-exec-10] o.s.web.method.HandlerMethod             : Could not resolve parameter [3] in public org.odpi.openmetadata.commonservices.ffdc.rest.VoidResponse org.odpi.openmetadata.adminservices.spring.ConfigIntegrationServicesResource.configureIntegrationService(java.lang.String,java.lang.String,java.lang.String,org.odpi.openmetadata.adminservices.rest.IntegrationServiceRequestBody): JSON parse error: Unexpected character ('\' (code 92)): was expecting double-quote to start field name; nested exception is com.fasterxml.jackson.core.JsonParseException: Unexpected character ('\' (code 92)): was expecting double-quote to start field name
 at [Source: (PushbackInputStream); line: 1, column: 4]
2022-02-02 15:07:21.125  WARN 49120 --- [io-9443-exec-10] .w.s.m.s.DefaultHandlerExceptionResolver : Resolved [org.springframework.http.converter.HttpMessageNotReadableException: JSON parse error: Unexpected character ('\' (code 92)): was expecting double-quote to start field name; nested exception is com.fasterxml.jackson.core.JsonParseException: Unexpected character ('\' (code 92)): was expecting double-quote to start field name<EOL> at [Source: (PushbackInputStream); line: 1, column: 4]]
2022-02-02 15:07:21.125 DEBUG 49120 --- [io-9443-exec-10] o.s.web.servlet.DispatcherServlet        : Completed 400 BAD_REQUEST

Very useful ....