test-log-debug.txt

# Testing and Logging, and Debugging 

## Testing

### Adding Unit Tests

When you [generate a model](generator#add-new-model), you will now get an _spec.rb file generated along with your controller.

	Generating with model generator:
	....
	[ADDED]  app/Person/person_spec.rb

This file contains tests for your controller and is in the mspec format: [rubyspec.org](http://rubyspec.org/) 

	:::ruby
	describe "Person" do
	  #this test always fails, you really should have tests!

	  it "should have tests" do
	    true.should == false
	  end
	end

We use this test format internally as well. You can see our specs for the core framework [here](http://github.com/rhomobile/rhodes/tree/1.4.0/spec/framework_spec/app/spec/) which use many functions of mspec.

To run these tests however, you need the testing framework to be included in your app. To add this, you would run the rhogen task in your application folder:

	:::term
	$ rhogen spec

You will then see the mspec framework added to your application:

	Generating with spec generator:
	     [ADDED]  app/SpecRunner
	     [ADDED]  app/spec
	     [ADDED]  app/mspec.rb
	     [ADDED]  app/spec_runner.rb

Finally, add the fileutils and mspec extensions to your build.yml:
	
	extensions: ["fileutils", "mspec"]

You are now ready to run the tests. Simply add a link to the SpecRunner controller, and you will get a summary of number of passing/failing tests

In your index.erb:
	:::html
	<li><a href="SpecRunner">Run tests</a></li>

A summary of the results will be displayed on the screen.

Detailed results will be displayed in your rholog.txt:

	I 01/15/2010 16:36:33 b0185000                  APP| FAIL: Product - Expected true
	 to equal false

	apps/app/mspec/expectations/expectations.rb:15:in `fail_with'
	apps/app/mspec/matchers/base.rb:8:in `=='
	apps/app/Product/product_spec.rb:5:in `block (2 levels) in <main>'
	...

And finally, a summary will be printed in rholog.txt as well:

	I 01/15/2010 16:36:33 b0185000                  APP| ***Total:  3
	I 01/15/2010 16:36:33 b0185000                  APP| ***Passed: 1
	I 01/15/2010 16:36:33 b0185000                  APP| ***Failed: 2

### Disabling tests
When you are ready to do a production build of your application, change build.yml's build property to 'release' and the specs will not be included in the binary:

	...
	vendor: Acme, Inc.
	build: release
	...

## Logging
There are two methods to log messages. 

From any controller you can log using the methods app_info and app_error. These methods take a string and will write that to rholog.txt with the category of your controllers name. See platform specific [build topic](build) to see notes on how to get rholog.txt.

Call app_info and app_error from a method in your controller:

	:::ruby
	def index
		app_info "My info message"
		app_error "My error message"
	end

There also is a logging Ruby class called RhoLog. This class has methods info and error which take 2 strings. The first string is the category, the second string is the message.

Call the RhoLog error or info methods from a method in your Rhodes app:

	:::ruby
	def index
		RhoLog.error("Some Category", "Some error message")
		RhoLog.info("Some Category", "Some info message")
	end

Additionally all common ruby output routines (like puts, print) are redirected to rhodes log with INFO level.

In rholog.txt the lines appear as follows:

	<Timestamp> <category> | <message>

To enable remote logging just add the line to `rhoconfig.txt`:

	rhologurl = 'http://<host>:<port>[/path]'

Then all log messages will be sent to the specified URL via POST HTTP-requests.

You can also send log to remote server manually. To do this add following lines to rholog.txt:

	logserver = 'http://<host>:<port>[/path]'
	logname = '<log_name>'

Then call RhoConfig.send_log:

	:::ruby
	def index
		Rho::RhoConfig.send_log()
	end

### RhoError class

You may find access to the error class useful in logging and reporting:

This class contains error codes and the method message() to translate error code to a text message.
All callbacks return an error code from this class. The status text in the callback contains some internal error message, so in most cases it should not be exposed to user.
Currently RhoError contains the following error codes:

	ERR_NONE = 0
	ERR_NETWORK = 1
	ERR_REMOTESERVER = 2
	ERR_RUNTIME = 3
	ERR_UNEXPECTEDSERVERRESPONSE = 4
	ERR_DIFFDOMAINSINSYNCSRC = 5
	ERR_NOSERVERRESPONSE = 6
	ERR_CLIENTISNOTLOGGEDIN = 7
	ERR_CUSTOMSYNCSERVER = 8
	ERR_UNATHORIZED = 9

### Sample
See [Login/Logout Manager]() as an example.

## Debugging

You can use the [RhoStudio debugger](/rhostudio.tutorial#using-the-debugger) to debug your Rhodes app. 


## Profiling

To perform performance measurements or found applications bottlenecks you can use RhoMobile Profiler tool.

RhoMobile Profiler use performance counters to calculate execution time of specific function/code. There are 2 types of counters: global and local:

* Global counters created once and can be stopped/started many times. When Global counter destroyed, it log accumulative time of all start/stop intervals.
* Local counters can be stopped/started only once. While stopped, counter will log time interval between start and stop.

### Profiler log.
When Counter stopped (Local counters) or destroyed(Global counters) information from counter will be logged in the following format:

(log prefix) PRFILER| (counter name)( (counter time) ): START/STOP

For example:

I 06/18/2012 23:27:20:311 00002ffc             PROFILER| BROWSER_PAGE (0:03:104) : STOP

### Enable Profiler.
Profiler is configurable at build time in build.yml file(Turned Off by default):

    profiler: 1

Will turn on Profiler

After Profiler ON/OFF - full rebuild is required.

### Built-in performance counters.

These counters start working after you turn on Profiler in build.yml:

* ERB_RENDER - ERB-file render (Ruby)
* CTRL_ACTION - Controller action (Ruby)
* INDEX_ACTION - Index page render
* ERB_RENDER - ERB-file render (Ruby)
* BROWSER_PAGE  - Browser page loading time (Native)
* SyncEngine components has several native counters:

    'Sync' - Full sync time
    
    'DB' - Time spend for database insert/update/delete while sync
    
    'Net' - Time spend for network communication while sync

These counters works only if you create them in application. You can create counter in controller action and destroy it after some operations:

* Sqlite database (Native)

    'SQLITE' - counter for whole time processing SQL query including data conversion , sqlite3_step and prepare statement
    
    'SQLITE_EXEC' - sqlite3_step time only. 

To Enable Ruby Garbage collector logging modify rhoconfig.txt(set log level to Trace):

    MinSeverity = 0

There are two Profiler API available: Ruby and Native(C/C++).

### RhoProfiler Ruby module.

RhoProfiler Ruby module will contain the following static methods:

* create_counter(name) # Create Global counter
* destroy_counter(name) #  Destroy Global counter
* start_counter(name) # Start Local or Global counter. If Global counter with this name exist , this global counter will started. If no global counter exists, local counter will be created and started.

* stop_counter(name) # Stop Global or local counter.
* flush_counter(name, message) # Log information from counter(Local or Global). Counter does not stopped or started.

* start_created_counter(name) # Counter will start only if it is already created previously(Global counter)

Example of custom counter:

	:::ruby
	def index
		RhoProfiler.create_counter('Counter1')

        RhoProfiler.start_counter('Counter1')
        function1()
        RhoProfiler.stop_counter('Counter1')

        #do something
        
        RhoProfiler.start_counter('Counter1')
        function2()
        RhoProfiler.stop_counter('Counter1')
                            		
		RhoProfiler.destroy_counter('Counter1') #Will log summary of function1 and function2 execution time
	end

Example using 'SQLITE' built-in counter:

	:::ruby
    def some_method

     RhoProfiler.create_counter('SQLITE')

     #do something: create/update objects for example

     RhoProfiler.destroy_counter('SQLITE')

    end
 
### RhoProfiler C/C++ API.
RhoProfiler C/C++ API contains several defines to manipulate Performance Counters.  Here is the list of defines:

    //Global accumulative counters
    #define PROF_CREATE_COUNTER(name)     // Create Global counter
    #define PROF_DESTROY_COUNTER(name)    // Destroy Global counter
    #define PROF_START(name) //Start Local or Global counter. If Global counter with this name exist , this global counter will started. If no global counter exists, local counter will be created and started.

    #define PROF_STOP(name) // Stop Global or local counter. 
    #define PROF_FLUSH_COUNTER(name,msg) //Log information from counter(Local or Global). Counter does not stopped or started. 
    #define PROF_START_CREATED(name) //Counter will start only if it is already created previously(Global counter)

Example:

	:::ruby
	#include "statistic/RhoProfiler.h"
	void testFunction()
	{
		PROF_CREATE_COUNTER("Counter1");

        PROF_START("Counter1");
        function1();
        PROF_STOP("Counter1");

        //do something
        
        PROF_START("Counter1")
        function2();
        PROF_STOP("Counter1")
                            		
		PROF_DESTROY_COUNTER("Counter1") #Will log summary of function1 and function2 execution time
	}