I use the TJvLogFile component to log information and errors for the current run session of my program. The component is created in the initialization section of my logging unit and set the filename, then set Active and AutoSave true.
Most of the time (always for me) it works perfectly, but a few users have submitted error reports which say that there’s been a CreateError. This occurs anywhere from 200ms to 20 minutes after program startup.
Cannot create file "xxxx.log".
The process cannot access the file because it is being used by another process.
Leading up to that error is:
LogNewSession (my function which calls TJvLogFile.Add)
TJvLogFile.Add
TJvLogFile.Add
TJvLogFile.DoAutoSave
TJvLogFile.SaveToFile
TFileStream.Create
TFileStream.Create
So it looks like TJvLogFile is calling TFileStream.Create twice, hence the error ?
The two Add calls together at the start of that sequence seems wrong too.
Save the App start datetime (or even the fileName)
…
some time has elapsed
…
Create an instance using the saved filename or date
…
some more time has elapsed
…
Create the second instance of the component (object) using the same saved filename.
You may even be using the same TJvLogFile variable, which would mean that the first instance may not be freed
The issue happens very rarely. There are a lot of users and only the odd report. I don’t know if those users are seeing the error more than once per Windows session.
No, that’s just because TFileStream.Create/2 calls TFileStream.Create/3 internally.
To start with TJvLogFile whilst convenient for very simple purposes is not a great for any significant file logging (with AutoSave on) due to the following reasons:
Performs a full rewrite of the logfile each time it logs a line.
Keeps all the log entries in memory
Needs to iterate through all the entries and get the string output of each log line each time you add line.
Has some AnsiString stuff on writing the log, so you lose data if you’re working in a UNICODE environment.
That said assuming all the other points that people have raised above are true:
Single instance of component
Single instance of application
Single instance of form created
Then I would check for things like an antivirus that’s scanning the file, because it’s doing a full rewrite of the file and closing the file handle each time a log entry is written it’s the perfect scenario for an AV to scan the file after the log file is written and before it opens. Adding a new log line too soon after the previous line is written and you may end up interacting with a badly with the AV. Typically I use ProcessMonitor (MS SysInternals) to track down these errors, add a filter for the expected log file path, drop filtered events and see what processes are touching the file. If you’ve got the monitoring running when it fails to write the file, you should be able to see what other process was busy with the file at the same time.
@David_Duffy are you sure your application is 100% single threaded?
Firstly, your trace log is fine because TFileStream.create passes onto a second overloaded function.
However, the code in TJvLogFile makes no sense to me. If auto save is on it saves out the entire log every single time you add an entry, and uses TFileStream.create(filename,fmCreate) every time. That doesn’t work if the file already exists as far as I know so not sure how it actually functions if you log 2 entries.
Turns out I’m wrong about TFileStream.create(fileName,fmCreate) - I thought it didn’t work if the file already exists but it seems it does.
However, in a multi-threaded test the code does fail with the error you are getting i.e.
begin
JvLogFile1.FileName := ‘C:\Temp\Log.txt’;
JvLogFile1.AutoSave := true;
TThread.CreateAnonymousThread(procedure
var
i: integer;
begin
for i := 0 to 1000 do
begin
JvLogFile1.Add(‘Hia’);
end;
end ).Start;
TThread.CreateAnonymousThread(procedure
var
i: integer;
begin
for i := 0 to 1000 do
begin
JvLogFile1.Add(‘Hib’);
end;
end ).Start;
end;
In my experience, Windows has been producing such spurious file errors since Windows 7 at least, hence my reluctance to use any 3rd-party solutions, which you can never know what they do, unless you are prepared to walk through every line of their code thrice. My own logging implementation caches messages and retries file operations as needed to insulate the caller from this.
@hsvandrew that’s a good point. My code does use threads for a few tasks, so I should check to see if I’m using any logging in those. I’m not convinced that the errors I’m seeing are due to that though, especially on the ones where the exception is 200ms after program startup.
What’s the solution for threaded applications? Are the other libraries discussed suitable for that?
Hi,
I have a bit of code like the following, unfortunately I don’t know if the queue method is available in xe.
(Spring4d also has some logging functionality, it seems to support xe)
procedure TlogMulti.LLog(Level: TLogLevel; s: string);
// Send the message to all loggers.
var
i: integer;
ThreadID: String;
begin
IF TThread.CurrentThread.threadID <> MainThreadID then
begin
ThreadID := TThread.CurrentThread.threadID.ToString;
TThread.queue(nil,
procedure
begin
LLog(Level, 'T' + ThreadID + ' ' + s);
end
);
exit;
end;