r1 - 2012-05-21 - 03:48:03 - RajulSrivastavaYou are here: NTP >  Dev Web > GoogleSummerOfCode > GSoC2012LoggingDebugging > GSoC2012LoggingDebuggingFrameworkDesign
NTP users are strongly urged to take immediate action to ensure that their NTP daemons are not susceptible to being used in distributed denial-of-service (DDoS) attacks. Please also take this opportunity to defeat denial-of-service attacks by implementing Ingress and Egress filtering through BCP38.

ntp-4.2.8p13 was released on 07 March 2019. It addresses 1 medium-severity security issue in ntpd, and provides 17 non-security bugfixes and 1 other improvements over 4.2.8p12.

Please see the NTP Security Notice for vulnerability and mitigation details.

Are you using Autokey in production? If so, please contact Harlan - he's got some questions for you.

LOG ENTRIES FORMAT

Present FORMAT of Log Messages

timestamp computer process: message

Example : May 12 23:25:33 rajul-Ideapad-Z560 ntpd[6934]: proto: precision = 0.769 usec

Proposed FORMAT of Log Messages

timestamp, [user], computer, process : [section, severity, [__FILE__], FUNCTION, [__LINE__]], message [show refclock info [show refclock X inf, show refclock X unit Y], show network traffic, show network traffic on interface X, show network traffic for IP X/24 or X::ipv6netmask, Show all traffic that uses autokey or ... autokey #x]

PARTS OF THE LOG ENTRIES

TimeStamp

This can be of the format DD/Mon/YYYY:HH:MM:SS format taking time from the system clock (like in Apache log files)

-However the framework shall have functionality for the timestamp to be changed to som other type like Mon DD HH:MM:SS type format, or any other type of format which can even be custom defined.

User (optional)

Name of the user running the process. Is optional, but may be needed in case the logs are needed to be used as Security logs

Computer Name

Name of the Computer on which process is running

Process Name

Name of the process that generated the log

Message

The message generated by the process

FUNCTION [__FILE__, __LINE__]

These options may be included and be helpful during to DEBUG. FUNCTION shall be useful and sufficient for most of the cases. However, FILE and LINE may also be required by some programmer for debugging purposes (I cannot think of any other of their uses) to accurately pin-point the troubles' location. But this extra information is not so useful generally and takes a lot of space, resulting in too much noise. However, they may of extreme use for Debugging. But the developer shall be needed to explicitly specify that he needs this option and needs to have the debug mode activated.

Section

Besides its record message, any trivial log message is marked with a line number, time stamp, thread identifier and severity level. The record message section in the log shall be composed of a simple string which must include the trace of the events that has caused the log-record. The various parts of the record message shall be separated by slashes, making then easier to be searched using regular expressions.

For instance, lets say we have say, network, file or driver operations

MSG_TRACE("network/open", "msg", ...)

MSG_TRACE("network/send", "msg", ...)

MSG_TRACE("network/ipv4/send", "msg", ...)

MSG_TRACE("driver/udp/..", "msg", ...)

It shall be extremely useful if sections simply be a string seperated by a slash. This way we can filter based on regular expressions. Like,

/open ro get all open operations, or *network to get a network op anywhere on the message 'stack'

This way we shall have a static set of 'level's but no definition of macros for sections are needed

We can also create a system to document these sections too. eg, (network, ipv4, send, open) in the above example a verbose message could be Network->IPV4->Open: msg with substitution of the section names to their verbose versions So, in the record message, there shall be the trace of events, followed by the message, so that we may document the sections if needed.

Severity Levels

Current

  • INFO
  • NOTICE
  • ERROR

Levels used in most logging frameworks (like Python, Apache, Google Logging Library, and so many places I looked)

  • DEBUG Info useful to developers for debugging the application, not useful during operations.
  • INFO Normal operational messages - may be harvested for reporting, measuring throughput, etc. - no action required.
  • WARNING Warning messages, not an error, but indication that an error will occur if action is not taken, e.g. file system 85% full - each item must be resolved within a given time.
  • ERROR Non-urgent failures, these should be relayed to developers or admins; each item must be resolved within a given time.
  • CRITICAL/FATAL Should be corrected immediately, but indicates failure in a primary system, an example is a loss of primary ISP connection.

But, as in syslog, we have levels like

  • EMERGENCY A "panic" condition usually affecting multiple apps/servers/sites. At this level it would usually notify all tech staff on call.
  • ALERT Should be corrected immediately, therefore notify staff who can fix the problem. An example would be the loss of a backup ISP connection.
  • CRITICAL
  • ERROR
  • WARNING
  • NOTICE Events that are unusual but not error conditions - might be summarized in an email to developers or admins to spot potential problems - no immediate action required.
  • INFORMATIONAL
  • DEBUG

Using levels like EMERGENCY and ALERT seems to be a good idea for a software like NTP, that runs on such large distributed systems.

Going over the ntpd System Log Messages page in the documentation on the website, I found that currently the messages are classified as INFO, NOTICE, ERROR. So, from this I deduce that mostly the messages are one these three types of severity. However, I feel that many of the messages currently classified under ERROR are actually of type CRITICAL, similarly for NOTICE and ERROR, many of them are more of WARNING type. So, it shall be better if we can introduce these two levels, for want of better classification.

For the ALERT and EMERGENCY types, they can be needed at primary servers in stratum 1 or stratum 2, if something goes wrong there, as that shall actually be a prime EMERGENCY or ALERT condition, considering so many clients depend on them.

Introduction of DEBUG level shall be most useful to the developers in case of trying to debug something.

So, finally:

It shall be for the best, if we can conserve all the severity levels used in 'Syslog' for our use in NTP logging and debugging system, for the resons given above.

LOGGER (SINK-TYPE of LOGGER)

A logger is the entry point into the logging system. Each logger is a named bucket to which messages can be written for processing. A logger is configured to have a log level.

Each message that is written to the logger is a Log Record. Each log record also has a log level indicating the severity of that specific message. A log record can also contain useful metadata that describes the event that is being logged. This can include details such as a stack trace or an error code.

When a message is given to the logger, the log level of the message is compared to the log level of the logger. If the log level of the message meets or exceeds the log level of the logger itself, the message will undergo further processing. If it doesn’t, the

A SINK TYPE LOGGING SYSTEM

As NTP is time-sensitive software, the logging operations are required to be as fast as possible. Therefore, it shall be best to use a 'sink' type logging system.

In sink-type logging messages are dumped, unformatted in a sink. The cost of its operation shall be very low.

We can then attach emitters onto this sink to either dump to a log file or to stdout. The configuration file also allows you to specify that only certain elements of your application, or particular processes within it, produce logging.

In a sink type logging system, basically, the messages produced by the application are dumped in a sink, thus, producing a stream of log messages. These log messages exist un-formatted inside the sink. Now, some mechanism can be used to channel out of the sink and tap these messages, most likely some emitter functions that emit out messages of certain types out of the sink. Thus, in a sink type logging, with some rotation interval or size specified after which the stream starts its rotation, the logs exist in the sink as a stream where this stream may be inside the memory or in a file at a given time. However there may be emitters defined for the stream that can emit out messages, with certain tags or markers out of the sink and these messages are formatted and logged.

Design Overview

Trivial Logging: Any trivial log message is marked with a line number, time stamp, thread identifier and severity level. Trivial logging with filters: We may apply filters to write only significant records to the file (here used for SINK) and ignore the rest. Setting up sinks: We initialize a logging sink, with optional rotation size and interval limits. Emitting significant log messages: These shall enable the selective formatting of the selective messages to be written to the file/stdout while ignoring the rest of the messages in the sink. Log record formatting: Specifying and implementing format for the log-records message will be ignored.

LOG MESSAGES LOCATION

Log Messages may be sent to some

  • local device
  • disk file (by default): at present they are by default sent to syslog however i think that it shall be better if the are sent to a specific location, say /var/log/ntp/, for NTP logs
  • remote server

-- RajulSrivastava - 2012-05-21

Edit | WYSIWYG | Attach | Printable | Raw View | Backlinks: Web, All Webs | History: r1 | More topic actions
 
SSL security by CAcert
Get the CAcert Root Certificate
This site is powered by the TWiki collaboration platform
IPv6 Ready
Copyright & 1999-2020 by the contributing authors. All material on this collaboration platform is the property of the contributing authors. Ideas, requests, problems regarding the site? Send feedback