Upload Timestamps changed after Powerwall reboot


#1

For some unknown reason my Powerwall gateway rebooted itself this morning. The pvintegration service had a bit of a timestamp meltdown which I only noticed hours later.

It went from Europe/London to Sydney time (at a guess) - 06:35 jumped to 14:35, effectively.

Log lines -

2018-12-17 06:33:25,794  INFO [Thread-0] (Controller.java:1806) - >>> 20181217,06:35,-1,-1,-1.0,527,-1000.0,243.7,540,527.982,
243.663,-17.651,96.093,14.85
2018-12-17 06:33:25,794  INFO [Thread-0] (WebClient.java:133) - >>> http://pvoutput.org:80/service/r2/addbatchstatus.jsp?data=
20181217,06:35,-1,-1,-1.0,527,-1000.0,243.7,540,527.982,243.663,-17.651,96.093,14.85
...
2018-12-17 06:37:53,292 ERROR [Thread-9] (AHttpLogReader.java:463) - Http Error
java.net.SocketTimeoutException: Read timed out
...
2018-12-17 06:39:58,181  INFO [Thread-0] (Controller.java:1806) - >>> 20181217,14:40,-1,-1,-1.0,3235,-1000.0,246.3,3330,3235.126,246.349,-157.755,95.359,-3.779
2018-12-17 06:39:58,182  INFO [Thread-0] (WebClient.java:133) - >>> http://pvoutput.org:80/service/r2/addbatchstatus.jsp?data=20181217,14:40,-1,-1,-1.0,3235,-1000.0,246.3,3330,3235.126,246.349,-157.755,95.359,-3.779

Note that the log entries themselves use the correct local time.

Also, running on Linux and

2018-12-17 12:24:21,210  INFO [main] (Controller.java:109) - *** Starting PVOutput Integration Service v1.5.3.1

A restart fixed it.

Edit: I checked the details manually on the Powerwall using REST calls and the time and timezone was correct. The pvintegration service only corrected itself after a restart, no other action.


#2

A bit strange, the powerwall gateway resetting shouldn’t affect the timezone the service uses as this is set to UTC during startup and will only change if the gateway provides a timezone in the timestamp data.


#3

I can reproduce if you want further debug - I can switch the gateway off at the breaker to reset - but only if it’s useful. Any specific extra debug options? I can also post the full log from yesterday, but it looked “boring” to me apart from the lines I posted.


#4

Larger log segment, if it helps.

2018-12-17 06:33:25,794  INFO [Thread-0] (Controller.java:1806) - >>> 20181217,06:35,-1,-1,-1.0,527,-1000.0,243.7,540,527.982,243.663,-17.651,96.093,14.85
2018-12-17 06:33:25,794  INFO [Thread-0] (WebClient.java:133) - >>> http://pvoutput.org:80/service/r2/addbatchstatus.jsp?data=20181217,06:35,-1,-1,-1.0,527,-1000.0,243.7,540,527.982,243.663,-17.651,96.093,14.85
2018-12-17 06:33:37,867  INFO [Thread-9] (WebClient.java:243) - >>> https://192.168.234.43:443/api/meters/aggregates
2018-12-17 06:33:37,892  INFO [Thread-9] (WebClient.java:155) - >>> https://192.168.234.43/api/system_status/soe
2018-12-17 06:33:58,091  INFO [Thread-0] (Controller.java:1834) - <<< 20181217,06:35,1
2018-12-17 06:34:07,913  INFO [Thread-9] (WebClient.java:243) - >>> https://192.168.234.43:443/api/meters/aggregates
2018-12-17 06:34:07,945  INFO [Thread-9] (WebClient.java:155) - >>> https://192.168.234.43/api/system_status/soe
2018-12-17 06:34:37,961  INFO [Thread-9] (WebClient.java:243) - >>> https://192.168.234.43:443/api/meters/aggregates
2018-12-17 06:34:37,989  INFO [Thread-9] (WebClient.java:155) - >>> https://192.168.234.43/api/system_status/soe
2018-12-17 06:35:08,010  INFO [Thread-9] (WebClient.java:243) - >>> https://192.168.234.43:443/api/meters/aggregates
2018-12-17 06:35:08,042  INFO [Thread-9] (WebClient.java:155) - >>> https://192.168.234.43/api/system_status/soe
2018-12-17 06:35:38,068  INFO [Thread-9] (WebClient.java:243) - >>> https://192.168.234.43:443/api/meters/aggregates
2018-12-17 06:35:38,093  INFO [Thread-9] (WebClient.java:155) - >>> https://192.168.234.43/api/system_status/soe
2018-12-17 06:36:08,108  INFO [Thread-9] (WebClient.java:243) - >>> https://192.168.234.43:443/api/meters/aggregates
2018-12-17 06:36:08,176  INFO [Thread-9] (WebClient.java:155) - >>> https://192.168.234.43/api/system_status/soe
2018-12-17 06:36:38,212  INFO [Thread-9] (WebClient.java:243) - >>> https://192.168.234.43:443/api/meters/aggregates
2018-12-17 06:36:38,223  INFO [Thread-9] (WebClient.java:155) - >>> https://192.168.234.43/api/system_status/soe
2018-12-17 06:37:08,239  INFO [Thread-9] (WebClient.java:243) - >>> https://192.168.234.43:443/api/meters/aggregates
2018-12-17 06:37:53,292 ERROR [Thread-9] (AHttpLogReader.java:463) - Http Error
java.net.SocketTimeoutException: Read timed out
        at java.net.SocketInputStream.socketRead0(Native Method)
        at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
        at java.net.SocketInputStream.read(SocketInputStream.java:171)
        at java.net.SocketInputStream.read(SocketInputStream.java:141)
        at sun.security.ssl.InputRecord.readFully(InputRecord.java:465)
        at sun.security.ssl.InputRecord.read(InputRecord.java:503)
        at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:983)
        at sun.security.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:940)
        at sun.security.ssl.AppInputStream.read(AppInputStream.java:105)
        at org.apache.http.impl.io.AbstractSessionInputBuffer.fillBuffer(AbstractSessionInputBuffer.java:149)
        at org.apache.http.impl.io.SocketInputBuffer.fillBuffer(SocketInputBuffer.java:110)
        at org.apache.http.impl.io.AbstractSessionInputBuffer.readLine(AbstractSessionInputBuffer.java:264)
        at org.apache.http.impl.conn.DefaultResponseParser.parseHead(DefaultResponseParser.java:98)
        at org.apache.http.impl.io.AbstractMessageParser.parse(AbstractMessageParser.java:252)
        at org.apache.http.impl.AbstractHttpClientConnection.receiveResponseHeader(AbstractHttpClientConnection.java:281)
        at org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader(DefaultClientConnection.java:247)
        at org.apache.http.impl.conn.AbstractClientConnAdapter.receiveResponseHeader(AbstractClientConnAdapter.java:219)
        at org.apache.http.protocol.HttpRequestExecutor.doReceiveResponse(HttpRequestExecutor.java:298)
        at org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:125)
        at org.apache.http.impl.client.DefaultRequestDirector.tryExecute(DefaultRequestDirector.java:645)
        at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:464)
        at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:820)
        at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:754)
        at org.pvoutput.integration.reader.AHttpLogReader$ASimpleLogFileWriter.get(AHttpLogReader.java:430)
        at org.pvoutput.integration.reader.AHttpLogReader$ASimpleLogFileWriter.run(AHttpLogReader.java:354)
2018-12-17 06:38:23,294  INFO [Thread-9] (WebClient.java:243) - >>> https://192.168.234.43:443/api/meters/aggregates
2018-12-17 06:38:23,300 ERROR [Thread-9] (AHttpLogReader.java:463) - Http Error
org.apache.http.conn.HttpHostConnectException: Connection to https://192.168.234.43:443 refused
        at org.apache.http.impl.conn.DefaultClientConnectionOperator.openConnection(DefaultClientConnectionOperator.java:158)
        at org.apache.http.impl.conn.AbstractPoolEntry.open(AbstractPoolEntry.java:149)
        at org.apache.http.impl.conn.AbstractPooledConnAdapter.open(AbstractPooledConnAdapter.java:121)
        at org.apache.http.impl.client.DefaultRequestDirector.tryConnect(DefaultRequestDirector.java:573)
        at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:425)
        at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:820)
        at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:754)
        at org.pvoutput.integration.reader.AHttpLogReader$ASimpleLogFileWriter.get(AHttpLogReader.java:430)
        at org.pvoutput.integration.reader.AHttpLogReader$ASimpleLogFileWriter.run(AHttpLogReader.java:354)
Caused by: java.net.ConnectException: Connection refused (Connection refused)
        at java.net.PlainSocketImpl.socketConnect(Native Method)
        at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350)
        at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206)
        at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)
        at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
        at java.net.Socket.connect(Socket.java:589)
        at sun.security.ssl.SSLSocketImpl.connect(SSLSocketImpl.java:673)
        at org.apache.http.conn.ssl.SSLSocketFactory.connectSocket(SSLSocketFactory.java:375)
        at org.apache.http.impl.conn.DefaultClientConnectionOperator.openConnection(DefaultClientConnectionOperator.java:148)
        ... 8 more
2018-12-17 06:38:53,301  INFO [Thread-9] (WebClient.java:243) - >>> https://192.168.234.43:443/api/meters/aggregates
2018-12-17 06:38:53,411  INFO [Thread-9] (WebClient.java:155) - >>> https://192.168.234.43/api/system_status/soe
2018-12-17 06:38:53,423  INFO [Thread-9] (DefaultRequestDirector.java:656) - I/O exception (java.net.SocketException) caught when processing request: Connection reset
2018-12-17 06:38:53,423  INFO [Thread-9] (DefaultRequestDirector.java:663) - Retrying request
2018-12-17 06:39:23,505  INFO [Thread-9] (WebClient.java:243) - >>> https://192.168.234.43:443/api/meters/aggregates
2018-12-17 06:39:23,522  INFO [Thread-9] (WebClient.java:155) - >>> https://192.168.234.43/api/system_status/soe
2018-12-17 06:39:53,540  INFO [Thread-9] (WebClient.java:243) - >>> https://192.168.234.43:443/api/meters/aggregates
2018-12-17 06:39:53,558  INFO [Thread-9] (WebClient.java:155) - >>> https://192.168.234.43/api/system_status/soe
2018-12-17 06:39:58,181  INFO [Thread-0] (Controller.java:1806) - >>> 20181217,14:40,-1,-1,-1.0,3235,-1000.0,246.3,3330,3235.126,246.349,-157.755,95.359,-3.779
2018-12-17 06:39:58,182  INFO [Thread-0] (WebClient.java:133) - >>> http://pvoutput.org:80/service/r2/addbatchstatus.jsp?data=20181217,14:40,-1,-1,-1.0,3235,-1000.0,246.3,3330,3235.126,246.349,-157.755,95.359,-3.779
2018-12-17 06:40:23,579  INFO [Thread-9] (WebClient.java:243) - >>> https://192.168.234.43:443/api/meters/aggregates
2018-12-17 06:40:23,605  INFO [Thread-9] (WebClient.java:155) - >>> https://192.168.234.43/api/system_status/soe
2018-12-17 06:40:29,266  INFO [Thread-0] (Controller.java:1834) - <<< 20181217,14:40,1
2018-12-17 06:40:53,646  INFO [Thread-9] (WebClient.java:243) - >>> https://192.168.234.43:443/api/meters/aggregates
2018-12-17 06:40:53,657  INFO [Thread-9] (WebClient.java:155) - >>> https://192.168.234.43/api/system_status/soe
2018-12-17 06:41:23,674  INFO [Thread-9] (WebClient.java:243) - >>> https://192.168.234.43:443/api/meters/aggregates
2018-12-17 06:41:23,701  INFO [Thread-9] (WebClient.java:155) - >>> https://192.168.234.43/api/system_status/soe
2018-12-17 06:41:53,723  INFO [Thread-9] (WebClient.java:243) - >>> https://192.168.234.43:443/api/meters/aggregates
2018-12-17 06:41:53,779  INFO [Thread-9] (WebClient.java:155) - >>> https://192.168.234.43/api/system_status/soe
2018-12-17 06:42:23,811  INFO [Thread-9] (WebClient.java:243) - >>> https://192.168.234.43:443/api/meters/aggregates
2018-12-17 06:42:23,835  INFO [Thread-9] (WebClient.java:155) - >>> https://192.168.234.43/api/system_status/soe
2018-12-17 06:42:53,852  INFO [Thread-9] (WebClient.java:243) - >>> https://192.168.234.43:443/api/meters/aggregates
2018-12-17 06:42:53,885  INFO [Thread-9] (WebClient.java:155) - >>> https://192.168.234.43/api/system_status/soe
2018-12-17 06:43:23,956  INFO [Thread-9] (WebClient.java:243) - >>> https://192.168.234.43:443/api/meters/aggregates
2018-12-17 06:43:23,967  INFO [Thread-9] (WebClient.java:155) - >>> https://192.168.234.43/api/system_status/soe
2018-12-17 06:43:29,309  INFO [Thread-0] (Controller.java:1806) - >>> 20181217,14:45,-1,-1,-1.0,3052,-1000.0,245.1,3050,3052.398,245.13,6.768,94.684,1.071
2018-12-17 06:43:29,309  INFO [Thread-0] (WebClient.java:133) - >>> http://pvoutput.org:80/service/r2/addbatchstatus.jsp?data=20181217,14:45,-1,-1,-1.0,3052,-1000.0,245.1,3050,3052.398,245.13,6.768,94.684,1.071
2018-12-17 06:43:53,985  INFO [Thread-9] (WebClient.java:243) - >>> https://192.168.234.43:443/api/meters/aggregates
2018-12-17 06:43:54,013  INFO [Thread-9] (WebClient.java:155) - >>> https://192.168.234.43/api/system_status/soe
2018-12-17 06:44:00,216  INFO [Thread-0] (Controller.java:1834) - <<< 20181217,14:45,1

#5

If possible, it would be helpful to try this.

If this reproduces the issue, check in pvoutput.ini that timezone is set, by default it runs on the timezone used by the machine, but better to explicitly set one

timezone=UTC

List of available timezones https://pvoutput.org/help.html#live-settings-timezone


#6

I will reboot once I am home.

Just checked and I have

timezone=Europe/London

in pvoutput.ini

(I do this because the machine is set to use UTC but my tariffs are in “local” time which is currently the same but will change in March)

lrwxrwxrwx 1 root root 27 Oct  3 11:25 /etc/localtime -> /usr/share/zoneinfo/Etc/UTC

#7

Power cycled the gateway and the integration service recovered fine, no change in timezone. No changes in the config. Only thing was no secondary “Connection refused” exception, just the one HTTP failure, so there may have been a very specific timing issue in the REST API from the gateway.

I guess this is a closed report if/until it happens again or someone else sees the same and finds this thread via search.