Logging
SlashDB has 3 sources of logs:
- SlashDB application
- WSGI server
- NGINX reverse proxy
Logging for SlashDB and the WSGI server is configured in the
SlashDB INI file located at
/etc/slashdb/slashdb.ini
Logging for the reverse proxy is configured in /etc/slashdb/nginx.conf
.
Info
Each log source has been adjusted to use a common format which uses the pipe character
|
as a separator. This allows for easier log browsing, merging log files
together and tracking requests across all components.
All loggers have placeholders for different attributes such as timestamp, request ID, URL, HTTP response status, etc.
Expand for the full list of attributes
Generic | SlashDB | uWSGI internal | uWSGI request | NGINX | |
---|---|---|---|---|---|
date & time | Yes | Yes | Yes | Yes | Yes |
timestamp | Yes | Yes | Yes | Yes | Yes |
source | Yes | Yes | Yes | Yes | Yes |
logger name | Yes | Yes | Yes | Yes | Yes |
level | Yes | Yes | Yes | Yes | Yes |
pid | Yes | Yes | Yes | Yes | Yes |
thread name | Yes | Yes | Yes | Yes | |
request id | Yes | Yes | Yes | ||
request method | Yes | Yes | Yes | ||
URL | Yes | Yes | Yes | ||
resp status code | Yes | Yes | Yes | ||
request processing time | Yes | Yes | |||
request size (header + body) | Yes | ||||
response size (headers + body) | Yes | Yes | |||
remote address | Yes | Yes | Yes | ||
http referer | Yes | Yes | Yes | ||
http user agent | Yes | Yes | Yes | ||
python module | Yes | Yes | |||
user id | Yes | ||||
message | Yes | Yes | Yes |
Here is an example of log entries from all three sources regarding the same request:
2024-02-05 13:03:05 | 1707138185141 | sdbapp | slashdb.requests | INFO | 25 | uWSGIWorker1Core4 | 42d58aadec19c9e11c36284adb236e0c | GET | /db/databricks-chinook/customer.json?limit=29 | | | | | 192.168.32.3 | https://beta.slashdb.com/db/databricks-chinook.html?retryToken=34VycJU:1 | Mozilla/5.0 (X11; Linux x86_64; rv:122.0) Gecko/20100101 Firefox/122.0 | adapters:derived_subscriber:101 | | Received request
2024-02-05 13:03:06 | 1707138186845 | sdbapp | slashdb | DEBUG | 25 | uWSGIWorker1Core4 | 42d58aadec19c9e11c36284adb236e0c | GET | /db/databricks-chinook/customer.json?limit=29 | | | | | 192.168.32.3 | https://beta.slashdb.com/db/databricks-chinook.html?retryToken=34VycJU:1 | Mozilla/5.0 (X11; Linux x86_64; rv:122.0) Gecko/20100101 Firefox/122.0 | __init__:get_view:8 | | Closed SQLAlchemy session
2024-02-05 13:03:06 | 1707138186845 | sdbapp | slashdb.requests | INFO | 25 | uWSGIWorker1Core4 | 42d58aadec19c9e11c36284adb236e0c | GET | /db/databricks-chinook/customer.json?limit=29 | | | | | 192.168.32.3 | https://beta.slashdb.com/db/databricks-chinook.html?retryToken=34VycJU:1 | Mozilla/5.0 (X11; Linux x86_64; rv:122.0) Gecko/20100101 Firefox/122.0 | adapters:derived_subscriber:101 | | Returned response
2024-02-05 13:03:06 | 1707138186846 | uwsgi | uwsgi | INFO | 25 | uWSGIWorker1Core4 | 42d58aadec19c9e11c36284adb236e0c | GET | /db/databricks-chinook/customer.json?limit=29 | 200 | 1.704940 | | 12955 | 192.168.32.3 | https://beta.slashdb.com/db/databricks-chinook.html?retryToken=34VycJU:1 | Mozilla/5.0 (X11; Linux x86_64; rv:122.0) Gecko/20100101 Firefox/122.0 | | |
2024-02-05 13:03:06 | 1707138186846 | nginx | nginx | INFO | 22 | | 42d58aadec19c9e11c36284adb236e0c | GET | /db/databricks-chinook/customer.json?limit=29 | 200 | 1.705 | 740 | 13544 | 192.168.32.3 | https://beta.slashdb.com/db/databricks-chinook.html?retryToken=34VycJU:1 | Mozilla/5.0 (X11; Linux x86_64; rv:122.0) Gecko/20100101 Firefox/122.0 | | |
SlashDB Application Logs
The application logs are configured in the
SlashDB INI file between lines
# Logging Config
and # End of Logging Config
. You can read more about Python 3
logging in the Logging HOWTO documentation.
The logging config allows users to customize what logs are collected, where they are sent and in what format.
Loggers
The base sources for logs are three loggers: root
, slashdb
and exc_logger
, which are enabled by default.
There are three others: sqlalchemy
,sqlalchemy_engine
and sqlalchemy_pool
are useful for debugging communication with databases and are disabled by default.
Logger root
Info
This is a special logger that collects log entries from all other loggers unless the other loggers are configured with propagate = 0
to prevent that behavior.
- level
INFO
- logs are passed to the
file
handler which uses thegeneric
formatter - logs are saved in
/var/log/slashdb/slashdb.log
.
[logger_root]
level = INFO
handlers = file
Logger slashdb
Info
A general SlashDB application logger which provides additional SlashDB specific log record attributes used by a formatter.
- level
INFO
- logs are sent to the
file_slashdb
handler which uses theslashdb
formatter propagate = 0
prevents duplicated logs by not passing logs to theroot
logger- logs are saved in
/var/log/slashdb/slashdb.log
[logger_slashdb]
level = INFO
handlers = file_slashdb
qualname = slashdb
propagate = 0
Logger exc_logger
Info
A logger for errors which are not handled by the application.
- level
ERROR
- logs are passed to the
exc_handler
handler and formatted with theexc_formatter
propagate = 0
prevents duplicated logs by not passing logs to theroot
logger- logs are saved in
/var/log/slashdb/exceptions.log
[logger_exc_logger]
level = ERROR
handlers = exc_handler
qualname = exc_logger
propagate = 0
Logger sqlalchemy
Info
A general logger for communication with databases. Provides information about connections, database reflect process, etc.
- level
WARNING
- the logger does not have a specific handler defined but logs are propagated
(
propagate = 1
), which means the logs will also be collected and handled by theroot
logger and saved in/var/log/slashdb/slashdb.log
.
[logger_sqlalchemy]
level = WARNING
handlers =
qualname = sqlalchemy
propagate = 1
Logger sqlalchemy_engine
Info
Similar to the sqlalchemy
logger, but monitors the database engine,
which allows it to log actual SQL statements that are sent to databases or even the returned data set.
[logger_sqlalchemy_engine]
level = INFO
handlers =
qualname = sqlalchemy.engine
propagate = 1
Logger sqlalchemy_pool
Info
Similar to the sqlalchemy
logger, but logs information related to creating database connections.
[logger_sqlalchemy_pool]
level = INFO
handlers =
qualname = sqlalchemy.pool
propagate = 1
Handlers
These receive log entries from loggers, format them using a predefined formatter
and
send them to an output stream like stdio, files, etc.
Tip
Read more about available handlers: Python 3 logging handlers.
Handler file
This is a ConcurrentRotatingFileHandler
which saves log entries in 10 files,
each 5 MB. The handler is configured to use the the generic
formatter.
[handler_file]
class = concurrent_log_handler.ConcurrentRotatingFileHandler
args = ("/var/log/slashdb/slashdb.log", "a", 5*1024*1024, 10, "utf-8")
level = NOTSET
formatter = generic
The args
are:
/var/log/slashdb/slashdb.log
location and name of the file where logs are storeda
is the file mode used to append data to the file5*1024*1024
is the maximum size of each file, i.e. 5 MB10
is number of files that are kept, the oldest file is removed to make space for newer logsutf-8
specifies the encoding of the file
Important
The args
for the two handlers handler_file
and handler_file_slashdb
must be exactly the same
because they save log entries to the same file /var/log/slashdb/slashdb.log
.
Handler file_slashdb
This is a ConcurrentRotatingFileHandler
which saves log entries in 10 files,
each 5 MB. The handler is configured to use the slashdb
formatter that can handle SlashDB-specific log record attributes.
[handler_file_slashdb]
class = concurrent_log_handler.ConcurrentRotatingFileHandler
args = ("/var/log/slashdb/slashdb.log", "a", 5*1024*1024, 10, "utf-8")
level = NOTSET
formatter = slashdb
The args
are:
/var/log/slashdb/slashdb.log
location and name of the file where logs are storeda
is the file mode used to append data to the file5*1024*1024
is the maximum size of each file, i.e. 5 MB10
is number of files that are kept, the oldest file is removed to make space for newer logsutf-8
specifies the encoding of the file
Important
The args
for the two handlers handler_file
and handler_file_slashdb
must be exactly the same
because they save log entries to the same file /var/log/slashdb/slashdb.log
.
Handler exc_handler
This is a ConcurrentRotatingFileHandler
which saves log entries in 10 files,
each 5 MB. The handler is configured to use the exc_formatter
[handler_exc_handler]
class = concurrent_log_handler.ConcurrentRotatingFileHandler
args = ("/var/log/slashdb/exceptions.log", "a", 5*1024*1024, 10, "utf-8")
level = ERROR
formatter = exc_formatter
The args
are:
/var/log/slashdb/exceptions.log
location and name of the file where logs are storeda
is the file mode used to append data to the file5*1024*1024
is the maximum size of each file, i.e. 2 MB10
is number of files that are kept, the oldest file is removed to make space for newer logsutf-8
specifies the encoding of the file
Formatters
These define how the text in log entries is formatted. Various
log record attributes can be used to provide additional information beyond the message from the source; for example, the log record attribute %(asctime)s
adds human readable date and time to the log entry.
Formatter generic
The general formatter that uses standard log record attributes.
[formatter_generic]
format = %(asctime)-.19s | %(created)d%(msecs)03d | sdbapp | %(name)s | %(levelname)-5.5s | %(process)d | %(threadName)s | | | | | | | | | | | %(module)s:%(funcName)s:%(lineno)d | | %(message)s
Info
Empty segments in the format are necessary to keep logs consistent with logs from different sources, making them easier to analyze together.
Formatter slashdb
The root
and slashdb
loggers are very similar but must be separated because only the slashdb
logger provides SlashDB-specific log record attributes. The formatter will fail to generate a log entry if an attribute is not available from its source. The slashdb
logger has a special formatter configuration for this purpose.
The formatter handles SlashDB-specific log record attributes associated with each log entry such as:
user_id
- SlashDB authenticated user idrequest_id
- unique request identifier that is the same across all loggers, making it easier to track a specific requestrequest_method
- HTTP request methodrequest_url
- request URLresponse_status_code
- status code of the HTTP responserequest_client_addr
- IP address of the client that sent the requestrequest_referer
- address of the web page from which the resource was requestedrequest_user_agent
- client user agent
[formatter_slashdb]
format = %(asctime)-.19s | %(created)d%(msecs)03d | sdbapp | %(name)s | %(levelname)-5.5s | %(process)d | %(threadName)s | %(request_id)s | %(request_method)s | %(request_url)s | %(response_status_code)s | | | | %(request_client_addr)s | %(request_referer)s | %(request_user_agent)s | %(module)s:%(funcName)s:%(lineno)d | %(user_id)s | %(message)s
Formatter exc_formatter
Formatter for exceptions that matches the unified log format.
[formatter_exc_formatter]
format = %(asctime)-.19s | %(created)d%(msecs)03d | sdbapp | %(name)s | %(levelname)-5.5s | %(process)d | %(threadName)s | | | | | | | | | | | %(module)s:%(funcName)s:%(lineno)d | | %(message)s
Debugging
Extended log details
There are 5 levels of event severity:
- DEBUG
- INFO
- WARNING
- ERROR
- CRITICAL
DEBUG
is the most detailed, CRITICAL
logs only the most important
events.
Info
In case more detailed logs are needed for debugging, you can change the log level severity:
- set level to
DEBUG
for theroot
andslashdb
loggers - set level to
INFO
for thesqlalchemy
logger
Detailed log entries will appear in /var/log/slashdb/slshdb.log
.
Limiting SQLAlchemy Logger Output for Clarity
Because the sqlalchemy
logger collects logs from many
SQLAlchemy modules, the output may be very cluttered when using the INFO
level. In such cases, it's better set the detailed logging level on a more specific logger, e.g sqlalchemy.engine
and keep the sqlalchemy
level as INFO
. The sqlalchemy.engine
logger can provide useful information like the SQL statements that are sent to databases.
Info
The sqlalchemy.engine
logger is already in the INI configuration file and
only has to be enabled. Just replace the logger key sqlalchemy
with sqlalchemy_engine
for the keys
option in the [loggers]
section of the INI file. The section should look like:
[loggers]
keys = root, slashdb, exc_logger, sqlalchemy_engine
uWSGI Server Logs
SlashDB is distributed with uWSGI server. By default, the server logs are saved
separately from application logs in /var/log/slashdb/uwsgi.log
The logs provided by uWSGI are configurable in the [uwsgi]
section starting at the line labeled # uWSGI Logging Settings
# uWSGI Logging Settings
logto = /var/log/slashdb/uwsgi.log
logfile-chown = slashdb:slashdb
# 20 MB
log-maxsize = %(20 * 1024 * 1024)
# internal uWSGI logs
logger = stdio
log-encoder = format ${strftime:%%Y-%%m-%%d %%H:%%M:%%S} | ${millis} | uwsgi | uwsgi | INFO | | | | | | | | | | | | | | | ${msgnl}
# request logs
logger-req = stdio
log-req-encoder = format ${strftime:%%Y-%%m-%%d %%H:%%M:%%S} | ${millis} | uwsgi | uwsgi | INFO | ${msgnl}
log-format = %(pid) | uWSGIWorker%(wid)Core%(core) | %(var.REQUEST_ID) | %(method) | %(uri) | %(status) | %(secs) | | %(size) | %(addr) | %(referer) | %(uagent) | | |
logto
- location of the uWSGI log file (not rotated)logfile-chown
- sets the log file owner and grouplog-maxsize
- maximum size of the file in byteslogger
- type of logger plugin to be used when optionlogto
is not present; used when uWSGI is started as foreground process for debugging purposeslog-encoder
- log encoder type and format for uWSGI internal logs which matches the unified log formatlog-req-encoder
- log encoder type and format for request logs which matches the unified log format
NGINX Logs
All HTTP requests are logged by the reverse proxy, NGINX. Request logs match the unified format and are saved in /var/log/nginx/access.log
. Errors are saved in /var/log/nginx/error.log
.
Info
NGINX does not allow configuring error message formats, but the
slashdb-diag
tool can parse these logs and output them in the unified format.
log_format sdblog '$time_iso8601mod | $msec_int | nginx | nginx | INFO '
'| $pid | | $request_id | $request_method | $request_uri '
'| $status | $request_time | $request_length | $bytes_sent '
'| $remote_addr | $http_referer | $http_user_agent | | | ';
access_log /var/log/nginx/access.log sdblog;
error_log /var/log/nginx/error.log;
log_format
- name and format for access logaccess_log
- path to file for access logerror_log
- path to file for error log
For more information on configuring logging, please refer to the NGINX documentation.
Collecting Logs with slashdb-diag
tool
The CLI tool slashb-diag
helps to collect logs and configuration files. It allows filtering logs by a specified date range, combining different logs, and zipping them with configuration files into a single file. For security purposes, all database and user credentials are masked.
To use the tool, SSH to the server, activate the SlashDB environment and run slashdb-diag
which by default collects all configs and logs from default locations, then combines all logs into a single log and finally makes a single zip file.
Info
For more options, run slashdb-diag --help
to see the help documentation.
source /opt/slashdb/bin/activate
slashdb-diag --help
Usage: slashdb-diag [OPTIONS] LOG_FILES
Tool for collecting log files and config files to help with troubleshooting.
Examples:
$ slashdb_diag
Will try to find configs and logs in standard locations
and will save them in a zip file.
$ slashdb_diag --ini /path/to/slashdb.ini --nginx-conf /path/to/nginx.conf
Will get configs and logs based on the paths provided.
$ slashdb_diag /var/log/slashdb/slashdb.log /var/log/slashdb/uwsgi.log --no-combined --no-zip
Will get only these two log files and save them in a folder.
$ slashdb_diag --start 2023-11-17T16:06:10 --end 2023-11-17T17:06:10
Will get only logs in the given time frame.
Options:
--ini FILE Path to slashdb.ini.
--nginx-conf FILE Path to nginx.conf.
--start [%Y-%m-%dT%H:%M:%S] Start date of the logs, YYYY-MM-DDTHH:mm:ss
format.
--end [%Y-%m-%dT%H:%M:%S] End date of the logs, YYYY-MM-DDTHH:mm:ss
format.
--configs / --no-configs Whether to include config files. [default:
configs]
--zip / --no-zip Whether to zip the resulting directory.
[default: zip]
--combined / --no-combined Whether to combine log files to a single file.
[default: combined]
--help Show this message and exit.
Saving Logs in S3
Assuming the AWS CLI is configured for root on the SlashDB instance, you can run a daily cron job that will copy log files.
Below is a cron job definition that runs every day at 2 AM, looking for files in SDB_LOGS_DIR that are not older than 1 day and sends them to an S3 bucket defined in SDB_LOGS_S3.
The same is done for NGINX logs from folder NGX_LOGS_DIR to bucket NGX_LOGS_S3.
To edit cron:
sudo crontab -e
then paste, assuming the environment variables SDB_LOGS_S3 and NGX_LOGS_S3 are S3 buckets and folders where you want to save the logs:
SDB_LOGS_DIR=/var/log/slashdb
SDB_LOGS_S3=s3://slashdb-logs/instance1/slashdb
NGX_LOGS_DIR=/var/log/nginx
NGX_LOGS_S3=s3://slashdb-logs/instance1/nginx
0 2 * * * find ${SDB_LOGS_DIR} -type f -mtime -1 | xargs -L 1 -I {} bash -c 'aws s3 cp {} ${SDB_LOGS_S3}'
0 2 * * * find ${NGX_LOGS_DIR} -type f -mtime -1 | xargs -L 1 -I {} bash -c 'aws s3 cp {} ${NGX_LOGS_S3}'
Sending Logs to CloudWatch
Info
The easiest way is to use amazon-cloudwatch-agent. That allows sending any logs without need to install additional Python libraries.
To start quickly, follow the blog post Monitoring NGINX with CloudWatch. It has straightforward instructions on how to setup the amazon-cloudwatch-agent.
To dive deeper, read the official Amazon documentation on the agent.