UPnP deadlock

[killyourtv]

I2P version: 0.9.22-20-deb1
Java version: Oracle Corporation 1.8.0_66-internal (OpenJDK Runtime Environment 1.8.0_66-internal-b17)
Wrapper version: 3.5.26
Server version: 8.1.17.v20150415
Servlet version: Jasper JSP 2.1 Engine
Platform: Linux amd64 4.2.0-1-amd64
Processor: Bulldozer FX-6100/8100 (athlon64)
Jbigi: Locally optimized native BigInteger library loaded from file
Encoding: UTF-8
Charset: UTF-8

2015/10/31 15:49:44 | Found one Java-level deadlock:
2015/10/31 15:49:44 | =============================
2015/10/31 15:49:44 | "GeoIP Lookup":
2015/10/31 15:49:44 |   waiting to lock monitor 0x00007f938c006f68 (object 0x00000000e91474a0, a java.lang.Object),
2015/10/31 15:49:44 |   which is held by "UPnP Port Opener 3"
2015/10/31 15:49:44 | "UPnP Port Opener 3":
2015/10/31 15:49:44 |   waiting to lock monitor 0x00007f940c007678 (object 0x00000000e89e4738, a java.lang.Object),
2015/10/31 15:49:44 |   which is held by "UPnP Port Opener 4"
2015/10/31 15:49:44 | "UPnP Port Opener 4":
2015/10/31 15:49:44 |   waiting to lock monitor 0x00007f938c006f68 (object 0x00000000e91474a0, a java.lang.Object),
2015/10/31 15:49:44 |   which is held by "UPnP Port Opener 3"
2015/10/31 15:49:44 |
2015/10/31 15:49:44 | Java stack information for the threads listed above:
2015/10/31 15:49:44 | ===================================================
2015/10/31 15:49:44 | "GeoIP Lookup":
2015/10/31 15:49:44 |   at net.i2p.router.Router.getRouterInfo(Router.java:493)
2015/10/31 15:49:44 |   - waiting to lock <0x00000000e91474a0> (a java.lang.Object)
2015/10/31 15:49:44 |   at net.i2p.router.RouterContext.routerHash(RouterContext.java:269)
2015/10/31 15:49:44 |   at net.i2p.router.transport.GeoIP.updateOurCountry(GeoIP.java:319)
2015/10/31 15:49:44 |   at net.i2p.router.transport.GeoIP.blockingLookup(GeoIP.java:125)
2015/10/31 15:49:44 |   at net.i2p.router.transport.CommSystemFacadeImpl$LookupThread.run(CommSystemFacadeImpl.java:366)
2015/10/31 15:49:44 | "UPnP Port Opener 3":
2015/10/31 15:49:44 |   at net.i2p.router.transport.udp.UDPTransport.getCurrentExternalAddress(UDPTransport.java:2119)
2015/10/31 15:49:44 |   - waiting to lock <0x00000000e89e4738> (a java.lang.Object)
2015/10/31 15:49:44 |   at net.i2p.router.transport.udp.UDPTransport.rebuildExternalAddress(UDPTransport.java:1910)
2015/10/31 15:49:44 |   at net.i2p.router.transport.udp.UDPTransport.updateAddress(UDPTransport.java:1865)
2015/10/31 15:49:44 |   at net.i2p.router.transport.TransportManager.getAddresses(TransportManager.java:466)
2015/10/31 15:49:44 |   at net.i2p.router.transport.CommSystemFacadeImpl.createAddresses(CommSystemFacadeImpl.java:212)
2015/10/31 15:49:44 |   at net.i2p.router.Router.locked_rebuildRouterInfo(Router.java:835)
2015/10/31 15:49:44 |   at net.i2p.router.Router.rebuildRouterInfo(Router.java:813)
2015/10/31 15:49:44 |   - locked <0x00000000e91474a0> (a java.lang.Object)
2015/10/31 15:49:44 |   at net.i2p.router.Router.rebuildRouterInfo(Router.java:802)
2015/10/31 15:49:44 |   at net.i2p.router.transport.udp.UDPTransport.changeAddress(UDPTransport.java:996)
2015/10/31 15:49:44 |   at net.i2p.router.transport.udp.UDPTransport.externalAddressReceived(UDPTransport.java:773)
2015/10/31 15:49:44 |   at net.i2p.router.transport.TransportManager.externalAddressReceived(TransportManager.java:206)
2015/10/31 15:49:44 |   at net.i2p.router.transport.UPnPManager$UPnPCallback.portForwardStatus(UPnPManager.java:247)
2015/10/31 15:49:44 |   at net.i2p.router.transport.UPnP$RegisterPortsThread.run(UPnP.java:1025)
2015/10/31 15:49:44 |   at java.lang.Thread.run(Thread.java:745)
2015/10/31 15:49:44 | "UPnP Port Opener 4":
2015/10/31 15:49:44 |   at net.i2p.router.Router.isHidden(Router.java:964)
2015/10/31 15:49:44 |   - waiting to lock <0x00000000e91474a0> (a java.lang.Object)
2015/10/31 15:49:44 |   at net.i2p.router.transport.udp.UDPTransport.locked_rebuildExternalAddress(UDPTransport.java:1956)
2015/10/31 15:49:44 |   at net.i2p.router.transport.udp.UDPTransport.rebuildExternalAddress(UDPTransport.java:1949)
2015/10/31 15:49:44 |   - locked <0x00000000e89e4738> (a java.lang.Object)
2015/10/31 15:49:44 |   at net.i2p.router.transport.udp.UDPTransport.rebuildExternalAddress(UDPTransport.java:1915)
2015/10/31 15:49:44 |   at net.i2p.router.transport.udp.UDPTransport.rebuildExternalAddress(UDPTransport.java:1877)
2015/10/31 15:49:44 |   at net.i2p.router.transport.udp.UDPTransport.locked_setReachabilityStatus(UDPTransport.java:2957)
2015/10/31 15:49:44 |   at net.i2p.router.transport.udp.UDPTransport.setReachabilityStatus(UDPTransport.java:2901)
2015/10/31 15:49:44 |   - locked <0x00000000e89e4738> (a java.lang.Object)
2015/10/31 15:49:44 |   at net.i2p.router.transport.udp.UDPTransport.forwardPortStatus(UDPTransport.java:804)
2015/10/31 15:49:44 |   at net.i2p.router.transport.TransportManager.forwardPortStatus(TransportManager.java:232)
2015/10/31 15:49:44 |   at net.i2p.router.transport.UPnPManager$UPnPCallback.portForwardStatus(UPnPManager.java:272)
2015/10/31 15:49:44 |   at net.i2p.router.transport.UPnP$RegisterPortsThread.run(UPnP.java:1025)
2015/10/31 15:49:44 |   at java.lang.Thread.run(Thread.java:745)
2015/10/31 15:49:44 |
2015/10/31 15:49:44 | Found 1 deadlock.
2015/10/31 15:49:44 |

More logs can be provided if required.

[zzz]

Analysis:

• The two locks are Router._routerInfoLock and UDPTransport._rebuildLock
• The two threads are the two 'UDP Port Opener x' callback threads started by UPnP
• GeoIPLookup is caught by the deadlock but innnocent
• There's complex paths through UDPTransport and Router that could deadlock
• The fix for this case is easy… only allow one callback to run at a time, locking in UPnPManager.UPnPCallback
• locking improvements in UDPTransport and/or Router may be req'd to prevent related deadlocks

[zzz]

easy fix in 2b916861b733feecb1dd1ac76a83a0269f27a4fc 0.9.22-21
possibly more to do, leaving open for testing and further investigation