[WIP] add more debug tracing around idx_init

[Eric Wong <e@80x24.org>]

Konstantin Ryabitsev <konstantin@linuxfoundation.org> wrote:
> On Mon, Jun 10, 2019 at 10:03:20PM +0000, Eric Wong wrote:
> > Maybe PATCH 14/11 fixes it:
> > 
> >  https://public-inbox.org/meta/20190610215811.untkksidetf3erf6@dcvr/
> 
> It didn't, unfortunately.
> 
> > But that won't get you Linux >=3.15 for OFD locks; so Xapian
> > is probably still using the nasty fork()-based lock in older
> > releases.
> > 
> > Maybe this dirty patch can dump more info:
> > ---------8<--------
> > Subject: [WIP] v2writable: support INBOX_DEBUG=replace
> 
> This is what I got right before the "Expected block" error:
> expect_oid: 19af5df050275fb91f4104180e0c86d4b155c23e at /home/mricon/perl5lib//PublicInbox/V2Writable.pm line 534.
> 
> Hope this helps!

It could be hitting something during idx_init.  Either that
or that message has no Message-IDs after editing.

You can probably sprinkle a:

	system("strace -f -o /tmp/strace.out -p $$ &");

Somewhere and get more deep into it w/o tracing mutt.
I use the MAIL_EDITOR env, in tests, but am kinda hesitant to
document/support it forever; but for now, you can use something
like:

  MAIL_EDITOR="perl -i -p -e 's/^Subject:/Foo:/'"

To try non-interactive editing and see if some mutt config
is doing something strange and clobbering Message-IDs, too.

-----8<------
Subject: [WIP] add more debug tracing around idx_init

---
 lib/PublicInbox/V2Writable.pm | 9 +++++++++
 1 file changed, 9 insertions(+)

diff --git a/lib/PublicInbox/V2Writable.pm b/lib/PublicInbox/V2Writable.pm
index 7d6d618..bd156c5 100644
--- a/lib/PublicInbox/V2Writable.pm
+++ b/lib/PublicInbox/V2Writable.pm
@@ -45,6 +45,7 @@ sub count_partitions ($) {
 	my ($self) = @_;
 	my $nparts = 0;
 	my $xpfx = $self->{xpfx};
+	warn 'counting partitions' if DBG_REPLACE;
 
 	# always load existing partitions in case core count changes:
 	# Also, partition count may change while -watch is running
@@ -58,6 +59,7 @@ sub count_partitions ($) {
 			};
 		}
 	}
+	warn "nparts=$nparts" if DBG_REPLACE;
 	$nparts;
 }
 
@@ -255,6 +257,7 @@ sub idx_init {
 	# do not leak read-only FDs to child processes, we only have these
 	# FDs for duplicate detection so they should not be
 	# frequently activated.
+	warn 'cleaning read-only elements' if DBG_REPLACE;
 	delete $ibx->{$_} foreach (qw(git mm search));
 
 	my $indexlevel = $ibx->{indexlevel};
@@ -263,6 +266,7 @@ sub idx_init {
 	}
 
 	if ($self->{parallel}) {
+		warn 'preparing {bnote}' if DBG_REPLACE;
 		pipe(my ($r, $w)) or die "pipe failed: $!";
 		# pipe for barrier notifications doesn't need to be big,
 		# 1031: F_SETPIPE_SZ
@@ -271,10 +275,12 @@ sub idx_init {
 		$w->autoflush(1);
 	}
 
+	warn 'preparing lock' if DBG_REPLACE;
 	my $over = $self->{over};
 	$ibx->umask_prepare;
 	$ibx->with_umask(sub {
 		$self->lock_acquire unless ($opt && $opt->{-skip_lock});
+		warn 'creating ->over' if DBG_REPLACE;
 		$over->create;
 
 		# -compact can change partition count while -watch is idle
@@ -287,10 +293,12 @@ sub idx_init {
 		my $max = $self->{partitions} - 1;
 
 		# idx_parts must be visible to all forked processes
+		warn 'preparing SearchIdxParts' if DBG_REPLACE;
 		my $idx = $self->{idx_parts} = [];
 		for my $i (0..$max) {
 			push @$idx, PublicInbox::SearchIdxPart->new($self, $i);
 		}
+		warn 'SearchIdxParts created' if DBG_REPLACE;
 
 		# Now that all subprocesses are up, we can open the FDs
 		# for SQLite:
@@ -358,6 +366,7 @@ sub content_matches ($$) {
 # used for removing or replacing (purging)
 sub rewrite_internal ($$;$$$) {
 	my ($self, $old_mime, $cmt_msg, $new_mime, $sref) = @_;
+	warn "idx_init" if DBG_REPLACE;
 	$self->idx_init;
 	my ($im, $need_reindex, $replace_map);
 	if ($sref) {
-- 
EW