Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Quotes or backslashes in fields break API Gateway logs JSON #4348

Closed
hannes-ucsc opened this issue Jul 29, 2022 · 13 comments
Closed

Quotes or backslashes in fields break API Gateway logs JSON #4348

hannes-ucsc opened this issue Jul 29, 2022 · 13 comments
Assignees
Labels
+ [priority] High bug [type] A defect preventing use of the system as specified debt [type] A defect incurring continued engineering cost demo [process] To be demonstrated at the end of the sprint demoed [process] Successfully demonstrated to team infra [subject] Project infrastructure like CI/CD, build and deployment scripts orange [process] Done by the Azul team spike:3 [process] Spike estimate of three points

Comments

@hannes-ucsc
Copy link
Member

We've determined that there is an issue with emitting JSON in API Gateway Logs. The documentation suggests that one can use a JSON template to do so but that suggestion is naive because the approach quickly fails for fields whose values might contain quote or backslash. Something would need to escape those but there is currently no mechanism to do so.

We will whittle down the list of logged fields in #4073 and then split the log template into two blocks: one JSON and one custom, like so:

{
    "safeField1", "$safeField1",
    "safeField2", "$safeField2"
}

unsafeField1: $unsafeField1
unsafeField2: $unsafeField2

A safe field is one whose value is guaranteed (or extremely unlikely) to contain quotes or backslashes. The CloudWatch heuristic that detects and parses JSON in log messages will then be able to parse the JSON from the first block and ignore the second block.

Originally posted by @hannes-ucsc in #4009 (comment)

@github-actions github-actions bot added the orange [process] Done by the Azul team label Jul 29, 2022
@melainalegaspi melainalegaspi added bug [type] A defect preventing use of the system as specified compliance [subject] Information and software security infra [subject] Project infrastructure like CI/CD, build and deployment scripts labels Aug 1, 2022
@theathorn theathorn added debt [type] A defect incurring continued engineering cost and removed compliance [subject] Information and software security labels Nov 8, 2022
@hannes-ucsc
Copy link
Member Author

hannes-ucsc commented Sep 25, 2023

Switching to WAF logging may be feasible workaround. See my comment on the blocker. We'd need to establish if the WAF logs contain sufficient information like response status and latency. I have the feeling, it doesn't but we should make sure in a spike after the blocker lands.

@dsotirho-ucsc
Copy link
Contributor

dsotirho-ucsc commented Jun 27, 2024

@hannes-ucsc: "There may be a solution: there is now $util.escapeJavaScript(). It even documents its use for embedding in JSON. The example also mentions .replaceAll which isn't documented anywhere but appears to be a JavaScript built-in. https://docs.aws.amazon.com/apigateway/latest/developerguide/api-gateway-mapping-template-reference.html#util-template-reference The fact that JavaScript functions are available in this context might come in handy for logging the request body length (instead of the entire body). "

@dsotirho-ucsc
Copy link
Contributor

Assignee to consider next steps.

@hannes-ucsc
Copy link
Member Author

Assignee to create a reproduction.

@hannes-ucsc hannes-ucsc removed their assignment Jul 2, 2024
@dsotirho-ucsc dsotirho-ucsc added the spike:2 [process] Spike estimate of two points label Jul 2, 2024
@achave11-ucsc
Copy link
Member

achave11-ucsc commented Jul 3, 2024

To reproduce, make a request to a service endpoint which forces the error_messageString field to be populated in the API Gateway logs. This can be achieved by running:

curl -X 'GET' 'https://service.dev.singlecell.gi.ucsc.edu/cause_a_malformed_gateway_log'

Then, once the associated logs are available after waiting a few minutes, use the following CW Log Insight Query to find the associated malformed (non-JSON parsable) APIGateway logs:

CloudWatch Logs Insights
region: us-east-1
log-group-names: /aws/apigateway/azul-service-dev
start-time: -900s
end-time: 0s
query-string:

fields @timestamp, @message, @log
| filter @message like 'cause_a_malformed_gateway_log'
| sort @timestamp asc
| limit 1

@timestamp @message @log
2024-07-03 21:37:19.193 {"accountId": "-", "apiId": "c1d9hqzaza", "authorizer_claims_property": "-", "authorizer_error": "-", "authorizer_principalId": "-", "authorizer_property": "-", "awsEndpointRequestId": "-", "awsEndpointRequestId2": "-", "customDomain_basePathMatched": "(none)", "dataProcessed": "-", "domainName": "service.dev.singlecell.gi.ucsc.edu", "domainPrefix": "service", "error_message": "Missing Authentication Token", "error_messageString": ""Missing Authentication Token"", "error_responseType": "MISSING_AUTHENTICATION_TOKEN", "extendedRequestId": "aWumaEnSIAMEbNA=", "httpMethod": "GET", "identity_accountId": "-", "identity_caller": "-", "identity_cognitoAuthenticationProvider": "-", "identity_cognitoAuthenticationType": "-", "identity_cognitoIdentityId": "-", "identity_cognitoIdentityPoolId": "-", "identity_principalOrgId": "-", "identity_clientCert_clientCertPem": "-", "identity_clientCert_subjectDN": "-", "identity_clientCert_issuerDN": "-", "identity_clientCert_serialNumber": "-", "identity_clientCert_validity_notBefore": "-", "identity_clientCert_validity_notAfter": "-", "identity_sourceIp": "128.114.225.140", "identity_user": "-", "identity_userAgent": "curl/8.6.0", "identity_userArn": "-", "integration_error": "-", "integration_integrationStatus": "-", "integration_latency": "-", "integration_requestId": "-", "integration_status": "-", "integrationErrorMessage": "-", "integrationLatency": "-", "integrationStatus": "-", "path": "/cause_a_malformed_gateway_log", "protocol": "HTTP/1.1", "requestId": "1290ef7f-7faf-409b-9bb6-8851d512f735", "requestTime": "03/Jul/2024:21:37:19 +0000", "requestTimeEpoch": "1720042639193", "responseLatency": "9", "responseLength": "42", "routeKey": "-", "stage": "dev", "status": "403"} 122796619775:/aws/apigateway/azul-service-dev

Which looks as follows in the CloudWatch Logs Insights console:

BadParseLog0

Alternatively, to find these type of malformed logs, one may use the following message filter hooks (verbatim):

  • "error_messageString": "" or …
  • ""

Both seemed equally effective in returning the desired log events.

@achave11-ucsc achave11-ucsc removed their assignment Jul 3, 2024
@hannes-ucsc
Copy link
Member Author

hannes-ucsc commented Jul 3, 2024

Assignee to expand screenshot to show that CloudWatch isn't able to parse the JSON in @message. Assignee to add a screenshot showing a log entry where CloudWatch is able to parse it.

@achave11-ucsc
Copy link
Member

achave11-ucsc commented Jul 3, 2024

Screenshot in #4348 (comment) has been updated to include the requested details.

A correctly parsed API Gateway log entry in CloudWatch is like the first entry in the following screenshot:

GoodParseLog0

@achave11-ucsc achave11-ucsc removed their assignment Jul 3, 2024
@hannes-ucsc
Copy link
Member Author

The field that breaks the JSON in the above reproduction is populated by API Gateway. While this is a valid reproduction, and one we need to fix, we should also try a reproduction in which the field value originates in the client. The severity of this issue would be elevated by the possibility to reproduce the issue with a field originating from the client, because that scenario could represent a potential string injection vulnerability. Looking at the list of log entry fields, the identity_userAgent field seems most promising in that context.

@dsotirho-ucsc
Copy link
Contributor

Spike to add a reproduction as outlined above.

@dsotirho-ucsc dsotirho-ucsc added spike:3 [process] Spike estimate of three points and removed spike:2 [process] Spike estimate of two points labels Jul 5, 2024
@achave11-ucsc
Copy link
Member

The following cURL requests with an altered User-Agent header did not cause malformations in the API Gateway Logs, as seen from the console.

cURL requests:

curl -H 'User-Agent: ""This is a special user-agent""' 'https://service.dev.singlecell.gi.ucsc.edu/index/projects'
curl -H 'User-Agent: "This is a special user-agent"' 'https://service.dev.singlecell.gi.ucsc.edu/index/projects'
curl -H 'User-Agent: """This is a special user-agent"""' 'https://service.dev.singlecell.gi.ucsc.edu/index/projects'
curl -H 'User-Agent: ""\"This is a special user-agent\"""' 'https://service.dev.singlecell.gi.ucsc.edu/index/projects'
curl -H 'User-Agent: "\\"\\"This is a special user-agent\\"\\""' 'https://service.dev.singlecell.gi.ucsc.edu/index/projects'
curl -H 'User-Agent: \\"\\"This is a special user-agent\\"\\"' 'https://service.dev.singlecell.gi.ucsc.edu/index/projects'

CloudWatch Logs Insights
region: us-east-1
log-group-names: /aws/apigateway/azul-service-dev
start-time: 2024-07-10T18:11:48.677Z
end-time: 2024-07-10T18:32:40.972Z
query-string:

fields @timestamp, @message, @logStream, @log
| filter @message like 'his is a special'
| sort @timestamp desc
| limit 10000

@timestamp @message @logstream @log
2024-07-10 18:30:33.524 {"accountId": "122796619775", "apiId": "c1d9hqzaza", "authorizer_claims_property": "-", "authorizer_error": "-", "authorizer_principalId": "-", "authorizer_property": "-", "awsEndpointRequestId": "57a0dbbc-4721-489a-bb08-c619f6150ff6", "awsEndpointRequestId2": "-", "customDomain_basePathMatched": "(none)", "dataProcessed": "-", "domainName": "service.dev.singlecell.gi.ucsc.edu", "domainPrefix": "service", "error_message": "-", "error_messageString": "-", "error_responseType": "-", "extendedRequestId": "atXziGZMIAMEGog=", "httpMethod": "GET", "identity_accountId": "-", "identity_caller": "-", "identity_cognitoAuthenticationProvider": "-", "identity_cognitoAuthenticationType": "-", "identity_cognitoIdentityId": "-", "identity_cognitoIdentityPoolId": "-", "identity_principalOrgId": "-", "identity_clientCert_clientCertPem": "-", "identity_clientCert_subjectDN": "-", "identity_clientCert_issuerDN": "-", "identity_clientCert_serialNumber": "-", "identity_clientCert_validity_notBefore": "-", "identity_clientCert_validity_notAfter": "-", "identity_sourceIp": "128.114.221.155", "identity_user": "-", "identity_userAgent": "\\"\\"This is a special user-agent\\"\\"", "identity_userArn": "-", "integration_error": "-", "integration_integrationStatus": "200", "integration_latency": "529", "integration_requestId": "57a0dbbc-4721-489a-bb08-c619f6150ff6", "integration_status": "200", "integrationErrorMessage": "-", "integrationLatency": "529", "integrationStatus": "200", "path": "/index/projects", "protocol": "HTTP/1.1", "requestId": "b9882e4c-726a-443d-949e-22146dc136b2", "requestTime": "10/Jul/2024:18:30:33 +0000", "requestTimeEpoch": "1720636233524", "responseLatency": "540", "responseLength": "223042", "routeKey": "-", "stage": "dev", "status": "200"} 11be73d73587f19737bb3a7bcfb4b291 122796619775:/aws/apigateway/azul-service-dev
2024-07-10 18:29:26.104 {"accountId": "122796619775", "apiId": "c1d9hqzaza", "authorizer_claims_property": "-", "authorizer_error": "-", "authorizer_principalId": "-", "authorizer_property": "-", "awsEndpointRequestId": "69405e58-dff6-4d1a-8905-d216b26e0071", "awsEndpointRequestId2": "-", "customDomain_basePathMatched": "(none)", "dataProcessed": "-", "domainName": "service.dev.singlecell.gi.ucsc.edu", "domainPrefix": "service", "error_message": "-", "error_messageString": "-", "error_responseType": "-", "extendedRequestId": "atXpAFPzIAMEEeQ=", "httpMethod": "GET", "identity_accountId": "-", "identity_caller": "-", "identity_cognitoAuthenticationProvider": "-", "identity_cognitoAuthenticationType": "-", "identity_cognitoIdentityId": "-", "identity_cognitoIdentityPoolId": "-", "identity_principalOrgId": "-", "identity_clientCert_clientCertPem": "-", "identity_clientCert_subjectDN": "-", "identity_clientCert_issuerDN": "-", "identity_clientCert_serialNumber": "-", "identity_clientCert_validity_notBefore": "-", "identity_clientCert_validity_notAfter": "-", "identity_sourceIp": "128.114.221.155", "identity_user": "-", "identity_userAgent": ""\\"\\"This is a special user-agent\\"\\""", "identity_userArn": "-", "integration_error": "-", "integration_integrationStatus": "200", "integration_latency": "547", "integration_requestId": "69405e58-dff6-4d1a-8905-d216b26e0071", "integration_status": "200", "integrationErrorMessage": "-", "integrationLatency": "547", "integrationStatus": "200", "path": "/index/projects", "protocol": "HTTP/1.1", "requestId": "d79b833d-86f4-4d47-8ce3-b770b8cb073a", "requestTime": "10/Jul/2024:18:29:26 +0000", "requestTimeEpoch": "1720636166104", "responseLatency": "561", "responseLength": "223042", "routeKey": "-", "stage": "dev", "status": "200"} 414b1818a2ed089829afbec05138a4ca 122796619775:/aws/apigateway/azul-service-dev
2024-07-10 18:15:21.799 {"accountId": "122796619775", "apiId": "c1d9hqzaza", "authorizer_claims_property": "-", "authorizer_error": "-", "authorizer_principalId": "-", "authorizer_property": "-", "awsEndpointRequestId": "cbe0b9a3-82ee-4dca-9635-caf9e8266df9", "awsEndpointRequestId2": "-", "customDomain_basePathMatched": "(none)", "dataProcessed": "-", "domainName": "service.dev.singlecell.gi.ucsc.edu", "domainPrefix": "service", "error_message": "-", "error_messageString": "-", "error_responseType": "-", "extendedRequestId": "atVlEHlUoAMEHlQ=", "httpMethod": "GET", "identity_accountId": "-", "identity_caller": "-", "identity_cognitoAuthenticationProvider": "-", "identity_cognitoAuthenticationType": "-", "identity_cognitoIdentityId": "-", "identity_cognitoIdentityPoolId": "-", "identity_principalOrgId": "-", "identity_clientCert_clientCertPem": "-", "identity_clientCert_subjectDN": "-", "identity_clientCert_issuerDN": "-", "identity_clientCert_serialNumber": "-", "identity_clientCert_validity_notBefore": "-", "identity_clientCert_validity_notAfter": "-", "identity_sourceIp": "128.114.221.155", "identity_user": "-", "identity_userAgent": """\"This is a special user-agent\"""", "identity_userArn": "-", "integration_error": "-", "integration_integrationStatus": "200", "integration_latency": "116", "integration_requestId": "cbe0b9a3-82ee-4dca-9635-caf9e8266df9", "integration_status": "200", "integrationErrorMessage": "-", "integrationLatency": "116", "integrationStatus": "200", "path": "/index/projects", "protocol": "HTTP/1.1", "requestId": "6499588b-5e44-45d7-84fa-cafc8a3b8ffd", "requestTime": "10/Jul/2024:18:15:21 +0000", "requestTimeEpoch": "1720635321799", "responseLatency": "124", "responseLength": "223042", "routeKey": "-", "stage": "dev", "status": "200"} f26f7a8ba2c8e74fb57b5d312dd32e1b 122796619775:/aws/apigateway/azul-service-dev
2024-07-10 18:15:05.723 {"accountId": "122796619775", "apiId": "c1d9hqzaza", "authorizer_claims_property": "-", "authorizer_error": "-", "authorizer_principalId": "-", "authorizer_property": "-", "awsEndpointRequestId": "54c48800-bcea-4826-8408-36144af32d50", "awsEndpointRequestId2": "-", "customDomain_basePathMatched": "(none)", "dataProcessed": "-", "domainName": "service.dev.singlecell.gi.ucsc.edu", "domainPrefix": "service", "error_message": "-", "error_messageString": "-", "error_responseType": "-", "extendedRequestId": "atVikE0UIAMEv9Q=", "httpMethod": "GET", "identity_accountId": "-", "identity_caller": "-", "identity_cognitoAuthenticationProvider": "-", "identity_cognitoAuthenticationType": "-", "identity_cognitoIdentityId": "-", "identity_cognitoIdentityPoolId": "-", "identity_principalOrgId": "-", "identity_clientCert_clientCertPem": "-", "identity_clientCert_subjectDN": "-", "identity_clientCert_issuerDN": "-", "identity_clientCert_serialNumber": "-", "identity_clientCert_validity_notBefore": "-", "identity_clientCert_validity_notAfter": "-", "identity_sourceIp": "128.114.221.155", "identity_user": "-", "identity_userAgent": """"This is a special user-agent"""", "identity_userArn": "-", "integration_error": "-", "integration_integrationStatus": "200", "integration_latency": "278", "integration_requestId": "54c48800-bcea-4826-8408-36144af32d50", "integration_status": "200", "integrationErrorMessage": "-", "integrationLatency": "278", "integrationStatus": "200", "path": "/index/projects", "protocol": "HTTP/1.1", "requestId": "871dec1f-f461-420b-a86c-b7d3308c2bae", "requestTime": "10/Jul/2024:18:15:05 +0000", "requestTimeEpoch": "1720635305723", "responseLatency": "291", "responseLength": "223042", "routeKey": "-", "stage": "dev", "status": "200"} b42528481e2d6411bd9cda13bfc94c97 122796619775:/aws/apigateway/azul-service-dev
2024-07-10 18:14:40.658 {"accountId": "122796619775", "apiId": "c1d9hqzaza", "authorizer_claims_property": "-", "authorizer_error": "-", "authorizer_principalId": "-", "authorizer_property": "-", "awsEndpointRequestId": "8a799066-e9b0-422f-ae9d-934321079050", "awsEndpointRequestId2": "-", "customDomain_basePathMatched": "(none)", "dataProcessed": "-", "domainName": "service.dev.singlecell.gi.ucsc.edu", "domainPrefix": "service", "error_message": "-", "error_messageString": "-", "error_responseType": "-", "extendedRequestId": "atVepEJOIAMEVBg=", "httpMethod": "GET", "identity_accountId": "-", "identity_caller": "-", "identity_cognitoAuthenticationProvider": "-", "identity_cognitoAuthenticationType": "-", "identity_cognitoIdentityId": "-", "identity_cognitoIdentityPoolId": "-", "identity_principalOrgId": "-", "identity_clientCert_clientCertPem": "-", "identity_clientCert_subjectDN": "-", "identity_clientCert_issuerDN": "-", "identity_clientCert_serialNumber": "-", "identity_clientCert_validity_notBefore": "-", "identity_clientCert_validity_notAfter": "-", "identity_sourceIp": "128.114.221.155", "identity_user": "-", "identity_userAgent": ""This is a special user-agent"", "identity_userArn": "-", "integration_error": "-", "integration_integrationStatus": "200", "integration_latency": "115", "integration_requestId": "8a799066-e9b0-422f-ae9d-934321079050", "integration_status": "200", "integrationErrorMessage": "-", "integrationLatency": "115", "integrationStatus": "200", "path": "/index/projects", "protocol": "HTTP/1.1", "requestId": "99062761-1a58-46a4-95f5-98a635aa8621", "requestTime": "10/Jul/2024:18:14:40 +0000", "requestTimeEpoch": "1720635280658", "responseLatency": "127", "responseLength": "223042", "routeKey": "-", "stage": "dev", "status": "200"} df7c015e4c387ef6b0ba61899df006be 122796619775:/aws/apigateway/azul-service-dev
2024-07-10 18:14:22.451 {"accountId": "122796619775", "apiId": "c1d9hqzaza", "authorizer_claims_property": "-", "authorizer_error": "-", "authorizer_principalId": "-", "authorizer_property": "-", "awsEndpointRequestId": "33ebbf12-898f-4462-92ce-74054cfd9239", "awsEndpointRequestId2": "-", "customDomain_basePathMatched": "(none)", "dataProcessed": "-", "domainName": "service.dev.singlecell.gi.ucsc.edu", "domainPrefix": "service", "error_message": "-", "error_messageString": "-", "error_responseType": "-", "extendedRequestId": "atVbzEAFIAMEHhQ=", "httpMethod": "GET", "identity_accountId": "-", "identity_caller": "-", "identity_cognitoAuthenticationProvider": "-", "identity_cognitoAuthenticationType": "-", "identity_cognitoIdentityId": "-", "identity_cognitoIdentityPoolId": "-", "identity_principalOrgId": "-", "identity_clientCert_clientCertPem": "-", "identity_clientCert_subjectDN": "-", "identity_clientCert_issuerDN": "-", "identity_clientCert_serialNumber": "-", "identity_clientCert_validity_notBefore": "-", "identity_clientCert_validity_notAfter": "-", "identity_sourceIp": "128.114.221.155", "identity_user": "-", "identity_userAgent": """This is a special user-agent""", "identity_userArn": "-", "integration_error": "-", "integration_integrationStatus": "200", "integration_latency": "617", "integration_requestId": "33ebbf12-898f-4462-92ce-74054cfd9239", "integration_status": "200", "integrationErrorMessage": "-", "integrationLatency": "617", "integrationStatus": "200", "path": "/index/projects", "protocol": "HTTP/1.1", "requestId": "e21d5914-d1e1-4e48-8826-8c968a40276a", "requestTime": "10/Jul/2024:18:14:22 +0000", "requestTimeEpoch": "1720635262451", "responseLatency": "629", "responseLength": "223042", "routeKey": "-", "stage": "dev", "status": "200"} 985fd7f9b554635b015267ebfe11868d 122796619775:/aws/apigateway/azul-service-dev

All the API Gateway logs corresponding to the cURL requests above show a properly parsed structure in the console.

Screenshot 2024-07-10 at 1 56 59 PM

@achave11-ucsc achave11-ucsc removed their assignment Jul 10, 2024
@achave11-ucsc
Copy link
Member

Assignee to consider next steps.

@hannes-ucsc
Copy link
Member Author

It looks like the JSON escaping works properly for all fields except error_messageString. Assignee to remove that field from the access logs. The same information is contained in error_message and is properly escaped there.

@hannes-ucsc hannes-ucsc removed their assignment Jul 11, 2024
@achave11-ucsc achave11-ucsc added the + [priority] High label Jul 12, 2024
@achave11-ucsc achave11-ucsc self-assigned this Jul 12, 2024
@hannes-ucsc hannes-ucsc added the demo [process] To be demonstrated at the end of the sprint label Jul 19, 2024
@hannes-ucsc
Copy link
Member Author

For demo, attempt to reproduce.

@achave11-ucsc achave11-ucsc added the demoed [process] Successfully demonstrated to team label Jul 23, 2024
@hannes-ucsc hannes-ucsc added no demo [process] Not to be demonstrated at the end of the sprint and removed no demo [process] Not to be demonstrated at the end of the sprint labels Jul 31, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
+ [priority] High bug [type] A defect preventing use of the system as specified debt [type] A defect incurring continued engineering cost demo [process] To be demonstrated at the end of the sprint demoed [process] Successfully demonstrated to team infra [subject] Project infrastructure like CI/CD, build and deployment scripts orange [process] Done by the Azul team spike:3 [process] Spike estimate of three points
Projects
None yet
Development

No branches or pull requests

5 participants