Logs

A log is an entry in a file or database that records an event that can be used as part of an audit trail. The entry could reflect a system event in the Erlang VM or operating system, or an event that triggers a state change in your business logic. Logs are used for a variety of purposes, including tracing, debugging, auditing, compliance monitoring, and billing. Different log entries are usually tagged, allowing you to decide the level of granularity of what is stored at runtime. Common tags include debug, info, notice, warning, and error.

The different ways logs are used by different people with varying technical skills and tool sets makes it hard to suggest a “one size fits all” approach. What is important, however, is to have logs that allow those using them to uniquely follow the flow of requests across nodes in order to locate issues or gather required data.

Picture our e-commerce example, where millions of requests run through the system daily. How do you handle a complaint from a customer who claims they never received their package, despite their credit card being charged? How do you narrow down your search and link the missing message to process crash reports or networking issues? You need to quickly find where in your code the request disappeared and admit guilt, or prove your innocence using a solid audit trail as evidence, thereby shifting the focus for finding the problem to your warehouse team or the courier.

Can you then use the same logs to create a customer profile based on the items purchased? Or look at the durations of user sessions to understand their shopping behavior? Understand how many users fill customers’ shopping carts but never check out? Or add up the total number of sales and, for revenue assurance purposes, compare it with the figures provided by the bank handling the credit card transactions? That is the level of granularity to aim for.

We saw the SASL logs that you get for free when using OTP in “The SASL Application”. If configured correctly, you get binary logs with supervisor, progress, error, and crash reports. You can also add your own handlers, forwarding crash and error logs to a central location. But saving the information is just the start to finding all the help it can provide when mined properly. Imagine a system with hundreds (or even thousands) of nodes, elastically scaling up and down. If you did not forward them to a central log repository, you would have to SSH onto a machine, connect to the Erlang shell, start the report browser, and search for crash reports, hoping they had not been rotated. If that were the case, how would you ever find out if something went wrong?

At one site we ran systems where processes were crashing daily. Since they were being automatically restarted, we were not aware of the issues, and the system was perceived as running normally, when in fact, a very small fraction of the requests were failing. Failure had been isolated so well, we had no idea our system was riddled with bugs. That’s not cool. If you want high availability, you need to automate the discovery of the SASL crash and error reports, and then ensure any faults get addressed. Although they may appear to be small in number, a user out there is experiencing each fault. And if many of these issues happen in quick succession, they could cause the supervisor to reach its maximum number of restarts, terminate, and escalate the issue, possibly taking the node down. Increasing the number of allowed restarts in your supervisor specification is not the solution. You need to solve the root problem that causes the crashes.

Users have often added their own log entries to the SASL logs, but this isn’t recommended because it mixes logs of different types and purposes in the same file. It might work for smaller systems with little traffic, but as soon as you have to handle tens of thousands of requests per second or more, where each request results in multiple log entries, you will quickly outgrow the capabilities of the SASL logs and will definitely want separate files (and possibly formats) for every log type.

To understand what business-specific items you should be logging, trace the functional information flow of each request, identifying where the request will change the state of the system, and then log items that will get the user to select different branches. Think about what will give the maintainers, support engineers, DevOps team, accountants, auditors, marketing, and customer service representatives a good overview of what is happening or has happened. Every time a notable change in state occurs, log useful information that was not previously stored.

Ensure that you can, through unique identifiers, link together the various log entries, recreating the functional information flow. You cannot rely on timestamps alone, because the quantities of data will be huge. Nor can you rely on the session ID, user ID, or phone number, as they will not be unique across multiple requests. Assign a unique ID every time a unique request is received by an external client. As external requests might consist of several independent requests within your system or other external systems, unique identifiers might vary from one log to another. To link them together, you must ensure they are available in the function call where you invoke the log and store them together. While log entries can be added later, you must think through your logging strategy before you start coding, as the logs might be the only reason for using unique IDs in your business logic. You do not want to refactor all your code because you’ve realized that right before a call to an external API, you do not have the request ID generated elsewhere. You should also be prepared to change what you log based on feedback from maintainers, the DevOps team, and other log consumers.

Try to reduce repetition across logs. Store information only once and link it together with other logs using your identifiers. Using a single log to store everything might work during development, but when tens of thousands of sustained transactions take place per second, it will be hard to efficiently extract useful data out of the file and it could become a potential bottleneck. Ideally, your logs should create a relational model, where depending on the flow, a log entry in a file with a unique ID is linked to an entry in another file. This unique ID could be a session ID, which links items browsed by a user, items placed in and removed from a shopping cart, and items paid for on checkout. One log file could contain all the items browsed by a user, including the time spent viewing an item, another file items added to and deleted from the shopping cart, and a third log file items that were paid for. Items that were paid for on checkout might have another unique ID generated by the payment gateway, linking the session to one or more payments. All payment logs, in turn, would not have to store the session ID, as the link between the two would be made from the checkout log.

Another way to view the logs is as FSMs, where every entry is a state, and transitions to new states take place based on a set of conditional evaluations in your business logic. Replaying the state transitions in the FSM would allow DevOps engineers to retrace the steps taken by users adding items to their shopping baskets and paying for them.

Identify the different levels of logging, and especially what is useful only in debug mode, so as to not overload the system with useless logs. As a minimum requirement, always log the incoming and outgoing requests and results where appropriate so you are later able to identify the problematic system or component. As an example, if you are calling an external API, create a log entry with the request, the latency, and any unique request ID the external API has provided you. If the API request to your external service times out, just replace the result with a timeout tag. You can later analyze the log and see whether you need to increase the timeout values.

You will have to log system-specific items in your business-specific logs irrespective of what the node or system does. We have already discussed SASL logs, which you get as part of OTP. Always log all Erlang shell commands and interactions. You will be surprised to learn how many outages are caused by operations staff who are not used to working in the shell. Knowing what they have done can be just as important for proving that your code was working correctly as it is for restoring the service. How you log shell commands will depend on your target architecture. You could redirect your I/O, use bash commands, or add a hook to log the entries in the Erlang VM itself.

Other items to log could include network connectivity and memory issues, which are notifications arising from the system_monitor BIF described in “The System Monitor”. Be careful with the latter, as we have caused nodes to crash after they ran out of disk space as a result of logging millions of distributed Erlang port busy notifications in a 24-hour period. The same applies to badly written code that caused memory spikes, triggering long gc and large heap messages. In these cases, an incremental counter that bumped up every time such a message was generated would be better than logging the messages themselves. You can build in the ability to toggle the logging of the messages, so that you can switch to retrieving details when you need to debug the situation.

It is often also worth logging times when code is loaded or purged, node restarts, and the successful saving (and renaming) of crash dumps. Log whatever you believe will make your life easier and help you understand and correlate abnormal behavior or corrupt system state to a series of events.

If you store logs locally, use append-only files, and make sure your data is organized properly. It is common for log files to be stored offline, in databases, or with SaaS providers. Disk space is cheap. Logs could be stored as CSV files in plain text and fed into a variety of systems used for troubleshooting, billing, compliance, and revenue assurance. Logs could follow a standard such as syslog, or have a proprietary format. Make sure the data is accessible in a friendly format for those who need it. To slightly misuse Pat Helland’s wise words, “a database is a cache of your event logs,” if your database (or state) gets corrupted, the logs should tell you why. If it is not corrupt, they will tell you why not.

Metrics

Metrics are sets of numeric data collected at regular intervals and organized in chronological order. Metrics are retrieved from all levels of your application stack. You need to retrieve data on the OS and network layers, on the middleware layer (which includes the Erlang virtual machine and many of the libraries described in this book), and in your business layer. Metrics can be used in many parts of a business and are needed for many reasons, all similar to the reasons you need alarms and logs:

• Developers use metrics to improve the performance and reliability of the system and troubleshoot issues after they have occurred.

• DevOps engineers monitor the system to detect abnormal behavior and prevent failures.

• Operations staff use metrics to predict trends and usage spikes, using the results to optimize hardware costs.

• Marketing uses them to study long-term user trends and user experience.

To visualize metrics, imagine an incremental counter called login that is bumped up every time someone tries to log on to the system. If they are successful, login_success could be bumped up, or upon failure, login_failure incremented instead. We could take this further, and create counters for different failure types such as bad_password, unknown_user, user_suspended, and userdb_error. Such metrics could help identify attempts to hack into the system, help monitor fraud attempts, or maybe just prove a poor user experience. If you are getting hundreds of unknown user or bad password errors from the same source, you might want to ask those responsible for security to review the logs and determine what is going on. Marketing might want to determine how many users who fail to log on actually retry and eventually succeed. This would also be determined by examining the logs, but metrics would provide the first hint that something is wrong.

The operations team might want to make sure the system load doesn’t exceed available resources, requesting metrics on the memory usage of the Erlang VM. You can poll not only the total memory usage, but also how much memory is used by processes, the system, the atom table, ETS tables, binaries, and to store the code. You could even take it a step further and differentiate between the space allocated to store process and atom memory versus the memory actually used.

As a developer, you might not think much about these issues as you rush to deliver the system, but once you have gone live and someone who does not speak Erlang has to figure out why it is running low on memory, imagine the power of being able to correlate spikes in process memory usage or large portions of time spent on garbage collecting data with particular user operations such as logging in.

Figure 16-2 plots the different types of memory usage in the Erlang VM, alongside total memory consumption. We can clearly see that the 50% increase in memory is due to an increase in the used process memory, which probably correlates either to increased system usage or to a buildup of processes that aren’t being properly terminated.

Figure 16-2. Memory usage

Metrics collected take on different values and formats depending on their purpose. One typical value is an amount, a discrete or continuous value with incremental and decremental capabilities. A common form of amount is counters, as we have seen.

Gauges are a form of counter that provide a value at a particular point in time. Although the number of login attempts since we started the system might not help someone in operations, the number of ongoing sessions will. Other typical examples of gauges are to measure memory or hard disk usage.

Time is another common measurement, mainly used to measure latency in all levels of the stack. Data collectors tend to group time readings into histograms, collections of values (not necessarily only time-related) that have had some form of statistical analysis applied to them. Histograms may show averages, minimum and maximum values, or percentiles. As examples, what was the latency of the fastest 1% of the requests? And the slowest 1%?

The third type of metric is a value in a particular unit of time. These are commonly called meters, which provide an increment-only counter whose values are evened out with mean rates and exponentially weighted moving averages. The adjustments ensure you do not see spikes and troughs that might occur.

A spiral is a form of meter with a sliding window count, showing the increment of a counter in a particular time frame. If you are showing a value relative to the last minute, the sliding count could drop readings older than 1 minute and replace them with new ones, each second. Values you could show include the bit rate per second and operations per second, such as the number of initiated sessions.

Metrics have a timestamp associated with them. They are retrieved and stored in a time series database at regular intervals. A time series database is optimized to handle data indexed by timestamps, allowing you to access data in chronological order. Metrics are often aggregated and consolidated over time to provide overviews on a system level. You might want to collect all counters from a particular node type or see the total number of requests for all nodes in the last 15 minutes, hour, day, or month.

Look at the counter in Figure 16-3, which shows the total length of all the process message queues over a 12-hour period. It was plotted based on data collected when investigating a node crash that occurred at 3:34 AM. The node crashed after running out of memory. The metrics not only allowed us to identify what caused the crash, but provided an operational insight: had someone been monitoring the process message queue length, there was a 3-hour window where the issue could have been noticed and addressed.

Figure 16-3. Message queue length

In Erlang, ETS tables have the atomic operation ets:update_counter that allows you to increment and decrement counters. They can be used for speed, but beware of global locks and bottlenecks when scaling on multicore architectures. Recommended open source applications that focus on metrics include folsom and exometer. They offer some of the basic system metrics you expect out of your Erlang VM, and let you create your own metrics on a per node-basis.

Alarms

Alarms are a subset of events associated with a state. While an event will tell you that something happened, an alarm will indicate that something is ongoing. For instance, an event tells you that a socket was closed abnormally, but an alarm warns of your inability to create any socket connections toward an external database.

An alarm is raised when the issue you are monitoring manifests itself. This could represent, for instance, losing the last socket connection toward the database or failing to create a connection at startup. The alarm is said to remain active until the issue is resolved—maybe on its own accord, or through automatic or manual intervention—and the state reverts back to normal. This could happen when connectivity toward the database is restored. When this happens, the alarm is said to be cleared.

Alarms can also be associated with a severity. Severities include cleared, indeterminate, critical, major, minor, and warning. Each alarm severity is configured individually in the OAM node on a system-by-system basis, allowing the DevOps teams (and automated scripts) to react differently to them. For example:

• An alarm about a disk that’s 80% full might be associated with a minor severity. You can get notified about it during office hours and deal with it after the coffee break.

• However, if the disk continues filling up and becomes 90% full, the severity might rise to major. You can get called about that during office hours, out of office hours, and on weekends, but not between 11 PM and 7 AM.

• If the disk becomes 95% full, the severity might then go to critical; regardless of when this occurs, a pager call alerts someone, perhaps getting them out of bed, to investigate and address the cause before the node runs out of space and crashes.

In other systems, however, where nodes can crash without affecting availability and reliability, a node that crashed because its disk is full could be handled when convenient during office hours, assuming there is enough redundancy to guarantee the system can still handle the load. There is no one size fits all solution; each system is unique and must be managed differently.

Alarms can originate from the affected node or in the OAM node itself. They can be based on thresholds or state changes, or a mixture of the two.

In threshold-based alarms, metrics are monitored and the alarm is raised if a limit is exceeded in one of the metrics. Depending on the exceeded value, such as a disk full alarm, you could configure and apply different severities based on the requirements of your system. Other examples of threshold-based metrics include system limits such as memory, number of sockets, ports, open files, or ETS tables. If you are monitoring the number of requests that went through your system using an incremental counter, and this counter has not changed in the last minute, there is probably an issue and you will want to have someone investigate.

Most threshold-based alarms can be managed in the OAM node, but there are exceptions created by the frequency at which you transfer the data and the volumes you are willing to move. As an example, processes with very long message queues are usually a symptom of issues about to happen. They are easy to monitor, but the monitoring and raising of alarms has to happen on the managed nodes, as it is not feasible to send the message queue lengths of all processes to the OAM node. There will also be times where you want to detect these issues and raise an alarm immediately, without having to wait for the OAM node to receive the metrics and raise a threshold-based alarm.

State-based alarms are triggered when a potentially harmful state change occurs. They include alarms highlighting hardware issues such as a cabinet door being opened or a cooling fan failing. Other examples include the connectivity toward an external API or database being unresponsive or a node going down.

It’s up to you to decide how many alarms to send and the levels of detail to include in these alarms. You might want to do sanity checks in your system. What happens if a .beam, .boot, .app, or sys.config file gets corrupted? You will not notice until the node is restarted. Although a node can take a few seconds to restart, marginally affecting your uptime, identifying the corrupt file is enough to kiss your five nines goodbye. Isolating the corrupt file and fixing it is not easy and will take time, drastically increasing your downtime. If you think it will not happen to you, think again, because it has happened to many others, us included!

SASL has a basic alarm handler, which we cover in “The SASL Alarm Handler”. It allows you to raise and clear alarms, but does not handle severities and dependencies. The idea behind the SASL alarm handler is to manage alarms on the affected nodes. These can be forwarded to more complex alarm applications in your OAM node or external tools. But if you do write your own OAM node, you will need something more complex and configurable, handling alarm duplication, severities, and operator interaction.

No two systems are alike. Based on their functionality, traffic load, and user behavioral patterns, they will need to be managed and configured differently. A critical alarm in one system might be a nonissue or a warning in another. Once you’ve gone live, you will need to configure and fine-tune your alarms. This is commonly done when you handle false positives and false negatives. A false positive is an alarm generated because of a nonissue. It could be caused by an overly sensitive threshold or even paranoid management asking you to monitor too much. In cases where disks fill up slowly, a 70% disk full alarm could be active for months without any need for intervention. But in systems where disks fill up quickly, such an alarm might warrant waking someone up in the middle of the night, as it might be a warning that the node is going to crash within the hour. It is important to fine-tune your system and eliminate false positives, as too many of them will result in serious alarms being ignored.

It is also important to do the opposite: namely, manage false negatives. A false negative is when alarms should have been raised, but are not. This could be because of threshold configuration or lack of coverage in particular parts of the system. After every failure or degradation of service, review which alarms could have been raised (if any) and start monitoring events that might indicate that failure or service degradation is imminent.

We see alarms in systems too rarely, and when they do exist, they have often been added as an afterthought. The majority are threshold-based, with the only state-based alarms being based on external probes sending requests to the system. Alarms play a critical role in detecting and addressing anomalies before they escalate and have been a must in the telecoms space for decades. It is time for other verticals to adopt these practices widely and apply the lessons learned about them. It will greatly facilitate support automation (covered in the following section) and be one of the pillars you can count on when trying to achieve five-nines availability.