makehistory can generate duplicate lines

Mon Nov 21 23:18:46 UTC 2022

Hi Kamil,

> 612982:[C1067871BE1F25B369114E7C94635D22]       1643427583~-~1566810112 @03FF31000000000000000000004400000008@
> 612983-[82BFD6304D1012333F22C559B8AF46A3]       1643427583~-~1566810146 @03FF31000000000000000000009100000007@
> 612984-[B2EAA6504DB45DC7F33C214880D99A50]       1643427583~-~1566810185 @03FF31000000000000000000009200000007@
> --
> 1242667-[4F893D038B278138E8AFB8E1C899BFFA]      1643431380~-~1595582940 @03FF3100000000000000001FFFF400000007@
> 1242668-[B22F99E507F22F30250D4A2D28742A19]      1643431380~-~1595582974 @03FF3100000000000000001FFFFD00000007@
> 1242669:[C1067871BE1F25B369114E7C94635D22]      1643427583~-~1566810112 @03FF31000000000000000000004400000008@
> 1242670:[6282400F8A293D047E9052468792AF18]      1643431380~-~1595583001 @03FF32000000000000000000004400000008@
> 1242671-[A0615E54374BB1263836C289CAB75EF9]      1643431380~-~1595583061 @03FF32000000000000000000004600000007@
> 1242672-[C07606242B08C0D7FC987945FE0CECA1]      1643431380~-~1595583073 @03FF32000000000000000000004700000007@

The last number in the token is the cycle number.  I note that the 1st article written has 1 cycle more than the others (though arrived before).  I would have thought it would have been "@03FF31000000000000000000004400000007@" but it ended with "08@"; that's surprising...  I'll speak about that at the end of this message.



> 2314183-[BC90903F831BFB1DE8CA39C98F8ED2C9]      1653058806~-~1653058751 @03FF3300000000000000001FFFF600000007@
> 2314184-[A505379E708A59F16DAA62541CCFDB67]      1653058866~-~1653058823 @03FF3300000000000000001FFFFE00000007@
> 2314185:[65B607B90549808E3D4A4E3E33DD6D4A]      1643433853~-~1623959630 @03FF33000000000000000000004400000008@
> 2314186-[1AA051033A3D96E8E79F6F42C2159419]      1643409332~-~1454972341 @03FF3400000000000000000EE11400000006@
> 2314187-[8FCA5D33F8688E4E75445850D7CCE398]      1643409332~-~1454972378 @03FF3400000000000000000EE11600000006@
> --
> 2921682-[8735D546AC02468CEC974116E2291BBA]      1669003873~-~1669003801 @03FF3400000000000000000EE10E00000007@
> 2921683-[4A8E1E3096F262C460C7963971964912]      1669004073~-~1669003319 @03FF3400000000000000000EE11000000007@
> 2921684:[E55B9C6F2E865C431F4466F1085D7596]      1643412102~-~1465897595 @03FF35000000000000000000004400000007@
> 2921685-[00F1642A04FEAA3F23269EAF258BDC4A]      1643412102~-~1465897596 @03FF35000000000000000000004800000006@
> 2921686-[9025840433BA049A341F2D7BF71F44AE]      1643412102~-~1465897596 @03FF35000000000000000000004A00000006@

Interesting.  When read in order, the 4th buffer begins at offset 0EE114 of cycle number 6, until the end, and then rewraps at its first article (probably offset 44 of cycle number 7) until the end at offset 0EE110 of cycle 7.
That's exactly the logics I found in the cnfs_next() function.

I believe the following patch would fix the issue.  (I don't know if you can try patches - it seems like you're running the package Debian distribution.)

--- a/storage/cnfs/cnfs.c
+++ b/storage/cnfs/cnfs.c
@@ -1804,6 +1804,14 @@ cnfs_next(ARTHANDLE *article, const RETRTYPE amount)
              if (middle >= cycbuff->len - cycbuff->blksz - 1) {
                  priv.rollover = true;
                  middle = cycbuff->minartoffset;
+                /* If the beginning of cycbuff is the next place where to write
+                 * an article, then the cycbuff has fully wrapped, and the
+                 * first article has already been walked through. */
+                if (middle == cycbuff->free) {
+                    if (!SMpreopen)
+                        CNFSshutdowncycbuff(cycbuff);
+                    continue;
+                }
              }
              break;
          } else {




I've rebuilt earlier today my own overview and saw the very problem you have:

makehistory: cannot write overview data "@030346523100000000000000002400000002@"


% sm -H '@030346523100000000000000002400000002@' | grep Message-ID
Message-ID: <61530a91$0$28586$426a74cc at news.free.fr>


% grephistory '<61530a91$0$28586$426a74cc at news.free.fr>'
grephistory: not found


% grep '@030346523100000000000000002400000002@' history
zsh: exit 1


This message is in my spool and overview (after rebuild) but not in my history file, like you.

Within an NNTP session:

ARTICLE <61530a91$0$28586$426a74cc at news.free.fr>
430 No such article

GROUP fr.soc.environnement
211 84759 219 153862 fr.soc.environnement

HDR Message-ID 142428
225 Header or metadata information for Message-ID follows (from overview)
142428 <61530a91$0$28586$426a74cc at news.free.fr>




Applying the above patch and rebuilding my overview did not show the error.
The above article is correctly present in my overview (I've checked).



> So I think problem is with "makehistory" when comes to "fully rotated"
> cycbuff.

Yes, I think that's now fixed.

What remains to understand is why and when the token disappeared from the history file.  It could be normal if it was cancelled... but I do not know how to find whether there had been a cancel or NoCeM notice for that article (I expire control.cancel after a month).
I think the next run of expireover will remove it from the overview as there's no history entry for it (I'll confirm tomorrow).

You had 7 such missing 1st articles from your history, so it would rather be a bug...  Notably when all 2nd, 3rd, etc. are present!
I am under the impression the real article had token "@03FF31000000000000000000004400000007@" and disappeared from the history when being known as "@03FF31000000000000000000004400000008@" after a wrap (just a thought).

It would mean that you currently have "@03FF34000000000000000000004400000007@" in your 4th buffer, in first position.  And when the buffer wraps, the token will disappear from your history file, and the article will be thought to be "@03FF34000000000000000000004400000008@".
I believe to have found the culprit.  When the history file is expired, it checks whether the storage token is retrievable.  And the cnfs_retrieve() function returns false for the first article of a cycbuff that has just rewrapped...  So the article is removed from the history :-(

Here is a patch that works:

--- a/storage/cnfs/cnfs.c
+++ b/storage/cnfs/cnfs.c
@@ -1138,7 +1138,7 @@ CNFSArtMayBeHere(CYCBUFF *cycbuff, off_t offset, uint32_t cycnum)
      ** avoid a false negative response, *not* a false positive response.
      */
      if (!(cycnum == cycbuff->cyclenum
-          || (cycnum == cycbuff->cyclenum - 1 && offset > cycbuff->free)
+          || (cycnum == cycbuff->cyclenum - 1 && offset >= cycbuff->free)
            || (cycnum + 1 == 0 && cycbuff->cyclenum == 2
                && offset > cycbuff->free))) {
          /* We've been overwritten */



With that patch, my Storage Manager (sm) sees both "@030346523100000000000000002400000001@" and "@030346523100000000000000002400000002@".
Whereas only "02@" was previously *wrongly* seen; "01@" should still have.
Hmm, the article can be retrievable with several different tokens but in fact it was already possible for all the articles.
The second article in the buffer was already retrievable with both "@030346523100000000000000002600000001@" and "@030346523100000000000000002600000002@".



So, don't we have fixed 2 CNFS bugs thanks to your message about makehistory? :-)
Thanks, Kamil!

-- 
Julien ÉLIE

« Qui habet aures audiendi, audiat. » (Évangiles)
