A different way to trace/debug without explicitly adding log messages.

Javier Arroyo · ‎10-07-2020

This post is about tracing an execution path when calling a function without having to explicitly add messages for the function being called, it's parameters or return value.

The trajectory path that the execution of a function takes through a code base can be very handy when debugging. As programmers, pieces of code be placed along that path to yield further information about the process. Data points like function names, inputs and out puts can become invaluable pieces of information when debugging.

While there is no doubt that those messages can be very helpful. The extra syntax quickly creates quite a lot of noise. In fact, it eventually bloats code, forcing readers to sift through unnecessary lines in search of the really important parts: what is code doing and how.

Like all else, the objective is to reduce code noise to reduce interpretations times. But, to get to that point requires a change in philosophy as to how code is, well, coded.

As we might have noticed, platform code isn't exactly welcoming to the eye. It is riddled with varying ideologies and styles that lead to all sorts of smelly code. Of worthy mention here are Long Methods, Long Parameter Lists, Multiple Responsibility Functions, non deterministic outputs, functions that don't return anything, anonymous functions and hardcoded gs.log sentences.

For example:

some_scope.Logger.get().debug("Some Sope Cart Js API - Create Ticket: Number of catalog item recevied in the request : "+ requestedItems.length);

The line of code above is a popular method for adding traces. Call debug and pass it some information to trace for us.

Hidden at first is why such a trace is needed. Especially when it has been the obvious solution for as long as we have been programming. And, obvious ideas just aren't questioned. Not questioning or improving a code base is a blatant disregard for the next reader. Deal with it, we are in Rome. It's as if we didn't care that someone behind will read this code long after we are gone.

I suggest that focus must shift to abandon strategies that don't build clean code. In order to get there code must be refactored to display less monolithic characteristics and become fully atomic in functionality. Limit the scope of functions, parameters and name, always return a value from functions in order to build single purpose algorithms. Once that is underway, logging can be improved, or at least, seen through the same lenses as programming as large: one function whose entire purpose is to log differently.

The shift of styles give rise to all sorts of possibility. Such as allowing the use of one function to log it all. No more need to have to imperatively add lines to leave traces of what is happening during the execution of a process. That's left behind in favor of something that does it for us.

For example:

function addLogging (fn) {
    return function execAndLog (value) {

        gs.debug('>> {0} : {1}', fn.name, JSON.stringify(arguments));

        var result = fn.apply(null, arguments);

        gs.debug('<< {0} : {1}', fn.name, JSON.stringify(result));

        return result;

    };
};

The piece of code above is a depth-2 curried function that given a function as its first execution parameter, returns a second function expecting some input. When that second function call is made, it executes the first parameter holding a function given the second. This then allows the programmer to addLogging to any function. No more need to add traces with long sentences. Now make sure functions are small, named very specific, and return a value.

It works because functions have been named, and fn.name is a property containing the name of that function. By properly naming the function, sentences or comments in traces can be omitted, allowing code itself to determine what is happening. As well as executing the function originally passed in, it prints the arguments that are to be used for the function, then the result of executing the function against those arguments.

A single single responsibility function that can help build a cleaner code base has been created.

It's usage is as follows.

First create some single responsibility named functions. The function names make up for having to add traces describing what is going on. And, because the single responsibility log function above takes care of arguments and result, there is no need to log those anywhere within the functions.

function getActiveUsers () {

   var gr = new GlideRecord('sys_user');
   gr.setLimit(10);
   gr.addActiveQuery();
  
   gr.query();

   return gr;

}

function getNames (sys_user) {
  return  sys_user.name + '';

}

function toUpperCase (name) {
   return name.toUpperCase();

}

function getUserNames (gr) {
    var names = [];
    var logGetNames = addLogging(getNames);
    var logUpperNames = addLogging(toUpperCase);

    while (gr.next() ) {
       names.push(logUpperNames(logGetNames(gr)));
   }

   return names;
}

Notice above addLogging. It says, hey functions, you now can log.

The entry point would then become this

addLogging(getUserNames)(getActiveUsers());

Notice the use of addLogging once more. This time to say, hey getUserNames, you too should can log.

The funny looking double ()() in that function call is because addLogging is a curried depth-2 function. Because it is curried, it must be called using that notation. Once for the very first function call, the second call to fully complete the execution cycle of the second and final returned function. The first call takes a function, the other the parameter to be used for the for the function passed in as an argument.

The output is as follows:

*** Script: [DEBUG] >> getUserNames - params: {"0":{"sys_meta":{"active":"1","array":"0","attributes":"all_tables.text_index_translations=true,display_image=photo,global_search_config_handler=UserConfig,iterativeDelete=true,metadata_link_exempt=true,ref_ac_columns=email,ref_ac_columns_search=true,ref_ac_order_by=name,ref_auto_completer=AJAXTableCompleter","audit":"0","calculation":"","choice":"0","choice_field":"","choice_table":"","create_roles":"user_admin","default_value":"","delete_roles":"","dependent":"","dependent_on_field":"","display":"name","dynamic_creation":"0","dynamic_creation_script":"dynamicUserCreation(current, value);","dynamic_default_value":"","dynamic_ref_qual":"","element_reference":"0","filterable":"1","foreign_database":"","function_definition":"","function_field":"0","groupable":"1","help":"","hint":"","i18n_sortable":"1","internal_type":"collection","label":"User","language":"en","mandatory":"0","matchable":"1","max_length":"40","multi_text":"0","name":"sys_user","plural":"Users","primary":"0","read_only":"0","read_roles":"","reference":"","reference_cascade_rule":"","reference_floats":"0","reference_key":"","reference_qual":"","reference_qual_condition":"","reference_type":"","sizeclass":"653","sortable":"1","spell_check":"0","staged":"0","sys_package":"b56574f3dbc200102eaf2bfa4b96191a","sys_scope":"global","table_reference":"0","text_index":"1","type":"0","type_description":"collection","unique":"0","url":"","url_target":"","use_dynamic_default":"0","use_reference_qualifier":"simple","virtual":"0","widget":"","write_roles":"","xml_view":"0"},"country":{},"calendar_integration":{},"last_position_update":{},"user_password":{},"last_login_time":{},"last_login_device":{},"source":{},"sys_updated_on":{},"building":{},"web_service_access_only":{},"notification":{},"managed_domain":{},"sys_updated_by":{},"enable_multifactor_authn":{},"sys_created_on":{},"sys_domain":{},"agent_status":{},"state":{},"vip":{},"sys_created_by":{},"longitude":{},"zip":{},"home_phone":{},"time_format":{},"accumulated_roles":{},"last_login":{},"default_perspective":{},"geolocation_tracked":{},"active":{},"last_password":{},"sys_domain_path":{},"phone":{},"cost_center":{},"name":{},"employee_number":{},"password_needs_reset":{},"gender":{},"city":{},"user_name":{},"failed_attempts":{},"edu_status":{},"latitude":{},"roles":{},"title":{},"sys_class_name":{},"sys_id":{},"internal_integration_user":{},"ldap_server":{},"mobile_phone":{},"street":{},"company":{},"department":{},"first_name":{},"preferred_language":{},"introduction":{},"email":{},"manager":{},"business_criticality":{},"locked_out":{},"sys_mod_count":{},"last_name":{},"photo":{},"avatar":{},"middle_name":{},"time_zone":{},"sys_tags":{},"schedule":{},"on_schedule":{},"date_format":{},"location":{}}}
*** Script: [DEBUG] >> getNames - params: {"0":{"sys_meta":{"active":"1","array":"0","attributes":"all_tables.text_index_translations=true,display_image=photo,global_search_config_handler=UserConfig,iterativeDelete=true,metadata_link_exempt=true,ref_ac_columns=email,ref_ac_columns_search=true,ref_ac_order_by=name,ref_auto_completer=AJAXTableCompleter","audit":"0","calculation":"","choice":"0","choice_field":"","choice_table":"","create_roles":"user_admin","default_value":"","delete_roles":"","dependent":"","dependent_on_field":"","display":"name","dynamic_creation":"0","dynamic_creation_script":"dynamicUserCreation(current, value);","dynamic_default_value":"","dynamic_ref_qual":"","element_reference":"0","filterable":"1","foreign_database":"","function_definition":"","function_field":"0","groupable":"1","help":"","hint":"","i18n_sortable":"1","internal_type":"collection","label":"User","language":"en","mandatory":"0","matchable":"1","max_length":"40","multi_text":"0","name":"sys_user","plural":"Users","primary":"0","read_only":"0","read_roles":"","reference":"","reference_cascade_rule":"","reference_floats":"0","reference_key":"","reference_qual":"","reference_qual_condition":"","reference_type":"","sizeclass":"653","sortable":"1","spell_check":"0","staged":"0","sys_package":"b56574f3dbc200102eaf2bfa4b96191a","sys_scope":"global","table_reference":"0","text_index":"1","type":"0","type_description":"collection","unique":"0","url":"","url_target":"","use_dynamic_default":"0","use_reference_qualifier":"simple","virtual":"0","widget":"","write_roles":"","xml_view":"0"},"country":{},"calendar_integration":{},"last_position_update":{},"user_password":{},"last_login_time":{},"last_login_device":{},"source":{},"sys_updated_on":{},"building":{},"web_service_access_only":{},"notification":{},"managed_domain":{},"sys_updated_by":{},"enable_multifactor_authn":{},"sys_created_on":{},"sys_domain":{},"agent_status":{},"state":{},"vip":{},"sys_created_by":{},"longitude":{},"zip":{},"home_phone":{},"time_format":{},"accumulated_roles":{},"last_login":{},"default_perspective":{},"geolocation_tracked":{},"active":{},"last_password":{},"sys_domain_path":{},"phone":{},"cost_center":{},"name":{},"employee_number":{},"password_needs_reset":{},"gender":{},"city":{},"user_name":{},"failed_attempts":{},"edu_status":{},"latitude":{},"roles":{},"title":{},"sys_class_name":{},"sys_id":{},"internal_integration_user":{},"ldap_server":{},"mobile_phone":{},"street":{},"company":{},"department":{},"first_name":{},"preferred_language":{},"introduction":{},"email":{},"manager":{},"business_criticality":{},"locked_out":{},"sys_mod_count":{},"last_name":{},"photo":{},"avatar":{},"middle_name":{},"time_zone":{},"sys_tags":{},"schedule":{},"on_schedule":{},"date_format":{},"location":{}}}
*** Script: [DEBUG] << getNames - result: "survey user"
*** Script: [DEBUG] >> toUpperCase - params: {"0":"survey user"}
*** Script: [DEBUG] << toUpperCase - result: "SURVEY USER"
*** Script: [DEBUG] >> getNames - params: {"0":{"sys_meta":{"active":"1","array":"0","attributes":"all_tables.text_index_translations=true,display_image=photo,global_search_config_handler=UserConfig,iterativeDelete=true,metadata_link_exempt=true,ref_ac_columns=email,ref_ac_columns_search=true,ref_ac_order_by=name,ref_auto_completer=AJAXTableCompleter","audit":"0","calculation":"","choice":"0","choice_field":"","choice_table":"","create_roles":"user_admin","default_value":"","delete_roles":"","dependent":"","dependent_on_field":"","display":"name","dynamic_creation":"0","dynamic_creation_script":"dynamicUserCreation(current, value);","dynamic_default_value":"","dynamic_ref_qual":"","element_reference":"0","filterable":"1","foreign_database":"","function_definition":"","function_field":"0","groupable":"1","help":"","hint":"","i18n_sortable":"1","internal_type":"collection","label":"User","language":"en","mandatory":"0","matchable":"1","max_length":"40","multi_text":"0","name":"sys_user","plural":"Users","primary":"0","read_only":"0","read_roles":"","reference":"","reference_cascade_rule":"","reference_floats":"0","reference_key":"","reference_qual":"","reference_qual_condition":"","reference_type":"","sizeclass":"653","sortable":"1","spell_check":"0","staged":"0","sys_package":"b56574f3dbc200102eaf2bfa4b96191a","sys_scope":"global","table_reference":"0","text_index":"1","type":"0","type_description":"collection","unique":"0","url":"","url_target":"","use_dynamic_default":"0","use_reference_qualifier":"simple","virtual":"0","widget":"","write_roles":"","xml_view":"0"},"country":{},"calendar_integration":{},"last_position_update":{},"user_password":{},"last_login_time":{},"last_login_device":{},"source":{},"sys_updated_on":{},"building":{},"web_service_access_only":{},"notification":{},"managed_domain":{},"sys_updated_by":{},"enable_multifactor_authn":{},"sys_created_on":{},"sys_domain":{},"agent_status":{},"state":{},"vip":{},"sys_created_by":{},"longitude":{},"zip":{},"home_phone":{},"time_format":{},"accumulated_roles":{},"last_login":{},"default_perspective":{},"geolocation_tracked":{},"active":{},"last_password":{},"sys_domain_path":{},"phone":{},"cost_center":{},"name":{},"employee_number":{},"password_needs_reset":{},"gender":{},"city":{},"user_name":{},"failed_attempts":{},"edu_status":{},"latitude":{},"roles":{},"title":{},"sys_class_name":{},"sys_id":{},"internal_integration_user":{},"ldap_server":{},"mobile_phone":{},"street":{},"company":{},"department":{},"first_name":{},"preferred_language":{},"introduction":{},"email":{},"manager":{},"business_criticality":{},"locked_out":{},"sys_mod_count":{},"last_name":{},"photo":{},"avatar":{},"middle_name":{},"time_zone":{},"sys_tags":{},"schedule":{},"on_schedule":{},"date_format":{},"location":{}}}
*** Script: [DEBUG] << getNames - result: "Ibrahim Jabbar"
*** Script: [DEBUG] >> toUpperCase - params: {"0":"Ibrahim Jabbar"}
*** Script: [DEBUG] << toUpperCase - result: "IBRAHIM JABBAR"
*** Script: [DEBUG] >> getNames - params: {"0":{"sys_meta":{"active":"1","array":"0","attributes":"all_tables.text_index_translations=true,display_image=photo,global_search_config_handler=UserConfig,iterativeDelete=true,metadata_link_exempt=true,ref_ac_columns=email,ref_ac_columns_search=true,ref_ac_order_by=name,ref_auto_completer=AJAXTableCompleter","audit":"0","calculation":"","choice":"0","choice_field":"","choice_table":"","create_roles":"user_admin","default_value":"","delete_roles":"","dependent":"","dependent_on_field":"","display":"name","dynamic_creation":"0","dynamic_creation_script":"dynamicUserCreation(current, value);","dynamic_default_value":"","dynamic_ref_qual":"","element_reference":"0","filterable":"1","foreign_database":"","function_definition":"","function_field":"0","groupable":"1","help":"","hint":"","i18n_sortable":"1","internal_type":"collection","label":"User","language":"en","mandatory":"0","matchable":"1","max_length":"40","multi_text":"0","name":"sys_user","plural":"Users","primary":"0","read_only":"0","read_roles":"","reference":"","reference_cascade_rule":"","reference_floats":"0","reference_key":"","reference_qual":"","reference_qual_condition":"","reference_type":"","sizeclass":"653","sortable":"1","spell_check":"0","staged":"0","sys_package":"b56574f3dbc200102eaf2bfa4b96191a","sys_scope":"global","table_reference":"0","text_index":"1","type":"0","type_description":"collection","unique":"0","url":"","url_target":"","use_dynamic_default":"0","use_reference_qualifier":"simple","virtual":"0","widget":"","write_roles":"","xml_view":"0"},"country":{},"calendar_integration":{},"last_position_update":{},"user_password":{},"last_login_time":{},"last_login_device":{},"source":{},"sys_updated_on":{},"building":{},"web_service_access_only":{},"notification":{},"managed_domain":{},"sys_updated_by":{},"enable_multifactor_authn":{},"sys_created_on":{},"sys_domain":{},"agent_status":{},"state":{},"vip":{},"sys_created_by":{},"longitude":{},"zip":{},"home_phone":{},"time_format":{},"accumulated_roles":{},"last_login":{},"default_perspective":{},"geolocation_tracked":{},"active":{},"last_password":{},"sys_domain_path":{},"phone":{},"cost_center":{},"name":{},"employee_number":{},"password_needs_reset":{},"gender":{},"city":{},"user_name":{},"failed_attempts":{},"edu_status":{},"latitude":{},"roles":{},"title":{},"sys_class_name":{},"sys_id":{},"internal_integration_user":{},"ldap_server":{},"mobile_phone":{},"street":{},"company":{},"department":{},"first_name":{},"preferred_language":{},"introduction":{},"email":{},"manager":{},"business_criticality":{},"locked_out":{},"sys_mod_count":{},"last_name":{},"photo":{},"avatar":{},"middle_name":{},"time_zone":{},"sys_tags":{},"schedule":{},"on_schedule":{},"date_format":{},"location":{}}}
*** Script: [DEBUG] << getNames - result: "Lucius Bagnoli"
*** Script: [DEBUG] >> toUpperCase - params: {"0":"Lucius Bagnoli"}
*** Script: [DEBUG] << toUpperCase - result: "LUCIUS BAGNOLI"
*** Script: [DEBUG] >> getNames - params: {"0":{"sys_meta":{"active":"1","array":"0","attributes":"all_tables.text_index_translations=true,display_image=photo,global_search_config_handler=UserConfig,iterativeDelete=true,metadata_link_exempt=true,ref_ac_columns=email,ref_ac_columns_search=true,ref_ac_order_by=name,ref_auto_completer=AJAXTableCompleter","audit":"0","calculation":"","choice":"0","choice_field":"","choice_table":"","create_roles":"user_admin","default_value":"","delete_roles":"","dependent":"","dependent_on_field":"","display":"name","dynamic_creation":"0","dynamic_creation_script":"dynamicUserCreation(current, value);","dynamic_default_value":"","dynamic_ref_qual":"","element_reference":"0","filterable":"1","foreign_database":"","function_definition":"","function_field":"0","groupable":"1","help":"","hint":"","i18n_sortable":"1","internal_type":"collection","label":"User","language":"en","mandatory":"0","matchable":"1","max_length":"40","multi_text":"0","name":"sys_user","plural":"Users","primary":"0","read_only":"0","read_roles":"","reference":"","reference_cascade_rule":"","reference_floats":"0","reference_key":"","reference_qual":"","reference_qual_condition":"","reference_type":"","sizeclass":"653","sortable":"1","spell_check":"0","staged":"0","sys_package":"b56574f3dbc200102eaf2bfa4b96191a","sys_scope":"global","table_reference":"0","text_index":"1","type":"0","type_description":"collection","unique":"0","url":"","url_target":"","use_dynamic_default":"0","use_reference_qualifier":"simple","virtual":"0","widget":"","write_roles":"","xml_view":"0"},"country":{},"calendar_integration":{},"last_position_update":{},"user_password":{},"last_login_time":{},"last_login_device":{},"source":{},"sys_updated_on":{},"building":{},"web_service_access_only":{},"notification":{},"managed_domain":{},"sys_updated_by":{},"enable_multifactor_authn":{},"sys_created_on":{},"sys_domain":{},"agent_status":{},"state":{},"vip":{},"sys_created_by":{},"longitude":{},"zip":{},"home_phone":{},"time_format":{},"accumulated_roles":{},"last_login":{},"default_perspective":{},"geolocation_tracked":{},"active":{},"last_password":{},"sys_domain_path":{},"phone":{},"cost_center":{},"name":{},"employee_number":{},"password_needs_reset":{},"gender":{},"city":{},"user_name":{},"failed_attempts":{},"edu_status":{},"latitude":{},"roles":{},"title":{},"sys_class_name":{},"sys_id":{},"internal_integration_user":{},"ldap_server":{},"mobile_phone":{},"street":{},"company":{},"department":{},"first_name":{},"preferred_language":{},"introduction":{},"email":{},"manager":{},"business_criticality":{},"locked_out":{},"sys_mod_count":{},"last_name":{},"photo":{},"avatar":{},"middle_name":{},"time_zone":{},"sys_tags":{},"schedule":{},"on_schedule":{},"date_format":{},"location":{}}}
*** Script: [DEBUG] << getNames - result: "Jimmie Barninger"
*** Script: [DEBUG] >> toUpperCase - params: {"0":"Jimmie Barninger"}
*** Script: [DEBUG] << toUpperCase - result: "JIMMIE BARNINGER"
*** Script: [DEBUG] << getUserNames - result: ["SURVEY USER","IBRAHIM JABBAR","LUCIUS BAGNOLI","JIMMIE BARNINGER"]

The result above is the trajectory followed by calling getUserNames. As demonstrated, function names called, their params and result are all displayed in the trace. No more need for explicit traces about what to log. JS already knows what is being called, leveraging it. Our job then is to use it eloquently enough to spotlight only the parts of it that matter (what's happening). To build code that quickly helps spotlight functionality.

Now, this is not a complete logging solution. it's just a function to showcase the strategy. In the future, i hope to write a few more comprehensive versions that account for error, debug, log, warn, info. The function showcased here was purposely bound and limited to debug.

Happy SNowing...