Added OnLogEntry event to iSCSIServer and VirtualSCSITarget

Implementors can now subscribe to OnLogEntry events and receive log
events.

ISCSI/ISCSI.csproj

@@ -115,6 +115,7 @@
     <Compile Include="Server\ServerResponseHelper.cs" />
     <Compile Include="Server\ConnectionState.cs" />
     <Compile Include="Server\TargetResponseHelper.cs" />
+    <Compile Include="Utilities\LogEntry.cs" />
     <Compile Include="Utilities\SocketUtils.cs" />
   </ItemGroup>
   <ItemGroup>

ISCSI/SCSITarget/VirtualSCSITarget.cs

@@ -10,7 +10,6 @@ using System.IO;
 using System.Text;
 using System.Runtime.InteropServices;
 using DiskAccessLibrary;
-using ISCSI.Server; // FIXME
 using Utilities;
 
 namespace SCSI
@@ -20,6 +19,8 @@ namespace SCSI
         private List<Disk> m_disks;
         private object m_ioLock = new object(); // "In multithreaded applications, a stream must be accessed in a thread-safe way"
 
+        public event EventHandler<LogEntry> OnLogEntry;
+
         public VirtualSCSITarget(List<Disk> disks)
         {
             m_disks = disks;
@@ -34,7 +35,7 @@ namespace SCSI
             }
             catch(UnsupportedSCSICommandException)
             {
-                ISCSIServer.Log("[ExecuteCommand] Unsupported SCSI Command (0x{0})", commandBytes[0].ToString("X"));
+                Log(Severity.Error, "Unsupported SCSI Command (0x{0})", commandBytes[0].ToString("X"));
                 response = FormatSenseData(SenseDataParameter.GetIllegalRequestUnsupportedCommandCodeSenseData());
                 return SCSIStatusCodeName.CheckCondition;
             }
@@ -44,7 +45,7 @@ namespace SCSI
 
         public SCSIStatusCodeName ExecuteCommand(SCSICommandDescriptorBlock command, LUNStructure lun, byte[] data, out byte[] response)
         {
-            ISCSIServer.Log("[ExecuteCommand] {0}", command.OpCode);
+            Log(Severity.Verbose, "Executing command: {0}", command.OpCode);
             if (command.OpCode == SCSIOpCodeName.ReportLUNs)
             {
                 uint allocationLength = command.TransferLength;
@@ -52,7 +53,7 @@ namespace SCSI
             }
             else if (lun >= m_disks.Count)
             {
-                ISCSIServer.Log("LUN {0}: Invalid LUN", lun);
+                Log(Severity.Error, "LUN {0}: Invalid LUN", lun);
                 response = FormatSenseData(SenseDataParameter.GetIllegalRequestInvalidLUNSenseData());
                 return SCSIStatusCodeName.CheckCondition;
             }
@@ -114,7 +115,7 @@ namespace SCSI
             }
             else
             {
-                ISCSIServer.Log("[ExecuteCommand] Unsupported SCSI Command (0x{0})", command.OpCode.ToString("X"));
+                Log(Severity.Error, "Unsupported SCSI Command (0x{0})", command.OpCode.ToString("X"));
                 response = FormatSenseData(SenseDataParameter.GetIllegalRequestUnsupportedCommandCodeSenseData());
                 return SCSIStatusCodeName.CheckCondition;
             }
@@ -139,14 +140,14 @@ namespace SCSI
                 }
                 else
                 {
-                    ISCSIServer.Log("[Inquiry] Invalid request");
+                    Log(Severity.Error, "Inquiry: Invalid request");
                     response = FormatSenseData(SenseDataParameter.GetIllegalRequestInvalidFieldInCDBSenseData());
                     return SCSIStatusCodeName.CheckCondition;
                 }
             }
             else
             {
-                ISCSIServer.Log("[Inquiry] Page code: 0x{0}", command.PageCode.ToString("X"));
+                Log(Severity.Verbose, "Inquiry: Page code: 0x{0}", command.PageCode.ToString("X"));
                 switch (command.PageCode)
                 {
                     case VitalProductDataPageName.SupportedVPDPages:
@@ -197,7 +198,7 @@ namespace SCSI
                         }
                     default:
                         {
-                            ISCSIServer.Log("[Inquiry] Unsupported VPD Page request (0x{0})", command.PageCode.ToString("X"));
+                            Log(Severity.Error, "Inquiry: Unsupported VPD Page request (0x{0})", command.PageCode.ToString("X"));
                             response = FormatSenseData(SenseDataParameter.GetIllegalRequestInvalidFieldInCDBSenseData());
                             return SCSIStatusCodeName.CheckCondition;
                         }
@@ -214,7 +215,7 @@ namespace SCSI
 
         public SCSIStatusCodeName ModeSense6(ModeSense6CommandDescriptorBlock command, LUNStructure lun, out byte[] response)
         {
-            ISCSIServer.Log("[ModeSense6] Page code: 0x{0}, Sub page code: 0x{1}", command.PageCode.ToString("X"), command.SubpageCode.ToString("X"));
+            Log(Severity.Verbose, "ModeSense6: Page code: 0x{0}, Sub page code: 0x{1}", command.PageCode.ToString("X"), command.SubpageCode.ToString("X"));
             byte[] pageData;
 
             switch ((ModePageCodeName)command.PageCode)
@@ -248,7 +249,7 @@ namespace SCSI
                         }
                         else
                         {
-                            ISCSIServer.Log("[ModeSense6] Power condition subpage 0x{0} is not implemented", command.SubpageCode.ToString("x"));
+                            Log(Severity.Error, "ModeSense6: Power condition subpage 0x{0} is not implemented", command.SubpageCode.ToString("x"));
                             response = FormatSenseData(SenseDataParameter.GetIllegalRequestInvalidFieldInCDBSenseData());
                             return SCSIStatusCodeName.CheckCondition;
                         }
@@ -279,7 +280,7 @@ namespace SCSI
                     }
                 default:
                     {
-                        ISCSIServer.Log("[ModeSense6] ModeSense6 page 0x{0} is not implemented", command.PageCode.ToString("x"));
+                        Log(Severity.Error, "ModeSense6: ModeSense6 page 0x{0} is not implemented", command.PageCode.ToString("x"));
                         response = FormatSenseData(SenseDataParameter.GetIllegalRequestInvalidFieldInCDBSenseData());
                         return SCSIStatusCodeName.CheckCondition;
                     }
@@ -346,6 +347,7 @@ namespace SCSI
         {
             Disk disk = m_disks[lun];
             int sectorCount = (int)command.TransferLength;
+            Log(Severity.Verbose, "LUN {0}: Reading {1} blocks starting from LBA {2}", lun, sectorCount, (long)command.LogicalBlockAddress64);
             try
             {
                 lock (m_ioLock)
@@ -356,7 +358,7 @@ namespace SCSI
             }
             catch (ArgumentOutOfRangeException)
             {
-                ISCSIServer.Log("[Read] Read error: LBA out of range");
+                Log(Severity.Error, "Read error: LBA out of range");
                 response = FormatSenseData(SenseDataParameter.GetIllegalRequestLBAOutOfRangeSenseData());
                 return SCSIStatusCodeName.CheckCondition;
             }
@@ -365,13 +367,13 @@ namespace SCSI
                 int error = Marshal.GetHRForException(ex);
                 if (error == (int)Win32Error.ERROR_CRC)
                 {
-                    ISCSIServer.Log("[Read] Read error: CRC error");
+                    Log(Severity.Error, "Read error: CRC error");
                     response = FormatSenseData(SenseDataParameter.GetWriteFaultSenseData());
                     return SCSIStatusCodeName.CheckCondition;
                 }
                 else
                 {
-                    ISCSIServer.Log("[Read] Read error: {0}", ex.ToString());
+                    Log(Severity.Error, "Read error: {0}", ex.ToString());
                     response = FormatSenseData(SenseDataParameter.GetMediumErrorUnrecoverableReadErrorSenseData());
                     return SCSIStatusCodeName.CheckCondition;
                 }
@@ -425,11 +427,13 @@ namespace SCSI
             Disk disk = m_disks[lun];
             if (disk.IsReadOnly)
             {
+                Log(Severity.Verbose, "LUN {0}: Refused attempt to write to a read-only disk", lun);
                 SenseDataParameter senseData = SenseDataParameter.GetDataProtectSenseData();
                 response = senseData.GetBytes();
                 return SCSIStatusCodeName.CheckCondition;
             }
 
+            Log(Severity.Verbose, "LUN {0}: Writing {1} blocks starting from LBA {2}", lun, command.TransferLength, (long)command.LogicalBlockAddress64);
             try
             {
                 lock (m_ioLock)
@@ -441,18 +445,33 @@ namespace SCSI
             }
             catch (ArgumentOutOfRangeException)
             {
-                ISCSIServer.Log("[Write] Write error: LBA out of range");
+                Log(Severity.Error, "Write error: LBA out of range");
                 response = FormatSenseData(SenseDataParameter.GetIllegalRequestLBAOutOfRangeSenseData());
                 return SCSIStatusCodeName.CheckCondition;
             }
             catch (IOException ex)
             {
-                ISCSIServer.Log("[Write] Write error: {0}", ex.ToString());
+                Log(Severity.Error, "Write error: {0}", ex.ToString());
                 response = FormatSenseData(SenseDataParameter.GetMediumErrorWriteFaultSenseData());
                 return SCSIStatusCodeName.CheckCondition;
             }
         }
 
+        public void Log(Severity severity, string message)
+        {
+            // To be thread-safe we must capture the delegate reference first
+            EventHandler<LogEntry> handler = OnLogEntry;
+            if (handler != null)
+            {
+                handler(this, new LogEntry(DateTime.Now, severity, "Virtual SCSI Target", message));
+            }
+        }
+
+        public void Log(Severity severity, string message, params object[] args)
+        {
+            Log(severity, String.Format(message, args));
+        }
+
         public List<Disk> Disks
         {
             get

ISCSI/Server/ISCSIServer.cs

@@ -42,8 +42,7 @@ namespace ISCSI.Server
         private bool m_listening;
         private static List<ConnectionState> m_activeConnections = new List<ConnectionState>();
 
-        public static object m_logSyncLock = new object();
-        private static FileStream m_logFile;
+        public event EventHandler<LogEntry> OnLogEntry;
         
         public ISCSIServer(List<ISCSITarget> targets) : this(targets, DefaultPort)
         { }
@@ -58,26 +57,13 @@ namespace ISCSI.Server
         {
             m_port = port;
             m_targets = targets;
-
-            if (logFilePath != String.Empty)
-            {
-                try
-                {
-                    // We must avoid using buffered writes, using it will negatively affect the performance and reliability.
-                    // Note: once the file system write buffer is filled, Windows may delay any (buffer-dependent) pending write operations, which will create a deadlock.
-                    m_logFile = new FileStream(logFilePath, FileMode.Append, FileAccess.Write, FileShare.Read, 0x1000, FileOptions.WriteThrough);
-                }
-                catch
-                {
-                    Console.WriteLine("Cannot open log file");
-                }
-            }
         }
 
         public void Start()
         {
             if (!m_listening)
             {
+                Log(Severity.Information, "Starting Server");
                 m_listening = true;
 
                 m_listenerSocket = new Socket(AddressFamily.InterNetwork, SocketType.Stream, ProtocolType.Tcp);
@@ -106,7 +92,7 @@ namespace ISCSI.Server
                 return;
             }
 
-            Log("[OnConnectRequest] New connection has been accepted");
+            Log(Severity.Information, "New connection has been accepted");
 
             ConnectionState state = new ConnectionState();
             state.ReceiveBuffer = new byte[ConnectionState.ReceiveBufferSize];
@@ -119,25 +105,20 @@ namespace ISCSI.Server
             }
             catch (ObjectDisposedException)
             {
-                Log("[OnConnectRequest] BeginReceive ObjectDisposedException");
+                Log(Severity.Debug, "[OnConnectRequest] BeginReceive ObjectDisposedException");
             }
             catch (SocketException ex)
             {
-                Log("[OnConnectRequest] BeginReceive SocketException: " + ex.Message);
+                Log(Severity.Debug, "[OnConnectRequest] BeginReceive SocketException: {0}", ex.Message);
             }
             m_listenerSocket.BeginAccept(ConnectRequestCallback, m_listenerSocket);
         }
 
         public void Stop()
         {
+            Log(Severity.Information, "Stopping Server");
             m_listening = false;
             SocketUtils.ReleaseSocket(m_listenerSocket);
-
-            if (m_logFile != null)
-            {
-                m_logFile.Close();
-                m_logFile = null;
-            }
         }
 
         private void ReceiveCallback(IAsyncResult result)
@@ -161,12 +142,12 @@ namespace ISCSI.Server
             }
             catch (ObjectDisposedException)
             {
-                Log("[ReceiveCallback] EndReceive ObjectDisposedException");
+                Log(Severity.Debug, "[ReceiveCallback] EndReceive ObjectDisposedException");
                 return;
             }
             catch (SocketException ex)
             {
-                Log("[ReceiveCallback] EndReceive SocketException: " + ex.Message);
+                Log(Severity.Debug, "[ReceiveCallback] EndReceive SocketException: {0}", ex.Message);
                 return;
             }
 
@@ -174,7 +155,7 @@ namespace ISCSI.Server
             {
                 // The other side has closed the connection
                 clientSocket.Close();
-                Log("[ReceiveCallback] The initiator has closed the connection");
+                Log(Severity.Verbose, "The initiator has closed the connection");
                 // Wait for pending I/O to complete.
                 state.RunningSCSICommands.WaitUntilZero();
                 lock (m_activeConnections)
@@ -197,11 +178,11 @@ namespace ISCSI.Server
             }
             catch (ObjectDisposedException)
             {
-                Log("[ReceiveCallback] BeginReceive ObjectDisposedException");
+                Log(Severity.Debug, "[ReceiveCallback] BeginReceive ObjectDisposedException");
             }
             catch (SocketException ex)
             {
-                Log("[ReceiveCallback] BeginReceive SocketException: " + ex.Message);
+                Log(Severity.Debug, "[ReceiveCallback] BeginReceive SocketException: {0}", ex.Message);
             }
         }
 
@@ -227,7 +208,7 @@ namespace ISCSI.Server
                 int pduLength = ISCSIPDU.GetPDULength(state.ConnectionBuffer, bufferOffset);
                 if (pduLength > bytesLeftInBuffer)
                 {
-                    Log("[{0}][ProcessCurrentBuffer] Bytes left in receive buffer: {1}", state.ConnectionIdentifier, bytesLeftInBuffer);
+                    Log(Severity.Debug, "[{0}][ProcessCurrentBuffer] Bytes left in receive buffer: {1}", state.ConnectionIdentifier, bytesLeftInBuffer);
                     break;
                 }
                 else
@@ -241,7 +222,7 @@ namespace ISCSI.Server
                     }
                     catch (Exception ex)
                     {
-                        Log("[{0}][ProcessCurrentBuffer] Failed to read PDU (Exception: {1})", state.ConnectionIdentifier, ex.Message);
+                        Log(Severity.Error, "[{0}] Failed to read PDU (Exception: {1})", state.ConnectionIdentifier, ex.Message);
                         RejectPDU reject = new RejectPDU();
                         reject.Reason = RejectReason.InvalidPDUField;
                         reject.Data = ByteReader.ReadBytes(pduBytes, 0, 48);
@@ -253,7 +234,7 @@ namespace ISCSI.Server
                     {
                         if (pdu.GetType() == typeof(ISCSIPDU))
                         {
-                            Log("[{0}][ProcessCurrentBuffer] Unsupported PDU (0x{1})", state.ConnectionIdentifier, pdu.OpCode.ToString("X"));
+                            Log(Severity.Error, "[{0}][ProcessCurrentBuffer] Unsupported PDU (0x{1})", state.ConnectionIdentifier, pdu.OpCode.ToString("X"));
                             // Unsupported PDU
                             RejectPDU reject = new RejectPDU();
                             reject.InitiatorTaskTag = pdu.InitiatorTaskTag;
@@ -272,7 +253,7 @@ namespace ISCSI.Server
                         // Do not continue to process the buffer if the other side closed the connection
                         if (bytesLeftInBuffer > 0)
                         {
-                            Log("[{0}][ProcessCurrentBuffer] Buffer processing aborted, bytes left in receive buffer: {1}", state.ConnectionIdentifier, bytesLeftInBuffer);
+                            Log(Severity.Debug, "[{0}] Buffer processing aborted, bytes left in receive buffer: {1}", state.ConnectionIdentifier, bytesLeftInBuffer);
                         }
                         return;
                     }
@@ -294,7 +275,8 @@ namespace ISCSI.Server
             Socket clientSocket = state.ClientSocket;
             
             uint? cmdSN = PDUHelper.GetCmdSN(pdu);
-            Log("[{0}][ProcessPDU] Received PDU from initiator, Operation: {1}, Size: {2}, CmdSN: {3}", state.ConnectionIdentifier, (ISCSIOpCodeName)pdu.OpCode, pdu.Length, cmdSN);
+            Log(Severity.Trace, "Entering ProcessPDU");
+            Log(Severity.Verbose, "[{0}] Received PDU from initiator, Operation: {1}, Size: {2}, CmdSN: {3}", state.ConnectionIdentifier, (ISCSIOpCodeName)pdu.OpCode, pdu.Length, cmdSN);
             // RFC 3720: On any connection, the iSCSI initiator MUST send the commands in increasing order of CmdSN,
             // except for commands that are retransmitted due to digest error recovery and connection recovery.
             if (cmdSN.HasValue)
@@ -303,8 +285,9 @@ namespace ISCSI.Server
                 {
                     if (cmdSN != state.SessionParameters.ExpCmdSN)
                     {
-                        Log("[{0}][ProcessPDU] CmdSN outside of expected range", state.ConnectionIdentifier);
+                        Log(Severity.Error, "[{0}] CmdSN outside of expected range", state.ConnectionIdentifier);
                         // We ignore this PDU
+                        Log(Severity.Trace, "Leaving ProcessPDU");
                         return;
                     }
                 }
@@ -328,7 +311,7 @@ namespace ISCSI.Server
                 if (pdu is LoginRequestPDU)
                 {
                     LoginRequestPDU request = (LoginRequestPDU)pdu;
-                    Log("[{0}][ReceiveCallback] Login Request, current stage: {1}, next stage: {2}, parameters: {3}", state.ConnectionIdentifier, request.CurrentStage, request.NextStage, KeyValuePairUtils.ToString(request.LoginParameters));
+                    Log(Severity.Verbose, "[{0}] Login Request, current stage: {1}, next stage: {2}, parameters: {3}", state.ConnectionIdentifier, request.CurrentStage, request.NextStage, KeyValuePairUtils.ToString(request.LoginParameters));
                     if (request.TSIH != 0)
                     {
                         // RFC 3720: A Login Request with a non-zero TSIH and a CID equal to that of an existing
@@ -339,13 +322,13 @@ namespace ISCSI.Server
                             if (existingConnectionIndex >= 0)
                             {
                                 // Perform implicit logout
-                                Log("[{0}][ProcessPDU] Initiating implicit logout", state.ConnectionIdentifier);
+                                Log(Severity.Verbose, "[{0}] Initiating implicit logout", state.ConnectionIdentifier);
                                 ConnectionState existingConnection = m_activeConnections[existingConnectionIndex];
                                 // Wait for pending I/O to complete.
                                 existingConnection.RunningSCSICommands.WaitUntilZero();
                                 SocketUtils.ReleaseSocket(existingConnection.ClientSocket);
                                 m_activeConnections.RemoveAt(existingConnectionIndex);
-                                Log("[{0}][ProcessPDU] Implicit logout completed", state.ConnectionIdentifier);
+                                Log(Severity.Verbose, "[{0}] Implicit logout completed", state.ConnectionIdentifier);
                             }
                         }
                     }
@@ -359,13 +342,13 @@ namespace ISCSI.Server
                             m_activeConnections.Add(state);
                         }
                     }
-                    Log("[{0}][ReceiveCallback] Login Response parameters: {1}", state.ConnectionIdentifier, KeyValuePairUtils.ToString(response.LoginParameters));
+                    Log(Severity.Verbose, "[{0}] Login Response parameters: {1}", state.ConnectionIdentifier, KeyValuePairUtils.ToString(response.LoginParameters));
                     TrySendPDU(state, response);
                 }
                 else
                 {
                     // Before the Full Feature Phase is established, only Login Request and Login Response PDUs are allowed.
-                    Log("[{0}][ProcessPDU] Improper command during login phase, OpCode: 0x{1}", state.ConnectionIdentifier, pdu.OpCode.ToString("x"));
+                    Log(Severity.Error, "[{0}] Improper command during login phase, OpCode: 0x{1}", state.ConnectionIdentifier, pdu.OpCode.ToString("x"));
                     if (state.SessionParameters.TSIH == 0)
                     {
                         // A target receiving any PDU except a Login request before the Login phase is started MUST
@@ -394,6 +377,7 @@ namespace ISCSI.Server
                 }
                 else if (pdu is LogoutRequestPDU)
                 {
+                    Log(Severity.Verbose, "[{0}] Logour Request", state.ConnectionIdentifier);
                     lock (m_activeConnections)
                     {
                         int connectionIndex = GetConnectionStateIndex(m_activeConnections, state.SessionParameters.ISID, state.SessionParameters.TSIH, state.ConnectionParameters.CID);
@@ -420,7 +404,7 @@ namespace ISCSI.Server
                 {
                     // The target MUST ONLY accept text requests with the SendTargets key and a logout
                     // request with the reason "close the session".  All other requests MUST be rejected.
-                    Log("[{0}][ProcessPDU] Improper command during discovery session, OpCode: 0x{1}", state.ConnectionIdentifier, pdu.OpCode.ToString("x"));
+                    Log(Severity.Error, "[{0}] Improper command during discovery session, OpCode: 0x{1}", state.ConnectionIdentifier, pdu.OpCode.ToString("x"));
                     RejectPDU reject = new RejectPDU();
                     reject.Reason = RejectReason.ProtocolError;
                     reject.Data = ByteReader.ReadBytes(pdu.GetBytes(), 0, 48);
@@ -445,14 +429,14 @@ namespace ISCSI.Server
                     if (pdu is SCSIDataOutPDU)
                     {
                         SCSIDataOutPDU request = (SCSIDataOutPDU)pdu;
-                        ISCSIServer.Log("[{0}][ProcessPDU] SCSIDataOutPDU: Target transfer tag: {1}, LUN: {2}, Buffer offset: {3}, Data segment length: {4}, DataSN: {5}, Final: {6}", state.ConnectionIdentifier, request.TargetTransferTag, (ushort)request.LUN, request.BufferOffset, request.DataSegmentLength, request.DataSN, request.Final);
+                        Log(Severity.Debug, "[{0}] SCSIDataOutPDU: Target transfer tag: {1}, LUN: {2}, Buffer offset: {3}, Data segment length: {4}, DataSN: {5}, Final: {6}", state.ConnectionIdentifier, request.TargetTransferTag, (ushort)request.LUN, request.BufferOffset, request.DataSegmentLength, request.DataSN, request.Final);
                         try
                         {
                             readyToTransferPDUs = TargetResponseHelper.GetReadyToTransferPDUs(request, state.Target, state.SessionParameters, state.ConnectionParameters, out commandsToExecute);
                         }
                         catch (InvalidTargetTransferTagException ex)
                         {
-                            ISCSIServer.Log("[{0}] Invalid TargetTransferTag: {1}", state.ConnectionIdentifier, ex.TargetTransferTag);
+                            Log(Severity.Error, "[{0}] Invalid TargetTransferTag: {1}", state.ConnectionIdentifier, ex.TargetTransferTag);
                             RejectPDU reject = new RejectPDU();
                             reject.InitiatorTaskTag = request.InitiatorTaskTag;
                             reject.Reason = RejectReason.InvalidPDUField;
@@ -463,7 +447,7 @@ namespace ISCSI.Server
                     else
                     {
                         SCSICommandPDU command = (SCSICommandPDU)pdu;
-                        ISCSIServer.Log("[{0}][ProcessPDU] SCSICommandPDU: CmdSN: {1}, LUN: {2}, Data segment length: {3}, Expected Data Transfer Length: {4}, Final: {5}", state.ConnectionIdentifier, command.CmdSN, (ushort)command.LUN, command.DataSegmentLength, command.ExpectedDataTransferLength, command.Final);
+                        Log(Severity.Debug, "[{0}] SCSICommandPDU: CmdSN: {1}, LUN: {2}, Data segment length: {3}, Expected Data Transfer Length: {4}, Final: {5}", state.ConnectionIdentifier, command.CmdSN, (ushort)command.LUN, command.DataSegmentLength, command.ExpectedDataTransferLength, command.Final);
                         readyToTransferPDUs = TargetResponseHelper.GetReadyToTransferPDUs(command, state.Target, state.SessionParameters, state.ConnectionParameters, out commandsToExecute);
                     }
                     foreach (ReadyToTransferPDU readyToTransferPDU in readyToTransferPDUs)
@@ -477,6 +461,7 @@ namespace ISCSI.Server
                     List<ISCSIPDU> responseList = new List<ISCSIPDU>();
                     foreach(SCSICommandPDU command in commandsToExecute)
                     {
+                        Log(Severity.Debug, "[{0}] Executing command: CmdSN: {1}", state.ConnectionIdentifier, command.CmdSN);
                         List<ISCSIPDU> commandResponseList = TargetResponseHelper.GetSCSICommandResponse(command, state.Target, state.SessionParameters, state.ConnectionParameters);
                         state.RunningSCSICommands.Decrement();
                         responseList.AddRange(commandResponseList);
@@ -493,7 +478,7 @@ namespace ISCSI.Server
                 }
                 else if (pdu is LoginRequestPDU)
                 {
-                    Log("[{0}][ProcessPDU] Protocol Error (Login request during full feature phase)", state.ConnectionIdentifier);
+                    Log(Severity.Error, "[{0}] Protocol Error (Login request during full feature phase)", state.ConnectionIdentifier);
                     // RFC 3720: Login requests and responses MUST be used exclusively during Login.
                     // On any connection, the login phase MUST immediately follow TCP connection establishment and
                     // a subsequent Login Phase MUST NOT occur before tearing down a connection
@@ -505,7 +490,7 @@ namespace ISCSI.Server
                 }
                 else
                 {
-                    Log("[{0}][ProcessPDU] Unsupported command, OpCode: 0x{1}", state.ConnectionIdentifier, pdu.OpCode.ToString("x"));
+                    Log(Severity.Error, "[{0}] Unsupported command, OpCode: 0x{1}", state.ConnectionIdentifier, pdu.OpCode.ToString("x"));
                     RejectPDU reject = new RejectPDU();
                     reject.Reason = RejectReason.CommandNotSupported;
                     reject.Data = ByteReader.ReadBytes(pdu.GetBytes(), 0, 48);
@@ -513,6 +498,7 @@ namespace ISCSI.Server
                     TrySendPDU(state, reject);
                 }
             }
+            Log(Severity.Trace, "Leaving ProcessPDU");
         }
 
         private static int GetConnectionStateIndex(List<ConnectionState> Connections, ulong isid, ushort tsih, ushort cid)
@@ -529,7 +515,7 @@ namespace ISCSI.Server
             return -1;
         }
 
-        private static void TrySendPDU(ConnectionState state, ISCSIPDU response)
+        private void TrySendPDU(ConnectionState state, ISCSIPDU response)
         {
             Socket clientSocket = state.ClientSocket;
             try
@@ -545,17 +531,32 @@ namespace ISCSI.Server
                     state.ConnectionParameters.StatSN++;
                 }
                 clientSocket.Send(response.GetBytes());
-                Log("[{0}][TrySendPDU] Sent response to initator, Operation: {1}, Size: {2}", state.ConnectionIdentifier, response.OpCode, response.Length);
+                Log(Severity.Debug, "[{0}] Sent response to initator, Operation: {1}, Size: {2}", state.ConnectionIdentifier, response.OpCode, response.Length);
             }
             catch (SocketException ex)
             {
-                Log("[{0}][TrySendPDU] Failed to send response to initator (Operation: {1}, Size: {2}), SocketException: {3}", state.ConnectionIdentifier, response.OpCode, response.Length, ex.Message);
+                Log(Severity.Debug, "[{0}] Failed to send response to initator (Operation: {1}, Size: {2}), SocketException: {3}", state.ConnectionIdentifier, response.OpCode, response.Length, ex.Message);
             }
             catch (ObjectDisposedException)
             {
             }
         }
 
+        public void Log(Severity severity, string message)
+        {
+            // To be thread-safe we must capture the delegate reference first
+            EventHandler<LogEntry> handler = OnLogEntry;
+            if (handler != null)
+            {
+                handler(this, new LogEntry(DateTime.Now, severity, "iSCSI Server", message));
+            }
+        }
+
+        public void Log(Severity severity, string message, params object[] args)
+        {
+            Log(severity, String.Format(message, args));
+        }
+
         public ushort GetNextTSIH()
         {
             // The iSCSI Target selects a non-zero value for the TSIH at
@@ -570,24 +571,5 @@ namespace ISCSI.Server
             }
             return nextTSIH;
         }
-
-        public static void Log(string message)
-        {
-            if (m_logFile != null)
-            {
-                lock (m_logSyncLock)
-                {
-                    StreamWriter writer = new StreamWriter(m_logFile);
-                    string timestamp = DateTime.Now.ToString("yyyy-MM-dd HH:mm:ss ");
-                    writer.WriteLine(timestamp + message);
-                    writer.Flush();
-                }
-            }
-        }
-
-        public static void Log(string message, params object[] args)
-        {
-            Log(String.Format(message, args));
-        }
     }
 }

ISCSI/Server/TargetResponseHelper.cs

@@ -75,8 +75,6 @@ namespace ISCSI.Server
 
             // Store segment (we only execute the command after receiving all of its data)
             Array.Copy(request.Data, 0, transfer.Command.Data, offset, request.DataSegmentLength);
-            
-            ISCSIServer.Log(String.Format("[{0}][GetSCSIDataOutResponsePDU] Buffer offset: {1}, Total length: {2}", connectionIdentifier, offset, totalLength));
 
             if (offset + request.DataSegmentLength == totalLength)
             {
@@ -119,7 +117,6 @@ namespace ISCSI.Server
         internal static List<ISCSIPDU> GetSCSICommandResponse(SCSICommandPDU command, SCSITarget target, SessionParameters session, ConnectionParameters connection)
         {
             string connectionIdentifier = ConnectionState.GetConnectionIdentifier(session, connection);
-            ISCSIServer.Log("[{0}] Executing Command: CmdSN: {1}", connectionIdentifier, command.CmdSN);
             byte[] scsiResponse;
             SCSIStatusCodeName status = target.ExecuteCommand(command.CommandDescriptorBlock, command.LUN, command.Data, out scsiResponse);
             return PrepareSCSICommandResponse(command, status, scsiResponse, connection);

ISCSI/Utilities/LogEntry.cs

@@ -0,0 +1,39 @@
+/* Copyright (C) 2012-2016 Tal Aloni <tal.aloni.il@gmail.com>. All rights reserved.
+ * 
+ * You can redistribute this program and/or modify it under the terms of
+ * the GNU Lesser Public License as published by the Free Software Foundation,
+ * either version 3 of the License, or (at your option) any later version.
+ */
+using System;
+using System.Collections.Generic;
+using System.Text;
+
+namespace Utilities
+{
+    public enum Severity
+    {
+        Critical = 1,
+        Error = 2,
+        Warning = 3,
+        Information = 4,
+        Verbose = 5,
+        Debug = 6,
+        Trace = 7,
+    }
+
+    public class LogEntry : EventArgs
+    {
+        public DateTime Time;
+        public Severity Severity;
+        public string Source;
+        public string Message;
+
+        public LogEntry(DateTime time, Severity severity, string source, string message)
+        {
+            Time = time;
+            Severity = severity;
+            Source = source;
+            Message = message;
+        }
+    }
+}

ISCSIConsole/ISCSIConsole.csproj

@@ -40,6 +40,7 @@
     <Compile Include="Program.DetailCommand.cs" />
     <Compile Include="Program.HelpCommand.cs" />
     <Compile Include="Program.ListCommand.cs" />
+    <Compile Include="Program.Log.cs" />
     <Compile Include="Program.SelectCommand.cs" />
     <Compile Include="Program.SetCommand.cs" />
     <Compile Include="Program.StartCommand.cs" />

ISCSIConsole/Program.AttachCommand.cs

@@ -255,7 +255,9 @@ namespace ISCSIConsole
         public static ISCSITarget AddTarget(string targetName)
         {
             List<Disk> disks = new List<Disk>();
-            ISCSITarget target = new ISCSITarget(targetName, disks);
+            VirtualSCSITarget scsiTarget = new VirtualSCSITarget(disks);
+            scsiTarget.OnLogEntry += new EventHandler<LogEntry>(OnLogEntry);
+            ISCSITarget target = new ISCSITarget(targetName, scsiTarget);
             m_targets.Add(target);
             return target;
         }

ISCSIConsole/Program.Log.cs

@@ -0,0 +1,53 @@
+using System;
+using System.Collections.Generic;
+using System.IO;
+using System.Text;
+using Utilities;
+
+namespace ISCSIConsole
+{
+    public partial class Program
+    {
+        private static FileStream m_logFile;
+
+        public static void OpenLogFile(string logFilePath)
+        {
+            try
+            {
+                // We must avoid using buffered writes, using it will negatively affect the performance and reliability.
+                // Note: once the file system write buffer is filled, Windows may delay any (buffer-dependent) pending write operations, which will create a deadlock.
+                m_logFile = new FileStream(logFilePath, FileMode.Append, FileAccess.Write, FileShare.Read, 0x1000, FileOptions.WriteThrough);
+            }
+            catch
+            {
+                Console.WriteLine("Cannot open log file");
+            }
+        }
+
+        public static void CloseLogFile()
+        {
+            if (m_logFile != null)
+            {
+                lock (m_logFile)
+                {
+                    m_logFile.Close();
+                    m_logFile = null;
+                }
+            }
+        }
+
+        public static void OnLogEntry(object sender, LogEntry entry)
+        {
+            if (m_logFile != null)
+            {
+                lock (m_logFile)
+                {
+                    StreamWriter writer = new StreamWriter(m_logFile);
+                    string timestamp = DateTime.Now.ToString("yyyy-MM-dd HH:mm:ss ");
+                    writer.WriteLine("{0} {1} [{2}] {3}", entry.Severity.ToString().PadRight(12), timestamp, entry.Source, entry.Message);
+                    writer.Flush();
+                }
+            }
+        }
+    }
+}

ISCSIConsole/Program.StartCommand.cs

@@ -46,14 +46,18 @@ namespace ISCSIConsole
                         logFile = parameters.ValueOf("log");
                     }
                     m_server = new ISCSIServer(m_targets, port, logFile);
-                    try
-                    {
-                        ISCSIServer.Log("Starting Server");
-                    }
-                    catch (IOException)
+                    m_server.OnLogEntry += new EventHandler<LogEntry>(OnLogEntry);
+                    if (logFile != String.Empty)
                     {
-                        Console.WriteLine("Could not append to log file");
-                        return;
+                        try
+                        {
+                            OpenLogFile(logFile);
+                        }
+                        catch (IOException)
+                        {
+                            Console.WriteLine("Could not append to log file");
+                            return;
+                        }
                     }
 
                     try
@@ -82,6 +86,7 @@ namespace ISCSIConsole
                 m_server.Stop();
                 m_server = null;
                 Console.WriteLine("iSCSI target is stopping");
+                CloseLogFile();
             }
             else
             {