Data Platform/Systems/Managing systemd timers

In phab:T172532 we decided to move away as much as possible from cron jobs since we were struggling to alarm when a job failed. Most of our recurrent jobs are running on an-coord1001 (analytics cluster coordinator), and the majority of them are systemd timers.

A systemd timer is composed by two parts: a unit and the timer itself. Let's pick an example:

elukey@an-coord1001:~$sudosystemctlcathdfs-balancer.timer
# /lib/systemd/system/hdfs-balancer.timer
[Unit]
Description=Periodicexecutionofhdfs-balancer.service
[Timer]
Unit=hdfs-balancer.service
# Accuracy sets the maximum time interval around the execution time we want to allow
AccuracySec=15sec
OnCalendar=*-*-*06:00:00
RandomizedDelaySec=0
[Install]
WantedBy=multi-user.target
elukey@an-coord1001:~$sudosystemctlcathdfs-balancer.service
# /lib/systemd/system/hdfs-balancer.service
[Unit]
Description=RuntheHDFSbalancerscripttokeepHDFSblocksreplicatedinthemostredundantandefficientway.
[Service]
User=hdfs
ExecStart=/usr/local/bin/hdfs-balancer

In this case, we are checking how it is configured the HDFS balancer timer. The .timer file references a systemd unit (the .service file), that it is the one doing the work, and a pattern of execution (in this case, every day at 6 AM UTC). The .service file defines a command, together with other info like environment variables and username that needs to execute it. This command that .service points to can be generated by puppet, so peek into it if you need to see the details, for example: sudo -u hdfs cat /usr/local/bin/refinery-sqoop-mediawiki.

We alarm on the return code of the .service Systemd unit: if it gets executed and the script mentioned by ExecStart returns a non-zero exit code, Nagios will alert us.

All these configuration files seem a bit confusing, but they are good from the operations point of view. A systemd .service can be started/restarted any time, basically forcing the execution of its script. In this case:

sudosystemctlstarthdfs-balancer.service

forces the hdfs-balancer to execute. Where do we find logs? At the moment the majority of them are only on journald, but they will be logged on files as well as soon as possible. If you want to check journald for a particular .service:

# start from the first log registered
sudojournalctl-uhdfs-balancer
# start from a specific moment of time
sudojournalctl-uhdfs-balancer--since'3 days ago'
# show only a specific timeframe
sudojournalctl--since"2018-10-21 23:15:00"--until"2018-10-21 23:20:00"
# tail -f equivalent
sudojournalctl-uhdfs-balancer--follow

An example of debugging for db1107: https://phabricator.wikimedia.org/T207165

Please note that the command executed by the service unit (the one assigned to the ExecStart field) is parsed following a systemd specific format, that is similar to what bash offers but very different in may ways. If you don't keep in mind this rule you'll end up writing units that either fail due to weird argument parsing or even worse executing with wrong parameters. The fix in https://gerrit.wikimedia.org/r/#/c/operations/puppet/+/530555/ is a good example: a shell redirection ( command > file.log) is not parsed as we expect by systemd, that 1) considers '>' as special char and 2) considers everything split by a whitespace (and not quoted) as separate argument.

The OnCalender interval syntax is powerful, but isn't always the most straightforward to figure out. There is a command to help: systemd-analyze.

To check the syntax of OnCalendar, you can run e.g.

$systemd-analyzecalendar'*-*-* *:05,35:00'
Normalizedform:*-*-**:05,35:00
Nextelapse:Thu2021-07-0814:35:00UTC
Fromnow:24minleft

systemctllist-timers

Example of output from stat1006:

elukey@stat1006:~$systemctllist-timers
NEXTLEFTLASTPASSEDUNITACTIVATES
Wed2019-03-2706:43:00UTC2min54sleftWed2019-03-2706:28:00UTC12minagoprometheus-node-exporter-apt.timerprometheus-node-exporter-apt.service
Wed2019-03-2707:00:00UTC19minleftWed2019-03-2706:00:00UTC40minagoreportupdater-cx.timerreportupdater-cx.service
Wed2019-03-2707:00:00UTC19minleftWed2019-03-2706:00:00UTC40minagoreportupdater-edit-beta-features.timerreportupdater-edit-beta-features.service
Wed2019-03-2707:00:00UTC19minleftWed2019-03-2706:00:00UTC40minagoreportupdater-ee-beta-features.timerreportupdater-ee-beta-features.service
Wed2019-03-2707:00:00UTC19minleftWed2019-03-2706:00:00UTC40minagoreportupdater-ee.timerreportupdater-ee.service
Wed2019-03-2707:00:00UTC19minleftWed2019-03-2706:00:00UTC40minagoreportupdater-flow-beta-features.timerreportupdater-flow-beta-features.service
Wed2019-03-2707:00:00UTC19minleftWed2019-03-2706:00:00UTC40minagoreportupdater-flow.timerreportupdater-flow.service
Wed2019-03-2707:00:00UTC19minleftWed2019-03-2706:00:00UTC40minagoreportupdater-language.timerreportupdater-language.service

To check on a specific timer, use status: systemctl status refinery-sqoop-whole-mediawiki

It is easy to see all the timings for a certain systemd timer and the units it runs. For example, the reportupdater-cx job has two units:

• reportupdater-cx.timer -> this is basically the equivalent of the cron definition (you can inspect it via systemctl cat reportupdater-cx.timer and see its config)
• reportupdater-cx.service -> this is the command to run together with its environment etc.., that is called/managed by the above .timer unit.

nuria@an-launcher1002:~$systemctlcatdrop-el-unsanitized-events.service
# /lib/systemd/system/drop-el-unsanitized-events.service
[Unit]
Description=DropunsanitizedEventLoggingdatafromtheeventdatabaseafterretentionperiod.
[Service]
User=analytics
Environment=PYTHONPATH=${PYTHONPATH}:/srv/deployment/analytics/refinery/python
ExecStart=/usr/local/bin/kerberos-run-commandanalytics/srv/deployment/analytics/refinery/bin/refinery-drop-older-than--some

Everything always starts with a systemctl list-timers (as explained above) to find the .timer unit to check. If we keep the stat1006 example above, let's say we want to check what user runs reportupdater-cx.timer: we'll need to inspect the related .service unit (since that one is the "real" command executed, the .timer one is only the cron-like definition and we don't care who runs it):

elukey@stat1006:~$systemctlcatreportupdater-cx
# /lib/systemd/system/reportupdater-cx.service
[Unit]
Description=ReportUpdaterjobforcx
[Service]
User=stats
SyslogIdentifier=reportupdater-cx
ExecStart=/usr/bin/python/srv/reportupdater/reportupdater/update_reports.py-linfo/srv/reportupdater/jobs/limn-language-data/cx/srv/reportupdater/output/metrics/cx

You need to look for the User=something definition. In this case, the unit is run by stats.

sudosystemctldisablename-of-the-timer.timer
sudosystemctlstopname-of-the-timer.timer

The former prevents the timer to be started after boot, the latter removes it from the regular scheduling. After you have done the above steps, verify with the following command that the timer is not listed anymore:

systemctllist-timers|grepname-of-the-timer

Finally don't forget to check if an icinga alarm was fired, and follow the next section accordingly if needed.

It might happen that an alert has fired for a timer but you just want to shut it off, because you have already been taken care of the problem (for example, executing a manual run, etc..). This is what is needed to do:

sudosystemctlreset-failedname-of-the-timer.service

It is important to reset the service unit, not the timer one, since it is only the former that causes the alarm (the timer unit's state is not important at this stage).

In the case of timers that run multiple commands, like refinery-sqoop-whole-mediawiki, see if you can finish running the commands manually and reset the alert as above. There's nothing special about these timers that can help resume operation or anything like that.

The first step is always to use systemctl list-timers, as explained above, to gather the name of the timer to check. In the above stat1006 example, let's pick reportupdater-cx.timer. The logs will be available simply doing:

# Note that we are not using the .timer unit, but the .service one!
# The .service suffix is assumed if no one is specified.
sudojournalctl-ureportupdater-cx

Usually for important jobs we log stuff to disk, since journald by default logs to a tmpfs partition (that stays in memory and gets flushed on each reboot). In order to see what is the log configuration, two things can be done:

• Check the puppet definition of the systemd timer, it will list the log directory.
• Check rsyslog.d configuration on the host itself.

Example for the former:

systemd::timer::job{"reportupdater-${title}":
ensure=>$ensure,
description=>"Report Updater job for ${title}",
command=>"/usr/bin/python ${::reportupdater::path}/update_reports.py -l info ${query_path} ${output_path}",
interval=>{
'start'=>'OnCalendar',
'interval'=>$interval
},
user=>$::reportupdater::user,
monitoring_enabled=>$monitoring_enabled,
monitoring_contact_groups=>'analytics',
logging_enabled=>true,
logfile_basedir=>$::reportupdater::log_path,<==================
logfile_name=>'syslog.log',
logfile_owner=>$::reportupdater::user,
logfile_group=>$::reportupdater::user,
logfile_perms=>'all',
syslog_force_stop=>true,
syslog_identifier=>"reportupdater-${title}",
}

About the latter: why rsyslog? Wasn't it journald? We have a rsyslog hooked in into journald so we can add specific rules to create log files. For example, let's check the reportupdater-cx job:

elukey@stat1006:~$cat/etc/rsyslog.d/
10-exporter.conf20-reportupdater-edit-beta-features.conf20-reportupdater-flow-beta-features.conf20-reportupdater-mt-engines.conf20-reportupdater-published-cx2-translations.conf
10-puppet-agent.conf20-reportupdater-ee-beta-features.conf20-reportupdater-flow.conf20-reportupdater-page-creation.conf30-remote-syslog.conf
20-reportupdater-cx.conf20-reportupdater-ee.conf20-reportupdater-language.conf20-reportupdater-pingback.confREADME
elukey@stat1006:~$cat/etc/rsyslog.d/20-reportupdater-cx.conf
# rsyslogd(8) configuration file for services.
# This file is managed by Puppet.
:programname,startswith,"reportupdater-cx"/srv/reportupdater/log/reportupdater-cx/syslog.log
&stop
elukey@stat1006:~$ls-l/srv/reportupdater/log/reportupdater-cx/syslog.log
-rw-r--r--1statsstats647027Mar2706:00/srv/reportupdater/log/reportupdater-cx/syslog.log

In this case, the journald logs are also replicated to /srv/reportupdater/log/reportupdater-cx/syslog.log

What to do when it's your ops week and an email has been sent to analytics-alert about a failed-timer?

Depending on jobs, logs are stored only in journald logs (see above), or split between journald and a log-file defined in the job command-line.

Usefull command:

sudo journalctl -u SERVICE_NAME

There are two options to reset a failed service to normal status (after investigation, potential correction etc):

Monitoring/systemd_unit_state

• Data platform
• Data platform systems