How to log SOAP API calls
I'm not sure if this is an IIS or Archer question, but here goes. We have an application that is making SOAP calls to our Archer instance. Most of the time everything works fine. However, quite often they get timeout errors. These occur even on just trying to establish a session, e.g., GetSessionToken.
We have looked at the Archer logs, IIS logs, HTTP logs, Windows system logs, and even our HP Monitoring software, and cannot find anything special that is happening around the time where the timeouts are being reported. And yes we are converting between GMT and ET where necessary.
We would like to see if there is a way to log their API calls. Can this be done? I don't care if it's through Archer or IIS configuration changes. Of course, if anyone has any other ideas what the issue might be that would avoid this, I'm open to that also. Oh, and we're on 5.5 SP1 P1.
I’m not sure why the timeout errors occur, but in regards to logging:
It sounds like you own the application making the SOAP calls, so why can’t you just add some code to write to a log file? Your log file doesn’t have to be perfect you could simply append to an existing text file or something like that. Instead, you could also send an email everytime an error happens. Potentially that’d be a lot of emails, but it’s something that’s fairly easy to do via code.
Ron how is your environment configured; load balancing, type of authentication and such?
I wonder if there a network connectivity issue in connecting to Archer or maybe if there is a load balancer, it's hitting a bad server.
Do you have any Archer-2-Archer data feeds? If so are they failing around the same time your API app is failing? Archer-2-Archer data feeds act in a similar way; GetsSssionToken and run the report.
Here's an example of a log file we write to during our API calls (just a simple .txt file):
4/10/2017 10:50:29 AM 244 - IGNORE: *****************************************
4/10/2017 10:50:29 AM 303 - IGNORE:
4/10/2017 10:50:29 AM 315 - IGNORE: SplunkListener
4/10/2017 10:50:29 AM 326 - IGNORE: Version: 0.0.3.0
4/10/2017 10:50:29 AM 334 - IGNORE:
4/10/2017 10:50:29 AM 340 - IGNORE: ********** Application started **********
4/10/2017 10:50:29 AM 395 - INFO: Config values encrypted.
4/10/2017 10:50:29 AM 405 - INFO: Running in NORMAL mode
4/10/2017 10:50:30 AM 152 - DEBUG: Executing method DeSerializeXml
4/10/2017 10:50:31 AM 11 - DEBUG: Executing Method InitArcherToken
4/10/2017 10:50:31 AM 20 - DEBUG: Token INIT
4/10/2017 10:50:33 AM 612 - INFO: Adding Listener for URI Prefix HTTP://+:2112/
4/10/2017 10:50:33 AM 675 - IGNORE: Splunk Listener is Running. Press CTRL+C to exit.
4/10/2017 10:50:33 AM 687 - IGNORE: Splunk Listener Waiting for Cnxns...
4/10/2017 10:51:04 AM 690 - DEBUG: Log file is 0 days old
4/10/2017 10:51:04 AM 701 - DEBUG: Received Push Message
4/10/2017 10:51:04 AM 714 - DEBUG: Adding received message to msg queue:
4/10/2017 10:51:04 AM 734 - DEBUG: Dequeued Splunk message:
4/10/2017 10:51:04 AM 750 - DEBUG: Closing HTTPListenerContext
4/10/2017 10:51:04 AM 764 - DEBUG: Executing method DeSerializeXml
4/10/2017 10:51:04 AM 782 - DEBUG: Executing Method ProcessSplunkPushMessage
4/10/2017 10:51:04 AM 793 - DEBUG: Executing Method SaveSMessage
4/10/2017 10:51:04 AM 806 - INFO: Writing to message dump file .\received_messages\splunkMsg_04102017_105104.json
4/10/2017 10:51:04 AM 820 - DEBUG: Message Saved To File.
4/10/2017 10:51:04 AM 830 - DEBUG: Creating Search Criteria
4/10/2017 10:51:04 AM 866 - DEBUG: Executing Method searchArcherRecord
4/10/2017 10:51:04 AM 880 - INFO: Preparing to search for Archer Record(s)
4/10/2017 10:51:04 AM 891 - DEBUG: Archer Search XML: <SearchReport><PageSize>100</PageSize><DisplayFields><DisplayField>16132</DisplayField><DisplayField>16108</DisplayField><DisplayField>16114</DisplayField><DisplayField>16627</DisplayField><DisplayField>16628</DisplayField></DisplayFields><Criteria><ModuleCriteria><Module>433</Module><IsKeywordModule>false</IsKeywordModule></ModuleCriteria><Filter><Conditions><TextFilterCondition><Operator>Contains</Operator><Field>16628</Field><Value>search_value</Value></TextFilterCondition><ValueListFilterCondition><Operator>DoesNotContain</Operator><Field>16114</Field><IsNoSelectionIncluded>True</IsNoSelectionIncluded><Values><Value>66336</Value></Values></ValueListFilterCondition></Conditions></Filter></Criteria></SearchReport>
4/10/2017 10:51:04 AM 910 - DEBUG: Executing Method GetArcherSessionToken
4/10/2017 10:51:04 AM 920 - DEBUG: An existing token value is present 136439F499DD76391907F36E41B3A2CC
4/10/2017 10:51:04 AM 932 - DEBUG: Testing session token 136439F499DD76391907F36E41B3A2CC
4/10/2017 10:51:13 AM 899 - DEBUG: Session token valid
4/10/2017 10:51:13 AM 911 - DEBUG: Returning existing Archer token 136439F499DD76391907F36E41B3A2CC
4/10/2017 10:51:20 AM 74 - DEBUG: Executing method DeSerializeXml
4/10/2017 10:51:20 AM 442 - DEBUG: Archer 1 Record(s) found
4/10/2017 10:51:20 AM 454 - INFO: Creating Alert tied to Security Incident: 212814
4/10/2017 10:51:31 AM 348 - DEBUG: Executing Method CreateArcherRecord
4/10/2017 10:51:31 AM 357 - INFO: Preparing to create Archer Record
4/10/2017 10:51:31 AM 370 - DEBUG: Archer Create XML: <createXMLgoesHere>
4/10/2017 10:51:31 AM 398 - DEBUG: Executing Method GetArcherSessionToken
4/10/2017 10:51:31 AM 407 - DEBUG: An existing token value is present 136439F499DD76391907F36E41B3A2CC
4/10/2017 10:51:31 AM 421 - DEBUG: Testing session token 136439F499DD76391907F36E41B3A2CC
4/10/2017 10:51:32 AM 73 - DEBUG: Session token valid
4/10/2017 10:51:32 AM 82 - DEBUG: Returning existing Archer token 136439F499DD76391907F36E41B3A2CC
4/10/2017 10:51:45 AM 993 - INFO: Archer Record created with content ID 212816
4/10/2017 10:51:46 AM 5 - INFO: Security Alert Record created: 212816
We don't own the code that is making the API calls. I've asked if they can add more logging but it's a production system and they are in a "service" organization that provides these sorts of interfaces. That's a long-winded way of saying that there is a lot of bureaucracy to get this change made. So, I'm trying to see if there is a way to do add more logging on the receiving end, i.e., IIS/Archer.
We are in a load-balanced environment with an F5 fronting 3 web servers. We have not seen any issues with any of our other processes, including data feeds, occurring at that time. All three web servers seem to be happily handling regular HTTPS requests. It's why I'd like to get additional logging on our IIS/Archer end to see just what they are up to. See my other response as to why getting the API calling folks to add additional logging is a non-starter.
Thanks Ron for the information.
Is the API application running on the same server as Archer or on a different server? If it's on a different server can your networking group put a network trace on it to see what's going on?
Personally I don't think any logs on the Archer servers that are going to help you being you getting a timeout issue in connecting, so if the API application cannot reach Archer/IIS than there would be no log entries for the attempt.
Would the F5 have logs you can take a look at to see if the server is actually getting to the F5?
I'm guessing the CPU/memory utilization is low when the connection fails? I could see that if the CPU/memory was maxed at the time the connection attempt was made could cause what you are seeing.
Lastly can you change the API application to use an IP address of one of the Archer servers to see if it's possibly a DNS/F5 issue?
The API application is running on different servers than Archer, although they are co-located (or supposed to be). We have monitoring software from HP that I've used to see what's going on when these timeouts happen and nothing has jumped out at me CPU- or memory-wise. I have recommended that we get the networking group to do some sniffing between the API application, the F5, and our web servers, but it's a different bunch of folks who have to make that happen (I'm just a lowly contractor).
Unfortunately, changing the API app is difficult due to it being a production environment and all the change control necessary for the group responsible to make changes. It's also why we haven't been able to get them to do some additional logging on their end. That's why I've been looking at additional logging at our end. Are the requests timing out at the F5, IIS, or Archer? That is something that would be nice to know.
One other thing to look at Ron is the DNS server configured for the server running the API application. That's the first thing that's typically (normally) queried before anything else.