Subject: NNCP panics

From: John Goerzen <[email-masked]>
Date: Sun, 03 Jan 2021 17:43:57 -0600

Hi,

A few quick bug reports here.

#1...  today my spooler machine had been down for a number of 
 hours.  When I brought it back up, the daemon would crash after a 
 few seconds of incoming packets with:

Jan 03 15:55:05 nncp nncp-daemon[862]: 2021-01-03T21:55:05Z Packet 
Z...Q is retreived (1.3 KiB)
Jan 03 15:55:05 nncp nncp-daemon[862]: panic: sync: WaitGroup is 
reused before previous Wait has returned
Jan 03 15:55:05 nncp nncp-daemon[862]: goroutine 13 [running]:
Jan 03 15:55:05 nncp nncp-daemon[862]: 
sync.(*WaitGroup).Wait(0x7aa188)
Jan 03 15:55:05 nncp nncp-daemon[862]: 
/usr/lib/go-1.11/src/sync/waitgroup.go:132 +0xad
Jan 03 15:55:05 nncp nncp-daemon[862]: 
go.cypherpunks.ru/nncp/v5.(*SPState).ProcessSP(0xc000122900, 
0xc000242000, 0xce6c, 0xce6c, 0x618823, 0xa, 0x0, 0xc000278000, 
0xce7c)
Jan 03 15:55:05 nncp nncp-daemon[862]: 
/tmp/nncp-5.4.1/src/go.cypherpunks.ru/nncp/v5/sp.go:992 +0x2288
Jan 03 15:55:05 nncp nncp-daemon[862]: 
go.cypherpunks.ru/nncp/v5.(*SPState).StartWorkers.func6(0xc000122900, 
0xc000196480, 0x7f3ee0475330, 0xc000196300)
Jan 03 15:55:05 nncp nncp-daemon[862]: 
/tmp/nncp-5.4.1/src/go.cypherpunks.ru/nncp/v5/sp.go:793 +0x64a
Jan 03 15:55:05 nncp nncp-daemon[862]: created by 
go.cypherpunks.ru/nncp/v5.(*SPState).StartWorkers
Jan 03 15:55:05 nncp nncp-daemon[862]: 
/tmp/nncp-5.4.1/src/go.cypherpunks.ru/nncp/v5/sp.go:756 +0x4f5
Jan 03 15:55:05 nncp systemd[1]: nncp-daemon.service: Main process 
exited, code=exited, status=2/INVALIDARGUMENT
Jan 03 15:55:05 nncp systemd[1]: nncp-daemon.service: Failed with 
result 'exit-code'.

systemd restarted it, and eventually it managed to catch up.  This 
would have been annoying had I had systems not using nncp-caller, 
but the systems reconnected and eventually it all went through.  I 
had some "already done" messages in the logs after the crashes; 
I'm assuming it detected an incoming packet had already been 
processed via .seen processing?

At the time of these panics -- there were 16 panics before it 
resumed normal processing, mostly occurring within 3-5 seconds of 
the :00 of a minute (so presumably when the nncp-callers were 
reconnecting), there were often around 3 or 4 clients connected 
according to the logs.  Two or three of them would have been 
sending quite a few packets.

Possibly related, after one of the restarts:

Jan 03 15:57:00 nncp systemd[1]: Stopped Main NNCP daemon.
Jan 03 15:57:00 nncp systemd[1]: Started Main NNCP daemon.
Jan 03 15:57:56 nncp nncp-daemon[1621]: 2021-01-03T21:57:56Z ERROR 
SP: EOF
Jan 03 15:57:56 nncp nncp-daemon[1621]: 2021-01-03T21:57:56Z ERROR 
Connection to unknown: EOF

I don't know what that means, but after that it started processing 
packets again.

#2...  on a different machine:

Jan 01 16:33:41 nncp2 nncp-caller-daemon[25317]: 
2021-01-01T22:33:41Z Packet 5...Q is retreived (981 B)
Jan 01 16:33:41 nncp2 nncp-caller-daemon[25317]: panic: send on 
closed channel
Jan 01 16:33:41 nncp2 nncp-caller-daemon[25317]: goroutine 168555 
[running]:
Jan 01 16:33:41 nncp2 nncp-caller-daemon[25317]: 
go.cypherpunks.ru/nncp/v5.(*SPState).ProcessSP.func1.1(0xc000158000, 
0xc00007f560)
Jan 01 16:33:41 nncp2 nncp-caller-daemon[25317]: 
/usr/local/nncp/build/nncp-5.4.1/src/go.cypherpunks.ru/nncp/v5/sp.go:1029 
+0x7d
Jan 01 16:33:41 nncp2 nncp-caller-daemon[25317]: created by 
go.cypherpunks.ru/nncp/v5.(*SPState).ProcessSP.func1
Jan 01 16:33:41 nncp2 nncp-caller-daemon[25317]: 
/usr/local/nncp/build/nncp-5.4.1/src/go.cypherpunks.ru/nncp/v5/sp.go:1028 
+0x54d
Jan 01 16:33:41 nncp2 systemd[1]: nncp-caller-bakfs.service: Main 
process exited, code=exited, status=2/INVALIDARGUMENT
Jan 01 16:33:41 nncp2 systemd[1]: nncp-caller-bakfs.service: 
Failed with result 'exit-code'.

Thanks again!

- John