Gather useful information for debugging and troubleshooting.
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 the release of the software. The system overhead for progress tracing is 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.
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.
applying transaction for running datastore usid=41 tid=1761 trace-id=d7f06482-41ad-4151-938d-7a8bc7b3ce33
entering validate phase
2021-05-25T17:28:12.267 taking transaction lock... ok (0.000 s)
2021-05-25T17:28:12.267 holding transaction lock...
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-manager: 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 (0.045 s)
entering write-start phase
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 (0.001 s)
entering prepare phase
2021-05-25T17:28:12.314 cdb: prepare
2021-05-25T17:28:12.314 device-manager: prepare
leaving prepare phase (0.003 s)
entering commit phase
2021-05-25T17:28:12.317 cdb: commit
2021-05-25T17:28:12.318 service-manager: commit
2021-05-25T17:28:12.318 device-manager: commit
2021-05-25T17:28:12.320 holding transaction lock: ok (0.033 s)
leaving commit phase (0.002 s)
applying transaction for running datastore usid=41 tid=1761 trace-id=d7f06482-41ad-4151-938d-7a8bc7b3ce33 (0.053 s)
Some actions (usually those involving device communication) also produce progress data.
The pipe details in the CLI are 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. 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>
Then, the unhide command is 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 NOTIF API for further details.
Verbosity
The verbosity parameter is used to control the level of output. The following levels are available:
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 exist 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);
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 of 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 with 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.
