Analyze Error Logs

Testing a feature

Testing a feature modeled with WebRatio Platform is easy. In fact, you just need to generate the Web Project and navigate the resulting Web application to see whether the specific feature is working or not. It’s common to encounter issues during the development phase. Analyzing the "Application Logs" can be useful for identifying and correcting undesired behaviors

The Application Logs

The Web application generated by WebRatio Platform provides you with four "Application Logs", each one having a specific goal. The "Application Logs" provide information on the application execution that allows you to trace all the errors that occur during the execution of the Application. Each log provides different information:

• "RTX.log" traces the history of the View Components, pages and operations that were executed, along with the executed queries and runtime errors.
• "RTXError.log" traces all the runtime errors.
• "WRStruts.log" trace the execution of Pages and Components, the executed Flows and the Data Flows, along with the outcome of their execution.
• "WRStrutsError.log" logs the errors of the "Struts Framework".

All logged information contains a reference to the Web Model, thus providing an instrument for the Web application debug. Each log has a "Level" that states the relevance of the information to be logged. There are five different levels:

• "TRACE"
• "DEBUG"
• "INFO"
• "WARN"
• "ERROR"

By default, when you generate the Web application all logs level are set to error, but you can easily change them. Two configuration files contain the setting for the logging features: "RTXLogConfig.properties", which configures the "RTXError" and "RTX" Runtime Logs; and "StrutsLogConfig.properties", which configures the "Struts" and "StrutsError" logs. Both files have similar structures.

Structure of the "RTXLogConfig.properties" file

The "Log Configuration" uses the "log4j" Java Library. The configuration file is structured in two main sections. The first section contains the configuration of the log in terms of "path", "size" and "format". Usually, this section is not changed until the deployment. The second section contains the configuration about which information must be logged. You will change this in the development phase.

• log4j.appender.RTXErrorLogFile=org.apache.log4j.RollingFileAppender

  This line specifies that there’s a specific log defined using the "log4j RollingFileAppender" Class.

• log4j.appender.RTXErrorLogFile.File = ${logDirectory}${file.separator}RTXError.log

  This line specifies the file that is used to write the log content. The file is specified to also include the "path".The "path" is written using some variables. The "logDirectory" variable can be configured in the "RTXConfig.properties" file and can contain a relative path starting from the "webapp" folder or an absolute path. It depends on the "logDirectoryIsAbsolute" variable value contained within the same configuration file. The "file.separator" variable is a system property that cannot be changed and its value depends on the Operating System.

• log4j.appender.RTXErrorLogFile.MaxFileSize = 1MB

  This line specifies the "Maximum Size" of the log file. Once the size specified is exceeded, the log content is erased or a new log file is created. The choice among the two specified behaviors depends on the "MaxBackupIndex" property. This property is configured in a dedicated line in the configuration file.

• log4j.appender.RTXErrorLogFile.MaxBackupIndex=3

  This line specifies the "number" of log files to be stored in the folder. The Web application creates a new log file every time the maximum file size is reached. The standard value is "3", which means that you can have three backup files in addition to the current one. After reaching this limit, the oldest file is erased and substituted with a new one.

• log4j.appender.RTXErrorLogFile.layout.ConversionPattern =  %d{dd MM yyyy HH:mm:ss,SSS}  %p [%t]  (%c:%L) - %m%n 

  This line specifies which "pattern" to be used to write each line of the log. The pattern can be specified using the documentation provided by the "log4j" Library. See the official website for further details. The current pattern results in the following line.

• log4j.appender.RTXErrorLogFile.Append = true

  This line specifies whether or not each log line must be appended to the content of the log file. If this property is true, then each new message will be appended to the file without erasing it with each new message.

• log4j.appender.RTXErrorLogFile.Threshold = ERROR

  This line specifies the "Level" of the information considered by the log file. All log lines having a different level are not stored inside the current log file.

Log Configuration

You can assign a specific "Log Level" to each information type. Each item to be logged is associated with an actual level of relevance and with the file where it is stored.

• log4j.logger.org.hibernate.SQL=DEBUG, RTXLogFile, RTXErrorLogFile

  You can choose to see all the queries performed by "Hibernate" by setting the log level of "Hibernate" to "DEBUG".

• log4j.logger.org.quartz=DEBUG, RTXLogFile, RTXErrorLogFile

  If you want to see all the information about the "Quartz" table, set the log level of the "quartz" to "DEBUG".

• log4j.logger.com.webratio.rtx=DEBUG, RTXLogFile, RTXErrorLogFile

  You can choose to see all the information about the "WebRatio Runtime" framework setting the log level of the "rtx" to "DEBUG".

• log4j.logger.com.webratio.units=DEBUG, RTXLogFile, RTXErrorLogFile

  You can choose to see the all the information about the "WebRatio Units" setting the log level of the "units" to "DEBUG".

• log4j.logger.com.webratio.units.bpm=DEBUG, BPMLogFile

  If you want to see all the information about "Bpm", set the log of the "bpm" to "DEBUG".

How to Change the Log Level

Now that you know the structure of the configuration file, let's look at the procedure for changing the "Log Level".

Let's suppose we want to set all log levels to "DEBUG". Select the WebRatio Explorer View, right-click on a Web Project folder of your choice under "Web Projects", and select "WebRatio" and then the "Edit RTXLogConfig.properties" option. This opens the file content in a dedicated editor. Now you can edit the file, changing the "Log Levels" on the package you want to trace. For example, let's write "DEBUG" for all packages. Save the file.

To apply the changes, you need to restart the Web application. To do this, right-click again on the Web Project in the WebRatio Explorer View and select "WebRatio" and then the "Reload Web Application" option. This option restarts the Web application and applies the changes done to the log level.

How to Analyze Logs

Now that you know how to configure the log content, let’s see how to view the "Logs". WebRatio Platform provides you a dedicated view for this purpose.

How to See the Log Content

To open the "View", go to the main menu and select "Window", then "Show View", then "Other", expand the "WebRatio" folder and choose "Runtime Log".

The "Runtime Log View" is placed, by default, at the bottom of the WebRatio Platform interface. Zoom on the "View". On the top right of the "View" you have buttons that allows you to open up each one of the four "Application Logs" you have at your disposal.

WebRatio Platform supposes that the files are stored in the "webapp" Tomcat folder. If this is not true, you can always open a log file stored in another directory using the "Open Generic Log File" button. In addition, you can choose whether to see the log content as plain text or in a structured way using the "Structured presentation" button.

Structure of Log Line

Each line of the log has a specific structure. It's important to know the structure in order to be able to read the log and find the desired information. This is a sample "Log" line.

27 nov 2013 15:36:14,085  DEBUG [http-8080-1] (com.webratio.units.content.rtx.db.PowerIndexUnitService_$$_javassist_17:44) - [CC027A45369385C07E7BC737D3AE4DCC][page14][pwu9]Setting parameter: p0={true}

A line is composed of seven parts:

• The "Timestamp", which is the time when the logged instruction is written in the log.
• The "Log Level", which is the level to which the log line belongs.
• The "Host", which is the host sending the request. In other words, the IP address of the computer used by the Web application User to navigate the application.
• The "Java" class, which is the java class executed.
• The "Session ID", which is the User session id.
• The "Model" element, which is the model element executed.
• The "Message", which is the log message.

The same structured log is showed in the Runtime View, subdividing the information log into columns [see example]. These columns allow the user to sort the information as desired. For example, selecting to sort by "session ID" groups all the log information that is related to a specific user session.

When to read the logs

Logs are useful during application development and testing to find out the causes of undesired behaviors and to understand how to fix the problems. For example, when the Web application shows the "error page", the first thing to do is to check the content of the "RTXError.log" file, which contains - by default - the full stack trace of the exception raised by the Web application.

Some common errors

For a new WebRatio Platform user, some mistakes are common during application development. This is a list of the most common errors you can experience with a Web application. Select each error to learn how to solve it.

Expected at least one element

This is a sample content of the "RTXError.log" file.

27 nov 2013 16:10:01,441  ERROR [http-8080-5]  (com.webratio.units.content.rtx.db.DataUnitService:73) - [7ACDF032A3075543D4956480E0538FC2][page1]Error reading the descriptor com.webratio.rtx.RTXException: Expected at least one element .. inside 

This error means that there is a component in the "page1" of the model that is not properly configured. Problems like this one are very common if you are a new WebRatio Platform user. In most cases, to solve these kinds of problems, check the model correctness using the "Find Model Problems" option on the page raising the exception. If you run the check on the specified page, you get an error in the "Problems View" like this: "The entity for the component is unspecified".

If you always use the "Find Model Problems" option before generating the project, you can see immediately the model element that is causing the problem because the log reports its ID.

In this case, to solve the problem you must simply select the element, go to the Properties View and set the "Entity" that this element refers to, and then choose the Display Attributes. Press the "Select" button next to the "Entity" property. In the opening dialog choose the entity that this refers to and press the "OK" button to confirm. Now, let’s choose the display attributes of the "Component": click the "Select" button next to the "Display Attributes" property and choose the attributes. Click the "OK" button to confirm.

Missing home element for Site View

In this case it may not be necessary to look at the log content. The "Page" is saying that for the current "Site View" the "Home Page" is missing. Many situations can generate this error, but basically it means that you have to set an element of the "Site View" as "Home".

Also in this case the "Find Model Problem" option could save time since it would have signaled the problem before proceeding with the project generation. The log exception corresponding to this error is the following:

07 gen 2014 14:34:13,860  ERROR [http-8080-6]  (com.webratio.struts.exceptions.GenericExceptionHandler:73) - An error occurred executing action for 'null' com.webratio.rtx.RTXException: Missing home page for site view 'Public [sv4]'

This exception is reported on the "StrutsError.log" file since the error is related to the choice of the page to be shown to the user and not to an execution error about the page content.

Missing Default Element for Area

In this case it may not be necessary to look at the log content. The error is saying that for the current "Area" the "Default" element is missing. So you just have to check the model of the "Area" and set the "Default" property on the correct element. The log exception corresponding to this error is the following:

28 mag 2014 15:37:02,030  ERROR [http-bio-8080-exec-12] (com.webratio.struts.exceptions.GenericExceptionHandler:73) - An error occurred executing action for 'null' com.webratio.rtx.RTXException: Missing default element for area 'Employees [area5]'

This exception is reported on the "WRStrutsError.log" file since the error is related to the choice of the "Page" to be shown to the user and not to an execution error about the page content.

Missing database for entity

In this case it may not be necessary to look at the log content. The error is saying that for the specific "Entity", the "Database" reference is missing, which means that maybe you forgot to synchronize the Domain Model with the "Database".

In order to solve the problem what you have to do is to use the "Find Model Problem" option on the "Domain Model". The log exception corresponding to this error is the following:

Could not create service 'dau1' from class: class com.webratio.units.content.rtx.db.DataUnitService
com.webratio.rtx.RTXException: Error creating service: dau1 - WEB-INF/descr/dau1.descr
...
Caused by: com.webratio.rtx.RTXException: Unable to retrieve the Hibernate service for entity 'Customer[id:ent2]'
...
Caused by: org.hibernate.HibernateException: Missing database for entity 'Customer[id:ent2]'

Other kind of problem

In some cases you do not have a specific exception in the log but the Web application has an unexpected behavior.

Let’s suppose that you modeled a page to search for companies. The model looks like the shown image. When generating the "Page" it seems that the search doesn’t work, because the result list does not change depending to the filled-in fields.

For these kind of problems there can be many different causes and the "Find Model Problems" may not be helpful in this case.

In order to understand the problem in this specific case, the first thing to do is to change the "Log Level" to "DEBUG" and analyze the log information. After you change the log level, restart the Application and test the feature again. If you open the "RTX.log" file in the "Runtime Log View", you can notice that a lot of information is saved in the file. You have to search for the "Component" that is not behaving correctly. In this case, you have to search for the "List" Component in the log using its "ID". When the "Component" gets executed you will see logs fragments like the ones shown on screen.

Example Log 1

This line shows the "Hibernate Query" produced starting from the model you designed in the "Page" for the "List" Component.

...
07 gen 2014 15:57:22,068  DEBUG [http-8080-1]  (com.webratio.units.content.rtx.db.PowerIndexUnitService_$$_javassist_32:44) - [C8EBF06FA627D28A441F8FDCEADF4AB3][page4][pwu4]Query Text Expander: com.webratio.rtx.core.DynamicSortHelper$1@4c4947d3

07 gen 2014 15:57:22,069  DEBUG [http-8080-1]  (com.webratio.units.content.rtx.db.PowerIndexUnitService_$$_javassist_32:44) - [C8EBF06FA627D28A441F8FDCEADF4AB3][page4][pwu4]Expanded query: 
select a_company.oid, a_company.nationality, a_salesManager_role38.initials, a_company.VAT, a_company.name from Company a_company left join a_company.companyToSalesManager a_salesManager_role38
where (((upper(safe_cast(a_company.name)) like upper(safe_cast(:p0_0_))))) and ((1 = 1))order by a_company.name ,a_company.nationality
...

Example Log 2

This line shows that a specific "Parameter" is bound to a condition of the "List" Component. You can see the passed value - "%apple%" in this case - and also the parameter - "p0_0_" .

...
07 gen 2014 15:57:22,085  DEBUG [http-8080-1]  (com.webratio.units.content.rtx.db.PowerIndexUnitService_$$_javassist_32:44) - [C8EBF06FA627D28A441F8FDCEADF4AB3][page4][pwu4]Setting parameter: p0_0_=%apple%
...

To really understand the "Parameter", you can refer to the line above showing the "Hibernate Query" or to the line below showing the "SQL query".

Example Log 3

This line shows the "SQL query" executed on the "Database". The "query" is reported because the "Log Level" is set to "DEBUG" and because the "View Component" is associated with an "Entity" with the duration of “Persistent”.

...
07 gen 2014 15:57:22,100  DEBUG [http-8080-1]  (org.hibernate.SQL:111) - 
    select
        company0_."oid" as col_0_0_,
        company0_."nationality" as col_1_0_,
        salesmanag1_."initials" as col_2_0_,
        company0_."vat" as col_3_0_,
        company0_."name" as col_4_0_ 
    from
        public."company" company0_ 
    left outer join
        public."sales_manager" salesmanag1_ 
            on company0_."sales_manager_oid"=salesmanag1_."user_oid" 
    left outer join
        public."user" salesmanag1_1_ 
            on salesmanag1_."user_oid"=salesmanag1_1_."oid" 
    where
        (
            upper(company0_."name") like upper(?)
        ) 
        and 1=1 
    order by
        company0_."name",
        company0_.”nationality"

You can use this query on the "Database Management System" to see if there’s a problem with the "Application Engine", or the "query" is really wrong.

Example Log 4

This line shows how many results the "Component" has retrieved using the above-mentioned "query".

...
07 gen 2014 15:57:22,133  DEBUG [http-8080-1]  (com.webratio.units.content.rtx.db.PowerIndexUnitService_$$_javassist_32:44) - [C8EBF06FA627D28A441F8FDCEADF4AB3][page4][pwu4][trace][0:0:0:0:0:0:0:1,C8EBF06FA627D28A441F8FDCEADF4AB3] RESULT_COUNT:1 {oid=[1]}
...

Example Log 5

This line shows the "Execution Time" of the "Component". It can be useful to understand which element takes too much time to be computed in case of performances issues.

...
07 gen 2014 15:57:22,134  DEBUG [http-8080-1]  (com.webratio.rtx.hibernate.DBCPConnectionProvider:44) - [C8EBF06FA627D28A441F8FDCEADF4AB3][page4][pwu4]active: 0 (max: 15)   idle: 1(max: 8)

07 gen 2014 15:57:22,135  DEBUG [http-8080-1]  (com.webratio.rtx.core.DefaultPageService_$$_javassist_28:44) - [C8EBF06FA627D28A441F8FDCEADF4AB3][page4][pwu4](68 ms) Executing 
...

Another example

In this case you can compare the model of the "List" Component with the executed query. In the model you can see on the "List" Component there are two conditions: one on the "Company Name" and one on the "Company VAT".

...
07 gen 2014 15:57:22,100  DEBUG [http-8080-1]  
(org.hibernate.SQL:111) - 
    select
        company0_."oid" as col_0_0_,
        company0_."nationality" as col_1_0_,
        salesmanag1_."initials" as col_2_0_,
        company0_."vat" as col_3_0_,
        company0_."name" as col_4_0_ 
    from
        public."company" company0_ 
    left outer join
        public."sales_manager" salesmanag1_ 
            on company0_."sales_manager_oid"=salesmanag1_."user_oid" 
    left outer join
        public."user" salesmanag1_1_ 
            on salesmanag1_."user_oid"=salesmanag1_1_."oid" 
    where
        (
            upper(company0_."name") like upper(?)
        ) 
        and 1=1 
    order by
        company0_."name",
        company0_.”nationality"
...

Since in the log there’s no SQL where condition on the "VAT" column even if in the Web Page you fill in a value in the "Field", it means that the field value is not passed to the "List" Component. So, what you have to check in the model is the binding between the "Form" Component and the "List" Component on the "Navigation Flow". In this Page, select the "Flow", double-click on it and define the "Parameters Binding".