https://kotlinlang.org logo
#http4k
Title
# http4k
d

dave

02/10/2021, 8:02 AM
e

Elizabeth Thomas

02/10/2021, 10:59 PM
I just came across the structured-logging yesterday. Is there a way to test that structured logging is happening when EventFilters are used in-combination with the Http filters?
I have my filter defined like this
Copy code
data class IncomingHttpRequest(val message: String = "", val status: Int = 0, val duration: Long = 0L) : Event

object ReportHttpTransactionFilter {
  operator fun invoke(
    events: Events = EventFilters.AddTimestamp().then(AutoMarshallingEvents(Jackson)),
    event: Event? = null
  ): Filter = Filter { next ->
    { request ->
      next(request).apply {
        ResponseFilters.ReportHttpTransaction { httpTransaction ->
          events(event ?: IncomingHttpRequest(
            httpTransaction.request.toMessage(),
            httpTransaction.response.status.code,
            httpTransaction.duration.toMillis())
          )
        }
      }
    }
  }
}
And my test class like this: (which fails)
Copy code
class ReportHttpTransactionFilterSpec : Spek({

  val request = Request(Method.GET, "/bob")
  val response = Response(OK)
  val recording = RecordingEvents()

  test("report http transaction filter emits events with timestamp") {
    val events = EventFilters.AddTimestamp().then(AutoMarshallingEvents(Jackson)).then(recording)
    val event = IncomingHttpRequest("some message", 200, 10)
    val handler = ReportHttpTransactionFilter(events, event).then { response }

    expectThat(handler(request)).isEqualTo(response)
    expectThat(recording.toList()).isEqualTo(listOf<Event>(MetadataEvent(
      event,
      mapOf("timestamp" to Clock.systemUTC().instant())))
    )
  }

})
The recording comes back as emptylist
Am I missing something here?
d

dave

02/11/2021, 8:37 AM
It looks strange - why are you passing in the event which then falls back?
Copy code
events(event ?: IncomingHttpRequest(
            httpTransaction.request.toMessage(),
            httpTransaction.response.status.code,
            httpTransaction.duration.toMillis())
          )
r

Razvan

02/11/2021, 8:37 AM
I think is yout ReportHttpTransactionFilter that is strange We did it this way:
Copy code
val events = EventFilters.AddTimestamp().then(AutoMarshallingEvents(AppJackson))
fun LogIncomingRequests() = ResponseFilters.ReportHttpTransaction {
   events(LogHttpTransaction.fromTransaction(it))
}

val app = LogIncomingRequests().then { response }
👍 1
e

Elizabeth Thomas

02/11/2021, 8:55 AM
@Razvan do you mean to say I will have to use LogHttpTransaction in my filter code instead of events(event)?
@dave if an event is passed, it will be events(event) call as in the test code but if event is not passed, it will use the httpTransaction to create IncomingHttpRequest and use it with events.
r

Razvan

02/11/2021, 9:00 AM
LogHttpTransaction is just a custom object like IncomingHttpRequest juste a data class with informations you can replace that with
Copy code
fun LogIncomingRequests() = ResponseFilters.ReportHttpTransaction {
   events(
      IncomingHttpRequest(
            itrequest.toMessage(),
            it.response.status.code,
            it.duration.toMillis())
          )
   )
}
if it helps to undersand
🙏 1
👍 1
d

dave

02/11/2021, 9:01 AM
@Elizabeth Thomas Yes - and that's exactly what you want to test. 🙃
👍 1
e

Elizabeth Thomas

02/11/2021, 9:08 AM
Okay let me try that!
@Razvan My
events
is configured as
val events = EventFilters.AddTimestamp().then(AutoMarshallingEvents(Jackson)).then(recording)
in my test class. And after running through the filter, when I check the
recording
object, I see it being empty.
@dave ^^
I am missing to see how to validate that events with timestamp were generated.
d

dave

02/11/2021, 6:00 PM
but really you should be testing that your events stack is doing the right thing. assuming that you always want metadata then isolate that part and test it separately to the filter
then you can just test your filter by testing that the correct events (IncomingHttpRequest) were generated, regardless of the metadata
e

Elizabeth Thomas

02/11/2021, 6:48 PM
Thanks @dave will use this approach!
d

dave

02/11/2021, 6:56 PM
👍
e

Elizabeth Thomas

02/11/2021, 8:49 PM
@dave your approach worked. Thanks! But I am failing to understand why my filter defined like this won’t work
Copy code
object ReportHttpTransactionFilter {
  object Log {
    operator fun invoke(
      rawEvents: Events,
      clock: Clock = Clock.systemUTC()
    ): Filter = Filter { next ->
      { request ->
        val events = AddTimestamp(clock).then(rawEvents)
        next(request).apply {
          ResponseFilters.ReportHttpTransaction(clock = clock) { httpTransaction ->
            events(
              IncomingHttpRequest(
                httpTransaction.request.method,
                httpTransaction.request.uri.path,
                httpTransaction.response.status.code,
                httpTransaction.duration.toMillis()
              )
            )
          }
        }
      }
    }
  }
d

dave

02/11/2021, 8:50 PM
because you're defining a filter within a filter - and that's not how filters work.. 🙂
Copy code
ResponseFilters.ReportHttpTransaction(clock = clock) { httpTransaction ->
            events(
              IncomingHttpRequest(
                httpTransaction.request.method,
                httpTransaction.request.uri.path,
                httpTransaction.response.status.code,
                httpTransaction.duration.toMillis()
              )
            )
          }
is a filter
you need to do
filter.then(filter).then(handler)
e

Elizabeth Thomas

02/11/2021, 8:52 PM
Ah, okay - I thought filter within a filter is possible.. 🙂
When you get a chance, could you share if there is any documentation that outlines this?
d

dave

02/11/2021, 8:54 PM
e

Elizabeth Thomas

02/11/2021, 8:54 PM
I was following this from ReportHttpTransaction
Copy code
object ReportHttpTransaction {
        operator fun invoke(
            clock: Clock = Clock.systemUTC(),
            transactionLabeler: HttpTransactionLabeler = { it },
            recordFn: (HttpTransaction) -> Unit
        ): Filter = Filter { next ->
            {
                clock.instant().let { start ->
                    next(it).apply {
                        recordFn(transactionLabeler(HttpTransaction(it, this, between(start, clock.instant()))))
                    }
                }
            }
        }
    }
d

dave

02/11/2021, 8:55 PM
yes - but the
apply()
there is actually doing something and not creting another filter
e

Elizabeth Thomas

02/11/2021, 8:57 PM
Ah, gotcha.. Makes sense. Thanks for explaining it to me!
Also the
LogHttpTransaction.fromTransaction
which @Razvan pointed out, is it in http4k-core? or some other module? I couldnt get the package for it. Again, its probably me doing something wrong.
r

Razvan

02/11/2021, 9:21 PM
No is just a personal data class with fields I want to log, that has a lot of fields and I don’t want to bother pas then in the constructor.
👍 1
14 Views