[request] want options to redirect Sikuli's log messages to my own logging

[RaiMan]

A previous thread that is closest to answering my current question is:
    https://answers.launchpad.net/sikuli/+question/248604
in which RaiMan suggest the usage of a setSikuliXLogCallback

I searched the net for setSikuliXLogCallback, but the only hit I got was that thread. Hence this question/plea for more detail.

I recently started looking into Sikuli using IDE first, then I moved onto using standalone Jython, and then finally had the courage to venture into using Ruby, which is the primary language of my test framework.
I was pleasantly surprised how easy and great the interface was. Kudos to RaiMan and contributors on this great tool.

Now, onto my question...
I can redirect the java output to a single log file via Debug.setLogFile(log_file).
My test framework, however, uses Log4R which direct the log output to multiple files as well as the console.
Ideally I would like to redirect the logging requests to my logger to do it's thing, so that I can get all the output like:
[LOG] CLICK on L(27,10)@S(0)[0,0 1440x900]
in the standard log files.

I kind-a implemented a workaround that does this as follows:
1. I put in a one-line callback patch in the native_exception_protect() method in the sikulix.rb file, like this:
            m.bind(self).call(*args) # previous existing line
            SikuliX4Ruby.post_region_callback(m) if SikuliX4Ruby.respond_to?(:post_region_callback) # line added

2. Redirected the java logs to a temp file first, by defining and calling the following:
module SikuliLib
   def self.log_file=(log_file)
    @@log_file = log_file
    Debug.setLogFile(log_file)
end

3. Captured the original logoutput and logged it via myLogger as such:
module SikuliX4Ruby
  def self.post_region_callback(method = nil, obj =nil)
    file = SikuliLib.log_file
    File.readlines(file).each { |line| myLogger.info(line.chomp) } if File.size?(file)
    FileUtils.rm file
  end
end

My workaround does the trick for now, but I'm not happy about the fact that I had to copy and patch the sikulix.rb file.
I would rather not muck with original SikuliX distribution files and use a callback that is officially supported, if there is one (The previous question thread hinted that there might be one already.)

[RaiMan (raimund-hocke)]

this is my idea about how to implement this:

you have some logger instance (e.g. myLogger), which in turn has some methods like .info, .error, .warning, ...., that accept a string as the one and only parameter.

now you can tell Debug to redirect to your logger using one of these methods:

Debug.setLoggerInfo(myLogger, "info");
Debug.setLoggerAction(myLogger, "whatever");
Debug.setLoggerError(myLogger, "whatever");
Debug.setLoggerDebug(myLogger, "whatever");

according to the message groups Settings.ActionLogs ( [log] ), Settings.InfoLogs( [info] ), Settings.DebugLogs ( [debug] )
additionally we have the error group ( [error] )

From now on messages created using Debug.info() would be redirected to myLogger.info(original_message) using reflection (the reason for the string parameter, to avoid the Java interface/callback implementation overhead).

question: should the prefix [.....] be contained in the message or would this be more flexible:
Debug.setLogger(myLogger)
Debug.setLoggerInfo("info", "new prefix");
Debug.setLoggerAction("whatever", "new prefix");
Debug.setLoggerError( "whatever", "new prefix");
Debug.setLoggerDebug("whatever", "new prefix");

additionally this could be convenient:
Debug.setLoggerAll(myLogger, "whatever", "new prefix");

which would return a message
[new prefix log/info/debug/error] message

[Lev (levent-atasoy)]

I think either of these approaches would work great.
Regarding the prefix question... being able to control the prefix would also be a nice feature.
In the case of my logger, it already prints its own prefix based on which method is called.
Since your proposal is redirecting Debug.setlogger[Info,Error,etc] individually into a corresponding Mylogger.[info,error,etc.],
it would be good also to have the option to turn off the prefix, maybe along the lines of passing False, or "" as the "new prefix"

[RaiMan (raimund-hocke)]

If you like to test: I have implemented a basic implementation (usage see javadocs).

you might download sikulixapi.jar or setup from
nightly.sikuli.de

the upload will be ready in about 4 hours. (3 am european time)

the github repo is uptodate already now.

the additional options I will implement tomorrow.

[RaiMan (raimund-hocke)]

sorry, but nightly upload did not work. have to check and fix. look later for a version stamped August 1st

[Lev (levent-atasoy)]

I see the newly added methods in http://nightly.sikuli.de/docs/index.html

I am not sure where to find the nightly download of the corresponding jar though.
I can't seem to find anything new in https://launchpad.net/sikuli/+download or other links.

By the way, I downloaded sikulix-1.1.0.1.gem thinking maybe it had something new (earlier I was using the lib/sikulix.rb that was created by the setup jar) and noticed that it is not compatible with the sikulxapi.jar because the sikulix.rb in there has
  java_import org.sikuli.basics.SikuliX
instead of
  java_import org.sikuli.basics.Sikulix

[RaiMan (raimund-hocke)]

start here:
http://sikulix.com

button <nightly builds>

there you find everything.

the current gem:
https://rubygems.org/gems/sikulix

[Lev (levent-atasoy)]

OK. I did not realize the beta release was the one being updated nightly.

I tried it with the updated jar. It could not get it to work.
Below is the code I added (I also tried strings 'info' instead of symbols :info):
$log.info $log.methods.include?(:info)
Debug.setLoggerNoPrefix($log)
Debug.setLoggerInfo(:info)
Debug.setLoggerDebug(:debug)
Debug.setLoggerAction(:info)
Debug.setLoggerError(:error)

When I run this, I get the following:

INFO 14-08-02 15:26:22 TrueClass: true
[error] Debug: setLoggerInfo: redirecting to info failed:
org.jruby.RubyObject.info(java.lang.String)
[log] CLICK on L(27,10)@S(0)[0,0 1440x900]
[log] CLICK on L(306,707)@S(0)[0,0 1440x900]

I also tried the following, but get the same results:
  Debug.setLogger($log)
  Debug.setLoggerAll('info')

On the gem front, something is really strange. I cleaned up and reinstalled the gem repeatedly, but the newly installed gem always has the capital 'SikuliX', even the the source on the rubygems.org displays 'Sikulix'.
I manually downloaded and installed the gem with the same result.
The source and downloaded gem both have version 1.1.01.
Is it possible that the source code was updated without updating the gem version and the updated source not pushed to the repository properly?

[RaiMan (raimund-hocke)]

-- the gem:
now only available on rubygems.org the version 1.1.0.2 should work.
https://rubygems.org/gems/sikulix

-- the logger redirect:
only to be clear:
$log must contain a logger instance, that contains as instance methods with the subsequently issued names.
the methods MUST have only one possible string parameter.

this was my functional test in Java, that worked.

public class APITest {

 @Test
 public void addingPrivateLogger() {
  Debug.test("addingPrivateLogger");
  Debug.info("this should be visible as info message");
  Debug.action("this should be visible as action log message");
  Debug.log("this should be visible as debug message");
  Debug.error("this should be visible as error message");
  boolean success = true;
  Debug.setLogger(new APITest());
  success &= Debug.setLoggerAll("info");
  Assert.assertTrue(success);
 }

 @Test
 public void usingPrivateLoggerInfo() {
  Debug.test("usingPrivateLogger");
  Debug.info("test message info");
  Debug.action("test message action log");
  Debug.error("test message error");
  Assert.assertTrue(true);
 }

 public void info(String msg) {
  System.out.println("[TEST] myLogger.info: " + msg);
 }
}

Might be, that you have to cast the given method name string to a java language string.

I think as a first step, you should make sure, that it works on the java level in your environment and then step up to JRuby.

[Lev (levent-atasoy)]

I tried your java code in Eclipse using Java/Junit. It works as you indicated.

Then I also tried it using Pydev with Jython in eclipse using the following code:
---
class MyLogger:
    def info(self,msg):
        print "MyLogger: " + msg
log = MyLogger()

log.info('Directly from the new logger')
Debug.info('from original logger')

Debug.setLogger(log)
Debug.setLoggerAll('info')
Debug.info('From redirected logger ')
---

It resulted in an error similar to the JRuby case:
---
MyLogger: Directly from the new logger
[info] from original logger
[error] Debug: setLoggerInfo: redirecting to info failed:
org.python.core.PyInstance.info(java.lang.String)
[info] From redirected logger
---

I do not have enough experience to cross-debug a Jython application though
They pydev debugger just steps through the above w/o going into it.

[RaiMan (raimund-hocke)]

Will check that tomorrow.

I guess, that this is the problem at least with Jython, that methods in Jython cannot be used directly as callbacks.
I guess the problem is similar for JRuby.

So this simple solution currently only works on the Java level.
Hope, I find a simple solution.

[RaiMan (raimund-hocke)]

I implemented a solution, that supports logging redirect in Jython scripting. JRuby not yet ready.
Should be available with the next nightly.

[RaiMan (raimund-hocke)]

was in a hurry last night.

It principally works, but every redirected log call returns an error and the log is repeated in the normal way.

I have fixed it and and some other quirks and will upload later today.