Logs

Note

The Bastion comes with a lot of traceability features, you have to ensure that you've done your configuration correctly so that those logs are kept in a safe place when you need them. It is warmly advised to enable at least the syslog option, and push your logs to a remote syslog server.

Message types

The Bastion has several configurable ways of logging events, but before detailing those, let's see the different message types that can be logged. The Bastion currently has 12 different message types, listed below:

First, let's list the fields that are common to all the message types:

uniqid

This is the unique connection ID, you can find all the logs relevant to the same connection by filtering on the uniqid. This ID is also, by default, part of the filename given to the ttyrec files, for easier correlation. The same ID is also used in the sqlite logs, if you enabled those. In some rare cases, the value can be "-", for example if a satellite script has something to log, not linked to an actual connection or session.

version

This indicates the version of The Bastion software that is writing the log

pid, ppid

This is the system PID (resp. system parent PID) of the process writing the log, for easier correlation with system audit logs if you have them

sysuser

This is the system user under which the process writing the log is currently running on, can be useful to detect abnormalities

sudo_user

When the value is present, it contains the system user name that has launched the sudo command the code is currently running under (this will be the case if a so-called "bastion helper" is pushing a log, for example). However this field will often have an empty value, it means that the code that is writing the log is not running under sudo

uid, gid

This is the system user ID aka UID (resp. group ID aka GID) under which the process writing the log is currently running

account

This is the name of the bastion account that launched the command that produced the log

The other fields depend on the message type, as detailed in the next sections.

open

This log is produced when a user established a session with the bastion.

Example:

Dec 28 11:12:26 myhostname bastion: open uniqid="e9e4baf6873b" version="3.01.03" pid="18721" ppid="18720"
sysuser="gthreepw" sudo_user="" uid="99998" gid="99998" account="gthreepw" cmdtype="ssh" allowed="true"
ip_from="172.17.0.1" port_from="39696" host_from="172.17.0.1" ip_bastion="172.17.0.2" port_bastion="22"
host_bastion="myhostname.example.org" user="foo" ip_to="172.17.0.123" port_to="22" host_to="srv123.example.org"
plugin="" globalsql="ok" accountsql="ok" comment="" params="ttyrec -f
/home/gthreepw/ttyrec/172.17.0.123/2020-12-28.11-12-26.074894.e9e4baf6873b.gthreepw.foo.172.17.0.123.22.ttyrec -F
/home/gthreepw/ttyrec/172.17.0.123/%Y--%d.%H-%M-%S.#usec#.e9e4baf6873b.gthreepw.foo.172.17.0.123.22.ttyrec --
/usr/bin/ssh 172.17.0.123 -l foo -p 22 -i /home/gthreepw/.ssh/id_rsa4096_private.1594384739 -i
/home/keykeeper/keyagroup/id_ed25519_agroup.1607524914 -o PreferredAuthentications=publickey"

Fields:

cmdtype

Indicates which category of command has been requested by the user:

  • ssh: the user is trying to establish an SSH egress connection to a remote server

  • telnet: the user is trying to establish a telnet egress connection to a remote server

  • abort: the action requested by the user has been aborted early, possibly because of permission issues or impossibility to understand the request, more information is available in the bastion_comment field

  • osh: the user is trying to execute a bastion plugin with the --osh command

  • interactive: the user just entered interactive mode. Note that all the commands launched through the interactive mode will still have their own log.

  • sshas: an administrator is currently establishing a connection on behalf of another user. This connection will also have its own log.

  • proxyhttp_daemon: the HTTPS proxy daemon received a request

  • proxyhttp_worker: the HTTPS proxy worker specifically spawned for the user by the daemon is handling the request

allowed

Indicates whether the requested action was allowed or not by the bastion, after executing the authorization phase. Will be either "true" or "false".

ip_from, port_from, host_from

These are the IP and source port as seen by the bastion, from which the ingress connection originates. If the bastion can resolve the reverse of the IP to a hostname, it'll be indicated in host_from, otherwise the IP will be repeated there.

ip_bastion, port_bastion, host_bastion

These are the IP and port of the bastion to which the ingress connection terminates. If your bastion has several IPs and/or interfaces, this can be useful. If the bastion can resolve the reverse of the IP to a hostname, it'll be indicated in host_bastion, otherwise the IP will be repeated there.

ip_to, port_to, host_to

These are the IP and destination port to which the bastion will connect on the egress side, on behalf of the requesting user. If the bastion can resolve the reverse of the IP to a hostname, it'll be indicated in host_to, otherwise the IP will be repeated there.

plugin

When cmdtype is osh, the name of the command (or plugin) will appear in this field. Otherwise it'll be blank.

accountsql

This field will contain either:

  • ok: when enableAccountSqlLog is enabled, and we successfully inserted a new row for the log

  • no: when enableAccountSqlLog is disabled

  • error: when we couldn't insert a new row, error followed by a detailed error message, for example "error SQL error [global] err 8 while doing [inserting data (execute)]: attempt to write a readonly database".

globalsql

This field can contain the same values than accountsql above, but for enableGlobalSqlLog instead of enableAccountSqlLog

comment

Some more information about the current event, depending on the cmdtype value.

params

This is the fully expanded command line that will be launched under the currently running user rights, to establish the egress connection, if applicable.

close

This log is produced when a user terminates a currently running session with The Bastion. It is always matched (through the uniqid) to another log with the open message type.

Example:

Dec 28 11:12:26 myhostname bastion: open uniqid="e9e4baf6873b" version="3.01.03" pid="18721" ppid="18720"
sysuser="gthreepw" sudo_user="" uid="99998" gid="99998" account="gthreepw" cmdtype="ssh" allowed="true"
ip_from="172.17.0.1" port_from="39696" host_from="172.17.0.1" ip_bastion="172.17.0.2" port_bastion="22"
host_bastion="myhostname.example.org" user="foo" ip_to="172.17.0.123" port_to="22"
host_to="srv123.example.org" plugin="" globalsql="ok" accountsql="ok" comment="" params="ttyrec -f
/home/gthreepw/ttyrec/172.17.0.123/2020-12-28.11-12-26.074894.e9e4baf6873b.gthreepw.foo.172.17.0.123.22.ttyrec -F
/home/gthreepw/ttyrec/172.17.0.123/%Y--%d.%H-%M-%S.#usec#.e9e4baf6873b.gthreepw.foo.172.17.0.123.22.ttyrec --
/usr/bin/ssh 172.17.0.123 -l foo -p 22 -i /home/gthreepw/.ssh/id_rsa4096_private.1594384739 -i
/home/keykeeper/keyagroup/id_ed25519_agroup.1607524914 -o PreferredAuthentications=publickey" sysret="0"
signal="" comment_close="hostkey_changed passauth_disabled" duration="43.692"

All the fields from the corresponding open log are repeated in this log line, in addition to the following fields:

sysret

Return code of the launched system command (that established the egress connection) or the plugin (if an --osh command was passed). If we don't have a return code, for example because we were interrupted by a signal, the value will be empty.

signal

Name of the UNIX signal that terminated the command, if any. For example "HUP" or "SEGV". If we got no signal, the value will be empty.

comment_close

A space-separated list of messages giving some hints gathered at the end of a session. For example hostkey_changed passauth_disabled means that we detected that our egress ssh client emitted a warning telling us that the remote keys changed, and also that password authentication has been disabled.

duration

Amount of seconds (with a millisecond precision) between the session open and the session close.

warn, die

These logs are produced when Perl emits a warning (using the warn() call), or respectively when Perl halts abruptly due to a die() call. This should not happen during nominal use. You might want to keep a look on those messages if they're produced.

Example:

Dec 28 11:12:26 myhostname bastion: warn uniqid="a46e51b5dce4" version="3.01.02" pid="3308212" ppid="3308206"
sysuser="lechuck" sudo_user="" uid="99994" gid="99994" msg="Cannot find termcap: TERM not set at
/usr/share/perl/5.28/Term/ReadLine.pm line 379.  " program="/opt/bastion/bin/shell/osh.pl" cmdline="-c^-i ssh
root@172.17.0.222 id" trace=" at /opt/bastion/bin/shell/../../lib/perl/OVH/Bastion.pm
line 41.   OVH::Bastion::__ANON__(\"Cannot find termcap: TERM not set at /usr/share/perl/5.28/Ter\"...)
called at /usr/share/perl/5.28/Term/ReadLine.pm line
391     Term::ReadLine::TermCap::ornaments(Term::ReadLine::Stub=ARRAY(0x5575da36b690), 1) called at
/opt/bastion/lib/perl/OVH/Bastion/interactive.inc line 77   OVH::Bastion::interactive(\"realOptions\", \"-i ssh
root\\@172.17.0.222 id\"..., \"timeoutHandler\", CODE(0x5575da15aa78), \"self\", \"lechuck\")
called at /opt/bastion/bin/shell/osh.pl line 485 "

Fields:

msg

This is the message used as a parameter to the warn() or die() call

program

Contains the name of the currently running program (first parameter of execve())

cmdline

Contains the full command line passed to the currently running program (remaining parameters of execve()). The command-line fields are separated by ^'s.

trace

The call trace leading to this warn() or die()

warn-info, die-info

These logs are produced when some known portion of code (including libraries) called warn() or die() but in a known case that can happen during nominal use. Don't use these logs to directly trigger an alert, but you can keep an eye on those, as e.g. an unusually high number of occurences in a short time may be a weak signal that somebody or something is misbehaving.

The fields are the same than the ones specified above for warn and die.

code-info

These logs are produced when some portion of the code encounters an minor issue that is worth logging, to e.g. help debugging an issue or understanding what happened in a specific use-case, for example if a user-session ended abruptly. These logs are not the result of an error on the bastion configuration and don't mandate immediate admin attention.

Example:

Dec 25 14:56:11 myhostname bastion: code-info uniqid="98d2f32b1a2d" version="3.07.00" pid="3708843"
ppid="3708842" sysuser="lechuck" sudo_user="" uid="8423" gid="8423" msg="execute():
error while syswriting(Broken pipe) on stderr, aborting this cycle"

Fields:

msg

A human-readable text describing the error

code-warning

These logs are produced when some portion of the code encounters an unexpected issue or abnormality that is worth logging. They'll usually not be emitted due to a bad user interaction, but rather if the bastion is misconfigured, or for anything that might need some attention or fixing from the admins.

Example:

Dec 28 11:12:26 myhostname bastion: code-warning uniqid="ffee33abd1ba" version="3.01.03" pid="3709643"
ppid="3709642" sysuser="lechuck" sudo_user="" uid="8423" gid="8423" msg="Configuration error
for plugin selfGenerateEgressKey on the 'disabled' key: expected a boolean, casted 'no' into false"

Fields:

msg

A human-readable text describing the error

acl

This log is produced when an access control list is modified, either personal accesses of an account, or a group servers list.

Example:

Dec 28 11:12:26 myhostname bastion: acl uniqid="f25fe71c6635" version="3.01.02" pid="3116604"
ppid="3116603" sysuser="keysomegroup" sudo_user="lechuck" uid="10006" gid="10057" action="add"
type="group" group="somegroup" account="" user="root" ip="172.16.2.2" port="22" ttl="" force_key="" comment=""

Fields:

action

Will be either add if an access is added, or del if an access is removed

type

Will be either group if we're modifying a group server list, in which case the group field will be filled, or account if we're modifying personal accesses of an account, in which case the account field will be filled

group

If type is group, indicates which group servers list has been modified

account

If type is account, indicates which account personal accesses have been modified

user

The remote user part of the access we're adding/removing

ip

The IP or IP block of the access we're adding/removing

port

The port of the access we're adding/removing

ttl

If set, represents the TTL after which the access will automatically be removed

force_key

If set, this contains the fingerprint of the key that'll be used for this access

comment

Any comment set by the user adding/removing the access

membership

This log is produced when one of a group's role list is modified: either an owner, member, guest, aclkeeper or gatekeeper.

Example:

Dec 28 11:12:26 myhostname bastion: membership uniqid="a00993ec6767" version="3.01.02"
pid="1072528" ppid="1072497" sysuser="lechuck" sudo_user="" uid="2070" gid="2070" action="add"
type="member" group="monkeys" account="stan" self="lechuck" user="" host="" port="" ttl=""

Fields:

action

Either add when an account is added to a group role list, or del when an account is removed

type

Type of the role list we're modifying, either member, aclkeeper, gatekeeper, guest or owner

group

Group whose one of the role list is being modified

account

Account being added/removed to/from the group role list

self

Account performing the change

user

When type is guest, the remote user part of the access we're adding/removing

host

When type is guest, the IP or IP block part of the access we're adding/removing

port

When type is guest, the port of the access we're adding/removing

ttl

When type is guest and action is add, if a TTL has been specified for the access, it appears here

security

This log is produced when an important security event has occurred, such as when an admin impersonates another user, or when a super owner uses his implicit global ownership to modify a group. You might want to watch those closely.

Example:

Dec 28 11:12:26 myhostname bastion: security uniqid="601a17b5e5ba" version="3.01.03" pid="20519"
ppid="20518" sysuser="lechuck" sudo_user="" uid="2604" gid="2604" type="admin-ssh-as" account="lechuck"
sudo-as="gthreepw" plugin="ssh" params="--user root --host supersecretserver.example.org --port 22"

Fields:

type

Type of the security event that occurred. Can be:

  • admin-ssh-as: an admin impersonated another user to establish an egress connection

  • admin-sudo: an admin impersonated another user and launched an osh plugin on their behalf

  • superowner-override: a super owner used his implicit ownership on all groups to modify a group

account

Account that emitted the security event

sudo-as

When type is admin-ssh-as or admin-sudo, name of the account that was impersonated

plugin

Name of the osh plugin that was launched

params

Parameters passed to the plugin, or command line used to establish the egress connection

group

This log is produced when a group is created or deleted. Note that membership modifications are referenced with the membership type instead, see above.

Example:

Dec 28 11:12:26 myhostname bastion: group uniqid="56f321fb3e58" version="3.01.03" pid="1325901"
ppid="1325900" sysuser="root" sudo_user="lechuck" uid="0" gid="0" action="create" group="themonkeys"
owner="stan" egress_ssh_key_algorithm="ed25519" egress_ssh_key_size="256" egress_ssh_key_encrypted="false"

Fields:

action

Either create or delete, indicating whether the group has just been created or deleted

group

The group name being created or deleted

owner

When action is create, the name of the owner of the new group we're creating

egress_ssh_key_algorithm, egress_ssh_key_size

When action is create, the algorithm (and size) used to generate the first pair of SSH keys, can be empty if --no-key was specified

egress_ssh_key_encrypted

When action is create, if a key was generated, will be true if --encrypted has been used, false otherwise

account

This log is produced when an account is created or deleted.

Example:

Dec 21 14:30:26 myhostname bastion: account uniqid="ee4c91000b75" version="3.01.02" pid="537253" ppid="537252"
sysuser="root" sudo_user="lechuck" uid="0" gid="0" action="create" account="stan" account_uid="8431"
public_key="ssh-rsa AAAAB[...]" always_active="false" uid_auto="false" osh_only="false" immutable_key="false"
comment="CREATED_BY=lechuck BASTION_VERSION=3.01.02 CREATION_TIME=Mon Dec 21 14:30:26 2020
CREATION_TIMESTAMP=1608561026 COMMENT=requested_by_the_sword_master_of_melee_island_see_ticket_no_1337"

Fields:

action

Either create or delete, indicating whether the account has just been created or deleted

account

The account name being created or deleted

account_uid

When action is create, the UID associated corresponding to the account we're creating

public_key

When action is create, the public key we've generated for the new account

always_active, uid_auto, osh_only, immutable_key

When action is create, true if the corresponding option was specified (--always-active, --uid-auto, --osh-only or --immutable-key), false otherwise

comment

When action is create, the comment specified at creation if any, with some metadata that'll be stored in the account properties (created_by, bastion_version, creation_time, creation_timestamp)

tty_group

When action is delete, the name of the tty group specific to this account that was deleted at the same time

Syslog

Files location

If you use syslog-ng and installed the provided templates (which is the default if you used the --new-install option to the install script), you'll have 4 files in your system log directory:

/var/log/bastion/bastion.log

This is where all the bastion usage logs will be written. All the above message types can be found in this file.

/var/log/bastion/bastion-die.log

This is where Perl crashes will be logged, with the message type die. On a production bastion, this file should normally be empty.

/var/log/bastion/bastion-warn.log

This is where Perl warnings will be logged, with the message type warning. On a production bastion, this file should mostly be empty.

/var/log/bastion/bastion-scripts.log

This is where all the satellite scripts (mostly found in the bin/cron/ directory) will log their output.

Log format

A syslog message will always match the following generic format:

SYSLOG_TIME SYSLOG_HOST bastion: MSGTYPE field1="value1" field2="second value" ...

Where SYSLOG_TIME is the usual datetime field added by your local syslog daemon, and SYSLOG_HOST the hostname of the local machine. The MSGTYPE indicates the message type of the log line (the list of types is further below). Then, a possibly long list of fields with quoted values, depending on the MSGTYPE.

An example follows:

Dec 28 11:14:23 myhostname bastion: code-warning uniqid="e192fce7553a" version="3.01.03"
pid="18803" ppid="18802" sysuser="gthreepw" sudo_user="" uid="99998" gid="99998"
msg="Configuration error: specified adminAccounts 'joe' is not a valid account, ignoring"

In that case, the MSGTYPE is code-warning, and we have a few field/value couples with some metadata of interest, followed by a human-readable message, indicated by the msg field.

Only satellite scripts will miss the field/value construction, which will just be replaced by a plain text message. These logs are stored in /var/log/bastion/bastion-scripts.log by default.

Access logs

If you don't or can't use Syslog, the bastion can create and use access log files on its own, without relying on a syslog daemon. Note that you can enable both syslog and these access logs, if you want.

These access logs will only contain open and close log types, which can be seen as "access logs". All the other log types, such as warn, die, membership, etc. are only logged through syslog.

These logs are enabled through the enableGlobalAccessLog and enableAccountAccessLog options.

enableGlobalAccessLog

When enabled, a single log file will be used, located in /home/logkeeper/global-log-YYYYMM.log. There will be one file per month. Note that it can grow quite large if you have a busy bastion.

enableAccountAccessLog

When enabled, one log file per account will be used, located in /home/USER/USER-log-YYYYMM.log. There will be one file per month.

If both options are enabled, it means that every access log will be logged twice, to two different locations. If you also enabled syslog, it's even three times!

SQLite logs

If you want to store access logs into local sqlite databases, you can enable either enableGlobalSqlLog, enableAccountSqlLog, or both.

enableGlobalSqlLog

When enabled, a global sqlite database will be created in /home/logkeeper/global-log-YYYYMM.sqlite. It'll contain one row per access (created at the same time the open log is emitted). The following columns exist: id, timestamp, account, cmdtype, allowed, ipfrom, ipto, portto, user, plugin, uniqid. Refer to the open log description to get the meaning of each column.

enableAccountSqlLog

When enabled, an sqlite database per account will be created in /home/USER/USER-log-YYYYMM.sqlite. It'll contain one row per access (created at the same time the open log is emitted), and the same row will be updated by the close event when it is emitted. The following columns exist: id, timestamp, timestampusec, account, cmdtype, allowed, hostfrom, ipfrom, bastionip, bastionport, hostto, ipto, portto, user, plugin, ttyrecfilee, params, timestampend, timestampendusec, returnvalue, comment, uniqid. Refer to the open log and close log descriptions to get the meaning of each column. Note that the enableAccountSqlLog option is required if you want the selfListSessions and selfPlaySession plugins to work, as they use this database.

Note that enabling these on a very busy bastion (several new connections per second) can create lock contention, especially on the global log: ensure you have a fast storage. In any case, if a connection can't get the lock after a few seconds, it'll proceed anyway, and skip writing the sql log. In that case, if you enabled syslog or local access logs, the globalsql and/or the accountsql field will contain the error detail.

Terminal recordings (ttyrec)

Every egress connection is started under ttyrec, which means that everything appearing on the console is recorded. If a password is asked by some program, for example, and typing the password prints '*' or doesn't print anything at all, this won't be recorded. This is by design. In other words, the keystrokes are not recorded, except if they produce something on the screen.

The ttyrec files location is always /home/USER/ttyrec/REMOTEIP/file.ttyrec, where the actual file.ttyrec name can be configured by the ttyrecFilenameFormat option. By default, it'll contain the date, time, account, remote ip, port and user used to start the egress connection, as well as the uniqid, for easier correlation between all the logs produced by the same connection. Note that for long connections, or connections producing a lot of output, ttyrec files will be transparently rotated, without interrupting the connection. This is to avoid ending up with ttyrec files of several gigabytes that would still be opened, written to, hence impossible to compress, encrypt, and push to an escrow filer. The uniqid will be the same for all the ttyrec files corresponding to the same connection.

To play ttyrec files, you can either use selfPlaySession for yourself, or, for admins having local access to the bastion machine, the ttyplay program can be used. Another software, perhaps more powerful than ttyplay, can also be used: IPBT (wiki), aka "It's PlayBack Time", by the PuTTY author. It can do more advanced things such as look for words appearing on any frame recorded in the ttyrec file, play files using a logarithmic speed, or display an OSD with the exact time output you're seeing has appeared. As ttyrec is a well-known format that has been around for a while, there are a bunch of other programs you can use to read or convert these files.