Logging Framework

Logback configuration

UniConfig distribution uses Logback as the implementation of the logging framework. Logback is the successor to to the log4j framework with many improvements such as more options for configuration, better performance, and context-based separation of logs. Context-based separation of logs is used widely in UniConfig to achieve per-device logging based on the set marker in the logs.

Logback configuration is placed in ‘config/logback.xml’ file under UniConfig distribution. For more information about formatting of logback configuration, look at the http://logback.qos.ch/manual/configuration.html site. This section describes parts of the configuration in the context of UniConfig application.

Appenders

The following appenders are used:

  1. ‘STDOUT’ - It is used for printing logs into console.

  2. ‘logs’ - Used for writing of all logs to output file on path ‘log/logs.log’. The rolling file appender is applied.

  3. ‘netconf-notifications’, ‘netconf-messages’, and ‘netconf-events’ - Sifting appenders that split logs per node ID that is set in the marker of logs. Logs are written to different subdirectories under ‘log’ directory and they are identified by node ID. The rolling file appender is applied.

  4. ‘restconf’ - Appender used for writing of RESTCONF messages into ‘log/restconf.log’ file. The rolling file appender is applied.

Loggers

There are 2 groups of loggers:

  1. Package-level logging brokers - Loggers that are used for writing general messages into console and single output file. Logging level is by default set to ‘INFO’. For debugging purposes it is handy to change logging threshold to ‘TRACE’ or ‘DEBUG’ level. Covered layers: UniConfig, Unified, Controller, RESTCONF, CLI, NETCONF. Used appenders: ‘STDOUT’ and ‘logs’.

  2. Loggers used for logging brokers - Loggers that should not be changed since the state of logging can be changed using RPC calls. Classpaths point to specific classes that represent implementations of logging brokers and logging level is set to ‘TRACE’. Used appenders: ‘netconf-notifications’, ‘netconf-messages’, ‘netconf-events’, and ‘restconf’.

Updating configuration

  • Logback is configured to scan for changes in its configuration file and automatically reconfigure itself when the configuration file changes.

  • Scanning period is set to 5 seconds.

Logging brokers

Logging broker represents configurable controller that logs one logical group of messages from single classpath. Logging of multiple messages from the same classpath simplifies configuration of loggers in Logback since only one logger per broker must be specified. Logging broker can be controlled using RESTCONF RPCs - there are multiple operation using which it is possible to trigger logging in whole broker or just for specified node IDs. Configuration of logger in the logback file that is assigned to logging broker should not be changed at all.

Implemented logging brokers

The following subsections describe currently implemented logging brokers.

RESTCONF

  • It is used for logging authenticated HTTP requests and responses - information about URI, source, HTTP method, query parameters, HTTP headers, and body.

  • Per-device logging cannot be enabled for this broker - all logs are saved to ‘log/restconf.log’ file.

  • It is possible to configure HTTP headers which content must be masked in logs (using asterisk characters). This is usable especially if there are some headers which contain private data (such as Authorization or Cookie header). Hidden HTTP headers are marked using header identifiers.

  • It is also possible to configure HTTP methods for which the communication (requests and responses) should not be logged to file.

  • Requests and responses are paired using unique message-id. This message-id is not part of the HTTP request - it is generated on RESTCONF server.

Example - request and corresponding response with the same message-id:

08:51:21.508 TRACE org.opendaylight.restconf.nb.rfc8040.jersey.providers.logging.RestconfLoggingBroker - HTTP request:
Message ID: 3
HTTP method: POST
URI: http://localhost:8181/rests/operations/logging:enable-device-logging
Source address: 0:0:0:0:0:0:0:1
Source port: 37472
User ID: admin@sdn
HTTP headers:
    User-Agent: [curl/7.69.1]
    Authorization: ***
    Host: [localhost:8181]
    Accept: [*/*]
    Content-Length: [116]
    Content-Type: [application/json]
Request body:
{
  "input": {
    "broker-identifier": "netconf_notifications",
    "device-list": [
      "xr6",
      "xr7"
    ]
  }
}

08:51:21.518 TRACE org.opendaylight.restconf.nb.rfc8040.jersey.providers.logging.RestconfLoggingBroker - HTTP response:
Request message ID: 3
Status code: 200
HTTP headers:
    Content-Type: [application/yang-data+json]
Response body:
{
  "output": {
    "message": "Successfully updated logging broker [netconf_notifications]",
    "status": "complete"
  }
}

NETCONF messages

  • Broker used for logging of all NETCONF incoming/outgoing messages except the NETCONF notifications (the distinct broker has been introduced for notifications).

  • NETCONF RPCs and responses can be matched using ‘message-id’ attribute that is placed in the RPC header.

  • Per-device logging is supported - logs for NETCONF messages are stored under ‘log/netconf-messages’ directory and named by ‘[node-id].log’ pattern.

Example - sending NETCONF GET RPC and receiving response:

11:10:15.038 TRACE org.opendaylight.netconf.logging.brokers.NetconfMessagesLoggingBroker - b1b2b9c1: Sending NETCONF message:
<rpc xmlns="urn:ietf:params:xml:ns:netconf:base:1.0" message-id="m-179">
    <get>
        <filter xmlns:ns0="urn:ietf:params:xml:ns:netconf:base:1.0" ns0:type="subtree">
            <netconf xmlns="urn:ietf:params:xml:ns:netmod:notification"/>
        </filter>
    </get>
</rpc>

11:10:15.055 TRACE org.opendaylight.netconf.logging.brokers.NetconfMessagesLoggingBroker - b1b2b9c1: Received NETCONF message:
<rpc-reply xmlns="urn:ietf:params:xml:ns:netconf:base:1.0" message-id="m-179">
    <data>
        <netconf xmlns="urn:ietf:params:xml:ns:netmod:notification">
            <streams>
                <stream>
                    <name>NETCONF</name>
                    <description>default NETCONF event stream</description>
                    <replaySupport>true</replaySupport>
                    <replayLogCreationTime>2020-09-29T09:49:54+00:00</replayLogCreationTime>
                </stream>
                <stream>
                    <name>oam</name>
                    <description>Vendor notifications</description>
                    <replaySupport>true</replaySupport>
                    <replayLogCreationTime>2020-11-09T13:20:01+00:00</replayLogCreationTime>
                </stream>
            </streams>
        </netconf>
    </data>
</rpc-reply>

Note

String ‘b1b2b9c1’ represents session ID. If multiple sessions are created between NETCONF server and NETCONF client and they are logically grouped by the same node ID, then logs from multiple sessions are stored to the same logging file - it is needed to distinguish between these sessions. Multiple NETCONF sessions between UniConfig and NETCONF server are created for each subscription to NETCONF stream.

NETCONF notifications

  • Broker used for logging of incoming NETCONF notifications.

  • Per-device logging is supported - logs for NETCONF notifications are stored under ‘log/netconf-notifications’ directory and named by ‘[node-id].log’ pattern.

Example - received two notifications:

11:37:03.907 TRACE org.opendaylight.netconf.logging.brokers.NotificationsLoggingBroker - 117123a1: Received NETCONF notification:
<notification xmlns="urn:ietf:params:xml:ns:netconf:notification:1.0">
    <eventTime>2020-11-11T02:36:54.484233-08:00</eventTime>
    <netconf-session-start xmlns="urn:ietf:params:xml:ns:yang:ietf-netconf-notifications">
        <username>admin</username>
        <session-id>35</session-id>
        <source-host>10.255.246.31</source-host>
    </netconf-session-start>
</notification>

11:37:04.515 TRACE org.opendaylight.netconf.logging.brokers.NotificationsLoggingBroker - 117123a1: Received NETCONF notification:
<notification xmlns="urn:ietf:params:xml:ns:netconf:notification:1.0">
    <eventTime>2020-11-11T02:36:55.098119-08:00</eventTime>
    <netconf-session-end xmlns="urn:ietf:params:xml:ns:yang:ietf-netconf-notifications">
        <username>admin</username>
        <session-id>35</session-id>
        <source-host>10.255.246.31</source-host>
        <termination-reason>dropped</termination-reason>
    </netconf-session-end>
</notification>

NETCONF events

  • Logs generated by this broker contain session-related information about establishment/closing of NETCONF session from the view of NETCONF client placed in UniConfig.

  • These logs don’t contain full printouts of sent/received NETCONF messages.

  • Per-device logging is supported - logs for NETCONF events are stored under ‘log/netconf-events’ directory and named by ‘[node-id].log’ pattern.

Example:

11:08:59.407 INFO org.opendaylight.netconf.logging.brokers.NetconfEventsLoggingBroker - node1: Connecting remote device with config: Node{getNodeId=Uri [_value=node1], augmentations={interface org.opendaylight.yang.gen.v1.urn.opendaylight.netconf.node.topology.rev150114.NetconfNode=NetconfNode{getActorResponseWaitTime=5, getBetweenAttemptsTimeoutMillis=2000, getConcurrentRpcLimit=0, getConnectionTimeoutMillis=60000, getCredentials=LoginPassword{getPassword=versa123, getUsername=admin, augmentations={}}, getCustomizationFactory=default, getDefaultRequestTimeoutMillis=60000, getDryRunJournalSize=0, getEditConfigTestOption=Set, getHost=Host [_ipAddress=IpAddress [_ipv4Address=Ipv4Address [_value=10.103.5.202]]], getKeepaliveDelay=5, getMaxConnectionAttempts=100, getPort=PortNumber [_value=2022], getSleepFactor=1.0, getYangModuleCapabilities=YangModuleCapabilities{getCapability=[http://tail-f.com/ns/docgen/experimental1?module=docgen&amp;revision=2019-11-01], isOverride=false, augmentations={}}, isEnabledNotifications=true, isReconnectOnChangedSchema=false, isSchemaless=false, isTcpOnly=false}, interface org.opendaylight.yang.gen.v1.http.frinx.io.yang.uniconfig.config.rev180703.UniconfigConfigNode=UniconfigConfigNode{getBlacklist=Blacklist{getExtension=[tailf:display-when false], augmentations={}}, isUniconfigNativeEnabled=true}}}
11:09:00.554 DEBUG org.opendaylight.netconf.logging.brokers.NetconfEventsLoggingBroker - node1: Session established
11:09:00.558 DEBUG org.opendaylight.netconf.logging.brokers.NetconfEventsLoggingBroker - node1: Session advertised capabilities: ...
11:09:00.832 DEBUG org.opendaylight.netconf.logging.brokers.NetconfEventsLoggingBroker - node1: Connector for node created successfully

Supported logging settings

Current logging broker settings are stored in Operational datastore under ‘logging-status’ root container. The following example shows GET query for displaying of settings:

curl --location --request GET 'http://127.0.0.1:8181/rests/data/logging-status?content=nonconfig' \
--header 'Accept: application/json'

Response:

{
    "logging-status": {
        "broker": [
            {
                "broker-identifier": "netconf_messages",
                "is-logging-broker-enabled": true,
                "is-logging-enabled-on-all-devices": true,
                "enabled-devices": [
                    "xr6",
                    "xr7"
                ]
            },
            {
                "broker-identifier": "restconf",
                "is-logging-broker-enabled": true,
                "restconf-logging:hidden-http-methods": [
                    "GET"
                ],
                "restconf-logging:hidden-http-headers": [
                    "Authorization",
                    "Cookie"
                ]
            },
            {
                "broker-identifier": "netconf_notifications",
                "is-logging-broker-enabled": true,
                "is-logging-enabled-on-all-devices": true
            },
            {
                "broker-identifier": "netconf_events",
                "is-logging-broker-enabled": true,
                "is-logging-enabled-on-all-devices": true
            }
        ],
        "global": {
            "hidden-types": [
                "password",
                "encrypted"
            ]
        }
    }
}

Logging settings are encapsulated inside multiple list entries (‘broker’ list) where one list entry contains settings for one logging broker. Description of settings that are placed under single logging entry:

  • broker-identifier - Unique identifier of the logging broker. Currently, 4 brokers are supported - ‘netconf_messages’, ‘restconf’, ‘netconf_notifications’, and ‘netconf_events’.

  • is-logging-broker-enabled - Flag that specifies whether logging broker is enabled. If logging broker is disabled, then no logging messages are generated.

  • is-logging-enabled-on-all-devices - If this flag is set to ‘true’, then logs are separated to distinct files in the scope of all devices. If it is set to ‘false’, then logging is enabled only for devices that are listed in the ‘enabled-devices’ leaf-list / array. This setting is unsupported in the ‘restconf’ logging broker since RESTCONF currently doesn’t differentiate node ID in the requests/responses.

  • enabled-devices - If ‘is-logging-enabled-on-all-devices’ is set to ‘false’, then logs are generated only for devices that are specified in this list - it acts as simple filtering mechanism based on whitelist. Blacklist approach is not supported - it is not possible to set ‘is-logging-enabled-on-all-devices’ to ‘true’ and specify devices for which logging feature is disabled. This field is not supported in the ‘restconf’ logging broker.

RESTCONF-specific settings:

  • restconf-logging:hidden-http-methods - HTTP requests (and associated HTTP responses) are not logged if request’s HTTP method is set to one of the methods in this list. Names of the HTTP methods must be specified using upper-case format.

  • restconf-logging:hidden-http-headers - List of HTTP headers (names of the headers) which content is hidden in the logs. Names of the HTTP headers are not case-sensitive.

Global settings that are common in all logging brokers:

  • hidden-types - Value of leaf or leaf-list that uses one of these types is hidden in the logs using asterisk characters. It can be used for masking of passwords or other confidential data from logs.

Initial configuration

By default, all logging brokers are disabled and logging is disabled on all devices - user must explicitly specify list of devices for which per-device logging is enabled. Also, RESTCONF-specific filtering is not configured - all HTTP requests/responses are logged with the whole content.

Initial logging configuration can be adjusted by adding ‘loggingController’ configuration into ‘config/lighty-uniconfig-config.json’ file. The structure of this configuration section conforms YANG structure that is described by ‘logging’ and ‘restconf-logging’ modules - it is possible to copy the state of Operational datastore under ‘logging-status’ into the ‘loggingController’ root JSON node.

The next JSON snippet shows sample ‘loggingController’ configuration - logging brokers ‘netconf_messages’ and ‘netconf_notifications’ are enabled; ‘netconf_messages’ broker is enabled for all devices while ‘netconf_notifications’ is enabled only for ‘xr6’ and ‘xr7’ devices.

{
  "loggingController": {
    "broker": [
      {
        "broker-identifier": "netconf_messages",
        "is-logging-broker-enabled": true,
        "is-logging-enabled-on-all-devices": true
      },
      {
        "broker-identifier": "netconf_notifications",
        "is-logging-broker-enabled": true,
        "is-logging-enabled-on-all-devices": false,
        "enabled-devices": [
          "xr7",
          "xr6"
        ]
      }
    ]
  }
}

Controlling of logging using RPC calls

Since logging settings are stored in Operational datastore, it is possible to adjust these settings on runtime only using RPC calls. The following subsections describe available RPCs.

Enable logging broker

  • RPC used for enabling logging broker. Enabled logging broker is able to write logs.

  • The input contains only name of the the logging broker - ‘broker-identifier’.

Example (enable logging broker with identifier ‘restconf’):

curl --location --request POST 'http://localhost:8181/rests/operations/logging:enable-logging' \
--header 'Accept: application/json' \
--header 'Content-Type: application/json' \
--data-raw '{
    "input": {
        "broker-identifier": "restconf"
    }
}'

Positive response (broker was previously in disabled state):

{
    "output": {
        "message": "Successfully updated logging broker [restconf]",
        "status": "complete"
    }
}

Disable logging broker

  • RPC used for turning off logging broker. Disabled logging broker doesn’t write any logs despite of other settings.

  • The input contains only name of the the logging broker - ‘broker-identifier’.

Example (disable logging broker with identifier ‘restconf’):

curl --location --request POST 'http://localhost:8181/rests/operations/logging:disable-logging' \
--header 'Accept: application/json' \
--header 'Content-Type: application/json' \
--data-raw '{
    "input": {
        "broker-identifier": "restconf"
    }
}'

Positive response (broker was previously in enabled state):

{
    "output": {
        "message": "Successfully updated logging broker [restconf]",
        "status": "complete"
    }
}

Enable default device logging

  • RPC used for setting default device logging to ‘true’ - logs will be written for all devices without filtering of any logs based on node ID.

  • The input contains only name of the the logging broker - ‘broker-identifier’.

  • Invocation of this RPC causes clearing of ‘enabled-devices’ leaf-list.

Example (enable default device logging in ‘netconf_messages’ logging broker):

curl --location --request POST 'http://localhost:8181/rests/operations/logging:enable-default-device-logging' \
--header 'Accept: application/json' \
--header 'Content-Type: application/json' \
--data-raw '{
    "input": {
        "broker-identifier": "netconf_messages"
    }
}'

Positive response (default device logging was previously disabled):

{
    "output": {
        "message": "Successfully updated logging broker [netconf_messages] default logging behaviour",
        "status": "complete"
    }
}

Disable default device logging

  • RPC used for setting default device logging to ‘false’ - logs will be written only for devices that are named in the ‘enabled-devices’ leaf-list. If ‘enabled-devices’ leaf-list doesn’t contain any node ID, then logging in the corresponding logging broker is effectively turned off.

  • The input contains only name of the the logging broker - ‘broker-identifier’.

Example (disable default device logging in ‘netconf_messages’ logging broker):

curl --location --request POST 'http://localhost:8181/rests/operations/logging:disable-default-device-logging' \
--header 'Accept: application/json' \
--header 'Content-Type: application/json' \
--data-raw '{
    "input": {
        "broker-identifier": "netconf_messages"
    }
}'

Positive response (default device logging was previously enabled):

{
    "output": {
        "message": "Successfully updated logging broker [netconf_messages] default logging behaviour",
        "status": "complete"
    }
}

Enable device logging

  • RPC used for enabling logging for specified devices that are identified by node IDs.

  • The input contains name of the the logging broker - ‘broker-identifier’ and list of node IDs - ‘device-list’.

Example (enable logging for devices with node IDs ‘node1’, ‘node2’, and ‘node3’ in the ‘netconf_events’ logging broker):

curl --location --request POST 'http://localhost:8181/rests/operations/logging:enable-device-logging' \
--header 'Accept: application/json' \
--header 'Content-Type: application/json' \
--data-raw '{
    "input": {
        "broker-identifier": "netconf_events",
        "device-list": [
            "node1",
            "node2",
            "node2"
        ]
    }
}'

Positive response (default device logging is disabled):

{
    "output": {
        "message": "Successfully updated logging broker [netconf_events]",
        "status": "complete"
    }
}

Disable device logging

  • RPC used for turning off logging for specified devices that are identified by node IDs.

  • The input contains name of the the logging broker - ‘broker-identifier’ and list of node IDs - ‘device-list’.

Example (disable logging for device with node ID ‘node1’ in the ‘netconf_events’ logging broker):

curl --location --request POST 'http://localhost:8181/rests/operations/logging:disable-device-logging' \
--header 'Accept: application/json' \
--header 'Content-Type: application/json' \
--data-raw '{
    "input": {
        "broker-identifier": "netconf_events",
        "device-list": [
            "node1"
        ]
    }
}'

Positive response (default device logging is disabled):

{
    "output": {
        "message": "Successfully updated logging broker [netconf_events]",
        "status": "complete"
    }
}

Setting global hidden types

  • RPC used for setting identifiers of hidden YANG type definitions. Values of leaves and leaf-lists that are described by these types are masked in the output logs.

  • This RPC overwrites all already configured hidden types. Empty list of hidden types disables filtering of data values.

  • Filtering of values applies to all logs including RESTCONF logs.

Example - setting 3 hidden types:

curl --location --request POST 'http://localhost:8181/rests/operations/logging:set-global-hidden-types' \
--header 'Accept: application/json' \
--header 'Content-Type: application/json' \
--data-raw '{
    "input": {
        "hidden-types": [
            "types:password",
            "types:encrypted",
            "types:hash"
        ]
    }
}'

Response:

{
    "output": {
        "message": "Global logging controller configuration has been successfully updated",
        "status": "complete"
    }
}

Setting hidden HTTP headers

  • RPC used for overwriting list of HTTP headers which content is masked in the output RESTCONF logs.

  • This RPC modifies behaviour of only ‘restconf’ logging broker.

  • HTTP headers in both requests and responses are masked.

  • The list of hidden HTTP headers denotes header identifiers.

  • The identifier of ‘hidden’ HTTP header still presents in the output logs, however, the content of such header is replaced by asterisk characters.

Example - hiding content of ‘Authorization’ and ‘Cookie’ HTTP headers:

curl --location --request POST 'http://localhost:8181/rests/operations/restconf-logging:set-hidden-http-headers' \
--header 'Accept: application/json' \
--header 'Content-Type: application/json' \
--data-raw '{
    "input": {
        "hidden-http-headers": [
            "Authorization",
            "Cookie"
        ]
    }
}'

Response:

{
    "output": {
        "message": "List of hidden HTTP headers have been successfully updated",
        "status": "complete"
    }
}

Setting hidden HTTP methods

  • RPC used for overwriting list of HTTP methods. RESTCONF communication, that may include invocation of hidden HTTP methods, is not displayed in the output logs.

  • Both requests and responses with hidden HTTP methods are not written to log files.

  • This RPC modifies behaviour of only ‘restconf’ logging behaviour.

Example - hiding GET and PATCH communication in the RESTCONF logs:

curl --location --request POST 'http://localhost:8181/rests/operations/restconf-logging:set-hidden-http-methods' \
--header 'Accept: application/json' \
--header 'Content-Type: application/json' \
--data-raw '{
    "input": {
        "hidden-http-methods": [
            "GET",
            "PATCH"
        ]
    }
}'

Response:

{
    "output": {
        "message": "List of hidden HTTP methods have been successfully updated",
        "status": "complete"
    }
}