feat: replace user identity strings with user IDs - #38775
Conversation
| }) | ||
| log.warning('email %s already exist', email) | ||
| if settings.FEATURES['SQUELCH_PII_IN_LOGS']: | ||
| log.warning('email [REDACTED] already exist') |
There was a problem hiding this comment.
If the logger warning is a necessity to know which user's email is being referred here , then as a suggestion we can use it as:
log.warning(
'email for user_id=%s already exists',
user.id,
)
Just a suggestion upto you to decide, can we use this or the current change is enough?
Other places also may need some attention to see if user id can be used in the logger, so take a look at those also.
| except SMTPException: | ||
| log.warning("Failure sending 'pending state' e-mail for %s to %s", user.email, studio_request_email) | ||
| if settings.FEATURES['SQUELCH_PII_IN_LOGS']: | ||
| log.warning("Failure sending 'pending state' e-mail for user ID %s to [REDACTED]", user.id) |
There was a problem hiding this comment.
- I'd keep away from using "REDACTED". That's a nice automated solution if we were trying to have Datadog redact based on regex, or something. But when updating code, we have the ability to spell things out in english in the message.
- Also, I was wondering what
studio_request_emailwas and how we'd spell that out. It turns out it is just a system email coming from a setting, so there is no reason to redact that email in the first place. Something this brings up, if we choose to not redact an email (something that looks like PII), what's a good way to annotate that? For now, you could just add a comment like:
# studio_request_email is a system email address, not PII, which can safely be logged.
robrap
left a comment
There was a problem hiding this comment.
I didn't finish, so I might have missed other things, but I'd rather go through after clean-up of the types of issues I already pointed out. Thank you.
| user.email_user(subject, message, studio_request_email) | ||
| except: # pylint: disable=bare-except | ||
| log.warning("Unable to send course creator status e-mail to %s", user.email) | ||
| except: # lint-amnesty, pylint: disable=bare-except |
There was a problem hiding this comment.
As discussed, lint-amnesty should never be add manually. It was used in the past, and means that the disable pragma was necessary to make pylint happy at one point in time, but could possibly be fixed. If the disable pragma is what is wanted permanently, then lint-amnesty should actually be removed. There is an OEP around this that was since deleted, but this should be documented somewhere at some point. Maybe I'll open a ticket.
There was a problem hiding this comment.
@ttak-apphelix: I was going to document something, but then I realized there are only 3 usages left: https://github.com/search?q=repo%3Aopenedx%2Fopenedx-platform%20lint-amnesty&type=code. I imagine there were zero at some point, but they returned via copy/paste somehow.
Was there a doc or something you saw that had you add #lint-amnesty? I wonder if there is something we can correct, and if we can help get rid of the remaining usages, even if on a separate PR?
There was a problem hiding this comment.
removed lint-amnesty from here. Will create a separate PR to remove lint-amnesty across the project.
| if settings.FEATURES['SQUELCH_PII_IN_LOGS']: | ||
| log.warning( | ||
| "User %s failed to enroll in course %s because enrollment is closed (can_upgrade=%s).", | ||
| user.id, | ||
| str(course_key), | ||
| can_upgrade, | ||
| ) | ||
| else: | ||
| log.warning( | ||
| "User %s failed to enroll in course %s because enrollment is closed (can_upgrade=%s).", | ||
| user.username, | ||
| str(course_key), | ||
| can_upgrade, | ||
| ) |
There was a problem hiding this comment.
I'm not sure how many places this would apply, but the following has a lot less redundancy, and thus changes to the log message are more likely to remain consistent.
| if settings.FEATURES['SQUELCH_PII_IN_LOGS']: | |
| log.warning( | |
| "User %s failed to enroll in course %s because enrollment is closed (can_upgrade=%s).", | |
| user.id, | |
| str(course_key), | |
| can_upgrade, | |
| ) | |
| else: | |
| log.warning( | |
| "User %s failed to enroll in course %s because enrollment is closed (can_upgrade=%s).", | |
| user.username, | |
| str(course_key), | |
| can_upgrade, | |
| ) | |
| if settings.FEATURES['SQUELCH_PII_IN_LOGS']: | |
| user_identifier_for_log = user.id | |
| else: | |
| user_identifier_for_log = user.username | |
| log.warning( | |
| "User %s failed to enroll in course %s because enrollment is closed (can_upgrade=%s).", | |
| user_identifier_for_log, | |
| str(course_key), | |
| can_upgrade, | |
| ) |
There was a problem hiding this comment.
Updated across the PR
| try: | ||
| ace.send(msg) | ||
| except Exception: # pylint: disable=broad-except | ||
| log.warning('Unable to send confirmation email to old address', exc_info=True) |
There was a problem hiding this comment.
- Why did this need to change? It wasn't including any user arguments?
- Note: If you remove this, you could probably remove the
# pylint: disable=too-many-statementsthat was added earlier as well.
- Are there other cases like this?
There was a problem hiding this comment.
- My bad, reverted the changes
- Removed # pylint: disable=too-many-statements
- NO
| except User.DoesNotExist: | ||
| log.exception(f'The user "{username}" does not exist.') | ||
| if settings.FEATURES['SQUELCH_PII_IN_LOGS']: | ||
| log.exception('A user does not exist for bulk retirement.') |
There was a problem hiding this comment.
One idea is to start the loop with for index, username in enumerate(usernames_to_retire): (note: this is untested code), and update the message to something like:
| log.exception('A user does not exist for bulk retirement.') | |
| log.exception('Bulk retirement user at index %s does not exist.', index) |
You could possibly add the index to the INFO log for consistency as well.
Alternatively, since we have all the other INFO logs, we could just use username_in_log='[REDACTED]', and someone could probably figure out which inputs weren't found.
| if not user.has_usable_password(): | ||
| log.info(f'Goal Reminder User is disabled {user.username} course {goal.course_key}') | ||
| if settings.FEATURES['SQUELCH_PII_IN_LOGS']: | ||
| log.info(f'Goal Reminder User is disabled user ID {user.id} course {goal.course_key}') |
There was a problem hiding this comment.
Alternative example with less redundancy:
| log.info(f'Goal Reminder User is disabled user ID {user.id} course {goal.course_key}') | |
| log.info('Goal Reminder User is disabled user %s course %s', user_identifier_for_log, goal.course_key) |
| if not is_course_passed(student, course): | ||
| log.info("User %s has not passed the course: %s", student.username, course_id) | ||
| if settings.FEATURES['SQUELCH_PII_IN_LOGS']: | ||
| log.info("User ID %s has not passed the course: %s", student.id, course_id) |
There was a problem hiding this comment.
Another example...
| log.info("User ID %s has not passed the course: %s", student.id, course_id) | |
| log.info("User %s has not passed the course: %s", user_identifier_for_log, course_id) |
There was a problem hiding this comment.
updated. Also updated at other places
| user = goal.user | ||
| if not user.has_usable_password(): | ||
| log.info(f'Goal Reminder User is disabled {user.username} course {goal.course_key}') | ||
| user_identifier_for_log = f"ID {user.id}" if getattr(settings, 'SQUELCH_PII_IN_LOGS', False) else user.username |
There was a problem hiding this comment.
| user_identifier_for_log = f"ID {user.id}" if getattr(settings, 'SQUELCH_PII_IN_LOGS', False) else user.username | |
| user_identifier_for_log = user.id if getattr(settings, 'SQUELCH_PII_IN_LOGS', False) else user.username |
| except User.DoesNotExist: | ||
| log.exception(f'The user "{username}" does not exist.') | ||
| if getattr(settings, 'SQUELCH_PII_IN_LOGS', False): | ||
| log.exception('Bulk retirement user at index %s does not exist.', index) |
There was a problem hiding this comment.
This is one place where adding "index" into the string may help differentiate, because index is non-obvious (unlike user id).
| log.exception('Bulk retirement user at index %s does not exist.', index) | |
| user_identifier_for_log = f"index {index}" if getattr(settings, 'SQUELCH_PII_IN_LOGS', False) else username | |
| log.exception('Bulk retirement user %s does not exist.', user_identifier_for_log) |
| f"user ID {user.id}" if getattr(settings, 'SQUELCH_PII_IN_LOGS', False) | ||
| else f"username '{username}' and email '{email}'" |
There was a problem hiding this comment.
This is an example where it is fine as-is, if we want different sets of values to represent the user.
| if getattr(settings, 'SQUELCH_PII_IN_LOGS', False): | ||
| log.error("Could not parse task input as valid json; task input is redacted") | ||
| else: | ||
| log.error("Could not parse task input as valid json; task input: %s", email_task.task_input) |
There was a problem hiding this comment.
I don't think I'd even use SQUELCH_PII_IN_LOGS here.
- I'm not sure what
CourseEmail, and whether it is even PII. - If something can't parse and we can't see what it was that couldn't parse, that would probably make it a lot harder to debug.
So, I'd err toward just leave this as is.
Do not do the following, but I'm adding it here to make a different point:
- I said in an earlier comment that text like "... task input is redacted" is very misleading, because it makes it seem like we redacted it in a database or something, not in the log message itself.
- If we were to proceed with this squelch, I'd possibly do something like the following:
email_task_for_log = "[REDACTED]" if getattr(settings, 'SQUELCH_PII_IN_LOGS', False) else email_task.task_input
log.error("Could not parse email task input as valid json; email task input: %s", email_task_for_log)
Again, I don't think this code should be used, but I want you to see the example to understand how I'd redact something in the log, if we ever chose to redact, which is unlikely.
There was a problem hiding this comment.
High-level feedback:
- I'm not certain how important this work is, so let's fix the most obvious issues, and possible skip things that are more debatable.
- This is linked to @Akanshu-2u's work on linting. Let's ensure that that linter is only finding major issues, or isn't used at all.
Thanks. - Also, I gave a number of example of patterns. Many of these I had given already, but it isn't what I am seeing. I'm not going to comment on every one, but I want the patterns to be reviewed for each case.
| email_for_log = "a redacted email" if getattr(settings, 'SQUELCH_PII_IN_LOGS', False) else f"email {email}" | ||
| log.error("Tried to enroll %s into course %s, but user not found", email_for_log, course_id) |
There was a problem hiding this comment.
The past comment about redacting in a message was here: #38775 (comment), and related to this code. Here is how I would update this code:
| email_for_log = "a redacted email" if getattr(settings, 'SQUELCH_PII_IN_LOGS', False) else f"email {email}" | |
| log.error("Tried to enroll %s into course %s, but user not found", email_for_log, course_id) | |
| email_for_log = "[REDACTED]" if getattr(settings, 'SQUELCH_PII_IN_LOGS', False) else email | |
| log.error("Tried to enroll email %s into course %s, but user not found", email_for_log, course_id) |
Note the difference between these log messages:
Tried to enroll email [REDACTED] into course ...
and
Tried to enroll a redacted email into course ...
The latter sounds like you know the email was redacted (retired), but really it was just an email with no matching user.
Update application logging to prevent exposure of customer identity information in logs when SQUELCH_PII_IN_LOGS is enabled. Log records that currently include usernames, email addresses, or other user-identifying strings should instead use non-PII identifiers (for example, numeric user IDs) where appropriate.
This change should be applied consistently across the platform to reduce PII exposure in logs
Private JIRA ticket:
https://2u-internal.atlassian.net/browse/BOMS-641