[New Binding] Enphase Envoy Solar System gateway

raaahbin · May 12, 2023, 1:20pm

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?

raaahbin · May 14, 2023, 2:04am

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)))"]]]]

hilbrand · May 14, 2023, 10:52am

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.

raaahbin · May 14, 2023, 3:56pm

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!

hilbrand · May 15, 2023, 3:24pm

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.

davebuk · May 15, 2023, 7:42pm

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.

hilbrand · May 16, 2023, 7:39am

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.

davebuk · May 16, 2023, 9:54am

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

hilbrand · May 16, 2023, 3:37pm

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.

raaahbin · May 16, 2023, 3:52pm

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!

raaahbin · May 16, 2023, 3:54pm

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

davebuk · May 16, 2023, 4:08pm

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?

davebuk · May 16, 2023, 4:24pm

I don’t know if it is of relevance but I know there are some differences from the new V7 local API and cloud based access.

https://entrez.enphaseenergy.com/login doesn’t load as a website for me but Enphase Authentication | Login page does. I guess your code is building up the token page url using the info from the .things file and you are using the web url method for obtaining a token?

hilbrand · May 17, 2023, 9:25am

@raaahbin It seems it can’t login. The login reports incorrect username/password. Did you configured the username and password for the Enphase portal? Or is there maybe a space extra in the username/password?

@davebuk It seems the binding has some issues with detecting what version it should use. For some reason the discovery doesn’t get the version. Therefor the binding falls back to trying to determine the version by connecting to the Envoy. However that seems to go wrong. I want to make this a bit more robust instead of guessing what it can be. Therefor can you check the following for me: In a browser open the following page to your envoy device: http://<ip of envoy>/info.xml (Make sure you’re not logged in, for example open in private browsing). Does it exists? And if so, what status does it return (a 200 or something else) and if it returns data what does it show in the tag <software>....</software>?

davebuk · May 17, 2023, 10:36am

**https**://<ip of envoy>/info.xml gives <software>D7.0.88</software>.

raaahbin · May 17, 2023, 11:43am

Yes - copied and pasted username and password directly from keychain, also manually used them to log into the Enphase portal. Plus I tried the version where you don’t configure the username and password and instead paste in the JWT, which gave the same error as davebuk was reporting, and also the version where I manually create a things file with the username and password in there for auto-JWT. I’ll do some more testing tomorrow - has the JAR been updated?

davebuk · May 17, 2023, 1:06pm

@raaahbin I believe the JAR on github is at V2 and is at the latest version for testing.

I’m very much appreciative of the efforts to get the binding updated but from a personal point of view, if the binding can still only update the values every 5 minutes, its not as much use to me as compared to what I have running using the http binding. I know it can be changed but will the binding allow a say 10 second update?

I have some rules setup to run some radiator heaters when power is exported to the grid and then switch those off when I’m importing. A 5 minute update is a bit too long a gap. I can refresh the data using the CURL commands every 10 seconds.

raaahbin · May 17, 2023, 1:26pm

I’ll have a look at replicating your HTTP binding approach when I next have some time to try things out. In the long run, perhaps the enphase binding for most info, coupled with the HTTP binding just for the really short-term “live” data might work best. I’d prefer not to just repeatedly hit the gateway with full queries every 10 seconds when most of the data doesn’t change except on the 5 minute, but I can see the benefit in having some “instantaneous” values too.

davebuk · May 18, 2023, 4:24pm

Hi

Just to follow up, I added a thing using the webGUI rather than a file and had the same result as @raaahbin . The thing will get the software version but fails to become ‘online’. I have tried using a working token and also the JWT auto mode checking for the correct user/password.

hilbrand · May 18, 2023, 6:56pm

@raaahbin and @davebuk I’ve updated the binding (date when showing binding in list binding in openHAB ui = 18-05-2023). I’ve improved detecting what version it should use and also found some other bugs related to configuration. I’ve tested login with my own login an I it goes past the login.

Regarding the readings of the ipv end points. On my system the meters are reporting as disabled. But I do get reading values, every time I call the readings endpoint. Although the value seems not to match the actual values. So it’s a bit weird. An option could be to add reading those values to the binding, but that requires some more thought to see how that would be best implemented.