search

hap-java / HAP-Java

Java implementation of the HomeKit Accessory Protocol
MIT License
153 stars 82 forks source link

Netty connection timed out #28

Open mariusz2108 opened 7 years ago

mariusz2108 commented 7 years ago

I wrote simple application using hap-java. Everything works fine with my iPad for few days and after that iPad cannot connect to accessories. When I restart application it works again for few days. I checked logs and it looks like netty doesn't close connections.

2016-11-22 13:36:42 [defaultEventExecutorGroup-4-1] [INFO ] [c.b.h.i.h.i.AccessoryHandler] - Terminated homekit connection from /192.168.10.6:50073
2016-11-22 13:36:44 [nioEventLoopGroup-2-1] [INFO ] [i.n.h.l.LoggingHandler] - [id: 0xf1f723d8, /0:0:0:0:0:0:0:0:9123] RECEIVED: [id: 0x3ae20211, /192.168.10.6:50120 => /192.168.10.154:9123]
2016-11-22 13:36:44 [defaultEventExecutorGroup-4-2] [INFO ] [c.b.h.i.h.i.AccessoryHandler] - New homekit connection from /192.168.10.6:50120
2016-11-22 13:36:44 [defaultEventExecutorGroup-4-2] [DEBUG] [c.b.h.i.p.PairVerificationManager] - Starting pair verification for Dom
2016-11-22 13:36:44 [defaultEventExecutorGroup-4-2] [INFO ] [c.b.h.i.h.HomekitClientConnection] - 200 /pair-verify
2016-11-22 13:36:45 [defaultEventExecutorGroup-4-2] [DEBUG] [c.b.h.i.p.PairVerificationManager] - Completed pair verification for Dom
2016-11-22 13:36:45 [defaultEventExecutorGroup-4-2] [INFO ] [c.b.h.i.h.HomekitClientConnection] - 200 /pair-verify
2016-11-22 13:36:47 [defaultEventExecutorGroup-4-2] [INFO ] [c.b.h.i.h.HomekitClientConnection] - 200 /accessories
2016-11-22 13:52:45 [JmDNS(pc220408-home.local.).Timer] [WARN ] [j.j.i.t.Responder] - Responder(pc220408-home.local.)run() exception 
java.io.IOException: Invalid argument
    at java.net.PlainDatagramSocketImpl.send(Native Method)
    at java.net.DatagramSocket.send(DatagramSocket.java:671)
    at javax.jmdns.impl.JmDNSImpl.send(JmDNSImpl.java:1536)
    at javax.jmdns.impl.tasks.Responder.run(Responder.java:148)
    at java.util.TimerThread.mainLoop(Timer.java:555)
    at java.util.TimerThread.run(Timer.java:505)
2016-11-22 13:52:45 [JmDNS(pc220408-home.local.).State.Timer] [WARN ] [j.j.i.t.s.DNSStateTask] - Canceler(pc220408-home.local.).run() exception 
java.io.IOException: Invalid argument
    at java.net.PlainDatagramSocketImpl.send(Native Method)
    at java.net.DatagramSocket.send(DatagramSocket.java:671)
    at javax.jmdns.impl.JmDNSImpl.send(JmDNSImpl.java:1536)
    at javax.jmdns.impl.tasks.state.DNSStateTask.run(DNSStateTask.java:131)
    at java.util.TimerThread.mainLoop(Timer.java:555)
    at java.util.TimerThread.run(Timer.java:505)
2016-11-22 13:52:50 [JmDNS(pc220408-home.local.).Timer] [WARN ] [j.j.i.DNSStatefulObject$DefaultImplementation] - Wait for canceled timed out: DNS: pc220408-home.local. state: canceling 1 task: null
2016-11-22 14:02:50 [nioEventLoopGroup-3-4] [ERROR] [c.b.h.i.h.i.BinaryHandler] - Exception in binary handler
java.io.IOException: Connection timed out
    at sun.nio.ch.FileDispatcherImpl.read0(Native Method)
    at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39)
    at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:223)
    at sun.nio.ch.IOUtil.read(IOUtil.java:192)
    at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:375)
    at io.netty.buffer.UnpooledUnsafeDirectByteBuf.setBytes(UnpooledUnsafeDirectByteBuf.java:447)
    at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:880)
    at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:242)
    at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:119)
    at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:511)
    at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:468)
    at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:382)
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:354)
    at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:112)
    at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:137)
    at java.lang.Thread.run(Thread.java:744)
2016-11-22 14:02:50 [defaultEventExecutorGroup-4-4] [ERROR] [c.b.h.i.h.i.AccessoryHandler] - Exception caught in web handler
java.io.IOException: Connection timed out
    at sun.nio.ch.FileDispatcherImpl.read0(Native Method)
    at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39)
    at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:223)
    at sun.nio.ch.IOUtil.read(IOUtil.java:192)
    at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:375)
    at io.netty.buffer.UnpooledUnsafeDirectByteBuf.setBytes(UnpooledUnsafeDirectByteBuf.java:447)
    at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:880)
    at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:242)
    at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:119)
    at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:511)
    at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:468)
    at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:382)
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:354)
    at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:112)
    at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:137)
    at java.lang.Thread.run(Thread.java:744)
2016-11-22 14:02:50 [defaultEventExecutorGroup-4-4] [INFO ] [c.b.h.i.h.i.AccessoryHandler] - Terminated homekit connection from /192.168.10.6:50058
2016-11-22 14:11:42 [nioEventLoopGroup-3-4] [ERROR] [c.b.h.i.h.i.BinaryHandler] - Exception in binary handler
java.io.IOException: Connection timed out
    at sun.nio.ch.FileDispatcherImpl.read0(Native Method)
    at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39)
    at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:223)
    at sun.nio.ch.IOUtil.read(IOUtil.java:192)
    at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:375)
    at io.netty.buffer.UnpooledUnsafeDirectByteBuf.setBytes(UnpooledUnsafeDirectByteBuf.java:447)
    at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:880)
    at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:242)
    at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:119)
    at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:511)
    at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:468)
    at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:382)
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:354)
    at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:112)
    at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:137)
    at java.lang.Thread.run(Thread.java:744)
2016-11-22 14:11:42 [defaultEventExecutorGroup-4-4] [ERROR] [c.b.h.i.h.i.AccessoryHandler] - Exception caught in web handler
java.io.IOException: Connection timed out
    at sun.nio.ch.FileDispatcherImpl.read0(Native Method)
    at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39)
    at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:223)
    at sun.nio.ch.IOUtil.read(IOUtil.java:192)
    at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:375)
    at io.netty.buffer.UnpooledUnsafeDirectByteBuf.setBytes(UnpooledUnsafeDirectByteBuf.java:447)
    at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:880)
    at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:242)
    at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:119)
    at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:511)
    at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:468)
    at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:382)
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:354)
    at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:112)
    at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:137)
    at java.lang.Thread.run(Thread.java:744)

I also made thread dump and there are lot of threads are waiting. Probably netty connection pool reached limit and that's why I cannot connect to accessories.

"defaultEventExecutorGroup-4-1" #32 prio=5 os_prio=0 tid=0x62e4a800 nid=0x7b1a waiting on condition [0x5fcfe000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x6a4d2598> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
    at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
    at io.netty.util.concurrent.SingleThreadEventExecutor.takeTask(SingleThreadEventExecutor.java:218)
    at io.netty.util.concurrent.DefaultEventExecutor.run(DefaultEventExecutor.java:34)
    at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:112)
    at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:137)
    at java.lang.Thread.run(Thread.java:744)
amedeomantica commented 2 years ago

me too

yfre commented 2 years ago

@amedeomantica @mariusz2108 we have upgraded netty. please try again, maybe issue is fixed in the latest netty version