Ankle deep into the ftp 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.

I wrote about how to review the ftpclient.log in the blog titled Wading through the ftpclient.log.  Reading and using that log is relatively easy.  You have information from the workflow, and can see all of the steps that you’re executing because you have the business process too.

What about the situation where someone is sending data to you using FTP?  What do you do when your partner just sends an error message, and asks you what caused the problem?  There’s information available!  Reading it is more challenging, but this blog will try to help.

If the partner has successfully reached your Sterling B2B Integrator FTP Server Adapter, the errors and connection information are recorded in the ftp.log.

This log can be set to three different levels:

   Error – will only record error messages

   Communication Trace – will record more information about an incoming session

   All – will record all of the information that is received or sent by the FTP Server Adapter

As a general rule, as with all logs, you should leave the ftp.log set to a Logging Level of Error unless you are diagnosing a specific problem.  When you open a PMR involving inbound FTP, your analyst will often ask you to turn on full logging for the ftp.log, which means to set the Logging Level to “All”.

1. Successful FTP communications:

Here is what you will see if your partner successfully connected to your FTP Server Adapter.

A) Logging Level of “ERROR”:  If your ftp.log is set to “Error” mode, and someone logs in, you will get some information about their connection.  I logged in from a local server, did a “get” of a file, then logged out.  I saw this:

[2017-11-15 14:43:26.116] ALL AUDIT: User [jep_myfg] from [9.55.52.33] has logged in using unsecure channel.

[2017-11-15 14:45:57.381] ALL AUDIT: User [jep_myfg] retrieving file [/Perimeter.log.D20171102.T160811].

 [2017-11-15 14:46:52.513] ALL AUDIT: User [jep_myfg] from [9.55.52.33] has quitted.

The information is very basic; the loginid, the site from which they logged in, and what they did.

B) Logging level of “Communication Trace”:  If the Logging Level is set to Communications Trace, I see the same information plus about 50 lines of detail data, including some of the behind-the-scenes information that is communicated between the client and the server, a timer for file transfer times, commands that are available, and other information.  The information added from Communications Trace level logging is labeled with “COMMTRACE”.  Here’s one of the first lines I saw:

[2017-11-22 10:59:40.199] COMMTRACE <1016373953 SJohn_FTP_port_4299_15113663597926:409> user=[jep)myfg], sessionId=[John_FTP_port_4299_15113663597926:409], ip=[9.55.52.33], type=[REQUEST], msg=[USER jep_myfg]

Note I outlined the Session ID in bold above.  The Session ID is a unique value.  It will be shown on every COMMTRACE line in the log, and so it can be used to identify other events from the same session.

It shows when I was required to enter a password:

[2017-11-22 10:59:40.21] COMMTRACE <-204605589 SJohn_FTP_port_4299_15113663597926:409> user=[jep_myfg], sessionId=[John_FTP_port_4299_15113663597926:409], ip=[9.55.52.33], type=[REPLY], msg=[331 Password required for jep_myfg.

And responses sent by the server to the client.  This is the SYST response which identifies the server type:

[2017-11-22 10:59:43.83] COMMTRACE <-204605589 SJohn_FTP_port_4299_15113663597926:409> user=[jep_myfg], sessionId=[John_FTP_port_4299_15113663597926:409], ip=[9.55.52.33], type=[REQUEST], msg=[SYST]

Here’s the system type, “UNIX” and the ASCII/BINARY mode, which is “A” or “ASCII”:

[2017-11-22 10:59:43.831] COMMTRACE <1015637311 SJohn_FTP_port_4299_15113663597926:409> user=[jep_myfg], sessionId=[John_FTP_port_4299_15113663597926:409], ip=[9.55.52.33], type=[REPLY], msg=[215 UNIX Type: A^M

]

C) Logging Level of “ALL”:  If the Logging Level is set to All, a lot of information is saved.  I did a test session and saw about 14,200 new lines, with debug information about states of the FTP server adapter.  A very meticulous amount of information is saved.  If there are no errors, that is not usually needed.  Few people are interested in the logs when there are no problems to diagnose.  The ftp.log with Logging Level set to “All” is excruciating to read if you’re not diagnosing an error.

The Logging Level of “All” adds lines with the DEBUG identifier.

The DEBUG lines have further identifiers, like this, the first indication I logged in:

[2017-11-22 12:14:14.778] DEBUG <John_FTP_port_4299_Thread_357321=2135724793> ControlTransferAgent.handleControlReceiveEvent() acquiring execute lock.

The marker “2135724793” is an identifier like the session ID.  The lines identified using it are all for the same connection.  This is very useful when you have a lot of FTP sessions coming to your server at once, and want to diagnose an issue with one of them.

2. Unsuccessful FTP communications:

When there is a problem, the logs become much more important.  Here’s a review of what can be seen in the logs when there was a bad login  In this case, I logged in using the wrong password.

Here is what the FTP client user saw:

220 Server ready for new user.

Name (oxnard:jperry): jep_myfg

331 Password required for jep_myfg.

Password:

530 Login incorrect.

ftp: Login failed.

ftp>

Now for a discussion of what it looks like when viewed in the ftp.log file:

1. Logging Level of “ERROR”:  : If the logging level is set to “error”, the ftp.log shows just one line:

[2017-11-22 11:19:56.572] ALL AUDIT: User [jep_myfg] from [9.55.52.33] has failed to log in.

2. Logging level of Communication Trace: If the logging level is set to Communication Trace, there are several lines describing what happened.  Note they all have the same session ID:

[2017-11-22 11:22:17.464] COMMTRACE user=[<unknown>], sessionId=[John_FTP_port_4299_15113677374409:412], ip=[9.55.52.33], type=[REPLY], msg=[220 Server ready for new user.^M

]

[2017-11-22 11:22:21.01] COMMTRACE user=[<unknown>], sessionId=[John_FTP_port_4299_15113677374409:412], ip=[9.55.52.33], type=[REQUEST], msg=[USER jep_myfg]

[2017-11-22 11:22:21.02] COMMTRACE user=[jep_myfg], sessionId=[John_FTP_port_4299_15113677374409:412], ip=[9.55.52.33], type=[REPLY], msg=[331 Password required for jep_myfg.

]

[2017-11-22 11:22:26.027] COMMTRACE user=[jep_myfg], sessionId=[John_FTP_port_4299_15113677374409:412], ip=[9.55.52.33], type=[REQUEST], msg=[PASS **** ]

 [2017-11-22 11:22:26.042] COMMTRACE user=[<unknown>], sessionId=[John_FTP_port_4299_15113677374409:412], ip=[9.55.52.33], type=[REPLY], msg=[530 Login incorrect.

]

Really, it’s just a detailed message saying the user failed to log in.  But when reviewing COMMTRACE information, note the session ID to make sure you are not mixing together different sessions.

3. Logging level of All:  If the logging level is set to “All”, there are 121 lines of log information, just from the one failed password.  But note they all have the same identifier, regardless of the type of information being reported (ALL, ERROR, COMMTRACE and DEBUG. Here are some sample lines:

The first line of the log:

[2017-11-22 12:14:14.778] DEBUG <John_FTP_port_4299_Thread_357321=2135724793> ControlTransferAgent.handleControlReceiveEvent() acquiring execute lock.

A COMMTRACE line, with both the identifier and the session ID.

[2017-11-22 12:14:14.781] COMMTRACE <2135724793 SJohn_FTP_port_4299_151137084984713:416> user=[jperry], sessionId=[John_FTP_port_4299_151137084984713:4

16], ip=[9.55.52.33], type=[REQUEST], msg=[PASS **** ]

The failure to log in itself:

[2017-11-22 12:14:14.935] ALL <2135724793 SJohn_FTP_port_4299_151137084984713:416> AUDIT: User [jperry] from [9.55.52.33] has failed to log in.

[2017-11-22 12:14:14.781] COMMTRACE <2135724793 SJohn_FTP_port_4299_151137084984713:416> user=[jperry], sessionId=[John_FTP_port_4299_151137084984713:4

16], ip=[9.55.52.33], type=[REQUEST], msg=[PASS **** ]

An “ALL” line indicating the error:

[2017-11-22 12:14:14.935] ALL <2135724793 SJohn_FTP_port_4299_151137084984713:416> AUDIT: User [jperry] from [9.55.52.33] has failed to log in.

And the end of the session:

[2017-11-22 12:14:21.45] DEBUG <2135724793> ControlConnection.processInput() exiting.

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 ftp.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!