Opened 5 months ago

Last modified 3 days ago

#2458 new defect

Router watchdog barking because of outdated leaset

Reported by: jogger Owned by:
Priority: minor Milestone: undecided
Component: router/general Version: 0.9.38
Keywords: Cc: Zlatin Balevsky
Parent Tickets: Sensitive: no

Description

I get this every minute in my logs, same leaseset for more than a week - router runs fine otherwise:

12.03.19, 09:16:37 ERROR [uterWatchdog] client.ClientManagerFacadeImpl?: Client bohwswqqx6orlerppkbvhuibxmrk5po6rlscxphzcd575xe3j74a.b32.i2p has a leaseSet that expired 13d ago
12.03.19, 09:16:37 ERROR [uterWatchdog] 2p.router.tasks.RouterWatchdog?: Ready and waiting jobs: 0
12.03.19, 09:16:37 ERROR [uterWatchdog] 2p.router.tasks.RouterWatchdog?: Job lag: 0
12.03.19, 09:16:37 ERROR [uterWatchdog] 2p.router.tasks.RouterWatchdog?: Participating tunnel count: 200
12.03.19, 09:16:37 ERROR [uterWatchdog] 2p.router.tasks.RouterWatchdog?: 1 minute send processing time: 210ms
12.03.19, 09:16:37 ERROR [uterWatchdog] 2p.router.tasks.RouterWatchdog?: Outbound send rate: 392,00KiBps
12.03.19, 09:16:37 ERROR [uterWatchdog] 2p.router.tasks.RouterWatchdog?: Memory: 89,70MiB / 128,00MiB

Subtickets

Change History (12)

comment:1 Changed 5 months ago by Zlatin Balevsky

Cc: Zlatin Balevsky added

Related: #2455

comment:2 Changed 5 months ago by zzz

13 days ago… hmm… any guess what client bohws… is?
whatever happened, we shouldn't be spamming the logs
can you go back 13 days ago in the logs and try to find the original problem?

comment:3 Changed 5 months ago by anonymous maybe

maybe this going to be useful:

  • I2P Version and Running Environment
 I2P version:	0.9.38-0-1ubuntu1
Java version:	Oracle Corporation 9-Debian (OpenJDK Runtime Environment 9-Debian+0-9b181-4bpo91)
Wrapper version:	3.5.30
Server version:	9.2.21.v20170120
Servlet version:	Jasper JSP 2.3 Engine
JSTL version:	standard-taglib 1.2.5
Platform:	Linux amd64 4.14.103-1.pvops.qubes.x86_64
Processor:	Haswell Core i3/i5/i7 model 60 (coreihwl)
JBigI status:	Locally optimized library libjbigi-linux-coreihwl_64.so loaded from file
GMP version:	6.1.2
JBigI version:	4
JCpuId version:	3
Encoding:	UTF-8
Charset:	UTF-8
Built By:	Undefined
  • Critical Logs
    3/15/19, 8:07:57 AM CRIT [uterWatchdog] 2p.router.tasks.RouterWatchdog: Router appears hung, or there is severe network congestion. Watchdog starts barking!
    3/14/19, 9:35:56 PM CRIT [uterWatchdog] 2p.router.tasks.RouterWatchdog: Router appears hung, or there is severe network congestion. Watchdog starts barking!
  • Router Logs
    3/15/19, 8:08:57 AM ERROR [uterWatchdog] 2p.router.tasks.RouterWatchdog: Memory: 52.55MiB / 966.69MiB
    3/15/19, 8:08:57 AM ERROR [uterWatchdog] 2p.router.tasks.RouterWatchdog: Outbound send rate: 926Bps
    3/15/19, 8:08:57 AM ERROR [uterWatchdog] 2p.router.tasks.RouterWatchdog: 1 minute send processing time: 95ms
    3/15/19, 8:08:57 AM ERROR [uterWatchdog] 2p.router.tasks.RouterWatchdog: Participating tunnel count: 2
    3/15/19, 8:08:57 AM ERROR [uterWatchdog] 2p.router.tasks.RouterWatchdog: Job lag: 0
    3/15/19, 8:08:57 AM ERROR [uterWatchdog] 2p.router.tasks.RouterWatchdog: Ready and waiting jobs: 0
    3/15/19, 8:08:57 AM ERROR [uterWatchdog] client.ClientManagerFacadeImpl: Client o5zh4hhe57o4c3npasnha4hul3ti5vxkvbggpdqusngo2tw3uxbq.b32.i2p has a leaseSet that expired 11m ago
    3/15/19, 8:07:57 AM CRIT [uterWatchdog] 2p.router.tasks.RouterWatchdog: Router appears hung, or there is severe network congestion. Watchdog starts barking!
    3/15/19, 8:07:57 AM ERROR [uterWatchdog] 2p.router.tasks.RouterWatchdog: Memory: 60.73MiB / 966.69MiB
    3/15/19, 8:07:57 AM ERROR [uterWatchdog] 2p.router.tasks.RouterWatchdog: Outbound send rate: 1.04KiBps
    3/15/19, 8:07:57 AM ERROR [uterWatchdog] 2p.router.tasks.RouterWatchdog: 1 minute send processing time: 126ms
    3/15/19, 8:07:57 AM ERROR [uterWatchdog] 2p.router.tasks.RouterWatchdog: Participating tunnel count: 2
    3/15/19, 8:07:57 AM ERROR [uterWatchdog] 2p.router.tasks.RouterWatchdog: Job lag: 0
    3/15/19, 8:07:57 AM ERROR [uterWatchdog] 2p.router.tasks.RouterWatchdog: Ready and waiting jobs: 0
    3/15/19, 8:07:57 AM ERROR [uterWatchdog] client.ClientManagerFacadeImpl: Client o5zh4hhe57o4c3npasnha4hul3ti5vxkvbggpdqusngo2tw3uxbq.b32.i2p has a leaseSet that expired 10m ago
    3/15/19, 6:14:06 AM DEBUG [nt Runner 16] .i2ptunnel.I2PTunnelHTTPClient: HTTPClient[4/2]: Destination: i2p-projekt.i2p
    3/15/19, 6:14:06 AM DEBUG [nt Runner 16] .i2ptunnel.I2PTunnelHTTPClient: HTTPClient[4/2]: NewRequest header: [GET /hosts.txt HTTP/1.1
         Host: udhdrtrcetjm5sxzskjyr5ztpeszydbh4dpl3pl4utgqqw2v4jna.b32.i2p
         Cache-Control: no-cache
         Pragma: no-cache
         If-None-Match: "1546003468.22-203509-3078492705-gzip"
         If-Modified-Since: Fri, 28 Dec 2018 13:24:28 GMT
         Accept-Encoding: gzip
         X-Accept-Encoding: x-i2p-gzip;q=1.0, identity;q=0.5, deflate;q=0, gzip;q=0, *;q=0
         User-Agent: MYOB/6.66 (AN/ON)
         Connection: close
        
         ]
    3/15/19, 6:14:06 AM DEBUG [nt Runner 16] .i2ptunnel.I2PTunnelHTTPClient: HTTPClient[4/2]: Line=[]
    3/15/19, 6:14:06 AM DEBUG [nt Runner 16] .i2ptunnel.I2PTunnelHTTPClient: HTTPClient[4/2]: Line=[Connection: close]
    3/15/19, 6:14:06 AM DEBUG [nt Runner 16] .i2ptunnel.I2PTunnelHTTPClient: HTTPClient[4/2]: Line=[User-Agent: Wget/1.11.4]
  • Service (Wrapper) Logs
2019/03/14 18:07:31 | --> Wrapper Started as Daemon
2019/03/14 18:07:31 | Java Service Wrapper Community Edition 64-bit 3.5.30
2019/03/14 18:07:31 |   Copyright (C) 1999-2016 Tanuki Software, Ltd. All Rights Reserved.
2019/03/14 18:07:31 |     http://wrapper.tanukisoftware.com
2019/03/14 18:07:31 | 
2019/03/14 18:07:31 | Launching a JVM...
2019/03/14 18:07:32 | WrapperManager: Initializing...
2019/03/14 18:07:32 | Starting I2P 0.9.38-0-1ubuntu1
2019/03/14 18:07:32 | INFO: Native CPUID library jcpuid-x86-linux loaded from file
2019/03/14 18:07:32 | INFO: Locally optimized library libjbigi-linux-coreihwl_64.so loaded from file
2019/03/14 18:07:36 | WARN: IP changed, restarting with a new identity and port
2019/03/14 18:07:36 | INFO:  Removing old identity file: router.info
2019/03/14 18:07:36 | INFO:  Removing old identity file: router.keys.dat
2019/03/14 18:07:36 | INFO:  Removing old identity file: keyBackup/privateEncryption.key
2019/03/14 18:07:36 | INFO:  Removing old identity file: keyBackup/publicEncryption.key
2019/03/14 18:07:36 | INFO:  Removing old identity file: keyBackup/privateSigning.key
2019/03/14 18:07:36 | INFO:  Removing old identity file: keyBackup/publicSigning.key
2019/03/14 18:07:37 | CRIT  [ Establisher] net.i2p.router.Router         : Starting final shutdown(4)
2019/03/14 18:07:37 | CRIT  [ Establisher] net.i2p.router.Router         : Shutdown(4) complete
2019/03/14 18:07:40 | on_exit trigger matched.  Restarting the JVM.  (Exit code: 4)
2019/03/14 18:07:55 | Launching a JVM...
2019/03/14 18:07:55 | WrapperManager: Initializing...
2019/03/14 18:07:55 | Starting I2P 0.9.38-0-1ubuntu1
2019/03/14 18:07:55 | INFO: Native CPUID library jcpuid-x86-linux loaded from file
2019/03/14 18:07:55 | INFO: Locally optimized library libjbigi-linux-coreihwl_64.so loaded from file
2019/03/14 21:36:15 | CRIT  [uterWatchdog] 2p.router.tasks.RouterWatchdog: Router appears hung, or there is severe network congestion.  Watchdog starts barking!
2019/03/15 08:07:58 | CRIT  [uterWatchdog] 2p.router.tasks.RouterWatchdog: Router appears hung, or there is severe network congestion.  Watchdog starts barking!

comment:4 Changed 5 months ago by jogger

It definitely depends on the peer. Saw barking with this guy 7vbgg4q5jxwwulex5cicga7iozu4xgivrwo3mc3y37h2fsrpre5a.b32.i2p twice for 11-12 min yesterday and today. Nothing else in the logs.

So far has only happened on routers with # of tunnels restricted.

comment:5 Changed 5 months ago by zzz

what do you mean "# of tunnels restricted" ? what is restricted? this is some manual configuration you did?

comment:6 Changed 5 months ago by jogger

I used this limiter:

router.maxParticipatingTunnels=200

comment:7 Changed 9 days ago by jogger

Sensitive: unset

Now reoccured on completely unrestricted router. Enhanced log below, barking continues up til now. Possibly related: "shared clients" went yellow, Proxy stopped working. Restarting the hidden service did not help.

11.08.19, 14:02:43 ERROR [JobQueue 2/2] uter.client.RequestLeaseSetJob: Failed to receive a leaseSet in the time allotted (59965): leaseSet request asking for [LeaseSet: 
	Destination: [Destination: 
	Hash: LZh4zcFDbc4bECZAjXBxZ6E0IJe2gtbSGFPRKDXzsro=
	Certificate: [Certificate: type: Null payload: null]
	PublicKey: [PublicKey ELGAMAL_2048 size: 256]
	SigningPublicKey: [SigningPublicKey DSA_SHA1 size: 128]]
	B32: fwmhrtobinw44gyqezai24drm6qtiiexw2bnnuqykpisqnptwk5a.b32.i2p
	EncryptionKey: null
	SigningKey: null
	Signature: null
	Leases: #1
		[Lease: 
	End Date: Sun Aug 11 12:10:24 GMT 2019
	Gateway: [Hash: 2VfDk9W0g~vZWbTjTOhR~XP2ewwEERKkoIw4BC5YlFY=]
	TunnelId: 2078576075]] having received null succeeding? false expiring on 1565524962611
11.08.19, 14:15:35 ERROR [uterWatchdog] client.ClientManagerFacadeImpl: Client 75xudomyiwr5jgcdzdd6rfpaa62jge6nsfzdum7g7g23moezhcfq.b32.i2p has a leaseSet that expired 10m ago
11.08.19, 14:15:35 ERROR [uterWatchdog] 2p.router.tasks.RouterWatchdog: Ready and waiting jobs: 0
11.08.19, 14:15:35 ERROR [uterWatchdog] 2p.router.tasks.RouterWatchdog: Job lag: 0
11.08.19, 14:15:35 ERROR [uterWatchdog] 2p.router.tasks.RouterWatchdog: Participating tunnel count: 2539
11.08.19, 14:15:35 ERROR [uterWatchdog] 2p.router.tasks.RouterWatchdog: 1 minute send processing time: 82ms
11.08.19, 14:15:35 ERROR [uterWatchdog] 2p.router.tasks.RouterWatchdog: Outbound send rate: 1,86MiBps
11.08.19, 14:15:35 ERROR [uterWatchdog] 2p.router.tasks.RouterWatchdog: Memory: 198,72MiB / 256,00MiB
11.08.19, 14:15:35 CRIT  [uterWatchdog] 2p.router.tasks.RouterWatchdog: Router appears hung, or there is severe network congestion.  Watchdog starts barking!
11.08.19, 14:15:36 CRIT  [uterWatchdog] et.i2p.router.tasks.ThreadDump: Threads dumped to /home/e/.i2p/wrapper.log

comment:8 Changed 5 days ago by zzz

Yeah, I don't see how a participating tunnel limit would make a difference.

Haven't gotten any reports on this from others. It may be a race with a close-on-idle tunnel, where the client goes away while the router is requesting a leaseset from it. I assume you don't recognize the b32 address as a local service… every report above has a different b32. You can check /netdb?l=2 leaseset page to look for the b32 in question. But if it doesn't have a leaseset, it may not be there.

Check, for example, the HTTP Proxy tunnel in the Hidden Services Manager - is the 'close tunnels after idle' box checked? New Keys on Reopen enable or disable? Have you tweaked any settings there you can remember?

Is this a high- or low-bandwidth router? busy or not?

I'll look through the code to see if I can find any races.

comment:9 Changed 5 days ago by jogger

High b/w and busy. HTTP Proxy not touched, Reduce on idle = 1 after 15 min. New keys disabled. Will look deeper, when it reappears.

comment:10 Changed 4 days ago by zzz

Is ' Close client tunnels after specified idle period' set on any running tunnel?

comment:11 Changed 4 days ago by jogger

Nope. Only enabled on IRC which I never start.

comment:12 Changed 3 days ago by zzz

ok, please try to identify which tunnel has the b32 that's complaining, comment 8 has the info

Note: See TracTickets for help on using tickets.