Log Entry Format

Each log entry is always output on a single line and the format of the log entry varies depending on its source. Note that the logging lines in the figures below are wrapped over two lines for clarity.

Dynamic/On-Demand Logging

Log entries consist of two parts:

  1. Header includes:

    T - Timestamp

    C - Context: [engine-type] host:port [start-id] [process-id (pid)] [node-id] PROCESS_STATE

  2. Content includes:

    L - ⇒ [Logging level,Logging category]

    M - A message dependent on logging category

On-Demand Log Format
Figure 1. On-Demand Log Format

Here is the logging generated when selecting from a non-existant table:

$> nuocmd show log-messages --db-name DBNAME --log-options sql-statements
2021-06-27T13:54:49.121: [TE] server-0:48006 [start_id = 7] [pid = 142] [node_id = 2] MONITORED:RUNNING =>[debug,sql-statements] [33,5363842]:select * from accounts; threw exception can't find table "ACCOUNTS" after 3220 micros
2021-06-27T13:54:49.121: [TE] server-0:48006 [start_id = 7] [pid = 142] [node_id = 2] MONITORED:RUNNING =>[debug,sql-statements] [33]: Txn 5363842 rolled back in 0 ms, open for 3 ms

Default Logging

AP Logging

  1. Header includes:

    T - Timestamp

    C - Context: LOGGING-LEVEL, [AP Server Host:Thread-id] (host my be empty)

  2. Content:

    M - A message dependent on logging category

All of these are actually the same format, but they look different enough to confuse.

AP Log Format
Figure 2. AP Log Formats

Here is the logging generated by nuoadmin in response to nuocmd show domain. Note that in the first line dw-3651 - POST /api/1/diagnostics/log is all the thread-id.

2021-06-27T13:49:28.059+0000 INFO  [:dw-3651 - POST /api/1/diagnostics/log] DiagnosticsResource 7cbfadbb1e38e8ee0d2d2494d8eaddcdfee9fd28
2021-06-27T13:49:28.060+0000 INFO  [:dw-3651] RequestLog 127.0.0.1 - - [27/Jun/2021:13:49:28 +0000] "POST /api/1/diagnostics/log HTTP/1.1" 200 121 "-" "python-requests/2.24.0" 2
2021-06-27T13:49:28.063+0000 INFO  [:dw-3653] RequestLog 127.0.0.1 - - [27/Jun/2021:13:49:28 +0000] "GET /api/1/peers HTTP/1.1" 200 330 "-" "python-requests/2.24.0" 1
2021-06-27T13:49:28.066+0000 INFO  [:dw-3654] RequestLog 127.0.0.1 - - [27/Jun/2021:13:49:28 +0000] "GET /api/1/databases HTTP/1.1" 200 189 "-" "python-requests/2.24.0" 1
2021-06-27T13:49:28.070+0000 INFO  [:dw-3651] RequestLog 127.0.0.1 - - [27/Jun/2021:13:49:28 +0000] "GET /api/1/processes HTTP/1.1" 200 599 "-" "python-requests/2.24.0" 2

TE/SM Logging

  1. Header includes:

    T - Timestamp

    C - Context: [process-id] (database-name, sid sss, node nnn) where sss is the start-id and nnn is the node-id

  2. Content:

    M - A message dependent on logging category

Engine logging has a slightly different format again:

TE/SM Log Format
Figure 3. Engine Log Format

Here is an example of the output when a new TE is started:

2021-06-30T16:34:56.882+0000 [5645] (testdb sid 10 node -1) Starting Transaction Engine 4.2.vee-4-cc1ec70747: database=testdb, startId=10, protocol=1.1441792.cc1ec70747 (4.2)
2021-06-30T16:34:56.884+0000 [5645] (testdb sid 10 node -1) Configuration parameters: --start-id 10 --database testdb --dba-user dba --node-port 48006 --agent-port 48004 --verbose error,warn --nuodb-home-dir /opt/nuodb --geo-region 0 --user-data {"incarnation":{"major":4,"minor":1},"startId":"10","labels":{}} --read-stdin
2021-06-30T16:34:56.884+0000 [5645] (testdb sid 10 node -1) TLS Support DISABLED
2021-06-30T16:34:56.884+0000 [5645] (testdb sid 10 node -1) Default SQL Engine: Vectorized
2021-06-30T16:34:56.884+0000 [5645] (testdb sid 10 node -1) Allowing 1048326 client connections based on system setting of 1048576
2021-06-30T16:34:56.884+0000 [5645] (testdb sid 10 node -1) Data encryption capability not available
2021-06-30T16:34:57.740+0000 [5645] (testdb sid 10 node -1) server-0:48009: Entering database via node server-0:48007
2021-06-30T16:34:58.742+0000 [5645] (testdb sid 10 node -1) server-0:48009: Entering database via node server-0:48006
2021-06-30T16:34:58.748+0000 [142] (testdb sid 7 node 2) Change in inter-node network detected by node 2 (TE), node list now: 1 (SM), 2 (TE), 4 (TE), 5 (TE) (node registered: 5 source node: 2)
2021-06-30T16:34:58.750+0000 [5614] (testdb sid 9 node 4) Change in inter-node network detected by node 4 (TE), node list now: 1 (SM), 2 (TE), 4 (TE), 5 (TE) (node registered: 5 source node: 2)
2021-06-30T16:34:58.753+0000 [135] (testdb sid 6 node 1) Change in inter-node network detected by node 1 (SM), node list now: 1 (SM), 2 (TE), 4 (TE), 5 (TE) (node registered: 5 source node: 2)
2021-06-30T16:34:58.751+0000 [5645] (testdb sid 10 node 5) Change in inter-node network detected by node 5 (TE), node list now: 1 (SM), 2 (TE), 4 (TE), 5 (TE) (nodes registered: 1, 2, 4, 5 source node: 2)
2021-06-30T16:34:58.752+0000 [5645] (testdb sid 10 node 5) Database entered: effective version 1441792 (4.2)
2021-06-30T16:34:58.752+0000 [5645] (testdb sid 10 node 5) TZ from system environment: none
2021-06-30T16:34:58.752+0000 [5645] (testdb sid 10 node 5) ICU TZ: UTC
2021-06-30T16:34:58.755+0000 [5645] (testdb sid 10 node 5) Ignoring --dba-user: database exists
2021-06-30T16:34:58.755+0000 [5645] (testdb sid 10 node 5) Ignoring --dba-password: database exists
2021-06-30T16:34:58.881+0000 [5645] (testdb sid 10 node 5) Number of CPUs = 4