diff --git a/src/Core/LdapPacket.cs b/src/Core/LdapPacket.cs index 539196a..d8336eb 100644 --- a/src/Core/LdapPacket.cs +++ b/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 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 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); + } } } diff --git a/src/Server/LdapProxy.cs b/src/Server/LdapProxy.cs index 71c1ee0..d05c820 100644 --- a/src/Server/LdapProxy.cs +++ b/src/Server/LdapProxy.cs @@ -39,6 +39,8 @@ public class LdapProxy private LdapProxyAuthenticationStatus _status; + private volatile bool _closing; + private static readonly ConcurrentDictionary _usersDn2Cn = new(); private static readonly ConcurrentDictionary _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,19 +71,27 @@ 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> process) + + private async Task DataExchange(TcpClient source, Stream sourceStream, TcpClient target, Stream targetStream, Func> 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 { @@ -89,11 +99,17 @@ private async Task DataExchange(TcpClient source, Stream sourceStream, TcpClient 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(); + 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(); + + 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, diff --git a/src/Server/LdapStream/LdapStreamReader.cs b/src/Server/LdapStream/LdapStreamReader.cs index c1a1e9c..b23fbb5 100644 --- a/src/Server/LdapStream/LdapStreamReader.cs +++ b/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 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 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 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); } diff --git a/src/Services/LdapService.cs b/src/Services/LdapService.cs index b4154ee..171aa06 100644 --- a/src/Services/LdapService.cs +++ b/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 GetBaseDn(Stream ldapConnectedStream, string userName) } public async Task 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 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> GetAllGroups(Stream ldapConnectedStream, LdapPro groups.AddRange(GetGroups(packet)); } + _logger.Debug("Loaded {count} group(s) of user {dn:l}", groups.Count, profile.Dn); + return groups; } diff --git a/tests/LdapStreamTests.cs b/tests/LdapStreamTests.cs index 3fea73c..6176b03 100644 --- a/tests/LdapStreamTests.cs +++ b/tests/LdapStreamTests.cs @@ -64,6 +64,61 @@ public async Task LdapStream_ShouldNotOverflow() } } + [Fact] + public async Task LdapStream_ShouldReadFragmentedPackage() + { + // a packet split between tcp segments: each read returns a single byte + var packet = GetPacket(); + using (var stream = new ChunkedStream(packet, chunkSize: 1)) + { + var reader = new LdapStreamReader(stream); + var result = await reader.ReadLdapPacket(); + Assert.True(result.PacketValid); + Assert.Equal(packet.Length, result.Data.Length); + } + } + + [Fact] + public async Task LdapStream_EmptyStream_ShouldReturnEmptyPacket() + { + // closed connection: the proxy treats an empty packet as end of stream + using (var stream = new MemoryStream()) + { + var reader = new LdapStreamReader(stream); + var result = await reader.ReadLdapPacket(); + Assert.False(result.PacketValid); + Assert.Empty(result.Data); + } + } + + [Fact] + public async Task LdapStream_ShouldReadSequentialFragmentedPackets() + { + // several packets on one connection, each read returns a single byte: + // the reader must not lose the frame boundaries between packets + var packet = GetPacket(); + var twoPackets = new byte[packet.Length * 2]; + packet.CopyTo(twoPackets, 0); + packet.CopyTo(twoPackets, packet.Length); + + using (var stream = new ChunkedStream(twoPackets, chunkSize: 1)) + { + var reader = new LdapStreamReader(stream); + + var first = await reader.ReadLdapPacket(); + Assert.True(first.PacketValid); + Assert.Equal(packet.Length, first.Data.Length); + + var second = await reader.ReadLdapPacket(); + Assert.True(second.PacketValid); + Assert.Equal(packet.Length, second.Data.Length); + + var end = await reader.ReadLdapPacket(); + Assert.False(end.PacketValid); + Assert.Empty(end.Data); + } + } + [Fact] public async Task LdapStream_ShouldNotReadVeryBigPacket() { @@ -77,5 +132,25 @@ public async Task LdapStream_ShouldNotReadVeryBigPacket() Assert.False(result.Data.Length > 2048); } } + + private class ChunkedStream : MemoryStream + { + private readonly int _chunkSize; + + public ChunkedStream(byte[] data, int chunkSize) : base(data) + { + _chunkSize = chunkSize; + } + + public override Task ReadAsync(byte[] buffer, int offset, int count, System.Threading.CancellationToken cancellationToken) + { + return base.ReadAsync(buffer, offset, Math.Min(count, _chunkSize), cancellationToken); + } + + public override ValueTask ReadAsync(Memory buffer, System.Threading.CancellationToken cancellationToken = default) + { + return base.ReadAsync(buffer.Slice(0, Math.Min(buffer.Length, _chunkSize)), cancellationToken); + } + } } }