Subject: Re: Areas interaction causes nncp-toss to always exit with error

From: John Goerzen <[email-masked]>
Date: Sat, 30 Oct 2021 10:15:42 -0500

Hi Sergey,

So I'm doing some more tracking down on this issue with nncp-toss
existing with an error and never advancing certain packets on to their
destination.  Reading through the docs and looking at things, here's
what I see.  First, the debug output:

When: 2021-10-30T14:44:28.314507042Z
Debug: true
Who: rx-area-echo-seen
Node: JGCHEG...
Pkt: DCLGLYKIJNHKMAWO4CBUEXRB2PEFXMHUR2WMVDRAC5O4TY3NQUXA
Nice: 96
Size: 2107
Type: area
Area: RVF...
AreaMsg: 6MBM3SG6LI7V5DMXOXCYP2WAHR66LTSEPWYTDVXNYE43TQ5WUF6Q
Echo: L3W...
Msg: Tossing self/DCLGLYKIJNHKMAWO4CBUEXRB2PEFXMHUR2WMVDRAC5O4TY3NQUXA (2.1 KiB): area localgit: echo to: alexandria: already sent

There is this file:

./JGCHEG.../tx/DCLGLYKIJNHKMAWO4CBUEXRB2PEFXMHUR2WMVDRAC5O4TY3NQUXA

JGCHEG... is self.

There is also:

./L3W.../area/RVF.../6MBM3SG6LI7V5DMXOXCYP2WAHR66LTSEPWYTDVXNYE43TQ5WUF6Q

L3W... is the destination alexandria that it says it's already been sent
to.  This is the one and only destination listed in the local
configuration for this area (that destination is a fan-out relay of
sorts that then distributes it to many other nodes).

There is NOT any hash for this item in self/area/AREA/MsgHash.  So
somehow it knows that it has sent it, but doesn't know that it has
processed it, and is never deleting it in the end.

So looking at toss.go, it is "already sent" but NOT "already seen".
Interesting.

In toss.go, I notice that if the rx-area-echo-seen is logged -- which it
is here (that's what logs the "already sent"), it runs "continue"
instead of "return JobRepeatProcess" which is what it would have done
had it created the "already sent" seenPath just now.  I don't know what
implication that has.

I can't figure out why the main "already seen" file in
self/area/AREA/MsgHash is never being created.  It could be that jobPath
== "", or that there was some other error above, but no other error is
ever logged.

Any ideas?

John

On Fri, Sep 24 2021, John Goerzen wrote:

> Hi,
>
> When using areas, I'm seeing something odd from nncp-toss.  It sometimes runs
> and always exits with an error.  -progress won't show anything, but -debug
> does:
>
> See below.
>
> JGCHEG... is the local node.  It'll do the same thing, over and over.
>
> If I rm the F2SYU.. and R2RCYM... packets, then all is fine.
>
> I've seen this happen on two different machines now, with the same symptom -
> including the "already sent".  The node alexandria is, on the effected
> machines, the only one in the subs list.  (subs on alexandria itself is
> longer; it does the distribution.)  It seems to somehow not be able to process
> that it's done with a packet and remove it... but only sometimes.
>
> Output below.  This exists on 7.7.0 as well.
>
> Thanks,
>
> John
>
> nncp-toss -debug
>
> When: 2021-09-09T02:20:30.042517609Z
> Debug: true
> Who: job
> XX: tx
> Node: JGCHEG...
> Name: F2SYUAB7ZWERF26Z6XWNDFOTZ2HUAHUP3XIU76DHA5JW4OBUH7YQ
> Nice: 96
> Size: 2645
> Msg: Job JGCHEG.../tx/F2SYUAB7ZWERF26Z6XWNDFOTZ2HUAHUP3XIU76DHA5JW4OBUH7YQ
> nice: P size: 2.6 KiB
>
> When: 2021-09-09T02:20:30.042805913Z
> Debug: true
> Who: job
> XX: tx
> Node: JGCHEG...
> Name: R2RCYMTJVRQONI2PLNS3FJ7ELTY4S47ZNDLEFT27QCYYHLM3PYBQ
> Nice: 96
> Size: 2544
> Msg: Job JGCHEG.../tx/R2RCYMTJVRQONI2PLNS3FJ7ELTY4S47ZNDLEFT27QCYYHLM3PYBQ
> nice: P size: 2.5 KiB
>
> When: 2021-09-09T02:20:30.044474556Z
> Debug: true
> Who: rx
> Node: JGCHEG...
> Pkt: F2SYUAB7ZWERF26Z6XWNDFOTZ2HUAHUP3XIU76DHA5JW4OBUH7YQ
> Nice: 96
> Size: 2157
> Msg: Tossing self/F2SYUAB7ZWERF26Z6XWNDFOTZ2HUAHUP3XIU76DHA5JW4OBUH7YQ (2.1
> KiB)
>
> When: 2021-09-09T02:20:30.04469246Z
> Debug: true
> Who: rx-area
> Node: JGCHEG...
> Pkt: F2SYUAB7ZWERF26Z6XWNDFOTZ2HUAHUP3XIU76DHA5JW4OBUH7YQ
> Nice: 96
> Size: 2157
> Type: area
> Area: RVFWL...
> AreaMsg: L3NQRYHGBDQLJPKRI5P7E2BQUJLFCIOTBGBWTXD5HGEEFGL7SEGA
> Msg: Tossing self/F2SYUAB7ZWERF26Z6XWNDFOTZ2HUAHUP3XIU76DHA5JW4OBUH7YQ (2.1
> KiB): area localgit
>
> When: 2021-09-09T02:20:30.04483773Z
> Debug: true
> Who: rx-area-echo-seen
> Node: JGCHEG...
> Pkt: F2SYUAB7ZWERF26Z6XWNDFOTZ2HUAHUP3XIU76DHA5JW4OBUH7YQ
> Nice: 96
> Size: 2157
> Type: area
> Area: RVFWL...
> AreaMsg: L3NQRYHGBDQLJPKRI5P7E2BQUJLFCIOTBGBWTXD5HGEEFGL7SEGA
> Echo: L3WOIONS7NFQN53SIDHT3VMJ7HELW3WLBRYTO7MEAH4OMC36JLHQ
> Msg: Tossing self/F2SYUAB7ZWERF26Z6XWNDFOTZ2HUAHUP3XIU76DHA5JW4OBUH7YQ (2.1
> KiB): area localgit: echo to: alexandria: already sent
>
> When: 2021-09-09T02:20:30.046258297Z
> Debug: true
> Who: rx
> Node: JGCHEG...
> Pkt: F2SYUAB7ZWERF26Z6XWNDFOTZ2HUAHUP3XIU76DHA5JW4OBUH7YQ
> Nice: 96
> Size: 2157
> Type: area
> Area: RVFWL...
> AreaMsg: L3NQRYHGBDQLJPKRI5P7E2BQUJLFCIOTBGBWTXD5HGEEFGL7SEGA
> Size: 1669
> Msg: Tossing
> localgit/area/RVFWL.../L3NQRYHGBDQLJPKRI5P7E2BQUJLFCIOTBGBWTXD5HGEEFGL7SEGA
> (1.6 KiB)
>
> When: 2021-09-09T02:20:30.047521024Z
> Debug: true
> Who: rx
> Node: JGCHEG...
> Pkt: R2RCYMTJVRQONI2PLNS3FJ7ELTY4S47ZNDLEFT27QCYYHLM3PYBQ
> Nice: 96
> Size: 2056
> Msg: Tossing self/R2RCYMTJVRQONI2PLNS3FJ7ELTY4S47ZNDLEFT27QCYYHLM3PYBQ (2.0
> KiB)
>
> When: 2021-09-09T02:20:30.047586954Z
> Debug: true
> Who: rx-area
> Node: JGCHEG...
> Pkt: R2RCYMTJVRQONI2PLNS3FJ7ELTY4S47ZNDLEFT27QCYYHLM3PYBQ
> Nice: 96
> Size: 2056
> Type: area
> Area: RVFWL...
> AreaMsg: 7DITYNACMUIQTZ6MZ7HDCUFBYFUKWXJ4MW3COQSPUMSUMVYVAVMA
> Msg: Tossing self/R2RCYMTJVRQONI2PLNS3FJ7ELTY4S47ZNDLEFT27QCYYHLM3PYBQ (2.0
> KiB): area localgit
>
> When: 2021-09-09T02:20:30.047604274Z
> Debug: true
> Who: rx-area-echo-seen
> Node: JGCHEG...
> Pkt: R2RCYMTJVRQONI2PLNS3FJ7ELTY4S47ZNDLEFT27QCYYHLM3PYBQ
> Nice: 96
> Size: 2056
> Type: area
> Area: RVFWL...
> AreaMsg: 7DITYNACMUIQTZ6MZ7HDCUFBYFUKWXJ4MW3COQSPUMSUMVYVAVMA
> Echo: L3WOIONS7NFQN53SIDHT3VMJ7HELW3WLBRYTO7MEAH4OMC36JLHQ
> Msg: Tossing self/R2RCYMTJVRQONI2PLNS3FJ7ELTY4S47ZNDLEFT27QCYYHLM3PYBQ (2.0
> KiB): area localgit: echo to: alexandria: already sent
>
> When: 2021-09-09T02:20:30.047975829Z
> Debug: true
> Who: rx
> Node: JGCHEG...
> Pkt: R2RCYMTJVRQONI2PLNS3FJ7ELTY4S47ZNDLEFT27QCYYHLM3PYBQ
> Nice: 96
> Size: 2056
> Type: area
> Area: RVFWL...
> AreaMsg: 7DITYNACMUIQTZ6MZ7HDCUFBYFUKWXJ4MW3COQSPUMSUMVYVAVMA
> Size: 1568
> Msg: Tossing
> localgit/area/RVFWL.../7DITYNACMUIQTZ6MZ7HDCUFBYFUKWXJ4MW3COQSPUMSUMVYVAVMA
> (1.5 KiB)