Technical Blog Post
Abstract
Wading through the ftpclient.log
Body
This blog is part of a series in which I am conducting swimming lessons to help Sterling B2B Integrator users to make use of the sea of information that is stored in some of our logs.
Let’s talk about the logs that are used for FTP. This protocol is one of the oldest ways in the computer industry for transferring data between two systems. It has dozens of command options, and several places where different types of data are specified. For example, the type option itself has two common parameters, ASCII or type A, BINARY or type B. (There are others, too…) It also has passive and binary options for how SSL/TLS security is handled. There are a lot of options and parameters in an FTP transfer.
This blog has two sections “Successful FTP Client Connection:” and “Unsuccessful FTP Client Connection:”
- Successful FTP Client connection:
In Sterling B2B Integrator, if you are initiating a connection with FTP, you are using the FTP Client Adapter. The logging for it is kept in the ftpclient.log.
I ran a very simple FTP business process. It has an FTP Client Begin Session Service which logs in to “oxnard” using port “4299”, userid “admin” and password “password”. It does an FTP Client List Service, then it disconnects.
With the ftpclient.log set to “Logging Level” of “No”, or error-only mode, nothing was added to the log, because there weren’t any errors.
When I turned the logging level to “Yes”, and ran the same process, 1572 lines were added to my ftpclient.log!
I’m not going to discuss all of them, but let’s look at some of them.
First, the workflow itself:
From this, you can note a few things that will be useful when we look at the log:
The Instance ID, which is 679116.
The date/time stamp for the beginning and end of each step of the business process.
The execution node. On a clustered environment, this information will tell which node was used to execute each line. All of the FTP steps will execute on the same node. There will be no useful information in the ftpclient.log for any other nodes.
The lines which have “info” buttons under Status Report, Document and Instance Data. All of these can have useful information which can be compared with the ftpclient.log to find even more information.
Looking in the ftpclient.log file itself, the first information in it will be from the FTP Client Begin Session Service. The first pertinent line is this one:
[2017-09-29 18:39:48.708] DEBUG <WFE.679116.Thread> FtpService.processData() - Starting ...
Note the parts I outlined in bold.
There’s the date/time stamp, which is provided to the thousandth of a second. Sometimes several events will occur within 1/1000 of a second.
There’s WFE.679116. That number is the Instance ID, which we also saw in the workflow. It can be highly useful to have that. Sometimes many FTP processes will run at the same time. It can be pretty difficult to figure out what lines go with which business process!
“WFE” means “workflow engine”.
There’s “Starting”. Every FTP client process begins with that. It’s the start of the business process.
So then to find out more, just analyze the next 1500 lines.
There are a couple of dozen lines defining paramters for the FTP Client Begin Session Service. Here are a few of them. Again, I will mark a couple of things in bold:
[2017-09-29 18:39:48.708] DEBUG <HAR.679116.Thread> FtpService.registerService() - Successfully registered service [FTPClientBeginSession] with Ops.
[2017-09-29 18:39:48.709] DEBUG <HAR.679116.Thread> FtpRequest.init() - The value for ProfileId was found to be null
[2017-09-29 18:39:48.709] DEBUG <HAR.679116.Thread> FtpRequest.init() - The value for ConnectionRetries was found to be null
They all have that tag, HAR.679116, which is “HAR” or “harness”, and then the instance ID.
65 lines of the ftpclient.log have that instance ID. Remember, though, that’s from more than 1500 lines that were generated from my simple business process.
There’s another useful identifier in the log, and it’s also found in the Status Report.
My status report for the FTP Client Begin Session Service looked like this:
FTPClientBeginSession finished successfully.
FTPClientAdapter=[FTPClientAdapter]
ServiceStartTime=[2017-09-29 18:39:48.724]
ServiceEndTime=[2017-09-29 18:39:48.999]
SessionToken=[FTPClientAdapter_FTPClientAdapter_node1_15067247887251001:493]
ServiceTranscript=[
220 Server ready for new user.
> USER admin
331 Password required for admin.
> PASS *****
230 User admin logged in.
]
I outlined the SessionToken, because it’s another useful identifier found in the ftpclient.log. It’s found in 306 lines among those 1500 from my simple example.
The SessionToken is how the FTP services are linked together when the business process runs. All of the services will use the same SessionToken. Services from other FTP processes will have other SessionTokens. If Sterling B2B Integrator itself uses the SessionToken to distinguish between different business processes, then so can a human reader.
The SessionToken is used by all communications adapters, and so is found in all client and server adapter logs if they are in full debug mode. It’s also found in the ui.log and system.log files.
Note that the Status Report itself is a mini-log file. It has some useful information, we can tell from it that the service started at 18:39:48.724, ended at 18:39:48.999, the business process connected to the server, received this line which was sent by the server as a welcome message:
220 Server ready for new user.
and that the business process then logged in as “admin”, sent a password, and the login was accepted by the server with this message:
230 User admin logged in.
The numbers “220” and “230” are standard response codes sent by all FTP servers.
There are hundreds of lines showing things going on with the FTP Client Begin Session Service. Around half of the lines generated by my simple process were from the Begin. It does a lot!
The first line that mentions any other services is this one, line 744 for my ftpclient.log:
[2017-09-29 18:39:49.08] DEBUG <WFE.679116.Thread> FtpListService.processData() - Starting ...
So here’s our familiar WFE.679116 which shows the workflow ID, and the command itself, FtpListService. “FTPListService” is the system name of the definition for the FTP Client List Service that was used by my business process.
The status report for the FTP Client List Service shows this:
|
FTPClientList finished successfully. FTPClientAdapter=[FTPClientAdapter_FTPClientAdapter_node1] ServiceStartTime=[2017-09-29 18:39:49.087] ServiceEndTime=[2017-09-29 18:39:49.53] SessionToken=[FTPClientAdapter_FTPClientAdapter_node1_15067247887251001:493]
ServiceTranscript=[ > PASV 227 Entering Passive Mode (9,55,52,33,191,56). > TYPE I 200 Type set to I. > LIST *.* 125 Data connection already open; transfer starting. 226 Closing data connection, Binary transfer complete. ]
List=[ -rw------- 1 message group 82097 Sep 15 09:50 filezilla.log ] |
I didn’t outline them all, but we can see the ServiceStartTime and ServiceEndTime, and the same SessionToken that we saw in the FTP Client Begin Session Service.
We see the ServiceTranscript, which shows the List command issuing the PASV command and entering Passive mode.
Then there’s the actual List command we sent to the server:
> LIST *.*
And the server’s response:
List=[
-rw------- 1 message group 82097 Sep 15 09:50 filezilla.log
]
So in this case, there was just one file in the folder, it’s called “filezilla.log”.
- Unsuccessful FTP Client Connection:
We’ve seen what happens for a successful connection but what about when there’s a problem? There’s not much to gain from viewing log files for successes, after all.
First, let’s see what happens if there’s a simple failed connection. I changed my BP to connect to an invalid port, and turned off logging for the ftpclient.log. Here’s what I see in the workflow:
We can clearly see what error occurred:
The status report shows this:
|
Status Report: |
|||
|
|
|
And the ftpclient.log in error-only mode shows this:
[2017-10-02 14:01:09.313] ERROR client.FtpCommand.handleActiveConnectFailedCommand(IS,b,O) got active connect failed command.
[2017-10-02 14:01:10.318] ERROR client.FtpCommand.handleActiveConnectFailedCommand(IS,b,O) got active connect failed command.
It’s very limited data. The status report really shows everything useful in this case.
Running it again with Logging Level turned to On, there were 342 lines added to ftpclient.log. I’m not going to include them all, but we can look at a few lines.
Note that the successful process produced more than 1500 lines to ftpclient.log in full debug mode, whereas the failed one added less than 350. Once the process fails, it ends, and no further steps will execute. Therefore, the logging is done too.
The start of the workflow is:
[2017-10-02 14:05:39.588] DEBUG <WFE.693112.Thread> FtpService.processData() - Starting ...
So we are working with workflow ID 693112.
Since this is in debug mode, we can see all of the information configured in the business process:
[2017-10-02 14:05:39.589] DEBUG <HAR.693112.Thread> FtpRequest.init() - The value for RemoteHost was found to be oxnard
[2017-10-02 14:05:39.589] DEBUG <HAR.693112.Thread> FtpRequest.init() - The value for RemotePort was found to be 4000
[2017-10-02 14:05:39.589] DEBUG <HAR.693112.Thread> FtpRequest.init() - The value for RemoteUserId was found to be admin
But not quite everything…
[2017-10-02 14:05:39.589] DEBUG <HAR.693112.Thread> FtpRequest.init() - The value for RemotePasswd was found to be ********
The password is obscured.
The error itself is still in the log in debug mode as it was in error-only mode:
[2017-10-02 14:05:40.612] ERROR <FtpClient5 LowSM SFTPClientAdapter_FTPClientAdapter_node1_15069675395921003:499> client.FtpCommand.handleActiveConnectFailedCommand(IS,b,O) got active connect failed command.
But there’s more information, too, that isn’t labeled as errors, but which could be useful in diagnosing the error:
[2017-10-02 14:05:40.611] DEBUG <FtpClient5 LowSM> StateMachine.handleCommand(IS,C,O) entering with state [WAITING_FOR_CONNECT], command [ActiveConnectFailed], and argument [Could not complete connection to specified host].
In this case, debug logging isn’t really useful in diagnosing the issue that I created. An analyst viewing just the log, or even the log with the workflow, would be able to tell there was a connection failure, but further diagnosis would be needed to determine why. The actual cause would be determined by trying another application to see if it could make an FTP connection to port 4000. Then the cause would have to be determined. There might be no such host, or it might not be listening on the port (which is the actual cause for this example). There could also be a firewall block from the sender or receiver side.
Conclusion:
Reviewing the ftpclient.log in full debug can often be very highly useful in diagnosing an issue. In conjunction with data such as the workflow; status report and instance data for the step that fails; and the business process and profile configuration information, the logs can help to quickly and accurately diagnose the cause of an issue.
Reading logs does take practice. The ftpclient.log in full debug has information you may already know (such as the parameters configured in your business process and partner profile). It also has repetitive details, and other information that’s not of great diagnostic value.
I want to keep this blog entry brief, lest I drown the reader with too much information! I haven’t addressed any specific examples of situations that can be diagnosed using different levels of logging for the ftpclient.log file. Perhaps I or another analyst will delve further into that in future blogs.
If you have any comments or suggestions to improve this blog, please add a comment below. I will review them and try to improve this if I can.
Thanks!
UID
ibm11120863