Debugging & error handling: MQL recipes

Recipes

Business errors with codes: raise, catch and parse [err]
Catch, log and rethrow with context
Follow an order through the logs with a correlation id
All the log lines of one process
Where the logs go: trace, show, ids and retention
Time a web service with date current_ms
Memory and CPU before and after a heavy step
Defensive checks before calling: exists, defaults, types
Read the errors of typed script parameters
A health snapshot of the server as JSON

executed on MentDB

Business errors with codes: raise, catch and parse [err]

A stock web service raises its business errors with exception and a code (404 unknown product, 409 not enough stock). The caller runs three orders, catches each error with try, parses the code and the message out of [err] with a regex, and builds a JSON report an API client can use.

Pipeline

01 · raiseError with a codeexception→02 · catchCatch per ordertry→03 · parseCode and message from [err]string regexp_extract→04 · reportJSON reportjson iarray

Script

admin

#1. The service raises coded errors;
script create post "tuto.cf.stock.reserve" false 1 (param
	(var "[sku]" {true} "Product code" is_null:false is_empty:false "SKU-1")
	(var "[qty]" {type is_integer [qty] 4} "Quantity" is_null:false is_empty:false "2")
;) "Reserve stock, raises 404 or 409" {
	if (equal [sku] "SKU-404") {exception (404) ("Product not found");};
	if (> [qty] 10) {exception (409) (concat "Not enough stock for " [sku]);};
	concat "reserved " [qty] " x " [sku];
} "A confirmation";
#2. Three orders, each one protected by try;
json load "tuto_cf_report" "[]";
-> "[orders]" "SKU-1:3,SKU-404:1,SKU-7:50";
for (-> "[i]" 1) (<= [i] (atom size [orders] ",")) (++ "[i]") {
	-> "[o]" (atom get [orders] [i] ",");
	try {
		-> "[r]" (execute "tuto.cf.stock.reserve.post" "[sku]" (atom get [o] 1 ":") "[qty]" (atom get [o] 2 ":"));
		json iarray "tuto_cf_report" / (concat "{\"order\": \"" [o] "\", \"code\": 200, \"msg\": \"" [r] "\"}") OBJ;
	} {
		#3. The last line of err is code: message;
		-> "[code]" (string regexp_extract [err] "([0-9]+): ([^\n]+)\s*$" 1);
		-> "[msg]" (string regexp_extract [err] "([0-9]+): ([^\n]+)\s*$" 2);
		json iarray "tuto_cf_report" / (concat "{\"order\": \"" [o] "\", \"code\": " [code] ", \"msg\": \"" [msg] "\"}") OBJ;
	} "[err]";
};
-> "[out]" (json doc "tuto_cf_report");
json unload "tuto_cf_report";
script delete "tuto.cf.stock.reserve.post";
[out];

Result

mentdb

[
  {
    "msg": "reserved 3 x SKU-1",
    "code": 200,
    "order": "SKU-1:3"
  },
  {
    "msg": "Product not found",
    "code": 404,
    "order": "SKU-404:1"
  },
  {
    "msg": "Not enough stock for SKU-7",
    "code": 409,
    "order": "SKU-7:50"
  }
]

Go further

In a REST web service, return the code as the HTTP status of the response
Keep codes stable in a table of your project: clients test the code, not the message

executed on MentDB

Catch, log and rethrow with context

Deep in a call chain, the raw error 'Product not found' says nothing about which order failed. The middle layer catches it, writes it to the server log with log trace, and rethrows a new exception with a code 500 and the order context; the top layer shows the full chain of messages.

Pipeline

01 · innerLow level errorexception→02 · middleCatch and tracelog trace→03 · rethrowNew code, more contextexception→04 · topFinal catchtry

Script

admin

#1. The low level service;
script create post "tuto.cf.stock.reserve" false 1 (param
	(var "[sku]" {true} "Product code" is_null:false is_empty:false "SKU-1")
	(var "[qty]" {type is_integer [qty] 4} "Quantity" is_null:false is_empty:false "2")
;) "Reserve stock, raises 404 or 409" {
	if (equal [sku] "SKU-404") {exception (404) ("Product not found");};
	if (> [qty] 10) {exception (409) (concat "Not enough stock for " [sku]);};
	concat "reserved " [qty] " x " [sku];
} "A confirmation";
#2. Middle layer: catch, trace, rethrow with the order context;
script create post "tuto.cf.order.place" false 1 (param (var "[order]" {true} "Order id" is_null:false is_empty:false "A-1") (var "[sku]" {true} "Product" is_null:false is_empty:false "SKU-1");) "Place an order" {
	try {
		execute "tuto.cf.stock.reserve.post" "[sku]" [sku] "[qty]" 1;
	} {
		log trace (concat "tuto_cf ORDER " [order] " failed: " (string regexp_extract [err] "[0-9]+: ([^\n]+)\s*$" 1));
		exception (500) (concat "ORDER/PLACE " [order] " < " (string regexp_extract [err] "([0-9]+: [^\n]+)\s*$" 1));
	} "[err]";
} "The confirmation";
#3. Top layer;
try {
	execute "tuto.cf.order.place.post" "[order]" "A-2031" "[sku]" "SKU-404";
} {-> "[final]" (string regexp_extract [err] "([0-9]+: [^\n]+)\s*$" 1);} "[err]";
-> "[traced]" (string contains (log show 50) "tuto_cf ORDER A-2031 failed: Product not found");
script delete "tuto.cf.order.place.post";
script delete "tuto.cf.stock.reserve.post";
concat "caller sees: " [final] [_n_] "written to the server log: " [traced];

Result

mentdb

caller sees: 500: ORDER/PLACE A-2031 < 404: Product not found
written to the server log: 1

Go further

Use a code per layer (500 for the order layer, 404 for stock) to find where the chain broke
log trace writes to the server log file: read it with log show 20

executed on MentDB

Follow an order through the logs with a correlation id

A payment script logs each step with log write and the client key corr_id. The caller generates a correlation id, calls the script, then searches the activity log for that id: the OK steps and the KO step (fraud check) come back as rows that the script reads with json.

Pipeline

01 · idCorrelation iddate current_ms→02 · writeOne log line per steplog write→03 · searchSearch by client keylog search→04 · readRows of the resultjson parse_array

Script

admin

#1. log write only writes when the script has its log activated: true;
script create post "tuto.cf.order.pay" true 1 (param (var "[corr]" {true} "Correlation id" is_null:false is_empty:false "ORD-1") (var "[amount]" {type is_double [amount]} "Amount" is_null:false is_empty:false "10");) "Pay an order" {
	log write "payment received" "OK" "corr_id" [corr];
	if (> [amount] 1000) {log write (concat "fraud check needed for " [amount]) "KO" "corr_id" [corr];} {log write "fraud check passed" "OK" "corr_id" [corr];};
	log write "invoice queued" "OK" "corr_id" [corr];
	[corr];
} "The correlation id";
#2. A unique id per call;
-> "[corr]" (concat "ORD-" (date current_ms));
execute "tuto.cf.order.pay.post" "[corr]" [corr] "[amount]" 1499.90;
#3. Search today, by client key and value, the result starts with a 39 chars editor tag;
-> "[from]" (concat (date sysdate) " 00:00:00");
-> "[to]" (concat (date sysdate) " 23:59:59");
json load "tuto_cf_ok" (string substring (log search "ok" "tuto.cf.order.pay.post" "corr_id" [corr] null [from] [to] ASC 1 50) 39);
json load "tuto_cf_ko" (string substring (log search "ko" null "corr_id" [corr] null [from] [to] ASC 1 50) 39);
-> "[steps]" "";
json parse_array "tuto_cf_ok" "/data" "[row]" {
	json load "tuto_cf_row" [row];
	-> "[steps]" (concat [steps] (json select "tuto_cf_row" "/msg") " > ");
	json unload "tuto_cf_row";
};
-> "[nb_ok]" (json count "tuto_cf_ok" "/data");
-> "[ko]" (json select "tuto_cf_ko" "/data[0]/msg");
json unload "tuto_cf_ok";
json unload "tuto_cf_ko";
script delete "tuto.cf.order.pay.post";
concat "correlation id found: " (string starts_with [corr] "ORD-") [_n_] [nb_ok] " OK steps: " [steps] [_n_] "KO step: " [ko];

Result

mentdb

correlation id found: 1
2 OK steps: payment received > invoice queued >
KO step: fraud check needed for 1499.90

Go further

Pass the correlation id from the HTTP header of your web service to every script it calls
Open log search ... alone in the editor: the result is shown as a table

executed on MentDB

All the log lines of one process

Each script execution has a process id, available as [PID] inside the script. The script returns its [PID], then log show_time and restricted show_pid read every line of that process, including the Begin and End markers that MentDB adds when the log of a script is activated.

Pipeline

01 · runScript returns its PIDexecute→02 · timeLines of the processlog show_time→03 · sameProcess and linked onesrestricted show_pid→04 · readCount and messagesjson count

Script

admin

script create post "tuto.cf.invoice.build" true 1 (param (var "[nb]" {type is_integer [nb] 3} "Number of lines" is_null:false is_empty:false "3");) "Build an invoice" {
	log write (concat "invoice with " [nb] " lines") "OK" "step" "build";
	log write "pdf rendered" "OK" "step" "render";
	[PID];
} "The process id";
#1. Run it and keep the PID;
-> "[pid]" (execute "tuto.cf.invoice.build.post" "[nb]" 3);
#2. Every line of this process, after the 39 chars editor tag;
json load "tuto_cf_proc" (string substring (log show_time [pid]) 39);
-> "[msgs]" "";
json parse_array "tuto_cf_proc" "/data" "[row]" {
	json load "tuto_cf_row" [row];
	-> "[msgs]" (concat [msgs] [_n_] "  " (json select "tuto_cf_row" "/msg"));
	json unload "tuto_cf_row";
};
-> "[n1]" (json count "tuto_cf_proc" "/data");
json unload "tuto_cf_proc";
#3. Same lines plus the linked processes;
json load "tuto_cf_proc2" (string substring (restricted show_pid [pid]) 39);
-> "[n2]" (json count "tuto_cf_proc2" "/data");
json unload "tuto_cf_proc2";
script delete "tuto.cf.invoice.build.post";
concat "log show_time: " [n1] " lines" [msgs] [_n_] "restricted show_pid: " [n2] " lines";

Result

mentdb

log show_time: 4 lines
  [---- Begin script ----]
  invoice with 3 lines
  pdf rendered
  [---- End script ----]
restricted show_pid: 4 lines

Go further

A script called with call or include from this one is a linked process: restricted show_pid shows them together
log show_time with two arguments takes the node name first, for a cluster

executed on MentDB

Where the logs go: trace, show, ids and retention

A new developer asks where the logs are. The script writes a tagged line with log trace, finds it again in the last lines of the server log with log show, and gathers the settings of the activity log: current id, retention in days, archive size and archive folder.

Pipeline

01 · traceTagged linelog trace→02 · showLast lines of the server loglog show→03 · idsCurrent log idlog current id→04 · settingsRetention and archiveslog retention day

Script

admin

#1. A tagged line in the server log;
-> "[tag]" (concat "tuto_cf_TRACE_" (date current_ms));
log trace (concat [tag] " cache rebuilt in 42 ms");
#2. Find it in the last 30 lines;
-> "[found]" (string regexp_count (log show 30) [tag]);
#3. Settings of the activity log;
concat "tag found in log show: " [found] [_n_] "current log id of the editor session: " (log current id) [_n_] "retention: " (log retention day) " days" [_n_] "archive size: " (log archive size) [_n_] "archive folder: " (log archive path);

Result

mentdb

tag found in log show: 1
current log id of the editor session: 0
retention: 50 days
archive size: 30
archive folder: archives/logs

Go further

log remove purges the activity log older than the retention: schedule it with a job
Use log write instead of log trace when you need to search by status or client key

executed on MentDB

Time a web service with date current_ms

Before optimising, measure. The script calls a web service 2000 times between two date current_ms readings, computes the average time per call in milliseconds and compares it with an inline version of the same formula, to see the cost of a script call.

Pipeline

01 · startStart timedate current_ms→02 · loop2000 callsexecute→03 · inlineSame work inlinewhile→04 · averageAverage per callmath round

Script

admin

script create post "tuto.cf.price.ttc" false 1 (param (var "[ht]" {type is_double [ht]} "Price" is_null:false is_empty:false "100");) "Price with VAT" {bd* [ht] 1.2;} "TTC";
#1. 2000 script calls;
-> "[n]" 2000;
-> "[t0]" (date current_ms);
-> "[sum1]" 0;
for (-> "[i]" 1) (<= [i] [n]) (++ "[i]") {-> "[sum1]" (bd+ [sum1] (execute "tuto.cf.price.ttc.post" "[ht]" [i]));};
-> "[t1]" (date current_ms);
#2. The same work inline;
-> "[i]" 1;
-> "[sum2]" 0;
while (<= [i] [n]) {-> "[sum2]" (bd+ [sum2] (bd* [i] 1.2)); ++ "[i]";};
-> "[t2]" (date current_ms);
script delete "tuto.cf.price.ttc.post";
#3. Compare;
-> "[per_call]" (math round (/ (- [t1] [t0]) [n]) 3);
-> "[per_inline]" (math round (/ (- [t2] [t1]) [n]) 3);
concat [n] " calls: " (- [t1] [t0]) " ms, " [per_call] " ms per call" [_n_] [n] " inline: " (- [t2] [t1]) " ms, " [per_inline] " ms per turn" [_n_] "same total: " (equal [sum1] [sum2]) " (" [sum1] ")";

Result

mentdb

2000 calls: 14 ms, 0.007 ms per call
2000 inline: 4 ms, 0.002 ms per turn
same total: 1 (2401200.0)

Go further

Wrap a slow step with two date current_ms and log write the difference with the correlation id
Times change at each run: run it several times before concluding

executed on MentDB

Memory and CPU before and after a heavy step

A script that builds a big JSON in memory is suspected of eating the JVM. The script reads the JVM memory (used/total/max in MB) and the CPU load before and after building a 20 000 items array, then frees it and prints the difference.

Pipeline

01 · beforeJVM memory used/total/maxmetric current mem jvm→02 · workHeavy stepjson iarray→03 · afterMemory and CPU aftermetric current cpu jvm→04 · freeFree and comparejson unload

Script

admin

#1. Before;
-> "[m0]" (metric current mem jvm);
-> "[free0]" (metric current free mem);
#2. Heavy step: 20000 items in a JSON array;
json load "tuto_cf_big" "[]";
for (-> "[i]" 1) (<= [i] 20000) (++ "[i]") {json iarray "tuto_cf_big" / (concat "item-" [i]) STR;};
-> "[n]" (json count "tuto_cf_big" /);
#3. After;
-> "[m1]" (metric current mem jvm);
-> "[cpu]" (metric current cpu jvm);
json unload "tuto_cf_big";
concat "items built: " [n] [_n_] "jvm memory used/total/max MB before: " [m0] ", after: " [m1] [_n_] "used delta MB: " (- (atom get [m1] 1 "/") (atom get [m0] 1 "/")) [_n_] "jvm cpu after: " [cpu] "%" [_n_] "free system memory MB before: " [free0] ", max jvm: " (atom get [m0] 3 "/");

Result

mentdb

items built: 20000
jvm memory used/total/max MB before: 225/512/2048, after: 294/512/2048
used delta MB: 69
jvm cpu after: 0.7%
free system memory MB before: 106, max jvm: 2048

Go further

The garbage collector may run in the middle: a negative delta is normal
Log metric current mem jvm with a job every minute to see a leak over time

executed on MentDB

Defensive checks before calling: exists, defaults, types

A script must not crash on a missing parameter or script. It checks that the web service exists before calling it, falls back to a default when a parameter is not set, validates a quantity with type is_integer before using it, and refuses a blank customer name, collecting every problem instead of stopping at the first.

Pipeline

01 · existsScript exists before callscript exist→02 · defaultParameter or defaultparameter exist→03 · typeValidate a valuetype is_integer→04 · blankBlank textstring is_blank

Script

admin

-> "[problems]" "";
#1. The service may not be deployed on this server;
if (script exist "tuto.cf.loyalty.points.post") {-> "[points]" (execute "tuto.cf.loyalty.points.post");} {
	-> "[points]" 0;
	-> "[problems]" (concat [problems] "loyalty service missing, points=0; ");
};
#2. Parameter with a default value;
if (parameter exist "tuto_cf_max_qty") {-> "[max]" (get_param "tuto_cf_max_qty");} {
	-> "[max]" 10;
	-> "[problems]" (concat [problems] "tuto_cf_max_qty not set, default 10; ");
};
#3. Validate the inputs;
-> "[qty]" "12x";
-> "[customer]" "   ";
if (not (type is_integer [qty] 4)) {-> "[problems]" (concat [problems] "qty '" [qty] "' is not an integer; ");};
if (string is_blank [customer]) {-> "[problems]" (concat [problems] "customer is blank; ");};
concat "points=" [points] ", max=" [max] [_n_] "problems: " [problems];

Result

mentdb

points=0, max=10
problems: loyalty service missing, points=0; tuto_cf_max_qty not set, default 10; qty '12x' is not an integer; customer is blank;

Go further

At the end, raise one exception with all the problems if the list is not empty
Typed script parameters like {type is_integer [qty] 4} do the type check for you: see the next recipe

executed on MentDB

Read the errors of typed script parameters

A web service declares its parameters with types and is_null/is_empty rules. The script calls it with a wrong type and with a missing parameter, catches both errors with try and extracts the readable sentence MentDB puts between [[[ and ]]], so the developer knows exactly which variable is wrong.

Pipeline

01 · declareTyped parametersscript create→02 · badWrong typeexecute→03 · missingMissing parametertry→04 · readReadable sentencestring regexp_extract

Script

admin

#1. The service with a typed quantity;
script create post "tuto.cf.stock.reserve" false 1 (param
	(var "[sku]" {true} "Product code" is_null:false is_empty:false "SKU-1")
	(var "[qty]" {type is_integer [qty] 4} "Quantity" is_null:false is_empty:false "2")
;) "Reserve stock, raises 404 or 409" {
	if (equal [sku] "SKU-404") {exception (404) ("Product not found");};
	if (> [qty] 10) {exception (409) (concat "Not enough stock for " [sku]);};
	concat "reserved " [qty] " x " [sku];
} "A confirmation";
#2. Wrong type;
try {execute "tuto.cf.stock.reserve.post" "[sku]" "SKU-1" "[qty]" "three";} {-> "[e1]" [err];} "[err]";
#3. Missing parameter;
try {execute "tuto.cf.stock.reserve.post" "[sku]" "SKU-1";} {-> "[e2]" [err];} "[err]";
#4. Good call;
-> "[ok]" (execute "tuto.cf.stock.reserve.post" "[sku]" "SKU-1" "[qty]" 3);
script delete "tuto.cf.stock.reserve.post";
#5. The readable sentence is between 3 brackets;
concat "wrong type: " (string regexp_extract [e1] "\[\[\[ (.+) \]\]\]" 1) [_n_] "missing: " (string regexp_extract [e2] "\[\[\[ (.+) \]\]\]" 1) [_n_] "good call: " [ok];

Result

mentdb

wrong type: Sorry, the variable '[qty]' in the script 'tuto.cf.stock.reserve.post' is not valid (type is_integer [qty] 4;).
missing: Sorry, the script 'tuto.cf.stock.reserve.post' does not has a valid number of parameters.
good call: reserved 3 x SKU-1

Go further

script show params "<script>" lists the expected parameters with their types
Generate a call with all the parameters using script generate execute "<script>"

executed on MentDB

A health snapshot of the server as JSON

When a user reports slowness, the first reflex is a health snapshot. The script reads the processors, memory, swap, CPU, Java and OS versions, the free space of the disk roots and the number of open sessions with the metric functions, and returns one JSON a monitoring page can display.

Pipeline

01 · cpuProcessors and CPUmetric system nb processor→02 · memMemory and swapmetric total mem→03 · diskDisk rootsmetric file system roots→04 · envJava and OSmetric java version→05 · jsonOne JSONjson iobject

Script

admin

json load "tuto_cf_health" "{}";
#1. CPU;
json iobject "tuto_cf_health" / "processors" (metric system nb processor) INT;
json iobject "tuto_cf_health" / "cpu_system_pct" (metric current cpu system) NUM;
#2. Memory in MB;
json iobject "tuto_cf_health" / "mem_total_mb" (metric total mem) INT;
json iobject "tuto_cf_health" / "mem_available_mb" (metric current available mem) INT;
json iobject "tuto_cf_health" / "mem_used_mb" (metric current used mem) INT;
json iobject "tuto_cf_health" / "swap_free_mb" (metric current free swap mem) INT;
json iobject "tuto_cf_health" / "swap_used_mb" (concat (metric current used swap mem) "/" (metric total swap mem)) STR;
#3. Disk: percent free of the first root;
json load "tuto_cf_roots" (metric file system roots);
json iobject "tuto_cf_health" / "disk_free_pct" (math round (* 100 (/ (json select "tuto_cf_roots" "/[0]/freeSpace") (json select "tuto_cf_roots" "/[0]/totalSpace"))) 1) NUM;
json unload "tuto_cf_roots";
#4. Software;
json iobject "tuto_cf_health" / "java" (concat (metric java version) " " (metric java vendor)) STR;
json iobject "tuto_cf_health" / "os" (concat (metric system name) " " (metric system version) " " (metric system architecture)) STR;
json iobject "tuto_cf_health" / "open_sessions" (count sessions) INT;
-> "[snap]" (json doc "tuto_cf_health");
json unload "tuto_cf_health";
[snap];

Result

mentdb

{
  "disk_free_pct": 31.5,
  "java": "21.0.13 Eclipse Adoptium",
  "mem_available_mb": 5072,
  "os": "Mac OS X 14.4 aarch64",
  "open_sessions": 2,
  "cpu_system_pct": 8.1,
  "mem_total_mb": 18432,
  "processors": 11,
  "mem_used_mb": 18055,
  "swap_used_mb": "1149/2048",
  "swap_free_mb": 898
}

Go further