CODEWITHSUNDEEP
c#asp.net-mvcasp.net-mvc-5hangfire
Reath
Reath

Reputation: 511

HangFire can't enquene (fire and forget) job

I have a long time running method that I decided I will use HangFire to execute in the background and manage them through the dashboard. I set up the Dashboard and Hangfire itself with this code:

HangFireConfiguration.cs

public static class HangFireConfiguration
{
    public static string DashboardUrl = "/tasks";

    public static void Configure(IAppBuilder app)
    {
        GlobalConfiguration.Configuration.UseSqlServerStorage("DefaultConnection");

        var options = new DashboardOptions
        {
            Authorization = new[]
            {
                new HangFireAuthorization()
            }
        };

        app.UseHangfireDashboard(DashboardUrl, options);
        app.UseHangfireServer(new BackgroundJobServerOptions()
        {
            //ShutdownTimeout = TimeSpan.FromHours(24)
        });
    }
}

HangFireAuthorization.cs

public class HangFireAuthorization : IDashboardAuthorizationFilter
{
    public static string DashboardUrl = "/tasks";

    public bool Authorize([NotNull] DashboardContext context)
    {
        if (HttpContext.Current.User != null && HttpContext.Current.User.Identity.IsAuthenticated)
        {
            return HttpContext.Current.User.IsInRole("admin");
        }
        return false;
    }
}

Here is the code:

public static void FireMakeArbitarge(LimitBuySellOrdersBindingModel model)
{
    BackgroundJob.Enqueue(() => MakeArbitrage(model));
}

public static async void MakeArbitrage(LimitBuySellOrdersBindingModel model)
{
    var orders = await PlaceOrders(model);
    Order buyOrder = orders[0];
    Order sellOrder = orders[1];

    if (buyOrder == null || sellOrder == null)
    {
        return; //Problem
    }

    ListenOrdersAndCreateArbitrage(buyOrder, sellOrder);
}

private static async Task<Order[]> PlaceOrders(LimitBuySellOrdersBindingModel model)
{
    SignalRUtility.ShowInfoNotificationToAdmins("Executing Buy and Sell Orders", 2);

    var buyOrderTask = Task<Order>.Factory.StartNew(() => TryPlacingOrder(model.BuyOrder));
    var sellOrderTask = Task<Order>.Factory.StartNew(() => TryPlacingOrder(model.SellOrder));
    var orders = await Task.WhenAll(buyOrderTask, sellOrderTask);
    return orders;
}

private static Order TryPlacingOrder(LimitOrderBindingModel model)
{
    try
    {
        var order = OrdersUtility.PlaceOrder(model);

        return order;
    }
    catch (Exception e)
    {
        return null;
    }
}

private static void ListenOrdersAndCreateArbitrage(Order buyOrder, Order sellOrder)
{
    var arbitrage = new Arbitrage()
    {
        BuyOrder = buyOrder,
        SellOrder = sellOrder
    };


    var isBuyFulfilled = false;
    var isSellFulfilled = false;


    using (var context = new CryptoStatisticsDbContext())
    {
        context.Orders.Attach(buyOrder);
        context.Orders.Attach(sellOrder);

        while (true)
        {

            if (!isBuyFulfilled)
            {
                ...
            }

            if (!isSellFulfilled)
            {
                ...
            }

            if (isSellFulfilled && isBuyFulfilled)
            {
                ...
                break; //This moment always comes, most often under 3-4 seconds, but theoritically can take up to 24h to finish
            }

            await Task.Delay(1000);
        }

        ...

        SignalRUtility.ShowSuccessNotificationToAdmins("Arbitrage successfuly made");
    }
    }

I'm calling FireMakeArbitrage(model) using SignalR:

public void MakeArbitrage(LimitBuySellOrdersBindingModel model)
{
    ArbitrageUtility.FireMakeArbitarge(model);
}

And through the debugger I can see that FireMakeArbitrage() is indeed invoked, thus BackgroundJob.Enqueue(() => MakeArbitrage(model)); runs, but absolutely nothing happens. Neither something is added to the db's columns, neither I can see any job in the dashboard.

Firstly I thought that it's something with the async method and the Task invocations in the method, so I tried the following: to only run the while (true) loop in a job.

public static async void MakeArbitrage(LimitBuySellOrdersBindingModel model)
{
    var orders = await PlaceOrders(model);
    Order buyOrder = orders[0];
    Order sellOrder = orders[1];

    if (buyOrder == null || sellOrder == null)
    {
        return; //Problem
    }

    BackgroundJob.Enqueue(() => ListenOrdersAndCreateArbitrage(buyOrder, sellOrder));
}

But again nothing happens.

Then I thought that something isn't ok with my setup for hangfire so I tried a simple

BackgroundJob.Enqueue(() => SignalRUtility.ShowSuccessNotificationToAdmins("test"));

And this worked, I received the notification and I could see the succeeded job in the dashboard. So Hangfire is working (all the tables are ok, the dashboard works), but when I try to invoke my method I receive this log, nothing happening runtime (my breakpoint is never hit):

2018-01-18 16:16:20.9220 INFO | Start installing Hangfire SQL objects...
2018-01-18 16:16:20.9910 INFO | Hangfire SQL objects installed.
2018-01-18 16:16:21.0150 INFO | Starting Hangfire Server
2018-01-18 16:16:21.0150 INFO | Using job storage: 'SQL Server: .@Market'
2018-01-18 16:16:21.0150 INFO | Using the following options for SQL Server job storage:
2018-01-18 16:16:21.0150 INFO |     Queue poll interval: 00:00:15.
2018-01-18 16:16:21.0150 INFO | Using the following options for Hangfire Server:
2018-01-18 16:16:21.0150 INFO |     Worker count: 20
2018-01-18 16:16:21.0150 INFO |     Listening queues: 'default'
2018-01-18 16:16:21.0150 INFO |     Shutdown timeout: 00:00:15
2018-01-18 16:16:21.0150 INFO |     Schedule polling interval: 00:00:15
2018-01-18 16:16:21.0410 DEBUG | Background process 'BackgroundProcessingServer' started.
2018-01-18 16:16:21.2490 DEBUG | Background process 'ServerHeartbeat' started.
2018-01-18 16:16:21.2800 DEBUG | Background process 'ServerWatchdog' started.
2018-01-18 16:16:21.2950 DEBUG | Background process 'Hangfire.SqlServer.ExpirationManager' started.
2018-01-18 16:16:21.2950 DEBUG | Removing outdated records from the 'AggregatedCounter' table...
2018-01-18 16:16:21.2950 INFO | 2 servers were removed due to timeout
2018-01-18 16:16:21.3260 DEBUG | Background process 'Hangfire.SqlServer.CountersAggregator' started.
2018-01-18 16:16:21.3260 DEBUG | Aggregating records in 'Counter' table...
2018-01-18 16:16:21.3260 DEBUG | Background process 'Worker #6e2ae928' started.
2018-01-18 16:16:21.3580 TRACE | Records from the 'Counter' table aggregated.
2018-01-18 16:16:21.3580 DEBUG | Background process 'Worker #3c3363a2' started.
2018-01-18 16:16:21.3580 TRACE | Outdated records removed from the 'AggregatedCounter' table.
2018-01-18 16:16:21.3580 DEBUG | Removing outdated records from the 'Job' table...
2018-01-18 16:16:21.3710 DEBUG | Background process 'Worker #50dfa590' started.
2018-01-18 16:16:21.3920 DEBUG | Background process 'Worker #6ad9aeb9' started.
2018-01-18 16:16:21.4140 DEBUG | Background process 'Worker #67fc5308' started.
2018-01-18 16:16:21.4240 TRACE | Outdated records removed from the 'Job' table.
2018-01-18 16:16:21.4240 DEBUG | Removing outdated records from the 'List' table...
2018-01-18 16:16:21.4360 DEBUG | Background process 'Worker #bbc2bf4e' started.
2018-01-18 16:16:21.4360 DEBUG | Background process 'Worker #115c5b69' started.
2018-01-18 16:16:21.4620 DEBUG | Background process 'Worker #43452cde' started.
2018-01-18 16:16:21.4640 TRACE | Outdated records removed from the 'List' table.
2018-01-18 16:16:21.4640 DEBUG | Removing outdated records from the 'Set' table...
2018-01-18 16:16:21.4790 DEBUG | Background process 'Worker #1447d454' started.
2018-01-18 16:16:21.4970 TRACE | Outdated records removed from the 'Set' table.
2018-01-18 16:16:21.4970 DEBUG | Removing outdated records from the 'Hash' table...
2018-01-18 16:16:21.4970 DEBUG | Background process 'Worker #363b3748' started.
2018-01-18 16:16:21.5220 DEBUG | Background process 'Worker #9e713cc5' started.
2018-01-18 16:16:21.5320 DEBUG | Background process 'Worker #82a5eb5f' started.
2018-01-18 16:16:21.5320 TRACE | Outdated records removed from the 'Hash' table.
2018-01-18 16:16:21.5610 DEBUG | Background process 'Worker #e3d98a1b' started.
2018-01-18 16:16:21.5770 DEBUG | Background process 'Worker #801593ad' started.
2018-01-18 16:16:21.5940 DEBUG | Background process 'Worker #5b7fdcd6' started.
2018-01-18 16:16:21.6170 DEBUG | Background process 'Worker #5506c4bf' started.
2018-01-18 16:16:21.6370 DEBUG | Background process 'Worker #0ed1b5a8' started.
2018-01-18 16:16:21.6640 DEBUG | Background process 'Worker #d3fdbe7b' started.
2018-01-18 16:16:21.6780 DEBUG | Background process 'Worker #ada59522' started.
2018-01-18 16:16:21.7010 DEBUG | Background process 'Worker #1e669bd5' started.
2018-01-18 16:16:21.7470 DEBUG | Background process 'RecurringJobScheduler' started.
2018-01-18 16:16:21.7470 DEBUG | Background process 'DelayedJobScheduler' started.

The thing that I think is the problem is this line: 2018-01-18 16:16:21.2950 INFO | 2 servers were removed due to timeout. First, I don't know why 2 servers. Second, they are removed the moment I invoke the method, I don't get why a timeout. After they are removed and I try to invoke the method again nothing more is logged to the file. I have to restart the app and try again

2018-01-18 16:21:22.1050 INFO | Start installing Hangfire SQL objects...
2018-01-18 16:21:22.2440 INFO | Hangfire SQL objects installed.
2018-01-18 16:21:22.2720 INFO | Starting Hangfire Server
2018-01-18 16:21:22.2720 INFO | Using job storage: 'SQL Server: .@Market'
2018-01-18 16:21:22.2720 INFO | Using the following options for SQL Server job storage:
2018-01-18 16:21:22.2720 INFO |     Queue poll interval: 00:00:15.
2018-01-18 16:21:22.2720 INFO | Using the following options for Hangfire Server:
2018-01-18 16:21:22.2720 INFO |     Worker count: 20
2018-01-18 16:21:22.2720 INFO |     Listening queues: 'default'
2018-01-18 16:21:22.2720 INFO |     Shutdown timeout: 00:00:15
2018-01-18 16:21:22.2720 INFO |     Schedule polling interval: 00:00:15
2018-01-18 16:21:22.3010 DEBUG | Background process 'BackgroundProcessingServer' started.
2018-01-18 16:21:22.5390 DEBUG | Background process 'ServerHeartbeat' started.
2018-01-18 16:21:22.5710 DEBUG | Background process 'ServerWatchdog' started.
2018-01-18 16:21:22.5840 DEBUG | Background process 'Hangfire.SqlServer.CountersAggregator' started.
2018-01-18 16:21:22.5840 DEBUG | Background process 'Hangfire.SqlServer.ExpirationManager' started.
2018-01-18 16:21:22.6130 DEBUG | Background process 'Worker #bb9381c4' started.
2018-01-18 16:21:22.6130 DEBUG | Removing outdated records from the 'AggregatedCounter' table...
2018-01-18 16:21:22.6130 DEBUG | Aggregating records in 'Counter' table...
2018-01-18 16:21:22.6470 DEBUG | Background process 'Worker #c0f3faa7' started.
2018-01-18 16:21:22.6780 DEBUG | Background process 'Worker #d4845d7a' started.
2018-01-18 16:21:22.6880 TRACE | Outdated records removed from the 'AggregatedCounter' table.
2018-01-18 16:21:22.6880 DEBUG | Removing outdated records from the 'Job' table...
2018-01-18 16:21:22.6880 TRACE | Records from the 'Counter' table aggregated.
2018-01-18 16:21:22.7250 DEBUG | Background process 'Worker #602982ac' started.
2018-01-18 16:21:22.7350 DEBUG | Background process 'Worker #82e492b8' started.
2018-01-18 16:21:22.7510 DEBUG | Background process 'Worker #9f981a7f' started.
2018-01-18 16:21:22.7670 TRACE | Outdated records removed from the 'Job' table.
2018-01-18 16:21:22.7670 DEBUG | Removing outdated records from the 'List' table...
2018-01-18 16:21:22.7800 DEBUG | Background process 'Worker #88198e45' started.
2018-01-18 16:21:22.7800 DEBUG | Background process 'Worker #c2fd7d9c' started.
2018-01-18 16:21:22.8030 DEBUG | Background process 'Worker #74c1711d' started.
2018-01-18 16:21:22.8170 TRACE | Outdated records removed from the 'List' table.
2018-01-18 16:21:22.8170 DEBUG | Removing outdated records from the 'Set' table...
2018-01-18 16:21:22.8760 DEBUG | Background process 'Worker #18785ae7' started.
2018-01-18 16:21:22.8920 DEBUG | Background process 'Worker #cd2e512e' started.
2018-01-18 16:21:22.9040 TRACE | Outdated records removed from the 'Set' table.
2018-01-18 16:21:22.9040 DEBUG | Removing outdated records from the 'Hash' table...
2018-01-18 16:21:22.9190 DEBUG | Background process 'Worker #11b64efe' started.
2018-01-18 16:21:22.9560 DEBUG | Background process 'Worker #506dc90a' started.
2018-01-18 16:21:22.9680 DEBUG | Background process 'Worker #a1ff6574' started.
2018-01-18 16:21:22.9680 TRACE | Outdated records removed from the 'Hash' table.
2018-01-18 16:21:22.9880 DEBUG | Background process 'Worker #48f5af2a' started.
2018-01-18 16:21:23.0080 DEBUG | Background process 'Worker #23240705' started.
2018-01-18 16:21:23.0190 DEBUG | Background process 'Worker #ddf2e718' started.
2018-01-18 16:21:23.0400 DEBUG | Background process 'Worker #c8fd3a14' started.
2018-01-18 16:21:23.0510 DEBUG | Background process 'Worker #9cbb1e99' started.
2018-01-18 16:21:23.0730 DEBUG | Background process 'Worker #eeaed48d' started.
2018-01-18 16:21:23.0770 DEBUG | Background process 'DelayedJobScheduler' started.
2018-01-18 16:21:23.1120 DEBUG | Background process 'RecurringJobScheduler' started.
2018-01-18 16:26:22.5900 INFO | 1 servers were removed due to timeout
2018-01-18 16:26:22.7060 DEBUG | Aggregating records in 'Counter' table...
2018-01-18 16:26:22.7060 TRACE | Records from the 'Counter' table aggregated.

EDIT: In a glance: 

public static async void MakeArbitrage(LimitBuySellOrdersBindingModel model)
{
    var msg = "this works";
    BackgroundJob.Enqueue(() => SignalRUtility.ShowSuccessNotificationToAdmins(msg, 60));
}

This however doesn't work:

 public static async void MakeArbitrage(LimitBuySellOrdersBindingModel model)
{
        var orders = await PlaceOrders(model);
        Order buyOrder = orders[0];
        Order sellOrder = orders[1];

        if (buyOrder == null || sellOrder == null)
        {
            return; //Problem
        }

        BackgroundJob.Enqueue(() => ListenOrdersAndCreateArbitrage(buyOrder, sellOrder));
}

In both examples this is how I call the method: ArbitrageUtility.MakeArbitrage(model);

Upvotes: 2

Views: 5815

Answers (1)

Reath
Reath

Reputation: 511

Making my method from private to public solved my problem. Nowhere in the Getting Started guide I saw that in order for my method to be called it must be public.

Upvotes: 5

Related Questions