Hi all,
after many days of investigation I need to post my persistence issues here - try to make it brief.
System Setup: Openhab2.1 on Ubuntu (installed via apt, stable version).
Running since some month logging a lot of data.
persistance service: Native MySQL binding (not via JDBC)
MySQL Server running on different VM in the local network.
Persistance Service was working as expected , also no issues with MySQL, beside one - which makes the system essentially unusable in daily operation:
- In unregular intervals MySQL queries seems to block all persistance actions in openhab
- It happens during access of pages (BasicUI) with charts querying a lot of history data.
- Then suddenly the chart is not displayed any more - only the rest of the page is displayed (e.g. other items like text or number items). Then no persistance actions are performed any more (no stores, no queries) by openhab - see logs.
events are still recieved by Openhab (checked with events.log) - but not processed by persistance any more. Finally also the UI is blocked and not responding any more. Then only openhab restart helped. - This issue happend depending on the usage of the sitemap - somtimes after minutes, sometimes after hours when accessing the sitemap e.g. first access in the morning -> then UI blocked.
This behaviour I could see over several weeks - however the exact event I could not determine.
It seems however my issue points to following issue: https://community.openhab.org/t/habpanel-gets-completely-broken-by-n3-line-chart-from-mysql-but-no-errors-in-log/34147/4
There is no error in OpenHAB logfile (even with DEBUG and TRACE) of everything:
small excerpt:
2017-11-29 18:05:07.690 [DEBUG] [ce.jetty.internal.HttpServiceContext] - Handling request for [/chart] using http context [DefaultHttpContext [bundle=org.eclipse.smarthome.ui_0.9.0.b5 [136], contextID=default]]
2017-11-29 18:05:07.690 [DEBUG] [y.internal.HttpServiceServletHandler] - handling request org.ops4j.pax.web.service.jetty.internal.HttpServiceRequestWrapper@66735611, org.ops4j.pax.web.service.jetty.internal.HttpServiceResponseWrapper@773c423e
2017-11-29 18:05:07.690 [DEBUG] [sql.internal.MysqlPersistenceService] - mySQL query: item is PelletOvenStatus
2017-11-29 18:05:07.691 [DEBUG] [sql.internal.MysqlPersistenceService] - mySQL: query:SELECT Time, Value FROM Item115 WHERE TIME<'2017-11-26 18:05:07' ORDER BY Time DESC LIMIT 0,1
2017-11-29 18:05:07.691 [DEBUG] [sql.internal.MysqlPersistenceService] - mySQL: query returned 1 rows in 0ms
2017-11-29 18:05:07.692 [DEBUG] [sql.internal.MysqlPersistenceService] - mySQL query: item is PelletOvenStatus
2017-11-29 18:05:07.692 [DEBUG] [sql.internal.MysqlPersistenceService] - mySQL: query:SELECT Time, Value FROM Item115 WHERE TIME>'2017-11-26 18:05:07' AND TIME<'2017-11-29 18:05:07' ORDER BY Time ASC
2017-11-29 18:05:07.693 [DEBUG] [sql.internal.MysqlPersistenceService] - mySQL: query returned 4 rows in 1ms
2017-11-29 18:05:07.694 [DEBUG] [sql.internal.MysqlPersistenceService] - mySQL query: item is Fuel_Pellet_kg
2017-11-29 18:05:07.694 [DEBUG] [sql.internal.MysqlPersistenceService] - mySQL: query:SELECT Time, Value FROM Item110 WHERE TIME<'2017-11-22 18:05:07' ORDER BY Time DESC LIMIT 0,1
2017-11-29 18:05:07.695 [DEBUG] [sql.internal.MysqlPersistenceService] - mySQL: query returned 1 rows in 1ms
2017-11-29 18:05:07.695 [DEBUG] [sql.internal.MysqlPersistenceService] - mySQL query: item is Fuel_Pellet_kg
2017-11-29 18:05:07.695 [DEBUG] [sql.internal.MysqlPersistenceService] - mySQL: query:SELECT Time, Value FROM Item110 WHERE TIME>'2017-11-22 18:05:07' AND TIME<'2017-11-29 18:05:07' ORDER BY Time ASC
2017-11-29 18:05:07.698 [TRACE] [commons.httpclient.methods.GetMethod] - enter GetMethod(String)
2017-11-29 18:05:07.698 [DEBUG] [.httpclient.params.DefaultHttpParams] - Set parameter http.socket.timeout = 5000
2017-11-29 18:05:07.698 [DEBUG] [.httpclient.params.DefaultHttpParams] - Set parameter http.method.retry-handler = org.apache.commons.httpclient.DefaultHttpMethodRetryHandler@17533b47
2017-11-29 18:05:07.699 [TRACE] [apache.commons.httpclient.HttpClient] - enter HttpClient.executeMethod(HttpMethod)
2017-11-29 18:05:07.699 [TRACE] [apache.commons.httpclient.HttpClient] - enter HttpClient.executeMethod(HostConfiguration,HttpMethod,HttpState)
2017-11-29 18:05:07.699 [TRACE] [ommons.httpclient.HttpMethodDirector] - Attempt number 1 to process request
2017-11-29 18:05:07.699 [TRACE] [he.commons.httpclient.HttpConnection] - enter HttpConnection.open()
2017-11-29 18:05:07.699 [DEBUG] [he.commons.httpclient.HttpConnection] - Open connection to raspiPellet1.home.lan:8020
2017-11-29 18:05:07.699 [DEBUG] [sql.internal.MysqlPersistenceService] - mySQL: query returned 562 rows in 4ms
2017-11-29 18:05:07.937 [TRACE] [he.commons.httpclient.HttpMethodBase] - enter HttpMethodBase.execute(HttpState, HttpConnection)
2017-11-29 18:05:07.937 [TRACE] [he.commons.httpclient.HttpMethodBase] - enter HttpMethodBase.writeRequest(HttpState, HttpConnection)
2017-11-29 18:05:07.937 [TRACE] [he.commons.httpclient.HttpMethodBase] - enter HttpMethodBase.writeRequestLine(HttpState, HttpConnection)
2017-11-29 18:05:07.937 [TRACE] [he.commons.httpclient.HttpMethodBase] - enter HttpMethodBase.generateRequestLine(HttpConnection, String, String, String, String)
2017-11-29 18:05:07.937 [DEBUG] [httpclient.wire.header ] - >> "GET /sensor/temperature/channel_1 HTTP/1.1[\r][\n]"
2017-11-29 18:05:07.937 [TRACE] [he.commons.httpclient.HttpConnection] - enter HttpConnection.print(String)
with corresponding mySQL log entries:
2017-11-29T18:05:07.691848+01:00 4 Query SELECT Time, Value FROM Item115 WHERE TIME<'2017-11-26 18:05:07' ORDER BY Time DESC LIMIT 0,1
2017-11-29T18:05:07.693174+01:00 4 Query SELECT Time, Value FROM Item115 WHERE TIME>'2017-11-26 18:05:07' AND TIME<'2017-11-29 18:05:07' ORDER BY Time ASC
2017-11-29T18:05:07.695356+01:00 4 Query SELECT Time, Value FROM Item110 WHERE TIME<'2017-11-22 18:05:07' ORDER BY Time DESC LIMIT 0,1
2017-11-29T18:05:07.696694+01:00 4 Query SELECT Time, Value FROM Item110 WHERE TIME>'2017-11-22 18:05:07' AND TIME<'2017-11-29 18:05:07' ORDER BY Time ASC
2017-11-29T18:05:25.463682+01:00 4 Query select @@session.tx_read_only
2017-11-29T18:05:25.465062+01:00 4 Query INSERT INTO Item108 (TIME, VALUE) VALUES('2017-11-29 18:05:25.462','137.60') ON DUPLICATE KEY UPDATE VALUE='137.60'
2017-11-29T18:05:25.522226+01:00 4 Query select @@session.tx_read_only
2017-11-29T18:05:25.522603+01:00 4 Query INSERT INTO Item140 (TIME, VALUE) VALUES('2017-11-29 18:05:25.521','20,1 % | 39,2 kg | Ofen=AUS') ON DUPLICATE KEY UPDATE VALUE='20,1 % | 39,2 kg | Ofen=AUS'
2017-11-29T18:05:25.545577+01:00 4 Query select @@session.tx_read_only
2017-11-29T18:05:25.545889+01:00 4 Query INSERT INTO Item109 (TIME, VALUE) VALUES('2017-11-29 18:05:25.544','20.09') ON DUPLICATE KEY UPDATE VALUE='20.09'
2017-11-29T18:05:25.572746+01:00 4 Query SELECT Time, Value FROM Item110 WHERE TIME<'2017-11-22 18:05:25' ORDER BY Time DESC LIMIT 0,1
2017-11-29T18:05:25.574043+01:00 4 Query SELECT Time, Value FROM Item110 WHERE TIME>'2017-11-22 18:05:25' AND TIME<'2017-11-29 18:05:25' ORDER BY Time ASC
2017-11-29T18:05:25.575333+01:00 4 Query SELECT Time, Value FROM Item110 WHERE TIME<'2017-11-28 18:05:25' ORDER BY Time DESC LIMIT 0,1
2017-11-29T18:05:25.576662+01:00 4 Query SELECT Time, Value FROM Item110 WHERE TIME>'2017-11-28 18:05:25' AND TIME<'2017-11-29 18:05:25' ORDER BY Time ASC
2017-11-29T18:05:25.577192+01:00 4 Query select @@session.tx_read_only
2017-11-29T18:05:25.577472+01:00 4 Query INSERT INTO Item110 (TIME, VALUE) VALUES('2017-11-29 18:05:25.575','39.18') ON DUPLICATE KEY UPDATE VALUE='39.18'
Then no entries any more in mysql.log ==> corresponding to openhab/persistance logging entries.
The entry "2017-11-29T18:05:25.577472+01:00 " is the last entry in the mySQL logfile - this is consistant with Openhab logfile where the last persitence entry is at “2017-11-29 18:05:07.695 [DEBUG] [sql.internal.MysqlPersistenceService] - mySQL: query:SELECT Time, Value FROM Item110 WHERE TIME>‘2017-11-22 18:05:07’ AND TIME<‘2017-11-29 18:05:07’ ORDER BY Time ASC”.
I could post the logfiles but they are quite big.
Mitigation:
In order to get rid of this issue I tried to switch to JDBC/mySQL connectivity - as suggested i the thread above - but the migration failed ==> this the next issue:
changed mysql.cfg to jdbc.cfg:
############################ jdbc Persistence Service ##################################
# the database url like 'jdbc:mysql://<host>:<port>/<database>'
#url=jdbc:mysql://homeserver2.home.lan:3306/OpenHAB
url=jdbc:mysql://homeserver2.home.lan:3306/OpenHABJDBC
# the database user
user=openhab
# the database password
password=*****
tableNamePrefix=Item
tableUseRealItemNames=false
tableIdDigitCount=0
errReconnectThreshold=10
# the reconnection counter
#reconnectCnt=5
# the connection timeout (in seconds)
#mysql:waitTimeout=28800
# optional tweaking of mysql datatypes
# example as described in https://github.com/openhab/openhab/issues/710
sqltype.string=VARCHAR(20000)
# Use MySQL Server time to store item values (=false) or use openHAB Server time (=true).
# For new installations, its recommend to set "mysql:localtime=true".
# (available since 1.9, optional, defaults to false)
#localtime=true
# enable logtime
enableLogTime=true
I also respected the mySQL to jdbc/mysql documentation in Openhab documentation (Items vs items, …)
Changed mysql.persist to jdbc.persist (Note that exactly the same .persist file was working with native mySQL persistance service without issue - so do not expect issue here)
// persistance strategy definition for homeserver2 mysql database
//
//
// following Strategies are defined:
// 1) Restore states on startup
Strategies {
everyMinute : "0 * * * * ?"
everyHour : "0 0 * * * ?"
everyDay : "0 0 0 * * ?"
// next line is not allowed - it must be a cron strategy, of "everyChange" should be used this must be used directly at the items
//EnergyTarifStrategy : everyChange
EnergyTarifStrategy : "0 */15 * * * ?"
// every 15 min
EnergyConsumptionStrategy : "0 */15 * * * ?"
//EnergyConsumptionStrategy : "0 */1 * * * ?"
// Pellet strategies
// <<<< TO BE DEFINED >>>>
// Weather strategies
// <<<< TO BE DEFINED >>>>
WeatherStrategy : "0 */15 * * * ?"
// Sprinkler strategies
//SprinklerStrategyParameters : everyChange
// default = everyUpdate
default = everyChange
}
// items lower case?
Items {
// persist all items on every change and restore them from the MapDB at startup
//* : strategy = everyChange, restoreOnStartup
gAlert* : strategy = everyChange, restoreOnStartup
// items for electrical Meter Energy
// using the group name gEnergy
gEnergy* : strategy = EnergyTarifStrategy, restoreOnStartup
gEnergyConsumption* : strategy = EnergyConsumptionStrategy, restoreOnStartup
// should be removed if the group definition is used.
//Tarif1_Energy_Plus : strategy = EnergyTarifStrategy, restoreOnStartup
//Tarif1_Energy_Minus : strategy = EnergyTarifStrategy, restoreOnStartup
//InstantVoltageL1 : strategy = EnergyTarifStrategy, restoreOnStartup
//InstantVoltageL2 : strategy = EnergyTarifStrategy, restoreOnStartup
//InstantVoltageL3 : strategy = EnergyTarifStrategy, restoreOnStartup
/* Testing of Yahoo Weather binding
Test_TemperatureMYSQL : strategy = everyMinute, restoreOnStartup
Test_HumidityMYSQL : strategy = everyMinute, restoreOnStartup
Test_PressureMYSQL : strategy = everyMinute, restoreOnStartup
*/
////////////////////////////////////////////////////////////////////
// Wheather items
////////////////////////////////////////////////////////////////////
gWetter* : strategy = WeatherStrategy, restoreOnStartup
gWheatherUnderground* : strategy = WeatherStrategy, restoreOnStartup
////////////////////////////////////////////////////////////////////
// Pellet items
////////////////////////////////////////////////////////////////////
// gPellet* : strategy = everyChange, everyUpdate, restoreOnStartup
gPellet* : strategy = everyChange, restoreOnStartup
///////////////////////////////////////
// Sprinkler items
///////////////////////////////////////
gWaterSource* : strategy = everyChange, restoreOnStartup
gWaterShaft* : strategy = everyChange, restoreOnStartup
gCistern* : strategy = everyChange, restoreOnStartup
SprTimeScalingFactor : strategy = everyChange, restoreOnStartup
SprGlobalState : strategy = everyChange, restoreOnStartup
SprStartingGroup_1_StartTime_Hour : strategy = everyChange, restoreOnStartup
SprStartingGroup_1_StartTime_Min : strategy = everyChange, restoreOnStartup
SprStartingGroup_2_StartTime_Hour : strategy = everyChange, restoreOnStartup
SprStartingGroup_2_StartTime_Min : strategy = everyChange, restoreOnStartup
SprStartingGroup_3_StartTime_Hour : strategy = everyChange, restoreOnStartup
SprStartingGroup_3_StartTime_Min : strategy = everyChange, restoreOnStartup
itemStartingGroup_1_TotalDurationTime : strategy = everyChange, restoreOnStartup
itemStartingGroup_2_TotalDurationTime : strategy = everyChange, restoreOnStartup
itemStartingGroup_3_TotalDurationTime : strategy = everyChange, restoreOnStartup
// Sprinkler groups
gCh* : strategy = everyChange, restoreOnStartup
}
After deinstalling mysql binding and installding jdbc/mysql binding the persistance was not working any more.
Excerpt of logfile:
2017-12-04 21:23:59.262 [DEBUG] [org.openhab.persistence.jdbc ] - BundleEvent STARTING - org.openhab.persistence.jdbc
2017-12-04 21:23:59.274 [DEBUG] [jdbc.internal.JdbcPersistenceService] - JDBC::setItemRegistry
2017-12-04 21:23:59.274 [DEBUG] [jdbc.internal.JdbcPersistenceService] - JDBC::activate: persistence service activated
2017-12-04 21:23:59.276 [DEBUG] [jdbc.internal.JdbcPersistenceService] - JDBC::updateConfig
2017-12-04 21:23:59.294 [DEBUG] [ence.jdbc.internal.JdbcConfiguration] - JDBC::JdbcConfiguration
2017-12-04 21:23:59.296 [DEBUG] [ence.jdbc.internal.JdbcConfiguration] - JDBC::updateConfig: configuration size = 16
2017-12-04 21:23:59.298 [DEBUG] [ence.jdbc.internal.JdbcConfiguration] - JDBC::updateConfig: user=openhab
2017-12-04 21:23:59.298 [DEBUG] [ence.jdbc.internal.JdbcConfiguration] - JDBC::updateConfig: password exists? true
2017-12-04 21:23:59.300 [DEBUG] [ence.jdbc.internal.JdbcConfiguration] - JDBC::updateConfig: url=jdbc:mysql://homeserver2.home.lan:3306/OpenHAB
2017-12-04 21:23:59.301 [DEBUG] [ence.jdbc.internal.JdbcConfiguration] - JDBC::updateConfig: found serviceName = 'mysql'
2017-12-04 21:23:59.301 [DEBUG] [ence.jdbc.internal.JdbcConfiguration] - JDBC::updateConfig: Init Data Access Object Class: 'org.openhab.persistence.jdbc.db.JdbcMysqlDAO'
2017-12-04 21:23:59.334 [DEBUG] [nhab.persistence.jdbc.db.JdbcBaseDAO] - JDBC::initSqlTypes: Initialize the type array
2017-12-04 21:23:59.341 [DEBUG] [nhab.persistence.jdbc.db.JdbcBaseDAO] - JDBC::initSqlQueries: 'JdbcMysqlDAO'
2017-12-04 21:23:59.342 [DEBUG] [hab.persistence.jdbc.db.JdbcMysqlDAO] - JDBC::initSqlTypes: Initialize the type array
2017-12-04 21:23:59.344 [DEBUG] [hab.persistence.jdbc.db.JdbcMysqlDAO] - JDBC::initSqlQueries: 'JdbcMysqlDAO'
2017-12-04 21:23:59.354 [DEBUG] [ence.jdbc.internal.JdbcConfiguration] - JDBC::updateConfig: dBDAO ClassName=org.openhab.persistence.jdbc.db.JdbcMysqlDAO
2017-12-04 21:23:59.359 [DEBUG] [ence.jdbc.internal.JdbcConfiguration] - JDBC::updateConfig: set sqlTypes: itemType=STRINGITEM value=VARCHAR(20000)
2017-12-04 21:23:59.361 [DEBUG] [ence.jdbc.internal.JdbcConfiguration] - JDBC::updateConfig: errReconnectThreshold=5
2017-12-04 21:23:59.374 [DEBUG] [ence.jdbc.internal.JdbcConfiguration] - JDBC::updateConfig: tableNamePrefix=Item
2017-12-04 21:23:59.376 [DEBUG] [ence.jdbc.internal.JdbcConfiguration] - JDBC::updateConfig: tableUseRealItemNames=false
2017-12-04 21:23:59.378 [DEBUG] [ence.jdbc.internal.JdbcConfiguration] - JDBC::updateConfig: tableIdDigitCount=0
2017-12-04 21:23:59.379 [DEBUG] [ence.jdbc.internal.JdbcConfiguration] - JDBC::updateConfig: enableLogTime true
2017-12-04 21:23:59.448 [DEBUG] [ence.jdbc.internal.JdbcConfiguration] - JDBC::updateConfig: load JDBC-driverClass was successful: 'com.mysql.jdbc.Driver'
2017-12-04 21:23:59.457 [DEBUG] [ence.jdbc.internal.JdbcConfiguration] - JDBC::updateConfig: configuration complete. service=jdbc
2017-12-04 21:23:59.458 [DEBUG] [persistence.jdbc.internal.JdbcMapper] - JDBC::pingDB
2017-12-04 21:23:59.458 [DEBUG] [persistence.jdbc.internal.JdbcMapper] - JDBC::openConnection isDriverAvailable: true
2017-12-04 21:23:59.459 [INFO ] [persistence.jdbc.internal.JdbcMapper] - JDBC::openConnection: Driver is available::Yank setupDataSource
2017-12-04 21:23:59.494 [INFO ] [com.zaxxer.hikari.HikariDataSource ] - yank-default - Started.
.......
2017-12-04 21:24:00.420 [INFO ] [org.knowm.yank.YankPoolManager ] - Initialized pool 'yank-default'
2017-12-04 21:24:00.421 [DEBUG] [ence.jdbc.internal.JdbcConfiguration] - JDBC::setDbConnected true
2017-12-04 21:24:00.421 [DEBUG] [hab.persistence.jdbc.db.JdbcMysqlDAO] - JDBC::initAfterFirstDbConnection: Initializing step, after db is connected.
2017-12-04 21:24:00.446 [DEBUG] [ab.persistence.jdbc.utils.DbMetaData] - dbMajorVersion = '5'
2017-12-04 21:24:00.446 [DEBUG] [ab.persistence.jdbc.utils.DbMetaData] - dbMinorVersion = '7'
2017-12-04 21:24:00.447 [DEBUG] [ab.persistence.jdbc.utils.DbMetaData] - driverMajorVersion = '5'
2017-12-04 21:24:00.447 [DEBUG] [ab.persistence.jdbc.utils.DbMetaData] - driverMinorVersion = '1'
2017-12-04 21:24:00.447 [DEBUG] [ab.persistence.jdbc.utils.DbMetaData] - dbProductName = 'MySQL'
2017-12-04 21:24:00.447 [DEBUG] [ab.persistence.jdbc.utils.DbMetaData] - dbProductVersion = '5.7.19-0ubuntu0.16.04.1-log'
2017-12-04 21:24:00.447 [DEBUG] [ence.jdbc.internal.JdbcConfiguration] - JDBC::updateConfig: set sqlTypes: itemType=STRINGITEM value=VARCHAR(20000)
2017-12-04 21:24:00.449 [DEBUG] [persistence.jdbc.internal.JdbcMapper] - JDBC::pingDB asking db for name as absolutely first db action, after connection is established.
2017-12-04 21:24:00.569 [INFO ] [persistence.jdbc.internal.JdbcMapper] - JDBC::logTime: 'pingDB':
afterAccess = 1111 ms
timeAverage50 = 1111 ms
timeAverage100 = 1111 ms
timeAverage200 = 1111 ms
afterAccessMin = 1111 ms
afterAccessMax = 1111 ms
1000Statements = 0 sec
statementCount = 1
2017-12-04 21:24:00.570 [DEBUG] [persistence.jdbc.internal.JdbcMapper] - JDBC::checkDBAcessability, first try connection: true
2017-12-04 21:24:00.570 [DEBUG] [jdbc.internal.JdbcPersistenceService] - JDBC::getName: returning name 'jdbc' for queryable persistence service.
2017-12-04 21:24:00.571 [DEBUG] [jdbc.internal.JdbcPersistenceService] - JDBC::updateConfig: configuration complete for service=jdbc.
2017-12-04 21:24:00.583 [DEBUG] [jdbc.internal.JdbcPersistenceService] - JDBC::getName: returning name 'jdbc' for queryable persistence service.
2017-12-04 21:24:00.589 [DEBUG] [jdbc.internal.JdbcPersistenceService] - JDBC::getName: returning name 'jdbc' for queryable persistence service.
2017-12-04 21:24:00.592 [DEBUG] [jdbc.internal.JdbcPersistenceService] - JDBC::getName: returning name 'jdbc' for queryable persistence service.
2017-12-04 21:24:00.592 [DEBUG] [jdbc.internal.JdbcPersistenceService] - JDBC::getName: returning name 'jdbc' for queryable persistence service.
2017-12-04 21:24:00.592 [DEBUG] [jdbc.internal.JdbcPersistenceService] - JDBC::getName: returning name 'jdbc' for queryable persistence service.
2017-12-04 21:24:00.600 [DEBUG] [persistence.jdbc.internal.JdbcMapper] - JDBC::pingDB
2017-12-04 21:24:00.600 [DEBUG] [persistence.jdbc.internal.JdbcMapper] - JDBC::openConnection isDriverAvailable: true
2017-12-04 21:24:00.604 [INFO ] [persistence.jdbc.internal.JdbcMapper] - JDBC::logTime: 'pingDB':
afterAccess = 4 ms
timeAverage50 = 557 ms
timeAverage100 = 557 ms
timeAverage200 = 557 ms
afterAccessMin = 4 ms
afterAccessMax = 1111 ms
1000Statements = 0 sec
statementCount = 2
2017-12-04 21:24:00.605 [DEBUG] [persistence.jdbc.internal.JdbcMapper] - JDBC::checkDBAcessability, first try connection: true
2017-12-04 21:24:00.605 [WARN ] [jdbc.internal.JdbcPersistenceService] - JDBC::query: database not connected, query aborted for item 'GlobalInfoString'
2017-12-04 21:24:00.607 [DEBUG] [persistence.jdbc.internal.JdbcMapper] - JDBC::pingDB
2017-12-04 21:24:00.607 [DEBUG] [persistence.jdbc.internal.JdbcMapper] - JDBC::openConnection isDriverAvailable: true
2017-12-04 21:24:00.611 [INFO ] [persistence.jdbc.internal.JdbcMapper] - JDBC::logTime: 'pingDB':
afterAccess = 4 ms
timeAverage50 = 373 ms
timeAverage100 = 373 ms
timeAverage200 = 373 ms
afterAccessMin = 4 ms
afterAccessMax = 1111 ms
1000Statements = 0 sec
statementCount = 3
2017-12-04 21:24:00.615 [DEBUG] [persistence.jdbc.internal.JdbcMapper] - JDBC::checkDBAcessability, first try connection: true
2017-12-04 21:24:00.619 [WARN ] [jdbc.internal.JdbcPersistenceService] - JDBC::query: database not connected, query aborted for item 'Tarif1_Energy_Minus'
2017-12-04 21:24:00.620 [DEBUG] [persistence.jdbc.internal.JdbcMapper] - JDBC::pingDB
2017-12-04 21:24:00.620 [DEBUG] [persistence.jdbc.internal.JdbcMapper] - JDBC::openConnection isDriverAvailable: true
2017-12-04 21:24:00.624 [INFO ] [persistence.jdbc.internal.JdbcMapper] - JDBC::logTime: 'pingDB':
afterAccess = 4 ms
timeAverage50 = 280 ms
timeAverage100 = 280 ms
timeAverage200 = 280 ms
afterAccessMin = 4 ms
afterAccessMax = 1111 ms
1000Statements = 0 sec
statementCount = 4
corresponding mySQL logfile:
2017-12-04T21:24:00.367236+01:00 1663 Connect openhab@10.0.1.59 on OpenHAB using TCP/IP
2017-12-04T21:24:00.375101+01:00 1663 Query /* mysql-connector-java-5.1.38 ( Revision: fe541c166cec739c74cc727c5da96c1028b4834a ) */SELECT @@session.auto_increment_increment AS auto_increment_increment, @@character_set_client AS character_set_client, @@character_set_connection AS character_set_connection, @@character_set_results AS character_set_results, @@character_set_server AS character_set_server, @@init_connect AS init_connect, @@interactive_timeout AS interactive_timeout, @@license AS license, @@lower_case_table_names AS lower_case_table_names, @@max_allowed_packet AS max_allowed_packet, @@net_buffer_length AS net_buffer_length, @@net_write_timeout AS net_write_timeout, @@query_cache_size AS query_cache_size, @@query_cache_type AS query_cache_type, @@sql_mode AS sql_mode, @@system_time_zone AS system_time_zone, @@time_zone AS time_zone, @@tx_isolation AS tx_isolation, @@wait_timeout AS wait_timeout
2017-12-04T21:24:00.407367+01:00 1663 Query SET NAMES latin1
2017-12-04T21:24:00.407930+01:00 1663 Query SET character_set_results = NULL
2017-12-04T21:24:00.408902+01:00 1663 Query SET autocommit=1
2017-12-04T21:24:00.410734+01:00 1663 Query set session transaction read write
2017-12-04T21:24:00.411056+01:00 1663 Query SET autocommit=1
2017-12-04T21:24:00.411878+01:00 1663 Query SELECT @@session.tx_isolation
2017-12-04T21:24:00.413030+01:00 1663 Quit
2017-12-04T21:24:00.427955+01:00 1664 Connect openhab@10.0.1.59 on OpenHAB using TCP/IP
2017-12-04T21:24:00.428443+01:00 1664 Query /* mysql-connector-java-5.1.38 ( Revision: fe541c166cec739c74cc727c5da96c1028b4834a ) */SELECT @@session.auto_increment_increment AS auto_increment_increment, @@character_set_client AS character_set_client, @@character_set_connection AS character_set_connection, @@character_set_results AS character_set_results, @@character_set_server AS character_set_server, @@init_connect AS init_connect, @@interactive_timeout AS interactive_timeout, @@license AS license, @@lower_case_table_names AS lower_case_table_names, @@max_allowed_packet AS max_allowed_packet, @@net_buffer_length AS net_buffer_length, @@net_write_timeout AS net_write_timeout, @@query_cache_size AS query_cache_size, @@query_cache_type AS query_cache_type, @@sql_mode AS sql_mode, @@system_time_zone AS system_time_zone, @@time_zone AS time_zone, @@tx_isolation AS tx_isolation, @@wait_timeout AS wait_timeout
2017-12-04T21:24:00.430414+01:00 1664 Query SET NAMES latin1
2017-12-04T21:24:00.430729+01:00 1664 Query SET character_set_results = NULL
2017-12-04T21:24:00.431042+01:00 1664 Query SET autocommit=1
2017-12-04T21:24:00.431369+01:00 1664 Query set session transaction read write
2017-12-04T21:24:00.431933+01:00 1664 Query SET autocommit=1
2017-12-04T21:24:00.469888+01:00 1665 Connect openhab@10.0.1.59 on OpenHAB using TCP/IP
2017-12-04T21:24:00.471825+01:00 1665 Query /* mysql-connector-java-5.1.38 ( Revision: fe541c166cec739c74cc727c5da96c1028b4834a ) */SELECT @@session.auto_increment_increment AS auto_increment_increment, @@character_set_client AS character_set_client, @@character_set_connection AS character_set_connection, @@character_set_results AS character_set_results, @@character_set_server AS character_set_server, @@init_connect AS init_connect, @@interactive_timeout AS interactive_timeout, @@license AS license, @@lower_case_table_names AS lower_case_table_names, @@max_allowed_packet AS max_allowed_packet, @@net_buffer_length AS net_buffer_length, @@net_write_timeout AS net_write_timeout, @@query_cache_size AS query_cache_size, @@query_cache_type AS query_cache_type, @@sql_mode AS sql_mode, @@system_time_zone AS system_time_zone, @@time_zone AS time_zone, @@tx_isolation AS tx_isolation, @@wait_timeout AS wait_timeout
2017-12-04T21:24:00.474943+01:00 1665 Query SET NAMES latin1
2017-12-04T21:24:00.477611+01:00 1665 Query SET character_set_results = NULL
2017-12-04T21:24:00.480441+01:00 1665 Query SET autocommit=1
2017-12-04T21:24:00.483073+01:00 1665 Query set session transaction read write
2017-12-04T21:24:00.484641+01:00 1665 Query SET autocommit=1
2017-12-04T21:24:00.520709+01:00 1666 Connect openhab@10.0.1.59 on OpenHAB using TCP/IP
2017-12-04T21:24:00.522873+01:00 1666 Query /* mysql-connector-java-5.1.38 ( Revision: fe541c166cec739c74cc727c5da96c1028b4834a ) */SELECT @@session.auto_increment_increment AS auto_increment_increment, @@character_set_client AS character_set_client, @@character_set_connection AS character_set_connection, @@character_set_results AS character_set_results, @@character_set_server AS character_set_server, @@init_connect AS init_connect, @@interactive_timeout AS interactive_timeout, @@license AS license, @@lower_case_table_names AS lower_case_table_names, @@max_allowed_packet AS max_allowed_packet, @@net_buffer_length AS net_buffer_length, @@net_write_timeout AS net_write_timeout, @@query_cache_size AS query_cache_size, @@query_cache_type AS query_cache_type, @@sql_mode AS sql_mode, @@system_time_zone AS system_time_zone, @@time_zone AS time_zone, @@tx_isolation AS tx_isolation, @@wait_timeout AS wait_timeout
2017-12-04T21:24:00.525601+01:00 1666 Query SET NAMES latin1
2017-12-04T21:24:00.528064+01:00 1666 Query SET character_set_results = NULL
2017-12-04T21:24:00.530399+01:00 1666 Query SET autocommit=1
2017-12-04T21:24:00.531839+01:00 1666 Query set session transaction read write
2017-12-04T21:24:00.537766+01:00 1666 Query SET autocommit=1
2017-12-04T21:24:00.542791+01:00 1665 Query SELECT DATABASE()
2017-12-04T21:24:00.596468+01:00 1665 Query SELECT 1
2017-12-04T21:24:00.603515+01:00 1665 Query SELECT 1
2017-12-04T21:24:00.616624+01:00 1665 Query SELECT 1
2017-12-04T21:24:00.623959+01:00 1665 Query SELECT 1
2017-12-04T21:24:00.632228+01:00 1665 Query SELECT 1
2017-12-04T21:24:00.637018+01:00 1665 Query SELECT 1
2017-12-04T21:24:00.693115+01:00 1665 Query SELECT 1
2017-12-04T21:24:00.703445+01:00 1665 Query SELECT 1
2017-12-04T21:24:00.709578+01:00 1665 Query SELECT 1
2017-12-04T21:24:00.734161+01:00 1665 Query SELECT 1
2017-12-04T21:24:00.740954+01:00 1665 Query SELECT 1
2017-12-04T21:24:00.764671+01:00 1665 Query SELECT 1
2017-12-04T21:24:00.769624+01:00 1665 Query SELECT 1
2017-12-04T21:24:00.775768+01:00 1665 Query SELECT 1
I also tried to drop the database completely that the tables are newly creaed - but also not successfull.
From the logfile entries in OpenHAB I tried to do some reverse engineering with the jdbc/openhab source code (in pseudo code below):
Class JdbcPersistanceService.java
execute class constructor
public void updateConfig(Map<Object, Object> configuration) {
logger.debug("JDBC::updateConfig");
conf = new JdbcConfiguration(configuration);
if (checkDBAccessability()) {
checkDBSchema();
// connection has been established ... initialization completed!
initialized = true;
} else {
initialized = false;
}
logger.debug("JDBC::updateConfig: configuration complete for service={}.", getName());
}
then execute
conf = new JdbcConfiguration(configuration);
public void setDbConnected(boolean dbConnected) {
logger.debug("JDBC::setDbConnected {}", dbConnected);
// Initializing step, after db is connected.
// Initialize sqlTypes, depending on DB version for example
dBDAO.initAfterFirstDbConnection();
// Running once again to prior external configured SqlTypes!
setSqlTypes();
this.dbConnected = dbConnected;
}
==> then exectute
dBDAO.initAfterFirstDbConnection();
public void initAfterFirstDbConnection() {
logger.debug("JDBC::initAfterFirstDbConnection: Initializing step, after db is connected.");
// Initialize sqlTypes, depending on DB version for example
dbMeta = new DbMetaData();// get DB information
}
==> then execute DbMetaData() ==> this is in import org.openhab.persistence.jdbc.utils.DbMetaData;
==> then execute (once again)
JdbcConfiguration::setSqlTypes();
==> then setDbConnected exit
==> then checkDBAccessability()
==> within: exec pingDB()
within PingdB:
check Dbname == null => "JDBC::pingDB asking db for name as absolutely first db action, after connection is established.")
set DBname
SELECT DATABASE() command is executed
>>>>>>>>>>Question: Is correct Database name given back???!!!!!!!!!!!!<<<<<<
==> then checkDBSchema();
==> within execture createItemsTableIfNot()
==> there is no DEBUG logfile entry any more (like >>>> logger.debug("JDBC::createItemsTableIfNot"); <<<<<)
It seems the database connectivity is always checked but not stored correctly or not percieved correctly from the DB.
Or either the DB-name is not received correctly or the tables could not be checked correctly (with checkDBSchema() frrom the existing DB.
Unfortunately there is no error seen. I do not know how to debug further… (hope the explanations above are somehow clear).
Any hint is appreciated.
Thanks a lot!