The FTP log reader is unloading
search cancel

The FTP log reader is unloading

book

Article ID: 166957

calendar_today

Updated On:

Products

Reporter ProxySG Software - SGOS

Issue/Introduction

The FTP log source, intermittently, closes itself down with this message " Fatal log processing error stopped log source 'bluecoat_reporter_logsourcename"

The FTP Log source, intermittently, issues a checkpoint message that says "Checkpoint while processing log source file'

The FTP Log source, intermittently, has trouble unzipping the access log and displays this message "Unzip log source './SG_main_XX231_0319.log.gz' failed with GZ error -5"

The FTP Log source, intermittently, issues a  "  Failed to post process FTP log source file ''bluecoat_reporter_logsourcename:./SG_main_XX231_0319.log.gz'"

Resolution

The "GZ error -5" is a unzipp error, which means we no longer have a buffer ready to unzip this file.  Looking at the journal file we see that Immediately after the unzip error, but before the other messages, mentioned above,  we see an unexpected response from the FTP server.   And, this is why we we have no buffer- because the FTP server terminated the connection.

Here's the response:

BCRJ:2010-03-20 01:16:32 (4ba48460) ALW.ERRO.LOGSO
   src/sg_logreader.cpp,4064,FTPGetReply
      worker_thread_00000764(1892),,
   Unexpected response code 426 instead of 226 in reply:
 '426 Connection closed; transfer aborted.'

NOTE: In this interaction, with the FTP server, the Bluecoat Reporter server is acting as a FTP client.

These two numbers, mentioned in this journal entry,  are standard FTP error codes which mean this:

  • 426 Connection closed; transfer aborted.
  • 226 Closing data connection. Requested file action successful (for example, file transfer or file abort).

The reason the log source unloaded was because the remote FTP server terminated the transfer early.  For the purposes of being complete, here is a complete list of all the journal entries for this FTP fault.

NOTE:  Early on, in the below journal , we see the FTP server successfully processing access logs, until it starts to download "SG_main_XX231_0319.log.gz' , which is where the fault occurs. Reporter, as we have seen , was expecting to see a 226 from the server, which would have indicated that it had received the complete file, and was ready to inject this last portion of it into the database. However, because it realized the file transfer had been interrupted, it instructed a log source to shutdown, waiting for human intervention. This is so the Reporter administrator can investigate why we lost the FTP connection, and conduct the necessary remediation.   As you can see below, we checkpoint the file so when we see this file again we will only continue where we stopped, and not inject the same data again. As soon as the log source is started up, we then pull down the entire file, discarding the data we have already processed, and finding, through what we recorded in the checkpoint, where we stopped so we can continue processing the data into the database at the right place.

BCRJ:2010-03-19 23:12:41 (4ba46759) NOR.INFO.LOGSO
   src/sg_logreader.cpp,4887,FTPGetLogFile
      worker_thread_0000111c(4380),,
   Processing FTP log source file 'bluecoat_reporter_db:useclifwp120:./SG_main_YY231_0319.log.gz'
BCRJ:2010-03-19 23:42:59 (4ba46e73) NOR.INFO.LOGSO
   src/sg_logreader.cpp,4887,FTPGetLogFile
      worker_thread_00000494(1172),,
   Processing FTP log source file 'bluecoat_reporter_db:useclifwp120:./SG_main_YY232_0319.log.gz'
BCRJ:2010-03-20 00:15:59 (4ba4762f) NOR.INFO.LOGSO
   src/sg_logreader.cpp,4887,FTPGetLogFile
      worker_thread_00001170(4464),,
   Processing FTP log source file 'bluecoat_reporter_db:useclifwp120:./SG_main_YY233_0319.log.gz'
BCRJ:2010-03-20 00:48:25 (4ba47dc9) NOR.INFO.LOGSO
   src/sg_logreader.cpp,4887,FTPGetLogFile
      worker_thread_00001160(4448),,
   Processing FTP log source file 'bluecoat_reporter_db:useclifwp120:./SG_main_XX231_0319.log.gz'
BCRJ:2010-03-20 01:16:32 (4ba48460) ALW.ERRO.LOGSO
   src/sg_logreader.cpp,2846,DeflateGZStream
      worker_thread_00000698(1688),,
   Unzip log source './SG_main_XX231_0319.log.gz' failed with GZ error -5
BCRJ:2010-03-20 01:16:32 (4ba48460) ALW.ERRO.LOGSO
   src/sg_logreader.cpp,4064,FTPGetReply
      worker_thread_00000764(1892),,
   Unexpected response code 426 instead of 226 in reply:
 '426 Connection closed; transfer aborted.'
BCRJ:2010-03-20 01:16:32 (4ba48460) NOR.INFO.LOGSO
   src/sg_logreader.cpp,5638,FTPCloseLogFile
      worker_thread_00000764(1892),,
   Failed to post process FTP log source file 'bluecoat_reporter_db:useclifwp120:./SG_main_XX231_0319.log.gz'
BCRJ:2010-03-20 01:16:32 (4ba48460) NOR.INFO.LOGSO
   src/sg_logreader.cpp,963,LogReader::WriteCheckpointFile
      worker_thread_00000764(1892),,
   Checkpoint while processing log source file 'bluecoat_reporter_db:useclifwp120:./SG_main_XX231_0319.log.gz'
BCRJ:2010-03-20 01:16:32 (4ba48460) ALW.ERRO.LOGSO
   src/sg_profile.cpp,4188,DatabaseManager::PhasedLogSource
      worker_thread_00000764(1892),,
   Fatal log processing error stopped log source ''bluecoat_reporter_logsourcename"'

In some other cases, you may see a 425, instead of a 426, such as this entry below, which means we can't open a data connection.  

BCRJ:2010-04-10 03:13:11 (4bbf6e37) ALW.ERRO.LOGSO
   src/sg_logreader.cpp,4064,FTPGetReply
      worker_thread_000010c0(4288),,
   Unexpected response code 425 instead of 125,150 in reply:'425 Can't open data connection.'