August 28, 2024, 11:00 am - 11:45 am central. Contact Stephen Fuqua for the meeting invitation.

Agenda

Demonstration of current work
Review the roadmap
Design Questions

Attendees: …, Brad Banister (Doubleline Partners on behalf of Ed-Fi), Vinaya Mayya (Ed-Fi Alliance), Stephen Fuqua (Ed-Fi Alliance).

Demonstration

Meeting notes:

Roadmap

Milestone 0.4

Milestone	Functional Goals
0.1 DONE	Compliant Discovery API, Descriptor API, and Resource API definition (except GET by query): able to run bulk upload, smoke test. Includes JSON validation based on API schema file. Fake OAuth (1).
0.2 DONE	📢 Milestone 0.2.0 has been reached! .NET application with PostgreSQL storage Level 0 and Level 1 document validation Reference and descriptor validation Error message like ODS/API 7.2 Docker and Kubernetes
0.3 IN PROGRESS	Streaming data out via Kafka GET by query using OpenSearch Cascading updates on allowed key changes Abandoned direct Kubernetes support as too costly by 10/1 (Ed-Fi Summit)
0.4 NEED TO ACCELERATE	Token authorization Client credentials management Namespace authorization Maybe by mid-October?
0.5	Design spikes around ed-org authorization Concurrency management with eTags Extensions Multiple data standards Maybe by mid-December?
0.6	Dynamic profiles Multitenancy and routing Maybe by mid-February?
0.7	Education organization authorization Claimset customization By Tech Congress?

Meeting notes:

Architecture

Storage of Metadata

This is a sample message in Kafka, created from Debezium:

_lastModifiedDate, _etag (and _lineage in the future?)
Store as metadata or add to the document itself? What should downstream consumers receive?
Already sending “API Standard” rather than “Data Standard”. Example: “SchoolYearType” instead of “SchoolYear”.

Tenancy Routing

GitHub Discussion for asynchronous conversation: Multitenancy / routing / instance management

Logging

Showing output from docker logs:

Initial Startup

dms-postgresql:5432 - no response
Waiting for PostgreSQL to start...
dms-postgresql:5432 - no response
Waiting for PostgreSQL to start...
dms-postgresql:5432 - accepting connections
PostgreSQL is ready.
Installing Data Management Service schema.
Master ConnectionString => Host=dms-postgresql;Port=5432;Username=postgres;Password=******;Database=postgres
Beginning database upgrade
Checking whether journal table exists..
Journal table does not exist
Executing Database Server script 'EdFi.DataManagementService.Backend.Postgresql.Deploy.Scripts.0000_Create_DMS_Schema.sql'
Checking whether journal table exists..
Creating the "schemaversions" table
The "schemaversions" table has been created
Executing Database Server script 'EdFi.DataManagementService.Backend.Postgresql.Deploy.Scripts.0001_Create_Document_Table.sql'
Executing Database Server script 'EdFi.DataManagementService.Backend.Postgresql.Deploy.Scripts.0002_Create_Alias_Table.sql'
Executing Database Server script 'EdFi.DataManagementService.Backend.Postgresql.Deploy.Scripts.0003_Create_Reference_Table.sql'
Executing Database Server script 'EdFi.DataManagementService.Backend.Postgresql.Deploy.Scripts.0004.1_Configure_Replication.sql'
Executing Database Server script 'EdFi.DataManagementService.Backend.Postgresql.Deploy.Scripts.0004.3_Configure_Replication.sql'
Executing Database Server script 'EdFi.DataManagementService.Backend.Postgresql.Deploy.Scripts.0010_Create_Insert_References_Procedure.sql'
Executing Database Server script 'EdFi.DataManagementService.Backend.Postgresql.Deploy.Scripts.1000_Create_Reference_Validation_FKs.sql'
Upgrade successful
2024-08-28 16:32:13.988 INF Injecting PostgreSQL as the primary backend datastore
2024-08-28 16:32:14.042 INF Injecting OpenSearch as the backend query handler
2024-08-28 16:32:14.133 DBG Hosting starting
2024-08-28 16:32:14.248 INF Now listening on: http://[::]:8080
2024-08-28 16:32:14.251 DBG Loaded hosting startup assembly EdFi.DataManagementService.Frontend.AspNetCore
2024-08-28 16:32:14.252 INF Application started. Press Ctrl+C to shut down.
2024-08-28 16:32:14.253 INF Hosting environment: Production
2024-08-28 16:32:14.253 INF Content root path: /app
2024-08-28 16:32:14.254 DBG Hosting started

First several lines are from a Bash script
Next block of lines, before the first one with a date/time stamp, is obviously from initial database setup.
any concern about these lines not having date/time stamp or a log level? If so, likely we can remedy that with a small user story. But if there is no concern, then it is not worth spending any time on it.

Happy Path Flow

2024-08-28 16:35:39.815 DBG Connection id "0HN67FTPTI90Q" accepted.
2024-08-28 16:35:39.816 DBG Connection id "0HN67FTPTI90Q" started.
2024-08-28 16:35:39.839 INF Request starting HTTP/1.1 POST http://localhost:8080/data/ed-fi/schoolYearTypes - null 103
2024-08-28 16:35:39.843 DBG Wildcard detected, all requests with hosts will be allowed.
2024-08-28 16:35:39.872 INF {"method":"POST","path":"/data/ed-fi/schoolYearTypes","traceId":"0HN67FTPTI90Q:00000001","clientId":{"Value":"localhost:8080","HasValue":true,"Host":"localhost","Port":8080}}
2024-08-28 16:35:39.915 DBG 1 candidate(s) found for the request path '/data/ed-fi/schoolYearTypes'
2024-08-28 16:35:39.917 DBG Endpoint 'HTTP: POST /data/{**dmsPath} => Upsert' with route pattern '/data/{**dmsPath}' is valid for the request path '/data/ed-fi/schoolYearTypes'
2024-08-28 16:35:39.918 DBG Request matched endpoint 'HTTP: POST /data/{**dmsPath} => Upsert'
2024-08-28 16:35:39.920 INF Executing endpoint 'HTTP: POST /data/{**dmsPath} => Upsert'
2024-08-28 16:35:40.046 DBG Connection id "0HN67FTPTI90Q", Request id "0HN67FTPTI90Q:00000001": started reading request body.
2024-08-28 16:35:40.046 DBG Connection id "0HN67FTPTI90Q", Request id "0HN67FTPTI90Q:00000001": done reading request body.
2024-08-28 16:35:40.056 DBG FrontendRequest: FrontendRequest { Path = /ed-fi/schoolYearTypes, Body = {
    "schoolYear": 2022,
    "schoolYearDescription": "2022-2023",
    "currentSchoolYear": true
}, QueryParameters = System.Collections.Generic.Dictionary`2[System.String,System.String], TraceId = TraceId { Value = 0HN67FTPTI90Q:00000001 } }
2024-08-28 16:35:40.056 DBG Entering ApiSchemaValidationMiddleware- TraceId { Value = 0HN67FTPTI90Q:00000001 }
2024-08-28 16:35:40.058 DBG Entering ApiSchemaFileLoader
2024-08-28 16:35:40.147 DBG Entering ApiSchemaSchemaProvider
2024-08-28 16:35:40.269 DBG Entering ProvideApiSchemaMiddleware- TraceId { Value = 0HN67FTPTI90Q:00000001 }
2024-08-28 16:35:40.270 DBG Entering ParsePathMiddleware - TraceId { Value = 0HN67FTPTI90Q:00000001 }
2024-08-28 16:35:40.273 DBG Entering ParseBodyMiddleware - TraceId { Value = 0HN67FTPTI90Q:00000001 }
2024-08-28 16:35:40.274 DBG Entering DuplicatePropertiesMiddleware - TraceId { Value = 0HN67FTPTI90Q:00000001 }
2024-08-28 16:35:40.275 DBG Entering ValidateEndpointMiddleware - TraceId { Value = 0HN67FTPTI90Q:00000001 }
2024-08-28 16:35:40.282 DBG Entering RejectResourceIdentifierMiddleware - TraceId { Value = 0HN67FTPTI90Q:00000001 }
2024-08-28 16:35:40.284 DBG Entering CoerceFromStringsMiddleware - TraceId { Value = 0HN67FTPTI90Q:00000001 }
2024-08-28 16:35:40.288 DBG Entering ValidateDocumentMiddleware- TraceId { Value = 0HN67FTPTI90Q:00000001 }
2024-08-28 16:35:40.296 DBG Entering ValidateEqualityConstraintMiddleware- TraceId { Value = 0HN67FTPTI90Q:00000001 }
2024-08-28 16:35:40.298 DBG Entering BuildResourceInfoMiddleware - TraceId { Value = 0HN67FTPTI90Q:00000001 }
2024-08-28 16:35:40.301 DBG Entering ExtractDocumentInfoMiddleware - TraceId { Value = 0HN67FTPTI90Q:00000001 }
2024-08-28 16:35:40.302 DBG IdentityExtractor.ExtractDocumentIdentity
2024-08-28 16:35:40.303 DBG IdentityExtractor.DeriveSuperclassIdentityFrom
2024-08-28 16:35:40.304 DBG ReferenceExtractor.Extract
2024-08-28 16:35:40.305 DBG DescriptorExtractor.Extract
2024-08-28 16:35:40.314 DBG Entering DuplicateReferencesMiddleware - TraceId { Value = 0HN67FTPTI90Q:00000001 }
2024-08-28 16:35:40.317 DBG Entering UpsertHandler - TraceId { Value = 0HN67FTPTI90Q:00000001 }
2024-08-28 16:35:40.323 DBG Resilience pipeline executing. Source: 'unknownFailureCircuitBreaker/(null)', Operation Key: 'null'
2024-08-28 16:35:40.332 DBG Entering PostgresqlDocumentStoreRepository.UpsertDocument - TraceId { Value = 0HN67FTPTI90Q:00000001 }
2024-08-28 16:35:40.403 DBG Entering UpsertDocument.Upsert - TraceId { Value = 0HN67FTPTI90Q:00000001 }
2024-08-28 16:35:40.496 DBG Upsert success as insert - TraceId { Value = 0HN67FTPTI90Q:00000001 }
2024-08-28 16:35:40.507 DBG Resilience pipeline executed. Source: 'unknownFailureCircuitBreaker/(null)', Operation Key: 'null', Result: 'InsertSuccess { NewDocumentUuid = DocumentUuid { Value = b0544561-30a3-4814-90ea-9a7c3e4104d5 } }', Execution Time: 182.7581ms
2024-08-28 16:35:40.509 DBG Document store UpsertDocument returned EdFi.DataManagementService.Core.External.Backend.UpsertResult+InsertSuccess- TraceId { Value = 0HN67FTPTI90Q:00000001 }
2024-08-28 16:35:40.511 DBG FrontendResponse: FrontendResponse { StatusCode = 201, Body = , Headers = System.Collections.Generic.Dictionary`2[System.String,System.String], LocationHeaderPath = /ed-fi/schoolYearTypes/b0544561-30a3-4814-90ea-9a7c3e4104d5 }
2024-08-28 16:35:40.519 INF Setting HTTP status code 201.
2024-08-28 16:35:40.519 INF Write content with HTTP Response ContentType of application/json; charset=utf-8
2024-08-28 16:35:40.520 INF Executed endpoint 'HTTP: POST /data/{**dmsPath} => Upsert'
2024-08-28 16:35:40.522 INF Request finished HTTP/1.1 POST http://localhost:8080/data/ed-fi/schoolYearTypes - 201 0 application/json; charset=utf-8 683.6045ms
2024-08-28 16:35:40.523 DBG Connection id "0HN67FTPTI90Q" disconnecting.
2024-08-28 16:35:40.523 DBG Connection id "0HN67FTPTI90Q" stopped.
2024-08-28 16:35:40.524 DBG Connection id "0HN67FTPTI90Q" sending FIN because: "The Socket transport's send loop completed gracefully."
2024-08-28 16:35:41.834 DBG Connection id "0HN67FTPTI90R" accepted.
2024-08-28 16:35:41.835 DBG Connection id "0HN67FTPTI90R" started.
2024-08-28 16:35:41.837 INF Request starting HTTP/1.1 GET http://localhost:8080/data/ed-fi/schoolYearTypes - null null
2024-08-28 16:35:41.837 INF {"method":"GET","path":"/data/ed-fi/schoolYearTypes","traceId":"0HN67FTPTI90R:00000001","clientId":{"Value":"localhost:8080","HasValue":true,"Host":"localhost","Port":8080}}
2024-08-28 16:35:41.839 DBG 1 candidate(s) found for the request path '/data/ed-fi/schoolYearTypes'
2024-08-28 16:35:41.839 DBG Endpoint 'HTTP: GET /data/{**dmsPath} => Get' with route pattern '/data/{**dmsPath}' is valid for the request path '/data/ed-fi/schoolYearTypes'
2024-08-28 16:35:41.839 DBG Request matched endpoint 'HTTP: GET /data/{**dmsPath} => Get'
2024-08-28 16:35:41.840 INF Executing endpoint 'HTTP: GET /data/{**dmsPath} => Get'
2024-08-28 16:35:41.843 DBG FrontendRequest: FrontendRequest { Path = /ed-fi/schoolYearTypes, Body = , QueryParameters = System.Collections.Generic.Dictionary`2[System.String,System.String], TraceId = TraceId { Value = 0HN67FTPTI90R:00000001 } }
2024-08-28 16:35:41.843 DBG Entering ApiSchemaValidationMiddleware- TraceId { Value = 0HN67FTPTI90R:00000001 }
2024-08-28 16:35:41.936 DBG Entering ProvideApiSchemaMiddleware- TraceId { Value = 0HN67FTPTI90R:00000001 }
2024-08-28 16:35:41.936 DBG Entering ParsePathMiddleware - TraceId { Value = 0HN67FTPTI90R:00000001 }
2024-08-28 16:35:41.936 DBG Entering ValidateEndpointMiddleware - TraceId { Value = 0HN67FTPTI90R:00000001 }
2024-08-28 16:35:41.936 DBG Entering BuildResourceInfoMiddleware - TraceId { Value = 0HN67FTPTI90R:00000001 }
2024-08-28 16:35:41.938 DBG Entering ValidateQueryMiddleware - TraceId { Value = 0HN67FTPTI90R:00000001 }
2024-08-28 16:35:41.940 DBG Entering QueryRequestHandler - TraceId { Value = 0HN67FTPTI90R:00000001 }
2024-08-28 16:35:41.940 DBG Resilience pipeline executing. Source: 'unknownFailureCircuitBreaker/(null)', Operation Key: 'null'
2024-08-28 16:35:41.942 DBG Entering OpenSearchQueryHandlerRepository.QueryDocuments - TraceId { Value = 0HN67FTPTI90R:00000001 }
2024-08-28 16:35:41.944 DBG Entering QueryOpenSearch.Query - TraceId { Value = 0HN67FTPTI90R:00000001 }
2024-08-28 16:35:42.030 DBG Resilience pipeline executed. Source: 'unknownFailureCircuitBreaker/(null)', Operation Key: 'null', Result: 'QuerySuccess { EdfiDocs = [], TotalCount = 0 }', Execution Time: 89.5347ms
2024-08-28 16:35:42.031 DBG QueryHandler returned EdFi.DataManagementService.Core.External.Backend.QueryResult+QuerySuccess- TraceId { Value = 0HN67FTPTI90R:00000001 }
2024-08-28 16:35:42.031 DBG FrontendResponse: FrontendResponse { StatusCode = 200, Body = [], Headers = System.Collections.Generic.Dictionary`2[System.String,System.String], LocationHeaderPath =  }
2024-08-28 16:35:42.032 INF Setting HTTP status code 200.
2024-08-28 16:35:42.032 INF Write content with HTTP Response ContentType of application/json; charset=utf-8
2024-08-28 16:35:42.033 INF Executed endpoint 'HTTP: GET /data/{**dmsPath} => Get'
2024-08-28 16:35:42.033 INF Request finished HTTP/1.1 GET http://localhost:8080/data/ed-fi/schoolYearTypes - 200 2 application/json; charset=utf-8 196.1507ms
2024-08-28 16:35:42.033 DBG Connection id "0HN67FTPTI90R" disconnecting.
2024-08-28 16:35:42.033 DBG Connection id "0HN67FTPTI90R" stopped.
2024-08-28 16:35:42.033 DBG Connection id "0HN67FTPTI90R" sending FIN because: "The Socket transport's send loop completed gracefully."

Most of this is telemetry information. Should this be going into the regular console log, or should we move that off to another log sink? (possibly using Open Telemetry).
We have not been very careful yet with our logging messages and we should do a little cleanup to make these more useful. For example:
```
INF Request starting HTTP/1.1 GET http://localhost:8080/data/ed-fi/schoolYearTypes - null null
INF {"method":"GET","path":"/data/ed-fi/schoolYearTypes","traceId":"0HN67FTPTI90R:00000001","clientId":{"Value":"localhost:8080","HasValue":true,"Host":"localhost","Port":8080}}
```
- We ended up logging the GET request twice
- We used structured logging in the second entry, but nowhere else.
- Sidenote: the traceId that you see here was auto-generated by ASP.NET. However, we have already built in support for using a correlation / trace ID header if it is present.
- I don’t know what that clientId value is about. Certainly not showing anything useful. I would have expected clientId to be something we pull from an auth token claim, but there was no auth token in this case.
- structured logs or unstructured? If we write our logging code correctly, we may be able to control this purely through Serilog settings, letting you choose structured or unstructured.
- The date/time and the level should probably be in the structured message.
Most of these debug messages show entry into a function. With the TraceId present, you can follow the performance for an individual request.
- The function entered is not consistently separated from TraceId with “space dash space”.
- Wouldn’t a structured message be easier to use here?

Client Error

Performed a POST operation with an invalid payload.

2024-08-28 16:49:48.668 DBG Connection id "0HN67FTPTI90S" accepted.
2024-08-28 16:49:48.669 DBG Connection id "0HN67FTPTI90S" started.
2024-08-28 16:49:48.670 INF Request starting HTTP/1.1 POST http://localhost:8080/data/ed-fi/schoolYearTypes - null 104
2024-08-28 16:49:48.670 INF {"method":"POST","path":"/data/ed-fi/schoolYearTypes","traceId":"0HN67FTPTI90S:00000001","clientId":{"Value":"localhost:8080","HasValue":true,"Host":"localhost","Port":8080}}
2024-08-28 16:49:48.670 DBG 1 candidate(s) found for the request path '/data/ed-fi/schoolYearTypes'
2024-08-28 16:49:48.671 DBG Endpoint 'HTTP: POST /data/{**dmsPath} => Upsert' with route pattern '/data/{**dmsPath}' is valid for the request path '/data/ed-fi/schoolYearTypes'
2024-08-28 16:49:48.671 DBG Request matched endpoint 'HTTP: POST /data/{**dmsPath} => Upsert'
2024-08-28 16:49:48.671 INF Executing endpoint 'HTTP: POST /data/{**dmsPath} => Upsert'
2024-08-28 16:49:48.671 DBG Connection id "0HN67FTPTI90S", Request id "0HN67FTPTI90S:00000001": started reading request body.
2024-08-28 16:49:48.671 DBG Connection id "0HN67FTPTI90S", Request id "0HN67FTPTI90S:00000001": done reading request body.
2024-08-28 16:49:48.671 DBG FrontendRequest: FrontendRequest { Path = /ed-fi/schoolYearTypes, Body = {
    "schoolYear": 2022,
    "schoolYearDescription": "2022-2023",
    "_currentSchoolYear": true
}, QueryParameters = System.Collections.Generic.Dictionary`2[System.String,System.String], TraceId = TraceId { Value = 0HN67FTPTI90S:00000001 } }
2024-08-28 16:49:48.672 DBG Entering ApiSchemaValidationMiddleware- TraceId { Value = 0HN67FTPTI90S:00000001 }
2024-08-28 16:49:48.672 DBG Entering ProvideApiSchemaMiddleware- TraceId { Value = 0HN67FTPTI90S:00000001 }
2024-08-28 16:49:48.672 DBG Entering ParsePathMiddleware - TraceId { Value = 0HN67FTPTI90S:00000001 }
2024-08-28 16:49:48.672 DBG Entering ParseBodyMiddleware - TraceId { Value = 0HN67FTPTI90S:00000001 }
2024-08-28 16:49:48.672 DBG Entering DuplicatePropertiesMiddleware - TraceId { Value = 0HN67FTPTI90S:00000001 }
2024-08-28 16:49:48.672 DBG Entering ValidateEndpointMiddleware - TraceId { Value = 0HN67FTPTI90S:00000001 }
2024-08-28 16:49:48.673 DBG Entering RejectResourceIdentifierMiddleware - TraceId { Value = 0HN67FTPTI90S:00000001 }
2024-08-28 16:49:48.673 DBG Entering CoerceFromStringsMiddleware - TraceId { Value = 0HN67FTPTI90S:00000001 }
2024-08-28 16:49:48.674 DBG Entering ValidateDocumentMiddleware- TraceId { Value = 0HN67FTPTI90S:00000001 }
2024-08-28 16:49:48.681 DBG '400'.'EndpointName { Value = schoolYearTypes }' - TraceId { Value = 0HN67FTPTI90S:00000001 }
2024-08-28 16:49:48.687 DBG FrontendResponse: FrontendResponse { StatusCode = 400, Body = {"validationErrors":{"$.currentSchoolYear":["currentSchoolYear is required."]},"errors":[],"detail":"Data validation failed. See 'validationErrors' for details.","type":"urn:ed-fi:api:bad-request:data-validation-failed","title":"Data Validation Failed","status":400,"correlationId":"0HN67FTPTI90S:00000001"}, Headers = System.Collections.Generic.Dictionary`2[System.String,System.String], LocationHeaderPath =  }
2024-08-28 16:49:48.687 INF Setting HTTP status code 400.
2024-08-28 16:49:48.687 INF Write content with HTTP Response ContentType of application/json; charset=utf-8
2024-08-28 16:49:48.687 INF Executed endpoint 'HTTP: POST /data/{**dmsPath} => Upsert'
2024-08-28 16:49:48.688 INF Request finished HTTP/1.1 POST http://localhost:8080/data/ed-fi/schoolYearTypes - 400 307 application/json; charset=utf-8 17.6019ms
2024-08-28 16:49:48.688 DBG Connection id "0HN67FTPTI90S" disconnecting.
2024-08-28 16:49:48.688 DBG Connection id "0HN67FTPTI90S" stopped.
2024-08-28 16:49:48.688 DBG Connection id "0HN67FTPTI90S" sending FIN because: "The Socket transport's send loop completed gracefully."

The debug messages include the raw input value with no data masking. In Meadowlark, we kept the structure while masking the values. Shall we do the same in the DMS?
Note that the client error is not treated as an application error (with ERR log level).

Application Error

Stopped the PostgreSQL container. Client received the following response:

{
  "error": "Unknown Failure",
  "correlationId": {
    "Value": "0HN67FTPTI90U:00000001"
  }
}

Console log:

2024-08-28 16:53:11.520 DBG Connection id "0HN67FTPTI90U" accepted.
2024-08-28 16:53:11.521 DBG Connection id "0HN67FTPTI90U" started.
2024-08-28 16:53:11.521 INF Request starting HTTP/1.1 POST http://localhost:8080/data/ed-fi/schoolYearTypes - null 103
2024-08-28 16:53:11.521 INF {"method":"POST","path":"/data/ed-fi/schoolYearTypes","traceId":"0HN67FTPTI90U:00000001","clientId":{"Value":"localhost:8080","HasValue":true,"Host":"localhost","Port":8080}}
2024-08-28 16:53:11.521 DBG 1 candidate(s) found for the request path '/data/ed-fi/schoolYearTypes'
2024-08-28 16:53:11.521 DBG Endpoint 'HTTP: POST /data/{**dmsPath} => Upsert' with route pattern '/data/{**dmsPath}' is valid for the request path '/data/ed-fi/schoolYearTypes'
2024-08-28 16:53:11.521 DBG Request matched endpoint 'HTTP: POST /data/{**dmsPath} => Upsert'
2024-08-28 16:53:11.521 INF Executing endpoint 'HTTP: POST /data/{**dmsPath} => Upsert'
2024-08-28 16:53:11.521 DBG Connection id "0HN67FTPTI90U", Request id "0HN67FTPTI90U:00000001": started reading request body.
2024-08-28 16:53:11.521 DBG Connection id "0HN67FTPTI90U", Request id "0HN67FTPTI90U:00000001": done reading request body.
2024-08-28 16:53:11.521 DBG FrontendRequest: FrontendRequest { Path = /ed-fi/schoolYearTypes, Body = {
    "schoolYear": 2022,
    "schoolYearDescription": "2022-2023",
    "currentSchoolYear": true
}, QueryParameters = System.Collections.Generic.Dictionary`2[System.String,System.String], TraceId = TraceId { Value = 0HN67FTPTI90U:00000001 } }
2024-08-28 16:53:11.521 DBG Entering ApiSchemaValidationMiddleware- TraceId { Value = 0HN67FTPTI90U:00000001 }
2024-08-28 16:53:11.521 DBG Entering ProvideApiSchemaMiddleware- TraceId { Value = 0HN67FTPTI90U:00000001 }
2024-08-28 16:53:11.521 DBG Entering ParsePathMiddleware - TraceId { Value = 0HN67FTPTI90U:00000001 }
2024-08-28 16:53:11.521 DBG Entering ParseBodyMiddleware - TraceId { Value = 0HN67FTPTI90U:00000001 }
2024-08-28 16:53:11.521 DBG Entering DuplicatePropertiesMiddleware - TraceId { Value = 0HN67FTPTI90U:00000001 }
2024-08-28 16:53:11.522 DBG Entering ValidateEndpointMiddleware - TraceId { Value = 0HN67FTPTI90U:00000001 }
2024-08-28 16:53:11.522 DBG Entering RejectResourceIdentifierMiddleware - TraceId { Value = 0HN67FTPTI90U:00000001 }
2024-08-28 16:53:11.522 DBG Entering CoerceFromStringsMiddleware - TraceId { Value = 0HN67FTPTI90U:00000001 }
2024-08-28 16:53:11.522 DBG Entering ValidateDocumentMiddleware- TraceId { Value = 0HN67FTPTI90U:00000001 }
2024-08-28 16:53:11.523 DBG Entering ValidateEqualityConstraintMiddleware- TraceId { Value = 0HN67FTPTI90U:00000001 }
2024-08-28 16:53:11.523 DBG Entering BuildResourceInfoMiddleware - TraceId { Value = 0HN67FTPTI90U:00000001 }
2024-08-28 16:53:11.523 DBG Entering ExtractDocumentInfoMiddleware - TraceId { Value = 0HN67FTPTI90U:00000001 }
2024-08-28 16:53:11.523 DBG IdentityExtractor.ExtractDocumentIdentity
2024-08-28 16:53:11.523 DBG IdentityExtractor.DeriveSuperclassIdentityFrom
2024-08-28 16:53:11.523 DBG ReferenceExtractor.Extract
2024-08-28 16:53:11.523 DBG DescriptorExtractor.Extract
2024-08-28 16:53:11.523 DBG Entering DuplicateReferencesMiddleware - TraceId { Value = 0HN67FTPTI90U:00000001 }
2024-08-28 16:53:11.523 DBG Entering UpsertHandler - TraceId { Value = 0HN67FTPTI90U:00000001 }
2024-08-28 16:53:11.523 DBG Resilience pipeline executing. Source: 'unknownFailureCircuitBreaker/(null)', Operation Key: 'null'
2024-08-28 16:53:11.523 DBG Entering PostgresqlDocumentStoreRepository.UpsertDocument - TraceId { Value = 0HN67FTPTI90U:00000001 }
2024-08-28 16:53:13.403 FTL Uncaught UpsertDocument failure - TraceId { Value = 0HN67FTPTI90U:00000001 }System.Net.Sockets.SocketException (00000005, 0xFFFDFFFF): Name does not resolve
   at System.Net.Dns.GetHostEntryOrAddressesCore(String hostName, Boolean justAddresses, AddressFamily addressFamily, Nullable`1 startingTimestamp)
   at System.Net.Dns.<>c.<GetHostEntryOrAddressesCoreAsync>b__33_0(Object s, Int64 startingTimestamp)
   at System.Net.Dns.<>c__DisplayClass39_0`1.<RunAsync>b__0(Task <p0>, Object <p1>)
   at System.Threading.Tasks.ContinuationResultTaskFromTask`1.InnerInvoke()
   at System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(Thread threadPoolThread, ExecutionContext executionContext, ContextCallback callback, Object state)
--- End of stack trace from previous location ---
   at System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(Thread threadPoolThread, ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot, Thread threadPoolThread)
--- End of stack trace from previous location ---
   at Npgsql.TaskTimeoutAndCancellation.ExecuteAsync(Func`2 getTaskFunc, NpgsqlTimeout timeout, CancellationToken cancellationToken)
   at Npgsql.TaskTimeoutAndCancellation.ExecuteAsync[TResult](Func`2 getTaskFunc, NpgsqlTimeout timeout, CancellationToken cancellationToken)
   at Npgsql.Internal.NpgsqlConnector.ConnectAsync(NpgsqlTimeout timeout, CancellationToken cancellationToken)
   at Npgsql.Internal.NpgsqlConnector.RawOpen(SslMode sslMode, NpgsqlTimeout timeout, Boolean async, CancellationToken cancellationToken, Boolean isFirstAttempt)
   at Npgsql.Internal.NpgsqlConnector.<Open>g__OpenCore|213_1(NpgsqlConnector conn, SslMode sslMode, NpgsqlTimeout timeout, Boolean async, CancellationToken cancellationToken, Boolean isFirstAttempt)
   at Npgsql.Internal.NpgsqlConnector.Open(NpgsqlTimeout timeout, Boolean async, CancellationToken cancellationToken)
   at Npgsql.PoolingDataSource.OpenNewConnector(NpgsqlConnection conn, NpgsqlTimeout timeout, Boolean async, CancellationToken cancellationToken)
   at Npgsql.PoolingDataSource.<Get>g__RentAsync|34_0(NpgsqlConnection conn, NpgsqlTimeout timeout, Boolean async, CancellationToken cancellationToken)
   at Npgsql.NpgsqlConnection.<Open>g__OpenAsync|42_0(Boolean async, CancellationToken cancellationToken)
   at Npgsql.NpgsqlDataSource.OpenConnectionAsync(CancellationToken cancellationToken)
   at Npgsql.NpgsqlDataSource.OpenConnectionAsync(CancellationToken cancellationToken)
   at EdFi.DataManagementService.Backend.Postgresql.PostgresqlDocumentStoreRepository.UpsertDocument(IUpsertRequest upsertRequest) in /source/backend/EdFi.DataManagementService.Backend.Postgresql/PostgresqlDocumentStoreRepository.cs:line 38

2024-08-28 16:53:13.415 DBG Resilience pipeline executed. Source: 'unknownFailureCircuitBreaker/(null)', Operation Key: 'null', Result: 'UnknownFailure { FailureMessage = Unknown Failure }', Execution Time: 1891.5335ms
2024-08-28 16:53:13.415 DBG Document store UpsertDocument returned EdFi.DataManagementService.Core.External.Backend.UpsertResult+UnknownFailure- TraceId { Value = 0HN67FTPTI90U:00000001 }
2024-08-28 16:53:13.419 DBG FrontendResponse: FrontendResponse { StatusCode = 500, Body = {"error":"Unknown Failure","correlationId":{"Value":"0HN67FTPTI90U:00000001"}}, Headers = System.Collections.Generic.Dictionary`2[System.String,System.String], LocationHeaderPath =  }
2024-08-28 16:53:13.419 INF Setting HTTP status code 500.
2024-08-28 16:53:13.419 INF Write content with HTTP Response ContentType of application/json; charset=utf-8
2024-08-28 16:53:13.419 INF Executed endpoint 'HTTP: POST /data/{**dmsPath} => Upsert'
2024-08-28 16:53:13.419 INF Request finished HTTP/1.1 POST http://localhost:8080/data/ed-fi/schoolYearTypes - 500 78 application/json; charset=utf-8 1898.1613ms
2024-08-28 16:53:13.419 DBG Connection id "0HN67FTPTI90U" disconnecting.
2024-08-28 16:53:13.419 DBG Connection id "0HN67FTPTI90U" stopped.
2024-08-28 16:53:13.419 DBG Connection id "0HN67FTPTI90U" sending FIN because: "The Socket transport's send loop completed gracefully."

We deliberately left the stack trace in place.
- Not “structured” today
bug - Some of the DBG messages are mistakenly missing the TraceId in their output.

Application Log - Circuit Breaker

We’ve implemented the circuit breaker pattern, with configurable settings. Sample log after “a bunch” of calls to the DMS while PostgreSQL is down:

2024-08-28 16:57:50.967 WRN Resilience event occurred. EventName: 'OnCircuitHalfOpened', Source: 'unknownFailureCircuitBreaker/(null)/CircuitBreaker', Operation Key: 'null', Result: 'null'
2024-08-28 16:57:50.968 DBG Entering PostgresqlDocumentStoreRepository.UpsertDocument - TraceId { Value = 0HN67FTPTI916:00000001 }
2024-08-28 16:57:52.762 FTL Uncaught UpsertDocument failure - TraceId { Value = 0HN67FTPTI916:00000001 }System.Net.Sockets.SocketException (00000005, 0xFFFDFFFF): Name does not resolve
   at System.Net.Dns.GetHostEntryOrAddressesCore(String hostName, Boolean justAddresses, AddressFamily addressFamily, Nullable`1 startingTimestamp)
   at System.Net.Dns.<>c.<GetHostEntryOrAddressesCoreAsync>b__33_0(Object s, Int64 startingTimestamp)
   at System.Net.Dns.<>c__DisplayClass39_0`1.<RunAsync>b__0(Task <p0>, Object <p1>)
   at System.Threading.Tasks.ContinuationResultTaskFromTask`1.InnerInvoke()
   at System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(Thread threadPoolThread, ExecutionContext executionContext, ContextCallback callback, Object state)
--- End of stack trace from previous location ---
   at System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(Thread threadPoolThread, ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot, Thread threadPoolThread)
--- End of stack trace from previous location ---
   at Npgsql.TaskTimeoutAndCancellation.ExecuteAsync(Func`2 getTaskFunc, NpgsqlTimeout timeout, CancellationToken cancellationToken)
   at Npgsql.TaskTimeoutAndCancellation.ExecuteAsync[TResult](Func`2 getTaskFunc, NpgsqlTimeout timeout, CancellationToken cancellationToken)
   at Npgsql.Internal.NpgsqlConnector.ConnectAsync(NpgsqlTimeout timeout, CancellationToken cancellationToken)
   at Npgsql.Internal.NpgsqlConnector.RawOpen(SslMode sslMode, NpgsqlTimeout timeout, Boolean async, CancellationToken cancellationToken, Boolean isFirstAttempt)
   at Npgsql.Internal.NpgsqlConnector.<Open>g__OpenCore|213_1(NpgsqlConnector conn, SslMode sslMode, NpgsqlTimeout timeout, Boolean async, CancellationToken cancellationToken, Boolean isFirstAttempt)
   at Npgsql.Internal.NpgsqlConnector.Open(NpgsqlTimeout timeout, Boolean async, CancellationToken cancellationToken)
   at Npgsql.PoolingDataSource.OpenNewConnector(NpgsqlConnection conn, NpgsqlTimeout timeout, Boolean async, CancellationToken cancellationToken)
   at Npgsql.PoolingDataSource.<Get>g__RentAsync|34_0(NpgsqlConnection conn, NpgsqlTimeout timeout, Boolean async, CancellationToken cancellationToken)
   at Npgsql.NpgsqlConnection.<Open>g__OpenAsync|42_0(Boolean async, CancellationToken cancellationToken)
   at Npgsql.NpgsqlDataSource.OpenConnectionAsync(CancellationToken cancellationToken)
   at Npgsql.NpgsqlDataSource.OpenConnectionAsync(CancellationToken cancellationToken)
   at EdFi.DataManagementService.Backend.Postgresql.PostgresqlDocumentStoreRepository.UpsertDocument(IUpsertRequest upsertRequest) in /source/backend/EdFi.DataManagementService.Backend.Postgresql/PostgresqlDocumentStoreRepository.cs:line 38

2024-08-28 16:57:52.763 ERR Resilience event occurred. EventName: 'OnCircuitOpened', Source: 'unknownFailureCircuitBreaker/(null)/CircuitBreaker', Operation Key: 'null', Result: 'UnknownFailure { FailureMessage = Unknown Failure }'
2024-08-28 16:57:52.763 DBG Resilience pipeline executed. Source: 'unknownFailureCircuitBreaker/(null)', Operation Key: 'null', Result: 'UnknownFailure { FailureMessage = Unknown Failure }', Execution Time: 1797.3568ms
2024-08-28 16:57:52.763 DBG Document store UpsertDocument returned EdFi.DataManagementService.Core.External.Backend.UpsertResult+UnknownFailure- TraceId { Value = 0HN67FTPTI916:00000001 }
2024-08-28 16:57:52.763 DBG FrontendResponse: FrontendResponse { StatusCode = 500, Body = {"error":"Unknown Failure","correlationId":{"Value":"0HN67FTPTI916:00000001"}}, Headers = System.Collections.Generic.Dictionary`2[System.String,System.String], LocationHeaderPath =  }
2024-08-28 16:57:52.763 INF Setting HTTP status code 500.
2024-08-28 16:57:52.763 INF Write content with HTTP Response ContentType of application/json; charset=utf-8
2024-08-28 16:57:52.763 INF Executed endpoint 'HTTP: POST /data/{**dmsPath} => Upsert'
2024-08-28 16:57:52.763 INF Request finished HTTP/1.1 POST http://localhost:8080/data/ed-fi/schoolYearTypes - 500 78 application/json; charset=utf-8 1799.2546ms
2024-08-28 16:57:52.763 DBG Connection id "0HN67FTPTI916" disconnecting.
2024-08-28 16:57:52.763 DBG Connection id "0HN67FTPTI916" stopped.
2024-08-28 16:57:52.763 DBG Connection id "0HN67FTPTI916" sending FIN because: "The Socket transport's send loop completed gracefully."
2024-08-28 16:57:53.379 DBG Connection id "0HN67FTPTI917" accepted.
2024-08-28 16:57:53.379 DBG Connection id "0HN67FTPTI917" started.
2024-08-28 16:57:53.380 INF Request starting HTTP/1.1 GET http://localhost:8080/data/ed-fi/schoolYearTypes - null null
2024-08-28 16:57:53.380 INF {"method":"GET","path":"/data/ed-fi/schoolYearTypes","traceId":"0HN67FTPTI917:00000001","clientId":{"Value":"localhost:8080","HasValue":true,"Host":"localhost","Port":8080}}
2024-08-28 16:57:53.380 DBG 1 candidate(s) found for the request path '/data/ed-fi/schoolYearTypes'
2024-08-28 16:57:53.380 DBG Endpoint 'HTTP: GET /data/{**dmsPath} => Get' with route pattern '/data/{**dmsPath}' is valid for the request path '/data/ed-fi/schoolYearTypes'
2024-08-28 16:57:53.380 DBG Request matched endpoint 'HTTP: GET /data/{**dmsPath} => Get'
2024-08-28 16:57:53.380 INF Executing endpoint 'HTTP: GET /data/{**dmsPath} => Get'
2024-08-28 16:57:53.380 DBG FrontendRequest: FrontendRequest { Path = /ed-fi/schoolYearTypes, Body = , QueryParameters = System.Collections.Generic.Dictionary`2[System.String,System.String], TraceId = TraceId { Value = 0HN67FTPTI917:00000001 } }
2024-08-28 16:57:53.380 DBG Entering ApiSchemaValidationMiddleware- TraceId { Value = 0HN67FTPTI917:00000001 }
2024-08-28 16:57:53.380 DBG Entering ProvideApiSchemaMiddleware- TraceId { Value = 0HN67FTPTI917:00000001 }
2024-08-28 16:57:53.380 DBG Entering ParsePathMiddleware - TraceId { Value = 0HN67FTPTI917:00000001 }
2024-08-28 16:57:53.380 DBG Entering ValidateEndpointMiddleware - TraceId { Value = 0HN67FTPTI917:00000001 }
2024-08-28 16:57:53.380 DBG Entering BuildResourceInfoMiddleware - TraceId { Value = 0HN67FTPTI917:00000001 }
2024-08-28 16:57:53.380 DBG Entering ValidateQueryMiddleware - TraceId { Value = 0HN67FTPTI917:00000001 }
2024-08-28 16:57:53.380 DBG Entering QueryRequestHandler - TraceId { Value = 0HN67FTPTI917:00000001 }
2024-08-28 16:57:53.381 DBG Resilience pipeline executing. Source: 'unknownFailureCircuitBreaker/(null)', Operation Key: 'null'
2024-08-28 16:57:53.381 DBG Resilience pipeline executed. Source: 'unknownFailureCircuitBreaker/(null)', Operation Key: 'null', Result: 'The circuit is now open and is not allowing calls.', Execution Time: 0.0758msPolly.CircuitBreaker.BrokenCircuitException: The circuit is now open and is not allowing calls.

2024-08-28 16:57:53.381 ERR Unknown Error - TraceId { Value = 0HN67FTPTI917:00000001 }Polly.CircuitBreaker.BrokenCircuitException: The circuit is now open and is not allowing calls.
   at Polly.Outcome`1.GetResultOrRethrow()
   at Polly.ResiliencePipeline.ExecuteAsync[TResult](Func`2 callback, CancellationToken cancellationToken)
   at EdFi.DataManagementService.Core.Handler.QueryRequestHandler.Execute(PipelineContext context, Func`1 next) in /source/core/EdFi.DataManagementService.Core/Handler/QueryRequestHandler.cs:line 23
   at EdFi.DataManagementService.Core.Pipeline.PipelineProvider.RunInternal(Int32 stepIndex, PipelineContext context) in /source/core/EdFi.DataManagementService.Core/Pipeline/PipelineProvider.cs:line 27
   at EdFi.DataManagementService.Core.Middleware.ValidateQueryMiddleware.Execute(PipelineContext context, Func`1 next) in /source/core/EdFi.DataManagementService.Core/Middleware/ValidateQueryMiddleware.cs:line 114
   at EdFi.DataManagementService.Core.Pipeline.PipelineProvider.RunInternal(Int32 stepIndex, PipelineContext context) in /source/core/EdFi.DataManagementService.Core/Pipeline/PipelineProvider.cs:line 27
   at EdFi.DataManagementService.Core.Middleware.BuildResourceInfoMiddleware.Execute(PipelineContext context, Func`1 next) in /source/core/EdFi.DataManagementService.Core/Middleware/BuildResourceInfoMiddleware.cs:line 28
   at EdFi.DataManagementService.Core.Pipeline.PipelineProvider.RunInternal(Int32 stepIndex, PipelineContext context) in /source/core/EdFi.DataManagementService.Core/Pipeline/PipelineProvider.cs:line 27
   at EdFi.DataManagementService.Core.Middleware.ValidateEndpointMiddleware.Execute(PipelineContext context, Func`1 next) in /source/core/EdFi.DataManagementService.Core/Middleware/ValidateEndpointMiddleware.cs:line 63
   at EdFi.DataManagementService.Core.Pipeline.PipelineProvider.RunInternal(Int32 stepIndex, PipelineContext context) in /source/core/EdFi.DataManagementService.Core/Pipeline/PipelineProvider.cs:line 27
   at EdFi.DataManagementService.Core.Middleware.ParsePathMiddleware.Execute(PipelineContext context, Func`1 next) in /source/core/EdFi.DataManagementService.Core/Middleware/ParsePathMiddleware.cs:line 81
   at EdFi.DataManagementService.Core.Pipeline.PipelineProvider.RunInternal(Int32 stepIndex, PipelineContext context) in /source/core/EdFi.DataManagementService.Core/Pipeline/PipelineProvider.cs:line 27
   at EdFi.DataManagementService.Core.Middleware.ProvideApiSchemaMiddleware.Execute(PipelineContext context, Func`1 next) in /source/core/EdFi.DataManagementService.Core/Middleware/ProvideApiSchemaMiddleware.cs:line 21
   at EdFi.DataManagementService.Core.Pipeline.PipelineProvider.RunInternal(Int32 stepIndex, PipelineContext context) in /source/core/EdFi.DataManagementService.Core/Pipeline/PipelineProvider.cs:line 27
   at EdFi.DataManagementService.Core.Middleware.ApiSchemaValidationMiddleware.Execute(PipelineContext context, Func`1 next) in /source/core/EdFi.DataManagementService.Core/Middleware/ApiSchemaValidationMiddleware.cs:line 50
   at EdFi.DataManagementService.Core.Pipeline.PipelineProvider.RunInternal(Int32 stepIndex, PipelineContext context) in /source/core/EdFi.DataManagementService.Core/Pipeline/PipelineProvider.cs:line 27
   at EdFi.DataManagementService.Core.Middleware.CoreLoggingMiddleware.Execute(PipelineContext context, Func`1 next) in /source/core/EdFi.DataManagementService.Core/Middleware/CoreLoggingMiddleware.cs:line 24

Note the WRN, FTL, and ERR logs.
Probably better to try to avoid the final stack trace, on the circuit breaker, as that does not add useful information.
However, a search on 0HN67FTPTI917 reveals that the actual error that finally cause the circuit to open has not been logged.
Should the FTL message have simply been an ERR? After all, the application is still running, and the database connection may restore itself after a time.

Restart PostgreSQL

2024-08-28 17:04:45.866 INF Resilience event occurred. EventName: 'OnCircuitClosed', Source: 'unknownFailureCircuitBreaker/(null)/CircuitBreaker', Operation Key: 'null', Result: 'QuerySuccess { EdfiDocs = [
  {
    "schoolYearDescription": "2022-2023",
    "schoolYear": 2022,
    "id": "b0544561-30a3-4814-90ea-9a7c3e4104d5",
    "currentSchoolYear": true
  }
], TotalCount = 1 }'

We shouldn’t be logging the query result when the circuit successfully re-closes.

August 2024 - Project Tanager Workgroup