HTTP Requests/Responses Logger

[norbertbede]

Motivation
We worked on a project where iDempiere data was transformed by Apache Camel to a REST API developed by an eCommerce software vendor.
The vendor had a lot of troubles and we got an unstable API - non-measurable performance and non-auditable request/responses. We were forced in middleware to route the rest req/responses, times, and endpoints to a logging system for additional processing.

This experience and topic motivated us to implement an out-of-box HTTP request/response logger in REST API.

Solution POC
The functionality logs each HTTP request and response. We mark each request that comes from an API gets a request identifier (UUID). The purpose of the request identifier is to allow referring to any request/response for further analysis (similar like AWS services API's). We decide to use structured JSON (includes: request details, body, HTTP status code (2xx, 4xx, 5xx), response time in milliseconds, and rest endpoint).

Logging Output:
HTTP log is stored to the filesystem at IDEMPIERE_HOME/logs/rest-yyyy-mm-dd-1.log.

Advanced log Processing
Logs can be easily processed/routed by logging software collectors/agents and transfer to a centralized log analyzer like elasti.co (filebeat, journalbeat, metricsbeat)

We assume auth-token can be used in the index for differentiating multiple API's eg. per tenant. (we are using OAuth client id in our private implementation)

[d-ruiz]

Hi guys,

Sorry for the delay, couldn't review the change before.

Could you please tell me how can I test this? Is it just about pulling the change and every time I run a request I'll get a file in IDEMPIERE_HOME/logs/rest-yyyy-mm-dd-1.log?

One more question, why is this a POC solution? what's missing?

Thanks a lot!
Diego Ruiz

[igorpojzl]

For Logging we are using Log4j2. I created initial configuration in com.trekglobal.idempiere.rest.api/log4j2.xml.
It can be changed. Configuration Documentation is here: http://logging.apache.org/log4j/2.x/manual/configuration.html

[norbertbede]

POC is because logger running but Requests body and response not included, coming soon.

[norbertbede]

hi,

we are almost there. #6
you can test and merge it. the format can be converted later depends on requirement.

{ "instant":{ "epochSecond":1600436486, "nanoOfSecond":275487000 }, "thread":"qtp553244494-955", "level":"INFO", "loggerName":"com.trekglobal.idempiere.rest.api.v1.filter.ResponseLoggingFilter", "message":{ "duration":167, "id":"4e39b3c8-19a5-46ea-b90c-46df207a77e3", "method":"GET", "requestHeaders":{ "Authorization":[ "Bearer eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJzdWIiOiIxMTMxNTA0IiwiTV9XYXJlaG91c2VfSUQiOjEwMDAxMzAsIkFEX1VzZXJfSUQiOjExUiOiJza19TSyIsInVwbiI6IjExMzE1MDQiLCJuYmYiOjE2MDA0MzY0ODMsIkFEX09yZ19JRCI6MCwiQURfQ2xpZW50X0lEIjoxMDAwMDE0LCJleHAiOjE2MDA0MzgyODMsImlhdCI6MTYwMDQzNjQ4MywianRpIjoiMWRjNDc5YTEtYzRkYS00MjkwLThkNDMtZDZiZjhmNzA4MzlkIn0.3RgTTaUHygzYaecP89JcnUCtS4ivN-cXhfi9NhEx8AI" ], "Accept":[ "application/json" ], "Cache-Control":[ "no-cache" ], "User-Agent":[ "PostmanRuntime/7.26.5" ], "Connection":[ "close" ], "X-Forwarded-For":[ "94.228.89.101" ], "Postman-Token":[ "8cf55ca2-5db6-45d4-958b-cfacfcee1d13" ], "Host":[ "test.cloudempiere.com" ], "Accept-Encoding":[ "gzip, deflate, br" ], "Content-Type":[ "application/json" ] }, "responseBody":"[{\"id\":1000067,\"uid\":\"e3eedc88-6a7f-44fa-9359-da12c240e26b\",\"createdBy\":{\"propertyLabel\":\"Vytvoril\",\"id\":1000579,\"identifier\":\"Norbert Bede\",\"model-name\":\"ad_user\"},\"AD_Org_ID\":{\"propertyLabel\":\"Organizácia\",\"id\":0,\"identifier\":\"*\",\"model-name\":\"ad_org\"},\"updatedBy\":{\"propertyLabel\":\"Aktualizoval\",\"id\":1000579,\"identifier\":\"Norbert Bede\",\"model-name\":\"ad_user\"},\"created\":\"2019-11-07T21:34:42Z\",\"description\":\"<mdb-icon fas icon=\\\"comment-alt\\\"></mdb-icon>\",\"name\":\"Incident\",\"updated\":\"2020-09-04T09:14:27Z\",\"isActive\":true,\"AD_Client_ID\":{\"propertyLabel\":\"Klient\",\"id\":1000014,\"identifier\":\"MULTIMAGE s.r.o.\",\"model-name\":\"ad_client\"},\"isDefault\":true,\"isSelfService\":true,\"dueDateTolerance\":7,\"isEMailWhenOverdue\":false,\"isEMailWhenDue\":false,\"isInvoiced\":false,\"autoDueDateDays\":0,\"confidentialType\":{\"propertyLabel\":\"Typ Dôvernosti\",\"id\":\"C\",\"identifier\":\"Dôverná, Partner\",\"model-name\":\"ad_ref_list\"},\"isAutoChangeRequest\":false,\"isConfidentialInfo\":false,\"R_StatusCategory_ID\":{\"propertyLabel\":\"Kategória Stavov\",\"id\":1000023,\"identifier\":\"HelpDesk\",\"model-name\":\"r_statuscategory\"},\"isIndexed\":false,\"R_Category_ID\":{\"propertyLabel\":\"Kategória\",\"id\":1000040,\"identifier\":\"Helpeskove\",\"model-name\":\"r_category\"},\"prefix\":\"INC\",\"model-name\":\"r_requesttype\"},{\"id\":1000070,\"uid\":\"8d553c17-9eb2-402a-8e3d-9b00f9a33a0d\",\"createdBy\":{\"propertyLabel\":\"Vytvoril\",\"id\":1000579,\"identifier\":\"Norbert Bede\",\"model-name\":\"ad_user\"},\"AD_Org_ID\":{\"propertyLabel\":\"Organizácia\",\"id\":0,\"identifier\":\"*\",\"model-name\":\"ad_org\"},\"updatedBy\":{\"propertyLabel\":\"Aktualizoval\",\"id\":1000579,\"identifier\":\"Norbert Bede\",\"model-name\":\"ad_user\"},\"created\":\"2019-11-16T11:57:01Z\",\"description\":\"<mdb-icon fas icon=\\\"question\\\"></mdb-icon>\",\"name\":\"Otázka\",\"updated\":\"2020-09-04T09:15:35Z\",\"isActive\":true,\"AD_Client_ID\":{\"propertyLabel\":\"Klient\",\"id\":1000014,\"identifier\":\"MULTIMAGE s.r.o.\",\"model-name\":\"ad_client\"},\"isDefault\":false,\"isSelfService\":true,\"dueDateTolerance\":7,\"isEMailWhenOverdue\":false,\"isEMailWhenDue\":false,\"isInvoiced\":false,\"autoDueDateDays\":0,\"confidentialType\":{\"propertyLabel\":\"Typ Dôvernosti\",\"id\":\"C\",\"identifier\":\"Dôverná, Partner\",\"model-name\":\"ad_ref_list\"},\"isAutoChangeRequest\":false,\"isConfidentialInfo\":false,\"R_StatusCategory_ID\":{\"propertyLabel\":\"Kategória Stavov\",\"id\":1000023,\"identifier\":\"HelpDesk\",\"model-name\":\"r_statuscategory\"},\"isIndexed\":false,\"R_Category_ID\":{\"propertyLabel\":\"Kategória\",\"id\":1000040,\"identifier\":\"Helpeskove\",\"model-name\":\"r_category\"},\"model-name\":\"r_requesttype\"},{\"id\":1000068,\"uid\":\"617fabc7-a88f-457a-8970-d4ede05620e4\",\"createdBy\":{\"propertyLabel\":\"Vytvoril\",\"id\":1000579,\"identifier\":\"Norbert Bede\",\"model-name\":\"ad_user\"},\"AD_Org_ID\":{\"propertyLabel\":\"Organizácia\",\"id\":0,\"identifier\":\"*\",\"model-name\":\"ad_org\"},\"updatedBy\":{\"propertyLabel\":\"Aktualizoval\",\"id\":1000579,\"identifier\":\"Norbert Bede\",\"model-name\":\"ad_user\"},\"created\":\"2019-11-07T21:34:55Z\",\"description\":\"<mdb-icon fas icon=\\\"newspaper\\\"></mdb-icon>\",\"name\":\"Nová Funkcionalita\",\"updated\":\"2020-09-04T09:15:43Z\",\"isActive\":true,\"AD_Client_ID\":{\"propertyLabel\":\"Klient\",\"id\":1000014,\"identifier\":\"MULTIMAGE s.r.o.\",\"model-name\":\"ad_client\"},\"isDefault\":false,\"isSelfService\":true,\"dueDateTolerance\":7,\"isEMailWhenOverdue\":false,\"isEMailWhenDue\":false,\"isInvoiced\":false,\"autoDueDateDays\":0,\"confidentialType\":{\"propertyLabel\":\"Typ Dôvernosti\",\"id\":\"C\",\"identifier\":\"Dôverná, Partner\",\"model-name\":\"ad_ref_list\"},\"isAutoChangeRequest\":false,\"isConfidentialInfo\":false,\"R_StatusCategory_ID\":{\"propertyLabel\":\"Kategória Stavov\",\"id\":1000023,\"identifier\":\"HelpDesk\",\"model-name\":\"r_statuscategory\"},\"isIndexed\":false,\"R_Category_ID\":{\"propertyLabel\":\"Kategória\",\"id\":1000040,\"identifier\":\"Helpeskove\",\"model-name\":\"r_category\"},\"prefix\":\"FR\",\"model-name\":\"r_requesttype\"},{\"id\":1000071,\"uid\":\"f9e12d21-79ac-4f9c-8b51-81489bed71c4\",\"createdBy\":{\"propertyLabel\":\"Vytvoril\",\"id\":1000579,\"identifier\":\"Norbert Bede\",\"model-name\":\"ad_user\"},\"AD_Org_ID\":{\"propertyLabel\":\"Organizácia\",\"id\":0,\"identifier\":\"*\",\"model-name\":\"ad_org\"},\"updatedBy\":{\"propertyLabel\":\"Aktualizoval\",\"id\":1000579,\"identifier\":\"Norbert Bede\",\"model-name\":\"ad_user\"},\"created\":\"2019-11-16T11:59:16Z\",\"description\":\"<mdb-icon fas icon=\\\"drum\\\"></mdb-icon>\",\"name\":\"Zmena\",\"updated\":\"2020-09-04T09:16:28Z\",\"isActive\":true,\"AD_Client_ID\":{\"propertyLabel\":\"Klient\",\"id\":1000014,\"identifier\":\"MULTIMAGE s.r.o.\",\"model-name\":\"ad_client\"},\"isDefault\":false,\"isSelfService\":true,\"dueDateTolerance\":7,\"isEMailWhenOverdue\":false,\"isEMailWhenDue\":false,\"isInvoiced\":false,\"autoDueDateDays\":0,\"confidentialType\":{\"propertyLabel\":\"Typ Dôvernosti\",\"id\":\"C\",\"identifier\":\"Dôverná, Partner\",\"model-name\":\"ad_ref_list\"},\"isAutoChangeRequest\":false,\"isConfidentialInfo\":false,\"R_StatusCategory_ID\":{\"propertyLabel\":\"Kategória Stavov\",\"id\":1000023,\"identifier\":\"HelpDesk\",\"model-name\":\"r_statuscategory\"},\"isIndexed\":false,\"headerColor\":\"#f4ec0b\",\"R_Category_ID\":{\"propertyLabel\":\"Kategória\",\"id\":1000040,\"identifier\":\"Helpeskove\",\"model-name\":\"r_category\"},\"model-name\":\"r_requesttype\"},{\"id\":1000073,\"uid\":\"88966964-d40c-4394-a65d-c9bb021b7c16\",\"createdBy\":{\"propertyLabel\":\"Vytvoril\",\"id\":1000579,\"identifier\":\"Norbert Bede\",\"model-name\":\"ad_user\"},\"AD_Org_ID\":{\"propertyLabel\":\"Organizácia\",\"id\":0,\"identifier\":\"*\",\"model-name\":\"ad_org\"},\"updatedBy\":{\"propertyLabel\":\"Aktualizoval\",\"id\":1000579,\"identifier\":\"Norbert Bede\",\"model-name\":\"ad_user\"},\"created\":\"2020-05-24T12:26:41Z\",\"description\":\"<mdb-icon fas icon=\\\"bug\\\"></mdb-icon>\",\"name\":\"Bug\",\"updated\":\"2020-09-04T09:16:45Z\",\"isActive\":true,\"AD_Client_ID\":{\"propertyLabel\":\"Klient\",\"id\":1000014,\"identifier\":\"MULTIMAGE s.r.o.\",\"model-name\":\"ad_client\"},\"isDefault\":false,\"isSelfService\":true,\"dueDateTolerance\":7,\"isEMailWhenOverdue\":false,\"isEMailWhenDue\":false,\"isInvoiced\":false,\"autoDueDateDays\":0,\"confidentialType\":{\"propertyLabel\":\"Typ Dôvernosti\",\"id\":\"C\",\"identifier\":\"Dôverná, Partner\",\"model-name\":\"ad_ref_list\"},\"isAutoChangeRequest\":false,\"isConfidentialInfo\":false,\"R_StatusCategory_ID\":{\"propertyLabel\":\"Kategória Stavov\",\"id\":1000023,\"identifier\":\"HelpDesk\",\"model-name\":\"r_statuscategory\"},\"isIndexed\":false,\"headerColor\":\"#f70202\",\"contentColor\":\"#ffbc05\",\"R_Category_ID\":{\"propertyLabel\":\"Kategória\",\"id\":1000041,\"identifier\":\"Development\",\"model-name\":\"r_category\"},\"model-name\":\"r_requesttype\"}]", "responseHeaders":{ "X-Page-Count":[ 1 ], "X-Page-Size":[ 100 ], "X-Page-Number":[ 1 ], "X-Row-Count":[ 5 ], "Content-Type":[ { "type":"application", "subtype":"json", "quality":1000, "wildcardType":false, "wildcardSubtype":false } ], "X-Request-ID":[ "4e39b3c8-19a5-46ea-b90c-46df207a77e3" ] }, "status":200, "time":"2020.09.18 15:41:26", "uri":"http://test.cloudempiere.com/api/v1/models/r_requesttype" }, "endOfBatch":false, "loggerFqcn":"org.apache.logging.log4j.spi.AbstractLogger", "threadId":955, "threadPriority":5 }

[d-ruiz]

Merged the pull request.

Please let me know if we can close this pull request or if there's something still pending.

[d-ruiz]

Hi @norbertbede / @igorpojzl,

I just checked again the log files, and I had to revert the commits.

There's a big security issue in this implementation.

The log file is saving the password plainly in the requestBody of the first POST call (see the attached file for reference).

These loggers should not save any sensitive data in the log files, which includes passwords, credit card data, email passwords, etc ...

Please go ahead and create the pull request again addressing this issue.

Best regards,
Diego Ruiz

[norbertbede]

hi.

yes, it is not the best, however, the log is totally inside the firewall.
what we can:

• exclude auth API plain passwords - but email is important to identify the user
• all fields has isSecureContent=¨Y¨

if any else we need specify from the experience the exact list
Need help on this - to identify use cases.

Norbert

[d-ruiz]

@norbertbede,

In the response body this sensitive information is hidden, Heng Sin wrote that ->
if (column.isSecure() || column.isEncrypted()) don't add it.

The password that is being exposed is on the request header, so there must be some logic in the RequestLogger that you guys wrote to not write those values on the plain file or at least replace them with *.

What needs to be hidden, varies according to countries and industries, you can have:

• payment card industry (PCI) compliance
• personally identifiable information (PII) compliance
• HIPAA Compliance
  and so on ....

If you have Nginx, for example, the logs might be store in Nginx. And this is about compliant with the law to avoid legal issues, it doesn't matter in that case if the info is behind a firewall, the laws state specifically that ceratin info should not be logged.

You can read more about it here: https://medium.com/ibm-garage/pci-and-pii-compliance-when-logging-data-in-digital-transformation-projects-7739bab159a6

best regards,
Diego Ruiz

[CarlosRuiz-globalqss]

xref -> https://mattermost.idempiere.org/idempiere/pl/jphefce15frb5e6ecbe6gf365a

this maybe can be closed? it seems is better to delegate this task to a gateway API

@d-ruiz? @norbertbede?