Log not found resources in bulk connection PATCH requests

[kwy404]

A PATCH in a /bulk connection request for an unknown sender or receiver id is answered with a 404 inside the 200 OK bulk response, but nothing was logged, so it was hard to tell from the logs why an item failed. A /single request already logs the generic "Route not found".

This logs a more_info message with the id and type in the /bulk handler when an item comes back as NotFound, leaving details::handle_connection_resource_patch and the /single path unchanged.

Fixes #522

[garethsb]

Thanks; I agree that the bulk response can be difficult to diagnose because the outer HTTP status remains as 200 OK.

I'm not sure this should be logged at warning inside handle_connection_resource_patch though. That helper is shared by single and bulk PATCHes, so a PATCH /single/... would gain this warning in addition to the existing "Route not found" log, which we try to avoid. Also, a missing resource is an ordinary 404 Not Found elsewhere in nmos-cpp; the nearby warning/error logs cover more exceptional activation-state failures.

Maybe we instead add a more_info log in the bulk handler when an item returns NotFound, including its id_type? That would fill the /bulk-specific gap without resulting in two log messages for the same issue in the /single case.

What do you think, @lo-simon ?

[kwy404]

Thanks @garethsb, that makes sense, I had missed that the helper is shared with /single and that it would duplicate the "Route not found" log there. In b120722 I removed the warning from handle_connection_resource_patch and instead log at more_info in the /bulk handler when an item comes back as NotFound, including its id_type ("Resource not found for sender: in bulk request"). So /single is unchanged and the /bulk case gets a single message. Happy to adjust the wording or level if @lo-simon prefers something else.

[lo-simon]

@garethsb and @kwy404 I think it would be better to move the logging inside the try-catch block after details::handle_connection_resource_patch. Also check status_codes::Conflict and status_codes::NotFound, since status_codes::Conflict hasn't been logged.

[kwy404]

Thanks @lo-simon, done in b381d3a. The log now sits inside the try block right after details::handle_connection_resource_patch, so it only covers results returned by that call (the exception handler already logs its own cases), and it logs both status_codes::NotFound ("Resource not found for <id_type> in bulk request") and status_codes::Conflict ("Resource conflict for <id_type> in bulk request"). @garethsb I kept both at more_info as you suggested, and /single is still unchanged. I could not run a full build on my machine, so I relied on the existing << id_type overload in slog.h that the other bulk logs already use; happy to tweak the wording if you prefer.

[lo-simon]

LGTM

[garethsb]

@lo-simon Would it be odd that we'd log status_codes::Locked, BadRequest, and InternalError as warning or error within details::handle_connection_resource_patch itself which would apply to both the bulk POST handler and the single PATCH handler, but status_codes::NotFound and Conflict would now be logged as more_info during a bulk POST handler:

nmos-cpp/Development/nmos/connection_api.cpp

Lines 531 to 533 in b381d3a

	slog::log<slog::severities::warning>(gate, SLOG_FLF) << "Rejecting PATCH request for " << id_type << " due to a pending scheduled activation";
	return details::make_connection_resource_patch_error_response(status_codes::Locked);

nmos-cpp/Development/nmos/connection_api.cpp

Lines 544 to 546 in b381d3a

	slog::log<slog::severities::error>(gate, SLOG_FLF) << "Rejecting PATCH request for " << id_type << " due to a pending immediate activation from the same bulk request";
	return details::make_connection_resource_patch_error_response(status_codes::BadRequest);

nmos-cpp/Development/nmos/connection_api.cpp

Lines 552 to 554 in b381d3a

	slog::log<slog::severities::error>(gate, SLOG_FLF) << "Rejecting PATCH request for " << id_type << " due to a pending immediate activation";
	return details::make_connection_resource_patch_error_response(status_codes::InternalError); // or ServiceUnavailable? probably not NotFound even if that's true after the timeout?

whereas for the single PATCH handler, "Route not found" is logged for NotFound as error as a result of make_api_finally_handler I think, but there's no logging for Conflict?

nmos-cpp/Development/nmos/api_utils.cpp

Lines 569 to 572 in b381d3a

	else if (status_codes::NotFound == res.status_code())
	{
	slog::log<slog::severities::error>(gate, SLOG_FLF) << "Route not found";
	}

I'm trying to think why Conflict isn't logged in details::handle_connection_resource_patch?

[kwy404]

Happy to go either way here. I can move the NotFound and Conflict logging into details::handle_connection_resource_patch, at the same levels as the Locked, BadRequest and InternalError cases, so /single and /bulk behave the same, or keep it in the /bulk handler as it is now. @garethsb @lo-simon just let me know which you prefer and I'll update the PR.