Result Get call not visible in ladybug

Question

Result Get call not visible in ladybug

Closed this issue 2 years ago · 5 comments

Describe the issue
When doing an get call using an Httpsender through test a pipeline, the result is shown in the GUI of test a pipeline yet the ladybug says empty string (I think this is due to streaming, because if i use an xsltpipe after the sender it does show up in de ladybug report)

Reporter
Tarik

To Reproduce
Use an Httpsender and send a message to an API, then look in the ladybug an look for the result

Screenshots
If applicable, add screenshots to help explain your problem.

Configuration

Please provide the configuration of the Pipe or Receiver with the problem.

<module>
	<adapter name="pand_info" description="This adapter fetches general information of the kadaster API " active="${pand_info.active}">
		<receiver name="pand_info">
			<listener name="pand_info" className="nl.nn.adapterframework.receivers.JavaListener"/>
		</receiver>
		
		<pipeline firstPipe="getAllInfo">
		
			<exits>
				<exit path="EXIT" state="success" code="200"/>
				<exit path="NotModified" state="success" code="304" empty="true" />
				<exit path="BadRequest" state="error" code="400" empty="true" />
				<exit path="NotAuthorized" state="error" code="401" empty="true" />
				<exit path="NotAllowed" state="error" code="403" empty="true" />
				<exit path="ServerError" state="error" code="500" />
			</exits>
			
			<pipe name="getAllInfo" className="nl.nn.adapterframework.pipes.SenderPipe">
				<sender className="nl.nn.adapterframework.http.HttpSender" 
					headersParams="X-Api-Key"
					methodType="GET"
					url="${test.url.algemeneInfo}">
	               <Param name="X-Api-Key" value="${apiKey}" />
            	</sender>
			</pipe>
			
			 <pipe name="formKeyRequest" className="nl.nn.adapterframework.pipes.XsltPipe"
			 	getInputFromFixedValue="&lt;dummy/&gt;"
				styleSheetName="pand-get/xsl/getRequestPand.xsl"
				storeResultInSessionKey="keyRequest">
				<param name="input" sessionKey="originalMessage" hidden="true"/>
			</pipe> 
			
		</pipeline>
	</adapter>
</module>

Input

Please provide an example of the input message. 
Alternatively, provide a Ladybug report.

Environment

FF! 7.7.1: frank4kadaster 002
Running on LPZWNL000033368 using Apache Tomcat/9.0.56
Java Version: OpenJDK Runtime Environment (1.8.0_292-b10)
Heap size: 147M, total JVM memory: 445M
Free disk space: 78GB, total disk space: 237GB
Up since: 2022-06-15 15:20:18 (24m)

Additional Environment

DBMS: [e.g. Oracle, MSSQL, MariaDB, MySql, PostgreSQL]
Browser: [e.g. Chrome, Safari, Edge, Firefox]

Additional Context
Add any other context about the problem here. (f.e. ladybug report / test adapter with larva test)

Answer 1 · 2022-06-20T10:02:49.000Z

It appears that the input and output of the last pipe is not shown in Ladybug, when inputstreaming is used.
See this ladybug report of a sequence of Base64Pipes: Pipeline HttpSender.zip
With a debug statement in the close() of the Base64InputStream logging is like:

2022-06-20 13:46:46,369 DEBUG [Thread-237] [mid [Test Tool correlation id(2)]] processors.MonitoringPipeProcessor - Pipeline of adapter [HttpSender] messageId [Test Tool correlation id(2)] is about to call pipe [b64_6] current result (Message) [InputStreamReader Message[1443fe0]: nl.nn.adapterframework.util.StreamUtil$8@8dfe84] 
2022-06-20 13:46:46,369 DEBUG [Thread-237] [mid [Test Tool correlation id(2)]] stream.Message - returning Reader Message[1443fe0] as InputStream
2022-06-20 13:46:46,369 DEBUG [Thread-237] [mid [Test Tool correlation id(2)]] stream.Message - creating capture of nl.nn.adapterframework.pipes.Base64Pipe$1
2022-06-20 13:46:46,369 DEBUG [Thread-237] [mid [Test Tool correlation id(2)]] stream.Message - returning InputStream Message[c68c22] as InputStream
2022-06-20 13:46:46,370 DEBUG [Thread-237] [mid [Test Tool correlation id(2)]] processors.CorePipeLineProcessor - Available session keys at finishing pipeline of adapter [HttpSender]:
 messageId=[Test Tool correlation id(2)]
 tsReceived=[2022-06-20 13:46:46.357]
 tcid=[Test Tool correlation id(2)]
 originalMessage=[String Message[159864]: <HttpListerSenderREQ/>]
 cid=[Test Tool correlation id(2)]
2022-06-20 13:46:46,370 DEBUG [Thread-237] [mid [Test Tool correlation id(2)]] processors.CorePipeLineProcessor - Pipeline of adapter [HttpSender] finished processing messageId [Test Tool correlation id(2)] result: (Message) [ Message[c68c22]: nl.nn.adapterframework.util.StreamUtil$7@15ab733] with exit-state [SUCCESS]
2022-06-20 13:46:46,372 DEBUG [Thread-237] [mid [Test Tool correlation id(2)]] core.Adapter - Adapter [HttpSender] messageId [Test Tool correlation id(2)] duration [14ms] got exit-state [SUCCESS] and result [ Message[c68c22]: nl.nn.adapterframework.util.StreamUtil$7@15ab733] from PipeLine
2022-06-20 13:46:46,374 DEBUG [Thread-237] [mid [Test Tool correlation id(2)]] core.Adapter - Adapter: [HttpSender] STAT: Finished processing message with messageId [Test Tool correlation id(2)] exit-state [SUCCESS] started 2022-06-20 13:46:46.358 finished 2022-06-20 13:46:46.373 total duration: 15 msecs
2022-06-20 13:46:46,374 DEBUG [Thread-237] null receivers.Receiver - Receiver [JavaListener] received result: exitState [SUCCESS], result [ Message[c68c22]: nl.nn.adapterframework.util.StreamUtil$7@15ab733]
2022-06-20 13:46:46,374 DEBUG [Thread-237] null receivers.Receiver - Receiver [JavaListener] canceling TimeoutGuard, isInterrupted [false]
2022-06-20 13:46:46,374 DEBUG [Thread-237] null receivers.Receiver - Receiver [JavaListener] caching first result for messageId [0a7244ab--39af5212_18180eec613_-7ffc]
2022-06-20 13:46:46,374 DEBUG [Thread-237] null receivers.Receiver - Receiver [JavaListener] finishes processing message
2022-06-20 13:46:46,374 DEBUG [Thread-237] null receivers.Receiver - Receiver [JavaListener] messageId [0a7244ab--39af5212_18180eec613_-7ffc] correlationId [Test Tool correlation id(2)] returning result [ Message[c68c22]: nl.nn.adapterframework.util.StreamUtil$7@15ab733]
2022-06-20 13:46:46,374 DEBUG [Thread-237] null stream.Message - returning InputStream Message[c68c22] as Reader
2022-06-20 13:46:46,374 DEBUG [Thread-237] null stream.Message - returning InputStream Message[c68c22] as InputStream
2022-06-20 13:46:46,375 DEBUG [Thread-237] null pipes.Base64Pipe - close Base64InputStream of [b64_6]
2022-06-20 13:46:46,375 DEBUG [Thread-237] null pipes.Base64Pipe - close Base64InputStream of [b64_5]
2022-06-20 13:46:46,375 DEBUG [Thread-237] null pipes.Base64Pipe - close Base64InputStream of [b64_4]
2022-06-20 13:46:46,375 DEBUG [Thread-237] null pipes.Base64Pipe - close Base64InputStream of [b64_3]
2022-06-20 13:46:46,375 DEBUG [Thread-237] null pipes.Base64Pipe - close Base64InputStream of [b64_2]
2022-06-20 13:46:46,375 DEBUG [Thread-237] null pipes.Base64Pipe - close Base64InputStream of [b64_1]
2022-06-20 13:46:46,375 DEBUG [Thread-237] null receivers.JavaListener$1 - Closing PipeLineSession

Answer 2 · 2022-07-02T21:02:57.000Z

I think the problem is that the message/stream isn't read or closed at the time the report is closed. Ladybug is configured to close the writer used in StreamUtil.captureReader() when the report is closed but the reader isn't read or closed at that time.

See also:

<property name="closeMessageCapturers" value="true"/> at https://github.com/ibissource/iaf/blob/master/ladybug/src/main/resources/springIbisTestTool.xml#L40

Message.captureCharacterStream() at https://github.com/ibissource/iaf/blob/master/ladybug/src/main/java/nl/nn/ibistesttool/MessageCapturer.java#L56

StreamUtil.captureReader() at https://github.com/ibissource/iaf/blob/master/core/src/main/java/nl/nn/adapterframework/stream/Message.java#L843

close() at https://github.com/ibissource/iaf/blob/master/core/src/main/java/nl/nn/adapterframework/util/StreamUtil.java#L602

Answer 3 · 2022-07-04T08:27:52.000Z

That sounds like a reasonable explanation, but there is a but: The preceding inputstreams, that Ladybug does show, are only closed when the last inputstream is closed.

Answer 4 · 2022-07-04T09:10:34.000Z

I hav modified line 118 of the Base64Pipe to contain the following code to display all calls to read() and close():

InputStream base64 = new Base64InputStream(binaryInputStream, directionEncode, getLineLength(), lineSeparatorArray) {

	@Override
	public int read() throws IOException {
		log.warn("--> read() "+getName());
		return super.read();
	}

	@Override
	public int read(byte[] array, int offset, int len) throws IOException {
		log.warn("--> read(array,offset,len) "+getName());
		return super.read(array, offset, len);
	}

	@Override
	public void close() throws IOException {
		log.warn("--> close() "+getName());
		super.close();
	}

	@Override
	public int read(byte[] arg0) throws IOException {
		log.warn("--> read(byte[]) "+getName());
		return super.read(arg0);
	}
	
};

This results in the following logging:

2022-07-04 12:39:31,681 DEBUG [Thread-239] [mid [Test Tool correlation id(2)]] stream.Message - returning InputStream Message[17a5fc7] as InputStream
2022-07-04 12:39:31,681 DEBUG [Thread-239] [mid [Test Tool correlation id(2)]] stream.Message - returning InputStream Message[125e670] as Reader
2022-07-04 12:39:31,681 DEBUG [Thread-239] [mid [Test Tool correlation id(2)]] stream.Message - returning InputStream Message[125e670] as InputStream
2022-07-04 12:39:31,681 WARN [Thread-239] [mid [Test Tool correlation id(2)]] pipes.Base64Pipe - --> read(array,offset,len) b64_1: [P]
2022-07-04 12:39:31,681 WARN [Thread-239] [mid [Test Tool correlation id(2)]] pipes.Base64Pipe - --> read(array,offset,len) b64_1: [E]
2022-07-04 12:39:31,681 WARN [Thread-239] [mid [Test Tool correlation id(2)]] pipes.Base64Pipe - --> read(array,offset,len) b64_1: [h]
2022-07-04 12:39:31,682 DEBUG [Thread-239] [mid [Test Tool correlation id(2)]] stream.Message - creating capture of InputStreamReader
2022-07-04 12:39:31,682 DEBUG [Thread-239] [mid [Test Tool correlation id(2)]] stream.Message - returning Reader Message[19d225] as Reader
2022-07-04 12:39:31,683 DEBUG [Thread-239] [mid [Test Tool correlation id(2)]] processors.MonitoringPipeProcessor - Pipeline of adapter [HttpSender] messageId [Test Tool correlation id(2)] is about to call pipe [b64_2] current result (Message) [InputStreamReader Message[19d225]: nl.nn.adapterframework.util.StreamUtil$8@13df12d]
2022-07-04 12:39:31,684 DEBUG [Thread-239] [mid [Test Tool correlation id(2)]] stream.Message - returning Reader Message[19d225] as InputStream
2022-07-04 12:39:31,684 DEBUG [Thread-239] [mid [Test Tool correlation id(2)]] stream.Message - creating capture of nl.nn.adapterframework.pipes.Base64Pipe$1
2022-07-04 12:39:31,684 DEBUG [Thread-239] [mid [Test Tool correlation id(2)]] stream.Message - returning InputStream Message[f07148] as InputStream
2022-07-04 12:39:31,685 DEBUG [Thread-239] [mid [Test Tool correlation id(2)]] processors.MonitoringPipeProcessor - Pipeline of adapter [HttpSender] messageId [Test Tool correlation id(2)] is about to call pipe [b64_3] current result (Message) [ Message[f07148]: nl.nn.adapterframework.util.StreamUtil$7@1920eb]
2022-07-04 12:39:31,685 DEBUG [Thread-239] [mid [Test Tool correlation id(2)]] stream.Message - returning InputStream Message[f07148] as InputStream
2022-07-04 12:39:31,685 DEBUG [Thread-239] [mid [Test Tool correlation id(2)]] stream.Message - returning InputStream Message[1d752be] as Reader
2022-07-04 12:39:31,685 DEBUG [Thread-239] [mid [Test Tool correlation id(2)]] stream.Message - returning InputStream Message[1d752be] as InputStream
2022-07-04 12:39:31,685 WARN [Thread-239] [mid [Test Tool correlation id(2)]] pipes.Base64Pipe - --> read(array,offset,len) b64_1: [0dHBMaXN0ZXJTZW5kZXJSRVEv]
2022-07-04 12:39:31,686 WARN [Thread-239] [mid [Test Tool correlation id(2)]] pipes.Base64Pipe - --> read(array,offset,len) b64_1: [Pg==
]
2022-07-04 12:39:31,687 WARN [Thread-239] [mid [Test Tool correlation id(2)]] pipes.Base64Pipe - --> read(array,offset,len) b64_1
2022-07-04 12:39:31,687 WARN [Thread-239] [mid [Test Tool correlation id(2)]] pipes.Base64Pipe - --> read(array,offset,len) b64_2: [<HttpListerSenderREQ/>]
2022-07-04 12:39:31,687 WARN [Thread-239] [mid [Test Tool correlation id(2)]] pipes.Base64Pipe - --> read(array,offset,len) b64_3: [P]
2022-07-04 12:39:31,687 WARN [Thread-239] [mid [Test Tool correlation id(2)]] pipes.Base64Pipe - --> read(array,offset,len) b64_3: [E]
2022-07-04 12:39:31,687 WARN [Thread-239] [mid [Test Tool correlation id(2)]] pipes.Base64Pipe - --> read(array,offset,len) b64_3: [h]
2022-07-04 12:39:31,688 DEBUG [Thread-239] [mid [Test Tool correlation id(2)]] stream.Message - creating capture of InputStreamReader
2022-07-04 12:39:31,688 DEBUG [Thread-239] [mid [Test Tool correlation id(2)]] stream.Message - returning Reader Message[19f00aa] as Reader
2022-07-04 12:39:31,688 DEBUG [Thread-239] [mid [Test Tool correlation id(2)]] processors.MonitoringPipeProcessor - Pipeline of adapter [HttpSender] messageId [Test Tool correlation id(2)] is about to call pipe [b64_4] current result (Message) [InputStreamReader Message[19f00aa]: nl.nn.adapterframework.util.StreamUtil$8@103ec6b]
2022-07-04 12:39:31,689 DEBUG [Thread-239] [mid [Test Tool correlation id(2)]] stream.Message - returning Reader Message[19f00aa] as InputStream
2022-07-04 12:39:31,689 DEBUG [Thread-239] [mid [Test Tool correlation id(2)]] stream.Message - creating capture of nl.nn.adapterframework.pipes.Base64Pipe$1
2022-07-04 12:39:31,689 DEBUG [Thread-239] [mid [Test Tool correlation id(2)]] stream.Message - returning InputStream Message[1b77381] as InputStream
2022-07-04 12:39:31,690 DEBUG [Thread-239] [mid [Test Tool correlation id(2)]] processors.CorePipeLineProcessor - Available session keys at finishing pipeline of adapter [HttpSender]:
messageId=[Test Tool correlation id(2)]
tsReceived=[2022-07-04 12:39:31.627]
tcid=[Test Tool correlation id(2)]
originalMessage=[String Message[18234b7]: <HttpListerSenderREQ/>]
cid=[Test Tool correlation id(2)]
2022-07-04 12:39:31,690 DEBUG [Thread-239] [mid [Test Tool correlation id(2)]] processors.CorePipeLineProcessor - Pipeline of adapter [HttpSender] finished processing messageId [Test Tool correlation id(2)] result: (Message) [ Message[1b77381]: nl.nn.adapterframework.util.StreamUtil$7@c6d88d] with exit-state [SUCCESS]
2022-07-04 12:39:31,690 WARN [Thread-239] [mid [Test Tool correlation id(2)]] processors.CorePipeLineProcessor - --> CorePipeLineProcessor.processPipeLine() exit
2022-07-04 12:39:31,692 DEBUG [Thread-239] [mid [Test Tool correlation id(2)]] core.Adapter - Adapter [HttpSender] messageId [Test Tool correlation id(2)] duration [63ms] got exit-state [SUCCESS] and result [ Message[1b77381]: nl.nn.adapterframework.util.StreamUtil$7@c6d88d] from PipeLine
2022-07-04 12:39:31,693 DEBUG [Thread-239] [mid [Test Tool correlation id(2)]] core.Adapter - Adapter: [HttpSender] STAT: Finished processing message with messageId [Test Tool correlation id(2)] exit-state [SUCCESS] started 2022-07-04 12:39:31.629 finished 2022-07-04 12:39:31.692 total duration: 63 msecs
2022-07-04 12:39:31,693 DEBUG [Thread-239] null receivers.Receiver - Receiver [JavaListener] received result: exitState [SUCCESS], result [ Message[1b77381]: nl.nn.adapterframework.util.StreamUtil$7@c6d88d]
2022-07-04 12:39:31,693 DEBUG [Thread-239] null receivers.Receiver - Receiver [JavaListener] canceling TimeoutGuard, isInterrupted [false]
2022-07-04 12:39:31,693 DEBUG [Thread-239] null receivers.Receiver - Receiver [JavaListener] caching first result for messageId [0a721a5c--4fa1762e_181c8a423e2_-7ffb]
2022-07-04 12:39:31,693 DEBUG [Thread-239] null receivers.Receiver - Receiver [JavaListener] finishes processing message
2022-07-04 12:39:31,693 DEBUG [Thread-239] null receivers.Receiver - Receiver [JavaListener] messageId [0a721a5c--4fa1762e_181c8a423e2_-7ffb] correlationId [Test Tool correlation id(2)] returning result [ Message[1b77381]: nl.nn.adapterframework.util.StreamUtil$7@c6d88d]
2022-07-04 12:39:31,693 DEBUG [Thread-239] null stream.Message - returning InputStream Message[1b77381] as Reader
2022-07-04 12:39:31,693 DEBUG [Thread-239] null stream.Message - returning InputStream Message[1b77381] as InputStream
2022-07-04 12:39:31,693 WARN [Thread-239] null pipes.Base64Pipe - --> read(array,offset,len) b64_3: [0dHBMaXN0ZXJTZW5kZXJSRVEv]
2022-07-04 12:39:31,694 WARN [Thread-239] null pipes.Base64Pipe - --> read(array,offset,len) b64_2
2022-07-04 12:39:31,694 WARN [Thread-239] null pipes.Base64Pipe - --> read(array,offset,len) b64_3: [Pg==
]
2022-07-04 12:39:31,694 WARN [Thread-239] null pipes.Base64Pipe - --> read(array,offset,len) b64_2
2022-07-04 12:39:31,694 WARN [Thread-239] null pipes.Base64Pipe - --> read(array,offset,len) b64_3
2022-07-04 12:39:31,694 WARN [Thread-239] null pipes.Base64Pipe - --> read(array,offset,len) b64_4: [<]
2022-07-04 12:39:31,694 WARN [Thread-239] null pipes.Base64Pipe - --> read(array,offset,len) b64_4: [H]
2022-07-04 12:39:31,694 WARN [Thread-239] null pipes.Base64Pipe - --> read(array,offset,len) b64_4: [t]
2022-07-04 12:39:31,694 WARN [Thread-239] null pipes.Base64Pipe - --> read(array,offset,len) b64_4: [tpListerSenderREQ/>]
2022-07-04 12:39:31,694 WARN [Thread-239] null pipes.Base64Pipe - --> read(array,offset,len) b64_4
2022-07-04 12:39:31,694 WARN [Thread-239] null pipes.Base64Pipe - --> close() b64_4
2022-07-04 12:39:31,694 WARN [Thread-239] null pipes.Base64Pipe - --> close() b64_3
2022-07-04 12:39:31,694 WARN [Thread-239] null pipes.Base64Pipe - --> close() b64_2
2022-07-04 12:39:31,694 WARN [Thread-239] null pipes.Base64Pipe - --> close() b64_1
2022-07-04 12:39:31,694 DEBUG [Thread-239] null stream.Message - closed InputStream and unregistering Message [context:
Content-Length: 22
Date: Mon, 04 Jul 2022 10:39:31 GMT
Keep-Alive: timeout=20
Connection: keep-alive
Metadata.Charset: ISO-8859-1
value:
ReleaseConnectionAfterReadInputStream Message[17a5fc7]: nl.nn.adapterframework.util.StreamUtil$7@1d6fcc3] from close on exit
2022-07-04 12:39:31,694 DEBUG [Thread-239] null receivers.JavaListener$1 - Closing PipeLineSession

Answer 5 · 2022-08-16T15:19:17.000Z

I've added CloseReportsTask that will give another option to close threads and message capturers:

e71b864

frankframework/frankframework#3575