From 4247cde0ac5b66f6aff59c0360c3b399d69907e1 Mon Sep 17 00:00:00 2001 From: anurse Date: Fri, 22 Nov 2013 22:49:27 -0800 Subject: [PATCH] Reworked monitoring --- .gitmodules | 3 + openssl | 0 .../Infrastructure/Job.cs | 33 ++- .../Infrastructure/JobDispatcher.cs | 21 +- .../Infrastructure/JobInvocationContext.cs | 4 +- .../Infrastructure/JobRunner.cs | 74 +++-- .../Jobs/CreateOnlineDatabaseBackupJob.cs | 102 +++---- src/NuGetGallery.Backend/Jobs/HelloJob.cs | 29 ++ .../Monitoring/BackendMonitoringHub.cs | 63 +---- .../Monitoring/InvocationEventSource.cs | 101 +++++++ .../Monitoring/InvocationMonitoringContext.cs | 85 ++++++ .../Monitoring/WorkerEventSource.cs | 253 +++++------------- .../NuGetGallery.Backend.csproj | 7 +- src/NuGetGallery.Backend/WorkerRole.cs | 18 +- .../{AsyncDisposable.cs => Completion.cs} | 6 +- .../Jobs/JobDequeueResult.cs | 27 ++ src/NuGetGallery.Core/Jobs/JobRequestQueue.cs | 11 +- .../Monitoring/Tables/InvocationsEntry.cs | 4 +- .../Monitoring/Tables/JobHistoryEntry.cs | 4 +- .../Monitoring/Tables/JobStatusEntry.cs | 4 +- .../Tables/WorkerInstanceHistoryEntry.cs | 4 +- .../Tables/WorkerInstanceStatusEntry.cs | 4 +- .../NuGetGallery.Core.csproj | 2 + 23 files changed, 484 insertions(+), 375 deletions(-) create mode 100644 .gitmodules create mode 100644 openssl create mode 100644 src/NuGetGallery.Backend/Jobs/HelloJob.cs create mode 100644 src/NuGetGallery.Backend/Monitoring/InvocationEventSource.cs create mode 100644 src/NuGetGallery.Backend/Monitoring/InvocationMonitoringContext.cs rename src/NuGetGallery.Core/{AsyncDisposable.cs => Completion.cs} (74%) create mode 100644 src/NuGetGallery.Core/Jobs/JobDequeueResult.cs diff --git a/.gitmodules b/.gitmodules new file mode 100644 index 0000000000..7c3720f00d --- /dev/null +++ b/.gitmodules @@ -0,0 +1,3 @@ +[submodule "ext/Slab"] + path = ext/Slab + url = https://git01.codeplex.com/slab diff --git a/openssl b/openssl new file mode 100644 index 0000000000..e69de29bb2 diff --git a/src/NuGetGallery.Backend/Infrastructure/Job.cs b/src/NuGetGallery.Backend/Infrastructure/Job.cs index 44f3300de2..961424995d 100644 --- a/src/NuGetGallery.Backend/Infrastructure/Job.cs +++ b/src/NuGetGallery.Backend/Infrastructure/Job.cs @@ -39,10 +39,17 @@ public virtual async Task Invoke(JobInvocationContext context) { // Bind invocation information Context = context; - BindProperties(Invocation.Request.Parameters); + try + { + BindProperties(Invocation.Request.Parameters); + } + catch (Exception ex) + { + context.Log.BindingError(ex); + return JobResult.Faulted(ex); + } // Invoke the job - WorkerEventSource.Log.JobStarted(Invocation.Request.Name, Invocation.Id); JobResult result; try { @@ -54,15 +61,6 @@ public virtual async Task Invoke(JobInvocationContext context) result = JobResult.Faulted(ex); } - if (result.Status != JobStatus.Faulted) - { - WorkerEventSource.Log.JobCompleted(Invocation.Request.Name, Invocation.Id); - } - else - { - WorkerEventSource.Log.JobFaulted(Invocation.Request.Name, result.Exception, Invocation.Id); - } - // Return the result return result; } @@ -144,4 +142,17 @@ public override object ConvertFrom(ITypeDescriptorContext context, System.Global } } } + + public abstract class Job : Job + where TEventSource : EventSource, new() + { + private TEventSource _log = new TEventSource(); + + public TEventSource Log { get { return _log; } } + + public override EventSource GetEventSource() + { + return Log; + } + } } diff --git a/src/NuGetGallery.Backend/Infrastructure/JobDispatcher.cs b/src/NuGetGallery.Backend/Infrastructure/JobDispatcher.cs index 8460594bc9..79e5c8551c 100644 --- a/src/NuGetGallery.Backend/Infrastructure/JobDispatcher.cs +++ b/src/NuGetGallery.Backend/Infrastructure/JobDispatcher.cs @@ -13,17 +13,16 @@ public class JobDispatcher private Dictionary _jobMap; private List _jobs; private BackendMonitoringHub _monitor; - + public IReadOnlyList Jobs { get { return _jobs.AsReadOnly(); } } public BackendConfiguration Config { get; private set; } - public JobDispatcher(BackendConfiguration config, IEnumerable jobs) : this(config, jobs, null) { } public JobDispatcher(BackendConfiguration config, IEnumerable jobs, BackendMonitoringHub monitor) { _jobs = jobs.ToList(); _jobMap = _jobs.ToDictionary(j => j.Name); _monitor = monitor; - + Config = config; foreach (var job in _jobs) @@ -32,7 +31,7 @@ public JobDispatcher(BackendConfiguration config, IEnumerable jobs, Backend } } - public virtual async Task Dispatch(JobInvocation invocation) + public virtual async Task Dispatch(JobInvocation invocation, InvocationEventSource log, InvocationMonitoringContext monitoring) { Job job; if (!_jobMap.TryGetValue(invocation.Request.Name, out job)) @@ -40,15 +39,14 @@ public virtual async Task Dispatch(JobInvocation invocation) throw new UnknownJobException(invocation.Request.Name); } - IAsyncDeferred monitorCompletion = null; - if (_monitor != null) + if (monitoring != null) { - monitorCompletion = await _monitor.InvokingJob(invocation, job); + await monitoring.SetJob(job); } - WorkerEventSource.Log.DispatchingRequest(invocation); + log.Invoking(job); JobResult result = null; - var context = new JobInvocationContext(invocation, Config, _monitor); + var context = new JobInvocationContext(invocation, Config, _monitor, log); try { result = await job.Invoke(context); @@ -57,11 +55,6 @@ public virtual async Task Dispatch(JobInvocation invocation) { result = JobResult.Faulted(ex); } - - if (monitorCompletion != null) - { - await monitorCompletion.Complete(result); - } return new JobResponse(invocation, result, DateTimeOffset.UtcNow); } diff --git a/src/NuGetGallery.Backend/Infrastructure/JobInvocationContext.cs b/src/NuGetGallery.Backend/Infrastructure/JobInvocationContext.cs index 51e9cdb4fc..e596995130 100644 --- a/src/NuGetGallery.Backend/Infrastructure/JobInvocationContext.cs +++ b/src/NuGetGallery.Backend/Infrastructure/JobInvocationContext.cs @@ -12,12 +12,14 @@ public class JobInvocationContext public JobInvocation Invocation { get; private set; } public BackendConfiguration Config { get; private set; } public BackendMonitoringHub Monitor { get; private set; } + public InvocationEventSource Log { get; private set; } - public JobInvocationContext(JobInvocation invocation, BackendConfiguration config, BackendMonitoringHub monitor) + public JobInvocationContext(JobInvocation invocation, BackendConfiguration config, BackendMonitoringHub monitor, InvocationEventSource log) { Invocation = invocation; Config = config; Monitor = monitor; + Log = log; } } } diff --git a/src/NuGetGallery.Backend/Infrastructure/JobRunner.cs b/src/NuGetGallery.Backend/Infrastructure/JobRunner.cs index 54d9d2500d..e47bdb6918 100644 --- a/src/NuGetGallery.Backend/Infrastructure/JobRunner.cs +++ b/src/NuGetGallery.Backend/Infrastructure/JobRunner.cs @@ -38,54 +38,76 @@ public JobRunner(JobDispatcher dispatcher, BackendConfiguration config, BackendM public async Task Run(CancellationToken cancelToken) { - WorkerEventSource.Log.WorkerDispatching(); - while (!cancelToken.IsCancellationRequested) + WorkerEventSource.Log.DispatchLoopStarted(); + try { - var response = await DispatchOne(cancelToken); - if (response != null) + while (!cancelToken.IsCancellationRequested) { - WorkerEventSource.Log.JobExecuted(response); - } - else - { - WorkerEventSource.Log.QueueEmpty(_config.QueuePollInterval); - await Task.Delay(_config.QueuePollInterval); + JobDequeueResult dequeued = await _queue.Dequeue(DefaultInvisibilityPeriod, cancelToken); + if (dequeued == null) + { + WorkerEventSource.Log.DispatchLoopWaiting(_config.QueuePollInterval); + await Task.Delay(_config.QueuePollInterval); + WorkerEventSource.Log.DispatchLoopResumed(); + } + else if (!dequeued.Success) + { + WorkerEventSource.Log.InvalidQueueMessage(dequeued.MessageBody, dequeued.ParseException); + } + else + { + Debug.Assert(dequeued.Request.Message != null); // Since we dequeued, there'd better be a CloudQueueMessage. + await Dispatch(dequeued.Request); + } } } - } - - private async Task DispatchOne(CancellationToken cancelToken) - { - var request = await _queue.Dequeue(DefaultInvisibilityPeriod, cancelToken); - if (request == null) + catch (Exception ex) { - return null; + WorkerEventSource.Log.DispatchLoopError(ex); } - Debug.Assert(request.Message != null); // Since we dequeued, there'd better be a CloudQueueMessage. - WorkerEventSource.Log.RequestReceived(request.Id, request.InsertionTime); + WorkerEventSource.Log.DispatchLoopEnded(); + } + private async Task Dispatch(JobRequest request) + { + // Construct an invocation. From here on, we're in the context of this invocation. var invocation = new JobInvocation(Guid.NewGuid(), request, DateTimeOffset.UtcNow); + var log = new InvocationEventSource(invocation.Id); + + var context = _monitoring.BeginInvocation(invocation, log); + log.Started(); + + JobResponse response = null; try { - JobResponse response = await _dispatcher.Dispatch(invocation); + response = await _dispatcher.Dispatch(invocation, log, context); + + if (response.Result.Status != JobStatus.Faulted) + { + log.Succeeded(response); + } + else + { + log.Faulted(response); + } if (request.ExpiresAt.HasValue && DateTimeOffset.UtcNow > request.ExpiresAt.Value) { - WorkerEventSource.Log.JobRequestExpired(request, request.Id, DateTimeOffset.UtcNow - request.ExpiresAt.Value); + log.RequestExpired(request); } // If dispatch throws, we don't delete the message // NOTE: If the JOB throws, the dispatcher should catch it and return the error in the response // Thus the request is considered "handled" await _queue.Acknowledge(request); - - return response; } - catch(Exception ex) + catch (Exception ex) { - WorkerEventSource.Log.DispatchError(invocation, ex); - return null; + log.DispatchError(ex); } + + log.Ended(); + await context.End(response == null ? null : response.Result); } } } diff --git a/src/NuGetGallery.Backend/Jobs/CreateOnlineDatabaseBackupJob.cs b/src/NuGetGallery.Backend/Jobs/CreateOnlineDatabaseBackupJob.cs index e92b96a1dd..aa4b99171b 100644 --- a/src/NuGetGallery.Backend/Jobs/CreateOnlineDatabaseBackupJob.cs +++ b/src/NuGetGallery.Backend/Jobs/CreateOnlineDatabaseBackupJob.cs @@ -11,7 +11,7 @@ namespace NuGetGallery.Backend.Jobs { - public class CreateOnlineDatabaseBackupJob : Job + public class CreateOnlineDatabaseBackupJob : Job { /// /// The target server, in the form of a known SQL Server (primary, warehouse, etc.) @@ -46,11 +46,6 @@ public class CreateOnlineDatabaseBackupJob : Job /// public bool Force { get; set; } - public override EventSource GetEventSource() - { - return JobEventSource.Log; - } - protected internal override async Task Execute() { // Resolve the connection if not specified explicitly @@ -60,7 +55,7 @@ protected internal override async Task Execute() .GetSqlServer(TargetServer) .ChangeDatabase(TargetDatabaseName); } - JobEventSource.Log.PreparingToBackup( + Log.PreparingToBackup( TargetDatabaseConnection.InitialCatalog, TargetDatabaseConnection.DataSource); // Connect to the master database @@ -69,7 +64,7 @@ protected internal override async Task Execute() if (!Force && MaxAge != null) { // Get databases - JobEventSource.Log.GettingDatabaseList(TargetDatabaseConnection.DataSource); + Log.GettingDatabaseList(TargetDatabaseConnection.DataSource); var databases = await GetDatabases(connection); // Gather backups with matching prefix and order descending @@ -88,7 +83,7 @@ orderby backupMeta.Timestamp descending if (mostRecent != null && mostRecent.Timestamp.IsYoungerThan(MaxAge.Value)) { // Skip the backup - JobEventSource.Log.BackupWithinMaxAge(mostRecent, MaxAge.Value); + Log.BackupWithinMaxAge(mostRecent, MaxAge.Value); return; } } @@ -98,19 +93,13 @@ orderby backupMeta.Timestamp descending // Start a copy // (have to build the SQL string manually because you can't parameterize CREATE DATABASE) - JobEventSource.Log.StartingCopy(TargetDatabaseConnection.InitialCatalog, backupName); + Log.StartingCopy(TargetDatabaseConnection.InitialCatalog, backupName); await connection.ExecuteAsync(String.Format( CultureInfo.InvariantCulture, "CREATE DATABASE {0} AS COPY OF {1}", backupName, TargetDatabaseConnection.InitialCatalog)); - JobEventSource.Log.StartedCopy(TargetDatabaseConnection.InitialCatalog, backupName); - - // Return a result to queue an async completion check in 5 minutes. - return JobResult.AsyncCompletion(new - { - DatabaseName = backupName - }, TimeSpan.FromMinutes(5)); + Log.StartedCopy(TargetDatabaseConnection.InitialCatalog, backupName); } } @@ -121,49 +110,42 @@ protected internal virtual Task> GetDatabases(SqlConnectio FROM sys.databases "); } + } - [EventSource(Name="NuGet-Jobs-CreateOnlineDatabaseBackup")] - public class JobEventSource : EventSource - { - public static readonly JobEventSource Log = new JobEventSource(); - - private JobEventSource() { } - -#pragma warning disable 0618 - [Event( - eventId: 1, - Level = EventLevel.Informational, - Message = "Skipping backup. {0} is within maximum age of {1}.")] - [Obsolete("This method supports ETL infrastructure. Use other overloads instead")] - public void BackupWithinMaxAge(string name, string age) { WriteEvent(1, name, age); } - - [NonEvent] - public void BackupWithinMaxAge(DatabaseBackup mostRecent, TimeSpan timeSpan) { BackupWithinMaxAge(mostRecent.Db.name, timeSpan.ToString()); } - - [Event( - eventId: 2, - Level = EventLevel.Informational, - Message = "Getting list of databases on {0}")] - public void GettingDatabaseList(string server) { WriteEvent(2, server); } - - [Event( - eventId: 3, - Level = EventLevel.Informational, - Message = "Preparing to backup {1} on server {0}")] - public void PreparingToBackup(string server, string database) { WriteEvent(3, server, database); } - - [Event( - eventId: 4, - Level = EventLevel.Informational, - Message = "Starting copy of {0} to {1}")] - public void StartingCopy(string source, string destination) { WriteEvent(4, source, destination); } - - [Event( - eventId: 5, - Level = EventLevel.Informational, - Message = "Started copy of {0} to {1}")] - public void StartedCopy(string source, string destination) { WriteEvent(5, source, destination); } -#pragma warning restore 0618 - } + [EventSource(Name = "NuGet-Jobs-CreateOnlineDatabaseBackup")] + public class CreateOnlineDatabaseBackupEventSource : EventSource + { + [Event( + eventId: 1, + Level = EventLevel.Informational, + Message = "Skipping backup. {0} is within maximum age of {1}.")] + private void BackupWithinMaxAge(string name, string age) { WriteEvent(1, name, age); } + + [NonEvent] + public void BackupWithinMaxAge(DatabaseBackup mostRecent, TimeSpan timeSpan) { BackupWithinMaxAge(mostRecent.Db.name, timeSpan.ToString()); } + + [Event( + eventId: 2, + Level = EventLevel.Informational, + Message = "Getting list of databases on {0}")] + public void GettingDatabaseList(string server) { WriteEvent(2, server); } + + [Event( + eventId: 3, + Level = EventLevel.Informational, + Message = "Preparing to backup {1} on server {0}")] + public void PreparingToBackup(string server, string database) { WriteEvent(3, server, database); } + + [Event( + eventId: 4, + Level = EventLevel.Informational, + Message = "Starting copy of {0} to {1}")] + public void StartingCopy(string source, string destination) { WriteEvent(4, source, destination); } + + [Event( + eventId: 5, + Level = EventLevel.Informational, + Message = "Started copy of {0} to {1}")] + public void StartedCopy(string source, string destination) { WriteEvent(5, source, destination); } } } diff --git a/src/NuGetGallery.Backend/Jobs/HelloJob.cs b/src/NuGetGallery.Backend/Jobs/HelloJob.cs new file mode 100644 index 0000000000..7fad516417 --- /dev/null +++ b/src/NuGetGallery.Backend/Jobs/HelloJob.cs @@ -0,0 +1,29 @@ +using System; +using System.Collections.Generic; +using System.Diagnostics.Tracing; +using System.Linq; +using System.Text; +using System.Threading.Tasks; + +namespace NuGetGallery.Backend.Jobs +{ + public class HelloJob : Job + { + protected internal override async Task Execute() + { + Log.Started(); + await Task.Delay(500); + Log.Saying("Hello!"); + await Task.Delay(500); + Log.Finished(); + } + } + + [EventSource(Name = "NuGet-Jobs-Hello")] + public class HelloEventSource : EventSource + { + public void Started() { WriteEvent(1); } + public void Saying(string message) { WriteEvent(2, message); } + public void Finished() { WriteEvent(3); } + } +} diff --git a/src/NuGetGallery.Backend/Monitoring/BackendMonitoringHub.cs b/src/NuGetGallery.Backend/Monitoring/BackendMonitoringHub.cs index 05a3857b8e..543f9c4167 100644 --- a/src/NuGetGallery.Backend/Monitoring/BackendMonitoringHub.cs +++ b/src/NuGetGallery.Backend/Monitoring/BackendMonitoringHub.cs @@ -23,8 +23,8 @@ namespace NuGetGallery.Backend.Monitoring { public class BackendMonitoringHub : MonitoringHub { - private const string BackendMonitoringContainerName = "backend-monitoring"; - private const string BackendTraceTableName = "BackendTrace"; + internal const string BackendMonitoringContainerName = "backend-monitoring"; + internal const string BackendTraceTableName = "BackendTrace"; private Dictionary _eventStreams = new Dictionary(); @@ -62,18 +62,6 @@ public BackendMonitoringHub( /// The job to register public virtual void RegisterJob(Job job) { - // Set up an event listener for the job - var eventStream = new ObservableEventListener(); - eventStream.EnableEvents(job.GetEventSource(), EventLevel.LogAlways); - _eventStreams[job] = eventStream; - - // Set up the table listener for this job - var tableName = GetTableFullName("Job" + job.Name); - eventStream.LogToWindowsAzureTable( - InstanceName, - StorageConnectionString, - tableAddress: tableName); - // Log an entry for the job in the status table _jobStatusTable.InsertOrIgnoreDuplicate(new JobStatusEntry(job.Name, DateTimeOffset.UtcNow)); } @@ -94,44 +82,17 @@ public override async Task Start() /// /// Handles monitoring tasks performed when a job request is dispatched. Call Complete(JobResult) - /// on the IAsyncDeferred returned by this method when the job finishes execution. + /// on the IComplete returned by this method when the job finishes execution. /// - public async Task> InvokingJob(JobInvocation invocation, Job job) + public InvocationMonitoringContext BeginInvocation(JobInvocation invocation, InvocationEventSource log) { - // Record start of job - DateTimeOffset startTime = DateTimeOffset.UtcNow; - await ReportStartJob(invocation, job, startTime); - - // Get the event stream for this job - ObservableEventListener eventStream; - if (!_eventStreams.TryGetValue(job, out eventStream)) - { - return null; - } - - // Capture the events into a flat file - var fileName = invocation.Id.ToString("N") + ".json"; - var path = Path.Combine(TempDirectory, "Invocations", fileName); - var token = eventStream.LogToFlatFile( - path, - new JsonEventTextFormatter(EventTextFormatting.None)); - return new AsyncDeferred(async result => - { - // Disconnect the listener - token.Dispose(); - - // Upload the file to blob storage - var blob = await UploadBlob(path, BackendMonitoringContainerName, "invocations/" + fileName); - - // Delete the temp file - File.Delete(path); - - // Record end of job - await ReportEndJob(invocation, result, job, blob.Uri.AbsoluteUri, startTime, DateTimeOffset.UtcNow); - }); + // Create a monitoring context + var context = new InvocationMonitoringContext(invocation, log, this); + context.Begin(); + return context; } - private Task ReportStartJob(JobInvocation invocation, Job job, DateTimeOffset startTime) + internal Task ReportStartJob(JobInvocation invocation, Job job, DateTimeOffset startTime) { return Task.WhenAll( // Add History Rows @@ -141,12 +102,12 @@ private Task ReportStartJob(JobInvocation invocation, Job job, DateTimeOffset st // Upsert Status Rows _jobStatusTable.Upsert(new JobStatusEntry(job.Name, startTime, invocation.Id, InstanceName)), _instanceStatusTable.Upsert(new WorkerInstanceStatusEntry(InstanceName, startTime, BackendInstanceStatus.Executing, invocation.Id, job.Name)), - + // Add invocation row _invocationsTable.Upsert(new InvocationsEntry(invocation))); } - private Task ReportEndJob(JobInvocation invocation, JobResult result, Job job, string logUrl, DateTimeOffset startTime, DateTimeOffset completionTime) + internal Task ReportEndJob(JobInvocation invocation, JobResult result, Job job, string logUrl, DateTimeOffset startTime, DateTimeOffset completionTime) { return Task.WhenAll( // Add History Rows @@ -158,7 +119,7 @@ private Task ReportEndJob(JobInvocation invocation, JobResult result, Job job, s _instanceStatusTable.Upsert(new WorkerInstanceStatusEntry(InstanceName, startTime, BackendInstanceStatus.Idle, invocation.Id, job.Name, result, completionTime)), // Update invocation row - _invocationsTable.Upsert(new InvocationsEntry(invocation, result, logUrl))); + _invocationsTable.Upsert(new InvocationsEntry(invocation, result, logUrl, completionTime))); } } } diff --git a/src/NuGetGallery.Backend/Monitoring/InvocationEventSource.cs b/src/NuGetGallery.Backend/Monitoring/InvocationEventSource.cs new file mode 100644 index 0000000000..e04a18bee1 --- /dev/null +++ b/src/NuGetGallery.Backend/Monitoring/InvocationEventSource.cs @@ -0,0 +1,101 @@ +using System; +using System.Collections.Generic; +using System.Diagnostics.Tracing; +using System.Linq; +using System.Text; +using System.Threading.Tasks; +using NuGetGallery.Jobs; + +namespace NuGetGallery.Backend.Monitoring +{ + [EventSource(Name = "NuGet-Worker-Invocation")] + public class InvocationEventSource : EventSource + { + private Guid _invocationId; + + public InvocationEventSource(Guid invocationId) + { + _invocationId = invocationId; + } + + public static class Tasks { + public const EventTask Invocation = (EventTask)1; + } + + [Event( + eventId: 1, + Task = Tasks.Invocation, + Opcode = EventOpcode.Start, + Level = EventLevel.Informational, + Message = "Invocation {0} started.")] + private void Started(Guid invocationId) { WriteEvent(1, invocationId); } + + [NonEvent] + public void Started() { Started(_invocationId); } + + [Event( + eventId: 2, + Task = Tasks.Invocation, + Opcode = EventOpcode.Stop, + Level = EventLevel.Informational, + Message = "Invocation {0} ended.")] + private void Ended(Guid invocationId) { WriteEvent(2, invocationId); } + + [NonEvent] + public void Ended() { Ended(_invocationId); } + + [Event( + eventId: 3, + Level = EventLevel.Critical, + Message = "Request expired while job was executing. Invocation: {0}. Job: {1}. Message ID: {2}. Inserted: {3}. Expired: {4}")] + private void RequestExpired(Guid invocationId, string jobName, string messageId, string inserted, string expired) { WriteEvent(3, jobName, messageId, inserted, expired); } + + [NonEvent] + public void RequestExpired(JobRequest request) { RequestExpired(_invocationId, request.Name, request.Message.Id, request.InsertionTime.ToString("O"), request.ExpiresAt.HasValue ? request.ExpiresAt.Value.ToString("O") : ""); } + + [Event( + eventId: 4, + Level = EventLevel.Critical, + Message = "Error Dispatching Invocation {0}: {1}")] + private void DispatchError(Guid invocationId, string exception) { WriteEvent(4, exception); } + + [NonEvent] + public void DispatchError(Exception ex) { DispatchError(_invocationId, ex.ToString()); } + + [Event( + eventId: 5, + Level = EventLevel.Informational, + Message = "Invoking invocation {0}. Job: {1}. Runtime: {2}")] + private void Invoking(Guid invocationId, string jobName, string jobRuntime) { WriteEvent(5, invocationId, jobName, jobRuntime); } + + [NonEvent] + public void Invoking(Job job) { Invoking(_invocationId, job.Name, job.GetType().AssemblyQualifiedName); } + + [Event( + eventId: 6, + Level = EventLevel.Error, + Message = "Parameter binding error during invocation {0}: {1}")] + private void BindingError(Guid invocationId, string exception) { WriteEvent(6, invocationId, exception); } + + [NonEvent] + public void BindingError(Exception ex) { BindingError(_invocationId, ex.ToString()); } + + [Event( + eventId: 7, + Level = EventLevel.Informational, + Message = "Invocation {0} succeeded at {1}")] + private void Succeeded(Guid invocationId, string completedAt) { WriteEvent(7, invocationId, completedAt); } + + [NonEvent] + public void Succeeded(JobResponse response) { Succeeded(_invocationId, response.CompletedAt.ToString("O")); } + + [Event( + eventId: 8, + Level = EventLevel.Error, + Message = "Invocation {0} faulted at {1}: {2}")] + private void Faulted(Guid invocationId, string completedAt, string exception) { WriteEvent(8, invocationId, completedAt, exception); } + + [NonEvent] + public void Faulted(JobResponse response) { Faulted(_invocationId, response.CompletedAt.ToString("O"), response.Result.Exception.ToString()); } + } +} diff --git a/src/NuGetGallery.Backend/Monitoring/InvocationMonitoringContext.cs b/src/NuGetGallery.Backend/Monitoring/InvocationMonitoringContext.cs new file mode 100644 index 0000000000..2bd42b68c9 --- /dev/null +++ b/src/NuGetGallery.Backend/Monitoring/InvocationMonitoringContext.cs @@ -0,0 +1,85 @@ +using System; +using System.Collections.Generic; +using System.Diagnostics.Tracing; +using System.IO; +using System.Linq; +using System.Text; +using System.Threading.Tasks; +using Microsoft.Practices.EnterpriseLibrary.SemanticLogging; +using Microsoft.Practices.EnterpriseLibrary.SemanticLogging.Formatters; +using NuGetGallery.Jobs; + +namespace NuGetGallery.Backend.Monitoring +{ + public class InvocationMonitoringContext + { + private InvocationEventSource _workerLog; + private ObservableEventListener _eventStream; + + private string _jsonLog; + private string _textLog; + private IDisposable _jsonSubscription; + private IDisposable _textSubscription; + private DateTimeOffset _startTime; + + public JobInvocation Invocation { get; private set; } + public BackendMonitoringHub Monitoring { get; private set; } + public Job Job { get; private set; } + + public InvocationMonitoringContext(JobInvocation invocation, InvocationEventSource log, BackendMonitoringHub monitoring) + { + Invocation = invocation; + Monitoring = monitoring; + _workerLog = log; + } + + public void Begin() + { + // Mark start time + _startTime = DateTimeOffset.UtcNow; + + // Set up an event stream + _eventStream = new ObservableEventListener(); + _eventStream.EnableEvents(_workerLog, EventLevel.Informational); + + // Capture the events into a flat file + var root = Path.Combine(Monitoring.TempDirectory, "Invocations"); + _jsonLog = Path.Combine(root, Invocation.Id.ToString("N") + ".json"); + _textLog = Path.Combine(root, Invocation.Id.ToString("N") + ".txt"); + + // Json Log + _jsonSubscription = _eventStream.LogToFlatFile(_jsonLog, new JsonEventTextFormatter(EventTextFormatting.Indented, dateTimeFormat: "O")); + + // Plain text log + _textSubscription = _eventStream.LogToFlatFile(_textLog, new EventTextFormatter(dateTimeFormat: "O")); + } + + public async Task End(JobResult result) + { + // Disconnect the listener + _jsonSubscription.Dispose(); + _textSubscription.Dispose(); + + // Upload the file to blob storage + var jsonBlob = await Monitoring.UploadBlob(_jsonLog, BackendMonitoringHub.BackendMonitoringContainerName, "invocations/" + Path.GetFileName(_jsonLog)); + await Monitoring.UploadBlob(_textLog, BackendMonitoringHub.BackendMonitoringContainerName, "invocations/" + Path.GetFileName(_textLog)); + + // Delete the temp files + File.Delete(_jsonLog); + File.Delete(_textLog); + + // Record end of job + await Monitoring.ReportEndJob(Invocation, result, Job, jsonBlob.Uri.AbsoluteUri, _startTime, DateTimeOffset.UtcNow); + } + + public async Task SetJob(Job job) + { + Job = job; + + // Record start of job + await Monitoring.ReportStartJob(Invocation, Job, _startTime); + + _eventStream.EnableEvents(Job.GetEventSource(), EventLevel.Informational); + } + } +} diff --git a/src/NuGetGallery.Backend/Monitoring/WorkerEventSource.cs b/src/NuGetGallery.Backend/Monitoring/WorkerEventSource.cs index 18b8a5ad93..6c16d6ebf4 100644 --- a/src/NuGetGallery.Backend/Monitoring/WorkerEventSource.cs +++ b/src/NuGetGallery.Backend/Monitoring/WorkerEventSource.cs @@ -15,245 +15,118 @@ public class WorkerEventSource : EventSource private WorkerEventSource() { } -#pragma warning disable 0618 + public static class Tasks + { + public const EventTask Startup = (EventTask)1; + public const EventTask Shutdown = (EventTask)2; + public const EventTask Dispatching = (EventTask)3; + } + [Event( eventId: 1, Level = EventLevel.Informational, + Task = Tasks.Startup, + Opcode = EventOpcode.Start, Message = "Worker Starting")] public void Starting() { WriteEvent(1); } [Event( eventId: 2, - Level = EventLevel.Error, - Message = "Worker encoutered a startup error: {0}.\r\nStack Trace: {1}.")] - [Obsolete("This method supports ETL infrastructure. Use other overloads instead")] - public void StartupError(string exception, string stackTrace) { WriteEvent(2, exception, stackTrace); } + Level = EventLevel.Critical, + Task = Tasks.Startup, + Opcode = EventOpcode.Stop, + Message = "Worker encountered a fatal startup error: {0}")] + private void StartupError(string exception) { WriteEvent(2, exception); } [NonEvent] - public void StartupError(Exception ex) { StartupError(ex.ToString(), ex.StackTrace); } + public void StartupError(Exception ex) { StartupError(ex.ToString()); } [Event( eventId: 3, - Level = EventLevel.Critical, - Message = "Worker encountered a fatal startup error: {0}.\r\nStack Trace: {1}.")] - [Obsolete("This method supports ETL infrastructure. Use other overloads instead")] - public void StartupFatal(string exception, string stackTrace) { WriteEvent(3, exception, stackTrace); } - - [NonEvent] - public void StartupFatal(Exception ex) { StartupFatal(ex.ToString(), ex.StackTrace); } + Message = "Worker has started", + Task = Tasks.Startup, + Opcode = EventOpcode.Stop, + Level = EventLevel.Informational)] + public void StartupComplete() { WriteEvent(3); } [Event( eventId: 4, - Level = EventLevel.Informational, - Message = "Worker Diagnostics Initialized")] - public void DiagnosticsInitialized() { WriteEvent(4); } - - [Event( - eventId: 5, - Level = EventLevel.Error, - Message = "Invalid Queue Message Received: {0}.\r\nException: {1}\r\nStack Trace: {2}")] - [Obsolete("This method supports ETL infrastructure. Use other overloads instead")] - public void InvalidQueueMessage(string message, string exception, string stackTrace) { WriteEvent(5, message, exception, stackTrace); } - - [NonEvent] - public void InvalidQueueMessage(string message, Exception ex) { InvalidQueueMessage(message, ex.ToString(), ex.StackTrace); } - - [NonEvent] - public void InvalidQueueMessage(string message, string error) { InvalidQueueMessage(message, error, ""); } - - [Event( - eventId: 6, - Level = EventLevel.Error, - Message = "Error reporting result of invoking {1} (ID: {0}).\r\nException: {1}\r\nStack Trace: {2}")] - [Obsolete("This method supports ETL infrastructure. Use other overloads instead")] - public void ReportingFailure(string invocationId, string jobName, string exception, string stackTrace) { WriteEvent(6, invocationId, jobName, exception, stackTrace); } - - [NonEvent] - public void ReportingFailure(JobResponse response, Exception ex) { ReportingFailure(response.Invocation.Id.ToString("N"), response.Invocation.Request.Name, ex.ToString(), ex.StackTrace); } - - [Event( - eventId: 7, Message = "{0} job discovered. Runtime: {1}", Level = EventLevel.Informational)] - [Obsolete("This method supports ETL infrastructure. Use other overloads instead")] - public void JobDiscovered(string jobName, string runtime) { WriteEvent(7, jobName, runtime); } + private void JobDiscovered(string jobName, string runtime) { WriteEvent(4, jobName, runtime); } [NonEvent] public void JobDiscovered(Job instance) { JobDiscovered(instance.Name, instance.GetType().AssemblyQualifiedName); } [Event( - eventId: 8, - Message = "Dispatching Invocation of {0}. Id: {1}", - Level = EventLevel.Informational)] - [Obsolete("This method supports ETL infrastructure. Use other overloads instead")] - public void DispatchingRequest(string jobName, string invocationId) { WriteEvent(8, jobName, invocationId); } - - [NonEvent] - public void DispatchingRequest(JobInvocation invocation) { DispatchingRequest(invocation.Request.Name, invocation.Id.ToString("N")); } - - [Event( - eventId: 9, + eventId: 5, + Task = Tasks.Shutdown, + Opcode = EventOpcode.Start, Message = "Worker is stopping", Level = EventLevel.Informational)] - public void Stopping() { WriteEvent(9); } + public void Stopping() { WriteEvent(5); } [Event( - eventId: 10, - Message = "Worker has started", + eventId: 6, + Task = Tasks.Shutdown, + Opcode = EventOpcode.Stop, + Message = "Worker has stopped", Level = EventLevel.Informational)] - public void StartupComplete() { WriteEvent(10); } - - [Event( - eventId: 11, - Level = EventLevel.Informational, - Message = "Worker Diagnostics Initializing")] - public void DiagnosticsInitializing() { WriteEvent(11); } - - [Event( - eventId: 12, - Level = EventLevel.Error, - Message = "Worker encoutered an error while initializing diagnostics: {0}.\r\nStack Trace: {1}.")] - [Obsolete("This method supports ETL infrastructure. Use other overloads instead")] - public void DiagnosticsInitializationError(string exception, string stackTrace) { WriteEvent(12, exception, stackTrace); } - - [NonEvent] - public void DiagnosticsInitializationError(Exception ex) { DiagnosticsInitializationError(ex.ToString(), ex.StackTrace); } - - [Event( - eventId: 13, - Level = EventLevel.Informational, - Message = "Initializing Diagnostics for {0} job.")] - public void DiagnosticsRegisterJob(string jobName) { WriteEvent(13, jobName); } - - [Event( - eventId: 14, - Level = EventLevel.Error, - Message = "Worker encoutered an error while initializing diagnostics for the {0} job: {1}.\r\nStack Trace: {2}.")] - [Obsolete("This method supports ETL infrastructure. Use other overloads instead")] - public void DiagnosticsJobRegisterError(string jobName, string exception, string stackTrace) { WriteEvent(14, jobName, exception, stackTrace); } - - [NonEvent] - public void DiagnosticsJobRegisterError(string jobName, Exception ex) { DiagnosticsJobRegisterError(jobName, ex.ToString(), ex.StackTrace); } - - [Event( - eventId: 15, - Level = EventLevel.Informational, - Message = "Initialized Diagnostics for {0} job. Table: {1}")] - public void DiagnosticsJobRegistered(string jobName, string tableName) { WriteEvent(15, jobName, tableName); } - - [Event( - eventId: 16, - Level = EventLevel.Informational, - Message = "Received Job Request Queue Message {0}. Inserted at: {1}")] - [Obsolete("This method supports ETL infrastructure. Use other overloads instead")] - public void RequestReceived(string messageId, string insertedAt) { WriteEvent(16, messageId, insertedAt); } - - [NonEvent] - public void RequestReceived(string messageId, DateTimeOffset? insertionTime) { RequestReceived(messageId, insertionTime.HasValue ? insertionTime.Value.ToString("s") : "<>"); } + public void Stopped() { WriteEvent(6); } [Event( - eventId: 17, + eventId: 7, + Task = Tasks.Dispatching, + Opcode = EventOpcode.Start, Level = EventLevel.Informational, - Message = "Error dispatching {1} job (invocation {0}).\r\nException: {1}\r\nStack Trace: {2}")] - [Obsolete("This method supports ETL infrastructure. Use other overloads instead")] - public void DispatchError(string invocationId, string jobName, string exception, string stackTrace) { WriteEvent(17, jobName, exception, stackTrace); } - - [NonEvent] - public void DispatchError(JobInvocation invocation, Exception ex) { DispatchError(invocation.Id.ToString("N"), invocation.Request.Name, ex.ToString(), ex.StackTrace); } + Message = "Worker has begun dispatching events")] + public void DispatchLoopStarted() { WriteEvent(7); } [Event( - eventId: 18, + eventId: 8, + Task = Tasks.Dispatching, + Opcode = EventOpcode.Stop, Level = EventLevel.Informational, - Message = "Invocation {0} of {1} job completed at {2}. Status: {3}.\r\nException: {4}\r\nStack Trace: {5}")] - [Obsolete("This method supports ETL infrastructure. Use other overloads instead")] - public void JobExecuted(string invocationId, string jobName, string completedAt, string status, string exception, string stackTrace) { WriteEvent(18, invocationId, jobName, completedAt, status, exception, stackTrace); } - - [NonEvent] - public void JobExecuted(JobResponse response) { - JobExecuted( - response.Invocation.Id.ToString("N"), - response.Invocation.Request.Name, - response.CompletedAt.ToString("s"), - response.Result.Status.ToString(), - response.Result.Exception == null ? String.Empty : response.Result.Exception.ToString(), - response.Result.Exception == null ? String.Empty : response.Result.Exception.StackTrace); - } + Message = "Worker has stopped dispatching events")] + public void DispatchLoopEnded() { WriteEvent(8); } [Event( - eventId: 19, + eventId: 9, Level = EventLevel.Critical, - Message = "Job Request expired while job was executing. Job: {0}, Message ID: {1}. Elapsed: {2}")] - [Obsolete("This method supports ETL infrastructure. Use other overloads instead")] - public void JobRequestExpired(string jobName, string messageId, string elapsed) { WriteEvent(19, jobName, messageId, elapsed); } + Task = Tasks.Startup, + Opcode = EventOpcode.Stop, + Message = "Worker encountered a fatal error in the dispatch loop: {0}")] + private void DispatchLoopError(string exception) { WriteEvent(9, exception); } [NonEvent] - public void JobRequestExpired(JobRequest req, string messageId, TimeSpan elapsed) { JobRequestExpired(req.Name, messageId, elapsed.ToString()); } - - [Event( - eventId: 20, - Level = EventLevel.Informational, - Message = "Worker is ready to dispatch events")] - public void WorkerDispatching() { WriteEvent(20); } + public void DispatchLoopError(Exception ex) { DispatchLoopError(ex.ToString()); } [Event( - eventId: 21, + eventId: 10, + Task = Tasks.Dispatching, + Opcode = EventOpcode.Suspend, Level = EventLevel.Verbose, - Message = "Work Queue is empty. Sleeping for {0}")] - [Obsolete("This method supports ETL infrastructure. Use other overloads instead")] - public void QueueEmpty(string sleepInterval) { WriteEvent(21, sleepInterval); } - - [NonEvent] - public void QueueEmpty(TimeSpan timeSpan) { QueueEmpty(timeSpan.ToString()); } - - [Event( - eventId: 22, - Level = EventLevel.Informational, - Message = "Exception Parsing Message: {0}\r\nException: {1}\r\nStack Trace: {2}")] - [Obsolete("This method supports ETL infrastructure. Use other overloads instead")] - public void MessageParseError(string message, string exception, string stackTrace) { WriteEvent(22, message, exception, stackTrace); } - - [NonEvent] - public void MessageParseError(string message, Exception ex) { MessageParseError(message, ex.ToString(), ex.StackTrace); } - - [Event( - eventId: 23, - Level = EventLevel.Informational, - Message = "Job {0} started execution. Invocation: {1}")] - [Obsolete("This method supports ETL infrastructure. Use other overloads instead")] - public void JobStarted(string jobName, string invocationId) { WriteEvent(23, jobName, invocationId); } - [NonEvent] - public void JobStarted(string jobName, Guid invocationId) { JobStarted(jobName, invocationId.ToString("N")); } - - [Event( - eventId: 24, - Level = EventLevel.Informational, - Message = "Job {0} completed. Invocation: {1}")] - [Obsolete("This method supports ETL infrastructure. Use other overloads instead")] - public void JobCompleted(string jobName, string invocationId) { WriteEvent(24, jobName, invocationId); } - [NonEvent] - public void JobCompleted(string jobName, Guid invocationId) { JobCompleted(jobName, invocationId.ToString("N")); } + Message = "Work Queue is empty. Worker is suspending for {0}")] + private void DispatchLoopWaiting(string sleepInterval) { WriteEvent(10, sleepInterval); } - [Event( - eventId: 25, - Level = EventLevel.Error, - Message = "Job {0} failed. Exception: {1}\r\nStack Trace: {2}\r\nInvocation: {3}")] - [Obsolete("This method supports ETL infrastructure. Use other overloads instead")] - public void JobFaulted(string jobName, string exception, string stackTrace, string invocationId) { WriteEvent(25, jobName, exception, stackTrace, invocationId); } [NonEvent] - public void JobFaulted(string jobName, Exception ex, Guid invocationId) { JobFaulted(jobName, ex.ToString(), ex.StackTrace, invocationId.ToString("N")); } + public void DispatchLoopWaiting(TimeSpan timeSpan) { DispatchLoopWaiting(timeSpan.ToString()); } [Event( - eventId: 26, + eventId: 11, + Task = Tasks.Dispatching, + Opcode = EventOpcode.Resume, Level = EventLevel.Verbose, - Message = "Invoking Query: {0}")] - public void InvokingQuery(string name) { WriteEvent(26, name); } + Message = "Worker has resumed dispatching events")] + public void DispatchLoopResumed() { WriteEvent(11); } [Event( - eventId: 27, - Level = EventLevel.Verbose, - Message = "Invoked Query: {0}")] - public void InvokedQuery(string name) { WriteEvent(27, name); } + eventId: 12, + Level = EventLevel.Error, + Message = "Invalid Queue Message Received: {0}. Exception: {1}")] + private void InvalidQueueMessage(string message, string exception) { WriteEvent(12, message, exception); } -#pragma warning restore 0618 + [NonEvent] + public void InvalidQueueMessage(string message, Exception ex) { InvalidQueueMessage(message, ex.ToString()); } } } diff --git a/src/NuGetGallery.Backend/NuGetGallery.Backend.csproj b/src/NuGetGallery.Backend/NuGetGallery.Backend.csproj index c31291ce03..5ba9ef52fe 100644 --- a/src/NuGetGallery.Backend/NuGetGallery.Backend.csproj +++ b/src/NuGetGallery.Backend/NuGetGallery.Backend.csproj @@ -91,6 +91,7 @@ + @@ -98,6 +99,8 @@ + + True @@ -122,7 +125,9 @@ Strings.Designer.cs - + + + {097b2cdd-9623-4c34-93c2-d373d51f5b4e} diff --git a/src/NuGetGallery.Backend/WorkerRole.cs b/src/NuGetGallery.Backend/WorkerRole.cs index 2bd9a35a08..f890af3c38 100644 --- a/src/NuGetGallery.Backend/WorkerRole.cs +++ b/src/NuGetGallery.Backend/WorkerRole.cs @@ -21,8 +21,12 @@ public class WorkerRole : RoleEntryPoint public override void Run() { - // Start the runner on it's own "thread" and just sleep until cancelled + // Start the runner. + // Right now, we only run a single runner thread because I haven't quite worked out + // how to capture the ETL events for a particular Invocation while it jumps between Task threads. _runner.Run(_cancelSource.Token).Wait(); + + WorkerEventSource.Log.Stopped(); } public override void OnStop() @@ -43,10 +47,10 @@ public override bool OnStart() ServicePointManager.DefaultConnectionLimit = 12; var config = BackendConfiguration.CreateAzure(); - var monitoring = ConfigureMonitoring(config); - var dispatcher = DiscoverJobs(config, monitoring); + var monitor = ConfigureMonitoring(config); + var dispatcher = DiscoverJobs(config, monitor); - _runner = new JobRunner(dispatcher, config, monitoring); + _runner = new JobRunner(dispatcher, config, monitor); WorkerEventSource.Log.StartupComplete(); return base.OnStart(); @@ -54,12 +58,12 @@ public override bool OnStart() catch (Exception ex) { // Exceptions that escape to this level are fatal - WorkerEventSource.Log.StartupFatal(ex); + WorkerEventSource.Log.StartupError(ex); return false; } } - private JobDispatcher DiscoverJobs(BackendConfiguration config, BackendMonitoringHub monitoring) + private JobDispatcher DiscoverJobs(BackendConfiguration config, BackendMonitoringHub monitor) { var jobs = typeof(WorkerRole) .Assembly @@ -67,7 +71,7 @@ private JobDispatcher DiscoverJobs(BackendConfiguration config, BackendMonitorin .Where(t => !t.IsAbstract && typeof(Job).IsAssignableFrom(t)) .Select(t => Activator.CreateInstance(t)) .Cast(); - return new JobDispatcher(config, jobs, monitoring); + return new JobDispatcher(config, jobs, monitor); } private BackendMonitoringHub ConfigureMonitoring(BackendConfiguration config) diff --git a/src/NuGetGallery.Core/AsyncDisposable.cs b/src/NuGetGallery.Core/Completion.cs similarity index 74% rename from src/NuGetGallery.Core/AsyncDisposable.cs rename to src/NuGetGallery.Core/Completion.cs index 5c5cc76331..ebeb9f7597 100644 --- a/src/NuGetGallery.Core/AsyncDisposable.cs +++ b/src/NuGetGallery.Core/Completion.cs @@ -6,16 +6,16 @@ namespace NuGetGallery.Backend.Monitoring { - public interface IAsyncDeferred + public interface ICompletion { Task Complete(T result); } - public class AsyncDeferred : IAsyncDeferred + public class Completion : ICompletion { private Func _action; - public AsyncDeferred(Func action) + public Completion(Func action) { _action = action; } diff --git a/src/NuGetGallery.Core/Jobs/JobDequeueResult.cs b/src/NuGetGallery.Core/Jobs/JobDequeueResult.cs new file mode 100644 index 0000000000..9ae88a808d --- /dev/null +++ b/src/NuGetGallery.Core/Jobs/JobDequeueResult.cs @@ -0,0 +1,27 @@ +using System; +using System.Collections.Generic; +using System.Linq; +using System.Text; +using System.Threading.Tasks; + +namespace NuGetGallery.Jobs +{ + public class JobDequeueResult + { + public JobRequest Request { get; set; } + public Exception ParseException { get; set; } + public string MessageBody { get; set; } + public bool Success { get { return Request != null; } } + + public JobDequeueResult(JobRequest request) + { + Request = request; + } + + public JobDequeueResult(Exception parseException, string messageBody) + { + ParseException = parseException; + MessageBody = messageBody; + } + } +} diff --git a/src/NuGetGallery.Core/Jobs/JobRequestQueue.cs b/src/NuGetGallery.Core/Jobs/JobRequestQueue.cs index 5da6d4dc9f..d3d560bd0c 100644 --- a/src/NuGetGallery.Core/Jobs/JobRequestQueue.cs +++ b/src/NuGetGallery.Core/Jobs/JobRequestQueue.cs @@ -31,7 +31,7 @@ public static JobRequestQueue WithDefaultName(CloudQueueClient client) return new JobRequestQueue(client.GetQueueReference(DefaultQueueName)); } - public async Task Dequeue(TimeSpan invisibleFor, CancellationToken token) + public async Task Dequeue(TimeSpan invisibleFor, CancellationToken token) { var message = await _queue.SafeExecute(q => q.GetMessageAsync( invisibleFor, @@ -45,7 +45,14 @@ public async Task Dequeue(TimeSpan invisibleFor, CancellationToken t } else { - return JobRequest.Parse(message.AsString, message); + try + { + return new JobDequeueResult(JobRequest.Parse(message.AsString, message)); + } + catch(Exception ex) + { + return new JobDequeueResult(ex, message.AsString); + } } } diff --git a/src/NuGetGallery.Core/Monitoring/Tables/InvocationsEntry.cs b/src/NuGetGallery.Core/Monitoring/Tables/InvocationsEntry.cs index c5c158b3d1..f3730b6bc0 100644 --- a/src/NuGetGallery.Core/Monitoring/Tables/InvocationsEntry.cs +++ b/src/NuGetGallery.Core/Monitoring/Tables/InvocationsEntry.cs @@ -30,9 +30,11 @@ public InvocationsEntry(JobInvocation invocation) : this(invocation.Id) RequestPayload = invocation.Request.Message == null ? null : invocation.Request.Message.AsString; } - public InvocationsEntry(JobInvocation invocation, JobResult result, string logUrl) : this(invocation) + public InvocationsEntry(JobInvocation invocation, JobResult result, string logUrl, DateTimeOffset completedAt) : this(invocation) { LogUrl = logUrl; + CompletedAt = completedAt; + Status = result == null ? JobStatus.Unspecified : result.Status; } public Guid InvocationId { get; set; } diff --git a/src/NuGetGallery.Core/Monitoring/Tables/JobHistoryEntry.cs b/src/NuGetGallery.Core/Monitoring/Tables/JobHistoryEntry.cs index bc3c151745..f4416e5a17 100644 --- a/src/NuGetGallery.Core/Monitoring/Tables/JobHistoryEntry.cs +++ b/src/NuGetGallery.Core/Monitoring/Tables/JobHistoryEntry.cs @@ -29,9 +29,9 @@ public JobHistoryEntry(string jobName, DateTimeOffset timestamp, Guid invocation public JobHistoryEntry(string jobName, DateTimeOffset timestamp, Guid invocationId, string instanceName, JobResult result, DateTimeOffset completedAt) : this(jobName, timestamp, invocationId, instanceName) { - Status = result.Status; + Status = result == null ? JobStatus.Unspecified : result.Status; CompletedAt = completedAt; - Exception = result.Exception == null ? null : result.Exception.ToString(); + Exception = result == null ? null : (result.Exception == null ? null : result.Exception.ToString()); } public Guid InvocationId { get; set; } diff --git a/src/NuGetGallery.Core/Monitoring/Tables/JobStatusEntry.cs b/src/NuGetGallery.Core/Monitoring/Tables/JobStatusEntry.cs index 6a69c351de..2bf85cdbf4 100644 --- a/src/NuGetGallery.Core/Monitoring/Tables/JobStatusEntry.cs +++ b/src/NuGetGallery.Core/Monitoring/Tables/JobStatusEntry.cs @@ -37,8 +37,8 @@ public JobStatusEntry(string jobName, DateTimeOffset timestamp, Guid lastInvocat public JobStatusEntry(string jobName, DateTimeOffset timestamp, Guid lastInvocationId, JobResult lastInvocationResult, string lastInstanceName, DateTimeOffset lastInvocationCompletedAt) : this(jobName, timestamp, lastInvocationId, lastInstanceName) { - LastInvocationStatus = lastInvocationResult.Status; - LastInvocationException = lastInvocationResult.Exception == null ? null : lastInvocationResult.Exception.ToString(); + LastInvocationStatus = lastInvocationResult == null ? JobStatus.Unspecified : lastInvocationResult.Status; + LastInvocationException = lastInvocationResult == null ? null : (lastInvocationResult.Exception == null ? null : lastInvocationResult.Exception.ToString()); LastInvocationCompletedAt = lastInvocationCompletedAt; } diff --git a/src/NuGetGallery.Core/Monitoring/Tables/WorkerInstanceHistoryEntry.cs b/src/NuGetGallery.Core/Monitoring/Tables/WorkerInstanceHistoryEntry.cs index 1bb0e81fb9..fe26a0c3bc 100644 --- a/src/NuGetGallery.Core/Monitoring/Tables/WorkerInstanceHistoryEntry.cs +++ b/src/NuGetGallery.Core/Monitoring/Tables/WorkerInstanceHistoryEntry.cs @@ -30,8 +30,8 @@ public WorkerInstanceHistoryEntry(string instanceName, DateTimeOffset timestamp, public WorkerInstanceHistoryEntry(string instanceName, DateTimeOffset timestamp, Guid invocationId, string jobName, JobResult result, DateTimeOffset completedAt) : this(instanceName, timestamp, invocationId, jobName) { - Status = result.Status; - Exception = result.Exception == null ? null : result.Exception.ToString(); + Status = result == null ? JobStatus.Unspecified : result.Status; + Exception = result == null ? null : (result.Exception == null ? null : result.Exception.ToString()); CompletedAt = completedAt; } diff --git a/src/NuGetGallery.Core/Monitoring/Tables/WorkerInstanceStatusEntry.cs b/src/NuGetGallery.Core/Monitoring/Tables/WorkerInstanceStatusEntry.cs index a71f2d5184..30d4512644 100644 --- a/src/NuGetGallery.Core/Monitoring/Tables/WorkerInstanceStatusEntry.cs +++ b/src/NuGetGallery.Core/Monitoring/Tables/WorkerInstanceStatusEntry.cs @@ -43,8 +43,8 @@ public WorkerInstanceStatusEntry(string instanceName, DateTimeOffset timestamp, public WorkerInstanceStatusEntry(string instanceName, DateTimeOffset timestamp, BackendInstanceStatus instanceStatus, Guid lastInvocation, string lastJob, JobResult lastInvocationResult, DateTimeOffset lastInvocationCompletedAt) : this(instanceName, timestamp, instanceStatus, lastInvocation, lastJob) { - LastInvocationStatus = lastInvocationResult.Status; - LastInvocationException = lastInvocationResult.Exception == null ? null : lastInvocationResult.Exception.ToString(); + LastInvocationStatus = lastInvocationResult == null ? JobStatus.Unspecified : lastInvocationResult.Status; + LastInvocationException = lastInvocationResult == null ? null : (lastInvocationResult.Exception == null ? null : lastInvocationResult.Exception.ToString()); LastInvocationCompletedAt = lastInvocationCompletedAt; } diff --git a/src/NuGetGallery.Core/NuGetGallery.Core.csproj b/src/NuGetGallery.Core/NuGetGallery.Core.csproj index c037c7aafd..740ca22242 100644 --- a/src/NuGetGallery.Core/NuGetGallery.Core.csproj +++ b/src/NuGetGallery.Core/NuGetGallery.Core.csproj @@ -92,7 +92,9 @@ + +