Manage Leaf timeouts

[artgoldberg]

Hello Leaf folks, @mh2727 and @jprosser

I'm running long queries (our CDM isn't properly indexed yet). They're all timing out at 60 sec.

To increase timeouts I've set both of the appsettings timeouts to 600 sec:

"Db": {
  "App": {
    "Connection": "LEAF_APP_DB",
    "DefaultTimeout": 600
  },
  "Clin": {
    "Connection": "LEAF_CLIN_DB",
    "DefaultTimeout": 600,
    "Cohort": {
      "QueryStrategy": "CTE",
      "MaxParallelThreads": 5
    }
  }
},

However, this had no observable effect. I also searched for "timeout" in the Leaf docs repo and didn't find any other settings to adjust.

These are the Leaf log entries that occur from the start of the query to the timeout. The last couple show the 60,000 ms query. And the record at "Timestamp":"2021-06-23T12:18:29.7189804-04:00" reports "Error","MessageTemplate":"Failed to execute query. Error:{Error}","Properties":{"Error":"System.Data.SqlClient.SqlException (0x80131904): A severe error occurred on the current command.

{"Timestamp":"2021-06-23T12:17:27.4005762-04:00","Level":"Information","MessageTemplate":"{HostingRequestStartingLog:l}","Properties":{"Protocol":"HTTP/1.1","Method":"GET","ContentType":null,"ContentLength":null,"Scheme":"http","Host":"10.95.46.180:5001","PathBase":"","Path":"/api/user/refresh","QueryString":"","HostingRequestStartingLog":"Request starting HTTP/1.1 GET http://10.95.46.180:5001/api/user/refresh  ","EventId":{"Id":1},"SourceContext":"Microsoft.AspNetCore.Hosting.Diagnostics","RequestId":"0HM9MBOQFA7T4:00000001","RequestPath":"/api/user/refresh","SpanId":"|274960c2-4d6b727c8f984133.","TraceId":"274960c2-4d6b727c8f984133","ParentId":"","ConnectionId":"0HM9MBOQFA7T4"},"Renderings":{"HostingRequestStartingLog":[{"Format":"l","Rendering":"Request starting HTTP/1.1 GET http://10.95.46.180:5001/api/user/refresh  "}]}}
{"Timestamp":"2021-06-23T12:17:27.4021748-04:00","Level":"Information","MessageTemplate":"Successfully validated the token.","Properties":{"EventId":{"Id":2,"Name":"TokenValidationSucceeded"},"SourceContext":"Microsoft.AspNetCore.Authentication.JwtBearer.JwtBearerHandler","RequestId":"0HM9MBOQFA7T4:00000001","RequestPath":"/api/user/refresh","SpanId":"|274960c2-4d6b727c8f984133.","TraceId":"274960c2-4d6b727c8f984133","ParentId":"","ConnectionId":"0HM9MBOQFA7T4"}}
{"Timestamp":"2021-06-23T12:17:27.4028893-04:00","Level":"Information","MessageTemplate":"Route matched with {RouteData}. Executing controller action with signature {MethodInfo} on controller {Controller} ({AssemblyName}).","Properties":{"RouteData":"{action = \"Refresh\", controller = \"User\"}","MethodInfo":"Microsoft.AspNetCore.Mvc.ActionResult`1[API.DTO.User.AccessTokenDTO] Refresh(Model.Authentication.ITokenBlacklistCache)","Controller":"API.Controllers.UserController","AssemblyName":"API","EventId":{"Id":3,"Name":"ControllerActionExecuting"},"SourceContext":"Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker","ActionId":"da90c4b0-9628-4fbe-a772-23c09a86e2fb","ActionName":"API.Controllers.UserController.Refresh (API)","RequestId":"0HM9MBOQFA7T4:00000001","RequestPath":"/api/user/refresh","SpanId":"|274960c2-4d6b727c8f984133.","TraceId":"274960c2-4d6b727c8f984133","ParentId":"","ConnectionId":"0HM9MBOQFA7T4","SessionId":"105e9736-208a-4888-85c2-b66de96f6c00","User":"[email protected]@urn:leaf:issuer:leaf.mssm.edu"}}
{"Timestamp":"2021-06-23T12:17:27.4032143-04:00","Level":"Information","MessageTemplate":"Authorization was successful.","Properties":{"EventId":{"Id":1,"Name":"UserAuthorizationSucceeded"},"SourceContext":"Microsoft.AspNetCore.Authorization.DefaultAuthorizationService","ActionId":"da90c4b0-9628-4fbe-a772-23c09a86e2fb","ActionName":"API.Controllers.UserController.Refresh (API)","RequestId":"0HM9MBOQFA7T4:00000001","RequestPath":"/api/user/refresh","SpanId":"|274960c2-4d6b727c8f984133.","TraceId":"274960c2-4d6b727c8f984133","ParentId":"","ConnectionId":"0HM9MBOQFA7T4","SessionId":"105e9736-208a-4888-85c2-b66de96f6c00","User":"[email protected]@urn:leaf:issuer:leaf.mssm.edu"}}
{"Timestamp":"2021-06-23T12:17:27.4115340-04:00","Level":"Information","MessageTemplate":"Refreshed Access Token. Token:{Token}","Properties":{"Token":"eyJhbGciOiJodHRwOi8vd3d3LnczLm9yZy8yMDAxLzA0L3htbGRzaWctbW9yZSNyc2Etc2hhNTEyIiwia2lkIjoiMkQ3NjczMjJDMDY5RUMxQUEwNjM4MEM2RUMzMDFFMUE4RkI2MzZGMCIsInR5cCI6IkpXVCJ9.eyJodHRwOi8vc2NoZW1hcy54bWxzb2FwLm9yZy93cy8yMDA1LzA1L2lkZW50aXR5L2NsYWltcy9uYW1lIjoiYXJ0aHVyLnAuZ29sZGJlcmdAbXNzbS5lZHUiLCJhdWQiOiJ1cm46bGVhZjppc3N1ZXI6bGVhZi5tc3NtLmVkdSIsImlkLW5vbmNlIjoiNDZlNDE0MWMtMjg3YS00YTA3LTk2MzAtMDk4ZTU2NjAzYTU0IiwiYXV0aC10eXBlIjoiU2FtbDIiLCJsZWFmLXZlcnNpb24iOiIzLjkuMS4wIiwiaHR0cDovL3NjaGVtYXMubWljcm9zb2Z0LmNvbS93cy8yMDA4LzA2L2lkZW50aXR5L2NsYWltcy9yb2xlIjpbImFkbWluIiwicGhpIl0sImlzcyI6InVybjpsZWFmOmlzc3VlcjpsZWFmLm1zc20uZWR1IiwiYWNjZXNzLW5vbmNlIjoiMTA1ZTk3MzYtMjA4YS00ODg4LTg1YzItYjY2ZGU5NmY2YzAwIiwic2Vzc2lvbi10eXBlIjoicWkiLCJkYXRhLWNsYXNzIjoibm9pZCIsImlhdCI6IjE2MjQ0NjUwNDciLCJ0b2tlbi10eXBlIjoiYWNjZXNzLXRva2VuIiwiZXhwIjoxNjI0NDY1NDA3fQ.ePIOd1-59lZBJN3AyouwNYwcE-ZlOOD3kHr3a85vyxbNFz8qTz6EwtSzV1DFF_9sZzcxLb295bD_Xz8CWF_ypDNDqqk_UyUMahRSoiCGTcfdmCKQRJRgLGAXV4ItH6JLANpDfNrBVZviERHXuhH1_HqzcW9VSGxTNwurjcQ8n4uLMogSYNHbN6_9YL9-ZfYd0y2gQyvdjpPTQ-TgDwUSC5NU_t3_bmY4LPTScf6HGdioAO9Mqicttc2X8UDMrAI9Z1BhFJUrlnP9vMwJNoDSmU1hDxB28KTll2OQdwJEkXmIHwE0ppC8ELYdngccLgxO6V0l0PNMvAe_gJ4xYAVQ_A","SourceContext":"API.Controllers.UserController","ActionId":"da90c4b0-9628-4fbe-a772-23c09a86e2fb","ActionName":"API.Controllers.UserController.Refresh (API)","RequestId":"0HM9MBOQFA7T4:00000001","RequestPath":"/api/user/refresh","SpanId":"|274960c2-4d6b727c8f984133.","TraceId":"274960c2-4d6b727c8f984133","ParentId":"","ConnectionId":"0HM9MBOQFA7T4","SessionId":"105e9736-208a-4888-85c2-b66de96f6c00","User":"[email protected]@urn:leaf:issuer:leaf.mssm.edu"}}
{"Timestamp":"2021-06-23T12:17:27.4119353-04:00","Level":"Information","MessageTemplate":"Executing ObjectResult, writing value of type '{Type}'.","Properties":{"Type":"API.DTO.User.AccessTokenDTO","EventId":{"Id":1,"Name":"ObjectResultExecuting"},"SourceContext":"Microsoft.AspNetCore.Mvc.Infrastructure.ObjectResultExecutor","ActionId":"da90c4b0-9628-4fbe-a772-23c09a86e2fb","ActionName":"API.Controllers.UserController.Refresh (API)","RequestId":"0HM9MBOQFA7T4:00000001","RequestPath":"/api/user/refresh","SpanId":"|274960c2-4d6b727c8f984133.","TraceId":"274960c2-4d6b727c8f984133","ParentId":"","ConnectionId":"0HM9MBOQFA7T4","SessionId":"105e9736-208a-4888-85c2-b66de96f6c00","User":"[email protected]@urn:leaf:issuer:leaf.mssm.edu"}}
{"Timestamp":"2021-06-23T12:17:27.4127225-04:00","Level":"Information","MessageTemplate":"Executed action {ActionName} in {ElapsedMilliseconds}ms","Properties":{"ActionName":"API.Controllers.UserController.Refresh (API)","ElapsedMilliseconds":9.6552,"EventId":{"Id":2,"Name":"ActionExecuted"},"SourceContext":"Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker","ActionId":"da90c4b0-9628-4fbe-a772-23c09a86e2fb","RequestId":"0HM9MBOQFA7T4:00000001","RequestPath":"/api/user/refresh","SpanId":"|274960c2-4d6b727c8f984133.","TraceId":"274960c2-4d6b727c8f984133","ParentId":"","ConnectionId":"0HM9MBOQFA7T4","SessionId":"105e9736-208a-4888-85c2-b66de96f6c00","User":"[email protected]@urn:leaf:issuer:leaf.mssm.edu"}}
{"Timestamp":"2021-06-23T12:17:27.4129389-04:00","Level":"Information","MessageTemplate":"{HostingRequestFinishedLog:l}","Properties":{"ElapsedMilliseconds":12.4083,"StatusCode":200,"ContentType":"application/json; charset=utf-8","HostingRequestFinishedLog":"Request finished in 12.4083ms 200 application/json; charset=utf-8","EventId":{"Id":2},"SourceContext":"Microsoft.AspNetCore.Hosting.Diagnostics","RequestId":"0HM9MBOQFA7T4:00000001","RequestPath":"/api/user/refresh","SpanId":"|274960c2-4d6b727c8f984133.","TraceId":"274960c2-4d6b727c8f984133","ParentId":"","ConnectionId":"0HM9MBOQFA7T4"},"Renderings":{"HostingRequestFinishedLog":[{"Format":"l","Rendering":"Request finished in 12.4083ms 200 application/json; charset=utf-8"}]}}
{"Timestamp":"2021-06-23T12:17:29.6912505-04:00","Level":"Information","MessageTemplate":"{HostingRequestStartingLog:l}","Properties":{"Protocol":"HTTP/1.1","Method":"POST","ContentType":"application/json;charset=UTF-8","ContentLength":2197,"Scheme":"http","Host":"10.95.46.180:5001","PathBase":"","Path":"/api/cohort/count","QueryString":"","HostingRequestStartingLog":"Request starting HTTP/1.1 POST http://10.95.46.180:5001/api/cohort/count application/json;charset=UTF-8 2197","EventId":{"Id":1},"SourceContext":"Microsoft.AspNetCore.Hosting.Diagnostics","RequestId":"0HM9MBOQFA7T4:00000002","RequestPath":"/api/cohort/count","SpanId":"|274960c3-4d6b727c8f984133.","TraceId":"274960c3-4d6b727c8f984133","ParentId":"","ConnectionId":"0HM9MBOQFA7T4"},"Renderings":{"HostingRequestStartingLog":[{"Format":"l","Rendering":"Request starting HTTP/1.1 POST http://10.95.46.180:5001/api/cohort/count application/json;charset=UTF-8 2197"}]}}
{"Timestamp":"2021-06-23T12:17:29.6916449-04:00","Level":"Information","MessageTemplate":"CORS policy execution successful.","Properties":{"EventId":{"Id":4,"Name":"PolicySuccess"},"SourceContext":"Microsoft.AspNetCore.Cors.Infrastructure.CorsService","RequestId":"0HM9MBOQFA7T4:00000002","RequestPath":"/api/cohort/count","SpanId":"|274960c3-4d6b727c8f984133.","TraceId":"274960c3-4d6b727c8f984133","ParentId":"","ConnectionId":"0HM9MBOQFA7T4"}}
{"Timestamp":"2021-06-23T12:17:29.6928969-04:00","Level":"Information","MessageTemplate":"Successfully validated the token.","Properties":{"EventId":{"Id":2,"Name":"TokenValidationSucceeded"},"SourceContext":"Microsoft.AspNetCore.Authentication.JwtBearer.JwtBearerHandler","RequestId":"0HM9MBOQFA7T4:00000002","RequestPath":"/api/cohort/count","SpanId":"|274960c3-4d6b727c8f984133.","TraceId":"274960c3-4d6b727c8f984133","ParentId":"","ConnectionId":"0HM9MBOQFA7T4"}}
{"Timestamp":"2021-06-23T12:17:29.6936149-04:00","Level":"Information","MessageTemplate":"Route matched with {RouteData}. Executing controller action with signature {MethodInfo} on controller {Controller} ({AssemblyName}).","Properties":{"RouteData":"{action = \"Count\", controller = \"CohortCount\"}","MethodInfo":"System.Threading.Tasks.Task`1[Microsoft.AspNetCore.Mvc.ActionResult`1[API.DTO.Cohort.CohortCountDTO]] Count(API.DTO.Cohort.PatientCountQueryDTO, Model.Cohort.CohortCounter, System.Threading.CancellationToken)","Controller":"API.Controllers.CohortCountController","AssemblyName":"API","EventId":{"Id":3,"Name":"ControllerActionExecuting"},"SourceContext":"Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker","ActionId":"49ef80c5-c148-43c9-895d-181bcf1e2170","ActionName":"API.Controllers.CohortCountController.Count (API)","RequestId":"0HM9MBOQFA7T4:00000002","RequestPath":"/api/cohort/count","SpanId":"|274960c3-4d6b727c8f984133.","TraceId":"274960c3-4d6b727c8f984133","ParentId":"","ConnectionId":"0HM9MBOQFA7T4","SessionId":"105e9736-208a-4888-85c2-b66de96f6c00","User":"[email protected]@urn:leaf:issuer:leaf.mssm.edu"}}
{"Timestamp":"2021-06-23T12:17:29.6939466-04:00","Level":"Information","MessageTemplate":"Authorization was successful.","Properties":{"EventId":{"Id":1,"Name":"UserAuthorizationSucceeded"},"SourceContext":"Microsoft.AspNetCore.Authorization.DefaultAuthorizationService","ActionId":"49ef80c5-c148-43c9-895d-181bcf1e2170","ActionName":"API.Controllers.CohortCountController.Count (API)","RequestId":"0HM9MBOQFA7T4:00000002","RequestPath":"/api/cohort/count","SpanId":"|274960c3-4d6b727c8f984133.","TraceId":"274960c3-4d6b727c8f984133","ParentId":"","ConnectionId":"0HM9MBOQFA7T4","SessionId":"105e9736-208a-4888-85c2-b66de96f6c00","User":"[email protected]@urn:leaf:issuer:leaf.mssm.edu"}}
{"Timestamp":"2021-06-23T12:17:29.6972583-04:00","Level":"Information","MessageTemplate":"FullCount starting. DTO:{@DTO}","Properties":{"DTO":{"_typeTag":"PatientCountQueryDTO","QueryId":"","Panels":[{"_typeTag":"PanelDTO","Id":"Qed-fUaG9jm","SubPanels":[{"_typeTag":"SubPanelDTO","Id":"gK5rux3EvLK","PanelItems":[{"_typeTag":"PanelItemDTO","Id":"Msj4N_oCI","Resource":{"_typeTag":"ResourceRef","Id":"fc9afd81-b1d3-eb11-9c20-000c29db1cc8","UniversalId":null,"UiDisplayName":"BANGLADESHI"},"Specializations":[],"NumericFilter":{"_typeTag":"NumericFilter","FilterType":"None","Filter":[]},"RecencyFilter":"None","Index":0,"SubPanelIndex":0,"PanelIndex":0}],"PanelIndex":0,"Index":0,"IncludeSubPanel":true,"MinimumCount":1,"JoinSequence":{"_typeTag":"SubPanelJoinSequence","Increment":1,"DateIncrementType":"Day","SequenceType":"Encounter"},"DateFilter":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":0,"DateIncrementType":"None"}},{"_typeTag":"SubPanelDTO","Id":"2WlO6Pis22","PanelItems":[],"PanelIndex":0,"Index":1,"IncludeSubPanel":true,"MinimumCount":1,"JoinSequence":{"_typeTag":"SubPanelJoinSequence","Increment":1,"DateIncrementType":"Day","SequenceType":"Encounter"},"DateFilter":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":0,"DateIncrementType":"None"}}],"DateFilter":{"_typeTag":"DateBoundary","Start":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":1,"DateIncrementType":"None"},"End":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":1,"DateIncrementType":"None"}},"IncludePanel":true,"Domain":"Panel","Index":0},{"_typeTag":"PanelDTO","Id":"Sm8ohKilz08","SubPanels":[{"_typeTag":"SubPanelDTO","Id":"VfHc3MIPSa9","PanelItems":[{"_typeTag":"PanelItemDTO","Id":"11k3tPCoo","Resource":{"_typeTag":"ResourceRef","Id":"099bfd81-b1d3-eb11-9c20-000c29db1cc8","UniversalId":null,"UiDisplayName":"Male"},"Specializations":[],"NumericFilter":{"_typeTag":"NumericFilter","FilterType":"None","Filter":[]},"RecencyFilter":"None","Index":0,"SubPanelIndex":0,"PanelIndex":0}],"PanelIndex":1,"Index":0,"IncludeSubPanel":true,"MinimumCount":1,"JoinSequence":{"_typeTag":"SubPanelJoinSequence","Increment":1,"DateIncrementType":"Day","SequenceType":"Encounter"},"DateFilter":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":0,"DateIncrementType":"None"}},{"_typeTag":"SubPanelDTO","Id":"g3q-tQvAhx","PanelItems":[],"PanelIndex":1,"Index":1,"IncludeSubPanel":true,"MinimumCount":1,"JoinSequence":{"_typeTag":"SubPanelJoinSequence","Increment":1,"DateIncrementType":"Day","SequenceType":"Encounter"},"DateFilter":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":0,"DateIncrementType":"None"}}],"DateFilter":{"_typeTag":"DateBoundary","Start":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":1,"DateIncrementType":"None"},"End":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":1,"DateIncrementType":"None"}},"IncludePanel":true,"Domain":"Panel","Index":1},{"_typeTag":"PanelDTO","Id":"vZ86DRG4wgm","SubPanels":[{"_typeTag":"SubPanelDTO","Id":"ZgbgB1_D_ob","PanelItems":[],"PanelIndex":2,"Index":0,"IncludeSubPanel":true,"MinimumCount":1,"JoinSequence":{"_typeTag":"SubPanelJoinSequence","Increment":1,"DateIncrementType":"Day","SequenceType":"Encounter"},"DateFilter":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":0,"DateIncrementType":"None"}}],"DateFilter":{"_typeTag":"DateBoundary","Start":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":1,"DateIncrementType":"None"},"End":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":1,"DateIncrementType":"None"}},"IncludePanel":true,"Domain":"Panel","Index":2}],"PanelFilters":[]},"SourceContext":"Model.Cohort.CohortCounter","ActionId":"49ef80c5-c148-43c9-895d-181bcf1e2170","ActionName":"API.Controllers.CohortCountController.Count (API)","RequestId":"0HM9MBOQFA7T4:00000002","RequestPath":"/api/cohort/count","SpanId":"|274960c3-4d6b727c8f984133.","TraceId":"274960c3-4d6b727c8f984133","ParentId":"","ConnectionId":"0HM9MBOQFA7T4","SessionId":"105e9736-208a-4888-85c2-b66de96f6c00","User":"[email protected]@urn:leaf:issuer:leaf.mssm.edu"}}
{"Timestamp":"2021-06-23T12:17:29.6978747-04:00","Level":"Information","MessageTemplate":"Getting preflight resources check. Refs:{@Refs}","Properties":{"Refs":{"_typeTag":"ResourceRefs","Concepts":[{"_typeTag":"ConceptRef","Id":"fc9afd81-b1d3-eb11-9c20-000c29db1cc8","UniversalId":null},{"_typeTag":"ConceptRef","Id":"099bfd81-b1d3-eb11-9c20-000c29db1cc8","UniversalId":null}],"Queries":[],"Imports":[]},"SourceContext":"Model.Search.PreflightResourceChecker","ActionId":"49ef80c5-c148-43c9-895d-181bcf1e2170","ActionName":"API.Controllers.CohortCountController.Count (API)","RequestId":"0HM9MBOQFA7T4:00000002","RequestPath":"/api/cohort/count","SpanId":"|274960c3-4d6b727c8f984133.","TraceId":"274960c3-4d6b727c8f984133","ParentId":"","ConnectionId":"0HM9MBOQFA7T4","SessionId":"105e9736-208a-4888-85c2-b66de96f6c00","User":"[email protected]@urn:leaf:issuer:leaf.mssm.edu"}}
{"Timestamp":"2021-06-23T12:17:29.7155385-04:00","Level":"Information","MessageTemplate":"FullCount panel validation context. Context:{@Context}","Properties":{"Context":{"_typeTag":"PanelValidationContext","QueryId":null,"UniversalId":null,"PreflightCheck":{"_typeTag":"PreflightResources","Ok":true,"DirectConceptsCheck":{"_typeTag":"PreflightConcepts","PreflightCheck":{"_typeTag":"ConceptPreflightCheck","Ok":true,"Results":[{"_typeTag":"ConceptPreflightCheckResult","Id":"fc9afd81-b1d3-eb11-9c20-000c29db1cc8","UniversalId":null,"IsPresent":true,"IsAuthorized":true},{"_typeTag":"ConceptPreflightCheckResult","Id":"099bfd81-b1d3-eb11-9c20-000c29db1cc8","UniversalId":null,"IsPresent":true,"IsAuthorized":true}],"IsPresent":true,"IsAuthorized":true},"Concepts":[{"_typeTag":"Concept","ParentId":"a99afd81-b1d3-eb11-9c20-000c29db1cc8","RootId":"0411ff7a-b1d3-eb11-9c20-000c29db1cc8","ExternalId":"demographics:race:2000001331","ExternalParentId":"demographics:race","IsNumeric":false,"IsEventBased":false,"IsParent":false,"IsEncounterBased":false,"IsPatientCountAutoCalculated":false,"IsSpecializable":false,"SqlSetFrom":"omop.cdm_std.person","SqlSetWhere":"/* BANGLADESHI */ @.race_concept_id = 2000001331","SqlFieldDate":null,"SqlFieldNumeric":null,"SqlFieldEvent":null,"UiDisplayName":"BANGLADESHI","UiDisplayText":"Identify as BANGLADESHI","UiDisplaySubtext":null,"UiDisplayUnits":null,"UiDisplayTooltip":null,"UiDisplayEventName":null,"UiDisplayPatientCount":11714,"EventTypeId":null,"SpecializationGroups":[],"UiDisplayPatientCountByYear":null,"UiNumericDefaultText":null,"Id":"fc9afd81-b1d3-eb11-9c20-000c29db1cc8","UniversalId":null},{"_typeTag":"Concept","ParentId":"1e9bfd81-b1d3-eb11-9c20-000c29db1cc8","RootId":"0411ff7a-b1d3-eb11-9c20-000c29db1cc8","ExternalId":"demographics:gender:2000001139","ExternalParentId":"demographics:gender","IsNumeric":false,"IsEventBased":false,"IsParent":false,"IsEncounterBased":false,"IsPatientCountAutoCalculated":false,"IsSpecializable":false,"SqlSetFrom":"omop.cdm_std.person","SqlSetWhere":"/* Male */ @.gender_concept_id = 2000001139","SqlFieldDate":null,"SqlFieldNumeric":null,"SqlFieldEvent":null,"UiDisplayName":"Male","UiDisplayText":"Identify as Male","UiDisplaySubtext":null,"UiDisplayUnits":null,"UiDisplayTooltip":null,"UiDisplayEventName":null,"UiDisplayPatientCount":2188556,"EventTypeId":null,"SpecializationGroups":[],"UiDisplayPatientCountByYear":null,"UiNumericDefaultText":null,"Id":"099bfd81-b1d3-eb11-9c20-000c29db1cc8","UniversalId":null}],"IsPresent":true,"IsAuthorized":true,"Ok":true},"DirectQueriesCheck":{"_typeTag":"PreflightQueries","Ok":true,"Results":[]},"DirectImportsCheck":{"_typeTag":"PreflightImports","Ok":true,"Results":[]},"GlobalPanelFilters":[]},"Requested":[{"_typeTag":"PanelDTO","Id":"Qed-fUaG9jm","SubPanels":[{"_typeTag":"SubPanelDTO","Id":"gK5rux3EvLK","PanelItems":[{"_typeTag":"PanelItemDTO","Id":"Msj4N_oCI","Resource":{"_typeTag":"ResourceRef","Id":"fc9afd81-b1d3-eb11-9c20-000c29db1cc8","UniversalId":null,"UiDisplayName":"BANGLADESHI"},"Specializations":[],"NumericFilter":{"_typeTag":"NumericFilter","FilterType":"None","Filter":[]},"RecencyFilter":"None","Index":0,"SubPanelIndex":0,"PanelIndex":0}],"PanelIndex":0,"Index":0,"IncludeSubPanel":true,"MinimumCount":1,"JoinSequence":{"_typeTag":"SubPanelJoinSequence","Increment":1,"DateIncrementType":"Day","SequenceType":"Encounter"},"DateFilter":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":0,"DateIncrementType":"None"}},{"_typeTag":"SubPanelDTO","Id":"2WlO6Pis22","PanelItems":[],"PanelIndex":0,"Index":1,"IncludeSubPanel":true,"MinimumCount":1,"JoinSequence":{"_typeTag":"SubPanelJoinSequence","Increment":1,"DateIncrementType":"Day","SequenceType":"Encounter"},"DateFilter":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":0,"DateIncrementType":"None"}}],"DateFilter":{"_typeTag":"DateBoundary","Start":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":1,"DateIncrementType":"None"},"End":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":1,"DateIncrementType":"None"}},"IncludePanel":true,"Domain":"Panel","Index":0},{"_typeTag":"PanelDTO","Id":"Sm8ohKilz08","SubPanels":[{"_typeTag":"SubPanelDTO","Id":"VfHc3MIPSa9","PanelItems":[{"_typeTag":"PanelItemDTO","Id":"11k3tPCoo","Resource":{"_typeTag":"ResourceRef","Id":"099bfd81-b1d3-eb11-9c20-000c29db1cc8","UniversalId":null,"UiDisplayName":"Male"},"Specializations":[],"NumericFilter":{"_typeTag":"NumericFilter","FilterType":"None","Filter":[]},"RecencyFilter":"None","Index":0,"SubPanelIndex":0,"PanelIndex":0}],"PanelIndex":1,"Index":0,"IncludeSubPanel":true,"MinimumCount":1,"JoinSequence":{"_typeTag":"SubPanelJoinSequence","Increment":1,"DateIncrementType":"Day","SequenceType":"Encounter"},"DateFilter":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":0,"DateIncrementType":"None"}},{"_typeTag":"SubPanelDTO","Id":"g3q-tQvAhx","PanelItems":[],"PanelIndex":1,"Index":1,"IncludeSubPanel":true,"MinimumCount":1,"JoinSequence":{"_typeTag":"SubPanelJoinSequence","Increment":1,"DateIncrementType":"Day","SequenceType":"Encounter"},"DateFilter":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":0,"DateIncrementType":"None"}}],"DateFilter":{"_typeTag":"DateBoundary","Start":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":1,"DateIncrementType":"None"},"End":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":1,"DateIncrementType":"None"}},"IncludePanel":true,"Domain":"Panel","Index":1},{"_typeTag":"PanelDTO","Id":"vZ86DRG4wgm","SubPanels":[{"_typeTag":"SubPanelDTO","Id":"ZgbgB1_D_ob","PanelItems":[],"PanelIndex":2,"Index":0,"IncludeSubPanel":true,"MinimumCount":1,"JoinSequence":{"_typeTag":"SubPanelJoinSequence","Increment":1,"DateIncrementType":"Day","SequenceType":"Encounter"},"DateFilter":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":0,"DateIncrementType":"None"}}],"DateFilter":{"_typeTag":"DateBoundary","Start":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":1,"DateIncrementType":"None"},"End":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":1,"DateIncrementType":"None"}},"IncludePanel":true,"Domain":"Panel","Index":2}],"Allowed":[{"_typeTag":"Panel","SubPanels":[{"_typeTag":"SubPanel","PanelItems":[{"_typeTag":"PanelItem","Concept":{"_typeTag":"Concept","ParentId":"a99afd81-b1d3-eb11-9c20-000c29db1cc8","RootId":"0411ff7a-b1d3-eb11-9c20-000c29db1cc8","ExternalId":"demographics:race:2000001331","ExternalParentId":"demographics:race","IsNumeric":false,"IsEventBased":false,"IsParent":false,"IsEncounterBased":false,"IsPatientCountAutoCalculated":false,"IsSpecializable":false,"SqlSetFrom":"omop.cdm_std.person","SqlSetWhere":"/* BANGLADESHI */ @.race_concept_id = 2000001331","SqlFieldDate":null,"SqlFieldNumeric":null,"SqlFieldEvent":null,"UiDisplayName":"BANGLADESHI","UiDisplayText":"Identify as BANGLADESHI","UiDisplaySubtext":null,"UiDisplayUnits":null,"UiDisplayTooltip":null,"UiDisplayEventName":null,"UiDisplayPatientCount":11714,"EventTypeId":null,"SpecializationGroups":[],"UiDisplayPatientCountByYear":null,"UiNumericDefaultText":null,"Id":"fc9afd81-b1d3-eb11-9c20-000c29db1cc8","UniversalId":null},"Specializations":[],"SqlRecencyFilter":null,"UseNumericFilter":false,"HasSpecializations":false,"UseRecencyFilter":false,"NumericFilter":{"_typeTag":"NumericFilter","FilterType":"None","Filter":[]},"RecencyFilter":"None","Index":0,"SubPanelIndex":0,"PanelIndex":0}],"HasCountFilter":false,"PanelIndex":0,"Index":0,"IncludeSubPanel":true,"MinimumCount":1,"JoinSequence":{"_typeTag":"SubPanelJoinSequence","Increment":1,"DateIncrementType":"Day","SequenceType":"Encounter"},"DateFilter":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":0,"DateIncrementType":"None"}},{"_typeTag":"SubPanel","PanelItems":[],"HasCountFilter":false,"PanelIndex":0,"Index":1,"IncludeSubPanel":true,"MinimumCount":1,"JoinSequence":{"_typeTag":"SubPanelJoinSequence","Increment":1,"DateIncrementType":"Day","SequenceType":"Encounter"},"DateFilter":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":0,"DateIncrementType":"None"}}],"PanelType":"Sequence","IsDateFiltered":false,"DateFilter":{"_typeTag":"DateBoundary","Start":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":1,"DateIncrementType":"None"},"End":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":1,"DateIncrementType":"None"}},"IncludePanel":true,"Domain":"Panel","Index":0},{"_typeTag":"Panel","SubPanels":[{"_typeTag":"SubPanel","PanelItems":[{"_typeTag":"PanelItem","Concept":{"_typeTag":"Concept","ParentId":"1e9bfd81-b1d3-eb11-9c20-000c29db1cc8","RootId":"0411ff7a-b1d3-eb11-9c20-000c29db1cc8","ExternalId":"demographics:gender:2000001139","ExternalParentId":"demographics:gender","IsNumeric":false,"IsEventBased":false,"IsParent":false,"IsEncounterBased":false,"IsPatientCountAutoCalculated":false,"IsSpecializable":false,"SqlSetFrom":"omop.cdm_std.person","SqlSetWhere":"/* Male */ @.gender_concept_id = 2000001139","SqlFieldDate":null,"SqlFieldNumeric":null,"SqlFieldEvent":null,"UiDisplayName":"Male","UiDisplayText":"Identify as Male","UiDisplaySubtext":null,"UiDisplayUnits":null,"UiDisplayTooltip":null,"UiDisplayEventName":null,"UiDisplayPatientCount":2188556,"EventTypeId":null,"SpecializationGroups":[],"UiDisplayPatientCountByYear":null,"UiNumericDefaultText":null,"Id":"099bfd81-b1d3-eb11-9c20-000c29db1cc8","UniversalId":null},"Specializations":[],"SqlRecencyFilter":null,"UseNumericFilter":false,"HasSpecializations":false,"UseRecencyFilter":false,"NumericFilter":{"_typeTag":"NumericFilter","FilterType":"None","Filter":[]},"RecencyFilter":"None","Index":0,"SubPanelIndex":0,"PanelIndex":0}],"HasCountFilter":false,"PanelIndex":1,"Index":0,"IncludeSubPanel":true,"MinimumCount":1,"JoinSequence":{"_typeTag":"SubPanelJoinSequence","Increment":1,"DateIncrementType":"Day","SequenceType":"Encounter"},"DateFilter":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":0,"DateIncrementType":"None"}},{"_typeTag":"SubPanel","PanelItems":[],"HasCountFilter":false,"PanelIndex":1,"Index":1,"IncludeSubPanel":true,"MinimumCount":1,"JoinSequence":{"_typeTag":"SubPanelJoinSequence","Increment":1,"DateIncrementType":"Day","SequenceType":"Encounter"},"DateFilter":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":0,"DateIncrementType":"None"}}],"PanelType":"Sequence","IsDateFiltered":false,"DateFilter":{"_typeTag":"DateBoundary","Start":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":1,"DateIncrementType":"None"},"End":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":1,"DateIncrementType":"None"}},"IncludePanel":true,"Domain":"Panel","Index":1},{"_typeTag":"Panel","SubPanels":[{"_typeTag":"SubPanel","PanelItems":[],"HasCountFilter":false,"PanelIndex":2,"Index":0,"IncludeSubPanel":true,"MinimumCount":1,"JoinSequence":{"_typeTag":"SubPanelJoinSequence","Increment":1,"DateIncrementType":"Day","SequenceType":"Encounter"},"DateFilter":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":0,"DateIncrementType":"None"}}],"PanelType":"Patient","IsDateFiltered":false,"DateFilter":{"_typeTag":"DateBoundary","Start":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":1,"DateIncrementType":"None"},"End":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":1,"DateIncrementType":"None"}},"IncludePanel":true,"Domain":"Panel","Index":2}],"PreflightPassed":true},"SourceContext":"Model.Cohort.CohortCounter","ActionId":"49ef80c5-c148-43c9-895d-181bcf1e2170","ActionName":"API.Controllers.CohortCountController.Count (API)","RequestId":"0HM9MBOQFA7T4:00000002","RequestPath":"/api/cohort/count","SpanId":"|274960c3-4d6b727c8f984133.","TraceId":"274960c3-4d6b727c8f984133","ParentId":"","ConnectionId":"0HM9MBOQFA7T4","SessionId":"105e9736-208a-4888-85c2-b66de96f6c00","User":"[email protected]@urn:leaf:issuer:leaf.mssm.edu"}}
{"Timestamp":"2021-06-23T12:17:29.7168899-04:00","Level":"Information","MessageTemplate":"FullCount cohort started.","Properties":{"SourceContext":"Model.Cohort.CohortCounter","ActionId":"49ef80c5-c148-43c9-895d-181bcf1e2170","ActionName":"API.Controllers.CohortCountController.Count (API)","RequestId":"0HM9MBOQFA7T4:00000002","RequestPath":"/api/cohort/count","SpanId":"|274960c3-4d6b727c8f984133.","TraceId":"274960c3-4d6b727c8f984133","ParentId":"","ConnectionId":"0HM9MBOQFA7T4","SessionId":"105e9736-208a-4888-85c2-b66de96f6c00","User":"[email protected]@urn:leaf:issuer:leaf.mssm.edu"}}
{"Timestamp":"2021-06-23T12:17:29.7177188-04:00","Level":"Information","MessageTemplate":"CTE SqlStatement:{Sql}","Properties":{"Sql":"DECLARE @IsIdentified BIT = 0; DECLARE @IsResearch   BIT = 0; DECLARE @IsQI         BIT = 1; WITH wrapper (personId) AS ( SELECT P0.person_id FROM ( SELECT  _S000.person_id FROM omop.cdm_std.person AS _S000 WHERE /* BANGLADESHI */ _S000.race_concept_id = 2000001331 ) AS P0 INTERSECT SELECT P1.person_id FROM ( SELECT  _S100.person_id FROM omop.cdm_std.person AS _S100 WHERE /* Male */ _S100.gender_concept_id = 2000001139 ) AS P1 ) SELECT personId FROM wrapper","SourceContext":"Model.Cohort.PatientCohortService","ActionId":"49ef80c5-c148-43c9-895d-181bcf1e2170","ActionName":"API.Controllers.CohortCountController.Count (API)","RequestId":"0HM9MBOQFA7T4:00000002","RequestPath":"/api/cohort/count","SpanId":"|274960c3-4d6b727c8f984133.","TraceId":"274960c3-4d6b727c8f984133","ParentId":"","ConnectionId":"0HM9MBOQFA7T4","SessionId":"105e9736-208a-4888-85c2-b66de96f6c00","User":"[email protected]@urn:leaf:issuer:leaf.mssm.edu"}}
{"Timestamp":"2021-06-23T12:17:31.1680602-04:00","Level":"Information","MessageTemplate":"Refreshed TokenBlacklistCache","Properties":{"SourceContext":"API.Jobs.BackgroundTokenBlacklistSynchronizer"}}
{"Timestamp":"2021-06-23T12:18:01.1710742-04:00","Level":"Information","MessageTemplate":"Refreshed TokenBlacklistCache","Properties":{"SourceContext":"API.Jobs.BackgroundTokenBlacklistSynchronizer"}}
{"Timestamp":"2021-06-23T12:18:29.7189804-04:00","Level":"Error","MessageTemplate":"Failed to execute query. Error:{Error}","Properties":{"Error":"System.Data.SqlClient.SqlException (0x80131904): A severe error occurred on the current command.  The results, if any, should be discarded.\nOperation cancelled by user.\n   at System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseInAction)\n   at System.Data.SqlClient.SqlInternalConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseInAction)\n   at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose)\n   at System.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady)\n   at System.Data.SqlClient.SqlDataReader.TryHasMoreRows(Boolean& moreRows)\n   at System.Data.SqlClient.SqlDataReader.TryReadInternal(Boolean setTimeout, Boolean& more)\n   at System.Data.SqlClient.SqlDataReader.Read()\n   at Services.Cohort.CtePatientCohortService.GetPatientSetAsync(ISqlStatement query, CancellationToken token) in /var/opt/leafapi/leaf_download/leaf/src/server/Services/Cohort/CtePatientCohortService.cs:line 54\n   at Services.Cohort.CtePatientCohortService.GetCohortAsync(PatientCountQuery query, CancellationToken token) in /var/opt/leafapi/leaf_download/leaf/src/server/Services/Cohort/CtePatientCohortService.cs:line 32\n   at Model.Cohort.PatientCohortService.GetPatientCohortAsync(PatientCountQuery query, CancellationToken token) in /var/opt/leafapi/leaf_download/leaf/src/server/Model/Cohort/PatientCohortService.cs:line 35\n   at Model.Cohort.CohortCounter.FullCount(IPatientCountQueryDTO queryDTO, CancellationToken token) in /var/opt/leafapi/leaf_download/leaf/src/server/Model/Cohort/CohortCounter.cs:line 177\n   at Model.Cohort.CohortCounter.Count(IPatientCountQueryDTO queryDTO, CancellationToken token) in /var/opt/leafapi/leaf_download/leaf/src/server/Model/Cohort/CohortCounter.cs:line 89\n   at API.Controllers.CohortCountController.Count(PatientCountQueryDTO patientCountQuery, CohortCounter counter, CancellationToken cancelToken) in /var/opt/leafapi/leaf_download/leaf/src/server/API/Controllers/CohortCountController.cs:line 40\nClientConnectionId:1c468d5a-fcfd-4efa-b4bd-ffc3ddba0ffb","SourceContext":"API.Controllers.CohortCountController","ActionId":"49ef80c5-c148-43c9-895d-181bcf1e2170","ActionName":"API.Controllers.CohortCountController.Count (API)","RequestId":"0HM9MBOQFA7T4:00000002","RequestPath":"/api/cohort/count","SpanId":"|274960c3-4d6b727c8f984133.","TraceId":"274960c3-4d6b727c8f984133","ParentId":"","ConnectionId":"0HM9MBOQFA7T4","SessionId":"105e9736-208a-4888-85c2-b66de96f6c00","User":"[email protected]@urn:leaf:issuer:leaf.mssm.edu"}}
{"Timestamp":"2021-06-23T12:18:29.7195953-04:00","Level":"Information","MessageTemplate":"Executing HttpStatusCodeResult, setting HTTP status code {StatusCode}","Properties":{"StatusCode":500,"EventId":{"Id":1,"Name":"HttpStatusCodeResultExecuting"},"SourceContext":"Microsoft.AspNetCore.Mvc.StatusCodeResult","ActionId":"49ef80c5-c148-43c9-895d-181bcf1e2170","ActionName":"API.Controllers.CohortCountController.Count (API)","RequestId":"0HM9MBOQFA7T4:00000002","RequestPath":"/api/cohort/count","SpanId":"|274960c3-4d6b727c8f984133.","TraceId":"274960c3-4d6b727c8f984133","ParentId":"","ConnectionId":"0HM9MBOQFA7T4","SessionId":"105e9736-208a-4888-85c2-b66de96f6c00","User":"[email protected]@urn:leaf:issuer:leaf.mssm.edu"}}
{"Timestamp":"2021-06-23T12:18:29.7198676-04:00","Level":"Information","MessageTemplate":"Executed action {ActionName} in {ElapsedMilliseconds}ms","Properties":{"ActionName":"API.Controllers.CohortCountController.Count (API)","ElapsedMilliseconds":60026.0671,"EventId":{"Id":2,"Name":"ActionExecuted"},"SourceContext":"Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker","ActionId":"49ef80c5-c148-43c9-895d-181bcf1e2170","RequestId":"0HM9MBOQFA7T4:00000002","RequestPath":"/api/cohort/count","SpanId":"|274960c3-4d6b727c8f984133.","TraceId":"274960c3-4d6b727c8f984133","ParentId":"","ConnectionId":"0HM9MBOQFA7T4","SessionId":"105e9736-208a-4888-85c2-b66de96f6c00","User":"[email protected]@urn:leaf:issuer:leaf.mssm.edu"}}
{"Timestamp":"2021-06-23T12:18:29.7201862-04:00","Level":"Information","MessageTemplate":"{HostingRequestFinishedLog:l}","Properties":{"ElapsedMilliseconds":60028.9739,"StatusCode":0,"ContentType":null,"HostingRequestFinishedLog":"Request finished in 60028.9739ms 0 ","EventId":{"Id":2},"SourceContext":"Microsoft.AspNetCore.Hosting.Diagnostics","RequestId":"0HM9MBOQFA7T4:00000002","RequestPath":"/api/cohort/count","SpanId":"|274960c3-4d6b727c8f984133.","TraceId":"274960c3-4d6b727c8f984133","ParentId":"","ConnectionId":"0HM9MBOQFA7T4"},"Renderings":{"HostingRequestFinishedLog":[{"Format":"l","Rendering":"Request finished in 60028.9739ms 0 "}]}}

I would appreciate your help.

Thanks very much.

Arthur

[ndobb]

Hi @artgoldberg,

Thanks for letting us know. I suspect this is perhaps an OOM or SQL Server configuration issue on the DB side for 2 reasons:

1. The Leaf API tells SQL how long to let queries run based on the DefaultTimeout value (https://github.com/uwrit/leaf/blob/master/src/server/Services/Cohort/CtePatientCohortService.cs#L50)
2. The "A severe error occurred on the current command" issue is often due to underlying performance problems (https://stackoverflow.com/questions/1175244/sql-server-error-on-update-command-a-severe-error-occurred-on-the-current-com)

While adding an appropriate index would be ideal, another possible workaround would be to switch Db.Clin.Cohort.QueryStrategy from "CTE" to "PARELLEL", which would execute the 2 SQL statements separately and intersect the resulting patients within the API, rather than by combining all panel queries in one single SQL statement. Anecdotally we've found the simplified queries to execute far faster in many cases.

There are tradeoffs to the above approach, but we use "PARELLEL" at UW for exactly these kinds of cases.

[artgoldberg]

Thanks @ndobb

I'll try the "PARALLEL" Db.Clin.Cohort.QueryStrategy and let you know what happens. However, I doubt that a performance problem is occuring because the queries all end almost exactly at 60 sec., and performance problems tend to be much more non-deterministic because they depend on stochastic loads, memory usage, etc. You can see the timing in the animation I posted above, and in the 60 sec. spacing between the log message reporting the query and the one reporting the error.

Regards Arthur

[artgoldberg]

Hi @ndobb

I have tried the "PARALLEL" Db.Clin.Cohort.QueryStrategy and the query completed without a timeout. Unfortunately, this isn't conclusive as the CDM is constantly changing. I'll find a query that takes more than 60 sec. in PARALLEL mode, and then switch back to CTE. If PARALLEL mode doesn't timeout and CTE mode does, then I'll have greater confidence that it's a real solution.

Also, I've asked the folks building the EHR to clinical DW to give me a schema that rarely changes, which will greatly help development & debugging.

Arthur

[ndobb]

Hi @artgoldberg ,

Thanks for catching my typos.

Regarding performance issues versus configuration, my point is simply that the Leaf API is providing the SQL Server a timeout value using the DefaultTimeout value provided, and given that the SQL engine was responding that it encountered a severe error (rather than a timeout) and 60 seconds is less than the provided DefaultTimeout, my best guess is that the SQL engine is granting 60 seconds for the query to resolve or memory usage to drop below that which the engine is allotting in a given memory grant, which fails and results in the error. However I have no empirical evidence and this is purely speculative. The seemingly deterministic 60 second time period is odd, but again I can only guess to be some internal configuration within SQL Server barring some other evidence.

I agree that while PARALLEL may offer a workaround for the current query it isn't a satisfying answer for why the SQL engine behaves as it does, again anecdotally I can say that it has worked reasonably well at UW for the past year or so that we've used it.

[artgoldberg]

Hi @ndobb

Thanks Nic. You've an interesting hypothesis RE MSSQL timing out because a query is not progressing, and that using PARALLEL may help avoid this.

With these timeout and QueryStrategy settings

"Db": {
  "App": {
    "Connection": "LEAF_APP_DB",
    "DefaultTimeout": 600
  },
  "Clin": {
    "Connection": "LEAF_CLIN_DB",
    "DefaultTimeout": 600,
    "Cohort": {
      "QueryStrategy": "PARALLEL",
      "MaxParallelThreads": 5
    }
  }
},

my Leaf continues to timeout at 60 s with deliberately, but not ridiculously, complex queries.

That raises the question: how should I debug this? Can we illustrate the problem clearly to the MSSQL folks? I'd like to isolate the query and, if possible, show traces of the ODBC connection traffic. I could then try the isolated query elsewhere, e.g., as a script or in a tool like DBeaver.

But with PARALLEL I don't see an SQL query in the Leaf log, nor do I see an error:

{"Timestamp":"2021-06-30T11:03:49.4040620-04:00","Level":"Information","MessageTemplate":"Refreshed TokenBlacklistCache","Properties":{"SourceContext":"API.Jobs.BackgroundTokenBlacklistSynchronizer"}}
{"Timestamp":"2021-06-30T11:03:54.9536337-04:00","Level":"Information","MessageTemplate":"{HostingRequestStartingLog:l}","Properties":{"Protocol":"HTTP/1.1","Method":"POST","ContentType":"application/json;charset=UTF-8","ContentLength":2204,"Scheme":"http","Host":"10.95.46.180:5001","PathBase":"","Path":"/api/cohort/count","QueryString":"","HostingRequestStartingLog":"Request starting HTTP/1.1 POST http://10.95.46.180:5001/api/cohort/count application/json;charset=UTF-8 2204","EventId":{"Id":1},"SourceContext":"Microsoft.AspNetCore.Hosting.Diagnostics","RequestId":"0HM9R3D81014H:00000001","RequestPath":"/api/cohort/count","SpanId":"|98600d3e-4256a881e8028080.","TraceId":"98600d3e-4256a881e8028080","ParentId":"","ConnectionId":"0HM9R3D81014H"},"Renderings":{"HostingRequestStartingLog":[{"Format":"l","Rendering":"Request starting HTTP/1.1 POST http://10.95.46.180:5001/api/cohort/count application/json;charset=UTF-8 2204"}]}}
{"Timestamp":"2021-06-30T11:03:54.9539610-04:00","Level":"Information","MessageTemplate":"CORS policy execution successful.","Properties":{"EventId":{"Id":4,"Name":"PolicySuccess"},"SourceContext":"Microsoft.AspNetCore.Cors.Infrastructure.CorsService","RequestId":"0HM9R3D81014H:00000001","RequestPath":"/api/cohort/count","SpanId":"|98600d3e-4256a881e8028080.","TraceId":"98600d3e-4256a881e8028080","ParentId":"","ConnectionId":"0HM9R3D81014H"}}
{"Timestamp":"2021-06-30T11:03:54.9548511-04:00","Level":"Information","MessageTemplate":"Successfully validated the token.","Properties":{"EventId":{"Id":2,"Name":"TokenValidationSucceeded"},"SourceContext":"Microsoft.AspNetCore.Authentication.JwtBearer.JwtBearerHandler","RequestId":"0HM9R3D81014H:00000001","RequestPath":"/api/cohort/count","SpanId":"|98600d3e-4256a881e8028080.","TraceId":"98600d3e-4256a881e8028080","ParentId":"","ConnectionId":"0HM9R3D81014H"}}
{"Timestamp":"2021-06-30T11:03:54.9551672-04:00","Level":"Information","MessageTemplate":"Route matched with {RouteData}. Executing controller action with signature {MethodInfo} on controller {Controller} ({AssemblyName}).","Properties":{"RouteData":"{action = \"Count\", controller = \"CohortCount\"}","MethodInfo":"System.Threading.Tasks.Task`1[Microsoft.AspNetCore.Mvc.ActionResult`1[API.DTO.Cohort.CohortCountDTO]] Count(API.DTO.Cohort.PatientCountQueryDTO, Model.Cohort.CohortCounter, System.Threading.CancellationToken)","Controller":"API.Controllers.CohortCountController","AssemblyName":"API","EventId":{"Id":3,"Name":"ControllerActionExecuting"},"SourceContext":"Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker","ActionId":"7c915b1a-2124-45b4-b5c5-bf8c57c79bad","ActionName":"API.Controllers.CohortCountController.Count (API)","RequestId":"0HM9R3D81014H:00000001","RequestPath":"/api/cohort/count","SpanId":"|98600d3e-4256a881e8028080.","TraceId":"98600d3e-4256a881e8028080","ParentId":"","ConnectionId":"0HM9R3D81014H","SessionId":"4991c429-d77c-45b2-8ea2-2f516d45c86d","User":"[email protected]@urn:leaf:issuer:leaf.mssm.edu"}}
{"Timestamp":"2021-06-30T11:03:54.9553817-04:00","Level":"Information","MessageTemplate":"Authorization was successful.","Properties":{"EventId":{"Id":1,"Name":"UserAuthorizationSucceeded"},"SourceContext":"Microsoft.AspNetCore.Authorization.DefaultAuthorizationService","ActionId":"7c915b1a-2124-45b4-b5c5-bf8c57c79bad","ActionName":"API.Controllers.CohortCountController.Count (API)","RequestId":"0HM9R3D81014H:00000001","RequestPath":"/api/cohort/count","SpanId":"|98600d3e-4256a881e8028080.","TraceId":"98600d3e-4256a881e8028080","ParentId":"","ConnectionId":"0HM9R3D81014H","SessionId":"4991c429-d77c-45b2-8ea2-2f516d45c86d","User":"[email protected]@urn:leaf:issuer:leaf.mssm.edu"}}
{"Timestamp":"2021-06-30T11:03:54.9570503-04:00","Level":"Information","MessageTemplate":"FullCount starting. DTO:{@DTO}","Properties":{"DTO":{"_typeTag":"PatientCountQueryDTO","QueryId":"","Panels":[{"_typeTag":"PanelDTO","Id":"mvtJ0aaEM_S","SubPanels":[{"_typeTag":"SubPanelDTO","Id":"giFjzB_PB1t","PanelItems":[],"PanelIndex":0,"Index":0,"IncludeSubPanel":true,"MinimumCount":1,"JoinSequence":{"_typeTag":"SubPanelJoinSequence","Increment":1,"DateIncrementType":"Day","SequenceType":"Encounter"},"DateFilter":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":0,"DateIncrementType":"None"}}],"DateFilter":{"_typeTag":"DateBoundary","Start":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":1,"DateIncrementType":"None"},"End":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":1,"DateIncrementType":"None"}},"IncludePanel":true,"Domain":"Panel","Index":0},{"_typeTag":"PanelDTO","Id":"eCzE90Bt-_G","SubPanels":[{"_typeTag":"SubPanelDTO","Id":"1q0GuB8CBbN","PanelItems":[{"_typeTag":"PanelItemDTO","Id":"uPNTE7avx","Resource":{"_typeTag":"ResourceRef","Id":"8d94847b-fbd8-eb11-9c20-000c29db1cc8","UniversalId":null,"UiDisplayName":"Age"},"Specializations":[],"NumericFilter":{"_typeTag":"NumericFilter","FilterType":"GreaterThanOrEqualTo","Filter":[111]},"RecencyFilter":"None","Index":0,"SubPanelIndex":0,"PanelIndex":0}],"PanelIndex":1,"Index":0,"IncludeSubPanel":true,"MinimumCount":1,"JoinSequence":{"_typeTag":"SubPanelJoinSequence","Increment":1,"DateIncrementType":"Day","SequenceType":"Encounter"},"DateFilter":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":0,"DateIncrementType":"None"}},{"_typeTag":"SubPanelDTO","Id":"dKSnWLB75M","PanelItems":[],"PanelIndex":1,"Index":1,"IncludeSubPanel":true,"MinimumCount":1,"JoinSequence":{"_typeTag":"SubPanelJoinSequence","Increment":1,"DateIncrementType":"Day","SequenceType":"Encounter"},"DateFilter":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":0,"DateIncrementType":"None"}}],"DateFilter":{"_typeTag":"DateBoundary","Start":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":1,"DateIncrementType":"None"},"End":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":1,"DateIncrementType":"None"}},"IncludePanel":true,"Domain":"Panel","Index":1},{"_typeTag":"PanelDTO","Id":"a9_nKHJMLPY","SubPanels":[{"_typeTag":"SubPanelDTO","Id":"uBoZDFdljNj","PanelItems":[{"_typeTag":"PanelItemDTO","Id":"B65kXE-xf","Resource":{"_typeTag":"ResourceRef","Id":"b7215ba6-fdd8-eb11-9c20-000c29db1cc8","UniversalId":null,"UiDisplayName":"Outpatient Visit"},"Specializations":[],"NumericFilter":{"_typeTag":"NumericFilter","FilterType":"None","Filter":[]},"RecencyFilter":"None","Index":0,"SubPanelIndex":0,"PanelIndex":0}],"PanelIndex":2,"Index":0,"IncludeSubPanel":true,"MinimumCount":1,"JoinSequence":{"_typeTag":"SubPanelJoinSequence","Increment":1,"DateIncrementType":"Day","SequenceType":"Encounter"},"DateFilter":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":0,"DateIncrementType":"None"}},{"_typeTag":"SubPanelDTO","Id":"W2FkdaZ7r5","PanelItems":[],"PanelIndex":2,"Index":1,"IncludeSubPanel":true,"MinimumCount":1,"JoinSequence":{"_typeTag":"SubPanelJoinSequence","Increment":1,"DateIncrementType":"Day","SequenceType":"Encounter"},"DateFilter":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":0,"DateIncrementType":"None"}}],"DateFilter":{"_typeTag":"DateBoundary","Start":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":1,"DateIncrementType":"None"},"End":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":1,"DateIncrementType":"None"}},"IncludePanel":true,"Domain":"Panel","Index":2}],"PanelFilters":[]},"SourceContext":"Model.Cohort.CohortCounter","ActionId":"7c915b1a-2124-45b4-b5c5-bf8c57c79bad","ActionName":"API.Controllers.CohortCountController.Count (API)","RequestId":"0HM9R3D81014H:00000001","RequestPath":"/api/cohort/count","SpanId":"|98600d3e-4256a881e8028080.","TraceId":"98600d3e-4256a881e8028080","ParentId":"","ConnectionId":"0HM9R3D81014H","SessionId":"4991c429-d77c-45b2-8ea2-2f516d45c86d","User":"[email protected]@urn:leaf:issuer:leaf.mssm.edu"}}
{"Timestamp":"2021-06-30T11:03:54.9576597-04:00","Level":"Information","MessageTemplate":"Getting preflight resources check. Refs:{@Refs}","Properties":{"Refs":{"_typeTag":"ResourceRefs","Concepts":[{"_typeTag":"ConceptRef","Id":"8d94847b-fbd8-eb11-9c20-000c29db1cc8","UniversalId":null},{"_typeTag":"ConceptRef","Id":"b7215ba6-fdd8-eb11-9c20-000c29db1cc8","UniversalId":null}],"Queries":[],"Imports":[]},"SourceContext":"Model.Search.PreflightResourceChecker","ActionId":"7c915b1a-2124-45b4-b5c5-bf8c57c79bad","ActionName":"API.Controllers.CohortCountController.Count (API)","RequestId":"0HM9R3D81014H:00000001","RequestPath":"/api/cohort/count","SpanId":"|98600d3e-4256a881e8028080.","TraceId":"98600d3e-4256a881e8028080","ParentId":"","ConnectionId":"0HM9R3D81014H","SessionId":"4991c429-d77c-45b2-8ea2-2f516d45c86d","User":"[email protected]@urn:leaf:issuer:leaf.mssm.edu"}}
{"Timestamp":"2021-06-30T11:03:54.9726725-04:00","Level":"Information","MessageTemplate":"FullCount panel validation context. Context:{@Context}","Properties":{"Context":{"_typeTag":"PanelValidationContext","QueryId":null,"UniversalId":null,"PreflightCheck":{"_typeTag":"PreflightResources","Ok":true,"DirectConceptsCheck":{"_typeTag":"PreflightConcepts","PreflightCheck":{"_typeTag":"ConceptPreflightCheck","Ok":true,"Results":[{"_typeTag":"ConceptPreflightCheckResult","Id":"8d94847b-fbd8-eb11-9c20-000c29db1cc8","UniversalId":null,"IsPresent":true,"IsAuthorized":true},{"_typeTag":"ConceptPreflightCheckResult","Id":"b7215ba6-fdd8-eb11-9c20-000c29db1cc8","UniversalId":null,"IsPresent":true,"IsAuthorized":true}],"IsPresent":true,"IsAuthorized":true},"Concepts":[{"_typeTag":"Concept","ParentId":"8c94847b-fbd8-eb11-9c20-000c29db1cc8","RootId":"8c94847b-fbd8-eb11-9c20-000c29db1cc8","ExternalId":"demographics:age","ExternalParentId":"demographics","IsNumeric":true,"IsEventBased":false,"IsParent":false,"IsEncounterBased":false,"IsPatientCountAutoCalculated":false,"IsSpecializable":false,"SqlSetFrom":"omop.cdm_std.person","SqlSetWhere":null,"SqlFieldDate":null,"SqlFieldNumeric":"/* Current Age */ (DATEDIFF(DAY, @.birth_datetime, GETDATE()) / 365.25)","SqlFieldEvent":null,"UiDisplayName":"Age","UiDisplayText":"Are","UiDisplaySubtext":null,"UiDisplayUnits":"years old","UiDisplayTooltip":null,"UiDisplayEventName":null,"UiDisplayPatientCount":68826766,"EventTypeId":null,"SpecializationGroups":[],"UiDisplayPatientCountByYear":null,"UiNumericDefaultText":"any current age","Id":"8d94847b-fbd8-eb11-9c20-000c29db1cc8","UniversalId":null},{"_typeTag":"Concept","ParentId":"b5215ba6-fdd8-eb11-9c20-000c29db1cc8","RootId":"b5215ba6-fdd8-eb11-9c20-000c29db1cc8","ExternalId":"visit:9202","ExternalParentId":"visit","IsNumeric":false,"IsEventBased":false,"IsParent":true,"IsEncounterBased":true,"IsPatientCountAutoCalculated":false,"IsSpecializable":false,"SqlSetFrom":"omop.cdm_std.visit_occurrence","SqlSetWhere":"/* Outpatient Visit */ @.visit_concept_id = 9202","SqlFieldDate":"@.visit_start_datetime","SqlFieldNumeric":null,"SqlFieldEvent":null,"UiDisplayName":"Outpatient Visit","UiDisplayText":"Had an Outpatient Visit","UiDisplaySubtext":null,"UiDisplayUnits":null,"UiDisplayTooltip":null,"UiDisplayEventName":null,"UiDisplayPatientCount":3346382,"EventTypeId":null,"SpecializationGroups":[],"UiDisplayPatientCountByYear":null,"UiNumericDefaultText":null,"Id":"b7215ba6-fdd8-eb11-9c20-000c29db1cc8","UniversalId":null}],"IsPresent":true,"IsAuthorized":true,"Ok":true},"DirectQueriesCheck":{"_typeTag":"PreflightQueries","Ok":true,"Results":[]},"DirectImportsCheck":{"_typeTag":"PreflightImports","Ok":true,"Results":[]},"GlobalPanelFilters":[]},"Requested":[{"_typeTag":"PanelDTO","Id":"mvtJ0aaEM_S","SubPanels":[{"_typeTag":"SubPanelDTO","Id":"giFjzB_PB1t","PanelItems":[],"PanelIndex":0,"Index":0,"IncludeSubPanel":true,"MinimumCount":1,"JoinSequence":{"_typeTag":"SubPanelJoinSequence","Increment":1,"DateIncrementType":"Day","SequenceType":"Encounter"},"DateFilter":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":0,"DateIncrementType":"None"}}],"DateFilter":{"_typeTag":"DateBoundary","Start":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":1,"DateIncrementType":"None"},"End":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":1,"DateIncrementType":"None"}},"IncludePanel":true,"Domain":"Panel","Index":0},{"_typeTag":"PanelDTO","Id":"eCzE90Bt-_G","SubPanels":[{"_typeTag":"SubPanelDTO","Id":"1q0GuB8CBbN","PanelItems":[{"_typeTag":"PanelItemDTO","Id":"uPNTE7avx","Resource":{"_typeTag":"ResourceRef","Id":"8d94847b-fbd8-eb11-9c20-000c29db1cc8","UniversalId":null,"UiDisplayName":"Age"},"Specializations":[],"NumericFilter":{"_typeTag":"NumericFilter","FilterType":"GreaterThanOrEqualTo","Filter":[111]},"RecencyFilter":"None","Index":0,"SubPanelIndex":0,"PanelIndex":0}],"PanelIndex":1,"Index":0,"IncludeSubPanel":true,"MinimumCount":1,"JoinSequence":{"_typeTag":"SubPanelJoinSequence","Increment":1,"DateIncrementType":"Day","SequenceType":"Encounter"},"DateFilter":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":0,"DateIncrementType":"None"}},{"_typeTag":"SubPanelDTO","Id":"dKSnWLB75M","PanelItems":[],"PanelIndex":1,"Index":1,"IncludeSubPanel":true,"MinimumCount":1,"JoinSequence":{"_typeTag":"SubPanelJoinSequence","Increment":1,"DateIncrementType":"Day","SequenceType":"Encounter"},"DateFilter":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":0,"DateIncrementType":"None"}}],"DateFilter":{"_typeTag":"DateBoundary","Start":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":1,"DateIncrementType":"None"},"End":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":1,"DateIncrementType":"None"}},"IncludePanel":true,"Domain":"Panel","Index":1},{"_typeTag":"PanelDTO","Id":"a9_nKHJMLPY","SubPanels":[{"_typeTag":"SubPanelDTO","Id":"uBoZDFdljNj","PanelItems":[{"_typeTag":"PanelItemDTO","Id":"B65kXE-xf","Resource":{"_typeTag":"ResourceRef","Id":"b7215ba6-fdd8-eb11-9c20-000c29db1cc8","UniversalId":null,"UiDisplayName":"Outpatient Visit"},"Specializations":[],"NumericFilter":{"_typeTag":"NumericFilter","FilterType":"None","Filter":[]},"RecencyFilter":"None","Index":0,"SubPanelIndex":0,"PanelIndex":0}],"PanelIndex":2,"Index":0,"IncludeSubPanel":true,"MinimumCount":1,"JoinSequence":{"_typeTag":"SubPanelJoinSequence","Increment":1,"DateIncrementType":"Day","SequenceType":"Encounter"},"DateFilter":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":0,"DateIncrementType":"None"}},{"_typeTag":"SubPanelDTO","Id":"W2FkdaZ7r5","PanelItems":[],"PanelIndex":2,"Index":1,"IncludeSubPanel":true,"MinimumCount":1,"JoinSequence":{"_typeTag":"SubPanelJoinSequence","Increment":1,"DateIncrementType":"Day","SequenceType":"Encounter"},"DateFilter":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":0,"DateIncrementType":"None"}}],"DateFilter":{"_typeTag":"DateBoundary","Start":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":1,"DateIncrementType":"None"},"End":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":1,"DateIncrementType":"None"}},"IncludePanel":true,"Domain":"Panel","Index":2}],"Allowed":[{"_typeTag":"Panel","SubPanels":[{"_typeTag":"SubPanel","PanelItems":[],"HasCountFilter":false,"PanelIndex":0,"Index":0,"IncludeSubPanel":true,"MinimumCount":1,"JoinSequence":{"_typeTag":"SubPanelJoinSequence","Increment":1,"DateIncrementType":"Day","SequenceType":"Encounter"},"DateFilter":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":0,"DateIncrementType":"None"}}],"PanelType":"Patient","IsDateFiltered":false,"DateFilter":{"_typeTag":"DateBoundary","Start":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":1,"DateIncrementType":"None"},"End":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":1,"DateIncrementType":"None"}},"IncludePanel":true,"Domain":"Panel","Index":0},{"_typeTag":"Panel","SubPanels":[{"_typeTag":"SubPanel","PanelItems":[{"_typeTag":"PanelItem","Concept":{"_typeTag":"Concept","ParentId":"8c94847b-fbd8-eb11-9c20-000c29db1cc8","RootId":"8c94847b-fbd8-eb11-9c20-000c29db1cc8","ExternalId":"demographics:age","ExternalParentId":"demographics","IsNumeric":true,"IsEventBased":false,"IsParent":false,"IsEncounterBased":false,"IsPatientCountAutoCalculated":false,"IsSpecializable":false,"SqlSetFrom":"omop.cdm_std.person","SqlSetWhere":null,"SqlFieldDate":null,"SqlFieldNumeric":"/* Current Age */ (DATEDIFF(DAY, @.birth_datetime, GETDATE()) / 365.25)","SqlFieldEvent":null,"UiDisplayName":"Age","UiDisplayText":"Are","UiDisplaySubtext":null,"UiDisplayUnits":"years old","UiDisplayTooltip":null,"UiDisplayEventName":null,"UiDisplayPatientCount":68826766,"EventTypeId":null,"SpecializationGroups":[],"UiDisplayPatientCountByYear":null,"UiNumericDefaultText":"any current age","Id":"8d94847b-fbd8-eb11-9c20-000c29db1cc8","UniversalId":null},"Specializations":[],"SqlRecencyFilter":null,"UseNumericFilter":true,"HasSpecializations":false,"UseRecencyFilter":false,"NumericFilter":{"_typeTag":"NumericFilter","FilterType":"GreaterThanOrEqualTo","Filter":[111]},"RecencyFilter":"None","Index":0,"SubPanelIndex":0,"PanelIndex":0}],"HasCountFilter":false,"PanelIndex":1,"Index":0,"IncludeSubPanel":true,"MinimumCount":1,"JoinSequence":{"_typeTag":"SubPanelJoinSequence","Increment":1,"DateIncrementType":"Day","SequenceType":"Encounter"},"DateFilter":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":0,"DateIncrementType":"None"}},{"_typeTag":"SubPanel","PanelItems":[],"HasCountFilter":false,"PanelIndex":1,"Index":1,"IncludeSubPanel":true,"MinimumCount":1,"JoinSequence":{"_typeTag":"SubPanelJoinSequence","Increment":1,"DateIncrementType":"Day","SequenceType":"Encounter"},"DateFilter":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":0,"DateIncrementType":"None"}}],"PanelType":"Sequence","IsDateFiltered":false,"DateFilter":{"_typeTag":"DateBoundary","Start":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":1,"DateIncrementType":"None"},"End":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":1,"DateIncrementType":"None"}},"IncludePanel":true,"Domain":"Panel","Index":1},{"_typeTag":"Panel","SubPanels":[{"_typeTag":"SubPanel","PanelItems":[{"_typeTag":"PanelItem","Concept":{"_typeTag":"Concept","ParentId":"b5215ba6-fdd8-eb11-9c20-000c29db1cc8","RootId":"b5215ba6-fdd8-eb11-9c20-000c29db1cc8","ExternalId":"visit:9202","ExternalParentId":"visit","IsNumeric":false,"IsEventBased":false,"IsParent":true,"IsEncounterBased":true,"IsPatientCountAutoCalculated":false,"IsSpecializable":false,"SqlSetFrom":"omop.cdm_std.visit_occurrence","SqlSetWhere":"/* Outpatient Visit */ @.visit_concept_id = 9202","SqlFieldDate":"@.visit_start_datetime","SqlFieldNumeric":null,"SqlFieldEvent":null,"UiDisplayName":"Outpatient Visit","UiDisplayText":"Had an Outpatient Visit","UiDisplaySubtext":null,"UiDisplayUnits":null,"UiDisplayTooltip":null,"UiDisplayEventName":null,"UiDisplayPatientCount":3346382,"EventTypeId":null,"SpecializationGroups":[],"UiDisplayPatientCountByYear":null,"UiNumericDefaultText":null,"Id":"b7215ba6-fdd8-eb11-9c20-000c29db1cc8","UniversalId":null},"Specializations":[],"SqlRecencyFilter":null,"UseNumericFilter":false,"HasSpecializations":false,"UseRecencyFilter":false,"NumericFilter":{"_typeTag":"NumericFilter","FilterType":"None","Filter":[]},"RecencyFilter":"None","Index":0,"SubPanelIndex":0,"PanelIndex":0}],"HasCountFilter":false,"PanelIndex":2,"Index":0,"IncludeSubPanel":true,"MinimumCount":1,"JoinSequence":{"_typeTag":"SubPanelJoinSequence","Increment":1,"DateIncrementType":"Day","SequenceType":"Encounter"},"DateFilter":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":0,"DateIncrementType":"None"}},{"_typeTag":"SubPanel","PanelItems":[],"HasCountFilter":false,"PanelIndex":2,"Index":1,"IncludeSubPanel":true,"MinimumCount":1,"JoinSequence":{"_typeTag":"SubPanelJoinSequence","Increment":1,"DateIncrementType":"Day","SequenceType":"Encounter"},"DateFilter":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":0,"DateIncrementType":"None"}}],"PanelType":"Sequence","IsDateFiltered":false,"DateFilter":{"_typeTag":"DateBoundary","Start":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":1,"DateIncrementType":"None"},"End":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":1,"DateIncrementType":"None"}},"IncludePanel":true,"Domain":"Panel","Index":2}],"PreflightPassed":true},"SourceContext":"Model.Cohort.CohortCounter","ActionId":"7c915b1a-2124-45b4-b5c5-bf8c57c79bad","ActionName":"API.Controllers.CohortCountController.Count (API)","RequestId":"0HM9R3D81014H:00000001","RequestPath":"/api/cohort/count","SpanId":"|98600d3e-4256a881e8028080.","TraceId":"98600d3e-4256a881e8028080","ParentId":"","ConnectionId":"0HM9R3D81014H","SessionId":"4991c429-d77c-45b2-8ea2-2f516d45c86d","User":"[email protected]@urn:leaf:issuer:leaf.mssm.edu"}}
{"Timestamp":"2021-06-30T11:03:54.9736826-04:00","Level":"Information","MessageTemplate":"FullCount cohort started.","Properties":{"SourceContext":"Model.Cohort.CohortCounter","ActionId":"7c915b1a-2124-45b4-b5c5-bf8c57c79bad","ActionName":"API.Controllers.CohortCountController.Count (API)","RequestId":"0HM9R3D81014H:00000001","RequestPath":"/api/cohort/count","SpanId":"|98600d3e-4256a881e8028080.","TraceId":"98600d3e-4256a881e8028080","ParentId":"","ConnectionId":"0HM9R3D81014H","SessionId":"4991c429-d77c-45b2-8ea2-2f516d45c86d","User":"[email protected]@urn:leaf:issuer:leaf.mssm.edu"}}
{"Timestamp":"2021-06-30T11:03:54.9739883-04:00","Level":"Information","MessageTemplate":"Parallel SqlStatements:{Sql}","Properties":{"Sql":["Model.Cohort.LeafQuery","Model.Cohort.LeafQuery"],"SourceContext":"Model.Cohort.PatientCohortService","ActionId":"7c915b1a-2124-45b4-b5c5-bf8c57c79bad","ActionName":"API.Controllers.CohortCountController.Count (API)","RequestId":"0HM9R3D81014H:00000001","RequestPath":"/api/cohort/count","SpanId":"|98600d3e-4256a881e8028080.","TraceId":"98600d3e-4256a881e8028080","ParentId":"","ConnectionId":"0HM9R3D81014H","SessionId":"4991c429-d77c-45b2-8ea2-2f516d45c86d","User":"[email protected]@urn:leaf:issuer:leaf.mssm.edu"}}
{"Timestamp":"2021-06-30T11:04:17.0369692-04:00","Level":"Information","MessageTemplate":"{HostingRequestStartingLog:l}","Properties":{"Protocol":"HTTP/1.1","Method":"GET","ContentType":null,"ContentLength":null,"Scheme":"http","Host":"10.95.46.180:5001","PathBase":"","Path":"/api/user/refresh","QueryString":"","HostingRequestStartingLog":"Request starting HTTP/1.1 GET http://10.95.46.180:5001/api/user/refresh  ","EventId":{"Id":1},"SourceContext":"Microsoft.AspNetCore.Hosting.Diagnostics","RequestId":"0HM9R3D81014I:00000001","RequestPath":"/api/user/refresh","SpanId":"|98600d3f-4256a881e8028080.","TraceId":"98600d3f-4256a881e8028080","ParentId":"","ConnectionId":"0HM9R3D81014I"},"Renderings":{"HostingRequestStartingLog":[{"Format":"l","Rendering":"Request starting HTTP/1.1 GET http://10.95.46.180:5001/api/user/refresh  "}]}}
{"Timestamp":"2021-06-30T11:04:17.0379935-04:00","Level":"Information","MessageTemplate":"Successfully validated the token.","Properties":{"EventId":{"Id":2,"Name":"TokenValidationSucceeded"},"SourceContext":"Microsoft.AspNetCore.Authentication.JwtBearer.JwtBearerHandler","RequestId":"0HM9R3D81014I:00000001","RequestPath":"/api/user/refresh","SpanId":"|98600d3f-4256a881e8028080.","TraceId":"98600d3f-4256a881e8028080","ParentId":"","ConnectionId":"0HM9R3D81014I"}}
{"Timestamp":"2021-06-30T11:04:17.0383124-04:00","Level":"Information","MessageTemplate":"Route matched with {RouteData}. Executing controller action with signature {MethodInfo} on controller {Controller} ({AssemblyName}).","Properties":{"RouteData":"{action = \"Refresh\", controller = \"User\"}","MethodInfo":"Microsoft.AspNetCore.Mvc.ActionResult`1[API.DTO.User.AccessTokenDTO] Refresh(Model.Authentication.ITokenBlacklistCache)","Controller":"API.Controllers.UserController","AssemblyName":"API","EventId":{"Id":3,"Name":"ControllerActionExecuting"},"SourceContext":"Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker","ActionId":"0d1b729b-6ac3-4e1a-a86f-4c5a2d2d765c","ActionName":"API.Controllers.UserController.Refresh (API)","RequestId":"0HM9R3D81014I:00000001","RequestPath":"/api/user/refresh","SpanId":"|98600d3f-4256a881e8028080.","TraceId":"98600d3f-4256a881e8028080","ParentId":"","ConnectionId":"0HM9R3D81014I","SessionId":"4991c429-d77c-45b2-8ea2-2f516d45c86d","User":"[email protected]@urn:leaf:issuer:leaf.mssm.edu"}}
{"Timestamp":"2021-06-30T11:04:17.0385277-04:00","Level":"Information","MessageTemplate":"Authorization was successful.","Properties":{"EventId":{"Id":1,"Name":"UserAuthorizationSucceeded"},"SourceContext":"Microsoft.AspNetCore.Authorization.DefaultAuthorizationService","ActionId":"0d1b729b-6ac3-4e1a-a86f-4c5a2d2d765c","ActionName":"API.Controllers.UserController.Refresh (API)","RequestId":"0HM9R3D81014I:00000001","RequestPath":"/api/user/refresh","SpanId":"|98600d3f-4256a881e8028080.","TraceId":"98600d3f-4256a881e8028080","ParentId":"","ConnectionId":"0HM9R3D81014I","SessionId":"4991c429-d77c-45b2-8ea2-2f516d45c86d","User":"[email protected]@urn:leaf:issuer:leaf.mssm.edu"}}
{"Timestamp":"2021-06-30T11:04:17.0471061-04:00","Level":"Information","MessageTemplate":"Refreshed Access Token. Token:{Token}","Properties":{"Token":"eyJhbGciOiJodHRwOi8vd3d3LnczLm9yZy8yMDAxLzA0L3htbGRzaWctbW9yZSNyc2Etc2hhNTEyIiwia2lkIjoiMkQ3NjczMjJDMDY5RUMxQUEwNjM4MEM2RUMzMDFFMUE4RkI2MzZGMCIsInR5cCI6IkpXVCJ9.eyJodHRwOi8vc2NoZW1hcy54bWxzb2FwLm9yZy93cy8yMDA1LzA1L2lkZW50aXR5L2NsYWltcy9uYW1lIjoiYXJ0aHVyLnAuZ29sZGJlcmdAbXNzbS5lZHUiLCJhdWQiOiJ1cm46bGVhZjppc3N1ZXI6bGVhZi5tc3NtLmVkdSIsImlkLW5vbmNlIjoiY2FlMmViNzctYTM0MS00YmE5LTk4ZTctOTZiNjI1OGYxMDcyIiwiYXV0aC10eXBlIjoiU2FtbDIiLCJsZWFmLXZlcnNpb24iOiIzLjkuMS4wIiwiaHR0cDovL3NjaGVtYXMubWljcm9zb2Z0LmNvbS93cy8yMDA4LzA2L2lkZW50aXR5L2NsYWltcy9yb2xlIjpbImFkbWluIiwicGhpIl0sImlzcyI6InVybjpsZWFmOmlzc3VlcjpsZWFmLm1zc20uZWR1IiwiYWNjZXNzLW5vbmNlIjoiNDk5MWM0MjktZDc3Yy00NWIyLThlYTItMmY1MTZkNDVjODZkIiwic2Vzc2lvbi10eXBlIjoicWkiLCJkYXRhLWNsYXNzIjoibm9pZCIsImlhdCI6IjE2MjUwNjU0NTciLCJ0b2tlbi10eXBlIjoiYWNjZXNzLXRva2VuIiwiZXhwIjoxNjI1MDY1ODE3fQ.HF5XGRbHvYY46AjzGXoc6WRhUcaInLp49bwFLZZ1jShpg3knhrSjDhw_F_YY9P2p6m8a0Vy3gS6WFfmWUlxKOAC1JxI41KHuozmDp8_4kibI734zlHpPOnS_Fh0kFWp8aPeDHBmeUz5fzyKoqCDJiJZfJOrURBraFlCZ7dOsBjc7DsfycRLqzBzeSQPOkX3GHVjvIcbDqRG8a8Xfzwrqzno8ZXTFTePCQ02x5OaKlA2D6J0DRSGxuIdGkHsVIVCeokoVdsHxAfdphhvWTw-AFbD76Bwo7Ii4JX748DZ0lH-dWv4VqlNbmr5p9FseeVOLELd7bCWNmeyZaTcK3iy2Rw","SourceContext":"API.Controllers.UserController","ActionId":"0d1b729b-6ac3-4e1a-a86f-4c5a2d2d765c","ActionName":"API.Controllers.UserController.Refresh (API)","RequestId":"0HM9R3D81014I:00000001","RequestPath":"/api/user/refresh","SpanId":"|98600d3f-4256a881e8028080.","TraceId":"98600d3f-4256a881e8028080","ParentId":"","ConnectionId":"0HM9R3D81014I","SessionId":"4991c429-d77c-45b2-8ea2-2f516d45c86d","User":"[email protected]@urn:leaf:issuer:leaf.mssm.edu"}}
{"Timestamp":"2021-06-30T11:04:17.0473628-04:00","Level":"Information","MessageTemplate":"Executing ObjectResult, writing value of type '{Type}'.","Properties":{"Type":"API.DTO.User.AccessTokenDTO","EventId":{"Id":1,"Name":"ObjectResultExecuting"},"SourceContext":"Microsoft.AspNetCore.Mvc.Infrastructure.ObjectResultExecutor","ActionId":"0d1b729b-6ac3-4e1a-a86f-4c5a2d2d765c","ActionName":"API.Controllers.UserController.Refresh (API)","RequestId":"0HM9R3D81014I:00000001","RequestPath":"/api/user/refresh","SpanId":"|98600d3f-4256a881e8028080.","TraceId":"98600d3f-4256a881e8028080","ParentId":"","ConnectionId":"0HM9R3D81014I","SessionId":"4991c429-d77c-45b2-8ea2-2f516d45c86d","User":"[email protected]@urn:leaf:issuer:leaf.mssm.edu"}}
{"Timestamp":"2021-06-30T11:04:17.0476211-04:00","Level":"Information","MessageTemplate":"Executed action {ActionName} in {ElapsedMilliseconds}ms","Properties":{"ActionName":"API.Controllers.UserController.Refresh (API)","ElapsedMilliseconds":9.1584,"EventId":{"Id":2,"Name":"ActionExecuted"},"SourceContext":"Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker","ActionId":"0d1b729b-6ac3-4e1a-a86f-4c5a2d2d765c","RequestId":"0HM9R3D81014I:00000001","RequestPath":"/api/user/refresh","SpanId":"|98600d3f-4256a881e8028080.","TraceId":"98600d3f-4256a881e8028080","ParentId":"","ConnectionId":"0HM9R3D81014I","SessionId":"4991c429-d77c-45b2-8ea2-2f516d45c86d","User":"[email protected]@urn:leaf:issuer:leaf.mssm.edu"}}
{"Timestamp":"2021-06-30T11:04:17.0477664-04:00","Level":"Information","MessageTemplate":"{HostingRequestFinishedLog:l}","Properties":{"ElapsedMilliseconds":10.8373,"StatusCode":200,"ContentType":"application/json; charset=utf-8","HostingRequestFinishedLog":"Request finished in 10.8373ms 200 application/json; charset=utf-8","EventId":{"Id":2},"SourceContext":"Microsoft.AspNetCore.Hosting.Diagnostics","RequestId":"0HM9R3D81014I:00000001","RequestPath":"/api/user/refresh","SpanId":"|98600d3f-4256a881e8028080.","TraceId":"98600d3f-4256a881e8028080","ParentId":"","ConnectionId":"0HM9R3D81014I"},"Renderings":{"HostingRequestFinishedLog":[{"Format":"l","Rendering":"Request finished in 10.8373ms 200 application/json; charset=utf-8"}]}}
{"Timestamp":"2021-06-30T11:04:17.0662415-04:00","Level":"Information","MessageTemplate":"{HostingRequestStartingLog:l}","Properties":{"Protocol":"HTTP/1.1","Method":"GET","ContentType":null,"ContentLength":null,"Scheme":"http","Host":"10.95.46.180:5001","PathBase":"","Path":"/api/user/refresh","QueryString":"","HostingRequestStartingLog":"Request starting HTTP/1.1 GET http://10.95.46.180:5001/api/user/refresh  ","EventId":{"Id":1},"SourceContext":"Microsoft.AspNetCore.Hosting.Diagnostics","RequestId":"0HM9R3D81014I:00000002","RequestPath":"/api/user/refresh","SpanId":"|98600d40-4256a881e8028080.","TraceId":"98600d40-4256a881e8028080","ParentId":"","ConnectionId":"0HM9R3D81014I"},"Renderings":{"HostingRequestStartingLog":[{"Format":"l","Rendering":"Request starting HTTP/1.1 GET http://10.95.46.180:5001/api/user/refresh  "}]}}
{"Timestamp":"2021-06-30T11:04:17.0671451-04:00","Level":"Information","MessageTemplate":"Successfully validated the token.","Properties":{"EventId":{"Id":2,"Name":"TokenValidationSucceeded"},"SourceContext":"Microsoft.AspNetCore.Authentication.JwtBearer.JwtBearerHandler","RequestId":"0HM9R3D81014I:00000002","RequestPath":"/api/user/refresh","SpanId":"|98600d40-4256a881e8028080.","TraceId":"98600d40-4256a881e8028080","ParentId":"","ConnectionId":"0HM9R3D81014I"}}
{"Timestamp":"2021-06-30T11:04:17.0674314-04:00","Level":"Information","MessageTemplate":"Route matched with {RouteData}. Executing controller action with signature {MethodInfo} on controller {Controller} ({AssemblyName}).","Properties":{"RouteData":"{action = \"Refresh\", controller = \"User\"}","MethodInfo":"Microsoft.AspNetCore.Mvc.ActionResult`1[API.DTO.User.AccessTokenDTO] Refresh(Model.Authentication.ITokenBlacklistCache)","Controller":"API.Controllers.UserController","AssemblyName":"API","EventId":{"Id":3,"Name":"ControllerActionExecuting"},"SourceContext":"Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker","ActionId":"0d1b729b-6ac3-4e1a-a86f-4c5a2d2d765c","ActionName":"API.Controllers.UserController.Refresh (API)","RequestId":"0HM9R3D81014I:00000002","RequestPath":"/api/user/refresh","SpanId":"|98600d40-4256a881e8028080.","TraceId":"98600d40-4256a881e8028080","ParentId":"","ConnectionId":"0HM9R3D81014I","SessionId":"4991c429-d77c-45b2-8ea2-2f516d45c86d","User":"[email protected]@urn:leaf:issuer:leaf.mssm.edu"}}
{"Timestamp":"2021-06-30T11:04:17.0676310-04:00","Level":"Information","MessageTemplate":"Authorization was successful.","Properties":{"EventId":{"Id":1,"Name":"UserAuthorizationSucceeded"},"SourceContext":"Microsoft.AspNetCore.Authorization.DefaultAuthorizationService","ActionId":"0d1b729b-6ac3-4e1a-a86f-4c5a2d2d765c","ActionName":"API.Controllers.UserController.Refresh (API)","RequestId":"0HM9R3D81014I:00000002","RequestPath":"/api/user/refresh","SpanId":"|98600d40-4256a881e8028080.","TraceId":"98600d40-4256a881e8028080","ParentId":"","ConnectionId":"0HM9R3D81014I","SessionId":"4991c429-d77c-45b2-8ea2-2f516d45c86d","User":"[email protected]@urn:leaf:issuer:leaf.mssm.edu"}}
{"Timestamp":"2021-06-30T11:04:17.0750167-04:00","Level":"Information","MessageTemplate":"Refreshed Access Token. Token:{Token}","Properties":{"Token":"eyJhbGciOiJodHRwOi8vd3d3LnczLm9yZy8yMDAxLzA0L3htbGRzaWctbW9yZSNyc2Etc2hhNTEyIiwia2lkIjoiMkQ3NjczMjJDMDY5RUMxQUEwNjM4MEM2RUMzMDFFMUE4RkI2MzZGMCIsInR5cCI6IkpXVCJ9.eyJodHRwOi8vc2NoZW1hcy54bWxzb2FwLm9yZy93cy8yMDA1LzA1L2lkZW50aXR5L2NsYWltcy9uYW1lIjoiYXJ0aHVyLnAuZ29sZGJlcmdAbXNzbS5lZHUiLCJhdWQiOiJ1cm46bGVhZjppc3N1ZXI6bGVhZi5tc3NtLmVkdSIsImlkLW5vbmNlIjoiY2FlMmViNzctYTM0MS00YmE5LTk4ZTctOTZiNjI1OGYxMDcyIiwiYXV0aC10eXBlIjoiU2FtbDIiLCJsZWFmLXZlcnNpb24iOiIzLjkuMS4wIiwiaHR0cDovL3NjaGVtYXMubWljcm9zb2Z0LmNvbS93cy8yMDA4LzA2L2lkZW50aXR5L2NsYWltcy9yb2xlIjpbImFkbWluIiwicGhpIl0sImlzcyI6InVybjpsZWFmOmlzc3VlcjpsZWFmLm1zc20uZWR1IiwiYWNjZXNzLW5vbmNlIjoiNDk5MWM0MjktZDc3Yy00NWIyLThlYTItMmY1MTZkNDVjODZkIiwic2Vzc2lvbi10eXBlIjoicWkiLCJkYXRhLWNsYXNzIjoibm9pZCIsImlhdCI6IjE2MjUwNjU0NTciLCJ0b2tlbi10eXBlIjoiYWNjZXNzLXRva2VuIiwiZXhwIjoxNjI1MDY1ODE3fQ.HF5XGRbHvYY46AjzGXoc6WRhUcaInLp49bwFLZZ1jShpg3knhrSjDhw_F_YY9P2p6m8a0Vy3gS6WFfmWUlxKOAC1JxI41KHuozmDp8_4kibI734zlHpPOnS_Fh0kFWp8aPeDHBmeUz5fzyKoqCDJiJZfJOrURBraFlCZ7dOsBjc7DsfycRLqzBzeSQPOkX3GHVjvIcbDqRG8a8Xfzwrqzno8ZXTFTePCQ02x5OaKlA2D6J0DRSGxuIdGkHsVIVCeokoVdsHxAfdphhvWTw-AFbD76Bwo7Ii4JX748DZ0lH-dWv4VqlNbmr5p9FseeVOLELd7bCWNmeyZaTcK3iy2Rw","SourceContext":"API.Controllers.UserController","ActionId":"0d1b729b-6ac3-4e1a-a86f-4c5a2d2d765c","ActionName":"API.Controllers.UserController.Refresh (API)","RequestId":"0HM9R3D81014I:00000002","RequestPath":"/api/user/refresh","SpanId":"|98600d40-4256a881e8028080.","TraceId":"98600d40-4256a881e8028080","ParentId":"","ConnectionId":"0HM9R3D81014I","SessionId":"4991c429-d77c-45b2-8ea2-2f516d45c86d","User":"[email protected]@urn:leaf:issuer:leaf.mssm.edu"}}
{"Timestamp":"2021-06-30T11:04:17.0752388-04:00","Level":"Information","MessageTemplate":"Executing ObjectResult, writing value of type '{Type}'.","Properties":{"Type":"API.DTO.User.AccessTokenDTO","EventId":{"Id":1,"Name":"ObjectResultExecuting"},"SourceContext":"Microsoft.AspNetCore.Mvc.Infrastructure.ObjectResultExecutor","ActionId":"0d1b729b-6ac3-4e1a-a86f-4c5a2d2d765c","ActionName":"API.Controllers.UserController.Refresh (API)","RequestId":"0HM9R3D81014I:00000002","RequestPath":"/api/user/refresh","SpanId":"|98600d40-4256a881e8028080.","TraceId":"98600d40-4256a881e8028080","ParentId":"","ConnectionId":"0HM9R3D81014I","SessionId":"4991c429-d77c-45b2-8ea2-2f516d45c86d","User":"[email protected]@urn:leaf:issuer:leaf.mssm.edu"}}
{"Timestamp":"2021-06-30T11:04:17.0755041-04:00","Level":"Information","MessageTemplate":"Executed action {ActionName} in {ElapsedMilliseconds}ms","Properties":{"ActionName":"API.Controllers.UserController.Refresh (API)","ElapsedMilliseconds":7.9297,"EventId":{"Id":2,"Name":"ActionExecuted"},"SourceContext":"Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker","ActionId":"0d1b729b-6ac3-4e1a-a86f-4c5a2d2d765c","RequestId":"0HM9R3D81014I:00000002","RequestPath":"/api/user/refresh","SpanId":"|98600d40-4256a881e8028080.","TraceId":"98600d40-4256a881e8028080","ParentId":"","ConnectionId":"0HM9R3D81014I","SessionId":"4991c429-d77c-45b2-8ea2-2f516d45c86d","User":"[email protected]@urn:leaf:issuer:leaf.mssm.edu"}}
{"Timestamp":"2021-06-30T11:04:17.0756308-04:00","Level":"Information","MessageTemplate":"{HostingRequestFinishedLog:l}","Properties":{"ElapsedMilliseconds":9.4231,"StatusCode":200,"ContentType":"application/json; charset=utf-8","HostingRequestFinishedLog":"Request finished in 9.4231ms 200 application/json; charset=utf-8","EventId":{"Id":2},"SourceContext":"Microsoft.AspNetCore.Hosting.Diagnostics","RequestId":"0HM9R3D81014I:00000002","RequestPath":"/api/user/refresh","SpanId":"|98600d40-4256a881e8028080.","TraceId":"98600d40-4256a881e8028080","ParentId":"","ConnectionId":"0HM9R3D81014I"},"Renderings":{"HostingRequestFinishedLog":[{"Format":"l","Rendering":"Request finished in 9.4231ms 200 application/json; charset=utf-8"}]}}
{"Timestamp":"2021-06-30T11:04:19.4046667-04:00","Level":"Information","MessageTemplate":"Refreshed TokenBlacklistCache","Properties":{"SourceContext":"API.Jobs.BackgroundTokenBlacklistSynchronizer"}}

Perhaps I should return to "QueryStrategy": "CTE", recreate the 'severe' error, isolate the query, and test its execution and duration in other environments. Can we have the dbms driver (ODBC, or another one) log its messages?

Thanks Arthur

[artgoldberg]

Hello again @ndobb

I returned to using "QueryStrategy": "CTE". This query (taken from the Leaf log) generates a timeout at 60 s. in Leaf:

WITH wrapper (personId) AS
 ( SELECT P1.person_id 
   FROM ( SELECT  _S100.person_id FROM omop.cdm_std.visit_occurrence AS
 _S100 
 WHERE /* Outpatient Visit */ _S100.visit_concept_id = 9202 
 GROUP BY _S100.person_id ) 
 AS
 P1 INTERSECT SELECT P0.person_id 
 FROM ( SELECT  _S000.person_id 
   FROM omop.cdm_std.person AS  _S000
   WHERE /* Current Age */ (DATEDIFF(DAY, _S000.birth_datetime, GETDATE()) / 365.25) >= 66 ) AS
 P0 ) SELECT personId FROM wrapper

But it runs for over 160 minutes when executed in DBeaver connected to the same SQL Server via Microsoft JDBC Driver for SQL Server. (At that point I terminated it.) Thus, some aspect of Leaf's connection to the DBMS or the parameters being passed to the DBMS are causing the timeout.

Here's the SQL Server version: SQL Server version: Microsoft SQL Server 2019 (RTM) - 15.0.2000.5 (X64) Sep 24 2019 13:48:23 Enterprise Edition: Core-based Licensing (64-bit) on Windows Server 2019 Standard 10.0 <X64> (Build 17763: ) (Hypervisor)

Below you find the Leaf log messages issued from just before the query was executed until it timed out. A 'severe' error arose: A severe error occurred on the current command.

{"Timestamp":"2021-06-30T13:11:09.1365281-04:00","Level":"Information","MessageTemplate":"Refreshed TokenBlacklistCache","Properties":{"SourceContext":"API.Jobs.BackgroundTokenBlacklistSynchronizer"}}
{"Timestamp":"2021-06-30T13:11:13.5299480-04:00","Level":"Information","MessageTemplate":"{HostingRequestStartingLog:l}","Properties":{"Protocol":"HTTP/1.1","Method":"POST","ContentType":"application/json;charset=UTF-8","ContentLength":2203,"Scheme":"http","Host":"10.95.46.180:5001","PathBase":"","Path":"/api/cohort/count","QueryString":"","HostingRequestStartingLog":"Request starting HTTP/1.1 POST http://10.95.46.180:5001/api/cohort/count application/json;charset=UTF-8 2203","EventId":{"Id":1},"SourceContext":"Microsoft.AspNetCore.Hosting.Diagnostics","RequestId":"0HM9RT887VBRD:00000001","RequestPath":"/api/cohort/count","SpanId":"|9bc165-4182130c06ea2b4d.","TraceId":"9bc165-4182130c06ea2b4d","ParentId":"","ConnectionId":"0HM9RT887VBRD"},"Renderings":{"HostingRequestStartingLog":[{"Format":"l","Rendering":"Request starting HTTP/1.1 POST http://10.95.46.180:5001/api/cohort/count application/json;charset=UTF-8 2203"}]}}
{"Timestamp":"2021-06-30T13:11:13.5345689-04:00","Level":"Information","MessageTemplate":"CORS policy execution successful.","Properties":{"EventId":{"Id":4,"Name":"PolicySuccess"},"SourceContext":"Microsoft.AspNetCore.Cors.Infrastructure.CorsService","RequestId":"0HM9RT887VBRD:00000001","RequestPath":"/api/cohort/count","SpanId":"|9bc165-4182130c06ea2b4d.","TraceId":"9bc165-4182130c06ea2b4d","ParentId":"","ConnectionId":"0HM9RT887VBRD"}}
{"Timestamp":"2021-06-30T13:11:13.6679374-04:00","Level":"Information","MessageTemplate":"Successfully validated the token.","Properties":{"EventId":{"Id":2,"Name":"TokenValidationSucceeded"},"SourceContext":"Microsoft.AspNetCore.Authentication.JwtBearer.JwtBearerHandler","RequestId":"0HM9RT887VBRD:00000001","RequestPath":"/api/cohort/count","SpanId":"|9bc165-4182130c06ea2b4d.","TraceId":"9bc165-4182130c06ea2b4d","ParentId":"","ConnectionId":"0HM9RT887VBRD"}}
{"Timestamp":"2021-06-30T13:11:13.7757214-04:00","Level":"Information","MessageTemplate":"Route matched with {RouteData}. Executing controller action with signature {MethodInfo} on controller {Controller} ({AssemblyName}).","Properties":{"RouteData":"{action = \"Count\", controller = \"CohortCount\"}","MethodInfo":"System.Threading.Tasks.Task`1[Microsoft.AspNetCore.Mvc.ActionResult`1[API.DTO.Cohort.CohortCountDTO]] Count(API.DTO.Cohort.PatientCountQueryDTO, Model.Cohort.CohortCounter, System.Threading.CancellationToken)","Controller":"API.Controllers.CohortCountController","AssemblyName":"API","EventId":{"Id":3,"Name":"ControllerActionExecuting"},"SourceContext":"Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker","ActionId":"3a529037-7e01-48ec-80ef-e7aed2136d5d","ActionName":"API.Controllers.CohortCountController.Count (API)","RequestId":"0HM9RT887VBRD:00000001","RequestPath":"/api/cohort/count","SpanId":"|9bc165-4182130c06ea2b4d.","TraceId":"9bc165-4182130c06ea2b4d","ParentId":"","ConnectionId":"0HM9RT887VBRD","SessionId":"72836c0a-50ca-4958-ac0b-e0b37f8587ab","User":"[email protected]@urn:leaf:issuer:leaf.mssm.edu"}}
{"Timestamp":"2021-06-30T13:11:13.7798051-04:00","Level":"Information","MessageTemplate":"Authorization was successful.","Properties":{"EventId":{"Id":1,"Name":"UserAuthorizationSucceeded"},"SourceContext":"Microsoft.AspNetCore.Authorization.DefaultAuthorizationService","ActionId":"3a529037-7e01-48ec-80ef-e7aed2136d5d","ActionName":"API.Controllers.CohortCountController.Count (API)","RequestId":"0HM9RT887VBRD:00000001","RequestPath":"/api/cohort/count","SpanId":"|9bc165-4182130c06ea2b4d.","TraceId":"9bc165-4182130c06ea2b4d","ParentId":"","ConnectionId":"0HM9RT887VBRD","SessionId":"72836c0a-50ca-4958-ac0b-e0b37f8587ab","User":"[email protected]@urn:leaf:issuer:leaf.mssm.edu"}}
{"Timestamp":"2021-06-30T13:11:13.9263576-04:00","Level":"Information","MessageTemplate":"FullCount starting. DTO:{@DTO}","Properties":{"DTO":{"_typeTag":"PatientCountQueryDTO","QueryId":"","Panels":[{"_typeTag":"PanelDTO","Id":"fZaIV_hgTIk","SubPanels":[{"_typeTag":"SubPanelDTO","Id":"peKNW6-KyPJ","PanelItems":[{"_typeTag":"PanelItemDTO","Id":"kebzDDgUO","Resource":{"_typeTag":"ResourceRef","Id":"8d94847b-fbd8-eb11-9c20-000c29db1cc8","UniversalId":null,"UiDisplayName":"Age"},"Specializations":[],"NumericFilter":{"_typeTag":"NumericFilter","FilterType":"GreaterThanOrEqualTo","Filter":[66]},"RecencyFilter":"None","Index":0,"SubPanelIndex":0,"PanelIndex":0}],"PanelIndex":0,"Index":0,"IncludeSubPanel":true,"MinimumCount":1,"JoinSequence":{"_typeTag":"SubPanelJoinSequence","Increment":1,"DateIncrementType":"Day","SequenceType":"Encounter"},"DateFilter":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":0,"DateIncrementType":"None"}},{"_typeTag":"SubPanelDTO","Id":"ETa3il37gG","PanelItems":[],"PanelIndex":0,"Index":1,"IncludeSubPanel":true,"MinimumCount":1,"JoinSequence":{"_typeTag":"SubPanelJoinSequence","Increment":1,"DateIncrementType":"Day","SequenceType":"Encounter"},"DateFilter":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":0,"DateIncrementType":"None"}}],"DateFilter":{"_typeTag":"DateBoundary","Start":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":1,"DateIncrementType":"None"},"End":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":1,"DateIncrementType":"None"}},"IncludePanel":true,"Domain":"Panel","Index":0},{"_typeTag":"PanelDTO","Id":"daVecIlCWma","SubPanels":[{"_typeTag":"SubPanelDTO","Id":"80dCqonfyo2","PanelItems":[{"_typeTag":"PanelItemDTO","Id":"DluGcUuPV","Resource":{"_typeTag":"ResourceRef","Id":"b7215ba6-fdd8-eb11-9c20-000c29db1cc8","UniversalId":null,"UiDisplayName":"Outpatient Visit"},"Specializations":[],"NumericFilter":{"_typeTag":"NumericFilter","FilterType":"None","Filter":[]},"RecencyFilter":"None","Index":0,"SubPanelIndex":0,"PanelIndex":0}],"PanelIndex":1,"Index":0,"IncludeSubPanel":true,"MinimumCount":1,"JoinSequence":{"_typeTag":"SubPanelJoinSequence","Increment":1,"DateIncrementType":"Day","SequenceType":"Encounter"},"DateFilter":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":0,"DateIncrementType":"None"}},{"_typeTag":"SubPanelDTO","Id":"XW0SMSnIGe","PanelItems":[],"PanelIndex":1,"Index":1,"IncludeSubPanel":true,"MinimumCount":1,"JoinSequence":{"_typeTag":"SubPanelJoinSequence","Increment":1,"DateIncrementType":"Day","SequenceType":"Encounter"},"DateFilter":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":0,"DateIncrementType":"None"}}],"DateFilter":{"_typeTag":"DateBoundary","Start":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":1,"DateIncrementType":"None"},"End":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":1,"DateIncrementType":"None"}},"IncludePanel":true,"Domain":"Panel","Index":1},{"_typeTag":"PanelDTO","Id":"_mLfoe9g2Wz","SubPanels":[{"_typeTag":"SubPanelDTO","Id":"_ungKfIAoVO","PanelItems":[],"PanelIndex":2,"Index":0,"IncludeSubPanel":true,"MinimumCount":1,"JoinSequence":{"_typeTag":"SubPanelJoinSequence","Increment":1,"DateIncrementType":"Day","SequenceType":"Encounter"},"DateFilter":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":0,"DateIncrementType":"None"}}],"DateFilter":{"_typeTag":"DateBoundary","Start":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":1,"DateIncrementType":"None"},"End":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":1,"DateIncrementType":"None"}},"IncludePanel":true,"Domain":"Panel","Index":2}],"PanelFilters":[]},"SourceContext":"Model.Cohort.CohortCounter","ActionId":"3a529037-7e01-48ec-80ef-e7aed2136d5d","ActionName":"API.Controllers.CohortCountController.Count (API)","RequestId":"0HM9RT887VBRD:00000001","RequestPath":"/api/cohort/count","SpanId":"|9bc165-4182130c06ea2b4d.","TraceId":"9bc165-4182130c06ea2b4d","ParentId":"","ConnectionId":"0HM9RT887VBRD","SessionId":"72836c0a-50ca-4958-ac0b-e0b37f8587ab","User":"[email protected]@urn:leaf:issuer:leaf.mssm.edu"}}
{"Timestamp":"2021-06-30T13:11:13.9330624-04:00","Level":"Information","MessageTemplate":"Getting preflight resources check. Refs:{@Refs}","Properties":{"Refs":{"_typeTag":"ResourceRefs","Concepts":[{"_typeTag":"ConceptRef","Id":"8d94847b-fbd8-eb11-9c20-000c29db1cc8","UniversalId":null},{"_typeTag":"ConceptRef","Id":"b7215ba6-fdd8-eb11-9c20-000c29db1cc8","UniversalId":null}],"Queries":[],"Imports":[]},"SourceContext":"Model.Search.PreflightResourceChecker","ActionId":"3a529037-7e01-48ec-80ef-e7aed2136d5d","ActionName":"API.Controllers.CohortCountController.Count (API)","RequestId":"0HM9RT887VBRD:00000001","RequestPath":"/api/cohort/count","SpanId":"|9bc165-4182130c06ea2b4d.","TraceId":"9bc165-4182130c06ea2b4d","ParentId":"","ConnectionId":"0HM9RT887VBRD","SessionId":"72836c0a-50ca-4958-ac0b-e0b37f8587ab","User":"[email protected]@urn:leaf:issuer:leaf.mssm.edu"}}
{"Timestamp":"2021-06-30T13:11:14.0464939-04:00","Level":"Information","MessageTemplate":"FullCount panel validation context. Context:{@Context}","Properties":{"Context":{"_typeTag":"PanelValidationContext","QueryId":null,"UniversalId":null,"PreflightCheck":{"_typeTag":"PreflightResources","Ok":true,"DirectConceptsCheck":{"_typeTag":"PreflightConcepts","PreflightCheck":{"_typeTag":"ConceptPreflightCheck","Ok":true,"Results":[{"_typeTag":"ConceptPreflightCheckResult","Id":"8d94847b-fbd8-eb11-9c20-000c29db1cc8","UniversalId":null,"IsPresent":true,"IsAuthorized":true},{"_typeTag":"ConceptPreflightCheckResult","Id":"b7215ba6-fdd8-eb11-9c20-000c29db1cc8","UniversalId":null,"IsPresent":true,"IsAuthorized":true}],"IsPresent":true,"IsAuthorized":true},"Concepts":[{"_typeTag":"Concept","ParentId":"8c94847b-fbd8-eb11-9c20-000c29db1cc8","RootId":"8c94847b-fbd8-eb11-9c20-000c29db1cc8","ExternalId":"demographics:age","ExternalParentId":"demographics","IsNumeric":true,"IsEventBased":false,"IsParent":false,"IsEncounterBased":false,"IsPatientCountAutoCalculated":false,"IsSpecializable":false,"SqlSetFrom":"omop.cdm_std.person","SqlSetWhere":null,"SqlFieldDate":null,"SqlFieldNumeric":"/* Current Age */ (DATEDIFF(DAY, @.birth_datetime, GETDATE()) / 365.25)","SqlFieldEvent":null,"UiDisplayName":"Age","UiDisplayText":"Are","UiDisplaySubtext":null,"UiDisplayUnits":"years old","UiDisplayTooltip":null,"UiDisplayEventName":null,"UiDisplayPatientCount":68826766,"EventTypeId":null,"SpecializationGroups":[],"UiDisplayPatientCountByYear":null,"UiNumericDefaultText":"any current age","Id":"8d94847b-fbd8-eb11-9c20-000c29db1cc8","UniversalId":null},{"_typeTag":"Concept","ParentId":"b5215ba6-fdd8-eb11-9c20-000c29db1cc8","RootId":"b5215ba6-fdd8-eb11-9c20-000c29db1cc8","ExternalId":"visit:9202","ExternalParentId":"visit","IsNumeric":false,"IsEventBased":false,"IsParent":true,"IsEncounterBased":true,"IsPatientCountAutoCalculated":false,"IsSpecializable":false,"SqlSetFrom":"omop.cdm_std.visit_occurrence","SqlSetWhere":"/* Outpatient Visit */ @.visit_concept_id = 9202","SqlFieldDate":"@.visit_start_datetime","SqlFieldNumeric":null,"SqlFieldEvent":null,"UiDisplayName":"Outpatient Visit","UiDisplayText":"Had an Outpatient Visit","UiDisplaySubtext":null,"UiDisplayUnits":null,"UiDisplayTooltip":null,"UiDisplayEventName":null,"UiDisplayPatientCount":3346382,"EventTypeId":null,"SpecializationGroups":[],"UiDisplayPatientCountByYear":null,"UiNumericDefaultText":null,"Id":"b7215ba6-fdd8-eb11-9c20-000c29db1cc8","UniversalId":null}],"IsPresent":true,"IsAuthorized":true,"Ok":true},"DirectQueriesCheck":{"_typeTag":"PreflightQueries","Ok":true,"Results":[]},"DirectImportsCheck":{"_typeTag":"PreflightImports","Ok":true,"Results":[]},"GlobalPanelFilters":[]},"Requested":[{"_typeTag":"PanelDTO","Id":"fZaIV_hgTIk","SubPanels":[{"_typeTag":"SubPanelDTO","Id":"peKNW6-KyPJ","PanelItems":[{"_typeTag":"PanelItemDTO","Id":"kebzDDgUO","Resource":{"_typeTag":"ResourceRef","Id":"8d94847b-fbd8-eb11-9c20-000c29db1cc8","UniversalId":null,"UiDisplayName":"Age"},"Specializations":[],"NumericFilter":{"_typeTag":"NumericFilter","FilterType":"GreaterThanOrEqualTo","Filter":[66]},"RecencyFilter":"None","Index":0,"SubPanelIndex":0,"PanelIndex":0}],"PanelIndex":0,"Index":0,"IncludeSubPanel":true,"MinimumCount":1,"JoinSequence":{"_typeTag":"SubPanelJoinSequence","Increment":1,"DateIncrementType":"Day","SequenceType":"Encounter"},"DateFilter":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":0,"DateIncrementType":"None"}},{"_typeTag":"SubPanelDTO","Id":"ETa3il37gG","PanelItems":[],"PanelIndex":0,"Index":1,"IncludeSubPanel":true,"MinimumCount":1,"JoinSequence":{"_typeTag":"SubPanelJoinSequence","Increment":1,"DateIncrementType":"Day","SequenceType":"Encounter"},"DateFilter":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":0,"DateIncrementType":"None"}}],"DateFilter":{"_typeTag":"DateBoundary","Start":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":1,"DateIncrementType":"None"},"End":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":1,"DateIncrementType":"None"}},"IncludePanel":true,"Domain":"Panel","Index":0},{"_typeTag":"PanelDTO","Id":"daVecIlCWma","SubPanels":[{"_typeTag":"SubPanelDTO","Id":"80dCqonfyo2","PanelItems":[{"_typeTag":"PanelItemDTO","Id":"DluGcUuPV","Resource":{"_typeTag":"ResourceRef","Id":"b7215ba6-fdd8-eb11-9c20-000c29db1cc8","UniversalId":null,"UiDisplayName":"Outpatient Visit"},"Specializations":[],"NumericFilter":{"_typeTag":"NumericFilter","FilterType":"None","Filter":[]},"RecencyFilter":"None","Index":0,"SubPanelIndex":0,"PanelIndex":0}],"PanelIndex":1,"Index":0,"IncludeSubPanel":true,"MinimumCount":1,"JoinSequence":{"_typeTag":"SubPanelJoinSequence","Increment":1,"DateIncrementType":"Day","SequenceType":"Encounter"},"DateFilter":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":0,"DateIncrementType":"None"}},{"_typeTag":"SubPanelDTO","Id":"XW0SMSnIGe","PanelItems":[],"PanelIndex":1,"Index":1,"IncludeSubPanel":true,"MinimumCount":1,"JoinSequence":{"_typeTag":"SubPanelJoinSequence","Increment":1,"DateIncrementType":"Day","SequenceType":"Encounter"},"DateFilter":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":0,"DateIncrementType":"None"}}],"DateFilter":{"_typeTag":"DateBoundary","Start":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":1,"DateIncrementType":"None"},"End":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":1,"DateIncrementType":"None"}},"IncludePanel":true,"Domain":"Panel","Index":1},{"_typeTag":"PanelDTO","Id":"_mLfoe9g2Wz","SubPanels":[{"_typeTag":"SubPanelDTO","Id":"_ungKfIAoVO","PanelItems":[],"PanelIndex":2,"Index":0,"IncludeSubPanel":true,"MinimumCount":1,"JoinSequence":{"_typeTag":"SubPanelJoinSequence","Increment":1,"DateIncrementType":"Day","SequenceType":"Encounter"},"DateFilter":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":0,"DateIncrementType":"None"}}],"DateFilter":{"_typeTag":"DateBoundary","Start":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":1,"DateIncrementType":"None"},"End":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":1,"DateIncrementType":"None"}},"IncludePanel":true,"Domain":"Panel","Index":2}],"Allowed":[{"_typeTag":"Panel","SubPanels":[{"_typeTag":"SubPanel","PanelItems":[{"_typeTag":"PanelItem","Concept":{"_typeTag":"Concept","ParentId":"8c94847b-fbd8-eb11-9c20-000c29db1cc8","RootId":"8c94847b-fbd8-eb11-9c20-000c29db1cc8","ExternalId":"demographics:age","ExternalParentId":"demographics","IsNumeric":true,"IsEventBased":false,"IsParent":false,"IsEncounterBased":false,"IsPatientCountAutoCalculated":false,"IsSpecializable":false,"SqlSetFrom":"omop.cdm_std.person","SqlSetWhere":null,"SqlFieldDate":null,"SqlFieldNumeric":"/* Current Age */ (DATEDIFF(DAY, @.birth_datetime, GETDATE()) / 365.25)","SqlFieldEvent":null,"UiDisplayName":"Age","UiDisplayText":"Are","UiDisplaySubtext":null,"UiDisplayUnits":"years old","UiDisplayTooltip":null,"UiDisplayEventName":null,"UiDisplayPatientCount":68826766,"EventTypeId":null,"SpecializationGroups":[],"UiDisplayPatientCountByYear":null,"UiNumericDefaultText":"any current age","Id":"8d94847b-fbd8-eb11-9c20-000c29db1cc8","UniversalId":null},"Specializations":[],"SqlRecencyFilter":null,"UseNumericFilter":true,"HasSpecializations":false,"UseRecencyFilter":false,"NumericFilter":{"_typeTag":"NumericFilter","FilterType":"GreaterThanOrEqualTo","Filter":[66]},"RecencyFilter":"None","Index":0,"SubPanelIndex":0,"PanelIndex":0}],"HasCountFilter":false,"PanelIndex":0,"Index":0,"IncludeSubPanel":true,"MinimumCount":1,"JoinSequence":{"_typeTag":"SubPanelJoinSequence","Increment":1,"DateIncrementType":"Day","SequenceType":"Encounter"},"DateFilter":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":0,"DateIncrementType":"None"}},{"_typeTag":"SubPanel","PanelItems":[],"HasCountFilter":false,"PanelIndex":0,"Index":1,"IncludeSubPanel":true,"MinimumCount":1,"JoinSequence":{"_typeTag":"SubPanelJoinSequence","Increment":1,"DateIncrementType":"Day","SequenceType":"Encounter"},"DateFilter":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":0,"DateIncrementType":"None"}}],"PanelType":"Sequence","IsDateFiltered":false,"DateFilter":{"_typeTag":"DateBoundary","Start":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":1,"DateIncrementType":"None"},"End":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":1,"DateIncrementType":"None"}},"IncludePanel":true,"Domain":"Panel","Index":0},{"_typeTag":"Panel","SubPanels":[{"_typeTag":"SubPanel","PanelItems":[{"_typeTag":"PanelItem","Concept":{"_typeTag":"Concept","ParentId":"b5215ba6-fdd8-eb11-9c20-000c29db1cc8","RootId":"b5215ba6-fdd8-eb11-9c20-000c29db1cc8","ExternalId":"visit:9202","ExternalParentId":"visit","IsNumeric":false,"IsEventBased":false,"IsParent":true,"IsEncounterBased":true,"IsPatientCountAutoCalculated":false,"IsSpecializable":false,"SqlSetFrom":"omop.cdm_std.visit_occurrence","SqlSetWhere":"/* Outpatient Visit */ @.visit_concept_id = 9202","SqlFieldDate":"@.visit_start_datetime","SqlFieldNumeric":null,"SqlFieldEvent":null,"UiDisplayName":"Outpatient Visit","UiDisplayText":"Had an Outpatient Visit","UiDisplaySubtext":null,"UiDisplayUnits":null,"UiDisplayTooltip":null,"UiDisplayEventName":null,"UiDisplayPatientCount":3346382,"EventTypeId":null,"SpecializationGroups":[],"UiDisplayPatientCountByYear":null,"UiNumericDefaultText":null,"Id":"b7215ba6-fdd8-eb11-9c20-000c29db1cc8","UniversalId":null},"Specializations":[],"SqlRecencyFilter":null,"UseNumericFilter":false,"HasSpecializations":false,"UseRecencyFilter":false,"NumericFilter":{"_typeTag":"NumericFilter","FilterType":"None","Filter":[]},"RecencyFilter":"None","Index":0,"SubPanelIndex":0,"PanelIndex":0}],"HasCountFilter":false,"PanelIndex":1,"Index":0,"IncludeSubPanel":true,"MinimumCount":1,"JoinSequence":{"_typeTag":"SubPanelJoinSequence","Increment":1,"DateIncrementType":"Day","SequenceType":"Encounter"},"DateFilter":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":0,"DateIncrementType":"None"}},{"_typeTag":"SubPanel","PanelItems":[],"HasCountFilter":false,"PanelIndex":1,"Index":1,"IncludeSubPanel":true,"MinimumCount":1,"JoinSequence":{"_typeTag":"SubPanelJoinSequence","Increment":1,"DateIncrementType":"Day","SequenceType":"Encounter"},"DateFilter":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":0,"DateIncrementType":"None"}}],"PanelType":"Sequence","IsDateFiltered":false,"DateFilter":{"_typeTag":"DateBoundary","Start":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":1,"DateIncrementType":"None"},"End":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":1,"DateIncrementType":"None"}},"IncludePanel":true,"Domain":"Panel","Index":1},{"_typeTag":"Panel","SubPanels":[{"_typeTag":"SubPanel","PanelItems":[],"HasCountFilter":false,"PanelIndex":2,"Index":0,"IncludeSubPanel":true,"MinimumCount":1,"JoinSequence":{"_typeTag":"SubPanelJoinSequence","Increment":1,"DateIncrementType":"Day","SequenceType":"Encounter"},"DateFilter":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":0,"DateIncrementType":"None"}}],"PanelType":"Patient","IsDateFiltered":false,"DateFilter":{"_typeTag":"DateBoundary","Start":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":1,"DateIncrementType":"None"},"End":{"_typeTag":"DateFilter","Date":"0001-01-01T00:00:00.0000000","Increment":1,"DateIncrementType":"None"}},"IncludePanel":true,"Domain":"Panel","Index":2}],"PreflightPassed":true},"SourceContext":"Model.Cohort.CohortCounter","ActionId":"3a529037-7e01-48ec-80ef-e7aed2136d5d","ActionName":"API.Controllers.CohortCountController.Count (API)","RequestId":"0HM9RT887VBRD:00000001","RequestPath":"/api/cohort/count","SpanId":"|9bc165-4182130c06ea2b4d.","TraceId":"9bc165-4182130c06ea2b4d","ParentId":"","ConnectionId":"0HM9RT887VBRD","SessionId":"72836c0a-50ca-4958-ac0b-e0b37f8587ab","User":"[email protected]@urn:leaf:issuer:leaf.mssm.edu"}}
{"Timestamp":"2021-06-30T13:11:14.0507468-04:00","Level":"Information","MessageTemplate":"FullCount cohort started.","Properties":{"SourceContext":"Model.Cohort.CohortCounter","ActionId":"3a529037-7e01-48ec-80ef-e7aed2136d5d","ActionName":"API.Controllers.CohortCountController.Count (API)","RequestId":"0HM9RT887VBRD:00000001","RequestPath":"/api/cohort/count","SpanId":"|9bc165-4182130c06ea2b4d.","TraceId":"9bc165-4182130c06ea2b4d","ParentId":"","ConnectionId":"0HM9RT887VBRD","SessionId":"72836c0a-50ca-4958-ac0b-e0b37f8587ab","User":"[email protected]@urn:leaf:issuer:leaf.mssm.edu"}}
{"Timestamp":"2021-06-30T13:11:14.0667480-04:00","Level":"Information","MessageTemplate":"CTE SqlStatement:{Sql}","Properties":{"Sql":"DECLARE @IsIdentified BIT = 0; DECLARE @IsResearch   BIT = 0; DECLARE @IsQI         BIT = 1; WITH wrapper (personId) AS ( SELECT P1.person_id FROM ( SELECT  _S100.person_id FROM omop.cdm_std.visit_occurrence AS _S100 WHERE /* Outpatient Visit */ _S100.visit_concept_id = 9202 GROUP BY _S100.person_id ) AS P1 INTERSECT SELECT P0.person_id FROM ( SELECT  _S000.person_id FROM omop.cdm_std.person AS _S000 WHERE /* Current Age */ (DATEDIFF(DAY, _S000.birth_datetime, GETDATE()) / 365.25) >= 66 ) AS P0 ) SELECT personId FROM wrapper","SourceContext":"Model.Cohort.PatientCohortService","ActionId":"3a529037-7e01-48ec-80ef-e7aed2136d5d","ActionName":"API.Controllers.CohortCountController.Count (API)","RequestId":"0HM9RT887VBRD:00000001","RequestPath":"/api/cohort/count","SpanId":"|9bc165-4182130c06ea2b4d.","TraceId":"9bc165-4182130c06ea2b4d","ParentId":"","ConnectionId":"0HM9RT887VBRD","SessionId":"72836c0a-50ca-4958-ac0b-e0b37f8587ab","User":"[email protected]@urn:leaf:issuer:leaf.mssm.edu"}}
{"Timestamp":"2021-06-30T13:11:39.1410886-04:00","Level":"Information","MessageTemplate":"Refreshed TokenBlacklistCache","Properties":{"SourceContext":"API.Jobs.BackgroundTokenBlacklistSynchronizer"}}
{"Timestamp":"2021-06-30T13:11:40.0820993-04:00","Level":"Information","MessageTemplate":"{HostingRequestStartingLog:l}","Properties":{"Protocol":"HTTP/1.1","Method":"GET","ContentType":null,"ContentLength":null,"Scheme":"http","Host":"10.95.46.180:5001","PathBase":"","Path":"/api/user/refresh","QueryString":"","HostingRequestStartingLog":"Request starting HTTP/1.1 GET http://10.95.46.180:5001/api/user/refresh  ","EventId":{"Id":1},"SourceContext":"Microsoft.AspNetCore.Hosting.Diagnostics","RequestId":"0HM9RT887VBRE:00000001","RequestPath":"/api/user/refresh","SpanId":"|9bc166-4182130c06ea2b4d.","TraceId":"9bc166-4182130c06ea2b4d","ParentId":"","ConnectionId":"0HM9RT887VBRE"},"Renderings":{"HostingRequestStartingLog":[{"Format":"l","Rendering":"Request starting HTTP/1.1 GET http://10.95.46.180:5001/api/user/refresh  "}]}}
{"Timestamp":"2021-06-30T13:11:40.0880636-04:00","Level":"Information","MessageTemplate":"Successfully validated the token.","Properties":{"EventId":{"Id":2,"Name":"TokenValidationSucceeded"},"SourceContext":"Microsoft.AspNetCore.Authentication.JwtBearer.JwtBearerHandler","RequestId":"0HM9RT887VBRE:00000001","RequestPath":"/api/user/refresh","SpanId":"|9bc166-4182130c06ea2b4d.","TraceId":"9bc166-4182130c06ea2b4d","ParentId":"","ConnectionId":"0HM9RT887VBRE"}}
{"Timestamp":"2021-06-30T13:11:40.0950746-04:00","Level":"Information","MessageTemplate":"Route matched with {RouteData}. Executing controller action with signature {MethodInfo} on controller {Controller} ({AssemblyName}).","Properties":{"RouteData":"{action = \"Refresh\", controller = \"User\"}","MethodInfo":"Microsoft.AspNetCore.Mvc.ActionResult`1[API.DTO.User.AccessTokenDTO] Refresh(Model.Authentication.ITokenBlacklistCache)","Controller":"API.Controllers.UserController","AssemblyName":"API","EventId":{"Id":3,"Name":"ControllerActionExecuting"},"SourceContext":"Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker","ActionId":"b98a5301-0f96-4431-b685-211f9a95fc63","ActionName":"API.Controllers.UserController.Refresh (API)","RequestId":"0HM9RT887VBRE:00000001","RequestPath":"/api/user/refresh","SpanId":"|9bc166-4182130c06ea2b4d.","TraceId":"9bc166-4182130c06ea2b4d","ParentId":"","ConnectionId":"0HM9RT887VBRE","SessionId":"72836c0a-50ca-4958-ac0b-e0b37f8587ab","User":"[email protected]@urn:leaf:issuer:leaf.mssm.edu"}}
{"Timestamp":"2021-06-30T13:11:40.0959168-04:00","Level":"Information","MessageTemplate":"Authorization was successful.","Properties":{"EventId":{"Id":1,"Name":"UserAuthorizationSucceeded"},"SourceContext":"Microsoft.AspNetCore.Authorization.DefaultAuthorizationService","ActionId":"b98a5301-0f96-4431-b685-211f9a95fc63","ActionName":"API.Controllers.UserController.Refresh (API)","RequestId":"0HM9RT887VBRE:00000001","RequestPath":"/api/user/refresh","SpanId":"|9bc166-4182130c06ea2b4d.","TraceId":"9bc166-4182130c06ea2b4d","ParentId":"","ConnectionId":"0HM9RT887VBRE","SessionId":"72836c0a-50ca-4958-ac0b-e0b37f8587ab","User":"[email protected]@urn:leaf:issuer:leaf.mssm.edu"}}
{"Timestamp":"2021-06-30T13:11:40.1313601-04:00","Level":"Information","MessageTemplate":"Refreshed Access Token. Token:{Token}","Properties":{"Token":"eyJhbGciOiJodHRwOi8vd3d3LnczLm9yZy8yMDAxLzA0L3htbGRzaWctbW9yZSNyc2Etc2hhNTEyIiwia2lkIjoiMkQ3NjczMjJDMDY5RUMxQUEwNjM4MEM2RUMzMDFFMUE4RkI2MzZGMCIsInR5cCI6IkpXVCJ9.eyJodHRwOi8vc2NoZW1hcy54bWxzb2FwLm9yZy93cy8yMDA1LzA1L2lkZW50aXR5L2NsYWltcy9uYW1lIjoiYXJ0aHVyLnAuZ29sZGJlcmdAbXNzbS5lZHUiLCJhdWQiOiJ1cm46bGVhZjppc3N1ZXI6bGVhZi5tc3NtLmVkdSIsImlkLW5vbmNlIjoiY2FlMmViNzctYTM0MS00YmE5LTk4ZTctOTZiNjI1OGYxMDcyIiwiYXV0aC10eXBlIjoiU2FtbDIiLCJsZWFmLXZlcnNpb24iOiIzLjkuMS4wIiwiaHR0cDovL3NjaGVtYXMubWljcm9zb2Z0LmNvbS93cy8yMDA4LzA2L2lkZW50aXR5L2NsYWltcy9yb2xlIjpbImFkbWluIiwicGhpIl0sImlzcyI6InVybjpsZWFmOmlzc3VlcjpsZWFmLm1zc20uZWR1IiwiYWNjZXNzLW5vbmNlIjoiNzI4MzZjMGEtNTBjYS00OTU4LWFjMGItZTBiMzdmODU4N2FiIiwic2Vzc2lvbi10eXBlIjoicWkiLCJkYXRhLWNsYXNzIjoibm9pZCIsImlhdCI6IjE2MjUwNzMxMDAiLCJ0b2tlbi10eXBlIjoiYWNjZXNzLXRva2VuIiwiZXhwIjoxNjI1MDczNDYwfQ.XWOKcxv3WCy8_-d88X52-OVj8huE9fdt5oEbQwH6gHJS1TMgqNUqTof8NFkpEGY3daf3bgp5XfH6tTp62DCtHYLmLm6NC4KImWqw6iWzV4PfKfh1M1GG60CjsycC6FitLTpBJ356A-O5HAyKZwmyGU9gzrj_uWOYHPvukNbTMShJ84ZWm8_Ca0wqfrW6uUtUvhklJBLY9vJGzIM1VJNDpF0Igrc9ELerYUZ36bnfD9dzTpFFnqiJBzcagF23f9PJEWuUWI75DaPJtRBWDsfv3rMi98umCvznPhPRhSAoZDpCvbyHVYJPMrwu1Gha_2IHd2xThrGQ23l6aLImYmQ83Q","SourceContext":"API.Controllers.UserController","ActionId":"b98a5301-0f96-4431-b685-211f9a95fc63","ActionName":"API.Controllers.UserController.Refresh (API)","RequestId":"0HM9RT887VBRE:00000001","RequestPath":"/api/user/refresh","SpanId":"|9bc166-4182130c06ea2b4d.","TraceId":"9bc166-4182130c06ea2b4d","ParentId":"","ConnectionId":"0HM9RT887VBRE","SessionId":"72836c0a-50ca-4958-ac0b-e0b37f8587ab","User":"[email protected]@urn:leaf:issuer:leaf.mssm.edu"}}
{"Timestamp":"2021-06-30T13:11:40.1360593-04:00","Level":"Information","MessageTemplate":"Executing ObjectResult, writing value of type '{Type}'.","Properties":{"Type":"API.DTO.User.AccessTokenDTO","EventId":{"Id":1,"Name":"ObjectResultExecuting"},"SourceContext":"Microsoft.AspNetCore.Mvc.Infrastructure.ObjectResultExecutor","ActionId":"b98a5301-0f96-4431-b685-211f9a95fc63","ActionName":"API.Controllers.UserController.Refresh (API)","RequestId":"0HM9RT887VBRE:00000001","RequestPath":"/api/user/refresh","SpanId":"|9bc166-4182130c06ea2b4d.","TraceId":"9bc166-4182130c06ea2b4d","ParentId":"","ConnectionId":"0HM9RT887VBRE","SessionId":"72836c0a-50ca-4958-ac0b-e0b37f8587ab","User":"[email protected]@urn:leaf:issuer:leaf.mssm.edu"}}
{"Timestamp":"2021-06-30T13:11:40.1661726-04:00","Level":"Information","MessageTemplate":"Executed action {ActionName} in {ElapsedMilliseconds}ms","Properties":{"ActionName":"API.Controllers.UserController.Refresh (API)","ElapsedMilliseconds":67.2718,"EventId":{"Id":2,"Name":"ActionExecuted"},"SourceContext":"Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker","ActionId":"b98a5301-0f96-4431-b685-211f9a95fc63","RequestId":"0HM9RT887VBRE:00000001","RequestPath":"/api/user/refresh","SpanId":"|9bc166-4182130c06ea2b4d.","TraceId":"9bc166-4182130c06ea2b4d","ParentId":"","ConnectionId":"0HM9RT887VBRE","SessionId":"72836c0a-50ca-4958-ac0b-e0b37f8587ab","User":"[email protected]@urn:leaf:issuer:leaf.mssm.edu"}}
{"Timestamp":"2021-06-30T13:11:40.1673763-04:00","Level":"Information","MessageTemplate":"{HostingRequestFinishedLog:l}","Properties":{"ElapsedMilliseconds":85.7094,"StatusCode":200,"ContentType":"application/json; charset=utf-8","HostingRequestFinishedLog":"Request finished in 85.7094ms 200 application/json; charset=utf-8","EventId":{"Id":2},"SourceContext":"Microsoft.AspNetCore.Hosting.Diagnostics","RequestId":"0HM9RT887VBRE:00000001","RequestPath":"/api/user/refresh","SpanId":"|9bc166-4182130c06ea2b4d.","TraceId":"9bc166-4182130c06ea2b4d","ParentId":"","ConnectionId":"0HM9RT887VBRE"},"Renderings":{"HostingRequestFinishedLog":[{"Format":"l","Rendering":"Request finished in 85.7094ms 200 application/json; charset=utf-8"}]}}
{"Timestamp":"2021-06-30T13:11:40.2027897-04:00","Level":"Information","MessageTemplate":"{HostingRequestStartingLog:l}","Properties":{"Protocol":"HTTP/1.1","Method":"GET","ContentType":null,"ContentLength":null,"Scheme":"http","Host":"10.95.46.180:5001","PathBase":"","Path":"/api/user/refresh","QueryString":"","HostingRequestStartingLog":"Request starting HTTP/1.1 GET http://10.95.46.180:5001/api/user/refresh  ","EventId":{"Id":1},"SourceContext":"Microsoft.AspNetCore.Hosting.Diagnostics","RequestId":"0HM9RT887VBRE:00000002","RequestPath":"/api/user/refresh","SpanId":"|9bc167-4182130c06ea2b4d.","TraceId":"9bc167-4182130c06ea2b4d","ParentId":"","ConnectionId":"0HM9RT887VBRE"},"Renderings":{"HostingRequestStartingLog":[{"Format":"l","Rendering":"Request starting HTTP/1.1 GET http://10.95.46.180:5001/api/user/refresh  "}]}}
{"Timestamp":"2021-06-30T13:11:40.2076507-04:00","Level":"Information","MessageTemplate":"Successfully validated the token.","Properties":{"EventId":{"Id":2,"Name":"TokenValidationSucceeded"},"SourceContext":"Microsoft.AspNetCore.Authentication.JwtBearer.JwtBearerHandler","RequestId":"0HM9RT887VBRE:00000002","RequestPath":"/api/user/refresh","SpanId":"|9bc167-4182130c06ea2b4d.","TraceId":"9bc167-4182130c06ea2b4d","ParentId":"","ConnectionId":"0HM9RT887VBRE"}}
{"Timestamp":"2021-06-30T13:11:40.2104555-04:00","Level":"Information","MessageTemplate":"Route matched with {RouteData}. Executing controller action with signature {MethodInfo} on controller {Controller} ({AssemblyName}).","Properties":{"RouteData":"{action = \"Refresh\", controller = \"User\"}","MethodInfo":"Microsoft.AspNetCore.Mvc.ActionResult`1[API.DTO.User.AccessTokenDTO] Refresh(Model.Authentication.ITokenBlacklistCache)","Controller":"API.Controllers.UserController","AssemblyName":"API","EventId":{"Id":3,"Name":"ControllerActionExecuting"},"SourceContext":"Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker","ActionId":"b98a5301-0f96-4431-b685-211f9a95fc63","ActionName":"API.Controllers.UserController.Refresh (API)","RequestId":"0HM9RT887VBRE:00000002","RequestPath":"/api/user/refresh","SpanId":"|9bc167-4182130c06ea2b4d.","TraceId":"9bc167-4182130c06ea2b4d","ParentId":"","ConnectionId":"0HM9RT887VBRE","SessionId":"72836c0a-50ca-4958-ac0b-e0b37f8587ab","User":"[email protected]@urn:leaf:issuer:leaf.mssm.edu"}}
{"Timestamp":"2021-06-30T13:11:40.2119576-04:00","Level":"Information","MessageTemplate":"Authorization was successful.","Properties":{"EventId":{"Id":1,"Name":"UserAuthorizationSucceeded"},"SourceContext":"Microsoft.AspNetCore.Authorization.DefaultAuthorizationService","ActionId":"b98a5301-0f96-4431-b685-211f9a95fc63","ActionName":"API.Controllers.UserController.Refresh (API)","RequestId":"0HM9RT887VBRE:00000002","RequestPath":"/api/user/refresh","SpanId":"|9bc167-4182130c06ea2b4d.","TraceId":"9bc167-4182130c06ea2b4d","ParentId":"","ConnectionId":"0HM9RT887VBRE","SessionId":"72836c0a-50ca-4958-ac0b-e0b37f8587ab","User":"[email protected]@urn:leaf:issuer:leaf.mssm.edu"}}
{"Timestamp":"2021-06-30T13:11:40.2186087-04:00","Level":"Information","MessageTemplate":"Refreshed Access Token. Token:{Token}","Properties":{"Token":"eyJhbGciOiJodHRwOi8vd3d3LnczLm9yZy8yMDAxLzA0L3htbGRzaWctbW9yZSNyc2Etc2hhNTEyIiwia2lkIjoiMkQ3NjczMjJDMDY5RUMxQUEwNjM4MEM2RUMzMDFFMUE4RkI2MzZGMCIsInR5cCI6IkpXVCJ9.eyJodHRwOi8vc2NoZW1hcy54bWxzb2FwLm9yZy93cy8yMDA1LzA1L2lkZW50aXR5L2NsYWltcy9uYW1lIjoiYXJ0aHVyLnAuZ29sZGJlcmdAbXNzbS5lZHUiLCJhdWQiOiJ1cm46bGVhZjppc3N1ZXI6bGVhZi5tc3NtLmVkdSIsImlkLW5vbmNlIjoiY2FlMmViNzctYTM0MS00YmE5LTk4ZTctOTZiNjI1OGYxMDcyIiwiYXV0aC10eXBlIjoiU2FtbDIiLCJsZWFmLXZlcnNpb24iOiIzLjkuMS4wIiwiaHR0cDovL3NjaGVtYXMubWljcm9zb2Z0LmNvbS93cy8yMDA4LzA2L2lkZW50aXR5L2NsYWltcy9yb2xlIjpbImFkbWluIiwicGhpIl0sImlzcyI6InVybjpsZWFmOmlzc3VlcjpsZWFmLm1zc20uZWR1IiwiYWNjZXNzLW5vbmNlIjoiNzI4MzZjMGEtNTBjYS00OTU4LWFjMGItZTBiMzdmODU4N2FiIiwic2Vzc2lvbi10eXBlIjoicWkiLCJkYXRhLWNsYXNzIjoibm9pZCIsImlhdCI6IjE2MjUwNzMxMDAiLCJ0b2tlbi10eXBlIjoiYWNjZXNzLXRva2VuIiwiZXhwIjoxNjI1MDczNDYwfQ.XWOKcxv3WCy8_-d88X52-OVj8huE9fdt5oEbQwH6gHJS1TMgqNUqTof8NFkpEGY3daf3bgp5XfH6tTp62DCtHYLmLm6NC4KImWqw6iWzV4PfKfh1M1GG60CjsycC6FitLTpBJ356A-O5HAyKZwmyGU9gzrj_uWOYHPvukNbTMShJ84ZWm8_Ca0wqfrW6uUtUvhklJBLY9vJGzIM1VJNDpF0Igrc9ELerYUZ36bnfD9dzTpFFnqiJBzcagF23f9PJEWuUWI75DaPJtRBWDsfv3rMi98umCvznPhPRhSAoZDpCvbyHVYJPMrwu1Gha_2IHd2xThrGQ23l6aLImYmQ83Q","SourceContext":"API.Controllers.UserController","ActionId":"b98a5301-0f96-4431-b685-211f9a95fc63","ActionName":"API.Controllers.UserController.Refresh (API)","RequestId":"0HM9RT887VBRE:00000002","RequestPath":"/api/user/refresh","SpanId":"|9bc167-4182130c06ea2b4d.","TraceId":"9bc167-4182130c06ea2b4d","ParentId":"","ConnectionId":"0HM9RT887VBRE","SessionId":"72836c0a-50ca-4958-ac0b-e0b37f8587ab","User":"[email protected]@urn:leaf:issuer:leaf.mssm.edu"}}
{"Timestamp":"2021-06-30T13:11:40.2190629-04:00","Level":"Information","MessageTemplate":"Executing ObjectResult, writing value of type '{Type}'.","Properties":{"Type":"API.DTO.User.AccessTokenDTO","EventId":{"Id":1,"Name":"ObjectResultExecuting"},"SourceContext":"Microsoft.AspNetCore.Mvc.Infrastructure.ObjectResultExecutor","ActionId":"b98a5301-0f96-4431-b685-211f9a95fc63","ActionName":"API.Controllers.UserController.Refresh (API)","RequestId":"0HM9RT887VBRE:00000002","RequestPath":"/api/user/refresh","SpanId":"|9bc167-4182130c06ea2b4d.","TraceId":"9bc167-4182130c06ea2b4d","ParentId":"","ConnectionId":"0HM9RT887VBRE","SessionId":"72836c0a-50ca-4958-ac0b-e0b37f8587ab","User":"[email protected]@urn:leaf:issuer:leaf.mssm.edu"}}
{"Timestamp":"2021-06-30T13:11:40.2196044-04:00","Level":"Information","MessageTemplate":"Executed action {ActionName} in {ElapsedMilliseconds}ms","Properties":{"ActionName":"API.Controllers.UserController.Refresh (API)","ElapsedMilliseconds":8.8866,"EventId":{"Id":2,"Name":"ActionExecuted"},"SourceContext":"Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker","ActionId":"b98a5301-0f96-4431-b685-211f9a95fc63","RequestId":"0HM9RT887VBRE:00000002","RequestPath":"/api/user/refresh","SpanId":"|9bc167-4182130c06ea2b4d.","TraceId":"9bc167-4182130c06ea2b4d","ParentId":"","ConnectionId":"0HM9RT887VBRE","SessionId":"72836c0a-50ca-4958-ac0b-e0b37f8587ab","User":"[email protected]@urn:leaf:issuer:leaf.mssm.edu"}}
{"Timestamp":"2021-06-30T13:11:40.2198390-04:00","Level":"Information","MessageTemplate":"{HostingRequestFinishedLog:l}","Properties":{"ElapsedMilliseconds":17.1082,"StatusCode":200,"ContentType":"application/json; charset=utf-8","HostingRequestFinishedLog":"Request finished in 17.1082ms 200 application/json; charset=utf-8","EventId":{"Id":2},"SourceContext":"Microsoft.AspNetCore.Hosting.Diagnostics","RequestId":"0HM9RT887VBRE:00000002","RequestPath":"/api/user/refresh","SpanId":"|9bc167-4182130c06ea2b4d.","TraceId":"9bc167-4182130c06ea2b4d","ParentId":"","ConnectionId":"0HM9RT887VBRE"},"Renderings":{"HostingRequestFinishedLog":[{"Format":"l","Rendering":"Request finished in 17.1082ms 200 application/json; charset=utf-8"}]}}
{"Timestamp":"2021-06-30T13:12:09.1463148-04:00","Level":"Information","MessageTemplate":"Refreshed TokenBlacklistCache","Properties":{"SourceContext":"API.Jobs.BackgroundTokenBlacklistSynchronizer"}}
{"Timestamp":"2021-06-30T13:12:13.5779231-04:00","Level":"Error","MessageTemplate":"Failed to execute query. Error:{Error}","Properties":{"Error":"System.Data.SqlClient.SqlException (0x80131904): A severe error occurred on the current command.  The results, if any, should be discarded.\nOperation cancelled by user.\n   at System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseInAction)\n   at System.Data.SqlClient.SqlInternalConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseInAction)\n   at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose)\n   at System.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady)\n   at System.Data.SqlClient.SqlDataReader.TryHasMoreRows(Boolean& moreRows)\n   at System.Data.SqlClient.SqlDataReader.TryReadInternal(Boolean setTimeout, Boolean& more)\n   at System.Data.SqlClient.SqlDataReader.Read()\n   at Services.Cohort.CtePatientCohortService.GetPatientSetAsync(ISqlStatement query, CancellationToken token) in /var/opt/leafapi/leaf_download/leaf/src/server/Services/Cohort/CtePatientCohortService.cs:line 54\n   at Services.Cohort.CtePatientCohortService.GetCohortAsync(PatientCountQuery query, CancellationToken token) in /var/opt/leafapi/leaf_download/leaf/src/server/Services/Cohort/CtePatientCohortService.cs:line 32\n   at Model.Cohort.PatientCohortService.GetPatientCohortAsync(PatientCountQuery query, CancellationToken token) in /var/opt/leafapi/leaf_download/leaf/src/server/Model/Cohort/PatientCohortService.cs:line 35\n   at Model.Cohort.CohortCounter.FullCount(IPatientCountQueryDTO queryDTO, CancellationToken token) in /var/opt/leafapi/leaf_download/leaf/src/server/Model/Cohort/CohortCounter.cs:line 177\n   at Model.Cohort.CohortCounter.Count(IPatientCountQueryDTO queryDTO, CancellationToken token) in /var/opt/leafapi/leaf_download/leaf/src/server/Model/Cohort/CohortCounter.cs:line 89\n   at API.Controllers.CohortCountController.Count(PatientCountQueryDTO patientCountQuery, CohortCounter counter, CancellationToken cancelToken) in /var/opt/leafapi/leaf_download/leaf/src/server/API/Controllers/CohortCountController.cs:line 40\nClientConnectionId:45f6bb26-c2ea-436d-81cc-80fa9df48b65","SourceContext":"API.Controllers.CohortCountController","ActionId":"3a529037-7e01-48ec-80ef-e7aed2136d5d","ActionName":"API.Controllers.CohortCountController.Count (API)","RequestId":"0HM9RT887VBRD:00000001","RequestPath":"/api/cohort/count","SpanId":"|9bc165-4182130c06ea2b4d.","TraceId":"9bc165-4182130c06ea2b4d","ParentId":"","ConnectionId":"0HM9RT887VBRD","SessionId":"72836c0a-50ca-4958-ac0b-e0b37f8587ab","User":"[email protected]@urn:leaf:issuer:leaf.mssm.edu"}}
{"Timestamp":"2021-06-30T13:12:13.5844233-04:00","Level":"Information","MessageTemplate":"Executing HttpStatusCodeResult, setting HTTP status code {StatusCode}","Properties":{"StatusCode":500,"EventId":{"Id":1,"Name":"HttpStatusCodeResultExecuting"},"SourceContext":"Microsoft.AspNetCore.Mvc.StatusCodeResult","ActionId":"3a529037-7e01-48ec-80ef-e7aed2136d5d","ActionName":"API.Controllers.CohortCountController.Count (API)","RequestId":"0HM9RT887VBRD:00000001","RequestPath":"/api/cohort/count","SpanId":"|9bc165-4182130c06ea2b4d.","TraceId":"9bc165-4182130c06ea2b4d","ParentId":"","ConnectionId":"0HM9RT887VBRD","SessionId":"72836c0a-50ca-4958-ac0b-e0b37f8587ab","User":"[email protected]@urn:leaf:issuer:leaf.mssm.edu"}}
{"Timestamp":"2021-06-30T13:12:13.5853292-04:00","Level":"Information","MessageTemplate":"Executed action {ActionName} in {ElapsedMilliseconds}ms","Properties":{"ActionName":"API.Controllers.CohortCountController.Count (API)","ElapsedMilliseconds":59809.1273,"EventId":{"Id":2,"Name":"ActionExecuted"},"SourceContext":"Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker","ActionId":"3a529037-7e01-48ec-80ef-e7aed2136d5d","RequestId":"0HM9RT887VBRD:00000001","RequestPath":"/api/cohort/count","SpanId":"|9bc165-4182130c06ea2b4d.","TraceId":"9bc165-4182130c06ea2b4d","ParentId":"","ConnectionId":"0HM9RT887VBRD","SessionId":"72836c0a-50ca-4958-ac0b-e0b37f8587ab","User":"[email protected]@urn:leaf:issuer:leaf.mssm.edu"}}
{"Timestamp":"2021-06-30T13:12:13.5873853-04:00","Level":"Information","MessageTemplate":"{HostingRequestFinishedLog:l}","Properties":{"ElapsedMilliseconds":60059.9102,"StatusCode":0,"ContentType":null,"HostingRequestFinishedLog":"Request finished in 60059.9102ms 0 ","EventId":{"Id":2},"SourceContext":"Microsoft.AspNetCore.Hosting.Diagnostics","RequestId":"0HM9RT887VBRD:00000001","RequestPath":"/api/cohort/count","SpanId":"|9bc165-4182130c06ea2b4d.","TraceId":"9bc165-4182130c06ea2b4d","ParentId":"","ConnectionId":"0HM9RT887VBRD"},"Renderings":{"HostingRequestFinishedLog":[{"Format":"l","Rendering":"Request finished in 60059.9102ms 0 "}]}}

I can contact the people who run our SQL Server about this problem. But I think that I'll need to provide them with more information about Leaf's DBMS connection and the parameters it is sending to SQL Server.

Thanks! Arthur

[jnahmias]

This is odd, according to the MS Documentation, https://docs.microsoft.com/en-us/dotnet/api/system.data.sqlclient.sqlcommand.commandtimeout, the default for CommandTimeout is 30 seconds -- not 60.

[artgoldberg]

Thanks for looking into this @jnahmias . I don't have any thoughts about your observation.

But I've run some searches on the code which might be interesting.

The appsettings for the timeout seems to be used at leaf/src/server/API/Options/Config.Db.cs. And this gets assigned to opts.DefaultTimeout in StartupExtensions.Options.cs.

Timeouts in queries appear to be passed to SQL Server in commandTimeout attributes. One curious thing about this is that in QueryService.cs these are taken from dbOpts.DefaultTimeout, which doesn't appear to get initialized anywhere in my local clone of the code.

FYI, we're running Leaf 3.9.1 which is at this commit.

Arthur

[artgoldberg]

Hi @jnahmias @ndobb

I've replaced all occurrences of dbOpts.DefaultTimeout in QueryService.cs with 10 (which is seconds according to MSFT) and run Leaf queries that take longer than 10 s. I therefore conclude that these queries are not the ones that are timing out at 60 s.

Unsure what to do next to debug this.

A

[ndobb]

Hi @artgoldberg and @jnahmias,

I'm still mystified by this one as well and unfortunately don't have much to add. I agree with all points so far.

The QueryService.cs you mention @artgoldberg (which is a service for retrieving user saved queries), is passed an AppDbOptions object via dependency injection, which is initialized at startup and read from the appsettings file.

If I've misunderstood or am missing anything please let me know.

Best, -nic

[artgoldberg]

@ndobb , I'm starting to investigate this. Here's my approach:

1. Make easily repeatable
   1. Find at least 1 simple Leaf query X that consistently times out at 60 s, but consistently completes outside Leaf – taking more than 60 s
      1. Write scripts
         1. sqlcmd script that executes query X and summarizes its results and runtime
         2. command line program that runs query X through Leaf's call stack and reports its results (data or exception) and runtime
2. Get help from the internet
   1. Ask question in https://social.msdn.microsoft.com/Forums/en-US/home?forum=sqldatabaseengine
   2. Ask question in stackoverflow.com
3. Get help from our new DBA

[artgoldberg]

Hello @ndobb, @jnahmias and @lawdank

Twenty-one months later, our colleague Sheersha finally resolved this problem! We were looking in the wrong place for our keys, guys.

We're using Apache. It also has a timeout (see TimeOut in Core Apache HTTP Server features), with a default value of 60 seconds. Argh.

Nice work Sheersha.

Arthur

[lawdank]

Thanks @artgoldberg ! :)

[jnahmias]

Yay Sheersha!!