Progress Trace

Introduction

Progress tracing in NSO provides developers with useful information for debugging, diagnostics and profiling. This information can be used both during development cycles and after release of the software. The system overhead for progress tracing are usually negligible.

When a transaction or action is applied, NSO emits progress events. These events can be displayed and recorded in a number of different ways. The easiest way is to pipe an action to details in the CLI.

admin@ncs% commit | details
Possible completions:
  debug  verbose  very-verbose
admin@ncs% commit | details

As seen by the details output, all events are recorded with a timestamp and in some cases with the duration. All phases of the transaction, service and device communication are printed.

 2021-05-25T17:28:12.267 applying transaction...
entering validate phase for running usid=41 tid=1761 trace-id=d7f06482-41ad-4151-938d-7a8bc7b3ce33
 2021-05-25T17:28:12.267 grabbing transaction lock... ok (0.000 s)
 2021-05-25T17:28:12.268 creating rollback file... ok (0.004 s)
 2021-05-25T17:28:12.272 run transforms and transaction hooks...
 2021-05-25T17:28:12.273 run pre-transform validation... ok (0.000 s)
 2021-05-25T17:28:12.275 service /ordserv[name='o2']: run service... ok (0.035 s)
 2021-05-25T17:28:12.311 run transforms and transaction hooks: ok (0.038 s)
 2021-05-25T17:28:12.311 mark inactive... ok (0.000 s)
 2021-05-25T17:28:12.311 pre validate... ok (0.000 s)
 2021-05-25T17:28:12.311 run validation over the changeset... ok (0.000 s)
 2021-05-25T17:28:12.312 run dependency-triggered validation... ok (0.000 s)
 2021-05-25T17:28:12.312 check configuration policies... ok (0.000 s)
leaving validate phase for running usid=41 tid=1761 trace-id=d7f06482-41ad-4151-938d-7a8bc7b3ce33 (0.045 s)
entering write-start phase for running usid=41 tid=1761 trace-id=d7f06482-41ad-4151-938d-7a8bc7b3ce33
 2021-05-25T17:28:12.312 cdb: write-start
 2021-05-25T17:28:12.313 check data kickers... ok (0.000 s)
leaving write-start phase for running usid=41 tid=1761 trace-id=d7f06482-41ad-4151-938d-7a8bc7b3ce33 (0.001 s)
entering prepare phase for running usid=41 tid=1761 trace-id=d7f06482-41ad-4151-938d-7a8bc7b3ce33
 2021-05-25T17:28:12.314 cdb: prepare
 2021-05-25T17:28:12.314 ncs-internal-device-mgr: prepare
leaving prepare phase for running usid=41 tid=1761 trace-id=d7f06482-41ad-4151-938d-7a8bc7b3ce33 (0.003 s)
entering commit phase for running usid=41 tid=1761 trace-id=d7f06482-41ad-4151-938d-7a8bc7b3ce33
 2021-05-25T17:28:12.317 cdb: commit
 2021-05-25T17:28:12.318 ncs-internal-service-mux: commit
 2021-05-25T17:28:12.318 ncs-internal-device-mgr: commit
 2021-05-25T17:28:12.320 releasing transaction lock
leaving commit phase for running usid=41 tid=1761 trace-id=d7f06482-41ad-4151-938d-7a8bc7b3ce33 (0.002 s)
 2021-05-25T17:28:12.320 applying transaction: ok (0.053 s)

Some actions (usually those involving device communication) also produces progress data.

admin@ncs% request devices device ce0 sync-from dry-run | details very-verbose
 2021-05-25T17:31:31.222 device ce0: sync-from...
 2021-05-25T17:31:31.222 device ce0: taking device lock... ok (0.000 s)
 2021-05-25T17:31:31.227 device ce0: connect... ok (0.013 s)
 2021-05-25T17:31:31.240 device ce0: show... ok (0.001 s)
 2021-05-25T17:31:31.242 device ce0: get-trans-id... ok (0.000 s)
 2021-05-25T17:31:31.242 device ce0: close... ok (0.000 s)
 2021-05-25T17:31:31.248 device ce0: releasing device lock
 2021-05-25T17:31:31.249 device ce0: sync-from: ok (0.026 s)

Configuring Progress Trace

The pipe details in the CLI is useful during development cycles of for example a service, but not as useful when tracing calls from other northbound interfaces or events in a released running system. Then it's better to configure a progress trace to be outputted to a file or operational data which can be retrieved through a northbound interface.

Unhide Progress Trace

The top level container progress is by default invisible due to a hidden attribute. In order to make progress visible in the CLI, two steps are required. First the following XML snippet must be added to ncs.conf :

<hide-group>
  <name>debug</name>
</hide-group>

Now the unhide command may be used in the CLI session:

admin@ncs% unhide debug

Log to File

Progress data can be outputted to a given file. This is useful when the data is to be analyzed in some third party software like a spreadsheet application.

admin@ncs% set progress trace test destination file event.csv format csv

The file can be formatted as a comma-separated values file defined by RFC 4180 or in a pretty printed log file with each event on a single line.

The location of the file is the directory of /ncs-config/logs/progress-trace/dir in ncs.conf.

Log as Operational Data

When the data is to be retrieved through a northbound interface it is more useful to output the progress events as operational data.

admin@ncs% set progress trace test destination oper-data

This will log non-persistent operational data to the /progress:progress/trace/event list. As this list might grow rapidly there is a maximum size of it (defaults to 1000 entries). When the maximum size is reached, the oldest list entry is purged.

admin@ncs% set progress trace test max-size 2000

Using the /progress:progress/trace/purge action the event list can be purged.

admin# request progress trace test purge

Log as Notification Events

Progress events can be subscribed to as Notifications events. See the section called “NOTIF API” for further details.

Verbosity

The verbosity parameter is used to control the level of output. The following levels are available:

normal - Informational messages that highlight the progress of the system at a coarse-grained level. Used mainly to give a high level overview. This is the default and the lowest verbosity level.
verbose - Detailed informational messages from the system. The various service and device phases and their duration will be traced. This is useful to get an overview over where time is spent in the system.
very-verbose - Very detailed informational messages from the system and its internal operations.
debug - The highest verbosity level. Fine-grained informational messages usable for debugging the system and its internal operations. Internal system transactions as well as data kicker evaluation and CDB subscribers will traced. Setting this level could result in a large number of events being generated.

Additional debug tracing can be turned on for various parts. These are consciously left out of the normal debug level due to the high amount of output and should only be turned on during development.

Using Filters

By default all transaction and action events with the given verbosity level will be logged. To get a more selective choice of events, filters can be used.

admin@ncs% show progress trace filter
Possible completions:
  all-devices  - Only log events for devices.
  all-services - Only log events for services.
  context      - Only log events for the specified context.
  device       - Only log events for the specified device(s).
  device-group - Only log events for devices in this group.
  local-user   - Only log events for the specified local user.
  service-type - Only log events for the specified service type.

The context filter can be used to only log events that originate through a specific northbound interface. The context is either one of netconf, cli, webui, snmp, rest, system or it can be any other context string defined through the use of MAAPI.

admin@ncs% set progress trace test filter context netconf

Report Progress Events from User Code

API methods to report progress events exists for Java, Python and C. There also exist specific methods to report progress events for services.

...
Maapi maapi = service.context().getMaapi();
int tHandle = service.context().getMaapiHandle();
ConfPath servicePath = new ConfPath(service.getKeyPath());
maapi.reportServiceProgress(tHandle, Maapi.Verbosity.VERBOSE,
                            "service test", servicePath);