Skip to content

Commit 3dca048

Browse files
patrickodpatrickod
authored
Print type or UNKNOWN alongside query arguments in INFO log (#1444)
Extend ExternalInstance with an `class_repr: Option<String>` which is passed for all *registered* classes, and left blank otherwise. Use this information later when printing logs to signal to the user class of an instance and whether that type is "known" to Polar.
1 parent ab3b7fb commit 3dca048

File tree

26 files changed

+332
-100
lines changed

26 files changed

+332
-100
lines changed

‎docs/content/any/project/changelogs/2021-12-22.md

+6
Original file line numberDiff line numberDiff line change
@@ -50,6 +50,12 @@ const bindings = new Map([['x', 1]]);
5050
oso.query('f(x)', { bindings });
5151
```
5252

53+
##### `POLAR_LOG` now supports multiple log levels
54+
55+
* Previously we supported `POLAR_LOG=trace` and `POLAR_LOG=on`, both of which enabled slightly different but verbose "TRACE"-level logging of the execution of queries and their constituent goals within the Polar VM.
56+
* `POLAR_LOG=on` was slightly less verbose than `POLAR_LOG=trace` but still produced a voluminous output which made it hard to parse and follow the execution of a particular query.
57+
* To enable easier query debugging we have broken out `POLAR_LOG` into new discrete `INFO` and `TRACE` levels. Specifying `POLAR_LOG=info` will cause Polar to emit a more concise log output intended to be consumed by developers as they build and debug their Polar policies. The more verbose TRACE output is still available through `POLAR_LOG=trace`. Check out our [documentation](/reference/tooling/tracing.html) for more information on tracing.
58+
5359
#### Other bugs & improvements
5460

5561
- Thanks to [`@Kn99HN`](https://github.com/Kn99HN) for adding the

‎docs/content/any/reference/tooling/info

+13
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,13 @@
1+
[oso][info] QUERY RULE: allow(<__main__.User object at 0x7f1db433d640> TYPE `User`, "view", <__main__.Repository object at 0x7f1db433d610> TYPE `Repository`)
2+
[oso][info] APPLICABLE_RULES:
3+
[oso][info] allow(actor, action, resource) at line 11, column 5
4+
[oso][info] QUERY RULE: has_permission(_actor_4, _action_5, _resource_6)
5+
[oso][info] QUERY RULE: has_relation(_actor_11, "owner", _repository_12)
6+
[oso][info] RESULT: SUCCESS
7+
True
8+
[oso][info] QUERY RULE: allow(<__main__.User object at 0x7f1db433d640> TYPE `User`, "view", <__main__.Project object at 0x7f1db433d310> TYPE `UNKNOWN`)
9+
[oso][info] APPLICABLE_RULES:
10+
[oso][info] allow(actor, action, resource) at line 11, column 5
11+
[oso][info] QUERY RULE: has_permission(_actor_26, _action_27, _resource_28)
12+
[oso][info] No matching rules found
13+
False

‎docs/content/any/reference/tooling/trace

+124
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,124 @@
1+
[oso][trace] Query(allow(<__main__.User object at 0x7f0013c99640> TYPE `User`, "view", <__main__.Repository object at 0x7f0013c99610> TYPE `Repository`))
2+
[oso][info] QUERY RULE: allow(<__main__.User object at 0x7f0013c99640> TYPE `User`, "view", <__main__.Repository object at 0x7f0013c99610> TYPE `Repository`), BINDINGS: {}
3+
[oso][info] APPLICABLE_RULES:
4+
[oso][info] allow(actor, action, resource) at line 11, column 5
5+
[oso][trace] TraceRule(...)
6+
[oso][trace] RULE: allow(actor, action, resource) if has_permission(actor, action, resource);
7+
[oso][trace] TraceStackPush
8+
[oso][trace] Unify(<__main__.User object at 0x7f0013c99640> TYPE `User`, _actor_4)
9+
[oso][trace] ⇒ bind: _actor_4 ← <__main__.User object at 0x7f0013c99640> TYPE `User`
10+
[oso][trace] Unify("view", _action_5)
11+
[oso][trace] ⇒ bind: _action_5 ← "view"
12+
[oso][trace] Unify(<__main__.Repository object at 0x7f0013c99610> TYPE `Repository`, _resource_6)
13+
[oso][trace] ⇒ bind: _resource_6 ← <__main__.Repository object at 0x7f0013c99610> TYPE `Repository`
14+
[oso][trace] Query(has_permission(_actor_4, _action_5, _resource_6))
15+
[oso][trace] TraceStackPush
16+
[oso][trace] Query(has_permission(_actor_4, _action_5, _resource_6))
17+
[oso][info] QUERY RULE: has_permission(_actor_4, _action_5, _resource_6), BINDINGS: {_actor_4 => <__main__.User object at 0x7f0013c99640> TYPE `User`, _action_5 => "view", _resource_6 => <__main__.Repository object at 0x7f0013c99610> TYPE `Repository`}
18+
[oso][trace] APPLICABLE_RULES:
19+
[oso][trace] has_permission(actor: Actor{}, "view", repository: Repository{}) at line 7, column 8
20+
[oso][trace] TraceRule(...)
21+
[oso][trace] RULE: has_permission(actor: Actor{}, "view", repository: Repository{}) if has_relation(actor, "owner", repository);
22+
[oso][trace] TraceStackPush
23+
[oso][trace] Unify(_actor_4, _actor_11)
24+
[oso][trace] ⇒ bind: _actor_4 ← _actor_11
25+
[oso][trace] Isa(_actor_11, Actor{})
26+
[oso][trace] MATCHES: _actor_11 matches Actor{}, BINDINGS: {_actor_11 => <__main__.User object at 0x7f0013c99640> TYPE `User`}
27+
[oso][trace] Isa(_actor_11, User{})
28+
[oso][trace] MATCHES: _actor_11 matches User{}, BINDINGS: {_actor_11 => <__main__.User object at 0x7f0013c99640> TYPE `User`}
29+
[oso][trace] Isa(<__main__.User object at 0x7f0013c99640> TYPE `User`, User{})
30+
[oso][trace] MATCHES: <__main__.User object at 0x7f0013c99640> TYPE `User` matches User{}, BINDINGS: {}
31+
[oso][trace] IsaExternal { instance: Term { source_info: Ffi, value: ExternalInstance(ExternalInstance { instance_id: 14, constructor: None, repr: None, class_repr: Some("User") }) }, literal: InstanceLiteral { tag: Symbol("User"), fields: Dictionary { fields: {} } } }
32+
[oso][trace] ⇒ bind: _isa_13 ← false
33+
[oso][trace] Unify(_isa_13, true)
34+
[oso][trace] Unify(true, true)
35+
[oso][trace] Isa(<__main__.User object at 0x7f0013c99640> TYPE `User`, {})
36+
[oso][trace] MATCHES: <__main__.User object at 0x7f0013c99640> TYPE `User` matches {}, BINDINGS: {}
37+
[oso][trace] Unify(_action_5, "view")
38+
[oso][trace] Unify("view", "view")
39+
[oso][trace] Unify(_resource_6, _repository_12)
40+
[oso][trace] ⇒ bind: _resource_6 ← _repository_12
41+
[oso][trace] Isa(_repository_12, Repository{})
42+
[oso][trace] MATCHES: _repository_12 matches Repository{}, BINDINGS: {_repository_12 => <__main__.Repository object at 0x7f0013c99610> TYPE `Repository`}
43+
[oso][trace] Isa(<__main__.Repository object at 0x7f0013c99610> TYPE `Repository`, Repository{})
44+
[oso][trace] MATCHES: <__main__.Repository object at 0x7f0013c99610> TYPE `Repository` matches Repository{}, BINDINGS: {}
45+
[oso][trace] IsaExternal { instance: Term { source_info: Ffi, value: ExternalInstance(ExternalInstance { instance_id: 15, constructor: None, repr: None, class_repr: Some("Repository") }) }, literal: InstanceLiteral { tag: Symbol("Repository"), fields: Dictionary { fields: {} } } }
46+
[oso][trace] ⇒ bind: _isa_14 ← false
47+
[oso][trace] Unify(_isa_14, true)
48+
[oso][trace] Unify(true, true)
49+
[oso][trace] Isa(<__main__.Repository object at 0x7f0013c99610> TYPE `Repository`, {})
50+
[oso][trace] MATCHES: <__main__.Repository object at 0x7f0013c99610> TYPE `Repository` matches {}, BINDINGS: {}
51+
[oso][trace] Query(has_relation(_actor_11, "owner", _repository_12))
52+
[oso][trace] TraceStackPush
53+
[oso][trace] Query(has_relation(_actor_11, "owner", _repository_12))
54+
[oso][info] QUERY RULE: has_relation(_actor_11, "owner", _repository_12), BINDINGS: {_actor_11 => <__main__.User object at 0x7f0013c99640> TYPE `User`, _repository_12 => <__main__.Repository object at 0x7f0013c99610> TYPE `Repository`}
55+
[oso][trace] APPLICABLE_RULES:
56+
[oso][trace] has_relation(_user: User{}, "owner", _repository: Repository{}) at line 10, column 5
57+
[oso][trace] TraceRule(...)
58+
[oso][trace] RULE: has_relation(_user: User{}, "owner", _repository: Repository{});
59+
[oso][trace] TraceStackPush
60+
[oso][trace] Unify(_actor_11, __user_19)
61+
[oso][trace] ⇒ bind: _actor_11 ← __user_19
62+
[oso][trace] Isa(__user_19, User{})
63+
[oso][trace] MATCHES: __user_19 matches User{}, BINDINGS: {__user_19 => <__main__.User object at 0x7f0013c99640> TYPE `User`}
64+
[oso][trace] Isa(<__main__.User object at 0x7f0013c99640> TYPE `User`, User{})
65+
[oso][trace] MATCHES: <__main__.User object at 0x7f0013c99640> TYPE `User` matches User{}, BINDINGS: {}
66+
[oso][trace] IsaExternal { instance: Term { source_info: Ffi, value: ExternalInstance(ExternalInstance { instance_id: 14, constructor: None, repr: None, class_repr: Some("User") }) }, literal: InstanceLiteral { tag: Symbol("User"), fields: Dictionary { fields: {} } } }
67+
[oso][trace] ⇒ bind: _isa_21 ← false
68+
[oso][trace] Unify(_isa_21, true)
69+
[oso][trace] Unify(true, true)
70+
[oso][trace] Isa(<__main__.User object at 0x7f0013c99640> TYPE `User`, {})
71+
[oso][trace] MATCHES: <__main__.User object at 0x7f0013c99640> TYPE `User` matches {}, BINDINGS: {}
72+
[oso][trace] Unify("owner", "owner")
73+
[oso][trace] Unify(_repository_12, __repository_20)
74+
[oso][trace] ⇒ bind: _repository_12 ← __repository_20
75+
[oso][trace] Isa(__repository_20, Repository{})
76+
[oso][trace] MATCHES: __repository_20 matches Repository{}, BINDINGS: {__repository_20 => <__main__.Repository object at 0x7f0013c99610> TYPE `Repository`}
77+
[oso][trace] Isa(<__main__.Repository object at 0x7f0013c99610> TYPE `Repository`, Repository{})
78+
[oso][trace] MATCHES: <__main__.Repository object at 0x7f0013c99610> TYPE `Repository` matches Repository{}, BINDINGS: {}
79+
[oso][trace] IsaExternal { instance: Term { source_info: Ffi, value: ExternalInstance(ExternalInstance { instance_id: 15, constructor: None, repr: None, class_repr: Some("Repository") }) }, literal: InstanceLiteral { tag: Symbol("Repository"), fields: Dictionary { fields: {} } } }
80+
[oso][trace] ⇒ bind: _isa_22 ← false
81+
[oso][trace] Unify(_isa_22, true)
82+
[oso][trace] Unify(true, true)
83+
[oso][trace] Isa(<__main__.Repository object at 0x7f0013c99610> TYPE `Repository`, {})
84+
[oso][trace] MATCHES: <__main__.Repository object at 0x7f0013c99610> TYPE `Repository` matches {}, BINDINGS: {}
85+
[oso][trace] Query((true))
86+
[oso][trace] TraceStackPush
87+
[oso][trace] TraceStackPop
88+
[oso][trace] PopQuery((true))
89+
[oso][trace] TraceStackPop
90+
[oso][trace] TraceStackPop
91+
[oso][trace] PopQuery(has_relation(_actor_11, "owner", _repository_12))
92+
[oso][trace] TraceStackPop
93+
[oso][trace] PopQuery(has_relation(_actor_11, "owner", _repository_12))
94+
[oso][trace] TraceStackPop
95+
[oso][trace] TraceStackPop
96+
[oso][trace] PopQuery(has_permission(_actor_4, _action_5, _resource_6))
97+
[oso][trace] TraceStackPop
98+
[oso][trace] PopQuery(has_permission(_actor_4, _action_5, _resource_6))
99+
[oso][trace] TraceStackPop
100+
[oso][trace] TraceStackPop
101+
[oso][trace] PopQuery(allow(<__main__.User object at 0x7f0013c99640> TYPE `User`, "view", <__main__.Repository object at 0x7f0013c99610> TYPE `Repository`))
102+
[oso][info] RESULT: SUCCESS
103+
True
104+
[oso][trace] Query(allow(<__main__.User object at 0x7f0013c99640> TYPE `User`, "view", <__main__.Project object at 0x7f0013c99310> TYPE `UNKNOWN`))
105+
[oso][info] QUERY RULE: allow(<__main__.User object at 0x7f0013c99640> TYPE `User`, "view", <__main__.Project object at 0x7f0013c99310> TYPE `UNKNOWN`), BINDINGS: {}
106+
[oso][info] APPLICABLE_RULES:
107+
[oso][info] allow(actor, action, resource) at line 11, column 5
108+
[oso][trace] TraceRule(...)
109+
[oso][trace] RULE: allow(actor, action, resource) if has_permission(actor, action, resource);
110+
[oso][trace] TraceStackPush
111+
[oso][trace] Unify(<__main__.User object at 0x7f0013c99640> TYPE `User`, _actor_26)
112+
[oso][trace] ⇒ bind: _actor_26 ← <__main__.User object at 0x7f0013c99640> TYPE `User`
113+
[oso][trace] Unify("view", _action_27)
114+
[oso][trace] ⇒ bind: _action_27 ← "view"
115+
[oso][trace] Unify(<__main__.Project object at 0x7f0013c99310> TYPE `UNKNOWN`, _resource_28)
116+
[oso][trace] ⇒ bind: _resource_28 ← <__main__.Project object at 0x7f0013c99310> TYPE `UNKNOWN`
117+
[oso][trace] Query(has_permission(_actor_26, _action_27, _resource_28))
118+
[oso][trace] TraceStackPush
119+
[oso][trace] Query(has_permission(_actor_26, _action_27, _resource_28))
120+
[oso][info] QUERY RULE: has_permission(_actor_26, _action_27, _resource_28), BINDINGS: {_action_27 => "view", _actor_26 => <__main__.User object at 0x7f0013c99640> TYPE `User`, _resource_28 => <__main__.Project object at 0x7f0013c99310> TYPE `UNKNOWN`}
121+
[oso][info] No matching rules found
122+
False
123+
124+

‎docs/content/any/reference/tooling/tracing.md

+20-50
Original file line numberDiff line numberDiff line change
@@ -7,67 +7,37 @@ description: Polar tracing shows logs of how a query is evaluated.
77

88
# Tracing
99

10-
Polar tracing shows logs of how a query is evaluated.
10+
Polar's tracing support prints logs of how a query is evaluated. It is available in both `INFO` and `TRACE` level outputs.
1111

12-
## Enabling Tracing
12+
## Enabling `INFO` output
1313

14-
Debug mode is enabled by setting an environment variable: `POLAR_LOG=1`.
14+
`INFO` traces are viewed by setting the environment variable: `POLAR_LOG=info`. The `INFO` output is a more concise subset of `TRACE` and is intended to by used by those developing and debugging polar policies in their local environment.
1515

16-
It will print out `[debug]` messages during query evaluation that show how the query is executed.
17-
Notable things include:
16+
It will print out `[oso][info]` messages for many notable points of the query execution, for example:
1817

18+
* Queries for rules.
19+
20+
* Source information for the rules which were applicable to each query, and a warning if none were found to be applicable.
21+
22+
* Query successes and the contents of any variable bindings returned by Oso.
23+
24+
## Enabling `TRACE` output
1925

20-
* Queries and sub-query evaluations.
26+
`TRACE` logs are viewed by setting an environment variable: `POLAR_LOG=trace`.
2127

28+
`POLAR_LOG=trace` exposes a more verbose view of a query execution in Polar and extends the contents of `POLAR_LOG=info`. The `POLAR_LOG=trace` traces will emit a log for every Goal encountered by the Polar virtual machine during the query execution. Notable examples include:
2229

23-
* Showing values that are bound to variables for each expression.
24-
25-
26-
* Showing which rules a Polar predicate call will evaluate.
30+
* Showing parameter type checking information during query applicability tests.
2731

32+
* Showing values that are bound to variables for each expression.
2833

2934
* Showing values returned from calls into the application.
3035

36+
* All query evaluations; not limited to rules like `POLAR_LOG=info`.
37+
3138
### Example
3239

33-
```
34-
query> f(12);
35-
[debug] QUERY: f(12), BINDINGS: {}
36-
[debug] APPLICABLE_RULES: [
37-
[debug] f(x) if new (Foo{x: x}, _instance_2) and .(_instance_2, foo(), _value_1) and _value_1 = x;
38-
[debug] f(x) if x = 1;
39-
[debug] f(x) if x + 1 and _op_3 == 2;
40-
[debug] ]
41-
[debug] RULE:
42-
[debug] f(x) if
43-
[debug] new Foo(x: x).foo() = x
44-
[debug] QUERY: new (Foo{x: _x_10}, _instance_2_11) and .(_instance_2_11, foo(), _value_1_12) and _value_1_12 = _x_10, BINDINGS: {"_x_10": "12"}
45-
[debug] QUERY: new (Foo{x: _x_10}, _instance_2_11), BINDINGS: {"_x_10": "12"}
46-
[debug] QUERY: .(_instance_2_11, foo(), _value_1_12) and _value_1_12 = _x_10, BINDINGS: {"_instance_2_11": "Foo{x: 12}", "_x_10": "12"}
47-
[debug] QUERY: .(_instance_2_11, foo(), _value_1_12), BINDINGS: {"_instance_2_11": "Foo{x: 12}"}
48-
[debug] LOOKUP: Foo{x: 12}.foo()
49-
[debug] => 13
50-
[debug] QUERY: _value_1_12 = _x_10, BINDINGS: {"_x_10": "12", "_value_1_12": "13"}
51-
[debug] BACKTRACK
52-
[debug] LOOKUP: Foo{x: 12}.foo()
53-
[debug] => No more results.
54-
[debug] BACKTRACK
55-
[debug] RULE:
56-
[debug] f(x) if
57-
[debug] x = 1
58-
[debug] QUERY: _x_13 = 1, BINDINGS: {"_x_13": "12"}
59-
[debug] BACKTRACK
60-
[debug] RULE:
61-
[debug] f(x) if
62-
[debug] x + 1 == 2
63-
[debug] QUERY: _x_14 + 1 and _op_3_15 == 2, BINDINGS: {"_x_14": "12"}
64-
[debug] QUERY: _x_14 + 1, BINDINGS: {"_x_14": "12"}
65-
[debug] MATH: 12 + 1 = _op_3_15, BINDINGS: {}
66-
[debug] QUERY: _op_3_15 == 2, BINDINGS: {"_op_3_15": "13"}
67-
[debug] CMP: 13 == 2, BINDINGS: {}
68-
[debug] BACKTRACK
69-
[debug] HALT
70-
False
71-
```
40+
{{<literalInclude path="reference/tooling/info" tabGroup="tracing">}}
41+
{{<literalInclude path="reference/tooling/trace" tabGroup="tracing">}}
7242

73-
Debug mode can be disabled by setting `POLAR_LOG=0` or `POLAR_LOG=off`.
43+
All `POLAR_LOG` output can be disabled by setting `POLAR_LOG=0` or `POLAR_LOG=off`.

‎languages/go/internal/host/host.go

+2
Original file line numberDiff line numberDiff line change
@@ -362,10 +362,12 @@ func (h Host) ToPolar(v interface{}) (*Value, error) {
362362
return nil, err
363363
}
364364
repr := fmt.Sprintf("%T%+v", v, v)
365+
classRepr := fmt.Sprintf("%T", v)
365366
inner := ValueExternalInstance{
366367
InstanceId: *instanceID,
367368
Constructor: nil,
368369
Repr: &repr,
370+
ClassRepr: &classRepr,
369371
}
370372
return &Value{inner}, nil
371373
}

‎languages/go/types/polar_types.go

+2
Original file line numberDiff line numberDiff line change
@@ -317,6 +317,8 @@ type ExternalInstance struct {
317317
Constructor *Term `json:"constructor"`
318318
// Repr
319319
Repr *string `json:"repr"`
320+
// Class Repr
321+
ClassRepr *string `json:"class_repr"`
320322
}
321323

322324
// FormattedPolarError struct

‎languages/java/oso/src/main/java/com/osohq/oso/Host.java

+12
Original file line numberDiff line numberDiff line change
@@ -281,6 +281,18 @@ public JSONObject toPolarTerm(Object value) throws Exceptions.OsoException {
281281

282282
attrs.put("instance_id", cacheInstance(value, instanceId));
283283
attrs.put("repr", value == null ? "null" : value.toString());
284+
285+
// pass a class_repr string *for registered types only*
286+
if (value != null) {
287+
Class classFromValue = value.getClass();
288+
String stringifiedClassFromValue = classFromValue.toString();
289+
stringifiedClassFromValue =
290+
classIds.containsKey(classFromValue) ? stringifiedClassFromValue : "null";
291+
attrs.put("class_repr", stringifiedClassFromValue);
292+
} else {
293+
attrs.put("class_repr", "null");
294+
}
295+
284296
jVal.put("ExternalInstance", attrs);
285297
}
286298

‎languages/js/src/Host.ts

+11-1
Original file line numberDiff line numberDiff line change
@@ -508,13 +508,23 @@ export class Host implements Required<DataFilteringQueryParams> {
508508
default: {
509509
let instanceId: number | undefined = undefined;
510510
if (isConstructor(v)) instanceId = this.getType(v)?.id;
511+
512+
// pass a string class repr *for registered types only*, otherwise pass
513+
// undefined (allow core to differentiate registered or not)
514+
const v_cast = v as NullishOrHasConstructor;
515+
let classRepr: string | undefined = v_cast?.constructor?.name;
516+
if (classRepr !== undefined && !this.types.has(classRepr)) {
517+
classRepr = undefined;
518+
}
519+
511520
const instance_id = this.cacheInstance(v, instanceId);
512521
return {
513522
value: {
514523
ExternalInstance: {
515524
instance_id,
516-
repr: repr(v),
517525
constructor: undefined,
526+
repr: repr(v),
527+
class_repr: classRepr,
518528
},
519529
},
520530
};

‎languages/js/src/types.ts

+1
Original file line numberDiff line numberDiff line change
@@ -179,6 +179,7 @@ interface PolarInstance {
179179
ExternalInstance: {
180180
instance_id: number;
181181
repr: string;
182+
class_repr?: string;
182183
constructor?: PolarTerm;
183184
};
184185
}

0 commit comments

Comments
 (0)