Search code examples
c#async-awaitserilog

The asynchronous method appears not to wait even though it contains "await" keyword in C#

The asynchronous SetAlarmLogToWebServiceAsync() method appears not to wait even though it contains "await" keyword.

The code below writes unexpected logs.

//Client Side
private async void FrmMain_Load(object sender, EventArgs e)
{
    await StartAllTasksAsync();
}

private async Task StartAllTasksAsync()
{
    var task = SetAlarmLogToWebServiceAsync();
    return Task.WhenAll(task);
}

public async Task SetAlarmLogToWebServiceAsync()
{
    while (true)
    {
        await Task.Delay(300);
        await _alarmLogManager.SetAlarmLogToWebServiceAsync();
    }
}

//Business Logic Side
public async Task SetAlarmLogToWebServiceAsync()
{
    var alarmLog = (await _alarmLogDal.GetListAsync()).FirstOrDefault();
    _logger.Verbose($"AlarmLog was gotten from db. AlarmId: {alarmLog.AlarmId}");
    
    try
    {
        var serviceResult = await _webServiceDal.SetAlarmLogAsync(alarmLog);
        if (serviceResult > 0)
        {
            _logger.Verbose($"AlarmLog was sent to web service. AlarmId: {alarmLog.AlarmId}");
            var dbResult = await _alarmLogDal.UpdateServiceStatusAsync(alarmLog);
        }
    }
    catch (Exception ex)
    {
        _logger.Error($"Error on sending AlarmLog to WebService. AlarmId: {alarmLog.AlarmId}" +
            $"\n    Exception message: {ex.Message}");
        await Task.Delay(3000);
    }
}

The logs:

2020-11-19 12:09:50.718 +03:00 [VRB] AlarmLog was gotten from db. AlarmId: 86944
2020-11-19 12:09:51.490 +03:00 [VRB] AlarmLog was gotten from db. AlarmId: 86944
2020-11-19 12:09:51.863 +03:00 [VRB] AlarmLog was gotten from db. AlarmId: 86944
2020-11-19 12:09:52.230 +03:00 [VRB] AlarmLog was gotten from db. AlarmId: 86944
2020-11-19 12:09:52.563 +03:00 [VRB] AlarmLog was gotten from db. AlarmId: 86944
2020-11-19 12:09:52.888 +03:00 [VRB] AlarmLog was gotten from db. AlarmId: 86944
2020-11-19 12:09:53.215 +03:00 [VRB] AlarmLog was gotten from db. AlarmId: 86944
2020-11-19 12:09:53.567 +03:00 [VRB] AlarmLog was gotten from db. AlarmId: 86944
2020-11-19 12:09:53.935 +03:00 [VRB] AlarmLog was gotten from db. AlarmId: 86944
2020-11-19 12:09:54.300 +03:00 [VRB] AlarmLog was gotten from db. AlarmId: 86944
2020-11-19 12:09:54.678 +03:00 [VRB] AlarmLog was gotten from db. AlarmId: 86944
2020-11-19 12:09:55.031 +03:00 [VRB] AlarmLog was gotten from db. AlarmId: 86944
2020-11-19 12:09:55.384 +03:00 [VRB] AlarmLog was gotten from db. AlarmId: 86944
2020-11-19 12:09:55.735 +03:00 [VRB] AlarmLog was gotten from db. AlarmId: 86944
2020-11-19 12:09:56.060 +03:00 [VRB] AlarmLog was gotten from db. AlarmId: 86944
2020-11-19 12:09:56.386 +03:00 [VRB] AlarmLog was gotten from db. AlarmId: 86944
2020-11-19 12:09:56.716 +03:00 [VRB] AlarmLog was gotten from db. AlarmId: 86944
2020-11-19 12:09:57.047 +03:00 [VRB] AlarmLog was gotten from db. AlarmId: 86944
2020-11-19 12:09:57.371 +03:00 [VRB] AlarmLog was gotten from db. AlarmId: 86944
2020-11-19 12:09:57.700 +03:00 [VRB] AlarmLog was gotten from db. AlarmId: 86944
2020-11-19 12:09:58.030 +03:00 [VRB] AlarmLog was gotten from db. AlarmId: 86944
2020-11-19 12:09:58.382 +03:00 [VRB] AlarmLog was gotten from db. AlarmId: 86944
2020-11-19 12:09:58.738 +03:00 [VRB] AlarmLog was gotten from db. AlarmId: 86944
2020-11-19 12:09:59.073 +03:00 [VRB] AlarmLog was gotten from db. AlarmId: 86944
2020-11-19 12:09:59.482 +03:00 [VRB] AlarmLog was gotten from db. AlarmId: 86944
2020-11-19 12:09:59.809 +03:00 [VRB] AlarmLog was gotten from db. AlarmId: 86944
2020-11-19 12:10:00.138 +03:00 [VRB] AlarmLog was gotten from db. AlarmId: 86944
2020-11-19 12:10:00.468 +03:00 [VRB] AlarmLog was gotten from db. AlarmId: 86944
2020-11-19 12:10:00.833 +03:00 [VRB] AlarmLog was gotten from db. AlarmId: 86944
2020-11-19 12:10:01.200 +03:00 [VRB] AlarmLog was gotten from db. AlarmId: 86944
2020-11-19 12:10:11.202 +03:00 [ERR] Error on sending AlarmLog to WebService. AlarmId: 86944
    Exception message: A task was canceled.
2020-11-19 12:10:14.543 +03:00 [VRB] AlarmLog was gotten from db. AlarmId: 86944
2020-11-19 12:10:24.546 +03:00 [ERR] Error on sending AlarmLog to WebService. AlarmId: 86944
    Exception message: A task was canceled.
2020-11-19 12:10:27.907 +03:00 [VRB] AlarmLog was gotten from db. AlarmId: 86944
2020-11-19 12:10:28.725 +03:00 [VRB] AlarmLog was gotten from db. AlarmId: 86944
2020-11-19 12:10:29.057 +03:00 [VRB] AlarmLog was gotten from db. AlarmId: 86944
2020-11-19 12:10:29.390 +03:00 [VRB] AlarmLog was gotten from db. AlarmId: 86944
2020-11-19 12:10:29.715 +03:00 [VRB] AlarmLog was gotten from db. AlarmId: 86944
2020-11-19 12:10:30.043 +03:00 [VRB] AlarmLog was gotten from db. AlarmId: 86944
2020-11-19 12:10:30.408 +03:00 [VRB] AlarmLog was gotten from db. AlarmId: 86944
2020-11-19 12:10:30.754 +03:00 [VRB] AlarmLog was gotten from db. AlarmId: 86944
2020-11-19 12:10:31.114 +03:00 [VRB] AlarmLog was gotten from db. AlarmId: 86944
2020-11-19 12:10:31.493 +03:00 [VRB] AlarmLog was gotten from db. AlarmId: 86944
2020-11-19 12:10:31.864 +03:00 [VRB] AlarmLog was gotten from db. AlarmId: 86944
2020-11-19 12:10:32.189 +03:00 [VRB] AlarmLog was gotten from db. AlarmId: 86944
2020-11-19 12:10:32.516 +03:00 [VRB] AlarmLog was gotten from db. AlarmId: 86944
2020-11-19 12:10:32.841 +03:00 [VRB] AlarmLog was gotten from db. AlarmId: 86944
2020-11-19 12:10:33.169 +03:00 [VRB] AlarmLog was gotten from db. AlarmId: 86944
2020-11-19 12:10:33.498 +03:00 [VRB] AlarmLog was gotten from db. AlarmId: 86944
2020-11-19 12:10:43.502 +03:00 [ERR] Error on sending AlarmLog to WebService. AlarmId: 86944
    Exception message: A task was canceled.
2020-11-19 12:10:46.848 +03:00 [VRB] AlarmLog was gotten from db. AlarmId: 86944
2020-11-19 12:10:56.862 +03:00 [ERR] Error on sending AlarmLog to WebService. AlarmId: 86944
    Exception message: A task was canceled.

I'm using Serilog for logging. The logger is being created like this:

public static Serilog.ILogger GetSerilogAsyncFileLogger(int retainedFileCountLimit = 2)
{
    return new LoggerConfiguration()
        .WriteTo.Async(a =>
        {
            a.File(
                path: "logs\\log.txt",
                outputTemplate: "{Timestamp:yyyy-MM-dd HH:mm:ss.fff zzz} [{Level:u3}] {Message:lj}{NewLine}{Exception}",
                rollingInterval: RollingInterval.Day,
                fileSizeLimitBytes: 500000000,
                rollOnFileSizeLimit: true,
                retainedFileCountLimit: retainedFileCountLimit);
        })
        .MinimumLevel.Verbose()
        .CreateLogger();
}

The SetAlarmLogToWebServiceAsync() must await for all calls. I expected the logs below. How can i get the logs below?

2020-11-19 12:10:01.200 +03:00 [VRB] AlarmLog was gotten from db. AlarmId: 86944
2020-11-19 12:10:11.202 +03:00 [ERR] Error on sending AlarmLog to WebService. AlarmId: 86944
    Exception message: A task was canceled.
2020-11-19 12:10:01.200 +03:00 [VRB] AlarmLog was gotten from db. AlarmId: 86944
2020-11-19 12:10:11.202 +03:00 [ERR] Error on sending AlarmLog to WebService. AlarmId: 86944
    Exception message: A task was canceled.
2020-11-19 12:10:01.200 +03:00 [VRB] AlarmLog was gotten from db. AlarmId: 86944
2020-11-19 12:10:11.202 +03:00 [ERR] Error on sending AlarmLog to WebService. AlarmId: 86944
    Exception message: A task was canceled.
2020-11-19 12:10:01.200 +03:00 [VRB] AlarmLog was gotten from db. AlarmId: 86944
2020-11-19 12:10:11.202 +03:00 [ERR] Error on sending AlarmLog to WebService. AlarmId: 86944
    Exception message: A task was canceled.
Solution

  • The behaviour you got may arise if serviceResult<=0 and the line var serviceResult = await _webServiceDal.SetAlarmLogAsync(alarmLog) didn't raise an exception. Try to add an else clause after the check and log something there to see if that's the case.

    if (serviceResult > 0) {...} else { _logger.Verbose(...); }