cockpit/test/verify/check-journal

603 lines
23 KiB
Python
Executable File

#!/usr/bin/python3
# This file is part of Cockpit.
#
# Copyright (C) 2013 Red Hat, Inc.
#
# Cockpit is free software; you can redistribute it and/or modify it
# under the terms of the GNU Lesser General Public License as published by
# the Free Software Foundation; either version 2.1 of the License, or
# (at your option) any later version.
#
# Cockpit is distributed in the hope that it will be useful, but
# WITHOUT ANY WARRANTY; without even the implied warranty of
# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU
# Lesser General Public License for more details.
#
# You should have received a copy of the GNU Lesser General Public License
# along with Cockpit; If not, see <http://www.gnu.org/licenses/>.
import parent
from testlib import *
class TestJournal(MachineCase):
def setUp(self):
super(TestJournal, self).setUp()
self.crash_fn = "__nanosleep"
def select_from_dropdown(self, browser, selector, value, click=True):
button_text_selector = "{0} button span:nth-of-type(1)".format(selector)
browser.wait_visible(selector)
if not browser.text(button_text_selector) == value:
item_selector = "{0} ul li a:contains({1})".format(selector, value)
browser.click("{0} button".format(selector))
browser.wait_present(item_selector)
if click:
browser.click(item_selector)
browser.wait_in_text(button_text_selector, value)
else:
browser.click(button_text_selector)
def crash(self):
m = self.machine
m.execute("ulimit -c unlimited")
sleep = m.spawn("sleep 1m", "sleep.log")
m.execute("kill -SEGV %d" % (sleep))
def testBasic(self):
b = self.browser
b.wait_timeout(120)
m = self.machine
self.allow_restart_journal_messages()
self.allow_journal_messages(".*Failed to get realtime timestamp: Cannot assign requested address.*")
# HACK: pmie and pmlogger take a looooong time to shutdown (https://bugzilla.redhat.com/show_bug.cgi?id=1703348)
# so disable them for this test, we don't test PCP here
m.execute("systemctl disable --now pmie pmlogger || true")
def inject_extras():
b.eval_js("""
ph_get_log_lines = function () {
var lines = [ ];
var panels = ph_find('.cockpit-log-panel').childNodes;
for (var i = 0; i < panels.length; ++i) {
var e = panels[i];
if (e.className === 'panel-heading') {
lines.push (e.textContent);
} else {
var msg = e.querySelector('.cockpit-log-message');
msg = msg ? msg.textContent : "";
var ident = '';
var count = '';
if (e.querySelectorAll('.cockpit-log-service-container').length > 0) {
ident = e.querySelector('.cockpit-log-service-reduced').textContent;
// we need to slice the whitespace
count = e.querySelector('.badge').textContent.slice(0, -1);
} else {
ident = e.querySelector('.cockpit-log-service');
ident = ident ? ident.textContent : "";
}
lines.push ([ ident, msg, count ]);
}
}
var journal_start_text = ph_find('.journal-start').textContent;
if (journal_start_text !== "")
lines.push(journal_start_text);
// console.log(JSON.stringify(lines));
return lines;
}
""")
# Certain versions of journald won't set _SYSTEMD_UNIT
# correctly for entries that are processed after the
# originating process has already exited. So we keep the
# process around for a bit longer after the last line has been
# output.
#
m.write("/etc/systemd/system/log123.service",
"""
[Unit]
Description=123 different log lines
[Service]
ExecStart=/bin/sh -c '/usr/bin/seq 123; sleep 10'
""")
m.write("/etc/systemd/system/slow10.service",
"""
[Unit]
Description=Slowly log 10 identical lines
[Service]
ExecStart=/bin/sh -c 'for s in $(seq 10); do echo SLOW; sleep 0.1; done; sleep 10'
""")
# Stop NTP and Chronyd if they are running. Timedatectl isn't
# necessarily aware of them.
#
# HACK - https://bugzilla.redhat.com/show_bug.cgi?id=1352905
#
m.execute("! systemctl --quiet is-active ntp || (systemctl disable ntp && systemctl stop ntp)")
m.execute("if systemctl --quiet is-active chrony; then systemctl disable chrony && systemctl stop chrony; fi")
m.execute("if systemctl --quiet is-active chronyd; then systemctl disable chronyd && systemctl stop chronyd; fi")
m.execute("timedatectl set-ntp off; timedatectl set-time 2038-01-01")
self.login_and_go("/system/logs")
inject_extras()
b.eval_js("""
localTime = function(time) {
var month_names = [
'January',
'February',
'March',
'April',
'May',
'June',
'July',
'August',
'September',
'October',
'November',
'December'
];
var d = new Date(time);
return month_names[d.getMonth()] + ' ' + d.getDate().toFixed() + ', ' + d.getFullYear().toFixed();
}
""")
# January 1, 2038 00:00:00Z in browser time
expected_date = b.eval_js("localTime(2145916800000)")
def wait_log_lines(expected):
b.wait_js_func("""(function (expected) {
var lines = ph_get_log_lines ();
if (expected.length != lines.length)
return false;
for (i = 0; i < expected.length; i++)
if (JSON.stringify(expected[i]) != JSON.stringify(lines[i]))
return false;
return true;
})""", expected)
def wait_journal_empty():
# Changed in #13039
if m.image == "rhel-8-1-distropkg":
wait_log_lines([])
else:
wait_log_lines(["No Logs FoundCan not find any logs using the current combination of filters."])
b.go("#/?prio=*&service=log123.service")
wait_journal_empty()
def wait_log123():
b.wait_js_func("""(function () {
var lines = ph_get_log_lines();
if (lines[0] != "%s")
return false;
var seq = 123;
var seen_day = false;
for (i = 1; i < lines.length; i++) {
l = lines[i];
if (l[2] != "") {
// console.log("repeat", l[2], "?");
return false;
}
if (l[0] == "systemd: ") {
// console.log(l[1], "?");
return false;
} else if (l[0] == "sh") {
if (l[1] != seq.toString()) {
// console.log(l[1], "?");
return false;
}
seq = seq - 1;
} else {
// console.log(l[0], "?");
return false;
}
}
if (seq != 0) {
// console.log("Didn't see all 'seq' lines.")
return false;
}
return true;
})""" % expected_date)
m.execute("systemctl start log123")
wait_log123()
b.go("#/?prio=*&start=oldest&service=nonexisting.service")
wait_journal_empty()
b.go("#/?prio=*&start=oldest&service=log123.service")
wait_log123()
b.go("#/?prio=*&start=recent&service=nonexisting.service")
wait_journal_empty()
b.go("#/?prio=*&start=recent&service=log123.service")
wait_log123()
b.go("#/?prio=*&start=recent&service=slow10.service")
wait_journal_empty()
def wait_slow10():
wait_log_lines([expected_date, ["sh", "SLOW", "10"]
])
def wait_log_present(message):
sel = "#journal-box .cockpit-logline .cockpit-log-message:contains('%s')" % message
b.wait_visible(sel)
def wait_log_not_present(message):
sel = "#journal-box .cockpit-logline .cockpit-log-message:contains('%s')" % message
b.wait_not_present(sel)
m.execute("systemctl start slow10")
wait_slow10()
b.go("#/?prio=*&start=oldest&service=nonexisting.service")
wait_journal_empty()
b.go("#/?prio=*&start=oldest&service=slow10.service")
wait_slow10()
# insert messages as errors because we know these will be shown by default
m.execute("systemctl start systemd-journald.service")
m.execute("logger -p user.err --tag check-journal BEFORE BOOT")
b.go("#/?tag=check-journal")
wait_log_lines([expected_date, ["check-journal", "BEFORE BOOT", ""]])
m.execute("systemctl stop systemd-journald.service")
# Now reboot things
m.spawn("sync && sync && sync && sleep 0.1 && reboot", "reboot")
m.wait_reboot()
m.execute("timedatectl set-time '2038-01-01 00:05:00'")
m.execute("logger -p user.err --tag check-journal AFTER BOOT")
m.start_cockpit()
b.switch_to_top()
b.relogin('/system/logs')
inject_extras()
b.go("#/?tag=check-journal")
wait_log_lines([expected_date,
["check-journal", "AFTER BOOT", ""],
["", "Reboot", ""],
["check-journal", "BEFORE BOOT", ""]
])
b.go("#/?start=boot&tag=check-journal")
wait_log_lines([expected_date,
["check-journal", "AFTER BOOT", ""],
"Load earlier entries",
])
# Changed in #13039
if m.image == "rhel-8-1-distropkg":
b.click('#journal-load-earlier')
else:
b.click('#start-box button:contains("Load earlier entries")')
wait_log_lines([expected_date,
["check-journal", "AFTER BOOT", ""],
["", "Reboot", ""],
["check-journal", "BEFORE BOOT", ""]
])
# Check selecting of services
b.go("#/?start=previous-boot&tag=check-journal")
wait_log_lines([expected_date,
["check-journal", "BEFORE BOOT", ""],
"Load earlier entries"
])
b.go("#/?start=boot&prio=6")
wait_log_present("AFTER BOOT")
m.execute("logger -p 5 --tag just-a-service WORK PLEASE")
wait_log_present("WORK PLEASE")
self.select_from_dropdown(b, "#journal-service-menu", "check-journal", click=False)
self.select_from_dropdown(b, "#journal-service-menu", "just-a-service", click=True)
wait_log_not_present("AFTER BOOT")
wait_log_present("WORK PLEASE")
self.select_from_dropdown(b, "#journal-service-menu", "All", click=True)
wait_log_present("AFTER BOOT")
wait_log_present("WORK PLEASE")
self.select_from_dropdown(b, "#journal-prio-menu", "Error and above")
self.select_from_dropdown(b, "#journal-service-menu", "check-journal", click=False)
b.click("#journal-service-menu button")
b.wait_not_present("#journal-services-list ul li a:contains('just-a-service')")
def testBinary(self):
b = self.browser
m = self.machine
m.execute(r"printf 'MESSAGE=Hello \01 World\nPRIORITY=3\nFOO=bar\nBIN=a\01b\02c\03\n' | logger --journald")
self.login_and_go("/system/logs")
sel = "#journal-box .cockpit-logline .cockpit-log-message:contains('[13 bytes of binary data]')"
b.click(sel)
b.wait_text("#journal-entry-message", "[13 bytes of binary data]")
def wait_field(name, value):
row_sel = "#journal-entry-fields tr:contains('" + name + "')"
b.wait_present(row_sel + " td:nth-child(2):contains('" + value + "')")
wait_field("FOO", "bar")
wait_field("BIN", "[6 bytes of binary data]")
def testNoMessage(self):
b = self.browser
m = self.machine
m.execute(r"printf 'PRIORITY=3\nFOO=bar\n' | logger --journald")
self.login_and_go("/system/logs")
sel = "#journal-box .cockpit-logline .cockpit-log-message:contains('[no data]')"
b.click(sel)
b.wait_text("#journal-entry-message", "[no data]")
def testLogLevel(self):
b = self.browser
m = self.machine
m.execute("logger -p user.info --tag check-journal INFO_MESSAGE")
m.execute("logger -p user.warn --tag check-journal WARNING_MESSAGE")
m.execute("logger -p user.emerg --tag check-journal EMERGENCY_MESSAGE")
self.login_and_go("/system/logs")
journal_line_selector = "#journal-box .cockpit-logline:has(span:contains({0}))"
self.select_from_dropdown(b, "#journal-prio-menu", "Only Emergency")
b.wait_present(journal_line_selector.format("EMERGENCY_MESSAGE"))
b.wait_not_present(journal_line_selector.format("WARNING_MESSAGE"))
b.wait_not_present(journal_line_selector.format("INFO_MESSAGE"))
self.select_from_dropdown(b, "#journal-prio-menu", "Warning and above")
b.wait_present(journal_line_selector.format("EMERGENCY_MESSAGE"))
b.wait_present(journal_line_selector.format("WARNING_MESSAGE"))
b.wait_not_present(journal_line_selector.format("INFO_MESSAGE"))
self.select_from_dropdown(b, "#journal-prio-menu", "Info and above")
b.wait_present(journal_line_selector.format("EMERGENCY_MESSAGE"))
b.wait_present(journal_line_selector.format("WARNING_MESSAGE"))
b.wait_present(journal_line_selector.format("INFO_MESSAGE"))
@skipImage("ABRT does not work on i386", "fedora-i386")
@skipImage("ABRT not available", "debian-stable", "debian-testing", "ubuntu-stable",
"ubuntu-1804", "fedora-coreos", "rhel-8-1", "rhel-8-1-distropkg", "rhel-8-2")
def testAbrtSegv(self):
self.allow_core_dumps = True
b = self.browser
self.crash()
self.login_and_go("/system/logs")
sel = "#journal-box .cockpit-logline .cockpit-log-message:contains('crashed in %s')" % self.crash_fn
self.select_from_dropdown(b, "#journal-prio-menu", "Critical and above")
b.wait_visible(sel)
self.select_from_dropdown(b, "#journal-prio-menu", "Alert and above")
b.wait_not_present(sel)
self.select_from_dropdown(b, "#journal-prio-menu", "Critical and above")
b.click(sel)
def wait_field(name, value):
row_sel = "#journal-entry-fields tr:contains('" + name + "')"
b.wait_present(row_sel + " td:nth-child(2):contains('" + value + "')")
wait_field("SYSLOG_IDENTIFIER", "abrt-notification")
b.click("li:contains(Problem info)")
wait_field("reason", "killed by SIGSEGV")
b.click("li:contains(Problem details)")
sel = "#journal-entry-fields #accordion-markup .panel .panel-heading"
sel += " .panel-title .accordion-toggle:contains('core_backtrace')"
b.click(sel)
sel = "#journal-entry #accordion-markup .panel .panel-collapse"
sel += " .panel-body:contains('signal: 11 executable: ')"
b.wait_present(sel)
@skipImage("ABRT does not work on i386", "fedora-i386")
@skipImage("ABRT not available", "debian-stable", "debian-testing", "ubuntu-stable",
"ubuntu-1804", "fedora-coreos", "rhel-8-1", "rhel-8-1-distropkg", "rhel-8-2")
def testAbrtDelete(self):
self.allow_core_dumps = True
b = self.browser
# A bit of a race might happen if you delete the journal entry whilst
# the reporting code is doing its thing.
self.allow_browser_errors("Failed to get workflows for problem /org/freedesktop/Problems2/Entry/.*:.*")
self.allow_browser_errors("Getting properties for problem /org/freedesktop/Problems2/Entry/.* failed:.*")
self.crash()
self.login_and_go("/system/logs")
sel = "#journal-box .cockpit-logline .cockpit-log-message:contains('crashed in %s')" % self.crash_fn
b.click(sel)
b.wait_in_text("#journal-entry-heading", "sleep")
sel = "#journal-entry-fields .nav .btn-danger"
b.click(sel)
b.wait_in_text('#journal-box', "crashed in " + self.crash_fn)
sel = "#journal-box .cockpit-logline .cockpit-log-message:contains('crashed in %s')" % self.crash_fn
b.click(sel)
b.wait_in_text("#journal-entry-heading", "sleep")
# details view should hide log view
b.wait_not_visible('.cockpit-log-panel')
b.wait_present("#journal-entry-message:contains('crashed in %s')" % self.crash_fn)
b.wait_not_present("#journal-entry-fields .nav .btn-danger")
@skipImage("ABRT does not work on i386", "fedora-i386")
@skipImage("ABRT not available", "debian-stable", "debian-testing", "ubuntu-stable",
"ubuntu-1804", "fedora-coreos", "rhel-8-1", "rhel-8-1-distropkg", "rhel-8-2")
def testAbrtReport(self):
self.allow_core_dumps = True
# The testing server is located at verify/files/mock-faf-server.py
# Adjust Handler.known for for the expected succession of known/unknown problems
b = self.browser
m = self.machine
# We restart the reportd service,
# which causes the D-Bus proxy to spit out an error when it tries to
# query its managed objects.
self.allow_journal_messages('.*Remote peer disconnected')
m.upload(["verify/files/mock-bugzilla-server.py"], "/tmp/")
m.spawn("setsid /tmp/mock-bugzilla-server.py", "mock-bugzilla.log")
m.execute("echo 'BugzillaURL=http://localhost:8080' >> /etc/libreport/plugins/bugzilla.conf")
# start mock FAF server
m.upload(["verify/files/mock-faf-server.py"], "/tmp/")
m.spawn("setsid /tmp/mock-faf-server.py", "mock-faf.log")
m.execute("echo 'URL=http://localhost:12345' >> /etc/libreport/plugins/ureport.conf")
self.crash()
self.login_and_go("/system/logs")
sel = "#journal-box .cockpit-logline .cockpit-log-message:contains('crashed in __nanosleep()')"
b.click(sel)
sel = "table.reporting-table tr:first-child .btn:contains('Report')"
b.click(sel)
sel = "table.reporting-table tr:first-child a[href$='/reports/bthash/123deadbeef'"
b.wait_present(sel)
# "Unreport" the problem to test reporting unknown problem
m.execute('find /var/spool/abrt -name "reported_to" -or -name "ureports_counter" | xargs rm')
# The service also needs to be restarted, because the daemon maintains
# its own cache that interferes with resetting the state.
m.execute('systemctl restart reportd')
# We have no network access.
m.execute("sed -i 's|abrt-action-perform-ccpp-analysis|true|' /etc/libreport/events.d/ccpp_event.conf")
# reporter-bugzilla will not be run without a duphash file present.
m.execute("find /var/spool/abrt -depth -maxdepth 1 | head -1 | xargs -I {} cp '{}/uuid' '{}/duphash'")
b.reload()
b.enter_page("/system/logs")
sel = "table.reporting-table tr:nth-child(2) button:contains('Report')"
b.click(sel)
test_user = 'correcthorsebatterystaple'
for purpose in ['text', 'password']:
b.wait_visible("#cockpit_modal_dialog .modal-content input[type='%s']" % (purpose))
sel = "#cockpit_modal_dialog .modal-content input"
b.set_val(sel, test_user)
sel = "#cockpit_modal_dialog .modal-footer button:contains('Send')"
b.click(sel)
sel = "#cockpit_modal_dialog .modal-content p:contains('Password')"
b.wait_not_present(sel)
sel = "#cockpit_modal_dialog .modal-footer button:contains('No')"
b.click(sel)
sel = "table.reporting-table tr:nth-child(2) a[href='https://bugzilla.example.com/show_bug.cgi?id=123456']"
b.wait_present(sel)
@skipImage("ABRT does not work on i386", "fedora-i386")
@skipImage("ABRT not available", "debian-stable", "debian-testing", "ubuntu-stable",
"ubuntu-1804", "fedora-coreos", "rhel-8-1", "rhel-8-1-distropkg", "rhel-8-2")
def testAbrtReportCancel(self):
self.allow_core_dumps = True
b = self.browser
m = self.machine
m.upload(["verify/files/mock-bugzilla-server.py"], "/tmp/")
m.spawn("setsid /tmp/mock-bugzilla-server.py", "mock-bugzilla.log")
m.execute("echo 'BugzillaURL=http://localhost:8080' >> /etc/libreport/plugins/bugzilla.conf")
# start mock FAF server
m.upload(["verify/files/mock-faf-server.py"], "/tmp/")
m.spawn("setsid /tmp/mock-faf-server.py", "mock-faf.log")
m.execute("echo 'URL=http://localhost:12345' >> /etc/libreport/plugins/ureport.conf")
self.crash()
self.login_and_go("/system/logs")
sel = "#journal-box .cockpit-logline .cockpit-log-message:contains('crashed in __nanosleep()')"
b.click(sel)
# Something long-running to not pop up an unexpected dialog.
m.execute("sed -i 's|abrt-action-perform-ccpp-analysis|echo Cancel me; sleep 5m|' /etc/libreport/events.d/ccpp_event.conf")
sel = "table.reporting-table tr:nth-child(2) button:contains('Report')"
b.click(sel)
sel = "table.reporting-table tr:nth-child(2) td:contains('Cancel me')"
b.wait_visible(sel)
sel = "table.reporting-table tr:nth-child(2) button:contains('Cancel')"
b.click(sel)
sel = "table.reporting-table tr:nth-child(2) td:contains('Reporting was canceled')"
b.wait_present(sel)
@skipImage("ABRT does not work on i386", "fedora-i386")
@skipImage("ABRT not available", "debian-stable", "debian-testing", "ubuntu-stable",
"ubuntu-1804", "fedora-coreos", "rhel-8-1", "rhel-8-1-distropkg", "rhel-8-2")
def testAbrtReportNoReportd(self):
self.allow_core_dumps = True
b = self.browser
m = self.machine
self.allow_browser_errors("Channel for reportd D-Bus client closed: .*")
# start mock FAF server
m.upload(["verify/files/mock-faf-server.py"], "/tmp/")
m.execute("setsid /tmp/mock-faf-server.py >/tmp/mock-faf.log 2>&1 &")
m.execute("echo 'URL=http://localhost:12345' >> /etc/libreport/plugins/ureport.conf")
m.execute("systemctl mask --now reportd")
self.crash()
self.login_and_go("/system/logs")
sel = "#journal-box .cockpit-logline .cockpit-log-message:contains('crashed in __nanosleep()')"
b.click(sel)
sel = "table.reporting-table tr:first-child .btn:contains('Report')"
b.click(sel)
sel = "table.reporting-table tr:first-child a[href$='/reports/bthash/123deadbeef'"
b.wait_present(sel)
if __name__ == '__main__':
test_main()