System Logs With ms Accuracy - Solved!

William Busby · ‎12-01-2023

For years I've waited for SNOW to provide better logging that shows actions taken in linear sequence to no avail. I recently inherited an app built by a true code monkey with a single script include of 4000 lines. When ran it generates approx 800 lines in the system log. Since it runs within a second or two the log becomes useless given that sequential actions can be logged dozens of lines away from prev/next actions.

This is my solution to log down to the ms (and I can attest it works on large script includes 😁 ). You can either add this in your own script include and call it remotely or add it to any Bravo Alpha script include but the heart of the solution is a function like this:

timestamp: function(){

return new GlideDateTime().getNumericValue();

},

Then, anyplace you log using gs.info/warn/error just invoke it as:

gs.info(this.timestamp() + <remainder of your message>); // if the function is in the same si

or

gs.info(new <si_name>().timestamp() + <remainder of your message>); // if the function is in a remote si

Now you can examine your logs by sorting on the Message field to see things happen in the correct sequence.

12/01/2023 02:49:09	Information	1701420549706 selectPoPPEPort --> closest PoP is siteId 9943311(9943311 : NGN - ITS NSP Infrastructure). At distance of 2.75 miles
12/01/2023 02:49:09	Information	1701420549707 selectPoPPEPort --> next closest PoP is siteId 9943317(9943317 : NGN - Raleigh POP). At distance of 3.20 miles
12/01/2023 02:49:09	Information	1701420549708 selectPoPPEPort --> NSTSK01126 is part of HA pair
12/01/2023 02:49:09	Information	1701420549713 selectPoPPEPort --> NSTSK01126 is part of HA pair, ignoring already allocated telco provider AT&T
12/01/2023 02:49:09	Information	1701420549713 selectPoPPEPort --> provider_to_ignore = AT&T
12/01/2023 02:49:09	Information	1701420549714 selectPoPPEPort --> calling get pe function for sec pe port using pop 9943311
12/01/2023 02:49:09	Information	1701420549715 getPEPort4Pop --> called with NSProTask NSTSK01126, pop site_id 9943311 and provider to ignore of AT&T
12/01/2023 02:49:09	Information	1701420549715 getPEPort4Pop --> NSProTask network service category is enterprise
12/01/2023 02:49:09	Information	1701420549716 getPEPort4Pop --> NSProTask NSTSK01126 service category is enterprise - Guaranteed.
12/01/2023 02:49:09	Information	1701420549717 getPEPort4Pop --> calling for telco selection by zip
12/01/2023 02:49:09	Information	1701420549718 selectTelcoByZip --> invoked with zip = 27604, service category = guaranteed
12/01/2023 02:49:09	Information	1701420549718 selectTelcoByZip --> trimmed zip is 27604
12/01/2023 02:49:09	Information	1701420549723 selectTelcoByZip --> pushing telco provider Spectrum
12/01/2023 02:49:09	Information	1701420549726 selectTelcoByZip --> pushing telco provider LMK
12/01/2023 02:49:09	Information	1701420549727 selectTelcoByZip --> pushing telco provider Lightower
12/01/2023 02:49:09	Information	1701420549729 selectTelcoByZip --> pushing telco provider Spirit
12/01/2023 02:49:09	Information	1701420549730 getPEPort4Pop --> primary telco is: Spectrum