...
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).
...
This is a sample message in Kafka, created from Debezium:
...
_lastModifiedDate,_etag→ store (and_lineagein 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”.
...
GitHub Discussion for asynchronous conversation: Multitenancy / routing / instance management
Logging
Showing output from docker logs:
Initial Startup
| Code Block | ||
|---|---|---|
| ||
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
| Code Block | ||
|---|---|---|
| ||
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:
Code Block 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
traceIdthat 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
clientIdvalue is about. Certainly not showing anything useful. I would have expectedclientIdto 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
TraceIdpresent, you can follow the performance for an individual request.The function entered is not consistently separated from
TraceIdwith “space dash space”.- Wouldn’t a structured message be easier to use here?
Client Error
Performed a POST operation with an invalid payload.
| Code Block | ||
|---|---|---|
| ||
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
ERRlog level).
Application Error
Stopped the PostgreSQL container. Client received the following response:
| Code Block |
|---|
{
"error": "Unknown Failure",
"correlationId": {
"Value": "0HN67FTPTI90U:00000001"
}
} |
Console log:
| Code Block | ||
|---|---|---|
| ||
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 TraceIdin 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:
| Code Block | ||
|---|---|---|
| ||
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, andERRlogs.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
0HN67FTPTI917reveals that the actual error that finally cause the circuit to open has not been logged. - Should the
FTLmessage have simply been anERR? After all, the application is still running, and the database connection may restore itself after a time.
Restart PostgreSQL
| Code Block | ||
|---|---|---|
| ||
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.