first version of a logger of zinc events

ba-st · Feb 9, 2024 · 1bc0d45 · 1bc0d45
1 parent 8f94739
commit 1bc0d45
Show file tree

Hide file tree

Showing 2 changed files with 294 additions and 0 deletions.
diff --git a/source/Hyperspace-Model-Tests/ZnEventToLogRecordControllerTest.class.st b/source/Hyperspace-Model-Tests/ZnEventToLogRecordControllerTest.class.st
@@ -0,0 +1,149 @@
+Class {
+	#name : #ZnEventToLogRecordControllerTest,
+	#superclass : #TestCase,
+	#instVars : [
+		'logsController',
+		'loggingAsserter'
+	],
+	#category : #'Hyperspace-Model-Tests-Zinc'
+}
+
+{ #category : #private }
+ZnEventToLogRecordControllerTest >> runMemoryLoggerDuring: aBlock assertingLogRecordsMatch: expectedLogEntries [
+
+	loggingAsserter
+		runMemoryLoggerDuring: aBlock;
+		assertLogRecordsMatch: expectedLogEntries
+]
+
+{ #category : #running }
+ZnEventToLogRecordControllerTest >> setUp [
+
+	super setUp.
+	loggingAsserter := LoggingAsserter on: self.
+	logsController := ZnEventToLogRecordController new
+]
+
+{ #category : #running }
+ZnEventToLogRecordControllerTest >> tearDown [
+
+	logsController stop.
+	loggingAsserter stopLoggers.
+
+	super tearDown
+]
+
+{ #category : #running }
+ZnEventToLogRecordControllerTest >> testLogsOfIncomingGetRequest [
+
+	logsController
+		logIncomingRequests: true;
+		startUp.
+
+	self
+		runMemoryLoggerDuring: [
+			self withServerDo: [ :server |
+				| client |
+
+				server onRequestRespond: [ :request |
+					( ZnResponse ok: ( ZnEntity textCRLF: 'OK' ) )
+						setConnectionClose;
+						yourself
+					].
+				client := ZnClient new.
+				client url: server localUrl.
+				client get
+				]
+			]
+		assertingLogRecordsMatch: #( 
+				'[DEBUG] Server accepted connection {"remoteAddress":"127.0.0.1","processId":598770,"eventId":63}'
+				'[DEBUG] Incoming HTTP request received {"summary":"2024-02-09 18:11:48 066 148126 Request Read a ZnRequest(GET /) 0ms","durationInMilliseconds":0,"request":{"method":"GET","uri":"/"},"processId":148126,"eventId":66}'
+				'[DEBUG] Incoming HTTP request responded {"summary":"2024-02-09 18:11:48 067 148126 Request Handled a ZnRequest(GET /) 2ms","durationInMilliseconds":2,"request":{"method":"GET","uri":"/"},"processId":148126,"eventId":67,"response":{"code":200,"totalSize":4}}'
+			   '[DEBUG] Server closed connection {"remoteAddress":"127.0.0.1","processId":148126,"eventId":70}' )
+]
+
+{ #category : #running }
+ZnEventToLogRecordControllerTest >> testLogsOfIncomingPostRequest [
+
+	logsController
+		logIncomingRequests: true;
+		startUp.
+
+	self
+		runMemoryLoggerDuring: [
+			self withServerDo: [ :server |
+				| client |
+
+				server onRequestRespond: [ :request |
+					( ZnResponse ok: ( ZnEntity textCRLF: 'Hi you too!' ) )
+						setConnectionClose;
+						yourself
+					].
+				client := ZnClient new.
+				client post: server localUrl contents: 'Hi there!'
+				]
+			]
+		assertingLogRecordsMatch: #( 
+				'[DEBUG] Server accepted connection {"remoteAddress":"127.0.0.1","processId":598770,"eventId":63}'
+				'[DEBUG] Incoming HTTP request received {"summary":"2024-02-09 18:11:48 066 148126 Request Read a ZnRequest(GET /) 0ms","durationInMilliseconds":0,"request":{"method":"GET","uri":"/"},"processId":148126,"eventId":66}'
+				'[DEBUG] Incoming HTTP request responded {"summary":"2024-02-09 18:11:48 067 148126 Request Handled a ZnRequest(GET /) 2ms","durationInMilliseconds":2,"request":{"method":"GET","uri":"/"},"processId":148126,"eventId":67,"response":{"code":200,"totalSize":4}}'
+			   '[DEBUG] Server closed connection {"remoteAddress":"127.0.0.1","processId":148126,"eventId":70}' )
+]
+
+{ #category : #running }
+ZnEventToLogRecordControllerTest >> testLogsOfOutgoingGetRequest [
+
+	logsController
+		logOutgoingRequests: true;
+		startUp.
+
+	self
+		runMemoryLoggerDuring: [
+			self withServerDo: [ :server |
+				| client |
+
+				server onRequestRespond: [ :request |
+					( ZnResponse ok: ( ZnEntity textCRLF: 'OK' ) )
+						setConnectionClose;
+						yourself
+					].
+				client := ZnClient new.
+				client url: server localUrl.
+				client get
+				]
+			]
+		assertingLogRecordsMatch:
+			#( '[DEBUG] Outgoing HTTP request sent {"summary":"2024-02-09 18:14:30 095 726586 Request Written a ZnRequest(GET /) 0ms","durationInMilliseconds":0,"request":{"method":"GET","uri":"http://localhost:35059/"},"processId":726586,"eventId":95}'
+			   '[DEBUG] Outgoing HTTP request responded {"summary":"2024-02-09 18:14:30 102 726586 GET / 200 4B 2ms","durationInMilliseconds":2,"request":{"method":"GET","uri":"http://localhost:35059/"},"processId":726586,"eventId":102,"response":{"code":200,"totalSize":4}}' )
+]
+
+{ #category : #running }
+ZnEventToLogRecordControllerTest >> testLogsOfOutgoingPostRequest [
+
+	logsController
+		logOutgoingRequests: true;
+		startUp.
+
+	self
+		runMemoryLoggerDuring: [
+			self withServerDo: [ :server |
+				| client |
+
+				server onRequestRespond: [ :request |
+					( ZnResponse ok: ( ZnEntity textCRLF: 'Hi you too!' ) )
+						setConnectionClose;
+						yourself
+					].
+				client := ZnClient new.
+				client post: server localUrl contents: 'Hi there!'
+				]
+			]
+		assertingLogRecordsMatch:
+			#( '[DEBUG] Outgoing HTTP request sent {"summary":"2024-02-09 18:14:30 095 726586 Request Written a ZnRequest(GET /) 0ms","durationInMilliseconds":0,"request":{"method":"GET","uri":"http://localhost:35059/"},"processId":726586,"eventId":95}'
+			   '[DEBUG] Outgoing HTTP request responded {"summary":"2024-02-09 18:14:30 102 726586 GET / 200 4B 2ms","durationInMilliseconds":2,"request":{"method":"GET","uri":"http://localhost:35059/"},"processId":726586,"eventId":102,"response":{"code":200,"totalSize":4}}' )
+]
+
+{ #category : #enumerating }
+ZnEventToLogRecordControllerTest >> withServerDo: block [
+	ZnServer withOSAssignedPortDo: block
+]
diff --git a/source/Hyperspace-Model/ZnEventToLogRecordController.class.st b/source/Hyperspace-Model/ZnEventToLogRecordController.class.st
@@ -0,0 +1,145 @@
+Class {
+	#name : #ZnEventToLogRecordController,
+	#superclass : #Object,
+	#instVars : [
+		'logOutgoingRequests',
+		'logIncomingRequests',
+		'subscriptions'
+	],
+	#category : #'Hyperspace-Model'
+}
+
+{ #category : #'private - dumping' }
+ZnEventToLogRecordController >> asStructuredRequest: aZnRequest [
+
+	| json |
+
+	json := NeoJSONObject new.
+	json
+		at: #method put: aZnRequest method;
+		at: #uri put: aZnRequest uri asString.
+	^json
+]
+
+{ #category : #'private - dumping' }
+ZnEventToLogRecordController >> asStructuredResponse: aZnResponse [
+
+	| json |
+
+	json := NeoJSONObject new.
+	json
+		at: #code put: aZnResponse code;
+		at: #totalSize put: aZnResponse contentLength.
+	^json
+]
+
+{ #category : #'private - dumping' }
+ZnEventToLogRecordController >> dumpConnectionEvent: aZnServerConnectionClosedEvent on: data [
+
+	 data
+		  at: #remoteAddress
+		  put: ( ZnNetworkingUtils ipAddressToString: aZnServerConnectionClosedEvent address );
+		  at: #processId put: aZnServerConnectionClosedEvent processId;
+		  at: #eventId put: aZnServerConnectionClosedEvent id
+]
+
+{ #category : #'private - dumping' }
+ZnEventToLogRecordController >> dumpRequestAndResponseOf: event on: json [
+
+	| response |
+
+	self dumpRequestOf: event on: json.
+	response := event response.
+	(response hasEntity
+		and: [response entity hasContentType and: [response entity contentType isBinary not]])
+			then: [json at: #response put: (self asStructuredResponse: response)].
+	^json
+]
+
+{ #category : #'private - dumping' }
+ZnEventToLogRecordController >> dumpRequestOf: event on: json [
+
+	json
+		at: #summary put: event printString;
+		at: #durationInMilliseconds put: event duration;
+		at: #request put: (self asStructuredRequest: event request); 
+		at: #processId put: event processId; 
+		at: #eventId put: event id. 
+	^json
+]
+
+{ #category : #'system startup' }
+ZnEventToLogRecordController >> initialize [
+
+	super initialize.
+
+	logOutgoingRequests := false.
+	logIncomingRequests := false.
+	subscriptions := OrderedCollection new
+]
+
+{ #category : #'private - configuring' }
+ZnEventToLogRecordController >> logIncomingRequests: aBoolean [
+
+	logIncomingRequests := aBoolean
+]
+
+{ #category : #'private - configuring' }
+ZnEventToLogRecordController >> logOutgoingRequests: aBoolean [
+
+	logOutgoingRequests := aBoolean
+]
+
+{ #category : #'system startup' }
+ZnEventToLogRecordController >> startUp [
+
+	logOutgoingRequests then: [ self startUpOutgoingRequestListeners ].
+
+	logIncomingRequests then: [ self startUpIncomingRequestListeners ]
+]
+
+{ #category : #'system startup' }
+ZnEventToLogRecordController >> startUpIncomingRequestListeners [
+
+	self subscribeToEventsOf: ZnServerConnectionClosedEvent andDo: [ :event |
+		LogRecord emitStructuredDebuggingInfo: 'Server closed connection'
+			with: [ :data | self dumpConnectionEvent: event on: data ]
+		].
+	self subscribeToEventsOf: ZnConnectionAcceptedEvent andDo: [ :event |
+		LogRecord emitStructuredDebuggingInfo: 'Server accepted connection'
+			with: [ :data | self dumpConnectionEvent: event on: data ]
+		].
+	self subscribeToEventsOf: ZnRequestReadEvent andDo: [ :event |
+		LogRecord emitStructuredDebuggingInfo: 'Incoming HTTP request received'
+			with: [ :data | self dumpRequestOf: event on: data ]
+		].
+	self subscribeToEventsOf: ZnRequestResponseHandledEvent andDo: [ :event |
+		LogRecord emitStructuredDebuggingInfo: 'Incoming HTTP request responded'
+			with: [ :data | self dumpRequestAndResponseOf: event on: data ]
+		]
+]
+
+{ #category : #'system startup' }
+ZnEventToLogRecordController >> startUpOutgoingRequestListeners [
+
+	self subscribeToEventsOf: ZnRequestWrittenEvent andDo: [ :event |
+		LogRecord emitStructuredDebuggingInfo: 'Outgoing HTTP request sent'
+			with: [ :data | self dumpRequestOf: event on: data ]
+		].
+	self subscribeToEventsOf: ZnClientTransactionEvent andDo: [ :event |
+		LogRecord emitStructuredDebuggingInfo: 'Outgoing HTTP request responded'
+			with: [ :data | self dumpRequestAndResponseOf: event on: data ]
+		]
+]
+
+{ #category : #'system startup' }
+ZnEventToLogRecordController >> stop [
+
+	subscriptions do: [:subscription | ZnLogEvent announcer removeSubscription: subscription]
+]
+
+{ #category : #'system startup' }
+ZnEventToLogRecordController >> subscribeToEventsOf: anEventType andDo: aBlock [
+
+	subscriptions add: (ZnLogEvent announcer when: anEventType do: aBlock)
+]