Subject: [alpine-devel] Attempting to debug C++ library and command via valgrind

From: Isaac Dunham <[email-masked]>
Date: Tue, 8 Jul 2014 21:39:47 -0700

Hello,
I've been trying to get Sword 1.7.3 (crosswire.org/sword) running on Alpine.
Sword is a library for free bible software that comes with a few utilities.
It builds fine and runs with few issues, but I'm having a bit of trouble figuring out one of the bugs:
valgrind was recommended, but I can't get valgrind to run the command properly.
I was asked to provide the output of roughly this command (adjusting for
Windows/*nix differences):
valgrind --leak-check=full --track-origins=yes \
  --keep-stacktraces=alloc-and-free \
  utilities/diatheke/.libs/diatheke  -b KJV -k Ps117

But when I do this, diatheke errors out:
-----
$ valgrind --leak-check=full --track-origins=yes --keep-stacktraces=all
oc-and-free diatheke  -b KJV -k Ps117
==5743== Memcheck, a memory error detector
==5743== Copyright (C) 2002-2013, and GNU GPL'd, by Julian Seward et al.
==5743== Using Valgrind-3.9.0 and LibVEX; rerun with -h for copyright info
==5743== Command: diatheke -b KJV -k Ps117
==5743== 
diatheke: cannot load -b: No such file or directory
==5743== 
==5743== HEAP SUMMARY:
==5743==     in use at exit: 0 bytes in 0 blocks
==5743==   total heap usage: 0 allocs, 0 frees, 0 bytes allocated
==5743== 
==5743== All heap blocks were freed -- no leaks are possible
==5743== 
==5743== For counts of detected and suppressed errors, rerun with: -v
==5743== ERROR SUMMARY: 0 errors from 0 contexts (suppressed: 0 from 0)
-----
Comparing this to the default output below, my guess is that the command line parsing is not happening when run from valgind.

The bug I'm trying to track down (background):
diatheke is a utility that comes with Sword that shows all verses or passages in a bible or book that match a key (such as a reference);
the basic command line looks like this:
diatheke -b book -k reference

The bug is that the last passage/verse gets repeated:
$ diatheke  -b KJV -k Ps117
Psalms 117:1: O praise the LORD, all ye nations: praise him, all ye people.
Psalms 117:2: For his merciful kindness is great toward us: and the truth of the LORD endureth for ever. Praise ye the LORD. 
: For his merciful kindness is great toward us: and the truth of the LORD endureth for ever. Praise ye the LORD. 
(KJV)

Currently running Alpine edge with linux-vanilla as kernel.
All binaries are built using abuild; the system CFLAGS were "-Os -pipe -fomit-frame-pointer", but the package adds "-O3".
I got the same results after changing CFLAGS in abuild.comf to "-g -pipe".

If the build scripts are desired, I can supply them.

Thanks,
Isaac Dunham

---
Unsubscribe:  [email-masked]
Help:         [email-masked]
---

---

From: John Spencer <[email-masked]>
Date: Fri, 11 Jul 2014 14:19:46 +0200

> I've been trying to get Sword 1.7.3 (crosswire.org/sword) running on Alpine.

sword seems to have a lot of issues...

the problems starts with lack of a pre-generated configure script.
this forces the user to have the complete fragile autoconf stack installed.

even running autogen.sh fails, because it uses AM_CONFIG_HEADER instead 
of AC_CONFIG_HEADER (the former is long obsolete and causes an error):

configure.ac:16: error: possibly undefined macro: AM_CONFIG_HEADER

patch:

--- configure.ac
+++ configure.ac.patched
@@ -13,7 +13,7 @@
  AC_CANONICAL_TARGET
  AM_INIT_AUTOMAKE

-AM_CONFIG_HEADER(include/config.h)
+AC_CONFIG_HEADER(include/config.h)

  AC_CONFIG_MACRO_DIR([m4])

with that fixed, compilation itself succeeds, however starting the 
diatheke program yields - nothing, not even an error message.

one thing i noticed is that it tries to dlopen any library it wants to 
use rather than linking it directly. if the binary doesn't find for 
example libsword.so, it prints no error and justs quits silently.

after putting the .so's where the binary searches for them, it iterates 
over a gazillion of files in /share/sword/locales.d/ like 
zh_CN-utf8.conf and reserves memory for them - apparently it caches them 
all even if they're not used...

then it justs quits without even trying to load the KJV file... (my 
guess is that it didn't find some .so it depends on and then stops 
somewhere where it would require the external lib functionality but has 
only a nullpointer).

so unfortunately due to above issues, i've not been able to reproduce 
your problem.

--JS

---

---

From: Isaac Dunham <[email-masked]>
Date: Fri, 11 Jul 2014 20:11:15 -0700

> this forces the user to have the complete fragile autoconf stack installed.

Ah, you're building from the VCS not tarballs.
I was building from this tarball:
http://www.crosswire.org/ftpmirror/pub/sword/source/v1.7/sword-1.7.3.tar.gz
which was released within the last month.

I know you're not building from the tarball, since...
$ tar tzf sword-1.7.3.tar.gz |grep configure
sword-1.7.3/bindings/swig/package/configure.ac
sword-1.7.3/bindings/swig/package/configure
sword-1.7.3/cmake/configure-iphone.sh
sword-1.7.3/cmake/configure-iphone-simulator.sh
sword-1.7.3/configure
sword-1.7.3/configure.ac

The documentation indicates that CMake is supported as well as autoconf.

But anyhow, someone on the sword-devel list sent me a patch which fixed
diatheke in their tests; it's a matter of brace placement.
I want to check for myself, though.

(IE: replicating and fixing is not needed.)
     ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^

But if you do want to go ahead:
In the build department, it may need one of --with-cxx11regex,
--with-internal-regex, or clucene; I haven't checked if POSIX regexes
get autodetected, and the configure help does not document use of
libc regexes. clucene presence is autodetected.
ICU is also usually used; there are references to optional use of "sword-icu",
but standard icu works well.
(I'm not sure how well it works, but building without icu is also possible.)
Most users will end up wanting curl support.
(in short: default config depends on clucene, curl, icu; all of those
could be pared away, but don't count on things working the same.)

> then it justs quits without even trying to load the KJV file... (my guess is
> that it didn't find some .so it depends on and then stops somewhere where it
> would require the external lib functionality but has only a nullpointer).

as far as the KJV part, if you still want to try:
mkdir ~/.sword && printf '[INSTALL]\nDataPath=%s/.sword\n' "$HOME" \
 >~/.sword/sword.conf && \
 echo yes | installmgr -rc && \
 echo yes | installmgr -r  CrossWire && \
 echo yes | installmgr -ri CrossWire KJV

(The above will only work if you build with curl.)

Thanks,
Isaac Dunham

---

---

From: Jeff Pohlmeyer <[email-masked]>
Date: Wed, 9 Jul 2014 10:30:11 -0500

> diatheke: cannot load -b: No such file or directory

I think it's a problem with the way valgrind tries to run musl's program loader.

Try adding "/lib/ld-musl-i386.so.1" to the command line, just before
the prgram name,
e.g.

  /lib/ld-musl-i386.so.1 \
   diatheke  -b KJV -k Ps117

 - Jeff

---

---

From: Jeff Pohlmeyer <[email-masked]>
Date: Wed, 9 Jul 2014 10:46:36 -0500

On Wed, Jul 9, 2014 at 10:30 AM, Jeff Pohlmeyer wrote:

> Try adding "/lib/ld-musl-i386.so.1" to the command line

Or that should be "/lib/libc.musl-x86_64.so.1" for 64-bit.

( Looks like gmail's auto-quoting probably messed up my example anyway. )

 - Jeff

---

---

From: Isaac Dunham <[email-masked]>
Date: Wed, 9 Jul 2014 21:13:49 -0700

>  --keep-stacktraces=alloc-and-free \

Thanks, this works for me.

Of course it really runs slow and spits out a ton of information;
the log is over 400 kb at 5464 lines. (I suppose sending it to these lists
might be inappropriate, given the size...)

Thank you,
Isaac Dunham

---

---

From: Rich Felker <[email-masked]>
Date: Thu, 10 Jul 2014 00:47:16 -0400

> might be inappropriate, given the size...)

If you have a reasonable place to dump the file you could just send a
link to the list. But I think you're getting ahead of things. What
actual failure is the program exhibiting? (Crash? Incorrect or no
output? Error messages?) Depending on what happens, a gdb backtrace or
an strace log may be more useful than the valgrind output.

Rich

---

---

From: Isaac Dunham <[email-masked]>
Date: Wed, 9 Jul 2014 23:50:08 -0700

> an strace log may be more useful than the valgrind output.
Incorrect output: specifically, it repeats (most of) the last line of the
intended output.
strace was my first resort, but it did not seem helpful to me;
since the program in question is using a large C++ library to access a
compressed text with a good deal of processing in memory, I could not
figure out how the syscalls mapped to code.
When I asked on the sword-devel list, valgrind was recommended.

The output compresses down to ~4k when bzipped, so I guess it
isn't a big issue.

Now I looked at strace again; here's what I found:
-100k lines of output, compressing to 500 kb (!).
-the relevant bit is likely this:

open("/home/idunham/.sword/modules/texts/ztext/kjv/ot.bzz", O_RDWR|O_LARGEFILE) = 5
_llseek(5, 0, [0], SEEK_SET)            = 0
_llseek(5, 1261942, [1261942], SEEK_SET) = 0
mmap2(NULL, 180224, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb57d5000
read(5, "x\234\354\275\353\222\343F\222&\372*\30\375\3325\253\321\20w\240\324S2iz\325\225\323\322hl"..., 177216) = 177216
mmap2(NULL, 180224, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb57a9000
mmap2(NULL, 3547136, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb5447000
mmap2(NULL, 1024000, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb534d000
munmap(0xb5447000, 3547136)             = 0
mmap2(NULL, 1024000, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb56af000
munmap(0xb57d5000, 180224)              = 0
ioctl(1, SNDCTL_TMR_TIMEBASE or SNDRV_TIMER_IOCTL_NEXT_DEVICE or TCGETS, 0xbfc21fa4) = -1 ENOTTY (Not a tty)
writev(1, [{"Psalms 117:1: O praise the LORD,"..., 75}, {"\n", 1}], 2Psalms 117:1: O praise the LORD, all ye nations: praise him, all ye people.
) = 76
_llseek(3, 164840, [164840], SEEK_SET)  = 0
read(3, "\23\0\0\0", 4)                 = 4
read(3, "\207\204\f\0", 4)              = 4
read(3, "\34\1", 2)                     = 2
_llseek(3, 164850, [164850], SEEK_SET)  = 0
read(3, "\23\0\0\0", 4)                 = 4
read(3, "\243\205\f\0", 4)              = 4
read(3, "'\2", 2)                       = 2
_llseek(3, 164850, [164850], SEEK_SET)  = 0
read(3, "\23\0\0\0", 4)                 = 4
read(3, "\243\205\f\0", 4)              = 4
read(3, "'\2", 2)                       = 2
_llseek(3, 164850, [164850], SEEK_SET)  = 0
read(3, "\23\0\0\0", 4)                 = 4
read(3, "\243\205\f\0", 4)              = 4
read(3, "'\2", 2)                       = 2
munmap(0xb56af000, 1024000)             = 0
munmap(0xb57a9000, 180224)              = 0
munmap(0xb534d000, 1024000)             = 0
close(4)                                = 0
close(5)                                = 0
close(3)                                = 0
writev(1, [{"Psalms 117:2: For his merciful k"..., 246}, {NULL, 0}], 2Psalms 117:2: For his merciful kindness is great toward us: and the truth of the LORD endureth for ever. Praise ye the LORD. 
: For his merciful kindness is great toward us: and the truth of the LORD endureth for ever. Praise ye the LORD. 
(KJV)
) = 246

Which looks like it's going through a loop twice when it reaches the exit condition.

Thanks,
Isaac Dunham

---

From: Rich Felker <[email-masked]>
Date: Thu, 10 Jul 2014 23:39:34 -0400

> Which looks like it's going through a loop twice when it reaches the exit condition.

The fact that it's using writev suggests strongly that the output is
being written via musl's stdio (to stdout, since it's fd #1) rather
than via some other mechanism, but it could be C++ iostreams using
stdio as their backend. It's hard to say whether this is due to
corruption of the FILE state or the actual calling code writing the
output twice. When I get a chance I can look over your valgrind output
a bit but FYI the way I would go about debugging this is putting a
breakpoint in __stdout_write conditional on f->fd==1 and looking at
the backtrace for how it's reached.

Rich

---

---

From: Isaac Dunham <[email-masked]>
Date: Fri, 11 Jul 2014 21:03:40 -0700

Hello,
Just so everyone knows, someone on the sword-devel list (the person who
asked me for valgrind output) found and fixed the bug.
Rich, thanks for mentioning strace; that ended up being the key.

> > On Thu, Jul 10, 2014 at 12:47:16AM -0400, Rich Felker wrote:
<snip> 
> > > But I think you're getting ahead of things. What
> output twice.
It turned out to be the calling code reading the last verse twice;
the closing curly braces were misplaced.

Thanks,
Isaac Dunham

---

---

From: Rich Felker <[email-masked]>
Date: Sat, 12 Jul 2014 00:09:31 -0400

> Rich, thanks for mentioning strace; that ended up being the key.

What did it end up being? Partly just curious, but I also figure it
might be useful to know if this was some sort of UB from the
application that corrupted stdio state (in which case it's a symptom
we might see again) or whether it was just an application logic bug
(writing the same thing twice).

Rich

---