Great, thank you @hilbrand, the bnd.importpackage change solved my issue as well.
When looking into the code, I was also thinking it might be best to separate the implementation for Envoy older than version 7 and version 7 and newer. That way it would easier (and less if/else) to also leverage additional data the new Envoy delivers.
Is your idea @hilbrand to duplicate the class EnvoyBridgeHandler and e.g. create a new EnvoyV7BridgeHandler in its own package?
What is the Unit the Production today is measured? Strange figure and unit (Joules?)
No, not a new bridge handler. Functionality wise it’s has the same channels at the moment, just different communication, and some data is in specific Things. My Idea is to create an EnvoyEntrezConnector that extends EnvoyConnector and would contains the entrez specific additional code. In the EnvoyHandlerFactory it creates the bridge handler with either one of these connectors. Depending on what thing it is (I was thinking about creating a new bridge called envoy-entrez). If in the future there would be more additional channels for the bridge it can always be an option to extend the current bridge with a new bridge with additional channels or adapt the current bridge.
I’ve already worked on some of these changes. But was waiting more or less on what @dfad1469 thinks of my suggested idea to create a pr against his branch with the changes.
The channel is a quantity type. That means it will display in the unit the item is configured. The binding sets it to Wh, but somehow your item thinks it is unit J and than Wh is converted to J. What is in your item configuration?
I think that’s a fine idea and I fully support it.
I apologize for the spotty drop in…life gets in the way. I just started a new job a few months ago and it’s starting to heat up. That said, I can definitely support checking pull requests and testing against my dev environment and Enphase equipment.
I am working on adding support for the Enphase battery equipment now so I can monitor those states as well. That’s easier for me to do and it will be more straightforward.
So, I will review any PR to my branches whenever I get them.
Thanks for the suggestion.as part of the learning curve did some research: I added the number formatting in the Item, metadata State Description and in the field Pattern: %,.0f Watt
Hi all
Is this binding change still a work in progress? I have a new system with v7 firmware.
Are there some more instructions on how to install the binding and configure it? I’m running openHAB 3.3.0 on a windows 10 machine.
Many thanks.
Enphase binding breaks with the Envoy V7 software upgrade - is there a plan to upgrade the binding?
I would really like to be able to do this… but I’m not sure I know what steps I should be taking to download and build it. Really just looking to drop in the fixed version of the enphase binding so that I can connect it to my new v7 system. Should I be doing some kind of git clone command and then the mvn command you showed above? I’m not sure how to pull the correct source code and it would be nice to know I’m not accidentally rebuilding just the stock enphase binding which doesn’t support v7. Would appreciate any help you can offer!
So I just tried this after downloading the whole “enphase” branch of that git repo, and ran into this error:
$ mvn clean install -DskipChecks -DskipTests -pl :org.openhab.binding.enphase
[INFO] Scanning for projects...
[INFO]
[INFO] -------< org.openhab.addons.bundles:org.openhab.binding.enphase >-------
[INFO] Building openHAB Add-ons :: Bundles :: Enphase Binding 4.0.0-SNAPSHOT
[INFO] from pom.xml
[INFO] --------------------------------[ jar ]---------------------------------
[WARNING] The POM for org.eclipse.orbit.bundles:net.i2p.crypto.eddsa:jar:0.3.0.v20220506-1020 is missing, no dependency information available
[INFO]
[INFO] --- clean:3.0.0:clean (default-clean) @ org.openhab.binding.enphase ---
[INFO]
[INFO] --- enforcer:3.0.0-M2:enforce (enforce-java) @ org.openhab.binding.enphase ---
[WARNING] Rule 0: org.apache.maven.plugins.enforcer.RequireJavaVersion failed with message:
Detected JDK Version: 20.0.1 is not in the allowed range [17.0,18.0).
[INFO] ------------------------------------------------------------------------
[INFO] BUILD FAILURE
[INFO] ------------------------------------------------------------------------
[INFO] Total time: 8.776 s
[INFO] Finished at: 2023-05-12T23:14:30+10:00
[INFO] ------------------------------------------------------------------------
[WARNING]
[WARNING] Plugin validation issues were detected in 3 plugin(s)
[WARNING]
[WARNING] * org.apache.karaf.tooling:karaf-maven-plugin:4.3.7
[WARNING] * org.apache.maven.plugins:maven-clean-plugin:3.0.0
[WARNING] * org.apache.maven.plugins:maven-enforcer-plugin:3.0.0-M2
[WARNING]
[WARNING] For more or less details, use 'maven.plugin.validation' property with one of the values (case insensitive): [BRIEF, DEFAULT, VERBOSE]
[WARNING]
[ERROR] Failed to execute goal org.apache.maven.plugins:maven-enforcer-plugin:3.0.0-M2:enforce (enforce-java) on project org.openhab.binding.enphase: Some Enforcer rules have failed. Look above for specific messages explaining why the rule failed. -> [Help 1]
[ERROR]
[ERROR] To see the full stack trace of the errors, re-run Maven with the -e switch.
[ERROR] Re-run Maven using the -X switch to enable full debug logging.
[ERROR]
[ERROR] For more information about the errors and possible solutions, please read the following articles:
[ERROR] [Help 1] http://cwiki.apache.org/confluence/display/MAVEN/MojoExecutionException
It looks like it’s complaining that my JDK version is too high… but if I run java --version it says I’m on JDK 17. I obviously don’t know enough of what I’m doing, but I’m coming to detest Java’s development environment at the moment (can’t run OH4 because it complains I don’t have Java 17, can’t build this because apparently I have Java 20?, but Java itself tells me it is version 17).
Any progress on this for folks like me who can’t seem to get the build process to run?
I’ve made some progress with mvn, but it’s still failing. Now it seems to be failing with something similar to what was mentioned above (I solved the Java version problem), but editing the pom.xml as described doesn’t seem to have fixed it. Any hints from those who wrangle these java builds on the regular?
[ERROR] Failed to execute goal org.apache.karaf.tooling:karaf-maven-plugin:4.3.7:verify (karaf-feature-verification) on project org.openhab.binding.enphase: Feature resolution failed for [openhab-binding-enphase/4.0.0.SNAPSHOT]
[ERROR] Message: Unable to resolve root: missing requirement [root] osgi.identity; osgi.identity=openhab-binding-enphase; type=karaf.feature; version=4.0.0.SNAPSHOT; filter:="(&(osgi.identity=openhab-binding-enphase)(type=karaf.feature)(version>=4.0.0.SNAPSHOT))" [caused by: Unable to resolve openhab-binding-enphase/4.0.0.SNAPSHOT: missing requirement [openhab-binding-enphase/4.0.0.SNAPSHOT] osgi.identity; osgi.identity=org.openhab.binding.enphase; type=osgi.bundle; version="[4.0.0.202305140155,4.0.0.202305140155]"; resolution:=mandatory [caused by: Unable to resolve org.openhab.binding.enphase/4.0.0.202305140155: missing requirement [org.openhab.binding.enphase/4.0.0.202305140155] osgi.wiring.package; filter:="(osgi.wiring.package=org.openhab.core.config.core)" [caused by: Unable to resolve org.openhab.core.config.core/4.0.0.202305130304: missing requirement [org.openhab.core.config.core/4.0.0.202305130304] osgi.wiring.package; filter:="(&(osgi.wiring.package=org.openhab.core.common)(version>=4.0.0)(!(version>=5.0.0)))" [caused by: Unable to resolve org.openhab.core/4.0.0.202305130301: missing requirement [org.openhab.core/4.0.0.202305130301] osgi.wiring.package; filter:="(&(osgi.wiring.package=org.osgi.framework)(version>=1.10.0)(!(version>=2.0.0)))"]]]]
I’ve actually implemented support for v7. However I’ve been very short on time lately to get it published. I’ve let it run on my system (< v7) and it seems to run fine, but I simply haven’t had time to publish it. My jar will work both on openHAB 3.4 and 4.0. since it’s now based on openHAB 4.0 it can’t be merged back directly to the original branch (as that was 3.4 based). I’ll see if I can find some time to publish the binding next week and submit a pull request.
2 Likes
That’s great news! I think I’m hitting a dead end when it comes to trying to build it myself, but it’s probably not the best use of anyone’s time or energy to get me past that (since I’m unlikely to ever build any other binding from source). Much better to have it implemented as part of the built-in binding so that anyone installing new enphase systems will be able to use it. I’ll keep an eye on this thread!
I’ve put the Enphase Envoy jar with 3.4 - 4.0 which should have version 7 support online. It can be found here: Release Enphase Envoy for version 7 [3.4.0, 4.0) - (19-08-2023) · Hilbrand/openhab-addons · GitHub Download the jar, uninstall the official binding if you have it installed and drop the jar in the addons folder. Let me know how it works.
2 Likes
Hi
Thanks for your hard work but unfortunately I can’t get it to work. I’m using stable build 3.3.0 on windows 10. XXXXXX used to hide personal data.
The main error I get is:
2023-05-15 20:23:19.025 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'enphase:envoy:XXXXXX' changed from UNKNOWN to OFFLINE (COMMUNICATION_ERROR): Could not retrieve data: HTTP protocol violation: Authentication challenge without WWW-Authenticate header
Although I have configured the .things file like this:
Bridge enphase:envoy:XXXXXX"Envoy" [ serialNumber="123456XXXXXX", autoJwt="true", siteName="XXXXXX", username="XXX@XXXcom", password="XXXXXX" ]
I get the following in the log:
Connection to Envoy determined by getting a reply from the Envoy using the orior to version 7 method.
I also tried autoJwr="false" and put the token key in the .things file, but that gave the same errors. I’m presuming I don’t need to configure each inverter and can just get the gateway data?
Additionally, from what I have working using the http binding, I can read live data every 10 seconds. Enphase - Envoy V7 local API to CURL-JSON on Windows - #39 by davebuk
Could the binding access this data as well?
Thanks.
It doesn’t seem to detect the new software version correctly. I’ve updated the binding (date 16-05-2023). Can you try again. If still not works, can you run with log level trace.
The binding can’t access the data it’s only available n the http binding.
Still not working. It didn’t seem to find the host address so I manually set it in the .things file.
Debug set to TRACE.
2023-05-16 10:46:45.800 [DEBUG] [ternal.handler.EnvoyConnectorWrapper] - Set Envoy version found in the Envoy data: null
2023-05-16 10:46:45.804 [TRACE] [.internal.handler.EnvoyBridgeHandler] - Check connection
2023-05-16 10:46:46.981 [TRACE] [hase.internal.handler.EnvoyConnector] - Checkconnection status from request is: 200
2023-05-16 10:46:46.982 [INFO ] [ternal.handler.EnvoyConnectorWrapper] - Connection to Envoy determined by getting a reply from the Envoy using the prior to version 7 method.
2023-05-16 10:46:46.982 [TRACE] [.internal.handler.EnvoyBridgeHandler] - No configuration error
2023-05-16 10:46:46.984 [TRACE] [hase.internal.handler.EnvoyConnector] - Retrieving data from 'http://192.168.1.XXX/api/v1/production'
2023-05-16 10:46:47.135 [DEBUG] [hase.internal.handler.EnvoyConnector] - ExecutionException: org.eclipse.jetty.client.HttpResponseException: HTTP protocol violation: Authentication challenge without WWW-Authenticate header
java.util.concurrent.ExecutionException: org.eclipse.jetty.client.HttpResponseException: HTTP protocol violation: Authentication challenge without WWW-Authenticate header
at org.eclipse.jetty.client.util.FutureResponseListener.getResult(FutureResponseListener.java:118) ~[?:?]
at org.eclipse.jetty.client.util.FutureResponseListener.get(FutureResponseListener.java:101) ~[?:?]
at org.eclipse.jetty.client.HttpRequest.send(HttpRequest.java:730) ~[?:?]
at org.openhab.binding.enphase.internal.handler.EnvoyConnector.send(EnvoyConnector.java:222) ~[?:?]
at org.openhab.binding.enphase.internal.handler.EnvoyConnector.retrieveData(EnvoyConnector.java:188) ~[?:?]
at org.openhab.binding.enphase.internal.handler.EnvoyConnector.getProduction(EnvoyConnector.java:134) ~[?:?]
at org.openhab.binding.enphase.internal.handler.EnvoyBridgeHandler.updateEnvoy(EnvoyBridgeHandler.java:313) ~[?:?]
at org.openhab.binding.enphase.internal.handler.EnvoyBridgeHandler.updateData(EnvoyBridgeHandler.java:262) ~[?:?]
at org.openhab.binding.enphase.internal.handler.EnvoyBridgeHandler.lambda$2(EnvoyBridgeHandler.java:159) ~[?:?]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [?:?]
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) [?:?]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) [?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
at java.lang.Thread.run(Thread.java:829) [?:?]
Caused by: org.eclipse.jetty.client.HttpResponseException: HTTP protocol violation: Authentication challenge without WWW-Authenticate header
at org.eclipse.jetty.client.AuthenticationProtocolHandler$AuthenticationListener.onComplete(AuthenticationProtocolHandler.java:164) ~[?:?]
at org.eclipse.jetty.client.ResponseNotifier.notifyComplete(ResponseNotifier.java:218) ~[?:?]
at org.eclipse.jetty.client.ResponseNotifier.notifyComplete(ResponseNotifier.java:210) ~[?:?]
at org.eclipse.jetty.client.HttpReceiver.terminateResponse(HttpReceiver.java:481) ~[?:?]
at org.eclipse.jetty.client.HttpReceiver.terminateResponse(HttpReceiver.java:461) ~[?:?]
at org.eclipse.jetty.client.HttpReceiver.responseSuccess(HttpReceiver.java:424) ~[?:?]
at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.messageComplete(HttpReceiverOverHTTP.java:374) ~[?:?]
at org.eclipse.jetty.http.HttpParser.handleContentMessage(HttpParser.java:597) ~[?:?]
at org.eclipse.jetty.http.HttpParser.parseContent(HttpParser.java:1722) ~[?:?]
at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:1551) ~[?:?]
at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.parse(HttpReceiverOverHTTP.java:208) ~[?:?]
at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.process(HttpReceiverOverHTTP.java:148) ~[?:?]
at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.receive(HttpReceiverOverHTTP.java:80) ~[?:?]
at org.eclipse.jetty.client.http.HttpChannelOverHTTP.receive(HttpChannelOverHTTP.java:131) ~[?:?]
at org.eclipse.jetty.client.http.HttpConnectionOverHTTP.onFillable(HttpConnectionOverHTTP.java:172) ~[?:?]
at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311) ~[?:?]
at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) ~[?:?]
at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.onFillable(SslConnection.java:555) ~[?:?]
at org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:410) ~[?:?]
at org.eclipse.jetty.io.ssl.SslConnection$2.succeeded(SslConnection.java:164) ~[?:?]
at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) ~[?:?]
at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104) ~[?:?]
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:338) ~[?:?]
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:315) ~[?:?]
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:173) ~[?:?]
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131) ~[?:?]
at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:409) ~[?:?]
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:883) ~[?:?]
at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1034) ~[?:?]
... 1 more
I guess its still not selecting the V7 method and requests http:// not https://?
2023-05-16 10:51:47.149 [TRACE] [.internal.handler.EnvoyBridgeHandler] - Check connection
2023-05-16 10:51:47.149 [TRACE] [.internal.handler.EnvoyBridgeHandler] - Has Connection
2023-05-16 10:51:47.150 [TRACE] [hase.internal.handler.EnvoyConnector] - Retrieving data from 'http://192.168.1.XXX/api/v1/production'
2023-05-16 10:51:47.303 [DEBUG] [hase.internal.handler.EnvoyConnector] - ExecutionException: org.eclipse.jetty.client.HttpResponseException: HTTP protocol violation: Authentication challenge without WWW-Authenticate header
java.util.concurrent.ExecutionException: org.eclipse.jetty.client.HttpResponseException: HTTP protocol violation: Authentication challenge without WWW-Authenticate header
at org.eclipse.jetty.client.util.FutureResponseListener.getResult(FutureResponseListener.java:118) ~[?:?]
at org.eclipse.jetty.client.util.FutureResponseListener.get(FutureResponseListener.java:101) ~[?:?]
at org.eclipse.jetty.client.HttpRequest.send(HttpRequest.java:730) ~[?:?]
at org.openhab.binding.enphase.internal.handler.EnvoyConnector.send(EnvoyConnector.java:222) ~[?:?]
at org.openhab.binding.enphase.internal.handler.EnvoyConnector.retrieveData(EnvoyConnector.java:188) ~[?:?]
at org.openhab.binding.enphase.internal.handler.EnvoyConnector.getProduction(EnvoyConnector.java:134) ~[?:?]
at org.openhab.binding.enphase.internal.handler.EnvoyBridgeHandler.updateEnvoy(EnvoyBridgeHandler.java:313) ~[?:?]
at org.openhab.binding.enphase.internal.handler.EnvoyBridgeHandler.updateData(EnvoyBridgeHandler.java:262) ~[?:?]
at org.openhab.binding.enphase.internal.handler.EnvoyBridgeHandler.lambda$2(EnvoyBridgeHandler.java:159) ~[?:?]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [?:?]
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) [?:?]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) [?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
at java.lang.Thread.run(Thread.java:829) [?:?]
Caused by: org.eclipse.jetty.client.HttpResponseException: HTTP protocol violation: Authentication challenge without WWW-Authenticate header
at org.eclipse.jetty.client.AuthenticationProtocolHandler$AuthenticationListener.onComplete(AuthenticationProtocolHandler.java:164) ~[?:?]
at org.eclipse.jetty.client.ResponseNotifier.notifyComplete(ResponseNotifier.java:218) ~[?:?]
at org.eclipse.jetty.client.ResponseNotifier.notifyComplete(ResponseNotifier.java:210) ~[?:?]
at org.eclipse.jetty.client.HttpReceiver.terminateResponse(HttpReceiver.java:481) ~[?:?]
at org.eclipse.jetty.client.HttpReceiver.terminateResponse(HttpReceiver.java:461) ~[?:?]
at org.eclipse.jetty.client.HttpReceiver.responseSuccess(HttpReceiver.java:424) ~[?:?]
at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.messageComplete(HttpReceiverOverHTTP.java:374) ~[?:?]
at org.eclipse.jetty.http.HttpParser.handleContentMessage(HttpParser.java:597) ~[?:?]
at org.eclipse.jetty.http.HttpParser.parseContent(HttpParser.java:1722) ~[?:?]
at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:1551) ~[?:?]
at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.parse(HttpReceiverOverHTTP.java:208) ~[?:?]
at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.process(HttpReceiverOverHTTP.java:148) ~[?:?]
at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.receive(HttpReceiverOverHTTP.java:80) ~[?:?]
at org.eclipse.jetty.client.http.HttpChannelOverHTTP.receive(HttpChannelOverHTTP.java:131) ~[?:?]
at org.eclipse.jetty.client.http.HttpConnectionOverHTTP.onFillable(HttpConnectionOverHTTP.java:172) ~[?:?]
at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311) ~[?:?]
at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) ~[?:?]
at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.onFillable(SslConnection.java:555) ~[?:?]
at org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:410) ~[?:?]
at org.eclipse.jetty.io.ssl.SslConnection$2.succeeded(SslConnection.java:164) ~[?:?]
at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) ~[?:?]
at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104) ~[?:?]
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:338) ~[?:?]
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:315) ~[?:?]
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:173) ~[?:?]
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131) ~[?:?]
at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:409) ~[?:?]
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:883) ~[?:?]
at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1034) ~[?:?]
... 1 more
Another try. It didn’t recognize the new version correctly and falls back to the old version method. That will result in followup errors. I’ve updated the binding to do the check a bit different.
I was just about to post my experience - so far same as davebuk, although I tried a few different ways (adding auto-discovered thing, manually configuring thing using .things file, with and without auto-JWT). Failed in two different ways (same way as davebuk with manually configured thing, an error attempting to log in to entrez.enphase when using auto-configured thing.
Has the new JAR been uploaded? I went to check just now and it said it was 3 hours old, which was the one I tried and got the errors.
Thanks so much for your work on this - it’s great to see it so tantalisingly close!
In case my different error (auto-config, auto-JWT on and off) is informative:
01:24:13.775 [DEBUG] [nternal.handler.EnvoyConnectorWrapper] - Set Envoy version found in the Envoy data: 7.0.88
01:24:13.775 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'enphase:envoy:122308070085' changed from OFFLINE (COMMUNICATION_ERROR): Could not login to Entrez JWT Portal. Status code:200 to UNKNOWN
01:24:13.775 [TRACE] [e.internal.handler.EnvoyBridgeHandler] - Check connection
01:24:13.775 [TRACE] [e.internal.handler.EnvoyBridgeHandler] - Has Connection
01:24:13.776 [TRACE] [hase.internal.handler.EntrezConnector] - Retrieving session id from 'https://entrez.enphaseenergy.com/login'
01:24:14.469 [DEBUG] [hase.internal.handler.EntrezConnector] - Failed to login to Entrez portal. Portal returned status: 200. Response from Entrez portal: <!DOCTYPE html>
<html>
<head>
<meta charset="UTF-8">
<meta name="viewport" content="width=device-width, initial-scale=1.0">
<title>Enphase Authentication | Login page</title>
<link rel="stylesheet" type="text/css" href="/main.css"/>
<script src="/main.js"></script>
</head>
<body>
<section class="login-container">
<section class="login">
<img class="logo" src="https://enphase.com/sites/all/themes/enphase/assets/images/svgs/src/enphase-logo.svg">
<div>
<p class="error">Wrong username or password</p>
</div>
<form class="login-form" action="/login" method="post">
<input type="text" id="username" name="username" autofocus="autofocus" placeholder="Username"/>
<input type="password" id="password" name="password" placeholder="Password"/>
<input class="button" type="submit" value="Log in"/>
<input type="text" id="codeChallenge" name="codeChallenge" value="" hidden=true/>
<input type="text" id="redirectUri" name="redirectUri" value="" hidden=true/>
<input type="text" id="client" name="client" value="" hidden=true/>
<input type="text" id="clientId" name="clientId" value="" hidden=true/>
<input type="text" id="authFlow" name="authFlow" value="" hidden=true/>
<input type="text" id="serialNum" name="serialNum" value="" hidden=true/>
<input type="text" id="grantType" name="grantType" value="" hidden=true/>
<input type="text" id="state" name="state" value="" hidden=true/>
<input type="text" id="invalidSerialNum" name="invalidSerialNum" value="" hidden=true/>
</form>
</section>
<a class="powered-by" href="https://enphase.com/" target="_blank">Enphase Energy, Inc. © 2022</a>
</section>
</body>
</html>
01:24:14.470 [DEBUG] [e.internal.handler.EnvoyBridgeHandler] - EntrezConnectionException in Enphase thing enphase:envoy:122308070085:
org.openhab.binding.enphase.internal.exception.EntrezConnectionException: Could not login to Entrez JWT Portal. Status code:200
at org.openhab.binding.enphase.internal.handler.EntrezConnector.login(EntrezConnector.java:139) ~[?:?]
at org.openhab.binding.enphase.internal.handler.EntrezConnector.retrieveJwt(EntrezConnector.java:72) ~[?:?]
at org.openhab.binding.enphase.internal.handler.EnvoyEntrezConnector.getNewSessionId(EnvoyEntrezConnector.java:130) ~[?:?]
at org.openhab.binding.enphase.internal.handler.EnvoyEntrezConnector.constructRequest(EnvoyEntrezConnector.java:96) ~[?:?]
at org.openhab.binding.enphase.internal.handler.EnvoyConnector.retrieveData(EnvoyConnector.java:188) ~[?:?]
at org.openhab.binding.enphase.internal.handler.EnvoyConnector.getProduction(EnvoyConnector.java:135) ~[?:?]
at org.openhab.binding.enphase.internal.handler.EnvoyBridgeHandler.updateEnvoy(EnvoyBridgeHandler.java:313) ~[?:?]
at org.openhab.binding.enphase.internal.handler.EnvoyBridgeHandler.updateData(EnvoyBridgeHandler.java:262) ~[?:?]
at org.openhab.binding.enphase.internal.handler.EnvoyBridgeHandler.lambda$2(EnvoyBridgeHandler.java:159) ~[?:?]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539) ~[?:?]
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) ~[?:?]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) ~[?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) ~[?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) ~[?:?]
at java.lang.Thread.run(Thread.java:833) ~[?:?]
01:24:14.472 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'enphase:envoy:122308070085' changed from UNKNOWN to OFFLINE (COMMUNICATION_ERROR): Could not login to Entrez JWT Portal. Status code:200
Also still failing.
2023-05-16 16:42:56.769 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305160640 (292)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(355)] : Querying state active
2023-05-16 16:42:56.771 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305160640 (292)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(355)] : Deactivating component
2023-05-16 16:42:56.771 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305160640 (292)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(355)] : registration change queue [unregistered]
2023-05-16 16:42:56.825 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305160640 (292)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(355)] : Querying state active
2023-05-16 16:42:56.826 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305160640 (292)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(355)] : getting deactivate: deactivate
2023-05-16 16:42:56.829 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305160640 (292)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(355)] : Locating method deactivate in class org.openhab.binding.enphase.internal.EnphaseHandlerFactory
2023-05-16 16:42:56.831 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305160640 (292)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(355)] : Declared Method org.openhab.binding.enphase.internal.EnphaseHandlerFactory.deactivate([interface org.osgi.service.component.ComponentContext]) not found
2023-05-16 16:42:56.833 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305160640 (292)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(355)] : Found deactivate method: public void org.openhab.binding.enphase.internal.EnphaseHandlerFactory.deactivate()
2023-05-16 16:42:56.833 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305160640 (292)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(355)] : invoking deactivate: deactivate: parameters []
2023-05-16 16:42:56.833 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305160640 (292)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(355)] : invoked deactivate: deactivate
2023-05-16 16:42:56.835 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305160640 (292)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(355)] : DependencyManager: $003 close component unbinding from org.apache.felix.scr.impl.manager.ComponentContextImpl@5defca04 at tracking count 4 refpairs: [[RefPair: ref: [{org.openhab.binding.enphase.internal.EnvoyHostAddressCache, org.openhab.core.config.discovery.mdns.MDNSDiscoveryParticipant}={service.id=1238, service.bundleid=292, service.scope=bundle, component.name=org.openhab.binding.enphase.internal.discovery.EnvoyDiscoveryParticipant, component.id=356}] service: [org.openhab.binding.enphase.internal.discovery.EnvoyDiscoveryParticipant@2d7add98]]]
2023-05-16 16:42:56.835 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305160640 (292)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(355)] : DependencyManager: $002 close component unbinding from org.apache.felix.scr.impl.manager.ComponentContextImpl@5defca04 at tracking count 3 refpairs: [[RefPair: ref: [{org.openhab.core.io.net.http.HttpClientFactory, org.openhab.core.io.net.http.WebSocketFactory}={service.id=278, service.bundleid=173, service.scope=bundle, component.name=org.openhab.core.io.net.http.internal.WebClientFactoryImpl, component.id=151}] service: [org.openhab.core.io.net.http.internal.WebClientFactoryImpl@62d8523]]]
2023-05-16 16:42:56.837 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305160640 (292)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(355)] : DependencyManager: $001 close component unbinding from org.apache.felix.scr.impl.manager.ComponentContextImpl@5defca04 at tracking count 2 refpairs: [[RefPair: ref: [{org.openhab.core.i18n.TranslationProvider, org.openhab.core.i18n.LocaleProvider, org.openhab.core.i18n.LocationProvider, org.openhab.core.i18n.TimeZoneProvider, org.openhab.core.i18n.UnitProvider}={location=50,-1, service.id=178, service.bundleid=148, service.scope=bundle, component.name=org.openhab.core.internal.i18n.I18nProviderImpl, language=en, service.config.label=Regional Settings, component.id=28, timezone=Europe/London, service.config.category=system, region=GB, service.config.description.uri=system:i18n, service.pid=[org.openhab.i18n, org.openhab.i18n]}] service: [org.openhab.core.internal.i18n.I18nProviderImpl@7c5765c5]]]
2023-05-16 16:42:56.837 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305160640 (292)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(355)] : DependencyManager: $000 close component unbinding from org.apache.felix.scr.impl.manager.ComponentContextImpl@5defca04 at tracking count 1 refpairs: [[RefPair: ref: [{org.openhab.core.i18n.TranslationProvider, org.openhab.core.i18n.LocaleProvider, org.openhab.core.i18n.LocationProvider, org.openhab.core.i18n.TimeZoneProvider, org.openhab.core.i18n.UnitProvider}={location=50,-1, service.id=178, service.bundleid=148, service.scope=bundle, component.name=org.openhab.core.internal.i18n.I18nProviderImpl, language=en, service.config.label=Regional Settings, component.id=28, timezone=Europe/London, service.config.category=system, region=GB, service.config.description.uri=system:i18n, service.pid=[org.openhab.i18n, org.openhab.i18n]}] service: [org.openhab.core.internal.i18n.I18nProviderImpl@7c5765c5]]]
2023-05-16 16:42:56.837 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305160640 (292)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(355)] : Unset and deconfigured implementation object for component in deleteComponent for reason Unspecified
2023-05-16 16:42:56.838 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305160640 (292)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(355)] : Changed state from active to satisfied
2023-05-16 16:42:56.839 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305160640 (292)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(355)] : Deactivating dependency managers
2023-05-16 16:42:56.839 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305160640 (292)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(355)] : Disabling dependency managers
2023-05-16 16:42:56.840 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305160640 (292)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(355)] : unregistering service listener for dependency $000
2023-05-16 16:42:56.840 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305160640 (292)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(355)] : unregistering service listener for dependency $001
2023-05-16 16:42:56.840 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305160640 (292)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(355)] : unregistering service listener for dependency $002
2023-05-16 16:42:56.840 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305160640 (292)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(355)] : unregistering service listener for dependency $003
2023-05-16 16:42:56.840 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305160640 (292)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(355)] : Querying state satisfied
2023-05-16 16:42:56.840 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305160640 (292)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(355)] : Changed state from satisfied to disposed
2023-05-16 16:42:56.840 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305160640 (292)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(355)] : Disposing component (reason: 6)
2023-05-16 16:42:56.841 [DEBUG] [.discovery.EnvoyDiscoveryParticipant] - bundle org.openhab.binding.enphase:4.0.0.202305160640 (292)[org.openhab.binding.enphase.internal.discovery.EnvoyDiscoveryParticipant(356)] : Querying state active
2023-05-16 16:42:56.841 [DEBUG] [.discovery.EnvoyDiscoveryParticipant] - bundle org.openhab.binding.enphase:4.0.0.202305160640 (292)[org.openhab.binding.enphase.internal.discovery.EnvoyDiscoveryParticipant(356)] : Deactivating component
2023-05-16 16:42:56.841 [DEBUG] [.discovery.EnvoyDiscoveryParticipant] - bundle org.openhab.binding.enphase:4.0.0.202305160640 (292)[org.openhab.binding.enphase.internal.discovery.EnvoyDiscoveryParticipant(356)] : registration change queue [unregistered]
2023-05-16 16:42:56.843 [DEBUG] [.discovery.EnvoyDiscoveryParticipant] - bundle org.openhab.binding.enphase:4.0.0.202305160640 (292)[org.openhab.binding.enphase.internal.discovery.EnvoyDiscoveryParticipant(356)] : Querying state active
2023-05-16 16:42:56.843 [DEBUG] [.discovery.EnvoyDiscoveryParticipant] - bundle org.openhab.binding.enphase:4.0.0.202305160640 (292)[org.openhab.binding.enphase.internal.discovery.EnvoyDiscoveryParticipant(356)] : getting deactivate: deactivate
2023-05-16 16:42:56.843 [DEBUG] [.discovery.EnvoyDiscoveryParticipant] - bundle org.openhab.binding.enphase:4.0.0.202305160640 (292)[org.openhab.binding.enphase.internal.discovery.EnvoyDiscoveryParticipant(356)] : Locating method deactivate in class org.openhab.binding.enphase.internal.discovery.EnvoyDiscoveryParticipant
2023-05-16 16:42:56.844 [DEBUG] [.discovery.EnvoyDiscoveryParticipant] - bundle org.openhab.binding.enphase:4.0.0.202305160640 (292)[org.openhab.binding.enphase.internal.discovery.EnvoyDiscoveryParticipant(356)] : Declared Method org.openhab.binding.enphase.internal.discovery.EnvoyDiscoveryParticipant.deactivate([interface org.osgi.service.component.ComponentContext]) not found
2023-05-16 16:42:56.844 [DEBUG] [.discovery.EnvoyDiscoveryParticipant] - bundle org.openhab.binding.enphase:4.0.0.202305160640 (292)[org.openhab.binding.enphase.internal.discovery.EnvoyDiscoveryParticipant(356)] : Locating method deactivate in class java.lang.Object
2023-05-16 16:42:56.844 [DEBUG] [.discovery.EnvoyDiscoveryParticipant] - bundle org.openhab.binding.enphase:4.0.0.202305160640 (292)[org.openhab.binding.enphase.internal.discovery.EnvoyDiscoveryParticipant(356)] : Declared Method java.lang.Object.deactivate([interface org.osgi.service.component.ComponentContext]) not found
2023-05-16 16:42:56.844 [DEBUG] [.discovery.EnvoyDiscoveryParticipant] - bundle org.openhab.binding.enphase:4.0.0.202305160640 (292)[org.openhab.binding.enphase.internal.discovery.EnvoyDiscoveryParticipant(356)] : deactivate method [deactivate] not found, ignoring
2023-05-16 16:42:56.844 [DEBUG] [.discovery.EnvoyDiscoveryParticipant] - bundle org.openhab.binding.enphase:4.0.0.202305160640 (292)[org.openhab.binding.enphase.internal.discovery.EnvoyDiscoveryParticipant(356)] : Unset and deconfigured implementation object for component in deleteComponent for reason Unspecified
2023-05-16 16:42:56.845 [DEBUG] [.discovery.EnvoyDiscoveryParticipant] - bundle org.openhab.binding.enphase:4.0.0.202305160640 (292)[org.openhab.binding.enphase.internal.discovery.EnvoyDiscoveryParticipant(356)] : Changed state from active to satisfied
2023-05-16 16:42:56.845 [DEBUG] [.discovery.EnvoyDiscoveryParticipant] - bundle org.openhab.binding.enphase:4.0.0.202305160640 (292)[org.openhab.binding.enphase.internal.discovery.EnvoyDiscoveryParticipant(356)] : Deactivating dependency managers
2023-05-16 16:42:56.845 [DEBUG] [.discovery.EnvoyDiscoveryParticipant] - bundle org.openhab.binding.enphase:4.0.0.202305160640 (292)[org.openhab.binding.enphase.internal.discovery.EnvoyDiscoveryParticipant(356)] : Disabling dependency managers
2023-05-16 16:42:56.845 [DEBUG] [.discovery.EnvoyDiscoveryParticipant] - bundle org.openhab.binding.enphase:4.0.0.202305160640 (292)[org.openhab.binding.enphase.internal.discovery.EnvoyDiscoveryParticipant(356)] : Querying state satisfied
2023-05-16 16:42:56.845 [DEBUG] [.discovery.EnvoyDiscoveryParticipant] - bundle org.openhab.binding.enphase:4.0.0.202305160640 (292)[org.openhab.binding.enphase.internal.discovery.EnvoyDiscoveryParticipant(356)] : Changed state from satisfied to disposed
2023-05-16 16:42:56.849 [DEBUG] [.discovery.EnvoyDiscoveryParticipant] - bundle org.openhab.binding.enphase:4.0.0.202305160640 (292)[org.openhab.binding.enphase.internal.discovery.EnvoyDiscoveryParticipant(356)] : Disposing component (reason: 6)
2023-05-16 16:43:38.210 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory] : BundleComponentActivator : ComponentHolder created.
2023-05-16 16:43:38.213 [DEBUG] [.discovery.EnvoyDiscoveryParticipant] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.discovery.EnvoyDiscoveryParticipant] : BundleComponentActivator : ComponentHolder created.
2023-05-16 16:43:38.224 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory] : Dependency Manager created $000interface=org.openhab.core.i18n.LocaleProvider, filter=null, policy=static, cardinality=1..1, bind=null, unbind=null, updated=null, field=null, field-option=null, collection-type=null, parameter=0
2023-05-16 16:43:38.224 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory] : Dependency Manager created $001interface=org.openhab.core.i18n.TranslationProvider, filter=null, policy=static, cardinality=1..1, bind=null, unbind=null, updated=null, field=null, field-option=null, collection-type=null, parameter=1
2023-05-16 16:43:38.225 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory] : Dependency Manager created $002interface=org.openhab.binding.enphase.internal.EnvoyHostAddressCache, filter=null, policy=static, cardinality=1..1, bind=null, unbind=null, updated=null, field=null, field-option=null, collection-type=null, parameter=2
2023-05-16 16:43:38.225 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory] : Component created: DS=DS14, implementation=org.openhab.binding.enphase.internal.EnphaseHandlerFactory, immediate=false, default-enabled=true, factory=null, configuration-policy=optional, activate=activate, deactivate=deactivate, modified=null configuration-pid=[binding.enphase]
2023-05-16 16:43:38.225 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory] : Component Services: scope=singleton, services=[org.openhab.core.thing.binding.ThingHandlerFactory]
2023-05-16 16:43:38.226 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory] : Component Properties: {}
2023-05-16 16:43:38.226 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory] : Querying state disabled
2023-05-16 16:43:38.227 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory] : Querying state disabled
2023-05-16 16:43:38.228 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory] : Component can not be activated since it is in state disabled
2023-05-16 16:43:38.232 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory] : Querying state disabled
2023-05-16 16:43:38.232 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(357)] : Updating target filters
2023-05-16 16:43:38.380 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(357)] : No change in target property for dependency $000: currently registered: false
2023-05-16 16:43:38.380 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(357)] : No existing service listener to unregister for dependency $000
2023-05-16 16:43:38.381 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(357)] : Setting target property for dependency $000 to null
2023-05-16 16:43:38.382 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(357)] : New service tracker for $000, initial active: false, previous references: {}, classFilter: (objectClass=org.openhab.core.i18n.LocaleProvider), initialReferenceFilter (objectClass=org.openhab.core.i18n.LocaleProvider)
2023-05-16 16:43:38.382 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(357)] : dm $000 tracker reset (closed)
2023-05-16 16:43:38.385 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(357)] : dm $000 tracking 1 SingleStatic added {org.openhab.core.i18n.TranslationProvider, org.openhab.core.i18n.LocaleProvider, org.openhab.core.i18n.LocationProvider, org.openhab.core.i18n.TimeZoneProvider, org.openhab.core.i18n.UnitProvider}={location=50,-1, service.id=178, service.bundleid=148, service.scope=bundle, component.name=org.openhab.core.internal.i18n.I18nProviderImpl, language=en, service.config.label=Regional Settings, component.id=28, timezone=Europe/London, service.config.category=system, region=GB, service.config.description.uri=system:i18n, service.pid=[org.openhab.i18n, org.openhab.i18n]} (enter)
2023-05-16 16:43:38.386 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(357)] : dm $000 tracking 1 SingleStatic active: false trackerOpened: false optional: false
2023-05-16 16:43:38.387 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(357)] : dm $000 tracking 1 SingleStatic added {org.openhab.core.i18n.TranslationProvider, org.openhab.core.i18n.LocaleProvider, org.openhab.core.i18n.LocationProvider, org.openhab.core.i18n.TimeZoneProvider, org.openhab.core.i18n.UnitProvider}={location=50,-1, service.id=178, service.bundleid=148, service.scope=bundle, component.name=org.openhab.core.internal.i18n.I18nProviderImpl, language=en, service.config.label=Regional Settings, component.id=28, timezone=Europe/London, service.config.category=system, region=GB, service.config.description.uri=system:i18n, service.pid=[org.openhab.i18n, org.openhab.i18n]} (exit)
2023-05-16 16:43:38.387 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(357)] : dm $000 tracker opened
2023-05-16 16:43:38.387 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(357)] : registering service listener for dependency $000
2023-05-16 16:43:38.388 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(357)] : No change in target property for dependency $001: currently registered: false
2023-05-16 16:43:38.388 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(357)] : No existing service listener to unregister for dependency $001
2023-05-16 16:43:38.389 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(357)] : Setting target property for dependency $001 to null
2023-05-16 16:43:38.389 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(357)] : New service tracker for $001, initial active: false, previous references: {}, classFilter: (objectClass=org.openhab.core.i18n.TranslationProvider), initialReferenceFilter (objectClass=org.openhab.core.i18n.TranslationProvider)
2023-05-16 16:43:38.390 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(357)] : dm $001 tracker reset (closed)
2023-05-16 16:43:38.391 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(357)] : dm $001 tracking 2 SingleStatic added {org.openhab.core.i18n.TranslationProvider, org.openhab.core.i18n.LocaleProvider, org.openhab.core.i18n.LocationProvider, org.openhab.core.i18n.TimeZoneProvider, org.openhab.core.i18n.UnitProvider}={location=50,-1, service.id=178, service.bundleid=148, service.scope=bundle, component.name=org.openhab.core.internal.i18n.I18nProviderImpl, language=en, service.config.label=Regional Settings, component.id=28, timezone=Europe/London, service.config.category=system, region=GB, service.config.description.uri=system:i18n, service.pid=[org.openhab.i18n, org.openhab.i18n]} (enter)
2023-05-16 16:43:38.392 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(357)] : dm $001 tracking 2 SingleStatic active: false trackerOpened: false optional: false
2023-05-16 16:43:38.392 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(357)] : dm $001 tracking 2 SingleStatic added {org.openhab.core.i18n.TranslationProvider, org.openhab.core.i18n.LocaleProvider, org.openhab.core.i18n.LocationProvider, org.openhab.core.i18n.TimeZoneProvider, org.openhab.core.i18n.UnitProvider}={location=50,-1, service.id=178, service.bundleid=148, service.scope=bundle, component.name=org.openhab.core.internal.i18n.I18nProviderImpl, language=en, service.config.label=Regional Settings, component.id=28, timezone=Europe/London, service.config.category=system, region=GB, service.config.description.uri=system:i18n, service.pid=[org.openhab.i18n, org.openhab.i18n]} (exit)
2023-05-16 16:43:38.392 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(357)] : dm $001 tracker opened
2023-05-16 16:43:38.392 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(357)] : registering service listener for dependency $001
2023-05-16 16:43:38.392 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(357)] : No change in target property for dependency $002: currently registered: false
2023-05-16 16:43:38.392 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(357)] : No existing service listener to unregister for dependency $002
2023-05-16 16:43:38.392 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(357)] : Setting target property for dependency $002 to null
2023-05-16 16:43:38.392 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(357)] : New service tracker for $002, initial active: false, previous references: {}, classFilter: (objectClass=org.openhab.binding.enphase.internal.EnvoyHostAddressCache), initialReferenceFilter (objectClass=org.openhab.binding.enphase.internal.EnvoyHostAddressCache)
2023-05-16 16:43:38.392 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(357)] : dm $002 tracker reset (closed)
2023-05-16 16:43:38.393 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(357)] : dm $002 tracker opened
2023-05-16 16:43:38.393 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(357)] : registering service listener for dependency $002
2023-05-16 16:43:38.393 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(357)] : Changed state from disabled to unsatisfiedReference
2023-05-16 16:43:38.393 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(357)] : Component enabled
2023-05-16 16:43:38.393 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(357)] : ActivateInternal
2023-05-16 16:43:38.393 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(357)] : Querying state unsatisfiedReference
2023-05-16 16:43:38.393 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(357)] : Querying state unsatisfiedReference
2023-05-16 16:43:38.393 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(357)] : Activating component from state unsatisfiedReference
2023-05-16 16:43:38.394 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(357)] : Querying state unsatisfiedReference
2023-05-16 16:43:38.395 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(357)] : Querying state unsatisfiedReference
2023-05-16 16:43:38.396 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(357)] : Dependency not satisfied: $002
2023-05-16 16:43:38.396 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(357)] : Not all dependencies satisfied, cannot activate
2023-05-16 16:43:38.396 [DEBUG] [.discovery.EnvoyDiscoveryParticipant] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.discovery.EnvoyDiscoveryParticipant] : Component created: DS=DS13, implementation=org.openhab.binding.enphase.internal.discovery.EnvoyDiscoveryParticipant, immediate=false, default-enabled=true, factory=null, configuration-policy=optional, activate=activate, deactivate=deactivate, modified=null configuration-pid=[org.openhab.binding.enphase.internal.discovery.EnvoyDiscoveryParticipant]
2023-05-16 16:43:38.396 [DEBUG] [.discovery.EnvoyDiscoveryParticipant] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.discovery.EnvoyDiscoveryParticipant] : Component Services: scope=singleton, services=[org.openhab.binding.enphase.internal.EnvoyHostAddressCache, org.openhab.core.config.discovery.mdns.MDNSDiscoveryParticipant]
2023-05-16 16:43:38.396 [DEBUG] [.discovery.EnvoyDiscoveryParticipant] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.discovery.EnvoyDiscoveryParticipant] : Component Properties: {}
2023-05-16 16:43:38.397 [DEBUG] [.discovery.EnvoyDiscoveryParticipant] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.discovery.EnvoyDiscoveryParticipant] : Querying state disabled
2023-05-16 16:43:38.397 [DEBUG] [.discovery.EnvoyDiscoveryParticipant] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.discovery.EnvoyDiscoveryParticipant] : Querying state disabled
2023-05-16 16:43:38.397 [DEBUG] [.discovery.EnvoyDiscoveryParticipant] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.discovery.EnvoyDiscoveryParticipant] : Component can not be activated since it is in state disabled
2023-05-16 16:43:38.397 [DEBUG] [.discovery.EnvoyDiscoveryParticipant] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.discovery.EnvoyDiscoveryParticipant] : Querying state disabled
2023-05-16 16:43:38.397 [DEBUG] [.discovery.EnvoyDiscoveryParticipant] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.discovery.EnvoyDiscoveryParticipant(358)] : Updating target filters
2023-05-16 16:43:38.397 [DEBUG] [.discovery.EnvoyDiscoveryParticipant] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.discovery.EnvoyDiscoveryParticipant(358)] : Changed state from disabled to unsatisfiedReference
2023-05-16 16:43:38.397 [DEBUG] [.discovery.EnvoyDiscoveryParticipant] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.discovery.EnvoyDiscoveryParticipant(358)] : Component enabled
2023-05-16 16:43:38.397 [DEBUG] [.discovery.EnvoyDiscoveryParticipant] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.discovery.EnvoyDiscoveryParticipant(358)] : ActivateInternal
2023-05-16 16:43:38.397 [DEBUG] [.discovery.EnvoyDiscoveryParticipant] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.discovery.EnvoyDiscoveryParticipant(358)] : Querying state unsatisfiedReference
2023-05-16 16:43:38.398 [DEBUG] [.discovery.EnvoyDiscoveryParticipant] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.discovery.EnvoyDiscoveryParticipant(358)] : Querying state unsatisfiedReference
2023-05-16 16:43:38.398 [DEBUG] [.discovery.EnvoyDiscoveryParticipant] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.discovery.EnvoyDiscoveryParticipant(358)] : Activating component from state unsatisfiedReference
2023-05-16 16:43:38.398 [DEBUG] [.discovery.EnvoyDiscoveryParticipant] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.discovery.EnvoyDiscoveryParticipant(358)] : Querying state unsatisfiedReference
2023-05-16 16:43:38.399 [DEBUG] [.discovery.EnvoyDiscoveryParticipant] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.discovery.EnvoyDiscoveryParticipant(358)] : Querying state unsatisfiedReference
2023-05-16 16:43:38.400 [DEBUG] [.discovery.EnvoyDiscoveryParticipant] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.discovery.EnvoyDiscoveryParticipant(358)] : Changed state from unsatisfiedReference to satisfied
2023-05-16 16:43:38.400 [DEBUG] [.discovery.EnvoyDiscoveryParticipant] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.discovery.EnvoyDiscoveryParticipant(358)] : registration change queue [registered]
2023-05-16 16:43:38.410 [DEBUG] [.discovery.EnvoyDiscoveryParticipant] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.discovery.EnvoyDiscoveryParticipant(358)] : Checking constructor public org.openhab.binding.enphase.internal.discovery.EnvoyDiscoveryParticipant()
2023-05-16 16:43:38.412 [DEBUG] [.discovery.EnvoyDiscoveryParticipant] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.discovery.EnvoyDiscoveryParticipant(358)] : Found constructor with 0 arguments : public org.openhab.binding.enphase.internal.discovery.EnvoyDiscoveryParticipant()
2023-05-16 16:43:38.413 [DEBUG] [.discovery.EnvoyDiscoveryParticipant] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.discovery.EnvoyDiscoveryParticipant(358)] : This thread collected dependencies
2023-05-16 16:43:38.413 [DEBUG] [.discovery.EnvoyDiscoveryParticipant] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.discovery.EnvoyDiscoveryParticipant(358)] : getService (single component manager) dependencies collected.
2023-05-16 16:43:38.413 [DEBUG] [.discovery.EnvoyDiscoveryParticipant] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.discovery.EnvoyDiscoveryParticipant(358)] : Querying state satisfied
2023-05-16 16:43:38.414 [DEBUG] [.discovery.EnvoyDiscoveryParticipant] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.discovery.EnvoyDiscoveryParticipant(358)] : Querying state satisfied
2023-05-16 16:43:38.415 [DEBUG] [.discovery.EnvoyDiscoveryParticipant] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.discovery.EnvoyDiscoveryParticipant(358)] : getting activate: activate
2023-05-16 16:43:38.416 [DEBUG] [.discovery.EnvoyDiscoveryParticipant] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.discovery.EnvoyDiscoveryParticipant(358)] : Locating method activate in class org.openhab.binding.enphase.internal.discovery.EnvoyDiscoveryParticipant
2023-05-16 16:43:38.417 [DEBUG] [.discovery.EnvoyDiscoveryParticipant] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.discovery.EnvoyDiscoveryParticipant(358)] : Declared Method org.openhab.binding.enphase.internal.discovery.EnvoyDiscoveryParticipant.activate([interface org.osgi.service.component.ComponentContext]) not found
2023-05-16 16:43:38.417 [DEBUG] [.discovery.EnvoyDiscoveryParticipant] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.discovery.EnvoyDiscoveryParticipant(358)] : Locating method activate in class java.lang.Object
2023-05-16 16:43:38.417 [DEBUG] [.discovery.EnvoyDiscoveryParticipant] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.discovery.EnvoyDiscoveryParticipant(358)] : Declared Method java.lang.Object.activate([interface org.osgi.service.component.ComponentContext]) not found
2023-05-16 16:43:38.417 [DEBUG] [.discovery.EnvoyDiscoveryParticipant] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.discovery.EnvoyDiscoveryParticipant(358)] : activate method [activate] not found, ignoring
2023-05-16 16:43:38.417 [DEBUG] [.discovery.EnvoyDiscoveryParticipant] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.discovery.EnvoyDiscoveryParticipant(358)] : Set implementation object for component
2023-05-16 16:43:38.417 [DEBUG] [.discovery.EnvoyDiscoveryParticipant] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.discovery.EnvoyDiscoveryParticipant(358)] : Changed state from satisfied to active
2023-05-16 16:43:38.419 [DEBUG] [.discovery.EnvoyDiscoveryParticipant] - id found: envoy with type: _enphase-envoy._tcp.local.
2023-05-16 16:43:38.419 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(357)] : dm $002 tracking 3 SingleStatic added {org.openhab.binding.enphase.internal.EnvoyHostAddressCache, org.openhab.core.config.discovery.mdns.MDNSDiscoveryParticipant}={service.id=1241, service.bundleid=293, service.scope=bundle, component.name=org.openhab.binding.enphase.internal.discovery.EnvoyDiscoveryParticipant, component.id=358} (enter)
2023-05-16 16:43:38.419 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(357)] : ActivateInternal
2023-05-16 16:43:38.420 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(357)] : Querying state unsatisfiedReference
2023-05-16 16:43:38.420 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(357)] : Querying state unsatisfiedReference
2023-05-16 16:43:38.420 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(357)] : Activating component from state unsatisfiedReference
2023-05-16 16:43:38.420 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(357)] : Querying state unsatisfiedReference
2023-05-16 16:43:38.420 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(357)] : Querying state unsatisfiedReference
2023-05-16 16:43:38.420 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(357)] : Changed state from unsatisfiedReference to satisfied
2023-05-16 16:43:38.420 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(357)] : registration change queue [registered]
2023-05-16 16:43:38.421 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(357)] : Checking constructor public org.openhab.binding.enphase.internal.EnphaseHandlerFactory(org.openhab.core.i18n.LocaleProvider,org.openhab.core.i18n.TranslationProvider,org.openhab.binding.enphase.internal.EnvoyHostAddressCache)
2023-05-16 16:43:38.422 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(357)] : getReferenceClass: Looking for interface class org.openhab.core.i18n.LocaleProvider through loader of org.openhab.binding.enphase.internal.EnphaseHandlerFactory
2023-05-16 16:43:38.423 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(357)] : getParameterClass: Found class org.openhab.core.i18n.LocaleProvider
2023-05-16 16:43:38.423 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(357)] : getReferenceClass: Looking for interface class org.openhab.core.i18n.TranslationProvider through loader of org.openhab.binding.enphase.internal.EnphaseHandlerFactory
2023-05-16 16:43:38.424 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(357)] : getParameterClass: Found class org.openhab.core.i18n.TranslationProvider
2023-05-16 16:43:38.424 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(357)] : getReferenceClass: Looking for interface class org.openhab.binding.enphase.internal.EnvoyHostAddressCache through loader of org.openhab.binding.enphase.internal.EnphaseHandlerFactory
2023-05-16 16:43:38.424 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(357)] : getParameterClass: Found class org.openhab.binding.enphase.internal.EnvoyHostAddressCache
2023-05-16 16:43:38.424 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(357)] : Found constructor with 3 arguments : public org.openhab.binding.enphase.internal.EnphaseHandlerFactory(org.openhab.core.i18n.LocaleProvider,org.openhab.core.i18n.TranslationProvider,org.openhab.binding.enphase.internal.EnvoyHostAddressCache)
2023-05-16 16:43:38.424 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(357)] : This thread collected dependencies
2023-05-16 16:43:38.425 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(357)] : getService (single component manager) dependencies collected.
2023-05-16 16:43:38.425 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(357)] : Querying state satisfied
2023-05-16 16:43:38.425 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(357)] : Querying state satisfied
2023-05-16 16:43:38.425 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(357)] : For dependency $000, optional: false; to bind: [[RefPair: ref: [{org.openhab.core.i18n.TranslationProvider, org.openhab.core.i18n.LocaleProvider, org.openhab.core.i18n.LocationProvider, org.openhab.core.i18n.TimeZoneProvider, org.openhab.core.i18n.UnitProvider}={location=50,-1, service.id=178, service.bundleid=148, service.scope=bundle, component.name=org.openhab.core.internal.i18n.I18nProviderImpl, language=en, service.config.label=Regional Settings, component.id=28, timezone=Europe/London, service.config.category=system, region=GB, service.config.description.uri=system:i18n, service.pid=[org.openhab.i18n, org.openhab.i18n]}] service: [null]]]
2023-05-16 16:43:38.425 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(357)] : For dependency $001, optional: false; to bind: [[RefPair: ref: [{org.openhab.core.i18n.TranslationProvider, org.openhab.core.i18n.LocaleProvider, org.openhab.core.i18n.LocationProvider, org.openhab.core.i18n.TimeZoneProvider, org.openhab.core.i18n.UnitProvider}={location=50,-1, service.id=178, service.bundleid=148, service.scope=bundle, component.name=org.openhab.core.internal.i18n.I18nProviderImpl, language=en, service.config.label=Regional Settings, component.id=28, timezone=Europe/London, service.config.category=system, region=GB, service.config.description.uri=system:i18n, service.pid=[org.openhab.i18n, org.openhab.i18n]}] service: [null]]]
2023-05-16 16:43:38.425 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(357)] : For dependency $002, optional: false; to bind: [[RefPair: ref: [{org.openhab.binding.enphase.internal.EnvoyHostAddressCache, org.openhab.core.config.discovery.mdns.MDNSDiscoveryParticipant}={service.id=1241, service.bundleid=293, service.scope=bundle, component.name=org.openhab.binding.enphase.internal.discovery.EnvoyDiscoveryParticipant, component.id=358}] service: [null]]]
2023-05-16 16:43:38.846 [WARN ] [ty.util.ssl.SslContextFactory.config] - Trusting all certificates configured for Client@20b2f6a6[provider=null,keyStore=null,trustStore=null]
2023-05-16 16:43:38.850 [WARN ] [ty.util.ssl.SslContextFactory.config] - No Client EndPointIdentificationAlgorithm configured for Client@20b2f6a6[provider=null,keyStore=null,trustStore=null]
2023-05-16 16:43:38.853 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(357)] : getting activate: activate
2023-05-16 16:43:38.853 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(357)] : Locating method activate in class org.openhab.binding.enphase.internal.EnphaseHandlerFactory
2023-05-16 16:43:38.853 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(357)] : Declared Method org.openhab.binding.enphase.internal.EnphaseHandlerFactory.activate([interface org.osgi.service.component.ComponentContext]) not found
2023-05-16 16:43:38.853 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(357)] : Locating method activate in class org.openhab.core.thing.binding.BaseThingHandlerFactory
2023-05-16 16:43:38.854 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(357)] : Found activate method: protected void org.openhab.core.thing.binding.BaseThingHandlerFactory.activate(org.osgi.service.component.ComponentContext)
2023-05-16 16:43:38.855 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(357)] : invoking activate: activate: parameters [org.apache.felix.scr.impl.manager.ComponentContextImpl]
2023-05-16 16:43:38.855 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(357)] : invoked activate: activate
2023-05-16 16:43:38.855 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(357)] : Set implementation object for component
2023-05-16 16:43:38.855 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(357)] : Changed state from satisfied to active
2023-05-16 16:43:38.858 [DEBUG] [phase.internal.EnphaseHandlerFactory] - bundle org.openhab.binding.enphase:4.0.0.202305161222 (293)[org.openhab.binding.enphase.internal.EnphaseHandlerFactory(357)] : dm $002 tracking 3 SingleStatic added {org.openhab.binding.enphase.internal.EnvoyHostAddressCache, org.openhab.core.config.discovery.mdns.MDNSDiscoveryParticipant}={service.id=1241, service.bundleid=293, service.scope=bundle, component.name=org.openhab.binding.enphase.internal.discovery.EnvoyDiscoveryParticipant, component.id=358} (exit)
2023-05-16 16:43:39.312 [DEBUG] [ternal.handler.EnvoyConnectorWrapper] - Set Envoy version found in the Envoy data: null
2023-05-16 16:43:39.390 [TRACE] [.internal.handler.EnvoyBridgeHandler] - Check connection
2023-05-16 16:43:39.810 [DEBUG] [hase.internal.handler.EnvoyConnector] - ExecutionException: org.eclipse.jetty.client.HttpResponseException: HTTP protocol violation: Authentication challenge without WWW-Authenticate header
java.util.concurrent.ExecutionException: org.eclipse.jetty.client.HttpResponseException: HTTP protocol violation: Authentication challenge without WWW-Authenticate header
at org.eclipse.jetty.client.util.FutureResponseListener.getResult(FutureResponseListener.java:118) ~[?:?]
at org.eclipse.jetty.client.util.FutureResponseListener.get(FutureResponseListener.java:101) ~[?:?]
at org.eclipse.jetty.client.HttpRequest.send(HttpRequest.java:730) ~[?:?]
at org.openhab.binding.enphase.internal.handler.EnvoyConnector.send(EnvoyConnector.java:223) ~[?:?]
at org.openhab.binding.enphase.internal.handler.EnvoyConnector.checkConnection(EnvoyConnector.java:121) ~[?:?]
at org.openhab.binding.enphase.internal.handler.EnvoyConnectorWrapper.determineConnector(EnvoyConnectorWrapper.java:98) ~[?:?]
at org.openhab.binding.enphase.internal.handler.EnvoyConnectorWrapper.setConnector(EnvoyConnectorWrapper.java:59) ~[?:?]
at org.openhab.binding.enphase.internal.handler.EnvoyBridgeHandler.checkConnection(EnvoyBridgeHandler.java:300) ~[?:?]
at org.openhab.binding.enphase.internal.handler.EnvoyBridgeHandler.updateData(EnvoyBridgeHandler.java:261) ~[?:?]
at org.openhab.binding.enphase.internal.handler.EnvoyBridgeHandler.lambda$2(EnvoyBridgeHandler.java:159) ~[?:?]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [?:?]
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) [?:?]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) [?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
at java.lang.Thread.run(Thread.java:829) [?:?]
Caused by: org.eclipse.jetty.client.HttpResponseException: HTTP protocol violation: Authentication challenge without WWW-Authenticate header
at org.eclipse.jetty.client.AuthenticationProtocolHandler$AuthenticationListener.onComplete(AuthenticationProtocolHandler.java:164) ~[?:?]
at org.eclipse.jetty.client.ResponseNotifier.notifyComplete(ResponseNotifier.java:218) ~[?:?]
at org.eclipse.jetty.client.ResponseNotifier.notifyComplete(ResponseNotifier.java:210) ~[?:?]
at org.eclipse.jetty.client.HttpReceiver.terminateResponse(HttpReceiver.java:481) ~[?:?]
at org.eclipse.jetty.client.HttpReceiver.terminateResponse(HttpReceiver.java:461) ~[?:?]
at org.eclipse.jetty.client.HttpReceiver.responseSuccess(HttpReceiver.java:424) ~[?:?]
at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.messageComplete(HttpReceiverOverHTTP.java:374) ~[?:?]
at org.eclipse.jetty.http.HttpParser.handleContentMessage(HttpParser.java:597) ~[?:?]
at org.eclipse.jetty.http.HttpParser.parseContent(HttpParser.java:1722) ~[?:?]
at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:1551) ~[?:?]
at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.parse(HttpReceiverOverHTTP.java:208) ~[?:?]
at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.process(HttpReceiverOverHTTP.java:148) ~[?:?]
at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.receive(HttpReceiverOverHTTP.java:80) ~[?:?]
at org.eclipse.jetty.client.http.HttpChannelOverHTTP.receive(HttpChannelOverHTTP.java:131) ~[?:?]
at org.eclipse.jetty.client.http.HttpConnectionOverHTTP.onFillable(HttpConnectionOverHTTP.java:172) ~[?:?]
at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311) ~[?:?]
at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) ~[?:?]
at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.onFillable(SslConnection.java:555) ~[?:?]
at org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:410) ~[?:?]
at org.eclipse.jetty.io.ssl.SslConnection$2.succeeded(SslConnection.java:164) ~[?:?]
at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) ~[?:?]
at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104) ~[?:?]
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:338) ~[?:?]
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:315) ~[?:?]
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:173) ~[?:?]
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131) ~[?:?]
at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:409) ~[?:?]
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:883) ~[?:?]
at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1034) ~[?:?]
... 1 more
2023-05-16 16:43:39.926 [DEBUG] [.internal.handler.EnvoyBridgeHandler] - Schedule hostname/ip address update for thing enphase:envoy:XXXXXX in 10 seconds.
2023-05-16 16:43:49.934 [DEBUG] [.internal.handler.EnvoyBridgeHandler] - Schedule hostname/ip address update for thing enphase:envoy:XXXXXX in 10 seconds.
I don’t seem to be getting the enphase version being set, currently null and even though I’ve set the hostname in the .things file it looks like its trying to update the IP address?