MySQL drops connection after a week

derabbink · January 28, 2016, 10:27pm

I have experienced this a couple of times now: I’m using the MySQL persistence addon to store temperatures that the weather plugin fetches, and after about a week of uptime, OpenHAB doesn’t want to connect to MySQL any more, even though I can connect to it just fine.

This is what I see in my logs whenever a new temperature reading is about to be written to MySQL:

2016-01-28 22:02:31.182 [ERROR] [.p.m.i.MysqlPersistenceService] - mySQL: Connection is not valid!
2016-01-28 22:02:31.182 [ERROR] [.p.m.i.MysqlPersistenceService] - mySQL: Connection is not valid!
2016-01-28 22:02:31.183 [ERROR] [.p.m.i.MysqlPersistenceService] - mySQL: Could not store item 'Weather_Temperature' in database with statement 'INSERT INTO Item2 (TIME, VALUE) VALUES(NOW(),?) ON DUPLICATE KEY UPDATE VALUE=?;': No operations allowed after connection closed.

Analogously, whenever I try to read the data back (e.g. when I try to render a chart), this happens in the logs:

2016-01-28 21:15:05.651 [WARN ] [e.jetty.servlet.ServletHandler] - /chart
java.lang.NullPointerException: null
        at org.openhab.ui.internal.chart.DefaultChartProvider.addItem(DefaultChartProvider.java:298) ~[na:na]
        at org.openhab.ui.internal.chart.DefaultChartProvider.createChart(DefaultChartProvider.java:184) ~[na:na]
        at org.openhab.ui.internal.chart.ChartServlet.doGet(ChartServlet.java:245) ~[na:na]
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:735) ~[javax.servlet_3.0.0.v201112011016.jar:na]
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:848) ~[javax.servlet_3.0.0.v201112011016.jar:na]
        at org.eclipse.equinox.http.servlet.internal.ServletRegistration.service(ServletRegistration.java:61) ~[na:na]
        at org.eclipse.equinox.http.servlet.internal.ProxyServlet.processAlias(ProxyServlet.java:128) ~[na:na]
        at org.eclipse.equinox.http.servlet.internal.ProxyServlet.service(ProxyServlet.java:60) ~[na:na]
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:848) ~[javax.servlet_3.0.0.v201112011016.jar:na]
        at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:598) ~[org.eclipse.jetty.servlet_8.1.3.v20120522.jar:8.1.3.v20120522]
        at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:486) [org.eclipse.jetty.servlet_8.1.3.v20120522.jar:8.1.3.v20120522]
        at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:231) [org.eclipse.jetty.server_8.1.3.v20120522.jar:8.1.3.v20120522]
        at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1065) [org.eclipse.jetty.server_8.1.3.v20120522.jar:8.1.3.v20120522]
        at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:413) [org.eclipse.jetty.servlet_8.1.3.v20120522.jar:8.1.3.v20120522]
        at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:192) [org.eclipse.jetty.server_8.1.3.v20120522.jar:8.1.3.v20120522]
        at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:999) [org.eclipse.jetty.server_8.1.3.v20120522.jar:8.1.3.v20120522]
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:117) [org.eclipse.jetty.server_8.1.3.v20120522.jar:8.1.3.v20120522]
        at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:250) [org.eclipse.jetty.server_8.1.3.v20120522.jar:8.1.3.v20120522]
        at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:149) [org.eclipse.jetty.server_8.1.3.v20120522.jar:8.1.3.v20120522]
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:111) [org.eclipse.jetty.server_8.1.3.v20120522.jar:8.1.3.v20120522]
        at org.eclipse.jetty.server.Server.handle(Server.java:350) [org.eclipse.jetty.server_8.1.3.v20120522.jar:8.1.3.v20120522]
        at org.eclipse.jetty.server.AbstractHttpConnection.handleRequest(AbstractHttpConnection.java:454) [org.eclipse.jetty.server_8.1.3.v20120522.jar:8.1.3.v20120522]
        at org.eclipse.jetty.server.AbstractHttpConnection.headerComplete(AbstractHttpConnection.java:890) [org.eclipse.jetty.server_8.1.3.v20120522.jar:8.1.3.v20120522]
        at org.eclipse.jetty.server.AbstractHttpConnection$RequestHandler.headerComplete(AbstractHttpConnection.java:944) [org.eclipse.jetty.server_8.1.3.v20120522.jar:8.1.3.v20120522]
        at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:630) [org.eclipse.jetty.http_8.1.3.v20120522.jar:8.1.3.v20120522]
        at org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:230) [org.eclipse.jetty.http_8.1.3.v20120522.jar:8.1.3.v20120522]
        at org.eclipse.jetty.server.AsyncHttpConnection.handle(AsyncHttpConnection.java:77) [org.eclipse.jetty.server_8.1.3.v20120522.jar:8.1.3.v20120522]
        at org.eclipse.jetty.io.nio.SslConnection.handle(SslConnection.java:191) [org.eclipse.jetty.io_8.1.3.v20120522.jar:8.1.3.v20120522]
        at org.eclipse.jetty.io.nio.SelectChannelEndPoint.handle(SelectChannelEndPoint.java:606) [org.eclipse.jetty.io_8.1.3.v20120522.jar:8.1.3.v20120522]
        at org.eclipse.jetty.io.nio.SelectChannelEndPoint$1.run(SelectChannelEndPoint.java:46) [org.eclipse.jetty.io_8.1.3.v20120522.jar:8.1.3.v20120522]
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:603) [org.eclipse.jetty.util_8.1.3.v20120522.jar:8.1.3.v20120522]
        at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:538) [org.eclipse.jetty.util_8.1.3.v20120522.jar:8.1.3.v20120522]
        at java.lang.Thread.run(Thread.java:745) [na:1.8.0_66]

This is very odd, as I have no trouble connection to MySQL from the command line (using the same credentials as OpenHAB).

How can I tell the MySQL persistence addon to stop complaining, and simply open a new connection when it detects that the last one it was using is no longer alive? Or better yet, how can I prevent it from dropping the connection in the 1st place?

I inspected the logs, but I didn’t find any clues as to what changed/what broke the connection with MySQL.

Moxified · February 6, 2016, 3:27am

I don’t know if you ever found a solution to this. I had a similar problem early on with the weather binding and MySQL. It would fail within minutes for me with the same duplicate key update error. Once it hits an error it seems to disconnect and not try again. There may be a way to force it to retry but the underlying issue still needs to be addressed.

In my case I deleted the item listed as having a duplicate index. In your case it looks like item2. Try dropping that table and removing the entry from the items table. Backup first of course

It should recreate the item with a different number in next change and move on, it did for me and I had no issues since.

Just a thought. Hope it helps.

derabbink · April 18, 2016, 12:55am

I tied tried, and my OH installation has been working fine since. thanks.

cmoore42 · April 22, 2016, 8:11pm

I think I’ve found the cause for this problem, and I have a fix - but I don’t have a working build environment and I’m not familiar with the process for submitting changes.

The isConnected() method checks for (connection != null && !connection.isValid(5000)). So if the server has timed out the connection then connection is going to be non-null (we never disconnected, so we never set it to null) but connection.isValid() is going to return true.

In this case we report “Connection is not valid!”, and the return connection != null. Well, connection isn’t null, so we return true (saying yes, we’re connected).

This patch should fix the problem, but I haven’t tested it:

index 87e36a4…8fa60ff 100644
— a/bundles/persistence/org.openhab.persistence.mysql/java/org/openhab/persistence/mysql/internal/MysqlPersistenceService.java
+++ b/bundles/persistence/org.openhab.persistence.mysql/java/org/openhab/persistence/mysql/internal/MysqlPersistenceService.java
@@ -463,9 +463,12 @@ public class MysqlPersistenceService implements QueryablePersistenceService {
* @return true if connection has been established, false otherwise
*/
private boolean isConnected() {

```
   boolean connected = true;
```

   // Check if connection is valid
   try {
       if (connection != null && !connection.isValid(5000)) {

           connected = false;
           errCnt++;
           logger.error("mySQL: Connection is not valid!");
       }

@@ -481,7 +484,7 @@ public class MysqlPersistenceService implements QueryablePersistenceService {
logger.error(“mySQL: Error count exceeded {}. Disconnecting database.”, errReconnectThreshold);
disconnectFromDatabase();
}

```
   return connection != null;
```

```
   return connected;
```
}

/**

lordsiris · June 15, 2016, 1:49pm

I’ve been having mysql persistence issues as well. Many the last couple days making openhab nearly unusable. Im running on Ubuntu 16.04 which is actually mariadb and wondering if that is causing some issues when using the mysql persistence directly. I just switched it over to jdbc with the mariadb driver and so far things look better. By that I mean i don’t just get errors that tables cant be queried and no new tables added (for new or newly responding devices after database table drop).

Chris

Toneus · June 15, 2016, 2:28pm

What are your connection timeout (waitTimeout) properties? Be aware that if you set too low, and the connection is not use, then it is deemed stale and will be closed on the MySQL side.

Note that the config details on the Wiki are in the OH1 format with the mysql: prefix, which is not used in OH2.

https://github.com/openhab/openhab/wiki/MySQL-Persistence

MySQL Wait Timeout Defined - The number of seconds the server waits for activity on a noninteractive connection before closing it.

Note that the default is 28800 seconds (8 hours), so if you have set it lower than this, it could be closing on you early. I made the initial mistake of setting it lower. On windows, you can go as high as 2147483 (nearly 25 days).

Good luck!

lordsiris · June 15, 2016, 4:35pm

So 10 seconds is probably a little too low… No idea when/why it got changed as I see the default is that setting commented out. May switch back but testing out using sqlite now as I’m guessing its a little faster, maybe.

Thanks for the info!!

Chris