Base solution for your next web application
Open Closed

Application lost response sometimes #5267

User avatar
0
trendline created

It is a very odd behavior, and confused me recent days. The application will lost response sometimes in a random chance, the client cannot get any response from the server.

First, the Tenancy specified access lost response from the server, then if clean the client cookie, it could access to the Host dashboard, but cannot impersonation to any Tenant, if try to impersonation a Tenant, then it will blocked on the redirect screen.

After several tries, the Host dashboard also will lost response from the server, by this time, all site lost response from the server.

The odd thing is all of these behaviors without exception logs to record, the server level or the application level both are looks work good, and the w3p.exe, application dotnet.exe both are working fine.

During the no response time, the application logs recorded request are received by the application, but cannot return any result to client. It will stop after redirect the route to login action of the account controller.

Every time encountered this behavior only restart the application pool could let the application run normally, no other approach can fix it.

Anybody have this issue too?

It is running under Zero v5.5.0, host on IIS 10 on Windows Server 2012 with SQL Server 2017 as the DB server.

Go to accepted answer
38 Answer(s)
  • User Avatar
    0
    ismcagdas created
    Support Team

    @trendline are you using ASP.NET Core MVC & JQuery version ? If so, could you try this fix <a class="postlink" href="https://github.com/aspnetzero/aspnet-zero-core/issues/1287">https://github.com/aspnetzero/aspnet-ze ... ssues/1287</a> ?

  • User Avatar
    0
    trendline created

    Yes, I am using the MVC&jQuery edition, I already found this fix and applied, the application is running normally almost one day, I hope this issue is the reason behind and it could be fixed by this approach.

    Thanks for your information.

  • User Avatar
    0
    ismcagdas created
    Support Team

    Ok, please let us know if you face the same problem again.

  • User Avatar
    0
    trendline created

    Unfortunately, this is not the real reason, after a new deployment, it happened again. logs record below repeated logs as below:

    INFO  2018-06-22 09:12:01,820 [10   ] soft.AspNetCore.Hosting.Internal.WebHost - Request starting HTTP/1.0 HEAD http://127.0.0.1:14395/  
INFO  2018-06-22 09:12:01,829 [10   ] ore.Mvc.Internal.ControllerActionInvoker - Route matched with {action = "Index", controller = "Home", area = ""}. Executing action Viewtance.SRP.Web.Controllers.HomeController.Index (Viewtance.SRP.Web.Mvc)
INFO  2018-06-22 09:12:01,832 [10   ] ore.Mvc.Internal.ControllerActionInvoker - Executing action method Viewtance.SRP.Web.Controllers.HomeController.Index (Viewtance.SRP.Web.Mvc) with arguments (, False) - Validation state: Valid
INFO  2018-06-22 09:12:01,832 [10   ] ore.Mvc.Internal.ControllerActionInvoker - Executed action method Viewtance.SRP.Web.Controllers.HomeController.Index (Viewtance.SRP.Web.Mvc), returned result Microsoft.AspNetCore.Mvc.RedirectToActionResult in 0.0266ms.
INFO  2018-06-22 09:12:01,844 [10   ] ft.AspNetCore.Mvc.RedirectToActionResult - Executing RedirectResult, redirecting to /Account/Login.
INFO  2018-06-22 09:12:01,844 [10   ] ore.Mvc.Internal.ControllerActionInvoker - Executed action Viewtance.SRP.Web.Controllers.HomeController.Index (Viewtance.SRP.Web.Mvc) in 15.145ms
INFO  2018-06-22 09:12:01,845 [10   ] soft.AspNetCore.Hosting.Internal.WebHost - Request finished in 24.635ms 302 
INFO  2018-06-22 09:18:12,102 [38   ] soft.AspNetCore.Hosting.Internal.WebHost - Request starting HTTP/1.0 HEAD http://127.0.0.1:14395/  
INFO  2018-06-22 09:18:12,109 [38   ] ore.Mvc.Internal.ControllerActionInvoker - Route matched with {action = "Index", controller = "Home", area = ""}. Executing action Viewtance.SRP.Web.Controllers.HomeController.Index (Viewtance.SRP.Web.Mvc)
INFO  2018-06-22 09:18:12,111 [38   ] ore.Mvc.Internal.ControllerActionInvoker - Executing action method Viewtance.SRP.Web.Controllers.HomeController.Index (Viewtance.SRP.Web.Mvc) with arguments (, False) - Validation state: Valid
INFO  2018-06-22 09:18:12,111 [38   ] ore.Mvc.Internal.ControllerActionInvoker - Executed action method Viewtance.SRP.Web.Controllers.HomeController.Index (Viewtance.SRP.Web.Mvc), returned result Microsoft.AspNetCore.Mvc.RedirectToActionResult in 0.0274ms.
INFO  2018-06-22 09:18:12,122 [38   ] ft.AspNetCore.Mvc.RedirectToActionResult - Executing RedirectResult, redirecting to /Account/Login.
INFO  2018-06-22 09:18:12,122 [38   ] ore.Mvc.Internal.ControllerActionInvoker - Executed action Viewtance.SRP.Web.Controllers.HomeController.Index (Viewtance.SRP.Web.Mvc) in 12.2954ms
INFO  2018-06-22 09:18:12,122 [38   ] soft.AspNetCore.Hosting.Internal.WebHost - Request finished in 20.5415ms 302 
INFO  2018-06-22 09:19:50,981 [25   ] soft.AspNetCore.Hosting.Internal.WebHost - Request starting HTTP/1.0 HEAD http://127.0.0.1:14395/  
INFO  2018-06-22 09:19:50,988 [25   ] ore.Mvc.Internal.ControllerActionInvoker - Route matched with {action = "Index", controller = "Home", area = ""}. Executing action Viewtance.SRP.Web.Controllers.HomeController.Index (Viewtance.SRP.Web.Mvc)
INFO  2018-06-22 09:19:50,990 [25   ] ore.Mvc.Internal.ControllerActionInvoker - Executing action method Viewtance.SRP.Web.Controllers.HomeController.Index (Viewtance.SRP.Web.Mvc) with arguments (, False) - Validation state: Valid
INFO  2018-06-22 09:19:50,990 [25   ] ore.Mvc.Internal.ControllerActionInvoker - Executed action method Viewtance.SRP.Web.Controllers.HomeController.Index (Viewtance.SRP.Web.Mvc), returned result Microsoft.AspNetCore.Mvc.RedirectToActionResult in 0.0244ms.
INFO  2018-06-22 09:19:51,002 [25   ] ft.AspNetCore.Mvc.RedirectToActionResult - Executing RedirectResult, redirecting to /Account/Login.
INFO  2018-06-22 09:19:51,002 [25   ] ore.Mvc.Internal.ControllerActionInvoker - Executed action Viewtance.SRP.Web.Controllers.HomeController.Index (Viewtance.SRP.Web.Mvc) in 13.4572ms
INFO  2018-06-22 09:19:51,002 [25   ] soft.AspNetCore.Hosting.Internal.WebHost - Request finished in 21.0892ms 302 
INFO  2018-06-22 09:22:22,434 [65   ] soft.AspNetCore.Hosting.Internal.WebHost - Request starting HTTP/1.0 HEAD http://127.0.0.1:14395/  
INFO  2018-06-22 09:22:22,442 [65   ] ore.Mvc.Internal.ControllerActionInvoker - Route matched with {action = "Index", controller = "Home", area = ""}. Executing action Viewtance.SRP.Web.Controllers.HomeController.Index (Viewtance.SRP.Web.Mvc)
INFO  2018-06-22 09:22:22,444 [65   ] ore.Mvc.Internal.ControllerActionInvoker - Executing action method Viewtance.SRP.Web.Controllers.HomeController.Index (Viewtance.SRP.Web.Mvc) with arguments (, False) - Validation state: Valid
INFO  2018-06-22 09:22:22,445 [65   ] ore.Mvc.Internal.ControllerActionInvoker - Executed action method Viewtance.SRP.Web.Controllers.HomeController.Index (Viewtance.SRP.Web.Mvc), returned result Microsoft.AspNetCore.Mvc.RedirectToActionResult in 0.0276ms.
INFO  2018-06-22 09:22:22,453 [65   ] ft.AspNetCore.Mvc.RedirectToActionResult - Executing RedirectResult, redirecting to /Account/Login.
INFO  2018-06-22 09:22:22,453 [65   ] ore.Mvc.Internal.ControllerActionInvoker - Executed action Viewtance.SRP.Web.Controllers.HomeController.Index (Viewtance.SRP.Web.Mvc) in 10.8877ms
INFO  2018-06-22 09:22:22,454 [65   ] soft.AspNetCore.Hosting.Internal.WebHost - Request finished in 19.8017ms 302
  • User Avatar
    0
    ismcagdas created
    Support Team

    @trendline It seems like there is no error on the log file. Have you tried setting your IIS application pool to Always On mode ?

  • User Avatar
    0
    trendline created

    @ismcagdas, yes, the application pool start model is always running, furthermore application pool without recycling.

    It is a so urgently confusion issue, I don't kown when the application will not availble, online service is unreliable。

  • User Avatar
    0
    trendline created

    Updated.

    when visit a service, suddenly, the server lost response, below logs recorded the request event, before server lost response I am visiting the GetAll method of the Bunk Service, then a Error Redirect action be recorded, but client cannot get any response from server, and other requests all blocked there, event the application received the request, but no response sent to client.

    Any logs for the error redirection could be recorded? there is no error or exception system logs on the OS.

    INFO  2018-06-24 10:32:31,355 [14   ] soft.AspNetCore.Hosting.Internal.WebHost - Request starting HTTP/1.1 GET http://mydomain.com/api/services/ga/Bunk/GetAll?filter=115&numberFilter=&descriptionFilter=&roomNameFilter=&userNameFilter=&stateIdFilter=&maxCheckInTimeFilter=&minCheckInTimeFilter=&maxCheckOutTimeFilter=&minCheckOutTimeFilter=&nameFilter=&sorting=bunk.number%20asc&skipCount=0&maxResultCount=10 application/json 
INFO  2018-06-24 10:32:31,364 [14   ] ore.Mvc.Internal.ControllerActionInvoker - Route matched with {area = "ga", action = "GetAll", controller = "Bunk"}. Executing action Viewtance.GA.Dormitories.BunkAppService.GetAll (Viewtance.GA.Application)
INFO  2018-06-24 10:32:31,376 [14   ] ore.Mvc.Internal.ControllerActionInvoker - Executing action method Viewtance.GA.Dormitories.BunkAppService.GetAll (Viewtance.GA.Application) with arguments (Viewtance.GA.Dormitories.Dtos.GetAllBunksInput) - Validation state: Valid
INFO  2018-06-24 10:32:31,470 [14   ] ore.Mvc.Internal.ControllerActionInvoker - Executed action method Viewtance.GA.Dormitories.BunkAppService.GetAll (Viewtance.GA.Application), returned result Microsoft.AspNetCore.Mvc.ObjectResult in 93.4549ms.
INFO  2018-06-24 10:32:31,480 [14   ] .Mvc.Infrastructure.ObjectResultExecutor - Executing ObjectResult, writing value of type 'Abp.Web.Models.AjaxResponse'.
INFO  2018-06-24 10:32:31,480 [14   ] ore.Mvc.Internal.ControllerActionInvoker - Executed action Viewtance.GA.Dormitories.BunkAppService.GetAll (Viewtance.GA.Application) in 116.1856ms
INFO  2018-06-24 10:32:31,480 [14   ] soft.AspNetCore.Hosting.Internal.WebHost - Request finished in 125.3737ms 200 application/json; charset=utf-8
INFO  2018-06-24 10:32:46,420 [63   ] soft.AspNetCore.Hosting.Internal.WebHost - Request starting HTTP/1.1 GET http://mydomain.com/api/services/ga/Bunk/GetAll?filter=115&numberFilter=&descriptionFilter=&roomNameFilter=&userNameFilter=&stateIdFilter=&maxCheckInTimeFilter=&minCheckInTimeFilter=&maxCheckOutTimeFilter=&minCheckOutTimeFilter=&nameFilter=&sorting=bunkStateName%20asc&skipCount=0&maxResultCount=10 application/json 
INFO  2018-06-24 10:32:46,434 [63   ] ore.Mvc.Internal.ControllerActionInvoker - Route matched with {area = "ga", action = "GetAll", controller = "Bunk"}. Executing action Viewtance.GA.Dormitories.BunkAppService.GetAll (Viewtance.GA.Application)
INFO  2018-06-24 10:32:46,447 [63   ] ore.Mvc.Internal.ControllerActionInvoker - Executing action method Viewtance.GA.Dormitories.BunkAppService.GetAll (Viewtance.GA.Application) with arguments (Viewtance.GA.Dormitories.Dtos.GetAllBunksInput) - Validation state: Valid
INFO  2018-06-24 10:32:46,532 [19   ] ore.Mvc.Internal.ControllerActionInvoker - Executed action method Viewtance.GA.Dormitories.BunkAppService.GetAll (Viewtance.GA.Application), returned result Microsoft.AspNetCore.Mvc.ObjectResult in 84.7127ms.
INFO  2018-06-24 10:32:46,541 [19   ] .Mvc.Infrastructure.ObjectResultExecutor - Executing ObjectResult, writing value of type 'Abp.Web.Models.AjaxResponse'.
INFO  2018-06-24 10:32:46,542 [19   ] ore.Mvc.Internal.ControllerActionInvoker - Executed action Viewtance.GA.Dormitories.BunkAppService.GetAll (Viewtance.GA.Application) in 107.9084ms
INFO  2018-06-24 10:32:46,542 [19   ] soft.AspNetCore.Hosting.Internal.WebHost - Request finished in 121.5354ms 200 application/json; charset=utf-8
DEBUG 2018-06-24 10:36:02,352 [19   ] Viewtance.SRP.Web.Chat.SignalR.ChatHub   - A client is disconnected: eXd406xHH5rdND1JdyuEQA
INFO  2018-06-24 10:36:02,352 [19   ] soft.AspNetCore.Hosting.Internal.WebHost - Request finished in 526880.4817ms 101 
INFO  2018-06-24 10:36:26,913 [19   ] soft.AspNetCore.Hosting.Internal.WebHost - Request starting HTTP/1.1 GET http://mydomain.com/api/services/ga/Bunk/GetAll?filter=115&numberFilter=&descriptionFilter=&roomNameFilter=&userNameFilter=&stateIdFilter=&maxCheckInTimeFilter=&minCheckInTimeFilter=&maxCheckOutTimeFilter=&minCheckOutTimeFilter=&nameFilter=&sorting=bunk.number%20asc&skipCount=0&maxResultCount=10 application/json 
INFO  2018-06-24 10:36:26,941 [63   ] ore.Mvc.Internal.ControllerActionInvoker - Route matched with {area = "ga", action = "GetAll", controller = "Bunk"}. Executing action Viewtance.GA.Dormitories.BunkAppService.GetAll (Viewtance.GA.Application)
INFO  2018-06-24 10:36:26,954 [63   ] ore.Mvc.Internal.ControllerActionInvoker - Executing action method Viewtance.GA.Dormitories.BunkAppService.GetAll (Viewtance.GA.Application) with arguments (Viewtance.GA.Dormitories.Dtos.GetAllBunksInput) - Validation state: Valid
INFO  2018-06-24 10:36:50,686 [14   ] soft.AspNetCore.Hosting.Internal.WebHost - Request starting HTTP/1.1 GET http://mydomain.com/lib/@aspnet/signalr/dist/browser/signalr.min.js/signalr.min.js.map  
INFO  2018-06-24 10:36:50,694 [14   ] soft.AspNetCore.Hosting.Internal.WebHost - Request finished in 8.0557ms 302 
INFO  2018-06-24 10:36:50,732 [37   ] soft.AspNetCore.Hosting.Internal.WebHost - Request starting HTTP/1.1 GET http://mydomain.com/Error?statusCode=404  
INFO  2018-06-24 10:36:50,741 [37   ] ore.Mvc.Internal.ControllerActionInvoker - Route matched with {action = "Index", controller = "Error", area = ""}. Executing action Viewtance.SRP.Web.Controllers.ErrorController.Index (Viewtance.SRP.Web.Mvc)
INFO  2018-06-24 10:36:50,742 [37   ] ore.Mvc.Internal.ControllerActionInvoker - Executing action method Viewtance.SRP.Web.Controllers.ErrorController.Index (Viewtance.SRP.Web.Mvc) with arguments (404) - Validation state: Valid
INFO  2018-06-24 10:36:50,743 [37   ] ore.Mvc.Internal.ControllerActionInvoker - Executed action method Viewtance.SRP.Web.Controllers.ErrorController.Index (Viewtance.SRP.Web.Mvc), returned result Microsoft.AspNetCore.Mvc.ViewResult in 0.0196ms.
INFO  2018-06-24 10:36:50,744 [37   ] Core.Mvc.ViewFeatures.ViewResultExecutor - Executing ViewResult, running view Error404.
INFO  2018-06-24 10:38:24,545 [39   ] soft.AspNetCore.Hosting.Internal.WebHost - Request starting HTTP/1.1 GET http://mydomain.com/GA/Dormitory/Rooms  
INFO  2018-06-24 10:38:24,554 [39   ] ore.Mvc.Internal.ControllerActionInvoker - Route matched with {area = "GA", action = "Rooms", controller = "Dormitory"}. Executing action Viewtance.SRP.Web.Areas.GA.Controllers.DormitoryController.Rooms (Viewtance.SRP.Web.Mvc)
INFO  2018-06-24 10:38:24,555 [39   ] uthorization.DefaultAuthorizationService - Authorization was successful.
INFO  2018-06-24 10:38:24,570 [39   ] ore.Mvc.Internal.ControllerActionInvoker - Executing action method Viewtance.SRP.Web.Areas.GA.Controllers.DormitoryController.Rooms (Viewtance.SRP.Web.Mvc) - Validation state: Valid
INFO  2018-06-24 10:38:24,570 [39   ] ore.Mvc.Internal.ControllerActionInvoker - Executed action method Viewtance.SRP.Web.Areas.GA.Controllers.DormitoryController.Rooms (Viewtance.SRP.Web.Mvc), returned result Microsoft.AspNetCore.Mvc.ViewResult in 0.0352ms.
INFO  2018-06-24 10:38:24,585 [19   ] Core.Mvc.ViewFeatures.ViewResultExecutor - Executing ViewResult, running view Rooms.
  • User Avatar
    0
    alper created
    Support Team

    first clear Windows Event Viewer and try to reproduce your issue. It'll show if any unhandled exception throwed. then you can see Chrome Logs to see if the client got some exceptions.

  • User Avatar
    0
    trendline created

    The strange is that no exception system log recorded, the application logs could found the request has been received.

    On the client, the status is no response from the server, no other response.

    If the dotnet process dead or no reponse, then the IIS proxy will throw a message that cannot get response from the upstream server, but in my case it seems upstream dotnet process received the requests, only cannot response result to client.

  • User Avatar
    0
    alper created
    Support Team

    Turn off any anti-virus running on your server or your PC. Actually this has nothing to do with AspNet Zero. You can ask on <a class="postlink" href="https://forums.iis.net/">https://forums.iis.net/</a>

  • User Avatar
    0
    trendline created

    No antivirus or firewall setting block the communication on the server.

    below are the odd behaviors, MVC request no response, see the Account/Login action redirect, but at the same time the API service could get result to client, but not all of the services could get result to client.

    It seems the response blocked after validation the state.

    INFO  2018-06-27 01:22:17,313 [99   ] soft.AspNetCore.Hosting.Internal.WebHost - Request starting HTTP/1.1 GET http://mydomain/  
INFO  2018-06-27 01:22:17,320 [99   ] ore.Mvc.Internal.ControllerActionInvoker - Route matched with {action = "Index", controller = "Home", area = ""}. Executing action Viewtance.SRP.Web.Controllers.HomeController.Index (Viewtance.SRP.Web.Mvc)
INFO  2018-06-27 01:22:17,322 [99   ] ore.Mvc.Internal.ControllerActionInvoker - Executing action method Viewtance.SRP.Web.Controllers.HomeController.Index (Viewtance.SRP.Web.Mvc) with arguments (, False) - Validation state: Valid
INFO  2018-06-27 01:22:17,322 [99   ] ore.Mvc.Internal.ControllerActionInvoker - Executed action method Viewtance.SRP.Web.Controllers.HomeController.Index (Viewtance.SRP.Web.Mvc), returned result Microsoft.AspNetCore.Mvc.RedirectToActionResult in 0.0264ms.
INFO  2018-06-27 01:22:17,331 [99   ] ft.AspNetCore.Mvc.RedirectToActionResult - Executing RedirectResult, redirecting to /Account/Login.
INFO  2018-06-27 01:22:17,331 [99   ] ore.Mvc.Internal.ControllerActionInvoker - Executed action Viewtance.SRP.Web.Controllers.HomeController.Index (Viewtance.SRP.Web.Mvc) in 10.5059ms
INFO  2018-06-27 01:22:17,331 [99   ] soft.AspNetCore.Hosting.Internal.WebHost - Request finished in 18.2885ms 302 
INFO  2018-06-27 01:22:17,466 [35   ] soft.AspNetCore.Hosting.Internal.WebHost - Request starting HTTP/1.1 GET http://mydomain/Account/Login  
INFO  2018-06-27 01:22:17,473 [35   ] ore.Mvc.Internal.ControllerActionInvoker - Route matched with {action = "Login", controller = "Account", area = ""}. Executing action Viewtance.SRP.Web.Controllers.AccountController.Login (Viewtance.SRP.Web.Mvc)
INFO  2018-06-27 01:22:17,501 [35   ] ore.Mvc.Internal.ControllerActionInvoker - Executing action method Viewtance.SRP.Web.Controllers.AccountController.Login (Viewtance.SRP.Web.Mvc) with arguments (, , , ) - Validation state: Valid
INFO  2018-06-27 01:22:17,502 [35   ] ore.Mvc.Internal.ControllerActionInvoker - Executed action method Viewtance.SRP.Web.Controllers.AccountController.Login (Viewtance.SRP.Web.Mvc), returned result Microsoft.AspNetCore.Mvc.ViewResult in 0.2948ms.
INFO  2018-06-27 01:22:17,510 [111  ] Core.Mvc.ViewFeatures.ViewResultExecutor - Executing ViewResult, running view Login.
INFO  2018-06-27 01:28:36,504 [16   ] soft.AspNetCore.Hosting.Internal.WebHost - Request starting HTTP/1.1 GET http://mydomain/Account/Login  
INFO  2018-06-27 01:28:36,512 [16   ] ore.Mvc.Internal.ControllerActionInvoker - Route matched with {action = "Login", controller = "Account", area = ""}. Executing action Viewtance.SRP.Web.Controllers.AccountController.Login (Viewtance.SRP.Web.Mvc)
INFO  2018-06-27 01:28:36,540 [16   ] ore.Mvc.Internal.ControllerActionInvoker - Executing action method Viewtance.SRP.Web.Controllers.AccountController.Login (Viewtance.SRP.Web.Mvc) with arguments (, , , ) - Validation state: Valid
INFO  2018-06-27 01:28:36,540 [16   ] ore.Mvc.Internal.ControllerActionInvoker - Executed action method Viewtance.SRP.Web.Controllers.AccountController.Login (Viewtance.SRP.Web.Mvc), returned result Microsoft.AspNetCore.Mvc.ViewResult in 0.3075ms.
INFO  2018-06-27 01:28:36,553 [35   ] Core.Mvc.ViewFeatures.ViewResultExecutor - Executing ViewResult, running view Login.
INFO  2018-06-27 01:29:43,442 [15   ] soft.AspNetCore.Hosting.Internal.WebHost - Request starting HTTP/1.1 GET http://mydomain/School/Students  
INFO  2018-06-27 01:29:43,473 [15   ] ore.Mvc.Internal.ControllerActionInvoker - Route matched with {area = "School", action = "Index", controller = "Students"}. Executing action Viewtance.SRP.Web.Areas.School.Controllers.StudentsController.Index (Viewtance.SRP.Web.Mvc)
INFO  2018-06-27 01:29:43,474 [15   ] uthorization.DefaultAuthorizationService - Authorization was successful.
INFO  2018-06-27 01:29:43,488 [15   ] ore.Mvc.Internal.ControllerActionInvoker - Executing action method Viewtance.SRP.Web.Areas.School.Controllers.StudentsController.Index (Viewtance.SRP.Web.Mvc) - Validation state: Valid
INFO  2018-06-27 01:31:58,710 [95   ] soft.AspNetCore.Hosting.Internal.WebHost - Request starting HTTP/1.1 GET http://mydomain/api/services/crm/InfoPath/GetAll?SkipCount=0&MaxResultCount=100 application/json 
INFO  2018-06-27 01:31:58,792 [95   ] uthentication.JwtBearer.JwtBearerHandler - Successfully validated the token.
INFO  2018-06-27 01:31:58,861 [95   ] ore.Mvc.Internal.ControllerActionInvoker - Route matched with {area = "crm", action = "GetAll", controller = "InfoPath"}. Executing action Viewtance.CRM.InfoPaths.InfoPathAppService.GetAll (Viewtance.CRM.Application)
INFO  2018-06-27 01:31:59,109 [95   ] ore.Mvc.Internal.ControllerActionInvoker - Executing action method Viewtance.CRM.InfoPaths.InfoPathAppService.GetAll (Viewtance.CRM.Application) with arguments (Viewtance.CRM.InfoPaths.Dtos.GetAllInfoPathsInput) - Validation state: Valid
INFO  2018-06-27 01:31:59,276 [14   ] ore.Mvc.Internal.ControllerActionInvoker - Executed action method Viewtance.CRM.InfoPaths.InfoPathAppService.GetAll (Viewtance.CRM.Application), returned result Microsoft.AspNetCore.Mvc.ObjectResult in 167.0071ms.
INFO  2018-06-27 01:31:59,286 [50   ] .Mvc.Infrastructure.ObjectResultExecutor - Executing ObjectResult, writing value of type 'Abp.Web.Models.AjaxResponse'.
INFO  2018-06-27 01:31:59,298 [50   ] ore.Mvc.Internal.ControllerActionInvoker - Executed action Viewtance.CRM.InfoPaths.InfoPathAppService.GetAll (Viewtance.CRM.Application) in 436.6494ms
INFO  2018-06-27 01:31:59,298 [50   ] soft.AspNetCore.Hosting.Internal.WebHost - Request finished in 588.662ms 200 application/json; charset=utf-8
INFO  2018-06-27 01:32:54,910 [117  ] soft.AspNetCore.Hosting.Internal.WebHost - Request starting HTTP/1.1 GET http://mydomain/api/services/school/Leaves/GetAll application/json 
INFO  2018-06-27 01:32:54,912 [117  ] uthentication.JwtBearer.JwtBearerHandler - Successfully validated the token.
INFO  2018-06-27 01:32:54,918 [117  ] ore.Mvc.Internal.ControllerActionInvoker - Route matched with {area = "school", action = "GetAll", controller = "Leaves"}. Executing action Viewtance.School.Approvals.LeavesAppService.GetAll (Viewtance.School.Application)
INFO  2018-06-27 01:32:54,932 [117  ] ore.Mvc.Internal.ControllerActionInvoker - Executing action method Viewtance.School.Approvals.LeavesAppService.GetAll (Viewtance.School.Application) with arguments (Viewtance.School.Approvals.Dtos.GetAllLeavesInput) - Validation state: Valid
  • User Avatar
    0
    ismcagdas created
    Support Team

    @trendline does this happen only for specific actions or is it random ?

  • User Avatar
    0
    trendline created

    It is a random behavior, without a specified duration or a concurrency request, it also not happened on a specified action, sometimes I am visiting a very simple action it also could lose response then the whole application seems dead.

  • User Avatar
    0
    trendline created

    Does it related to IdentityServer4 settings? IdentityServer4 settings enabled by default, and all the configuration are also default from the template.

  • User Avatar
    0
    ismcagdas created
    Support Team

    @trendline I'm not sure. You can disable it if you are not using it and see if it works.

    This might be related to your database as well. You can check your database logs to see if there are any problems.

  • User Avatar
    0
    trendline created

    I deployed the application to another server with a new database, it happened again, it really is a confused problem, make me crazy.

  • User Avatar
    0
    trendline created

    Anybody who can give me a favor on this issue?

  • User Avatar
    0
    ismcagdas created
    Support Team

    @trendline since there is no pattern for this problem, it is hard to identify it. Have you checked windows logs, IIS logs ? There might be some useful information on those logs.

  • User Avatar
    0
    trendline created

    @ismcagdas

    There are no exception record from windows/IIS logs, they seems works fine.

    The odd behavior is: The lost response happened on tenant site, then the host site works fine.

    On the tenant site the SigalR feature coud works fine during the lost response duration.

    On the client it always waiting from server, if we kill the dotnet.exe process then the client will get cannot retrieve message from upstream server immediately, if we kill the w3p.exe then both dotnet.exe and w3p.exe will restart.

    Furthermore, all of the time, not exception record found in the application logs.

  • User Avatar
    0
    alper created
    Support Team

    you can check the HTTP data traffic with WireShark in server. I guess your request headers are being trimmed. Some routers or firewalls in enterprise networks do that kind of things. Especially when used custom headers, NGINX removes in production (while it allows in development mode)

  • User Avatar
    0
    trendline created

    It should not that case, during the lost response duration, the application logs could record the inbound request, it received the request and route to controller and action, but cannot response to client.

  • User Avatar
    0
    trendline created

    @ismcagdas Could you help me to resolve this issue via TeamViewer when you have time?

  • User Avatar
    0
    alper created
    Support Team

    I am not saying request is completely denied by the routers, it removes some custom headers. If your project works on your development environment and doesn't work on the production this is mostly an environment problem which is kinda out of private support.

  • User Avatar
    0
    trendline created

    @alper, I have changed 2 different servers, they have the same issue in production environment, it maybe related to ABP framework, it only happened in release environment and not always happing.

  • User Avatar
    0
    ismcagdas created
    Support Team

    Hi @trendline,

    Sorry for the late response.

    1. Can we reproduce it if we install it locally on one of our machines ? Event if we don't use it but leave it run for one or two days ?
    2. If so, could you share your project via email including the log files on the server ?

    If not, we can think of something else.

  • User Avatar
    0
    trendline created

    I deployed one copy on another server, if don't use it, it works fine, once visit the application it is online.

    I will send to you my code and the logs on the server.

  • User Avatar
    0
    trendline created

    Any suggestion? It still happening, tenant site lost response, but host site works, then if clean the browser cookie Host site will also lost response.

    I think this is related to ABP tenancy, maybe cookie related?

  • User Avatar
    0
    maliming created
    Support Team

    The point is that you need to reproduce this error. Otherwise it is difficult to figure out what happened.

    You can reply to me in Chinese.

  • User Avatar
    0
    trendline created

    我已经加你的QQ了，看到的时候通过一下，下次再发生这种情况的时候，麻烦你在线指导一下，咱们都在一个时区与工作时间内，比较容易沟通，非常感谢。

  • User Avatar
    0
    trendline created

    As below code mentioned, from 16:30 the services work fine, but at 16:38 the services lost response, it keep the status until 16:49 then I restarted the application.

    INFO  2018-07-13 16:30:57,819 [76   ] ore.Mvc.Internal.ControllerActionInvoker - Executed action method Viewtance.SRP.Web.Areas.App.Controllers.DashboardController.Index (Viewtance.SRP.Web.Mvc), returned result Microsoft.AspNetCore.Mvc.ViewResult in 0.0131ms.
INFO  2018-07-13 16:30:57,826 [76   ] Core.Mvc.ViewFeatures.ViewResultExecutor - Executing ViewResult, running view Index.
DEBUG 2018-07-13 16:31:04,956 [102  ] Viewtance.SRP.Web.Chat.SignalR.ChatHub   - A client is disconnected: ty0wZ_0U61OgP8MWpq4dLw
INFO  2018-07-13 16:31:04,957 [102  ] soft.AspNetCore.Hosting.Internal.WebHost - Request finished in 5128581.7246ms 101 
INFO  2018-07-13 16:31:05,618 [102  ] soft.AspNetCore.Hosting.Internal.WebHost - Request starting HTTP/1.1 GET http://jnyk.viewtance.tech/School/Students  
INFO  2018-07-13 16:31:05,679 [102  ] ore.Mvc.Internal.ControllerActionInvoker - Route matched with {area = "School", action = "Index", controller = "Students"}. Executing action Viewtance.SRP.Web.Areas.School.Controllers.StudentsController.Index (Viewtance.SRP.Web.Mvc)
INFO  2018-07-13 16:31:05,700 [102  ] uthorization.DefaultAuthorizationService - Authorization was successful.
INFO  2018-07-13 16:31:05,713 [102  ] ore.Mvc.Internal.ControllerActionInvoker - Executing action method Viewtance.SRP.Web.Areas.School.Controllers.StudentsController.Index (Viewtance.SRP.Web.Mvc) - Validation state: Valid
INFO  2018-07-13 16:31:15,641 [107  ] soft.AspNetCore.Hosting.Internal.WebHost - Request starting HTTP/1.1 GET http://jnyk.viewtance.tech/School/Students  
INFO  2018-07-13 16:31:15,667 [107  ] ore.Mvc.Internal.ControllerActionInvoker - Route matched with {area = "School", action = "Index", controller = "Students"}. Executing action Viewtance.SRP.Web.Areas.School.Controllers.StudentsController.Index (Viewtance.SRP.Web.Mvc)
INFO  2018-07-13 16:31:15,668 [107  ] uthorization.DefaultAuthorizationService - Authorization was successful.
INFO  2018-07-13 16:31:15,680 [107  ] ore.Mvc.Internal.ControllerActionInvoker - Executing action method Viewtance.SRP.Web.Areas.School.Controllers.StudentsController.Index (Viewtance.SRP.Web.Mvc) - Validation state: Valid
INFO  2018-07-13 16:31:18,139 [103  ] soft.AspNetCore.Hosting.Internal.WebHost - Request starting HTTP/1.1 GET http://www.viewtance.tech/  
INFO  2018-07-13 16:31:18,147 [103  ] ore.Mvc.Internal.ControllerActionInvoker - Route matched with {action = "Index", controller = "Home", area = ""}. Executing action Viewtance.SRP.Web.Controllers.HomeController.Index (Viewtance.SRP.Web.Mvc)
INFO  2018-07-13 16:31:18,148 [103  ] ore.Mvc.Internal.ControllerActionInvoker - Executing action method Viewtance.SRP.Web.Controllers.HomeController.Index (Viewtance.SRP.Web.Mvc) with arguments (, False) - Validation state: Valid
INFO  2018-07-13 16:31:18,148 [103  ] ore.Mvc.Internal.ControllerActionInvoker - Executed action method Viewtance.SRP.Web.Controllers.HomeController.Index (Viewtance.SRP.Web.Mvc), returned result Microsoft.AspNetCore.Mvc.RedirectToActionResult in 0.0241ms.
INFO  2018-07-13 16:31:18,165 [103  ] ft.AspNetCore.Mvc.RedirectToActionResult - Executing RedirectResult, redirecting to /App.
INFO  2018-07-13 16:31:18,166 [103  ] ore.Mvc.Internal.ControllerActionInvoker - Executed action Viewtance.SRP.Web.Controllers.HomeController.Index (Viewtance.SRP.Web.Mvc) in 18.9194ms
INFO  2018-07-13 16:31:18,166 [103  ] soft.AspNetCore.Hosting.Internal.WebHost - Request finished in 26.3525ms 302 
INFO  2018-07-13 16:31:18,219 [103  ] soft.AspNetCore.Hosting.Internal.WebHost - Request starting HTTP/1.1 GET http://www.viewtance.tech/App  
INFO  2018-07-13 16:31:18,226 [103  ] ore.Mvc.Internal.ControllerActionInvoker - Route matched with {area = "App", action = "Index", controller = "Home"}. Executing action Viewtance.SRP.Web.Areas.App.Controllers.HomeController.Index (Viewtance.SRP.Web.Mvc)
INFO  2018-07-13 16:31:18,227 [103  ] uthorization.DefaultAuthorizationService - Authorization was successful.
INFO  2018-07-13 16:31:18,227 [103  ] ore.Mvc.Internal.ControllerActionInvoker - Executing action method Viewtance.SRP.Web.Areas.App.Controllers.HomeController.Index (Viewtance.SRP.Web.Mvc) - Validation state: Valid
INFO  2018-07-13 16:31:18,228 [103  ] ore.Mvc.Internal.ControllerActionInvoker - Executed action method Viewtance.SRP.Web.Areas.App.Controllers.HomeController.Index (Viewtance.SRP.Web.Mvc), returned result Microsoft.AspNetCore.Mvc.RedirectToActionResult in 0.2199ms.
INFO  2018-07-13 16:31:18,237 [103  ] ft.AspNetCore.Mvc.RedirectToActionResult - Executing RedirectResult, redirecting to /App/HostDashboard.
INFO  2018-07-13 16:31:18,237 [103  ] ore.Mvc.Internal.ControllerActionInvoker - Executed action Viewtance.SRP.Web.Areas.App.Controllers.HomeController.Index (Viewtance.SRP.Web.Mvc) in 10.8484ms
INFO  2018-07-13 16:31:18,237 [103  ] soft.AspNetCore.Hosting.Internal.WebHost - Request finished in 17.9599ms 302 
INFO  2018-07-13 16:31:38,301 [91   ] soft.AspNetCore.Hosting.Internal.WebHost - Request starting HTTP/1.1 GET http://www.viewtance.tech/App/HostDashboard  
INFO  2018-07-13 16:31:38,309 [91   ] ore.Mvc.Internal.ControllerActionInvoker - Route matched with {area = "App", action = "Index", controller = "HostDashboard"}. Executing action Viewtance.SRP.Web.Areas.App.Controllers.HostDashboardController.Index (Viewtance.SRP.Web.Mvc)
INFO  2018-07-13 16:31:38,310 [91   ] uthorization.DefaultAuthorizationService - Authorization was successful.
INFO  2018-07-13 16:31:38,311 [91   ] ore.Mvc.Internal.ControllerActionInvoker - Executing action method Viewtance.SRP.Web.Areas.App.Controllers.HostDashboardController.Index (Viewtance.SRP.Web.Mvc) - Validation state: Valid
INFO  2018-07-13 16:31:38,311 [91   ] ore.Mvc.Internal.ControllerActionInvoker - Executed action method Viewtance.SRP.Web.Areas.App.Controllers.HostDashboardController.Index (Viewtance.SRP.Web.Mvc), returned result Microsoft.AspNetCore.Mvc.ViewResult in 0.0255ms.
INFO  2018-07-13 16:31:38,325 [41   ] Core.Mvc.ViewFeatures.ViewResultExecutor - Executing ViewResult, running view Index.
INFO  2018-07-13 16:32:36,239 [91   ] soft.AspNetCore.Hosting.Internal.WebHost - Request starting HTTP/1.1 GET http://jnyk.viewtance.tech/School/Students  
INFO  2018-07-13 16:32:36,267 [91   ] ore.Mvc.Internal.ControllerActionInvoker - Route matched with {area = "School", action = "Index", controller = "Students"}. Executing action Viewtance.SRP.Web.Areas.School.Controllers.StudentsController.Index (Viewtance.SRP.Web.Mvc)
INFO  2018-07-13 16:32:36,267 [91   ] uthorization.DefaultAuthorizationService - Authorization was successful.
INFO  2018-07-13 16:32:36,278 [91   ] ore.Mvc.Internal.ControllerActionInvoker - Executing action method Viewtance.SRP.Web.Areas.School.Controllers.StudentsController.Index (Viewtance.SRP.Web.Mvc) - Validation state: Valid
DEBUG 2018-07-13 16:34:22,933 [86   ] Viewtance.SRP.Web.Chat.SignalR.ChatHub   - A client is disconnected: 4MtZEIi9Fc-9_TuXdgreeA
INFO  2018-07-13 16:34:22,934 [86   ] soft.AspNetCore.Hosting.Internal.WebHost - Request finished in 377446.8228ms 101 
INFO  2018-07-13 16:34:49,451 [86   ] soft.AspNetCore.Hosting.Internal.WebHost - Request starting HTTP/1.1 POST http://jnyk.viewtance.tech/signalr-chat/negotiate text/plain;charset=UTF-8 0
INFO  2018-07-13 16:34:49,458 [86   ] soft.AspNetCore.Hosting.Internal.WebHost - Request finished in 6.671ms 200 application/json
INFO  2018-07-13 16:34:52,557 [96   ] soft.AspNetCore.Hosting.Internal.WebHost - Request starting HTTP/1.1 GET http://jnyk.viewtance.tech/signalr-chat?id=Mx5FtDHAZ57kY5iMr4RhMQ  
INFO  2018-07-13 16:34:52,600 [96   ] .AspNetCore.SignalR.HubConnectionContext - Completed connection handshake. Using HubProtocol 'json'.
DEBUG 2018-07-13 16:34:52,612 [96   ] Viewtance.SRP.Web.Chat.SignalR.ChatHub   - A client is connected: {"ConnectionId":"Mx5FtDHAZ57kY5iMr4RhMQ","IpAddress":"1.198.22.195","TenantId":2,"UserId":1,"ConnectTime":"2018-07-13T16:34:52.606903+08:00","Properties":{}}
DEBUG 2018-07-13 16:38:32,942 [78   ] Viewtance.SRP.Web.Chat.SignalR.ChatHub   - A client is disconnected: 1l3J5pKOKsR6WPJ4R0n4WQ
INFO  2018-07-13 16:38:33,916 [78   ] soft.AspNetCore.Hosting.Internal.WebHost - Request finished in 977908.6658ms 101 
DEBUG 2018-07-13 16:38:37,944 [23   ] Viewtance.SRP.Web.Chat.SignalR.ChatHub   - A client is disconnected: Mx5FtDHAZ57kY5iMr4RhMQ
INFO  2018-07-13 16:38:37,945 [23   ] soft.AspNetCore.Hosting.Internal.WebHost - Request finished in 225382.1786ms 101 
INFO  2018-07-13 16:44:36,182 [82   ] soft.AspNetCore.Hosting.Internal.WebHost - Request starting HTTP/1.1 GET http://jnyk.viewtance.tech/  
INFO  2018-07-13 16:44:36,191 [82   ] ore.Mvc.Internal.ControllerActionInvoker - Route matched with {action = "Index", controller = "Home", area = ""}. Executing action Viewtance.SRP.Web.Controllers.HomeController.Index (Viewtance.SRP.Web.Mvc)
INFO  2018-07-13 16:44:36,192 [82   ] ore.Mvc.Internal.ControllerActionInvoker - Executing action method Viewtance.SRP.Web.Controllers.HomeController.Index (Viewtance.SRP.Web.Mvc) with arguments (, False) - Validation state: Valid
INFO  2018-07-13 16:44:36,192 [82   ] ore.Mvc.Internal.ControllerActionInvoker - Executed action method Viewtance.SRP.Web.Controllers.HomeController.Index (Viewtance.SRP.Web.Mvc), returned result Microsoft.AspNetCore.Mvc.RedirectToActionResult in 0.0268ms.
INFO  2018-07-13 16:44:36,209 [82   ] ft.AspNetCore.Mvc.RedirectToActionResult - Executing RedirectResult, redirecting to /App.
INFO  2018-07-13 16:44:36,209 [82   ] ore.Mvc.Internal.ControllerActionInvoker - Executed action Viewtance.SRP.Web.Controllers.HomeController.Index (Viewtance.SRP.Web.Mvc) in 18.1895ms
INFO  2018-07-13 16:44:36,209 [82   ] soft.AspNetCore.Hosting.Internal.WebHost - Request finished in 27.0485ms 302 
INFO  2018-07-13 16:44:36,247 [65   ] soft.AspNetCore.Hosting.Internal.WebHost - Request starting HTTP/1.1 GET http://jnyk.viewtance.tech/App  
INFO  2018-07-13 16:44:36,255 [65   ] ore.Mvc.Internal.ControllerActionInvoker - Route matched with {area = "App", action = "Index", controller = "Home"}. Executing action Viewtance.SRP.Web.Areas.App.Controllers.HomeController.Index (Viewtance.SRP.Web.Mvc)
INFO  2018-07-13 16:44:36,255 [65   ] uthorization.DefaultAuthorizationService - Authorization was successful.
INFO  2018-07-13 16:44:36,256 [65   ] ore.Mvc.Internal.ControllerActionInvoker - Executing action method Viewtance.SRP.Web.Areas.App.Controllers.HomeController.Index (Viewtance.SRP.Web.Mvc) - Validation state: Valid
INFO  2018-07-13 16:44:36,256 [65   ] ore.Mvc.Internal.ControllerActionInvoker - Executed action method Viewtance.SRP.Web.Areas.App.Controllers.HomeController.Index (Viewtance.SRP.Web.Mvc), returned result Microsoft.AspNetCore.Mvc.RedirectToActionResult in 0.2366ms.
INFO  2018-07-13 16:44:36,264 [82   ] ft.AspNetCore.Mvc.RedirectToActionResult - Executing RedirectResult, redirecting to /App/Dashboard.
INFO  2018-07-13 16:44:36,265 [82   ] ore.Mvc.Internal.ControllerActionInvoker - Executed action Viewtance.SRP.Web.Areas.App.Controllers.HomeController.Index (Viewtance.SRP.Web.Mvc) in 9.7314ms
INFO  2018-07-13 16:44:36,265 [82   ] soft.AspNetCore.Hosting.Internal.WebHost - Request finished in 17.6801ms 302 
INFO  2018-07-13 16:44:39,695 [65   ] soft.AspNetCore.Hosting.Internal.WebHost - Request starting HTTP/1.1 GET http://jnyk.viewtance.tech/  
INFO  2018-07-13 16:44:39,703 [65   ] ore.Mvc.Internal.ControllerActionInvoker - Route matched with {action = "Index", controller = "Home", area = ""}. Executing action Viewtance.SRP.Web.Controllers.HomeController.Index (Viewtance.SRP.Web.Mvc)
INFO  2018-07-13 16:44:39,705 [65   ] ore.Mvc.Internal.ControllerActionInvoker - Executing action method Viewtance.SRP.Web.Controllers.HomeController.Index (Viewtance.SRP.Web.Mvc) with arguments (, False) - Validation state: Valid
INFO  2018-07-13 16:44:39,705 [65   ] ore.Mvc.Internal.ControllerActionInvoker - Executed action method Viewtance.SRP.Web.Controllers.HomeController.Index (Viewtance.SRP.Web.Mvc), returned result Microsoft.AspNetCore.Mvc.RedirectToActionResult in 0.0263ms.
INFO  2018-07-13 16:44:39,716 [65   ] ft.AspNetCore.Mvc.RedirectToActionResult - Executing RedirectResult, redirecting to /App.
INFO  2018-07-13 16:44:39,716 [65   ] ore.Mvc.Internal.ControllerActionInvoker - Executed action Viewtance.SRP.Web.Controllers.HomeController.Index (Viewtance.SRP.Web.Mvc) in 12.603ms
INFO  2018-07-13 16:44:39,716 [65   ] soft.AspNetCore.Hosting.Internal.WebHost - Request finished in 21.6656ms 302 
INFO  2018-07-13 16:44:40,421 [65   ] soft.AspNetCore.Hosting.Internal.WebHost - Request starting HTTP/1.1 GET http://jnyk.viewtance.tech/App  
INFO  2018-07-13 16:44:40,429 [65   ] ore.Mvc.Internal.ControllerActionInvoker - Route matched with {area = "App", action = "Index", controller = "Home"}. Executing action Viewtance.SRP.Web.Areas.App.Controllers.HomeController.Index (Viewtance.SRP.Web.Mvc)
INFO  2018-07-13 16:44:40,429 [65   ] uthorization.DefaultAuthorizationService - Authorization was successful.
INFO  2018-07-13 16:44:40,430 [65   ] ore.Mvc.Internal.ControllerActionInvoker - Executing action method Viewtance.SRP.Web.Areas.App.Controllers.HomeController.Index (Viewtance.SRP.Web.Mvc) - Validation state: Valid
INFO  2018-07-13 16:44:40,431 [65   ] ore.Mvc.Internal.ControllerActionInvoker - Executed action method Viewtance.SRP.Web.Areas.App.Controllers.HomeController.Index (Viewtance.SRP.Web.Mvc), returned result Microsoft.AspNetCore.Mvc.RedirectToActionResult in 0.2476ms.
INFO  2018-07-13 16:44:40,440 [65   ] ft.AspNetCore.Mvc.RedirectToActionResult - Executing RedirectResult, redirecting to /App/Dashboard.
INFO  2018-07-13 16:44:40,440 [65   ] ore.Mvc.Internal.ControllerActionInvoker - Executed action Viewtance.SRP.Web.Areas.App.Controllers.HomeController.Index (Viewtance.SRP.Web.Mvc) in 11.4837ms
INFO  2018-07-13 16:44:40,441 [65   ] soft.AspNetCore.Hosting.Internal.WebHost - Request finished in 20.0444ms 302 
INFO  2018-07-13 16:44:56,318 [65   ] soft.AspNetCore.Hosting.Internal.WebHost - Request starting HTTP/1.1 GET http://jnyk.viewtance.tech/App/Dashboard  
INFO  2018-07-13 16:44:56,326 [65   ] ore.Mvc.Internal.ControllerActionInvoker - Route matched with {area = "App", action = "Index", controller = "Dashboard"}. Executing action Viewtance.SRP.Web.Areas.App.Controllers.DashboardController.Index (Viewtance.SRP.Web.Mvc)
INFO  2018-07-13 16:44:56,326 [65   ] uthorization.DefaultAuthorizationService - Authorization was successful.
INFO  2018-07-13 16:44:56,327 [65   ] ore.Mvc.Internal.ControllerActionInvoker - Executing action method Viewtance.SRP.Web.Areas.App.Controllers.DashboardController.Index (Viewtance.SRP.Web.Mvc) - Validation state: Valid
INFO  2018-07-13 16:44:56,327 [65   ] ore.Mvc.Internal.ControllerActionInvoker - Executed action method Viewtance.SRP.Web.Areas.App.Controllers.DashboardController.Index (Viewtance.SRP.Web.Mvc), returned result Microsoft.AspNetCore.Mvc.ViewResult in 0.0131ms.
INFO  2018-07-13 16:44:56,340 [65   ] Core.Mvc.ViewFeatures.ViewResultExecutor - Executing ViewResult, running view Index.
INFO  2018-07-13 16:45:01,111 [82   ] soft.AspNetCore.Hosting.Internal.WebHost - Request starting HTTP/1.1 GET http://jnyk.viewtance.tech/App/Dashboard  
INFO  2018-07-13 16:45:01,119 [82   ] ore.Mvc.Internal.ControllerActionInvoker - Route matched with {area = "App", action = "Index", controller = "Dashboard"}. Executing action Viewtance.SRP.Web.Areas.App.Controllers.DashboardController.Index (Viewtance.SRP.Web.Mvc)
INFO  2018-07-13 16:45:01,119 [82   ] uthorization.DefaultAuthorizationService - Authorization was successful.
INFO  2018-07-13 16:45:01,120 [82   ] ore.Mvc.Internal.ControllerActionInvoker - Executing action method Viewtance.SRP.Web.Areas.App.Controllers.DashboardController.Index (Viewtance.SRP.Web.Mvc) - Validation state: Valid
INFO  2018-07-13 16:45:01,120 [82   ] ore.Mvc.Internal.ControllerActionInvoker - Executed action method Viewtance.SRP.Web.Areas.App.Controllers.DashboardController.Index (Viewtance.SRP.Web.Mvc), returned result Microsoft.AspNetCore.Mvc.ViewResult in 0.0131ms.
INFO  2018-07-13 16:45:01,129 [82   ] Core.Mvc.ViewFeatures.ViewResultExecutor - Executing ViewResult, running view Index.
INFO  2018-07-13 16:47:42,857 [15   ] soft.AspNetCore.Hosting.Internal.WebHost - Request starting HTTP/1.1 GET http://jnyk.viewtance.tech/  
INFO  2018-07-13 16:47:42,864 [15   ] ore.Mvc.Internal.ControllerActionInvoker - Route matched with {action = "Index", controller = "Home", area = ""}. Executing action Viewtance.SRP.Web.Controllers.HomeController.Index (Viewtance.SRP.Web.Mvc)
INFO  2018-07-13 16:47:42,865 [15   ] ore.Mvc.Internal.ControllerActionInvoker - Executing action method Viewtance.SRP.Web.Controllers.HomeController.Index (Viewtance.SRP.Web.Mvc) with arguments (, False) - Validation state: Valid
INFO  2018-07-13 16:47:42,865 [15   ] ore.Mvc.Internal.ControllerActionInvoker - Executed action method Viewtance.SRP.Web.Controllers.HomeController.Index (Viewtance.SRP.Web.Mvc), returned result Microsoft.AspNetCore.Mvc.RedirectToActionResult in 0.0237ms.
INFO  2018-07-13 16:47:42,876 [15   ] ft.AspNetCore.Mvc.RedirectToActionResult - Executing RedirectResult, redirecting to /App.
INFO  2018-07-13 16:47:42,876 [15   ] ore.Mvc.Internal.ControllerActionInvoker - Executed action Viewtance.SRP.Web.Controllers.HomeController.Index (Viewtance.SRP.Web.Mvc) in 11.4195ms
INFO  2018-07-13 16:47:42,876 [15   ] soft.AspNetCore.Hosting.Internal.WebHost - Request finished in 19.4126ms 302 
INFO  2018-07-13 16:47:42,915 [12   ] soft.AspNetCore.Hosting.Internal.WebHost - Request starting HTTP/1.1 GET http://jnyk.viewtance.tech/App  
INFO  2018-07-13 16:47:42,924 [12   ] ore.Mvc.Internal.ControllerActionInvoker - Route matched with {area = "App", action = "Index", controller = "Home"}. Executing action Viewtance.SRP.Web.Areas.App.Controllers.HomeController.Index (Viewtance.SRP.Web.Mvc)
INFO  2018-07-13 16:47:42,924 [12   ] uthorization.DefaultAuthorizationService - Authorization was successful.
INFO  2018-07-13 16:47:42,925 [12   ] ore.Mvc.Internal.ControllerActionInvoker - Executing action method Viewtance.SRP.Web.Areas.App.Controllers.HomeController.Index (Viewtance.SRP.Web.Mvc) - Validation state: Valid
INFO  2018-07-13 16:47:42,926 [12   ] ore.Mvc.Internal.ControllerActionInvoker - Executed action method Viewtance.SRP.Web.Areas.App.Controllers.HomeController.Index (Viewtance.SRP.Web.Mvc), returned result Microsoft.AspNetCore.Mvc.RedirectToActionResult in 0.2802ms.
INFO  2018-07-13 16:47:42,935 [15   ] ft.AspNetCore.Mvc.RedirectToActionResult - Executing RedirectResult, redirecting to /App/Dashboard.
INFO  2018-07-13 16:47:42,935 [15   ] ore.Mvc.Internal.ControllerActionInvoker - Executed action Viewtance.SRP.Web.Areas.App.Controllers.HomeController.Index (Viewtance.SRP.Web.Mvc) in 11.3618ms
INFO  2018-07-13 16:47:42,936 [15   ] soft.AspNetCore.Hosting.Internal.WebHost - Request finished in 20.3603ms 302 
INFO  2018-07-13 16:47:42,976 [12   ] soft.AspNetCore.Hosting.Internal.WebHost - Request starting HTTP/1.1 GET http://jnyk.viewtance.tech/App/Dashboard  
INFO  2018-07-13 16:47:42,984 [12   ] ore.Mvc.Internal.ControllerActionInvoker - Route matched with {area = "App", action = "Index", controller = "Dashboard"}. Executing action Viewtance.SRP.Web.Areas.App.Controllers.DashboardController.Index (Viewtance.SRP.Web.Mvc)
INFO  2018-07-13 16:47:42,985 [12   ] uthorization.DefaultAuthorizationService - Authorization was successful.
INFO  2018-07-13 16:47:42,986 [12   ] ore.Mvc.Internal.ControllerActionInvoker - Executing action method Viewtance.SRP.Web.Areas.App.Controllers.DashboardController.Index (Viewtance.SRP.Web.Mvc) - Validation state: Valid
INFO  2018-07-13 16:47:42,986 [12   ] ore.Mvc.Internal.ControllerActionInvoker - Executed action method Viewtance.SRP.Web.Areas.App.Controllers.DashboardController.Index (Viewtance.SRP.Web.Mvc), returned result Microsoft.AspNetCore.Mvc.ViewResult in 0.0272ms.
INFO  2018-07-13 16:47:42,995 [10   ] Core.Mvc.ViewFeatures.ViewResultExecutor - Executing ViewResult, running view Index.
DEBUG 2018-07-13 16:49:33,140 [1    ] Abp.Modules.AbpModuleManager             - Loading Abp modules...
DEBUG 2018-07-13 16:49:33,178 [1    ] Abp.Modules.AbpModuleManager             - Found 34 ABP modules in total.
DEBUG 2018-07-13 16:49:33,251 [1    ] Abp.Modules.AbpModuleManager             - Loaded module: Viewtance.SRP.Web.Startup.SRPWebMvcModule, Viewtance.SRP.Web.Mvc, Version=5.0.0.0, Culture=neutral, PublicKeyToken=null
DEBUG 2018-07-13 16:49:33,256 [1    ] Abp.Modules.AbpModuleManager             - Loaded module: Viewtance.SRP.Web.SRPWebCoreModule, Viewtance.SRP.Web.Core, Version=5.0.0.0, Culture=neutral, PublicKeyToken=null
DEBUG 2018-07-13 16:49:33,257 [1    ] Abp.Modules.AbpModuleManager             - Loaded module: Viewtance.FM.FMApplicationModule, Viewtance.FM.Application, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null
DEBUG 2018-07-13 16:49:33,257 [1    ] Abp.Modules.AbpModuleManager             - Loaded module: Viewtance.FM.FMCoreModule, Viewtance.FM.Core, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null
DEBUG 2018-07-13 16:49:33,257 [1    ] Abp.Modules.AbpModuleManager             - Loaded module: Abp.Zero.AbpZeroCoreModule, Abp.ZeroCore, Version=3.7.2.0, Culture=neutral, PublicKeyToken=null
DEBUG 2018-07-13 16:49:33,258 [1    ] Abp.Modules.AbpModuleManager             - Loaded module: Abp.Zero.AbpZeroCommonModule, Abp.Zero.Common, Version=3.7.2.0, Culture=neutral, PublicKeyToken=null
DEBUG 2018-07-13 16:49:33,258 [1    ] Abp.Modules.AbpModuleManager             - Loaded module: Abp.AbpKernelModule, Abp, Version=3.7.2.0, Culture=neutral, PublicKeyToken=null
DEBUG 2018-07-13 16:49:33,258 [1    ] Abp.Modules.AbpModuleManager             - Loaded module: Abp.Zero.Ldap.AbpZeroLdapModule, Abp.Zero.Ldap, Version=3.7.2.0, Culture=neutral, PublicKeyToken=null
DEBUG 2018-07-13 16:49:33,259 [1    ] Abp.Modules.AbpModuleManager             - Loaded module: Abp.AutoMapper.AbpAutoMapperModule, Abp.AutoMapper, Version=3.7.2.0, Culture=neutral, PublicKeyToken=null
DEBUG 2018-07-13 16:49:33,259 [1    ] Abp.Modules.AbpModuleManager             - Loaded module: Abp.AspNetZeroCore.AbpAspNetZeroCoreModule, Abp.AspNetZeroCore, Version=1.1.3.0, Culture=neutral, PublicKeyToken=null
DEBUG 2018-07-13 16:49:33,260 [1    ] Abp.Modules.AbpModuleManager             - Loaded module: Abp.MailKit.AbpMailKitModule, Abp.MailKit, Version=3.7.2.0, Culture=neutral, PublicKeyToken=null
DEBUG 2018-07-13 16:49:33,260 [1    ] Abp.Modules.AbpModuleManager             - Loaded module: Viewtance.CRM.CRMApplicationModule, Viewtance.CRM.Application, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null
DEBUG 2018-07-13 16:49:33,260 [1    ] Abp.Modules.AbpModuleManager             - Loaded module: Viewtance.CRM.CRMCoreModule, Viewtance.CRM.Core, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null
DEBUG 2018-07-13 16:49:33,260 [1    ] Abp.Modules.AbpModuleManager             - Loaded module: Viewtance.School.SchoolApplicationModule, Viewtance.School.Application, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null
DEBUG 2018-07-13 16:49:33,261 [1    ] Abp.Modules.AbpModuleManager             - Loaded module: Viewtance.School.SchoolCoreModule, Viewtance.School.Core, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null
DEBUG 2018-07-13 16:49:33,261 [1    ] Abp.Modules.AbpModuleManager             - Loaded module: Viewtance.GA.GAApplicationModule, Viewtance.GA.Application, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null
DEBUG 2018-07-13 16:49:33,261 [1    ] Abp.Modules.AbpModuleManager             - Loaded module: Viewtance.GA.GACoreModule, Viewtance.GA.Core, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null
DEBUG 2018-07-13 16:49:33,262 [1    ] Abp.Modules.AbpModuleManager             - Loaded module: Viewtance.Teaching.TeachingApplicationModule, Viewtance.Teaching.Application, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null
DEBUG 2018-07-13 16:49:33,262 [1    ] Abp.Modules.AbpModuleManager             - Loaded module: Viewtance.Teaching.TeachingCoreModule, Viewtance.Teaching.Core, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null
DEBUG 2018-07-13 16:49:33,262 [1    ] Abp.Modules.AbpModuleManager             - Loaded module: Viewtance.SRP.SRPApplicationModule, Viewtance.SRP.Application, Version=5.0.0.0, Culture=neutral, PublicKeyToken=null
DEBUG 2018-07-13 16:49:33,263 [1    ] Abp.Modules.AbpModuleManager             - Loaded module: Viewtance.SRP.SRPCoreModule, Viewtance.SRP.Core, Version=5.0.0.0, Culture=neutral, PublicKeyToken=null
DEBUG 2018-07-13 16:49:33,263 [1    ] Abp.Modules.AbpModuleManager             - Loaded module: Viewtance.SRP.EntityFrameworkCore.SRPEntityFrameworkCoreModule, Viewtance.SRP.EntityFrameworkCore, Version=5.0.0.0, Culture=neutral, PublicKeyToken=null
DEBUG 2018-07-13 16:49:33,263 [1    ] Abp.Modules.AbpModuleManager             - Loaded module: Abp.Zero.EntityFrameworkCore.AbpZeroCoreEntityFrameworkCoreModule, Abp.ZeroCore.EntityFrameworkCore, Version=3.7.2.0, Culture=neutral, PublicKeyToken=null
DEBUG 2018-07-13 16:49:33,264 [1    ] Abp.Modules.AbpModuleManager             - Loaded module: Abp.EntityFrameworkCore.AbpEntityFrameworkCoreModule, Abp.EntityFrameworkCore, Version=3.7.2.0, Culture=neutral, PublicKeyToken=null
DEBUG 2018-07-13 16:49:33,264 [1    ] Abp.Modules.AbpModuleManager             - Loaded module: Abp.EntityFramework.AbpEntityFrameworkCommonModule, Abp.EntityFramework.Common, Version=3.7.2.0, Culture=neutral, PublicKeyToken=null
DEBUG 2018-07-13 16:49:33,265 [1    ] Abp.Modules.AbpModuleManager             - Loaded module: Abp.Dapper.AbpDapperModule, Abp.Dapper, Version=3.7.2.0, Culture=neutral, PublicKeyToken=null
DEBUG 2018-07-13 16:49:33,265 [1    ] Abp.Modules.AbpModuleManager             - Loaded module: Abp.IdentityServer4.AbpZeroCoreIdentityServerEntityFrameworkCoreModule, Abp.ZeroCore.IdentityServer4.EntityFrameworkCore, Version=3.7.2.0, Culture=neutral, PublicKeyToken=null
DEBUG 2018-07-13 16:49:33,266 [1    ] Abp.Modules.AbpModuleManager             - Loaded module: Abp.IdentityServer4.AbpZeroCoreIdentityServerModule, Abp.ZeroCore.IdentityServer4, Version=3.7.2.0, Culture=neutral, PublicKeyToken=null
DEBUG 2018-07-13 16:49:33,266 [1    ] Abp.Modules.AbpModuleManager             - Loaded module: Abp.AspNetZeroCore.Web.AbpAspNetZeroCoreWebModule, Abp.AspNetZeroCore.Web, Version=1.1.3.0, Culture=neutral, PublicKeyToken=null
DEBUG 2018-07-13 16:49:33,266 [1    ] Abp.Modules.AbpModuleManager             - Loaded module: Abp.AspNetCore.AbpAspNetCoreModule, Abp.AspNetCore, Version=3.7.2.0, Culture=neutral, PublicKeyToken=null
DEBUG 2018-07-13 16:49:33,266 [1    ] Abp.Modules.AbpModuleManager             - Loaded module: Abp.Web.AbpWebCommonModule, Abp.Web.Common, Version=3.7.2.0, Culture=neutral, PublicKeyToken=null
DEBUG 2018-07-13 16:49:33,267 [1    ] Abp.Modules.AbpModuleManager             - Loaded module: Abp.AspNetCore.SignalR.AbpAspNetCoreSignalRModule, Abp.AspNetCore.SignalR, Version=3.7.2.0, Culture=neutral, PublicKeyToken=null
DEBUG 2018-07-13 16:49:33,267 [1    ] Abp.Modules.AbpModuleManager             - Loaded module: Abp.Runtime.Caching.Redis.AbpRedisCacheModule, Abp.RedisCache, Version=3.7.2.0, Culture=neutral, PublicKeyToken=null
DEBUG 2018-07-13 16:49:33,267 [1    ] Abp.Modules.AbpModuleManager             - Loaded module: Abp.Hangfire.AbpHangfireAspNetCoreModule, Abp.HangFire.AspNetCore, Version=3.7.2.0, Culture=neutral, PublicKeyToken=null
DEBUG 2018-07-13 16:49:33,272 [1    ] Abp.Modules.AbpModuleManager             - 34 modules loaded.
  • User Avatar
    0
    maliming created
    Support Team

    Turning Microsoft's log level to Debug or Trace may reveal more information.

  • User Avatar
    0
    trendline created

    Log settings on IIS?

  • User Avatar
    0
    maliming created
    Support Team

    [https://docs.microsoft.com/zh-cn/aspnet/core/fundamentals/logging/?view=aspnetcore-2.1#settings-file-configuration])

    "System": "Information" "Microsoft": "Information"

    Modify the System and Microsoft log levels.

  • User Avatar
    0
    trendline created

    Is this logging setting could make ABP logs more detail? BTW, I have sent a request to your QQ, please check.

  • User Avatar
    0
    maliming created
    Support Team

    Can make information about Microsoft related components very rich to help debug. My qq answer can be filled in at will.

  • User Avatar
    0
    trendline created

    我还没有看到你的回复，或者你可以加一下我的QQ，我的qq是286285280

  • User Avatar
    0
    trendline created

    It seems related to User login expired, every time the logs record below exception, the application start lose response

    Abp.Authorization.AbpAuthorizationException: [Current user did not login to the application]
   at Abp.Authorization.AuthorizationHelper.AuthorizeAsync(IEnumerable`1 authorizeAttributes)
   at Abp.Authorization.AuthorizationHelper.CheckPermissions(MethodInfo methodInfo, Type type)
   at Abp.Authorization.AuthorizationHelper.AuthorizeAsync(MethodInfo methodInfo, Type type)
   at Abp.AspNetCore.Mvc.Authorization.AbpAuthorizationFilter.OnAuthorizationAsync(AuthorizationFilterContext context)
Abp.Authorization.AbpAuthorizationException: [Current user did not login to the application]
   at Abp.Authorization.AuthorizationHelper.AuthorizeAsync(IEnumerable`1 authorizeAttributes)
   at Abp.Authorization.AuthorizationHelper.CheckPermissions(MethodInfo methodInfo, Type type)
   at Abp.Authorization.AuthorizationHelper.AuthorizeAsync(MethodInfo methodInfo, Type type)
   at Abp.AspNetCore.Mvc.Authorization.AbpAuthorizationFilter.OnAuthorizationAsync(AuthorizationFilterContext context)
  • User Avatar
    0
    trendline created

    Any suggestion? Anybody who can Help me? It seems caused by AbpSession timeout, then no redirect login could reach.

Assignee
No one
Labels
Non yet