1762161 - Many warnings: "WARNING: Malformed header (expected 'name: value')" in debug build.

Status: RESOLVED FIXED

(Thunderbird :: General, defect)

Description

[ISHIKAWA, Chiaki]

In the last several days, I noticed many forms of warning during test of debug version of the form:

 4:04.07 GECKO(10206) [Parent 10206, Main Thread] WARNING: Malformed header (expected 'name: value'): file /NEW-SSD/moz-obj-dir/objdir-tb3/dist/include/HeaderReader.h:264

The warning are visible in other people's debug version tests on try-com-central.

See, for example, Geoff's job:
https://treeherder.mozilla.org/jobs?repo=try-comm-central&selectedTaskRun=CFiSiwt3Tbao5Pzmc6ujZg.0&revision=0c1e010093278608ba5fec2f6e0eee879ce6ccb0

bct1, live.log
https://firefoxci.taskcluster-artifacts.net/CFiSiwt3Tbao5Pzmc6ujZg/0/public/logs/live_backing.log

The lines are so many and easily noticeable. About a week ago, it appeared 503 times during local mochitest, and 326 times during xpcshell test.
I am running xpcshell tests with "--serialize --verbose" switches to capture these warning and error messages.

ishikawa@ip030:/NREF-COMM-CENTRAL/mozilla$ grep "Malformed header" /FF-NEW/log1392-mochitest-12.txt | wc
    503    7042   86406
ishikawa@ip030:/NREF-COMM-CENTRAL/mozilla$ grep "Malformed header" /FF-NEW/log1393-xpctest-12.txt | wc
    326    4564   55094
ishikawa@ip030:/NREF-COMM-CENTRAL/mozilla$ 

I got worried since I am testing bufferred-write and other I/O related patches locally and I thought I broke TB, but it turns out TB without my patches showed the same behavior as I explained at the beginning of my post. Other people's debug builds spew out same warnings.

I got curious and modified HeaderReader.h as follows and tried to capture the
unrecognized lines.

diff --git a/mailnews/base/src/HeaderReader.h b/mailnews/base/src/HeaderReader.h
--- a/mailnews/base/src/HeaderReader.h
+++ b/mailnews/base/src/HeaderReader.h
@@ -257,16 +257,32 @@ bool HeaderReader::HandleLine(mozilla::S
     mHdr = Hdr();
   }
 
   auto colon = std::find(line.cbegin(), line.cend(), ':');
   if (colon == line.cend()) {
     // UHOH. We were expecting a "name: value" line, but didn't find one.
     // Just ignore this line.
     NS_WARNING("Malformed header (expected 'name: value')");
+#ifdef DEBUG
+    {
+      auto start = line.cbegin();
+      fflush(stdout);
+      printf("{debug} line-> '");
+
+      // I am lazy to find out more about std span data type and its
+      // associated operation.
+      long unsigned i = 1;
+      for (; i <= line.Length() && start < line.cend() && *start != '\0'; start++, i++)  {
+        printf("%c", *start);
+      }
+      printf("'\n");
+    }
+#endif
+
     mPos += line.Length();
     return keepGoing;
   }
   auto val = colon + 1;
   if (*val == ' ' || *val == '\t') {
     // Skip single leading whitespace.
     ++val;
   }

The result is revealing.
The following is the first such output lines from a modified xpcshell test run.

 0:06.21 pid:201682 [Parent 201682, Main Thread] WARNING: Malformed header (expected 'name: value'): file /NEW-SSD/moz-obj-dir/objdir-tb3/dist/include/HeaderReader.h:264
 0:06.21 pid:201682 {debug} line-> 'From [e-mail]
 0:06.22 pid:201682 '
 0:06.22 pid:201682 [Parent 201682, Main Thread] WARNING: Malformed header (expected 'name: value'): file /NEW-SSD/moz-obj-dir/objdir-tb3/dist/include/HeaderReader.h:264
 0:06.22 pid:201682 {debug} line-> 'From [e-mail]
 0:06.22 pid:201682 '
 0:06.22 pid:201682 [Parent 201682, Main Thread] WARNING: Malformed header (expected 'name: value'): file /NEW-SSD/moz-obj-dir/objdir-tb3/dist/include/HeaderReader.h:264
 0:06.22 pid:201682 {debug} line-> 'From [e-mail]
 0:06.22 pid:201682 '
 0:06.22 pid:201682 [Parent 201682, Main Thread] WARNING: Malformed header (expected 'name: value'): file /NEW-SSD/moz-obj-dir/objdir-tb3/dist/include/HeaderReader.h:264
 0:06.22 pid:201682 {debug} line-> 'From [e-mail]
 0:06.22 pid:201682 '

It seems that the code does not handle the mbox-format well.
Each message block in mbox-format file starts with the first line of the following form.

From sender-email-address

That is, it contains NO COLON at all.

Here is the start of a real-world mbox file.

From [e-mail] Tue Nov 12 00:35:17 2013
Return-path: <[e-mail]>
Envelope-to: [e-mail]
Delivery-date: Tue, 12 Nov 2013 00:35:17 +0900
Received: from root by vm-debian-amd64.example.com with local (Exim 4.80)
	(envelope-from <[e-mail]>)
	id 1VftWH-0006rx-Jp
	for [e-mail]; Tue, 12 Nov 2013 00:35:17 +0900
MIME-Version: 1.0
Content-Type: text/plain; charset="utf-8"
Content-Transfer-Encoding: 7bit
Auto-Submitted: auto-generated
Subject: apt-listchanges: news for vm-debian-amd64
To: [e-mail]
Message-Id: <[e-mail]>
From: root <[e-mail]>
Date: Tue, 12 Nov 2013 00:35:17 +0900
Status: RO

libhtml-tree-perl (5.03-1) unstable; urgency=low

[rest omitted]

(I unwisely used example.com for internal home LAN domain back then. Subsequently I changed the name.)

We should properly recognize these lines that start messages in an mbox file.
I have no idea whether the failure to do so resulted in other unwanted warnings/errors.

The code seems to have been modified lately in bug 1756520.

Comment 1

[ISHIKAWA, Chiaki]

Wait, my mbox message block starts with

From　e-mail-address  DATE&TIME

Date&time part actually contains ":". Hmm...

Comment 2

[ISHIKAWA, Chiaki]

So maybe we should handle "From e-mail-address some-stuff-that-follows" at the beginning of message block in mbox file as a special case. (It appears at the beginning of each message: it is a starting line for a new message.)

Comment 3

[Ben Campbell]

Ahh yes - I should tidy this up!

Ultimately, nobody should ever see those mbox "From " lines except mbox-specific code. But for now they are produced/consumed/expected all over the place. So we're in an odd spot where we need to be tolerant of "From " lines.

The HeaderReader currently copes with "From " lines by just ignoring it as a malformed header - but that spits out that alarming warning! So I should special-case it for now.
(I think the HeaderReader is currently only used to in-place editing of X-Mozilla-* headers when message flags and keywords change, but I'm using on folder compaction next)

Comment 4

[Ben Campbell]

Attachment: Bug 1762161 - Allow for mbox "From " lines in nsMsgLocalStoreUtils X-Mozilla-* header manipulations. r=mkmelin

Previously, the utility functions in nsMsgLocalStoreUtils.cpp would just let the HeaderReader class deal with "From " lines.
It would handle them by ignoring them as malformed headers. This worked fine, but spat out an ugly warning message.
This patch checks for and skips such "From " lines before attempting to parse the headers.

Comment 5

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/comm-central/rev/8d807385d14e
Allow for mbox "From " lines in nsMsgLocalStoreUtils X-Mozilla-* header manipulations. r=mkmelin