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

Missing messages in log


#1

Something weird is happening to me. Some of the messages are lost when viewing through SI Console. Sometimes when restarting application these messages miraculously appears (when logging them again by calling LogMemory method). So it should be not a problem with incorrect log levels set. In contrast it seems that all messages are simultaneously logged to file. The total number of log messages is 1668 so it shouldnt be performance problem. I have found that missing start to appear after the SI throws EReadError exception:

:7577812f KERNELBASE.RaiseException + 0x54
:006D99DA System::Classes::TStream::ReadBuffer(Self=???, Buffer=:00D8D011, Count=???)
:00d8d011 ; CompileLogEntry
:00d8cde1 ; Compile
:00d7ed1d ; ImplWritePacket
:00d7fae6 ; WritePacket
:00d814df ; ProcessPacket
:00d81650 ; SendLogEntry
:00d86c3f ; SendLogEntry
:00d86aee ; SendContext
:00d87270 ; LogMemory
:0064E05B SCom::Write(this=:049EAEA0, c=’\x02’)

This is related source code in runtime-library:

procedure TStream.ReadBuffer(var Buffer; Count: Longint);
var
  LTotalCount,
  LReadCount: Longint;
begin
  { Perform a read directly. Most of the time this will succeed
    without the need to go into the WHILE loop. }
  LTotalCount := Read(Buffer, Count);

  while (LTotalCount < Count) do
  begin
    { Try to read a contiguous block of <Count> size }
    LReadCount := Read(PByte(PByte(@Buffer) + LTotalCount)^,
      (Count - LTotalCount));

    { Check if we read something and decrease the number of bytes left to read }
    if LReadCount <= 0 then
      raise EReadError.CreateRes(@SReadError) <----- exception is throwed here
    else
      Inc(LTotalCount, LReadCount);
  end
end;

This is code in my application that throws exception:

char c = 0;
UnicodeString str;
str.printf(L"Writing data to COM%d", VaComm->PortNum);
char arr[32] = {c};
session->LogMemory(lvVerbose, str, arr, 1); <------ exception is throwed inside this method

This is SI configuration file:

AppName = ELMA
Connections = text(append="true", filename="logs\log.txt", maxparts="10", maxsize="10240", rotate="daily", pattern="[%timestamp%] %session% %level%: %title%", async.enabled="true", async.queue="1024"), pipe(pipename="ELMA-smartinspect")
DefaultLevel = Warning
Enabled = True
Level = Verbose
Session.SerialCom.Active = True
Session.SerialCom.Color = 0x80FF80
Session.SerialCom.Level = Debug

Is this a bug in SI?


#2

Hello,

Thanks for your posting. Do you see this behavior also with other methods or just LogMemory?

Regards,
Tobias


#3

[quote=tgurock]Hello,

Thanks for your posting. Do you see this behavior also with other methods or just LogMemory?

Regards,
Tobias[/quote]

Thank you for reply. Just for LogMemory, not sure if other methods are problematic too. Just familiarizing with library.


#4

Thanks for the update. It would be great if you could try this with another method as well (e.g. LogMessage or LogText) as LogMemory is quite complicated and this may also be caused by side effects regarding the passed arguments. We will try to reproduce this behavior in the meantime as well.

Regards,
Tobias


#5

Today I tested LogMessage, LogError and LogVerbose methods a few hours. Logging outputs were console and binary file. I didnt notice EReadError exception.


#6

We couldn’t reproduce this behavior so far but are still testing. Do you have the option to test this with Delphi as well?

Regards,
Tobias


#7

[quote=tgurock]We couldn’t reproduce this behavior so far but are still testing. Do you have the option to test this with Delphi as well?

Regards,
Tobias[/quote]

Unfortunately not.
I am testing it already a few days. Exceptions keeps occurring. When exception occurs the messages in one of outputs are lost. Other outputs are not affected. Sometimes after first EReadError exception second occurs (with random delay) and messages in one of remaining connections are too stopped being logged. The problem is not limited to pipe protocol. Also tcp and file protocols can be influenced. As I said it seems the problem is somehow limited to LogMemory. This is a serious bug for me as I am considering buying a few licenses of SI for our company. Nevertheless continuing in testing.


#8

Does this also occur when you have only a single connection in the connection string? Also, could you please disable asynchronous logging for your connections?

Regards,
Tobias


#9

[quote=tgurock]Does this also occur when you have only a single connection in the connection string? Also, could you please disable asynchronous logging for your connections?

Regards,
Tobias[/quote]

After disabling asynchronous logging exceptions disappeared.


#10

[quote=truthseeker][quote=tgurock]Does this also occur when you have only a single connection in the connection string? Also, could you please disable asynchronous logging for your connections?

Regards,
Tobias[/quote]

After disabling asynchronous logging exceptions disappeared.[/quote]

Please ignore this message. More thorough testing showed that it isnt true. Exceptions occurs also when asynchronous logging disabled. Problem is that sometimes they occur after a few minutes of testing, sometimes 2 - 3 hours isnt enough (i restarted program many times so it wasnt running nonstop).


#11

Hello,

Thanks a lot for your feedback. Could you also test this with just a single connection? Also, have you disabled asynchronous logging for all connections?

Regards,
Tobias


#12

[quote=tgurock]Also, have you disabled asynchronous logging for all connections?

Regards,
Tobias[/quote]

Yes.


#13

Could you please send us a simple/minimal example so that we can reproduce this? It would be great if you could email this to:

contact@gurock.com

Thanks again.

Regards,
Tobias