Timer not running in prpduction - but in debug mode

jens-jensen · April 29, 2017, 12:40pm

Hey Mark,

thanks for your immediate reply. I ran the timers in debug mode and got the following stacktrace:

java.lang.reflect.InvocationTargetException
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:497)
at com.backendless.coderunner.runtime.task.EventInvocationTask.runImpl(EventInvocationTask.java:117)
at com.backendless.coderunner.runtime.executor.ExtendedRunnable.run(ExtendedRunnable.java:38)
at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.ExceptionInInitializerError
at com.rometools.rome.io.SyndFeedInput.build(SyndFeedInput.java:133)
at de.tifosi.backend.parser.RssParser.lambda$parse$9(RssParser.java:42)
at com.github.nocatch.NoCatch.noCatch(NoCatch.java:100)
at com.github.nocatch.NoCatch.noCatch(NoCatch.java:82)
at de.tifosi.backend.parser.RssParser.parse(RssParser.java:42)
at de.tifosi.backend.updaters.NewsUpdater.updateFromFeed(NewsUpdater.java:148)
at de.tifosi.backend.updaters.NewsUpdater.update(NewsUpdater.java:138)
at java.util.Arrays$ArrayList.forEach(Arrays.java:3880)
at de.tifosi.backend.updaters.NewsUpdater.updateNewsFromFeeds(NewsUpdater.java:125)
at de.tifosi.backend.updaters.NewsUpdater.run(NewsUpdater.java:112)
at de.fortuna.timers.CabineUpdateTimer.execute(CabineUpdateTimer.java:97)
… 7 more
Caused by: java.lang.RuntimeException: could not instantiate plugin null
at com.rometools.rome.io.impl.PluginManager.loadPlugins(PluginManager.java:133)
at com.rometools.rome.io.impl.PluginManager.<init>(PluginManager.java:63)
at com.rometools.rome.io.impl.PluginManager.<init>(PluginManager.java:56)
at com.rometools.rome.feed.synd.impl.Converters.<init>(Converters.java:37)
at com.rometools.rome.feed.synd.SyndFeedImpl.<clinit>(SyndFeedImpl.java:84)
… 18 more
Caused by: java.security.AccessControlException: access denied (“java.util.PropertyPermission” “rome.pluginmanager.useloadclass” “read”)
at java.security.AccessControlContext.checkPermission(AccessControlContext.java:472)
at java.security.AccessController.checkPermission(AccessController.java:884)
at java.lang.SecurityManager.checkPermission(SecurityManager.java:549)
at com.backendless.coderunner.runtime.security.CodeRunnerSecurityManager.checkPermission(CodeRunnerSecurityManager.java:93)
at java.lang.SecurityManager.checkPropertyAccess(SecurityManager.java:1294)
at java.lang.System.getProperty(System.java:753)
at com.rometools.rome.io.impl.PluginManager.getClasses(PluginManager.java:159)
at com.rometools.rome.io.impl.PluginManager.loadPlugins(PluginManager.java:97)
… 22 more

To me it look like rome tools tries to read property java.util.PropertyPermission but Backendless does not allow it. Is it possible, to grant this permission? Locally in debug mode, I can edit security.profile to make the code run.

mark-piller · April 29, 2017, 3:37pm

Jens,

That explains it - the security manager does not allow reading of properties. I will discuss with the team to understand why there is such a restriction and respond back to you.

Regards,
Mark

jens-jensen · April 29, 2017, 6:38pm

Okay, thanks Mark. I hope we can make this work, as I would really like to stay with Backendless.

jens-jensen · April 30, 2017, 12:47pm

Hey Mark,

I have forked the lib from Github and deleted the code which caused the former error. Now I get a new error:

Caused by: java.security.AccessControlException: You have no permission to create thread in CodeRunner secure group.
at com.backendless.coderunner.runtime.security.CodeRunnerSecurityManager.checkAccess(CodeRunnerSecurityManager.java:59)

I thought Backendless 4 allows users to create threads in custom business logic?

mark-piller · April 30, 2017, 1:34pm

The config setting says 2 threads are allowed. Let me experiment with it and I will let you know.

mark-piller · April 30, 2017, 3:53pm

Hi Jens,

I put together the following example which confirms that creating an additional thread is working:

@Asset( "Person" )
public class PersonTableEventHandler extends com.backendless.servercode.extension.PersistenceExtender&lt;Person&gt;
{
 
 @Override
 public void beforeCreate( RunnerContext context, Person person) throws Exception
 {
 try
 {
 Backendless.Logging.getLogger( "BL" ).info( "in before create" );
 Thread t = new Thread( new Runnable()
 {
 @Override
 public void run()
 {
 Backendless.Logging.getLogger( "BL" ).info( "running 2nd thread" );
 HashMap&lt;String, String&gt; testObj = new HashMap&lt;String, String&gt;();
 testObj.put( "foo", "bar" );
 Backendless.Data.of( "Test" ).save( testObj );
 Backendless.Logging.getLogger( "BL" ).info( "2nd thread is done" );
 }
 } );
 t.start();
 Thread.sleep( 2000 );
 Backendless.Logging.getLogger( "BL" ).info( "exiting from beforeCreate" );
 }
 catch( Throwable t )
 {
 Backendless.Logging.getLogger( "BL" ).error( "general failure", t );
 }
 }
}

When I run the code, it does create a separate thread and the object is saved.
The logging also confirms this:

2017-04-30 15:35:31,643 | BL | INFO | in before create
2017-04-30 15:35:31,675 | BL | INFO | running 2nd thread
2017-04-30 15:35:31,765 | BL | INFO | 2nd thread is done
2017-04-30 15:35:33,678 | BL | INFO | exiting from beforeCreate

However, as soon as I refactor code and add 3rd thread, I get an exception. Here’s a
failing example:

@Asset( "Person" )
public class PersonTableEventHandler extends com.backendless.servercode.extension.PersistenceExtender&lt;Person&gt;
{
 
 @Override
 public void beforeCreate( RunnerContext context, Person person) throws Exception
 {
 Backendless.Logging.setLogReportingPolicy( 1, 0 );
 System.out.println( "in before create");
 try
 {
 Backendless.Logging.getLogger( "BL" ).info( "in before create" );

 Thread t1 = getThread();
 Thread t2 = getThread();

 t1.start();
 t2.start();

 Thread.sleep( 2000 );

 Backendless.Logging.getLogger( "BL" ).info( "exiting from beforeCreate" );
 }
 catch( Throwable t )
 {
 Backendless.Logging.getLogger( "BL" ).error( "general failure", t );
 }
 }

 private Thread getThread()
 {
 return new Thread( new Runnable()
 {
 @Override
 public void run()
 {
 Backendless.Logging.getLogger( "BL" ).info( "running additional thread" );
 HashMap&lt;String, String&gt; testObj = new HashMap&lt;String, String&gt;();
 testObj.put( "foo", "bar" );
 Backendless.Data.of( "Test" ).save( testObj );
 Backendless.Logging.getLogger( "BL" ).info( "additional thread is done" );
 }
 } );
 }
 
}

In this case I get the following error:

2017-04-30 15:45:32,413 | BL | ERROR | general failure : java.security.AccessControlException: Cannot allocate new thread. You can remove this limitation by purchasing a function pack in Backendless Marketplace.
at com.backendless.coderunner.runtime.security.CodeRunnerSecurityManager.checkAccess(CodeRunnerSecurityManager.java:76)
at java.lang.ThreadGroup.checkAccess(ThreadGroup.java:315)
at java.lang.Thread.init(Thread.java:391)
at java.lang.Thread.init(Thread.java:349)
at java.lang.Thread.&lt;init&gt;(Thread.java:461)
at com.consoledemo.events.persistence_service.PersonTableEventHandler.getThread(PersonTableEventHandler.java:57)
at com.consoledemo.events.persistence_service.PersonTableEventHandler.beforeCreate(PersonTableEventHandler.java:40)
at com.consoledemo.events.persistence_service.PersonTableEventHandler.beforeCreate(PersonTableEventHandler.java:26)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:497)
at com.backendless.coderunner.runtime.task.EventInvocationTask.runImpl(EventInvocationTask.java:117)
at com.backendless.coderunner.runtime.executor.ExtendedRunnable.run(ExtendedRunnable.java:38)
at java.lang.Thread.run(Thread.java:745)

I suspect in your code more than thread is created and that’s why you’re getting the exception. We can bump up the limit of threads why the product is in beta. Please keep in mind that the capability to start new threads will be a commercial feature.

jens-jensen · April 30, 2017, 5:33pm

Hey Mark,

thanks for your effort and the quick response.

“We can bump up the limit of threads why the product is in beta. Please keep in mind that the capability to start new threads will be a commercial feature.”

As the threads are created by a lib that I use, I currently don’t know how many threads are started. It would be great if you can bump up the limit of threads in the beta version. But how many threads will be allowed, when I purchase the function pack in the final version 4.0? This is very important for me to know, because in worst case my product won’t work with Backendless.

mark-piller · April 30, 2017, 5:46pm

I am going to check on the price and let you know. What does the lib do that it needs extra threads? I’d be concerned with a library that is hungry for threads…

jens-jensen · May 13, 2017, 11:04am

Hey Mark,

we still got problems and I have no idea where they come from. Code runs perfectly in debug mode, but not on the server. This is the stacktrace:

Caused by: java.security.AccessControlException: You have no permission to create thread in CodeRunner secure group.
at com.backendless.coderunner.runtime.security.CodeRunnerSecurityManager.checkAccess(CodeRunnerSecurityManager.java:59)
at java.lang.ThreadGroup.checkAccess(ThreadGroup.java:315)
at java.lang.ThreadGroup.getParent(ThreadGroup.java:167)
at sun.net.www.http.KeepAliveCache$1.run(KeepAliveCache.java:102)
at sun.net.www.http.KeepAliveCache$1.run(KeepAliveCache.java:96)
at java.security.AccessController.doPrivileged(Native Method)
at sun.net.www.http.KeepAliveCache.put(KeepAliveCache.java:95)
at sun.net.www.http.HttpClient.putInKeepAliveCache(HttpClient.java:407)
at sun.net.www.http.HttpClient.finished(HttpClient.java:364)
at sun.net.www.http.KeepAliveStream.close(KeepAliveStream.java:97)
at sun.net.www.MeteredStream.justRead(MeteredStream.java:93)
at sun.net.www.MeteredStream.read(MeteredStream.java:135)
at java.io.FilterInputStream.read(FilterInputStream.java:133)
at sun.net.www.protocol.http.HttpURLConnection$HttpInputStream.read(HttpURLConnection.java:3336)
at java.io.BufferedInputStream.read1(BufferedInputStream.java:284)
at java.io.BufferedInputStream.read(BufferedInputStream.java:345)
at sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:284)
at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:326)
at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:178)
at sun.nio.cs.StreamDecoder.read0(StreamDecoder.java:127)
at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:171)
at java.io.InputStreamReader.read(InputStreamReader.java:184)
at com.rometools.rome.io.XmlReader.read(XmlReader.java:437)
at java.io.Reader.read(Reader.java:121)
at com.rometools.rome.io.impl.XmlFixerReader.read(XmlFixerReader.java:191)
at com.rometools.rome.io.impl.XmlFixerReader.read(XmlFixerReader.java:336)
at com.sun.org.apache.xerces.internal.impl.XMLEntityScanner.load(XMLEntityScanner.java:1793)
at com.sun.org.apache.xerces.internal.impl.XMLEntityScanner.scanQName(XMLEntityScanner.java:852)
at com.sun.org.apache.xerces.internal.impl.XMLNSDocumentScannerImpl.scanAttribute(XMLNSDocumentScannerImpl.java:414)
at com.sun.org.apache.xerces.internal.impl.XMLNSDocumentScannerImpl.scanStartElement(XMLNSDocumentScannerImpl.java:256)
at com.sun.org.apache.xerces.internal.impl.XMLNSDocumentScannerImpl$NSContentDriver.scanRootElementHook(XMLNSDocumentScannerImpl.java:614)
at com.sun.org.apache.xerces.internal.impl.XMLDocumentFragmentScannerImpl$FragmentContentDriver.next(XMLDocumentFragmentScannerImpl.java:3135)
at com.sun.org.apache.xerces.internal.impl.XMLDocumentScannerImpl$PrologDriver.next(XMLDocumentScannerImpl.java:880)
at com.sun.org.apache.xerces.internal.impl.XMLDocumentScannerImpl.next(XMLDocumentScannerImpl.java:606)
at com.sun.org.apache.xerces.internal.impl.XMLNSDocumentScannerImpl.next(XMLNSDocumentScannerImpl.java:118)
at com.sun.org.apache.xerces.internal.impl.XMLDocumentFragmentScannerImpl.scanDocument(XMLDocumentFragmentScannerImpl.java:510)
at com.sun.org.apache.xerces.internal.parsers.XML11Configuration.parse(XML11Configuration.java:848)
at com.sun.org.apache.xerces.internal.parsers.XML11Configuration.parse(XML11Configuration.java:777)
at com.sun.org.apache.xerces.internal.parsers.XMLParser.parse(XMLParser.java:141)
at com.sun.org.apache.xerces.internal.parsers.AbstractSAXParser.parse(AbstractSAXParser.java:1213)
at com.sun.org.apache.xerces.internal.jaxp.SAXParserImpl$JAXPSAXParser.parse(SAXParserImpl.java:643)
at org.jdom2.input.sax.SAXBuilderEngine.build(SAXBuilderEngine.java:217)
at org.jdom2.input.sax.SAXBuilderEngine.build(SAXBuilderEngine.java:303)
at org.jdom2.input.SAXBuilder.build(SAXBuilder.java:1196)
at com.rometools.rome.io.WireFeedInput.build(WireFeedInput.java:233)
… 18 common frames omitted

IMHO there is no thread created at this point and we are just reading from an InputStream. Can you please explain this?

mark-piller · May 13, 2017, 1:38pm

Hi Jen,

A thread is being created in that code, see lines 86-115:
http://www.docjar.com/html/api/sun/net/www/http/KeepAliveCache.java.html

Regards,
Mark

jens-jensen · May 19, 2017, 7:04am

Hey Mark,

I made some changes in the libs code and not it kinda works partially. After deploying the new timers, they ran for a couple of times. Now I’ve checked the log after the night and it is full of errors again and the timers don’t run anymore:

2017-05-18 21:25:13,113 | Coderunner | ERROR | Business logic execution has been stopped, due to error: Code: 0 Class: java.lang.ThreadDeath Message: null
2017-05-18 21:55:10,747 | Coderunner | ERROR | Business logic execution has been stopped, with message: null
2017-05-18 22:25:10,409 | Coderunner | ERROR | Business logic execution has been stopped, with message: null
2017-05-18 22:40:10,365 | Coderunner | ERROR | Business logic execution has been stopped, with message: null
2017-05-18 22:40:12,588 | Coderunner | ERROR | Business logic execution has been stopped, with message: null
2017-05-18 22:55:12,369 | Coderunner | ERROR | Business logic execution has been stopped, with message: null
2017-05-18 23:25:10,419 | Coderunner | ERROR | Business logic execution has been stopped, with message: null
2017-05-18 23:40:12,276 | Coderunner | ERROR | Business logic execution has been stopped, due to error: Code: 0 Class: java.lang.ThreadDeath Message: null
2017-05-18 23:40:13,309 | Coderunner | ERROR | Business logic execution has been stopped, due to error: Code: 0 Class: java.lang.ThreadDeath Message: null
2017-05-18 23:55:10,389 | Coderunner | ERROR | Business logic execution has been stopped, due to error: Code: 0 Class: java.lang.ThreadDeath Message: null
2017-05-19 00:10:11,050 | Coderunner | ERROR | Business logic execution has been stopped, with message: null
2017-05-19 01:25:10,699 | Coderunner | ERROR | Business logic execution has been stopped, with message: null
2017-05-19 01:55:10,423 | Coderunner | ERROR | Business logic execution has been stopped, due to error: Code: 0 Class: java.lang.ThreadDeath Message: null
2017-05-19 02:40:10,437 | Coderunner | ERROR | Business logic execution has been stopped, with message: null
2017-05-19 02:40:10,544 | Coderunner | ERROR | Business logic execution has been stopped, due to error: Code: 0 Class: java.lang.ThreadDeath Message: null
2017-05-19 02:55:10,406 | Coderunner | ERROR | Business logic execution has been stopped, due to error: Code: 0 Class: java.lang.ThreadDeath Message: null
2017-05-19 03:10:10,456 | Coderunner | ERROR | Business logic execution has been stopped, due to error: Code: 0 Class: java.lang.ThreadDeath Message: null
2017-05-19 03:10:10,562 | Coderunner | ERROR | Business logic execution has been stopped, due to error: Code: 0 Class: java.lang.ThreadDeath Message: null
2017-05-19 03:25:12,717 | Coderunner | ERROR | Business logic execution has been stopped, due to error: Code: 0 Class: java.lang.ThreadDeath Message: null
2017-05-19 03:25:13,725 | Coderunner | ERROR | Business logic execution has been stopped, with message: null
2017-05-19 03:55:10,852 | Coderunner | ERROR | Business logic execution has been stopped, with message: null
2017-05-19 03:55:11,013 | Coderunner | ERROR | Business logic execution has been stopped, due to error: Code: 0 Class: java.lang.ThreadDeath Message: null
2017-05-19 04:40:10,945 | Coderunner | ERROR | Business logic execution has been stopped, due to error: Code: 0 Class: java.lang.ThreadDeath Message: null
2017-05-19 04:55:11,633 | Coderunner | ERROR | Business logic execution has been stopped, due to error: Code: 0 Class: java.lang.ThreadDeath Message: null
2017-05-19 05:10:10,405 | Coderunner | ERROR | Business logic execution has been stopped, with message: null
2017-05-19 05:40:13,000 | Coderunner | ERROR | Business logic execution has been stopped, with message: null
2017-05-19 05:55:12,987 | Coderunner | ERROR | Business logic execution has been stopped, due to error: Code: 0 Class: java.lang.ThreadDeath Message: null
2017-05-19 06:25:10,443 | Coderunner | ERROR | Business logic execution has been stopped, with message: null
2017-05-19 06:25:12,900 | Coderunner | ERROR | Business logic execution has been stopped, due to error: Code: 0 Class: java.lang.ThreadDeath Message: null
2017-05-19 06:55:10,507 | Coderunner | ERROR | Business logic execution has been stopped, due to error: Code: 0 Class: java.lang.ThreadDeath Message: null

mark-piller · May 20, 2017, 1:46am

Hi Jens,

I would add a bunch extra logging to see how far the execution gets. Also add a try/catch around the whole timer method body so you catch (and log) any exceptions.

Mark

jens-jensen · May 20, 2017, 9:30am

Okay, I’ll do that.
Can I use the existing Coderunner Logger for writing extra logging information to the log files? I can’t find a documentation for Logging in Backendless 4.

mark-piller · May 20, 2017, 12:00pm

Backendless Logging API for Java is documented at:

https://backendless.com/docs/android/doc.html#ut_logging

jens-jensen · May 22, 2017, 7:27am

Thanks. Wasn’t searching for it in the Android section.