diff --git a/.gitignore b/.gitignore new file mode 100644 index 00000000..1377554e --- /dev/null +++ b/.gitignore @@ -0,0 +1 @@ +*.swp diff --git a/usage/test.csv b/usage/test.csv new file mode 100644 index 00000000..558e902d --- /dev/null +++ b/usage/test.csv @@ -0,0 +1,121 @@ +action,ms,bytes,lang,code,repeat,minver,comment + +run,0,0,q,.usage.init[],1,1,out-of-the-box configuration +run,0,0,q,.testusg.runhandler[`.z.pw;(`test_user;"pass123")],1,1, +run,0,0,q,.testusg.runhandler[`.z.po;1i],1,1, +run,0,0,q,.testusg.runhandler[`.z.pc;2i],1,1, +run,0,0,q,.testusg.runhandler[`.z.wo;3i],1,1, +run,0,0,q,.testusg.runhandler[`.z.wc;4i],1,1, +run,0,0,q,.testusg.runhandler[`.z.ws;-8!"1+1"],1,1, +run,0,0,q,.testusg.runhandler[`.z.pg;"1+1"],1,1, +run,0,0,q,.testusg.runhandler[`.z.ps;(+;2;2)],1,1, +run,0,0,q,.testusg.runhandler[`.z.ph;(.j.j`x`y`z!(1;"http%3a%2f%2fdomain.com";`get);`hdr1`hdr2!("hello";"goodbye"))],1,1, +run,0,0,q,.testusg.runhandler[`.z.pp;(.j.j`x`y`z!(1;"http%3a%2f%2fdomain.com";`post);`hdr1`hdr2!("hello";"goodbye"))],1,1, +run,0,0,q,.testusg.runhandler[`.z.exit;0],1,1, +true,0,0,q,.testusg.chkusage[],1,1, +run,0,0,q,.testusg.reset[],1,1, + +run,0,0,q,.testusg.setcustomhandlers[],1,1,run with custom handlers and verify that they are properly invoked +run,0,0,q,.usage.init[],1,1, +run,0,0,q,.testusg.runhandler[`.z.pw;(`test_user;"pass123")],1,1, +run,0,0,q,.testusg.runhandler[`.z.po;1i],1,1, +run,0,0,q,.testusg.runhandler[`.z.pc;2i],1,1, +run,0,0,q,.testusg.runhandler[`.z.wo;3i],1,1, +run,0,0,q,.testusg.runhandler[`.z.wc;4i],1,1, +run,0,0,q,.testusg.runhandler[`.z.ws;-8!"1+1"],1,1, +run,0,0,q,.testusg.runhandler[`.z.pg;"1+1"],1,1, +run,0,0,q,.testusg.runhandler[`.z.ps;(+;2;2)],1,1, +run,0,0,q,.testusg.runhandler[`.z.ph;"dummy"],1,1, +run,0,0,q,.testusg.runhandler[`.z.pp;"dummy"],1,1, +run,0,0,q,.testusg.runhandler[`.z.exit;255],1,1, +true,0,0,q,.testusg.chkusage[],1,1, +true,0,0,q,([]zcmd:`.z.pw`.z.po`.z.pc`.z.wo`.z.wc`.z.ws`.z.pg`.z.ps`.z.ph`.z.pp`.z.exit;args:((`test_user;"pass123");1i;2i;3i;4i;-8!"1+1";"1+1";(+;2;2);"dummy";"dummy";255))~1_.testusg.customtracker,1,1, +run,0,0,q,.testusg.reset[],1,1, + +run,0,0,q,.test.mock[`.usage.logtodisk;1b],1,1,should error on invalid logging configurations +true,0,0,q,@[.usage.init;::;::]~"logname and logdir must be set to enable on disk usage logging. .usage.logToDisk disabled",1,1, +run,0,0,q,.test.mock'[`.usage.logtodisk`.usage.logdir`.usage.logname;(1b;".";"")],1,1, +true,0,0,q,@[.usage.init;::;::]~"logname and logdir must be set to enable on disk usage logging. .usage.logToDisk disabled",1,1, +run,0,0,q,.test.mock'[`.usage.logtodisk`.usage.logdir`.usage.logname;(1b;"";"test")],1,1, +true,0,0,q,@[.usage.init;::;::]~"logname and logdir must be set to enable on disk usage logging. .usage.logToDisk disabled",1,1, + +run,0,0,q,.test.mock[`.usage.createlog;{z;'"some error"}],1,1,should fail if log file creation errors +run,0,0,q,.test.mock'[`.usage.logtodisk`.usage.logdir`.usage.logname;(1b;".";"test")],1,1, +true,0,0,q,@[.usage.init;::;::]like"Error creating log file: ./usage_test_* | Error: some error",1,1, +run,0,0,q,.test.unmock[],1,1, +run,0,0,q,.testusg.reset[],1,1, + +run,0,0,q,.test.mock'[`.usage.logtodisk`.usage.logdir`.usage.logname;(1b;".";"test")],1,1,should correctly write to and read from log file +run,0,0,q,@[system;"rm usage_test_* 2> /dev/null";::];,1,1,clean up in case of previous run +run,0,0,q,.usage.init[],1,1, +run,0,0,q,.testusg.runhandler[`.z.po;1i],1,1, +run,0,0,q,.testusg.runhandler[`.z.pg;"1+1"],1,1, +run,0,0,q,.testusg.runhandler[`.z.pg;(avg;1 2 3)],1,1, +run,0,0,q,.testusg.runhandler[`.z.pc;1i],1,1, +true,0,0,q,.testusg.chkusage .usage.readlog first system"ls usage_test_*",1,1, +run,0,0,q,.testusg.reset[],1,1, +run,0,0,q,.test.unmock[],1,1, +run,0,0,q,system"rm usage_test_*",1,1, + +run,0,0,q,.usage.init[],1,1,log at different levels +run,0,0,q,.test.mock[`.usage.level;0],1,1,log nothing +run,0,0,q,.z.po 1i,1,1, +run,0,0,q,.z.pg"1+1",1,1, +fail,0,0,q,.z.pg"1+`a",1,1, +run,0,0,q,.z.pc 1i,1,1, +true,0,0,q,0=count .usage.usage,1,1, +run,0,0,q,.test.mock[`.usage.level;1],1,1,log errors only +run,0,0,q,.z.po 1i,1,1, +run,0,0,q,.z.pg"1+1",1,1, +fail,0,0,q,.z.pg"1+`a",1,1, +run,0,0,q,.z.pc 1i,1,1, +true,0,0,q,(1=count .usage.usage)&.usage.usage[0;`zcmd`status`cmd`error]~(`pg;"e";"1+`a";"type"),1,1, +run,0,0,q,.usage.usage:0#.usage.usage,1,1, +run,0,0,q,.test.mock[`.usage.level;2],1,1,log open/close/queries (no "before" queries) +run,0,0,q,.z.ps"1+1",1,1, +run,0,0,q,(1=count .usage.usage)&.usage.usage[0;`zcmd`status`cmd]~(`ps;"c";"1+1"),1,1, +run,0,0,q,.usage.usage:0#.usage.usage,1,1, +run,0,0,q,.test.unmock[],1,1,restore default level + +run,0,0,q,.test.mock'[`.usage.ignore`.usage.ignorelist;(1b;(`upd;"0+0"))],1,1, +run,0,0,q,.test.mock[;{y;}]each`upd`fn,1,1, +run,0,0,q,.z.ps(+;1;2),1,1,not ignored +run,0,0,q,.z.ps(`upd;`trade;([]x:1 2)),1,1,ignored +run,0,0,q,.z.ps(`fn;`trade;([]x:1 2)),1,1,not ignored +run,0,0,q,.z.ps"0+0",1,1,ignored +run,0,0,q,.z.ps"1+0",1,1,not ignored +true,0,0,q,([]zcmd:`ps;status:6#"bc";cmd:(.Q.s1(+;1;2);.Q.s1(`fn;`trade;([]x:1 2));"1+0")where 3#2)~`zcmd`status`cmd#.usage.usage,1,1, +run,0,0,q,.usage.usage:0#.usage.usage,1,1, +run,0,0,q,.test.unmock[],1,1, + +run,0,0,q,".test.mock[`.usage.ext;{.testusg.ext,:enlist x}]",1,1,test extension +run,0,0,q,.z.pw[`test_user;"pass123"],1,1, +run,0,0,q,.z.po 1i,1,1, +run,0,0,q,.z.pc 2i,1,1, +run,0,0,q,.z.wo 3i,1,1, +run,0,0,q,.z.wc 4i,1,1, +run,0,0,q,.test.mock[`.z.ps;{}],1,1, +run,0,0,q,.z.ws -8!"1+1",1,1, +run,0,0,q,.test.unmock`.z.ps,1,1, +run,0,0,q,.z.pg"1+1",1,1, +run,0,0,q,.z.ps(+;2;2),1,1, +run,0,0,q,.z.ph(.j.j`x`y`z!(1;"http%3a%2f%2fdomain.com";`get);`hdr1`hdr2!("hello";"goodbye")),1,1, +run,0,0,q,.z.pp(.j.j`x`y`z!(1;"http%3a%2f%2fdomain.com";`post);`hdr1`hdr2!("hello";"goodbye")),1,1, +run,0,0,q,.z.exit 0,1,1, +true,0,0,q,.usage.usage~flip key[flip .usage.usage]!flip .testusg.ext,1,1, +run,0,0,q,.usage.usage:0#.usage.usage,1,1, +run,0,0,q,.test.unmock[],1,1, + +run,0,0,q,.test.mock[`.usage.usage;([]id:1 1 2 2 3;time:2025.07.24+0D12 0D12:00:00.1 0D12:01:59.999999999 0D12:02 0D12:05)],1,1, +run,0,0,q,.test.mock[`.usage.currenttime;{2025.07.24D12:07}] +run,0,0,q,.usage.flushusage 0D00:05,1,1, +true,0,0,q,.usage.usage~([]id:2 3;time:2025.07.24+0D12:02 0D12:05),1,1, +run,0,0,q,.usage.flushusage 5D,1,1,nop +true,0,0,q,.usage.usage~([]id:2 3;time:2025.07.24+0D12:02 0D12:05),1,1, +run,0,0,q,.usage.flushusage 0,1,1,wipe +true,0,0,q,0=count .usage.usage,1,1, +run,0,0,q,.usage.flushusage 0D00:01,1,1,no effect on empty table +true,0,0,q,0=count .usage.usage,1,1, +run,0,0,q,.test.unmock[],1,1, + + diff --git a/usage/test.q b/usage/test.q new file mode 100644 index 00000000..9715e09d --- /dev/null +++ b/usage/test.q @@ -0,0 +1,93 @@ +/ load helper scripts and run tests. + +/ handlers we overwrite with their type and default kdb implementations (or null if none) +.testusg.handlers:1!flip + (`name; `typ; `default)!flip( + (`.z.pw; `auth; ::); + (`.z.po; `conn; ::); + (`.z.pc; `conn; ::); + (`.z.wo; `conn; ::); + (`.z.wc; `conn; ::); + (`.z.ws; `query; ::); + (`.z.pg; `query; ::); + (`.z.ps; `query; ::); + (`.z.ph; `query; .z.ph); + (`.z.pp; `query; ::); + (`.z.exit; `query; ::)); + +/ internal tables/metadata we use to facilitate testing +.testusg.exusage:flip`id`zcmd`status`a`u`w`cmd`sz`error!"jscisi*j*"$\:(); / same schema as `.usage.usage` +.testusg.customtracker:enlist`zcmd`args!(`;""); / keeps track of invocation +.testusg.wildcols:`time`extime`mem!12 16 0h; / `.usage.usage` columns we can't accurately predict + +/ runs a handler and keeps track of it internally so we can validate it against the usage table afterwards +.testusg.runhandler:{[handler;args] + .testusg.id+:1; + if[b:handler~`.z.ws;.test.mock[`.z.ps;{}]]; / swallow websocket response + res:$[`.z.pw~handler;.;@][handler;args]; + if[b;.test.unmock`.z.ps]; + typ:.testusg.handlers[handler;`typ]; + .testusg[typ][last` vs handler;args;res]; + }; + +/ appends auth-type calls to `.testusg.exusage` +.testusg.auth:{[zcmd;args;res] + .testusg.exusage,:(.testusg.id;zcmd;"c";.z.a;.z.u;0i;.usage.formatarg[zcmd;(first args;"***")];0N;""); + }; + +/ appends conn-type calls to `.testusg.exusage` +.testusg.conn:{[zcmd;args;res] + .testusg.exusage,:(.testusg.id;zcmd;"c";.z.a;.z.u;0i;.usage.formatarg[zcmd;args];0N;""); + }; + +/ appends conn-type calls to `.testusg.exusage` +.testusg.query:{[zcmd;args;res] + rows:([] + id:.testusg.id; + zcmd; + status:"bc"; + a:.z.a; + u:.z.u; + w:0i; + cmd:.usage.formatarg[zcmd;]each(args;args); + sz:0N,-22!res; + error:("";"")); + .testusg.exusage,:rows; + }; + +/ checks that the `.testusg.exusage` table matches the specified table +.testusg.chkusage:{[tbl] + usg:$[tbl~(::);.usage.usage;tbl]; + + // wild columns -- we know the type but can't accurately predict the value + if[not type'[.usage.usage key .testusg.wildcols]~value .testusg.wildcols;:0b]; + + // other columns should match our expectations exactly + .testusg.exusage~key[flip .testusg.exusage]#.usage.usage + }; + +/ resets all internal variable, must call `.usage.init` afterwards +.testusg.reset:{[] + .testusg.wipehandlers[]; + .usage.usage:0#.usage.usage; + .testusg.exusage:0#.testusg.exusage; + .testusg.customtracker:1#.testusg.customtracker; + }; + +/ wipes all handler definitions +.testusg.wipehandlers:{[] + b:(t:0!.testusg.handlers)[`default]~\:(::); + system each"x ",/:string t[where b;`name]; + exec name set'default from t where not b; + }; + +/ sets all handlers in `.testusg.handler` to custom functions to override the defaults +/ we set the handlers to a projection of `.testusg.customhandler` +.testusg.setcustomhandlers:{[] + exec name set'{('[x y;enlist])}[.testusg.customhandler;]each name from .testusg.handlers; + } + +/ custom handler, which logs calls to `.testusg.customtracker` +.testusg.customhandler:{[zcmd;args] + .testusg.customtracker,:(zcmd;$[1=count args;first;]args); + }; diff --git a/usage/usage.md b/usage/usage.md new file mode 100644 index 00000000..787b1110 --- /dev/null +++ b/usage/usage.md @@ -0,0 +1,166 @@ +# `usage.q` – External Usage Logging for kdb+ + +A utility library for logging external queries and connections to a kdb+ session. It captures metadata such as execution time, memory usage, user information, command content, and errors. + +> **Note:** Initialising this library **overwrites `.z` message handlers** with wrapped versions for logging. + +--- + +## :sparkles: Features + +- Tracks external usage: connections, queries, authentication. +- Logs to memory (in-table) and/or disk (append-only file). +- Supports filtering via ignore lists. +- Captures execution times, arguments, system info, and result sizes. +- Pluggable `.usage.ext` function for custom log sinks. +- Flush/parse logs from memory or file. + +--- + +## :label: Usage Table Schema + +Logs are stored in `.usage.usage` with the following columns: + +| Column | Type | Description | +|--------|-----------|-------------------------------------------| +| time | `timestamp` | Time of the event | +| id | `long` | Unique ID for the request | +| extime | `timespan` | Execution duration (if applicable) | +| zcmd | `symbol` | `.z` command (`pg`, `ph`, `pw`, etc.) | +| status | `char` | `b` = before, `c` = complete, `e` = error | +| a | `int` | Remote IP address | +| u | `symbol` | Remote user | +| w | `int` | Connection handle | +| cmd | `string` | Formatted query/argument to handler | +| mem | `list` | Partial memory stats from `system "w"` | +| sz | `long` | Size of result in bytes | +| error | `string` | Error message (if applicable) | + +--- + +## :gear: Configuration + +Depending on the desired behaviour, config variables can be set **before running** `.usage.init`: + +```q +.usage.localtime : 1b // Log using local time or UTC (default: 1b, local) +.usage.logdir : "/path/to/logs"; // Path to log directory +.usage.logname : "rdb"; // Identifier used in log file name: usage_{logname}_{timestamp}.log +.usage.logtimestamp : {.z.Z}; // Function to give log name timestamp suffix (default: {[] :.z.D;}) +.usage.logtodisk : 1b; // Log to disk (default: 0b) +.usage.logtomemory : 1b; // Log to memory table (default: 1b) +.usage.level : 2; // Logging level (0–3, see below) (default: 3) +.usage.ignore : 1b; // Enable log-skipping for configured functions (default: 1b) +.usage.ignorelist : enlist `upd; // Functions to skip logging (in .z.ps only) +``` + +Log level meanings: + +| Level | Description | +|-------|-------------------------------------------------| +| 0 | Disable all logging | +| 1 | Only errors | +| 2 | + connection open/close, query complete | +| 3 | + query begin events | + +--- + +## :wrench: Functions + +### :pencil2: Logging Functions + +| Function | Description | +|---------------------------|------------------------------------------------------| +| `.usage.logauth` | Log user/password validation | +| `.usage.logconnection` | Log connection open/close | +| `.usage.logquery` | Log before/after a query | +| `.usage.logqueryfiltered` | Like `logquery`, but skips if in `.usage.ignorelist` | +| `.usage.logdirect` | Low-level: log a completed request | +| `.usage.logbefore` | Low-level: log query start | +| `.usage.logafter` | Low-level: log query completion | +| `.usage.logerror` | Low-level: log query failure | + +### :rocket: Initialisation + +The package is initialised by calling the nullary function `.usage.init[]` which calls the `usage.inithandlers` and `.usage.initlog` functions, overriding the `.z.*` message handlers +and initiates the in memory logs/ on disk logs if enabled. + +| Function | Description | +|-----------------------|--------------------------------------------------------------------------------------------------------------------------| +| `.usage.inithandlers` | Wrap `.z.*` message handlers for logging | +| `.usage.initlog` | Create file handle if `.usage.logtodisk` is set. Will fail if `.usage.logdir` or `.usage.logname` have not be configured | +| `.usage.init` | Run full initialisation | + + +--- + +## :memo: Log File Output + +- Log files are created as: `usage_{logname}_{timestamp}.log` +- Format: pipe-delimited strings with same columns as `.usage.usage` + +Use `.usage.readlog` to parse logs from disk: + +```q +.usage.readlog["logs/usage_rdb_2025.06.25.log"] +``` + +--- + +## :hammer_and_wrench: Utilities + +| Function | Description | +|------------------------|---------------------------------------------------------------------------------------------------| +| `.usage.flushusage[t]` | Remove records older than `t` (timespan) ago from memory | +| `.usage.ext[x]` | Optional extension hook for each record written (`x` is a list of column data for `.usage.usage`) | +| `.usage.nextid[]` | Generate next usage ID | +| `.usage.meminfo[]` | Get partial system memory stats | +| `.usage.formatarg` | Format incoming `.z` argument for logging | + +--- + +## :arrows_counterclockwise: Overridden `.z` Handlers + +The following `.z` handlers are wrapped automatically (with custom handler function staying preserved): + +- `.z.pw` – password check → `logauth` +- `.z.po`, `.z.pc`, `.z.wo`, `.z.wc` – connection open/close → `logconnection` +- `.z.ws`, `.z.pg`, `.z.ph`, `.z.pp`, `.z.exit` – queries → `logquery` +- `.z.ps` – query (with filtering) → `logqueryfiltered` + +Default handlers will be defined if not previously set. + +--- + +## :bulb: Notes + +- You can override `.usage.ext` to forward records to a pub/sub topic, REST endpoint, etc. +- The in-memory logging table can be disabled by setting `.usage.logtomemory:0b`. +- This module is compatible with kdb+ 3.0 or later. + +--- + +## :test_tube: Example + +```q +// Set up logging to disk and memory +.usage.localtime:1b; +.usage.logdir:"logs"; +.usage.logname:"rdb"; +.usage.logtodisk:1b; +.usage.logtomemory:1b; +.usage.ignorelist,:(`upd; ".hb.checkheartbeat[]"); +\l usage.q +.usage.init[] + +// Check usage table for synchronous user queries +select from .usage.usage where zcmd=`pg +time id extime zcmd status a u w cmd mem sz error +----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- +2025.07.04D11:57:59.474947647 194 pg b 2130706433 kdbNoob 14 "tables[]" 8273600 67108864 67108864 0 0 "" +2025.07.04D11:57:59.475151569 194 0D00:00:00.000009790 pg c 2130706433 kdbNoob 14 "tables[]" 8274560 67108864 67108864 0 0 71 "" +2025.07.04D11:58:05.535593991 196 pg b 2130706433 kdbNoob 14 "select from quote where sym in (\"AAPL\";\"MSFT\"), time>.z.p-00:05" 8274912 67108864 67108864 0 0 "" +2025.07.04D11:58:05.536083945 196 0D00:00:00.000001382 pg e 2130706433 kdbNoob 14 "select from quote where sym in (\"AAPL\";\"MSFT\"), time>.z.p-00:05" 8275440 67108864 67108864 0 0 "type" +2025.07.04D11:58:19.986818174 200 pg b 2130706433 kdbNoob 14 "select from quote where sym in `AAPL`MSFT, time>.z.p-00:05" 8277664 67108864 67108864 0 0 "" +2025.07.04D11:58:19.987270684 200 0D00:00:00.000026848 pg c 2130706433 kdbNoob 14 "select from quote where sym in `AAPL`MSFT, time>.z.p-00:05" 8278208 67108864 67108864 0 0 118 "" +``` diff --git a/usage/usage.q b/usage/usage.q new file mode 100644 index 00000000..e2a6476b --- /dev/null +++ b/usage/usage.q @@ -0,0 +1,207 @@ +/ library for logging external usage of a kdb+ session +/ note that initialising this library will overwrite .z message +/ handlers with usage-logging wrappers of their current definitions + +/ table to store usage info +.usage.usage:@[value;`.usage.usage;([] + time:`timestamp$(); + id:`long$(); + extime:`timespan$(); + zcmd:`symbol$(); + status:`char$(); + a:`int$(); + u:`symbol$(); + w:`int$(); + cmd:(); + mem:(); + sz:`long$(); + error:())]; + +/ flags and variables + +/ whether to log to disk +.usage.logtodisk:@[value;`.usage.logtodisk;0b]; + +/ whether to log to memory +.usage.logtomemory:@[value;`.usage.logtomemory;1b]; + +/ whether to check the ignore list for function calls to not log +.usage.ignore:@[value;`.usage.ignore;1b]; + +/ list of function to not log usage of +.usage.ignorelist:@[value;`.usage.ignorelist;()]; + +/ function to generate the log file timestamp suffix +.usage.logtimestamp:@[value;`.usage.logtimestamp;{{[local] $[local;.z.D;.z.d]}}]; + +/ log directory +/ should be set before loading library to initialise on disk logging +.usage.logdir:@[value;`.usage.logdir;""]; + +/ log file will take the form "usage_{logname}_{date/time}.log" +/ should be set before loading library to initialise on disk logging +.usage.logname:@[value;`.usage.logname;""]; + +/ log level +/ 0 = nothing +/ 1 = errors only +/ 2 = + open, close, queries +/ 3 = + log queries before execution +.usage.level:@[value;`.usage.level;3]; + +/ ID for tracking external queries +.usage.id:@[value;`.usage.id;0]; + +/ increment ID and return new value +.usage.nextid:{[] :.usage.id+:1;}; + +/ check time preference. Default local time +.usage.localtime:@[value;`.usage.localtime;1b]; + +/ return local time or UTC +.usage.currenttime:{[local] $[local;.z.P;.z.p]}; + +/ handle to the log file +.usage.logh:@[value;`.usage.logh;0]; + +/ write a query log message +.usage.write:{[x] + if[.usage.logtodisk; @[neg .usage.logh;"|" sv .Q.s1 each x;()]]; + if[.usage.logtomemory;`.usage.usage upsert x]; + .usage.ext[x]; + }; + +// Extension function to extend the logging e.g. publish the log message +.usage.ext:{[x]}; + +// Flush out in-memory usage records older than flushtime +.usage.flushusage:{[flushtime] delete from `.usage.usage where time<.usage.currenttime[.usage.localtime]-flushtime;} + +// Create usage log on disk +.usage.createlog:{[logdir;logname;timestamp] + basename:"usage_",logname,"_",string[timestamp],".log"; + / close the current log handle if there is one + @[hclose;.usage.logh;()]; + / open the file + .usage.logh:hopen hsym`$logdir,"/",basename; + }; + +/ parse a usage log file and return as a usage table +.usage.readlog:{[filename] + / remove leading backtick from symbol columns, drop "i" suffix from a and w columns and cast back to integers + :update + zcmd:`$1_'string zcmd,u:`$1_'string u,a:"I"$-1_'a,w:"I"$-1_'w + from + @[{update "J"$'" " vs' mem from flip (cols .usage.usage)!("PJNSC*S***J*";"|")0: x}; + hsym`$filename; + {'"failed to read log file : ",x}]; + }; + +/ get the memory info - we don't want to log the physical memory each time +.usage.meminfo:{[] :5#system"w";}; + +/ format the message handler argument as a string +.usage.formatarg:{[zcmd;arg] + str:$[10=abs type arg;arg,();.Q.s1 arg]; + / replace %xx hexsequences in HTTP request arguments + if[zcmd in`ph`pp;str:.h.uh str]; + :str; + }; + +/ log the completion of an external request and return the result +.usage.logdirect:{[id;zcmd;endtime;result;arg;starttime] + if[.usage.level>1; + .usage.write (starttime;id;endtime-starttime;zcmd;"c";.z.a;.z.u;.z.w;.usage.formatarg[zcmd;arg];.usage.meminfo[];0Nj;"")]; + :result; + }; + +/ log stats of query before execution +.usage.logbefore:{[id;zcmd;arg;starttime] + if[.usage.level>2; + .usage.write (starttime;id;0Nn;zcmd;"b";.z.a;.z.u;.z.w;.usage.formatarg[zcmd;arg];.usage.meminfo[];0Nj;"")]; + }; + +/ log stats of a completed query and return the result +.usage.logafter:{[id;zcmd;endtime;result;arg;starttime] + if[.usage.level>1; + .usage.write (endtime;id;endtime-starttime;zcmd;"c";.z.a;.z.u;.z.w;.usage.formatarg[zcmd;arg];.usage.meminfo[];-22!result;"")]; + :result; + }; + +/ log stats of a failed query and raise the error +.usage.logerror:{[id;zcmd;endtime;arg;starttime;error] + if[.usage.level>0; + .usage.write (endtime;id;endtime-starttime;zcmd;"e";.z.a;.z.u;.z.w;.usage.formatarg[zcmd;arg];.usage.meminfo[];0Nj;error)]; + 'error; + }; + +/ log successful user validation +.usage.logauth:{[zcmd;handler;user;pass] + :.usage.logdirect[.usage.nextid[];zcmd;.usage.currenttime[.usage.localtime];handler[user;pass];(user;"***");.usage.currenttime[.usage.localtime]]; + }; + +/ log successful connection opening/closing +.usage.logconnection:{[zcmd;handler;arg] + :.usage.logdirect[.usage.nextid[];zcmd;.usage.currenttime[.usage.localtime];handler arg;arg;.usage.currenttime[.usage.localtime]]; + }; + +/ log before and after query execution is attempted +.usage.logquery:{[zcmd;handler;arg] + id:.usage.nextid[]; + .usage.logbefore[id;zcmd;arg;.usage.currenttime[.usage.localtime]]; + :.usage.logafter[id;zcmd;.usage.currenttime[.usage.localtime];@[handler;arg;.usage.logerror[id;zcmd;.usage.currenttime[.usage.localtime];arg;start;]];arg;start:.usage.currenttime[.usage.localtime]]; + }; + +/ log before and after query execution is attempted, filtering with .usage.ignoreList +.usage.logqueryfiltered:{[zcmd;handler;arg] + if[.usage.ignore; + if[0h=type arg; + if[any first[arg]~/:.usage.ignorelist;:handler arg]]; + if[10h=type arg; + if[any arg~/:.usage.ignorelist;:handler arg]]]; + :.usage.logquery[zcmd;handler;arg]; + }; + +/ initialise .z functions with usage logging functionality +.usage.inithandlers:{[] + / initialise unassigned message handlers with default values + .z.pw:@[value;`.z.pw;{{[x;y] 1b}}]; + .z.po:@[value;`.z.po;{{}}]; + .z.pc:@[value;`.z.pc;{{}}]; + .z.wo:@[value;`.z.wo;{{}}]; + .z.wc:@[value;`.z.wc;{{}}]; + .z.ws:@[value;`.z.ws;{{neg[.z.w] x;}}]; + .z.pg:@[value;`.z.pg;{value}]; + .z.ps:@[value;`.z.ps;{value}]; + .z.pp:@[value;`.z.pp;{{}}]; + .z.exit:@[value;`.z.exit;{{}}]; + + / reassign message handlers with usage-logging wrappers + .z.pw:.usage.logauth[`pw;.z.pw;;]; + .z.po:.usage.logconnection[`po;.z.po;]; + .z.pc:.usage.logconnection[`pc;.z.pc;]; + .z.wo:.usage.logconnection[`wo;.z.wo;]; + .z.wc:.usage.logconnection[`wc;.z.wc;]; + .z.ws:.usage.logquery[`ws;.z.ws;]; + .z.pg:.usage.logquery[`pg;.z.pg;]; + .z.ps:.usage.logqueryfiltered[`ps;.z.ps;]; + .z.ph:.usage.logquery[`ph;.z.ph;]; + .z.pp:.usage.logquery[`pp;.z.pp;]; + .z.exit:.usage.logquery[`exit;.z.exit;]; + }; + +/ initialise on disk usage logging, if enabled +.usage.initlog:{[] + if[.usage.logtodisk; + if[""in(.usage.logname;.usage.logdir); + .usage.logtodisk:0b; + '"logname and logdir must be set to enable on disk usage logging. .usage.logToDisk disabled"]; + .[.usage.createlog; + (.usage.logdir;.usage.logname;.usage.logtimestamp[.usage.localtime]); + {.usage.logtodisk:0b;'"Error creating log file: ",.usage.logdir,"/usage_",.usage.logname,"_",string[.usage.logtimestamp[.usage.localtime]]," | Error: " ,x}]]; + }; + +.usage.init:{[] + .usage.inithandlers[]; + .usage.initlog[]; + };