Add logging to MssqlStream and SSRP instance resolution

Co-authored-by: contact <[email protected]>

Author: cursoragent

sqlx-core/src/mssql/connection/ssrp.rs

@@ -9,26 +9,47 @@ const SVR_RESP: u8 = 0x05;
 const SSRP_TIMEOUT: Duration = Duration::from_secs(1);
 
 pub(crate) async fn resolve_instance_port(server: &str, instance: &str) -> Result<u16, Error> {
+    log::debug!(
+        "resolving SQL Server instance port for '{}' on server '{}'",
+        instance,
+        server
+    );
+
     let mut request = Vec::with_capacity(1 + instance.len() + 1);
     request.push(CLNT_UCAST_INST);
     request.extend_from_slice(instance.as_bytes());
     request.push(0);
 
     let socket = UdpSocket::bind("0.0.0.0:0").await.map_err(|e| {
+        log::debug!("failed to bind UDP socket for SSRP: {}", e);
         err_protocol!("failed to bind UDP socket for SSRP: {}", e)
     })?;
 
+    log::debug!(
+        "sending SSRP CLNT_UCAST_INST request to {}:{} for instance '{}'",
+        server,
+        SSRP_PORT,
+        instance
+    );
+
     socket
         .send_to(&request, (server, SSRP_PORT))
         .await
         .map_err(|e| {
+            log::debug!("failed to send SSRP request to {}:{}: {}", server, SSRP_PORT, e);
             err_protocol!("failed to send SSRP request to {}:{}: {}", server, SSRP_PORT, e)
         })?;
 
     let mut buffer = [0u8; 1024];
     let bytes_read = timeout(SSRP_TIMEOUT, socket.recv(&mut buffer))
         .await
         .map_err(|_| {
+            log::debug!(
+                "SSRP request to {} for instance {} timed out after {:?}",
+                server,
+                instance,
+                SSRP_TIMEOUT
+            );
             err_protocol!(
                 "SSRP request to {} for instance {} timed out after {:?}",
                 server,
@@ -37,6 +58,12 @@ pub(crate) async fn resolve_instance_port(server: &str, instance: &str) -> Resul
             )
         })?
         .map_err(|e| {
+            log::debug!(
+                "failed to receive SSRP response from {} for instance {}: {}",
+                server,
+                instance,
+                e
+            );
             err_protocol!(
                 "failed to receive SSRP response from {} for instance {}: {}",
                 server,
@@ -45,14 +72,25 @@ pub(crate) async fn resolve_instance_port(server: &str, instance: &str) -> Resul
             )
         })?;
 
+    log::debug!(
+        "received SSRP response from {} ({} bytes)",
+        server,
+        bytes_read
+    );
+
     if bytes_read < 3 {
+        log::debug!("SSRP response too short: {} bytes", bytes_read);
         return Err(err_protocol!(
             "SSRP response too short: {} bytes",
             bytes_read
         ));
     }
 
     if buffer[0] != SVR_RESP {
+        log::debug!(
+            "invalid SSRP response type: expected 0x05, got 0x{:02x}",
+            buffer[0]
+        );
         return Err(err_protocol!(
             "invalid SSRP response type: expected 0x05, got 0x{:02x}",
             buffer[0]
@@ -61,6 +99,11 @@ pub(crate) async fn resolve_instance_port(server: &str, instance: &str) -> Resul
 
     let response_size = u16::from_le_bytes([buffer[1], buffer[2]]) as usize;
     if response_size + 3 > bytes_read {
+        log::debug!(
+            "SSRP response size mismatch: expected {} bytes, got {}",
+            response_size + 3,
+            bytes_read
+        );
         return Err(err_protocol!(
             "SSRP response size mismatch: expected {} bytes, got {}",
             response_size + 3,
@@ -69,13 +112,22 @@ pub(crate) async fn resolve_instance_port(server: &str, instance: &str) -> Resul
     }
 
     let response_data = String::from_utf8(buffer[3..(3 + response_size)].to_vec())
-        .map_err(|e| err_protocol!("SSRP response is not valid UTF-8: {}", e))?;
+        .map_err(|e| {
+            log::debug!("SSRP response is not valid UTF-8: {}", e);
+            err_protocol!("SSRP response is not valid UTF-8: {}", e)
+        })?;
+
+    log::debug!("SSRP response data: {}", response_data);
 
     parse_ssrp_response(&response_data, instance)
 }
 
 fn parse_ssrp_response(data: &str, instance_name: &str) -> Result<u16, Error> {
     let instances: Vec<&str> = data.split(";;").collect();
+    log::debug!(
+        "parsing SSRP response, found {} instance entries",
+        instances.len()
+    );
 
     for instance_data in instances {
         if instance_data.is_empty() {
@@ -94,16 +146,42 @@ fn parse_ssrp_response(data: &str, instance_name: &str) -> Result<u16, Error> {
         }
 
         if let Some(name) = properties.get("InstanceName") {
+            log::debug!("found instance '{}' in SSRP response", name);
+            
             if name.eq_ignore_ascii_case(instance_name) {
+                log::debug!(
+                    "instance '{}' matches requested instance '{}'",
+                    name,
+                    instance_name
+                );
+                
                 if let Some(tcp_port_str) = properties.get("tcp") {
-                    return tcp_port_str.parse::<u16>().map_err(|e| {
+                    let port = tcp_port_str.parse::<u16>().map_err(|e| {
+                        log::debug!(
+                            "invalid TCP port '{}' in SSRP response: {}",
+                            tcp_port_str,
+                            e
+                        );
                         err_protocol!(
                             "invalid TCP port '{}' in SSRP response: {}",
                             tcp_port_str,
                             e
                         )
-                    });
+                    })?;
+                    
+                    log::debug!(
+                        "resolved instance '{}' to port {}",
+                        instance_name,
+                        port
+                    );
+                    
+                    return Ok(port);
                 } else {
+                    log::debug!(
+                        "instance '{}' found but no TCP port available in properties: {:?}",
+                        instance_name,
+                        properties.keys().collect::<Vec<_>>()
+                    );
                     return Err(err_protocol!(
                         "instance '{}' found but no TCP port available",
                         instance_name
@@ -113,6 +191,10 @@ fn parse_ssrp_response(data: &str, instance_name: &str) -> Result<u16, Error> {
         }
     }
 
+    log::debug!(
+        "instance '{}' not found in SSRP response",
+        instance_name
+    );
     Err(err_protocol!(
         "instance '{}' not found in SSRP response",
         instance_name

sqlx-core/src/mssql/connection/stream.rs

@@ -57,7 +57,10 @@ impl MssqlStream {
             options.port
         };
 
+        log::debug!("establishing TCP connection to {}:{}", options.host, port);
         let tcp_stream = TcpStream::connect((&*options.host, port)).await?;
+        log::debug!("TCP connection established to {}:{}", options.host, port);
+        
         let wrapped_stream = TlsPreloginWrapper::new(tcp_stream);
         let inner = BufStream::new(MaybeTlsStream::Raw(wrapped_stream));