search

dotnet / aspnetcore

ASP.NET Core is a cross-platform .NET framework for building modern cloud-based web applications on Windows, Mac, or Linux.
https://asp.net
MIT License
35.19k stars 9.93k forks source link

Error 503. The service is unavailable (blazor server side) #10012

Closed islandmanllc closed 5 years ago

islandmanllc commented 5 years ago

Describe the bug

Using HttpClient multiple times in a row causes responses to start lagging and eventually return HTTP Error 503. The service is unavailable despite the api service reporting no issues at all and keeps responding to other calls. Asp.net core version: 3.0.100-preview4-011223

To Reproduce

Please note that the code is a bit messy due to troubleshooting. Here's the code: The service that is injected into the .razor page

public async Task<PagedResult<ProductViewModels.Details>> GetProductsAsync(int? pageIndex, int itemsPerPage)
        {
            var url = $"{_baseUrl}/products/list/{pageIndex},{itemsPerPage}";
            try
            {
                var response = await _client.GetAsync(url);

                if (response.IsSuccessStatusCode)
                {
                    var jsonString = await response.Content.ReadAsStringAsync();
                    var jObj = (JObject) JsonConvert.DeserializeObject(jsonString);

                    var paged =
                        JsonConvert.DeserializeObject<PagedResult<ProductViewModels.Details>>(
                            jObj["payLoad"].ToString());

                    return paged;
                }
                else
                {
                    var msg =
                        $"Unsuccessful request to {url} {response.StatusCode} {await response.Content.ReadAsStringAsync()}";
                    _logger.LogError(
                        msg);
                    throw new Exception(msg);
                }
            }
            catch (Exception e)
            {
                _logger.LogError($"Exception when trying to get product records from {url}", e);
                throw;
            }
        }`

The .razor page:

@page "/products"
@using Kiss.Application.Features.Products.ViewModels
@using Microsoft.AspNetCore.Components

<DataTable Items="@_products" TItem="ProductViewModels.Details">
    <HeaderTemplate>
        <th>Name</th>
        <th>Description</th>
    </HeaderTemplate>
    <RowTemplate Context="Item">
        <td>@Item.Name</td>
        <td>@Item.Description</td>
    </RowTemplate>
    <FooterTemplate Context="Item">
        <td colspan="2">@_itemsTotal products found.</td>
    </FooterTemplate>
</DataTable>
<Paginator ref="_paginator" LastPageIndex="@_lastPageIndex" />

@functions {
    private int _itemsPerPage = 5;
    private int _lastPageIndex = 0;

    private IEnumerable<ProductViewModels.Details> _products = new List<ProductViewModels.Details>();
    private int _itemsTotal = 0;

    private Paginator _paginator = new Paginator();

    [Inject] IProductService ProductService { get; set; }

    protected override void OnAfterRender()
    {
        _paginator.PageChanged += PageChangedEvent;
    }

    public async void PageChangedEvent(int pageIndex)
    {
        await UpdateProducts(pageIndex, _itemsPerPage);
    }

    protected override async Task OnInitAsync()
    {
        await UpdateProducts(0, _itemsPerPage);
    }

    private async Task UpdateProducts(int pageIndex, int itemsPerPage)
    {
        if (ProductService != null)
        {
            var result = await ProductService.GetProductsAsync(pageIndex, itemsPerPage);
            if (result != null)
            {
                _products = result.Items;
                _itemsTotal = result.ItemsTotal;
                _itemsPerPage = result.ItemsPerPage;
                _lastPageIndex = result.TotalPages - 1;
                StateHasChanged();
            }
        }
    }
}

The paginator that triggers the api calls

@using Microsoft.AspNetCore.Components
<div class="dataTables_paginate paging_simple_numbers" id="DataTables_Table_0_paginate">
    <ul class="pagination">
        <li class="paginate_button page-item previous @Disabled(0)" id="DataTables_Table_0_previous">
            <a aria-controls="DataTables_Table_0" data-dt-idx="0" tabindex="0" class="page-link" onclick="@FirstPage">First</a>
        </li>
        <li class="paginate_button page-item previous @Disabled(0)" id="DataTables_Table_0_previous">
            <a aria-controls="DataTables_Table_0" data-dt-idx="1" tabindex="0" class="page-link" onclick="@PreviousPage">Previous</a>
        </li>

        <li class="paginate_button page-item next @Disabled(LastPageIndex)" id="DataTables_Table_0_next">
            <a aria-controls="DataTables_Table_0" data-dt-idx="2" tabindex="0" class="page-link" onclick="@NextPage">Next</a>
        </li>
        <li class="paginate_button page-item next @Disabled(LastPageIndex)" id="DataTables_Table_0_next">
            <a aria-controls="DataTables_Table_0" data-dt-idx="3" tabindex="0" class="page-link" onclick="@LastPage">Last</a>
        </li>
    </ul>
</div>

@functions
{
    private int _currentPageIndex = 0;

    [Parameter]
    private int LastPageIndex { get; set; }

    [Parameter]
    public Action<int> PageChanged { get; set; }

    void ChangeCurrentPageIndex(int pageIndex)
    {
        if (pageIndex != _currentPageIndex)
        {
            _currentPageIndex = pageIndex;
            PageChanged?.Invoke(_currentPageIndex);
        }
    }

    string Disabled(int pageIndex)
    {
        return _currentPageIndex == pageIndex ? "disabled" : "";
    }

    void FirstPage()
    {
        ChangeCurrentPageIndex(0);
    }

    void NextPage()
    {
        if (_currentPageIndex < LastPageIndex)
        {
            ChangeCurrentPageIndex(_currentPageIndex + 1);
        }
    }

    void PreviousPage()
    {
        if (_currentPageIndex > 0)
        {
            ChangeCurrentPageIndex(_currentPageIndex - 1);
        }
    }

    void LastPage()
    {
        ChangeCurrentPageIndex(LastPageIndex);
    }
}

Startup.cs:

public class Startup
    {
        public Startup(IConfiguration configuration)
        {
            Log.Logger = new LoggerConfiguration().ReadFrom.Configuration(configuration).CreateLogger();
        }

        // This method gets called by the runtime. Use this method to add services to the container.
        // For more information on how to configure your application, visit https://go.microsoft.com/fwlink/?LinkID=398940
        public void ConfigureServices(IServiceCollection services)
        {
            services.AddHttpClient();
            services.AddScoped<HttpClient>(s =>
            {
                // Creating the URI helper needs to wait until the JS Runtime is initialized, so defer it.
                var uriHelper = s.GetRequiredService<IUriHelper>();
                return new HttpClient
                {
                    BaseAddress = new Uri(uriHelper.GetBaseUri())
                };
            });
            services.AddScoped<IProductService, ProductService>();

            services.AddRazorPages();
            services.AddServerSideBlazor();
        }

        // This method gets called by the runtime. Use this method to configure the HTTP request pipeline.
        public void Configure(IApplicationBuilder app, IWebHostEnvironment env, ILoggerFactory loggerFactory)
        {
            if (env.IsDevelopment())
            {
                app.UseDeveloperExceptionPage();
            }
            else
            {
                // The default HSTS value is 30 days. You may want to change this for production scenarios, see https://aka.ms/aspnetcore-hsts.
                app.UseHsts();
            }

            loggerFactory.AddSerilog();
            app.UseHttpsRedirection();

            app.UseStaticFiles();

            app.UseRouting();

            app.UseEndpoints(endpoints =>
            {
                endpoints.MapBlazorHub();
                endpoints.MapFallbackToPage("/_Host");
            });
        }
    }

Symptom

After the page loads the table of records loads correctly. When clicking on Next and Previous repeatedly to go back and forth (not particularly fast), it takes about 3 iterations for the response to start lagging and eventually stop with an error. I hard coded the api endpoint and tried it in isolation and it's responding very quickly without any issues (hardcoded or not). I've searched a lot to see if my setup is incorrect but can't find anything that would suggest so at this point. One minor thing to note is that the event handler in the products.razor page is async void, which I thought may be a reason.

Exceptions Thrown

[2019-05-06T20:23:43.734Z] Error: System.Exception: Unsuccessful request to http://localhost/kiss.api/products/list/0,5 ServiceUnavailable <!DOCTYPE HTML PUBLIC "-//W3C//DTD HTML 4.01//EN""http://www.w3.org/TR/html4/strict.dtd">
<HTML><HEAD><TITLE>Service Unavailable</TITLE>
<META HTTP-EQUIV="Content-Type" Content="text/html; charset=us-ascii"></HEAD>
<BODY><h2>Service Unavailable</h2>
<hr><p>HTTP Error 503. The service is unavailable.</p>
</BODY></HTML>

   at Kiss.Web.Services.ProductService.GetProductsAsync(Nullable`1 pageIndex, Int32 itemsPerPage) in C:\dev\TVProjects\Kiss\Kiss.Web\Services\ProductService.cs:line 54
   at Kiss.Web.Pages.Products.UpdateProducts(Int32 pageIndex, Int32 itemsPerPage) in C:\dev\TVProjects\Kiss\Kiss.Web\Pages\Products.razor:line 50
   at Kiss.Web.Pages.Products.PageChangedEvent(Int32 pageIndex) in C:\dev\TVProjects\Kiss\Kiss.Web\Pages\Products.razor:line 38
   at System.Threading.Tasks.Task.<>c.<ThrowAsync>b__139_0(Object state)
   at Microsoft.AspNetCore.Components.Rendering.RendererSynchronizationContext.ExecuteSynchronously(TaskCompletionSource`1 completion, SendOrPostCallback d, Object state)
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.AspNetCore.Components.Rendering.RendererSynchronizationContext.ExecuteBackground(WorkItem item)

and

blazor.server.js:1 Uncaught (in promise) Error: Cannot send data if the connection is not in the 'Connected' State.
    at e.send (blazor.server.js:1)
    at e.sendMessage (blazor.server.js:1)
    at e.send (blazor.server.js:1)
    at Object.beginInvokeDotNetFromJS (blazor.server.js:8)
    at c (blazor.server.js:8)
    at Object.s [as invokeMethodAsync] (blazor.server.js:8)
    at blazor.server.js:8
    at e.onEvent (blazor.server.js:8)
    at e.onGlobalEvent (blazor.server.js:8)

Expected behavior

Since the api service is working fine, the expectation is that I should be able to use the pagination to go back and forth without a degradation/lagging and eventually error that requires a page reload.

Screenshots

image

Additional context

This is the first time I post on GitHub, hope I did it right and hope for a solution. Apologies if I made a mistake here.

Thanks

dcarr42 commented 5 years ago

Interestingly I'm not sure newing up HttpClient is proper usage here.

islandmanllc commented 5 years ago

Well, even with the following, the same issue occurs:

services.AddScoped<HttpClient>();
services.AddScoped<IProductService, ProductService>();

I've also tried using IHttpClientFactory but same result...

islandmanllc commented 5 years ago

Oh, and I'm using 3.0.100-preview4-011223 for the blazor (server side) project with a 2.2 web service.

dcarr42 commented 5 years ago

Maybe add the server logs. Also how were you implementing HttpClientFactory as it would be a better approach? Also but no biggy why are you scoping the ProductService to the request?

islandmanllc commented 5 years ago

First I scoped the service as singleton, but got an error that I can't scope it singleton when httpclient has a different scope. Going to try to scope the service singleton and use the IHttpClientFactory instead right now.

islandmanllc commented 5 years ago

Still same issue. Here are the changes: Startup.cs

services.AddHttpClient();
services.AddSingleton<IProductService, ProductService>();

ProductService.cs

        internal HttpClient _clientFactory;
        internal ILogger<ProductService> _logger;

        private readonly string _baseUrl = "http://localhost/kiss.api";
        public ProductService(IHttpClientFactory clientFactory, ILogger<ProductService> logger)
        {
            _clientFactory = clientFactory.CreateClient();
            _logger = logger;
        }
...

However, I didn't have any issues with the Service being scoped a singleton, which is definitely correct.

islandmanllc commented 5 years ago

Server log from Serilog: Logs from reloading the page:

2019-05-06 11:34:46.473 -10:00 [Information] Application started. Press Ctrl+C to shut down.
2019-05-06 11:34:46.487 -10:00 [Information] Request starting HTTP/2.0 GET https://localhost/kiss.web/products  
2019-05-06 11:34:46.496 -10:00 [Information] Hosting environment: "Development"
2019-05-06 11:34:46.497 -10:00 [Information] Content root path: "C:\inetpub\wwwroot\Kiss.Web"
2019-05-06 11:34:46.543 -10:00 [Information] Executing endpoint '"/_Host"'
2019-05-06 11:34:46.570 -10:00 [Information] Route matched with "{page = \"/_Host\"}". Executing page "/_Host"
2019-05-06 11:34:46.593 -10:00 [Information] Executing an implicit handler method - ModelState is Valid
2019-05-06 11:34:46.593 -10:00 [Information] Executed an implicit handler method, returned result "Microsoft.AspNetCore.Mvc.RazorPages.PageResult".
2019-05-06 11:34:46.670 -10:00 [Information] Start processing HTTP request "GET" http://localhost/kiss.api/products/list/0,5
2019-05-06 11:34:46.671 -10:00 [Information] Sending HTTP request "GET" http://localhost/kiss.api/products/list/0,5
2019-05-06 11:34:46.746 -10:00 [Information] Received HTTP response after 68.7769ms - OK
2019-05-06 11:34:46.747 -10:00 [Information] End processing HTTP request after 81.2154ms - OK
2019-05-06 11:34:46.966 -10:00 [Information] Executed page "/_Host" in 385.3535ms
2019-05-06 11:34:46.967 -10:00 [Information] Request starting HTTP/2.0 GET https://localhost/kiss.web/css/bootstrap/bootstrap.min.css  
2019-05-06 11:34:46.968 -10:00 [Information] Executed endpoint '"/_Host"'
2019-05-06 11:34:46.968 -10:00 [Information] Request starting HTTP/2.0 GET https://localhost/kiss.web/font-awesome/css/font-awesome.css  
2019-05-06 11:34:46.968 -10:00 [Information] Request starting HTTP/2.0 GET https://localhost/kiss.web/css/animate.css  
2019-05-06 11:34:46.969 -10:00 [Information] Request starting HTTP/2.0 GET https://localhost/kiss.web/css/site.css  
2019-05-06 11:34:46.969 -10:00 [Information] Request starting HTTP/2.0 GET https://localhost/kiss.web/img/profile_small.jpg  
2019-05-06 11:34:46.969 -10:00 [Information] Request starting HTTP/2.0 GET https://localhost/kiss.web/img/a4.jpg  
2019-05-06 11:34:46.969 -10:00 [Information] Request starting HTTP/2.0 GET https://localhost/kiss.web/img/a7.jpg  
2019-05-06 11:34:46.969 -10:00 [Information] Request starting HTTP/2.0 GET https://localhost/kiss.web/img/profile.jpg  
2019-05-06 11:34:46.971 -10:00 [Information] Request finished in 1.6425ms 404 
2019-05-06 11:34:46.971 -10:00 [Information] Request finished in 1.7163000000000002ms 404 
2019-05-06 11:34:46.971 -10:00 [Information] Request finished in 1.9593ms 404 
2019-05-06 11:34:46.971 -10:00 [Information] Request finished in 1.6851ms 404 
2019-05-06 11:34:46.975 -10:00 [Information] The file "/css/site.css" was not modified
2019-05-06 11:34:46.975 -10:00 [Information] The file "/css/animate.css" was not modified
2019-05-06 11:34:46.975 -10:00 [Information] The file "/css/bootstrap/bootstrap.min.css" was not modified
2019-05-06 11:34:46.975 -10:00 [Information] The file "/font-awesome/css/font-awesome.css" was not modified
2019-05-06 11:34:46.977 -10:00 [Information] Request finished in 8.929ms 304 text/css
2019-05-06 11:34:46.977 -10:00 [Information] Request finished in 10.1891ms 304 text/css
2019-05-06 11:34:46.977 -10:00 [Information] Request finished in 8.2196ms 304 text/css
2019-05-06 11:34:46.977 -10:00 [Information] Request finished in 9.353900000000001ms 304 text/css
2019-05-06 11:34:46.983 -10:00 [Information] Request finished in 499.10670000000005ms 200 text/html; charset=utf-8
2019-05-06 11:34:46.989 -10:00 [Information] Request starting HTTP/2.0 GET https://localhost/kiss.web/assets/images/feeds/a1.jpg  
2019-05-06 11:34:46.989 -10:00 [Information] Request starting HTTP/2.0 GET https://localhost/kiss.web/assets/images/feeds/a2.jpg  
2019-05-06 11:34:46.990 -10:00 [Information] Request starting HTTP/2.0 GET https://localhost/kiss.web/_framework/blazor.server.js  
2019-05-06 11:34:46.990 -10:00 [Information] The file "/assets/images/feeds/a2.jpg" was not modified
2019-05-06 11:34:46.990 -10:00 [Information] The file "/assets/images/feeds/a1.jpg" was not modified
2019-05-06 11:34:46.990 -10:00 [Information] Request starting HTTP/2.0 GET https://localhost/kiss.web/assets/images/feeds/a3.jpg  
2019-05-06 11:34:46.990 -10:00 [Information] The file "/_framework/blazor.server.js" was not modified
2019-05-06 11:34:46.990 -10:00 [Information] Request finished in 0.8199000000000001ms 304 image/jpeg
2019-05-06 11:34:46.990 -10:00 [Information] Request finished in 0.8961ms 304 image/jpeg
2019-05-06 11:34:46.990 -10:00 [Information] Request finished in 0.4949ms 304 application/javascript
2019-05-06 11:34:46.990 -10:00 [Information] The file "/assets/images/feeds/a3.jpg" was not modified
2019-05-06 11:34:46.991 -10:00 [Information] Request finished in 0.6795ms 304 image/jpeg
2019-05-06 11:34:47.003 -10:00 [Information] Request starting HTTP/2.0 GET https://localhost/kiss.web/css/patterns/header-profile.png  
2019-05-06 11:34:47.003 -10:00 [Information] Request finished in 0.341ms 404 
2019-05-06 11:34:47.007 -10:00 [Information] Request starting HTTP/2.0 GET https://localhost/kiss.web/font-awesome/fonts/fontawesome-webfont.woff2?v=4.7.0  
2019-05-06 11:34:47.008 -10:00 [Information] The file "/font-awesome/fonts/fontawesome-webfont.woff2" was not modified
2019-05-06 11:34:47.008 -10:00 [Information] Request finished in 0.47690000000000005ms 304 font/woff2
2019-05-06 11:34:47.044 -10:00 [Information] Request starting HTTP/2.0 GET https://localhost/kiss.web/css/bootstrap/bootstrap.min.css.map  
2019-05-06 11:34:47.045 -10:00 [Information] The file "/css/bootstrap/bootstrap.min.css.map" was not modified
2019-05-06 11:34:47.045 -10:00 [Information] Request finished in 0.512ms 304 text/plain
2019-05-06 11:34:47.056 -10:00 [Information] Request starting HTTP/2.0 GET https://localhost/kiss.web/_framework/blazor.boot.json  
2019-05-06 11:34:47.057 -10:00 [Information] The file "/_framework/blazor.boot.json" was not modified
2019-05-06 11:34:47.057 -10:00 [Information] Request finished in 0.6259ms 304 application/json
2019-05-06 11:34:47.060 -10:00 [Information] Request starting HTTP/2.0 POST https://localhost/kiss.web/_blazor/negotiate text/plain;charset=UTF-8 0
2019-05-06 11:34:47.060 -10:00 [Information] Executing endpoint '"/_blazor/negotiate"'
2019-05-06 11:34:47.070 -10:00 [Information] Executed endpoint '"/_blazor/negotiate"'
2019-05-06 11:34:47.070 -10:00 [Information] Request finished in 10.4281ms 200 application/json
2019-05-06 11:34:47.084 -10:00 [Information] Request starting HTTP/1.1 GET https://localhost/kiss.web/_blazor?id=COyoVCWVyPoD_dwLfHRRPw  
2019-05-06 11:34:47.084 -10:00 [Information] Executing endpoint '"/_blazor"'
2019-05-06 11:34:47.111 -10:00 [Information] Completed connection handshake. Using HubProtocol '"blazorpack"'.
2019-05-06 11:34:47.160 -10:00 [Information] Request starting HTTP/2.0 GET https://localhost/kiss.web/img/profile_small.jpg  
2019-05-06 11:34:47.160 -10:00 [Information] Request starting HTTP/2.0 GET https://localhost/kiss.web/img/a7.jpg  
2019-05-06 11:34:47.161 -10:00 [Information] Request finished in 0.318ms 404 
2019-05-06 11:34:47.161 -10:00 [Information] Request finished in 0.2936ms 404 
2019-05-06 11:34:47.161 -10:00 [Information] Request starting HTTP/2.0 GET https://localhost/kiss.web/img/a4.jpg  
2019-05-06 11:34:47.161 -10:00 [Information] Request starting HTTP/2.0 GET https://localhost/kiss.web/img/profile.jpg  
2019-05-06 11:34:47.162 -10:00 [Information] Request finished in 0.28350000000000003ms 404 
2019-05-06 11:34:47.162 -10:00 [Information] Request finished in 0.2922ms 404

Hitting Next once

2019-05-06 11:37:36.232 -10:00 [Information] Start processing HTTP request "GET" http://localhost/kiss.api/products/list/1,5
2019-05-06 11:37:36.233 -10:00 [Information] Sending HTTP request "GET" http://localhost/kiss.api/products/list/1,5
2019-05-06 11:37:36.237 -10:00 [Information] Start processing HTTP request "GET" http://localhost/kiss.api/products/list/1,5
2019-05-06 11:37:36.237 -10:00 [Information] Sending HTTP request "GET" http://localhost/kiss.api/products/list/1,5
2019-05-06 11:37:36.237 -10:00 [Information] Received HTTP response after 4.8215ms - OK
2019-05-06 11:37:36.238 -10:00 [Information] Start processing HTTP request "GET" http://localhost/kiss.api/products/list/1,5
2019-05-06 11:37:36.238 -10:00 [Information] End processing HTTP request after 5.2216000000000005ms - OK
2019-05-06 11:37:36.238 -10:00 [Information] Sending HTTP request "GET" http://localhost/kiss.api/products/list/1,5
2019-05-06 11:37:36.243 -10:00 [Information] Received HTTP response after 6.213ms - OK
2019-05-06 11:37:36.243 -10:00 [Information] Received HTTP response after 5.6725ms - OK
2019-05-06 11:37:36.243 -10:00 [Information] End processing HTTP request after 6.5445ms - OK
2019-05-06 11:37:36.243 -10:00 [Information] End processing HTTP request after 5.976100000000001ms - OK

Hitting previous:

2019-05-06 11:38:14.292 -10:00 [Information] Start processing HTTP request "GET" http://localhost/kiss.api/products/list/0,5
2019-05-06 11:38:14.292 -10:00 [Information] Sending HTTP request "GET" http://localhost/kiss.api/products/list/0,5
2019-05-06 11:38:14.293 -10:00 [Information] Start processing HTTP request "GET" http://localhost/kiss.api/products/list/0,5
2019-05-06 11:38:14.293 -10:00 [Information] Sending HTTP request "GET" http://localhost/kiss.api/products/list/0,5
2019-05-06 11:38:14.294 -10:00 [Information] Start processing HTTP request "GET" http://localhost/kiss.api/products/list/0,5
2019-05-06 11:38:14.294 -10:00 [Information] Sending HTTP request "GET" http://localhost/kiss.api/products/list/0,5
2019-05-06 11:38:14.295 -10:00 [Information] Received HTTP response after 2.4604ms - OK
2019-05-06 11:38:14.295 -10:00 [Information] Start processing HTTP request "GET" http://localhost/kiss.api/products/list/0,5
2019-05-06 11:38:14.295 -10:00 [Information] Received HTTP response after 1.8995000000000002ms - OK
2019-05-06 11:38:14.295 -10:00 [Information] End processing HTTP request after 3.2358000000000002ms - OK
2019-05-06 11:38:14.295 -10:00 [Information] Sending HTTP request "GET" http://localhost/kiss.api/products/list/0,5
2019-05-06 11:38:14.295 -10:00 [Information] End processing HTTP request after 2.5296000000000003ms - OK
2019-05-06 11:38:14.296 -10:00 [Information] Received HTTP response after 1.6727ms - OK
2019-05-06 11:38:14.296 -10:00 [Information] End processing HTTP request after 2.6272ms - OK
2019-05-06 11:38:14.297 -10:00 [Information] Start processing HTTP request "GET" http://localhost/kiss.api/products/list/0,5
2019-05-06 11:38:14.297 -10:00 [Information] Sending HTTP request "GET" http://localhost/kiss.api/products/list/0,5
2019-05-06 11:38:14.297 -10:00 [Information] Start processing HTTP request "GET" http://localhost/kiss.api/products/list/0,5
2019-05-06 11:38:14.297 -10:00 [Information] Received HTTP response after 2.2126ms - OK
2019-05-06 11:38:14.298 -10:00 [Information] Sending HTTP request "GET" http://localhost/kiss.api/products/list/0,5
2019-05-06 11:38:14.298 -10:00 [Information] End processing HTTP request after 2.9069000000000003ms - OK
2019-05-06 11:38:14.298 -10:00 [Information] Received HTTP response after 1.2989000000000002ms - OK
2019-05-06 11:38:14.298 -10:00 [Information] End processing HTTP request after 1.7729000000000001ms - OK
2019-05-06 11:38:14.299 -10:00 [Information] Received HTTP response after 1.6263ms - OK
2019-05-06 11:38:14.300 -10:00 [Information] End processing HTTP request after 2.2295000000000003ms - OK

Based on this, it seems to me that it's making too many requests

dcarr42 commented 5 years ago

Yeah...looks better. Is that url correct in the exception which I'm guessing it is? Can you get some logs off the api?

dcarr42 commented 5 years ago

That's going nuts. 😂

islandmanllc commented 5 years ago

Yeah, looks like every request queues up more requests. Hmmm, that's very odd.

dcarr42 commented 5 years ago

I'm not sure could be normal for a blazor app but I am sceptical.

islandmanllc commented 5 years ago

I hope it's not normal :( I can't see any obvious reason for it to keep increasing the requests. Almost looks like something where I fire one event and it's fine. Second event fires the first one again and a second one and so on until the number of requests goes out of hand...

dcarr42 commented 5 years ago

Are you sure the pagination is working as expected?

islandmanllc commented 5 years ago

Well in terms of expected results, yes. Right now, I have a hard coded list with ts just to rule out the backend but when connected, it paged as expected.

islandmanllc commented 5 years ago

To me this points to the event mechanism. Maybe an async/sync issue. Going to move the pagination into the main page and drop the event to test now.

dcarr42 commented 5 years ago

The OnAfterRender is a little suspicious.

dcarr42 commented 5 years ago

async void usage is not good.

islandmanllc commented 5 years ago

Agree on the async void, but I read an article that made me think it's ok. Anyway, I moved the pagination into the page and removed the event mechanism and made all calls async and now it works. Here's the page now:

@page "/products"
@using Kiss.Application.Features.Products.ViewModels
@using Microsoft.AspNetCore.Components

<DataTable Items="@_products" TItem="ProductViewModels.Details">
    <HeaderTemplate>
        <th>Name</th>
        <th>Description</th>
    </HeaderTemplate>
    <RowTemplate Context="Item">
        <td>@Item.Name</td>
        <td>@Item.Description</td>
    </RowTemplate>
    <FooterTemplate Context="Item">
        <td colspan="2">@_itemsTotal products found.</td>
    </FooterTemplate>
</DataTable>
<div class="dataTables_paginate paging_simple_numbers" id="DataTables_Table_0_paginate">
    <ul class="pagination">
        <li class="paginate_button page-item previous @Disabled(0)" id="DataTables_Table_0_previous">
            <a aria-controls="DataTables_Table_0" data-dt-idx="0" tabindex="0" class="page-link" onclick="@FirstPage">First</a>
        </li>
        <li class="paginate_button page-item previous @Disabled(0)" id="DataTables_Table_0_previous">
            <a aria-controls="DataTables_Table_0" data-dt-idx="1" tabindex="0" class="page-link" onclick="@PreviousPage">Previous</a>
        </li>

        <li class="paginate_button page-item next @Disabled(LastPageIndex)" id="DataTables_Table_0_next">
            <a aria-controls="DataTables_Table_0" data-dt-idx="2" tabindex="0" class="page-link" onclick="@NextPage">Next</a>
        </li>
        <li class="paginate_button page-item next @Disabled(LastPageIndex)" id="DataTables_Table_0_next">
            <a aria-controls="DataTables_Table_0" data-dt-idx="3" tabindex="0" class="page-link" onclick="@LastPage">Last</a>
        </li>
    </ul>
</div>

@functions {
    private int _itemsPerPage = 5;
    private int _lastPageIndex = 0;

    private IEnumerable<ProductViewModels.Details> _products = new List<ProductViewModels.Details>();
    private int _itemsTotal = 0;

    [Inject] IProductService ProductService { get; set; }

    protected override async Task OnInitAsync()
    {
        await UpdateProducts(0, _itemsPerPage);
    }

    private async Task UpdateProducts(int pageIndex, int itemsPerPage)
    {
        if (ProductService != null)
        {
            var result = await ProductService.GetProductsAsync(pageIndex, itemsPerPage);
            if (result != null)
            {
                _products = result.Items;
                _itemsTotal = result.ItemsTotal;
                _itemsPerPage = result.ItemsPerPage;
                _lastPageIndex = result.TotalPages - 1;
                StateHasChanged();
            }
        }
    }

    private int _currentPageIndex = 0;

    [Parameter]
    private int LastPageIndex { get; set; } = 3;

    async Task ChangeCurrentPageIndex(int pageIndex)
    {
        if (pageIndex != _currentPageIndex)
        {
            _currentPageIndex = pageIndex;
            await UpdateProducts(_currentPageIndex, _itemsPerPage);
        }
    }

    string Disabled(int pageIndex)
    {
        return _currentPageIndex == pageIndex ? "disabled" : "";
    }

    async Task FirstPage()
    {
        await ChangeCurrentPageIndex(0);
    }

    async Task NextPage()
    {
        if (_currentPageIndex < LastPageIndex)
        {
            await ChangeCurrentPageIndex(_currentPageIndex + 1);
        }
    }

    async Task PreviousPage()
    {
        if (_currentPageIndex > 0)
        {
            await ChangeCurrentPageIndex(_currentPageIndex - 1);
        }
    }

    async Task LastPage()
    {
        await ChangeCurrentPageIndex(LastPageIndex);
    }
}

So, it's something with the event coupled with the async/void I believe,.

islandmanllc commented 5 years ago

Having said that, I still don't know the root cause other than it seems to be related to using the sync event with an async handling of the event. This may be by design and I just used it incorrectly.

dcarr42 commented 5 years ago

Correct but I'm not sure in this context. Need to call on any Blazor aficionados.

islandmanllc commented 5 years ago

Haha, yeah, I'll wait for that and move on for now. Thanks a lot for responding. First time I posted here and you made it worth while! Aloha from Hawaii!

dcarr42 commented 5 years ago

https://github.com/aspnet/Blazor/issues/519#issuecomment-384781166

islandmanllc commented 5 years ago

Ok, problem resolved. My bad. The issue was with OnAfterRender. This is of course triggered multiple times. The solution to this problem is as follows:

Pass in the event handler as a param to the child:

<Paginator ref="@_paginator" OnPageChangeEvent="@PageChangedEventAsync" LastPageIndex="@_lastPageIndex" />

Remove the OnAfterRender override method.

`` Invoke the passed in event handler of the parent in the child:

    {
        if (pageIndex != _currentPageIndex)
        {
            _currentPageIndex = pageIndex;
            OnPageChangeEvent?.Invoke(_currentPageIndex);
        }
    }

Thanks! This can be closed.

islandmanllc commented 5 years ago

Misuse by registering parent component event handler to child component in parent OnAfterRender instead of passing in the parent component event handler as a param to the child component.