search

openhab / openhab1-addons

Add-ons for openHAB 1.x
Eclipse Public License 2.0
3.43k stars 1.7k forks source link

Mysql exception during startup #5706

Closed mhilbush closed 5 years ago

mhilbush commented 5 years ago

Just installed build 1423 and I'm seeing a mysql exception during startup.

I'm on this version of mysql Server version: 5.7.23-0ubuntu0.16.04.1 (Ubuntu)

@martinvw Possibly related to this PR? https://github.com/openhab/openhab1-addons/pull/5699

2018-11-13 11:43:20.868 [ERROR] [sql.internal.MysqlPersistenceService] - mySQL: Failed connecting to the SQL database using: driverClass=com.mysql.jdbc.Driver, url=jdbc:mysql://localhost:3306/openhab, user=openhab
java.sql.SQLException: The server time zone value 'EDT' is unrecognized or represents more than one time zone. You must configure either the server or JDBC driver (via the serverTimezone configuration property) to use a more specifc time zone value if you want to utilize time zone support.
    at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:129) ~[238:org.openhab.persistence.mysql:1.13.0.201811130308]
    at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:97) ~[238:org.openhab.persistence.mysql:1.13.0.201811130308]
    at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:89) ~[238:org.openhab.persistence.mysql:1.13.0.201811130308]
    at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:63) ~[238:org.openhab.persistence.mysql:1.13.0.201811130308]
    at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:73) ~[238:org.openhab.persistence.mysql:1.13.0.201811130308]
    at com.mysql.cj.jdbc.exceptions.SQLExceptionsMapping.translateException(SQLExceptionsMapping.java:76) ~[238:org.openhab.persistence.mysql:1.13.0.201811130308]
    at com.mysql.cj.jdbc.ConnectionImpl.createNewIO(ConnectionImpl.java:835) ~[238:org.openhab.persistence.mysql:1.13.0.201811130308]
    at com.mysql.cj.jdbc.ConnectionImpl.<init>(ConnectionImpl.java:455) ~[238:org.openhab.persistence.mysql:1.13.0.201811130308]
    at com.mysql.cj.jdbc.ConnectionImpl.getInstance(ConnectionImpl.java:240) ~[238:org.openhab.persistence.mysql:1.13.0.201811130308]
    at com.mysql.cj.jdbc.NonRegisteringDriver.connect(NonRegisteringDriver.java:207) ~[238:org.openhab.persistence.mysql:1.13.0.201811130308]
    at java.sql.DriverManager.getConnection(DriverManager.java:664) ~[?:?]
    at java.sql.DriverManager.getConnection(DriverManager.java:247) ~[?:?]
    at org.openhab.persistence.mysql.internal.MysqlPersistenceService.connectToDatabase(MysqlPersistenceService.java:521) [238:org.openhab.persistence.mysql:1.13.0.201811130308]
    at org.openhab.persistence.mysql.internal.MysqlPersistenceService.activate(MysqlPersistenceService.java:191) [238:org.openhab.persistence.mysql:1.13.0.201811130308]
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
    at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
    at org.apache.felix.scr.impl.inject.methods.BaseMethod.invokeMethod(BaseMethod.java:228) [39:org.apache.felix.scr:2.1.2]
    at org.apache.felix.scr.impl.inject.methods.BaseMethod.access$500(BaseMethod.java:41) [39:org.apache.felix.scr:2.1.2]
    at org.apache.felix.scr.impl.inject.methods.BaseMethod$Resolved.invoke(BaseMethod.java:664) [39:org.apache.felix.scr:2.1.2]
    at org.apache.felix.scr.impl.inject.methods.BaseMethod.invoke(BaseMethod.java:510) [39:org.apache.felix.scr:2.1.2]
    at org.apache.felix.scr.impl.inject.methods.ActivateMethod.invoke(ActivateMethod.java:317) [39:org.apache.felix.scr:2.1.2]
    at org.apache.felix.scr.impl.inject.methods.ActivateMethod.invoke(ActivateMethod.java:307) [39:org.apache.felix.scr:2.1.2]
    at org.apache.felix.scr.impl.manager.SingleComponentManager.createImplementationObject(SingleComponentManager.java:334) [39:org.apache.felix.scr:2.1.2]
    at org.apache.felix.scr.impl.manager.SingleComponentManager.createComponent(SingleComponentManager.java:114) [39:org.apache.felix.scr:2.1.2]
    at org.apache.felix.scr.impl.manager.SingleComponentManager.getService(SingleComponentManager.java:947) [39:org.apache.felix.scr:2.1.2]
    at org.apache.felix.scr.impl.manager.SingleComponentManager.getServiceInternal(SingleComponentManager.java:919) [39:org.apache.felix.scr:2.1.2]
    at org.apache.felix.scr.impl.manager.SingleComponentManager.getService(SingleComponentManager.java:863) [39:org.apache.felix.scr:2.1.2]
    at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse$1.run(ServiceFactoryUse.java:212) [?:?]
    at java.security.AccessController.doPrivileged(Native Method) ~[?:?]
    at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.factoryGetService(ServiceFactoryUse.java:210) [?:?]
    at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.getService(ServiceFactoryUse.java:111) [?:?]
    at org.eclipse.osgi.internal.serviceregistry.ServiceConsumer$2.getService(ServiceConsumer.java:45) [?:?]
    at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.getService(ServiceRegistrationImpl.java:508) [?:?]
    at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.getService(ServiceRegistry.java:461) [?:?]
    at org.eclipse.osgi.internal.framework.BundleContextImpl.getService(BundleContextImpl.java:624) [?:?]
    at org.apache.felix.scr.impl.manager.SingleRefPair.getServiceObject(SingleRefPair.java:73) [39:org.apache.felix.scr:2.1.2]
    at org.apache.felix.scr.impl.inject.BindParameters.getServiceObject(BindParameters.java:47) [39:org.apache.felix.scr:2.1.2]
    at org.apache.felix.scr.impl.inject.methods.BindMethod.getServiceObject(BindMethod.java:662) [39:org.apache.felix.scr:2.1.2]
    at org.apache.felix.scr.impl.manager.DependencyManager.getServiceObject(DependencyManager.java:2304) [39:org.apache.felix.scr:2.1.2]
    at org.apache.felix.scr.impl.manager.DependencyManager.doInvokeBindMethod(DependencyManager.java:1801) [39:org.apache.felix.scr:2.1.2]
    at org.apache.felix.scr.impl.manager.DependencyManager.invokeBindMethod(DependencyManager.java:1784) [39:org.apache.felix.scr:2.1.2]
    at org.apache.felix.scr.impl.manager.SingleComponentManager.invokeBindMethod(SingleComponentManager.java:409) [39:org.apache.felix.scr:2.1.2]
    at org.apache.felix.scr.impl.manager.DependencyManager$MultipleDynamicCustomizer.addedService(DependencyManager.java:333) [39:org.apache.felix.scr:2.1.2]
    at org.apache.felix.scr.impl.manager.DependencyManager$MultipleDynamicCustomizer.addedService(DependencyManager.java:302) [39:org.apache.felix.scr:2.1.2]
    at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerAdded(ServiceTracker.java:1216) [39:org.apache.felix.scr:2.1.2]
    at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerAdded(ServiceTracker.java:1137) [39:org.apache.felix.scr:2.1.2]
    at org.apache.felix.scr.impl.manager.ServiceTracker$AbstractTracked.trackAdding(ServiceTracker.java:944) [39:org.apache.felix.scr:2.1.2]
    at org.apache.felix.scr.impl.manager.ServiceTracker$AbstractTracked.track(ServiceTracker.java:880) [39:org.apache.felix.scr:2.1.2]
    at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.serviceChanged(ServiceTracker.java:1168) [39:org.apache.felix.scr:2.1.2]
    at org.apache.felix.scr.impl.BundleComponentActivator$ListenerInfo.serviceChanged(BundleComponentActivator.java:125) [39:org.apache.felix.scr:2.1.2]
    at org.eclipse.osgi.internal.serviceregistry.FilteredServiceListener.serviceChanged(FilteredServiceListener.java:109) [?:?]
    at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:920) [?:?]
    at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230) [?:?]
    at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148) [?:?]
    at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEventPrivileged(ServiceRegistry.java:862) [?:?]
    at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEvent(ServiceRegistry.java:801) [?:?]
    at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.register(ServiceRegistrationImpl.java:127) [?:?]
    at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.registerService(ServiceRegistry.java:225) [?:?]
    at org.eclipse.osgi.internal.framework.BundleContextImpl.registerService(BundleContextImpl.java:469) [?:?]
    at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:891) [39:org.apache.felix.scr:2.1.2]
    at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:877) [39:org.apache.felix.scr:2.1.2]
    at org.apache.felix.scr.impl.manager.RegistrationManager.changeRegistration(RegistrationManager.java:128) [39:org.apache.felix.scr:2.1.2]
    at org.apache.felix.scr.impl.manager.AbstractComponentManager.registerService(AbstractComponentManager.java:944) [39:org.apache.felix.scr:2.1.2]
    at org.apache.felix.scr.impl.manager.AbstractComponentManager.activateInternal(AbstractComponentManager.java:727) [39:org.apache.felix.scr:2.1.2]
    at org.apache.felix.scr.impl.manager.AbstractComponentManager.enableInternal(AbstractComponentManager.java:661) [39:org.apache.felix.scr:2.1.2]
    at org.apache.felix.scr.impl.manager.AbstractComponentManager.enable(AbstractComponentManager.java:427) [39:org.apache.felix.scr:2.1.2]
    at org.apache.felix.scr.impl.manager.ConfigurableComponentHolder.enableComponents(ConfigurableComponentHolder.java:665) [39:org.apache.felix.scr:2.1.2]
    at org.apache.felix.scr.impl.BundleComponentActivator.initialEnable(BundleComponentActivator.java:339) [39:org.apache.felix.scr:2.1.2]
    at org.apache.felix.scr.impl.Activator.loadComponents(Activator.java:381) [39:org.apache.felix.scr:2.1.2]
    at org.apache.felix.scr.impl.Activator.access$200(Activator.java:49) [39:org.apache.felix.scr:2.1.2]
    at org.apache.felix.scr.impl.Activator$ScrExtension.start(Activator.java:263) [39:org.apache.felix.scr:2.1.2]
    at org.apache.felix.scr.impl.AbstractExtender.createExtension(AbstractExtender.java:196) [39:org.apache.felix.scr:2.1.2]
    at org.apache.felix.scr.impl.AbstractExtender.modifiedBundle(AbstractExtender.java:169) [39:org.apache.felix.scr:2.1.2]
    at org.apache.felix.scr.impl.AbstractExtender.modifiedBundle(AbstractExtender.java:49) [39:org.apache.felix.scr:2.1.2]
    at org.osgi.util.tracker.BundleTracker$Tracked.customizerModified(BundleTracker.java:482) [?:?]
    at org.osgi.util.tracker.BundleTracker$Tracked.customizerModified(BundleTracker.java:415) [?:?]
    at org.osgi.util.tracker.AbstractTracked.track(AbstractTracked.java:232) [?:?]
    at org.osgi.util.tracker.BundleTracker$Tracked.bundleChanged(BundleTracker.java:444) [?:?]
    at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:908) [?:?]
    at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230) [?:?]
    at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148) [?:?]
    at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEventPrivileged(EquinoxEventPublisher.java:213) [?:?]
    at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:120) [?:?]
    at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:112) [?:?]
    at org.eclipse.osgi.internal.framework.EquinoxContainerAdaptor.publishModuleEvent(EquinoxContainerAdaptor.java:168) [?:?]
    at org.eclipse.osgi.container.Module.publishEvent(Module.java:476) [?:?]
    at org.eclipse.osgi.container.Module.start(Module.java:467) [?:?]
    at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1634) [?:?]
    at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1614) [?:?]
    at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.doContainerStartLevel(ModuleContainer.java:1585) [?:?]
    at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1528) [?:?]
    at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1) [?:?]
    at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230) [?:?]
    at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(EventManager.java:340) [?:?]
Caused by: com.mysql.cj.exceptions.InvalidConnectionAttributeException: The server time zone value 'EDT' is unrecognized or represents more than one time zone. You must configure either the server or JDBC driver (via the serverTimezone configuration property) to use a more specifc time zone value if you want to utilize time zone support.
    at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) ~[?:?]
    at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62) ~[?:?]
    at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) ~[?:?]
    at java.lang.reflect.Constructor.newInstance(Constructor.java:423) ~[?:?]
    at com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:61) ~[?:?]
    at com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:85) ~[?:?]
    at com.mysql.cj.util.TimeUtil.getCanonicalTimezone(TimeUtil.java:132) ~[?:?]
    at com.mysql.cj.protocol.a.NativeProtocol.configureTimezone(NativeProtocol.java:2234) ~[?:?]
    at com.mysql.cj.protocol.a.NativeProtocol.initServerSession(NativeProtocol.java:2258) ~[?:?]
    at com.mysql.cj.jdbc.ConnectionImpl.initializePropsFromServer(ConnectionImpl.java:1319) ~[?:?]
    at com.mysql.cj.jdbc.ConnectionImpl.connectOneTryOnly(ConnectionImpl.java:966) ~[?:?]
    at com.mysql.cj.jdbc.ConnectionImpl.createNewIO(ConnectionImpl.java:825) ~[?:?]
    ... 89 more
mhilbush commented 5 years ago

I can make the exception go away if I change the database URL in mysql.cfg from this

url=jdbc:mysql://localhost:3306/openhab

to this

url=jdbc:mysql://localhost:3306/openhab?serverTimezone=EST (Eastern Standard Time)

The error returns if I set the URL to this

url=jdbc:mysql://localhost:3306/openhab?serverTimezone=EDT (Eastern Daylight Time)

Interestingly, it is no longer DST here in the US, so I'm not sure where the EDT is coming from when using the first URL above.

martinvw commented 5 years ago

👍 I will check what I can configure in java but this should help some people out. Can you check whether the MySQL config contains a reference to EDT?

mhilbush commented 5 years ago

It does not contain EDT.

# the database url like 'jdbc:mysql://<host>:<port>/<database>' (without quotes)                                                                   
url=jdbc:mysql://localhost:3306/openhab

# the database user
user=openhab

# the database password
password=XXXXXXX

# the reconnection counter
reconnectCnt=1

# the connection timeout (in seconds)
#waitTimeout=
martinvw commented 5 years ago

I meant the config of the MySQL server

mhilbush commented 5 years ago

Oops, sorry.

Nothing in any of the config files in /etc/mysql. Anywhere else I should look?

martinvw commented 5 years ago

Last option could be your OS?

mhilbush commented 5 years ago

/etc/timezone contains 

America/New_York
mhilbush commented 5 years ago

The box has been up for 52 days (DST ended a little over a week ago), so I'm going to reboot it.

Unfortunately, if the problem goes away, I may not be able to recreate it.

mhilbush commented 5 years ago

Sure enough, after a reboot the problem went away.

In hindsight, I should've restarted the mysql server to see if the problem would clear. ☹️

I have another system that's been up for 255 days. Let me see how that one's behaving...

mhilbush commented 5 years ago

I was able to recreate it on the system that was up for 255 days. A restart of the mysql server cleared the error.

So, it appears that the upgrade to the connector exposed an issue that can be cleared by restarting the mysql server.

I'm going to close this. We can reference this issue if anyone else stumbles across the problem.

mhilbush commented 5 years ago

FTR, I also have a system whose uptime was only 5 days (i.e. it was rebooted after the DST change). After installing build 1423, it did not exhibit the issue.

So I think that pretty much seals it.

martinvw commented 5 years ago

Thanks for looking into it and documenting your findings!

Could you write a suggestion for the README of the mysql bundle? It would maybe be a more sensible place to look then a closed issue. Thanks!

mhilbush commented 5 years ago

Sure. Were you thinking something like there being a possible need to restart the mysql server in the event of an error message in the log about an unrecognized server timezone value?

martinvw commented 5 years ago

Yes and maybe a reference to the serverTimezone parameter? Could be useful as well!

dogmaphobic commented 5 years ago

This is still there. 

==> openhab.log <==
2019-03-15 07:39:35.892 [ERROR] [sql.internal.MysqlPersistenceService] - mySQL: Failed connecting to the SQL database using: driverClass=com.mysql.jdbc.Driver, url=jdbc:mysql://127.0.0.1:3306/openHab, user=openHab
java.sql.SQLException: The server time zone value 'EDT' is unrecognized or represents more than one time zone. You must configure either the server or JDBC driver (via the serverTimezone configuration property) to use a more specifc time zone value if you want to utilize time zone support.

MySQL by default uses SYSTEM for time_zone , which means it gets it from the OS (Ubuntu 18.04).

This is fresh install on a new server.

$ openhab-cli info

Version:     2.5.0-SNAPSHOT (#1555)

User:        openhab (Environment Variable Set)
User Groups: openhab tty dialout audio bluetooth

Note that we are now back to EDT as of last Sunday (it was EST before):

$ timedatectl status | grep "Time zone"
                       Time zone: America/New_York (EDT, -0400)

Changing the configuration to

url=jdbc:mysql://127.0.0.1:3306/openHab?serverTimezone=EST (Eastern Standard Time)

as shown above gets a different error:

==> openhab.log <==
2019-03-15 07:53:40.011 [ERROR] [sql.internal.MysqlPersistenceService] - mySQL: Failed connecting to the SQL database using: driverClass=com.mysql.jdbc.Driver, url=jdbc:mysql://127.0.0.1:3306/openHab?serverTimezone=EST (Eastern Standard Time), user=openHab
java.sql.SQLException: No timezone mapping entry for 'EST (Eastern Standard Time)'

If I manually configure MySQL to use UTC instead, OpenHAB then connects fine;

SET time_zone = '+00:00';

That however, causes the time to be recorded in UTC even though the configuration says to use "local" time

# Use MySQL Server time to store item values (=false) or use openHAB Server time (=true).
# For new installations, its recommend to set "localtime=true".
# (optional, defaults to false)
localtime=true

(Item2 == Sun elevation)

$ date
Fri Mar 15 08:21:03 EDT 2019
mysql> SELECT * FROM `Item2` LIMIT=10;
+---------------------+-------------------+
| Time                | Value             |
+---------------------+-------------------+
| 2019-03-15 12:08:40 | 7.570988932723573 |
| 2019-03-15 12:09:03 | 7.570988932723573 |
| 2019-03-15 12:09:38 | 7.765190239551979 |
| 2019-03-15 12:10:02 | 7.765190239551979 |
| 2019-03-15 12:10:38 | 7.965844045811203 |
| 2019-03-15 12:11:01 | 7.965844045811203 |
| 2019-03-15 12:11:38 | 8.166377760499284 |
| 2019-03-15 12:12:02 | 8.166377760499284 |
| 2019-03-15 12:12:38 | 8.366830272647348 |
| 2019-03-15 12:13:01 | 8.366830272647348 |
+---------------------+-------------------+
10 rows in set (0.00 sec)

Post Edit

Only after all of the above did I notice this is the openhab1 repo. I'm using openhab2 as shown above. Sorry for the mess...

syphr42 commented 5 years ago

I ran into the same issue when the time changed this week. There clearly is a problem with the MySQL driver in OH 2.4 that causes an error when the timezone changes between standard and daylight saving time (or vice versa). Restarting my Docker Swarm services for MySQL and openHAB did not fix the problem.

For me (America/New_York system timezone), it looks like it's fixed by adding ?serverTimezone=EST5EDT to the end of the JDBC URL in services/mysql.cfg and leaving the MySQL server alone (which uses SYSTEM).