Dynamic or On-Demand Logging

Dynamic or on-demand logging can be streamed using these NuoDB Command subcommands:

It allows additional logging to requested while the database is running, for as long as needed, until you stop it.

Logging to the Console

The logging commands referenced above do not return control back to the CLI prompt. Logging information is streamed to the console until CTRL-C is pressed to stop it.

In the examples below, the logging category sql-statements is enabled to emit information about SQL statements being executed. Assume that the following simple SQL statement was executed:

select getnodeid() from dual;

This would generate the following logging on the nuocmd show log-messages invocation:

nuocmd show log-messages --db-name DBNAME --log-options sql-statements
2021-06-27T16:04:28.374: [TE] server-0:48006 [start_id = 7] [pid = 142] [node_id = 2] MONITORED:RUNNING =>[debug,sql-statements] [34,5435266]:select getnodeid() from dual; executed in 106 micros
2021-06-27T16:04:28.374: [TE] server-0:48006 [start_id = 7] [pid = 142] [node_id = 2] MONITORED:RUNNING =>[debug,sql-statements] [34,5435266]:ResultSet[2] append 18 bytes for 1 rows in 9 micros
2021-06-27T16:04:28.375: [TE] server-0:48006 [start_id = 7] [pid = 142] [node_id = 2] MONITORED:RUNNING =>[debug,sql-statements] [34,5435266]:ResultSet[2] returned total 18 bytes for 1 rows. Open for 411 micros
2021-06-27T16:04:28.375: [TE] server-0:48006 [start_id = 7] [pid = 142] [node_id = 2] MONITORED:RUNNING =>[debug,sql-statements] [34]: Txn 5435266 committed in 0 ms, open for 0 ms
...

Here is the same output for nuocmd get log-messages. Note that it is in JSON format.

nuocmd get log-messages --db-name DBNAME --log-options sql-statements
{
  "msg": {
    "Count": "1",
    "LogMessage": "[34,5433858]:select getnodeid() from dual; executed in 813 micros",
    "Options": "debug,sql-statements",
    "Time": "2021-06-27T16:02:23.639"
  },
  "startId": "7"
}
{
  "msg": {
    "Count": "2",
    "LogMessage": "[34,5433858]:ResultSet[1] append 18 bytes for 1 rows in 14 micros",
    "Options": "debug,sql-statements",
    "Time": "2021-06-27T16:02:23.641"
  },
  "startId": "7"
}
{
  "msg": {
    "Count": "3",
    "LogMessage": "[34,5433858]:ResultSet[1] returned total 18 bytes for 1 rows. Open for 954 micros",
    "Options": "debug,sql-statements",
    "Time": "2021-06-27T16:02:23.642"
  },
  "startId": "7"
}
{
  "msg": {
    "Count": "4",
    "LogMessage": "[34]: Txn 5433858 committed in 0 ms, open for 2 ms",
    "Options": "debug,sql-statements",
    "Time": "2021-06-27T16:02:23.642"
  },
  "startId": "7"
}
...

Logging to a File

Specify --engine-file LOG_FILE_ROOT_NAME to nuocmd get log-messages or nuocmd show log-messages to log messages to a file on the database process host rather than sending the log data over the network (which can introduce overhead to the system). The command does not return, but periodically (every 10 seconds) echoes to the console the number of messages (if any) written to the file by each engine on the host. For example:

nuocmd show log-messages --db-name DBNAME --log-options sql-statements --engine-file engine-sql
2021-09-26T11:30:08.198: [TE] server-0:48006 [start_id = 7] [pid = 142] [node_id = 2] MONITORED:RUNNING =>[security,sql-statements] /var/log/nuodb/eng-testdb-sid7-6.log: Written 0 messages
2021-09-26T11:30:18.203: [TE] server-0:48006 [start_id = 7] [pid = 142] [node_id = 2] MONITORED:RUNNING =>[security,sql-statements] /var/log/nuodb/eng-testdb-sid7-6.log: Written 0 messages
2021-09-26T11:30:28.343: [TE] server-0:48006 [start_id = 7] [pid = 142] [node_id = 2] MONITORED:RUNNING =>[security,sql-statements] /var/log/nuodb/eng-testdb-sid7-6.log: Written 4 messages
...

This will create the file engine-sql-DBNAME-sid7-N.log in /var/log/nuodb/ on the host, where 7 is the process start-id and N is a unique number so that you can run the command multiple times and not overwrite previous log files. If you have multiple TEs running on the same host, a log file is created for each of them (start-ids are unique).

In this example, after 20s, four messages were written to the log. The log file can be retrieved or viewed as needed. This is a useful technique for running a known series of events and recording the logging output, which can later be shared with colleagues or NuoDB support.

Dyanamic Logging Format

The format of dynamic logging can be customized using the --log-format option.

Default Format

The default format is below (the color coding is only for matching the pattern to the output, log output is not color coded). The output is all on a single line, but these examples are wrapped for clarity.

Default format pattern
Figure 1. Default format pattern

Initiate dynamic logging for explain plans:

nuocmd show log-messages --db-name DBNAME --log-options sql-statements,sql-statement-explain-plans

Generates output like this:

2021-11-27T16:16:50.423: [TE] localhost:48006 [start_id = 5][pid = 1227] [node_id = 4] MONITORED:RUNNING=>[debug,sql-statement-explain-plans] [5,8390788]:EXPLAIN ANALYZE ... [cost: 6.00, rows: 1.00]
Matching output
Figure 2. Same output color coded

Customized Format

In many cases the default format contains more information than you need. Suppose I am doing all my testing on a single machine, VM or container. Let’s make it less verbose by removing hostname, node and process ids. To reduce long lines of output, the deliberate newline in the format string forces the actual log message, {msg[LogMessage]}, onto its own line.

nuocmd show log-messages --log-options sql-results,sql-statements  --log-format \
    "{msg[Time]}: [{engine_type}:{start_id}@{port}:{msg[Options]}]
{msg[LogMessage]}"

The output looks like this:

2021-11-28T15:35:26.112: [TE:5@48006:debug,sql-statements]
[5,17827970,DBA,USER] select * from TEST;
executed in 64 micros
2021-11-28T15:35:26.114: [TE:5@48006:info,sql-results] [5,17827970]
Columns: NAME|AGE
2021-11-28T15:35:26.114: [TE:5@48006:info,sql-results] [5,17827970]
Row 1:Fred|22
2021-11-28T15:35:26.114: [TE:5@48006:info,sql-results] [5,17827970]
Row 2:Wilma|38

Logging Pattern Fields

The logging pattern may contain any of the following fields:

Table 1. Dynamic Logging Format Options
Logging Field Example

address

localhost:48006

archive_id

None

dbName

testdb

durableState

MONITORED

engine_state

RUNNING

engine_type

TE

host

nuoadmin1

hostname

localhost

ipAddress

172.22.0.2

isExternalStartup

True

labels

te,te1

lastHeardFrom

3111

last_ack

3.111

msg[LogMessage]

Some info …

msg[Options]

debug,msgs

msg[Time]

2019-11-29T09:32:04.223

nodeId

2

options[agent]

nuoadmin1:48004 (see below)

options[alt-address]

test-te-1 (see below)

options[ext-start]

true (see below)

options[geo-region]

0

options[log-over-conn]

enable

options[read-stdin]

true

options[user-data]

{"incarnation" {"major":2,"minor":0}, "startId":"3","labels":{"te":"te1"}}

options[verbose]

error,warn

pid

38

port

48006

regionId

0

regionName

Default

server_id

nuoadmin1

startId

3

state

RUNNING

storageGroups

https://localhost:8888/api/1/processes/3/storageGroups

type

TE

version

4.2.master-2293
options[agent], options[alt-address], options[ext-start] are not always present in the log message and logging may fail if they are not.