Add more debug statements for experimental AS-mode for Matrix ID invites

src/main/java/io/kamax/mxisd/as/AppServiceHandler.java

@@ -22,6 +22,7 @@ package io.kamax.mxisd.as;
 
 import com.google.gson.JsonObject;
 import io.kamax.matrix.MatrixID;
+import io.kamax.matrix.ThreePidMedium;
 import io.kamax.matrix._MatrixID;
 import io.kamax.matrix._ThreePid;
 import io.kamax.matrix.event.EventKey;
@@ -39,6 +40,7 @@ import org.springframework.stereotype.Component;
 import java.util.HashMap;
 import java.util.List;
 import java.util.Map;
+import java.util.stream.Collectors;
 
 @Component
 public class AppServiceHandler {
@@ -60,52 +62,77 @@ public class AppServiceHandler {
 
     public void processTransaction(List<JsonObject> eventsJson) {
         eventsJson.forEach(ev -> {
+            String evId = EventKey.Id.getStringOrNull(ev);
+            if (StringUtils.isBlank(evId)) {
+                log.warn("Event has no ID, skipping");
+                log.debug("Event:\n{}", GsonUtil.getPrettyForLog(ev));
+                return;
+            }
+            log.debug("Event {}: processing start", evId);
+
+            String roomId = EventKey.RoomId.getStringOrNull(ev);
+            if (StringUtils.isBlank(roomId)) {
+                log.debug("Event has no room ID, skipping");
+                return;
+            }
+
+            String senderId = EventKey.Sender.getStringOrNull(ev);
+            if (StringUtils.isBlank(senderId)) {
+                log.debug("Event has no room ID, skipping");
+                return;
+            }
+            _MatrixID sender = MatrixID.asAcceptable(senderId);
+
             if (!StringUtils.equals("m.room.member", GsonUtil.getStringOrNull(ev, "type"))) {
+                log.debug("This is not a room membership event, skipping");
                 return;
             }
 
             if (!StringUtils.equals("invite", GsonUtil.getStringOrNull(ev, "membership"))) {
+                log.debug("This is not an invite event, skipping");
                 return;
             }
 
-            String roomId = GsonUtil.getStringOrNull(ev, "room_id");
+            String inviteeId = EventKey.StateKey.getStringOrNull(ev);
-            _MatrixID sender = MatrixID.asAcceptable(GsonUtil.getStringOrNull(ev, "sender"));
+            if (StringUtils.isBlank(inviteeId)) {
-            EventKey.StateKey.findString(ev).ifPresent(id -> {
+                log.warn("Invalid event: No invitee ID, skipping");
-                _MatrixID mxid = MatrixID.asAcceptable(id);
+                return;
-                if (!StringUtils.equals(mxid.getDomain(), cfg.getDomain())) {
+            }
-                    log.debug("Ignoring invite for {}: not a local user");
-                    return;
-                }
-                log.info("Got invite for {}", id);
 
-                boolean wasSent = false;
+            _MatrixID invitee = MatrixID.asAcceptable(inviteeId);
-                List<_ThreePid> tpids = profiler.getThreepids(mxid);
+            if (!StringUtils.equals(invitee.getDomain(), cfg.getDomain())) {
-                if (tpids.isEmpty()) {
+                log.debug("Ignoring invite for {}: not a local user");
-                    log.info("No email found in identity stores for {}", id);
+                return;
+            }
+
+            log.info("Got invite for {}", inviteeId);
+
+            boolean wasSent = false;
+            List<_ThreePid> tpids = profiler.getThreepids(invitee).stream()
+                    .filter(tpid -> ThreePidMedium.Email.is(tpid.getMedium()))
+                    .collect(Collectors.toList());
+            log.info("Found {} email(s) in identity store for {}", tpids.size(), inviteeId);
+
+            for (_ThreePid tpid : tpids) {
+                log.info("Found Email to notify about room invitation: {}", tpid.getAddress());
+                Map<String, String> properties = new HashMap<>();
+                profiler.getDisplayName(sender).ifPresent(name -> properties.put("sender_display_name", name));
+                try {
+                    synapse.getRoomName(roomId).ifPresent(name -> properties.put("room_name", name));
+                } catch (RuntimeException e) {
+                    log.warn("Could not fetch room name", e);
+                    log.warn("Unable to fetch room name: Did you integrate your Homeserver as documented?");
                 }
 
-                for (_ThreePid tpid : tpids) {
+                IMatrixIdInvite inv = new MatrixIdInvite(roomId, sender, invitee, tpid.getMedium(), tpid.getAddress(), properties);
-                    if (!StringUtils.equals("email", tpid.getMedium())) {
+                notif.sendForInvite(inv);
-                        continue;
+                log.info("Notification for invite of {} sent to {}", inviteeId, tpid.getAddress());
-                    }
+                wasSent = true;
+            }
 
-                    log.info("Found an email address to notify about room invitation: {}", tpid.getAddress());
+            log.info("Was notification sent? {}", wasSent);
-                    Map<String, String> properties = new HashMap<>();
-                    profiler.getDisplayName(sender).ifPresent(name -> properties.put("sender_display_name", name));
-                    try {
-                        synapse.getRoomName(roomId).ifPresent(name -> properties.put("room_name", name));
-                    } catch (RuntimeException e) {
-                        log.warn("Unable to fetch room name - Did you provide synapse DB information as documented?");
-                        log.warn("Underlying error:", e);
-                    }
 
-                    IMatrixIdInvite inv = new MatrixIdInvite(roomId, sender, mxid, tpid.getMedium(), tpid.getAddress(), properties);
+            log.debug("Event {}: processing end", evId);
-                    notif.sendForInvite(inv);
-                    wasSent = true;
-                }
-
-                log.info("Was notification sent? {}", wasSent);
-            });
         });
     }
 

src/main/java/io/kamax/mxisd/controller/app/v1/AppServiceController.java

@@ -89,19 +89,20 @@ public class AppServiceController {
     }
 
     @RequestMapping(value = "/transactions/{txnId:.+}", method = PUT)
-    public Object getTransaction(
+    public String getTransaction(
             HttpServletRequest request,
             @RequestParam(name = "access_token", required = false) String token,
             @PathVariable String txnId) {
         try {
             validateToken(token);
 
-            log.info("Processing transaction {}", txnId);
+            log.info("Transaction {}: Processing start", txnId);
             List<JsonObject> events = GsonUtil.asList(GsonUtil.getArray(parser.parse(request.getInputStream()), "events"), JsonObject.class);
+            log.debug("Transaction {}: {} events to process", txnId, events.size());
             handler.processTransaction(events);
-            return "{}";
+            log.info("Transaction {}: Processing end", txnId);
         } catch (Throwable e) {
-            log.warn("Unable to properly process transaction", e);
+            log.error("Unable to properly process transaction {}", txnId, e);
         }
 
         return "{}";

src/main/resources/application.yaml

@@ -14,6 +14,8 @@ logging:
       apache:
         catalina: 'WARN'
         directory: 'WARN'
+    io.kamax.mxisd.controller.app.v1.AppServiceController: 'DEBUG'
+    io.kamax.mxisd.as.AppServiceHandler: 'DEBUG'
   pattern:
     console: '%d{yyyy-MM-dd HH:mm:ss.SSS} ${LOG_LEVEL_PATTERN:%5p} [%15.15t] %35.35logger{34} : %m%n${LOG_EXCEPTION_CONVERSION_WORD:%wEx}'