More logging, delete, new convo

core/kordophone/src/api/http_client.rs

@@ -65,7 +65,15 @@ impl std::error::Error for Error {
 
 impl std::fmt::Display for Error {
     fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
-        write!(f, "{:?}", self)
+        match self {
+            Error::ClientError(message) => write!(f, "{}", message),
+            Error::HTTPError(err) => write!(f, "HTTP transport error: {}", err),
+            Error::SerdeError(err) => write!(f, "JSON error: {}", err),
+            Error::DecodeError(message) => write!(f, "Decode error: {}", message),
+            Error::PongError(err) => write!(f, "WebSocket error: {}", err),
+            Error::URLError => write!(f, "Invalid URL"),
+            Error::Unauthorized => write!(f, "Unauthorized"),
+        }
     }
 }
 
@@ -284,6 +292,17 @@ impl<K: AuthenticationStore + Send + Sync> APIInterface for HTTPAPIClient<K> {
         Ok(())
     }
 
+    async fn delete_conversation(
+        &mut self,
+        conversation_id: &ConversationID,
+    ) -> Result<(), Self::Error> {
+        // SERVER JANK: This should be DELETE or POST, but it's GET for some reason.
+        let endpoint = format!("delete?guid={}", conversation_id);
+        self.response_with_body_retry(&endpoint, Method::GET, Body::empty, true)
+            .await?;
+        Ok(())
+    }
+
     async fn get_messages(
         &mut self,
         conversation_id: &ConversationID,
@@ -313,6 +332,25 @@ impl<K: AuthenticationStore + Send + Sync> APIInterface for HTTPAPIClient<K> {
         &mut self,
         outgoing_message: &OutgoingMessage,
     ) -> Result<SendMessageResponse, Self::Error> {
+        match &outgoing_message.target {
+            OutgoingMessageTarget::Conversation(conversation_id) => {
+                log::debug!(
+                    "Sending message to conversation {} (body_length={}, attachment_count={})",
+                    conversation_id,
+                    outgoing_message.text.len(),
+                    outgoing_message.file_transfer_guids.len()
+                );
+            }
+            OutgoingMessageTarget::Handles(handle_ids) => {
+                log::debug!(
+                    "Sending message to resolved handles {:?} (body_length={}, attachment_count={})",
+                    handle_ids,
+                    outgoing_message.text.len(),
+                    outgoing_message.file_transfer_guids.len()
+                );
+            }
+        }
+
         let message: SendMessageResponse = self
             .deserialized_response_with_body("sendMessage", Method::POST, || {
                 Self::send_message_request_body(outgoing_message)
@@ -326,6 +364,7 @@ impl<K: AuthenticationStore + Send + Sync> APIInterface for HTTPAPIClient<K> {
         &mut self,
         handle_id: &str,
     ) -> Result<ResolveHandleResponse, Self::Error> {
+        log::debug!("Resolving handle {}", handle_id);
         let endpoint = format!("resolveHandle?id={}", urlencoding::encode(handle_id));
         let response: ResolveHandleResponse =
             self.deserialized_response(&endpoint, Method::GET).await?;
@@ -542,6 +581,18 @@ impl<K: AuthenticationStore + Send + Sync> HTTPAPIClient<K> {
         }
     }
 
+    fn log_transport_error(method: &Method, target: &str, err: &hyper::Error) {
+        log::error!("HTTP transport error for {} {}: {}", method, target, err);
+
+        if format!("{:?}", err).contains("IncompleteMessage") {
+            log::error!(
+                "The server closed the connection before a complete response was received for {} {}.",
+                method,
+                target
+            );
+        }
+    }
+
     async fn deserialized_response<T: DeserializeOwned>(
         &mut self,
         endpoint: &str,
@@ -575,15 +626,26 @@ impl<K: AuthenticationStore + Send + Sync> HTTPAPIClient<K> {
         T: DeserializeOwned,
     {
         let response = self
-            .response_with_body_retry(endpoint, method, body_fn, retry_auth)
+            .response_with_body_retry(endpoint, method.clone(), body_fn, retry_auth)
             .await?;
 
         // Read and parse response body
-        let body = hyper::body::to_bytes(response.into_body()).await?;
+        let body = match hyper::body::to_bytes(response.into_body()).await {
+            Ok(body) => body,
+            Err(err) => {
+                Self::log_transport_error(&method, endpoint, &err);
+                return Err(Error::HTTPError(err));
+            }
+        };
         let parsed: T = match serde_json::from_slice(&body) {
             Ok(result) => Ok(result),
             Err(json_err) => {
-                log::error!("Error deserializing JSON: {:?}", json_err);
+                log::error!(
+                    "Error deserializing JSON for {} {}: {:?}",
+                    method,
+                    endpoint,
+                    json_err
+                );
                 log::error!("Body: {:?}", String::from_utf8_lossy(&body));
 
                 // If JSON deserialization fails, try to interpret it as plain text
@@ -606,7 +668,8 @@ impl<K: AuthenticationStore + Send + Sync> HTTPAPIClient<K> {
         use hyper::StatusCode;
 
         let uri = self.uri_for_endpoint(endpoint, None)?;
-        log::debug!("Requesting {:?} {:?}", method, uri);
+        let uri_string = uri.to_string();
+        log::debug!("Requesting {} {}", method, uri_string);
 
         let mut build_request = |auth: &Option<String>| {
             let body = body_fn();
@@ -620,13 +683,24 @@ impl<K: AuthenticationStore + Send + Sync> HTTPAPIClient<K> {
 
         log::trace!("Obtaining token from auth store");
         let token = self.auth_store.get_token().await;
-        log::trace!("Token: {:?}", token);
+        log::trace!("Token present: {}", token.is_some());
 
         let request = build_request(&token);
-        log::trace!("Request: {:?}. Sending request...", request);
+        log::trace!(
+            "Sending request: method={} uri={} authenticated={}",
+            method,
+            uri_string,
+            token.is_some()
+        );
 
-        let mut response = self.client.request(request).await?;
+        let mut response = match self.client.request(request).await {
-        log::debug!("-> Response: {:}", response.status());
+            Ok(response) => response,
+            Err(err) => {
+                Self::log_transport_error(&method, &uri_string, &err);
+                return Err(Error::HTTPError(err));
+            }
+        };
+        log::debug!("-> Response: {}", response.status());
 
         match response.status() {
             StatusCode::OK => { /* cool */ }
@@ -645,7 +719,19 @@ impl<K: AuthenticationStore + Send + Sync> HTTPAPIClient<K> {
                     let new_token = self.authenticate(credentials.clone()).await?;
 
                     let request = build_request(&Some(new_token.to_string()));
-                    response = self.client.request(request).await?;
+                    log::trace!(
+                        "Retrying request after authentication: method={} uri={} authenticated=true",
+                        method,
+                        uri_string
+                    );
+                    response = match self.client.request(request).await {
+                        Ok(response) => response,
+                        Err(err) => {
+                            Self::log_transport_error(&method, &uri_string, &err);
+                            return Err(Error::HTTPError(err));
+                        }
+                    };
+                    log::debug!("-> Retry response: {}", response.status());
                 } else {
                     return Err(Error::ClientError(
                         "Unauthorized, no credentials provided".into(),

core/kordophone/src/api/mod.rs

@@ -79,6 +79,12 @@ pub trait APIInterface {
         conversation_id: &ConversationID,
     ) -> Result<(), Self::Error>;
 
+    // (GET) /delete
+    async fn delete_conversation(
+        &mut self,
+        conversation_id: &ConversationID,
+    ) -> Result<(), Self::Error>;
+
     // (WS) /updates
     async fn open_event_socket(
         &mut self,

core/kordophone/src/tests/mod.rs

@@ -52,4 +52,20 @@ pub mod api_interface {
         assert_eq!(sent.message.text, "hello");
         assert_eq!(sent.conversation_id, None);
     }
+
+    #[tokio::test]
+    async fn test_delete_conversation() {
+        let mut client = TestClient::new();
+
+        let test_convo = Conversation::builder()
+            .display_name("Delete Me")
+            .build();
+
+        client.conversations.push(test_convo.clone());
+
+        client.delete_conversation(&test_convo.guid).await.unwrap();
+
+        let conversations = client.get_conversations().await.unwrap();
+        assert!(conversations.is_empty());
+    }
 }

core/kordophone/src/tests/test_client.rs

@@ -187,4 +187,19 @@ impl APIInterface for TestClient {
     ) -> Result<(), Self::Error> {
         Ok(())
     }
+
+    async fn delete_conversation(
+        &mut self,
+        conversation_id: &ConversationID,
+    ) -> Result<(), Self::Error> {
+        let previous_len = self.conversations.len();
+        self.conversations.retain(|c| &c.guid != conversation_id);
+        self.messages.remove(conversation_id);
+
+        if self.conversations.len() == previous_len {
+            return Err(TestError::ConversationNotFound);
+        }
+
+        Ok(())
+    }
 }

core/kpcli/src/client/mod.rs

@@ -5,10 +5,10 @@ use kordophone::api::InMemoryAuthenticationStore;
 use kordophone::APIInterface;
 
 use crate::printers::{ConversationPrinter, MessagePrinter};
-use anyhow::Result;
+use anyhow::{bail, Result};
 use clap::Subcommand;
 use kordophone::model::event::EventData;
-use kordophone::model::outgoing_message::OutgoingMessage;
+use kordophone::model::{HandleResolutionStatus, OutgoingMessage, OutgoingMessageTarget};
 
 use futures_util::StreamExt;
 
@@ -47,14 +47,29 @@ pub enum Commands {
     /// Prints all raw updates from the server.
     RawUpdates,
 
-    /// Sends a message to the server.
+    /// Resolves an address to a canonical handle.
-    SendMessage {
+    #[command(alias = "resolve")]
+    ResolveHandle { address: String },
+
+    /// Replies to an existing conversation.
+    #[command(alias = "send-message")]
+    Reply {
         conversation_id: String,
         message: String,
     },
 
+    /// Starts a new message to one or more resolved handles.
+    New {
+        #[arg(long = "handle", required = true)]
+        handle_ids: Vec<String>,
+        message: String,
+    },
+
     /// Marks a conversation as read.
     Mark { conversation_id: String },
+
+    /// Deletes a conversation from the server.
+    Delete { conversation_id: String },
 }
 
 impl Commands {
@@ -66,13 +81,19 @@ impl Commands {
             Commands::Messages { conversation_id } => client.print_messages(conversation_id).await,
             Commands::RawUpdates => client.print_raw_updates().await,
             Commands::Events => client.print_events().await,
-            Commands::SendMessage {
+            Commands::ResolveHandle { address } => client.resolve_handle(address).await,
+            Commands::Reply {
                 conversation_id,
                 message,
-            } => client.send_message(conversation_id, message).await,
+            } => client.reply(conversation_id, message).await,
+            Commands::New {
+                handle_ids,
+                message,
+            } => client.new_message(handle_ids, message).await,
             Commands::Mark { conversation_id } => {
                 client.mark_conversation_as_read(conversation_id).await
             }
+            Commands::Delete { conversation_id } => client.delete_conversation(conversation_id).await,
         }
     }
 }
@@ -167,20 +188,92 @@ impl ClientCli {
         Ok(())
     }
 
-    pub async fn send_message(&mut self, conversation_id: String, message: String) -> Result<()> {
+    pub async fn resolve_handle(&mut self, address: String) -> Result<()> {
+        let response = self.api.resolve_handle(&address).await?;
+        let status = match response.status {
+            HandleResolutionStatus::Valid => "valid",
+            HandleResolutionStatus::Invalid => "invalid",
+            HandleResolutionStatus::Unknown => "unknown",
+        };
+
+        println!("Resolved handle: {}", response.resolved_handle.id);
+
+        if let Some(name) = response.resolved_handle.name {
+            println!("Name: {}", name);
+        }
+
+        println!("Status: {}", status);
+
+        if let Some(conversation_id) = response.existing_chat {
+            println!("Existing conversation: {}", conversation_id);
+        }
+
+        Ok(())
+    }
+
+    async fn send_message(
+        &mut self,
+        target: OutgoingMessageTarget,
+        message: String,
+    ) -> Result<()> {
         let outgoing_message = OutgoingMessage::builder()
-            .conversation_id(conversation_id)
+            .target(target)
             .text(message)
             .build();
 
         let response = self.api.send_message(&outgoing_message).await?;
-        println!("Message sent: {}", response.message.guid);
+        if let Some(conversation_id) = response.conversation_id {
+            println!(
+                "Message sent: {} conversation: {}",
+                response.message.guid, conversation_id
+            );
+        } else {
+            println!("Message sent: {}", response.message.guid);
+        }
         Ok(())
     }
 
+    async fn resolve_handle_ids(&mut self, handle_ids: Vec<String>) -> Result<Vec<String>> {
+        let mut resolved_handle_ids = Vec::with_capacity(handle_ids.len());
+
+        for handle_id in handle_ids {
+            let response = self.api.resolve_handle(&handle_id).await?;
+            match response.status {
+                HandleResolutionStatus::Valid => {
+                    resolved_handle_ids.push(response.resolved_handle.id);
+                }
+                HandleResolutionStatus::Invalid => {
+                    bail!("Handle '{}' is not iMessage-capable.", handle_id);
+                }
+                HandleResolutionStatus::Unknown => {
+                    bail!("Handle '{}' could not be resolved.", handle_id);
+                }
+            }
+        }
+
+        Ok(resolved_handle_ids)
+    }
+
+    pub async fn reply(&mut self, conversation_id: String, message: String) -> Result<()> {
+        self.send_message(OutgoingMessageTarget::Conversation(conversation_id), message)
+            .await
+    }
+
+    pub async fn new_message(&mut self, handle_ids: Vec<String>, message: String) -> Result<()> {
+        let resolved_handle_ids = self.resolve_handle_ids(handle_ids).await?;
+        self.send_message(OutgoingMessageTarget::Handles(resolved_handle_ids), message)
+            .await
+    }
+
     pub async fn mark_conversation_as_read(&mut self, conversation_id: String) -> Result<()> {
         self.api.mark_conversation_as_read(&conversation_id).await?;
         println!("Conversation marked as read: {}", conversation_id);
         Ok(())
     }
+
+    pub async fn delete_conversation(&mut self, conversation_id: String) -> Result<()> {
+        self.api.delete_conversation(&conversation_id).await?;
+        println!("Conversation deleted: {}", conversation_id);
+        Ok(())
+    }
 }

server/kordophone/Bridge/MBIMHTTPConnection.m

@@ -14,6 +14,7 @@
 #import "MBIMAuthToken.h"
 #import "MBIMUpdateQueue.h"
 #import "MBIMURLUtilities.h"
+#import "MBIMLogging.h"
 
 #import <Security/Security.h>
 #import "HTTPMessage.h"
@@ -98,6 +99,10 @@
     __block NSObject<HTTPResponse> *response = nil;
     dispatch_semaphore_t sema = dispatch_semaphore_create(0);
     MBIMBridgeOperationCompletionBlock completion = ^(NSObject<HTTPResponse> *incomingResponse) {
+        if (incomingResponse == nil) {
+            MBIMLogError(@"Operation for %@ %@ completed with a nil response.", method, path);
+        }
+
         response = incomingResponse;
         dispatch_semaphore_signal(sema);
     };
@@ -125,6 +130,11 @@
         response = [_currentOperation cancelAndReturnTimeoutResponse];
     }
 
+    if (response == nil) {
+        MBIMLogError(@"Returning fallback 500 for %@ %@ because the operation produced no response.", method, path);
+        response = [[HTTPErrorResponse alloc] initWithErrorCode:500];
+    }
+    
     return response;
 }
 

server/kordophone/Bridge/Operations/MBIMSendMessageOperation.m

@@ -23,6 +23,8 @@
 
 - (nullable IMChat *)_chatForHandleIDs:(NSArray<NSString *> *)handleIDs registry:(IMChatRegistry *)registry
 {
+    MBIMLogInfo(@"Resolving send target for handles: %@", handleIDs);
+
     IMAccount *iMessageAccount = [[IMAccountController sharedInstance] bestAccountForService:[IMServiceImpl iMessageService]];
     if (!iMessageAccount) {
         MBIMLogError(@"Unable to find an iMessage account for message send.");
@@ -47,6 +49,12 @@
             chat = [registry chatWithHandle:handle];
         }
 
+        if (chat) {
+            MBIMLogInfo(@"Resolved send target %@ to chat %@", [handle ID], [chat guid] ?: @"<unknown>");
+        } else {
+            MBIMLogError(@"Unable to locate or create chat for handle %@", [handle ID]);
+        }
+
         return chat;
     }
 
@@ -60,6 +68,12 @@
         chat = [registry chatWithHandles:handles displayName:nil joinedChatsOnly:YES];
     }
 
+    if (chat) {
+        MBIMLogInfo(@"Resolved handles %@ to chat %@", handleIDs, [chat guid] ?: @"<unknown>");
+    } else {
+        MBIMLogError(@"Unable to locate or create chat for handles %@", handleIDs);
+    }
+
     return chat;
 }
 
@@ -69,6 +83,13 @@
         return nil;
     }
 
+    NSString *chatGUID = [chat guid];
+    if (!chatGUID) {
+        chatGUID = [[[IMChatRegistry sharedInstance] allGUIDsForChat:chat] firstObject];
+    }
+
+    MBIMLogInfo(@"Preparing sendMessage for chat %@ (bodyLength=%lu attachmentCount=%lu)", chatGUID ?: @"<unknown>", (unsigned long)[messageBody length], (unsigned long)[guids count]);
+
     IMAccount *sendingAccount = [chat account];
     if (!sendingAccount) {
         sendingAccount = [[IMAccountController sharedInstance] bestAccountForService:[IMServiceImpl iMessageService]];
@@ -92,9 +113,15 @@
         [[IMFileTransferCenter sharedInstance] assignTransfer:guid toMessage:reply account:sendingAccount];
     }
 
-    NSMutableDictionary *result = [[reply mbim_dictionaryRepresentation] mutableCopy];
+    NSDictionary *replyRepresentation = [reply mbim_dictionaryRepresentation];
+    if (![replyRepresentation isKindOfClass:[NSDictionary class]]) {
+        MBIMLogError(@"Unable to encode sent message for chat %@", chatGUID ?: @"<unknown>");
+        return nil;
+    }
+
+    NSMutableDictionary *result = [replyRepresentation mutableCopy];
     if (includeConversationGUID) {
-        NSString *conversationGUID = [chat guid];
+        NSString *conversationGUID = chatGUID;
         if (!conversationGUID) {
             conversationGUID = [[[IMChatRegistry sharedInstance] allGUIDsForChat:chat] firstObject];
         }
@@ -104,6 +131,7 @@
         }
     }
 
+    MBIMLogInfo(@"Dispatching IMCore send for chat %@", chatGUID ?: @"<unknown>");
     dispatch_async(dispatch_get_main_queue(), ^{
         [chat sendMessage:reply];
     });
@@ -138,6 +166,7 @@
     NSError *error = nil;
     NSDictionary *args = [NSJSONSerialization JSONObjectWithData:self.requestBodyData options:0 error:&error];
     if (error || args.count == 0) {
+        MBIMLogError(@"Unable to parse sendMessage request body: %@", error);
         self.serverCompletionBlock(response);
         return;
     }
@@ -180,34 +209,65 @@
         }
     }
 
-    dispatch_sync([[self class] sharedIMAccessQueue], ^{
+    MBIMLogInfo(@"sendMessage request received. guid=%@ handleIDs=%@ bodyLength=%lu attachmentGUIDs=%@", hasGUID ? guid : @"<none>", handleIDs, (unsigned long)[messageBody length], transferGUIDs);
-        IMChatRegistry *registry = [IMChatRegistry sharedInstance];
-        IMChat *chat = nil;
-        BOOL includeConversationGUID = NO;
 
-        if (hasGUID) {
+    @try {
-            chat = [registry existingChatWithGUID:guid];
+        dispatch_sync([[self class] sharedIMAccessQueue], ^{
-            if (!chat) {
+            IMChatRegistry *registry = [IMChatRegistry sharedInstance];
-                response = [[MBIMErrorResponse alloc] initWithErrorCode:500 message:@"Chat does not exist for the provided guid."];
+            IMChat *chat = nil;
+            BOOL includeConversationGUID = NO;
+
+            if (hasGUID) {
+                MBIMLogInfo(@"sendMessage targeting existing conversation %@", guid);
+                chat = [registry existingChatWithGUID:guid];
+                if (!chat) {
+                    MBIMLogError(@"Chat does not exist for guid %@", guid);
+                    response = [[MBIMErrorResponse alloc] initWithErrorCode:500 message:@"Chat does not exist for the provided guid."];
+                    return;
+                }
+            } else {
+                MBIMLogInfo(@"sendMessage targeting handles %@", handleIDs);
+                chat = [self _chatForHandleIDs:handleIDs registry:registry];
+                includeConversationGUID = YES;
+                if (!chat) {
+                    response = [[MBIMErrorResponse alloc] initWithErrorCode:500 message:@"Unable to create or locate a chat for the provided handles."];
+                    return;
+                }
+            }
+
+            NSString *resolvedChatGUID = [chat guid];
+            if (!resolvedChatGUID) {
+                resolvedChatGUID = [[[IMChatRegistry sharedInstance] allGUIDsForChat:chat] firstObject];
+            }
+            MBIMLogInfo(@"sendMessage resolved target chat %@", resolvedChatGUID ?: @"<unknown>");
+
+            NSDictionary *result = [self _sendMessage:messageBody
+                                               toChat:chat
+                                      attachmentGUIDs:transferGUIDs
+                               includeConversationGUID:includeConversationGUID];
+            if (!result) {
+                MBIMLogError(@"sendMessage failed before a response payload could be encoded for chat %@", resolvedChatGUID ?: @"<unknown>");
+                response = [[MBIMErrorResponse alloc] initWithErrorCode:500 message:@"Unable to construct sent message response."];
                 return;
             }
-        } else {
-            chat = [self _chatForHandleIDs:handleIDs registry:registry];
-            includeConversationGUID = YES;
-            if (!chat) {
-                response = [[MBIMErrorResponse alloc] initWithErrorCode:500 message:@"Unable to create or locate a chat for the provided handles."];
-                return;
-            }
-        }
 
-        NSDictionary *result = [self _sendMessage:messageBody
+            NSObject<HTTPResponse> *jsonResponse = [MBIMJSONDataResponse responseWithJSONObject:result];
-                                           toChat:chat
+            if (jsonResponse) {
-                                  attachmentGUIDs:transferGUIDs
+                response = jsonResponse;
-                           includeConversationGUID:includeConversationGUID];
+            } else {
-        if (result) {
+                MBIMLogError(@"Unable to encode sendMessage JSON response for chat %@", resolvedChatGUID ?: @"<unknown>");
-            response = [MBIMJSONDataResponse responseWithJSONObject:result];
+                response = [[MBIMErrorResponse alloc] initWithErrorCode:500 message:@"Unable to encode sendMessage response."];
-        }
+            }
-    });
+        });
+    } @catch (NSException *exception) {
+        MBIMLogError(@"Unhandled exception during sendMessage. name=%@ reason=%@ userInfo=%@", exception.name, exception.reason, exception.userInfo);
+        response = [[MBIMErrorResponse alloc] initWithErrorCode:500 message:@"Unhandled exception while sending message. Check server logs."];
+    }
+
+    if (response == nil) {
+        MBIMLogError(@"sendMessage completed without producing a response. guid=%@ handleIDs=%@", hasGUID ? guid : @"<none>", handleIDs);
+        response = [[MBIMErrorResponse alloc] initWithErrorCode:500 message:@"sendMessage did not produce a response. Check server logs."];
+    }
     
     self.serverCompletionBlock(response);
 }