Check correct working of audio cache - seems to have hickups

[ewjmulder]

See logging below. Expected result: all in cahce, since adventure had been played before. Seems like saving in cache sometimes fails. Update: also still cache misses after reboot of system: something buggy in whole cache system...

Using properties in file: /home/emulder/pyh/repos/adventure-service/server/src/test/resources/config/test.adventureroom.properties

. ____ _ __ _ _
/\ / ' __ _ () __ __ _ \ \ \
( ( )__ | '_ | '| | ' / ` | \ \ \
\/ )| |)| | | | | || (| | ) ) ) )
' || .__|| ||| |_, | / / / /
=========||==============|/=////
:: Spring Boot :: (v1.4.1.RELEASE)

2018-08-06 00:04:10.305 INFO 5937 --- [ main] c.p.adventureroom.AdventureRoom : Starting AdventureRoom on emulder-qsd with PID 5937 (/home/emulder/pyh/repos/adventure-service/server/target/classes started by emulder in /home/emulder/pyh/repos/adventure-service/server)
2018-08-06 00:04:10.307 DEBUG 5937 --- [ main] c.p.adventureroom.AdventureRoom : Running with Spring Boot v1.4.1.RELEASE, Spring v4.3.3.RELEASE
2018-08-06 00:04:10.307 INFO 5937 --- [ main] c.p.adventureroom.AdventureRoom : No active profile set, falling back to default profiles: default
2018-08-06 00:04:10.340 INFO 5937 --- [ main] ationConfigEmbeddedWebApplicationContext : Refreshing org.springframework.boot.context.embedded.AnnotationConfigEmbeddedWebApplicationContext@6e171cd7: startup date [Mon Aug 06 00:04:10 CEST 2018]; root of context hierarchy
2018-08-06 00:04:11.074 INFO 5937 --- [ main] f.a.AutowiredAnnotationBeanPostProcessor : JSR-330 'javax.inject.Inject' annotation found and supported for autowiring
2018-08-06 00:04:11.421 INFO 5937 --- [ main] s.b.c.e.t.TomcatEmbeddedServletContainer : Tomcat initialized with port(s): 19161 (http)
2018-08-06 00:04:11.432 INFO 5937 --- [ main] o.apache.catalina.core.StandardService : Starting service Tomcat
2018-08-06 00:04:11.433 INFO 5937 --- [ main] org.apache.catalina.core.StandardEngine : Starting Servlet Engine: Apache Tomcat/8.5.5
2018-08-06 00:04:11.523 INFO 5937 --- [ost-startStop-1] o.a.c.c.C.[Tomcat].[localhost].[/] : Initializing Spring embedded WebApplicationContext
2018-08-06 00:04:11.523 INFO 5937 --- [ost-startStop-1] o.s.web.context.ContextLoader : Root WebApplicationContext: initialization completed in 1185 ms
2018-08-06 00:04:11.673 INFO 5937 --- [ost-startStop-1] o.s.b.w.servlet.ServletRegistrationBean : Mapping servlet: 'dispatcherServlet' to [/]
2018-08-06 00:04:11.677 INFO 5937 --- [ost-startStop-1] o.s.b.w.servlet.FilterRegistrationBean : Mapping filter: 'characterEncodingFilter' to: [/]
2018-08-06 00:04:11.677 INFO 5937 --- [ost-startStop-1] o.s.b.w.servlet.FilterRegistrationBean : Mapping filter: 'hiddenHttpMethodFilter' to: [/]
2018-08-06 00:04:11.677 INFO 5937 --- [ost-startStop-1] o.s.b.w.servlet.FilterRegistrationBean : Mapping filter: 'httpPutFormContentFilter' to: [/]
2018-08-06 00:04:11.678 INFO 5937 --- [ost-startStop-1] o.s.b.w.servlet.FilterRegistrationBean : Mapping filter: 'requestContextFilter' to: [/]
Character: com.programyourhome.adventureroom.module.amazonpolly.model.characters.PollyCharacter@503fbbc6[voiceId=Joanna,id=casey,name=Casey,description=Cool Casey]
Character: com.programyourhome.adventureroom.module.amazonpolly.model.characters.PollyCharacter@55f45b92[voiceId=Matthew,id=pete,name=Pete,description=Lonesome Pete]
Resource: com.programyourhome.adventureroom.module.immerse.model.SpeakerExternalResource@c7a977f
Resource: com.programyourhome.adventureroom.module.immerse.model.SpeakerExternalResource@2c383e33
Resource: com.programyourhome.adventureroom.module.immerse.model.SpeakerExternalResource@74a195a4
Resource: com.programyourhome.adventureroom.module.immerse.model.SpeakerExternalResource@76304b46
Resource: com.programyourhome.adventureroom.module.immerse.model.SpeakerExternalResource@2fa3be26
Resource: com.programyourhome.adventureroom.module.immerse.model.SpeakerExternalResource@4287d447
Resource: com.programyourhome.adventureroom.module.immerse.model.SpeakerExternalResource@3af37506
Resource: com.programyourhome.adventureroom.module.immerse.model.SpeakerExternalResource@4e6d7365
Resource: com.programyourhome.adventureroom.module.immerse.model.SpeakerExternalResource@7c0da600
Resource: com.programyourhome.adventureroom.module.immerse.model.SpeakerExternalResource@d4602a
Resource: com.programyourhome.adventureroom.module.immerse.model.SpeakerExternalResource@21ae6e73
Resource: com.programyourhome.adventureroom.module.immerse.model.SpeakerExternalResource@47dd778
Resource: com.programyourhome.adventureroom.module.philipshue.model.resources.colors.ColorRGB@b0964b2[red=0,green=255,blue=255,id=yellow,name=Yellow,description=]
Resource: com.programyourhome.adventureroom.module.philipshue.model.resources.colors.ColorRGB@48e7b3d2[red=0,green=255,blue=0,id=green,name=Green,description=]
Resource: com.programyourhome.adventureroom.module.philipshue.model.resources.colors.ColorRGB@7f4037ed[red=255,green=0,blue=0,id=red,name=Red,description=]
Resource: com.programyourhome.adventureroom.module.philipshue.model.resources.colors.ColorRGB@24e8de5c[red=102,green=51,blue=153,id=purple,name=Purple,description=]
Resource: com.programyourhome.adventureroom.module.philipshue.model.resources.colors.ColorRGB@64040287[red=255,green=255,blue=255,id=white,name=White,description=]
Resource: com.programyourhome.adventureroom.module.philipshue.model.resources.colors.ColorRGB@110844f6[red=0,green=0,blue=255,id=blue,name=Blue,description=]
Resource: com.programyourhome.adventureroom.module.philipshue.model.resources.lights.Light@df1cff6[idInBridge=1,id=testlight1,name=Test Light 1,description=]
Resource: com.programyourhome.adventureroom.module.philipshue.model.resources.lights.Light@4925f4f5[idInBridge=2,id=testlight2,name=Test Light 2,description=]
Resource: com.programyourhome.adventureroom.module.philipshue.model.resources.plugs.Plug@3a43d133[idInBridge=3,id=plug1,name=Plug 1,description=]
Character: com.programyourhome.adventureroom.module.amazonpolly.model.characters.PollyCharacter@39ce27f2[voiceId=Joanna,id=casey,name=Casey,description=Cool Casey]
Character: com.programyourhome.adventureroom.module.amazonpolly.model.characters.PollyCharacter@5f2afe62[voiceId=Matthew,id=pete,name=Pete,description=Lonesome Pete]
2018-08-06 00:04:12.040 INFO 5937 --- [ main] s.w.s.m.m.a.RequestMappingHandlerAdapter : Looking for @ControllerAdvice: org.springframework.boot.context.embedded.AnnotationConfigEmbeddedWebApplicationContext@6e171cd7: startup date [Mon Aug 06 00:04:10 CEST 2018]; root of context hierarchy
2018-08-06 00:04:12.087 INFO 5937 --- [ main] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped "{[/adventures]}" onto public java.util.Set<com.programyourhome.adventureroom.model.Describable> com.programyourhome.adventureroom.server.controllers.AdventuresController.listAdventures()
2018-08-06 00:04:12.088 INFO 5937 --- [ main] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped "{[/adventures/{id}]}" onto public com.programyourhome.adventureroom.model.Describable com.programyourhome.adventureroom.server.controllers.AdventuresController.getAdventure(java.lang.String)
2018-08-06 00:04:12.089 INFO 5937 --- [ main] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped "{[/adventures/{id}/start]}" onto public void com.programyourhome.adventureroom.server.controllers.AdventuresController.startAdventure(java.lang.String)
2018-08-06 00:04:12.089 INFO 5937 --- [ main] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped "{[/adventures/stop]}" onto public void com.programyourhome.adventureroom.server.controllers.AdventuresController.stopAdventure()
2018-08-06 00:04:12.091 INFO 5937 --- [ main] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped "{[/streams/{id}],methods=[GET]}" onto public org.springframework.http.ResponseEntity<org.springframework.core.io.InputStreamResource> com.programyourhome.adventureroom.server.controllers.DataStreamToUrlController.getStream(java.lang.String)
2018-08-06 00:04:12.092 INFO 5937 --- [ main] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped "{[/meta/server/shutdown]}" onto public void com.programyourhome.adventureroom.server.controllers.MetaController.shutdownServer()
2018-08-06 00:04:12.092 INFO 5937 --- [ main] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped "{[/meta/status/ping]}" onto public java.lang.String com.programyourhome.adventureroom.server.controllers.MetaController.pingServer()
2018-08-06 00:04:12.093 INFO 5937 --- [ main] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped "{[/scripts/{id}]}" onto public com.programyourhome.adventureroom.model.Describable com.programyourhome.adventureroom.server.controllers.ScriptsController.getScript(java.lang.String)
2018-08-06 00:04:12.093 INFO 5937 --- [ main] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped "{[/scripts]}" onto public java.util.Collection<com.programyourhome.adventureroom.model.Describable> com.programyourhome.adventureroom.server.controllers.ScriptsController.listScripts()
2018-08-06 00:04:12.093 INFO 5937 --- [ main] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped "{[/scripts/{id}/run]}" onto public void com.programyourhome.adventureroom.server.controllers.ScriptsController.runScript(java.lang.String)
2018-08-06 00:04:12.096 INFO 5937 --- [ main] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped "{[/error]}" onto public org.springframework.http.ResponseEntity<java.util.Map<java.lang.String, java.lang.Object>> org.springframework.boot.autoconfigure.web.BasicErrorController.error(javax.servlet.http.HttpServletRequest)
2018-08-06 00:04:12.096 INFO 5937 --- [ main] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped "{[/error],produces=[text/html]}" onto public org.springframework.web.servlet.ModelAndView org.springframework.boot.autoconfigure.web.BasicErrorController.errorHtml(javax.servlet.http.HttpServletRequest,javax.servlet.http.HttpServletResponse)
2018-08-06 00:04:12.126 INFO 5937 --- [ main] o.s.w.s.handler.SimpleUrlHandlerMapping : Mapped URL path [/webjars/] onto handler of type [class org.springframework.web.servlet.resource.ResourceHttpRequestHandler]
2018-08-06 00:04:12.127 INFO 5937 --- [ main] o.s.w.s.handler.SimpleUrlHandlerMapping : Mapped URL path [/] onto handler of type [class org.springframework.web.servlet.resource.ResourceHttpRequestHandler]
2018-08-06 00:04:12.162 INFO 5937 --- [ main] o.s.w.s.handler.SimpleUrlHandlerMapping : Mapped URL path [/**/favicon.ico] onto handler of type [class org.springframework.web.servlet.resource.ResourceHttpRequestHandler]
2018-08-06 00:04:12.279 INFO 5937 --- [ main] o.s.j.e.a.AnnotationMBeanExporter : Registering beans for JMX exposure on startup
2018-08-06 00:04:12.316 INFO 5937 --- [ main] s.b.c.e.t.TomcatEmbeddedServletContainer : Tomcat started on port(s): 19161 (http)
2018-08-06 00:04:12.319 INFO 5937 --- [ main] c.p.adventureroom.AdventureRoom : Started AdventureRoom in 2.323 seconds (JVM running for 2.539)
2018-08-06 00:04:15.654 INFO 5937 --- [.0-19161-exec-1] o.a.c.c.C.[Tomcat].[localhost].[/] : Initializing Spring FrameworkServlet 'dispatcherServlet'
2018-08-06 00:04:15.655 INFO 5937 --- [.0-19161-exec-1] o.s.web.servlet.DispatcherServlet : FrameworkServlet 'dispatcherServlet': initialization started
2018-08-06 00:04:15.664 INFO 5937 --- [.0-19161-exec-1] o.s.web.servlet.DispatcherServlet : FrameworkServlet 'dispatcherServlet': initialization completed in 9 ms

Starting task [Connect to Immerse client] for module [Immerse]
Immerse client connection successful!
Starting task [Connect to Amazon AWS] for module [Amazon Polly]

Resource not found in cache, invoking actual Polly service
Resource not found in cache, invoking actual Polly service
Resource not found in cache, invoking actual Polly service
Resource not found in cache, invoking actual Polly service
Resource found in cache! Using cached Polly result.
Resource not found in cache, invoking actual Polly service
Resource found in cache! Using cached Polly result.
Resource found in cache! Using cached Polly result.
Resource found in cache! Using cached Polly result.
Resource found in cache! Using cached Polly result.
Resource found in cache! Using cached Polly result.
Resource found in cache! Using cached Polly result.

Resource found in cache! Using cached Polly result.
Resource found in cache! Using cached Polly result.
Resource found in cache! Using cached Polly result.
Resource found in cache! Using cached Polly result.
Resource found in cache! Using cached Polly result.
Resource not found in cache, invoking actual Polly service
Resource found in cache! Using cached Polly result.
Resource found in cache! Using cached Polly result.
Resource found in cache! Using cached Polly result.
Resource found in cache! Using cached Polly result.
Resource found in cache! Using cached Polly result.

Resource found in cache! Using cached Polly result.
Resource found in cache! Using cached Polly result.
Resource found in cache! Using cached Polly result.
Resource found in cache! Using cached Polly result.
Resource found in cache! Using cached Polly result.
Resource found in cache! Using cached Polly result.
Resource found in cache! Using cached Polly result.
Resource found in cache! Using cached Polly result.
Resource found in cache! Using cached Polly result.
Resource found in cache! Using cached Polly result.
Resource found in cache! Using cached Polly result.
Resource found in cache! Using cached Polly result.

Resource found in cache! Using cached Polly result.
Resource found in cache! Using cached Polly result.
Resource found in cache! Using cached Polly result.
Resource found in cache! Using cached Polly result.
Resource found in cache! Using cached Polly result.
Resource found in cache! Using cached Polly result.
Resource found in cache! Using cached Polly result.
Resource found in cache! Using cached Polly result.
Resource found in cache! Using cached Polly result.
Resource found in cache! Using cached Polly result.
Resource found in cache! Using cached Polly result.
Resource found in cache! Using cached Polly result.
Resource found in cache! Using cached Polly result.