Debugging and Diagnostics

From Zymonic
Jump to navigation Jump to search

Before completing almost any project, you'll usually have a bug or ten in your system. That's where debugging comes in handy, however it's not a miracle worker; you have to have an idea where in general the issue may lie, or you'll be scrawling through a 130,000 line long debug log with no idea what you're looking for (yes, I speak with experience on this point). The best way to debug is to create theories in your head, and prove/disprove them as you go (you may dynamically create more theories or merge them as you go through the debugs and collate more information surrounding the problem).

Using Diagnostics Tools[edit]

Introduction[edit]

Before starting to play with the actual debugger and other fun toys, you may want to read this section about actually getting the data you need to diagnose issues. This section goes into detail about using Firefox Developer edition, amongst other seemingly obvious and menial tasks.

Firefox Developer Edition[edit]

Without a doubt, this is one of the most useful browsers created for development. This section will go into detail on how to use the inbuilt tools and functions for diagnosing and resolving issues (it may even mean you can avoid debugging at all!). For the purposes of this, we're going to assume you know most of the basic functions of Firefox Developer.

Using Network
In the devlopment tools, there is a curious tool called 'Network' that we can use to see what data is transferred. First and foremost, it can be most useful for getting the filename and path of the most recent debug. This can be achieved by going into the response of the XML that has been transferred and going right to the end of the document, where it written like:

<session_errors>Debugs being written to : /tmp/dafz28231aafq53tc0odmmab9uzsb2.1535011074.64373.hfnexrcqiu.log</session_errors>

This file can be used to either interactively debug or go through the debugs manually, which is explained later. However, most importantly this feature can be used to debug solo filters; by refreshing the filter and not the page you can get a much more concise, accurate debug. This is the only way to get that type of debug - the other method explained later only works for a whole page.

Using Console
Console is pretty self-explanatory - it throws up errors and warnings. If a program dies before it outputs what it is meant to, the last error usually is the root cause of the issue, hence it helps to narrow down your search criteria.

Debugging XML stored in JS variables
The inspector by default shows XML in a var as an XMLDocument object - which is next to impossible to use with large documents. To copy it into a text editor as XML requires the following e.g. for this.filterXML.

var s = new XMLSerializer();
str= s.serializeToString(this.filterXML);
copy(str)

Then paste into a document.

Using Inspector
Another extremely useful (and hopefully familiar) tool is Inspector, in which you can get the ZName of most objects on the page to assist in theorising and debugging. It is coded in HTML, and provides the basic necessities for a lot of diagnostical issues: for example, you may be getting the definition of an object but no results appear - you can use the Inspector to get the ZName and get_def using zymonic_toolkit.pl to see if the data you are trying to pull actually exists in the first place.

Using the Web-Based Debug Viewer
On a system with the ZymonicDebugs module installed you can type into the URL bar:

http://[server]/zymonicdebugs?branch=[trunk|qa|live|mgt-live]&zymonic_rev=[zymonic rev]&zcps_rev=[zcps rev]&file=[the filename of the debugs without the path or .log extension]

Terminal[edit]

The Linux terminal is Linux's answer to Window's command prompt. Mixed with Zymonic, it becomes a whole lot better - specific tools are included within Zymonic to help with debugging and diagnosis. Click here for more information on Zymonic terminal-based commands; this section will be purely focused on useful Linux commands.

Vim
As your friendly neighbourhood command line text editor, vim can be launched as read-only or editable - to edit in vim you would usually use sudo. This section briefly explains certain functions which are used regularly in vim, the following commands launch vim read-only and editable (respectively):

vi FILENAME
sudo vi FILENAME

The following is a list of common commands and what they do (for usage, use google - the information is out there, easily available):

  • G - skips to the end of the document
  • / - searches the document for a text pattern
  • i - Allows editing of the document
  • esc - Stops editing of the document to allow other commands to be used
  • :w! - forcibly writes the documents to memory
  • :q! - forcibly quits the editor, wiping all unsaved changes
  • gg - goes to the start of the document
  • dd - delete line
  • :x! - forcibly save and quit

pscp
Whilst not strictly Linux terminal, pscp comes with PuTTY and is used to transfer files between a remote computer and your own. It is used in command prompt, and usage is as follows:

pscp username@remote_ip_or_computer_name:/file/location/filename ~\Downloads\FILENAME.extension

It's that simple, obviously you substitute my fake details for real information.

Module Loading
Using perls in built functions, we can test to see if a module loads by running the following command (replace the non-existent modules though):

perl -e 'use Zymonic::Module::MaybeAnother;'

GUI Based Debug Analysis (Performance)[edit]

This allows you to view what methods etc are taking up the most processing time, and thereby narrow down issues with performance in Zymonic.

Setting up the server[edit]

You will need dynaload installed into [webroot]/dynaload. If there are errors with that they will show in the console, you can then find the exact file path if it is not installed correctly. This should be done through svn in the future.

Install the zymonic debug manifest:

sudo zymonic_toolkit.pl Installer install --manifests debugs --apacheconf /etc/apache2/httpd.conf

You will also need to install the cpan module DBD::SQLite.

Run the task from the GUI with debugs enabled[edit]

Add &ZZdebug=true to the address (or click enable debugs from the user / developer menu of Zymonic)

Then perform the task to be investigated.

This will then create a debug log in the default debug directory (usually /tmp)

On a busy system use the network tab to check which debug file.

Convert the debug log to a DB file[edit]

Use zymonic_toolkit.pl Debugs convert_to_sqlite e.g.

 [Mon Dec 17 13:02:40] alex@alex ~ $ zymonic_toolkit.pl Debugs convert_to_sqlite --inputfile /tmp/7edd1xlhuwaf8mdqrtemg6f0ndk0q7.1545051649.7295.hawfdcqptx.log --outputfile userlist2 --branch trunk --zymonicversion 36094 --zcpsversion 2000 --system customer_main
 Opened SQLite file : /tmp/userlist2.sdf
 Added 10172 nodes to the SQLite file
 Method convert_to_sqlite completed.

(Note that you can't use underscores (_) in the outputfile name, only letters and numbers)

You may also need to copy the created file to [webroot]/zymonicdebugs

View the UI[edit]

https://[server]/zymonicdebugs/?file=[filename]

Bear in mind you should *not* put the file extension in the web address.

Debugging with the Interactive Debugger[edit]

Introduction[edit]

Whilst creating code, you may find that you cannot diagnose an error in the potential 6000 lines it could be in - that's where debugging comes in! Zymonic can make use of Perl's inbuilt debugger to go through code, line by line, to diagnose errors (for more information on using the Perl debugger visit the Perl docs website).

The sections below explain how to access the debugger in perl.

Debug the Config Build[edit]

If you have changed part of the config build and it results in an error/outputs unexpected results, you may want to try the following (replace 'test_system' with your system):

sudo perl -d `which zymonic_toolkit.pl` System config_build --system test_system

From here, you will be presented with a command line - use perl debugger commands to get to the correct area of code (example below) and test your variables to see where the error might be coming from.

DB<1> use Zymonic::SystemDefinition
DB<2> c Zymonic::SystemDefinition::some_random_function

You can then either use 'c' or 'n' to navigate through the code, searching for the problematic area. Don't forget, in the Perl debugger you can assign temporary variables, view a variable's definition, change existing variables in the code and actually look what the output of a command would be (examples all below, respectively). Line DB<7> would have an extremely long output, hence we won't view that on here.

5652:       my $self = shift;

DB<3> c 5704
Zymonic::SystemDefinition::some_random_function(/usr/local/lib64/perl5/5.24.3/Zymonic/SystemDefinition.pm:60000):
5704:       foreach my $test ( keys %{$hash_ref} )
5705:       {

DB<4> n
5706:           my $hash_ref_2 = $self->get_def( 'Object_Type', $test, 'no_error' );

DB<4> $tempvar = 'Zymonic is the greatest'

DB<5> x $tempvar
0  'Zymonic is the greatest'

DB<6> $test = 'This has now changed'

DB<7> x $self->get_def( 'Object_Type', $test, 'no_error' )

Using this method, we can achieve a step-by-step analysis of the code for the config build.

Debug in Runtime[edit]

There are, of course, times where you cannot debug in the config build, and the error is in the runtime code. This is more complicated to debug, but still possible. A diagram is below to help with finding GUI objects.

  1. You must enable debugs in the UI
  2. Once you have done that, you will have a message button appear. Hover over it, and carefully highlight the filename that comes up and copy it
  3. Now, you will want to run the following command, inserting the filename you copied where FILENAME is.
    grep DEBUG [FILENAME] | perl -pe 'use HTML::Entities; decode_entities($_);' >~/grepoutput.log
    
  4. Cat the file grepped to.
    cat grepoutput.log
    

    There will be a very long string of text after "PERL DEBUGGER COMMAND: "
    Copy all of it, and paste it into the command line. It should begin "REMOTE_ADDR="

  5. It will then begin loading the debugger; use the same commands as you did with the config build debugger to diagnose issues. There is another way to easily get the debug filename, see Using Firefox Developer Tools for more details


Debug GUI.jpg

Finding the 'Enable Debugs' option and message button in the GUI















Debugging without the Interactive Debugger[edit]

Introduction[edit]

Sometimes it's not appropriate to use Perl's inbuilt debugger to diagnose issues - for example, when you are working on a live copy of the code and have no access to the systems, only the debug logs. Fortunately, Zymonic debug logs are able to support you.

Adding a Working Copy Debug[edit]

This is generally used to debug code that you have already - you can add a debug line in the code for maximum error reporting, so you know exactly what area in the code the error is, and which object is being currently used (it depends on how you set it up).

  1. Locate the working copy - check with your sysadmin.
  2. Change directory to the correct 'module' containing folder
  3. Using the following command, open the module you want in vim (or your preferred editor):
    sudo vi FILENAME
    
  4. Add the debug - for more information, see the below section titled 'Adding a Debug to your Code'
  5. Run the following command:
    sudo make install
    
  6. To view the difference or to create a patch to send (respectively):
    sudo svn diff FILENAME
    sudo svn diff FILENAME ~/mypatch.patch
    

    You may wish to make a more meaningful patch name to send to someone.

  7. To remove the debug:
    sudo svn revert FILENAME ; sudo make install
    
  8. Depending on the change you may need to do an apache reload:
    sudo /etc/init.d/apache2 reload
    

Adding a Debug to your Code To add a debug to give more detailed debug log files, just enter the following second line in your code (where you want to get the debug data, it's not going to magically know where you want it):

my $yourvariablehere = "Success";
debug( "The Current State is: " . $yourvariablehere);

This debug would output a line saying: "The Current State is: Success"
The potential advantages are high, for example if one item in a foreach loop were failing, you could identify it and resolve the issue.

Debugging using the Debug Logs[edit]

Sometimes, you have access to the debug logs alone - you can still find errors in there using debug commands within the code and searching through the code to find the correct areas.

Debugging Saxon XSLT
The easiest way to debug a Saxon XSLT transformation is: Run the transformation in the GUI (like you usually would) with debugs enabled. Grep the debugs for the xsl

grep xsl /tmp/i6l0ocp74ekdbwr1y2hdt1c2ag7fhh.155177*

/tmp/i6l0ocp74ekdbwr1y2hdt1c2ag7fhh.1551778032.94094.wwzoifzbpo.log:Saxon Servlet XSLT URL: http://test_server_gal.zymonic.com:8080/xslt/SaxonServlet?source=m/test_server/xml/6728_1551778062_ivygudshpn_full_report.xml&style=m/test_server/xsl//test_report.xsl

Tried the transform manually on test_server

[Thu Mar 14 08:27:28] test_user@test_server ~ $ saxon /devshared/tomcat/m/test_server/xml/6728_1551778062_ivygudshpn_full_report.xml /devshared/tomcat/m/test_server/xsl/test_report.xsl

...
     <tr class="odd_row">
            <td>03/07/2018 09:39:06</td>
            <td>test Branch</td>
            <td>test Safe</td>
            <td>615</td>
            <td>SELL<Validation error on line 281 of test_report.xsl:
  FORG0001: Cannot convert string "" to a double
  at xsl:call-template name="items" (file:/devshared/tomcat/m/test_server/xsl/test_report.xsl#168)
  at xsl:call-template name="branch_report" (file:/devshared/tomcat/m/test_server/xsl/test_report.xsl#110)
  in built-in template rule
Transformation failed: Run-time errors were reported

You can then use this to change code and compare output, without having to rerun reports or other actions consistently. Debugging SQL errors
This section will allow you to find the exact command QueryBuilder creates for you, this will help you see if your changes have took effect, or precisely what your changes have done to the SQL.

  1. Refresh results with debugs enabled and Network tab of developer console open - in the response find the session_errors line:
    <session_errors>Debugs being written to : /tmp/dafz28231aafq53tc0odmmab9uzsb2.1535011074.64373.hfnexrcqiu.log</session_errors>
    
  2. Next we need to find the 'main' SQL query; to do this we need the SQL name of the base table:
    • Find the id (ident) of the filter using inspect element - will be the first part of all the ids within the block:
    • > 4409_test_filter_
      > BlockID: 4409
      > Filter ZName: test_filter
    • Now you need to get the definition of the filter to find the BaseTable:
      zymonic_toolkit.pl Definition get_def --definition test_system --zname test_filter >~/output.xml
      vi ~/output.xml
      

      The BaseTable element will look something like (you want the ZName contents):

      <BaseTable>
        <ZName>test_table</ZName>
      </BaseTable>
      
    • Now you will want to get the definition of the BaseTable ZName to find the SQLName of the table:
      zymonic_toolkit.pl Definition get_def --definition test_system --zname test_table >~output.xml              
      vi ~/output.xml
      

      The SQLName element will look something like:

      <SQLName>test_sqlname</SQLName>
      
    • Now we can grep for the SQL section of the debugs, however the entities will be encoded, so you will want to run:
      grep "FROM test_sqlname" /tmp/dafz28231aafq53tc0odmmab9uzsb2.1535011074.64373.hfnexrcqiu.log | perl -pe 'use HTML::Entities; decode_entities($_);'
      
    • With these results, you want the full SQL command (it will usually be very long). You can then see if changes you made took effect (you can also copy the command into an SQL query to test the data that comes up).

Debugging Perl errors
You may also want to debug Perl issues from a debug - not an issue.

  1. Refresh results with debugs enabled and Network tab of developer console open - in the response find the session_errors line:
    <session_errors>Debugs being written to : /tmp/dafz28231aafq53tc0odmmab9uzsb2.1535011074.64373.hfnexrcqiu.log</session_errors>
    
  2. From the command line, type in the following command to open the debug logs - use vim's in built commands to search through to find what you need.
    vi /tmp/dafz28231aafq53tc0odmmab9uzsb2.1535011074.64373.hfnexrcqiu.log
    
  3. You can also add extra data into your debug by setting up working copy debugs in your code (see above); this will allow you to collect extra information to resolve issues faster and with more accuracy.


grep
The grep tool can also be used to grab information from a debug log. The following are some useful ones:

  • List of SQL queries sorted by execution time (assuming debug done with debug_sql set in SystemOptions.xml)
grep "FULL" DEBUG_FILE | awk -F"\t" '{print $3, $2}' | sort -n | less -S
  • Count of all objects loaded:
grep "Loaded Zymonic::" DEBUG_FILE | awk -F"\t" '{print $2}' | awk -F" " '{print $2}' | sort | uniq -c
  • Count of all of a specific object loaded by zname (Change Zymonic::Filter to the required object)
grep "Loaded Zymonic::Filter " DEBUG_FILE | awk -F"\t" '{print $2}' | awk -F" " '{print $3}' | sort | uniq -c

Error Logs[edit]

When you have an error come up in a Zymonic system, the error can be viewed in more detail from the error logs. An easy way to find the correct one is to view the most recent doing the below command in the terminal:

view `ls -1tr /var/errors/*.xml | tail -n1`

The top error is the most recent and will give you a description of the error along with a line number. Below this will be a list of all the functions in the caller stack. You may be able to save time debugging at this point by simply looking at the code with the error message in mind, to spot simple mistakes.

A point to note, this trick can be used in /tmp/...log by doing:

view `ls -1tr /tmp/*.log | tail -n1`

Tracking down missing Zymonic Pages / Menu items[edit]

In a situation where you expect to be able to see a certain Zymonic object (Filter, Process, Page) in a system but don't, it is very likely a permissions issue. Try these steps in tracking them down:

1. Check your user has a role permission set up to be able to access the object permissions.

2. Run the check_permissions command for the sec_id of the missing object Check Permissions.

3. Check if the missing menu item is in zz_fap:

select * from zz_fap where zname = '[name of filter or process]'\G

or that the page is in zz_pages in the same way.

4. Using the sec_id from 3, check the security table (zz_[table]_rs) or zz_record_security for 'old security mode' tables:

select * from zz_zz_fap_rs where sec_id = '[sec_id]'

5. Check the entry in zz_security_ids for the sec_id in question:

select * from zz_security_ids where uniq_sec_id = '[numeric part of sec_id]'

If the 'unique_targets' is empty then it means that none of the relationship permissions from the table underlying the filter or process returns any valid 'targets' for the filter or process being secured. The implications of this are either:

a) there is no base table for the filter / process (and the filter/process itself will need relationship permissions).

b) there are no relationship permissions on the base table for the process / filter (and thus they need adding).

c) Or the only relationship permissions on the base table for the process / filter are locked-down by a FAP list and the process/filter in question isn't on that FAP list.

6. Double check the role permission exists in role_permissions, for the role you expect:

select * from zz_role_permissions where role = '[role]' and role_permission = '[rolepermission]'

7. Generate debugs for the action, for example a page refresh or refreshing the menu filter. And track down the sql generated, with this you should be able to narrow down why it's not appearing.


When you have the problem[edit]

Possible solutions, depending on the problem are: -resecure tables

sudo zymonic_toolkit.pl Security resecure --system [system] --zname '*'

-update_fap

sudo zymonic_toolkit.pl System update_fap --system ztsm --full yes

-change security modes Click here

Javascript Debugging[edit]

Error reported in 'html' but debugger shows XML[edit]

Because the page source is actually an XML document clicking on the console error's line number where the error is in the HTML (resulting from transforming the XML) will, in most browsers at the time of writing, show the XML and not the correct line of HTML.

To workaround this the best option is to 'save page as' and save the complete page and then reload the saved page in a new tab; this should then give you the correct line.

Slow Queries and identifying issues with SQL[edit]

If a performance issue is tracked down to the time taken to run an SQL query then the best way forward is to use explain to determine if indices are being used as expected.

Explain output key things to look for:

1) key field being NULL - suggests a table join is being done without a key - this is very time consuming.

2) using temporary; using filesort - these will be creating a temporary table and depending on the configuration of the server these can be created on disk and take some time to create.

If you need to look at the query itself then it is worth using a reformatter e.g. http://www.dpriver.com/pp/sqlformat.htm

Field not found / Unable to find field[edit]

These system errors occur when a field lookup within zymonic fails for some reason. The most common case of this will be during development when a field is referenced (e.g. in a field fill, or in an action) which is not on the main form nor the underlying table (for a process), or is a not a report/search field (for a filter)

An example of such an error might be:

   <ErrorMessage>Unable to find field field_zname</ErrorMessage>
   <call_function></call_function>
   <catchable></catchable>
   <catchable_message></catchable_message>
   <category></category>
   <description>Unable to find field field_zname</description>
   <email></email>
   <error_code></error_code>
   <error_type>Zymonic::Exception::FieldLookup</error_type>
   <extras></extras>
   <field_zname></field_zname>
   <generate_error_log></generate_error_log>
   <hkey>
     <parent>
       <ident>_ztsm_scanner_fetch_files_autoprocess__ztsm_stocktake_scanned_file_stocktake_count_update_zz_table_ztsm_stocktake_itemsztsm_stocktake_scanned_file_stocktake_count_update_dest_tableztsm_stocktake_items</ident>
       <type>Zymonic::Table</type>
       <zname>ztsm_stocktake_items</zname>
     </parent>
     <parent_ident>_ztsm_scanner_fetch_files_autoprocess__ztsm_stocktake_scanned_file_stocktake_count_update_zz_table_ztsm_stocktake_itemsztsm_stocktake_scanned_file_stocktake_count_update_dest_tableztsm_stocktake_items</parent_ident>
     <record>
       <ZZid>
         <id>2434</id>
       </ZZid>
       <ident>_ztsm_scanner_fetch_files_autoprocess__ztsm_stocktake_scanned_file_stocktake_count_update50525152_</ident>
     </record>
     <zname></zname>
   </hkey>
   <info_msg></info_msg>
   <no_catch_filter_action></no_catch_filter_action>
   <no_catch_transition></no_catch_transition>
   <parent_zname>NOPARENT</parent_zname>
   <zname>ztsm_stocktake_items</zname>

The important parts to look at here are:

zname

   <zname>ztsm_stocktake_items</zname>

This tells you the object the lookup was done from, so gives you context of where to start looking for the problem.

hkey -> parent

     <parent>
       <ident>_ztsm_scanner_fetch_files_autoprocess__ztsm_stocktake_scanned_file_stocktake_count_update_zz_table_ztsm_stocktake_itemsztsm_stocktake_scanned_file_stocktake_count_update_dest_tableztsm_stocktake_items</ident>
       <type>Zymonic::Table</type>
       <zname>ztsm_stocktake_items</zname>
     </parent>

This tells you the contextual parent the lookup was done on, i.e. the object we checked for the field on. Generally it will be either a Table or a Filter. This can differ from zname, for example, if an Action hits this error, the zname will be the Action zname, however the parent will tell you which Table within that Action the lookup is being done on. This can usually then point you in the right direction to spot the missing field.

hkey -> record

     <record>
       <ZZid>
         <id>2434</id>
       </ZZid>
       <ident>_ztsm_scanner_fetch_files_autoprocess__ztsm_stocktake_scanned_file_stocktake_count_update50525152_</ident>
     </record>    

This is the specific record in the hkey parent that the field is being looked up from. Generally this is not as useful, as fields should be the same across all records, however its ident can be useful, as you can search through the rest of the log, or debugs, to see which fields are commonly looked up for that record. Specific debug message for this is: Field Factory got field refs using: [parent_ident] - [record ident] [field znames]

call stack

   <zymocallers>
     <file>/usr/local/lib64/perl5/5.30.3/Zymonic/Table.pm</file>
     <line>6070</line>
     <package>Zymonic::Table</package>
   </zymocallers>

This lets you trace back through the function calls to figure out where it is that the field lookup is done from, if only to assert that it is what you expect.