Log plug-ins HTTP communications

A lot of the Orchestrator plug-ins use the Apache HTTP client to communicate with the target hosts. You may want to log the HTTP communications for many purposes:
  • Understanding how vCO does the API calls
  • Troubleshoot a problem with a target host
  • Re-engineering an existing call with capturing it, changing it as you like and use it via the REST or SOAP plug-in
  • Brag you have found an "Onyx" like functionality for most Orchestrated products wink

This article will guide you on how to log these calls to a file.

In a previous article I explained how the Orchestrator logs work and how to update the log4j configuration file.
Orchestrator leverages a powerful logging framework named log4j.
This framework can log the activity of the Apache HTTP client as documented here.

Log4j has two configuration files. A log4j.properties file and in the case of orchestrator is using a log4j.xml file. The Apache documentation only covers the first one but it is not hard to adapt it to the xml one with understanding the basics of log4j appenders and loggers.

The following modification is not supported in production. It will considerably slow down your Orchestrator server since it will log all the Apache HTTP traffic, all the headers and other information to a file. It is recommended to be used on a test / dev environment only. Also updating the log configuration from the Orchestrator web based configuration will overwrite the changes you will apply to log4j.

First ssh in your Orchestrator appliance (or open RDP on your Windows host).
Locate the log4j.xml file (in /etc/vco/app-server in the appliance)
Edit log4j.xml (I use VI on the appliance - you may use another editor or transfer the file on your host, modify it and send it back)


Insert the highlighted lines.

<?xml version="1.0" encoding="UTF-8" standalone="no"?>
<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">
<log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/" debug="true" reset="false" threshold="null">
 
    <appender name="rolling" class="org.apache.log4j.DailyRollingFileAppender">
        <param name="File" value="${catalina.base}/logs/http.log"/>
        <layout class="org.apache.log4j.PatternLayout">
            <param name="ConversionPattern" value="%d [%t] %-5p %c:%L - %m%n"/>
        </layout>
    </appender>
    <logger name="org.apache.http">
        <level value="DEBUG"/>
        <appender-ref ref="rolling"/>
    </logger>

 


The appender define a new log target and the log format. It is going to be the file named http.log that will be located in the /var/log/vco/app-server in the appliance.
The logger defines what is logged. Here we log all Apache HTTP log.

Save and quit the file.

You can now watch all the HTTP traffic.
To do this on the appliance you can use tail -f /var/log/vco/app-server/http.log
On windows you can use baretail

You may notice traffic being logged right away for the vCenter and SSO Identity server SOAP connections.

Now let's say I want to know what request the NSX plug-in is doing to display its datacenter objects in the inventory. I have just to unfold the Datacenters object and watch the logs.


2015-04-15 22:00:10,426 [http-bio-172.16.3.131-8281-exec-3] DEBUG org.apache.http.headers:124 - http-outgoing-2 >> GET /api/2.0/services/usermgmt/scopingobjects HTTP/1.1
2015-04-15 22:00:10,427 [http-bio-172.16.3.131-8281-exec-3] DEBUG org.apache.http.headers:127 - http-outgoing-2 >> Accept: application/xml, text/xml, application/*+xml
2015-04-15 22:00:10,427 [http-bio-172.16.3.131-8281-exec-3] DEBUG org.apache.http.headers:127 - http-outgoing-2 >> Host: home.cdecanini.fr
2015-04-15 22:00:10,427 [http-bio-172.16.3.131-8281-exec-3] DEBUG org.apache.http.headers:127 - http-outgoing-2 >> Connection: Keep-Alive
2015-04-15 22:00:10,428 [http-bio-172.16.3.131-8281-exec-3] DEBUG org.apache.http.headers:127 - http-outgoing-2 >> User-Agent: Apache-HttpClient/4.3.3 (java 1.5)
2015-04-15 22:00:10,428 [http-bio-172.16.3.131-8281-exec-3] DEBUG org.apache.http.headers:127 - http-outgoing-2 >> Accept-Encoding: gzip,deflate
2015-04-15 22:00:10,429 [http-bio-172.16.3.131-8281-exec-3] DEBUG org.apache.http.headers:127 - http-outgoing-2 >> Authorization: Basic YSWERCtRaEWT
2015-04-15 22:00:10,429 [http-bio-172.16.3.131-8281-exec-3] DEBUG org.apache.http.wire:72 - http-outgoing-2 >> "GET /api/2.0/services/usermgmt/scopingobjects HTTP/1.1[\r][\n]"
2015-04-15 22:00:10,429 [http-bio-172.16.3.131-8281-exec-3] DEBUG org.apache.http.wire:72 - http-outgoing-2 >> "Accept: application/xml, text/xml, application/*+xml[\r][\n]"
2015-04-15 22:00:10,429 [http-bio-172.16.3.131-8281-exec-3] DEBUG org.apache.http.wire:72 - http-outgoing-2 >> "Host: home.cdecanini.fr[\r][\n]"
2015-04-15 22:00:10,430 [http-bio-172.16.3.131-8281-exec-3] DEBUG org.apache.http.wire:72 - http-outgoing-2 >> "Connection: Keep-Alive[\r][\n]"
2015-04-15 22:00:10,430 [http-bio-172.16.3.131-8281-exec-3] DEBUG org.apache.http.wire:72 - http-outgoing-2 >> "User-Agent: Apache-HttpClient/4.3.3 (java 1.5)[\r][\n]"
2015-04-15 22:00:10,430 [http-bio-172.16.3.131-8281-exec-3] DEBUG org.apache.http.wire:72 - http-outgoing-2 >> "Accept-Encoding: gzip,deflate[\r][\n]"
2015-04-15 22:00:10,431 [http-bio-172.16.3.131-8281-exec-3] DEBUG org.apache.http.wire:72 - http-outgoing-2 >> "Authorization: Basic YSWERCtRaEWT[\r][\n]"
2015-04-15 22:00:10,432 [http-bio-172.16.3.131-8281-exec-3] DEBUG org.apache.http.wire:72 - http-outgoing-2 >> "[\r][\n]"
2015-04-15 22:00:10,898 [http-bio-172.16.3.131-8281-exec-3] DEBUG org.apache.http.wire:72 - http-outgoing-2 << "HTTP/1.1 200 OK[\r][\n]"
2015-04-15 22:00:10,899 [http-bio-172.16.3.131-8281-exec-3] DEBUG org.apache.http.wire:72 - http-outgoing-2 << "Cache-Control: private[\r][\n]"
2015-04-15 22:00:10,899 [http-bio-172.16.3.131-8281-exec-3] DEBUG org.apache.http.wire:72 - http-outgoing-2 << "Expires: Thu, 01 Jan 1970 00:00:00 GMT[\r][\n]"
2015-04-15 22:00:10,900 [http-bio-172.16.3.131-8281-exec-3] DEBUG org.apache.http.wire:72 - http-outgoing-2 << "Server:  [\r][\n]"
2015-04-15 22:00:10,900 [http-bio-172.16.3.131-8281-exec-3] DEBUG org.apache.http.wire:72 - http-outgoing-2 << "Cache-Control: no-cache[\r][\n]"
2015-04-15 22:00:10,900 [http-bio-172.16.3.131-8281-exec-3] DEBUG org.apache.http.wire:72 - http-outgoing-2 << "Set-Cookie: JSESSIONID=32B7A5CBF7E338498FCE36ABA5DD708B; Path=/[\r][\n]"
2015-04-15 22:00:10,901 [http-bio-172.16.3.131-8281-exec-3] DEBUG org.apache.http.wire:72 - http-outgoing-2 << "Date: Wed, 15 Apr 2015 20:00:09 GMT[\r][\n]"
2015-04-15 22:00:10,901 [http-bio-172.16.3.131-8281-exec-3] DEBUG org.apache.http.wire:72 - http-outgoing-2 << "Content-Type: application/xml[\r][\n]"
2015-04-15 22:00:10,901 [http-bio-172.16.3.131-8281-exec-3] DEBUG org.apache.http.wire:72 - http-outgoing-2 << "Transfer-Encoding: chunked[\r][\n]"
2015-04-15 22:00:10,901 [http-bio-172.16.3.131-8281-exec-3] DEBUG org.apache.http.wire:72 - http-outgoing-2 << "[\r][\n]"
2015-04-15 22:00:10,902 [http-bio-172.16.3.131-8281-exec-3] DEBUG org.apache.http.wire:72 - http-outgoing-2 << "fbe[\r][\n]"
2015-04-15 22:00:10,902 [http-bio-172.16.3.131-8281-exec-3] DEBUG org.apache.http.wire:72 - http-outgoing-2 << "<?xml version="1.0" encoding="UTF-8"?>[\n]"
2015-04-15 22:00:10,902 [http-bio-172.16.3.131-8281-exec-3] DEBUG org.apache.http.wire:72 - http-outgoing-2 << "<scopingObjects><object><objectId>network-39</objectId><objectTypeName>Network</objectTypeName><vsmUuid>42022E92-A37C-259D-962A-947649CEDBA7</vsmUuid><revision>33</revision><type><typeName>Network</typeName></type><name>VM Network</name><scope><id>datacenter-21</id><objectTypeName>Datacenter</objectTypeName><name>Homelab</name></scope><clientHandle></clientHandle><extendedAttributes/></object><object><objectId>edge-16</objectId><objectTypeName>Edge</objectTypeName><vsmUuid>42022E92-A37C-259D-962A-947649CEDBA7</vsmUuid><revision>4</revision><type><typeName>Edge</typeName></type><name>Christophe</name><description></description><clientHandle></clientHandle><extendedAttributes/></object><object><objectId>virtualwire-4</objectId><objectTypeName>VirtualWire</objectTypeName><vsmUuid>42022E92-A37C-259D-962A-947649CEDBA7</vsmUuid><revision>49</revision><type><typeName>VirtualWire</typeName></type><name>LS-TransitNetwork</name><description></description><clientHandle></clientHandle><extendedAttributes/></object><object><objectId>virtualwire-3</objectId><objectTypeName>VirtualWire</objectTypeName><vsmUuid>42022E92-A37C-259D-962A-947649CEDBA7</vsmUuid><revision>49</revision><type><typeName>VirtualWire</typeName></type><name>LS-DBTier</name><description></description><clientHandle></clientHandle><extendedAttributes/></object><object><objectId>virtualwire-2</objectId><objectTypeName>VirtualWire</objectTypeName><vsmUuid>42022E92-A37C-259D-962A-947649CEDBA7</vsmUuid><revision>49</revision><type><typeName>VirtualWire</typeName></type><name>LS-AppTier</name><description></description><clientHandle></clientHandle><extendedAttributes/></object><object><objectId>dvportgroup-58</objectId><objectTypeName>DistributedVirtualPortgroup</objectTypeName><vsmUuid>42022E92-A37C-259D-962A-947649CEDBA7</vsmUuid><revision>8</revision><type><typeName>DistributedVirtualPortgroup</typeName></type><name>dvPortGroup-Mgmt</name><scope><id>datacenter-21</id><objectTypeName>Datacenter</objectTypeName><name>Homelab</name></scope><clientHandle></clientHandle><extendedAttributes/></object><object><objectId>virtualwire-1</objectId><objectTypeName>VirtualWire</objectTypeName><vsmUuid>42022E92-A37C-259D-962A-947649CEDBA7</vsmUuid><revision>50</revision><type><typeName>VirtualWire</typeName></type><name>LS-WebTier</name><description></description><clientHandle></clientHandle><extendedAttributes/></object><object><objectId>edge-1</objectId><objectTypeName>Edge</objectTypeName><vsmUuid>42022E92-A37C-259D-962A-947649CEDBA7</vsmUuid><revision>43</revision><type><typeName>Edge</typeName></type><name>LDR-Lab</name><clientHandle></clientHandle><extendedAttributes/></object><object><objectId>edge-2</objectId><objectTypeName>Edge</objectTypeName><vsmUuid>42022E92-A37C-259D-962A-947649CEDBA7</vsmUuid><revision>220</revision><type><typeName>Edge</typeName></type><name>ESG-Lab</name><clientHandle></clientHandle><extendedAttributes/></object><object><objectId>datacenter-21</objectId><objectTypeName>Datacenter</objectTypeName><vsmUuid>42022E92-A37C-259D-962A-947649CEDBA7</vsmUuid><revision>5</revision><type><typeName>Datacenter</typeName></type><name>Homelab</name><scope><id>group-d1</id><objectTypeName>Folder</objectTypeName><name>Datacenters</name></scope><clientHandle></clientHandle><extendedAttributes/></object><object><objectId>network-131</objectId><objectTypeName>Network</objectTypeName><vsmUuid>42022E92-A37C-259D-962A-947649CEDBA7</vsmUuid><revision>12</revision><type><typeName>Network</typeName></type><name>none</name><scope><id>datacenter-21</id><objectTypeName>Datacenter</objectTypeName><name>Homelab</name></scope><clientHandle></clientHandle><extendedAttributes/></object><object><objectId>globalroot-0</objectId><objectTypeName>GlobalRoot</objectTypeName><vsmUuid>42022E92-A37C-259D-962A-947649CEDBA7</vsmUuid><revision>21</revision><type><typeName>GlobalRoot</typeName></type><name>Global</name><clientHandle></clientHandle><extendedAttributes/></object></scopingObjects>[\r][\n]"

The first highlighted line is the HTTP method and URL.
The second one the headers that were passed : XML is sent and recieved to from / NSX
Then the authorization type : basic with my encrypted password.

These are all the headers log. The next logs are the wire logs. Any HTTP traffic between Orchastrator Apache library and the remote system will appear here.
A line of interest is the 200 Status code meaning the request was successful and the response on the last line including a long XML string I have formatted below:

<scopingObjects>
	<object>
		<objectId>network-39</objectId>
		<objectTypeName>Network</objectTypeName>
		<vsmUuid>42022E92-A37C-259D-962A-947649CEDBA7</vsmUuid>
		<revision>33</revision>
		<type>
			<typeName>Network</typeName>
		</type>
		<name>VM Network</name>
		<scope>
			<id>datacenter-21</id>
			<objectTypeName>Datacenter</objectTypeName>
			<name>Homelab</name>
		</scope>
		<clientHandle></clientHandle>
		<extendedAttributes/>
	</object>
	<object>
		<objectId>edge-16</objectId>
		<objectTypeName>Edge</objectTypeName>
		<vsmUuid>42022E92-A37C-259D-962A-947649CEDBA7</vsmUuid>
		<revision>4</revision>
		<type>
			<typeName>Edge</typeName>
		</type>
		<name>Christophe</name>
		<description></description>
		<clientHandle></clientHandle>
		<extendedAttributes/>
	</object>
	<object>
		<objectId>virtualwire-4</objectId>
		<objectTypeName>VirtualWire</objectTypeName>
		<vsmUuid>42022E92-A37C-259D-962A-947649CEDBA7</vsmUuid>
		<revision>49</revision>
		<type>
			<typeName>VirtualWire</typeName>
		</type>
		<name>LS-TransitNetwork</name>
		<description></description>
		<clientHandle></clientHandle>
		<extendedAttributes/>
	</object>
	<object>
		<objectId>virtualwire-3</objectId>
		<objectTypeName>VirtualWire</objectTypeName>
		<vsmUuid>42022E92-A37C-259D-962A-947649CEDBA7</vsmUuid>
		<revision>49</revision>
		<type>
			<typeName>VirtualWire</typeName>
		</type>
		<name>LS-DBTier</name>
		<description></description>
		<clientHandle></clientHandle>
		<extendedAttributes/>
	</object>
	<object>
		<objectId>virtualwire-2</objectId>
		<objectTypeName>VirtualWire</objectTypeName>
		<vsmUuid>42022E92-A37C-259D-962A-947649CEDBA7</vsmUuid>
		<revision>49</revision>
		<type>
			<typeName>VirtualWire</typeName>
		</type>
		<name>LS-AppTier</name>
		<description></description>
		<clientHandle></clientHandle>
		<extendedAttributes/>
	</object>
	<object>
		<objectId>dvportgroup-58</objectId>
		<objectTypeName>DistributedVirtualPortgroup</objectTypeName>
		<vsmUuid>42022E92-A37C-259D-962A-947649CEDBA7</vsmUuid>
		<revision>8</revision>
		<type>
			<typeName>DistributedVirtualPortgroup</typeName>
		</type>
		<name>dvPortGroup-Mgmt</name>
		<scope>
			<id>datacenter-21</id>
			<objectTypeName>Datacenter</objectTypeName>
			<name>Homelab</name>
		</scope>
		<clientHandle></clientHandle>
		<extendedAttributes/>
	</object>
	<object>
		<objectId>virtualwire-1</objectId>
		<objectTypeName>VirtualWire</objectTypeName>
		<vsmUuid>42022E92-A37C-259D-962A-947649CEDBA7</vsmUuid>
		<revision>50</revision>
		<type>
			<typeName>VirtualWire</typeName>
		</type>
		<name>LS-WebTier</name>
		<description></description>
		<clientHandle></clientHandle>
		<extendedAttributes/>
	</object>
	<object>
		<objectId>edge-1</objectId>
		<objectTypeName>Edge</objectTypeName>
		<vsmUuid>42022E92-A37C-259D-962A-947649CEDBA7</vsmUuid>
		<revision>43</revision>
		<type>
			<typeName>Edge</typeName>
		</type>
		<name>LDR-Lab</name>
		<clientHandle></clientHandle>
		<extendedAttributes/>
	</object>
	<object>
		<objectId>edge-2</objectId>
		<objectTypeName>Edge</objectTypeName>
		<vsmUuid>42022E92-A37C-259D-962A-947649CEDBA7</vsmUuid>
		<revision>220</revision>
		<type>
			<typeName>Edge</typeName>
		</type>
		<name>ESG-Lab</name>
		<clientHandle></clientHandle>
		<extendedAttributes/>
	</object>
	<object>
		<objectId>datacenter-21</objectId>
		<objectTypeName>Datacenter</objectTypeName>
		<vsmUuid>42022E92-A37C-259D-962A-947649CEDBA7</vsmUuid>
		<revision>5</revision>
		<type>
			<typeName>Datacenter</typeName>
		</type>
		<name>Homelab</name>
		<scope>
			<id>group-d1</id>
			<objectTypeName>Folder</objectTypeName>
			<name>Datacenters</name>
		</scope>
		<clientHandle></clientHandle>
		<extendedAttributes/>
	</object>
	<object>
		<objectId>network-131</objectId>
		<objectTypeName>Network</objectTypeName>
		<vsmUuid>42022E92-A37C-259D-962A-947649CEDBA7</vsmUuid>
		<revision>12</revision>
		<type>
			<typeName>Network</typeName>
		</type>
		<name>none</name>
		<scope>
			<id>datacenter-21</id>
			<objectTypeName>Datacenter</objectTypeName>
			<name>Homelab</name>
		</scope>
		<clientHandle></clientHandle>
		<extendedAttributes/>
	</object>
	<object>
		<objectId>globalroot-0</objectId>
		<objectTypeName>GlobalRoot</objectTypeName>
		<vsmUuid>42022E92-A37C-259D-962A-947649CEDBA7</vsmUuid>
		<revision>21</revision>
		<type>
			<typeName>GlobalRoot</typeName>
		</type>
		<name>Global</name>
		<clientHandle></clientHandle>
		<extendedAttributes/>
	</object>
</scopingObjects>

The highlighted text shows the information that is used to be displayed in the inventory tree : The homelab datacenter. The plug-in had to pull all this XML just to get this piece of information.
With this log I can now do a lot more. For example the NSX plug-in has several workflows applying changes on NSX. I can capture the traffic and include similar operations in my NSX Dynamic Type plug-in or slightly different ones with checking the API documentation and changing some of the parameters.

I can also do the same thing with the vCAC plug-in to get a good understanding on how the REST API is leveraged. I could push it to do some custom SOAP calls to vCenter if I really wanted. There are also several third parties plug-ins to control storage, network, IPAM, CMDB, ticketing systems that I could learn just by running their workflows and possibly extend creating my own HTTP REST or SOAP requests. I can also understand how the communication to the identity appliance is working.

The possibilities are endless and the knowledge to get from using this logging enormous.



NUC Lab Kit

Below are my thoughts for a vSAN nuc lab. Since I already have cables, not including them here. I ordered (and received by Nov 30, 2016)
3 x nuc, 3 x 32GB Crucial mem, 3 x Toshiba NVMe drive, 3 x Startech USB to GB NIC, and 3 x Crucial 1TB SSD. I've also been very happy with my Cisco SG300-10 so I bought one more since my existing one only has one port available. Each of the items listed here are linked below - all were purchased using the provided links below.
single NIC (See this post for details on using the USB -> GB NIC item listed below

I stayed with the i5 for the power consumption and form factor vs. the i7 Skull Canyon ;)

 

Search

Experts Exchange