BUG - OH3.2 FINAL Map Transformation with Large Items File (Rest API on Items)

Hardware: New install on new hardware (Pi4)

Hi OH3 Team,

I have discovered a bug with OH 3.2m4 with Map Transformation and a large .items file.

This .items file was taken directly from an OH 2.4 working platform and it works natively fine when Map Transformation is NOT installed on OH 3.2m4. Once I install it, I get errors such as this from the REST API (http://openhabian:8080/rest/items).

{"link":"http://openhabian:8080/rest/items/Dimmer_StringLights_State","state":"1002.0","transformedState":"Short Released Butto"{\"error\":{\"message\":\"begin 0, end -1, length 12\",\"http-code\":500,\"exception\":{\"class\":\"java.lang.StringIndexOutOfBoundsException\",\"message\":\"begin 0, end -1, length 12\",\"localized-message\":\"begin 0, end -1, length 12\"}}}"

I’m using the basic MAP syntax that OH 2.x has used → “State [MAP(HUERemote.map):%s]”

This is just one example, if I reload the REST API it will be a different item next time.

Here’s another thread I discuss the same thing, thinking I resolved it BUT it’s tied to Map Transformation Service.

Best, Jay

Hi @Lolodomo,

Is the issue above the same as this below?

[transform][map] Added default i18n properties file by cweitkamp · Pull Request #11574 · openhab/openhab-addons (github.com)

Best, Jay

Absolutely no relation.

I have tested adding more memory to the Java heap but that did NOT fix this MAP bug.

EXTRA_JAVA_OPTS=-Xmx1024m

Best, Jay

Here’s the actual dump of the issue.

2021-11-16 17:09:58.236 [ERROR] [rg.apache.cxf.jaxrs.utils.JAXRSUtils] - Problem with writing the data, class org.openhab.core.io.rest.Stream2JSONInputStream, ContentType: application/json
2021-11-16 17:09:58.248 [ERROR] [internal.JSONResponseExceptionMapper] - Unexpected exception occurred while processing REST request.
java.lang.StringIndexOutOfBoundsException: begin 0, end -1, length 12
	at java.lang.String.checkBoundsBeginEnd(String.java:3319) ~[?:?]
	at java.lang.String.substring(String.java:1874) ~[?:?]
	at org.openhab.core.transform.AbstractFileTransformationService.getLocalizedProposedFilename(AbstractFileTransformationService.java:274) ~[?:?]
	at org.openhab.core.transform.AbstractFileTransformationService.transform(AbstractFileTransformationService.java:135) ~[?:?]
	at org.openhab.core.transform.TransformationHelper.transform(TransformationHelper.java:125) ~[?:?]
	at org.openhab.core.transform.TransformationHelper.transform(TransformationHelper.java:100) ~[?:?]
	at org.openhab.core.io.rest.core.item.EnrichedItemDTOMapper.considerTransformation(EnrichedItemDTOMapper.java:131) ~[?:?]
	at org.openhab.core.io.rest.core.item.EnrichedItemDTOMapper.map(EnrichedItemDTOMapper.java:68) ~[?:?]
	at org.openhab.core.io.rest.core.item.EnrichedItemDTOMapper.map(EnrichedItemDTOMapper.java:62) ~[?:?]
	at org.openhab.core.io.rest.core.internal.item.ItemResource.lambda$2(ItemResource.java:215) ~[?:?]
	at java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:195) ~[?:?]
	at java.util.HashMap$KeySpliterator.tryAdvance(HashMap.java:1642) ~[?:?]
	at java.util.stream.StreamSpliterators$WrappingSpliterator.lambda$initPartialTraversalState$0(StreamSpliterators.java:294) ~[?:?]
	at java.util.stream.StreamSpliterators$AbstractWrappingSpliterator.fillBuffer(StreamSpliterators.java:206) ~[?:?]
	at java.util.stream.StreamSpliterators$AbstractWrappingSpliterator.doAdvance(StreamSpliterators.java:169) ~[?:?]
	at java.util.stream.StreamSpliterators$WrappingSpliterator.tryAdvance(StreamSpliterators.java:300) ~[?:?]
	at java.util.Spliterators$1Adapter.hasNext(Spliterators.java:681) ~[?:?]
	at org.openhab.core.io.rest.Stream2JSONInputStream.fillBuffer(Stream2JSONInputStream.java:94) ~[?:?]
	at org.openhab.core.io.rest.Stream2JSONInputStream.read(Stream2JSONInputStream.java:70) ~[?:?]
	at java.io.InputStream.read(InputStream.java:280) ~[?:?]
	at java.io.InputStream.transferTo(InputStream.java:704) ~[?:?]
	at org.openhab.core.io.rest.core.internal.GsonMessageBodyWriter.writeTo(GsonMessageBodyWriter.java:84) ~[?:?]
	at org.openhab.core.io.rest.core.internal.MediaTypeExtension.writeTo(MediaTypeExtension.java:84) ~[?:?]
	at org.apache.cxf.jaxrs.utils.JAXRSUtils.writeMessageBody(JAXRSUtils.java:1543) ~[bundleFile:3.4.5]
	at org.apache.cxf.jaxrs.interceptor.JAXRSOutInterceptor.serializeMessage(JAXRSOutInterceptor.java:249) ~[bundleFile:3.4.5]
	at org.apache.cxf.jaxrs.interceptor.JAXRSOutInterceptor.processResponse(JAXRSOutInterceptor.java:122) ~[bundleFile:3.4.5]
	at org.apache.cxf.jaxrs.interceptor.JAXRSOutInterceptor.handleMessage(JAXRSOutInterceptor.java:84) ~[bundleFile:3.4.5]
	at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:308) ~[bundleFile:3.4.5]
	at org.apache.cxf.interceptor.OutgoingChainInterceptor.handleMessage(OutgoingChainInterceptor.java:90) ~[bundleFile:3.4.5]
	at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:308) ~[bundleFile:3.4.5]
	at org.apache.cxf.transport.ChainInitiationObserver.onMessage(ChainInitiationObserver.java:121) ~[bundleFile:3.4.5]
	at org.apache.cxf.transport.http.AbstractHTTPDestination.invoke(AbstractHTTPDestination.java:265) ~[bundleFile:3.4.5]
	at org.apache.cxf.transport.servlet.ServletController.invokeDestination(ServletController.java:234) ~[bundleFile:3.4.5]
	at org.apache.cxf.transport.servlet.ServletController.invoke(ServletController.java:208) ~[bundleFile:3.4.5]
	at org.apache.cxf.transport.servlet.ServletController.invoke(ServletController.java:160) ~[bundleFile:3.4.5]
	at org.apache.cxf.transport.servlet.CXFNonSpringServlet.invoke(CXFNonSpringServlet.java:225) ~[bundleFile:3.4.5]
	at org.apache.cxf.transport.servlet.AbstractHTTPServlet.handleRequest(AbstractHTTPServlet.java:298) ~[bundleFile:3.4.5]
	at org.apache.cxf.transport.servlet.AbstractHTTPServlet.doGet(AbstractHTTPServlet.java:222) ~[bundleFile:3.4.5]
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:687) ~[bundleFile:3.1.0]
	at org.apache.cxf.transport.servlet.AbstractHTTPServlet.service(AbstractHTTPServlet.java:273) ~[bundleFile:3.4.5]
	at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:799) ~[bundleFile:9.4.43.v20210629]
	at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:550) ~[bundleFile:9.4.43.v20210629]
	at org.ops4j.pax.web.service.jetty.internal.HttpServiceServletHandler.doHandle(HttpServiceServletHandler.java:71) ~[bundleFile:?]
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143) ~[bundleFile:9.4.43.v20210629]
	at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:602) ~[bundleFile:9.4.43.v20210629]
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) ~[bundleFile:9.4.43.v20210629]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235) ~[bundleFile:9.4.43.v20210629]
	at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1624) ~[bundleFile:9.4.43.v20210629]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233) ~[bundleFile:9.4.43.v20210629]
	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1434) ~[bundleFile:9.4.43.v20210629]
	at org.ops4j.pax.web.service.jetty.internal.HttpServiceContext.doHandle(HttpServiceContext.java:294) ~[bundleFile:?]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188) ~[bundleFile:9.4.43.v20210629]
	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:501) ~[bundleFile:9.4.43.v20210629]
	at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1594) ~[bundleFile:9.4.43.v20210629]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186) ~[bundleFile:9.4.43.v20210629]
	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1349) ~[bundleFile:9.4.43.v20210629]
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) ~[bundleFile:9.4.43.v20210629]
	at org.ops4j.pax.web.service.jetty.internal.JettyServerHandlerCollection.handle(JettyServerHandlerCollection.java:82) ~[bundleFile:?]
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) ~[bundleFile:9.4.43.v20210629]
	at org.eclipse.jetty.server.Server.handle(Server.java:516) ~[bundleFile:9.4.43.v20210629]
	at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:388) ~[bundleFile:9.4.43.v20210629]
	at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:633) [bundleFile:9.4.43.v20210629]
	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:380) [bundleFile:9.4.43.v20210629]
	at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:277) [bundleFile:9.4.43.v20210629]
	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311) [bundleFile:9.4.43.v20210629]
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) [bundleFile:9.4.43.v20210629]
	at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104) [bundleFile:9.4.43.v20210629]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:338) [bundleFile:9.4.43.v20210629]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:315) [bundleFile:9.4.43.v20210629]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:173) [bundleFile:9.4.43.v20210629]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131) [bundleFile:9.4.43.v20210629]
	at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:386) [bundleFile:9.4.43.v20210629]
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:883) [bundleFile:9.4.43.v20210629]
	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1034) [bundleFile:9.4.43.v20210629]
	at java.lang.Thread.run(Thread.java:829) [?:?]

Best, Jay

Considering the code, it could happen in case you missed the extension (.map).
Are you really sure that you use everywhere something like “[MAP(HUERemote.map):%s]” and never [MAP(HUERemote):%s] ?

This is literarily copying the .item and .map files from OH 2.x to OH 3.x.

If I comment out that specific item, it will randomly choose another item that has mapping tied to it. It happens at the end of the REST API call, meaning it works (displays properly) for about 1500+ items then it starts the issue failing.

I believe it could be a memory error on the mapping transition binding OR it could be a timeout issue going across the REST API calling the mapping transition binding.

I wish I could set the timeout value either on the REST API or map transition binding to something higher to rule that out.

Best, Jay

Your exception is clearly when building the path of the transformation file and I believe this exception will be thrown if no extension was provided.

But from this and other examples, it would appear that the actual MAP transform has already taken place but the output text gets cut off and error JSON inserted.
"transformedState":"Short Released Butto"{\"error\":{\"message\"
i.e. not a fundamental transform problem, but something like a timeout or messed-up return format.
In the linked thread the unexpected error gets inserted at different points in REST output, not always in transformedState, e.g. in the middle of options

Agreed, as you can see text is getting cut off randomly on the return of the JSON.

I’d be glad to send either @rossko57 or @Lolodomo my item file. It’s just one large file used with OH 2.x for 3 years now.

Best, Jay

Ok I understand the argument.
Unfortunately, I don’t know well the code lawyer behind the REST API call.

No thanks, I’ve zero insight into how REST API builds its output either.

I speculate it’s something else messing up - retrieving Item options or whatever - because of extra time taken by transformation. Based on working OK with MAP disabled. Trying a transformation with more overhead like JS might show it up more.

What’s the host box here? Sometimes race conditions show upon higher powered multi-core boxes beyond the average plodding Pi.

This part seems consistent -
{\"error\":{\"message\":\"begin 0, end -1, length 12\" ...
but I wouldn’t know if “always 12” is a clue. Looks like we’re trying to get char 12 from an empty string somewhere.

Brand new dedicated RaspberryPi4 with 4 GB of RAM.

Specifications

  • Broadcom BCM2711, Quad core Cortex-A72 (ARM v8) 64-bit SoC @ 1.5GHz
  • 2GB, 4GB or 8GB LPDDR4-3200 SDRAM (depending on model)
  • 2.4 GHz and 5.0 GHz IEEE 802.11ac wireless, Bluetooth 5.0, BLE
  • Gigabit Ethernet
  • 2 USB 3.0 ports; 2 USB 2.0 ports.
  • Raspberry Pi standard 40 pin GPIO header (fully backwards compatible with previous boards)
  • 2 × micro-HDMI ports (up to 4kp60 supported)
  • 2-lane MIPI DSI display port
  • 2-lane MIPI CSI camera port
  • 4-pole stereo audio and composite video port
  • H.265 (4kp60 decode), H264 (1080p60 decode, 1080p30 encode)
  • OpenGL ES 3.1, Vulkan 1.0
  • Micro-SD card slot for loading operating system and data storage
  • 5V DC via USB-C connector (minimum 3A*)
  • 5V DC via GPIO header (minimum 3A*)
  • Power over Ethernet (PoE) enabled (requires separate PoE HAT)
  • Operating temperature: 0 – 50 degrees C ambient

Best, Jay

Doesn’t seem extra special. Guessing you’re using openhabian and so have zram active, which should I think put the JSONDB in memory for speed. Ordinary enough.

Looking like sheer number of Items is the unique factor ??

I have been told to turn OFF zRAM in another thread about RaspberryPi that has 4 GB of RAM.

Here’s my Thing and Item count which are all in 1 file for each.

Capture

Best, Jay

Might be relevant. Building JSON for all Items hammers the JSONDB - I don’t know if all/some is held in memory (hurrah for freeing up with ZRAM off !) and/or in filestore (boo for no ZRAM to speed up i/o access !).
The API will hit multiple JSONDB to assemble each Item, and obviously transforms on top is further file accesses.

Likely irrelevant. xxx.items file is parsed once at bootup and converted to a working copy in JSONDB.

When I do this command w/o the MAP binding installed; it takes less than 2 seconds to retrieve all 2417 items in the browser w/o issue.

http://openhabian:8080/rest/items

Best, Jay

This is in relation with the exception. Substring is called with -1 as last position.
And 12 is the length of the nap filename.

Good theory. So I looked more closely at OPs longer list of example corruptions -

and unfortunately it’s always 12 even with
“pattern”:“MAP(onkyo_source.map):%s”
“pattern”:“MAP(On_Off.map):%s”
“pattern”:“MAP(HUERemote.map):%s”

Here’s those files.

HUERemote.map.txt (892 Bytes)
On_Off.map.txt (232 Bytes)
onkyo_source.map.txt (354 Bytes)

Best, Jay