Debug Logging in Hangfire?

question
1

The company I work for owns a Hangfire.Pro license, so I took the opportunity to start learning the API in small side project that I’m working on during lunch breaks (will be using it in one of our actual products soon so I wanted to figure stuff out in advance), and I’ve managed to reach a situation where I have a recurring job which uses the IBatchJobClient to create batches of jobs to execute. The internally-running background jobs are using an IMyHttpClient abstraction to execute HTTP calls and get data. Before the jobs are enqueued an initial http call is made and N urls to check are retrieved, after that for reach url a background job is enqueued using the IBatchedAction

Right now I have :

// pseudocode
public class InMemoryHttpClient : IMyHttpClient
{
// used to return a hardcoded list of urls
}

public class MyHttpClient : IMyHttpClient
{
// lots of Delegating handlers here with async/await and .ConfigureAwait(false) everywhere
// returns the urls from an actual data source
}

If I inject the in-memory http client - everything works as expected. If I inject the actual HttpClient I wish to use, the call is executed successfully, the resulting URLs are returned however none of the enqueued bacground jobs start, and the dashboard shows the batch as completed with 0/0 progress.

I’d like to understand what have I done wrong, so I’d like to be able to enable some trace logging - how can I do that? I’m using ASP.NET Core 3.0, also if this sounds familiar I’d apreciate any hints you could offer, as this seems a bit awkward :slight_smile:

/best regards

2

I’ve found a section in the docs on how to create a custom logging provider (so I did) and here’s my logging output:

geo-geojson-svc_1   | Trace: Hangfire.Server.ServerJobCancellationWatcher Checking for aborted jobs... 
geo-geojson-svc_1   | Trace: Hangfire.Server.ServerJobCancellationWatcher No newly aborted jobs found. 
geo-geojson-svc_1   | Trace: Hangfire.Server.ServerJobCancellationWatcher Checking for aborted jobs... 
geo-geojson-svc_1   | Trace: Hangfire.Server.ServerJobCancellationWatcher No newly aborted jobs found. 
geo-geojson-svc_1   | Trace: Hangfire.Server.ServerJobCancellationWatcher Checking for aborted jobs... 
geo-geojson-svc_1   | Trace: Hangfire.Server.ServerJobCancellationWatcher No newly aborted jobs found. 
geo-geojson-svc_1   | Trace: Hangfire.Server.ServerJobCancellationWatcher Checking for aborted jobs... 
geo-geojson-svc_1   | Trace: Hangfire.Server.ServerJobCancellationWatcher No newly aborted jobs found. 
geo-geojson-svc_1   | Trace: Hangfire.Server.ServerJobCancellationWatcher Checking for aborted jobs... 
geo-geojson-svc_1   | Trace: Hangfire.Server.ServerJobCancellationWatcher No newly aborted jobs found. 
geo-geojson-svc_1   | Trace: Hangfire.Server.ServerJobCancellationWatcher Checking for aborted jobs... 
geo-geojson-svc_1   | Trace: Hangfire.Server.ServerJobCancellationWatcher No newly aborted jobs found. 
geo-geojson-svc_1   | [11:12:13 INF] Resolving geo-api client: {"Mode": "HttpClient", "$type": "GeoApiSettings"}
geo-geojson-svc_1   | [11:12:13 INF] Syncing GeoJson for {"Id": "146501-1", "Scope": "District", "$type": "MonitoredRegion"}
geo-geojson-svc_1   | [11:12:14 INF] GET http://geo-api/regions/146501-1/children?type=District <-- OK 1776 [B] in 1622 [ms]. {"Version": {"Major": 1, "Minor": 1, "Build": -1, "Revision": -1, "MajorRevision": -1, "MinorRevision": -1, "$type": "Version"}, "Content": {"Headers": [{"Key": "Content-Type", "Value": ["application/json; charset=utf-8"], "$type": "KeyValuePair`2"}, {"Key": "Content-Length", "Value": ["1776"], "$type": "KeyValuePair`2"}], "$type": "HttpConnectionResponseContent"}, "StatusCode": "OK", "ReasonPhrase": "OK", "Headers": [{"Key": "Date", "Value": ["Sat, 02 Nov 2019 11:12:14 GMT"], "$type": "KeyValuePair`2"}, {"Key": "Server", "Value": ["Kestrel"], "$type": "KeyValuePair`2"}], "TrailingHeaders": [], "RequestMessage": {"Version": {"Major": 1, "Minor": 1, "Build": -1, "Revision": -1, "MajorRevision": -1, "MinorRevision": -1, "$type": "Version"}, "Content": null, "Method": {"Method": "GET", "$type": "HttpMethod"}, "RequestUri": "http://geo-api/regions/146501-1/children?type=District", "Headers": [], "Properties": {}, "$type": "HttpRequestMessage"}, "IsSuccessStatusCode": true, "$type": "HttpResponseMessage"} 
geo-geojson-svc_1   | [11:12:14 INF] 18 regions retrieved
geo-api_1           | [11:12:14 INF] HTTP GET /regions/146501-1/children responded with 200 in 1567.4548 [ms]
geo-geojson-svc_1   | Trace: Hangfire.Server.ServerJobCancellationWatcher Checking for aborted jobs... 
geo-geojson-svc_1   | Trace: Hangfire.Server.ServerJobCancellationWatcher No newly aborted jobs found. 
geo-geojson-svc_1   | Trace: Hangfire.Server.ServerJobCancellationWatcher Checking for aborted jobs... 
geo-geojson-svc_1   | Trace: Hangfire.Server.ServerJobCancellationWatcher No newly aborted jobs found. 
geo-geojson-svc_1   | Trace: Hangfire.Server.ServerJobCancellationWatcher Checking for aborted jobs... 
geo-geojson-svc_1   | Trace: Hangfire.Server.ServerJobCancellationWatcher No newly aborted jobs found. 
geo-geojson-svc_1   | Trace: Hangfire.Server.ServerJobCancellationWatcher Checking for aborted jobs... 
geo-geojson-svc_1   | Trace: Hangfire.Server.ServerJobCancellationWatcher No newly aborted jobs found.

My 1st impression is that those jobs were never registered?

3

Here’s the job implementation:

(The .OnSuccess() and .OnFailure() calls are Vladimir Khorikov-style attempts at functional programming :smiley:

public class SyncRegionBatchJob
    {
        private readonly IBatchJobClient batchClient;
        private readonly IGeoApiClient client;
        private readonly ILogger<SyncRegionBatchJob> logger;

        public SyncRegionBatchJob(IBatchJobClient batchClient, IGeoApiClient client, ILoggerFactory loggerFactory)
        {
            this.batchClient = batchClient ?? throw new ArgumentNullException(nameof(batchClient));
            this.client = client ?? throw new ArgumentNullException(nameof(client));
            this.logger = loggerFactory?.CreateLogger<SyncRegionBatchJob>() ?? throw new ArgumentNullException(nameof(loggerFactory));
        }

        public Task InvokeAsync(RegionSyncSettings settings)
        {
            var region = new MonitoredRegion()
            {
                Id = settings.Region,
                Scope = settings.Scope
            };

            logger.LogInformation("Syncing GeoJson for {@Region}", region);

            batchClient.Create(async batch =>
            {
                (await client.GetMonitoredRegionsAsync(region))
                    .OnSuccess(regions =>
                    {
                        logger.LogInformation("{Count} regions retrieved", regions.Count());
                        regions.ForEach(rgn =>
                        {
                            // this seems not to get enqueued when using an actual client rather than the in-memory mock
                            batch.Enqueue<SyncRegionGeoJsonJob>(x => x.Invoke(rgn));
                        });
                    })
                    .OnFailure(x =>
                    {
                        logger.LogError("Syncing GeoJson for {@Region} failed", region);
                    });
            }, new BatchStartedState(), $"sync-region-geojson-batch-{region.Id}-{region.Scope.ToString()}");

            return Task.CompletedTask;
        }
    }