Skip to end of metadata
Go to start of metadata

You are viewing an old version of this page. View the current version.

Compare with Current View Page History

« Previous Version 3 Next »

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

image-20240828-161611.png

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

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:

image-20240828-162238.png

  • _lastModifiedDate, _etag (and _lineage in the future?)

  • (question) 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

There are the requirements gathered from the multitenancy / routing / instance management workgroup:

  • Allow ODS instances to reside on separate database servers.

  • Support various database segmentation strategies: ODS per year, ODS per district, ODS per district per year, and ODS per tenant. (Reference: Segmentation strategies in ODS API)

  • Enable API administrators to choose between implicit routes (segmentation information not visible in the routes) and explicit routes (Reference: Context-Based Routing).

  • Provide isolated configuration for client and security setup by tenants, making it easier to onboard new tenants or remove existing ones.

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.

  • (question) 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. (question) 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.

    • (question) 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”.

    • (question) 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."

  • (question) 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.

    • (question) Not “structured” today

  • (warning) 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.

  • (question) However, a search on 0HN67FTPTI917 reveals that the actual error that finally cause the circuit to open has not been logged.

  • (question) 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 }'

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

  • No labels