Project

General

Profile

Actions

action #43055

closed

[functional][y] test fails in kate - excessive systemd debug level?

Added by StefanBruens over 5 years ago. Updated over 5 years ago.

Status:
Resolved
Priority:
Normal
Assignee:
Category:
Bugs in existing tests
Target version:
SUSE QA - Milestone 21
Start date:
2018-10-29
Due date:
2018-12-18
% Done:

0%

Estimated time:
Difficulty:

Description

Observation

openQA test in scenario opensuse-Tumbleweed-DVD-x86_64-kde@64bit fails in
kate

kate.journal:

Oct 29 09:58:03 susetest systemd[1]: Received SIGCHLD from PID 13216 (snapperd).
Oct 29 09:58:03 susetest systemd[1]: Child 13216 (snapperd) died (code=exited, status=0/SUCCESS)
Oct 29 09:58:03 susetest systemd[1]: dbus.service: Child 13216 belongs to dbus.service.
Oct 29 09:58:29 susetest systemd[1]: systemd-udevd.service: Got notification message from PID 385 (WATCHDOG=1)
Oct 29 09:58:39 susetest systemd[1]: systemd-logind.service: Got notification message from PID 866 (WATCHDOG=1)
Oct 29 09:59:39 susetest systemd[1]: systemd-journald.service: Got notification message from PID 363 (WATCHDOG=1)
Oct 29 10:00:39 susetest systemd[1]: systemd-udevd.service: Got notification message from PID 385 (WATCHDOG=1)
Oct 29 10:00:39 susetest systemd[1]: systemd-logind.service: Got notification message from PID 866 (WATCHDOG=1)
Oct 29 10:01:29 susetest systemd[1]: systemd-journald.service: Got notification message from PID 363 (WATCHDOG=1)
Oct 29 10:01:45 susetest kernel: sysrq: SysRq : Show Blocked State
Oct 29 10:01:45 susetest kernel:   task                        PC stack   pid father

Oct 29 10:01:45 susetest kernel: kglobalaccel5   D    0 12766   1275 0x00000000

Oct 29 10:01:45 susetest kernel: Call Trace:
Oct 29 10:01:45 susetest kernel:  ? __schedule+0x29a/0x880
Oct 29 10:01:45 susetest kernel:  schedule+0x2f/0x90
Oct 29 10:01:45 susetest kernel:  io_schedule+0x12/0x40
Oct 29 10:01:45 susetest kernel:  __lock_page_or_retry+0x174/0x2e0
Oct 29 10:01:45 susetest kernel:  ? radix_tree_lookup_slot+0xe/0x20
Oct 29 10:01:45 susetest kernel:  ? page_cache_tree_insert+0xb0/0xb0
Oct 29 10:01:45 susetest kernel:  filemap_fault+0x14f/0x740
Oct 29 10:01:45 susetest kernel:  ? filemap_map_pages+0x1f6/0x390
Oct 29 10:01:45 susetest kernel:  __do_fault+0x20/0xe0
Oct 29 10:01:45 susetest kernel:  handle_pte_fault+0x931/0xff0
Oct 29 10:01:45 susetest kernel:  __handle_mm_fault+0x3ed/0x540
Oct 29 10:01:45 susetest kernel:  handle_mm_fault+0xfd/0x240
Oct 29 10:01:45 susetest kernel:  __do_page_fault+0x211/0x4e0
Oct 29 10:01:45 susetest kernel:  ? async_page_fault+0x8/0x30
Oct 29 10:01:45 susetest kernel:  async_page_fault+0x1e/0x30
Oct 29 10:01:45 susetest kernel: RIP: 0033:0x7f35a1da0f10
Oct 29 10:01:45 susetest kernel: Code: Bad RIP value.
Oct 29 10:01:45 susetest kernel: RSP: 002b:00007ffd9309aaa8 EFLAGS: 00010206
Oct 29 10:01:45 susetest kernel: RAX: 0000000000000000 RBX: 00007f3594005670 RCX: 00007f359c819ad8
Oct 29 10:01:45 susetest kernel: RDX: 00007f3594005670 RSI: 00007f359ab320db RDI: 0000000000000013
Oct 29 10:01:45 susetest kernel: RBP: 000055e28db475f0 R08: 000055e28dc4ec50 R09: 0000000000000000
Oct 29 10:01:45 susetest kernel: R10: 0000000000000001 R11: 0000000000000000 R12: 000055e28db3d090
Oct 29 10:01:45 susetest kernel: R13: 00007f3594005670 R14: 00007ffd9309ab68 R15: 000055e28db3d7f0
Oct 29 10:01:47 susetest systemd-logind[866]: VT changed to 5
Oct 29 10:01:47 susetest systemd-logind[866]: Sent message type=signal sender=n/a destination=n/a
  path=/org/freedesktop/login1/session/_37 interface=org.freedesktop.DBus.Properties member=PropertiesChanged
  cookie=510 reply_cookie=0 signature=sa{sv}as error-

systemd is started with log level debug:

Oct 29 09:17:14 linux-shhx kernel: Command line: BOOT_IMAGE=/boot/vmlinuz-4.18.15-1-default
root=UUID=427af700-989b-448a-91d5-2b6f10627ffb splash=silent video=1024x768-16 plymouth.ignore-serial-consoles
console=ttyS0 console=tty systemd.log_level=debug systemd.log_target=kmsg log_buf_len=1M printk.devkmsg=on
enforcing=0 resume=/dev/disk/by-path/pci-0000:00:08.0-part4 quiet

The log level is apparently set during the installation:
https://openqa.opensuse.org/tests/783612#step/disable_grub_timeout/9

Reproducible

Fails since (at least) Build 20181023

Expected result

Last good: 20181022 (or more recent)

Further details

Always latest result in this scenario: latest

Actions #1

Updated by okurz over 5 years ago

  • Subject changed from test fails in kate - excessive systemd debug level? to [functional][y] test fails in kate - excessive systemd debug level?
  • Assignee set to oorlov
  • Target version set to Milestone 21

@oorlov I assume this is since you increased systemd debugging info in shutdown?

Actions #2

Updated by oorlov over 5 years ago

Well, DEBUG_SHUTDOWN=1 is applied for the kde test suite and sets 'systemd.log_level=debug systemd.log_target=kmsg' in boot.

If it is the issue, then DEBUG_SHUTDOWN could be removed. And it actually has to be removed, as it was added to gather shutdown failing statistics, but shutdown is not failing anymore there.

The other question is why "Kate" module fails more then the others and on the same KRunner call? KRunner simply does not show prompt on typing. Does logging can load system so much?

Actions #3

Updated by oorlov over 5 years ago

  • Status changed from New to Feedback

I've removed the DEBUG_SHUTDOWN from kde scenario. Will monitor the kde issue in the next runs.

Actions #4

Updated by okurz over 5 years ago

  • Due date set to 2018-12-18
Actions #5

Updated by oorlov over 5 years ago

  • Status changed from Feedback to Resolved

Test is not failed anymore.

Actions #6

Updated by okurz over 5 years ago

  • Status changed from Resolved to Feedback

so does that mean that there can not be any "excessive systemd debug" information anymore?

Actions #7

Updated by okurz over 5 years ago

  • Status changed from Feedback to Resolved

As confirmed by oorlov: Yes, that means that the excessing systemd debugging is prevented.

Actions

Also available in: Atom PDF