Debug logging of http requests and responses

[duncwebb]

Hi! Is there a mechanism in the API listeners and node behaviour code for logging (at trace / debug level) http requests and response information? I've read through connection_api.cpp looking at the PATCH handler and node_behaviour.cpp at the various POST requests in the registration state machine but I can't see any calls to slog that would dump that information. Do you know if there's support lower down the stack in CPPRestSDK itself to dump this information? Many thanks!

[garethsb]

Every request/response gets logged (not the body of either, but more than enough to populate an Apache-style access log). The example apps write the access log to file if you specify "access_log": "filename" in config.

[duncwebb]

I've got that enabled thanks - that gives me the sender IP address, path and operation and response status code which is really helpful for tracking access - though is there a way to (at a verbose logging level) also dump out the request headers & body and response headers & body? For our purposes I think perhaps I need to use a proxy to catch this and push the info to syslog (something like tinyproxy).

[garethsb]

At least the (request and response) headers would be easy to add. The logging is initiated at

https://github.com/sony/nmos-cpp/blob/fe4e9e6cecf29cfc37f0ea573d3ebcd7459aac62/Development/nmos/api_utils.cpp#L569

so stashing the headers as well and extracting and logging those would be a quick hack.

The response body would also be fairly trivial.

The logging of those is just a performance trade off.

The request body may be more complicated because as far as I remember it can only be read from the request once.

[duncwebb]

Cool - I've managed to get back to looking at this and I've spent a while reading up on CPPRestSDK and tracing through connection_api.cpp and api_utils.cpp and I'm up to speed now : ). The extract_string() method of the http_request object does say that the content of the request body gets 'moved out' as an optimisation so can only be read once. Hmm... I'm loathed to go down the reverse proxy route as that's only going to work for http not https (which I suspect will be more common in field). I'll have a go at coming up with something. Thanks for the pointer!

[duncwebb]

The http_request::to_string() method is not documented as having an effect on the content of the body but it doesn't reliably contain it so that's fine for dumping out the http method, headers etc.

Wrt the request / response body, a problem I hit with my first attempt was that the content of the http_request is being read with extract_json(). Further down the chain in the connection_api.cpp code I can log the serialized json::value but this only will be available if the request body was valid JSON and got past the parser. Ideally I need to see the raw body content as a string.

One idea was to change the extract_json template function in api_utils.cpp at line 64 from:

return msg.extract(json);

to extract the body as a string, log it and then parse it into a json::value and wrap it in a ppxl::task:

    auto nonConstMsg = const_cast<HttpMessage&>(msg); 
    auto bodyString = nonConstMsg.extract_string(true).get();
    slog::log<slog::severities::too_much_info>(gate, SLOG_FLF) << "Raw body string: |" << bodyString << "|";
                
    using web::json::value;
    using utility::stringstream_t;

    utility::stringstream_t bodyStringStream;
    bodyStringStream << bodyString;

    return pplx::task_from_result(web::json::value::parse(bodyStringStream));

This 'works' but this has two serious problems - firstly the (un)const_cast and secondly it essentially makes the function synchronous.

[garethsb]

The http_request::to_string() method is not documented as having an effect on the content of the body but it doesn't reliably contain it so that's fine for dumping out the http method, headers etc.

In what way unreliable? It may depend on whether you wait for the body to be available - that's why the extract functions are asynchronous.

One idea was to change the extract_json template function in api_utils.cpp at line 64 from:

return msg.extract(json);

to extract the body as a string, log it and then parse it into a json::value and wrap it in a ppxl::task:

    auto bodyString = nonConstMsg.extract_string(true).get();
    slog::log<slog::severities::too_much_info>(gate, SLOG_FLF) << "Raw body string: |" << bodyString << "|";
                
    using web::json::value;
    using utility::stringstream_t;

    utility::stringstream_t bodyStringStream;
    bodyStringStream << bodyString;

    return pplx::task_from_result(web::json::value::parse(bodyStringStream));

This 'works' but this has two serious problems - firstly the (un)const_cast and secondly it essentially makes the function synchronous.

You could keep it asynchronous by using a then continuation rather than a blocking get. There may be some performance downside to extracting as string and then parsing, but probably not much if we're careful.

Stepping back a bit, it would be nice to find one consistent code path to log all information about all requests. Doing this in an early handler in the API routers, or in an outer router seems to make most sense. So e.g. adding logging of the request body without extracting it, via a continuation that waits for the body to be ready, to the code at https://github.com/sony/nmos-cpp/blob/master/Development/nmos/api_utils.cpp#L659-L666. That would delay initial handling of the request path/headers in the 'real' API routers until the body had arrived, but that's probably not a significant issue.