API Access Log

The API Access Log is a custom extension to WSO2's API Manager that logs API invocations for debugging and auditing.  It logs incoming requests, outgoing responses and several common error conditions.  It logs the entire URL, including query parameters but does not log headers or the payload.  

Debugging

This tool is designed to be used in conjunction with logging done by the backend service, specifically it helps cover the cases where the backend service doesn't get invoked.

The API Access Log will allow API publishers to see

• URL doesn't match a deployed API (e.g. your API's context is /myapi and they called /my-api) (404)
• The client has incorrect or missing credentials (401)
• The credentials provided don't have sufficient permissions to invoke the resource. (401/403)
• Mismatched resources (e.g. you have a resource called /items and they are calling /item) (404)
• The URL Path and Query Parameters passed by the client.
• Which backend url was called by the API manager.

Auditing

The tool also enables API developers to verify that incoming requests to the API Manager are being properly proxied to the appropriate backend service.

Viewing the Log

The API Access Log is a separate log file from all other logging by the API Manager which allows us to expose this very controlled dataset to all API developers.  The log is monitored by Splunk (UCSD's log aggregation and analysis tool) and stored in a unique index soa_api_public_i.  You can log into splunk at https://its-splunk.ucsd.edu with your AD credentials.  Doing a query for index=soa_api_public_i will show all events generated by the API Access Log.  See the Splunk Queries section below for more advanced queries.

Log Format

Log events are broken up into three event types: incoming requests, outgoing responses and errors.

INCOMING_REQUEST

Logged right after the API is identified, before any work like checking authorization.

Contains:

• RequestInURL – the url that the client invoked on the API Manager.
• API – The API being invoked.

2017-05-26T13:23:25.118-0700 [AM][hMessageProcessor-56]{D_APIAccessLog.AccessLogWriter}[-] INFO  Event="INCOMING_REQUEST", MessageID="urn:uuid:c78c4359-8efe-49a2-b442-f020ae595df1", API="lzelus--Echo:v1.0.0", RequestInURL="/echo/1.0.0/noauth", RequestInMethod="GET", UserAgent="check_http/v2.0.3 (nagios-plugins 2.0.3)"

REQUEST_COMPLETE

Logged upon receiving an answer from the back end service.  This can be correlated with a INCOMING_REQUEST but also repeats much of the data from that item.

Contains:

• RequestOutURL – The URL on the back end service that the API Manager invoked.
• StatusCode - The HTTP Status Code returned by the backend service.
• ResponseTo – The unique message identifier of the matching INCOMING_REQUEST
• Most of the data from the associated INCOMING_REQUEST

2017-05-26T13:23:25.127-0700 [AM][hMessageProcessor-58]{D_APIAccessLog.AccessLogWriter}[-] INFO  Event="REQUEST_COMPLETE", MessageID="urn:uuid:3eae16d5-1988-4f4f-bf1e-ebf00a6cba4d", API="lzelus--Echo:v1.0.0", ResponseTo="urn:uuid:c78c4359-8efe-49a2-b442-f020ae595df1", APPLICATION_NAME="null", END_USER_NAME="null", StatusCode="200", RequestOutURL="https://api-qa.ucsd.edu:8243/_echo/noauth", RequestOutMethod="GET", RequestInURL="/echo/1.0.0/noauth", RequestInMethod="GET"

ERROR

Logged when an error condition is detected.

Contains:

• ErrorSource – A identifier of where the error was raised. This gives an indication of the type of error (e.g. Authorization vs API not found).
• API – The API that matched the request. This may not be present if the API couldn’t be identified.
• ERROR_CODE – The API Manager Error code that will be returned.
• ERROR_MESSAGE – The error message to be returned.
• StatusCode – The HTTP status code that will be returned. Due to implementation limitations, this may be subtly inaccurate (e.g. 401 instead of 403) or missing, depending on the type of error.

Error Sources

• _auth_failure_handler_ - Logged when the incoming request did not meet the authorization requirements to invoke the requested API/Resource. This includes missing credentials, invalid credentials and insufficient permissions.
• main – Logged when the “main” sequence is invoked. In practice this only seems to be called if the request couldn’t be matched to an API (i.e. 404 errors)
• fault – Logged when the “fault” sequence is invoked. This covers any general error, but most useful / common it is called when the backend service couldn’t be contacted.

2017-05-26T12:27:11.063-0700 [AM][MessageProcessor-573]{D_APIAccessLog.AccessLogWriter}[-] INFO  ErrorSource="_auth_failure_handler_", Event="ERROR", MessageID="urn:uuid:628b87e3-1c59-4ef0-ba07-242eb5cd64d2", API="g1zhang--ecoiws:vv2.0", StatusCode="null", ERROR_CODE="900901", ERROR_MESSAGE="Invalid Credentials", RequestInURL="/ecoiws/v2.0/compliancecheck/projectstatus?sid=1&pid=00010920", RequestInMethod="GET", UserAgent="Java/1.7.0_131", RemoteIP="172.16.180.45"

Splunk Queries

So now to the fun part, viewing and visualizing the data!

APIs invoked over a period of time

index=soa_api_public_i INCOMING_REQUEST | timechart count by API

Restrict to an API

index=soa_api_public_i API=*Echo*

Exclude an API

The Echo API is called A LOT by NAGIOS and the Load Balancer and so spams up the logs.  Excluding it from your queries may be helpful.

index=soa_api_public_i  NOT API=*Echo*

Filter by incoming URL

Helpful to identify people attempting to access your API.

index=soa_api_public_i RequestInURL="*CCES*"

Success / Failure Counts By API

This bar graph shows successes and different error types, by API. 

index=soa_api_public_i NOT INCOMING_REQUEST | eval result=if(Event=="REQUEST_COMPLETE", "Success", ERROR_MESSAGE) | chart count by API, result

Requested URLs that couldn't be mapped to an API

index=soa_api_public_i StatusCode=404 | stats count by RequestInURL