phoenixhawke

I'm having a problem writing to some log files. I'm in the process of debugging a multithreaded windows service I've been writing to monitor a remote ftp server for new files, download them, decrypt, unzip, and sort to another remote drive.

The problem I'm having is regarding the log files that I'm using:

The first time it writes, it writes to the file with no problems, like so:

10:07 AM - Connected to *server removed*
10:07 AM - 0 file(s) available.

On each subsequent write, it will garble the last line of the file that was already there, and then write a new entry like above:

9:07 AM - Connected to *server removed*
9:0- EOFG$ jw2P[ UH Oe! N

9:26 AM - Connected to *server removed*
9:26 AM - 0 file(s) avAewoBQ &yV

9:27 AM - Connected to *server removed*
9:27 AM - W4 aL E a-O lxO) mo

9:47 AM - Connected to *server removed*
9:47 AM - 0 file(s) availablO E<D(

10:07 AM - Connected to *server removed*
10:07 AM - 0 file(s) available.

Note that the last write is perfectly legible, but each previous write has been garbled.

The code I'm using to create the file:
if (!Directory.Exists(curPath) && serviceStarted)
Directory.CreateDirectory(curPath);
if (serviceStarted)
{
if (!File.Exists(curPath + "\\FtpLog.txt"))
{
downloadLogFile = new FileStream(curPath + "\\FtpLog.txt", FileMode.Create, FileAccess.Write, FileShare.Write);
downloadLogFile.Close();
sw_ftp = new StreamWriter(curPath + "\\FtpLog.txt", true, Encoding.ASCII);
}

else
{
downloadLogFile = new FileStream(curPath + "\\FtpLog.txt", FileMode.Append, FileAccess.Write, FileShare.Write);
downloadLogFile.Close();
sw_ftp = new StreamWriter(curPath + "\\FtpLog.txt", true, Encoding.ASCII);
lock (sw_ftp)
{
sw_ftp.WriteLine("\r\n");
}
}
}

Then I subsequently write to the file using further sw_ftp.WriteLine("") statements. At the end of the loop, I call sw_ftp.Close().

I've searched all over the internet looking for something similar but haven't had much luck.

Any help you can provide would be appreciated



Re: .NET Base Class Library Problem writing to a file (C#)

eradicator

The downloadLogFile variable is useless. All you're doing there is creating/opening the file and immediately closing it afterwards. The use of sw_ftp already does that job for you.

I'd have to venture a guess that by the time you open the file for append mode, something has already corrupted it, or you have a bad disk. The code you're using (except for the superfluous code mentioned above) looks fine for appending more data to the file.






Re: .NET Base Class Library Problem writing to a file (C#)

OmegaMan

You mentioned that this is multi-threaded. Do you have the log write process on its own thread and it receives messages by extracting them from the queue which has been made thread safe by locks Or is each thread responsible for writing to the log If you are not doing the first method, then I would recommend it...it sounds like your stream is getting corrupted.





Re: .NET Base Class Library Problem writing to a file (C#)

phoenixhawke

I do a statement block as follows

lock(sw_ftp)
{
sw_ftp.writeline("blah");
}

every time i need to write to the log file. According to the spec that should acquire an exclusive right to use sw_ftp for as long as the thread is in that statement block.

The reason I'm not using a separate logging thread is I'm actually running multiple logs for different events (user events, the service writes to the system event log for any state information). And also because I didn't think of it Wink

But given that I'm locking the streamwriter each time I need to write something it doesn't make sense to me that that the threading is the issue, unless i'm doing something wrong on that front




Re: .NET Base Class Library Problem writing to a file (C#)

eradicator

Unless each thread is locking on the same object, they're not cooperating. I suspect that one thread's sw_ftp reference is pointing to a different object than another's. It doesn't matter that they're all ending up writing to the same file. You're locking objects here, not physical files.

On another note, this kind of thing (logging messages) is what a good logging framework, such as Log4Net or Microsoft's logging application block, is for. They've already accounted for multi-threaded use. You're basically reinventing the wheel here.






Re: .NET Base Class Library Problem writing to a file (C#)

phoenixhawke

sw_ftp's declaration:

private static StreamWriter sw_ftp;

ie it is a class-level private variable.



Re: your previous post, i redid the file creation section as follows:
bool newFile;

if (serviceStarted)
{
if (File.Exists(curPath + "\\FtpLog.txt"))
newFile = true;
else
newFile = false;
sw_ftp = new StreamWriter(curPath + "\\FtpLog.txt", true, Encoding.ASCII);
if (!newFile)
sw_ftp.WriteLine("\r\n");
}
the writelinemakes no difference to the garbling of the text, i tried with and without, however allowing the streamwriter to create/open the file still garbles the last line of the file.




Re: .NET Base Class Library Problem writing to a file (C#)

eradicator

Re: your previous post, i redid the file creation section as follows:
...

I never claimed that would fix the garbling; it was a side-note that you had superfluous code with the usage of both FileStream and StreamWriter objects.

Are you sure you're not writing to this physical file in another way outside of using the shared sw_ftp reference

Are you sure you're initializing sw_ftp once and only once during the lifetime of this application

And again, please consider throwing this away and using a nice free logging framework which will do the job for you.






Re: .NET Base Class Library Problem writing to a file (C#)

phoenixhawke

I need it to log to actual txt files, not to the windows event log, as the files in question are sent as attachments in emails. I am writing service state information (service started, exceptions, etc) to the windows event log already. I'm wanting a very simple, clean, user-friendly text doc that somebody who's never seen an event log (or even knows they exist) can understand what it's telling them.




Re: .NET Base Class Library Problem writing to a file (C#)

eradicator

phoenixhawke wrote:
I need it to log to actual txt files, not to the windows event log, as the files in question are sent as attachments in emails. I am writing service state information (service started, exceptions, etc) to the windows event log already. I'm wanting a very simple, clean, user-friendly text doc that somebody who's never seen an event log (or even knows they exist) can understand what it's telling them.

Logging frameworks can write to simple text files. It looks like you believe they only write to the event log. That is not the case.

Plus, they'll handle rolling files over by date or size as well, so you don't have to worry about an ever-growing file problem. Your current solution is going to keep adding more and more messages to a single file. Have you thought about the problem that introduces when it gets bigger than a manageable size






Re: .NET Base Class Library Problem writing to a file (C#)

phoenixhawke

Cool... I appreciate the suggestion and I'll look into that for the next build but for the moment i need to get this working in it's current design, without rewriting the whole thing. So, setting aside third party logging code for now, what would be causing this issue

Incidentally sw_ftp is used in an ftpmonitor thread, which conditionally spawns 3 sub-threads to simultaneously download files from the ftp site. These sub-threads also use it, but it is not used anywhere else in the code. This issue crops up regardless of whether the download threads are spawned.


Also, curPath is in the format 10092007, as of midnight it will automatically roll over to 10102007 and create new log files




Re: .NET Base Class Library Problem writing to a file (C#)

eradicator

Also, curpath is in the format 10092007, as of midnight it will automatically roll over to 10102007 and create new log files

That tells me you are creating new StreamWriter objects at multiple occasions in the code. So I'd have to now guess that your threads are probably not in fact cooperating with (locking) the same object. If sw_ftp was referencing one StreamWriter object and a thread locks it, but another thread sets sw_ftp to reference a new or different StreamWriter object (forget that all these objects are talking to the same physical file, they're still seperate objects) and locks it, these are two seperate objects so the lock on one doesn't lock out the other.




Re: .NET Base Class Library Problem writing to a file (C#)

phoenixhawke

Here is the full source code for the two functions in question. Ignoring all of the ftp-related issues, and keeping in mind that sw_ftp is declared as a private static variable and is in scope for both threads.

#region Fn: FTPMonitor() (Thread!)
public static void FTPMonitor()
{
if (!EventLog.SourceExists("FTP_Monitor"))
EventLog.CreateEventSource("FTP_Monitor", eLogName);
EventLog.WriteEntry("FTP_Monitor", "Started ALS FTP Monitoring Thread\nSee \"" + curPath + "\\FtpLog.txt\" for details");

#region Variable Declarations & Initialization
downloadPath = curPath + "\\Downloading";
ArrayList ServerFileList, FileNames;
FileNames = new ArrayList();
string FileInfo = "";
string[] parts = new string[14];
bool fileStarted = false, newFile = false;
downloads = new Thread[3];
int filecount;
filesProcessed = 0;
numFilesDownloaded = 0;
string oldDownloadPath = "";
#endregion

while (serviceStarted)
{
#region Account for possibility of a change in directories while files are still being downloaded
oldDownloadPath = downloadPath;
downloadPath = curPath + "\\Downloading";
if (!oldDownloadPath.Equals(downloadPath))
{
foreach (string pgpFile in Directory.GetFiles(oldDownloadPath + "\\..\\"))
if (pgpFile.EndsWith(".pgp"))
File.Move(pgpFile, downloadPath + "\\..\\" + pgpFile.Split('\\')[pgpFile.Split('\\').Length]);
}
#endregion

#region Ftp Log
if (!Directory.Exists(curPath) && serviceStarted)
Directory.CreateDirectory(curPath);

if (serviceStarted)
{
if (File.Exists(curPath + "\\FtpLog.txt"))
newFile = false;
else
newFile = true;
sw_ftp = new StreamWriter(curPath + "\\FtpLog.txt", true, Encoding.ASCII);
if (!newFile)
sw_ftp.WriteLine("\r\n");
}
#endregion

try
{
FTPLib[0] = new FTP(FtpLogInServer, FtpLoginName, FtpPass);

lock (FTPLib[0])
{
downloads[0] = downloads[1] = downloads[2] = null;

#region Connect
if (!FTPLib[0].IsConnected && serviceStarted)
{
FTPLib[0].Connect();
lock (sw_ftp)
{
sw_ftp.WriteLine(DateTime.Now.ToShortTimeString() + " - Connected to " + FTPLib[0].server);
}
}
#endregion

#region Get Server File List
ServerFileList = FTPLib[0].ListFiles();
filecount = ServerFileList.Count;
FTPLib[0].Disconnect();

lock (sw_ftp)
{
if (filecount > 0 && serviceStarted)
{
if (!Directory.Exists(downloadPath))
Directory.CreateDirectory(downloadPath);

now = DateTime.Now;
sw_ftp.WriteLine(DateTime.Now.ToShortTimeString() + " - New Files Available:\r\n");
foreach (string file in ServerFileList)
{
FileInfo = file.ToString();
parts = FileInfo.Split(' ');
FileNames.Add(parts[parts.Length - 1]);
sw_ftp.WriteLine(DateTime.Now.ToShortTimeString() + " - " + parts[parts.Length - 1]);
}

}
sw_ftp.WriteLine(DateTime.Now.ToShortTimeString() + " - " + ServerFileList.Count + " file(s) available.\r\n");
sw_ftp.Flush();
}
#endregion

#region Download Files (Threaded for multiple simultaneous downloads)
foreach (string remotefile in FileNames)
{
#region Wait for available thread
if (serviceStarted)
{
while (!fileStarted && serviceStarted)
{
#region Thread 0
if (downloads[0] == null || !(downloads[0].IsAlive) && serviceStarted)
{
downloads[0] = new Thread(DownloadFile);
downloads[0].Start(remotefile);
//Console.WriteLine("Downloading " + remotefile + " in thread 0");
fileStarted = true;
}
#endregion

#region Thread 1
else if (downloads[1] == null || !(downloads[1].IsAlive) && serviceStarted)
{
downloads[1] = new Thread(DownloadFile);
downloads[1].Start(remotefile);
//Console.WriteLine("Downloading " + remotefile + " in thread 1");
fileStarted = true;
}
#endregion

#region Thread 2
else if (downloads[2] == null || !(downloads[2].IsAlive) && serviceStarted)
{
downloads[2] = new Thread(DownloadFile);
downloads[2].Start(remotefile);
//Console.WriteLine("Downloading " + remotefile + " in thread 2");
fileStarted = true;
}
#endregion

#region Thread 3 (inactive code)
//else if (downloads[3] == null || !(downloads[3].IsAlive) && serviceStarted)
//{
// downloads[3] = new Thread(DownloadFile);
// downloads[3].Start(remotefile);
// //Console.WriteLine("Downloading " + remotefile + " in thread 3");
// fileStarted = true;
//}
#endregion

#region Thread 4 (inactive code)
//else if (downloads[4] == null || !(downloads[4].IsAlive) && serviceStarted)
//{
// downloads[4] = new Thread(DownloadFile);
// downloads[4].Start(remotefile);
// //Console.WriteLine("Downloading " + remotefile + " in thread 4");
// fileStarted = true;
//}
#endregion

}
}
#endregion

fileStarted = false;
}

#region Wait for all threads to join
foreach (Thread download in downloads)
if ((download != null) && serviceStarted == true)
download.Join();
else if ((download != null) && serviceStarted == false)
download.Join(new TimeSpan(0, 0, 0));
#endregion

ServerFileList.Clear();
FileNames.Clear();

lock (sw_ftp)
{
if (filecount > 0 && serviceStarted)
sw_ftp.WriteLine("\r\n");
sw_ftp.Flush();
sw_ftp.Close();
}
#endregion

#region Log # files downloaded
now = DateTime.Now;
if (filesProcessed > 0)
{
#region Create Download Log
if (!File.Exists(curPath + "\\DownloadLog.txt"))
downloadLog = new FileStream(curPath + "\\DownloadLog.txt", FileMode.Create, FileAccess.Write, FileShare.Write);
else
downloadLog = new FileStream(curPath + "\\DownloadLog.txt", FileMode.Append, FileAccess.Write, FileShare.Write);
downloadLog.Close();

sw = new StreamWriter(curPath + "\\DownloadLog.txt", true, Encoding.ASCII);
#endregion

#region Write to and close Download Log
lock (sw)
{
sw.WriteLine(now.ToShortTimeString() + " - Downloaded " + filesProcessed + " files.\r\n");
sw.Flush();
sw.Close();
}
#endregion
}
#endregion

#region Sleep if no files downloaded
if (filecount == 0 && serviceStarted)
{
try
{
Thread.Sleep(Minutes_to_mS(FTPWaitTime));
}
catch (ThreadInterruptedException) { }
}
#endregion
}
}
#region Error Handling
catch (Exception e)
{
if (!EventLog.SourceExists("FTP_Monitor"))
EventLog.CreateEventSource("FTP_Monitor", eLogName);
EventLog.WriteEntry("FTP_Monitor", e.Message + "\nSource = " + e.Source, EventLogEntryType.Error);
lock (sw_ftp)
{
sw_ftp.Close();
}
}
#endregion
finally
{
FTPLib[0] = null;
}

filesProcessed = 0;
}
}
#endregion

#region Fn: DownloadFile(object remotefile) (Thread!)
private static void DownloadFile(object remotefile)
{
int LibNum = 1;
try
{

LibNum = FindUnlockedFtpLib();
if (LibNum > 0)
{
#region Acquire Lock on FTP object
FTPLib[LibNum] = new FTP(FtpLogInServer, FtpLoginName, FtpPass);
Monitor.TryEnter(FTPLib[LibNum], 30);
#endregion

#region Connect
string localFilePath = downloadPath + "\\" + remotefile.ToString();
if (!FTPLib[LibNum].IsConnected && serviceStarted)
{
FTPLib[LibNum].Connect();
//Console.WriteLine("Connected to " + FTPLib.server + "\n");
}
#endregion

#region Download File
int perc = 0;
lock (sw_ftp)
{
sw_ftp.WriteLine(DateTime.Now.ToShortTimeString() + " - Downloading " + remotefile.ToString());
sw_ftp.Flush();
}

if (File.Exists(localFilePath))//if file already exists then download failure, delete and retry
File.Delete(localFilePath);//ftplib supports resume but not reliably

FTPLib[LibNum].OpenDownload(remotefile.ToString(), localFilePath, false);
while (FTPLib[LibNum].DoDownload() > 0 && serviceStarted)
{
perc = (int)(((FTPLib[LibNum].BytesTotal) * 100) / FTPLib[LibNum].FileSize);
}
#endregion

#region Do if download successful
if (perc == 100)
{
FTPLib[LibNum].RemoveFile(remotefile.ToString());
lock (sw_ftp)
{
sw_ftp.WriteLine(DateTime.Now.ToShortTimeString() + " - Download Successful: " + remotefile.ToString());
}
numFilesDownloaded++;
//Console.WriteLine(localFilePath + "\r\n" + curPath + "\\" + remotefile.ToString());
File.Move(localFilePath, curPath + "\\" + remotefile.ToString());
filesProcessed++;
}
#endregion
}
else
throw new ArgumentOutOfRangeException("LibNum","Error in Download Thread Processing; too many download threads active");
}
#region Error Handling
catch (Exception e)
{
if (!EventLog.SourceExists("DownloadFile"))
EventLog.CreateEventSource("DownloadFile", eLogName);
EventLog.WriteEntry("DownloadFile", e.Message + "\nSource = " + e.Source, EventLogEntryType.Error);
lock (sw_ftp)
{
sw_ftp.Flush();
}
}
#endregion
finally
{
if (LibNum > 0)
{
FTPLib[LibNum].Disconnect();
Monitor.Exit(FTPLib[LibNum]);
FTPLib[LibNum] = null;
}
}
}
#endregion





Re: .NET Base Class Library Problem writing to a file (C#)

phoenixhawke

An extra tidbit of info - I've been tweaking the code and just stopped the service, rebuilt the project, deleted the log file, then restarted it, and the log (first write) was fine. I then restarted the service again and the issue popped in again immediately.






Re: .NET Base Class Library Problem writing to a file (C#)

OmegaMan

IMHO - Ouch, this code hurts to read and hence it hurts to maintain.

I would recommend that you break up this code into objects with predefined actions. One start is to break out the logging into a class and create the locks and other items of need within the class. That way you are assured that the locking does happen on a consistent basis. While looking at the code, you have multiple writes with multiple locking mechanisms. By placing it into a class it becomes more manageable and less prone to bizzare tweaks.

Also by breaking it out you can unit test the logging class with different tests to verify it does what it is designed for...sorry I can't provide a smoking gun, maybe someone else can, but code such as this has inherent problems which broken down unit tested code, is less prone to.



Re: .NET Base Class Library Problem writing to a file (C#)

phoenixhawke

I have a degree in programming but as far as real world programming experience i'm rather unexperienced... and i'm not exactly working with a group of programmers to give feedback either. This is my first attempt at threaded programming (excepting a project using pthreads back in college) as well as my first stab at doing anything in C# (previous experience is almost exclusively C++).

That said, I certainly see what you're saying about breaking things into separate classes and whatnot, i'm just not really sure how to make multiple classes interact with each other. So far I've written this as one mega-class with a bunch of separate functions (essentially an old-school c++ project with some threaded tweaks added in, wrapped in a class). So - Given all that i think this little bit of spaghetti code is pretty good :-P

Definitely needs work though. I've learned quite a lot in the process of doing this, and my next build will likely be quite the rewrite.

But I still am not getting why on earth the writeline is messing up the previous data in the file - I just checked what happens if I open the file with no writes, and nothing happens, but then i added

sw_ftp.WriteLine(Environment.NewLine);

and it immediately garbled it. It just doesn't make sense.

....just occurred to me that i'm having an issue on my box with trying to install .net framework 3.0, windowsupdate just fails with a generic error code, i wonder if my existing .net framework is corrupted and the code is fine*

Maybe i need to break down and let my buddies at the helpdesk go ahead and reimage the laptop



*fine being understood as bearing a strong resemblance to a bowl of spaghetti but nevertheless functional