Skip to content

Add usage lib #2

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
jmlemay merged 10 commits into from
Aug 5, 2025
Merged

Add usage lib #2

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
10 commits
Select commit Hold shift + click to select a range
5702bcd
Add usage lib
KyleBonnes Jul 4, 2025
999ffcd
Remove call to init and fix indentation
DHopkinson-DI Jul 14, 2025
d8dda84
Updates to usage.q and usage.md based on review
DHopkinson-DI Jul 16, 2025
d71acb6
Add timezone logic, error trap log and fix case
DHopkinson-DI Jul 22, 2025
53f6404
added some test coverage
jmlemay Jul 24, 2025
c314c3a
ready for review
jmlemay Jul 24, 2025
180ee2a
review fixes
jmlemay Jul 25, 2025
dec950e
style pass
jmlemay Jul 29, 2025
3f608fd
unbroke test I broke
jmlemay Jul 29, 2025
dc12a39
small fix from merge
jmlemay Jul 30, 2025
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
1 change: 1 addition & 0 deletions .gitignore
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -0,0 +1 @@
*.swp
121 changes: 121 additions & 0 deletions usage/test.csv
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -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,


93 changes: 93 additions & 0 deletions usage/test.q
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -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);
};
166 changes: 166 additions & 0 deletions usage/usage.md
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -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 ""
```
Loading