diff --git a/.github/workflows/dotnet.yml b/.github/workflows/dotnet.yml index dd24896..7731db3 100644 --- a/.github/workflows/dotnet.yml +++ b/.github/workflows/dotnet.yml @@ -8,7 +8,8 @@ on: jobs: build: - runs-on: arc-runner-set + #runs-on: arc-runner-set + runs-on: ubuntu-latest steps: - uses: actions/checkout@v3 diff --git a/src/Grace.Actors/Branch.Actor.fs b/src/Grace.Actors/Branch.Actor.fs index 987d5f4..5479b77 100644 --- a/src/Grace.Actors/Branch.Actor.fs +++ b/src/Grace.Actors/Branch.Actor.fs @@ -90,13 +90,16 @@ module Branch = } override this.OnActivateAsync() = + let activateStartTime = getCurrentInstant() let stateManager = this.StateManager - log.LogInformation($"{getCurrentInstantExtended()} Activated BranchActor {host.Id}.") task { let! retrievedDto = Storage.RetrieveState stateManager dtoStateName match retrievedDto with | Some retrievedDto -> branchDto <- retrievedDto | None -> branchDto <- BranchDto.Default + + let duration = getCurrentInstant().Minus(activateStartTime) + log.LogInformation("{CurrentInstant}: Activated {ActorType} {ActorId}. Retrieved from storage in {duration}ms.", getCurrentInstantExtended(), actorName, host.Id, duration.TotalMilliseconds.ToString("F3")) } :> Task member private this.SetMaintenanceReminder() = @@ -115,7 +118,7 @@ module Branch = actorStartTime <- getCurrentInstant() logScope <- log.BeginScope("Actor {actorName}", actorName) currentCommand <- String.Empty - //log.LogInformation("{CurrentInstant}: Started {ActorName}.{MethodName} Id: {Id}.", getCurrentInstantExtended(), actorName, context.MethodName, this.Id.GetId()) + //log.LogInformation("{CurrentInstant}: Started {ActorName}.{MethodName} Id: {Id}.", getCurrentInstantExtended(), actorName, context.MethodName, this.Id) // This checks if the actor is still active, but in an undefined state, which will _almost_ never happen. // isDisposed is set when the actor is deleted, or if an error occurs where we're not sure of the state and want to reload from the database. @@ -126,11 +129,11 @@ module Branch = Task.CompletedTask override this.OnPostActorMethodAsync(context) = - let duration = getCurrentInstant().Minus(actorStartTime) + let durationμs = (getCurrentInstant().Minus(actorStartTime).TotalMilliseconds * 1000.0).ToString("F0") if String.IsNullOrEmpty(currentCommand) then - log.LogInformation("{CurrentInstant}: Finished {ActorName}.{MethodName}; Id: {Id}; Duration: {duration}ms.", $"{getCurrentInstantExtended(),-28}", actorName, context.MethodName, this.Id.GetId(), duration.TotalMilliseconds.ToString("F3")) + log.LogInformation("{CurrentInstant}: Finished {ActorName}.{MethodName}; Id: {Id}; Duration: {duration}μs.", getCurrentInstantExtended(), actorName, context.MethodName, this.Id, durationμs) else - log.LogInformation("{CurrentInstant}: Finished {ActorName}.{MethodName}; Command: {Command}; Id: {Id}; Duration: {duration}ms.", $"{getCurrentInstantExtended(),-28}", actorName, context.MethodName, currentCommand, this.Id.GetId(), duration.TotalMilliseconds.ToString("F3")) + log.LogInformation("{CurrentInstant}: Finished {ActorName}.{MethodName}; Command: {Command}; Id: {Id}; Duration: {duration}μs.", getCurrentInstantExtended(), actorName, context.MethodName, currentCommand, this.Id, durationμs) logScope.Dispose() Task.CompletedTask diff --git a/src/Grace.Actors/BranchName.Actor.fs b/src/Grace.Actors/BranchName.Actor.fs index 6e3d0a7..051809b 100644 --- a/src/Grace.Actors/BranchName.Actor.fs +++ b/src/Grace.Actors/BranchName.Actor.fs @@ -27,12 +27,12 @@ module BranchName = override this.OnPreActorMethodAsync(context) = actorStartTime <- getCurrentInstant() logScope <- log.BeginScope("Actor {actorName}", actorName) - //log.LogInformation("{CurrentInstant}: Started {ActorName}.{MethodName} Id: {Id}.", getCurrentInstantExtended(), actorName, context.MethodName, this.Id.GetId()) + log.LogTrace("{CurrentInstant}: Started {ActorName}.{MethodName} Id: {Id}.", getCurrentInstantExtended(), actorName, context.MethodName, this.Id) Task.CompletedTask override this.OnPostActorMethodAsync(context) = - let duration = getCurrentInstant().Minus(actorStartTime) - log.LogInformation("{CurrentInstant}: Finished {ActorName}.{MethodName} Id: {Id}; Duration: {duration}ms.", getCurrentInstantExtended(), actorName, context.MethodName, this.Id.GetId(), duration.TotalMilliseconds.ToString("F3")) + let durationμs = (getCurrentInstant().Minus(actorStartTime).TotalMilliseconds * 1000.0).ToString("F0") + log.LogInformation("{CurrentInstant}: Finished {ActorName}.{MethodName}; Id: {Id}; Duration: {duration}μs.", getCurrentInstantExtended(), actorName, context.MethodName, this.Id, durationμs) logScope.Dispose() Task.CompletedTask diff --git a/src/Grace.Actors/Diff.Actor.fs b/src/Grace.Actors/Diff.Actor.fs index 593c805..ff2b5e7 100644 --- a/src/Grace.Actors/Diff.Actor.fs +++ b/src/Grace.Actors/Diff.Actor.fs @@ -133,24 +133,27 @@ module Diff = task.Wait() override this.OnActivateAsync() = + let activateStartTime = getCurrentInstant() let stateManager = this.StateManager - log.LogInformation("{CurrentInstant}: Activated {ActorType} {ActorId}.", getCurrentInstantExtended(), this.GetType().Name, host.Id) task { let! retrievedDto = Storage.RetrieveState stateManager dtoStateName match retrievedDto with | Some retrievedDto -> diffDto <- retrievedDto | None -> diffDto <- DiffDto.Default + + let duration = getCurrentInstant().Minus(activateStartTime) + log.LogInformation("{CurrentInstant}: Activated {ActorType} {ActorId}. Retrieved from storage in {duration}ms.", getCurrentInstantExtended(), actorName, host.Id, duration.TotalMilliseconds.ToString("F3")) } :> Task override this.OnPreActorMethodAsync(context) = actorStartTime <- getCurrentInstant() logScope <- log.BeginScope("Actor {actorName}", actorName) - //log.LogInformation("{CurrentInstant}: Started {ActorName}.{MethodName} Id: {Id}.", getCurrentInstantExtended(), actorName, context.MethodName, this.Id.GetId()) + //log.LogInformation("{CurrentInstant}: Started {ActorName}.{MethodName} Id: {Id}.", getCurrentInstantExtended(), actorName, context.MethodName, this.Id) Task.CompletedTask override this.OnPostActorMethodAsync(context) = - let duration = getCurrentInstant().Minus(actorStartTime) - log.LogInformation("{CurrentInstant}: Finished {ActorName}.{MethodName} Id: {Id}; Duration: {duration}ms.", getCurrentInstantExtended(), actorName, context.MethodName, this.Id.GetId(), duration.TotalMilliseconds.ToString("F3")) + let durationμs = (getCurrentInstant().Minus(actorStartTime).TotalMilliseconds * 1000.0).ToString("F0") + log.LogInformation("{CurrentInstant}: Finished {ActorName}.{MethodName}; Id: {Id}; Duration: {duration}μs.", getCurrentInstantExtended(), actorName, context.MethodName, this.Id, durationμs) logScope.Dispose() Task.CompletedTask diff --git a/src/Grace.Actors/DirectoryVersion.Actor.fs b/src/Grace.Actors/DirectoryVersion.Actor.fs index 1ce8b05..4d6348e 100644 --- a/src/Grace.Actors/DirectoryVersion.Actor.fs +++ b/src/Grace.Actors/DirectoryVersion.Actor.fs @@ -37,8 +37,8 @@ module DirectoryVersion = let mutable logScope: IDisposable = null override this.OnActivateAsync() = + let activateStartTime = getCurrentInstant() let stateManager = this.StateManager - log.LogInformation("{CurrentInstant} Activated {ActorType} {ActorId}.", getCurrentInstantExtended(), this.GetType().Name, host.Id) task { try let! retrievedDto = Storage.RetrieveState stateManager dtoStateName @@ -49,17 +49,20 @@ module DirectoryVersion = let exc = createExceptionResponse ex log.LogError("{CurrentInstant} Error in {ActorType} {ActorId}.", getCurrentInstantExtended(), this.GetType().Name, host.Id) log.LogError("{CurrentInstant} {ExceptionDetails}", getCurrentInstantExtended(), exc.ToString()) + + let duration = getCurrentInstant().Minus(activateStartTime) + log.LogInformation("{CurrentInstant}: Activated {ActorType} {ActorId}. Retrieved from storage in {duration}ms.", getCurrentInstantExtended(), actorName, host.Id, duration.TotalMilliseconds.ToString("F3")) } :> Task override this.OnPreActorMethodAsync(context) = actorStartTime <- getCurrentInstant() logScope <- log.BeginScope("Actor {actorName}", actorName) - //log.LogInformation("{CurrentInstant}: Started {ActorName}.{MethodName} Id: {Id}.", getCurrentInstantExtended(), actorName, context.MethodName, this.Id.GetId()) + log.LogTrace("{CurrentInstant}: Started {ActorName}.{MethodName} Id: {Id}.", getCurrentInstantExtended(), actorName, context.MethodName, this.Id) Task.CompletedTask override this.OnPostActorMethodAsync(context) = - let duration = getCurrentInstant().Minus(actorStartTime) - log.LogInformation("{CurrentInstant}: Finished {ActorName}.{MethodName} Id: {Id}; Duration: {duration}ms.", getCurrentInstantExtended(), actorName, context.MethodName, this.Id.GetId(), duration.TotalMilliseconds.ToString("F3")) + let durationμs = (getCurrentInstant().Minus(actorStartTime).TotalMilliseconds * 1000.0).ToString("F0") + log.LogInformation("{CurrentInstant}: Finished {ActorName}.{MethodName}; Id: {Id}; Duration: {duration}μs.", getCurrentInstantExtended(), actorName, context.MethodName, this.Id, durationμs) logScope.Dispose() Task.CompletedTask @@ -136,10 +139,10 @@ module DirectoryVersion = //let cachedSubdirectoryVersions = None match cachedSubdirectoryVersions with | Some subdirectoryVersions -> - logToConsole $"In DirectoryVersionActor.GetDirectoryVersionsRecursive({this.Id.GetId()}). SubdirectoryVersions already cached." + logToConsole $"In DirectoryVersionActor.GetDirectoryVersionsRecursive({this.Id}). SubdirectoryVersions already cached." return subdirectoryVersions | None -> - logToConsole $"In DirectoryVersionActor.GetDirectoryVersionsRecursive({this.Id.GetId()}). SubdirectoryVersions not cached; generating the list." + logToConsole $"In DirectoryVersionActor.GetDirectoryVersionsRecursive({this.Id}). SubdirectoryVersions not cached; generating the list." let subdirectoryVersions = ConcurrentQueue() subdirectoryVersions.Enqueue(directoryVersion) do! Parallel.ForEachAsync(directoryVersion.Directories, Constants.ParallelOptions, (fun directoryId ct -> diff --git a/src/Grace.Actors/Grace.Actors.fsproj b/src/Grace.Actors/Grace.Actors.fsproj index 1f220ce..16e4a89 100644 --- a/src/Grace.Actors/Grace.Actors.fsproj +++ b/src/Grace.Actors/Grace.Actors.fsproj @@ -6,7 +6,7 @@ FS0025 1057 AnyCPU;x64 - true + false diff --git a/src/Grace.Actors/Organization.Actor.fs b/src/Grace.Actors/Organization.Actor.fs index a8340c6..21c8d65 100644 --- a/src/Grace.Actors/Organization.Actor.fs +++ b/src/Grace.Actors/Organization.Actor.fs @@ -30,11 +30,11 @@ module Organization = let GetActorId (organizationId: OrganizationId) = ActorId($"{organizationId}") - type OrganizationActor(host: ActorHost) as this = + type OrganizationActor(host: ActorHost) = inherit Actor(host) let actorName = ActorName.Organization - let log = this.Logger + let log = host.LoggerFactory.CreateLogger(actorName) let mutable actorStartTime = Instant.MinValue let mutable logScope: IDisposable = null let mutable currentCommand = String.Empty @@ -63,13 +63,16 @@ module Organization = {newOrganizationDto with UpdatedAt = Some (getCurrentInstant())} override this.OnActivateAsync() = + let activateStartTime = getCurrentInstant() let stateManager = this.StateManager - log.LogInformation("{CurrentInstant} Activated {ActorType} {ActorId}.", getCurrentInstantExtended(), this.GetType().Name, host.Id) task { let! retrievedDto = Storage.RetrieveState stateManager dtoStateName match retrievedDto with | Some retrievedDto -> organizationDto <- retrievedDto | None -> organizationDto <- OrganizationDto.Default + + let duration = getCurrentInstant().Minus(activateStartTime) + log.LogInformation("{CurrentInstant}: Activated {ActorType} {ActorId}. Retrieved from storage in {duration}ms.", getCurrentInstantExtended(), actorName, host.Id, duration.TotalMilliseconds.ToString("F3")) } :> Task member private this.SetMaintenanceReminder() = @@ -88,22 +91,21 @@ module Organization = actorStartTime <- getCurrentInstant() logScope <- log.BeginScope("Actor {actorName}", actorName) currentCommand <- String.Empty - //log.LogInformation("{CurrentInstant}: Started {ActorName}.{MethodName} Id: {Id}.", getCurrentInstantExtended(), actorName, context.MethodName, this.Id.GetId()) + log.LogTrace("{CurrentInstant}: Started {ActorName}.{MethodName} Id: {Id}.", getCurrentInstantExtended(), actorName, context.MethodName, this.Id) // This checks if the actor is still active, but in an undefined state, which will _almost_ never happen. // isDisposed is set when the actor is deleted, or if an error occurs where we're not sure of the state and want to reload from the database. if isDisposed then this.OnActivateAsync().Wait() isDisposed <- false - Task.CompletedTask override this.OnPostActorMethodAsync(context) = - let duration = getCurrentInstant().Minus(actorStartTime) + let durationμs = (getCurrentInstant().Minus(actorStartTime).TotalMilliseconds * 1000.0).ToString("F0") if String.IsNullOrEmpty(currentCommand) then - log.LogInformation("{CurrentInstant}: Finished {ActorName}.{MethodName}; Id: {Id}; Duration: {duration}ms.", $"{getCurrentInstantExtended(),-28}", actorName, context.MethodName, this.Id.GetId(), duration.TotalMilliseconds.ToString("F3")) + log.LogInformation("{CurrentInstant}: Finished {ActorName}.{MethodName}; Id: {Id}; Duration: {duration}μs.", getCurrentInstantExtended(), actorName, context.MethodName, this.Id, durationμs) else - log.LogInformation("{CurrentInstant}: Finished {ActorName}.{MethodName}; Command: {Command}; Id: {Id}; Duration: {duration}ms.", $"{getCurrentInstantExtended(),-28}", actorName, context.MethodName, currentCommand, this.Id.GetId(), duration.TotalMilliseconds.ToString("F3")) + log.LogInformation("{CurrentInstant}: Finished {ActorName}.{MethodName}; Command: {Command}; Id: {Id}; Duration: {duration}μs.", getCurrentInstantExtended(), actorName, context.MethodName, currentCommand, this.Id, durationμs) logScope.Dispose() Task.CompletedTask diff --git a/src/Grace.Actors/OrganizationName.Actor.fs b/src/Grace.Actors/OrganizationName.Actor.fs index 2d75f2a..b9371f4 100644 --- a/src/Grace.Actors/OrganizationName.Actor.fs +++ b/src/Grace.Actors/OrganizationName.Actor.fs @@ -28,12 +28,12 @@ module OrganizationName = override this.OnPreActorMethodAsync(context) = actorStartTime <- getCurrentInstant() logScope <- log.BeginScope("Actor {actorName}", actorName) - //log.LogInformation("{CurrentInstant}: Started {ActorName}.{MethodName} Id: {Id}.", getCurrentInstantExtended(), actorName, context.MethodName, this.Id.GetId()) + log.LogTrace("{CurrentInstant}: Started {ActorName}.{MethodName} Id: {Id}.", getCurrentInstantExtended(), actorName, context.MethodName, this.Id) Task.CompletedTask override this.OnPostActorMethodAsync(context) = - let duration = getCurrentInstant().Minus(actorStartTime) - log.LogInformation("{CurrentInstant}: Finished {ActorName}.{MethodName} Id: {Id}; Duration: {duration}ms.", getCurrentInstantExtended(), actorName, context.MethodName, this.Id.GetId(), duration.TotalMilliseconds.ToString("F3")) + let durationμs = (getCurrentInstant().Minus(actorStartTime).TotalMilliseconds * 1000.0).ToString("F0") + log.LogInformation("{CurrentInstant}: Finished {ActorName}.{MethodName}; Id: {Id}; Duration: {duration}μs.", getCurrentInstantExtended(), actorName, context.MethodName, this.Id, durationμs) logScope.Dispose() Task.CompletedTask diff --git a/src/Grace.Actors/Owner.Actor.fs b/src/Grace.Actors/Owner.Actor.fs index e5ec094..09a30c6 100644 --- a/src/Grace.Actors/Owner.Actor.fs +++ b/src/Grace.Actors/Owner.Actor.fs @@ -2,12 +2,14 @@ open Dapr.Actors open Dapr.Actors.Runtime +open FSharp.Control open Grace.Actors.Commands.Owner open Grace.Actors.Services open Grace.Actors.Events.Owner open Grace.Actors.Interfaces open Grace.Shared open Grace.Shared.Constants +open Grace.Shared.Dto.Organization open Grace.Shared.Dto.Owner open Grace.Shared.Types open Grace.Shared.Utilities @@ -15,24 +17,22 @@ open Grace.Shared.Validation.Errors.Owner open Microsoft.Extensions.Logging open NodaTime open System +open System.Collections.Concurrent open System.Collections.Generic open System.Runtime.Serialization open System.Text.Json open System.Threading.Tasks -open FSharp.Control open Constants -open System.Collections.Concurrent -open Grace.Shared.Dto.Organization module Owner = let GetActorId (ownerId: OwnerId) = ActorId($"{ownerId}") - type OwnerActor(host: ActorHost) as this = + type OwnerActor(host: ActorHost) = inherit Actor(host) let actorName = Constants.ActorName.Owner - let log = this.Logger + let log = host.LoggerFactory.CreateLogger(actorName) let mutable actorStartTime = Instant.MinValue let mutable logScope: IDisposable = null let mutable currentCommand = String.Empty @@ -61,13 +61,16 @@ module Owner = {newOwnerDto with UpdatedAt = Some (getCurrentInstant())} override this.OnActivateAsync() = + let activateStartTime = getCurrentInstant() let stateManager = this.StateManager - log.LogInformation("{CurrentInstant}: Activated {ActorType} {ActorId}.", getCurrentInstantExtended(), this.GetType().Name, host.Id) task { let! retrievedDto = Storage.RetrieveState stateManager (dtoStateName) match retrievedDto with | Some retrievedDto -> ownerDto <- retrievedDto | None -> ownerDto <- OwnerDto.Default + + let duration = getCurrentInstant().Minus(activateStartTime) + log.LogInformation("{CurrentInstant}: Activated {ActorType} {ActorId}. Retrieved from storage in {duration}ms.", getCurrentInstantExtended(), actorName, host.Id, duration.TotalMilliseconds.ToString("F3")) } :> Task member private this.SetMaintenanceReminder() = @@ -84,10 +87,11 @@ module Owner = override this.OnPreActorMethodAsync(context) = if context.CallType = ActorCallType.ReminderMethod then - log.LogInformation("{CurrentInstant}: Reminder {ActorName}.{MethodName} Id: {Id}.", getCurrentInstantExtended(), actorName, context.MethodName, this.Id.GetId()) + log.LogInformation("{CurrentInstant}: Reminder {ActorName}.{MethodName} Id: {Id}.", getCurrentInstantExtended(), actorName, context.MethodName, this.Id) actorStartTime <- getCurrentInstant() logScope <- log.BeginScope("Actor {actorName}", actorName) currentCommand <- String.Empty + log.LogTrace("{CurrentInstant}: Started {ActorName}.{MethodName} Id: {Id}.", getCurrentInstantExtended(), actorName, context.MethodName, this.Id) // This checks if the actor is still active, but in an undefined state, which will _almost_ never happen. // isDisposed is set when the actor is deleted, or if an error occurs where we're not sure of the state and want to reload from the database. @@ -95,15 +99,15 @@ module Owner = this.OnActivateAsync().Wait() isDisposed <- false - //log.LogInformation("{CurrentInstant}: Started {ActorName}.{MethodName} Id: {Id}.", getCurrentInstantExtended(), actorName, context.MethodName, this.Id.GetId()) + //log.LogInformation("{CurrentInstant}: Started {ActorName}.{MethodName} Id: {Id}.", getCurrentInstantExtended(), actorName, context.MethodName, this.Id) Task.CompletedTask override this.OnPostActorMethodAsync(context) = - let duration = getCurrentInstant().Minus(actorStartTime) + let durationμs = (getCurrentInstant().Minus(actorStartTime).TotalMilliseconds * 1000.0).ToString("F0") if String.IsNullOrEmpty(currentCommand) then - log.LogInformation("{CurrentInstant}: Finished {ActorName}.{MethodName}; Id: {Id}; Duration: {duration}ms.", $"{getCurrentInstantExtended(),-28}", actorName, context.MethodName, this.Id.GetId(), duration.TotalMilliseconds.ToString("F3")) + log.LogInformation("{CurrentInstant}: Finished {ActorName}.{MethodName}; Id: {Id}; Duration: {duration}μs.", getCurrentInstantExtended(), actorName, context.MethodName, this.Id, durationμs) else - log.LogInformation("{CurrentInstant}: Finished {ActorName}.{MethodName}; Command: {Command}; Id: {Id}; Duration: {duration}ms.", $"{getCurrentInstantExtended(),-28}", actorName, context.MethodName, currentCommand, this.Id.GetId(), duration.TotalMilliseconds.ToString("F3")) + log.LogInformation("{CurrentInstant}: Finished {ActorName}.{MethodName}; Command: {Command}; Id: {Id}; Duration: {duration}μs.", getCurrentInstantExtended(), actorName, context.MethodName, currentCommand, this.Id, durationμs) logScope.Dispose() Task.CompletedTask diff --git a/src/Grace.Actors/OwnerName.Actor.fs b/src/Grace.Actors/OwnerName.Actor.fs index 69bbd01..0434965 100644 --- a/src/Grace.Actors/OwnerName.Actor.fs +++ b/src/Grace.Actors/OwnerName.Actor.fs @@ -29,12 +29,12 @@ module OwnerName = override this.OnPreActorMethodAsync(context) = actorStartTime <- getCurrentInstant() logScope <- log.BeginScope("Actor {actorName}", actorName) - //log.LogInformation("{CurrentInstant}: Started {ActorName}.{MethodName} Id: {Id}.", getCurrentInstantExtended(), actorName, context.MethodName, this.Id.GetId()) + log.LogTrace("{CurrentInstant}: Started {ActorName}.{MethodName} Id: {Id}.", getCurrentInstantExtended(), actorName, context.MethodName, this.Id) Task.CompletedTask override this.OnPostActorMethodAsync(context) = - let duration = getCurrentInstant().Minus(actorStartTime) - log.LogInformation("{CurrentInstant}: Finished {ActorName}.{MethodName} Id: {Id}; Duration: {duration}ms.", getCurrentInstantExtended(), actorName, context.MethodName, this.Id.GetId(), duration.TotalMilliseconds.ToString("F3")) + let durationμs = (getCurrentInstant().Minus(actorStartTime).TotalMilliseconds * 1000.0).ToString("F0") + log.LogInformation("{CurrentInstant}: Finished {ActorName}.{MethodName}; Id: {Id}; Duration: {duration}μs.", getCurrentInstantExtended(), actorName, context.MethodName, this.Id, durationμs) logScope.Dispose() Task.CompletedTask diff --git a/src/Grace.Actors/Repository.Actor.fs b/src/Grace.Actors/Repository.Actor.fs index 6b2375e..75b4122 100644 --- a/src/Grace.Actors/Repository.Actor.fs +++ b/src/Grace.Actors/Repository.Actor.fs @@ -53,20 +53,41 @@ module Repository = let mutable repositoryEvents: List = null override this.OnActivateAsync() = + let activateStartTime = getCurrentInstant() let stateManager = this.StateManager - log.LogInformation("{CurrentInstant}: Activated {ActorType} {ActorId}.", getCurrentInstantExtended(), this.GetType().Name, host.Id) task { let! retrievedDto = Storage.RetrieveState stateManager dtoStateName match retrievedDto with | Some retrievedDto -> repositoryDto <- retrievedDto | None -> repositoryDto <- RepositoryDto.Default - //let! retrievedEvents = Storage.RetrieveState> stateManager eventsStateName - //match retrievedEvents with - // | Some retrievedEvents -> repositoryEvents.AddRange(retrievedEvents) - // | None -> this.onFirstActivation() + let duration = getCurrentInstant().Minus(activateStartTime) + log.LogInformation("{CurrentInstant}: Activated {ActorType} {ActorId}. Retrieved from storage in {duration}ms.", getCurrentInstantExtended(), actorName, host.Id, duration.TotalMilliseconds.ToString("F3")) } :> Task + override this.OnPreActorMethodAsync(context) = + actorStartTime <- getCurrentInstant() + logScope <- log.BeginScope("Actor {actorName}", actorName) + currentCommand <- String.Empty + log.LogTrace("{CurrentInstant}: Started {ActorName}.{MethodName}, Id: {Id}.", getCurrentInstantExtended(), actorName, context.MethodName, this.Id) + + // This checks if the actor is still active, but in an undefined state, which will _almost_ never happen. + // isDisposed is set when the actor is deleted, or if an error occurs where we're not sure of the state and want to reload from the database. + if isDisposed then + this.OnActivateAsync().Wait() + isDisposed <- false + + Task.CompletedTask + + override this.OnPostActorMethodAsync(context) = + let durationμs = (getCurrentInstant().Minus(actorStartTime).TotalMilliseconds * 1000.0).ToString("F0") + if String.IsNullOrEmpty(currentCommand) then + log.LogInformation("{CurrentInstant}: Finished {ActorName}.{MethodName}; Id: {Id}; Duration: {duration}μs.", getCurrentInstantExtended(), actorName, context.MethodName, this.Id, durationμs) + else + log.LogInformation("{CurrentInstant}: Finished {ActorName}.{MethodName}; Command: {Command}; Id: {Id}; Duration: {duration}μs.", getCurrentInstantExtended(), actorName, context.MethodName, currentCommand, this.Id, durationμs) + logScope.Dispose() + Task.CompletedTask + member private this.SetMaintenanceReminder() = this.RegisterReminderAsync(ReminderType.Maintenance, Array.empty, TimeSpan.FromDays(7.0), TimeSpan.FromDays(7.0)) @@ -229,29 +250,6 @@ module Repository = member private this.SchedulePhysicalDeletion(deleteReason) = this.RegisterReminderAsync(ReminderType.PhysicalDeletion, convertToByteArray deleteReason, Constants.DefaultPhysicalDeletionReminderTime, TimeSpan.FromMilliseconds(-1)).Wait() - override this.OnPreActorMethodAsync(context) = - actorStartTime <- getCurrentInstant() - logScope <- log.BeginScope("Actor {actorName}", actorName) - currentCommand <- String.Empty - //log.LogInformation("{CurrentInstant}: Started {ActorName}.{MethodName}, Id: {Id}.", getCurrentInstantExtended(), actorName, context.MethodName, this.Id.GetId()) - - // This checks if the actor is still active, but in an undefined state, which will _almost_ never happen. - // isDisposed is set when the actor is deleted, or if an error occurs where we're not sure of the state and want to reload from the database. - if isDisposed then - this.OnActivateAsync().Wait() - isDisposed <- false - - Task.CompletedTask - - override this.OnPostActorMethodAsync(context) = - let duration = getCurrentInstant().Minus(actorStartTime) - if String.IsNullOrEmpty(currentCommand) then - log.LogInformation("{CurrentInstant}: Finished {ActorName}.{MethodName}; Id: {Id}; Duration: {duration}ms.", $"{getCurrentInstantExtended(),-28}", actorName, context.MethodName, this.Id.GetId(), duration.TotalMilliseconds.ToString("F3")) - else - log.LogInformation("{CurrentInstant}: Finished {ActorName}.{MethodName}; Command: {Command}; Id: {Id}; Duration: {duration}ms.", $"{getCurrentInstantExtended(),-28}", actorName, context.MethodName, currentCommand, this.Id.GetId(), duration.TotalMilliseconds.ToString("F3")) - logScope.Dispose() - Task.CompletedTask - interface IExportable with member this.Export() = task { diff --git a/src/Grace.Actors/RepositoryName.Actor.fs b/src/Grace.Actors/RepositoryName.Actor.fs index 509e01c..d077d04 100644 --- a/src/Grace.Actors/RepositoryName.Actor.fs +++ b/src/Grace.Actors/RepositoryName.Actor.fs @@ -29,12 +29,12 @@ module RepositoryName = override this.OnPreActorMethodAsync(context) = actorStartTime <- getCurrentInstant() logScope <- log.BeginScope("Actor {actorName}", actorName) - //log.LogInformation("{CurrentInstant}: Started {ActorName}.{MethodName} Id: {Id}.", getCurrentInstantExtended(), actorName, context.MethodName, this.Id.GetId()) + log.LogTrace("{CurrentInstant}: Started {ActorName}.{MethodName} Id: {Id}.", getCurrentInstantExtended(), actorName, context.MethodName, this.Id) Task.CompletedTask override this.OnPostActorMethodAsync(context) = - let duration = getCurrentInstant().Minus(actorStartTime) - log.LogInformation("{CurrentInstant}: Finished {ActorName}.{MethodName} Id: {Id}; Duration: {duration}ms.", getCurrentInstantExtended(), actorName, context.MethodName, this.Id.GetId(), duration.TotalMilliseconds.ToString("F3")) + let durationμs = (getCurrentInstant().Minus(actorStartTime).TotalMilliseconds * 1000.0).ToString("F0") + log.LogInformation("{CurrentInstant}: Finished {ActorName}.{MethodName}; Id: {Id}; Duration: {duration}μs.", getCurrentInstantExtended(), actorName, context.MethodName, this.Id, durationμs) logScope.Dispose() Task.CompletedTask diff --git a/src/Grace.Actors/Services.Actor.fs b/src/Grace.Actors/Services.Actor.fs index 5dfe6ac..deb6986 100644 --- a/src/Grace.Actors/Services.Actor.fs +++ b/src/Grace.Actors/Services.Actor.fs @@ -10,24 +10,24 @@ open Grace.Actors.Constants open Grace.Actors.Interfaces open Grace.Shared open Grace.Shared.Constants +open Grace.Shared.Dto.Branch +open Grace.Shared.Dto.Organization +open Grace.Shared.Dto.Reference open Grace.Shared.Dto.Repository open Grace.Shared.Types open Grace.Shared.Utilities open Microsoft.Azure.Cosmos open Microsoft.Azure.Cosmos.Linq +open Microsoft.Extensions.Logging open System open System.Collections.Concurrent open System.Collections.Generic +open System.Diagnostics open System.IO open System.Linq -open System.Threading.Tasks -open System.Text -open Services -open Grace.Shared.Dto.Branch -open Grace.Shared.Dto.Reference -open System.Diagnostics open System.Net -open Grace.Shared.Dto.Organization +open System.Text +open System.Threading.Tasks module Services = @@ -68,6 +68,10 @@ module Services = let setCosmosContainer (container: Container) = cosmosContainer <- container + let mutable internal loggerFactory: ILoggerFactory = null + let setLoggerFactory (factory: ILoggerFactory) = + loggerFactory <- factory + let linqSerializerOptions = CosmosLinqSerializerOptions(PropertyNamingPolicy = CosmosPropertyNamingPolicy.CamelCase) /// Custom QueryRequestOptions that requests Index Metrics only in DEBUG build. diff --git a/src/Grace.CLI/Command/Services.CLI.fs b/src/Grace.CLI/Command/Services.CLI.fs index 9d551eb..9169fb7 100644 --- a/src/Grace.CLI/Command/Services.CLI.fs +++ b/src/Grace.CLI/Command/Services.CLI.fs @@ -31,7 +31,7 @@ open System.Threading.Tasks module Services = /// Utility method to write to the console using color. - let logToAnsiConsole color message = AnsiConsole.MarkupLine $"[{color}]{getCurrentInstantExtended(),-28} {Environment.CurrentManagedThreadId:X2} {Markup.Escape(message)}[/]" + let logToAnsiConsole color message = AnsiConsole.MarkupLine $"[{color}]{getCurrentInstantExtended()} {Environment.CurrentManagedThreadId:X2} {Markup.Escape(message)}[/]" /// A cache of paths that we've already decided to ignore or not. let private shouldIgnoreCache = ConcurrentDictionary() diff --git a/src/Grace.Server/ApplicationContext.Server.fs b/src/Grace.Server/ApplicationContext.Server.fs index aab7744..bfec1e6 100644 --- a/src/Grace.Server/ApplicationContext.Server.fs +++ b/src/Grace.Server/ApplicationContext.Server.fs @@ -12,14 +12,13 @@ open Grace.Shared.Utilities open Microsoft.Azure.Cosmos open Microsoft.Extensions.Configuration open Microsoft.Extensions.DependencyInjection -open NodaTime +open Microsoft.Extensions.Logging open System open System.Collections.Concurrent open System.Collections.Generic open System.Globalization open System.Linq open System.Threading.Tasks -open NodaTime.Text open System.Net.Http open System @@ -30,6 +29,7 @@ module ApplicationContext = let mutable private actorProxyFactory: IActorProxyFactory = null let mutable private actorStateStorageProvider: ActorStateStorageProvider = ActorStateStorageProvider.Unknown + let mutable loggerFactory: ILoggerFactory = null let ActorProxyFactory() = actorProxyFactory let ActorStateStorageProvider() = actorStateStorageProvider @@ -51,6 +51,10 @@ module ApplicationContext = actorStateStorageProvider <- actorStateStorage Grace.Actors.Services.setActorStateStorageProvider actorStateStorageProvider + let setLoggerFactory logFactory = + loggerFactory <- logFactory + Grace.Actors.Services.setLoggerFactory loggerFactory + type StorageAccount = { StorageAccountName: string; diff --git a/src/Grace.Server/Grace.Server.fsproj b/src/Grace.Server/Grace.Server.fsproj index 7d3ff27..3e0ab14 100644 --- a/src/Grace.Server/Grace.Server.fsproj +++ b/src/Grace.Server/Grace.Server.fsproj @@ -11,7 +11,7 @@ false NETSDK1057 AnyCPU;x64 - true + false preview true https://github.com/ScottArbeit/Grace diff --git a/src/Grace.Server/Program.Server.fs b/src/Grace.Server/Program.Server.fs index 0bcca3a..ca0eb58 100644 --- a/src/Grace.Server/Program.Server.fs +++ b/src/Grace.Server/Program.Server.fs @@ -14,6 +14,7 @@ open System.Security.Authentication open System.Threading.Tasks open System.Net open Grace.Shared.Utilities +open Microsoft.Extensions.Logging module Program = let createHostBuilder (args: string[]) : IHostBuilder = @@ -49,6 +50,8 @@ module Program = files |> Seq.iter (fun file -> logToConsole $"{file.Name}: {file.Length} bytes") logToConsole "-----------------------------------------------------------" let host = createHostBuilder(args).Build() + let loggerFactory = host.Services.GetService(typeof) :?> ILoggerFactory + ApplicationContext.setLoggerFactory(loggerFactory) host.Run() 0 // Exit code diff --git a/src/Grace.Server/Startup.Server.fs b/src/Grace.Server/Startup.Server.fs index 2771498..7d49ccb 100644 --- a/src/Grace.Server/Startup.Server.fs +++ b/src/Grace.Server/Startup.Server.fs @@ -337,6 +337,9 @@ module Application = services.AddSignalR(fun options -> options.EnableDetailedErrors <- true) .AddJsonProtocol(fun options -> options.PayloadSerializerOptions <- Constants.JsonSerializerOptions) |> ignore + // List all services to the log. + //services |> Seq.iter (fun service -> logToConsole $"Service: {service.ServiceType}.") + member _.Configure(app: IApplicationBuilder, env: IWebHostEnvironment) = if env.IsDevelopment() then app//.UseSwagger() diff --git a/src/Grace.Shared/Constants.Shared.fs b/src/Grace.Shared/Constants.Shared.fs index 94c4d68..67f992b 100644 --- a/src/Grace.Shared/Constants.Shared.fs +++ b/src/Grace.Shared/Constants.Shared.fs @@ -39,12 +39,13 @@ module Constants = JsonSerializerOptions.DefaultBufferSize <- 64 * 1024 JsonSerializerOptions.DefaultIgnoreCondition <- JsonIgnoreCondition.WhenWritingDefault // JsonSerializerOptions.IgnoreNullValues is deprecated. This is the new way to say it. JsonSerializerOptions.NumberHandling <- JsonNumberHandling.AllowReadingFromString - JsonSerializerOptions.PropertyNameCaseInsensitive <- true + JsonSerializerOptions.PropertyNameCaseInsensitive <- true // Case sensitivity is from the 1970's. We should let it go. //JsonSerializerOptions.PropertyNamingPolicy <- JsonNamingPolicy.CamelCase JsonSerializerOptions.ReadCommentHandling <- JsonCommentHandling.Skip JsonSerializerOptions.ReferenceHandler <- ReferenceHandler.IgnoreCycles JsonSerializerOptions.UnknownTypeHandling <- JsonUnknownTypeHandling.JsonElement JsonSerializerOptions.WriteIndented <- true + JsonSerializerOptions.MaxDepth <- 16 // Default is 64, but if we exceed a depth of 16, we're probably doing something wrong. /// Converts the full name of a discriminated union to a string. Example: ServerApiVersions.Latest -> "ServerApiVersions.Latest" let discriminatedUnionFullName (value:'T) = diff --git a/src/Grace.Shared/Utilities.Shared.fs b/src/Grace.Shared/Utilities.Shared.fs index ccde2b6..ca8eca1 100644 --- a/src/Grace.Shared/Utilities.Shared.fs +++ b/src/Grace.Shared/Utilities.Shared.fs @@ -43,11 +43,17 @@ module Utilities = /// Gets the current instant. let getCurrentInstant() = SystemClock.Instance.GetCurrentInstant() - /// Gets the current instant as a string in ExtendedIso format. Example: "2009-06-15T13:45:30.0000000Z". - let getCurrentInstantExtended() = getCurrentInstant().ToString(InstantPattern.ExtendedIso.PatternText, CultureInfo.InvariantCulture) + /// Formats an instant as a string in ExtendedIso format. Example: "2009-06-15T13:45:30.0000000Z". + let formatInstantExtended (instant: Instant) = $"{instant.ToString(InstantPattern.ExtendedIso.PatternText, CultureInfo.InvariantCulture),-28}" + + /// Gets the current instant as a string in ExtendedIso format. Example: "2009-06-15T13:45:30.0000000Z". + let getCurrentInstantExtended() = getCurrentInstant() |> formatInstantExtended + + /// Gets the current instant as a string in General format. Example: "2009-06-15T13:45:30Z". + let formatInstantGeneral (instant: Instant) = instant.ToString(InstantPattern.General.PatternText, CultureInfo.InvariantCulture) /// Gets the current instant as a string in General format. Example: "2009-06-15T13:45:30Z". - let getCurrentInstantGeneral() = getCurrentInstant().ToString(InstantPattern.General.PatternText, CultureInfo.InvariantCulture) + let getCurrentInstantGeneral() = getCurrentInstant() |> formatInstantGeneral /// Converts an Instant to local time, and produces a string in short date/time format, using the CurrentUICulture. let instantToLocalTime (instant: Instant) = instant.ToDateTimeUtc().ToLocalTime().ToString("g", CultureInfo.CurrentUICulture) @@ -56,7 +62,7 @@ module Utilities = let getCurrentInstantLocal() = getCurrentInstant() |> instantToLocalTime /// Logs the message to the console, with the current instant, thread ID, and message. - let logToConsole message = printfn $"{getCurrentInstantExtended(),-28} {Environment.CurrentManagedThreadId:X2} {message}" + let logToConsole message = printfn $"{getCurrentInstantExtended()} {Environment.CurrentManagedThreadId:X2} {message}" /// Gets the first eight characters of a SHA256 hash. let getShortenedSha256Hash (sha256Hash: String) =