Overview
HTTPRequest nodes are used to interact with web services. In the message flow, once the execution reaches the HTTPRequest node, it constructs an HTTP or an HTTP over SSL (HTTPS) request from the specified contents of the input message, and sends this request to the web service. The node receives the response from the web service, and parses the response for inclusion in the output tree. The node also generates HTTP headers if they are required by your configuration. As you can see the node performs multiple tasks and sometimes it is required to find out the exact time the node taken to send and get back the response from the external web server. This is mainly required in case if there is a performance issue observed with HTTPRequest node, then to confirm whether the delay is with external Web Server or not.
Different approaches to find out the exact time taken for web server interaction.
A node level Accounting and Statistics data can give us the time taken by the HTTPRequest node. But from this statistics alone, it is not possible to determine the time taken by the external webserver. In our illustration we use a message flow GetAccountMessageFlow with an HTTPRequest node named ‘get Account Details’. This node invokes the URL 'http://account-02-small-ace.cp.fyre.ibm.com/getAccountDetails'. The accounting and statistics data shows that on an average ‘get Account Details’ HTTPRequest nod is taking 5225 milliseconds to complete.
Now we will find out, out of this 5225 milliseconds, how much time the HTTPRequest node takes to get the response from the web server by looking at different logs.
User Trace or Service Trace.
We can use a User Trace or Service trace to find out the time taken by HTTPRequest node for its web server interaction. More information about User Trace and Service trace of IBM App Connect is available here < https://www.ibm.com/docs/en/app-connect/12.0?topic=support-using-trace>
Before the HTTPRequest node establishes a socket connection to the Web Server, it writes a BIP13072I trace entry in the User Trace and service trace file.
BIP13072I :
2024-02-20 10:09:18.070508 49608 UserTrace BIP13072I: Invoking a Web Service.
URL: 'http://account-02-small-ace.cp.fyre.ibm.com/getAccountDetails',
Request headers: '166' bytes, request body: '2' bytes
After establishing the socket connection to the web server and just before sending the request, the node writes a BIP3633I to the trace files.
BIP3633I :
2024-02-20 10:09:18.459788 49608 UserTrace BIP3633I: Node GetAccountDetails.get Account Details sending HTTP data to URL /getAccountDetails at host account-02-small-ace.cp.fyre.ibm.com (port 80).
The integration node is sending data via HTTP to a remote server at host account-02-small-ace.cp.fyre.ibm.com (port 80) using URL /getAccountDetails. See subsequent messages for success or failure messages relating to this request.
Then immediately after receiving the response from the web server, the node writes a BIP3634I and BIP13073I entries to the trace files.
BIP3634I :
2024-02-20 10:09:23.284420 49608 UserTrace BIP3634I: Node GetAccountDetails.get Account Details received HTTP data from host account-02-small-ace.cp.fyre.ibm.com with status code of 200.
The integration node has received data via HTTP from a remote server at host account-02-small-ace.cp.fyre.ibm.com with an HTTP status code of 200. Status codes beginning with a 2 indicate success; others imply errors in either client or server.
BIP13073I :
2024-02-20 10:09:23.284530 49608 UserTrace BIP13073I: Received reply from Web Server.
URL: 'http://account-02-small-ace.cp.fyre.ibm.com/getAccountDetails',
HTTP status code: '200',
Response headers: '267' bytes, response body: '110' bytes,
Total request time: '5215' ms
BIP13073I shows the total time in milliseconds, the node has taken to send the request and to receive the reply from the web server, here Total request time: '5215' ms.
Activity Logs
Activity logs help us to understand what our message flows are doing by providing a high-level overview of how they interact with external resources. More information about activity logs are available here < https://www.ibm.com/docs/en/app-connect/12.0?topic=management-activity-logs?.
Like user trace and service trace, activity log file is also logged with two entries ‘13072I’ and ‘13073I’ related to HTTPRequest node’s interaction with external web server.
13072I get logged before the invocation of the URL.
13072 :
13072,I,"2024-02-20 04:39:18.070349",49608,"BIP13072I: Invoking a Web Service.","MSGFLOW=GetAccountDetails,NODE=get Account Details,RM=WebService,",http://account-02-small-ace.cp.fyre.ibm.com/getAccountDetails,166,2,(0000C1C8-65D42CF6-00000001),
13073I get logged immediately after receiving a reply from the web server.
13073 :
13073,I,"2024-02-20 04:39:23.284494",49608,"BIP13073I: Received reply from Web Server.","MSGFLOW=GetAccountDetails,NODE=get Account Details,RM=WebService,",http://account-02-small-ace.cp.fyre.ibm.com/getAccountDetails,200,267,110,5215,(0000C1C8-65D42CF6-00000001),
Above 13073I entry can be interpreted as :
URL : http://account-02-small-ace.cp.fyre.ibm.com/getAccountDetails
response code = 200
response header size = 267
Response header body size = 110
Total request time = 5215 milliseconds.
So, by looking at the 13073I entry in the activity log file, we can find out the time taken by the HTTPRequest node for the web server interaction.
Please note, in the activity log files timestamps are in GMT which is different from user trace and service trace where the timestamps are in local time.
Network Traces
If a network trace which captured the traffic between the HTTPRequest node and the webserver is available then the same can be used to find out the time taken to create the socket connection, time taken to send the request and the time taken to receive a reply from the web server. If wireshark is used to view the network trace, then a filter like the following can be applied to view only the packets sent and received by the web server.
(ip.src == web server ip address|| ip.dst == web server ip address) && (tcp.dstport == web server port || tcp.srcport == web server port)
TCP Delta time column gives us the time interval between each packets. The delta time associated with the ‘HTTP/11 200 OK’ packet mostly shows the time taken by the web server to process the request. The highlighted entry shows the server has taken 4511 milli seconds. If we also consider the time taken to establish the socket connection and time taken to send the request, then the total time in the network trace also comes around 5200 milliseconds like the value observed in our trace files and activity logs.
Conclusion
In this article we have provided different approaches to find out the time taken by HTTPRequest node for its interaction to the external web server.