Fixing bugs and logging future lazy messages

Bnet/Bnet Client.vb

@@ -349,14 +349,16 @@ Namespace Bnet
             _socket.ObservePackets().InCurrentSyncContext().Observe(
                 Sub(data)
                     Dim id = DirectCast(data(1), Bnet.Protocol.PacketId)
-                    Logger.Log(Function() "Received {0} from {1}".Frmt(id, "bnet"), LogMessageType.DataEvent)
+                    Dim t = New TaskCompletionSource(Of String)()
                     Dim body = data.SkipExact(4)
-                    Call Async Sub()
-                             Dim parsed = Await _manualPacketHandler.Push(id, body)
-                             If parsed Is Nothing Then Throw New IO.IOException("Unhandled packet: {0}".Frmt(id))
-                             If parsed.Data.Count < data.Count Then Logger.Log("Data left over after parsing.", LogMessageType.Problem)
-                             Logger.Log(Function() "Received {0} from {1}: {2}".Frmt(id, "bnet", parsed.Description()), LogMessageType.DataParsed)
-                         End Sub()
+                    Dim description = Async Function() As Task(Of Func(Of String))
+                                          Dim parsed = Await _manualPacketHandler.Push(id, body)
+                                          If parsed Is Nothing Then Throw New IO.IOException("Unhandled packet: {0}".Frmt(id))
+                                          If parsed.Data.Count < body.Count Then Logger.Log("Data left over after parsing.", LogMessageType.Problem)
+                                          Return Function() "Received {0} from {1}: {2}".Frmt(id, "bnet", parsed.Description())
+                                      End Function()
+                    Logger.Log(Function() "Received {0} from {1}".Frmt(id, "bnet"), LogMessageType.DataEvent)
+                    Logger.FutureLog(Function() "Received {0} from {1}: Parsing...".Frmt(id, "bnet"), description, LogMessageType.DataParsed)
                 End Sub,
                 Sub()
                 End Sub,
@@ -433,8 +435,9 @@ Namespace Bnet
 
                     BeginHandlingPacketsPresync()
 
-                    TrySendPacketSynq(Protocol.MakeAuthenticationBegin(_productInfoProvider.MajorVersion, New Net.IPAddress(GetCachedIPAddressBytes(external:=False))))
-                    Dim authBeginVals = Await walker.WalkValueAsync(Protocol.Packets.ServerToClient.ProgramAuthenticationBegin)
+                    Dim authBeginVals = Await SendReceivePacketAsync(
+                        Protocol.MakeAuthenticationBegin(_productInfoProvider.MajorVersion, New Net.IPAddress(GetCachedIPAddressBytes(external:=False))),
+                        Protocol.Packets.ServerToClient.ProgramAuthenticationBegin)
                     If ct.IsCancellationRequested Then Throw New TaskCanceledException()
                     If authBeginVals.ItemAs(Of Protocol.ProgramAuthenticationBeginLogOnType)("logon type") <> Protocol.ProgramAuthenticationBeginLogOnType.Warcraft3 Then
                         Throw New IO.InvalidDataException("Unrecognized logon type from server.")
@@ -570,10 +573,9 @@ Namespace Bnet
             Dim clientProof = Me._userCredentials.ClientPasswordProof(accountPasswordSalt, serverPublicKey)
             Dim expectedServerProof = Me._userCredentials.ServerPasswordProof(accountPasswordSalt, serverPublicKey)
 
-
             'Finish authentication
             Dim authFinishVals = Await SendReceivePacketAsync(
-                Protocol.MakeAccountLogOnFinish(clientProof),
+                Protocol.MakeUserAuthenticationFinish(clientProof),
                 Protocol.Packets.ServerToClient.UserAuthenticationFinish)
             If ct.IsCancellationRequested Then Throw New TaskCanceledException()
             Dim result = authFinishVals.ItemAs(Of Protocol.UserAuthenticationFinishResult)("result")

Bnet/Protocol/Bnet Protocol Packers.vb

@@ -83,7 +83,7 @@ Namespace Bnet.Protocol
         End Function
 
         <Pure()>
-        Public Function MakeAccountLogOnFinish(clientPasswordProof As IRist(Of Byte)) As Packet
+        Public Function MakeUserAuthenticationFinish(clientPasswordProof As IRist(Of Byte)) As Packet
             Contract.Requires(clientPasswordProof IsNot Nothing)
             Contract.Ensures(Contract.Result(Of Packet)() IsNot Nothing)
             Return Packet.FromValue(Packets.ClientToServer.UserAuthenticationFinish, clientPasswordProof)

Components/Component Extensions.vb

@@ -14,7 +14,8 @@
                 component.Logger.Log("Command: {0}".Frmt(argDesc), LogMessageType.Typical)
 
                 component.Logger.FutureLog(placeholder:="[running command {0}...]".Frmt(argDesc),
-                                           message:=SafeInvokeCommand(component, argument).AssumeNotNull())
+                                           message:=SafeInvokeCommand(component, argument).AssumeNotNull(),
+                                           messageType:=LogMessageType.Typical)
             Catch e As Exception
                 e.RaiseAsUnexpected("UIInvokeCommand for {0}:{1}".Frmt(component.Type, component.Name))
             End Try

HostBotTests/BnetProtocolPackersTest.vb

@@ -17,7 +17,7 @@ Public Class BnetProtocolPackersTest
     End Sub
     <TestMethod()>
     Public Sub MakeAccountLogOnFinishTest()
-        MakeAccountLogOnFinish(CByte(1).Repeated(20))
+        MakeUserAuthenticationFinish(CByte(1).Repeated(20))
     End Sub
     <TestMethod()>
     Public Sub MakeAuthenticationBeginTest()

Interface/LoggerControl.vb

@@ -271,43 +271,48 @@ Public Class LoggerControl
             e.RaiseAsUnexpected("Exception rose post LoggerControl.emptyQueue")
         End Try
     End Sub
-    Private Sub LogFutureMessage(placeholder As String, futureMessage As Task(Of String))
+    Private Async Sub LogFutureMessage(type As LogMessageType, placeholder As Func(Of String), futureMessage As Task(Of Func(Of String)))
         Contract.Requires(placeholder IsNot Nothing)
         Contract.Requires(futureMessage IsNot Nothing)
 
-        Dim m = New QueuedMessage(placeholder, Color.DarkGoldenrod)
-        LogMessage(m)
-        futureMessage.ContinueWith(
-            Sub(task)
-                SyncLock lock
-                    Dim message = If(task.Status = TaskStatus.Faulted,
-                                     task.Exception.Summarize,
-                                     task.Result)
-                    Dim color = callbackColorMap(If(task.Status = TaskStatus.RanToCompletion AndAlso Not message Like "Failed: *",
-                                                    LogMessageType.Positive,
-                                                    LogMessageType.Problem))
-                    LogMessage(New QueuedMessage(message, color, m))
-                End SyncLock
-            End Sub
-        )
+        Dim fileOnly As Boolean
+        SyncLock lock
+            If callbackModeMap(type) = CallbackMode.Off Then Return
+            fileOnly = callbackModeMap(type) = CallbackMode.File
+        End SyncLock
+
+        Dim m = New QueuedMessage(placeholder(), Color.DarkGoldenrod)
+        LogMessage(m, fileOnly)
+
+        Try
+            Dim f = Await futureMessage
+            Dim message = f()
+            Dim color = callbackColorMap(type)
+            If message.StartsWith("Failed:") Then color = callbackColorMap(LogMessageType.Problem)
+            LogMessage(New QueuedMessage(message, color, m), fileOnly)
+        Catch ex As Exception
+            SyncLock lock
+                LogMessage(New QueuedMessage(ex.Summarize, callbackColorMap(LogMessageType.Problem), m))
+            End SyncLock
+        End Try
     End Sub
 #End Region
 
 #Region "Log Events"
     Private Sub OnLoggedMessage(type As LogMessageType,
                                 message As Lazy(Of String)) Handles _logger.LoggedMessage
-        Dim color As Color
         Dim fileOnly As Boolean
         SyncLock lock
             If callbackModeMap(type) = CallbackMode.Off Then Return
-            color = callbackColorMap(type)
             fileOnly = callbackModeMap(type) = CallbackMode.File
         End SyncLock
+        Dim color = callbackColorMap(type)
         LogMessage(message, color, fileOnly)
     End Sub
-    Private Sub OnLoggedFutureMessage(placeholder As String,
-                                      out As Task(Of String)) Handles _logger.LoggedFutureMessage
-        uiRef.QueueAction(Sub() LogFutureMessage(placeholder, out))
+    Private Sub OnLoggedFutureMessage(type As LogMessageType,
+                                      placeholder As Func(Of String),
+                                      out As Task(Of Func(Of String))) Handles _logger.LoggedFutureMessage
+        uiRef.QueueAction(Sub() LogFutureMessage(type, placeholder, out))
     End Sub
 #End Region
 

Library/Logging.vb

@@ -10,7 +10,7 @@ End Enum
 
 Public NotInheritable Class Logger
     Public Event LoggedMessage(type As LogMessageType, message As Lazy(Of String))
-    Public Event LoggedFutureMessage(placeholder As String, message As Task(Of String))
+    Public Event LoggedFutureMessage(type As LogMessageType, placeholder As Func(Of String), message As Task(Of Func(Of String)))
     Private ReadOnly outQueue As CallQueue
 
     <ContractInvariantMethod()> Private Sub ObjectInvariant()
@@ -21,10 +21,19 @@ Public NotInheritable Class Logger
         Me.outQueue = If(outQueue, MakeTaskedCallQueue())
     End Sub
 
-    Public Sub FutureLog(placeholder As String, message As Task(Of String))
+    Public Sub FutureLog(placeholder As String, message As Task(Of String), messageType As LogMessageType)
         Contract.Requires(placeholder IsNot Nothing)
         Contract.Requires(message IsNot Nothing)
-        outQueue.QueueAction(Sub() RaiseEvent LoggedFutureMessage(placeholder, message))
+        Dim msg = Async Function() As Task(Of Func(Of String))
+                      Dim r = Await message
+                      Return Function() r
+                  End Function()
+        outQueue.QueueAction(Sub() RaiseEvent LoggedFutureMessage(messageType, Function() placeholder, msg))
+    End Sub
+    Public Sub FutureLog(placeholder As Func(Of String), message As Task(Of Func(Of String)), messageType As LogMessageType)
+        Contract.Requires(placeholder IsNot Nothing)
+        Contract.Requires(message IsNot Nothing)
+        outQueue.QueueAction(Sub() RaiseEvent LoggedFutureMessage(messageType, placeholder, message))
     End Sub
     Public Sub Log(message As Lazy(Of String), messageType As LogMessageType)
         Contract.Requires(message IsNot Nothing)

Library/Reactive.vb

@@ -237,7 +237,7 @@ Public Class ManualValuePusher(Of T, R)
             Interlocked.Decrement(_headRefCount)
         End Sub
         Public Sub PassWithoutHandling()
-            If Interlocked.Decrement(_headRefCount) = 1 Then
+            If Interlocked.Decrement(_headRefCount) = 0 Then
                 _parsed.TrySetResult(Nothing)
             End If
         End Sub
@@ -273,12 +273,12 @@ Public Class ManualValuePusher(Of T, R)
 
         Public Async Function WalkAsync(filter As Func(Of T, Boolean), parser As Func(Of T, R)) As Task(Of R) Implements IValueWalker(Of T, R).WalkAsync
             Do
-                Dim n = _head
-                If n Is Nothing Then Throw New ObjectDisposedException("Walker")
-                n = Await n.NextAsync
+                Dim p = _head
+                If p Is Nothing Then Throw New ObjectDisposedException("Walker")
+                Dim n = Await p.NextAsync
                 SyncLock _lock
                     If _head Is Nothing Then Throw New ObjectDisposedException("Walker")
-                    If n IsNot _head Then Throw New InvalidOperationException("Overlapping WalkAsync calls")
+                    If p IsNot _head Then Throw New InvalidOperationException("Overlapping WalkAsync calls")
                     If filter(n.Data) Then
                         Dim r = parser(n.Data)
                         _head = n