Final 1.0.0 errors and crash report....

Tag

I have tried your commands:

sudo systemctl restart mysgw.service
sudo systemctl stop mysgw.service
sudo systemctl start mysgw.service

This is my output:

root@orangepizero:/var/log# tail -f syslog
Oct 10 22:25:09 localhost systemd[1]: Started MySensors Gateway daemon.
Oct 10 22:25:09 localhost mysgw: Starting gateway...
Oct 10 22:25:09 localhost mysgw: Protocol version - 2.2.0-beta
Oct 10 22:25:39 localhost systemd[1]: Stopping MySensors Gateway daemon...
Oct 10 22:25:39 localhost mysgw: Received SIGTERM
Oct 10 22:25:39 localhost systemd[1]: Stopped MySensors Gateway daemon.
Oct 10 22:25:56 localhost systemd[1]: Starting MySensors Gateway daemon...
Oct 10 22:25:56 localhost systemd[1]: Started MySensors Gateway daemon.
Oct 10 22:25:56 localhost mysgw: Starting gateway...
Oct 10 22:25:56 localhost mysgw: Protocol version - 2.2.0-beta

Does this match your output?

looking at the /dev/ device directory, the device file /dev/ttyMySensorsGateway is gone once stopped. and recreated when the mysgw daemon started again...

(i also had to re-enable the GW in mycontroller...since it got disabled...)

Tag

@skywatch

the link seems okay. now i am wondering what is behind the link...

root@orangepizero:~/MySensors/bin# ls -l  /dev/ttyMySensorsGateway 
lrwxrwxrwx 1 root root 10 Oct 12 18:45 /dev/ttyMySensorsGateway -> /dev/pts/2
root@orangepizero:~/MySensors/bin# ll /dev/pts/2
crw--w---- 1 root tty 136, 2 Oct 12 18:46 /dev/pts/2

if you do an

ls -l /dev/pts/1

what does that look like?

did you use the correct flags to build mysgw? (as described here)

skywatch

@Tag
thanks for the support but the mystery is solved (at least this bit) - I rebooted the pi before giving the mysgw -d and of course mysgw was already started at boot and so was trying to start a second session and that is why the strange messages happened.

I have the system working again now and hope that it will stay that way for many weeks! ......

Tag

@skywatch said in Final 1.0.0 errors and crash report....:

but the mystery is solved (at least this

ah okay!! good!,
It will stay running

good luck!

skywatch

It didn't stay running - It crashed again.

Nothing in the myc log.
The MYSGW log shows data still being received from the sensor nodes.

Now I am stumped.....really stumped, as to how to get this sorted out......

Tag

@skywatch

Sad to hear.....

Have you tried setting up an arduino with an NRF21L01 attached to the arduino?,
Arduino can be connected to USB and the gateway can be pointed to i.e. /dev/ttyUSB0

skywatch

Sorry for the delay,

I am trying some other solution now and will report back if successful.

skywatch

I tried powering the rf module via the 5V pi rail via a 3.3V regulator just incase the 3.3v from the pi wasn't very clean. Still the same.......

So...... Today I have made a promini (3V, 8MHz) gateway adn connected to the pi via serial connecting.

I got Final-1.1.0-SNAPSHOT and installed that fresh and reconfigured it all from scratch. So far all sensors bar one have come up and behaving as they should. So now it is a waiting game (with a little investigation as to why one node is not showing - it seems to be registering as node0 when it should be node1 - I may reflash it and force the node id to see if that has an effect).

It will be annoying if it is a broken pi gw from mysensors, but not everything works as you expect it to I have discovered.

Cheers!

Tag

@skywatch

Okay great!,
About the node, it might be that it has a value in the eeprom where the node id is stored..
A sketch exists wich "clears" the eeprom (it is in the examples) , maybe upload that sketch, reset the promini and re-upload your original sketch (without the forced node id...)

see if that will fix the node id issue

skywatch

@Tag

Thanks!

Somehow it sorted itself out while I was tweaking my dashboards and now seems to working as expected (still some 'extra' sensors on that node showing in the topology page - but I can live with that).

So now onto some bootloader testing and low power stuff for battery sensors. Then onto signing and automation - you can bet I'll be back with more requests for help soon!

Tag

@skywatch

keep building!!
(maybe nice to explain a little on your setup in this topic, it may spark inspiration for the mycontroller/mysensors community ;))

skywatch

Now with external gateway, it crashed this morning....here is the myc log file.....

2017-10-31 13:52:13,051 INFO [main] [org.mycontroller.standalone.AppProperties:500] Created directory location: [/home/mycontroller/bin/tmp]
2017-10-31 13:52:13,069 INFO [main] [org.mycontroller.standalone.AppProperties:500] Created directory location: [/home/mycontroller/conf/resources/scripts]
2017-10-31 13:52:13,070 INFO [main] [org.mycontroller.standalone.AppProperties:500] Created directory location: [/home/mycontroller/conf/resources/scripts/conditions]
2017-10-31 13:52:13,072 INFO [main] [org.mycontroller.standalone.AppProperties:500] Created directory location: [/home/mycontroller/conf/resources/scripts/operations]
2017-10-31 13:52:13,076 INFO [main] [org.mycontroller.standalone.AppProperties:500] Created directory location: [/home/mycontroller/www/_configurations]
2017-10-31 13:52:13,078 INFO [main] [org.mycontroller.standalone.AppProperties:500] Created directory location: [/home/mycontroller/conf/persistent_stores]
2017-10-31 13:52:13,194 INFO [main] [org.mycontroller.standalone.db.DataBaseUtils:116] Checking migration...
2017-10-31 13:52:16,745 INFO [main] [org.mycontroller.standalone.db.migration.V1_01__Initial_Configuration:398] Migration completed successfully.
2017-10-31 13:52:17,012 INFO [main] [org.mycontroller.standalone.db.migration.V1_01_01__SNAPSHOT:63] Migration completed successfully.
2017-10-31 13:52:17,156 INFO [main] [org.mycontroller.standalone.db.migration.V1_01_02__SNAPSHOT:127] Migration completed successfully.
2017-10-31 13:52:17,281 INFO [main] [org.mycontroller.standalone.db.migration.V1_01_03__SNAPSHOT:48] Migration completed successfully.
2017-10-31 13:52:17,408 INFO [main] [org.mycontroller.standalone.db.migration.V1_01_04__SNAPSHOT:107] Migration completed successfully.
2017-10-31 13:52:17,503 INFO [main] [org.mycontroller.standalone.db.migration.V1_01_05__0_0_3_alpha1:49] Migration completed successfully.
2017-10-31 13:52:17,766 INFO [main] [org.mycontroller.standalone.db.migration.V1_02_04__2016_Apr_25:58] Migration completed successfully.
2017-10-31 13:52:17,780 INFO [main] [org.mycontroller.standalone.db.migration.V1_02_01__2016_Mar_24:340] Migration completed successfully.
2017-10-31 13:52:17,948 INFO [main] [org.mycontroller.standalone.db.migration.V1_02_02__2016_Apr_11:66] Migration completed successfully.
2017-10-31 13:52:22,128 INFO [main] [org.mycontroller.standalone.db.migration.V1_02_03__2016_Apr_14:85] Migration completed successfully.
2017-10-31 13:52:22,311 INFO [main] [org.mycontroller.standalone.db.migration.V1_02_04__2016_Apr_25:58] Migration completed successfully.
2017-10-31 13:52:22,358 INFO [main] [org.mycontroller.standalone.db.migration.V1_02_05__2016_Apr_27:68] Migration completed successfully.
2017-10-31 13:52:22,412 INFO [main] [org.mycontroller.standalone.db.migration.V1_02_06__2016_May_10:49] Migration completed successfully.
2017-10-31 13:52:22,461 INFO [main] [org.mycontroller.standalone.db.migration.V1_02_07__2016_May_19:57] Migration completed successfully.
2017-10-31 13:52:22,527 INFO [main] [org.mycontroller.standalone.db.migration.V1_02_08__2016_Jul_01:108] Migration completed successfully.
2017-10-31 13:52:22,578 INFO [main] [org.mycontroller.standalone.db.migration.V1_02_09__2016_Jul_16:93] Migration completed successfully.
2017-10-31 13:52:22,630 INFO [main] [org.mycontroller.standalone.db.migration.V1_02_10__2016_Jul_29:53] Migration completed successfully.
2017-10-31 13:52:22,698 INFO [main] [org.mycontroller.standalone.db.migration.V1_03_01__2016_Aug_03:66] Migration completed successfully.
2017-10-31 13:52:22,746 INFO [main] [org.mycontroller.standalone.db.migration.V1_03_02__2016_Aug_06:63] Migration completed successfully.
2017-10-31 13:52:22,789 INFO [main] [org.mycontroller.standalone.db.migration.V1_03_03__2016_Sep_20:95] Migration completed successfully.
2017-10-31 13:52:22,829 INFO [main] [org.mycontroller.standalone.db.migration.V1_03_04__2016_Oct_19:61] Migration completed successfully.
2017-10-31 13:52:22,875 INFO [main] [org.mycontroller.standalone.db.migration.V1_03_05__2016_Nov_18:77] Migration completed successfully.
2017-10-31 13:52:23,012 INFO [main] [org.mycontroller.standalone.db.migration.V1_03_06__2017_Mar_03:66] Migration completed successfully.
2017-10-31 13:52:23,142 INFO [main] [org.mycontroller.standalone.db.migration.V1_04_01__2017_Oct_25:56] Migration completed successfully.
2017-10-31 13:52:23,583 INFO [main] [org.mycontroller.standalone.db.DataBaseUtils:161] Number of migrations done:23
2017-10-31 13:52:23,587 INFO [main] [org.mycontroller.standalone.db.DataBaseUtils:167] Application information: [Version:1.1.0-SNAPSHOT, Database(type:H2 database embedded, version:1.4.194 (2017-03-10), schema version:1.04.01 - 2017 Oct 25), Built on:2017-10-27T14:48:26+0530, Git commit:ed159dab66c596b45631f8cf5dcfd3b2fccb8b53:development]
2017-10-31 13:52:23,892 INFO [main] [org.mycontroller.standalone.AppProperties:500] Created directory location: [/home/mycontroller/conf/persistent_stores/mc]
2017-10-31 13:52:24,590 INFO [Thread-9] [org.mycontroller.standalone.message.RawMessageQueue:54] Cleared offline messages[0] from the queue.
2017-10-31 13:52:25,440 INFO [main] [org.mycontroller.standalone.mqttbroker.MoquetteMqttBroker:52] MQTT Broker started successfully. MqttBrokerSettings(enabled=true, bindAddress=0.0.0.0, httpPort=1883, websocketPort=7080, allowAnonymous=false)
2017-10-31 13:52:28,082 INFO [main] [org.mycontroller.standalone.StartApp:214] TJWS server started successfully, HTTPS Enabled?:true, HTTP(S) Port: [8443]
2017-10-31 13:52:28,083 INFO [main] [org.mycontroller.standalone.StartApp:112] MyController.org server started in [15069] ms
[Tue Oct 31 13:52:56 GMT 2017] IO error: javax.net.ssl.SSLException: Connection has been shutdown: javax.net.ssl.SSLHandshakeException: Received fatal alert: unknown_ca in processing a request from /192.168.1.6:8443 / sun.security.ssl.SSLSocketImpl
2017-10-31 14:02:06,535 INFO [Acme.Utils.ThreadPool(2)-PooledThread: Acme.Serve.Serve$ServeConnection@1050dd3] [org.mycontroller.standalone.mqttbroker.MoquetteMqttBroker:78] MQTT broker restart triggered...
2017-10-31 14:02:06,772 INFO [Acme.Utils.ThreadPool(2)-PooledThread: Acme.Serve.Serve$ServeConnection@1050dd3] [org.mycontroller.standalone.mqttbroker.MoquetteMqttBroker:70] MQTT Broker has been stopped successfully
2017-10-31 14:02:06,861 INFO [Acme.Utils.ThreadPool(2)-PooledThread: Acme.Serve.Serve$ServeConnection@1050dd3] [org.mycontroller.standalone.mqttbroker.MoquetteMqttBroker:52] MQTT Broker started successfully. MqttBrokerSettings(enabled=true, bindAddress=0.0.0.0, httpPort=1883, websocketPort=7080, allowAnonymous=true)
2017-10-31 14:04:14,851 INFO [Acme.Utils.ThreadPool(3)-PooledThread: Acme.Serve.Serve$ServeConnection@1b0570b] [org.mycontroller.standalone.gateway.mqtt.MqttGatewayImpl:67] MQTT Gateway[name:Raspberry Pi, URI:tcp://localhost:1883, NetworkType:MyController] connected successfully..
[Tue Oct 31 14:56:45 GMT 2017] Accept: java.net.SocketException: Socket closed
2017-10-31 14:56:47,710 INFO [MyController.org Shutdown-Hook] [org.mycontroller.standalone.mqttbroker.MoquetteMqttBroker:70] MQTT Broker has been stopped successfully
2017-10-31 14:56:47,774 INFO [MyController.org Shutdown-Hook] [org.mycontroller.standalone.AppShutdownHook:36] Bye, Have a nice day! See you soon
2017-10-31 14:57:08,823 INFO [main] [org.mycontroller.standalone.db.DataBaseUtils:116] Checking migration...
2017-10-31 14:57:14,598 INFO [main] [org.mycontroller.standalone.db.DataBaseUtils:167] Application information: [Version:1.1.0-SNAPSHOT, Database(type:H2 database embedded, version:1.4.194 (2017-03-10), schema version:1.04.01 - 2017 Oct 25), Built on:2017-10-27T14:48:26+0530, Git commit:ed159dab66c596b45631f8cf5dcfd3b2fccb8b53:development]
2017-10-31 14:57:15,603 INFO [Thread-6] [org.mycontroller.standalone.message.RawMessageQueue:54] Cleared offline messages[0] from the queue.
2017-10-31 14:57:16,645 INFO [main] [org.mycontroller.standalone.mqttbroker.MoquetteMqttBroker:52] MQTT Broker started successfully. MqttBrokerSettings(enabled=true, bindAddress=0.0.0.0, httpPort=1883, websocketPort=7080, allowAnonymous=true)
2017-10-31 14:57:18,214 INFO [main] [org.mycontroller.standalone.gateway.mqtt.MqttGatewayImpl:67] MQTT Gateway[name:Raspberry Pi, URI:tcp://localhost:1883, NetworkType:MyController] connected successfully..
2017-10-31 14:57:22,058 INFO [main] [org.mycontroller.standalone.StartApp:214] TJWS server started successfully, HTTPS Enabled?:true, HTTP(S) Port: [8443]
2017-10-31 14:57:22,059 INFO [main] [org.mycontroller.standalone.StartApp:112] MyController.org server started in [13939] ms
[Tue Oct 31 14:59:26 GMT 2017] IO error: javax.net.ssl.SSLHandshakeException: Received fatal alert: unknown_ca in processing a request from /192.168.1.6:8443 / sun.security.ssl.SSLSocketImpl
[Tue Oct 31 20:34:57 GMT 2017] IO error: javax.net.ssl.SSLHandshakeException: Received fatal alert: unknown_ca in processing a request from /192.168.1.6:8443 / sun.security.ssl.SSLSocketImpl
[Tue Oct 31 21:13:12 GMT 2017] Accept: java.net.SocketException: Socket closed
2017-10-31 21:13:13,931 INFO [MyController.org Shutdown-Hook] [org.mycontroller.standalone.mqttbroker.MoquetteMqttBroker:70] MQTT Broker has been stopped successfully
2017-10-31 21:13:14,014 INFO [MyController.org Shutdown-Hook] [org.mycontroller.standalone.AppShutdownHook:36] Bye, Have a nice day! See you soon
2017-10-31 21:13:32,804 INFO [main] [org.mycontroller.standalone.db.DataBaseUtils:116] Checking migration...
2017-10-31 21:13:38,365 INFO [main] [org.mycontroller.standalone.db.DataBaseUtils:167] Application information: [Version:1.1.0-SNAPSHOT, Database(type:H2 database embedded, version:1.4.194 (2017-03-10), schema version:1.04.01 - 2017 Oct 25), Built on:2017-10-27T14:48:26+0530, Git commit:ed159dab66c596b45631f8cf5dcfd3b2fccb8b53:development]
2017-10-31 21:13:39,459 INFO [Thread-7] [org.mycontroller.standalone.message.RawMessageQueue:54] Cleared offline messages[0] from the queue.
2017-10-31 21:13:40,500 INFO [main] [org.mycontroller.standalone.mqttbroker.MoquetteMqttBroker:52] MQTT Broker started successfully. MqttBrokerSettings(enabled=true, bindAddress=0.0.0.0, httpPort=1883, websocketPort=7080, allowAnonymous=true)
2017-10-31 21:13:42,590 INFO [main] [org.mycontroller.standalone.gateway.mqtt.MqttGatewayImpl:67] MQTT Gateway[name:Raspberry Pi, URI:tcp://localhost:1883, NetworkType:MyController] connected successfully..
2017-10-31 21:13:46,173 INFO [main] [org.mycontroller.standalone.StartApp:214] TJWS server started successfully, HTTPS Enabled?:true, HTTP(S) Port: [8443]
2017-10-31 21:13:46,174 INFO [main] [org.mycontroller.standalone.StartApp:112] MyController.org server started in [13995] ms
[Wed Nov 01 08:56:11 GMT 2017] IO error: javax.net.ssl.SSLHandshakeException: Received fatal alert: unknown_ca in processing a request from /192.168.1.6:8443 / sun.security.ssl.SSLSocketImpl
2017-11-01 11:25:41,743 INFO [main] [org.mycontroller.standalone.db.DataBaseUtils:116] Checking migration...
2017-11-01 11:25:42,850 ERROR [main] [org.mycontroller.standalone.db.DataBaseUtils:119] Migration exception, 
org.flywaydb.core.internal.dbsupport.FlywaySqlException: 
Unable to obtain Jdbc connection from DataSource (jdbc:h2:file:../conf/mycontroller;MVCC=TRUE) for user 'mycontroller': IO Exception: null [90028-194]
------------------------------------------------------------------------------------------------------------------------------------------------------
SQL State  : 90028
Error Code : 90028
Message    : IO Exception: null [90028-194]

	at org.flywaydb.core.internal.util.jdbc.DriverDataSource.getConnectionFromDriver(DriverDataSource.java:401)
	at org.flywaydb.core.internal.util.jdbc.DriverDataSource.getConnection(DriverDataSource.java:363)
	at org.flywaydb.core.internal.util.jdbc.JdbcUtils.openConnection(JdbcUtils.java:51)
	at org.flywaydb.core.Flyway.execute(Flyway.java:1367)
	at org.flywaydb.core.Flyway.migrate(Flyway.java:930)
	at org.mycontroller.standalone.db.DataBaseUtils.runDatabaseMigration(DataBaseUtils.java:117)
	at org.mycontroller.standalone.StartApp.startServices(StartApp.java:254)
	at org.mycontroller.standalone.StartApp.startMycontroller(StartApp.java:111)
	at org.mycontroller.standalone.StartApp.main(StartApp.java:97)
Caused by: org.h2.jdbc.JdbcSQLException: IO Exception: null [90028-194]
	at org.h2.message.DbException.getJdbcSQLException(DbException.java:345)
	at org.h2.message.DbException.get(DbException.java:168)
	at org.h2.mvstore.db.MVTableEngine$Store.convertIllegalStateException(MVTableEngine.java:192)
	at org.h2.mvstore.db.MVTableEngine$Store.open(MVTableEngine.java:168)
	at org.h2.mvstore.db.MVTableEngine.init(MVTableEngine.java:100)
	at org.h2.engine.Database.getPageStore(Database.java:2474)
	at org.h2.engine.Database.open(Database.java:697)
	at org.h2.engine.Database.openDatabase(Database.java:276)
	at org.h2.engine.Database.<init>(Database.java:270)
	at org.h2.engine.Engine.openSession(Engine.java:64)
	at org.h2.engine.Engine.openSession(Engine.java:176)
	at org.h2.engine.Engine.createSessionAndValidate(Engine.java:154)
	at org.h2.engine.Engine.createSession(Engine.java:137)
	at org.h2.engine.Engine.createSession(Engine.java:27)
	at org.h2.engine.SessionRemote.connectEmbeddedOrServer(SessionRemote.java:354)
	at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:116)
	at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:100)
	at org.h2.Driver.connect(Driver.java:69)
	at org.flywaydb.core.internal.util.jdbc.DriverDataSource.getConnectionFromDriver(DriverDataSource.java:398)
	... 8 common frames omitted
Caused by: java.lang.IllegalStateException: Reading from nio:/home/mycontroller/conf/mycontroller.mv.db failed; file length 3260416 read length 768 at 3339921 [1.4.194/1]
	at org.h2.mvstore.DataUtils.newIllegalStateException(DataUtils.java:765)
	at org.h2.mvstore.DataUtils.readFully(DataUtils.java:435)
	at org.h2.mvstore.FileStore.readFully(FileStore.java:98)
	at org.h2.mvstore.Page.read(Page.java:190)
	at org.h2.mvstore.MVStore.readPage(MVStore.java:1952)
	at org.h2.mvstore.MVMap.readPage(MVMap.java:741)
	at org.h2.mvstore.Page.getChildPage(Page.java:217)
	at org.h2.mvstore.Cursor.fetchNext(Cursor.java:150)
	at org.h2.mvstore.Cursor.next(Cursor.java:50)
	at org.h2.mvstore.MVStore.loadChunkMeta(MVStore.java:695)
	at org.h2.mvstore.MVStore.readStoreHeader(MVStore.java:675)
	at org.h2.mvstore.MVStore.<init>(MVStore.java:358)
	at org.h2.mvstore.MVStore$Builder.open(MVStore.java:2930)
	at org.h2.mvstore.db.MVTableEngine$Store.open(MVTableEngine.java:155)
	... 23 common frames omitted
Caused by: java.io.EOFException: null
	at org.h2.mvstore.DataUtils.readFully(DataUtils.java:423)
	... 35 common frames omitted
2017-11-01 11:25:42,880 ERROR [main] [org.mycontroller.standalone.db.DataBaseUtils:132] Unable to close flyway connection
org.flywaydb.core.internal.dbsupport.FlywaySqlException: 
Unable to obtain Jdbc connection from DataSource (jdbc:h2:file:../conf/mycontroller;MVCC=TRUE) for user 'mycontroller': IO Exception: null [90028-194]
------------------------------------------------------------------------------------------------------------------------------------------------------
SQL State  : 90028
Error Code : 90028
Message    : IO Exception: null [90028-194]

	at org.flywaydb.core.internal.util.jdbc.DriverDataSource.getConnectionFromDriver(DriverDataSource.java:401)
	at org.flywaydb.core.internal.util.jdbc.DriverDataSource.getConnection(DriverDataSource.java:363)
	at org.mycontroller.standalone.db.DataBaseUtils.runDatabaseMigration(DataBaseUtils.java:127)
	at org.mycontroller.standalone.StartApp.startServices(StartApp.java:254)
	at org.mycontroller.standalone.StartApp.startMycontroller(StartApp.java:111)
	at org.mycontroller.standalone.StartApp.main(StartApp.java:97)
Caused by: org.h2.jdbc.JdbcSQLException: IO Exception: null [90028-194]
	at org.h2.message.DbException.getJdbcSQLException(DbException.java:345)
	at org.h2.message.DbException.get(DbException.java:168)
	at org.h2.mvstore.db.MVTableEngine$Store.convertIllegalStateException(MVTableEngine.java:192)
	at org.h2.mvstore.db.MVTableEngine$Store.open(MVTableEngine.java:168)
	at org.h2.mvstore.db.MVTableEngine.init(MVTableEngine.java:100)
	at org.h2.engine.Database.getPageStore(Database.java:2474)
	at org.h2.engine.Database.open(Database.java:697)
	at org.h2.engine.Database.openDatabase(Database.java:276)
	at org.h2.engine.Database.<init>(Database.java:270)
	at org.h2.engine.Engine.openSession(Engine.java:64)
	at org.h2.engine.Engine.openSession(Engine.java:176)
	at org.h2.engine.Engine.createSessionAndValidate(Engine.java:154)
	at org.h2.engine.Engine.createSession(Engine.java:137)
	at org.h2.engine.Engine.createSession(Engine.java:27)
	at org.h2.engine.SessionRemote.connectEmbeddedOrServer(SessionRemote.java:354)
	at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:116)
	at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:100)
	at org.h2.Driver.connect(Driver.java:69)
	at org.flywaydb.core.internal.util.jdbc.DriverDataSource.getConnectionFromDriver(DriverDataSource.java:398)
	... 5 common frames omitted
Caused by: java.lang.IllegalStateException: Reading from nio:/home/mycontroller/conf/mycontroller.mv.db failed; file length 3260416 read length 768 at 3339921 [1.4.194/1]
	at org.h2.mvstore.DataUtils.newIllegalStateException(DataUtils.java:765)
	at org.h2.mvstore.DataUtils.readFully(DataUtils.java:435)
	at org.h2.mvstore.FileStore.readFully(FileStore.java:98)
	at org.h2.mvstore.Page.read(Page.java:190)
	at org.h2.mvstore.MVStore.readPage(MVStore.java:1952)
	at org.h2.mvstore.MVMap.readPage(MVMap.java:741)
	at org.h2.mvstore.Page.getChildPage(Page.java:217)
	at org.h2.mvstore.Cursor.fetchNext(Cursor.java:150)
	at org.h2.mvstore.Cursor.next(Cursor.java:50)
	at org.h2.mvstore.MVStore.loadChunkMeta(MVStore.java:695)
	at org.h2.mvstore.MVStore.readStoreHeader(MVStore.java:675)
	at org.h2.mvstore.MVStore.<init>(MVStore.java:358)
	at org.h2.mvstore.MVStore$Builder.open(MVStore.java:2930)
	at org.h2.mvstore.db.MVTableEngine$Store.open(MVTableEngine.java:155)
	... 20 common frames omitted
Caused by: java.io.EOFException: null
	at org.h2.mvstore.DataUtils.readFully(DataUtils.java:423)
	... 32 common frames omitted
2017-11-01 11:25:43,542 ERROR [main] [org.mycontroller.standalone.db.DaoUtils:198] Unable to load Dao,
org.h2.jdbc.JdbcSQLException: IO Exception: null [90028-194]
	at org.h2.message.DbException.getJdbcSQLException(DbException.java:345)
	at org.h2.message.DbException.get(DbException.java:168)
	at org.h2.mvstore.db.MVTableEngine$Store.convertIllegalStateException(MVTableEngine.java:192)
	at org.h2.mvstore.db.MVTableEngine$Store.open(MVTableEngine.java:168)
	at org.h2.mvstore.db.MVTableEngine.init(MVTableEngine.java:100)
	at org.h2.engine.Database.getPageStore(Database.java:2474)
	at org.h2.engine.Database.open(Database.java:697)
	at org.h2.engine.Database.openDatabase(Database.java:276)
	at org.h2.engine.Database.<init>(Database.java:270)
	at org.h2.engine.Engine.openSession(Engine.java:64)
	at org.h2.engine.Engine.openSession(Engine.java:176)
	at org.h2.engine.Engine.createSessionAndValidate(Engine.java:154)
	at org.h2.engine.Engine.createSession(Engine.java:137)
	at org.h2.engine.Engine.createSession(Engine.java:27)
	at org.h2.engine.SessionRemote.connectEmbeddedOrServer(SessionRemote.java:354)
	at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:116)
	at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:100)
	at org.h2.Driver.connect(Driver.java:69)
	at java.sql.DriverManager.getConnection(DriverManager.java:664)
	at java.sql.DriverManager.getConnection(DriverManager.java:208)
	at com.j256.ormlite.jdbc.JdbcConnectionSource.makeConnection(JdbcConnectionSource.java:266)
	at com.j256.ormlite.jdbc.JdbcPooledConnectionSource.getReadWriteConnection(JdbcPooledConnectionSource.java:140)
	at com.j256.ormlite.table.TableUtils.doCreateTable(TableUtils.java:397)
	at com.j256.ormlite.table.TableUtils.doCreateTable(TableUtils.java:383)
	at com.j256.ormlite.table.TableUtils.createTableIfNotExists(TableUtils.java:75)
	at org.mycontroller.standalone.db.dao.BaseAbstractDaoImpl.<init>(BaseAbstractDaoImpl.java:65)
	at org.mycontroller.standalone.db.dao.ExternalServerDaoImpl.<init>(ExternalServerDaoImpl.java:38)
	at org.mycontroller.standalone.db.DaoUtils.loadAllDao(DaoUtils.java:157)
	at org.mycontroller.standalone.db.DataBaseUtils.runDatabaseMigration(DataBaseUtils.java:136)
	at org.mycontroller.standalone.StartApp.startServices(StartApp.java:254)
	at org.mycontroller.standalone.StartApp.startMycontroller(StartApp.java:111)
	at org.mycontroller.standalone.StartApp.main(StartApp.java:97)
Caused by: java.lang.IllegalStateException: Reading from nio:/home/mycontroller/conf/mycontroller.mv.db failed; file length 3260416 read length 768 at 3339921 [1.4.194/1]
	at org.h2.mvstore.DataUtils.newIllegalStateException(DataUtils.java:765)
	at org.h2.mvstore.DataUtils.readFully(DataUtils.java:435)
	at org.h2.mvstore.FileStore.readFully(FileStore.java:98)
	at org.h2.mvstore.Page.read(Page.java:190)
	at org.h2.mvstore.MVStore.readPage(MVStore.java:1952)
	at org.h2.mvstore.MVMap.readPage(MVMap.java:741)
	at org.h2.mvstore.Page.getChildPage(Page.java:217)
	at org.h2.mvstore.Cursor.fetchNext(Cursor.java:150)
	at org.h2.mvstore.Cursor.next(Cursor.java:50)
	at org.h2.mvstore.MVStore.loadChunkMeta(MVStore.java:695)
	at org.h2.mvstore.MVStore.readStoreHeader(MVStore.java:675)
	at org.h2.mvstore.MVStore.<init>(MVStore.java:358)
	at org.h2.mvstore.MVStore$Builder.open(MVStore.java:2930)
	at org.h2.mvstore.db.MVTableEngine$Store.open(MVTableEngine.java:155)
	... 28 common frames omitted
Caused by: java.io.EOFException: null
	at org.h2.mvstore.DataUtils.readFully(DataUtils.java:423)
	... 40 common frames omitted
2017-11-01 11:25:44,467 ERROR [main] [org.mycontroller.standalone.StartApp:99] Unable to start application, refer error log,
java.lang.NullPointerException: null
	at org.mycontroller.standalone.settings.SettingsUtils.getValue(SettingsUtils.java:57)
	at org.mycontroller.standalone.settings.SettingsUtils.getValue(SettingsUtils.java:62)
	at org.mycontroller.standalone.settings.LocationSettings.getValue(LocationSettings.java:72)
	at org.mycontroller.standalone.settings.LocationSettings.get(LocationSettings.java:57)
	at org.mycontroller.standalone.AppProperties.loadPropertiesFromDb(AppProperties.java:525)
	at org.mycontroller.standalone.db.DataBaseUtils.runDatabaseMigration(DataBaseUtils.java:141)
	at org.mycontroller.standalone.StartApp.startServices(StartApp.java:254)
	at org.mycontroller.standalone.StartApp.startMycontroller(StartApp.java:111)
	at org.mycontroller.standalone.StartApp.main(StartApp.java:97)
Exception in thread "MyController.org Shutdown-Hook" java.lang.NullPointerException
	at Acme.Serve.Serve.stopBackground(Serve.java:684)
	at org.jboss.resteasy.plugins.server.tjws.TJWSServletServer.stop(TJWSServletServer.java:184)
	at org.mycontroller.standalone.StartApp.stopHTTPWebServer(StartApp.java:225)
	at org.mycontroller.standalone.StartApp.stopServices(StartApp.java:309)
	at org.mycontroller.standalone.AppShutdownHook$1.run(AppShutdownHook.java:34)

Even after power off/power on cycle I get no web interface from myc.

Any ideas????

jkandasa

@skywatch Looks like your database corrupted. You may need to restore from your backup.

skywatch

I can't get a http connection so how to do this manually? The api only shows how to do it from the console and I cannot access that at all!

Thanks

jkandasa

@skywatch do a fresh installation. then restore from your backup

Tag

@skywatch

I looked at the data base backup, it seems to be one giant sql file....
(it is a zip in the backup zip file, you can extract it with the unzip command)

Still wondering why your database can get corrupted, it might be that if you restore your database, you restore the corruption also. Just for testing purpouses, you could start with a completely fresh install.

Are you 100% sure that the medium you use (sdcard/harddrive) is in good condition?
Which version of Java are you using? (I use the oracle one and that works fine)

skywatch

@jkandasa

Now I feel stupid!

@Tag

Media was new for this project and passed h2testw no issues (sandisk)...

Java is.....

 apt list --installed | grep java

WARNING: apt does not have a stable CLI interface yet. Use with caution in scripts.

java-common/oldstable,now 0.52 all [installed]
javascript-common/oldstable,now 11 all [installed,automatic]
libhsqldb1.8.0-java/oldstable,now 1.8.0.10+dfsg-3 all [installed,automatic]
libjavascriptcoregtk-3.0-0/stable,now 1:2.4.1-1rpi53rpi1g armhf [installed,automatic]
libreoffice-java-common/stable,now 1:4.3.3-2+rpi4 all [installed]
libservlet2.5-java/oldstable,now 6.0.45+dfsg-1~deb8u1 all [installed]
oracle-java8-jdk/stable,now 8u65 armhf [installed]

So looks OK to me.

Back running on backup image again and will see what happens. The 240v is from a filtered and spike protected distribution, nothing else power from this has any problem. Maybe I'll swap out the 5V 3A psu and see if that helps, but I don't think that is the issue here.

Tag

@skywatch

Dont feel stupid, not asking is stupid

So we assume the media is okay, good!!

Looking into java...seems your java is a bit older... 8u65, below is the version I use..

apt list --installed | grep java

WARNING: apt does not have a stable CLI interface yet. Use with caution in scripts.

java-common/oldstable,now 0.52 all [installed,automatic]
oracle-java8-installer/xenial,now 8u151-1~webupd8~0 all [installed]

Some time ago i created this topic about java on the RPI
It would be intersting to see how the issue evolves if you update to the latest java version...

skywatch

@Tag
Thanks for the response. Good idea, although I update/upgrade the pi often I guess if apt doesn't install it then it doesn't know to update it!
I have upgraded and now have....

 $ apt list --installed | grep java

WARNING: apt does not have a stable CLI interface yet. Use with caution in scripts.

java-common/oldstable,now 0.52 all [installed]
javascript-common/oldstable,now 11 all [installed,automatic]
libhsqldb1.8.0-java/oldstable,now 1.8.0.10+dfsg-3 all [installed,automatic]
libjavascriptcoregtk-3.0-0/stable,now 1:2.4.1-1rpi53rpi1g armhf [installed,automatic]
libreoffice-java-common/stable,now 1:4.3.3-2+rpi4 all [installed]
libservlet2.5-java/oldstable,now 6.0.45+dfsg-1~deb8u1 all [installed]
oracle-java8-jdk/stable,now 8u65 armhf [installed]

@jkandasa

May I suggest it would be a good idea to add to the documentation @tags java upgrade instructions with a reminder to check this manually at regular intervals? - It might help reduce the number of suport requests.

You guys are brilliant!

skywatch

Hmmmm.....Seems that after d/l and un-packing and installing the new '151' java I still show 8u65......

On config I get a choice as below....

There are 3 choices for the alternative javac (providing /usr/bin/javac).

  Selection    Path                                                Priority   Status
------------------------------------------------------------
  0            /usr/lib/jvm/jdk-8-oracle-arm32-vfp-hflt/bin/javac   318       auto mode
  1            /opt/jdk1.8.0_131/bin/javac                          1         manual mode
* 2            /opt/jdk1.8.0_151/bin/javac                          1         manual mode
  3            /usr/lib/jvm/jdk-8-oracle-arm32-vfp-hflt/bin/javac   318       manual mode

Press enter to keep the current choice[*], or type selection number:

I choose '2' and yet still don't see 151....any ideas?

Final 1.0.0 errors and crash report....

0

546

524

3.4k