Learning Heroku Postgres (2015)

Chapter 7. Understanding Log Statements and Common Errors

Logs are important tools to discover problems and failures in your applications. Through logs, it is possible to identify the causes and find appropriate solutions. Heroku Postgres provides all logs generated by your databases.

The main component in the Heroku structure is the Logplex. It collects logs from different sources and provides them in a single channel so that you can analyze them and take appropriate actions in real time.

In this chapter, you will learn how to view logs. You will understand the most common errors and also learn how to collect metrics from the logs.

This chapter will cover:

· Log statements

· Common errors

· Metrics logs

Log statements

The first step is to ensure that you have access to all logs in real time. The Heroku client provides the heroku logs command that allows you to view all logs collected by the Logplex in a unified manner. Using this command, you can filter through the postgres process to view only database logs. You can also use the -t option (tail); this opens a continuous stream of data logs. Here is an example:

$ heroku logs -p postgres -t --app your-app-name

2014-11-01T23:41:42Z app[postgres.10]: [CHARCOAL] checkpoint complete: wrote 0 buffers (0.0%); 0 transaction log file(s) added, 0 removed, 1 recycled; write=0.000 s, sync=0.000 s, total=0.004 s; sync files=0, longest=0.000 s, average=0.000 s

This way, you can view the logs generated by your Postgres database, perform the diagnosis, and identify the common errors.

The heroku logs command provides the following options to display the recent log output:

· -n, --num NUM: This refers to the number of lines to display

· -p, --ps PS: This only display logs from the given process

· -s, --source SOURCE: This only display logs from the given source

· -t, --tail: This refers to continually streaming logs

Tip

The logs are available for production database plans. They are not available for plans in the Hobby tier.

Common errors

There are a number of common errors that can be easily identified through the logs. Understanding these errors and analyzing can help you in the process of continuous database improvement.

Then you will understand the most common ones so that you can take the necessary action in order to solve them.

LOG: long duration

Queries that take longer than 2 seconds are logged automatically so that you can identify and optimize your code. These logs are generated in the following format:

[8-2] g0afa5bjht [GOLD] LOG: duration: 63.697 ms statement: SELECT "courses".* FROM "courses"...

If there are large numbers of these logs, probably your application has performance problems. A good recommendation is to try to reduce the execution time of your queries by 10 ms. You can achieve this optimization by adding indexes or using the EXPLAINcommand from PostgreSQL to understand the performance issues in your query.

LOG: unexpected EOF on client connection

This error occurs when your application does not disconnect the Postgres database appropriately. It indicates that there was a connection loss between the application and the database; this states that the connection was not clear and the problem still remains. The following example illustrates this situation:

app[postgres]: LOG: could not receive data from client: Connection reset by peer app[postgres]: LOG: unexpected EOF on client connection

heroku[router]: at=error code=H13 desc="Connection closed without response" method=GET path=/crash host=alphabeta.herokuapp.com dyno=web.1 connect=1ms service=10ms status=503 bytes=0

heroku[web.1]: Process exited with status 1

heroku[web.1]: State changed from up to crashed

The recommended solution for this problem is to analyze the logs relating to your application and identify the causes of this connection loss. Usually, this error is related to the code that implements the database connection.

PGError: permission denied for relation

This error occurs when you are working with the database plan in the Hobby tier. It has limitations on the amount of records that can be inserted into the database. When this limit is reached, the following log line appears:

PGError: ERROR: permission denied for relation courses

In order to solve this problem, you should migrate to another database plan in the production tier that does not provide constraints on the amount of records.

PGError: operator does not exist

You may see this error when different data types are compared without performing the casting, for example, a string comparison with an integer. A log similar to the following one will appear:

PGError: ERROR: operator does not exist: character varying = integer

The solution for this error is to fix the SQL so that it uses the appropriate casting or change the SQL query for the same data type.

PGError: relation "table-name" does not exist

This is a standard error when you try to access a table in the database that does not exist:

PGError: ERROR: relation "students" does not exist

You can solve this problem by checking whether all database migrations were performed or by checking whether your SQL syntax is written correctly.

PGError: column "column-name" cannot...

This is an error that occurs when PostgreSQL does not know how to convert the data type to another format. For example, if you have a string out of the pattern and the database attempts to transform it into a date, the following log is generated:

PGError: ERROR: column "created_at" cannot be cast to type "date"

You can solve this error by fixing the problem in the column data or checking whether your SQL query is written correctly.

PGError: SSL SYSCALL error: EOF detected

This is an error that indicates a problem on the client side. It can occur because of two situations: the first is a sharing connection problem between more than one process, and the second one is due to an abrupt disconnection on the client side:

PGError: ERROR: SSL SYSCALL error: EOF detected: SELECT "doctors".* FROM "doctors" ORDER BY id DESC LIMIT 10

This error is commonly solved by Heroku. It automatically detects the problem, kills the dyno, and creates a new dyno, thus re-establishing the connection.

PGError: prepared statement "a30" already exists

This is another problem related to sharing a connection between multiple processes when the client side tries to prepare a statement with a name already used by another process, usually without clearing the original statement.

To solve this problem, you need to consider all current processes and make the necessary corrections to avoid the sharing connection problem.

FATAL: too many connections for role

You may find this error when you are using the plans in the Hobby tier. They offer a limitation of 20 simultaneous connections to the database, thus displaying this log message:

FATAL: too many connections for role "[role name]"

There are several suggestions to solve this problem. The first one is to close some connections with the database that you are not using, and the other suggestion is to migrate the database plan for one that supports a larger number of connections.

FATAL: could not receive data...

This problem is associated with database replication to a follower database when a network problem or a SSL failed negotiation occurs. The following error is logged:

FATAL: could not receive data from WAL stream: SSL error: sslv3 alert unexpected message

The solution to this problem is executed automatically by the Heroku architecture, so the network problem or SSL is resolved. The primary database completes the synchronization with the follower database.

FATAL: role "role-name"...

This is an error that occurs when the database is deprovisioned but its connection still exists:

FATAL: role "g5hja7jkeu" is not permitted to log in (PG::Error)

There are two solutions for this problem: the first one is to provision a new database through the heroku adds:add heroku-postgresql command, and the second one is to promote one database as a primary database through the heroku pg:promote HEROKU_POSTGRESQL_[COLOR]_URL command.

FATAL: terminating connection due to administrator command

This error is caused when the connection process with the database is killed. This can be accomplished in two ways: through the heroku pg:kill command and by running the SELECT pg_cancel_backend(pid) query. The following log is generated:

FATAL: terminating connection due to administrator command

FATAL: remaining connection slots are reserved for non-replication superuser connections

All database plans on Heroku Postgres have a maximum number of connections; this error is generated when the number of connections has been reached. Also, it indicates that there are a number of connections reserved for the Heroku team:

FATAL: remaining connection slots are reserved for non-replication superuser connections

The indicated solution for this problem is to search for idle connections and kill their processes. Another suggestion is to migrate to a database plan that supports a higher number of connections.

Temporary file: path "file path", size "file size"

This is an informational log; it announces that the maximum size for temporary logs, which is 10240 KB, has been reached. These logs are used for temporary queries. Overuse of these temporary logs can impact SQL query performance:

temporary file: path "base/pgsql_tmp/pgsql_tmp234678.434", size 1075741736

Metrics logs

Heroku Postgres has a log statement that provides metrics on database usage. This feature is important to monitor the behavior of the database over time.

The metrics information helps you improve database configurations, and identify critical issues, it also teaches you how to improve your application's architecture.

To view the metrics logs, you should use the heroku logs command by filtering through the heroku-postgres process, as shown in the following example:

$ heroku logs -p heroku-postgres -t --app your-app-name

2014-11-02T00:35:38+00:00 app[heroku-postgres]: source=HEROKU_POSTGRESQL_CHARCOAL sample#current_transaction=179097 sample#db_size=61229240bytes sample#tables=38 sample#active-connections=9 sample#waiting-connections=0 sample#index-cache-hit-rate=0.99999 sample#table-cache-hit-rate=1 sample#load-avg-1m=0.395 sample#load-avg-5m=0.44 sample#load-avg-15m=0.435 sample#read-iops=17.042 sample#write-iops=1.7437 sample#memory-total=7629452kB sample#memory-free=64876kB sample#memory-cached=6838076kB sample#memory-postgres=364248kB

Tip

The information on the metrics is available in the standard, premium, and enterprise plans.

The following list will help you understand every piece of information available for each attribute.

· The logs show the timestamp of the period measurement.

· source: This is the database associated with data measurement.

· sample#db_size: The byte number contained in the database. This includes all tables and indexes, including the database bloat data.

· sample#tables: The table numbers in the database.

· sample#active-connections: The connection numbers established in the database.

· sample#current_transaction: The current transaction ID.

· sample#index-cache-hit-rate: The rate of the lookups index provided by the shared buffer cache, rounded to 5 decimal points.

· sample#table-cache-hit-rate: The rate of table lookups provided by the shared buffer cache, rounded to 5 decimal points.

· sample#waiting-connections: Connection numbers waiting to be purchased. If many connections are waiting, this can be a sign of database concurrence mistreated.

· sample#load-avg-1m, sample#load-avg-5m and sample#load-avg-15m: The system load average within 1 minute, 5 minutes, and 15 minutes, divided by the number of available CPUs.

· sample#read-iops and sample#writes-iops: The number of reads and writes for each block of 16 KB of I/O.

· sample#memory-total: Total available memory in KB.

· sample#memory-free: Total free memory in KB.

· sample#memory-cached: Total cache memory in KB.

· sample#memory-postgres: Approximate total of memory used by PostgreSQL in KB.

Self-test questions

Answer true or false.

1. Are logs important information source for identifying problems in your database?

2. Does the heroku logs command only show database logs?

3. Is the Postgres process necessary to filter the database logs?

4. Is Logplex a feature that allows a unified view of logs?

5. Can errors be divided into three common categories: LOG, FATAL, and PGError?

6. Is there an error that informs users if the query is taking more than 2 seconds?

7. Do the plans in the Hobby tier offer many limitations?

8. Should you always be careful about processes that use the same connection with the database?

9. Can you view important information about database metrics through the heroku logs command using the heroku-postgres filter?

10. Is the metrics data log with sample# information just examples?

Summary

In this chapter, you learned how to access logs generated by Heroku Postgres. You understood that logs are important tools for investigating and solving problems related to your application and database. You also learned how to identify and solve the most common errors that may occur.

In the last part of this chapter, you learned how to gather metrics information on your database. You understood that this information is important for you to make decisions in order to improve your database, and that some issues can be resolved by optimizing your application.

In the next and final chapter of this book, you will learn about some additional issues necessary for many developers, and you will learn how to use some tools such as full text search, data caching, PostGIS, and some other interesting extensions.