Skip to content

Request payload logging customization

Smriti Garg requested to merge smriti-426167/log_user_ip_and_username into master

What does this MR do and why?

Solves #426167 (comment 1589358598)

TokensController right now does not have information like remote_ip, username, user_ip logged as part of controller payload. This makes it difficult to debug the issues.

With this MR we are overriding method append_info_to_payload and adding custom information to payload.

This method was already defined in ApplicationController. Every class that extends from ApplicationController had the loggiing available. Since TokensController does not extend from ApplicationController the information was not getting logged.

I extracted the logic to a common concern and same is included in both the controllers for keeping the logic DRY.

How to set up and validate locally

After running the relevant curl command

curl  --request POST https://gdk.test:3443/oauth/token --header "Content-Type: application/json" --data '{"grant_type": "password", "username": "nonexistent", "password": "boom!"}'

Tail tail -f log/development_json.log and observe the controller payload being logged.

CONTROLLER payload after changes. Please observe additional fields like remote_ip and user_agent being logged

{"method":"POST","path":"/oauth/token","format":"*/*","controller":"Oauth::TokensController","action":"create","status":400,"time":"2023-10-16T10:04:16.594Z","params":[{"key":"grant_type","value":"password"},{"key":"username","value":"nonexistent"},{"key":"password","value":"[FILTERED]"},{"key":"token","value":{"grant_type":"password","username":"nonexistent","password":"[FILTERED]"}}],"correlation_id":"01HCVZ309KZRRE2VZNFCR39FVF","remote_ip":"127.0.0.1","ua":"curl/8.1.2","queue_duration_s":0.30895,"redis_calls":11,"redis_duration_s":0.004719,"redis_read_bytes":1700,"redis_write_bytes":575,"redis_cache_calls":2,"redis_cache_duration_s":0.000946,"redis_cache_read_bytes":114,"redis_cache_write_bytes":56,"redis_feature_flag_calls":9,"redis_feature_flag_duration_s":0.003773,"redis_feature_flag_read_bytes":1586,"redis_feature_flag_write_bytes":519,"db_count":3,"db_write_count":0,"db_cached_count":0,"db_replica_count":0,"db_primary_count":3,"db_main_count":3,"db_ci_count":0,"db_main_replica_count":0,"db_ci_replica_count":0,"db_replica_cached_count":0,"db_primary_cached_count":0,"db_main_cached_count":0,"db_ci_cached_count":0,"db_main_replica_cached_count":0,"db_ci_replica_cached_count":0,"db_replica_wal_count":0,"db_primary_wal_count":0,"db_main_wal_count":0,"db_ci_wal_count":0,"db_main_replica_wal_count":0,"db_ci_replica_wal_count":0,"db_replica_wal_cached_count":0,"db_primary_wal_cached_count":0,"db_main_wal_cached_count":0,"db_ci_wal_cached_count":0,"db_main_replica_wal_cached_count":0,"db_ci_replica_wal_cached_count":0,"db_replica_duration_s":0.0,"db_primary_duration_s":0.011,"db_main_duration_s":0.011,"db_ci_duration_s":0.0,"db_main_replica_duration_s":0.0,"db_ci_replica_duration_s":0.0,"cpu_s":0.372655,"pid":12224,"worker_id":"puma_0","rate_limiting_gates":[],"db_duration_s":0.005,"view_duration_s":0.00041,"duration_s":0.12585}

/oauth/authorize

Create Gitlab Application as Oauth User - https://docs.gitlab.com/ee/integration/oauth_provider.html#create-a-user-owned-application

Request an authorization code, observe remote_ip and ua information missing in logs since we are not overriding this part of code from Doorkeeper in our application.

https://gitlab.example.com/oauth/authorize?client_id=APP_ID&redirect_uri=REDIRECT_URI&response_type=code&state=STATE&scope=REQUESTED_SCOPES&code_challenge=CODE_CHALLENGE&code_challenge_method=S256
{"method":"GET","path":"/oauth/authorize","format":"html","controller":"Oauth::AuthorizationsController","action":"new","status":200,"time":"2023-10-16T10:51:33.146Z","params":[{"key":"client_id","value":"1bb84ce07b10ba2f04ff9fbebe8ac97bc34e354569606ba97533f8da108150c9\\"},{"key":"redirect_uri\\","value":"[FILTERED]"},{"key":"response_type\\","value":"code\\"},{"key":"state\\","value":"STATE\\"},{"key":"scope\\","value":"api"}],"redis_calls":17,"redis_allowed_cross_slot_calls":1,"redis_duration_s":0.002971,"redis_read_bytes":2982,"redis_write_bytes":1300,"redis_cache_calls":12,"redis_cache_duration_s":0.002274,"redis_cache_read_bytes":2709,"redis_cache_write_bytes":610,"redis_sessions_calls":3,"redis_sessions_allowed_cross_slot_calls":1,"redis_sessions_duration_s":0.000548,"redis_sessions_read_bytes":273,"redis_sessions_write_bytes":586,"redis_shared_state_calls":2,"redis_shared_state_duration_s":0.000149,"redis_shared_state_write_bytes":104,"db_count":12,"db_write_count":0,"db_cached_count":4,"db_replica_count":0,"db_primary_count":12,"db_main_count":12,"db_ci_count":0,"db_main_replica_count":0,"db_ci_replica_count":0,"db_replica_cached_count":0,"db_primary_cached_count":4,"db_main_cached_count":4,"db_ci_cached_count":0,"db_main_replica_cached_count":0,"db_ci_replica_cached_count":0,"db_replica_wal_count":0,"db_primary_wal_count":0,"db_main_wal_count":0,"db_ci_wal_count":0,"db_main_replica_wal_count":0,"db_ci_replica_wal_count":0,"db_replica_wal_cached_count":0,"db_primary_wal_cached_count":0,"db_main_wal_cached_count":0,"db_ci_wal_cached_count":0,"db_main_replica_wal_cached_count":0,"db_ci_replica_wal_cached_count":0,"db_replica_duration_s":0.0,"db_primary_duration_s":0.016,"db_main_duration_s":0.016,"db_ci_duration_s":0.0,"db_main_replica_duration_s":0.0,"db_ci_replica_duration_s":0.0,"cpu_s":0.22518,"pid":28778,"worker_id":"process_28778","rate_limiting_gates":[],"correlation_id":"01HCW1SJN5WBEM29DBV6S64K2Y","db_duration_s":0.00197,"view_duration_s":0.22162,"duration_s":0.23341}

/oauth/token

Use the authorization code returned in previous command and Create a token after following the instructions here -

parameters = 'client_id=APP_ID&client_secret=APP_SECRET&token=TOKEN'
RestClient.post 'https://gdk.test:3443/oauth/revoke', parameters
{"method":"POST","path":"/oauth/token","format":"*/*","controller":"Oauth::TokensController","action":"create","status":200,"time":"2023-10-16T10:54:37.714Z","params":[{"key":"client_id","value":"1bb84ce07b10ba2f04ff9fbebe8ac97bc34e354569606ba97533f8da108150c9"},{"key":"client_secret","value":"[FILTERED]"},{"key":"code","value":"[FILTERED]"},{"key":"grant_type","value":"authorization_code"},{"key":"redirect_uri","value":"[FILTERED]"}],"correlation_id":"01HCW1Z6YKFVCF0MGNEZXK07JE","remote_ip":"127.0.0.1","ua":"rest-client/2.1.0 (darwin22 arm64) ruby/3.1.4p223","redis_calls":10,"redis_duration_s":0.00232,"redis_read_bytes":1589,"redis_write_bytes":730,"redis_cache_calls":2,"redis_cache_duration_s":0.000423,"redis_cache_read_bytes":2,"redis_cache_write_bytes":218,"redis_feature_flag_calls":8,"redis_feature_flag_duration_s":0.001897,"redis_feature_flag_read_bytes":1587,"redis_feature_flag_write_bytes":512,"db_count":12,"db_write_count":3,"db_cached_count":0,"db_replica_count":0,"db_primary_count":12,"db_main_count":12,"db_ci_count":0,"db_main_replica_count":0,"db_ci_replica_count":0,"db_replica_cached_count":0,"db_primary_cached_count":0,"db_main_cached_count":0,"db_ci_cached_count":0,"db_main_replica_cached_count":0,"db_ci_replica_cached_count":0,"db_replica_wal_count":0,"db_primary_wal_count":0,"db_main_wal_count":0,"db_ci_wal_count":0,"db_main_replica_wal_count":0,"db_ci_replica_wal_count":0,"db_replica_wal_cached_count":0,"db_primary_wal_cached_count":0,"db_main_wal_cached_count":0,"db_ci_wal_cached_count":0,"db_main_replica_wal_cached_count":0,"db_ci_replica_wal_cached_count":0,"db_replica_duration_s":0.0,"db_primary_duration_s":0.021,"db_main_duration_s":0.021,"db_ci_duration_s":0.0,"db_main_replica_duration_s":0.0,"db_ci_replica_duration_s":0.0,"cpu_s":0.169904,"pid":28778,"worker_id":"process_28778","rate_limiting_gates":[],"db_duration_s":0.00712,"view_duration_s":0.00024,"duration_s":0.14482}

/oauth/revoke

To revoke the token, follow the instructions provided in documentation https://docs.gitlab.com/ee/api/oauth2.html#revoke-a-token

Observe the logs

{"method":"POST","path":"/oauth/revoke","format":"*/*","controller":"Oauth::TokensController","action":"revoke","status":200,"time":"2023-10-16T10:35:40.283Z","params":[{"key":"client_id","value":"1bb84ce07b10ba2f04ff9fbebe8ac97bc34e354569606ba97533f8da108150c9"},{"key":"client_secret","value":"[FILTERED]"},{"key":"token","value":"[FILTERED]"}],"correlation_id":"01HCW0WG6QDAD5VFQBCT4ZJ429","remote_ip":"127.0.0.1","ua":"rest-client/2.1.0 (darwin22 arm64) ruby/3.1.4p223","queue_duration_s":0.028257,"redis_calls":9,"redis_duration_s":0.001941,"redis_read_bytes":1700,"redis_write_bytes":561,"redis_cache_calls":1,"redis_cache_duration_s":0.000154,"redis_cache_read_bytes":114,"redis_cache_write_bytes":49,"redis_feature_flag_calls":8,"redis_feature_flag_duration_s":0.001787,"redis_feature_flag_read_bytes":1586,"redis_feature_flag_write_bytes":512,"db_count":5,"db_write_count":0,"db_cached_count":0,"db_replica_count":0,"db_primary_count":5,"db_main_count":5,"db_ci_count":0,"db_main_replica_count":0,"db_ci_replica_count":0,"db_replica_cached_count":0,"db_primary_cached_count":0,"db_main_cached_count":0,"db_ci_cached_count":0,"db_main_replica_cached_count":0,"db_ci_replica_cached_count":0,"db_replica_wal_count":0,"db_primary_wal_count":0,"db_main_wal_count":0,"db_ci_wal_count":0,"db_main_replica_wal_count":0,"db_ci_replica_wal_count":0,"db_replica_wal_cached_count":0,"db_primary_wal_cached_count":0,"db_main_wal_cached_count":0,"db_ci_wal_cached_count":0,"db_main_replica_wal_cached_count":0,"db_ci_replica_wal_cached_count":0,"db_replica_duration_s":0.0,"db_primary_duration_s":0.011,"db_main_duration_s":0.011,"db_ci_duration_s":0.0,"db_main_replica_duration_s":0.0,"db_ci_replica_duration_s":0.0,"cpu_s":0.157661,"pid":14540,"worker_id":"puma_1","rate_limiting_gates":[],"db_duration_s":0.00282,"view_duration_s":0.00017,"duration_s":0.0421}

/oauth/userinfo

This call is handled by Doorkeeper::OpenidConnect::UserInfoController Here as well we can observe the logs do not contain the newly added information to the TokensController payload

{"method":"POST","path":"/oauth/userinfo","format":"*/*","controller":"Doorkeeper::OpenidConnect::UserinfoController","action":"show","status":401,"time":"2023-10-16T11:01:20.022Z","params":[{"key":"client_id","value":"1bb84ce07b10ba2f04ff9fbebe8ac97bc34e354569606ba97533f8da108150c9"},{"key":"client_secret","value":"[FILTERED]"},{"key":"code","value":"[FILTERED]"},{"key":"grant_type","value":"authorization_code"},{"key":"redirect_uri","value":"[FILTERED]"}],"redis_calls":7,"redis_duration_s":0.00105,"redis_read_bytes":1304,"redis_write_bytes":434,"redis_cache_calls":1,"redis_cache_duration_s":0.00013,"redis_cache_read_bytes":113,"redis_cache_write_bytes":49,"redis_feature_flag_calls":6,"redis_feature_flag_duration_s":0.00092,"redis_feature_flag_read_bytes":1191,"redis_feature_flag_write_bytes":385,"db_count":1,"db_write_count":0,"db_cached_count":0,"db_replica_count":0,"db_primary_count":1,"db_main_count":1,"db_ci_count":0,"db_main_replica_count":0,"db_ci_replica_count":0,"db_replica_cached_count":0,"db_primary_cached_count":0,"db_main_cached_count":0,"db_ci_cached_count":0,"db_main_replica_cached_count":0,"db_ci_replica_cached_count":0,"db_replica_wal_count":0,"db_primary_wal_count":0,"db_main_wal_count":0,"db_ci_wal_count":0,"db_main_replica_wal_count":0,"db_ci_replica_wal_count":0,"db_replica_wal_cached_count":0,"db_primary_wal_cached_count":0,"db_main_wal_cached_count":0,"db_ci_wal_cached_count":0,"db_main_replica_wal_cached_count":0,"db_ci_replica_wal_cached_count":0,"db_replica_duration_s":0.0,"db_primary_duration_s":0.004,"db_main_duration_s":0.004,"db_ci_duration_s":0.0,"db_main_replica_duration_s":0.0,"db_ci_replica_duration_s":0.0,"cpu_s":0.101351,"pid":28778,"worker_id":"process_28778","rate_limiting_gates":[],"correlation_id":"01HCW2BFX8QDJE936AYYF8F2J8","db_duration_s":0.0,"view_duration_s":0.0,"duration_s":0.0036}

MR acceptance checklist

This checklist encourages us to confirm any changes have been analyzed to reduce risks in quality, performance, reliability, security, and maintainability.

Edited by Smriti Garg

Merge request reports