Internal Exception in Coyote about coyote HOT 26 CLOSED

Thanks for reporting @ankushdesai, this seems like a bug in the logger, we will check it out (and ask you if we need any more info)!

from coyote.

Thanks @pdeligia, coyote gets stuck for a long time on an iteration and then crashes with this exception.

from coyote.

Btw, can you reproduce this easily, or is it only happening very rarely?

from coyote.

It is happening always for a particular BIG program but I am not sure how to reduce it to a small example.

I updated the error message above. Is there a quick work around that I can try without upgrading to 1.0.0?

from coyote.

I will try to see if there is something obvious in the code, but without a reliable way to reproduce it will be a bit tricky to debug! It might also be that this was already fixed in the latest version. One question that might help guide this: does this always happen at the end of an iteration or during an iteration? Could you perhaps paste here the output of running the tester on the command line (with the iterations getting printed out, but without verbosity from the program), as it might help?

from coyote.

Starting TestingProcessScheduler in process 99459
... Created '1' testing task.
... Task 0 is using 'Random' strategy (seed:795).
..... Iteration #1
..... Iteration #2
..... Iteration #3
..... Iteration #4
..... Iteration #5
..... Iteration #6
..... Iteration #7
..... Iteration #8
..... Iteration #9
..... Iteration #10
..... Iteration #20
..... Iteration #30
..... Iteration #40
..... Iteration #50
..... Iteration #60
..... Iteration #70
..... Iteration #80
..... Iteration #90
..... Iteration #100
..... Iteration #200
..... Iteration #300
..... Iteration #400
..... Iteration #500
..... Iteration #600
..... Iteration #700
..... Iteration #800
..... Iteration #900
..... Iteration #1000
Error: [CoyoteTester] unhandled exception: System.NullReferenceException: Object reference not set to an instance of an object.
   at System.Text.StringBuilder.Append(String value)
   at System.Text.StringBuilder.AppendLine(String value)
   at Microsoft.Coyote.IO.InMemoryLogger.WriteLine(String value)
   at Microsoft.Coyote.Runtime.LogWriter.LogAssertionFailure(String error)
   at Microsoft.Coyote.TestingServices.Scheduling.OperationScheduler.NotifyAssertionFailure(String text, Boolean killTasks, Boolean cancelExecution)
   at Microsoft.Coyote.TestingServices.Runtime.SystematicTestingRuntime.ProcessUnhandledExceptionInOperation(AsyncOperation op, Exception ex)
   at Microsoft.Coyote.TestingServices.Runtime.SystematicTestingRuntime.<>c__DisplayClass29_0.<<RunActorEventHandler>b__0>d.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
--- End of stack trace from previous location where exception was thrown ---
   at System.Threading.ThreadPoolWorkQueue.Dispatch()

from coyote.

Thanks! And what was the coyote command line that you run? (feel free to remove/anonymize the dll)

from coyote.

<coyote> test.dll -i 10000

No parameters passed as such

from coyote.

Looking at Coyote's latest bits I cannot explain how this could happen. OperationScheduler.NotifyAssertionFailure never passes null, LogWriter.LogAssertionFailure, LogWriter.LogAssertionFailure passes the error through to InMemoryLogger, and InMemoryLogger passes it through to StringBuilder. Strange....

from coyote.

Not sure if this helps, but before throwing this exception, the coyote tester seems to get stuck and uses a lot of CPU.

Also, I am using rc9, could that version have this problem?

from coyote.

Yeah, could be fixed in rc12.

from coyote.

I did some more debugging and it seems like, the problem is:

System.OutOfMemoryException
  HResult=0x8007000E
  Message=Insufficient memory to continue the execution of the program.
  Source=System.Private.CoreLib
  StackTrace:
   at System.Text.StringBuilder.ExpandByABlock(Int32 minBlockCharCount) in E:\A\_work\482\s\src\mscorlib\shared\System\Text\StringBuilder.cs:line 2223

But that should not lead to crashing of coyote, right?

from coyote.

The length of the stringBuilder object in the LogFormatter is: 2147478720

from coyote.

This was super useful, thanks for digging in!

What I suspect is that the program has a potential liveness bug (or something along these lines) that causes an iteration to become infinite (or extremely long), this means that the iteration goes forever (and that's why you get the feeling that its "stuck"), but meanwhile it keeps adding to the string builder, which expands in memory and then explodes and crashes your test!

Can you try use --max-steps N or -ms N, where N is the bound in scheduling points per iteration? This should make sure that no iteration is infinite.

Saying this, we will try to figure ways to guard against this (by trying to detect this automatically, and imposing a max bound and give a warning, but in the meantime the workaround above should work, assuming my intuition about what is happening is correct).

Could you please confirm?

from coyote.

Question: Would putting a max-steps make Coyote miss liveness bugs?

from coyote.

Nope, the underlying heuristic works together with the max steps!

However, putting a really small max steps could potentially lead to a false positive liveness bug (although usually the heuristic works well in practice that we rarely see a false positive). Usually people pick up a max steps with some trial and error, but it should be a number large enough that allows an infinite test to reach a state that you care about (if you try it with a couple of iterations and verbosity).

from coyote.

Thanks, is there a way to find or generate an error trace that reaches that max-steps bound?
I see that 0.3% of the executions have length > 10000.

Can I see one such execution?

from coyote.

As far as I remember, sadly we don't provide support for doing this right now without tweaking the code of the tester. So if you wanted to generate an error trace like this, you would need to hack this is to have a counter that increments and you have an assert that fails when it reaches a very high level.

It would be an interesting idea to spit out a "debug" trace based on some test parameters (e.g. if it exceeds N steps) which could be helpful for debugging. We can brainstorm other useful things someone could do along these lines!

from coyote.

We used to have something like this in the Zing and PTester. This was extremely useful to help programmers debug unintentional infinite executions.

from coyote.

I agree, I just opened a work item so we get on this!

from coyote.

Excellent! Looking forward to it.

To fix this item, I would suggest, adding an assertion that if the stringBuilder is full then catch it instead of throwing an internal exception.

from coyote.

from coyote.

from coyote.

@ankushdesai, if you have a liveness monitor installed already, then you definitely need a max-steps flag. The flag is crucial (for now) to turn on the liveness check. See here for more info.

from coyote.

Following up what Akash said, I am adding a link to the coyote corresponding doc: https://github.com/microsoft/coyote/blob/master/docs/_learn/specifications/liveness-checking.md

from coyote.

Closing this for now.

from coyote.