[JDBC] Player items are not persisted #5347

5iver · 2017-10-31T02:09:58Z

Current Behavior

Items of type PLAYER are not persisted and the following error occurs on startup:

2017-Oct-14 13:00:07.603 [WARN ] [b.persistence.jdbc.internal.JdbcPersistenceService] - JDBC::query: unable to find table for query, no data in database for item 'DS_FamilyRoom_Kodi_Control'. Current number of tables in the database: 1408
2017-Oct-14 13:00:07.605 [WARN ] [b.persistence.jdbc.internal.JdbcPersistenceService] - JDBC::query: no way to generate the table for item 'DS_FamilyRoom_Kodi_Control'

This behavior has been confirmed by others in the forum. The same occurs with a dummy PLAYER item, so this is not related to the Kodi 2.x binding.

Possible Solution

I expect JDBC SQL Persistence bundle has not been updated since PLAYER items were introduced. Although, it could be the MariaDB JDBC Client, as it has only been confirmed with MariaDB databases.

Steps to Reproduce (for bugs)

Setup JDBC persistence
Create a PLAYER item
Restart OH and monitor log for error above
Change PLAYER item states and observe not states are persisted

Context

I used persistence to pause and unpause Kodi during an audio alert. Once I upgraded to the Kodi 2.x binding, with a PLAYER item, I can no longer get the persisted data. I have modified my affected rules by simply setting a variable to hold the state of the Kodi player.

Your Environment

OH 2.2.0 snapshot build 1072 (and previous versions)
Fedora 25
MariaDB JDBC Client 1.3.5.0
openHAB JDBC SQL Persistence bundle 1.11.0.201710292249
mariadb-config-10.1.25-1.fc25.x86_64
mariadb-common-10.1.25-1.fc25.x86_64
mariadb-server-10.1.25-1.fc25.x86_64
mariadb-errmsg-10.1.25-1.fc25.x86_64
mariadb-libs-10.1.25-1.fc25.x86_64
mariadb-server-utils-10.1.25-1.fc25.x86_64
mariadb-java-client-1.4.6-1.fc25.noarch
mariadb-10.1.25-1.fc25.x86_64

The text was updated successfully, but these errors were encountered:

9037568 · 2017-10-31T02:25:35Z

Please provide a debug log and your configuration settings.

5iver · 2017-10-31T03:21:10Z

This is the log while JDBC is in DEBUG:

2017-10-24 03:31:40.792 [DEBUG] [b.persistence.jdbc.internal.JdbcPersistenceService] - JDBC::query: item is US_MasterBedroom_Kodi_Control
2017-10-24 03:31:40.793 [WARN ] [b.persistence.jdbc.internal.JdbcPersistenceService] - JDBC::query: unable to find table for query, no data in database for item 'US_MasterBedroom_Kodi_Control'. Current number of tables in the database: 1440
2017-10-24 03:31:40.794 [WARN ] [b.persistence.jdbc.internal.JdbcPersistenceService] - JDBC::query: no way to generate the table for item 'US_MasterBedroom_Kodi_Control'

Or are you asking for OH to be run with the debug script?

Here are the configurations:
jdbc.cfg.txt
jdbc.persist.txt

9037568 · 2017-10-31T03:49:55Z

Yes, that's what I was after. My guess is the problem occurs when the item is first created, though, which isn't captured here.

9037568 · 2017-10-31T04:01:09Z

If you list your items in the console, does this item show up?

The code I'm looking at would appear to indicate the item is not being found in the registry:

       if (table == null) {
            logger.warn(
                    "JDBC::query: unable to find table for query, no data in database for item '{}'. Current number of tables in the database: {}",
                    itemName, sqlTables.size());
            // if enabled, table will be created immediately
            if (item != null) {
                logger.warn("JDBC::query: try to generate the table for item '{}'", itemName);
                table = getTable(item);
            } else {
                logger.warn("JDBC::query: no way to generate the table for item '{}'", itemName);
                return Collections.emptyList();
            }
        }

5iver · 2017-10-31T04:20:57Z

If you list your items in the console, does this item show up?
Yes

DS_FamilyRoom_Kodi_Control (Type=PlayerItem, State=NULL, Label=Kodi (Family Room) Control, Category=none, Groups=[gKodiFamilyRoom])
US_MasterBedroom_Kodi_Control (Type=PlayerItem, State=NULL, Label=Kodi (Bedoom) Control, Category=none, Groups=[gKodiBedroom])
Virtual_Player_1 (Type=PlayerItem, State=NULL, Label=Virtual Player 1, Category=none, Groups=[gVirtual])
Virtual_Player_2 (Type=PlayerItem, State=PLAY, Label=Virtual Player 2, Category=null)

Here is a log with JDBC and rootLogger both in DEBUG while creating Virtual_Player_2 in PaperUI. I'll need to research more on what the debug script is turning on for logging if this is not enough detail.

2017-10-30 23:54:47.200 [DEBUG] [org.eclipse.jetty.server.HttpChannel              ] - REQUEST for //fedora01.rushworth.us:8080/rest/items/Virtual_Player_2 on HttpChannelOverHttp@63642d60{r=31,c=false,a=IDLE,uri=//fedora01.rushworth.us:8080/rest/items/Virtual_Player_2}
PUT //fedora01.rushworth.us:8080/rest/items/Virtual_Player_2 HTTP/1.1
Host: fedora01.rushworth.us:8080
Connection: keep-alive
Content-Length: 86
Accept: application/json, text/plain, */*
Origin: http://fedora01.rushworth.us:8080
Accept-Language: en
User-Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/61.0.3163.100 Safari/537.36
Content-Type: application/json;charset=UTF-8
DNT: 1
Referer: http://fedora01.rushworth.us:8080/paperui/index.html
Accept-Encoding: gzip, deflate


2017-10-30 23:54:47.201 [DEBUG] [org.eclipse.jetty.server.HttpConnection           ] - HttpConnection@5db723e1[SelectChannelEndPoint@29f8b823{/10.5.5.5:61414<->8080,Open,in,out,-,-,32/30000,HttpConnection@5db723e1}{io=0/0,kio=0,kro=1}][p=HttpParser{s=CONTENT,0 of 86},g=HttpGenerator@3162b1d4{s=START},c=HttpChannelOverHttp@63642d60{r=31,c=false,a=IDLE,uri=//fedora01.rushworth.us:8080/rest/items/Virtual_Player_2}] parsed true HttpParser{s=CONTENT,0 of 86}
2017-10-30 23:54:47.202 [DEBUG] [org.eclipse.jetty.server.HttpChannel              ] - HttpChannelOverHttp@63642d60{r=31,c=false,a=IDLE,uri=//fedora01.rushworth.us:8080/rest/items/Virtual_Player_2} handle //fedora01.rushworth.us:8080/rest/items/Virtual_Player_2 
2017-10-30 23:54:47.203 [DEBUG] [org.eclipse.jetty.server.HttpChannelState         ] - HttpChannelState@55a8595{s=IDLE a=NOT_ASYNC i=true r=!P!U w=false} handling IDLE
2017-10-30 23:54:47.204 [DEBUG] [org.eclipse.jetty.server.HttpChannel              ] - HttpChannelOverHttp@63642d60{r=31,c=false,a=DISPATCHED,uri=//fedora01.rushworth.us:8080/rest/items/Virtual_Player_2} action DISPATCH
2017-10-30 23:54:47.205 [DEBUG] [org.eclipse.jetty.server.Server                   ] - REQUEST PUT /rest/items/Virtual_Player_2 on HttpChannelOverHttp@63642d60{r=31,c=false,a=DISPATCHED,uri=//fedora01.rushworth.us:8080/rest/items/Virtual_Player_2}
2017-10-30 23:54:47.206 [DEBUG] [org.ops4j.pax.web.service.spi.model.ServerModel   ] - Matching [/rest/items/Virtual_Player_2]...
2017-10-30 23:54:47.207 [DEBUG] [org.ops4j.pax.web.service.spi.model.ServerModel   ] - Path [/rest/items/Virtual_Player_2] matched to {pattern=/rest/.*,model=ServletModel{id=org.ops4j.pax.web.service.spi.model.ServletModel-19,name=org.ops4j.pax.web.service.spi.model.ServletModel-19,urlPatterns=[/rest/*],alias=/rest,servlet=com.eclipsesource.jaxrs.publisher.internal.ServletContainerBridge@18ab1980,initParams={},context=ContextModel{id=org.ops4j.pax.web.service.spi.model.ContextModel-18,name=,httpContext=DefaultHttpContext [bundle=com.eclipsesource.jaxrs.publisher_5.3.1.201602281253 [17], contextID=default],contextParams={},virtualHosts={},connectors={}}}}
2017-10-30 23:54:47.208 [DEBUG] [org.eclipse.jetty.server.handler.ContextHandler   ] - scope null||/rest/items/Virtual_Player_2 @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=com.eclipsesource.jaxrs.publisher_5.3.1.201602281253 [17], contextID=default]}
2017-10-30 23:54:47.210 [DEBUG] [org.eclipse.jetty.server.handler.ContextHandler   ] - context=||/rest/items/Virtual_Player_2 @ HttpServiceContext{httpContext=DefaultHttpContext [bundle=com.eclipsesource.jaxrs.publisher_5.3.1.201602281253 [17], contextID=default]}
2017-10-30 23:54:47.211 [DEBUG] [org.eclipse.jetty.server.session                  ] - sessionManager=org.ops4j.pax.web.service.jetty.internal.LateInvalidatingHashSessionManager@2ca46fd5
2017-10-30 23:54:47.212 [DEBUG] [org.eclipse.jetty.server.session                  ] - session=null
2017-10-30 23:54:47.213 [DEBUG] [org.eclipse.jetty.servlet.ServletHandler          ] - servlet |/rest|/items/Virtual_Player_2 -> org.ops4j.pax.web.service.spi.model.ServletModel-19@b9f03e60==com.eclipsesource.jaxrs.publisher.internal.ServletContainerBridge,-1,true
2017-10-30 23:54:47.214 [DEBUG] [.pax.web.service.jetty.internal.HttpServiceContext] - Handling request for [/rest/items/Virtual_Player_2] using http context [DefaultHttpContext [bundle=com.eclipsesource.jaxrs.publisher_5.3.1.201602281253 [17], contextID=default]]
2017-10-30 23:54:47.215 [DEBUG] [b.service.jetty.internal.HttpServiceServletHandler] - handling request org.ops4j.pax.web.service.jetty.internal.HttpServiceRequestWrapper@3f64e8f6, org.ops4j.pax.web.service.jetty.internal.HttpServiceResponseWrapper@1bb0e08c
2017-10-30 23:54:47.216 [DEBUG] [org.eclipse.jetty.servlet.ServletHandler          ] - chain=null
2017-10-30 23:54:47.219 [DEBUG] [org.eclipse.jetty.server.HttpConnection           ] - HttpConnection@5db723e1[SelectChannelEndPoint@29f8b823{/10.5.5.5:61414<->8080,Open,in,out,-,-,50/30000,HttpConnection@5db723e1}{io=0/0,kio=0,kro=1}][p=HttpParser{s=CONTENT,0 of 86},g=HttpGenerator@3162b1d4{s=START},c=HttpChannelOverHttp@63642d60{r=31,c=false,a=DISPATCHED,uri=//fedora01.rushworth.us:8080/rest/items/Virtual_Player_2}] parse HeapByteBuffer@2b0c2247[p=508,l=594,c=8192,r=86]={PUT /rest/items/V...ip, deflate\r\n\r\n<<<{"groupNames":[],...tual Player 2"}>>>": {}\\n    }\\n}"}...style=\\\\\\"backg} {}
2017-10-30 23:54:47.221 [DEBUG] [org.eclipse.jetty.http.HttpParser                 ] - parseNext s=CONTENT HeapByteBuffer@2b0c2247[p=508,l=594,c=8192,r=86]={PUT /rest/items/V...ip, deflate\r\n\r\n<<<{"groupNames":[],...tual Player 2"}>>>": {}\\n    }\\n}"}...style=\\\\\\"backg}
2017-10-30 23:54:47.223 [DEBUG] [org.eclipse.jetty.server.HttpChannel              ] - HttpChannelOverHttp@63642d60{r=31,c=false,a=DISPATCHED,uri=//fedora01.rushworth.us:8080/rest/items/Virtual_Player_2} content Content@3800d889{HeapByteBufferR@20bba427[p=508,l=594,c=8192,r=86]={PUT /rest/items/V...ip, deflate\r\n\r\n<<<{"groupNames":[],...tual Player 2"}>>>": {}\\n    }\\n}"}...style=\\\\\\"backg}}
2017-10-30 23:54:47.225 [DEBUG] [org.eclipse.jetty.server.HttpInput                ] - HttpInputOverHTTP@3e69c27f[c=0,q=1,[0]=Content@3800d889{HeapByteBufferR@20bba427[p=508,l=594,c=8192,r=86]={PUT /rest/items/V...ip, deflate\r\n\r\n<<<{"groupNames":[],...tual Player 2"}>>>": {}\\n    }\\n}"}...style=\\\\\\"backg}},s=STREAM] addContent Content@3800d889{HeapByteBufferR@20bba427[p=508,l=594,c=8192,r=86]={PUT /rest/items/V...ip, deflate\r\n\r\n<<<{"groupNames":[],...tual Player 2"}>>>": {}\\n    }\\n}"}...style=\\\\\\"backg}}
2017-10-30 23:54:47.226 [DEBUG] [org.eclipse.jetty.http.HttpParser                 ] - CONTENT --> END
2017-10-30 23:54:47.227 [DEBUG] [org.eclipse.jetty.server.HttpChannel              ] - HttpChannelOverHttp@63642d60{r=31,c=false,a=DISPATCHED,uri=//fedora01.rushworth.us:8080/rest/items/Virtual_Player_2} onRequestComplete
2017-10-30 23:54:47.228 [DEBUG] [org.eclipse.jetty.server.HttpInput                ] - HttpInputOverHTTP@3e69c27f[c=0,q=2,[0]=Content@3800d889{HeapByteBufferR@20bba427[p=508,l=594,c=8192,r=86]={PUT /rest/items/V...ip, deflate\r\n\r\n<<<{"groupNames":[],...tual Player 2"}>>>": {}\\n    }\\n}"}...style=\\\\\\"backg}},s=STREAM] addContent EOF
2017-10-30 23:54:47.229 [DEBUG] [org.eclipse.jetty.server.HttpConnection           ] - HttpConnection@5db723e1[SelectChannelEndPoint@29f8b823{/10.5.5.5:61414<->8080,Open,in,out,-,-,60/30000,HttpConnection@5db723e1}{io=0/0,kio=0,kro=1}][p=HttpParser{s=END,86 of 86},g=HttpGenerator@3162b1d4{s=START},c=HttpChannelOverHttp@63642d60{r=31,c=false,a=DISPATCHED,uri=//fedora01.rushworth.us:8080/rest/items/Virtual_Player_2}] parsed false HttpParser{s=END,86 of 86}
2017-10-30 23:54:47.230 [DEBUG] [org.eclipse.jetty.server.HttpInput                ] - HttpInputOverHTTP@3e69c27f[c=86,q=2,[0]=Content@3800d889{HeapByteBufferR@20bba427[p=594,l=594,c=8192,r=0]={PUT /rest/items/V...tual Player 2"}<<<>>>": {}\\n    }\\n}"}...style=\\\\\\"backg}},s=STREAM] read 86 from Content@3800d889{HeapByteBufferR@20bba427[p=594,l=594,c=8192,r=0]={PUT /rest/items/V...tual Player 2"}<<<>>>": {}\\n    }\\n}"}...style=\\\\\\"backg}}
2017-10-30 23:54:47.231 [DEBUG] [org.eclipse.jetty.server.HttpConnection           ] - releaseRequestBuffer HttpConnection@5db723e1[SelectChannelEndPoint@29f8b823{/10.5.5.5:61414<->8080,Open,in,out,-,-,62/30000,HttpConnection@5db723e1}{io=0/0,kio=0,kro=1}][p=HttpParser{s=END,86 of 86},g=HttpGenerator@3162b1d4{s=START},c=HttpChannelOverHttp@63642d60{r=31,c=false,a=DISPATCHED,uri=//fedora01.rushworth.us:8080/rest/items/Virtual_Player_2}]
2017-10-30 23:54:47.232 [DEBUG] [org.eclipse.jetty.server.HttpInput                ] - HttpInputOverHTTP@3e69c27f[c=86,q=1,[0]=EOF,s=STREAM] consumed Content@3800d889{HeapByteBufferR@20bba427[p=594,l=594,c=8192,r=0]={PUT /rest/items/V...tual Player 2"}<<<>>>": {}\\n    }\\n}"}...style=\\\\\\"backg}}
2017-10-30 23:54:47.233 [DEBUG] [org.eclipse.jetty.server.HttpInput                ] - HttpInputOverHTTP@3e69c27f[c=86,q=0,[0]=null,s=STREAM] consumed EOF
2017-10-30 23:54:47.238 [DEBUG] [.jersey.message.internal.ReaderInterceptorExecutor] - Message body reader (class org.eclipse.smarthome.io.rest.core.internal.GsonProvider) is trying to close the entity input stream. Not closing.
2017-10-30 23:54:47.243 [WARN ] [b.persistence.jdbc.internal.JdbcPersistenceService] - JDBC::query: unable to find table for query, no data in database for item 'Virtual_Player_2'. Current number of tables in the database: 1467
2017-10-30 23:54:47.244 [WARN ] [b.persistence.jdbc.internal.JdbcPersistenceService] - JDBC::query: no way to generate the table for item 'Virtual_Player_2'
2017-10-30 23:54:47.253 [DEBUG] [org.eclipse.jetty.server.HttpChannel              ] - sendResponse info=null content=DirectByteBuffer@43698d99[p=0,l=222,c=32768,r=222]={<<<event: message\nda...mAddedEvent"}\n\n>>>}\n\ntype":"GroupIt..."category":"tem} complete=false committing=false callback=Blocker@20da89fe{null}
2017-10-30 23:54:47.254 [DEBUG] [org.eclipse.jetty.server.HttpConnection           ] - org.eclipse.jetty.server.HttpConnection$SendCallback@39be3b3c[PROCESSING][i=null,cb=Blocker@20da89fe{null}] generate: FLUSH (null,[p=0,l=222,c=32768,r=222],false)@COMMITTED
2017-10-30 23:54:47.262 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint              ] - flushed 228 SelectChannelEndPoint@91391af{/10.5.5.5:56237<->8080,Open,in,out,-,W,787/30000,HttpConnection@3701fa13}{io=0/0,kio=0,kro=1}
2017-10-30 23:54:47.262 [DEBUG] [org.eclipse.jetty.io.WriteFlusher                 ] - Flushed=true 6/6+1 WriteFlusher@388bbc2f{WRITING}
2017-10-30 23:54:47.262 [DEBUG] [org.eclipse.jetty.server.HttpChannel              ] - sendResponse info=null content=HeapByteBuffer@2b51baac[p=0,l=182,c=8192,r=182]={<<<{"link":"http://f...groupNames":[]}>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00} complete=true committing=true callback=Blocker@1de26ed4{null}
2017-10-30 23:54:47.263 [DEBUG] [org.eclipse.jetty.server.HttpConnection           ] - org.eclipse.jetty.server.HttpConnection$SendCallback@39be3b3c[PROCESSING][i=null,cb=Blocker@20da89fe{null}] generate: DONE (null,[p=222,l=222,c=32768,r=0],false)@COMMITTED
2017-10-30 23:54:47.264 [DEBUG] [org.eclipse.jetty.server.HttpChannel              ] - COMMIT for /rest/items/Virtual_Player_2 on HttpChannelOverHttp@63642d60{r=31,c=true,a=DISPATCHED,uri=//fedora01.rushworth.us:8080/rest/items/Virtual_Player_2}
201 Created HTTP/1.1
Content-Length: 182
Content-Type: application/json


2017-10-30 23:54:47.264 [DEBUG] [org.eclipse.jetty.server.HttpChannel              ] - sendResponse info=null content=DirectByteBuffer@2d3c0a3c[p=0,l=222,c=32768,r=222]={<<<event: message\nda...mAddedEvent"}\n\n>>>}\n\ntype":"GroupIt...,"state":"NULL"} complete=false committing=false callback=Blocker@618a2bd9{null}
2017-10-30 23:54:47.264 [DEBUG] [org.eclipse.jetty.server.HttpConnection           ] - org.eclipse.jetty.server.HttpConnection$SendCallback@3fba9f5b[PROCESSING][i=null,cb=Blocker@618a2bd9{null}] generate: FLUSH (null,[p=0,l=222,c=32768,r=222],false)@COMMITTED
2017-10-30 23:54:47.264 [DEBUG] [org.eclipse.jetty.server.HttpConnection           ] - org.eclipse.jetty.server.HttpConnection$SendCallback@5e9a519[PROCESSING][i=HTTP/1.1{s=201,h=2},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@15abfbdf] generate: NEED_HEADER (null,[p=0,l=182,c=8192,r=182],true)@START
2017-10-30 23:54:47.266 [DEBUG] [org.eclipse.jetty.server.HttpConnection           ] - org.eclipse.jetty.server.HttpConnection$SendCallback@5e9a519[PROCESSING][i=HTTP/1.1{s=201,h=2},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@15abfbdf] generate: FLUSH ([p=0,l=110,c=8192,r=110],[p=0,l=182,c=8192,r=182],true)@COMPLETING
2017-10-30 23:54:47.266 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint              ] - flushed 228 SelectChannelEndPoint@54ea2fd4{/10.5.5.5:61412<->8080,Open,in,out,-,W,789/30000,HttpConnection@61fe2a25}{io=0/0,kio=0,kro=1}
2017-10-30 23:54:47.267 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint              ] - flushed 292 SelectChannelEndPoint@29f8b823{/10.5.5.5:61414<->8080,Open,in,out,-,W,98/30000,HttpConnection@5db723e1}{io=0/0,kio=0,kro=1}
2017-10-30 23:54:47.268 [DEBUG] [org.eclipse.jetty.io.WriteFlusher                 ] - Flushed=true 6/6+1 WriteFlusher@5219ff39{WRITING}
2017-10-30 23:54:47.268 [DEBUG] [org.eclipse.jetty.io.WriteFlusher                 ] - Flushed=true 110/110+1 WriteFlusher@278d698a{WRITING}
2017-10-30 23:54:47.269 [DEBUG] [org.eclipse.jetty.server.HttpConnection           ] - org.eclipse.jetty.server.HttpConnection$SendCallback@5e9a519[PROCESSING][i=HTTP/1.1{s=201,h=2},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@15abfbdf] generate: DONE ([p=110,l=110,c=8192,r=0],[p=182,l=182,c=8192,r=0],true)@END
2017-10-30 23:54:47.269 [DEBUG] [org.eclipse.jetty.server.HttpConnection           ] - org.eclipse.jetty.server.HttpConnection$SendCallback@3fba9f5b[PROCESSING][i=null,cb=Blocker@618a2bd9{null}] generate: DONE (null,[p=222,l=222,c=32768,r=0],false)@COMMITTED
2017-10-30 23:54:47.270 [DEBUG] [org.eclipse.jetty.server.Server                   ] - handled=true async=false committed=true on HttpChannelOverHttp@63642d60{r=31,c=true,a=DISPATCHED,uri=//fedora01.rushworth.us:8080/rest/items/Virtual_Player_2}
2017-10-30 23:54:47.270 [DEBUG] [org.eclipse.jetty.server.HttpChannelState         ] - HttpChannelState@55a8595{s=DISPATCHED a=NOT_ASYNC i=true r=!P!U w=false} unhandle DISPATCHED
2017-10-30 23:54:47.272 [DEBUG] [org.eclipse.jetty.server.HttpChannel              ] - HttpChannelOverHttp@63642d60{r=31,c=true,a=COMPLETING,uri=//fedora01.rushworth.us:8080/rest/items/Virtual_Player_2} action COMPLETE
2017-10-30 23:54:47.273 [DEBUG] [org.eclipse.jetty.server.HttpChannel              ] - COMPLETE for /rest/items/Virtual_Player_2 written=182

5iver · 2017-10-31T04:42:59Z

When changing the state of this new dummy item (Virtual_Player_2) from the console, I see

2017-10-31 00:30:25.570 [DEBUG] [ll.impl.console.osgi.LoggingCommandSessionListener] - Executing command: 'smarthome:send Virtual_Player_2 PLAY'
2017-10-31 00:30:25.577 [DEBUG] [ll.impl.console.osgi.LoggingCommandSessionListener] - Command: 'smarthome:send Virtual_Player_2 PLAY' returned 'null'

But nothing from JDBC. I would expect storeItemValue to log "JDBC::store: Unable to store item '{}'."

The state is changing properly, as displayed from the console.

9037568 · 2017-10-31T06:10:01Z

There doesn't appear to be any debug output coming from JDBC in those logs.

This appears to be the package that should be set to DEBUG: org.openhab.persistence.jdbc

5iver · 2017-10-31T06:16:11Z

I was surprised by this as well! I tested some other items and JDBC logged them.

openhab> log:get
Logger │ Level
────────────────────────────────────────────┼──────
ROOT │ DEBUG
org.openhab.persistence.jdbc │ DEBUG

9037568 · 2017-10-31T06:25:43Z

It appears the PersistenceServiceDelegate silently drops items whose type it doesn't recognize:

@Override
public void store(Item item) {
    org.openhab.core.items.Item ohItem = ItemMapper.mapToOpenHABItem(item);
    if (ohItem != null) {
        service.store(ohItem);
    }
}

The mapToOpenHABItem method doesn't grok Player.

We may need @kaikreuzer to weigh in on whether the compat1x layer should support unknown types.

kaikreuzer · 2017-10-31T19:25:00Z

The compat layer deals with the types that exist in openHAB 1 (and Player is not one of them) as it delegates to services that were implemented for openHAB 1 only and that therefore would not know a Player type.
The correct long term approach would be to migrate the persistence service implementations to the ESH APIs, so that no compat layer is required for them anymore.

9037568 · 2017-10-31T23:44:29Z

@openhab-5iver would you like to open a feature request on OH2 for porting the persistence? I'll do it if not...

5iver · 2017-11-01T08:56:29Z

@9037568, hopefully I have provided enough detail. And thank you very much for tracking down the root of the issue!

9037568 added the awaiting-feedback label Oct 31, 2017

9037568 removed the awaiting-feedback label Oct 31, 2017

9037568 added awaiting-feedback esh openHAB2 labels Oct 31, 2017

9037568 added wontfix and removed awaiting-feedback labels Oct 31, 2017

9037568 closed this as completed Oct 31, 2017

5iver mentioned this issue Nov 1, 2017

Add JDBC Persistence openhab/openhab-addons#2819

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[JDBC] Player items are not persisted #5347

[JDBC] Player items are not persisted #5347

5iver commented Oct 31, 2017 •

edited

9037568 commented Oct 31, 2017

5iver commented Oct 31, 2017

9037568 commented Oct 31, 2017

9037568 commented Oct 31, 2017 •

edited

5iver commented Oct 31, 2017 •

edited

5iver commented Oct 31, 2017 •

edited

9037568 commented Oct 31, 2017

5iver commented Oct 31, 2017 •

edited

9037568 commented Oct 31, 2017

kaikreuzer commented Oct 31, 2017

9037568 commented Oct 31, 2017

5iver commented Nov 1, 2017 •

edited

[JDBC] Player items are not persisted #5347

[JDBC] Player items are not persisted #5347

Comments

5iver commented Oct 31, 2017 • edited

Current Behavior

Possible Solution

Steps to Reproduce (for bugs)

Context

Your Environment

9037568 commented Oct 31, 2017

5iver commented Oct 31, 2017

9037568 commented Oct 31, 2017

9037568 commented Oct 31, 2017 • edited

5iver commented Oct 31, 2017 • edited

5iver commented Oct 31, 2017 • edited

9037568 commented Oct 31, 2017

5iver commented Oct 31, 2017 • edited

9037568 commented Oct 31, 2017

kaikreuzer commented Oct 31, 2017

9037568 commented Oct 31, 2017

5iver commented Nov 1, 2017 • edited

5iver commented Oct 31, 2017 •

edited

9037568 commented Oct 31, 2017 •

edited

5iver commented Oct 31, 2017 •

edited

5iver commented Oct 31, 2017 •

edited

5iver commented Oct 31, 2017 •

edited

5iver commented Nov 1, 2017 •

edited