Background:
I have a simple Spring Boot application consisting of three services. The services communicate via HTTP REST calls. Below is a brief description of the services.
Mission planner (localhost:9100)
/v1/missionServices/missionPlanning/planMission) from a "client". A simple response message is returned to the caller.Route Generator (localhost:9110)
/v1/missionServices/missionPlanning/generateRoute). Returns a response message to the mission planner.Route Assessor (localhost:9120)
/v1/missionServices/missionPlanning/assessRoute). Returns a response message to the mission planner.The mission planner "client" is a fourth service that triggers the "plan mission" process by sending a POST request to the mission planner. This is not part of the integration test. Instead, the Citrus test takes its place.
Objective:
I'm attempting to use the Citrus Framework to perform integration tests on the services, separately and as a whole (end-to-end). I have been successful with the simpler service cases (i.e. the route generator and route assessor), but testing the mission planner has proven to present many difficulties.
Below is the Citrus test I've written for the mission planner. Currently I am "mocking" the route generator and route assessor services, but for an end-to-end test, will need to figure out how to do this will all three services "live" - I won't worry about that for now. I have built this based on examples I have found and from what I have learned during my experience.
MissionPlannerIT.java:
public class MissionPlannerIT extends JUnit4CitrusTest {
@Autowired
@Qualifier("routeGeneratorServer")
private HttpServer rgServer;
@Autowired
@Qualifier("routeAssessorServer")
private HttpServer raServer;
@Autowired
@Qualifier("missionPlannerClient")
private HttpClient sutClient;
@Test
@CitrusTest
// @formatter:off
public void testPlanMission(@CitrusResource TestRunner runner) {
runner.description("Test mission planning 'plan mission' REST endpoint");
// Call mission planner to plan a mission.
runner.http(builder -> builder
.client(sutClient)
.send()
.post("/v1/missionServices/missionPlanning/planMission"));
runner.echo("Sent plan mission");
// Set route generator to receive and validate generate route command.
runner.http(builder -> builder
.server(rgServer)
.receive()
.post("/v1/missionServices/missionPlanning/generateRoute")
.accept(ContentType.APPLICATION_JSON.getMimeType())
.payload(new ClassPathResource("templates/gen-route-command.json")));
runner.echo("RG received generate route");
// Set route generator to return response.
runner.http(builder -> builder
.server(rgServer)
.send()
.response(HttpStatus.OK)
.messageType(MessageType.JSON)
.contentType(ContentType.APPLICATION_JSON.getMimeType())
.payload(new ClassPathResource("templates/gen-route-status.json")));
runner.echo("RG sent generate route status");
// Set route assessor to receive and validate assess route command.
runner.http(builder -> builder
.server(raServer)
.receive()
.post("/v1/missionServices/missionPlanning/assessRoute")
.accept(ContentType.APPLICATION_JSON.getMimeType())
.payload(new ClassPathResource("templates/assess-route-command.json")));
runner.echo("RA received assess route");
// Set route assessor to return response.
runner.http(builder -> builder
.server(raServer)
.send()
.response(HttpStatus.OK)
.messageType(MessageType.JSON)
.contentType(ContentType.APPLICATION_JSON.getMimeType())
.payload(new ClassPathResource("templates/assess-route-status.json")));
runner.echo("RA sent assess route status");
// Expect a success response from mission planner.
runner.http(builder -> builder
.client(sutClient)
.receive()
.response(HttpStatus.OK)
.messageType(MessageType.JSON)
.payload(new ClassPathResource("templates/plan-mission-response.json")));
runner.echo("Received MP response");
// Shut down route services. TODO may not need this
runner.stop(rgServer);
runner.stop(raServer);
}
// @formatter:on
}
EndpointConfig.java:
@Configuration
public class EndpointConfig {
@Bean
public HttpClient missionPlannerClient() {
return CitrusEndpoints.http().client().requestUrl("http://localhost:9100").build();
}
@Bean
public Server routeGeneratorServer() {
return CitrusEndpoints.http().server().port(9110).timeout(10000).autoStart(true).build();
}
@Bean
public Server routeAssessorServer() {
return CitrusEndpoints.http().server().port(9120).timeout(10000).autoStart(true).build();
}
@Bean("defaultJsonMessageValidator")
public JsonTextMessageValidator jsonValidator() {
return new JsonTextMessageValidator();
}
}
There are a couple of ways I run this test: 1) as part of a maven build, and 2) using eclipse. I'm having issues when running it as a maven build, where most of the test console output is not output (see Citrus Framework logging - how to enable/use and Citrus Framework - echo action does not "echo"). When I run it via eclipse, I need to start the mission planner manually before running the test.
Output:
I'm including portions of the console log from the eclipse run method, since it includes information missing when using the maven method. I will try to include what I think are pertinent sections and include my notes/thoughts along the way.
Summary:
Test step 1 - Do the initial POST to mission planner to start process:
15:00:50.689 [main] DEBUG com.consol.citrus.report.LoggingReporter - TEST STEP 1: send
15:00:52.598 [main] DEBUG com.consol.citrus.message.correlation.DefaultCorrelationManager - Saving correlation key for 'citrus_message_correlator_missionPlannerClient'
15:00:52.598 [main] DEBUG com.consol.citrus.context.TestContext - Setting variable: citrus_message_correlator_missionPlannerClient with value: 'citrus_message_id = '3f242515-7eb2-4aed-a85c-53a4560029b4''
15:00:52.598 [main] DEBUG com.consol.citrus.http.client.HttpClient - Sending HTTP message to: 'http://localhost:9100/v1/missionServices/missionPlanning/planMission'
15:00:52.598 [main] DEBUG com.consol.citrus.http.client.HttpClient - Message to send:
15:00:52.601 [main] DEBUG org.springframework.integration.http.support.DefaultHttpHeaderMapper - outboundHeaderNames=[Accept, Accept-Charset, Accept-Encoding, Accept-Language, Accept-Ranges, Authorization, Cache-Control, Connection, Content-Length, Content-Type, Cookie, Date, Expect, From, Host, If-Match, If-Modified-Since, If-None-Match, If-Range, If-Unmodified-Since, Max-Forwards, Pragma, Proxy-Authorization, Range, Referer, TE, Upgrade, User-Agent, Via, Warning]
15:00:52.601 [main] DEBUG org.springframework.integration.http.support.DefaultHttpHeaderMapper - headerName=[citrus_message_timestamp] WILL NOT be mapped
15:00:52.601 [main] DEBUG org.springframework.integration.http.support.DefaultHttpHeaderMapper - headerName=[citrus_message_type] WILL NOT be mapped
15:00:52.601 [main] DEBUG org.springframework.integration.http.support.DefaultHttpHeaderMapper - headerName=[citrus_request_path] WILL NOT be mapped
15:00:52.601 [main] DEBUG org.springframework.integration.http.support.DefaultHttpHeaderMapper - headerName=[citrus_http_request_uri] WILL NOT be mapped
15:00:52.601 [main] DEBUG org.springframework.integration.http.support.DefaultHttpHeaderMapper - headerName=[id] WILL NOT be mapped
15:00:52.601 [main] DEBUG org.springframework.integration.http.support.DefaultHttpHeaderMapper - headerName=[citrus_message_id] WILL NOT be mapped
15:00:52.601 [main] DEBUG org.springframework.integration.http.support.DefaultHttpHeaderMapper - headerName=[citrus_http_method] WILL NOT be mapped
15:00:52.601 [main] DEBUG org.springframework.integration.http.support.DefaultHttpHeaderMapper - headerName=[timestamp] WILL NOT be mapped
15:00:52.607 [main] DEBUG org.springframework.web.client.RestTemplate - HTTP POST http://localhost:9100/v1/missionServices/missionPlanning/planMission
15:00:52.610 [main] DEBUG org.springframework.web.client.RestTemplate - Accept=[text/plain, application/json, application/*+json, */*]
15:00:52.611 [main] DEBUG org.springframework.web.client.RestTemplate - Writing [] as "text/plain;charset=UTF-8"
15:00:52.656 [main] DEBUG com.consol.citrus.http.interceptor.LoggingClientInterceptor - Sending Http request message
15:00:52.657 [main] DEBUG Logger.Message_OUT - POST http://localhost:9100/v1/missionServices/missionPlanning/planMission
Accept:text/plain, application/json, application/*+json, */*
Content-Type:text/plain;charset=UTF-8
Content-Length:0
Accept-Charset:big5, big5-hkscs, cesu-8, euc-jp, euc-kr, gb18030, gb2312, gbk, ibm-thai, ibm00858, ibm01140, ibm01141, ibm01142, ibm01143, ibm01144, ibm01145, ibm01146, ibm01147, ibm01148, ibm01149, ibm037, ibm1026, ibm1047, ibm273, ibm277, ibm278, ibm280, ibm284, ibm285, ibm290, ibm297, ibm420, ibm424, ibm437, ibm500, ibm775, ibm850, ibm852, ibm855, ibm857, ibm860, ibm861, ibm862, ibm863, ibm864, ibm865, ibm866, ibm868, ibm869, ibm870, ibm871, ibm918, iso-2022-cn, iso-2022-jp, iso-2022-jp-2, iso-2022-kr, iso-8859-1, iso-8859-13, iso-8859-15, iso-8859-2, iso-8859-3, iso-8859-4, iso-8859-5, iso-8859-6, iso-8859-7, iso-8859-8, iso-8859-9, jis_x0201, jis_x0212-1990, koi8-r, koi8-u, shift_jis, tis-620, us-ascii, utf-16, utf-16be, utf-16le, utf-32, utf-32be, utf-32le, utf-8, windows-1250, windows-1251, windows-1252, windows-1253, windows-1254, windows-1255, windows-1256, windows-1257, windows-1258, windows-31j, x-big5-hkscs-2001, x-big5-solaris, x-euc-jp-linux, x-euc-tw, x-eucjp-open, x-ibm1006, x-ibm1025, x-ibm1046, x-ibm1097, x-ibm1098, x-ibm1112, x-ibm1122, x-ibm1123, x-ibm1124, x-ibm1166, x-ibm1364, x-ibm1381, x-ibm1383, x-ibm300, x-ibm33722, x-ibm737, x-ibm833, x-ibm834, x-ibm856, x-ibm874, x-ibm875, x-ibm921, x-ibm922, x-ibm930, x-ibm933, x-ibm935, x-ibm937, x-ibm939, x-ibm942, x-ibm942c, x-ibm943, x-ibm943c, x-ibm948, x-ibm949, x-ibm949c, x-ibm950, x-ibm964, x-ibm970, x-iscii91, x-iso-2022-cn-cns, x-iso-2022-cn-gb, x-iso-8859-11, x-jis0208, x-jisautodetect, x-johab, x-macarabic, x-maccentraleurope, x-maccroatian, x-maccyrillic, x-macdingbat, x-macgreek, x-machebrew, x-maciceland, x-macroman, x-macromania, x-macsymbol, x-macthai, x-macturkish, x-macukraine, x-ms932_0213, x-ms950-hkscs, x-ms950-hkscs-xp, x-mswin-936, x-pck, x-sjis_0213, x-utf-16le-bom, x-utf-32be-bom, x-utf-32le-bom, x-windows-50220, x-windows-50221, x-windows-874, x-windows-949, x-windows-950, x-windows-iso2022jp
I assume this is recording activity indicating that the mission planner has made the POST request to the route generator:
15:00:52.801 [qtp923083575-34] DEBUG org.eclipse.jetty.server.HttpChannel - REQUEST for //localhost:9110/v1/missionServices/missionPlanning/generateRoute on HttpChannelOverHttp@4df838fc{r=1,c=false,c=false/false,a=IDLE,uri=//localhost:9110/v1/missionServices/missionPlanning/generateRoute,age=1}
POST //localhost:9110/v1/missionServices/missionPlanning/generateRoute HTTP/1.1
Accept: application/json
Content-Type: application/json
elastic-apm-traceparent: 00-eb0d1dffcf09adda45d39323efc6f883-7236b8b42e4e90d5-01
Content-Length: 311
Host: localhost:9110
Connection: keep-alive
User-Agent: Apache-HttpClient/4.5.9 (Java/1.8.0_201)
Accept-Encoding: gzip,deflate
...
15:00:52.828 [qtp923083575-34] DEBUG com.consol.citrus.http.interceptor.LoggingHandlerInterceptor - Received Http request:
HTTP/1.1 POST /v1/missionServices/missionPlanning/generateRoute
elastic-apm-traceparent:00-eb0d1dffcf09adda45d39323efc6f883-7236b8b42e4e90d5-01
Accept:application/json
Connection:keep-alive
User-Agent:Apache-HttpClient/4.5.9 (Java/1.8.0_201)
Host:localhost:9110
Accept-Encoding:gzip,deflate
Content-Length:311
Content-Type:application/json
{"header":{"timestamp":1581364852723,"typeID":"edu.mit.ll.mission_services.messages.GenerateRouteCommand","transaction":{"id":2,"startTime":1581364852723},"signature":{"algorithm":null,"keySize":0,"keyValue":null,"sender":null}},"commandID":"60b684f1-5065-47d6-8e7d-a4f101b44d22","commandType":"GENERATE_ROUTE"}
...
15:00:52.851 [qtp923083575-34] DEBUG com.consol.citrus.channel.ChannelSyncProducer - Sending message to channel: 'routeGeneratorServer.inbound'
15:00:52.851 [qtp923083575-34] DEBUG com.consol.citrus.channel.ChannelSyncProducer - Message to send is:
HTTPMESSAGE [id: 900d8f51-b1cf-427e-9f00-cd5b242b5dca, payload: {"header":{"timestamp":1581364852723,"typeID":"edu.mit.ll.mission_services.messages.GenerateRouteCommand","transaction":{"id":2,"startTime":1581364852723},"signature":{"algorithm":null,"keySize":0,"keyValue":null,"sender":null}},"commandID":"60b684f1-5065-47d6-8e7d-a4f101b44d22","commandType":"GENERATE_ROUTE"}][headers: {Accept=application/json, Connection=keep-alive, User-Agent=Apache-HttpClient/4.5.9 (Java/1.8.0_201), Host=localhost:9110, Accept-Encoding=gzip,deflate, Content-Length=311, contentType=application/json;charset=UTF-8, citrus_message_id=900d8f51-b1cf-427e-9f00-cd5b242b5dca, citrus_message_timestamp=1581364852849, elastic-apm-traceparent=00-eb0d1dffcf09adda45d39323efc6f883-7236b8b42e4e90d5-01, Content-Type=application/json;charset=UTF-8, citrus_http_request_uri=/v1/missionServices/missionPlanning/generateRoute, citrus_request_path=/v1/missionServices/missionPlanning/generateRoute, citrus_endpoint_uri=/v1/missionServices/missionPlanning/generateRoute, citrus_http_context_path=, citrus_http_query_params=, citrus_query_params=, citrus_http_version=HTTP/1.1, citrus_http_method=POST}]
15:00:52.851 [qtp923083575-34] INFO com.consol.citrus.channel.ChannelSyncProducer - Message was sent to channel: 'routeGeneratorServer.inbound'
15:00:57.729 [main] DEBUG org.apache.http.wire - http-outgoing-0 << "HTTP/1.1 503 Service Unavailable[\r][\n]"
15:00:57.730 [main] DEBUG org.apache.http.wire - http-outgoing-0 << "Date: Mon, 10 Feb 2020 20:00:52 GMT[\r][\n]"
15:00:57.730 [main] DEBUG org.apache.http.wire - http-outgoing-0 << "X-Content-Type-Options: nosniff[\r][\n]"
15:00:57.730 [main] DEBUG org.apache.http.wire - http-outgoing-0 << "X-XSS-Protection: 1; mode=block[\r][\n]"
15:00:57.730 [main] DEBUG org.apache.http.wire - http-outgoing-0 << "Pragma: no-cache[\r][\n]"
15:00:57.730 [main] DEBUG org.apache.http.wire - http-outgoing-0 << "X-Frame-Options: DENY[\r][\n]"
15:00:57.730 [main] DEBUG org.apache.http.wire - http-outgoing-0 << "X-Content-Type-Options: nosniff[\r][\n]"
15:00:57.730 [main] DEBUG org.apache.http.wire - http-outgoing-0 << "Content-Type: application/json;charset=utf-8[\r][\n]"
15:00:57.730 [main] DEBUG org.apache.http.wire - http-outgoing-0 << "Transfer-Encoding: chunked[\r][\n]"
15:00:57.730 [main] DEBUG org.apache.http.wire - http-outgoing-0 << "[\r][\n]"
15:00:57.730 [main] DEBUG org.apache.http.wire - http-outgoing-0 << "B0[\r][\n]"
15:00:57.730 [main] DEBUG org.apache.http.wire - http-outgoing-0 << "{"timestamp":"2020-02-10T20:00:57.728+0000","status":503,"error":"Service Unavailable","message":"Service Unavailable","path":"/v1/missionServices/missionPlanning/planMission"}"
15:00:57.736 [main] DEBUG org.apache.http.headers - http-outgoing-0 << HTTP/1.1 503 Service Unavailable
15:00:57.736 [main] DEBUG org.apache.http.headers - http-outgoing-0 << Date: Mon, 10 Feb 2020 20:00:52 GMT
15:00:57.736 [main] DEBUG org.apache.http.headers - http-outgoing-0 << X-Content-Type-Options: nosniff
15:00:57.736 [main] DEBUG org.apache.http.headers - http-outgoing-0 << X-XSS-Protection: 1; mode=block
15:00:57.736 [main] DEBUG org.apache.http.headers - http-outgoing-0 << Pragma: no-cache
15:00:57.736 [main] DEBUG org.apache.http.headers - http-outgoing-0 << X-Frame-Options: DENY
15:00:57.736 [main] DEBUG org.apache.http.headers - http-outgoing-0 << X-Content-Type-Options: nosniff
15:00:57.736 [main] DEBUG org.apache.http.headers - http-outgoing-0 << Content-Type: application/json;charset=utf-8
15:00:57.736 [main] DEBUG org.apache.http.headers - http-outgoing-0 << Transfer-Encoding: chunked
15:00:57.747 [main] DEBUG org.apache.http.impl.execchain.MainClientExec - Connection can be kept alive indefinitely
15:00:57.751 [main] DEBUG org.apache.http.wire - http-outgoing-0 << "[\r][\n]"
15:00:57.751 [main] DEBUG org.apache.http.wire - http-outgoing-0 << "0[\r][\n]"
15:00:57.751 [main] DEBUG org.apache.http.wire - http-outgoing-0 << "[\r][\n]"
Our first indication of a problem - we are still in test step 1 by the way:
15:00:57.752 [main] DEBUG com.consol.citrus.http.interceptor.LoggingClientInterceptor - Received Http response message
15:00:57.752 [main] DEBUG Logger.Message_IN - HTTP/1.1 503 SERVICE_UNAVAILABLE Service Unavailable
Date:Mon, 10 Feb 2020 20:00:52 GMT
X-Content-Type-Options:nosniff,nosniff
X-XSS-Protection:1; mode=block
Pragma:no-cache
X-Frame-Options:DENY
Content-Type:application/json;charset=utf-8
Transfer-Encoding:chunked
{"timestamp":"2020-02-10T20:00:57.728+0000","status":503,"error":"Service Unavailable","message":"Service Unavailable","path":"/v1/missionServices/missionPlanning/planMission"}
15:00:57.752 [main] DEBUG org.springframework.web.client.RestTemplate - Response 503 SERVICE_UNAVAILABLE
15:00:57.757 [main] INFO com.consol.citrus.http.client.HttpClient - Caught HTTP rest client exception: 503 Service Unavailable
15:00:57.757 [main] INFO com.consol.citrus.http.client.HttpClient - Propagating HTTP rest client exception according to error handling strategy
Completion of test step 1:
15:00:57.760 [main] DEBUG com.consol.citrus.message.correlation.DefaultCorrelationManager - Saving correlated object for 'citrus_message_id = '3f242515-7eb2-4aed-a85c-53a4560029b4''
15:00:57.760 [main] INFO com.consol.citrus.report.LoggingReporter -
15:00:57.760 [main] DEBUG com.consol.citrus.report.LoggingReporter - TEST STEP 1 SUCCESS
Test step 3 - mock route generator receive request from mission planner:
15:00:57.779 [main] DEBUG com.consol.citrus.util.FileUtils - Reading file resource: 'gen-route-command.json' (encoding is 'UTF-8')
15:00:57.781 [main] INFO com.consol.citrus.report.LoggingReporter -
15:00:57.781 [main] DEBUG com.consol.citrus.report.LoggingReporter - TEST STEP 3: receive
15:00:57.791 [main] DEBUG com.consol.citrus.channel.ChannelConsumer - Receiving message from: routeGeneratorServer.inbound
15:00:57.792 [main] DEBUG com.consol.citrus.channel.ChannelConsumer - Received message from: routeGeneratorServer.inbound
... Received request from mission planner
15:00:57.801 [main] DEBUG com.consol.citrus.validation.MessageValidatorRegistry - Found 4 message validators for message type: XML
15:00:57.801 [main] DEBUG com.consol.citrus.validation.json.JsonTextMessageValidator - Start JSON message validation ...
15:00:57.801 [main] DEBUG com.consol.citrus.validation.json.JsonTextMessageValidator - Received message:
HTTPMESSAGE [id: 900d8f51-b1cf-427e-9f00-cd5b242b5dca, payload: {"header":{"timestamp":1581364852723,"typeID":"edu.mit.ll.mission_services.messages.GenerateRouteCommand","transaction":{"id":2,"startTime":1581364852723},"signature":{"algorithm":null,"keySize":0,"keyValue":null,"sender":null}},"commandID":"60b684f1-5065-47d6-8e7d-a4f101b44d22","commandType":"GENERATE_ROUTE"}][headers: {Accept=application/json, Connection=keep-alive, User-Agent=Apache-HttpClient/4.5.9 (Java/1.8.0_201), Host=localhost:9110, Accept-Encoding=gzip,deflate, Content-Length=311, contentType=application/json;charset=UTF-8, citrus_message_id=900d8f51-b1cf-427e-9f00-cd5b242b5dca, citrus_message_timestamp=1581364852849, elastic-apm-traceparent=00-eb0d1dffcf09adda45d39323efc6f883-7236b8b42e4e90d5-01, Content-Type=application/json;charset=UTF-8, citrus_http_request_uri=/v1/missionServices/missionPlanning/generateRoute, citrus_request_path=/v1/missionServices/missionPlanning/generateRoute, citrus_endpoint_uri=/v1/missionServices/missionPlanning/generateRoute, citrus_http_context_path=, citrus_http_query_params=, citrus_query_params=, citrus_http_version=HTTP/1.1, citrus_http_method=POST, replyChannel=org.springframework.messaging.core.GenericMessagingTemplate$TemporaryReplyChannel@3db663d0, errorChannel=org.springframework.messaging.core.GenericMessagingTemplate$TemporaryReplyChannel@3db663d0, id=10be4cec-6d61-d00a-f0e6-baed32421725, timestamp=1581364852856}]
15:00:57.802 [main] DEBUG com.consol.citrus.validation.json.JsonTextMessageValidator - Control message:
HTTPMESSAGE [id: d0d27c94-533e-4724-b87a-5a8d4d05950d, payload: {
"header": {
"timestamp": "@isNumber()@",
"typeID": "edu.mit.ll.mission_services.messages.GenerateRouteCommand",
"transaction": {
"id": "@isNumber()@",
"startTime": "@isNumber()@"
},
"signature": {
"algorithm": null,
"keySize": 0,
"keyValue": null,
"sender": null
}
},
"commandID": "@ignore@",
"commandType": "GENERATE_ROUTE"
}][headers: {citrus_message_id=d0d27c94-533e-4724-b87a-5a8d4d05950d, citrus_message_timestamp=1581364857769, citrus_http_method=POST, citrus_http_request_uri=/v1/missionServices/missionPlanning/generateRoute, citrus_request_path=/v1/missionServices/missionPlanning/generateRoute, Accept=application/json, citrus_message_type=XML}]
15:00:57.923 [main] DEBUG com.consol.citrus.report.LoggingReporter - TEST STEP 3 SUCCESS
Skip forward to completion of step 10 (an echo). I assume this is step 9 activity finishing up.
15:00:57.986 [main] DEBUG com.consol.citrus.report.LoggingReporter - TEST STEP 10 SUCCESS
15:00:57.987 [qtp203936099-36] DEBUG org.springframework.web.servlet.mvc.method.annotation.HttpEntityMethodProcessor - Found 'Content-Type:application/json' in response
15:00:57.987 [qtp203936099-36] DEBUG org.springframework.web.servlet.mvc.method.annotation.HttpEntityMethodProcessor - Writing ["{
"header": {
"timestamp": 1580761681867,
"typeID": "edu.mit.ll.mission_services.messages.Asse (truncated)...]
15:00:57.987 [qtp203936099-36] DEBUG com.consol.citrus.http.interceptor.LoggingHandlerInterceptor - Sending Http response:
com.consol.citrus.http.servlet.GzipHttpServletResponseWrapper@61196037
{
"header": {
"timestamp": 1580761681867,
"typeID": "edu.mit.ll.mission_services.messages.AssessRouteStatus",
"transaction": {
"id": 1,
"startTime": 1580761681867
},
"signature": {
"algorithm": null,
"keySize": 0,
"keyValue": null,
"sender": null
}
},
"commandID": "0710d523-43da-4f68-90c7-a2b4544a955d",
"status": "COMPLETED"
}
15:00:57.987 [qtp203936099-36] DEBUG com.consol.citrus.http.servlet.CitrusDispatcherServlet - Completed 200 OK
Finally, this where the test reports a failure, although I think the problem started in step 1.
15:00:57.998 [main] DEBUG com.consol.citrus.report.LoggingReporter - TEST STEP 11: receive
15:00:58.000 [main] DEBUG com.consol.citrus.validation.MessageValidatorRegistry - Found 4 message validators for message type: JSON
15:00:58.000 [main] DEBUG com.consol.citrus.validation.json.JsonTextMessageValidator - Start JSON message validation ...
15:00:58.000 [main] DEBUG com.consol.citrus.validation.json.JsonTextMessageValidator - Received message:
HTTPMESSAGE [id: 43da4bd7-9929-4536-a9e6-caaabcb72c62, payload: {"timestamp":"2020-02-10T20:00:57.728+0000","status":503,"error":"Service Unavailable","message":"Service Unavailable","path":"/v1/missionServices/missionPlanning/planMission"}][headers: {Transfer-Encoding=chunked, Pragma=no-cache, contentType=application/json;charset=utf-8, Date=1581364852000, citrus_message_id=43da4bd7-9929-4536-a9e6-caaabcb72c62, citrus_message_timestamp=1581364857760, X-Frame-Options=DENY, X-Content-Type-Options=nosniff,nosniff, X-XSS-Protection=1; mode=block, Content-Type=application/json;charset=utf-8, citrus_http_status_code=503, citrus_http_reason_phrase=SERVICE_UNAVAILABLE, citrus_http_version=HTTP/1.1}]
15:00:58.000 [main] DEBUG com.consol.citrus.validation.json.JsonTextMessageValidator - Control message:
HTTPMESSAGE [id: 069509f7-2591-452f-886a-f3c1bb556b09, payload: {
"message": "Transaction complete"
}][headers: {citrus_message_id=069509f7-2591-452f-886a-f3c1bb556b09, citrus_message_timestamp=1581364857989, citrus_http_status_code=200, citrus_http_reason_phrase=OK, citrus_message_type=JSON}]
15:00:58.002 [main] INFO com.consol.citrus.report.LoggingReporter -
15:00:58.004 [main] ERROR com.consol.citrus.report.LoggingReporter - TEST FAILED MissionPlannerIT.testPlanMission <edu.mit.ll.mission_services.service.mission_planner> Nested exception is:
com.consol.citrus.exceptions.TestCaseFailedException: Failed to validate JSON text:
{"timestamp":"2020-02-10T20:00:57.728+0000","status":503,"error":"Service Unavailable","message":"Service Unavailable","path":"/v1/missionServices/missionPlanning/planMission"} Number of JSON entries not equal for element: '$.', expected '1' but was '5'
Thoughts:
The interactions between the SUT (the mission planner service) and the mocked generators seems to have all worked as expected. The messages passed back and forth and there appear to be no problems. What I don't understand is the appearance of the HTTP 503 error. It seems to occur during the first test step, but I have no idea what could be wrong.
I'm not even sure how to try to debug any of this. I'm not that familiar with how HTTP works. From my perspective, a lot of what's happening is going on behind the scenes and I don't know how to see what's going on in there.
If anyone sees something wrong in what I'm doing, please let me know. If anyone has ideas what might be happening, that would be very helpful. Finally, any suggestions on what I might do to try to debug this, would very much appreciated.
UPDATE:
I have modified the test to add timeout calls to the client and server endpoints. E.g.:
@Bean
public HttpClient missionPlannerClient() {
return CitrusEndpoints.http().client().requestUrl("http://localhost:9100").timeout(30000).build();
}
Unfortunately, this has had no impact on my problem.
I have also added the following to the SUT (mission planner) application.yml:
server:
port: 9100
...
jetty:
http:
idleTimeout: 60000
stopTimeout: 60000
connection-idle-timeout: 60000
thread-idle-timeout: 60000
This also seems to have no affect. I'm not 100% sure if I'm using the correct properties.
NOTE:
I ran an interesting experiment that did not involve Citrus, but where I ran all three real services and then attempted to POST the "plan mission" call via Postman. I got the same HTTP 503 response.
Now it turns out the real "route" services have a built-in, configurable delay to simulate a long running task. The delay was set to 5 seconds for each service.
I set these delays to 0 and POSTed with Postman again. This time it worked! I'm assuming that Postman has a default timeout and that the service delays exceeded that time, causing the observed result. Maybe? I would think I would get some sort of timeout message rather than "service unavailable".
The delays definitely had an impact on this test result, however, in the Citrus test case, the "route" services are being mocked and should not be introducing any artificial delay.
Just an interesting observation.
You are missing a fork=true on the very 1st test step where the Http client sends the initial request. Http is a synchronous protocol by nature and this means the the 1st step in your test will wait for the Http response before continuing with the other test steps. This means that all other test steps are not executed so your Http server mocks will not be able to operate properly.
I guess you will be hitting a lot of request timeouts on both client and Http server side because of this. And this may lead to the Http 503.