Join 34,000+ subscribers and receive articles from our
blog about software quality, testing, QA and security.

Filenames ending in aaaaaa


#1

Hi,

I am currently observing log files that look like this:

EdmEmulatorCAN-2009-06-04-13-00-00aaaaaa[many more 'a’s]aaaaaaaaaaa.sil

Where EdmEmulatorCAN is the filename I supplied, followed by the date and time and one to many (>200) 'a’s

Is this something the SmartInspect logger does automatically or did I do anything stupid?
If the former: What’s the reason for this? If the latter: Any idea what I might have done?

twm


#2

The file protocol adds an ‘a’ to the file name of a log in case a log file with the same name already exists (and must not be overridden). Are you using a combination of rotate by date and size?


#3

Only by date, unless I made a mistake.

Is this a recent addition to the library? I don’t remember seeing this before the last update.


#4

We added this functionality in the 3.0 release. In the 3.0 release we reworked the rotate feature so that you could specify rotation by date and size at the same time. If you enable log rotation, we always append the time stamp to the file name, so that file names stay consistent and compatible between the different rotate modes (date, size, date + size).

Since the added time stamp has a precision of one second, it is possible that the file protocol rotates a file and gets the same file name as the previous log file (exactly in the case when it creates two log files in the same second). So we needed some way to distinguish log file names in this rare case and added a routine to add an ‘a’ to the file name in case the file already exists.

Your particular case looks a bit odd to me. It seems that the logger is not able to get a value for the minute/second part and therefore generates the same log file name over and over again. I have a few more questions:

What does your connection string look like exactly?
Which SmartInspect library do you use (Delphi, correct?) and which version?
Which .NET/Java/Delphi version do you use and which Windows version?


#5

‘file(append=“true”, filename=“c:\log\ArgVideo.sil”, maxsize=“0”, rotate=“hourly”, backlog=“0”, caption=“file”, flushon=“error”, keepopen=“true”, level=“debug”, reconnect=“false”)’

(That’s not the connection string from the example log above, but it happens with this one as well:
ArgVideo-2009-06-04-16-00-00aaaaaaaaaaaaaaaaaaa.sil)

with DefaultLevel=lvVerbose and Level=lvVerbose

Delphi, 3.1.0.8000

Delphi 2007 on Windows XP current SP and current fixes.


#6

Thanks a lot, I will try to reproduce this behavior here.


#7

I unfortunately couldn’t reproduce the problem. I suspect it’s an issue with a routine to get the current time stamp but I cannot confirm it (yet). It looks like that the routine isn’t able to get a value for the minute/second parts in your case. Could you try executing the routine below a few times on your machine and post the results?

function UtcNow: TDateTime; var LSystemTime: TSystemTime; begin GetSystemTime(LSystemTime); with LSystemTime do begin Result := EncodeDate(wYear, wMonth, wDay) + EncodeTime(wHour, wMinute, wSecond, wMilliseconds); end; end;

What’s also odd is that there are so many 'a’s in your file names. Your log files indicate that they were created just a few hours before your postings and already contain dozens of 'a’s (especially in the first case, ‘EdmEmulatorCAN’). 'a’s may be added only during a rotate operation and such a rotate operation shouldn’t occur more than once per hour in your case. Log rotation also uses the above time stamp routine, so maybe that’s the reason for this problem as well.

When you encounter a log file with so many 'a’s, is this the only file for this particular log or are also there many other similar log files (with less 'a’s)? For example, in case of ‘ArgVideo-2009-06-04-16-00-00aaaaaaaaaaaaaaaaaaa.sil’ are there also other logs like ‘ArgVideo-2009-06-04-16-00-00a.sil’, ‘ArgVideo-2009-06-04-16-00-00aa.sil’, ‘ArgVideo-2009-06-04-16-00-00aaa.sil’ etc.?

Also, are the logs the result of one longer run of your application or have you (re-)started your application multiple times?

It’s a bit difficult to track down the cause of this problem, so I appreciate your help.


#8

Hi Tobias,

these files get created all the time and yes, there always are files starting with zero 'a’s and from there it goes up to many:
ArgVideo-2009-06-04-16-00-00.sil
ArgVideo-2009-06-04-16-00-00a.sil
ArgVideo-2009-06-04-16-00-00aa.sil
ArgVideo-2009-06-04-16-00-00aaa.sil
etc.

In case this matters: All these programs are multithreaded and there are multiple threads that call the log methods in parallel. The box has got a quad core processor.

All the logs are the result of a program over a longer run.

I currently cannot try your function on that computer but I will as soon as I have got the chance.


#9

Hello Thomas,

Have you had the time/chance to try the function?

It would also be great if you could take a look at the file creation dates of the generated log files. They should normally be created once per hour, but I suspect they are created more than that in your case.

Multi-threading shouldn’t influence the behavior of the rotation feature, the logger and the file protocol are thread-safe.


#10

I run it 100 times, I got 27 times 3.99763044200231E+0004 and the rest 3.99763044202083E+0004

does that help?

twm


#11

Thanks for trying this function. It seems that the function is working as expected. This is both a good and a bad thing actually. Good in the sense that the function is working flawlessly and bad because I suspected that the rotation issue might be related to this function in some way.

Have you also checked the file creation dates of the generated log files? It would be interesting to know if they were created once per hour or more than that.


#12

I am not at work right now so I can’t check, but I doubt that they were created once per hour because that would mean they had been created over the span of several days. The longest filename had over 100 'a’s in it. I usually delete the logs on my development machine at least once a day.


#13

Thanks for the additional information. It’s odd, really. Since the time stamp routine seems to be working fine, I suspect it may be an issue within the file protocol itself. I’ve already checked the file protocol (and our unit tests) but I’ll investigate it once more over the weekend and get back to you on Monday. Have a nice weekend!


#14

I have now checked it and the files are all created within the same second (according to the windows creation timestamp).
All of them contain only one line, which is written from a background thread (which writes to the log very(!) frequently). Oddly enough, there is nothing from the foreground thread, even though it should also write to the log.

There is also sometimes another file without 'a’s that apparently is created one second after the new hour and which contains the missing log messages as well as more from the background thread:

EdmEmulatorCAN-2009-06-09-10-00-00aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.sil
EdmEmulatorCAN-2009-06-09-10-00-01.sil

I am pretty sure now that this is a multithreading issue.


#15

Thanks for the additional information. I will try to reproduce this behavior here with the multi-threading aspect in mind. Have you seen this behavior on multiple machines or just one computer?


#16

I have so far seen it only on one computer, which is running windows xp on a quad-core cpu. But it is quite possible that there are others which I have not yet been told about.


#17

Finally found the bug. It’s related to the rotation algorithm and fortunately not a multi-threading issue. I’m currently working on a fix. The hint that the files were all created in the same second did the trick. Thanks a lot for your help!


#18

Fixed the bug, the change will be included in the next release. It turned out to be a tricky bug, but the fix is actually quite simple. If you want to, you can replace line 28316 in SmartInspect.pas with the following line until the new release is available:


#19

Thanks, I’ve just patched my unit.