search

VirusTotal / yara

The pattern matching swiss knife
https://virustotal.github.io/yara/
BSD 3-Clause "New" or "Revised" License
8.3k stars 1.45k forks source link

YARA 4.0.0/4.0.1 timeout switches ignored #1299

Closed norwayfinland closed 4 years ago

norwayfinland commented 4 years ago

I patched around ERROR_SCAN_TIMEOUT. Here is the issue, it is reproducible on Ubuntu and RHEL.

Patched:

$ time yara -w ~/tools/Oreo/yara.txt ./7dad254921a9c060dc6ca493ad81cee4c45a1527106d61dc2f9a3e5cba6dab70.bin
PE_MZ_DoYouEvenNullBruh ./7dad254921a9c060dc6ca493ad81cee4c45a1527106d61dc2f9a3e5cba6dab70.bin
PE_MZ_SleepyKernels ./7dad254921a9c060dc6ca493ad81cee4c45a1527106d61dc2f9a3e5cba6dab70.bin
PE_HeaderNonZeroEntropy ./7dad254921a9c060dc6ca493ad81cee4c45a1527106d61dc2f9a3e5cba6dab70.bin
PE_MZ_MF_36 ./7dad254921a9c060dc6ca493ad81cee4c45a1527106d61dc2f9a3e5cba6dab70.bin
PE_MZ_MF_3F_3E ./7dad254921a9c060dc6ca493ad81cee4c45a1527106d61dc2f9a3e5cba6dab70.bin
PE_MZ_MF_lumberjax6x8 ./7dad254921a9c060dc6ca493ad81cee4c45a1527106d61dc2f9a3e5cba6dab70.bin
PE_MZ_MF_inc_add_db ./7dad254921a9c060dc6ca493ad81cee4c45a1527106d61dc2f9a3e5cba6dab70.bin
PE_MZ_MF_xor_enter ./7dad254921a9c060dc6ca493ad81cee4c45a1527106d61dc2f9a3e5cba6dab70.bin
too_many_high_ascii_ffff ./7dad254921a9c060dc6ca493ad81cee4c45a1527106d61dc2f9a3e5cba6dab70.bin
PE_MZ_Mega_Flowbissa ./7dad254921a9c060dc6ca493ad81cee4c45a1527106d61dc2f9a3e5cba6dab70.bin
PE_MZ_Bracket_Storm ./7dad254921a9c060dc6ca493ad81cee4c45a1527106d61dc2f9a3e5cba6dab70.bin
MZ_PE_Double_Kernel_API ./7dad254921a9c060dc6ca493ad81cee4c45a1527106d61dc2f9a3e5cba6dab70.bin
MZ_PE_Double_Kernel ./7dad254921a9c060dc6ca493ad81cee4c45a1527106d61dc2f9a3e5cba6dab70.bin
PE_1010_2020_API_WW_NUL_EOF ./7dad254921a9c060dc6ca493ad81cee4c45a1527106d61dc2f9a3e5cba6dab70.bin
PE_MZ_VERSION_NUL ./7dad254921a9c060dc6ca493ad81cee4c45a1527106d61dc2f9a3e5cba6dab70.bin
PE_MZ_Nymaim_KernelSanders ./7dad254921a9c060dc6ca493ad81cee4c45a1527106d61dc2f9a3e5cba6dab70.bin
Hawkeye_Keylogger_MZ ./7dad254921a9c060dc6ca493ad81cee4c45a1527106d61dc2f9a3e5cba6dab70.bin
Random_Hunt_20190320 ./7dad254921a9c060dc6ca493ad81cee4c45a1527106d61dc2f9a3e5cba6dab70.bin
VM_Detect_BadAPI_MZ_Pad ./7dad254921a9c060dc6ca493ad81cee4c45a1527106d61dc2f9a3e5cba6dab70.bin
njRAT_AutoIT_API ./7dad254921a9c060dc6ca493ad81cee4c45a1527106d61dc2f9a3e5cba6dab70.bin

real    0m12.276s
user    0m6.876s
sys    0m5.174s

Unpatched, and... times out well before 300 seconds and seems to completely ignore that value.

$ time yara -w ~/tools/Oreo/yara.txt ./7dad254921a9c060dc6ca493ad81cee4c45a1527106d61dc2f9a3e5cba6dab70.bin
error scanning ./7dad254921a9c060dc6ca493ad81cee4c45a1527106d61dc2f9a3e5cba6dab70.bin: scanning timed out

real    0m2.946s
user    0m2.786s
sys    0m0.100s

$ time yara --timeout=300 -w ~/tools/Oreo/yara.txt ./7dad254921a9c060dc6ca493ad81cee4c45a1527106d61dc2f9a3e5cba6dab70.bin
error scanning ./7dad254921a9c060dc6ca493ad81cee4c45a1527106d61dc2f9a3e5cba6dab70.bin: scanning timed out

real    0m3.894s
user    0m3.746s
sys    0m0.089s

$ time yara -a 300 -w ~/tools/Oreo/yara.txt ./7dad254921a9c060dc6ca493ad81cee4c45a1527106d61dc2f9a3e5cba6dab70.bin
error scanning ./7dad254921a9c060dc6ca493ad81cee4c45a1527106d61dc2f9a3e5cba6dab70.bin: scanning timed out

real    0m3.819s
user    0m3.671s
sys    0m0.100s

$ yara --help|grep timeout
  -a,  --timeout=SECONDS                abort scanning after the given number of SECONDS
plusvic commented 4 years ago

Can you please share the YARA rule that you are using in your tests?

norwayfinland commented 4 years ago

Sadly I cannot, as the ruleset is significant in volume. Quite a few of the rules throw performance warnings as a result of Aho Corsick atom selection and those atoms are poor quality as far as performance goes but are significant in the context of identifying malware. Let me see if I can replicate the behavior with a similar poor quality rule.

norwayfinland commented 4 years ago

Done, I can replicate it with this rule which uses REGEX and poor quality (from an Aho Corsick aspect) atom selection. As you can see below the timeout parameter is ignored.

Rule:

    rule Performance_Warning_Timeout{
    meta:
        author = "Norway Finland"
        date = "2020-06-11"
        comments = "This rule is to test the issue described at https://github.com/VirusTotal/yara/issues/1299"

    strings:
        $ = /\x00{2048}/

    condition:
        uint16(0) == 0x4d5a
        and all of them
    }

Sample:

    6001fc5fd25cbabcb2aad96b0c00de99 *7dad254921a9c060dc6ca493ad81cee4c45a1527106d61dc2f9a3e5cba6dab70.bin

Patched to work around ERROR_SCAN_TIMEOUT:

    $ time yara -w test.yar     ./7dad254921a9c060dc6ca493ad81cee4c45a1527106d61dc2f9a3e5cba6dab70.bin

    real    0m3.684s
    user    0m3.588s
    sys 0m0.024s

Unpatched YARA 4.0.1:

    $ time yara -w --timeout=300 test.yar ./7dad254921a9c060dc6ca493ad81cee4c45a1527106d61dc2f9a3e5cba6dab70.bin
    error scanning ./7dad254921a9c060dc6ca493ad81cee4c45a1527106d61dc2f9a3e5cba6dab70.bin: scanning timed out

    real    0m3.982s
    user    0m3.910s
    sys 0m0.052s

    $ time yara -w -a 300 test.yar ./7dad254921a9c060dc6ca493ad81cee4c45a1527106d61dc2f9a3e5cba6dab70.bin
    error scnning ./7dad254921a9c060dc6ca493ad81cee4c45a1527106d61dc2f9a3e5cba6dab70.bin: scanning timed out

    real    0m4.086s
    user    0m4.005s
    sys 0m0.048s

Cheers and thank you

norwayfinland commented 4 years ago

Reverse the byte ordering in the uint16(0) or use uint16be(0) if you want the rule to actually match. For the purposes of testing the bug report, it doesn't matter because Aho Corsick atom extraction appears to occur before uint16 conditional testing.

plusvic commented 4 years ago

Can you make sure that the version you have installed is the one you compiled by running sudo make install? For a moment I was experiencing the same problem than you after building version 4.0.1, but then noticed that I was running the command as yara not ./yara so I was running the version I had already installed.

norwayfinland commented 4 years ago

It was built as root on RHEL and Ubuntu, I am able to replicate it with 4.0.1 and 4.0.0 installed into /usr/local/bin during 'make install'. Path completion ensures yara is installed in /usr/local/bin and called from there. I can reproduce this issue on multiple systems and distributions using the above sample and rule. Prior to validation I validate the version by issuing "yara --version" or "/usr/local/bin/yara --version".

I know I am calling the correct one when I reverse the patch and/or recommit the patch and recompile.

Below is the patch I am using to work around this issue. The insulting comments in the patch are not directed at you but reflect the kludgy nature of my patching around the problem to make it work.

--- libyara/scanner_orig.c  2020-04-28 03:41:59.000000000 -0500
+++ libyara/scanner.c   2020-06-10 11:11:24.200134522 -0500
@@ -61,11 +61,14 @@

   while (i < block->size)
   {
+    /*Nathan Fowler, 2020-06-10
+    This is terribly terribly stupid.
     if (i % 4096 == 0 && scanner->timeout > 0)
     {
       if (yr_stopwatch_elapsed_ns(&scanner->stopwatch) > scanner->timeout)
         return ERROR_SCAN_TIMEOUT;
     }
+    */

     if (match_table[state] != 0)
     {
--- libyara/exec_orig.c 2020-04-28 03:41:59.000000000 -0500
+++ libyara/exec.c  2020-06-10 11:14:11.690808150 -0500
@@ -1642,7 +1642,6 @@

     // Check for timeout every 100 instruction cycles. If timeout == 0 it means
     // no timeout at all.
-
     if (context->timeout > 0L && ++cycle == 100)
     {
       elapsed_time = yr_stopwatch_elapsed_ns(&context->stopwatch);
@@ -1653,8 +1652,12 @@
         context->profiling_info[current_rule_idx].exec_time += (
             elapsed_time - start_time);
         #endif
+    /* Nathan Fowler, 2020-06-10
+       This is completely stupid
+
         result = ERROR_SCAN_TIMEOUT;
         stop = true;
+    */
       }

       cycle = 0;
norwayfinland commented 4 years ago

I have uploaded the malware to meows://bazaar.abuse.ch/sample/7dad254921a9c060dc6ca493ad81cee4c45a1527106d61dc2f9a3e5cba6dab70/ please note that this is malware and is malicious.

If this bug is related to cpu cycles across a time frame it may help if you concatenate the malware sample above into itself a few times to increase the size to say, 10MB, for testing. I can repeatedly reproduce this error with the YARA rule shared and the above sample. Without committing the patch above the file is never successfully scanned and all attempts to use --timeout or -a are ignored and not processed as they should be, hence this bug report.

Thank you in advance

plusvic commented 4 years ago

This is really weird because at some point I saw that error too, but after reinstalling I can't replicate it anymore. Can you share the output of your ./configure command?

norwayfinland commented 4 years ago

Certainly, also for what it is worth I can repeat this every time using a 1 CPU "resource limited" from a CPU aspect VM running i368 Ubuntu. I can also repeat this on production RHEL systems that are multi-cpu.

root@linuxenboxen:~/src/yara-4.0.1# uname -a
Linux linuxenboxen 4.15.0-101-generic #102-Ubuntu SMP Mon May 11 10:10:03 UTC 2020 i686 i686 i686 GNU/Linux
root@linuxenboxen:~/src/yara-4.0.1# cat /etc/lsb-release 
DISTRIB_ID=Ubuntu
DISTRIB_RELEASE=18.04
DISTRIB_CODENAME=bionic
DISTRIB_DESCRIPTION="Ubuntu 18.04.4 LTS"
root@linuxenboxen:~/src/yara-4.0.1#

Attached, thank you:

checking whether make supports nested variables... yes
checking for a BSD-compatible install... /usr/bin/install -c
checking whether build environment is sane... yes
checking for a thread-safe mkdir -p... /bin/mkdir -p
checking for gawk... gawk
checking whether make sets $(MAKE)... yes
checking for style of include used by make... GNU
checking for gcc... gcc
checking whether the C compiler works... yes
checking for C compiler default output file name... a.out
checking for suffix of executables... 
checking whether we are cross compiling... no
checking for suffix of object files... o
checking whether we are using the GNU C compiler... yes
checking whether gcc accepts -g... yes
checking for gcc option to accept ISO C89... none needed
checking whether gcc understands -c and -o together... yes
checking dependency style of gcc... gcc3
checking for ar... ar
checking the archiver (ar) interface... ar
checking for gcc... (cached) gcc
checking whether we are using the GNU C compiler... (cached) yes
checking whether gcc accepts -g... (cached) yes
checking for gcc option to accept ISO C89... (cached) none needed
checking whether gcc understands -c and -o together... (cached) yes
checking dependency style of gcc... (cached) gcc3
checking for gcc option to accept ISO C99... none needed
checking for flex... flex
checking lex output file root... lex.yy
checking lex library... -lfl
checking whether yytext is a pointer... yes
checking for bison... bison -y
checking for inline... inline
checking how to run the C preprocessor... gcc -E
checking for grep that handles long lines and -e... /bin/grep
checking for egrep... /bin/grep -E
checking for ANSI C header files... yes
checking for sys/types.h... yes
checking for sys/stat.h... yes
checking for stdlib.h... yes
checking for string.h... yes
checking for memory.h... yes
checking for strings.h... yes
checking for inttypes.h... yes
checking for stdint.h... yes
checking for unistd.h... yes
checking whether byte ordering is bigendian... no
checking for special C compiler options needed for large files... no
checking for _FILE_OFFSET_BITS value needed for large files... 64
checking build system type... i686-pc-linux-gnu
checking host system type... i686-pc-linux-gnu
checking how to print strings... printf
checking for a sed that does not truncate output... /bin/sed
checking for fgrep... /bin/grep -F
checking for ld used by gcc... /usr/bin/ld
checking if the linker (/usr/bin/ld) is GNU ld... yes
checking for BSD- or MS-compatible name lister (nm)... /usr/bin/nm -B
checking the name lister (/usr/bin/nm -B) interface... BSD nm
checking whether ln -s works... yes
checking the maximum length of command line arguments... 1572864
checking how to convert i686-pc-linux-gnu file names to i686-pc-linux-gnu format... func_convert_file_noop
checking how to convert i686-pc-linux-gnu file names to toolchain format... func_convert_file_noop
checking for /usr/bin/ld option to reload object files... -r
checking for objdump... objdump
checking how to recognize dependent libraries... pass_all
checking for dlltool... no
checking how to associate runtime and link libraries... printf %s\n
checking for archiver @FILE support... @
checking for strip... strip
checking for ranlib... ranlib
checking command to parse /usr/bin/nm -B output from gcc object... ok
checking for sysroot... no
checking for a working dd... /bin/dd
checking how to truncate binary pipes... /bin/dd bs=4096 count=1
checking for mt... mt
checking if mt is a manifest tool... no
checking for dlfcn.h... yes
checking for objdir... .libs
checking if gcc supports -fno-rtti -fno-exceptions... no
checking for gcc option to produce PIC... -fPIC -DPIC
checking if gcc PIC flag -fPIC -DPIC works... yes
checking if gcc static flag -static works... yes
checking if gcc supports -c -o file.o... yes
checking if gcc supports -c -o file.o... (cached) yes
checking whether the gcc linker (/usr/bin/ld) supports shared libraries... yes
checking whether -lc should be explicitly linked in... no
checking dynamic linker characteristics... GNU/Linux ld.so
checking how to hardcode library paths into programs... immediate
checking whether stripping libraries is possible... yes
checking if libtool supports shared libraries... yes
checking whether to build shared libraries... yes
checking whether to build static libraries... yes
checking for the pthreads library -lpthreads... no
checking whether pthreads work without any flags... no
checking whether pthreads work with -Kthread... no
checking whether pthreads work with -kthread... no
checking for the pthreads library -llthread... no
checking whether pthreads work with -pthread... yes
checking for joinable pthread attribute... PTHREAD_CREATE_JOINABLE
checking if more special flags are required for pthreads... no
checking whether to check for GCC pthread/shared inconsistencies... yes
checking whether -pthread is sufficient with -shared... yes
checking for isnan in -lm... yes
checking for log2 in -lm... yes
checking for strlcpy... no
checking for strlcat... no
checking for memmem... yes
checking for timegm... yes
checking for _mkgmtime... no
checking for clock_gettime... yes
checking stdbool.h usability... yes
checking stdbool.h presence... yes
checking for stdbool.h... yes
checking for pkg-config... /usr/bin/pkg-config
checking pkg-config is at least version 0.9.0... yes
checking openssl/md5.h usability... yes
checking openssl/md5.h presence... yes
checking for openssl/md5.h... yes
checking openssl/sha.h usability... yes
checking openssl/sha.h presence... yes
checking for openssl/sha.h... yes
checking openssl/asn1.h usability... yes
checking openssl/asn1.h presence... yes
checking for openssl/asn1.h... yes
checking openssl/crypto.h usability... yes
checking openssl/crypto.h presence... yes
checking for openssl/crypto.h... yes
checking openssl/bio.h usability... yes
checking openssl/bio.h presence... yes
checking for openssl/bio.h... yes
checking openssl/pkcs7.h usability... yes
checking openssl/pkcs7.h presence... yes
checking for openssl/pkcs7.h... yes
checking openssl/x509.h usability... yes
checking openssl/x509.h presence... yes
checking for openssl/x509.h... yes
checking openssl/safestack.h usability... yes
checking openssl/safestack.h presence... yes
checking for openssl/safestack.h... yes
checking for MD5_Init in -lcrypto... yes
checking for MD5_Update in -lcrypto... yes
checking for MD5_Final in -lcrypto... yes
checking for SHA256_Init in -lcrypto... yes
checking for SHA256_Update in -lcrypto... yes
checking for SHA256_Final in -lcrypto... yes
checking that generated files are newer than configure... done
configure: creating ./config.status
config.status: creating Makefile
config.status: creating libyara/Makefile
config.status: creating libyara/yara.pc
config.status: executing depfiles commands
config.status: executing libtool commands

Cheers and thank you

plusvic commented 4 years ago

I recommend printing the results from calls to yr_stopwatch_elapsed_ns() in order to see what they are returning. This could give us some hint.

norwayfinland commented 4 years ago

On it, thank you -- standby, will share shortly. Need to back my patch out and recompiled 4.0.1 native/unmodified.

norwayfinland commented 4 years ago 
$ /usr/local/bin/yara -w ./test.yar ./7dad254921a9c060dc6ca493ad81cee4c45a1527106d61dc2f9a3e5cba6dab70.bin
error scanning ./7dad254921a9c060dc6ca493ad81cee4c45a1527106d61dc2f9a3e5cba6dab70.bin: scanning timed out
DEBUG ERROR_SCAN_TIME yr_stopwatch_elapsed_ns -1337583911 is greater than scanner->timeout -1530494976

Oddly enough, after patching this in, I can not repeatedly produce it, but I was able to consistently reproduce it once again by increasing the file size. It seems to hinge on available CPU cycles instead of an actual timeout in seconds as specified in the -a and --timeout arguments.

luser@linuxenboxen:~/Downloads$ cat 7dad254921a9c060dc6ca493ad81cee4c45a1527106d61dc2f9a3e5cba6dab70.bin > meow
luser@linuxenboxen:~/Downloads$ cat 7dad254921a9c060dc6ca493ad81cee4c45a1527106d61dc2f9a3e5cba6dab70.bin >> meow
luser@linuxenboxen:~/Downloads$ cat 7dad254921a9c060dc6ca493ad81cee4c45a1527106d61dc2f9a3e5cba6dab70.bin >> meow

$ time /usr/local/bin/yara -a 300 -w ./test.yar ./meow; echo
error scanning ./meow: scanning timed out
DEBUG ERROR_SCAN_TIME yr_stopwatch_elapsed_ns -599078855 is greater than scanner->timeout -647710720
real    0m3.708s
user    0m3.571s
sys 0m0.063s

$ time /usr/local/bin/yara --timeout=300 -w ./test.yar ./meow; echo
error scanning ./meow: scanning timed out
DEBUG ERROR_SCAN_TIME yr_stopwatch_elapsed_ns -647077405 is greater than scanner->timeout -647710720
real    0m3.660s
user    0m3.578s
sys 0m0.048s

Here are my code changes to a vanilla/native YARA 4.0.1 tar.gz release:

  while (i < block->size)
  {
    if (i % 4096 == 0 && scanner->timeout > 0)
    {
      if (yr_stopwatch_elapsed_ns(&scanner->stopwatch) > scanner->timeout){
        printf("DEBUG ERROR_SCAN_TIME yr_stopwatch_elapsed_ns %lld is greater than scanner->timeout %lld",yr_stopwatch_elapsed_ns(&scanner->stopwatch),scanner->timeout);
        return ERROR_SCAN_TIMEOUT;
      }
    }
plusvic commented 4 years ago

Mmmm, it bothers me that timeout is negative, can you use %llu instead od %lld? The timeout is unsigned.

norwayfinland commented 4 years ago

Certainly, below are the code changes:

  {
    if (i % 4096 == 0 && scanner->timeout > 0)
    {
      if (yr_stopwatch_elapsed_ns(&scanner->stopwatch) > scanner->timeout){
        printf("DEBUG ERROR_SCAN_TIME yr_stopwatch_elapsed_ns %llu is greater than scanner->timeout %llu\n",yr_stopwatch_elapsed_ns(&scanner->stopwatch),scanner->timeout);
        return ERROR_SCAN_TIMEOUT;
      }
    }

I have done: make clean && make && make install

I know I am running the correct version because I added a newline :)

luser@linuxenboxen:~/Downloads$ time /usr/local/bin/yara --timeout=300 -w ./test.yar ./meow
DEBUG ERROR_SCAN_TIME yr_stopwatch_elapsed_ns 18446744073152629720 is greater than scanner->timeout 18446744073061840896
error scanning ./meow: scanning timed out

real    0m3.750s
user    0m3.685s
sys 0m0.048s
luser@linuxenboxen:~/Downloads$ time /usr/local/bin/yara -a 300 -w ./test.yar ./meow
DEBUG ERROR_SCAN_TIME yr_stopwatch_elapsed_ns 18446744073080667227 is greater than scanner->timeout 18446744073061840896
error scanning ./meow: scanning timed out

real    0m3.674s
user    0m3.542s
sys 0m0.047s
luser@linuxenboxen:~/Downloads$
norwayfinland commented 4 years ago

Additionally, as I was thinking perhaps this was a math error, but even this is not considered:

luser@linuxenboxen:~/Downloads$ time /usr/local/bin/yara -a 99999999999999 -w ./test.yar ./meow
DEBUG ERROR_SCAN_TIME yr_stopwatch_elapsed_ns 18446744072762457991 is greater than scanner->timeout 18446744072709551616
error scanning ./meow: scanning timed out

real    0m3.356s
user    0m3.296s
sys 0m0.048s
luser@linuxenboxen:~/Downloads$ time /usr/local/bin/yara --timeout=99999999999999 -w ./test.yar ./meow
DEBUG ERROR_SCAN_TIME yr_stopwatch_elapsed_ns 18446744072958450603 is greater than scanner->timeout 18446744072709551616
error scanning ./meow: scanning timed out

real    0m3.556s
user    0m3.499s
sys 0m0.044s

And even:

luser@linuxenboxen:~/Downloads$ time /usr/local/bin/yara --timeout=999999999999999999999999999999999999999999999999 -w ./test.yar ./meow
DEBUG ERROR_SCAN_TIME yr_stopwatch_elapsed_ns 18446744072862454265 is greater than scanner->timeout 18446744072709551616
error scanning ./meow: scanning timed out

real    0m3.460s
user    0m3.400s
sys 0m0.028s
norwayfinland commented 4 years ago

Unsure if this helps but I am attaching a stack trace from this run:

$ strace -ff -s4096 /usr/local/bin/yara -w --timeout=999999999999999 ./test.yar ./meow 2> ./trace.txt
DEBUG ERROR_SCAN_TIME yr_stopwatch_elapsed_ns 18446744072974494516 is greater than scanner->timeout 18446744072709551616

Trace:

execve("/usr/local/bin/yara", ["/usr/local/bin/yara", "-w", "--timeout=999999999999999", "./test.yar", "./meow"], 0xbfc52598 /* 47 vars */) = 0
brk(NULL)                               = 0xed0000
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
mmap2(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7f01000
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
fstat64(3, {st_mode=S_IFREG|0644, st_size=117399, ...}) = 0
mmap2(NULL, 117399, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7ee4000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/local/lib/libyara.so.4", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0`6\0\0004\0\0\0x\216\7\0\0\0\0\0004\0 \0\7\0(\0\35\0\34\0\1\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0l\267\6\0l\267\6\0\5\0\0\0\0\20\0\0\1\0\0\0\270\273\6\0\270\313\6\0\270\313\6\0X\v\0\0\310\r\0\0\6\0\0\0\0\20\0\0\2\0\0\0\274\276\6\0\274\316\6\0\274\316\6\0\0\1\0\0\0\1\0\0\6\0\0\0\4\0\0\0\4\0\0\0\24\1\0\0\24\1\0\0\24\1\0\0$\0\0\0$\0\0\0\4\0\0\0\4\0\0\0P\345tdxG\5\0xG\5\0xG\5\0\214\20\0\0\214\20\0\0\4\0\0\0\4\0\0\0Q\345td\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\6\0\0\0\20\0\0\0R\345td\270\273\6\0\270\313\6\0\270\313\6\0H\4\0\0H\4\0\0\4\0\0\0\1\0\0\0\4\0\0\0\24\0\0\0\3\0\0\0GNU\0003\200+N3X\251@\221\270\211\306\250OU\212%*3&C\0\0\0w\0\0\0\20\0\0\0\t\0\0\0T\340\f\0S9\30G\16\10  `\200@\20\300\10\10\261P\1\24\340^+\352#\24\0\1\0\0P\20\242Lv\3E\f\202a\10\241\231\300\0310\5\0\200@\1\2\t\366\236:I\210Fc\3w\0\0\0z\0\0\0\0\0\0\0{\0\0\0|\0\0\0}\0\0\0\177\0\0\0\0\0\0\0\0\0\0\0\200\0\0\0\202\0\0\0\205\0\0\0\206\0\0\0\211\0\0\0\0\0\0\0\0\0\0\0\212\0\0\0\213\0\0\0\216\0\0\0\0\0\0\0\217\0\0\0\221\0\0\0\223\0\0\0\0\0\0\0\225\0\0\0\0\0\0\0\227\0\0\0\231\0\0\0\233\0\0\0\0\0\0\0", 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=496384, ...}) = 0
mmap2(NULL, 448896, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb7e76000
mmap2(0xb7ee2000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x6b000) = 0xb7ee2000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/lib/i386-linux-gnu/libpthread.so.0", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\300P\0\0004\0\0\0\244'\2\0\0\0\0\0004\0 \0\t\0(\0(\0'\0\6\0\0\0004\0\0\0004\0\0\0004\0\0\0 \1\0\0 \1\0\0\4\0\0\0\4\0\0\0\3\0\0\0<P\1\0<P\1\0<P\1\0\23\0\0\0\23\0\0\0\4\0\0\0\4\0\0\0\1\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\24\255\1\0\24\255\1\0\5\0\0\0\0\20\0\0\1\0\0\0\260\255\1\0\260\275\1\0\260\275\1\0\324\3\0\0\350$\0\0\6\0\0\0\0\20\0\0\2\0\0\0\224\256\1\0\224\276\1\0\224\276\1\0\30\1\0\0\30\1\0\0\6\0\0\0\4\0\0\0\4\0\0\0T\1\0\0T\1\0\0T\1\0\0D\0\0\0D\0\0\0\4\0\0\0\4\0\0\0P\345tdPP\1\0PP\1\0PP\1\0\254\t\0\0\254\t\0\0\4\0\0\0\4\0\0\0Q\345td\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\6\0\0\0\20\0\0\0R\345td\260\255\1\0\260\275\1\0\260\275\1\0P\2\0\0P\2\0\0\4\0\0\0\1\0\0\0\4\0\0\0\24\0\0\0\3\0\0\0GNU\0\317T\26\21\r\21\312B0\255p\350\3360u\3504V\272\\\4\0\0\0\20\0\0\0\1\0\0\0GNU\0\0\0\0\0\3\0\0\0\2\0\0\0\0\0\0\0\4\2\0\0]\0\0\0@\0\0\0\v\0\0\0\31!\2\221\1\n\20\"@H \331\3\0I4\200\0\0@\0 \200\200\221Q`\300@\22\213\0020D\0\0\20\1\0\n\0\1\r\0\204\n\360\1X\260\r\240\200\10 $\204\20B\242)m\10G\234V\20\0\224 \204$H\0X(\1\222\34\301B\240\220\22\10\f \2", 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=142820, ...}) = 0
mmap2(NULL, 123544, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb7e57000
mmap2(0xb7e72000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1a000) = 0xb7e72000
mmap2(0xb7e74000, 4760, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xb7e74000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/lib/i386-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\1\1\1\3\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\20\220\1\0004\0\0\0H\232\35\0\0\0\0\0004\0 \0\n\0(\0F\0E\0\6\0\0\0004\0\0\0004\0\0\0004\0\0\0@\1\0\0@\1\0\0\4\0\0\0\4\0\0\0\3\0\0\0Lx\30\0Lx\30\0Lx\30\0\23\0\0\0\23\0\0\0\4\0\0\0\4\0\0\0\1\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\20D\35\0\20D\35\0\5\0\0\0\0\20\0\0\1\0\0\0\\Q\35\0\\a\35\0\\a\35\0\230-\0\0\300X\0\0\6\0\0\0\0\20\0\0\2\0\0\0lm\35\0l}\35\0l}\35\0\360\0\0\0\360\0\0\0\6\0\0\0\4\0\0\0\4\0\0\0t\1\0\0t\1\0\0t\1\0\0D\0\0\0D\0\0\0\4\0\0\0\4\0\0\0\7\0\0\0\\Q\35\0\\a\35\0\\a\35\0\10\0\0\0T\0\0\0\4\0\0\0\4\0\0\0P\345td`x\30\0`x\30\0`x\30\0\\e\0\0\\e\0\0\4\0\0\0\4\0\0\0Q\345td\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\6\0\0\0\20\0\0\0R\345td\\Q\35\0\\a\35\0\\a\35\0\244\36\0\0\244\36\0\0\4\0\0\0\1\0\0\0\4\0\0\0\24\0\0\0\3\0\0\0GNU\0\16\30\216\305\360\234\30zz\222xMK\227\252%\33\25\251<\4\0\0\0\20\0\0\0\1\0\0\0GNU\0\0\0\0\0\3\0\0\0\2\0\0\0\0\0\0\0\363\3\0\0\f\0\0\0\0\2\0\0\16\0\0\0\2400\20D\200 \2\1\214\3\346\220AE\210\0\204\0\10\0G\204Pp\300\200\1\f\212\f@\0010\0\10@2\10\252\0\210H6m\240\0368\0&\204\200\216\4\10B$", 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=1942840, ...}) = 0
mmap2(NULL, 1948188, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb7c7b000
mprotect(0xb7e50000, 4096, PROT_NONE)   = 0
mmap2(0xb7e51000, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1d5000) = 0xb7e51000
mmap2(0xb7e54000, 10780, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xb7e54000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/lib/i386-linux-gnu/libcrypto.so.1.1", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\0\200\4\0004\0\0\0\10\217*\0\0\0\0\0004\0 \0\7\0(\0\33\0\32\0\1\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\364\365(\0\364\365(\0\5\0\0\0\0\20\0\0\1\0\0\0\30\375(\0\30\r)\0\30\r)\0\304\220\1\0P\275\1\0\6\0\0\0\0\20\0\0\2\0\0\0,x*\0,\210*\0,\210*\0\30\1\0\0\30\1\0\0\6\0\0\0\4\0\0\0\4\0\0\0\24\1\0\0\24\1\0\0\24\1\0\0$\0\0\0$\0\0\0\4\0\0\0\4\0\0\0P\345tdt\242\37\0t\242\37\0t\242\37\0\334\273\0\0\334\273\0\0\4\0\0\0\4\0\0\0Q\345td\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\6\0\0\0\20\0\0\0R\345td\30\375(\0\30\r)\0\30\r)\0\350\202\1\0\350\202\1\0\4\0\0\0\1\0\0\0\4\0\0\0\24\0\0\0\3\0\0\0GNU\0\200}\307\324\337T5D3\24b2<\337;\306!>g\245\3\20\0\0\212\0\0\0\0\4\0\0\17\0\0\0Y\f\31\305M\6\200\301@\0\4\0\1\0\5 \201\0\0\0\30\206\4\250\20\0@\300\10\0\1\0\5\204\3\0\200$e\21V\t\f\310\0\3\200\24\0\0\252\24\211\3I\204\10\0\4\20\0\2!8\10\0\1\204\0\0\1\200\r\20t\305\262\fD\0\t\22\4E\t@\312@\f\205\16\200\4V\24@$\1\0D(\f\301\v\10T\210\0\0\f\1\0\300@P\240\21\3.\230\205\5!L\210\350\3^\0\20\0\4\6@\10\0\0\6\240\2@\0\30\35\1\0\2\0c\360\222\2\20\220\0\20\0\0042H\0\0\0\0\350\20!\1\1c\4\250D \10\2\10\0\4\201\3!\3\201", 512) = 512
fstat64(3, {st_mode=S_IFREG|0644, st_size=2790208, ...}) = 0
mmap2(NULL, 2804328, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb79ce000
mmap2(0xb7c5e000, 106496, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x28f000) = 0xb7c5e000
mmap2(0xb7c78000, 10856, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xb7c78000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/lib/i386-linux-gnu/libm.so.6", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\1\1\1\3\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\220\225\0\0004\0\0\0\310\2\20\0\0\0\0\0004\0 \0\7\0(\0\37\0\36\0\1\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0<\374\17\0<\374\17\0\5\0\0\0\0\20\0\0\1\0\0\0\274\376\17\0\274\16\20\0\274\16\20\0\244\1\0\0\254\1\0\0\6\0\0\0\0\20\0\0\2\0\0\0\304\376\17\0\304\16\20\0\304\16\20\0\20\1\0\0\20\1\0\0\6\0\0\0\4\0\0\0\4\0\0\0\24\1\0\0\24\1\0\0\24\1\0\0D\0\0\0D\0\0\0\4\0\0\0\4\0\0\0P\345td\0107\16\0\0107\16\0\0107\16\0\34\27\0\0\34\27\0\0\4\0\0\0\4\0\0\0Q\345td\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\6\0\0\0\20\0\0\0R\345td\274\376\17\0\274\16\20\0\274\16\20\0D\1\0\0D\1\0\0\4\0\0\0\1\0\0\0\4\0\0\0\24\0\0\0\3\0\0\0GNU\0u\312\254k_\222\2\374b\241\326\231\260\2478.\244\2607\360\4\0\0\0\20\0\0\0\1\0\0\0GNU\0\0\0\0\0\3\0\0\0\2\0\0\0\0\0\0\0\372\3\0\0\22\0\0\0\0\1\0\0\r\0\0\0%H\0@\301@\0\0\"_$N\2\6E\0J`\210\"\0\371\0\312\10\0\0\200@vJ@\24\0,\20P\301\332\300P\21J\211\0\0 \202\24\10\0\232\2\0\200 \252\0001\0\212`\10@\0#\0F\"\20(\1\1\24\10f\25q\6\16\21\0\0\0\4!\22@\20\10\0000EJ: \200\0\10\22Q\204iJG\311,\20\200\200\0\0` \222\6\n\r\0\20\2\210\0\6\0\210\2@\2\10\307\20`\204\5I E\r\0\230\"\0 @B\21@\203!@\0", 512) = 512
fstat64(3, {st_mode=S_IFREG|0644, st_size=1050528, ...}) = 0
mmap2(NULL, 1052776, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb78cc000
mmap2(0xb79cc000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0xff000) = 0xb79cc000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/lib/i386-linux-gnu/libdl.so.2", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\320\n\0\0004\0\0\0\\1\0\0\0\0\0\0004\0 \0\7\0(\0\35\0\34\0\1\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\210%\0\0\210%\0\0\5\0\0\0\0\20\0\0\1\0\0\0\270.\0\0\270>\0\0\270>\0\0\214\1\0\0\274\1\0\0\6\0\0\0\0\20\0\0\2\0\0\0\310.\0\0\310>\0\0\310>\0\0\10\1\0\0\10\1\0\0\6\0\0\0\4\0\0\0\4\0\0\0\24\1\0\0\24\1\0\0\24\1\0\0D\0\0\0D\0\0\0\4\0\0\0\4\0\0\0P\345td<\33\0\0<\33\0\0<\33\0\0\344\0\0\0\344\0\0\0\4\0\0\0\4\0\0\0Q\345td\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\6\0\0\0\20\0\0\0R\345td\270.\0\0\270>\0\0\270>\0\0H\1\0\0H\1\0\0\4\0\0\0\1\0\0\0\4\0\0\0\24\0\0\0\3\0\0\0GNU\0\252\225c\256\240\267\213\376\r\22\305\236\236\256\234I|\36\342|\4\0\0\0\20\0\0\0\1\0\0\0GNU\0\0\0\0\0\3\0\0\0\2\0\0\0\0\0\0\0\26\0\0\0\34\0\0\0\4\0\0\0\7\0\0\0\230\0\21\0\0B\0\0\202\0`\10\223(\10\336\34\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\35\0\0\0\0\0\0\0\36\0\0\0\37\0\0\0\0\0\0\0!\0\0\0\0\0\0\0\0\0\0\0\"\0\0\0$\0\0\0%\0\0\0\0\0\0\0\0\0\0\0&\0\0\0(\0\0\0)\0\0\0\0\0\0\0+\0\0\0\221!\374\370\225\263_\31\5\350\7\371\6\2\4\371\7\2\4\371\301S\200\30`\242\222\6\257\304M\17\325=l\366\327=l\366\352\26\251\30\371\31sB", 512) = 512
fstat64(3, {st_mode=S_IFREG|0644, st_size=13796, ...}) = 0
mmap2(NULL, 16500, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb78c7000
mmap2(0xb78ca000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x2000) = 0xb78ca000
close(3)                                = 0
mmap2(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb78c5000
set_thread_area({entry_number=-1, base_addr=0xb78c5700, limit=0x0fffff, seg_32bit=1, contents=0, read_exec_only=0, limit_in_pages=1, seg_not_present=0, useable=1}) = 0 (entry_number=6)
mprotect(0xb7e51000, 8192, PROT_READ)   = 0
mprotect(0xb78ca000, 4096, PROT_READ)   = 0
mprotect(0xb79cc000, 4096, PROT_READ)   = 0
mprotect(0xb7e72000, 4096, PROT_READ)   = 0
mprotect(0xb7c5e000, 102400, PROT_READ) = 0
mprotect(0xb7ee2000, 4096, PROT_READ)   = 0
mprotect(0x4a2000, 4096, PROT_READ)     = 0
mprotect(0xb7f2e000, 4096, PROT_READ)   = 0
munmap(0xb7ee4000, 117399)              = 0
set_tid_address(0xb78c5768)             = 21286
set_robust_list(0xb78c5770, 12)         = 0
rt_sigaction(SIGRTMIN, {sa_handler=0xb7e5baf0, sa_mask=[], sa_flags=SA_SIGINFO}, NULL, 8) = 0
rt_sigaction(SIGRT_1, {sa_handler=0xb7e5bb80, sa_mask=[], sa_flags=SA_RESTART|SA_SIGINFO}, NULL, 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [RTMIN RT_1], NULL, 8) = 0
ugetrlimit(RLIMIT_STACK, {rlim_cur=8192*1024, rlim_max=RLIM_INFINITY}) = 0
uname({sysname="Linux", nodename="linuxenboxen", ...}) = 0
brk(NULL)                               = 0xed0000
brk(0xef1000)                           = 0xef1000
brk(0xef2000)                           = 0xef2000
access("./test.yar", F_OK)              = 0
openat(AT_FDCWD, "./test.yar", O_RDONLY|O_LARGEFILE) = 3
mmap2(NULL, 1052672, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb77c4000
mmap2(NULL, 1052672, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb76c3000
fstat64(3, {st_mode=S_IFREG|0664, st_size=274, ...}) = 0
read(3, "rule Performance_Warning_Timeout{\nmeta:\n\tauthor = \"Norway Finland\"\n\tdate = \"2020-06-11\"\n\tcomments = \"This rule is to test the issue described at https://github.com/VirusTotal/yara/issues/1299\"\n\nstrings:\n\t$ = /\\x00{2048}/\n\ncondition:\n\tuint16(0) == 0x5a4d\n\tand all of them\n}\n\n", 8192) = 274
read(3, "", 4096)                       = 0
mmap2(NULL, 1052672, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb75c2000
mmap2(NULL, 1052672, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb74c1000
mmap2(NULL, 1052672, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb73c0000
mmap2(NULL, 1052672, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb72bf000
mmap2(NULL, 1052672, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb71be000
mmap2(NULL, 1052672, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb70bd000
read(3, "", 8192)                       = 0
close(3)                                = 0
mmap2(NULL, 1052672, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb6fbc000
mmap2(NULL, 1052672, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb6ebb000
mmap2(NULL, 1052672, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb6dba000
mmap2(NULL, 1052672, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb6cb9000
stat64("./meow", {st_mode=S_IFREG|0664, st_size=5683200, ...}) = 0
openat(AT_FDCWD, "./meow", O_RDONLY|O_LARGEFILE) = 3
fstat64(3, {st_mode=S_IFREG|0664, st_size=5683200, ...}) = 0
mmap2(NULL, 5683200, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb674d000
madvise(0xb674d000, 5683200, MADV_SEQUENTIAL) = 0
mmap2(NULL, 573440, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb66c1000
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=384476079}) = 0
rt_sigaction(SIGBUS, {sa_handler=0xb7ebd9d0, sa_mask=~[RTMIN RT_1], sa_flags=0}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
rt_sigaction(SIGSEGV, {sa_handler=0xb7ebd9d0, sa_mask=~[RTMIN RT_1], sa_flags=0}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
rt_sigprocmask(SIG_BLOCK, NULL, [], 8)  = 0
rt_sigaction(SIGBUS, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, NULL, 8) = 0
rt_sigaction(SIGSEGV, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, NULL, 8) = 0
rt_sigaction(SIGBUS, {sa_handler=0xb7ebd9d0, sa_mask=~[RTMIN RT_1], sa_flags=0}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
rt_sigaction(SIGSEGV, {sa_handler=0xb7ebd9d0, sa_mask=~[RTMIN RT_1], sa_flags=0}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
rt_sigprocmask(SIG_BLOCK, NULL, [], 8)  = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=384476079}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=388475979}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=388475979}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=388475979}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=388475979}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=388475979}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=388475979}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=388475979}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=388475979}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=388475979}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=388475979}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=388475979}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=388475979}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=392475878}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=392475878}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=392475878}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=392475878}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=392475878}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=392475878}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=392475878}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=392475878}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=392475878}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=392475878}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=392475878}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=392475878}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=392475878}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=392475878}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=392475878}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=392475878}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=392475878}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=392475878}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=392475878}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=392475878}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=392475878}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=392475878}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=392475878}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=392475878}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=392475878}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=392475878}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=392475878}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=392475878}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=392475878}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=392475878}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=392475878}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=392475878}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=392475878}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=392475878}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=392475878}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=392475878}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=392475878}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=392475878}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=396475777}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=396475777}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=396475777}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=396475777}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=396475777}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=396475777}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=396475777}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=396475777}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=396475777}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=396475777}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=396475777}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=396475777}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=396475777}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=396475777}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=396475777}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=396475777}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=396475777}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=396475777}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=396475777}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=396475777}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=396475777}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=396475777}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=396475777}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=396475777}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=396475777}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=396475777}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=396475777}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=396475777}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=396475777}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=396475777}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=396475777}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=396475777}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=396475777}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=396475777}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=396475777}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=396475777}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=396475777}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=396475777}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=396475777}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=396475777}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=396475777}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=396475777}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=396475777}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=396475777}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=396475777}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=396475777}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=396475777}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=396475777}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=400475676}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=400475676}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=400475676}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=400475676}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=400475676}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=400475676}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=400475676}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=400475676}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=400475676}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=400475676}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=400475676}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=400475676}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=400475676}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=400475676}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=400475676}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=400475676}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=400475676}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=400475676}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=400475676}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=400475676}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=400475676}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=400475676}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=404475575}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=404475575}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=404475575}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=404475575}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=404475575}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=404475575}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=404475575}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=404475575}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=404475575}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=404475575}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=404475575}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=404475575}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=404475575}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=404475575}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=404475575}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=404475575}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=404475575}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=404475575}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=404475575}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=404475575}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=404475575}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=404475575}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=404475575}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=404475575}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=404475575}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=404475575}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=404475575}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=404475575}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=404475575}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=404475575}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=404475575}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=404475575}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=404475575}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=404475575}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=408475474}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=408475474}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=408475474}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=408475474}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=408475474}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=412475373}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=412475373}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=412475373}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=412475373}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=416475272}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=416475272}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=416475272}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=416475272}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=416475272}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=416475272}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=416475272}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=416475272}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=416475272}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=416475272}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=416475272}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=416475272}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=420475171}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=420475171}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=420475171}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=420475171}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=420475171}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=420475171}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=420475171}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=420475171}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=420475171}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=420475171}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=420475171}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=420475171}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=420475171}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=420475171}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=420475171}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=440474667}) = 0
mmap2(NULL, 573440, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb6635000
mmap2(NULL, 573440, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb65a9000
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22070, tv_nsec=748466899}) = 0
mmap2(NULL, 573440, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb651d000
mmap2(NULL, 573440, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb6491000
mmap2(NULL, 573440, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb6405000
mmap2(NULL, 573440, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb6379000
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22071, tv_nsec=256454086}) = 0
mmap2(NULL, 573440, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb62ed000
mmap2(NULL, 573440, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb6261000
mmap2(NULL, 573440, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb61d5000
mmap2(NULL, 573440, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb6149000
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22071, tv_nsec=804440263}) = 0
mmap2(NULL, 573440, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb60bd000
mmap2(NULL, 573440, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb6031000
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22072, tv_nsec=176430879}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22072, tv_nsec=176430879}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22072, tv_nsec=176430879}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22072, tv_nsec=176430879}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22072, tv_nsec=176430879}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22072, tv_nsec=176430879}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22072, tv_nsec=176430879}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22072, tv_nsec=176430879}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22072, tv_nsec=176430879}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22072, tv_nsec=176430879}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22072, tv_nsec=176430879}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22072, tv_nsec=176430879}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22072, tv_nsec=220429769}) = 0
mmap2(NULL, 573440, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb5fa5000
mmap2(NULL, 573440, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb5f19000
mmap2(NULL, 573440, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb5e8d000
mmap2(NULL, 573440, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb5e01000
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22072, tv_nsec=764416045}) = 0
mmap2(NULL, 573440, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb5d75000
mmap2(NULL, 573440, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb5ce9000
mmap2(NULL, 573440, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb5c5d000
mmap2(NULL, 573440, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb5bd1000
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22073, tv_nsec=344401413}) = 0
mmap2(NULL, 573440, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb5b45000
mmap2(NULL, 573440, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb5ab9000
mmap2(NULL, 573440, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb5a2d000
mmap2(NULL, 573440, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb59a1000
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22073, tv_nsec=944386275}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=22073, tv_nsec=944386275}) = 0
fstat64(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 0), ...}) = 0
write(1, "DEBUG ERROR_SCAN_TIME yr_stopwatch_elapsed_ns 18446744072974494516 is greater than scanner->timeout 18446744072709551616\n", 121) = 121
rt_sigaction(SIGBUS, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, NULL, 8) = 0
rt_sigaction(SIGSEGV, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, NULL, 8) = 0
munmap(0xb59a1000, 573440)              = 0
munmap(0xb5a2d000, 573440)              = 0
munmap(0xb5ab9000, 573440)              = 0
munmap(0xb5b45000, 573440)              = 0
munmap(0xb5bd1000, 573440)              = 0
munmap(0xb5c5d000, 573440)              = 0
munmap(0xb5ce9000, 573440)              = 0
munmap(0xb5d75000, 573440)              = 0
munmap(0xb5e01000, 573440)              = 0
munmap(0xb5e8d000, 573440)              = 0
munmap(0xb5f19000, 573440)              = 0
munmap(0xb5fa5000, 573440)              = 0
munmap(0xb6031000, 573440)              = 0
munmap(0xb60bd000, 573440)              = 0
munmap(0xb6149000, 573440)              = 0
munmap(0xb61d5000, 573440)              = 0
munmap(0xb6261000, 573440)              = 0
munmap(0xb62ed000, 573440)              = 0
munmap(0xb6379000, 573440)              = 0
munmap(0xb6405000, 573440)              = 0
munmap(0xb6491000, 573440)              = 0
munmap(0xb651d000, 573440)              = 0
munmap(0xb65a9000, 573440)              = 0
munmap(0xb6635000, 573440)              = 0
munmap(0xb66c1000, 573440)              = 0
munmap(0xb674d000, 5683200)             = 0
close(3)                                = 0
write(2, "error scanning ./meow: ", 23error scanning ./meow: ) = 23
write(2, "scanning timed out\n", 19scanning timed out
)    = 19
munmap(0xb77c4000, 1052672)             = 0
munmap(0xb75c2000, 1052672)             = 0
munmap(0xb73c0000, 1052672)             = 0
munmap(0xb72bf000, 1052672)             = 0
munmap(0xb6fbc000, 1052672)             = 0
munmap(0xb76c3000, 1052672)             = 0
munmap(0xb74c1000, 1052672)             = 0
munmap(0xb71be000, 1052672)             = 0
munmap(0xb6ebb000, 1052672)             = 0
munmap(0xb6dba000, 1052672)             = 0
munmap(0xb70bd000, 1052672)             = 0
munmap(0xb6cb9000, 1052672)             = 0
exit_group(1)                           = ?
+++ exited with 1 +++
plusvic commented 4 years ago

So, scanner->timeout is always the same number 18446744072709551616 regardless of the value you specify in the command line. That's really weird, can you put a printf in this function?

https://github.com/VirusTotal/yara/blob/master/libyara/scanner.c#L291

Print scanner->timeout just after being set in that function.

Also, the values returned by yr_stopwatch_elapsed_ns do not match with the calls to clock_gettime in the trace. yr_stopwatch_elapsed_ns is returning values larger than expected.

Another interesting thing to log would be the values of stopwatch->ts_start.tv_sec, stopwatch->ts_start.tv_nsec, ts_stop.tv_sec and ts_stop.tv_nsec at https://github.com/VirusTotal/yara/blob/master/libyara/stopwatch.c#L98, just before the call to timespecsub

norwayfinland commented 4 years ago

Sorry for the delay, I'm US Central Time. Patched in the printf statements like you requested and have re-compiled. I had to use %lu since the compiler warned they were long int instead of long long int.

$ time /usr/local/bin/yara -w --timeout=32768 ./test.yar ./meow > debug
error scanning ./meow: scanning timed out

real    0m1.744s
user    0m1.720s
sys 0m0.012s

Contents of ./debug

DEBUG yr_scanner_set_timeout set scanner->timeout to 1694498816
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 143538263
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 146455338
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 146481054
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 146505125
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 146530368
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 146553766
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 146575983
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 146598237
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 146622409
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 146653327
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 146684299
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 146722158
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 146748247
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 146773893
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 146805000
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 146839283
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 146881580
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 146917562
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 146939052
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 146963288
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 146996828
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 147022561
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 147059250
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 147108027
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 147142257
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 147230816
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 147346439
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 147457590
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 147573708
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 147689566
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 147801331
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 147917796
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 147971023
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 148058211
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 148075560
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 148098122
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 148120008
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 148141729
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 148163566
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 148184679
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 148209668
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 148232720
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 148262410
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 148282503
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 148302936
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 148324113
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 148357877
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 148380993
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 148404820
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 148425868
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 148447424
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 148468170
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 148489752
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 148509015
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 148528858
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 148547745
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 148569839
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 148589176
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 148616641
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 148638267
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 148660951
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 148681276
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 148701062
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 148721745
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 148756813
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 148778435
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 148800416
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 148825319
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 148845443
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 148890586
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 148921926
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 148953064
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 148995814
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 149019122
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 149047170
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 149070795
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 149093834
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 149118924
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 149142486
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 149163049
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 149215145
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 149235880
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 149255361
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 149273544
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 149294093
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 149314117
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 149333410
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 149354183
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 149375309
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 149397440
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 149426948
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 149449912
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 149478556
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 149498809
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 149518000
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 149536520
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 149557269
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 149580691
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 149601609
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 149622902
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 149643098
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 149662892
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 149682172
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 149702604
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 149723686
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 149744352
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 149769126
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 149788836
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 149808286
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 149827269
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 149846361
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 149865910
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 149884492
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 149903923
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 149925306
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 149965647
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 149986117
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 150005116
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 150025550
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 150045855
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 150065842
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 150085482
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 150109683
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 150128583
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 150147320
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 150166431
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 150186413
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 150206659
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 150227148
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 150227690
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 150264518
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 150283944
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 150304518
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 150325692
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 150349007
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 150373128
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 150396797
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 150419550
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 150455325
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 150479541
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 150502660
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 150526449
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 150546331
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 150653724
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 150718825
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 150791790
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 150875033
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 151080237
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 151227119
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 151350123
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 151412751
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 151469255
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 151706829
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 151749337
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 151802496
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 151825860
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 152129098
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 152552809
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 152828400
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 152909689
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 156841798
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 157018067
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 157133374
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 157198251
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 159099680
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 161331998
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 161391956
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 161448074
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 161499400
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 161547975
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 161599637
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 161641497
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 161681094
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 161717563
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 161752833
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 161786821
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 161818972
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 161869502
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 161898144
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 161925132
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 161950329
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 161974621
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 162086405
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 162416919
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 163452864
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 163527390
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 163632139
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 164023579
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 164117072
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 164140342
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 164162316
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 179899117
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 483684083
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 793
DEBUG ts_stop.tv_nsec has value 987877798
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 794
DEBUG ts_stop.tv_nsec has value 509851396
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 794
DEBUG ts_stop.tv_nsec has value 878328692
DEBUG stopwatch->ts_start.tv_sec has value 793
DEBUG stopwatch->ts_start.tv_nsec has value 143501422
DEBUG ts_stop.tv_sec has value 794
DEBUG ts_stop.tv_nsec has value 878350578
DEBUG ERROR_SCAN_TIME yr_stopwatch_elapsed_ns 1734849156 is greater than scanner->timeout 1694498816
norwayfinland commented 4 years ago

Ooops, same command as above, here is the output with the printf statements before timespecsub as you initially requested. The above is after timespecsub. Sorry, not enough coffee yet :)

$ time /usr/local/bin/yara -w --timeout=32768 ./test.yar ./meow > debug
error scanning ./meow: scanning timed out

real    0m1.799s
user    0m1.693s
sys 0m0.048s

Contents of ./debug

DEBUG yr_scanner_set_timeout set scanner->timeout to 1694498816
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 764355436
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 767669541
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 767697521
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 767721782
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 767747033
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 767770737
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 767792767
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 767814925
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 767839102
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 767869891
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 767900563
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 767938295
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 767964502
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 767970931
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 768051758
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 768109608
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 768153148
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 768192016
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 768213320
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 768237637
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 768271252
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 768297331
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 768320025
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 768363740
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 768397392
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 768485475
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 768610993
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 768722393
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 768857499
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 769005549
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 769155667
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 769296026
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 769375428
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 769406394
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 769429254
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 769462926
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 769493684
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 769522003
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 769569759
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 769598480
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 769630745
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 769659329
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 769690175
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 769715803
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 769741709
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 769768968
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 769819438
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 769849810
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 769887393
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 769913651
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 769939177
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 769964049
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 769989762
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 770013139
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 770037162
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 770153544
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 770182724
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 770202463
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 770223643
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 770245587
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 770268400
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 770288675
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 770312116
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 770339642
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 770396638
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 770426473
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 770455839
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 770488347
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 770533338
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 770576181
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 770613780
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 770671075
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 770707368
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 770731471
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 770753936
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 770777080
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 770800127
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 770828002
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 770858400
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 770886062
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 770960677
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 770987781
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 771013772
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 771037043
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 771062112
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 771087250
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 771111543
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 771159057
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 771180853
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 771202800
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 771228269
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 771271489
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 771299795
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 771325284
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 771350719
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 771375799
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 771410760
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 771428883
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 771481182
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 771508191
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 771533690
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 771559772
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 771585014
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 771627973
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 771655611
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 771682953
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 771712109
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 771743179
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 771773609
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 771802672
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 771831351
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 771862018
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 771900447
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 771932582
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 773544222
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 773580483
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 773612335
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 773644893
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 773673888
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 773702501
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 773730620
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 773758078
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 773807426
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 773835120
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 773861021
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 773886626
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 773913255
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 774127681
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 774170596
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 774197815
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 774221676
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 774247642
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 774272896
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 774317193
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 774347123
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 775574160
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 775606692
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 775660847
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 775691137
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 775721977
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 775751163
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 775799850
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 775826812
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 778481330
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 778582116
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 778703071
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 778804320
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 778968662
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 779171356
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 779332739
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 779414324
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 779488822
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 779833202
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 779889237
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 779952883
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 780067593
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 780605704
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 781101054
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 781328654
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 781417669
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 786350701
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 786561989
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 786681204
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 786965240
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 789141816
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 792709178
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 792738974
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 792765258
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 792788175
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 792813054
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 792836569
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 792859703
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 792884426
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 792908363
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 792932964
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 792957783
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 792998127
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 793023581
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 793048731
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 793073552
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 793095619
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 793117759
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 793282460
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 794635635
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 795912959
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 796072286
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 796227189
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 796347702
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 796582551
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 796613920
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 796642145
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1070
DEBUG ts_stop.tv_nsec has value 820135180
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1071
DEBUG ts_stop.tv_nsec has value 254298486
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1071
DEBUG ts_stop.tv_nsec has value 949974263
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1072
DEBUG ts_stop.tv_nsec has value 550616767
DEBUG stopwatch->ts_start.tv_sec has value 1070
DEBUG stopwatch->ts_start.tv_nsec has value 764331095
DEBUG ts_stop.tv_sec has value 1072
DEBUG ts_stop.tv_nsec has value 550626086
DEBUG ERROR_SCAN_TIME yr_stopwatch_elapsed_ns 1786294991 is greater than scanner->timeout 1694498816
norwayfinland commented 4 years ago

The patches for printf

root@linuxenboxen:~/src/yara-4.0.1# grep "DEBUG" -A5 -B5 libyara/scanner.c
  while (i < block->size)
  {
    if (i % 4096 == 0 && scanner->timeout > 0)
    {
      if (yr_stopwatch_elapsed_ns(&scanner->stopwatch) > scanner->timeout){
        printf("DEBUG ERROR_SCAN_TIME yr_stopwatch_elapsed_ns %llu is greater than scanner->timeout %llu\n",yr_stopwatch_elapsed_ns(&scanner->stopwatch),scanner->timeout);
        return ERROR_SCAN_TIMEOUT;
      }
    }

    if (match_table[state] != 0)
--
YR_API void yr_scanner_set_timeout(
    YR_SCANNER* scanner,
    int timeout)
{
  scanner->timeout = timeout * 1000000000L;  // convert timeout to nanoseconds.
  printf("DEBUG yr_scanner_set_timeout set scanner->timeout to %llu\n", scanner->timeout);
}

YR_API void yr_scanner_set_flags(
    YR_SCANNER* scanner,
root@linuxenboxen:~/src/yara-4.0.1# grep "DEBUG" -A5 -B5 libyara/stopwatch.c 
  struct timespec ts_stop;
  struct timespec ts_elapsed;

  clock_gettime(CLOCK_MONOTONIC, &ts_stop);

  printf("DEBUG stopwatch->ts_start.tv_sec has value %lu\n",stopwatch->ts_start.tv_sec);
  printf("DEBUG stopwatch->ts_start.tv_nsec has value %lu\n",stopwatch->ts_start.tv_nsec);
  printf("DEBUG ts_stop.tv_sec has value %lu\n",ts_stop.tv_sec);
  printf("DEBUG ts_stop.tv_nsec has value %lu\n",ts_stop.tv_nsec);

  timespecsub(&ts_stop, &stopwatch->ts_start, &ts_elapsed);

  return ts_elapsed.tv_sec * 1000000000L + ts_elapsed.tv_nsec;
}
root@linuxenboxen:~/src/yara-4.0.1#
plusvic commented 4 years ago

The values looks correct, and the result from yr_stopwatch_elapsed_ns looks correct too. The scanner->timeout value doesn't make sense, though. Where the 1694498816 is coming from?

This is really really strange. Can you print the value of scanner->timeout at this poing https://github.com/VirusTotal/yara/blob/master/libyara/scanner.c#L421?

norwayfinland commented 4 years ago

You and I are thinking the exact same thing. This is what I had written up just now:

This is odd to me:

DEBUG yr_scanner_set_timeout set scanner->timeout to 1694498816

32768 seconds in nano-seconds should be 32768000000000

1694498816 is significantly less than 32768000000000

To me, as a laymen, it seems that yr_scanner_set_timeout is not properly setting the timeout value. Perhaps 'timeout' is not being passed properly, I am going to debug that now.

norwayfinland commented 4 years ago

Well... it has it correctly, but I am confused.

DEBUG yr_scanner_set_timeout says timeout is 32768
DEBUG yr_scanner_set_timeout set scanner->timeout to 1694498816

I am not sure how 1694498816 can be reflective of 32768 in nanoseconds which is 32768000000000.

I am using %llu for scanner->timeout and %u for timeout.

YR_API void yr_scanner_set_timeout(
    YR_SCANNER* scanner,
    int timeout)
{
  scanner->timeout = timeout * 1000000000L;  // convert timeout to nanoseconds.
  printf("DEBUG yr_scanner_set_timeout says timeout is %u\n", timeout);
  printf("DEBUG yr_scanner_set_timeout set scanner->timeout to %llu\n", scanner->timeout);
}
norwayfinland commented 4 years ago

I believe I have fixed it.

DEBUG yr_scanner_set_timeout says timeout is 32768
DEBUG yr_scanner_set_timeout set scanner->timeout to 32768000000000

At least in that part.

Should this:

scanner->timeout = timeout * 1000000000L;  // convert timeout to nanoseconds.

Actually be this?

  scanner->timeout = timeout * 1000000000ULL;  // convert timeout to nanoseconds.

When I make that adjustment I see that the value is set correctly. However, I do still receive a timeout.

DEBUG yr_scanner_set_timeout says timeout is 32768
DEBUG yr_scanner_set_timeout set scanner->timeout to 32768000000000
DEBUG stopwatch->ts_start.tv_sec has value 2512
DEBUG stopwatch->ts_start.tv_nsec has value 577141355
DEBUG ts_stop.tv_sec has value 2512
DEBUG ts_stop.tv_nsec has value 577162079
DEBUG stopwatch->ts_start.tv_sec has value 2512
DEBUG stopwatch->ts_start.tv_nsec has value 577141355
DEBUG ts_stop.tv_sec has value 2512
DEBUG ts_stop.tv_nsec has value 580172421
...snip...
DEBUG ts_stop.tv_sec has value 2514
DEBUG ts_stop.tv_nsec has value 388248301
DEBUG stopwatch->ts_start.tv_sec has value 2512
DEBUG stopwatch->ts_start.tv_nsec has value 577141355
DEBUG ts_stop.tv_sec has value 2514
DEBUG ts_stop.tv_nsec has value 892903221
DEBUG stopwatch->ts_start.tv_sec has value 2512
DEBUG stopwatch->ts_start.tv_nsec has value 577141355
DEBUG ts_stop.tv_sec has value 2514
DEBUG ts_stop.tv_nsec has value 892942850
DEBUG ERROR_SCAN_TIME yr_stopwatch_elapsed_ns 18446744071730385815 is greater than scanner->timeout 32768000000000

This leads me to believe, based on the now correct value of scanner->timeout that yr_stopwatch_elapsed_ns is unrealistically too large as it is larger than 32,768 seconds but the timeout itself happened in less than 2 seconds. Could this be a math or casting issue similar to what I believe has happened with scanner->timeout?

norwayfinland commented 4 years ago

I believe I have identified and resolved the bug.

In ./libyara/scanner.c:

This:

scanner->timeout = timeout * 1000000000L;  // convert timeout to nanoseconds.

To this:

scanner->timeout = timeout * 1000000000ULL;  // convert timeout to nanoseconds.

In ./libyara/stopwatch.c, all items referencing multiplication for nanosecond conversion using 100[0]+L have been replaced with 100[0]+ULL.

It no longer times out as it did before and does the full runtime.

$ time /usr/local/bin/yara -w --timeout=32768 ./test.yar ./meow > debug

real    0m10.965s
user    0m10.833s
sys 0m0.044s

Here is the debug log:

DEBUG yr_scanner_set_timeout says timeout is 32768
DEBUG yr_scanner_set_timeout set scanner->timeout to 32768000000000
DEBUG stopwatch->ts_start.tv_sec has value 8541
DEBUG stopwatch->ts_start.tv_nsec has value 841378081
DEBUG ts_stop.tv_sec has value 8541
DEBUG ts_stop.tv_nsec has value 841418239
... SNIP ...

DEBUG ts_stop.tv_nsec has value 793435311
DEBUG stopwatch->ts_start.tv_sec has value 8541
DEBUG stopwatch->ts_start.tv_nsec has value 841378081
DEBUG ts_stop.tv_sec has value 8552
DEBUG ts_stop.tv_nsec has value 793452967
Performance_Warning_Timeout ./meow

Here I can have --timeout obey properly, in this case I have set it to 2 seconds and it has properly timed out as it should:

luser@linuxenboxen:~/Downloads$ time /usr/local/bin/yara -w --timeout=2 ./test.yar ./meow > debug
error scanning ./meow: scanning timed out

real    0m2.341s
user    0m2.320s
sys 0m0.016s
luser@linuxenboxen:~/Downloads$

And the debug log from the above correct timeout:

DEBUG yr_scanner_set_timeout says timeout is 2
DEBUG yr_scanner_set_timeout set scanner->timeout to 2000000000
DEBUG stopwatch->ts_start.tv_sec has value 8692
DEBUG stopwatch->ts_start.tv_nsec has value 290859769
...SNIP...
DEBUG stopwatch->ts_start.tv_sec has value 8692
DEBUG stopwatch->ts_start.tv_nsec has value 290859769
DEBUG ts_stop.tv_sec has value 8694
DEBUG ts_stop.tv_nsec has value 621874406
DEBUG ERROR_SCAN_TIME yr_stopwatch_elapsed_ns 2331014637 is greater than scanner->timeout 2000000000

As you can see it now appears that all time values, in nano seconds, are correct with respect to real/user/sys times. 2331014637 is 2.33 seconds and 2000000000 is indeed 2 seconds.

It seems the issue is relating to casting or use of long mixed with unsigned long long for nanosecond handling perhaps leading to an overflow issue due to cast. This results in insanely large values as seen in prior debug logs which in a sense create a situation where YARA will randomly timeout improperly based on file size and/or signature and/or CPU tick.

Same with six seconds, all figures are properly converted to nanoseconds and the timeout happens properly at six seconds:

$ time /usr/local/bin/yara -w --timeout=6 ./test.yar ./meow > debug
error scanning ./meow: scanning timed out

real    0m6.105s
user    0m5.968s
sys 0m0.048s

And from the debug log:

luser@linuxenboxen:~/Downloads$ head -n 5 debug; echo "...snip..."; tail -n 5 debug 
DEBUG yr_scanner_set_timeout says timeout is 6
DEBUG yr_scanner_set_timeout set scanner->timeout to 6000000000
DEBUG stopwatch->ts_start.tv_sec has value 12264
DEBUG stopwatch->ts_start.tv_nsec has value 835969957
DEBUG ts_stop.tv_sec has value 12264
...snip...
DEBUG stopwatch->ts_start.tv_sec has value 12264
DEBUG stopwatch->ts_start.tv_nsec has value 835969957
DEBUG ts_stop.tv_sec has value 12270
DEBUG ts_stop.tv_nsec has value 921320877
DEBUG ERROR_SCAN_TIME yr_stopwatch_elapsed_ns 6085350920 is greater than scanner->timeout 6000000000
luser@linuxenboxen:~/Downloads$

Here are my changes for your consideration:

root@linuxenboxen:~/src/yara-4.0.1/libyara# grep "0ULL" *.c -A5 -B5
scanner.c-
scanner.c-YR_API void yr_scanner_set_timeout(
scanner.c-    YR_SCANNER* scanner,
scanner.c-    int timeout)
scanner.c-{
scanner.c:  scanner->timeout = timeout * 1000000000ULL;  // convert timeout to nanoseconds.
scanner.c-  printf("DEBUG yr_scanner_set_timeout says timeout is %u\n", timeout);
scanner.c-  printf("DEBUG yr_scanner_set_timeout set scanner->timeout to %llu\n", scanner->timeout);
scanner.c-}
scanner.c-
scanner.c-
--
stopwatch.c-{
stopwatch.c-  LARGE_INTEGER li;
stopwatch.c-
stopwatch.c-  QueryPerformanceCounter(&li);
stopwatch.c-
stopwatch.c:  return (li.QuadPart - sw->start.QuadPart) * 1000000000ULL / sw->frequency.QuadPart;
stopwatch.c-}
stopwatch.c-
stopwatch.c-
stopwatch.c-#elif defined(__APPLE__) && defined(__MACH__)
stopwatch.c-
--
stopwatch.c-do {                                                    \
stopwatch.c-  (vsp)->tv_sec = (tsp)->tv_sec - (usp)->tv_sec;        \
stopwatch.c-  (vsp)->tv_nsec = (tsp)->tv_nsec - (usp)->tv_nsec;     \
stopwatch.c-  if ((vsp)->tv_nsec < 0) {                             \
stopwatch.c-    (vsp)->tv_sec--;                                    \
stopwatch.c:    (vsp)->tv_nsec += 1000000000ULL;                    \
stopwatch.c-  }                                                     \
stopwatch.c-} while (0)
stopwatch.c-
stopwatch.c-
stopwatch.c-void yr_stopwatch_start(
--
stopwatch.c-  printf("DEBUG ts_stop.tv_sec has value %lu\n",ts_stop.tv_sec);
stopwatch.c-  printf("DEBUG ts_stop.tv_nsec has value %lu\n",ts_stop.tv_nsec);
stopwatch.c-
stopwatch.c-  timespecsub(&ts_stop, &stopwatch->ts_start, &ts_elapsed);
stopwatch.c-
stopwatch.c:  return ts_elapsed.tv_sec * 1000000000ULL + ts_elapsed.tv_nsec;
stopwatch.c-}
stopwatch.c-
stopwatch.c-
stopwatch.c-#else
stopwatch.c-
--
stopwatch.c-do {                                                    \
stopwatch.c-  (vvp)->tv_sec = (tvp)->tv_sec - (uvp)->tv_sec;        \
stopwatch.c-  (vvp)->tv_usec = (tvp)->tv_usec - (uvp)->tv_usec;     \
stopwatch.c-  if ((vvp)->tv_usec < 0) {                             \
stopwatch.c-    (vvp)->tv_sec--;                                    \
stopwatch.c:    (vvp)->tv_usec += 1000000ULL;                       \
stopwatch.c-  }                                                     \
stopwatch.c-} while (0)
stopwatch.c-
stopwatch.c-
stopwatch.c-void yr_stopwatch_start(
--
stopwatch.c-  struct timeval tv_stop;
stopwatch.c-  struct timeval tv_elapsed;
stopwatch.c-
stopwatch.c-  gettimeofday(&tv_stop, NULL);
stopwatch.c-  timevalsub(&tv_stop, &stopwatch->tv_start, &tv_elapsed);
stopwatch.c:  return tv_elapsed.tv_sec * 1000000000ULL + tv_elapsed.tv_usec * 1000ULL;
stopwatch.c-}
stopwatch.c-
stopwatch.c-#endif

I believe making those adjustments above (minus the debug printf statements) will resolve this issue and the random timeout issue experienced. Those adjustments would be moving from L to ULL during conversion. Thank you and all the best.

plusvic commented 4 years ago

Good catch! Now it makes sense.

In the operation timeout * 1000000000L one operand is int and the other is long, so the compiler treats the result of that multiplication as a long. If long is 32-bits, then we are causing an overflow, and only the lower 32-bits are copied into scanner->timeout.

This only happens with 32-bits compilers of course, in 64-bits compilers long is 64-bits and everything works fine. So, you must be using a 32-bit compiler for this to make sense... and you are! I just noticed the i686 in :

Linux linuxenboxen 4.15.0-101-generic #102-Ubuntu SMP Mon May 11 10:10:03 UTC 2020 i686 i686 i686 GNU/Linux

So everything is explained now.

norwayfinland commented 4 years ago

Great! Sorry I am very much a novice in C so most of my commentary comes from very limited understanding and history. It seems you understand it much better than I for sure. Very happy to help and thank you for all your work you've done with YARA!

I want to say I've had similar on amd64 though but I've been doing all my debugging on i686 32bit. Yes, indeed, this issue exists on amd64/64bit systems as well.

This is a production system with a much faster CPU, the test files are the same as used in my i686 VM. As you can see below the timeout is not honored. I suspect the changes proposed above will resolve this on i686 and amd64 systems.

Thank you again Victor!

root@seiisdtest03# uname -a
Linux seiisdtest03 3.10.0-1062.12.1.el7.x86_64 #1 SMP Thu Dec 12 06:44:49 EST 2019 x86_64 x86_64 x86_64 GNU/Linux
root@seiisdtest03# time yara --timeout=1 -w ./test.yar ./meow
Performance_Warning_Timeout ./meow

real    0m2.268s
user    0m2.209s
sys 0m0.056s
root@seiisdtest03#
plusvic commented 4 years ago

Please try this branch and let me know how it goes: https://github.com/VirusTotal/yara/tree/issue_1299

norwayfinland commented 4 years ago

Pulling now, thanks!

plusvic commented 4 years ago

Ummm, but take into account that timeout measurement is not exact. The program can actually take a bit more time than the specified in the timeout, you should be concerned if you set a 1s timeout and the program takes 10s to complete, but a few seconds off is expected.

norwayfinland commented 4 years ago

Fixed correctly in 32bit systems:

$ time /usr/local/bin/yara -w --timeout=32768 ./test.yar ./meow
Performance_Warning_Timeout ./meow

real    0m11.139s
user    0m11.060s
sys 0m0.064s
luser@linuxenboxen:~/Downloads$ time /usr/local/bin/yara -w --timeout=1 ./test.yar ./meow
error scanning ./meow: scanning timed out

real    0m1.553s
user    0m1.505s
sys 0m0.024s

Also the --timeout=1 not working on amd64 is also now fixed:

Prior:

root@seiisdtest03# uname -a
Linux seiisdtest03 3.10.0-1062.12.1.el7.x86_64 #1 SMP Thu Dec 12 06:44:49 EST 2019 x86_64 x86_64 x86_64 GNU/Linux

root@seiisdtest03# time yara --timeout=1 -w ./test.yar ./meow
Performance_Warning_Timeout ./meow

real    0m2.268s
user    0m2.209s
sys 0m0.056s
root@seiisdtest03#

Using this branch has resolved this:

root@seiisdtest03# time /usr/local/bin/yara -w --timeout=1 ./test.yar ./meow
error scanning ./meow: scanning timed out

real    0m1.089s
user    0m1.059s
sys 0m0.027s
root@seiisdtest03#

Looks like amd64 was equally effected in some way by the overflow issue. Both are now operating correctly with the branch at issue_1299. Nicely done sir!

norwayfinland commented 4 years ago

Well, I tried to debug similar in 64bits but I can't reproduce similar results, I tend to agree now 32bit only issue. Thanks again!

root@seiisdtest03# ./yara --timeout=1 -w /tmp/test.yar /tmp/meow
DEBUG yr_scanner_set_timeout says timeout is 1
DEBUG yr_scanner_set_timeout set scanner->timeout to 1000000000
DEBUG ERROR_SCAN_TIME yr_stopwatch_elapsed_ns 1105356118 is greater than scanner->timeout 1000000000
error scanning /tmp/meow: scanning timed out
root@seiisdtest03#

I hope you have a wonderful weekend

-Nathan Fowler