DEV-1449

src/Core/LdapPacket.cs

@@ -23,6 +23,7 @@
 //OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE
 //SOFTWARE.
 
+using Serilog;
 using System;
 using System.IO;
 using System.Linq;
@@ -97,9 +98,11 @@ public static async Task<LdapPacket> ParsePacket(Stream stream)
                     var packet = new LdapPacket(Tag.Parse(tagByte[0]));
                     packet.ChildAttributes.AddRange(await ParseAttributes(contentBytes, 0, contentLength.Length));
 
-                    if (packet.ChildAttributes.Any(attr => attr.LdapOperation == Core.LdapOperation.SearchResultDone))
+                    var searchDone = packet.ChildAttributes.FirstOrDefault(attr => attr.LdapOperation == Core.LdapOperation.SearchResultDone);
+                    if (searchDone != null)
                     {
-                        return null; //thats all, stop reading
+                        LogNonSuccessResult(searchDone);
+                        return null;
                     }
 
                     return packet;
@@ -113,5 +116,28 @@ public static async Task<LdapPacket> ParsePacket(Stream stream)
 
             return null;
         }
+
+        private static void LogNonSuccessResult(LdapAttribute searchDone)
+        {
+            var resultAttr = searchDone.ChildAttributes.FirstOrDefault(attr => attr.DataType == UniversalDataType.Enumerated);
+            if (resultAttr == null || resultAttr.Value.Length == 0)
+            {
+                return;
+            }
+
+            var result = (LdapResult)resultAttr.GetValue();
+            if (result == LdapResult.success)
+            {
+                return;
+            }
+
+            if (result is LdapResult.referral or LdapResult.sizeLimitExceeded or LdapResult.timeLimitExceeded)
+            {
+                Log.Logger.Debug("LDAP search operation completed with {result} result", result);
+                return;
+            }
+
+            Log.Logger.Warning("LDAP search operation completed with {result} result", result);
+        }
     }
 }

src/Server/LdapProxy.cs

@@ -39,6 +39,8 @@ public class LdapProxy
 
         private LdapProxyAuthenticationStatus _status;
 
+        private volatile bool _closing;
+
         private static readonly ConcurrentDictionary<string, string> _usersDn2Cn = new();
         private static readonly ConcurrentDictionary<string, string> _usersCn2Dn = new();
 
@@ -58,7 +60,7 @@ public LdapProxy(TcpClient clientConnection, Stream clientStream, TcpClient serv
             _clientConfig = clientConfig ?? throw new ArgumentNullException(nameof(clientConfig));
             _logger = logger ?? throw new ArgumentNullException(nameof(logger));
 
-            _ldapService = new LdapService(clientConfig);
+            _ldapService = new LdapService(clientConfig, logger);
             _nameResolverService = nameResolverService;
         }
 
@@ -69,31 +71,45 @@ public async Task ProcessDataExchange()
 
             _logger.Information("Opened {client} => {server} client {clientName:l}", from, to, _clientConfig.Name);
 
+            var requestStats = new ExchangeStats();
+            var responseStats = new ExchangeStats();
+
             await Task.WhenAny(
-                DataExchange(_clientConnection, _clientStream, _serverConnection, _serverStream, ParseAndProcessRequest),
-                DataExchange(_serverConnection, _serverStream, _clientConnection, _clientStream, ParseAndProcessResponse));
-
-            _logger.Debug("Closed {client} => {server} client {clientName:l}", from, to, _clientConfig.Name);
+                DataExchange(_clientConnection, _clientStream, _serverConnection, _serverStream, ParseAndProcessRequest, requestStats),
+                DataExchange(_serverConnection, _serverStream, _clientConnection, _clientStream, ParseAndProcessResponse, responseStats));
+
+            _closing = true;
+
+            _logger.Information("Closed {client} => {server} client {clientName:l} : requests {requestPackets} packet(s) / {requestBytes} byte(s), responses {responsePackets} packet(s) / {responseBytes} byte(s)",
+                from, to, _clientConfig.Name, requestStats.Packets, requestStats.Bytes, responseStats.Packets, responseStats.Bytes);
         }
-
 
-        private async Task DataExchange(TcpClient source, Stream sourceStream, TcpClient target, Stream targetStream, Func<byte[], int, Task<(byte[], int)>> process)
+
+        private async Task DataExchange(TcpClient source, Stream sourceStream, TcpClient target, Stream targetStream, Func<byte[], int, Task<(byte[], int)>> process, ExchangeStats stats)
         {
+            var from = source.Client.RemoteEndPoint.ToString();
+            var to = target.Client.RemoteEndPoint.ToString();
             try
             {
-                var streamReader = new LdapStreamReader(sourceStream);
+                var streamReader = new LdapStreamReader(sourceStream, _logger);
                 LdapPacketBuffer ldapPacket;
                 do
                 {
                     //read packet
                     ldapPacket = await streamReader.ReadLdapPacket();
                     if (ldapPacket.Data.Length == 0)
                     {
+                        _logger.Debug("Connection {from} => {to} finished, end of stream", from, to);
                         break;
                     }
+
+                    stats.Packets++;
+                    stats.Bytes += ldapPacket.Data.Length;
+
                     if (!ldapPacket.PacketValid)
                     {
                         // bypass data
+                        _logger.Warning("Bypassed {length} byte(s) of unparsed data from {from} to {to}", ldapPacket.Data.Length, from, to);
                         await targetStream.WriteAsync(ldapPacket.Data, 0, ldapPacket.Data.Length);
                         continue;
                     }
@@ -110,20 +126,32 @@ private async Task DataExchange(TcpClient source, Stream sourceStream, TcpClient
                     }
                 } while (ldapPacket.Data.Length > 0);
             }
-            catch (IOException)
+            catch (IOException) when (_closing)
             {
-                //connection closed unexpectly
-                //_logger.Debug(ioex, "proxy");
+                //other side has finished and streams are being disposed, aborted read is expected here
+            }
+            catch (IOException ex)
+            {
+                _logger.Warning("Connection {from} => {to} closed unexpectedly: {message:l}", from, to, ex.Message);
             }
             catch (Exception ex)
             {
-                _logger.Error(ex, "Data exchange error from {client} to {server}", source.Client.RemoteEndPoint, target.Client.RemoteEndPoint);
+                _logger.Error(ex, "Data exchange error from {from} to {to}", from, to);
             }
         }
 
         private async Task<(byte[], int)> ParseAndProcessRequest(byte[] data, int length)
         {
-            var request = await LdapRequest.FromBytesAsync(data);
+            LdapRequest request;
+            try
+            {
+                request = await LdapRequest.FromBytesAsync(data);
+            }
+            catch (Exception ex)
+            {
+                _logger.Warning(ex, "Failed to parse {length} byte(s) request from {client}, bypassing as-is", length, _clientConnection.Client.RemoteEndPoint);
+                return await Task.FromResult((data, length));
+            }
 
             if (request.RequestType == LdapRequestType.SearchRequest)
             {
@@ -196,6 +224,7 @@ private async Task DataExchange(TcpClient source, Stream sourceStream, TcpClient
 
                     if (bound)  //first factor authenticated
                     {
+                        _logger.Debug("User '{user:l}' first factor verified at {server}", _userName, _serverConnection.Client.RemoteEndPoint);
                         var bypass = false;
 
                         //apply login transformation users if any
@@ -337,24 +366,33 @@ private async Task DataExchange(TcpClient source, Stream sourceStream, TcpClient
 
             if (_status == LdapProxyAuthenticationStatus.UserDnSearch)
             {
-                var packet = await LdapPacket.ParsePacket(data);
-                var searchResultEntry = packet.ChildAttributes.SingleOrDefault(c => c.LdapOperation == LdapOperation.SearchResultEntry);
-
-                if (searchResultEntry != null)
+                try
                 {
-                    var userDn = searchResultEntry.ChildAttributes[0].GetValue<string>();
+                    var packet = await LdapPacket.ParsePacket(data);
+                    var searchResultEntry = packet.ChildAttributes.SingleOrDefault(c => c.LdapOperation == LdapOperation.SearchResultEntry);
 
-                    if (_lookupUserName != null && userDn != null)
+                    if (searchResultEntry != null)
                     {
-                        userDn = userDn.ToLower(); //becouse some apps do it
+                        var userDn = searchResultEntry.ChildAttributes[0].GetValue<string>();
+
+                        if (_lookupUserName != null && userDn != null)
+                        {
+                            userDn = userDn.ToLower(); //becouse some apps do it
+
+                            _usersDn2Cn.TryRemove(userDn, out _);
+                            _usersDn2Cn.TryAdd(userDn, _lookupUserName);
 
-                        _usersDn2Cn.TryRemove(userDn, out _);
-                        _usersDn2Cn.TryAdd(userDn, _lookupUserName);
+                            _usersCn2Dn.TryRemove(_lookupUserName, out _);
+                            _usersCn2Dn.TryAdd(_lookupUserName, userDn);
 
-                        _usersCn2Dn.TryRemove(_lookupUserName, out _);
-                        _usersCn2Dn.TryAdd(_lookupUserName, userDn);
+                            _logger.Debug("Resolved user '{user:l}' DN: {dn:l}", _lookupUserName, userDn);
+                        }
                     }
                 }
+                catch (Exception ex)
+                {
+                    _logger.Warning(ex, "Failed to parse DN search response of {length} byte(s), bypassing as-is", length);
+                }
 
                 _status = LdapProxyAuthenticationStatus.None;
             }
@@ -459,6 +497,12 @@ private bool IsMemberOf(LdapProfile profile, string group)
         }
     }
 
+    internal class ExchangeStats
+    {
+        public long Packets;
+        public long Bytes;
+    }
+
     public enum LdapProxyAuthenticationStatus
     {
         None,

src/Server/LdapStream/LdapStreamReader.cs

@@ -1,4 +1,5 @@
-using MultiFactor.Ldap.Adapter.Core;
+using MultiFactor.Ldap.Adapter.Core;
+using Serilog;
 using System;
 using System.IO;
 using System.Threading.Tasks;
@@ -8,15 +9,19 @@ namespace MultiFactor.Ldap.Adapter.Server.LdapStream
     public class LdapStreamReader 
     {
         private const int DEFAULT_BUFFER_SIZE = 32768;
+        private const int MAX_PACKET_SIZE = 64 * Constants.BYTES_IN_MB;
 
         private byte[] _readBuffer;
         private Stream _inputStream;
-        public LdapStreamReader(Stream inputStream) : this(inputStream, DEFAULT_BUFFER_SIZE)
+        private readonly ILogger _logger;
+
+        public LdapStreamReader(Stream inputStream, ILogger logger = null) : this(inputStream, DEFAULT_BUFFER_SIZE, logger)
         { }
-        public LdapStreamReader(Stream inputStream, int bufferSize)
+        public LdapStreamReader(Stream inputStream, int bufferSize, ILogger logger = null)
         {
             _readBuffer = new byte[bufferSize];
             _inputStream = inputStream;
+            _logger = logger ?? Log.Logger;
         }
 
         private LdapPacketBuffer GetResultPacket(byte[] buffer, int totalRead, bool packetValid)
@@ -32,20 +37,37 @@ private LdapPacketBuffer GetResultPacket(byte[] buffer, int totalRead, bool pack
 
         public async Task<LdapPacketBuffer> ReadLdapPacket()
         {
-            int totalRead = await _inputStream.ReadAsync(_readBuffer, 0, 2);
-            if (totalRead < 2)
+            int totalRead;
+            try
             {
-                return GetResultPacket(_readBuffer, totalRead, false);
+                await _inputStream.ReadExactlyAsync(_readBuffer, 0, 2);
+                totalRead = 2;
             }
-            //  handle multi-octate BER LEN!!
+            catch (EndOfStreamException)
+            {
+                _logger.Debug("End of stream while reading LDAP packet header, connection closed");
+                return GetResultPacket(_readBuffer, 0, false);
+            }
+            //  handle multi-octet BER LEN
             if (_readBuffer[1] >> 7 == 1)
             {
-                totalRead += await _inputStream.ReadAsync(_readBuffer, totalRead, _readBuffer[1] & 127);
+                var lengthOctets = _readBuffer[1] & 127;
+                try
+                {
+                    await _inputStream.ReadExactlyAsync(_readBuffer, totalRead, lengthOctets);
+                    totalRead += lengthOctets;
+                }
+                catch (EndOfStreamException)
+                {
+                    _logger.Warning("Unexpected end of stream while reading LDAP packet length: expected {expected} length octet(s)", lengthOctets);
+                    return GetResultPacket(_readBuffer, 0, false);
+                }
             }
             var berLen = await Utils.BerLengthToInt(_readBuffer, 1);
             int berLenWithHeading = berLen.Length + berLen.BerByteCount + 1;
-            if(berLenWithHeading > 64 * Constants.BYTES_IN_MB)
+            if (berLen.Length < 0 || berLenWithHeading > MAX_PACKET_SIZE)
             {
+                _logger.Warning("LDAP packet of {size} byte(s) exceeds the {limit} byte(s) limit and will be bypassed without processing", berLenWithHeading, MAX_PACKET_SIZE);
                 return GetResultPacket(_readBuffer, totalRead, false);
             }
             if(berLenWithHeading >= _readBuffer.Length)
@@ -54,6 +76,7 @@ public async Task<LdapPacketBuffer> ReadLdapPacket()
                 Array.Copy(_readBuffer, newBuffer, totalRead);
                 _readBuffer = newBuffer;
             }
+
             // read packet until end
             int attempts = 0;
             while (totalRead < berLenWithHeading)
@@ -64,6 +87,7 @@ public async Task<LdapPacketBuffer> ReadLdapPacket()
                     attempts++;
                     if (attempts > 3)
                     {
+                        _logger.Warning("Unexpected end of stream while reading LDAP packet: got {read} of {expected} byte(s)", totalRead, berLenWithHeading);
                         return GetResultPacket(_readBuffer, totalRead, false);
                     }
 

src/Services/LdapService.cs

@@ -5,6 +5,7 @@
 using MultiFactor.Ldap.Adapter.Configuration;
 using MultiFactor.Ldap.Adapter.Core;
 using MultiFactor.Ldap.Adapter.Core.NameResolving;
+using Serilog;
 using System;
 using System.Collections.Generic;
 using System.IO;
@@ -19,10 +20,12 @@ public class LdapService
         //must not repeat proxied messages ids
         private int _messageId = Int32.MaxValue - 9999;
         private readonly ClientConfiguration _config;
+        private readonly ILogger _logger;
 
-        public LdapService(ClientConfiguration config)
+        public LdapService(ClientConfiguration config, ILogger logger = null)
         {
             _config = config ?? throw new ArgumentNullException(nameof(config));
+            _logger = logger ?? Log.Logger;
         }
 
         #region requests builders
@@ -61,7 +64,7 @@ private LdapPacket BuildLoadProfileRequest(string userName, string baseDn)
             searchRequest.ChildAttributes.Add(new LdapAttribute(UniversalDataType.OctetString, baseDn));    //base dn
             searchRequest.ChildAttributes.Add(new LdapAttribute(UniversalDataType.Enumerated, (byte)2));    //scope: subtree
             searchRequest.ChildAttributes.Add(new LdapAttribute(UniversalDataType.Enumerated, (byte)3));    //aliases: never
-            searchRequest.ChildAttributes.Add(new LdapAttribute(UniversalDataType.Integer, byte.MaxValue - 1)); //size limit: 127
+            searchRequest.ChildAttributes.Add(new LdapAttribute(UniversalDataType.Integer, byte.MaxValue - 1)); //size limit: 254
             searchRequest.ChildAttributes.Add(new LdapAttribute(UniversalDataType.Integer, (byte)60));      //time limit: 60
             searchRequest.ChildAttributes.Add(new LdapAttribute(UniversalDataType.Boolean, false));         //typesOnly: false
 
@@ -322,6 +325,8 @@ public async Task<string> GetBaseDn(Stream ldapConnectedStream, string userName)
         }
         public async Task<LdapProfile> LoadProfile(Stream ldapConnectedStream, string userName, string baseDn)
         {
+            _logger.Debug("Loading profile of user '{user:l}' in {baseDn:l}", userName, baseDn);
+
             var request = BuildLoadProfileRequest(userName, baseDn);
             var requestData = request.GetBytes();
 
@@ -374,11 +379,16 @@ public async Task<LdapProfile> LoadProfile(Stream ldapConnectedStream, string us
                 }
             }
 
-            if (profile != null)
+            if (profile == null)
             {
-                profile.Email = GetMail(mailEntries);
+                _logger.Debug("Profile of user '{user:l}' was not found in {baseDn:l}", userName, baseDn);
+
+                return null;
             }
 
+            profile.Email = GetMail(mailEntries);
+            _logger.Debug("Loaded profile of user '{user:l}' ({dn:l})", userName, profile.Dn);
+
             return profile;
         }
 
@@ -405,6 +415,8 @@ public async Task<List<string>> GetAllGroups(Stream ldapConnectedStream, LdapPro
                 groups.AddRange(GetGroups(packet));
             }
 
+            _logger.Debug("Loaded {count} group(s) of user {dn:l}", groups.Count, profile.Dn);
+
             return groups;
         }