diff --git a/src/main/java/uk/ac/cam/cl/dtg/segue/api/managers/ExternalAccountManager.java b/src/main/java/uk/ac/cam/cl/dtg/segue/api/managers/ExternalAccountManager.java index b0af27a09f..049a3bd194 100644 --- a/src/main/java/uk/ac/cam/cl/dtg/segue/api/managers/ExternalAccountManager.java +++ b/src/main/java/uk/ac/cam/cl/dtg/segue/api/managers/ExternalAccountManager.java @@ -19,7 +19,11 @@ import com.mailjet.client.errors.MailjetClientCommunicationException; import com.mailjet.client.errors.MailjetException; import com.mailjet.client.errors.MailjetRateLimitException; +import java.io.PrintWriter; +import java.io.StringWriter; import java.util.List; + +import org.json.JSONException; import org.json.JSONObject; import org.slf4j.Logger; import org.slf4j.LoggerFactory; @@ -58,111 +62,463 @@ public ExternalAccountManager(final MailJetApiClientWrapper mailjetApi, final IE */ @Override public synchronized void synchroniseChangedUsers() throws ExternalAccountSynchronisationException { + long startTime = System.currentTimeMillis(); + log.info("MAILJET - === Starting Mailjet user synchronisation ==="); + int totalUsersProcessed = 0; + int successfulSyncs = 0; + int failedSyncs = 0; + int skippedUsers = 0; + try { List userRecordsToUpdate = database.getRecentlyChangedRecords(); + log.info("MAILJET - Found {} users requiring synchronisation", userRecordsToUpdate.size()); for (UserExternalAccountChanges userRecord : userRecordsToUpdate) { - + totalUsersProcessed++; Long userId = userRecord.getUserId(); - log.debug(String.format("Processing user: %s", userId)); + String accountEmail = userRecord.getAccountEmail(); + + // Rate limiting: 2 second delay between each user + if (totalUsersProcessed > 1) { + try { + Thread.sleep(2000); // 2 seconds between users + } catch (InterruptedException e) { + Thread.currentThread().interrupt(); + log.warn("MAILJET - Thread interrupted during rate limit delay"); + } + } + + // Additional delay every 100 users to avoid rate limits + if (totalUsersProcessed % 100 == 0) { + try { + log.info("MAILJET - Processed {} users, pausing 10 seconds to avoid rate limits", totalUsersProcessed); + Thread.sleep(10000); // 10 seconds every 100 users + } catch (InterruptedException e) { + Thread.currentThread().interrupt(); + log.warn("MAILJET - Thread interrupted during extended rate limit delay"); + } + } + + log.debug("MAILJET - [User {}] Starting sync for email: {}", userId, sanitiseEmailForLogging(accountEmail)); + log.debug("MAILJET - [User {}] Details: deleted={}, emailStatus={}, mailjetId={}, allowsNews={}, allowsEvents={}, role={}, stage={}", + userId, + userRecord.isDeleted(), + userRecord.getEmailVerificationStatus(), + userRecord.getProviderUserId(), + userRecord.allowsNewsEmails(), + userRecord.allowsEventsEmails(), + userRecord.getRole(), + userRecord.getStage()); + try { + boolean syncSuccess = processSingleUser(userRecord); - String accountEmail = userRecord.getAccountEmail(); - boolean accountEmailDeliveryFailed = - EmailVerificationStatus.DELIVERY_FAILED.equals(userRecord.getEmailVerificationStatus()); - String mailjetId = userRecord.getProviderUserId(); - JSONObject mailjetDetails; - - if (null != mailjetId) { - // If there is a "mailjet_id", get the account from MailJet. - mailjetDetails = mailjetApi.getAccountByIdOrEmail(mailjetId); - if (userRecord.isDeleted()) { - // Case: deleted from Isaac but still on MailJet: - // Expect: "deleted" but non-null "mailjet_id" - // Action: GDPR deletion, null out MailJet ID?, update provider_last_updated - log.debug("Case: deletion."); - deleteUserFromMailJet(mailjetId, userRecord); - } else if (accountEmailDeliveryFailed) { - // Case: DELIVERY_FAILED but already on MailJet - // Expect: DELIVERY_FAILED, but non-null "mailjet_id" - // Action: same as deletion? Or just remove from lists for now? - log.debug("Case: delivery failed."); - mailjetApi.updateUserSubscriptions(mailjetId, MailJetSubscriptionAction.REMOVE, - MailJetSubscriptionAction.REMOVE); - } else if (!accountEmail.toLowerCase().equals(mailjetDetails.getString("Email"))) { - // Case: account email change: - // Expect: non-null "mailjet_id", email in MailJet != email in database - // Action: delete old email, add new user for new email - log.debug("Case: account email change."); - mailjetApi.permanentlyDeleteAccountById(mailjetId); - mailjetId = mailjetApi.addNewUserOrGetUserIfExists(accountEmail); - updateUserOnMailJet(mailjetId, userRecord); - } else { - // Case: changed details/preferences: - // Expect: not deleted, not DELIVERY_FAILED - // Action: update details, update subscriptions, update provider_last_updated - log.debug("Case: generic preferences update."); - updateUserOnMailJet(mailjetId, userRecord); - } + if (syncSuccess) { + successfulSyncs++; + log.info("MAILJET - [User {}] Successfully synced to Mailjet", userId); } else { - if (!accountEmailDeliveryFailed && !userRecord.isDeleted()) { - // Case: new to Isaac, not on MailJet: - // Expect: null "mailjet_id", not DELIVERY_FAILED, not deleted - // Action: create MailJet ID, update details, update subscriptions, update provider_last_updated - // This will upload even users who are not subscribed to emails. - log.debug("Case: new to Isaac/not yet on MailJet"); - mailjetId = mailjetApi.addNewUserOrGetUserIfExists(accountEmail); - updateUserOnMailJet(mailjetId, userRecord); - } else { - // Case: not on MailJet, do not upload to Mailjet: - // Expect: either invalid email, deleted, or not subscribed at all so don't upload. - log.debug("Case: invalid/incorrect/already-unsubscribed user to skip."); - database.updateExternalAccount(userId, null); - } + skippedUsers++; + log.debug("MAILJET - [User {}] Skipped (invalid/deleted/unsubscribed user)", userId); } - // Iff action done successfully, update the provider_last_updated time: - log.debug("Update provider_last_updated."); - database.updateProviderLastUpdated(userId); } catch (SegueDatabaseException e) { - log.error(String.format("Error storing record of MailJet update to user (%s)!", userId)); + failedSyncs++; + log.error("MAILJET - [User {}] Database error during sync - will retry on next run: {}", userId, e.getMessage()); + // Don't update provider_last_updated so it will be retried + } catch (MailjetClientCommunicationException e) { - log.error("Failed to talk to MailJet!"); + failedSyncs++; + log.error("MAILJET - [User {}] Failed to communicate with Mailjet API: {}", userId, e.getMessage()); throw new ExternalAccountSynchronisationException("Failed to successfully connect to MailJet!"); + } catch (MailjetRateLimitException e) { - log.warn("MailJet rate limiting!"); + failedSyncs++; + log.warn("MAILJET - [User {}] Hit Mailjet rate limit - stopping sync", userId); throw new ExternalAccountSynchronisationException("MailJet API rate limits exceeded!"); + } catch (MailjetException e) { - log.error(e.getMessage()); - throw new ExternalAccountSynchronisationException(e.getMessage()); + failedSyncs++; + log.error("MAILJET - [User {}] Mailjet API error: {} - {}", userId, e.getClass().getSimpleName(), e.getMessage()); + // Log stack trace at debug level to avoid flooding logs + log.debug("MAILJET - [User {}] Full stack trace:", userId, e); + // Don't throw - continue processing other users + + } catch (Exception e) { + failedSyncs++; + log.error("MAILJET - [User {}] Unexpected error: {} - {}", userId, e.getClass().getSimpleName(), e.getMessage()); + log.debug("MAILJET - [User {}] Full stack trace:", userId, e); + // Continue processing other users } } + } catch (SegueDatabaseException e) { - log.error("Database error whilst collecting users whose details have changed!", e); + log.error("MAILJET - Database error whilst collecting users: {}", e.getMessage(), e); + throw new ExternalAccountSynchronisationException("Database error during user collection"); + } + + log.info("MAILJET - === Mailjet synchronisation complete ==="); + log.info("MAILJET - Total users processed: {}", totalUsersProcessed); + log.info("MAILJET - Successful syncs: {}", successfulSyncs); + log.info("MAILJET - Failed syncs: {}", failedSyncs); + log.info("MAILJET - Skipped users: {}", skippedUsers); + + long duration = (System.currentTimeMillis() - startTime) / 1000; + log.info("MAILJET - Sync duration: {} seconds ({} minutes)", duration, duration / 60); + } + + /** + * Process a single user synchronisation. + * + * @param userRecord the user record to process + * @return true if sync succeeded, false if user was skipped + * @throws SegueDatabaseException if database operations fail + * @throws MailjetException if Mailjet API calls fail + */ + private boolean processSingleUser(UserExternalAccountChanges userRecord) + throws SegueDatabaseException, MailjetException { + + Long userId = userRecord.getUserId(); + String accountEmail = userRecord.getAccountEmail(); + boolean accountEmailDeliveryFailed = + EmailVerificationStatus.DELIVERY_FAILED.equals(userRecord.getEmailVerificationStatus()); + String mailjetId = userRecord.getProviderUserId(); + + // Validate user data before attempting sync + if (!validateUserData(userRecord)) { + log.warn("MAILJET - [User {}] Skipping sync due to invalid user data", userId); + // Still update provider_last_updated to prevent repeated attempts + database.updateProviderLastUpdated(userId); + return false; + } + + // Check if user should be synced to Mailjet at all + // Skip users who are not subscribed to any emails and don't already exist in Mailjet + if (mailjetId == null && !shouldSyncToMailjet(userRecord)) { + log.debug("MAILJET - [User {}] Skipping - user not subscribed to any emails", userId); + database.updateProviderLastUpdated(userId); + return false; + } + + if (null != mailjetId) { + log.debug("MAILJET - [User {}] Existing Mailjet user with ID: {}", userId, mailjetId); + + // Verify the user still exists in Mailjet + try { + JSONObject mailjetDetails = mailjetApi.getAccountByIdOrEmail(mailjetId); + + if (mailjetDetails == null) { + log.warn("MAILJET - [User {}] Mailjet ID {} not found - will recreate if needed", userId, mailjetId); + database.updateExternalAccount(userId, null); + mailjetId = null; + } else { + log.debug("MAILJET - [User {}] Found existing Mailjet account", userId); + } + } catch (MailjetException e) { + // If we get 404, clear the ID + if (is404Error(e)) { + log.warn("MAILJET - [User {}] Mailjet contact {} returned 404 - clearing stale ID", userId, mailjetId); + database.updateExternalAccount(userId, null); + mailjetId = null; + } else { + throw e; + } + } + } + + if (null != mailjetId) { + // User exists in Mailjet - handle updates/deletions + return handleExistingMailjetUser(userRecord, mailjetId); + + } else { + // User doesn't exist in Mailjet yet + return handleNewMailjetUser(userRecord); + } + } + + /** + * Determines if a user should be synced to Mailjet. + * Users should be synced if they are subscribed to any emails OR if they already exist in Mailjet. + */ + private boolean shouldSyncToMailjet(UserExternalAccountChanges userRecord) { + // Don't sync deleted users or users with delivery failures + if (userRecord.isDeleted() || + EmailVerificationStatus.DELIVERY_FAILED.equals(userRecord.getEmailVerificationStatus())) { + return false; } + + // Sync if user is subscribed to news or events + return (userRecord.allowsNewsEmails() != null && userRecord.allowsNewsEmails()) + || (userRecord.allowsEventsEmails() != null && userRecord.allowsEventsEmails()); + } + + /** + * Handles sync for a user who already exists in Mailjet. + */ + private boolean handleExistingMailjetUser(UserExternalAccountChanges userRecord, String mailjetId) + throws SegueDatabaseException, MailjetException { + + Long userId = userRecord.getUserId(); + String accountEmail = userRecord.getAccountEmail(); + + try { + JSONObject mailjetDetails = mailjetApi.getAccountByIdOrEmail(mailjetId); + + if (userRecord.isDeleted()) { + log.info("MAILJET - [User {}] Processing deletion from Mailjet", userId); + deleteUserFromMailJet(mailjetId, userRecord); + + } else if (EmailVerificationStatus.DELIVERY_FAILED.equals(userRecord.getEmailVerificationStatus())) { + log.info("MAILJET - [User {}] Email delivery failed - removing from lists", userId); + mailjetApi.updateUserSubscriptions(mailjetId, MailJetSubscriptionAction.REMOVE, + MailJetSubscriptionAction.REMOVE); + database.updateProviderLastUpdated(userId); + + } else if (!accountEmail.toLowerCase().equals(mailjetDetails.getString("Email").toLowerCase())) { + log.info("MAILJET - [User {}] Email changed - recreating Mailjet contact", userId); + mailjetApi.permanentlyDeleteAccountById(mailjetId); + log.debug("MAILJET - [User {}] Deleted old Mailjet contact", userId); + + mailjetId = mailjetApi.addNewUserOrGetUserIfExists(accountEmail); + log.info("MAILJET - [User {}] Created new Mailjet contact with ID: {}", userId, mailjetId); + + updateUserOnMailJet(mailjetId, userRecord); + + } else { + log.debug("MAILJET - [User {}] Updating existing Mailjet contact", userId); + updateUserOnMailJet(mailjetId, userRecord); + } + + database.updateProviderLastUpdated(userId); + return true; + + } catch (JSONException e) { + log.error("MAILJET - [User {}] Failed to parse Mailjet account details: {}", userId, e.getMessage()); + throw new MailjetException("Failed to parse Mailjet response", e); + } + } + + /** + * Handles sync for a user who doesn't exist in Mailjet yet. + */ + private boolean handleNewMailjetUser(UserExternalAccountChanges userRecord) + throws SegueDatabaseException, MailjetException { + + Long userId = userRecord.getUserId(); + String accountEmail = userRecord.getAccountEmail(); + + // Only create new contacts if user is subscribed + if (!shouldSyncToMailjet(userRecord)) { + log.debug("MAILJET - [User {}] Skipping creation - not subscribed to any emails", userId); + database.updateProviderLastUpdated(userId); + return false; + } + + log.info("MAILJET - [User {}] New user - creating Mailjet contact", userId); + + // Create the contact + String mailjetId = mailjetApi.addNewUserOrGetUserIfExists(accountEmail); + + if (mailjetId == null) { + log.error("MAILJET - [User {}] Failed to create Mailjet contact - returned null ID", userId); + throw new MailjetException("Failed to create Mailjet contact - returned null ID"); + } + + log.info("MAILJET - [User {}] Created Mailjet contact with ID: {}", userId, mailjetId); + + // Update properties and subscriptions + boolean updateSucceeded = false; + try { + updateUserOnMailJet(mailjetId, userRecord); + updateSucceeded = true; + } finally { + if (!updateSucceeded) { + log.error("MAILJET - [User {}] Failed to update properties/subscriptions for Mailjet ID {} - contact exists but may have incomplete data", + userId, mailjetId); + // Store the mailjet ID anyway so we don't create duplicates + database.updateExternalAccount(userId, mailjetId); + } + } + + database.updateProviderLastUpdated(userId); + return true; + } + + /** + * Validate user data before attempting Mailjet sync. + */ + private boolean validateUserData(UserExternalAccountChanges userRecord) { + Long userId = userRecord.getUserId(); + String accountEmail = userRecord.getAccountEmail(); + + if (accountEmail == null || accountEmail.trim().isEmpty()) { + log.error("MAILJET - [User {}] Invalid data: email is null or empty", userId); + return false; + } + + if (!accountEmail.contains("@")) { + log.error("MAILJET - [User {}] Invalid data: email '{}' does not contain @", + userId, sanitiseEmailForLogging(accountEmail)); + return false; + } + + // Log warnings for null fields but don't fail validation + if (userRecord.getGivenName() == null) { + log.debug("MAILJET - [User {}] Warning: given_name is null", userId); + } + + if (userRecord.getRole() == null) { + log.warn("MAILJET - [User {}] Warning: role is null", userId); + } + + if (userRecord.getStage() == null) { + log.debug("MAILJET - [User {}] Warning: stage is null", userId); + } + + if (userRecord.getEmailVerificationStatus() == null) { + log.warn("MAILJET - [User {}] Warning: email_verification_status is null", userId); + } + + return true; } private void updateUserOnMailJet(final String mailjetId, final UserExternalAccountChanges userRecord) - throws SegueDatabaseException, MailjetException { + throws SegueDatabaseException, MailjetException { + Long userId = userRecord.getUserId(); - mailjetApi.updateUserProperties(mailjetId, userRecord.getGivenName(), userRecord.getRole().toString(), - userRecord.getEmailVerificationStatus().toString(), userRecord.getStage()); - - MailJetSubscriptionAction newsStatus = (userRecord.allowsNewsEmails() != null - && userRecord.allowsNewsEmails()) ? MailJetSubscriptionAction.FORCE_SUBSCRIBE : - MailJetSubscriptionAction.UNSUBSCRIBE; - MailJetSubscriptionAction eventsStatus = (userRecord.allowsEventsEmails() != null - && userRecord.allowsEventsEmails()) ? MailJetSubscriptionAction.FORCE_SUBSCRIBE : - MailJetSubscriptionAction.UNSUBSCRIBE; - mailjetApi.updateUserSubscriptions(mailjetId, newsStatus, eventsStatus); - - database.updateExternalAccount(userId, mailjetId); + log.debug("MAILJET - [User {}] Updating properties for Mailjet ID: {}", userId, mailjetId); + + // Update properties + try { + String firstName = userRecord.getGivenName(); + String role = userRecord.getRole() != null ? userRecord.getRole().toString() : ""; + String verificationStatus = userRecord.getEmailVerificationStatus() != null + ? userRecord.getEmailVerificationStatus().toString() : ""; + String stage = userRecord.getStage() != null ? userRecord.getStage() : "not_specified"; + + log.debug("MAILJET - [User {}] Setting properties - firstName: {}, role: {}, stage: {}", + userId, firstName, role, stage); + + mailjetApi.updateUserProperties(mailjetId, firstName, role, verificationStatus, stage); + log.debug("MAILJET - [User {}] Successfully updated Mailjet properties", userId); + + } catch (MailjetException e) { + if (is404Error(e)) { + log.warn("MAILJET - [User {}] Contact {} not found (404) during property update - clearing stale ID", + userId, mailjetId); + handleStaleMailjetId(userId, mailjetId); + return; + } + log.error("MAILJET - [User {}] Failed to update Mailjet properties for ID {}", userId, mailjetId); + throw e; + } + + // Update subscriptions + try { + MailJetSubscriptionAction newsStatus = (userRecord.allowsNewsEmails() != null + && userRecord.allowsNewsEmails()) ? MailJetSubscriptionAction.FORCE_SUBSCRIBE : + MailJetSubscriptionAction.UNSUBSCRIBE; + MailJetSubscriptionAction eventsStatus = (userRecord.allowsEventsEmails() != null + && userRecord.allowsEventsEmails()) ? MailJetSubscriptionAction.FORCE_SUBSCRIBE : + MailJetSubscriptionAction.UNSUBSCRIBE; + + log.debug("MAILJET - [User {}] Setting subscriptions - news: {}, events: {}", + userId, newsStatus, eventsStatus); + + mailjetApi.updateUserSubscriptions(mailjetId, newsStatus, eventsStatus); + log.debug("MAILJET - [User {}] Successfully updated Mailjet subscriptions", userId); + + } catch (MailjetException e) { + if (is404Error(e)) { + log.warn("MAILJET - [User {}] Contact {} not found (404) during subscription update - clearing stale ID", + userId, mailjetId); + handleStaleMailjetId(userId, mailjetId); + return; + } + log.error("MAILJET - [User {}] Failed to update Mailjet subscriptions for ID {}", userId, mailjetId); + throw e; + } + + // Store the Mailjet ID + try { + database.updateExternalAccount(userId, mailjetId); + log.debug("MAILJET - [User {}] Stored Mailjet ID in database: {}", userId, mailjetId); + } catch (SegueDatabaseException e) { + log.error("MAILJET - [User {}] Failed to store Mailjet ID {} in database", userId, mailjetId); + throw e; + } + } + + /** + * Checks if a MailjetException is a 404 error. + */ + private boolean is404Error(MailjetException e) { + if (e == null || e.getMessage() == null) { + return false; + } + + String message = e.getMessage(); + return message.contains("\"StatusCode\" : 404") || + message.contains("\"StatusCode\": 404") || + message.contains("Object not found") || + message.contains("404"); + } + + /** + * Handles a stale Mailjet ID by clearing it from the database. + */ + private void handleStaleMailjetId(Long userId, String staleMailjetId) throws SegueDatabaseException { + log.info("MAILJET - [User {}] Clearing stale Mailjet ID: {}", userId, staleMailjetId); + + try { + database.updateExternalAccount(userId, null); + log.info("MAILJET - [User {}] Cleared stale Mailjet ID. Will be recreated on next sync.", userId); + } catch (SegueDatabaseException e) { + log.error("MAILJET - [User {}] CRITICAL: Failed to clear stale Mailjet ID {}", userId, staleMailjetId); + throw e; + } } private void deleteUserFromMailJet(final String mailjetId, final UserExternalAccountChanges userRecord) - throws SegueDatabaseException, MailjetException { + throws SegueDatabaseException, MailjetException { Long userId = userRecord.getUserId(); - mailjetApi.permanentlyDeleteAccountById(mailjetId); - database.updateExternalAccount(userId, null); + log.info("MAILJET - [User {}] Deleting from Mailjet, ID: {}", userId, mailjetId); + + try { + mailjetApi.permanentlyDeleteAccountById(mailjetId); + log.info("MAILJET - [User {}] Successfully deleted from Mailjet", userId); + } catch (MailjetException e) { + // If already deleted (404), that's fine + if (is404Error(e)) { + log.info("MAILJET - [User {}] Contact already deleted from Mailjet (404)", userId); + } else { + log.error("MAILJET - [User {}] Failed to delete from Mailjet, ID: {}", userId, mailjetId); + throw e; + } + } + + try { + database.updateExternalAccount(userId, null); + log.debug("MAILJET - [User {}] Cleared Mailjet ID from database", userId); + } catch (SegueDatabaseException e) { + log.error("MAILJET - [User {}] Failed to clear Mailjet ID from database", userId); + throw e; + } + } + + /** + * Sanitise email for logging to prevent log injection and reduce PII exposure. + */ + private String sanitiseEmailForLogging(String email) { + if (email == null) { + return "null"; + } + if (!email.contains("@")) { + return "invalid-email"; + } + String[] parts = email.split("@"); + if (parts[0].length() <= 2) { + return parts[0].charAt(0) + "***@" + parts[1]; + } + return parts[0].charAt(0) + "***@" + parts[1]; } -} +} \ No newline at end of file diff --git a/src/main/java/uk/ac/cam/cl/dtg/segue/configuration/SegueGuiceConfigurationModule.java b/src/main/java/uk/ac/cam/cl/dtg/segue/configuration/SegueGuiceConfigurationModule.java index ac5cf51c3c..feda53b41c 100644 --- a/src/main/java/uk/ac/cam/cl/dtg/segue/configuration/SegueGuiceConfigurationModule.java +++ b/src/main/java/uk/ac/cam/cl/dtg/segue/configuration/SegueGuiceConfigurationModule.java @@ -972,7 +972,7 @@ private static StatisticsManager getStatsManager(final UserAccountManager userMa static final String CRON_STRING_0700_DAILY = "0 0 7 * * ?"; static final String CRON_STRING_2000_DAILY = "0 0 20 * * ?"; static final String CRON_STRING_HOURLY = "0 0 * ? * * *"; - static final String CRON_STRING_EVERY_FOUR_HOURS = "0 0 0/4 ? * * *"; + static final String CRON_MAIL_JET = "0 0/30 * ? * * *"; // Every 4 hours static final String CRON_GROUP_NAME_SQL_MAINTENANCE = "SQLMaintenance"; static final String CRON_GROUP_NAME_JAVA_JOB = "JavaJob"; @@ -1054,7 +1054,7 @@ private static SegueJobService getSegueJobService(final PropertiesLoader propert "syncMailjetUsersJob", CRON_GROUP_NAME_JAVA_JOB, "Sync users to mailjet", - CRON_STRING_EVERY_FOUR_HOURS); + CRON_MAIL_JET); List configuredScheduledJobs = new ArrayList<>(Arrays.asList( piiSqlJob, diff --git a/src/main/java/uk/ac/cam/cl/dtg/segue/dao/users/PgExternalAccountPersistenceManager.java b/src/main/java/uk/ac/cam/cl/dtg/segue/dao/users/PgExternalAccountPersistenceManager.java index 6fb0992236..39287e0d2f 100644 --- a/src/main/java/uk/ac/cam/cl/dtg/segue/dao/users/PgExternalAccountPersistenceManager.java +++ b/src/main/java/uk/ac/cam/cl/dtg/segue/dao/users/PgExternalAccountPersistenceManager.java @@ -10,6 +10,7 @@ import java.time.Instant; import java.util.List; import org.json.JSONArray; +import org.json.JSONException; import org.json.JSONObject; import org.slf4j.Logger; import org.slf4j.LoggerFactory; @@ -18,7 +19,6 @@ import uk.ac.cam.cl.dtg.isaac.dos.users.UserExternalAccountChanges; import uk.ac.cam.cl.dtg.segue.dao.SegueDatabaseException; import uk.ac.cam.cl.dtg.segue.database.PostgresSqlDb; - /** * This class is responsible for managing and persisting user data. */ @@ -39,18 +39,27 @@ public PgExternalAccountPersistenceManager(final PostgresSqlDb database) { @Override public List getRecentlyChangedRecords() throws SegueDatabaseException { - String query = "SELECT id, provider_user_identifier, email, role, given_name, deleted, email_verification_status, " - + " news_prefs.preference_value AS news_emails, events_prefs.preference_value AS events_emails " - + "FROM users " - + " LEFT OUTER JOIN user_preferences AS news_prefs ON users.id = news_prefs.user_id " - + "AND news_prefs.preference_type='EMAIL_PREFERENCE' " - + "AND news_prefs.preference_name='NEWS_AND_UPDATES' " - + " LEFT OUTER JOIN user_preferences AS events_prefs ON users.id = events_prefs.user_id " - + "AND events_prefs.preference_type='EMAIL_PREFERENCE' " - + "AND events_prefs.preference_name='EVENTS' " - + " LEFT OUTER JOIN external_accounts ON users.id=external_accounts.user_id AND provider_name='MailJet' " - + "WHERE (users.last_updated >= provider_last_updated OR news_prefs.last_updated >= provider_last_updated " - + " OR events_prefs.last_updated >= provider_last_updated OR provider_last_updated IS NULL)"; + String query = "SELECT users.id, provider_user_identifier, email, role, given_name, deleted, email_verification_status, " + + " registered_contexts, " + + " news_prefs.preference_value AS news_emails, " + + " events_prefs.preference_value AS events_emails " + + "FROM users " + + " LEFT OUTER JOIN user_preferences AS news_prefs ON users.id = news_prefs.user_id " + + " AND news_prefs.preference_type='EMAIL_PREFERENCE' " + + " AND news_prefs.preference_name='NEWS_AND_UPDATES' " + + " LEFT OUTER JOIN user_preferences AS events_prefs ON users.id = events_prefs.user_id " + + " AND events_prefs.preference_type='EMAIL_PREFERENCE' " + + " AND events_prefs.preference_name='EVENTS' " + + " LEFT OUTER JOIN external_accounts ON users.id=external_accounts.user_id " + + " AND provider_name='MailJet' " + + "WHERE (users.last_updated >= provider_last_updated " + + " OR news_prefs.last_updated >= provider_last_updated " + + " OR events_prefs.last_updated >= provider_last_updated " + + " OR provider_last_updated IS NULL) " + + "ORDER BY users.id"; + + log.info("MAILJET - Fetching recently changed records for sync"); + try (Connection conn = database.getDatabaseConnection(); PreparedStatement pst = conn.prepareStatement(query); ResultSet results = pst.executeQuery() @@ -61,9 +70,11 @@ public List getRecentlyChangedRecords() throws Segue listOfResults.add(buildUserExternalAccountChanges(results)); } + log.info("MAILJET - Retrieved {} users requiring synchronisation", listOfResults.size()); return listOfResults; } catch (SQLException e) { + log.error("MAILJET - Database error fetching recently changed records", e); throw new SegueDatabaseException("Postgres exception", e); } } @@ -85,12 +96,12 @@ public void updateProviderLastUpdated(final Long userId) throws SegueDatabaseExc @Override public void updateExternalAccount(final Long userId, final String providerUserIdentifier) - throws SegueDatabaseException { + throws SegueDatabaseException { // Upsert the value in, using Postgres 9.5 syntax 'ON CONFLICT DO UPDATE ...' String query = - "INSERT INTO external_accounts(user_id, provider_name, provider_user_identifier) VALUES (?, 'MailJet', ?)" - + " ON CONFLICT (user_id, provider_name) DO UPDATE SET" - + " provider_user_identifier=excluded.provider_user_identifier"; + "INSERT INTO external_accounts(user_id, provider_name, provider_user_identifier) VALUES (?, 'MailJet', ?)" + + " ON CONFLICT (user_id, provider_name) DO UPDATE SET" + + " provider_user_identifier=excluded.provider_user_identifier"; try (Connection conn = database.getDatabaseConnection(); PreparedStatement pst = conn.prepareStatement(query) ) { @@ -103,31 +114,103 @@ public void updateExternalAccount(final Long userId, final String providerUserId } } + /** + * Builds a UserExternalAccountChanges object from a ResultSet. + * Properly parses the registered_contexts array which contains JSON strings like: + * {"{\"stage\": \"gcse\", \"examBoard\": \"all\"}","{\"stage\": \"a_level\", \"examBoard\": \"all\"}"} + * + * @param results the ResultSet containing user data + * @return UserExternalAccountChanges object + * @throws SQLException if database access fails + */ private UserExternalAccountChanges buildUserExternalAccountChanges(final ResultSet results) throws SQLException { - String registeredContextsJson = results.getString("registered_contexts"); + Long userId = results.getLong("id"); + + try { + // Extract basic fields + String providerUserId = results.getString("provider_user_identifier"); + String email = results.getString("email"); + String roleStr = results.getString("role"); + Role role = Role.valueOf(roleStr); + String givenName = results.getString("given_name"); + boolean deleted = results.getBoolean("deleted"); + String emailVerificationStatusStr = results.getString("email_verification_status"); + EmailVerificationStatus emailVerificationStatus = EmailVerificationStatus.valueOf(emailVerificationStatusStr); + + // Handle nullable booleans from LEFT OUTER JOIN + Boolean newsEmails = (Boolean) results.getObject("news_emails"); + Boolean eventsEmails = (Boolean) results.getObject("events_emails"); + + // Parse registered_contexts array to extract stage + String stage = parseStageFromRegisteredContexts(results.getString("registered_contexts"), userId); + + return new UserExternalAccountChanges( + userId, + providerUserId, + email, + role, + givenName, + deleted, + emailVerificationStatus, + newsEmails, + eventsEmails, + stage + ); + + } catch (Exception e) { + log.error("MAILJET - Failed to build UserExternalAccountChanges for user {}: {}", userId, e.getMessage()); + throw new SQLException("Failed to parse user data for user " + userId, e); + } + } - // Parse the JSON string if it's not null - JSONObject registeredContexts = null; - if (registeredContextsJson != null && !registeredContextsJson.isEmpty()) { - registeredContexts = new JSONObject(registeredContextsJson); + /** + * Parses the registered_contexts PostgreSQL array to extract stage information. + * The array contains JSON strings like: {"{\"stage\": \"gcse\"}","{\"stage\": \"a_level\"}"} + * or is empty: {} + * + * @param registeredContextsStr the raw string from the database + * @param userId the user ID for logging purposes + * @return a stage string: "gcse", "a_level", "gcse_and_a_level", or "not_specified" + */ + private String parseStageFromRegisteredContexts(String registeredContextsStr, Long userId) { + if (registeredContextsStr == null || registeredContextsStr.trim().isEmpty() || registeredContextsStr.equals("{}")) { + return "not_specified"; } - // Extract stage from the JSON object, or use a default value - String stage = (registeredContexts != null && registeredContexts.has("stage")) - ? registeredContexts.getString("stage") - : "unknown"; - - return new UserExternalAccountChanges( - results.getLong("id"), - results.getString("provider_user_identifier"), - results.getString("email"), - Role.valueOf(results.getString("role")), - results.getString("given_name"), - results.getBoolean("deleted"), - EmailVerificationStatus.valueOf(results.getString("email_verification_status")), - results.getBoolean("news_emails"), - results.getBoolean("events_emails"), - stage // Pass the extracted stage as a string - ); + try { + // PostgreSQL array format: {"element1","element2"} + // Remove the outer braces and split by comma (handling quoted strings) + String cleaned = registeredContextsStr.trim(); + if (cleaned.startsWith("{") && cleaned.endsWith("}")) { + cleaned = cleaned.substring(1, cleaned.length() - 1); + } + + boolean hasGcse = false; + boolean hasALevel = false; + + // Check if the string contains stage information + // The array elements are JSON strings like "{\"stage\": \"gcse\", \"examBoard\": \"all\"}" + if (cleaned.toLowerCase().contains("\"stage\"") || cleaned.toLowerCase().contains("stage")) { + // Simple pattern matching - more reliable than parsing complex nested structures + String lowerCleaned = cleaned.toLowerCase(); + hasGcse = lowerCleaned.contains("\"stage\": \"gcse\"") || lowerCleaned.contains("stage\": \"gcse"); + hasALevel = lowerCleaned.contains("\"stage\": \"a_level\"") || lowerCleaned.contains("stage\": \"a_level"); + } + + if (hasGcse && hasALevel) { + return "gcse_and_a_level"; + } else if (hasGcse) { + return "gcse"; + } else if (hasALevel) { + return "a_level"; + } else { + return "not_specified"; + } + + } catch (Exception e) { + log.warn("MAILJET - Failed to parse registered_contexts for user {}: {}. Raw value: {}", + userId, e.getMessage(), registeredContextsStr); + return "not_specified"; + } } } diff --git a/src/main/java/uk/ac/cam/cl/dtg/util/email/MailJetApiClientWrapper.java b/src/main/java/uk/ac/cam/cl/dtg/util/email/MailJetApiClientWrapper.java index b1e5b160ed..4a1a9e31c3 100644 --- a/src/main/java/uk/ac/cam/cl/dtg/util/email/MailJetApiClientWrapper.java +++ b/src/main/java/uk/ac/cam/cl/dtg/util/email/MailJetApiClientWrapper.java @@ -35,7 +35,6 @@ import org.json.JSONObject; import org.slf4j.Logger; import org.slf4j.LoggerFactory; - public class MailJetApiClientWrapper { private static final Logger log = LoggerFactory.getLogger(MailJetApiClientWrapper.class); @@ -58,14 +57,17 @@ public MailJetApiClientWrapper(final String mailjetApiKey, final String mailjetA final String mailjetNewsListId, final String mailjetEventsListId, final String mailjetLegalListId) { ClientOptions options = ClientOptions.builder() - .apiKey(mailjetApiKey) - .apiSecretKey(mailjetApiSecret) - .build(); + .apiKey(mailjetApiKey) + .apiSecretKey(mailjetApiSecret) + .build(); this.mailjetClient = new MailjetClient(options); this.newsListId = mailjetNewsListId; this.eventsListId = mailjetEventsListId; this.legalListId = mailjetLegalListId; + + log.info("MAILJET - MailJetApiClientWrapper initialized with list IDs - News: {}, Events: {}, Legal: {}", + newsListId, eventsListId, legalListId); } /** @@ -77,15 +79,37 @@ public MailJetApiClientWrapper(final String mailjetApiKey, final String mailjetA */ public JSONObject getAccountByIdOrEmail(final String mailjetIdOrEmail) throws MailjetException { if (null == mailjetIdOrEmail) { + log.warn("MAILJET - getAccountByIdOrEmail called with null mailjetIdOrEmail"); return null; } - MailjetRequest request = new MailjetRequest(Contact.resource, mailjetIdOrEmail); - MailjetResponse response = mailjetClient.get(request); - JSONArray responseData = response.getData(); - if (response.getTotal() == 1) { - return responseData.getJSONObject(0); + + log.debug("MAILJET - Getting Mailjet account for: {}", mailjetIdOrEmail); + + try { + MailjetRequest request = new MailjetRequest(Contact.resource, mailjetIdOrEmail); + MailjetResponse response = mailjetClient.get(request); + + log.debug("MAILJET - Mailjet GET Contact response - Status: {}, Total: {}", + response.getStatus(), response.getTotal()); + + JSONArray responseData = response.getData(); + if (response.getTotal() == 1) { + JSONObject result = responseData.getJSONObject(0); + log.debug("MAILJET - Found Mailjet contact: ID={}, Email={}", + result.optInt("ID"), result.optString("Email")); + return result; + } + + log.warn("MAILJET - Mailjet account not found for: {}", mailjetIdOrEmail); + return null; + + } catch (MailjetException e) { + log.error("MAILJET - MailjetException in getAccountByIdOrEmail for: {}", mailjetIdOrEmail, e); + throw e; + } catch (Exception e) { + log.error("MAILJET - Unexpected exception in getAccountByIdOrEmail for: {}", mailjetIdOrEmail, e); + throw new MailjetException("Unexpected error getting account: " + e.getMessage(), e); } - return null; } /** @@ -96,8 +120,28 @@ public JSONObject getAccountByIdOrEmail(final String mailjetIdOrEmail) throws Ma */ public void permanentlyDeleteAccountById(final String mailjetId) throws MailjetException { requireNonNull(mailjetId); - MailjetRequest request = new MailjetRequest(Contacts.resource, mailjetId); - mailjetClient.delete(request); + + log.info("MAILJET - Permanently deleting Mailjet account: {}", mailjetId); + + try { + MailjetRequest request = new MailjetRequest(Contacts.resource, mailjetId); + MailjetResponse response = mailjetClient.delete(request); + + log.info("MAILJET - Mailjet DELETE response - Status: {}, mailjetId: {}", + response.getStatus(), mailjetId); + + if (response.getStatus() != 204 && response.getStatus() != 200) { + log.warn("MAILJET - Unexpected status code {} when deleting Mailjet account {}", + response.getStatus(), mailjetId); + } + + } catch (MailjetException e) { + log.error("MAILJET - MailjetException deleting account: {}", mailjetId, e); + throw e; + } catch (Exception e) { + log.error("MAILJET - Unexpected exception deleting account: {}", mailjetId, e); + throw new MailjetException("Unexpected error deleting account: " + e.getMessage(), e); + } } /** @@ -111,27 +155,67 @@ public void permanentlyDeleteAccountById(final String mailjetId) throws MailjetE */ public String addNewUserOrGetUserIfExists(final String email) throws MailjetException { if (null == email) { + log.error("MAILJET - addNewUserOrGetUserIfExists called with null email"); return null; } + + log.info("MAILJET - Creating Mailjet contact for email: {}", sanitiseEmailForLogging(email)); + try { MailjetRequest request = new MailjetRequest(Contact.resource).property(Contact.EMAIL, email); MailjetResponse response = mailjetClient.post(request); + + log.debug("MAILJET - Mailjet POST Contact response - Status: {}, Total: {}", + response.getStatus(), response.getTotal()); + // Get MailJet ID out: JSONObject responseData = response.getData().getJSONObject(0); - return Integer.toString(responseData.getInt("ID")); + String mailjetId = Integer.toString(responseData.getInt("ID")); + + log.info("MAILJET - Successfully created Mailjet contact with ID: {} for email: {}", + mailjetId, sanitiseEmailForLogging(email)); + + return mailjetId; + } catch (MailjetClientRequestException e) { + log.warn("MAILJET - MailjetClientRequestException creating contact for email: {} - Message: {}", + sanitiseEmailForLogging(email), e.getMessage()); + if (e.getMessage().contains("already exists")) { - // FIXME - we need to test that this response always comes back with "already exists" in the message - log.warn(String.format("Attempted to create a user with email (%s) that already existed!", email)); - JSONObject existingMailJetAccount = getAccountByIdOrEmail(email); - return Integer.toString(existingMailJetAccount.getInt("ID")); + log.info("MAILJET - Contact already exists, attempting to retrieve existing contact for: {}", + sanitiseEmailForLogging(email)); + + try { + JSONObject existingMailJetAccount = getAccountByIdOrEmail(email); + if (existingMailJetAccount != null) { + String existingId = Integer.toString(existingMailJetAccount.getInt("ID")); + log.info("MAILJET - Found existing Mailjet contact with ID: {} for email: {}", + existingId, sanitiseEmailForLogging(email)); + return existingId; + } else { + log.error("MAILJET - Contact 'already exists' but getAccountByIdOrEmail returned null for: {}", + sanitiseEmailForLogging(email)); + throw new MailjetException("Contact exists but could not be retrieved"); + } + } catch (JSONException jsonEx) { + log.error("MAILJET - JSONException retrieving existing contact for: {}", + sanitiseEmailForLogging(email), jsonEx); + throw new MailjetException("Failed to parse existing contact data", jsonEx); + } } else { - log.error(String.format("Failed to create user in MailJet with email: %s", email), e); + log.error("MAILJET - Failed to create user in MailJet with email: {} - Error: {}", + sanitiseEmailForLogging(email), e.getMessage(), e); + throw new MailjetException("Failed to create contact: " + e.getMessage(), e); } } catch (JSONException e) { - log.error(String.format("Failed to create user in MailJet with email: %s", email), e); + log.error("MAILJET - JSONException creating user in MailJet with email: {}", + sanitiseEmailForLogging(email), e); + throw new MailjetException("Failed to parse Mailjet response", e); + } catch (Exception e) { + log.error("MAILJET - Unexpected exception creating user in MailJet with email: {}", + sanitiseEmailForLogging(email), e); + throw new MailjetException("Unexpected error creating contact: " + e.getMessage(), e); } - return null; } /** @@ -147,16 +231,47 @@ public String addNewUserOrGetUserIfExists(final String email) throws MailjetExce public void updateUserProperties(final String mailjetId, final String firstName, final String role, final String emailVerificationStatus, String stage) throws MailjetException { requireNonNull(mailjetId); - MailjetRequest request = new MailjetRequest(Contactdata.resource, mailjetId) - .property(Contactdata.DATA, new JSONArray() - .put(new JSONObject().put("Name", "firstname").put("value", firstName)) - .put(new JSONObject().put("Name", "role").put("value", role)) - .put(new JSONObject().put("Name", "verification_status").put("value", emailVerificationStatus)) - .put(new JSONObject().put("Name", "stage").put("value", stage)) - ); - MailjetResponse response = mailjetClient.put(request); - if (response.getTotal() != 1) { - throw new MailjetException("Failed to update user!" + response.getTotal()); + + log.info("MAILJET - Updating properties for Mailjet ID: {}", mailjetId); + log.debug("MAILJET - Properties - firstName: {}, role: {}, verificationStatus: {}, stage: {}", + firstName, role, emailVerificationStatus, stage); + + try { + JSONArray propertiesArray = new JSONArray() + .put(new JSONObject().put("Name", "firstname").put("value", firstName)) + .put(new JSONObject().put("Name", "role").put("value", role)) + .put(new JSONObject().put("Name", "verification_status").put("value", emailVerificationStatus)) + .put(new JSONObject().put("Name", "stage").put("value", stage)); + + log.debug("MAILJET - Property JSON array: {}", propertiesArray.toString()); + + MailjetRequest request = new MailjetRequest(Contactdata.resource, mailjetId) + .property(Contactdata.DATA, propertiesArray); + + MailjetResponse response = mailjetClient.put(request); + + log.debug("MAILJET - Mailjet PUT Contactdata response - Status: {}, Total: {}", + response.getStatus(), response.getTotal()); + + if (response.getTotal() != 1) { + log.error("MAILJET - Failed to update user properties! Expected 1, got {} for Mailjet ID: {}", + response.getTotal(), mailjetId); + log.error("MAILJET - Response status: {}, Response data: {}", + response.getStatus(), response.getData().toString()); + throw new MailjetException("Failed to update user! Response total: " + response.getTotal()); + } + + log.info("MAILJET - Successfully updated properties for Mailjet ID: {}", mailjetId); + + } catch (MailjetException e) { + log.error("MAILJET - MailjetException updating properties for Mailjet ID: {}", mailjetId, e); + throw e; + } catch (JSONException e) { + log.error("MAILJET - JSONException creating property data for Mailjet ID: {}", mailjetId, e); + throw new MailjetException("Failed to create property JSON", e); + } catch (Exception e) { + log.error("MAILJET - Unexpected exception updating properties for Mailjet ID: {}", mailjetId, e); + throw new MailjetException("Unexpected error updating properties: " + e.getMessage(), e); } } @@ -171,22 +286,72 @@ public void updateUserProperties(final String mailjetId, final String firstName, public void updateUserSubscriptions(final String mailjetId, final MailJetSubscriptionAction newsEmails, final MailJetSubscriptionAction eventsEmails) throws MailjetException { requireNonNull(mailjetId); - MailjetRequest request = new MailjetRequest(ContactManagecontactslists.resource, mailjetId) - .property(ContactManagecontactslists.CONTACTSLISTS, new JSONArray() - .put(new JSONObject() - .put(ContactslistImportList.LISTID, legalListId) - .put(ContactslistImportList.ACTION, MailJetSubscriptionAction.FORCE_SUBSCRIBE.getValue())) - .put(new JSONObject() - .put(ContactslistImportList.LISTID, newsListId) - .put(ContactslistImportList.ACTION, newsEmails.getValue())) - .put(new JSONObject() - .put(ContactslistImportList.LISTID, eventsListId) - .put(ContactslistImportList.ACTION, eventsEmails.getValue())) - ); - MailjetResponse response = mailjetClient.post(request); - if (response.getTotal() != 1) { - throw new MailjetException("Failed to update user subscriptions!" + response.getTotal()); + + log.info("MAILJET - Updating subscriptions for Mailjet ID: {}", mailjetId); + log.debug("MAILJET - Subscriptions - news: {}, events: {}", newsEmails, eventsEmails); + log.debug("MAILJET - Using list IDs - Legal: {}, News: {}, Events: {}", legalListId, newsListId, eventsListId); + + try { + JSONArray subscriptionsArray = new JSONArray() + .put(new JSONObject() + .put(ContactslistImportList.LISTID, legalListId) + .put(ContactslistImportList.ACTION, MailJetSubscriptionAction.FORCE_SUBSCRIBE.getValue())) + .put(new JSONObject() + .put(ContactslistImportList.LISTID, newsListId) + .put(ContactslistImportList.ACTION, newsEmails.getValue())) + .put(new JSONObject() + .put(ContactslistImportList.LISTID, eventsListId) + .put(ContactslistImportList.ACTION, eventsEmails.getValue())); + + log.debug("MAILJET - Subscription JSON array: {}", subscriptionsArray.toString()); + + MailjetRequest request = new MailjetRequest(ContactManagecontactslists.resource, mailjetId) + .property(ContactManagecontactslists.CONTACTSLISTS, subscriptionsArray); + + MailjetResponse response = mailjetClient.post(request); + + log.debug("MAILJET - Mailjet POST ContactManagecontactslists response - Status: {}, Total: {}", + response.getStatus(), response.getTotal()); + + if (response.getTotal() != 1) { + log.error("MAILJET - Failed to update user subscriptions! Expected 1, got {} for Mailjet ID: {}", + response.getTotal(), mailjetId); + log.error("MAILJET - Response status: {}, Response data: {}", + response.getStatus(), response.getData().toString()); + throw new MailjetException("Failed to update user subscriptions! Response total: " + response.getTotal()); + } + + log.info("MAILJET - Successfully updated subscriptions for Mailjet ID: {}", mailjetId); + + } catch (MailjetException e) { + log.error("MAILJET - MailjetException updating subscriptions for Mailjet ID: {}", mailjetId, e); + throw e; + } catch (JSONException e) { + log.error("MAILJET - JSONException creating subscription data for Mailjet ID: {}", mailjetId, e); + throw new MailjetException("Failed to create subscription JSON", e); + } catch (Exception e) { + log.error("MAILJET - Unexpected exception updating subscriptions for Mailjet ID: {}", mailjetId, e); + throw new MailjetException("Unexpected error updating subscriptions: " + e.getMessage(), e); } } -} + /** + * Sanitise email for logging to prevent log injection and reduce PII exposure. + * + * @param email the email to sanitise + * @return sanitised email (e.g., "u***@example.com") + */ + private String sanitiseEmailForLogging(String email) { + if (email == null) { + return "null"; + } + if (!email.contains("@")) { + return "invalid-email"; + } + String[] parts = email.split("@"); + if (parts[0].length() <= 2) { + return parts[0].charAt(0) + "***@" + parts[1]; + } + return parts[0].charAt(0) + "***@" + parts[1]; + } +} \ No newline at end of file