OOAnalyzer: Initial sanity check failed, indicating the OO rules are incorrect.

[srett]

Trying OOAnalyzer for the first time, no idea what I'm doing really, but a simple run of ooanalyzer -F=facts.txt -R=results.txt --prolog-loglevel=3 TS2.exe resulted in an error telling me to report a bug, so here I am.

Log file attached, I shortened it quite a bit in the middle because the "Missing return value from new() call" errors were quite excessive (12k+ lines) oo_log.txt

=facts.txt

The binary was compiled with VS2015 and CFG enabled as far as I know.

[sei-eschwartz]

It looks like you are running out of memory which is probably causing the inconsistency error you are seeing. Try running with --maximum-memory=128000 or a suitably large number. See here for some more advice for using OOAnalyzer in practice.

Let us know if you still run into problems when running with more memory.

[srett]

Thanks for getting back so quickly. Checked out the guide, no more messages about exceeding memory limits now. These were the commands I used:

partition --serialize=ooprog.ser --maximum-memory=250000 TS2.exe &> 01-partitioner.txt

ooanalyzer --serialize=ooprog.ser --maximum-memory 250000 --prolog-facts=ooprog-facts.pl --threads=128 --per-function-timeout=900000 TS2.exe &> 02-analysis.txt

(Side tangent: I had to set --per-function-timeout to a ridiculously large value to not immediately get "CPU time exceeded" spam in step two. Is this value affected by the number of threads I'm running, i.e. is it the cumulative CPU time of all threads, or is each thread supposed to be working on a different function?)

ooprolog --facts ooprog-facts.pl --results ooprog-results.pl --log-level=6 &> 03-prolog-analysis.txt

Then in step three, in the end I got the same error as before unfortunately:

Class 0x73078c inherits from 0x72c324 at offsets 0 and 0x4
Initial sanity check failed, indicating the OO rules are incorrect.
Please report this failure to the Pharos developers!
  [29] prolog_stack:get_prolog_backtrace(100,[frame(29,clause(<clause>(0x56092ad19610),6),_15723592)|_15723580],[goal_term_depth(100)]) at /usr/local/lib/swipl/library/prolog_stack.pl:137
  [28] throw_with_backtrace(error(system_error(initialSanityChecks))) at /usr/local/share/pharos/prolog/oorules/util.pl:185
  [26] solve_internal at /usr/local/share/pharos/prolog/oorules/setup.pl:679
  [25] catch(user:solve_internal,_15723816,user:((_15723884=error(resource_error(private_table_space),_15723898)->complain_table_space(ooscript);_15723948=error(resource_error(stack),_15723962)->complain_stack_size(ooscript);true),throw(_15723994))) at /usr/local/lib/swipl/boot/init.pl:562
  [24] solve(ooscript) at /usr/local/share/pharos/prolog/oorules/setup.pl:617
  [23] psolve_no_halt('<garbage_collected>') at /usr/local/share/pharos/prolog/oorules/report.pl:23
  [22] catch(user:psolve_no_halt(stream(<stream>(0x56092aebe510))),_15724168,user:(print_message(error,_15724234),(globalHalt->halt(1);true))) at /usr/local/lib/swipl/boot/init.pl:562
  [21] catch_with_backtrace('<garbage_collected>','<garbage_collected>','<garbage_collected>') at /usr/local/lib/swipl/boot/init.pl:629
  [20] run_with_backtrace('<garbage_collected>') at /usr/local/bin/ooprolog:177
  [19] <meta call>
  [18] with_output_to(<stream>(0x56092aebe790),run_with_backtrace(psolve_no_halt(stream(<stream>(0x56092aebe510))))) <foreign>
  [17] setup_call_catcher_cleanup(user:(var('ooprog-results.pl')->open_null_stream(<stream>(0x56092aebe790));open('ooprog-results.pl',write,<stream>(0x56092aebe790))),user:with_output_to(<stream>(0x56092aebe790),run_with_backtrace(psolve_no_halt(stream(<stream>(0x56092aebe510))))),_15724586,user:close(<stream>(0x56092aebe790))) at /usr/local/lib/swipl/boot/init.pl:663
  [15] setup_call_catcher_cleanup(user:open('ooprog-facts.pl',read,<stream>(0x56092aebe510)),user:setup_call_cleanup((var('ooprog-results.pl')->open_null_stream(<stream>(0x56092aebe790));open('ooprog-results.pl',write,<stream>(0x56092aebe790))),with_output_to(<stream>(0x56092aebe790),run_with_backtrace(psolve_no_halt(stream(<stream>(0x56092aebe510))))),close(<stream>(0x56092aebe790))),_15724796,user:close(<stream>(0x56092aebe510))) at /usr/local/lib/swipl/boot/init.pl:663
  [12] run([script('/usr/local/bin/ooprolog'),json(_15725074),ground(_15725094),rtti(true),guess(true),config(_15725154),stacklimit(200000000000),tablespace(200000000000),oorulespath(_15725214),halt(true),load_only(false),help(_15725274),facts('ooprog-facts.pl'),results('ooprog-results.pl'),loglevel(6)]) at /usr/local/bin/ooprolog:235
   [9] catch(user:main(['/usr/local/bin/ooprolog','--facts','ooprog-facts.pl','--results','ooprog-results.pl','--log-level=6']),_15725398,user:(print_message(error,_15725528),halt(1))) at /usr/local/lib/swipl/boot/init.pl:562
   [7] catch(user:main,_15725602,'$toplevel':true) at /usr/local/lib/swipl/boot/init.pl:562
   [6] catch_with_backtrace('<garbage_collected>','<garbage_collected>','<garbage_collected>') at /usr/local/lib/swipl/boot/init.pl:629

Note: some frames are missing due to last-call optimization.
Re-run your program in debug mode (:- debug.) to get more detail.
ERROR: ooprog-facts.pl:408561:
ERROR:    Unknown message: error(system_error(initialSanityChecks))

01-partitioner.txt 02-analysis.txt

The log file of step three is is 151MB, is there anything I should be looking for?

[sei-eschwartz]

Ok, that is most likely an issue with our rules that I will need to look into.

Can you compress and share ooprog-facts.pl and/or TS2.exe?

[sei-ccohen]

You wrote:

Side tangent: I had to set --per-function-timeout to a ridiculously large value to not immediately get "CPU time exceeded" spam in step two. Is this value affected by the number of threads I'm running, i.e. is it the cumulative CPU time of all threads, or is each thread supposed to be working on a different function?)

The per-function-timeout is per function, and per thread.

The intention was that you would set --timeout=0 (the overall multi-thread analysis timeout to no timeout, which is now the default) and then set the per function timeout to something "reasonable". The default is 20 seconds, but values as high as a few hundred seconds could be ok as well. The algorithm is supposed to complete eventually, but for some functions, it goes a little berserk and can consume much longer than that. Since those functions probably aren't going to give correct answers anyway, the goal was to cut them off rather than waste that CPU time. When the timeout is exceeded, you get no facts for that function, which isn't supposed to be fatal. On the other hand, if your run completed with the per function timeout set ridiculously high, there's probably no problem with what you did.

[srett]

Can you compress and share ooprog-facts.pl and/or TS2.exe?

If all went well it should have reached you via mail. :-)

[srett]

The per-function-timeout is per function, and per thread.

The intention was that you would set --timeout=0 (the overall multi-thread analysis timeout to no timeout, which is now the default) and then set the per function timeout to something "reasonable". The default is 20 seconds, but values as high as a few hundred seconds could be ok as well.

I see, that makes sense. I started out with --per-function-timeout=60 as given in the example for step two. When I increased it to 900 (which I expected to result in ~15 minutes per function) I also got "CPU time exceeded" messages after only about 1-2 minutes, which confused me at first.

[sei-eschwartz]

Thanks, I have the file and am trying to reproduce the problem now.

[sei-ccohen]

Amongst other reasons why the function analysis might fail is that the partitioning (function boundary detection) for that particular function was bad, and so we're trying to analyze nonsense instructions. I would say the goal for setting the timeouts is to strike a balance where no more than a few functions timeout, but the overall runtime isn't ridiculous. Think of all the valid functions you could have processed at <1 second each while waiting 900 seconds for a couple of bad apples. But again, there's nothing wrong with just waiting and having no timeouts either.

[sei-eschwartz]

So 0x72c324 is OBJECT::vftable according to IDA and 0x73078c is RECTLIST::vftable.

These are the problematic facts:

reasonDerivedClass_D(0x76b058, 0x769840, 0x73078c, 0x72c324, 0). factObjectInObject(0x73078c, 0x72c324, 0x4)

The former is RTTI telling us that OBJECT is a non-virtual base of RECTLIST.

% We think that 0x73078c, RECTLIST::vftable belongs to class 0x4638b0 because of the constructor rule in VFTableBelongsToClass.
3479126 reasonMergeVFTables_A(constructor, 0x73078c, 0x4638b0, 0x73078c, 0, factVFTableWrite(0x4638f1, 0x4638b0, 0, 0x73078c)).
3479192 Concluding mergeVFTables(0x73078c, 0x4638b0).
3479193 Merging class 0x4638b0 into 0x73078c ...

[sei-eschwartz]

RTTI tells us that RECTLIST does inherit from OBJECT at offset 0. It also tells us that there is not inheritance at offset 4. So where is that coming from?

[sei-eschwartz]

3479201 Retracting factObjectInObject(0x4638b0, 0x72c324, 0x4) and asserting factObjectInObject(0x73078c, 0x72c324, 0x4) ...

factObjectInObject(0x4638b0, 0x72c324, 0x4) comes from reasonOIO_F...

% If a method installs a vftable at two different offsets, it must be embedded or inherited.

This is coming from analyzing method=0x4638b0...

Here is the relevant snippet:

mov     edi, ecx
mov     [ebp+var_10], edi
mov     dword ptr [edi], offset ??_7OBJECT@@6B@ ; const OBJECT::`vftable'
call    @_guard_check_icall_nop@4 ; _guard_check_icall_nop(x)
;   try {
mov     [ebp+var_4], 0
lea     esi, [edi+4]
mov     dword ptr [edi], offset ??_7RECTLIST@@6B@ ; const RECTLIST::`vftable'
mov     ecx, esi        ; void *
mov     [ebp+var_14], esi
mov     dword ptr [esi], offset ??_7OBJECT@@6B@ ; const OBJECT::`vftable'
call    @_guard_check_icall_nop@4 ; _guard_check_icall_nop(x)
;   } // starts at 4638E7
;   try {
mov     byte ptr [ebp+var_4], 1
mov     ecx, esi
mov     dword ptr [esi], offset ??_7SLISTBASE@@6B@ ; const SLISTBASE::`vftable'

We are RECTLIST and inherit from Object at 0. We then inherit or embed SLISTBASE at 4, which also inherits from OBJECT.

Unfortunately, reasonObjectInObject_F says that RECTLIST inherits from OBJECT at 4 instead of SLISTBASE.

This will take some thought about how to fix. For now I'm going to try to comment out this rule and see if we get something sensible.

[sei-eschwartz]

This problem sounds a little bit similar to this... https://github.com/cmu-sei/pharos/blob/master/share/prolog/oorules/rules.pl#L3375

[sei-eschwartz]

I think the question in this case is: Can we be sure that SLISTBASE is embedded at offset 4, or might it be some object that just happens to contain SLISTBASE?

[sei-eschwartz]

Can you try this commit?

https://github.com/cmu-sei/pharos/compare/master...sei-eschwartz:pharos:master

[srett]

Short version: Step two now completed successfully, step three as well:

Guessed 1,324 methods of 4,492, guessed contrary conclusions: 0 of 0
Guessed 372 constructors of 674, guessed contrary conclusions: 1,653 of 3,813
Guessed 14 destructors of 250, guessed contrary conclusions: 0 of 3,420
Guessed 8 deleting destructors of 199, guessed contrary conclusions: 0 of 5,185
Guessed 12 virtual function calls of 381, guessed contrary conclusions: 4 of 4
Guessed 126 virtual function tables of 539, guessed contrary conclusions: 11 of 6,186
Guessed 8 virtual base tables of 8, guessed contrary conclusions: 0 of 0
Guessed 413 virtual function table entries of 5,026, guessed contrary conclusions: 1 of 490
Guessed 173 derived classes of 483, guessed contrary conclusions: 0 of 132
Guessed 28 embedded objects of 132, guessed contrary conclusions: 0 of 2,323
Guessed 40 has a base class of 461, guessed contrary conclusions: 2,511 of 2,535
Object oriented analysis and reporting complete, exiting.

Long story: Just to be sure, I wanted to start from scratch; step one and two don't take that long anyways.

Initially, I could not get past step two:

ooanalyzer --serialize=ooprog.ser --maximum-memory 250000 --prolog-facts=ooprog-facts.pl --threads=128 --per-function-timeout=900000 TS2.exe &> 02-analysis.txt ended in

[INFO ]: Pharos main error: (pharos::SQLLiteApiDictionary::SQLError) bad parameter or other API misuse
OOAN[FATAL]: Backtrace:
OOAN[FATAL]: | /usr/local/bin/../lib/libpharos.so(+0x942b67) [0x7ff77c688b67]
OOAN[FATAL]: | /lib/x86_64-linux-gnu/libstdc++.so.6(+0xae28c) [0x7ff7752e128c]
OOAN[FATAL]: | /lib/x86_64-linux-gnu/libstdc++.so.6(+0xae2f7) [0x7ff7752e12f7]
OOAN[FATAL]: | /lib/x86_64-linux-gnu/libstdc++.so.6(+0xae558) [0x7ff7752e1558]
OOAN[FATAL]: | /usr/local/bin/../lib/libpharos.so(pharos::SQLLiteApiDictionary::Data::throw_error(int)+0x50) [0x7ff77c6687ba]
OOAN[FATAL]: | /usr/local/bin/../lib/libpharos.so(+0x9208de) [0x7ff77c6668de]
OOAN[FATAL]: | /usr/local/bin/../lib/libpharos.so(pharos::SQLLiteApiDictionary::Data::get_api_definition(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&) const+0x2ab) [0x7ff77c88501b]
OOAN[FATAL]: | /usr/local/bin/../lib/libpharos.so(pharos::SQLLiteApiDictionary::get_api_definition(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&) const+0x26) [0x7ff77c8850f6]
OOAN[FATAL]: | /usr/local/bin/../lib/libpharos.so(pharos::DLLStateCacheDict::get_api_definition(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&) const+0x9a) [0x7ff77c8819ca]
OOAN[FATAL]: | /usr/local/bin/../lib/libpharos.so(std::vector<std::shared_ptr<pharos::APIDefinition const>, std::allocator<std::shared_ptr<pharos::APIDefinition const> > > pharos::ReportDictionary::get_definition<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >(char const*, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&) const+0x75) [0x7ff77c898e25]
OOAN[FATAL]: | /usr/local/bin/../lib/libpharos.so(pharos::ReportDictionary::get_api_definition(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&) const+0x2f) [0x7ff77c8875df]
OOAN[FATAL]: | /usr/local/bin/../lib/libpharos.so(pharos::MultiApiDictionary::get_api_definition(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&) const+0x51) [0x7ff77c8815d1]
OOAN[FATAL]: | /usr/local/bin/../lib/libpharos.so(std::vector<std::shared_ptr<pharos::APIDefinition const>, std::allocator<std::shared_ptr<pharos::APIDefinition const> > > pharos::ReportDictionary::get_definition<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >(char const*, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&) const+0x75) [0x7ff77c898e25]
OOAN[FATAL]: | /usr/local/bin/../lib/libpharos.so(pharos::ReportDictionary::get_api_definition(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&) const+0x2f) [0x7ff77c8875df]
OOAN[FATAL]: | /usr/local/bin/../lib/libpharos.so(pharos::OOAnalyzer::visit(pharos::FunctionDescriptor*)+0x8fc) [0x7ff77c9d0f8c]
OOAN[FATAL]: | /usr/local/bin/../lib/libpharos.so(+0xbab42d) [0x7ff77c8f142d]
OOAN[FATAL]: | /usr/local/bin/../lib/libpharos.so(+0xbab720) [0x7ff77c8f1720]
OOAN[FATAL]: | /lib/x86_64-linux-gnu/libboost_thread.so.1.74.0(+0x150cb) [0x7ff774c2d0cb]
OOAN[FATAL]: | /lib/x86_64-linux-gnu/libc.so.6(+0x94b43) [0x7ff77507db43]
ooanalyzer: /usr/include/boost/thread/pthread/mutex.hpp:70: void boost::mutex::unlock(): Assertion `!posix::pthread_mutex_unlock(&m)' failed.

How does a change in the prolog rules make SQLite fall on its face? To be extra sure, I just rebuilt the docker container with the Dockerfile from your branch, as I just swapped rules.pl in the official container in my first attempt; just on the off chance that some information from the .pl file ends up compiled into the main program.... But I got the same error.

Then I tried adding --verbose 5 in the hopes of getting anything useful, but to my surprise, the run completed successfully now. Other workarounds are to get rid of my excessive per-function timeout (tried 90, resulting in 2397 timeouts in log), or lowering the thread count to 64. Looks like a completely unrelated concurrency issue somewhere that got triggered just now. Is it worth opening another issue for this?

[Trass3r]

I modified /usr/local/share/pharos/prolog/oorules/rules.pl in the Docker container, is that enough? Analysis still fails for me.

[sei-eschwartz]

Looks like a completely unrelated concurrency issue somewhere that got triggered just now. Is it worth opening another issue for this?

It does sound like a completely unrelated concurrency issue. I have opened a new issue for that. Hopefully my colleague will be able to sort that out.

[sei-eschwartz]

I modified /usr/local/share/pharos/prolog/oorules/rules.pl in the Docker container, is that enough? Analysis still fails for me.

That should be enough. I'll look into it.

[sei-eschwartz]

@srett We'll close this issue when the patch is merged into master on github. But if you have any comments about the results you got, please let us know. Often times when we run on new "large" executables we find problems.

[tati1454]

Can you try this commit?

master...sei-eschwartz:pharos:master

I've applied this patches and it finished for me.