Skip to content

Commit fc00608

Browse files
karl-runkarl-run
committed
chore: full trace logging in message handler
1 parent 9b459c1 commit fc00608

File tree

1 file changed

+43
-3
lines changed

1 file changed

+43
-3
lines changed

‎src/main/kotlin/no/nav/syfo/application/BlockingApplicationRunner.kt

+43-3
Original file line numberDiff line numberDiff line change
@@ -110,9 +110,9 @@ class BlockingApplicationRunner(
110110
wrapExceptions {
111111
loop@ while (applicationState.ready) {
112112
val randomUuid = UUID.randomUUID().toString()
113-
logger.info("Polling for message, trace id: $randomUuid")
113+
logger.info("TRACE_DEBUG: Polling for message, trace id: $randomUuid")
114114
val message = inputconsumer.receive(1000)
115-
logger.info("Received message, trace id: $randomUuid")
115+
logger.info("TRACE_DEBUG: Received message, trace id: $randomUuid")
116116

117117
var loggingMeta: LoggingMeta? = null
118118
if (message == null) {
@@ -133,17 +133,19 @@ class BlockingApplicationRunner(
133133
val requestLatency = REQUEST_TIME.startTimer()
134134
val fellesformat = safeUnmarshal(inputMessageText)
135135

136+
logger.info("TRACE_DEBUG: Before vedlegg, trace id: $randomUuid")
136137
val vedlegg = getVedlegg(fellesformat)
137138
if (vedlegg.isNotEmpty()) {
138139
SYKMELDING_VEDLEGG_COUNTER.inc()
139140
removeVedleggFromFellesformat(fellesformat)
140141
}
142+
logger.info("TRACE_DEBUG: After vedlegg, trace id: $randomUuid")
141143
val fellesformatText =
142144
when (vedlegg.isNotEmpty()) {
143145
true -> fellesformatMarshaller.toString(fellesformat)
144146
false -> inputMessageText
145147
}
146-
148+
logger.info("TRACE_DEBUG: AFter fellesformat, trace id: $randomUuid")
147149
val receiverBlock = fellesformat.get<XMLMottakenhetBlokk>()
148150
val msgHead = fellesformat.get<XMLMsgHead>()
149151
val legekontorOrgNr =
@@ -157,13 +159,16 @@ class BlockingApplicationRunner(
157159
orgNr = legekontorOrgNr,
158160
msgId = msgHead.msgInfo.msgId,
159161
)
162+
logger.info("TRACE_DEBUG: Received message, trace id: $randomUuid")
160163
logger.info("Received message, {}", StructuredArguments.fields(loggingMeta))
161164

162165
val healthInformation = extractHelseOpplysningerArbeidsuforhet(fellesformat)
163166
val ediLoggId = receiverBlock.ediLoggId
164167
val sha256String = sha256hashstring(healthInformation)
165168
val msgId = msgHead.msgInfo.msgId
166169

170+
logger.info("TRACE_DEBUG: After health information, trace id: $randomUuid")
171+
167172
val legekontorHerId = extractOrganisationHerNumberFromSender(fellesformat)?.id
168173
val legekontorReshId = extractOrganisationRashNumberFromSender(fellesformat)?.id
169174
val legekontorOrgName =
@@ -172,6 +177,8 @@ class BlockingApplicationRunner(
172177
""
173178
)
174179

180+
logger.info("TRACE_DEBUG: After legekontorstuff, trace id: $randomUuid")
181+
175182
val partnerReferanse = receiverBlock.partnerReferanse
176183

177184
val originaltPasientFnr = healthInformation.pasient.fodselsnummer.id
@@ -186,6 +193,7 @@ class BlockingApplicationRunner(
186193

187194
val avsenderSystem = healthInformation.avsenderSystem.toAvsenderSystem()
188195

196+
logger.info("TRACE_DEBUG: Before sykmelding stuff, trace id: $randomUuid")
189197
val sykmeldingId = UUID.randomUUID().toString()
190198

191199
val rulesetVersion = healthInformation.regelSettVersjon
@@ -203,6 +211,7 @@ class BlockingApplicationRunner(
203211
rulesetVersion,
204212
)
205213

214+
logger.info("TRACE_DEBUG: Before extract, trace id: $randomUuid")
206215
logger.info(
207216
"Extracted data, ready to make sync calls to get more data, {}",
208217
StructuredArguments.fields(loggingMeta),
@@ -221,6 +230,7 @@ class BlockingApplicationRunner(
221230
)
222231
}
223232

233+
logger.info("TRACE_DEBUG: Before signatur, trace id: $randomUuid")
224234
val signaturFnr =
225235
if (erVirksomhetSykmelding) {
226236
logger.info(
@@ -269,20 +279,27 @@ class BlockingApplicationRunner(
269279
} else {
270280
receiverBlock.avsenderFnrFraDigSignatur
271281
}
282+
logger.info("TRACE_DEBUG: After signatur, trace id: $randomUuid")
272283

284+
logger.info("TRACE_DEBUG: before PDL, trace id: $randomUuid")
273285
val identer =
274286
pdlPersonService.getIdenter(
275287
listOf(signaturFnr, originaltPasientFnr),
276288
loggingMeta,
277289
)
290+
logger.info("TRACE_DEBUG: After PDL, trace id: $randomUuid")
278291

292+
logger.info("TRACE_DEBUG: Before TSSID, trace id: $randomUuid")
279293
val tssIdEmottak =
280294
smtssClient.findBestTssIdEmottak(
281295
signaturFnr,
282296
legekontorOrgName,
283297
loggingMeta,
284298
sykmeldingId,
285299
)
300+
logger.info("TRACE_DEBUG: After TSSID, trace id: $randomUuid")
301+
302+
logger.info("TRACE_DEBUG: Before TSSID INFOTOAST, trace id: $randomUuid")
286303
val tssIdInfotrygd =
287304
if (!tssIdEmottak.isNullOrEmpty()) {
288305
tssIdEmottak
@@ -294,6 +311,7 @@ class BlockingApplicationRunner(
294311
sykmeldingId,
295312
)
296313
}
314+
logger.info("TRACE_DEBUG: After TTSID INFOTOAST, trace id: $randomUuid")
297315

298316
logger.info(
299317
"tssIdEmottak is $tssIdEmottak {}",
@@ -304,6 +322,7 @@ class BlockingApplicationRunner(
304322
StructuredArguments.fields(loggingMeta),
305323
)
306324

325+
logger.info("TRACE_DEBUG: Before emottak sub, trace id: $randomUuid")
307326
handleEmottakSubscription(
308327
tssIdEmottak,
309328
emottakSubscriptionClient,
@@ -312,11 +331,16 @@ class BlockingApplicationRunner(
312331
partnerReferanse,
313332
loggingMeta,
314333
)
334+
logger.info("TRACE_DEBUG: After emottak sub, trace id: $randomUuid")
335+
315336

337+
logger.info("TRACE_DEBUG: Before dup check, trace id: $randomUuid")
316338
val duplicationCheckSha256String =
317339
duplicationService.getDuplicationCheck(sha256String, ediLoggId)
340+
logger.info("TRACE_DEBUG: After dup check, trace id: $randomUuid")
318341

319342
if (duplicationCheckSha256String != null) {
343+
logger.info("TRACE_DEBUG: Inside dup check not null, trace id: $randomUuid")
320344
val duplicate =
321345
Duplicate(
322346
sykmeldingId,
@@ -341,8 +365,10 @@ class BlockingApplicationRunner(
341365
duplicationService,
342366
duplicate,
343367
)
368+
logger.info("TRACE_DEBUG: After dup check not null, trace id: $randomUuid")
344369
continue@loop
345370
} else {
371+
logger.info("TRACE_DEBUG: Inside dup check IS! null, trace id: $randomUuid")
346372
val pasient = identer[originaltPasientFnr]
347373
val behandler = identer[signaturFnr]
348374

@@ -363,14 +389,17 @@ class BlockingApplicationRunner(
363389
duplicateCheck,
364390
)
365391
) {
392+
logger.info("TRACE_DEBUG: Inside dup check skipping??, trace id: $randomUuid")
366393
continue@loop
367394
}
368395

396+
logger.info("TRACE_DEBUG: Inside dup check before behandler, trace id: $randomUuid")
369397
val signerendeBehandler =
370398
norskHelsenettClient.getByFnr(
371399
fnr = signaturFnr,
372400
loggingMeta = loggingMeta,
373401
)
402+
logger.info("TRACE_DEBUG: Inside dup check after behandler, trace id: $randomUuid")
374403

375404
val behandlenedeBehandler =
376405
if (
@@ -388,6 +417,7 @@ class BlockingApplicationRunner(
388417
null
389418
}
390419

420+
logger.info("TRACE_DEBUG: Inside dup check before behandlene behandler, trace id: $randomUuid")
391421
val behandlenedeBehandlerFnr =
392422
extractFnrDnrFraBehandler(healthInformation)
393423
?: getBehandlerFnr(
@@ -396,7 +426,9 @@ class BlockingApplicationRunner(
396426
behandlenedeBehandler = behandlenedeBehandler,
397427
)
398428
?: signaturFnr
429+
logger.info("TRACE_DEBUG: Inside dup check after behandlene behandler, trace id: $randomUuid")
399430

431+
logger.info("TRACE_DEBUG: Inside dup check before behandlene behandler (HPR), trace id: $randomUuid")
400432
val behandlenedeBehandlerhprNummer =
401433
padHpr(extractHpr(fellesformat)?.id?.trim())
402434
?: getBehandlerHprNr(
@@ -405,6 +437,7 @@ class BlockingApplicationRunner(
405437
avsenderHpr = padHpr(extractHpr(fellesformat)?.id?.trim()),
406438
behandlenedeBehandler = behandlenedeBehandler,
407439
)
440+
logger.info("TRACE_DEBUG: Inside dup check after behandlene behandler (HPR), trace id: $randomUuid")
408441

409442
val sykmelding =
410443
healthInformation.toSykmelding(
@@ -430,6 +463,7 @@ class BlockingApplicationRunner(
430463
)
431464
}
432465

466+
logger.info("TRACE_DEBUG: Inside dup check before vedlegg, trace id: $randomUuid")
433467
if (vedlegg.isNotEmpty()) {
434468
val vedleggOver300MegaByte =
435469
vedlegg.filter {
@@ -468,6 +502,8 @@ class BlockingApplicationRunner(
468502
continue@loop
469503
}
470504
}
505+
logger.info("TRACE_DEBUG: Inside dup check after vedlegg, trace id: $randomUuid")
506+
471507

472508
if (sykmelding.signaturDato.isAfter(LocalDateTime.now())) {
473509
handleSignaturDatoInTheFuture(
@@ -484,6 +520,7 @@ class BlockingApplicationRunner(
484520
continue@loop
485521
}
486522

523+
logger.info("TRACE_DEBUG: Inside dup check before vedlegg LISTE, trace id: $randomUuid")
487524
val vedleggListe: List<String> =
488525
if (vedlegg.isNotEmpty()) {
489526
bucketUploadService.lastOppVedlegg(
@@ -503,7 +540,9 @@ class BlockingApplicationRunner(
503540
} else {
504541
emptyList()
505542
}
543+
logger.info("TRACE_DEBUG: Inside dup check after vedlegg LISTE, trace id: $randomUuid")
506544

545+
// ASSUMED OK HER
507546
val receivedSykmelding =
508547
ReceivedSykmelding(
509548
sykmelding = sykmelding,
@@ -553,6 +592,7 @@ class BlockingApplicationRunner(
553592
loggingMeta,
554593
)
555594

595+
logger.info("TRACE_DEBUG: Inside dup check before WHEN, trace id: $randomUuid")
556596
when (validationResult.status) {
557597
Status.OK ->
558598
handleStatusOK(

0 commit comments

Comments
 (0)