ovh/the-bastion
1
1
Fork 0
mirror of https://github.com/ovh/the-bastion.git synced 2025-01-04 06:27:11 +08:00
Code Issues Projects Releases Packages Wiki Activity
the-bastion/doc/sphinx/administration/logs.rst
Stéphane Lesimple 716594e20e chore: doc: limit .rst lines to 120 chars
2021-12-30 15:39:31 +01:00

599 lines
26 KiB
ReStructuredText
Raw Blame History

====
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.
.. contents::
:depth: 5
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:
- :ref:`log_open`
- :ref:`log_close`
- :ref:`log_warn`
- :ref:`log_warninfo`
- :ref:`log_codewarn`
- :ref:`log_acl`
- :ref:`log_membership`
- :ref:`log_security`
- :ref:`log_group`
- :ref:`log_account`
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.
.. _log_open:
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 :ref:`enableAccountSqlLog` is enabled, and we successfully inserted a new row for the log
- no: when :ref:`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.
.. _log_close:
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.
.. _log_warn:
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()``
.. _log_warninfo:
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**.
.. _log_codeinfo:
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
.. _log_codewarn:
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
.. _log_acl:
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
.. _log_membership:
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
.. _log_security:
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
.. _log_group:
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
.. _log_account:
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:
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 :file:`/var/log/bastion/bastion-scripts.log` by default.
Access logs
===========
If you don't or can't use :ref:`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 :ref:`log_open` and :ref:`log_close` log types, which can be seen as "access logs".
All the other log types, such as :ref:`log_warn`, :ref:`log_membership`, etc. are only logged through syslog.
These logs are enabled through the :ref:`enableGlobalAccessLog` and :ref:`enableAccountAccessLog` options.
enableGlobalAccessLog
When enabled, a single log file will be used, located in :file:`/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 :file:`/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 :ref:`enableGlobalSqlLog`,
:ref:`enableAccountSqlLog`, or both.
enableGlobalSqlLog
When enabled, a global sqlite database will be created in :file:`/home/logkeeper/global-log-YYYYMM.sqlite`.
It'll contain one row per access (created at the same time the :ref:`log_open` log is emitted).
The following columns exist: id, timestamp, account, cmdtype, allowed, ipfrom, ipto, portto, user, plugin, uniqid.
Refer to the :ref:`log_open` log description to get the meaning of each column.
enableAccountSqlLog
When enabled, an sqlite database per account will be created in :file:`/home/USER/USER-log-YYYYMM.sqlite`.
It'll contain one row per access (created at the same time the :ref:`log_open` log is emitted),
and the same row will be updated by the :ref:`log_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 :ref:`log_open` log and :ref:`log_close` log descriptions to get the meaning of each column.
Note that the :ref:`enableAccountSqlLog` option is required if you want the :doc:`/plugins/open/selfListSessions`
and :doc:`/plugins/open/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 :file:`/home/USER/ttyrec/REMOTEIP/file.ttyrec`, where the actual `file.ttyrec`
name can be configured by the :ref:`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 :doc:`/plugins/open/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 <https://www.chiark.greenend.org.uk/~sgtatham/ipbt/>`_ (`wiki <https://nethackwiki.com/wiki/IPBT>`_),
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.
Reference in a new issue View git blame Copy permalink