hap-java/HAP-Java

Can not add bridge with iOS13?

christiantschoerner opened this issue · 55 comments

Since iOS 13 I can not add the bridge. With iOS 12 it works. Is there anything new what is should be aware of? The iPhone says it can not be added because it could not connect to the device. Thanks for help and thank you for the project!

I have the same problem

are you running the latest code from HAP-Java, including 0201d9a ? That should fix iOS 13. If you're using it within OpenHAB, you might want to check out https://github.com/ccutrer/openhab2-addons/releases/tag/2.5.0-cody2 (but with caveats). Otherwise, you'll need to compile and drop latest HAP-Java into whatever other project yourself; there's not a new release yet.

J-N-K commented

Pairing is not working for me, too. It seems that netty closes the connection too early. I added some Thread.sleep and it helped to get some steps further, but finally failed.

are you running the latest code from HAP-Java, including 0201d9a ? That should fix iOS 13. If you're using it within OpenHAB, you might want to check out https://github.com/ccutrer/openhab2-addons/releases/tag/2.5.0-cody2 (but with caveats). Otherwise, you'll need to compile and drop latest HAP-Java into whatever other project yourself; there's not a new release yet.

Compiled current code but same issue :/.

I'm having the same issue. I'm seeing the following error when I try to pair my phone to openHAB:

2019-11-01 23:09:59.435 [ERROR] [.hapjava.impl.pairing.PairingManager] - Exception while finalizing pairing org.bouncycastle.crypto.tls.TlsFatalAlert: bad_record_mac(20) at io.github.hapjava.impl.crypto.ChachaDecoder.decodeCiphertext(ChachaDecoder.java:31) ~[299:org.openhab.io.homekit:2.5.0.201911012204] at io.github.hapjava.impl.crypto.ChachaDecoder.decodeCiphertext(ChachaDecoder.java:41) ~[299:org.openhab.io.homekit:2.5.0.201911012204] at io.github.hapjava.impl.pairing.FinalPairHandler.decrypt(FinalPairHandler.java:44) ~[299:org.openhab.io.homekit:2.5.0.201911012204] at io.github.hapjava.impl.pairing.FinalPairHandler.handle(FinalPairHandler.java:39) ~[299:org.openhab.io.homekit:2.5.0.201911012204] at io.github.hapjava.impl.pairing.PairingManager.handle(PairingManager.java:59) [299:org.openhab.io.homekit:2.5.0.201911012204] at io.github.hapjava.impl.connections.HttpSession.handlePairSetup(HttpSession.java:109) [299:org.openhab.io.homekit:2.5.0.201911012204] at io.github.hapjava.impl.connections.HttpSession.handleRequest(HttpSession.java:53) [299:org.openhab.io.homekit:2.5.0.201911012204] at io.github.hapjava.impl.connections.ConnectionImpl.doHandleRequest(ConnectionImpl.java:54) [299:org.openhab.io.homekit:2.5.0.201911012204] at io.github.hapjava.impl.connections.ConnectionImpl.handleRequest(ConnectionImpl.java:47) [299:org.openhab.io.homekit:2.5.0.201911012204] at io.github.hapjava.impl.http.impl.AccessoryHandler.channelRead0(AccessoryHandler.java:52) [299:org.openhab.io.homekit:2.5.0.201911012204] at io.github.hapjava.impl.http.impl.AccessoryHandler.channelRead0(AccessoryHandler.java:17) [299:org.openhab.io.homekit:2.5.0.201911012204] at io.netty.channel.SimpleChannelInboundHandler.channelRead(SimpleChannelInboundHandler.java:105) [274:io.netty.transport:4.1.34.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:359) [274:io.netty.transport:4.1.34.Final] at io.netty.channel.AbstractChannelHandlerContext.access$600(AbstractChannelHandlerContext.java:38) [274:io.netty.transport:4.1.34.Final] at io.netty.channel.AbstractChannelHandlerContext$7.run(AbstractChannelHandlerContext.java:350) [274:io.netty.transport:4.1.34.Final] at io.netty.util.concurrent.DefaultEventExecutor.run(DefaultEventExecutor.java:66) [271:io.netty.common:4.1.34.Final] at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:905) [271:io.netty.common:4.1.34.Final] at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [271:io.netty.common:4.1.34.Final] at java.lang.Thread.run(Thread.java:748) [?:?]

J-N-K commented

@frank-f this is with an upgraded bcprov, right? That‘s not working.

@J-N-K I finally got the version from your repo to compile - it's that one.

Edit: I downgraded bcprov in your fork back to 1.51 - it's not working like that either.

yfre commented

home app has different functions for initial devices load (json parsing) and for device updates.
the initial load is more strict if something not exactly to specification it just stops. the procedure was change with ios13.
what helps - start with a small set of device, e.g. lights, do initial load / add bridge, add more device afterwards.
e.g. there was an issue with thermostat. i add first light and then thermostats.

if you have time, please try to figure out which device exactly is making issue (but trying to bridge with one device with two, etc), so that we can fix it.

home app has different functions for initial devices load (json parsing) and for device updates.
the initial load is more strict if something not exactly to specification it just stops. the procedure was change with ios13.
what helps - start with a small set of device, e.g. lights, do initial load / add bridge, add more device afterwards.
e.g. there was an issue with thermostat. i add first light and then thermostats.

if you have time, please try to figure out which device exactly is making issue (but trying to bridge with one device with two, etc), so that we can fix it.

Hey nice catch. But I even tried adding a bridge without any devices and that did not work as well. :(

yfre commented

Hey nice catch. But I even tried adding a bridge without any devices and that did not work as well. :(
and was it working on ios12? maybe something on the network level.
enable logging with

  1. ssh -p 8101 openhab@localhost
    default password is (habopen)
  2. log:set DEBUG org.openhab.io.homekit
  3. log:set DEBUG io.github.hapjava

and you should see the request from the phone in openhab.log

Hey nice catch. But I even tried adding a bridge without any devices and that did not work as well. :(
and was it working on ios12? maybe something on the network level.
enable logging with

  1. ssh -p 8101 openhab@localhost
    default password is (habopen)
  2. log:set DEBUG org.openhab.io.homekit
  3. log:set DEBUG io.github.hapjava

and you should see the request from the phone in openhab.log

I am not using openHAB I am using it as Library

if you have time, please try to figure out which device exactly is making issue (but trying to bridge with one device with two, etc), so that we can fix it.

Honestly, I gave up with this.

I installed v2.4.0-homekit-6 (https://github.com/hap-java/openhab2-addons/releases/), which didn't work with iOS 13 either. So I booted up an old iOS 12 device, added everything flawlessly on the first try and now I'm happy I have my smart home stuff working again.

I have thermostats, lights (on/off and dimmable), a temperature sensor and door/window sensors - if that helps.

I have the same issue. I use the source code from here with a simple java main (from samples branch) but i am unable to bind with my iPhone. But it seams that some kind of timeout happen.

If i couple with on iPhone using iOS 12 it work but the iOS 13 devices still dont have access.
Didt some one mage to get it run? Or is someone looking for an solution.

I also tryed:
https://github.com/timcharper/HAP-Java
https://github.com/ccutrer/HAP-Java

yfre commented

i got it working. i have around 90 devices of all different types and it works perfect with ios13 as well as with latest Ipados and tvOs.
my changes are merged to master branch here, but it looks like they dont work for everyone.

if you want to give a try,

the repos
https://github.com/yfre/HAP-Java
https://github.com/yfre/openhab2-addons/tree/2.4.0/new_devices

i got it working. i have around 90 devices of all different types and it works perfect with ios13 as well as with latest Ipados and tvOs.
my changes are merged to master branch here, but it looks like they dont work for everyone.

if you want to give a try,

the repos
https://github.com/yfre/HAP-Java
https://github.com/yfre/openhab2-addons/tree/2.4.0/new_devices

Does not work for me :(

yfre commented

ok. try to enable the logging "io.github.hapjava" = DEBUG. then you should see the JSON the library sends to home app. this JSON must not have any "null" value or values out of range (json has min/max values as well).
here is an example from my json (target mode for thermostat, which must be between 0 and 3

                  {
                     "iid":11,
                     "type":"33",
                     "perms":[
                        "pw",
                        "pr",
                        "ev"
                     ],
                     "format":"int",
                     "ev":false,
                     "description":"Target Mode",
                     "value":0,
                     "minValue":0,
                     "maxValue":3,
                     "minStep":1
                  },

if you get your JSON, please paste it here, this will help us to fix the library and make it more robust.

Like the others, 12 worked for me, 13 does not.
The problem appears to be with pairing - pairing completes and it seems (and is reported in HAB as) successful but then HomeKit disconnects. It does not attempt to reconnect. HomeKit gives up a few minutes later complaining it could not add the bridge and does not retry.
As far as I can tell it never gets to the step of loading accessories.

J-N-K commented

Exactly. We get to the final pairing step, then the connection closes. If we add sleeps (so that the connection stays alive a little bit longer), we sometimes get to the accessories read step and fail then.

@yfre I checked out: https://github.com/yfre/HAP-Java -b master

Then i add the java main from samples and a log4j2.xml with default log level debug:
The binding still failed. Here is the log from the connection attempt.

Using persisted auth
2019-11-10 20:53:02,482 main DEBUG Initializing configuration XmlConfiguration[location=C:\Users\heiko\workspace\HAP-Java\target\classes\log4j2.xml]
2019-11-10 20:53:02,489 main DEBUG Installed script engines
2019-11-10 20:53:02,824 main DEBUG Oracle Nashorn Version: 1.8.0_201, Language: ECMAScript, Threading: Not Thread Safe, Compile: true, Names: {nashorn, Nashorn, js, JS, JavaScript, javascript, ECMAScript, ecmascript}
2019-11-10 20:53:02,824 main DEBUG PluginManager 'Core' found 107 plugins
2019-11-10 20:53:02,825 main DEBUG PluginManager 'Level' found 0 plugins
2019-11-10 20:53:02,829 main DEBUG Log4j2 ConfigurationScheduler: No scheduled items
2019-11-10 20:53:02,829 main DEBUG PluginManager 'Lookup' found 13 plugins
2019-11-10 20:53:02,831 main DEBUG Building Plugin[name=layout, class=org.apache.logging.log4j.core.layout.PatternLayout].
2019-11-10 20:53:02,844 main DEBUG PluginManager 'TypeConverter' found 23 plugins
2019-11-10 20:53:02,857 main DEBUG PatternLayout$Builder(pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n", PatternSelector=null, Configuration(C:\Users\heiko\workspace\HAP-Java\target\classes\log4j2.xml), Replace=null, charset="null", alwaysWriteExceptions="null", noConsoleNoAnsi="null", header="null", footer="null")
2019-11-10 20:53:02,858 main DEBUG PluginManager 'Converter' found 41 plugins
2019-11-10 20:53:02,858 main DEBUG Building Plugin[name=appender, class=org.apache.logging.log4j.core.appender.ConsoleAppender].
2019-11-10 20:53:02,868 main DEBUG ConsoleAppender$Builder(target="SYSTEM_OUT", follow="null", direct="null", bufferedIo="null", bufferSize="null", immediateFlush="null", ignoreExceptions="null", PatternLayout(%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n), name="Console", Filter=null)
2019-11-10 20:53:02,869 main DEBUG Jansi is not installed, cannot find org.fusesource.jansi.WindowsAnsiOutputStream
2019-11-10 20:53:02,869 main DEBUG Starting OutputStreamManager SYSTEM_OUT.false.false
2019-11-10 20:53:02,869 main DEBUG Building Plugin[name=appenders, class=org.apache.logging.log4j.core.config.AppendersPlugin].
2019-11-10 20:53:02,871 main DEBUG createAppenders(={Console})
2019-11-10 20:53:02,872 main DEBUG Building Plugin[name=AppenderRef, class=org.apache.logging.log4j.core.config.AppenderRef].
2019-11-10 20:53:02,879 main DEBUG createAppenderRef(ref="Console", level="null", Filter=null)
2019-11-10 20:53:02,880 main DEBUG Building Plugin[name=root, class=org.apache.logging.log4j.core.config.LoggerConfig$RootLogger].
2019-11-10 20:53:02,881 main DEBUG createLogger(additivity="null", level="DEBUG", includeLocation="null", ={Console}, ={}, Configuration(C:\Users\heiko\workspace\HAP-Java\target\classes\log4j2.xml), Filter=null)
2019-11-10 20:53:02,886 main DEBUG Building Plugin[name=loggers, class=org.apache.logging.log4j.core.config.LoggersPlugin].
2019-11-10 20:53:02,887 main DEBUG createLoggers(={root})
2019-11-10 20:53:02,889 main DEBUG Configuration XmlConfiguration[location=C:\Users\heiko\workspace\HAP-Java\target\classes\log4j2.xml] initialized
2019-11-10 20:53:02,889 main DEBUG Starting configuration XmlConfiguration[location=C:\Users\heiko\workspace\HAP-Java\target\classes\log4j2.xml]
2019-11-10 20:53:02,889 main DEBUG Started configuration XmlConfiguration[location=C:\Users\heiko\workspace\HAP-Java\target\classes\log4j2.xml] OK.
2019-11-10 20:53:02,890 main DEBUG Shutting down OutputStreamManager SYSTEM_OUT.false.false-1
2019-11-10 20:53:02,890 main DEBUG Shut down OutputStreamManager SYSTEM_OUT.false.false-1, all resources released: true
2019-11-10 20:53:02,891 main DEBUG Stopped org.apache.logging.log4j.core.config.DefaultConfiguration@311d617d OK
2019-11-10 20:53:02,943 main DEBUG Registering MBean org.apache.logging.log4j2:type=73d16e93
2019-11-10 20:53:02,947 main DEBUG Registering MBean org.apache.logging.log4j2:type=73d16e93,component=StatusLogger
2019-11-10 20:53:02,949 main DEBUG Registering MBean org.apache.logging.log4j2:type=73d16e93,component=ContextSelector
2019-11-10 20:53:02,952 main DEBUG Registering MBean org.apache.logging.log4j2:type=73d16e93,component=Loggers,name=
2019-11-10 20:53:02,954 main DEBUG Registering MBean org.apache.logging.log4j2:type=73d16e93,component=Appenders,name=Console
2019-11-10 20:53:02,957 main DEBUG Reconfiguration complete for context[name=73d16e93] at URI C:\Users\heiko\workspace\HAP-Java\target\classes\log4j2.xml (org.apache.logging.log4j.core.LoggerContext@2a798d51) with optional ClassLoader: null
2019-11-10 20:53:02,957 main DEBUG Shutdown hook enabled. Registering a new one.
2019-11-10 20:53:02,959 main DEBUG LoggerContext[name=73d16e93, org.apache.logging.log4j.core.LoggerContext@2a798d51] started OK.
20:53:02.969 [main] DEBUG io.github.hapjava.HomekitRoot - foo
The PIN for pairing is 131-45-154
20:53:03.614 [main] INFO  io.github.hapjava.HomekitRoot - Added accessory Test Bridge
State has changed! Writing
20:53:03.623 [main] INFO  io.github.hapjava.HomekitRoot - Added accessory Test Lightbulb
20:53:03.643 [main] DEBUG io.netty.util.internal.logging.InternalLoggerFactory - Using SLF4J as the default logging framework
20:53:03.652 [main] DEBUG io.netty.util.internal.PlatformDependent0 - java.nio.Buffer.address: available
20:53:03.653 [main] DEBUG io.netty.util.internal.PlatformDependent0 - sun.misc.Unsafe.theUnsafe: available
20:53:03.653 [main] DEBUG io.netty.util.internal.PlatformDependent0 - sun.misc.Unsafe.copyMemory: available
20:53:03.653 [main] DEBUG io.netty.util.internal.PlatformDependent0 - java.nio.Bits.unaligned: true
20:53:03.654 [main] DEBUG io.netty.util.internal.PlatformDependent - Platform: Windows
20:53:03.655 [main] DEBUG io.netty.util.internal.PlatformDependent - Java version: 8
20:53:03.655 [main] DEBUG io.netty.util.internal.PlatformDependent - -Dio.netty.noUnsafe: false
20:53:03.655 [main] DEBUG io.netty.util.internal.PlatformDependent - sun.misc.Unsafe: available
20:53:03.655 [main] DEBUG io.netty.util.internal.PlatformDependent - -Dio.netty.noJavassist: false
20:53:03.656 [main] DEBUG io.netty.util.internal.PlatformDependent - Javassist: unavailable
20:53:03.656 [main] DEBUG io.netty.util.internal.PlatformDependent - You don't have Javassist in your class path or you don't have enough permission to load dynamically generated classes.  Please check the configuration for better performance.
20:53:03.656 [main] DEBUG io.netty.util.internal.PlatformDependent - -Dio.netty.tmpdir: C:\Users\heiko\AppData\Local\Temp (java.io.tmpdir)
20:53:03.657 [main] DEBUG io.netty.util.internal.PlatformDependent - -Dio.netty.bitMode: 64 (sun.arch.data.model)
20:53:03.657 [main] DEBUG io.netty.util.internal.PlatformDependent - -Dio.netty.noPreferDirect: false
20:53:03.668 [main] DEBUG io.netty.channel.MultithreadEventLoopGroup - -Dio.netty.eventLoopThreads: 8
20:53:03.674 [main] DEBUG io.netty.channel.nio.NioEventLoop - -Dio.netty.noKeySetOptimization: false
20:53:03.675 [main] DEBUG io.netty.channel.nio.NioEventLoop - -Dio.netty.selectorAutoRebuildThreshold: 512
20:53:04.065 [main] DEBUG io.netty.util.internal.ThreadLocalRandom - -Dio.netty.initialSeedUniquifier: 0x4747fc96431efde6 (took 1 ms)
20:53:04.097 [main] DEBUG io.netty.buffer.ByteBufUtil - -Dio.netty.allocator.type: unpooled
20:53:04.097 [main] DEBUG io.netty.buffer.ByteBufUtil - -Dio.netty.threadLocalDirectBufferSize: 65536
20:53:04.400 [main] DEBUG io.netty.util.NetUtil - Loopback interface: lo (Software Loopback Interface 1, 127.0.0.1)
20:53:04.401 [main] DEBUG io.netty.util.NetUtil - \proc\sys\net\core\somaxconn: 200 (non-existent)
20:53:04.407 [nioEventLoopGroup-2-1] INFO  io.netty.handler.logging.LoggingHandler - [id: 0xe64a50a7] REGISTERED
20:53:04.408 [nioEventLoopGroup-2-1] INFO  io.netty.handler.logging.LoggingHandler - [id: 0xe64a50a7] BIND(LAPTOP-D3SSRIQB/192.168.50.114:9123)
20:53:04.410 [nioEventLoopGroup-2-1] INFO  io.github.hapjava.impl.http.impl.NettyHomekitHttpService - Bound homekit listener to /192.168.50.114:9123
20:53:04.410 [nioEventLoopGroup-2-1] INFO  io.github.hapjava.impl.jmdns.JmdnsHomekitAdvertiser - Advertising accessory Test Bridge
20:53:04.410 [nioEventLoopGroup-2-1] INFO  io.github.hapjava.impl.jmdns.JmdnsHomekitAdvertiser - Registering _hap._tcp.local. on port 9123
20:53:11.159 [nioEventLoopGroup-2-1] INFO  io.netty.handler.logging.LoggingHandler - [id: 0xe64a50a7, /192.168.50.114:9123] ACTIVE
20:53:18.156 [nioEventLoopGroup-2-1] INFO  io.netty.handler.logging.LoggingHandler - [id: 0xe64a50a7, /192.168.50.114:9123] RECEIVED: [id: 0xc4300328, /192.168.50.126:52940 => /192.168.50.114:9123]
20:53:18.174 [nioEventLoopGroup-3-1] DEBUG io.netty.util.ResourceLeakDetector - -Dio.netty.leakDetection.level: simple
20:53:18.174 [nioEventLoopGroup-3-1] DEBUG io.netty.util.ResourceLeakDetector - -Dio.netty.leakDetection.maxRecords: 4
20:53:18.198 [defaultEventExecutorGroup-4-1] INFO  io.github.hapjava.impl.http.impl.AccessoryHandler - New homekit connection from /192.168.50.126:52940
20:53:18.198 [nioEventLoopGroup-3-1] DEBUG io.netty.util.Recycler - -Dio.netty.recycler.maxCapacity.default: 262144
20:53:18.209 [defaultEventExecutorGroup-4-1] INFO  io.github.hapjava.impl.pairing.PairingManager - Starting pair for Test Bridge
20:53:18.330 [defaultEventExecutorGroup-4-1] INFO  io.github.hapjava.impl.http.HomekitClientConnection - 200 /pair-setup
20:53:18.334 [defaultEventExecutorGroup-4-1] DEBUG io.netty.util.internal.Cleaner0 - java.nio.ByteBuffer.cleaner(): available
20:53:21.922 [defaultEventExecutorGroup-4-1] INFO  io.github.hapjava.impl.http.impl.AccessoryHandler - Terminated homekit connection from /192.168.50.126:52940
---> 5 secs later i am done with enter the secure code on iPhone

Here a tcpdum of the connection:
192.168.50.114 == notebook
192.168.50.126 == iPhone

homekit_pairing.zip

yfre commented

thanks for details @GreenRover
i have two good news:

  • i could reproduce it with the sample and got exactly the same logs, behaviour and network traffic.
  • i found the issue/solution.

it does not like spaces in the bridge name. :(
please change in Main.java
HomekitRoot bridge = homekit.createBridge(mockAuth, "Test Bridge", "TestBridge, Inc.", "G6", "111abe234");
to
HomekitRoot bridge = homekit.createBridge(mockAuth, "TestBridge", "TestBridge, Inc.", "G6", "111abe234");

and try again.

@yfre Now i get some steps further

Iphone XS IOS 13.1.3
Swiss/German

Server:
Java 1.8.0 201 Oracle JDK

23:04:56.586 [defaultEventExecutorGroup-4-1] INFO  io.github.hapjava.impl.http.impl.AccessoryHandler - New homekit connection from /192.168.50.126:52997
23:04:56.589 [nioEventLoopGroup-3-1] DEBUG io.netty.util.Recycler - -Dio.netty.recycler.maxCapacity.default: 262144
23:04:56.640 [defaultEventExecutorGroup-4-1] INFO  io.github.hapjava.impl.pairing.PairingManager - Starting pair for baaaa
23:04:56.861 [defaultEventExecutorGroup-4-1] INFO  io.github.hapjava.impl.http.HomekitClientConnection - 200 /pair-setup
23:04:56.865 [defaultEventExecutorGroup-4-1] DEBUG io.netty.util.internal.Cleaner0 - java.nio.ByteBuffer.cleaner(): available
23:05:03.961 [defaultEventExecutorGroup-4-1] DEBUG io.github.hapjava.impl.pairing.PairingManager - Entering second stage of pair for baaaa
23:05:04.100 [defaultEventExecutorGroup-4-1] INFO  io.github.hapjava.impl.http.HomekitClientConnection - 200 /pair-setup
23:05:04.145 [defaultEventExecutorGroup-4-1] DEBUG io.github.hapjava.impl.pairing.PairingManager - Entering third stage of pair for baaaa
Added pairing for aa:d4:e3:18:17:b6E012AC74-5B04-42DC-81EF-9A82F3FF4F64
State has changed! Writing
23:05:04.412 [defaultEventExecutorGroup-4-1] INFO  io.github.hapjava.impl.jmdns.JmdnsHomekitAdvertiser - Re-creating service due to change in discoverability to false
23:05:06.418 [defaultEventExecutorGroup-4-1] INFO  io.github.hapjava.impl.jmdns.JmdnsHomekitAdvertiser - Registering _hap._tcp.local. on port 9124
23:05:08.992 [defaultEventExecutorGroup-4-1] INFO  io.github.hapjava.impl.http.HomekitClientConnection - 200 /pair-setup
23:05:08.993 [defaultEventExecutorGroup-4-1] INFO  io.github.hapjava.impl.http.impl.AccessoryHandler - Terminated homekit connection from /192.168.50.126:52997

HomeKit_Pairing2.zip

@yfre No that changes nothing.
Same problem as before.

Iphone XS IOS 13.1.3
Swiss/German

Server:
Java 1.8.0 201 Oracle JDK

Does not change anything for me as well. iPhone XS iOS 13.2.2

yfre commented

hmm. i did some tests. it does not really stable. sometimes it works, sometime it doesnt.. kind of 50/50. need to investigate further
here is my log when it works.

defaultEventExecutorGroup-4-1] INFO io.github.hapjava.impl.pairing.PairingManager - Starting pair for TestBridge
[defaultEventExecutorGroup-4-1] INFO io.github.hapjava.impl.http.HomekitClientConnection - 200 /pair-setup
[defaultEventExecutorGroup-4-1] DEBUG io.netty.util.internal.Cleaner0 - java.nio.ByteBuffer.cleaner(): available
[defaultEventExecutorGroup-4-1] DEBUG io.github.hapjava.impl.pairing.PairingManager - Entering second stage of pair for TestBridge
[defaultEventExecutorGroup-4-1] INFO io.github.hapjava.impl.http.HomekitClientConnection - 200 /pair-setup
[defaultEventExecutorGroup-4-1] DEBUG io.github.hapjava.impl.pairing.PairingManager - Entering third stage of pair for TestBridge
Added pairing for 6e:4f:3f:30:a:ceBA18A45D-721F-48C1-94AD-81F9B120D169
State has changed! Writing
[defaultEventExecutorGroup-4-1] INFO io.github.hapjava.impl.jmdns.JmdnsHomekitAdvertiser - Re-creating service due to change in discoverability to false
[defaultEventExecutorGroup-4-1] INFO io.github.hapjava.impl.jmdns.JmdnsHomekitAdvertiser - Registering _hap._tcp.local. on port 9123
[defaultEventExecutorGroup-4-1] INFO io.github.hapjava.impl.http.HomekitClientConnection - 200 /pair-setup
[defaultEventExecutorGroup-4-1] INFO io.github.hapjava.impl.http.impl.AccessoryHandler - Terminated homekit connection from /192.168.1.71:53255
[nioEventLoopGroup-2-1] INFO io.netty.handler.logging.LoggingHandler - [id: 0x0d199f2a, /192.168.1.79:9123] RECEIVED: [id: 0xbb245cae, /192.168.1.71:53257 => /192.168.1.79:9123]
[defaultEventExecutorGroup-4-2] INFO io.github.hapjava.impl.http.impl.AccessoryHandler - New homekit connection from /192.168.1.71:53257
[defaultEventExecutorGroup-4-2] DEBUG io.github.hapjava.impl.pairing.PairVerificationManager - Starting pair verification for TestBridge
[defaultEventExecutorGroup-4-2] INFO io.github.hapjava.impl.http.HomekitClientConnection - 200 /pair-verify
[defaultEventExecutorGroup-4-2] DEBUG io.github.hapjava.impl.pairing.PairVerificationManager - Completed pair verification for TestBridge
[defaultEventExecutorGroup-4-2] INFO io.github.hapjava.impl.http.HomekitClientConnection - 200 /pair-verify
[nioEventLoopGroup-3-2] DEBUG io.github.hapjava.impl.http.impl.BinaryHandler - Received data [/192.168.1.71:53257]:
GET /accessories HTTP/1.1
Host: TestBridge._hap._tcp.local 
yfre commented

@GreenRover @christiantschoerner
can i ask you to do one more test with this hap jar
https://1drv.ms/u/s!AqqiEfFRr6WAgYQ-iybGMnJ0B6GYRQ?e=QrzsNr

as many are affected i want to get this fixed asap.

@yfre (-; That worked (tested 1 times, later more tests, the add device button of my iPhone wont work any more)

2019-11-11 06:27:36,973 main DEBUG Initializing configuration XmlConfiguration[location=C:\Users\heiko\workspace2\HAP-Jar\bin\log4j2.xml]
2019-11-11 06:27:36,980 main DEBUG Installed script engines
2019-11-11 06:27:37,332 main DEBUG Oracle Nashorn Version: 1.8.0_201, Language: ECMAScript, Threading: Not Thread Safe, Compile: true, Names: {nashorn, Nashorn, js, JS, JavaScript, javascript, ECMAScript, ecmascript}
2019-11-11 06:27:37,335 main DEBUG PluginManager 'Core' found 107 plugins
2019-11-11 06:27:37,337 main DEBUG PluginManager 'Level' found 0 plugins
2019-11-11 06:27:37,342 main DEBUG Log4j2 ConfigurationScheduler: No scheduled items
2019-11-11 06:27:37,342 main DEBUG PluginManager 'Lookup' found 13 plugins
2019-11-11 06:27:37,344 main DEBUG Building Plugin[name=layout, class=org.apache.logging.log4j.core.layout.PatternLayout].
2019-11-11 06:27:37,357 main DEBUG PluginManager 'TypeConverter' found 23 plugins
2019-11-11 06:27:37,372 main DEBUG PatternLayout$Builder(pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n", PatternSelector=null, Configuration(C:\Users\heiko\workspace2\HAP-Jar\bin\log4j2.xml), Replace=null, charset="null", alwaysWriteExceptions="null", noConsoleNoAnsi="null", header="null", footer="null")
2019-11-11 06:27:37,373 main DEBUG PluginManager 'Converter' found 41 plugins
2019-11-11 06:27:37,374 main DEBUG Building Plugin[name=appender, class=org.apache.logging.log4j.core.appender.ConsoleAppender].
2019-11-11 06:27:37,385 main DEBUG ConsoleAppender$Builder(target="SYSTEM_OUT", follow="null", direct="null", bufferedIo="null", bufferSize="null", immediateFlush="null", ignoreExceptions="null", PatternLayout(%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n), name="Console", Filter=null)
2019-11-11 06:27:37,386 main DEBUG Jansi is not installed, cannot find org.fusesource.jansi.WindowsAnsiOutputStream
2019-11-11 06:27:37,387 main DEBUG Starting OutputStreamManager SYSTEM_OUT.false.false
2019-11-11 06:27:37,387 main DEBUG Building Plugin[name=appenders, class=org.apache.logging.log4j.core.config.AppendersPlugin].
2019-11-11 06:27:37,395 main DEBUG createAppenders(={Console})
2019-11-11 06:27:37,396 main DEBUG Building Plugin[name=AppenderRef, class=org.apache.logging.log4j.core.config.AppenderRef].
2019-11-11 06:27:37,405 main DEBUG createAppenderRef(ref="Console", level="null", Filter=null)
2019-11-11 06:27:37,405 main DEBUG Building Plugin[name=root, class=org.apache.logging.log4j.core.config.LoggerConfig$RootLogger].
2019-11-11 06:27:37,406 main DEBUG createLogger(additivity="null", level="DEBUG", includeLocation="null", ={Console}, ={}, Configuration(C:\Users\heiko\workspace2\HAP-Jar\bin\log4j2.xml), Filter=null)
2019-11-11 06:27:37,413 main DEBUG Building Plugin[name=loggers, class=org.apache.logging.log4j.core.config.LoggersPlugin].
2019-11-11 06:27:37,414 main DEBUG createLoggers(={root})
2019-11-11 06:27:37,415 main DEBUG Configuration XmlConfiguration[location=C:\Users\heiko\workspace2\HAP-Jar\bin\log4j2.xml] initialized
2019-11-11 06:27:37,415 main DEBUG Starting configuration XmlConfiguration[location=C:\Users\heiko\workspace2\HAP-Jar\bin\log4j2.xml]
2019-11-11 06:27:37,415 main DEBUG Started configuration XmlConfiguration[location=C:\Users\heiko\workspace2\HAP-Jar\bin\log4j2.xml] OK.
2019-11-11 06:27:37,416 main DEBUG Shutting down OutputStreamManager SYSTEM_OUT.false.false-1
2019-11-11 06:27:37,416 main DEBUG Shut down OutputStreamManager SYSTEM_OUT.false.false-1, all resources released: true
2019-11-11 06:27:37,417 main DEBUG Stopped org.apache.logging.log4j.core.config.DefaultConfiguration@5e8c92f4 OK
2019-11-11 06:27:37,509 main DEBUG Registering MBean org.apache.logging.log4j2:type=73d16e93
2019-11-11 06:27:37,514 main DEBUG Registering MBean org.apache.logging.log4j2:type=73d16e93,component=StatusLogger
2019-11-11 06:27:37,516 main DEBUG Registering MBean org.apache.logging.log4j2:type=73d16e93,component=ContextSelector
2019-11-11 06:27:37,518 main DEBUG Registering MBean org.apache.logging.log4j2:type=73d16e93,component=Loggers,name=
2019-11-11 06:27:37,520 main DEBUG Registering MBean org.apache.logging.log4j2:type=73d16e93,component=Appenders,name=Console
2019-11-11 06:27:37,523 main DEBUG Reconfiguration complete for context[name=73d16e93] at URI C:\Users\heiko\workspace2\HAP-Jar\bin\log4j2.xml (org.apache.logging.log4j.core.LoggerContext@359f7cdf) with optional ClassLoader: null
2019-11-11 06:27:37,525 main DEBUG Shutdown hook enabled. Registering a new one.
2019-11-11 06:27:37,527 main DEBUG LoggerContext[name=73d16e93, org.apache.logging.log4j.core.LoggerContext@359f7cdf] started OK.
06:27:37.983 [main] DEBUG io.github.hapjava.HomekitRoot - foo
The PIN for pairing is 131-45-154
06:27:38.683 [main] INFO  io.github.hapjava.HomekitRoot - Added accessory baaaa
State has changed! Writing
06:27:38.701 [main] INFO  io.github.hapjava.HomekitRoot - Added accessory Test Lightbulb
06:27:38.723 [main] DEBUG io.netty.util.internal.logging.InternalLoggerFactory - Using SLF4J as the default logging framework
06:27:38.735 [main] DEBUG io.netty.util.internal.PlatformDependent0 - java.nio.Buffer.address: available
06:27:38.735 [main] DEBUG io.netty.util.internal.PlatformDependent0 - sun.misc.Unsafe.theUnsafe: available
06:27:38.736 [main] DEBUG io.netty.util.internal.PlatformDependent0 - sun.misc.Unsafe.copyMemory: available
06:27:38.736 [main] DEBUG io.netty.util.internal.PlatformDependent0 - java.nio.Bits.unaligned: true
06:27:38.737 [main] DEBUG io.netty.util.internal.PlatformDependent - Platform: Windows
06:27:38.738 [main] DEBUG io.netty.util.internal.PlatformDependent - Java version: 8
06:27:38.739 [main] DEBUG io.netty.util.internal.PlatformDependent - -Dio.netty.noUnsafe: false
06:27:38.739 [main] DEBUG io.netty.util.internal.PlatformDependent - sun.misc.Unsafe: available
06:27:38.739 [main] DEBUG io.netty.util.internal.PlatformDependent - -Dio.netty.noJavassist: false
06:27:38.740 [main] DEBUG io.netty.util.internal.PlatformDependent - Javassist: unavailable
06:27:38.740 [main] DEBUG io.netty.util.internal.PlatformDependent - You don't have Javassist in your class path or you don't have enough permission to load dynamically generated classes.  Please check the configuration for better performance.
06:27:38.740 [main] DEBUG io.netty.util.internal.PlatformDependent - -Dio.netty.tmpdir: C:\Users\heiko\AppData\Local\Temp (java.io.tmpdir)
06:27:38.741 [main] DEBUG io.netty.util.internal.PlatformDependent - -Dio.netty.bitMode: 64 (sun.arch.data.model)
06:27:38.741 [main] DEBUG io.netty.util.internal.PlatformDependent - -Dio.netty.noPreferDirect: false
06:27:38.751 [main] DEBUG io.netty.channel.MultithreadEventLoopGroup - -Dio.netty.eventLoopThreads: 8
06:27:38.760 [main] DEBUG io.netty.channel.nio.NioEventLoop - -Dio.netty.noKeySetOptimization: false
06:27:38.760 [main] DEBUG io.netty.channel.nio.NioEventLoop - -Dio.netty.selectorAutoRebuildThreshold: 512
06:27:38.825 [main] DEBUG io.netty.util.internal.ThreadLocalRandom - -Dio.netty.initialSeedUniquifier: 0x5c1fe64bbf098685 (took 1 ms)
06:27:38.870 [main] DEBUG io.netty.buffer.ByteBufUtil - -Dio.netty.allocator.type: unpooled
06:27:38.870 [main] DEBUG io.netty.buffer.ByteBufUtil - -Dio.netty.threadLocalDirectBufferSize: 65536
06:27:39.211 [main] DEBUG io.netty.util.NetUtil - Loopback interface: lo (Software Loopback Interface 1, 127.0.0.1)
06:27:39.213 [main] DEBUG io.netty.util.NetUtil - \proc\sys\net\core\somaxconn: 200 (non-existent)
06:27:39.219 [nioEventLoopGroup-2-1] DEBUG io.netty.handler.logging.LoggingHandler - [id: 0xaa9e789b] REGISTERED
06:27:39.221 [nioEventLoopGroup-2-1] DEBUG io.netty.handler.logging.LoggingHandler - [id: 0xaa9e789b] BIND(LAPTOP-D3SSRIQB/192.168.50.114:9124)
06:27:39.222 [nioEventLoopGroup-2-1] INFO  io.github.hapjava.impl.http.impl.NettyHomekitHttpService - Bound homekit listener to /192.168.50.114:9124
06:27:39.222 [nioEventLoopGroup-2-1] INFO  io.github.hapjava.impl.jmdns.JmdnsHomekitAdvertiser - Advertising accessory baaaa
06:27:39.222 [nioEventLoopGroup-2-1] INFO  io.github.hapjava.impl.jmdns.JmdnsHomekitAdvertiser - Registering _hap._tcp.local. on port 9124
06:27:46.360 [nioEventLoopGroup-2-1] DEBUG io.netty.handler.logging.LoggingHandler - [id: 0xaa9e789b, /192.168.50.114:9124] ACTIVE
06:27:50.565 [nioEventLoopGroup-2-1] DEBUG io.netty.handler.logging.LoggingHandler - [id: 0xaa9e789b, /192.168.50.114:9124] RECEIVED: [id: 0xeb79bb51, /192.168.50.126:53114 => /192.168.50.114:9124]
06:27:50.582 [nioEventLoopGroup-3-1] DEBUG io.netty.util.ResourceLeakDetector - -Dio.netty.leakDetection.level: simple
06:27:50.582 [nioEventLoopGroup-3-1] DEBUG io.netty.util.ResourceLeakDetector - -Dio.netty.leakDetection.maxRecords: 4
06:27:50.610 [nioEventLoopGroup-3-1] DEBUG io.netty.util.Recycler - -Dio.netty.recycler.maxCapacity.default: 262144
06:27:50.610 [defaultEventExecutorGroup-4-1] INFO  io.github.hapjava.impl.http.impl.AccessoryHandler - New homekit connection from /192.168.50.126:53114
06:27:50.619 [defaultEventExecutorGroup-4-1] DEBUG io.github.hapjava.impl.http.HomekitClientConnection - doHandleRequest: /pair-setupis upgraded:false
06:27:50.625 [defaultEventExecutorGroup-4-1] INFO  io.github.hapjava.impl.pairing.PairingManager - Starting pair for baaaa
06:27:50.777 [defaultEventExecutorGroup-4-1] INFO  io.github.hapjava.impl.http.HomekitClientConnection - 200 /pair-setup
06:27:50.785 [defaultEventExecutorGroup-4-1] DEBUG io.netty.util.internal.Cleaner0 - java.nio.ByteBuffer.cleaner(): available
06:27:53.591 [defaultEventExecutorGroup-4-1] DEBUG io.github.hapjava.impl.http.HomekitClientConnection - doHandleRequest: /pair-setupis upgraded:false
06:27:53.591 [defaultEventExecutorGroup-4-1] DEBUG io.github.hapjava.impl.pairing.PairingManager - Entering second stage of pair for baaaa
06:27:53.647 [defaultEventExecutorGroup-4-1] INFO  io.github.hapjava.impl.http.HomekitClientConnection - 200 /pair-setup
06:27:53.697 [defaultEventExecutorGroup-4-1] DEBUG io.github.hapjava.impl.http.HomekitClientConnection - doHandleRequest: /pair-setupis upgraded:false
06:27:53.697 [defaultEventExecutorGroup-4-1] DEBUG io.github.hapjava.impl.pairing.PairingManager - Entering third stage of pair for baaaa
06:27:53.810 [defaultEventExecutorGroup-4-1] DEBUG io.github.hapjava.impl.pairing.FinalPairHandler - handle request
06:27:53.829 [defaultEventExecutorGroup-4-1] DEBUG io.github.hapjava.impl.pairing.FinalPairHandler - decrypt plaintext:[B@e7ca986
06:27:53.829 [defaultEventExecutorGroup-4-1] DEBUG io.github.hapjava.impl.pairing.FinalPairHandler - decrypt username:[B@3b499c5
06:27:53.829 [defaultEventExecutorGroup-4-1] DEBUG io.github.hapjava.impl.pairing.FinalPairHandler - decrypt error:null
Added pairing for d2:bb:de:6d:4b:2eE012AC74-5B04-42DC-81EF-9A82F3FF4F64
State has changed! Writing
06:27:53.837 [defaultEventExecutorGroup-4-1] DEBUG io.github.hapjava.impl.pairing.FinalPairHandler - create response
06:27:53.841 [defaultEventExecutorGroup-4-1] DEBUG io.github.hapjava.impl.pairing.FinalPairHandler - create response done
06:27:53.842 [defaultEventExecutorGroup-4-1] INFO  io.github.hapjava.impl.http.HomekitClientConnection - 200 /pair-setup
06:27:53.911 [defaultEventExecutorGroup-4-1] INFO  io.github.hapjava.impl.http.impl.AccessoryHandler - Terminated homekit connection from /192.168.50.126:53114
06:27:53.918 [nioEventLoopGroup-2-1] DEBUG io.netty.handler.logging.LoggingHandler - [id: 0xaa9e789b, /192.168.50.114:9124] RECEIVED: [id: 0xc1e57f64, /192.168.50.126:53115 => /192.168.50.114:9124]
06:27:53.922 [defaultEventExecutorGroup-4-2] INFO  io.github.hapjava.impl.http.impl.AccessoryHandler - New homekit connection from /192.168.50.126:53115
06:27:53.923 [defaultEventExecutorGroup-4-2] DEBUG io.github.hapjava.impl.http.HomekitClientConnection - doHandleRequest: /pair-verifyis upgraded:false
06:27:53.928 [defaultEventExecutorGroup-4-2] DEBUG io.github.hapjava.impl.pairing.PairVerificationManager - Starting pair verification for baaaa
06:27:53.941 [defaultEventExecutorGroup-4-2] INFO  io.github.hapjava.impl.http.HomekitClientConnection - 200 /pair-verify
06:27:54.036 [defaultEventExecutorGroup-4-2] DEBUG io.github.hapjava.impl.http.HomekitClientConnection - doHandleRequest: /pair-verifyis upgraded:false
06:27:54.038 [defaultEventExecutorGroup-4-2] DEBUG io.github.hapjava.impl.pairing.PairVerificationManager - Completed pair verification for baaaa
06:27:54.039 [defaultEventExecutorGroup-4-2] INFO  io.github.hapjava.impl.http.HomekitClientConnection - 200 /pair-verify
06:27:54.068 [nioEventLoopGroup-3-2] DEBUG io.github.hapjava.impl.http.impl.BinaryHandler - Received data [/192.168.50.126:53115]:
GET /accessories HTTP/1.1
Host: baaaa._hap._tcp.local


06:27:54.069 [defaultEventExecutorGroup-4-2] DEBUG io.github.hapjava.impl.http.HomekitClientConnection - doHandleRequest: /accessoriesis upgraded:true
06:27:54.093 [defaultEventExecutorGroup-4-2] INFO  io.github.hapjava.impl.http.HomekitClientConnection - 200 /accessories
06:27:54.094 [nioEventLoopGroup-3-2] DEBUG io.github.hapjava.impl.http.impl.BinaryHandler - Sending data [/192.168.50.126:53115]:
HTTP/1.1 200 OK
Content-type: application/hap+json
Content-Length: 1850
Connection: keep-alive

{"accessories":[{"aid":1,"services":[{"iid":1,"type":"3E","characteristics":[{"iid":2,"type":"23","perms":["pr"],"format":"string","ev":false,"description":"Name of the accessory","value":"baaaa","maxLen":255},{"iid":3,"type":"20","perms":["pr"],"format":"string","ev":false,"description":"The name of the manufacturer","value":"foooo","maxLen":255},{"iid":4,"type":"21","perms":["pr"],"format":"string","ev":false,"description":"The name of the model","value":"G6","maxLen":255},{"iid":5,"type":"30","perms":["pr"],"format":"string","ev":false,"description":"The serial number of the accessory","value":"123456789","maxLen":255},{"iid":6,"type":"14","perms":["pw"],"format":"bool","ev":false,"description":"Identifies the accessory via a physical action on the accessory"}]}]},{"aid":2,"services":[{"iid":1,"type":"3E","characteristics":[{"iid":2,"type":"23","perms":["pr"],"format":"string","ev":false,"description":"Name of the accessory","value":"Test Lightbulb","maxLen":255},{"iid":3,"type":"20","perms":["pr"],"format":"string","ev":false,"description":"The name of the manufacturer","value":"none","maxLen":255},{"iid":4,"type":"21","perms":["pr"],"format":"string","ev":false,"description":"The name of the model","value":"none","maxLen":255},{"iid":5,"type":"30","perms":["pr"],"format":"string","ev":false,"description":"The serial number of the accessory","value":"none","maxLen":255},{"iid":6,"type":"14","perms":["pw"],"format":"bool","ev":false,"description":"Identifies the accessory via a physical action on the accessory"}]},{"iid":7,"type":"43","characteristics":[{"iid":8,"type":"23","perms":["pr"],"format":"string","ev":false,"description":"Name of the accessory","value":"Test Lightbulb","maxLen":255},{"iid":9,"type":"25","perms":["pw","pr","ev"],"format":"bool","ev":false,"description":"Turn on and off","value":false}]}]}]}
06:27:54.205 [nioEventLoopGroup-3-2] DEBUG io.github.hapjava.impl.http.impl.BinaryHandler - Received data [/192.168.50.126:53115]:
PUT /characteristics HTTP/1.1
Host: baaaa._hap._tcp.local
Content-Length: 49
Content-Type: application/hap+json

{"characteristics":[{"aid":2,"iid":9,"ev":true}]}
06:27:54.205 [defaultEventExecutorGroup-4-2] DEBUG io.github.hapjava.impl.http.HomekitClientConnection - doHandleRequest: /characteristicsis upgraded:true
06:27:54.223 [defaultEventExecutorGroup-4-2] DEBUG io.github.hapjava.impl.connections.SubscriptionManager - Added subscription to class io.github.hapjava.impl.characteristics.common.PowerStateCharacteristic for 872651142
06:27:54.224 [defaultEventExecutorGroup-4-2] INFO  io.github.hapjava.impl.http.HomekitClientConnection - 204 /characteristics
06:27:54.225 [nioEventLoopGroup-3-2] DEBUG io.github.hapjava.impl.http.impl.BinaryHandler - Sending data [/192.168.50.126:53115]:
HTTP/1.1 204 No Content
Content-type: application/hap+json
Content-Length: 0
Connection: keep-alive


06:27:54.392 [nioEventLoopGroup-3-2] DEBUG io.github.hapjava.impl.http.impl.BinaryHandler - Received data [/192.168.50.126:53115]:
PUT /characteristics HTTP/1.1
Host: baaaa._hap._tcp.local
Content-Length: 49
Content-Type: application/hap+json

{"characteristics":[{"aid":2,"iid":9,"ev":true}]}
06:27:54.392 [defaultEventExecutorGroup-4-2] DEBUG io.github.hapjava.impl.http.HomekitClientConnection - doHandleRequest: /characteristicsis upgraded:true
06:27:54.393 [defaultEventExecutorGroup-4-2] DEBUG io.github.hapjava.impl.connections.SubscriptionManager - Added subscription to class io.github.hapjava.impl.characteristics.common.PowerStateCharacteristic for 872651142
06:27:54.393 [defaultEventExecutorGroup-4-2] INFO  io.github.hapjava.impl.http.HomekitClientConnection - 204 /characteristics
06:27:54.394 [nioEventLoopGroup-3-2] DEBUG io.github.hapjava.impl.http.impl.BinaryHandler - Sending data [/192.168.50.126:53115]:
HTTP/1.1 204 No Content
Content-type: application/hap+json
Content-Length: 0
Connection: keep-alive


06:27:54.465 [nioEventLoopGroup-3-2] DEBUG io.github.hapjava.impl.http.impl.BinaryHandler - Received data [/192.168.50.126:53115]:
PUT /characteristics HTTP/1.1
Host: baaaa._hap._tcp.local
Content-Length: 49
Content-Type: application/hap+json

{"characteristics":[{"aid":2,"iid":9,"ev":true}]}
06:27:54.465 [defaultEventExecutorGroup-4-2] DEBUG io.github.hapjava.impl.http.HomekitClientConnection - doHandleRequest: /characteristicsis upgraded:true
06:27:54.466 [defaultEventExecutorGroup-4-2] DEBUG io.github.hapjava.impl.connections.SubscriptionManager - Added subscription to class io.github.hapjava.impl.characteristics.common.PowerStateCharacteristic for 872651142
06:27:54.466 [defaultEventExecutorGroup-4-2] INFO  io.github.hapjava.impl.http.HomekitClientConnection - 204 /characteristics
06:27:54.466 [nioEventLoopGroup-3-2] DEBUG io.github.hapjava.impl.http.impl.BinaryHandler - Sending data [/192.168.50.126:53115]:
HTTP/1.1 204 No Content
Content-type: application/hap+json
Content-Length: 0
Connection: keep-alive


06:27:54.746 [nioEventLoopGroup-3-2] DEBUG io.github.hapjava.impl.http.impl.BinaryHandler - Received data [/192.168.50.126:53115]:
GET /characteristics?id=2.9 HTTP/1.1
Host: baaaa._hap._tcp.local


06:27:54.746 [defaultEventExecutorGroup-4-2] DEBUG io.github.hapjava.impl.http.HomekitClientConnection - doHandleRequest: /characteristics?id=2.9is upgraded:true
06:27:54.748 [defaultEventExecutorGroup-4-2] INFO  io.github.hapjava.impl.http.HomekitClientConnection - 200 /characteristics?id=2.9
06:27:54.749 [nioEventLoopGroup-3-2] DEBUG io.github.hapjava.impl.http.impl.BinaryHandler - Sending data [/192.168.50.126:53115]:
HTTP/1.1 200 OK
Content-type: application/hap+json
Content-Length: 53
Connection: keep-alive

{"characteristics":[{"value":false,"aid":2,"iid":9}]}
06:28:37.382 [nioEventLoopGroup-3-2] DEBUG io.github.hapjava.impl.http.impl.BinaryHandler - Received data [/192.168.50.126:53115]:

06:28:37.382 [defaultEventExecutorGroup-4-2] INFO  io.github.hapjava.impl.http.impl.AccessoryHandler - Terminated homekit connection from /192.168.50.126:53115

Looks good for me too, had a chance to try it a few times. Nice work!

yfre commented

ok. background:
bridge (java-hap) must mark itself as bound/non discoverable once the pairing is successfully completed. this should ensure the bridge is linked to only one controller / icloud account.
we did it a little too early - just before that last step of pairing. ios12 was fine with it, ios13 is dropping pairing immediately when controller gets marked as bound. depending on exact order of messages: bound info or pairing completion, it was sometimes working sometimes not.

the quick fix was: do not mark as bound at all, keep it discoverable.
now i will try to implement the proper solution - mark as bound after the last step of pairing.

Way back in iOS9, there was an issue caused by leaving the advertisement discoverable. Given the success Apple has with driving upgrades, it's probably not worth maintaining backwards compatibility with older iOS versions, but thought I'd point it out: de6822d#diff-066f526e6b621ce14b59cda4b6dc2a81

J-N-K commented

Way back in iOS9, there was an issue caused by leaving the advertisement discoverable. Given the success Apple has with driving upgrades, it's probably not worth maintaining backwards compatibility with older iOS versions, but thought I'd point it out:

I agree. If this solution works on 10-13 we should be good (10 is the last to work in iPad 4 and iPhone 5s).

So consensus is to merge #95 as-is?

So guys what is the final result. Do we have a fix or not :D

As i understand it it only was a temporary fix. Or is there still a final one?

@yfre can you please update the status?

yfre commented

added one more change to PR to ensure discoverability is disabled once pairing is completed. works fine with ios13 but could not test with older version.
it is final from my perspective.

added one more change to PR to ensure discoverability is disabled once pairing is completed. works fine with ios13 but could not test with older version.
it is final from my perspective.

Okay Am I silly or where can I download this? The last "release" was in March and the last push to production was 2 months ago. And do I need to change anything special in my code?

Hello,
I am trying with the new iOS but its also not working with 13.4. I am the only one struggling with this problem? #95 fixed the discoverability but the pairing issue is still active

yfre commented

Hello,
I am trying with the new iOS but its also not working with 13.4. I am the only one struggling with this problem? #95 fixed the discoverability but the pairing issue is still active

what kind of issue you have? how the log look like?can you try with reduced number of device - e.g. try with a simple switch / light first and once it works, add other devices

Hello,
I am trying with the new iOS but its also not working with 13.4. I am the only one struggling with this problem? #95 fixed the discoverability but the pairing issue is still active

what kind of issue you have? how the log look like?can you try with reduced number of device - e.g. try with a simple switch / light first and once it works, add other devices

I am trying with the Sample project, with the simple MockSwitch.

Using persisted auth
The PIN for pairing is 131-45-154
12:17:17.996 [main] INFO  io.github.hapjava.HomekitRoot - Added accessory TestBridge
State has changed! Writing
12:17:18.077 [main] INFO  io.github.hapjava.HomekitRoot - Added accessory TestLightbulb
12:17:18.107 [main] DEBUG i.n.u.i.l.InternalLoggerFactory - Using SLF4J as the default logging framework
12:17:18.122 [main] DEBUG i.n.util.internal.PlatformDependent0 - java.nio.Buffer.address: available
12:17:18.123 [main] DEBUG i.n.util.internal.PlatformDependent0 - sun.misc.Unsafe.theUnsafe: available
12:17:18.123 [main] DEBUG i.n.util.internal.PlatformDependent0 - sun.misc.Unsafe.copyMemory: available
12:17:18.124 [main] DEBUG i.n.util.internal.PlatformDependent0 - java.nio.Bits.unaligned: true
12:17:18.126 [main] DEBUG i.n.util.internal.PlatformDependent - Java version: 8
12:17:18.126 [main] DEBUG i.n.util.internal.PlatformDependent - -Dio.netty.noUnsafe: false
12:17:18.127 [main] DEBUG i.n.util.internal.PlatformDependent - sun.misc.Unsafe: available
12:17:18.127 [main] DEBUG i.n.util.internal.PlatformDependent - -Dio.netty.noJavassist: false
12:17:18.128 [main] DEBUG i.n.util.internal.PlatformDependent - Javassist: unavailable
12:17:18.128 [main] DEBUG i.n.util.internal.PlatformDependent - You don't have Javassist in your class path or you don't have enough permission to load dynamically generated classes.  Please check the configuration for better performance.
12:17:18.129 [main] DEBUG i.n.util.internal.PlatformDependent - -Dio.netty.tmpdir: /tmp (java.io.tmpdir)
12:17:18.129 [main] DEBUG i.n.util.internal.PlatformDependent - -Dio.netty.bitMode: 64 (sun.arch.data.model)
12:17:18.129 [main] DEBUG i.n.util.internal.PlatformDependent - -Dio.netty.noPreferDirect: false
12:17:18.169 [main] DEBUG i.n.c.MultithreadEventLoopGroup - -Dio.netty.eventLoopThreads: 8
12:17:18.180 [main] DEBUG io.netty.channel.nio.NioEventLoop - -Dio.netty.noKeySetOptimization: false
12:17:18.181 [main] DEBUG io.netty.channel.nio.NioEventLoop - -Dio.netty.selectorAutoRebuildThreshold: 512
12:17:18.190 [main] TRACE io.netty.channel.nio.NioEventLoop - Instrumented an optimized java.util.Set into: sun.nio.ch.EPollSelectorImpl@5700d6b1
12:17:18.190 [main] TRACE io.netty.channel.nio.NioEventLoop - Instrumented an optimized java.util.Set into: sun.nio.ch.EPollSelectorImpl@6fd02e5
12:17:18.190 [main] TRACE io.netty.channel.nio.NioEventLoop - Instrumented an optimized java.util.Set into: sun.nio.ch.EPollSelectorImpl@5bcab519
12:17:18.190 [main] TRACE io.netty.channel.nio.NioEventLoop - Instrumented an optimized java.util.Set into: sun.nio.ch.EPollSelectorImpl@e45f292
12:17:18.190 [main] TRACE io.netty.channel.nio.NioEventLoop - Instrumented an optimized java.util.Set into: sun.nio.ch.EPollSelectorImpl@5f2108b5
12:17:18.191 [main] TRACE io.netty.channel.nio.NioEventLoop - Instrumented an optimized java.util.Set into: sun.nio.ch.EPollSelectorImpl@31a5c39e
12:17:18.192 [main] TRACE io.netty.channel.nio.NioEventLoop - Instrumented an optimized java.util.Set into: sun.nio.ch.EPollSelectorImpl@3f49dace
12:17:18.192 [main] TRACE io.netty.channel.nio.NioEventLoop - Instrumented an optimized java.util.Set into: sun.nio.ch.EPollSelectorImpl@1e397ed7
12:17:18.192 [main] TRACE io.netty.channel.nio.NioEventLoop - Instrumented an optimized java.util.Set into: sun.nio.ch.EPollSelectorImpl@27c20538
12:17:18.193 [main] TRACE io.netty.channel.nio.NioEventLoop - Instrumented an optimized java.util.Set into: sun.nio.ch.EPollSelectorImpl@72d818d1
12:17:18.193 [main] TRACE io.netty.channel.nio.NioEventLoop - Instrumented an optimized java.util.Set into: sun.nio.ch.EPollSelectorImpl@6e06451e
12:17:18.193 [main] TRACE io.netty.channel.nio.NioEventLoop - Instrumented an optimized java.util.Set into: sun.nio.ch.EPollSelectorImpl@59494225
12:17:18.193 [main] TRACE io.netty.channel.nio.NioEventLoop - Instrumented an optimized java.util.Set into: sun.nio.ch.EPollSelectorImpl@6e1567f1
12:17:18.194 [main] TRACE io.netty.channel.nio.NioEventLoop - Instrumented an optimized java.util.Set into: sun.nio.ch.EPollSelectorImpl@5cb9f472
12:17:18.195 [main] TRACE io.netty.channel.nio.NioEventLoop - Instrumented an optimized java.util.Set into: sun.nio.ch.EPollSelectorImpl@cb644e
12:17:18.196 [main] TRACE io.netty.channel.nio.NioEventLoop - Instrumented an optimized java.util.Set into: sun.nio.ch.EPollSelectorImpl@13805618
12:17:18.227 [main] DEBUG i.n.util.internal.ThreadLocalRandom - -Dio.netty.initialSeedUniquifier: 0xceaa20b0108ae084 (took 2 ms)
12:17:18.288 [main] DEBUG io.netty.buffer.ByteBufUtil - -Dio.netty.allocator.type: unpooled
12:17:18.289 [main] DEBUG io.netty.buffer.ByteBufUtil - -Dio.netty.threadLocalDirectBufferSize: 65536
12:17:18.292 [main] DEBUG io.netty.util.NetUtil - Loopback interface: lo (lo, 0:0:0:0:0:0:0:1%lo)
12:17:18.293 [main] DEBUG io.netty.util.NetUtil - /proc/sys/net/core/somaxconn: 128
12:17:18.321 [nioEventLoopGroup-2-1] INFO  i.n.handler.logging.LoggingHandler - [id: 0xed094031] REGISTERED
12:17:18.322 [nioEventLoopGroup-2-1] INFO  i.n.handler.logging.LoggingHandler - [id: 0xed094031] BIND(10.0.100.17/10.0.100.17:51826)
12:17:18.323 [nioEventLoopGroup-2-1] INFO  i.g.h.i.h.i.NettyHomekitHttpService - Bound homekit listener to /10.0.100.17:51826
12:17:18.323 [nioEventLoopGroup-2-1] INFO  i.g.h.i.jmdns.JmdnsHomekitAdvertiser - Advertising accessory TestBridge
12:17:18.324 [nioEventLoopGroup-2-1] INFO  i.g.h.i.jmdns.JmdnsHomekitAdvertiser - Registering _hap._tcp.local. on port 51826
yfre commented

Hello,
I am trying with the new iOS but its also not working with 13.4. I am the only one struggling with this problem? #95 fixed the discoverability but the pairing issue is still active

what kind of issue you have? how the log look like?can you try with reduced number of device - e.g. try with a simple switch / light first and once it works, add other devices

I am trying with the Sample project, with the simple MockSwitch.

Using persisted auth
The PIN for pairing is 131-45-154
12:17:17.996 [main] INFO  io.github.hapjava.HomekitRoot - Added accessory TestBridge
State has changed! Writing
12:17:18.077 [main] INFO  io.github.hapjava.HomekitRoot - Added accessory TestLightbulb
12:17:18.107 [main] DEBUG i.n.u.i.l.InternalLoggerFactory - Using SLF4J as the default logging framework
12:17:18.122 [main] DEBUG i.n.util.internal.PlatformDependent0 - java.nio.Buffer.address: available
12:17:18.123 [main] DEBUG i.n.util.internal.PlatformDependent0 - sun.misc.Unsafe.theUnsafe: available
12:17:18.123 [main] DEBUG i.n.util.internal.PlatformDependent0 - sun.misc.Unsafe.copyMemory: available
12:17:18.124 [main] DEBUG i.n.util.internal.PlatformDependent0 - java.nio.Bits.unaligned: true
12:17:18.126 [main] DEBUG i.n.util.internal.PlatformDependent - Java version: 8
12:17:18.126 [main] DEBUG i.n.util.internal.PlatformDependent - -Dio.netty.noUnsafe: false
12:17:18.127 [main] DEBUG i.n.util.internal.PlatformDependent - sun.misc.Unsafe: available
12:17:18.127 [main] DEBUG i.n.util.internal.PlatformDependent - -Dio.netty.noJavassist: false
12:17:18.128 [main] DEBUG i.n.util.internal.PlatformDependent - Javassist: unavailable
12:17:18.128 [main] DEBUG i.n.util.internal.PlatformDependent - You don't have Javassist in your class path or you don't have enough permission to load dynamically generated classes.  Please check the configuration for better performance.
12:17:18.129 [main] DEBUG i.n.util.internal.PlatformDependent - -Dio.netty.tmpdir: /tmp (java.io.tmpdir)
12:17:18.129 [main] DEBUG i.n.util.internal.PlatformDependent - -Dio.netty.bitMode: 64 (sun.arch.data.model)
12:17:18.129 [main] DEBUG i.n.util.internal.PlatformDependent - -Dio.netty.noPreferDirect: false
12:17:18.169 [main] DEBUG i.n.c.MultithreadEventLoopGroup - -Dio.netty.eventLoopThreads: 8
12:17:18.180 [main] DEBUG io.netty.channel.nio.NioEventLoop - -Dio.netty.noKeySetOptimization: false
12:17:18.181 [main] DEBUG io.netty.channel.nio.NioEventLoop - -Dio.netty.selectorAutoRebuildThreshold: 512
12:17:18.190 [main] TRACE io.netty.channel.nio.NioEventLoop - Instrumented an optimized java.util.Set into: sun.nio.ch.EPollSelectorImpl@5700d6b1
12:17:18.190 [main] TRACE io.netty.channel.nio.NioEventLoop - Instrumented an optimized java.util.Set into: sun.nio.ch.EPollSelectorImpl@6fd02e5
12:17:18.190 [main] TRACE io.netty.channel.nio.NioEventLoop - Instrumented an optimized java.util.Set into: sun.nio.ch.EPollSelectorImpl@5bcab519
12:17:18.190 [main] TRACE io.netty.channel.nio.NioEventLoop - Instrumented an optimized java.util.Set into: sun.nio.ch.EPollSelectorImpl@e45f292
12:17:18.190 [main] TRACE io.netty.channel.nio.NioEventLoop - Instrumented an optimized java.util.Set into: sun.nio.ch.EPollSelectorImpl@5f2108b5
12:17:18.191 [main] TRACE io.netty.channel.nio.NioEventLoop - Instrumented an optimized java.util.Set into: sun.nio.ch.EPollSelectorImpl@31a5c39e
12:17:18.192 [main] TRACE io.netty.channel.nio.NioEventLoop - Instrumented an optimized java.util.Set into: sun.nio.ch.EPollSelectorImpl@3f49dace
12:17:18.192 [main] TRACE io.netty.channel.nio.NioEventLoop - Instrumented an optimized java.util.Set into: sun.nio.ch.EPollSelectorImpl@1e397ed7
12:17:18.192 [main] TRACE io.netty.channel.nio.NioEventLoop - Instrumented an optimized java.util.Set into: sun.nio.ch.EPollSelectorImpl@27c20538
12:17:18.193 [main] TRACE io.netty.channel.nio.NioEventLoop - Instrumented an optimized java.util.Set into: sun.nio.ch.EPollSelectorImpl@72d818d1
12:17:18.193 [main] TRACE io.netty.channel.nio.NioEventLoop - Instrumented an optimized java.util.Set into: sun.nio.ch.EPollSelectorImpl@6e06451e
12:17:18.193 [main] TRACE io.netty.channel.nio.NioEventLoop - Instrumented an optimized java.util.Set into: sun.nio.ch.EPollSelectorImpl@59494225
12:17:18.193 [main] TRACE io.netty.channel.nio.NioEventLoop - Instrumented an optimized java.util.Set into: sun.nio.ch.EPollSelectorImpl@6e1567f1
12:17:18.194 [main] TRACE io.netty.channel.nio.NioEventLoop - Instrumented an optimized java.util.Set into: sun.nio.ch.EPollSelectorImpl@5cb9f472
12:17:18.195 [main] TRACE io.netty.channel.nio.NioEventLoop - Instrumented an optimized java.util.Set into: sun.nio.ch.EPollSelectorImpl@cb644e
12:17:18.196 [main] TRACE io.netty.channel.nio.NioEventLoop - Instrumented an optimized java.util.Set into: sun.nio.ch.EPollSelectorImpl@13805618
12:17:18.227 [main] DEBUG i.n.util.internal.ThreadLocalRandom - -Dio.netty.initialSeedUniquifier: 0xceaa20b0108ae084 (took 2 ms)
12:17:18.288 [main] DEBUG io.netty.buffer.ByteBufUtil - -Dio.netty.allocator.type: unpooled
12:17:18.289 [main] DEBUG io.netty.buffer.ByteBufUtil - -Dio.netty.threadLocalDirectBufferSize: 65536
12:17:18.292 [main] DEBUG io.netty.util.NetUtil - Loopback interface: lo (lo, 0:0:0:0:0:0:0:1%lo)
12:17:18.293 [main] DEBUG io.netty.util.NetUtil - /proc/sys/net/core/somaxconn: 128
12:17:18.321 [nioEventLoopGroup-2-1] INFO  i.n.handler.logging.LoggingHandler - [id: 0xed094031] REGISTERED
12:17:18.322 [nioEventLoopGroup-2-1] INFO  i.n.handler.logging.LoggingHandler - [id: 0xed094031] BIND(10.0.100.17/10.0.100.17:51826)
12:17:18.323 [nioEventLoopGroup-2-1] INFO  i.g.h.i.h.i.NettyHomekitHttpService - Bound homekit listener to /10.0.100.17:51826
12:17:18.323 [nioEventLoopGroup-2-1] INFO  i.g.h.i.jmdns.JmdnsHomekitAdvertiser - Advertising accessory TestBridge
12:17:18.324 [nioEventLoopGroup-2-1] INFO  i.g.h.i.jmdns.JmdnsHomekitAdvertiser - Registering _hap._tcp.local. on port 51826

what happening afterwards? can you see the bridge in home app ? does it ask for PIN?
can you run with "-Dorg.slf4j.simpleLogger.defaultLogLevel=DEBUG"

Yes, i can see the bridge in home app, and it is ask for the pin. After that nothing happen (no log record), just wheeling and timeouting the accessory (birdge) adding.

yfre commented

just tried with ios13.4 and it works but maybe i have a newer version of java-hap
which version do you use? the one from master branch or the binary from release 1.1.5?

Just turned off the firewall and it is working like a charm. My fault, so sorry :/
Anyway thank you for your time!

yfre commented

Just turned off the firewall and it is working like a charm. My fault, so sorry :/
Anyway thank you for your time!

cool! added firewall to my checklist :)

Doesn't work for me. Pairing completes, the service says it's re-registering, and then removeUser is called and the device says the process failed. iOS 13.3.1. I already tried with and without re-registering the service, but to no avail.

What I find strange is that the request for accessories is received BEFORE the service is re-registering itself. Could this be the problem? Is there maybe a better way like updating the service instead of re-registering it (by using ServiceInfo.setText)? Or re-register the service immediately after sending the final pairing response, so that the service is ready when the next request comes?

Update: if I remove the MockSwitch and just create the bridge, I can add the bridge successfully. So it must have something to do with the device. I already checked the JSON and it's identical to the one posted here for a successful attempt. No null or anything strange. Any idea?

yfre commented

in the older iOS i had to remove "home" and create again time-to-time to get rid of some strange issues. but with ios 13.3.x i could repeat pairing many times without getting any issues.

can you now add the device? without removing the bridge and home. just add device and restart the sample.

No, I can't, because I have to search again and then the bridge isn't found, because it's paired :-(

I also cleared Home completely, but that changes nothing. Any info I can provide?

yfre commented

i did recently the refactoring of HAP in order to add support for optional attributes. the changes are not merged yet, but it would be interesting to know whether you get the same issue with a newer version.

could you maybe try run the sample that is based on the refactored version?
you can download it here
https://1drv.ms/u/s!AqqiEfFRr6WAgYgRlv15LrGLAPkq8g?e=UsqzQ2
and run with " java -jar target/hap-sample-0.0.2-SNAPSHOT.jar"

or build it yourself form #102

Hmm, the jar is only 10 kb and doesn't seem to work? And building it myself would require updating the library, too, because the sample uses parameters for createBridge that I haven't seen before ;-)

yfre commented

you are right. the libs are missing.
so, i have ziped the target folder with zip and jar.
if you have time, could you please try it one more time
https://1drv.ms/u/s!AqqiEfFRr6WAgYgSE-Tb84IKu4ev9A?e=vwozRf

Hmm, ok, that one works, so the error is probably somewhere on my side. Ok, here's what I'm trying to do: I'm triyng to get HAP-Java working with IKVM in C#/.NET. Which seems to work for the most part, but I have no idea why it fails on this "small" detail.

If you have time, I have put the logs of both your sample and mine (using the same, cross-compiled 2.0 jar). Apart from the logging difference, I can't make out much difference, only that your's works and mine doesn't :-(

https://1drv.ms/u/s!AtK4xQ8gVYfFmF4oiRQcptvbOPZ1?e=1q1JgT

After numerous attempts and switching of library versions, I finally got it working. In the end, the problem was one single character in the Json file ;-) I returned a .NET bool for the power state, which converted to "False" instead of "false". doh ;-)

Otah commented

Hi, I hope I didn't miss it in the discussion: in which version is this expected to be fixed?

As far as I can tell right now, I tried both 1.1.3 and then 1.1.5 and in both of them the pairing does not work with iOS 13.x. It happened to me once from like 20-30 attempts that it worked, but it was literally just once.

Is there a plan to port the fix to the original 1.1.x "beowulfe" series? Or do I have to eventually migrate to the 1.2.x series? I am using HAP Java 1.1.x as a "driver" for HAP Scala and my derived personal projects.

Otah commented

Probably never mind. So far it seems that the migration to 1.2 is extremely smooth. I will hopefully not need the older versions. (But maybe somebody else will?)

yfre commented

closing as obsolete