Logging
This page details how logging works in Insights Enterprise.
The query path in kdb Insights and Enterprise works as follows (see Overview):
-
A Gateway (GW) receives the request and sends to a Resource Coordinator (RC).
-
The RC receives the request and sends to other RCs and/or to Data Access Processes (DAPs).
-
DAPs execute their request individual portions and send their partial responses to an Aggregator (Agg).
-
Agg awaits responses from all DAPs. Once all responses are in, it aggregates and sends the response back to the GW.
-
The GW returns the response to the caller.
Each process logs various messages at each step of the query path. In this page, we go through all relevant log messages for a successful query. If you run into any issues, refer to Troubleshooting for steps to follow when attempting to debug.
Pre-request logs
Before a request can be successfully executed, all processes must connect and, in some cases, register as available with the RC. The logs can be used to verify that all handshaking has been done successfully. Details on how to configure connections between each process can be found in resiliency configuration.
Gateway to resource coordinator
The GWs open connection(s) to their configured RC(s). The log messages surrounding this depend on the configured GW-RC connection method.
Environment variable
Kubernetes control plane
Note that the GW may emit one or more WARN messages if the RC has not yet come up.
text
[main] INFO com.kx.sg.kxi.IPCService - Connecting to resource coordinator KXI_SG_RC_ADDR=10.244.0.64:5050
[main] INFO com.kx.sg.kxi.IPCService - Connecting to coordinator 10.244.0.64:5050
[main] WARN com.kx.sg.kxi.IPCService - Coordinator connection establish error: java.net.UnknownHostException: 10.244.0.64. Will try again in 5 seconds...
...
[main] INFO com.kx.sg.kxi.IPCService - Connected to coordinator 10.244.0.64:5050
text
[main] INFO com.kx.sg.kxi.IPCService - Initializing pod watcher for resource-coordinators="app.kubernetes.io/name=resource-coordinator"
[pool-2-thread-1] INFO com.kx.sg.KubernetesWatcher - Initial pods found against resourceVersion=4141992, labelSelector=app.kubernetes.io/name=resource-coordinator
[pool-2-thread-1] INFO com.kx.sg.kxi.IPCService - Connecting to coordinator id=sg-rc-0, hostport=10.244.0.64:5050
[pool-2-thread-1] INFO com.kx.sg.kxi.IPCService - Connected to coordinator id=sg-rc-0, hostport=10.244.0.64:5050
Once the GW establishes a connection with an RC, it checks that the RC is ready to receive requests (the RC is ready if it has at least one Agg registered, see Aggregator to resource coordinator).
text
[pool-2-thread-1] DEBUG com.kx.sg.tasks.CoordinatorTask - Checking if coordinator=10.244.0.64:5050 is ready for service
[pool-2-thread-1] DEBUG com.kx.sg.tasks.CoordinatorTask - Coordinator 10.244.0.64:5050 is ready for service
Data access process to resource coordinator
DAPs open a connection to their RC. The log messages surrounding this depend on the configured DAP-RC connection method.
Environment variable
Package
RC endpoint defined by environment variable, KXI_SG_RC_ADDR=%s
text
[rdb] INFO DA RC endpoint defined by environment variable, KXI_SG_RC_ADDR=sg-rc-0.sg-rc.default.svc:5050
[rdb] INFO DA Initializing RC connection, rc=`sg-rc-0.sg-rc.default.svc:5050
text
[rdb] INFO DA Initializing RC connection, rc=`sg-rc-0.sg-rc.default.svc:5050
Once the RC is found, the DAP establishes a connection to the RC. The DAP may emit one or more WARN messages if the RC has not come up yet.
text
[rdb] INFO DA Attempting connection to RC...
[rdb] DEBUG DA Opening connection to rc at :sg-rc-0.sg-rc.default.svc:5050
[rdb] WARN DA Error opening connection to rc at :sg-rc-0.sg-rc.default.svc:5050 err=...
[rdb] WARN DA Failed connection retry to RC, retrying in 0D00:00:05...
...
[rdb] DEBUG DA Opening connection to rc at :sg-rc-0.sg-rc.default.svc:5050
[rdb] INFO DA Connected to RC on 9
[rdb] DEBUG DA RC connection table: `rc`addr`handle`retry [1]: (`sg-rc-0.sg-rc.default.svc:5050,`:sg-rc-0.sg-rc.default.svc:5050,9i,1b)
Once the connection is established, the DAP registers with the RC. The RC accepts the registration (if valid) and establishes heartbeating .
text
[KXI-SG-RC-sg-rc-0] DEBUG SGRC DAP registration details, handle=11 asm=canada instance=rdb addr=:da-rdb-canada-0:5080 avail=... refVintage=... purview=...
[KXI-SG-RC-sg-rc-0] TRACE SGRC DAP registration details, handle=11 metadata=...
[KXI-SG-RC-sg-rc-0] INFO SGRC Registering valid DAP, handle=11 asm=canada instance=rdb addr=:da-rdb-0:5080
[KXI-SG-RC-sg-rc-0] DEBUG KXAPIHB Adding heartbeat, handle=11
Note that in the registration details is a field avail=..., which specifies the DAP's availability. If avail=Y, the DAP is ready to service queries immediately. If avail=N, the DAP is still waiting on a readiness condition. A log message of the following form should appear some time later.
text
[KXI-SG-RC-sg-rc-0] DEBUG SGRC Received DAP update, handle=11 dets=[=`;avail=1b]
Aggregator to resource coordinator
Aggregators open a connection to their RC.
Once the RC is found, or if it is configured using an environment variable, the aggregator connects to the RC, establishes heartbeating, and registers with the RC. Note that the aggregator may emit one or more WARN messages if the RC has not come up yet.
text
[KXI-SG-AGG-sg-agg-0-0] INFO SGAGG Attempting to register with RC, hp=:sg-rc-0.sg-rc.default.svc:5050
[KXI-SG-AGG-sg-agg-0-0] WARN SGAGG Unable to hopen to, proc=RC addr=:sg-rc-0.sg-rc.default.svc error=...
[KXI-SG-AGG-sg-agg-0-0] WARN SGAGG Unable to connect to RC
...
[KXI-SG-AGG-sg-agg-0-0] INFO SGAGG Connected to RC, handle=7
[KXI-SG-AGG-sg-agg-0-0] DEBUG KXAPIHB Adding heartbeat, handle=7
[KXI-SG-AGG-sg-agg-0-0] INFO SGAGG Sending metadata to RC, handle=7
[KXI-SG-AGG-sg-agg-0-0] TRACE SGAGG Sending to RC: (`.sgrc.registerAgg;`10.244.0.241;5070i;...
The RC accepts the registration and establishes its own heartbeat.
text
[KXI-SG-RC-sg-rc-0] INFO SGRC Registering Agg, host=10.244.0.241 port=5070 handle=7
[KXI-SG-RC-sg-rc-0] DEBUG KXAPIHB Adding heartbeat, handle=7
Request logs
To each request, we associate a log correlator. This correlator appears in every log message related to the request (unless noted otherwise), which allows users to easily search through logs to trace their request at each point along the query path. The log correlator can be set explicitly by the caller as an optional argument. If not specified, the log correlator is a random GUID assigned by the GW at request time. In this case, the user does not know the log correlator ahead of time, but it can be found in the response header. Moreover, by default, requests are logged at the DEBUG or TRACE level in order to prevent logging from having a performance impact on production systems. In general, verbose messages or messages containing sensitive information is only logged at the TRACE level, not at the DEBUG level. Users can use the following parameters that control the log correlator and log level behavior.
|
parameter |
description |
|---|---|
|
|
Used at the debug/trace levels. |
|
|
Used to enable info-level logs. |
The logCorr parameter overrides the default random GUID assigned by the GW. That is, all DEBUG or TRACE messages use the string specified by logCorr rather than a random GUID. The auditID parameter is used to trigger INFO level messages on receipt of a request in each process. If auditID is specified, but logCorr is not specified, then auditID is used as the log correlator for the debug/trace log messages as well. If both auditID and logCorr are specified, then auditID is used for INFO level log messages, and logCorr is used for DEBUG and TRACE level log messages.
The following sections describe the log messages emitted by the various processes along the query path. In the sections below, we use a call to .kxi.getData with log correlator logExample. For readability, log messages displayed here are in text format. See JSON for notes on logs in JSON format.
Gateway
The GW logs messages on receipt of a request from a caller, then on receipt of the response from the Agg.
Note
If specifying logCorr or auditID in the request opts, the logs display it. If undefined, it uses the unique GUID (the correlator) assigned to the request.
text
DEBUG com.kx.sg.kxi.HTTPRCWorker - HTTP method=POST uri=/kxi/getData sender=<address> assigned to request=c74b66f3-b547-4be1-bb5c-e611568ab007
DEBUG com.kx.sg.tasks.RCRequestBuilder - Request=c74b66f3-b547-4be1-bb5c-e611568ab007 has been assigned logging correlator='logExample' from auditId
INFO com.kx.sg.tasks.RCRequestBuilder - Request='logExample' for api=.kxi.getData over HTTP method=POST, path=/kxi/getData, user=<id>, auditId=logExample, from=<address>
DEBUG com.kx.sg.kxi.RcSet - Getting next coordinator, assembly=
DEBUG com.kx.sg.kxi.RcSet - Got coordinator, id=sg-rc-0.sg-rc.default.svc:5050 assembly=
DEBUG com.kx.sg.kxi.HTTPRCWorker - Selected coordinator=sg-rc-0.sg-rc.default.svc:5050 to service request=logExample
...
DEBUG com.kx.sg.tasks.ResponderTask - Responding to request=logExample, responder=aggregator 10.244.0.146:30000
Resource coordinator
The RC logs messages related to the state and routing of the request. In the case that a request can be immediately allocated to DAPs, logs for an incoming request are as follows. Note that the only parameters displayed at the DEBUG level are startTS and endTS, whereas the full list of parameters is displayed at the TRACE level.
text
[KXI-SG-RC-sg-rc-0] DEBUG SGRC {logExample} Received request for resources, api=.kxi.getData time=[startTS=2021.02.28D00:00:00.000000000;endTS=2021.03.02D00:00:00.000000000]
[KXI-SG-RC-sg-rc-0] TRACE SGRC {logExample} Request: hdr=[rcvTS=2022.12.15D21:01:43.535000000;corr=c74b66f3-b547-4be1-bb5c-e611568ab007;protocol=`gw;logCorr="logExample";client=`:10.244.0.144:30000;api=`.kxi.getData;timeout=30000] args=[table=`trade;startTS=2021.02.28D00:00:00.000000000;endTS=2021.03.02D00:00:00.000000000;filter=,("=";`sym;`ABC)]
[KXI-SG-RC-sg-rc-0] DEBUG SGRC {logExample} Getting resources
[KXI-SG-RC-sg-rc-0] DEBUG SGRC {logExample} Selected agg to service request, agg=:10.244.0.146:5070
[KXI-SG-RC-sg-rc-0] DEBUG SGRC {logExample} Allocating resources, client=:10.244.0.144:30000 daps=`:da-hdb-canada-5dbbf9f78-dfcfl:5100`:da-rdb-canada-577fd89557-b2gfh:5080`:da-idb-canada-766c6bdbfb-jjh5s:5090
[KXI-SG-RC-sg-rc-0] TRACE SGRC {logExample} Sending to DAPs, rcs=+`dap`hdr`args`pvID`rpID`refVintage!(`:da-hdb-0:5100`:da-rdb-canada-0:5080`:da-idb-0:5090;...
In the case that a portion of the request must be queued, the RC emits the following logs when queuing and dequeueing the request portion.
text
[KXI-SG-RC-sg-rc-0] DEBUG SGRC {logExample} Enqueuing 1 request portion
[KXI-SG-RC-sg-rc-0] DEBUG SGRC {logExample} Storing new request in allocating status
...
[KXI-SG-RC-sg-rc-0] TRACE SGRC {logExample} Attempting dequeue, dap=:da-hdb-0:5100 q=[idx=0;corr=52ae6a7e-935a-46c2-a360-6d971b5a94d7;api=`.kxi.getData;ts=2022.12.15D21:02:35.014882200;rpID=0;anyPV=0b;pvID=1;ogStartTS=2021.02.28D00:00:00.000000000;startTS=2021.02.28D00:00:00.000000000;ogEndTS=2021.03.01D00:00:00.000000000;endTS=2021.03.01D00:00:00.000000000;refVintage=2022121500000000039]
[KXI-SG-RC-sg-rc-0] DEBUG SGRC {logExample} Dequeueing request, dap=:da-hdb-0:5100 q=[idx=0;corr=76a7c250-c0be-40be-b589-37cff4075a06;api=`.kxi.getData;ts=2022.12.15D21:02:35.014882200;rpID=0;anyPV=0b;pvID=1;ogStartTS=2021.02.28D00:00:00.000000000;startTS=2021.02.28D00:00:00.000000000;ogEndTS=2021.03.01D00:00:00.000000000;endTS=2021.03.01D00:00:00.000000000;refVintage=2022121500000000039]
[KXI-SG-RC-sg-rc-0] TRACE SGRC {logExample} Sending to DAP, rcs=[dap=`:da-hdb-0:5100;...
[KXI-SG-RC-sg-rc-0] DEBUG SGRC {logExample} Switching request status from allocating to executing
Once the request is distributed, DAPs respond with "partial response" notifications and the Agg responds with a "complete response" notification. Note that these may appear in any order.
text
[KXI-SG-RC-sg-rc-0] DEBUG SGRC {logExample} Received partial response, dap=:da-rdb-0:5080 rc=0 ac=0 ai=
[KXI-SG-RC-sg-rc-0] DEBUG SGRC {logExample} Received partial response, dap=:da-hdb-0:5100 rc=0 ac=0 ai=
[KXI-SG-RC-sg-rc-0] DEBUG SGRC {logExample} Received partial response, dap=:da-idb-0:5090 rc=0 ac=0 ai=
[KXI-SG-RC-sg-rc-0] DEBUG SGRC {logExample} Received complete response, rc=0 ac=0 agg=:10.244.0.146:5070
Data access processes
The DAPs print log messages related to executing the API on the database.
text
[rdb] DEBUG DA {logExample} Executing .kxi.getData
[rdb] DEBUG LOG {logExample} GetData called for table=trade at timestamps=2021.03.01D11:59:59.500000001 2021.03.02D00:00:00.000000000
[rdb] DEBUG DA {logExample} Completed .kxi.getData, rc=0 ac=0 ai=
[rdb] DEBUG DA {logExample} Sending response to aggregator, agg=:10.244.0.146:5070
Aggregator
The Agg prints log messages on receipt of partial responses from the DAPs and, once all responses have been received, it logs details about the aggregation.
text
[KXI-SG-AGG-sg-agg-0-0] DEBUG SGAGG {logExample} Received partial response
[KXI-SG-AGG-sg-agg-0-0] TRACE SGAGG {logExample} Checking request status, counts=[pl=1;hdr=...
[KXI-SG-AGG-sg-agg-0-0] DEBUG SGAGG {logExample} Received partial response
[KXI-SG-AGG-sg-agg-0-0] TRACE SGAGG {logExample} Checking request status, counts=[pl=2;hdr=...
[KXI-SG-AGG-sg-agg-0-0] DEBUG SGAGG {logExample} Received partial response
[KXI-SG-AGG-sg-agg-0-0] TRACE SGAGG {logExample} Checking request status, counts=[pl=3;hdr=...
[KXI-SG-AGG-sg-agg-0-0] DEBUG SGAGG {logExample} All portions/responses received, triggering aggregation
[KXI-SG-AGG-sg-agg-0-0] DEBUG SGAGG {logExample} Aggregating, api=.kxi.getData aggFn=.sgagg.getData numResp=3
[KXI-SG-AGG-sg-agg-0-0] DEBUG SGAGG {logExample} Finished aggregation, rc=0 ac=0 ai=
[KXI-SG-AGG-sg-agg-0-0] DEBUG SGAGG {logExample} Completing request
[KXI-SG-AGG-sg-agg-0-0] DEBUG SGAGG {logExample} Sending response to client, addr=:10.244.0.144:30000
[KXI-SG-AGG-sg-agg-0-0] TRACE SGAGG {logExample} Sending to RC: (`.sgrc.onComplete;...
Specifying logCorr and auditID
The logCorr and auditID parameters can be specified as opts.
q
Rest
q
args: enlist[`table]!enlist `myTable;
// logCorr.
opts: enlist[`logCorr]!enlist "logExample";
// auditID.
opts: enlist[`auditID]!enlist "logExample";
GATEWAY (`.kxi.getData; args; `; opts)
bash
# logCorr.
curl -X POST "$GATEWAY/data" \
-H "Content-Type: application/json" \
-H "Accept: application/json" \
-H "Authorization: Bearer $INSIGHTS_TOKEN" \
-d "$(jq -n \
'{
table : "myTable",
opts : {"logCorr": "logExample"}
}' | jq -cr .)"
# auditID.
curl -X POST "$GATEWAY/data" \
-H "Content-Type: application/json" \
-H "Accept: application/json" \
-H "Authorization: Bearer $INSIGHTS_TOKEN" \
-d "$(jq -n \
'{
table : "myTable",
opts : {"auditID": "logExample"}
}' | jq -cr .)"Alternatively, auditID can be specified as an HTTP header under the AUDIT-ID key.
bash
curl -X POST "$GATEWAY/data" \
-H "Content-Type: application/json" \
-H "Accept: application/json" \
-H "Authorization: Bearer $INSIGHTS_TOKEN" \
-H "AUDIT-ID: logExample" \
-d "$(jq -n \
'{
table : "myTable",
}' | jq -cr .)"JSON logs
If the log format is set to JSON (default), then log messages are printed as JSON objects. The log correlator appears as the corr key in the JSON object for RC/DAP/Agg processes. For example,
JSON
{"time":"2024-10-31T18:04:11.497z","corr":"logExample","component":"SGRC","level":"DEBUG","message":"[KXI-SG-RC-sg-rc-0] Received request for resources, api=.kxi.getData time=[]"}
For the GW, the default log formatting is in text format. JSON logs can be enabled by configuring logback.xml. Use the provided com.kx.sg.KxiJsonLayout:
JSON
<configuration>
<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
<encoder class="ch.qos.logback.core.encoder.LayoutWrappingEncoder">
<layout class="com.kx.sg.KxiJsonLayout"/>
</encoder>
</appender>
<root level="WARN">
<appender-ref ref="STDOUT" />
</root>
</configuration>
Only the following message is logged with the corr key in the log message and only if auditID is specified:
JSON
{"corr":"logExample","component":"Audit","level":"INFO","logger":"com.kx.sg.tasks.RCRequestBuilder","time":"2024-11-01 20:11:20.917","thread":"nioEventLoopGroup-3-3","message":"Request='myAuditID2' for api=.kxi.getData over HTTP method=POST, path=/kxi/getData, user=***, auditId=logExample, from=ip-10-244-0-1.us-east-2.compute.internal:47983"}
Similarly, DAP, RC and Agg process log formatting can be configured for json format by setting the environment variable KXI_LOG_FORMAT to json.
Sample RC logging:
JSON
{"time":"2024-11-01T20:11:20.930z","corr":"logExample","component":"Audit","level":"INFO","message":"Executing api=.kxi.getData userID=*** auditID=logExample logCorr=myAuditID2"}
Sample DAP logging:
JSON
{"time":"2024-11-01T20:11:20.941z","corr":"logExample","component":"Audit","level":"INFO","message":"Executing api=.kxi.getData userID=*** auditID=logExample logCorr=myAuditID2"}
Sample Agg logging:
JSON
{"time":"2024-11-01T20:11:20.959z","corr":"logExample","component":"Audit","level":"INFO","message":"Executing api=.kxi.getData userID=*** auditID=logExample logCorr=myAuditID2"}
Note that if using a different encoder/layout in the GW, corr is contained in the key-value pair of the log event and component="Audit".