cockpit icon indicating copy to clipboard operation
cockpit copied to clipboard

Published 20 hours ago • verified publisher icon cockpit-project

Use fsinfo for cockpit.file.watch()

Open jelly opened this issue 1 year ago • 13 comments

  • [ ] Machines PR succeeds https://github.com/cockpit-project/cockpit-machines/pull/1449

jelly avatar Feb 13 '24 17:02 jelly

TestPages.testFrameReload and TestMultiMachine.testFrameReload fail due to a difference of handling a non-existent file.

[jelle@t14s][~/projects/cockpit/main]%cpf open fsread1 path=/tmp/counter  | cockpit-bridge
963

{
  "capabilities": {
    "explicit-superuser": true
  },
  "command": "init",
  "os-release": {
    "NAME": "Arch Linux",
    "PRETTY_NAME": "Arch Linux",
    "ID": "arch",
    "BUILD_ID": "rolling",
    "ANSI_COLOR": "38;2;23;147;209",
    "HOME_URL": "https://archlinux.org/",
    "DOCUMENTATION_URL": "https://wiki.archlinux.org/",
    "SUPPORT_URL": "https://bbs.archlinux.org/",
    "BUG_REPORT_URL": "https://gitlab.archlinux.org/groups/archlinux/-/issues",
    "PRIVACY_POLICY_URL": "https://terms.archlinux.org/docs/privacy-policy/",
    "LOGO": "archlinux-logo"
  },
  "version": 1,
  "packages": {
    "apps": null,
    "base1": null,
    "playground": null,
    "users": null,
    "metrics": null,
    "system": null,
    "static": null,
    "network": null,
    "shell": null,
    "storage": null,
    "kdump": null,
    "updates": null,
    "sosreport": null,
    "iframewalk": null,
    "machines": null,
    "podman": null,
    "pcp": null
  }
}
45

{
  "channel": "ch1",
  "command": "done"
}
60

{
  "tag": "-",
  "command": "close",
  "channel": "ch1"
}

Versus:

[jelle@t14s][~/projects/cockpit/main]%cpf fsinfo /tmp/counter tag  : wait | cockpit-bridge
963

{
  "capabilities": {
    "explicit-superuser": true
  },
  "command": "init",
  "os-release": {
    "NAME": "Arch Linux",
    "PRETTY_NAME": "Arch Linux",
    "ID": "arch",
    "BUILD_ID": "rolling",
    "ANSI_COLOR": "38;2;23;147;209",
    "HOME_URL": "https://archlinux.org/",
    "DOCUMENTATION_URL": "https://wiki.archlinux.org/",
    "SUPPORT_URL": "https://bbs.archlinux.org/",
    "BUG_REPORT_URL": "https://gitlab.archlinux.org/groups/archlinux/-/issues",
    "PRIVACY_POLICY_URL": "https://terms.archlinux.org/docs/privacy-policy/",
    "LOGO": "archlinux-logo"
  },
  "version": 1,
  "packages": {
    "apps": null,
    "base1": null,
    "playground": null,
    "users": null,
    "metrics": null,
    "system": null,
    "static": null,
    "network": null,
    "shell": null,
    "storage": null,
    "kdump": null,
    "updates": null,
    "sosreport": null,
    "iframewalk": null,
    "machines": null,
    "podman": null,
    "pcp": null
  }
}
46

{
  "channel": "ch1",
  "command": "ready"
}
119
ch1
{
  "error": {
    "problem": "not-found",
    "message": "No such file or directory",
    "errno": "ENOENT"
  }
}

jelly avatar Feb 19 '24 16:02 jelly

@martinpitt There are two open issues in this PR for which I'd like your opinion on:

  • Providing fsinfo in Cockpit, the current split out file relies on a hack by importing cockpit.js as last line, so we don't run into a circular import situation. Options are:

    • Move it untyped in cockpit.js
    • Convert cockpit.js to cockpit.ts and move it in there
    • Keep the hack around

  • fsinfo API, having a separate file in pkg/lib basically means we have declared the fsinfo api "stable". Can we live with that or do we want to hide it for now. Also we have a copy in navigator:

    • Keep it separate, but note that it's private
    • Put it into Cockpit.js and don't expose it, downside is that we have a copy in navigator

Ideally cockpit.file would get a cockpit.file.info which is our new fsinfo channel high level wrapper. I think this is a great idea, but I don't want to work on that now. After all I was only interested in fixing https://github.com/cockpit-project/cockpit/issues/19983 not exposing fsinfo in general :)

Also there was talk about fsinfo reading small files, possibly a great addition for cockpit.file.watch() like for watching /etc/hostname or crypto policies. So maybe we should wait on that first before declaring public.

jelly avatar Feb 20 '24 14:02 jelly

Thanks! Some minor cleanups, but this is nice enough to land it even with the import hack IMHO.

Wrt. your questions above:

* I don't like moving it here untyped, that feels like a step backwards. My preferred route would be to land this PR, then send a new one which renames cockpit.js to cockpit.ts (which according to Lis should be fine, except that we need to install and integrate `tsc` of course). Then you can re-integrate fsinfo.ts, or rearrange things differently to not require circular imports (but the latter is a huge task, let's not do that now).

This was also my idea more of less. Plus at least typing the basics of Cockpit maybe with any?

* I'm fine with declaring fsinfo "stable" now, but @allisonkarlitskaya is the one who has the last word on that. However, I don't see how that needs to be done for this PR -- all that it does is to move `cockpit.file().watch()` over to it, and we can adjust that in the future if necessary.

Well it does make a pkg/lib/cockpit-fsinfo.ts so one could see that as "stable".

* Agreed that cockpit.file().info() would be nice as next step, but not a blocker for navigator I think.

:+1:

For now in navigator we vendor fsinfo.ts, but yeah we should declare this properly and write user docs, QUnit tests. All at least some work.

jelly avatar Feb 21 '24 09:02 jelly

Well it does make a pkg/lib/cockpit-fsinfo.ts so one could see that as "stable".

You mean because projects grab a particular SHA of pkg/lib, and if we change the bridge it would break. That's a good point. So if we do that, the bridge fsinfo channel needs to remain backwards compatible at least for the (rather limited) API that cockpit.file.watch() uses -- i.e. .effect(), state.info and so on.

So one thing about this: .effect() is really weird. The usual API is to have something like watch_channel.addEventListener("changed", state => {....}), or perhaps "event" or so. That's actually something I'd

martinpitt avatar Feb 21 '24 09:02 martinpitt

Thanks! Some minor cleanups, but this is nice enough to land it even with the import hack IMHO.

I agree with everything in this comment, including "next steps".

For now in navigator we vendor fsinfo.ts

Can't vendor it if it isn't "upstream" yet :sweat_smile:

allisonkarlitskaya avatar Feb 21 '24 09:02 allisonkarlitskaya

I can't get testExpire to ever pass, I think it's due to the passwd -S flood

rhel4edge, fcos

jelly avatar Feb 22 '24 12:02 jelly

testExpire is a legit issue, with limited access we don't fire a callback so getLogins does not seem to be called.

jelly avatar Feb 26 '24 17:02 jelly

Blocked as we get an error now and close the channel when you are in limited access and try to watch /etc/shadow, potential fix:

so in filesystem.py line ~502 i'd try changing if err is None to if fd is not None and see what happens. depending on how /etc/shadow is updated (trunc vs. atomic) it may or may not work

jelly avatar Feb 28 '24 08:02 jelly

Only OSTree based images have a suspicious issue, where the accounts page does not load when we initially login and go to /users/#newuser. Pressing F5 makes the page load.

Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.transports-DEBUG: Read ready on <cockpit.transports.SubprocessTransport object at 0x7f10757ea150> <cockpit.channels.stream.SubprocessStreamChannel object at 0x7f10756d98e0> 23
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.transports-DEBUG:   got EOF
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: sending control message None {'channel': '1:2!5', 'command': 'done'}
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: writing to transport <cockpit.transports.StdioTransport object at 0x7f1075648ad0>
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.router-DEBUG: shutdown_endpoint(<cockpit.channels.stream.SubprocessStreamChannel object at 0x7f10756d98e0>, {}) will close {'1:2!5'}
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: sending control message {'exit-status': 0, 'message': ''} {'command': 'close', 'channel': '1:2!5'}
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: writing to transport <cockpit.transports.StdioTransport object at 0x7f1075648ad0>
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.router-DEBUG: router dropped channel 1:2!5
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.transports-DEBUG: won't attempt 15 to process 2356.  It exited already.
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit._vendor.ferny.interaction_agent-DEBUG: _got_data(b'\x00', [20, 22, 26])
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit._vendor.ferny.interaction_agent-DEBUG: _invoke_command(bytearray(b'\nWe trust you have received the usual lecture from the local System\nAdministrator. It usually boils down to these three things:\n\n    #>
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.transports-DEBUG: Read ready on <cockpit.transports.StdioTransport object at 0x7f1075648ad0> <cockpit.bridge.Bridge object at 0x7f10769d8d70> 0
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.transports-DEBUG:   read 1311 bytes
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: channel control received {'channel': '1:4!3', 'command': 'pong', 'sequence': 24013}
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: channel control received {'channel': '1:4!3', 'command': 'pong', 'sequence': 24013}
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: channel control received {'channel': '1:4!3', 'command': 'pong', 'sequence': 24013}
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: channel control received {'channel': '1:4!3', 'command': 'pong', 'sequence': 24013}
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: channel control received {'channel': '1:4!3', 'command': 'pong', 'sequence': 24013}
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: data received: 97 bytes of data for channel 1:4!3
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.channels.dbus-DEBUG: receive dbus request org.freedesktop.systemd1 {'call': ['/org/freedesktop/systemd1', 'org.freedesktop.systemd1.Manager', 'Subscribe', []], 'id': '3'}
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: data received: 119 bytes of data for channel 1:4!3
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.channels.dbus-DEBUG: receive dbus request org.freedesktop.systemd1 {'call': ['/org/freedesktop/systemd1', 'org.freedesktop.systemd1.Manager', 'LoadUnit', ['insights-client.timer']], 'id': '4'}
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: data received: 136 bytes of data for channel 1:4!3
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.channels.dbus-DEBUG: receive dbus request org.freedesktop.systemd1 {'call': ['/org/freedesktop/systemd1', 'org.freedesktop.systemd1.Manager', 'LoadUnit', ['dbus-org.freedesktop.timedate1.service']], 'id': >
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: data received: 123 bytes of data for channel 1:4!3
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.channels.dbus-DEBUG: receive dbus request org.freedesktop.systemd1 {'call': ['/org/freedesktop/systemd1', 'org.freedesktop.systemd1.Manager', 'LoadUnit', ['systemd-timesyncd.service']], 'id': '6'}
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: data received: 113 bytes of data for channel 1:4!3
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.channels.dbus-DEBUG: receive dbus request org.freedesktop.systemd1 {'call': ['/org/freedesktop/systemd1', 'org.freedesktop.systemd1.Manager', 'LoadUnit', ['chronyd.service']], 'id': '7'}
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: data received: 111 bytes of data for channel 1:4!3
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.channels.dbus-DEBUG: receive dbus request org.freedesktop.systemd1 {'call': ['/org/freedesktop/systemd1', 'org.freedesktop.systemd1.Manager', 'LoadUnit', ['tuned.service']], 'id': '8'}
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: data received: 67 bytes of data for channel 1:4!1
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.channels.dbus-DEBUG: receive dbus request None {'add-match': {'path': '/superuser', 'interface': 'cockpit.Superuser'}}
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: data received: 73 bytes of data for channel 1:4!1
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.channels.dbus-DEBUG: receive dbus request None {'watch': {'path': '/superuser', 'interface': 'cockpit.Superuser'}, 'id': '14'}
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: data received: 99 bytes of data for channel 1:4!1
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.channels.dbus-DEBUG: receive dbus request None {'type': 's', 'call': ['/user', 'org.freedesktop.DBus.Properties', 'GetAll', ['cockpit.User']], 'id': '15'}
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit._vendor.systemd_ctypes.bus-DEBUG: Doing async method call None /superuser org.freedesktop.DBus.Introspectable Introspect  ()
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit._vendor.ferny.interaction_agent-DEBUG: run_command(ferny.askpass, (['/usr/libexec/cockpit-askpass', '[sudo] password for scruffy: '], {'SHELL': '/bin/bash', 'EDITOR': '/usr/bin/nano', 'PWD': '/var/home/scr>
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: We trust you have received the usual lecture from the local System
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: Administrator. It usually boils down to these three things:
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]:
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]:     #1) Respect the privacy of others.
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]:     #2) Think before you type.
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]:     #3) With great power comes great responsibility.
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]:
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: For security reasons, the password you type will not be visible.
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]:
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: )
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit._vendor.ferny.interaction_agent-DEBUG: _askpass_command((['/usr/libexec/cockpit-askpass', '[sudo] password for scruffy: '], {'SHELL': '/bin/bash', 'EDITOR': '/usr/bin/nano', 'PWD': '/var/home/scruffy', 'LO>
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: We trust you have received the usual lecture from the local System
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: Administrator. It usually boils down to these three things:
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]:
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]:     #1) Respect the privacy of others.
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]:     #2) Think before you type.
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]:     #3) With great power comes great responsibility.
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]:
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: For security reasons, the password you type will not be visible.
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]:
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: )
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit._vendor.ferny.interaction_agent-DEBUG: do_askpass('\nWe trust you have received the usual lecture from the local System\nAdministrator. It usually boils down to these three things:\n\n    #1) Respect the p>
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: sending control message None {'command': 'authorize', 'challenge': 'plain1:73637275666679', 'cookie': 'f2f68e61-e298-430c-b442-e9036fc44817'}
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: writing to transport <cockpit.transports.StdioTransport object at 0x7f1075648ad0>
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.channels.dbus-DEBUG: Doing introspection request for org.freedesktop.systemd1.Manager LoadUnit
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.channels.dbus-DEBUG: Doing introspection request for org.freedesktop.systemd1.Manager LoadUnit
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.channels.dbus-DEBUG: Doing introspection request for org.freedesktop.systemd1.Manager LoadUnit
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.channels.dbus-DEBUG: Doing introspection request for org.freedesktop.systemd1.Manager LoadUnit
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.channels.dbus-DEBUG: Doing introspection request for org.freedesktop.systemd1.Manager LoadUnit
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.channels.dbus-DEBUG: adding match {'path': '/superuser', 'interface': 'cockpit.Superuser'}
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: writing to transport <cockpit.transports.StdioTransport object at 0x7f1075648ad0>
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit._vendor.systemd_ctypes.bus-DEBUG: Doing async method call None /superuser org.freedesktop.DBus.Properties GetAll s ('cockpit.Superuser',)
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.transports-DEBUG: Read ready on <cockpit.transports.StdioTransport object at 0x7f1075648ad0> <cockpit.bridge.Bridge object at 0x7f10769d8d70> 0
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.transports-DEBUG:   read 95 bytes
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: transport control received {'command': 'authorize', 'cookie': 'f2f68e61-e298-430c-b442-e9036fc44817', 'response': 'foobar'}
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit._vendor.ferny.interaction_agent-DEBUG: do_askpass answer 'foobar'
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: writing to transport <cockpit.transports.StdioTransport object at 0x7f1075648ad0>
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.channels.dbus-DEBUG: got match
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: writing to transport <cockpit.transports.StdioTransport object at 0x7f1075648ad0>
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: writing to transport <cockpit.transports.StdioTransport object at 0x7f1075648ad0>
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: writing to transport <cockpit.transports.StdioTransport object at 0x7f1075648ad0>
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: writing to transport <cockpit.transports.StdioTransport object at 0x7f1075648ad0>
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.channels.dbus-DEBUG: got match
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: writing to transport <cockpit.transports.StdioTransport object at 0x7f1075648ad0>
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: writing to transport <cockpit.transports.StdioTransport object at 0x7f1075648ad0>
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: writing to transport <cockpit.transports.StdioTransport object at 0x7f1075648ad0>
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: writing to transport <cockpit.transports.StdioTransport object at 0x7f1075648ad0>
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: writing to transport <cockpit.transports.StdioTransport object at 0x7f1075648ad0>
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.channels.dbus-DEBUG: got match
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: writing to transport <cockpit.transports.StdioTransport object at 0x7f1075648ad0>
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.channels.dbus-DEBUG: got match
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: writing to transport <cockpit.transports.StdioTransport object at 0x7f1075648ad0>
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit._vendor.ferny.interaction_agent-DEBUG: <cockpit.superuser.AuthorizeResponder object at 0x7f107678f620> completed cleanly
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit._vendor.ferny.interaction_agent-DEBUG: _consider_completion(<cockpit._vendor.ferny.interaction_agent.InteractionAgent object at 0x7f10758ab800>)
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit._vendor.ferny.interaction_agent-DEBUG:   but not ready yet
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit._vendor.systemd_ctypes.bus-DEBUG: Doing async method call None /superuser org.freedesktop.DBus.Introspectable Introspect  ()
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.transports-DEBUG: Read ready on <cockpit.transports.StdioTransport object at 0x7f1075648ad0> <cockpit.bridge.Bridge object at 0x7f10769d8d70> 0
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.transports-DEBUG:   read 558 bytes
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: data received: 125 bytes of data for channel 1:4!3
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.channels.dbus-DEBUG: receive dbus request org.freedesktop.systemd1 {'add-match': {'path': '/org/freedesktop/systemd1/unit/insights_2dclient_2etimer', 'interface': 'org.freedesktop.systemd1.Unit'}}
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: data received: 131 bytes of data for channel 1:4!3
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.channels.dbus-DEBUG: receive dbus request org.freedesktop.systemd1 {'watch': {'path': '/org/freedesktop/systemd1/unit/insights_2dclient_2etimer', 'interface': 'org.freedesktop.systemd1.Unit'}, 'id': '10'}
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: data received: 128 bytes of data for channel 1:4!3
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.channels.dbus-DEBUG: receive dbus request org.freedesktop.systemd1 {'add-match': {'path': '/org/freedesktop/systemd1/unit/insights_2dclient_2etimer', 'interface': 'org.freedesktop.systemd1.Service'}}
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: data received: 134 bytes of data for channel 1:4!3
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.channels.dbus-DEBUG: receive dbus request org.freedesktop.systemd1 {'watch': {'path': '/org/freedesktop/systemd1/unit/insights_2dclient_2etimer', 'interface': 'org.freedesktop.systemd1.Service'}, 'id': '12>
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.channels.dbus-DEBUG: adding match {'path': '/org/freedesktop/systemd1/unit/insights_2dclient_2etimer', 'interface': 'org.freedesktop.systemd1.Unit'}
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit._vendor.systemd_ctypes.bus-DEBUG: Doing async method call org.freedesktop.systemd1 /org/freedesktop/systemd1/unit/insights_2dclient_2etimer org.freedesktop.DBus.Introspectable Introspect  ()
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.channels.dbus-DEBUG: adding match {'path': '/org/freedesktop/systemd1/unit/insights_2dclient_2etimer', 'interface': 'org.freedesktop.systemd1.Service'}
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit._vendor.systemd_ctypes.bus-DEBUG: Doing async method call None /superuser org.freedesktop.DBus.Properties GetAll s ('cockpit.Superuser',)
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.transports-DEBUG: Read ready on <cockpit.transports.StdioTransport object at 0x7f1075648ad0> <cockpit.bridge.Bridge object at 0x7f10769d8d70> 0
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.transports-DEBUG:   read 2192 bytes
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: data received: 129 bytes of data for channel 1:4!3
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.channels.dbus-DEBUG: receive dbus request org.freedesktop.systemd1 {'add-match': {'path': '/org/freedesktop/systemd1/unit/systemd_2dtimedated_2eservice', 'interface': 'org.freedesktop.systemd1.Unit'}}
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: data received: 135 bytes of data for channel 1:4!3
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.channels.dbus-DEBUG: receive dbus request org.freedesktop.systemd1 {'watch': {'path': '/org/freedesktop/systemd1/unit/systemd_2dtimedated_2eservice', 'interface': 'org.freedesktop.systemd1.Unit'}, 'id': '1>
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: data received: 132 bytes of data for channel 1:4!3
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.channels.dbus-DEBUG: receive dbus request org.freedesktop.systemd1 {'add-match': {'path': '/org/freedesktop/systemd1/unit/systemd_2dtimedated_2eservice', 'interface': 'org.freedesktop.systemd1.Service'}}
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: data received: 138 bytes of data for channel 1:4!3
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.channels.dbus-DEBUG: receive dbus request org.freedesktop.systemd1 {'watch': {'path': '/org/freedesktop/systemd1/unit/systemd_2dtimedated_2eservice', 'interface': 'org.freedesktop.systemd1.Service'}, 'id':>
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: data received: 129 bytes of data for channel 1:4!3
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.channels.dbus-DEBUG: receive dbus request org.freedesktop.systemd1 {'add-match': {'path': '/org/freedesktop/systemd1/unit/systemd_2dtimesyncd_2eservice', 'interface': 'org.freedesktop.systemd1.Unit'}}
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: data received: 135 bytes of data for channel 1:4!3
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.channels.dbus-DEBUG: receive dbus request org.freedesktop.systemd1 {'watch': {'path': '/org/freedesktop/systemd1/unit/systemd_2dtimesyncd_2eservice', 'interface': 'org.freedesktop.systemd1.Unit'}, 'id': '1>
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: data received: 132 bytes of data for channel 1:4!3
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.channels.dbus-DEBUG: receive dbus request org.freedesktop.systemd1 {'add-match': {'path': '/org/freedesktop/systemd1/unit/systemd_2dtimesyncd_2eservice', 'interface': 'org.freedesktop.systemd1.Service'}}
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: data received: 138 bytes of data for channel 1:4!3
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.channels.dbus-DEBUG: receive dbus request org.freedesktop.systemd1 {'watch': {'path': '/org/freedesktop/systemd1/unit/systemd_2dtimesyncd_2eservice', 'interface': 'org.freedesktop.systemd1.Service'}, 'id':>
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: data received: 117 bytes of data for channel 1:4!3
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.channels.dbus-DEBUG: receive dbus request org.freedesktop.systemd1 {'add-match': {'path': '/org/freedesktop/systemd1/unit/chronyd_2eservice', 'interface': 'org.freedesktop.systemd1.Unit'}}
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: data received: 123 bytes of data for channel 1:4!3
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.channels.dbus-DEBUG: receive dbus request org.freedesktop.systemd1 {'watch': {'path': '/org/freedesktop/systemd1/unit/chronyd_2eservice', 'interface': 'org.freedesktop.systemd1.Unit'}, 'id': '22'}
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: data received: 120 bytes of data for channel 1:4!3
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.channels.dbus-DEBUG: receive dbus request org.freedesktop.systemd1 {'add-match': {'path': '/org/freedesktop/systemd1/unit/chronyd_2eservice', 'interface': 'org.freedesktop.systemd1.Service'}}
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: data received: 126 bytes of data for channel 1:4!3
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.channels.dbus-DEBUG: receive dbus request org.freedesktop.systemd1 {'watch': {'path': '/org/freedesktop/systemd1/unit/chronyd_2eservice', 'interface': 'org.freedesktop.systemd1.Service'}, 'id': '24'}
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: data received: 115 bytes of data for channel 1:4!3
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.channels.dbus-DEBUG: receive dbus request org.freedesktop.systemd1 {'add-match': {'path': '/org/freedesktop/systemd1/unit/tuned_2eservice', 'interface': 'org.freedesktop.systemd1.Unit'}}
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: data received: 121 bytes of data for channel 1:4!3
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.channels.dbus-DEBUG: receive dbus request org.freedesktop.systemd1 {'watch': {'path': '/org/freedesktop/systemd1/unit/tuned_2eservice', 'interface': 'org.freedesktop.systemd1.Unit'}, 'id': '26'}
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: data received: 118 bytes of data for channel 1:4!3
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.channels.dbus-DEBUG: receive dbus request org.freedesktop.systemd1 {'add-match': {'path': '/org/freedesktop/systemd1/unit/tuned_2eservice', 'interface': 'org.freedesktop.systemd1.Service'}}
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: data received: 124 bytes of data for channel 1:4!3
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.channels.dbus-DEBUG: receive dbus request org.freedesktop.systemd1 {'watch': {'path': '/org/freedesktop/systemd1/unit/tuned_2eservice', 'interface': 'org.freedesktop.systemd1.Service'}, 'id': '28'}
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.channels.dbus-DEBUG: adding match {'path': '/org/freedesktop/systemd1/unit/systemd_2dtimedated_2eservice', 'interface': 'org.freedesktop.systemd1.Unit'}
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.channels.dbus-DEBUG: adding match {'path': '/org/freedesktop/systemd1/unit/systemd_2dtimedated_2eservice', 'interface': 'org.freedesktop.systemd1.Service'}
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.channels.dbus-DEBUG: adding match {'path': '/org/freedesktop/systemd1/unit/systemd_2dtimesyncd_2eservice', 'interface': 'org.freedesktop.systemd1.Unit'}
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.channels.dbus-DEBUG: adding match {'path': '/org/freedesktop/systemd1/unit/systemd_2dtimesyncd_2eservice', 'interface': 'org.freedesktop.systemd1.Service'}
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.channels.dbus-DEBUG: adding match {'path': '/org/freedesktop/systemd1/unit/chronyd_2eservice', 'interface': 'org.freedesktop.systemd1.Unit'}
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.channels.dbus-DEBUG: adding match {'path': '/org/freedesktop/systemd1/unit/chronyd_2eservice', 'interface': 'org.freedesktop.systemd1.Service'}
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.channels.dbus-DEBUG: adding match {'path': '/org/freedesktop/systemd1/unit/tuned_2eservice', 'interface': 'org.freedesktop.systemd1.Unit'}
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.channels.dbus-DEBUG: adding match {'path': '/org/freedesktop/systemd1/unit/tuned_2eservice', 'interface': 'org.freedesktop.systemd1.Service'}
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit._vendor.systemd_ctypes.bus-DEBUG: Doing async method call org.freedesktop.systemd1 /org/freedesktop/systemd1/unit/insights_2dclient_2etimer org.freedesktop.DBus.Properties GetAll s ('org.freedesktop.system>
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.channels.dbus-DEBUG: got match
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: writing to transport <cockpit.transports.StdioTransport object at 0x7f1075648ad0>
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: writing to transport <cockpit.transports.StdioTransport object at 0x7f1075648ad0>
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: writing to transport <cockpit.transports.StdioTransport object at 0x7f1075648ad0>
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.channels.dbus-DEBUG: got match
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: writing to transport <cockpit.transports.StdioTransport object at 0x7f1075648ad0>
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: writing to transport <cockpit.transports.StdioTransport object at 0x7f1075648ad0>
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: sending control message None {'channel': '1:4!3', 'command': 'ping', 'sequence': 42468}
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: writing to transport <cockpit.transports.StdioTransport object at 0x7f1075648ad0>
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: writing to transport <cockpit.transports.StdioTransport object at 0x7f1075648ad0>
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: writing to transport <cockpit.transports.StdioTransport object at 0x7f1075648ad0>
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.channels.dbus-DEBUG: got match
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.channels.dbus-DEBUG: got match
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: writing to transport <cockpit.transports.StdioTransport object at 0x7f1075648ad0>
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit._vendor.systemd_ctypes.bus-DEBUG: Doing async method call org.freedesktop.systemd1 /org/freedesktop/systemd1/unit/insights_2dclient_2etimer org.freedesktop.DBus.Introspectable Introspect  ()
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: writing to transport <cockpit.transports.StdioTransport object at 0x7f1075648ad0>
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: writing to transport <cockpit.transports.StdioTransport object at 0x7f1075648ad0>
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit._vendor.systemd_ctypes.bus-DEBUG: Doing async method call org.freedesktop.systemd1 /org/freedesktop/systemd1/unit/insights_2dclient_2etimer org.freedesktop.DBus.Properties GetAll s ('org.freedesktop.system>
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.channels.dbus-DEBUG: got match
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.channels.dbus-DEBUG: got match
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit._vendor.systemd_ctypes.bus-DEBUG: Doing async method call None /superuser org.freedesktop.DBus.Introspectable Introspect  ()
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: writing to transport <cockpit.transports.StdioTransport object at 0x7f1075648ad0>
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: writing to transport <cockpit.transports.StdioTransport object at 0x7f1075648ad0>
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: writing to transport <cockpit.transports.StdioTransport object at 0x7f1075648ad0>
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.channels.dbus-DEBUG: got match
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.channels.dbus-DEBUG: got match
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.transports-DEBUG: Read ready on <cockpit.transports.StdioTransport object at 0x7f1075648ad0> <cockpit.bridge.Bridge object at 0x7f10769d8d70> 0
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.transports-DEBUG:   read 364 bytes
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: channel control received {'channel': '1:4!3', 'command': 'pong', 'sequence': 42468}
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: channel control received {'channel': '1:4!3', 'command': 'pong', 'sequence': 42468}
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: channel control received {'channel': '1:4!3', 'command': 'pong', 'sequence': 42468}
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: channel control received {'channel': '1:4!3', 'command': 'pong', 'sequence': 42468}
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: channel control received {'channel': '1:4!3', 'command': 'pong', 'sequence': 42468}
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: data received: 70 bytes of data for channel 1:4!1
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.channels.dbus-DEBUG: receive dbus request None {'call': ['/LoginMessages', 'cockpit.LoginMessages', 'Get', []], 'id': '16'}
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit._vendor.systemd_ctypes.bus-DEBUG: Doing async method call org.freedesktop.systemd1 /org/freedesktop/systemd1/unit/systemd_2dtimedated_2eservice org.freedesktop.DBus.Introspectable Introspect  ()
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit._vendor.systemd_ctypes.bus-DEBUG: Doing async method call None /superuser org.freedesktop.DBus.Properties GetAll s ('cockpit.Superuser',)
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: writing to transport <cockpit.transports.StdioTransport object at 0x7f1075648ad0>
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: writing to transport <cockpit.transports.StdioTransport object at 0x7f1075648ad0>
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: writing to transport <cockpit.transports.StdioTransport object at 0x7f1075648ad0>
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: writing to transport <cockpit.transports.StdioTransport object at 0x7f1075648ad0>
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.transports-DEBUG: won't attempt 15 to process 2356.  It exited already.
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.transports-DEBUG: won't attempt 15 to process 2358.  It exited already.
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.transports-DEBUG: won't attempt 15 to process 2359.  It exited already.
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit._vendor.systemd_ctypes.bus-DEBUG: Doing async method call org.freedesktop.systemd1 /org/freedesktop/systemd1/unit/systemd_2dtimedated_2eservice org.freedesktop.DBus.Properties GetAll s ('org.freedesktop.sy>

Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 sudo[2346]:  scruffy : user NOT in sudoers ; PWD=/var/home/scruffy ; USER=root ; COMMAND=/usr/bin/cockpit-bridge --privileged
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit._vendor.systemd_ctypes.bus-DEBUG: Doing async method call org.freedesktop.systemd1 /org/freedesktop/systemd1/unit/systemd_2dtimesyncd_2eservice org.freedesktop.DBus.Properties GetAll s ('org.freedesktop.sy>
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit._vendor.ferny.interaction_agent-DEBUG: _got_data(b'scruffy is not in the sudoers file.\n', [])
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.transports-DEBUG: Read ready on <cockpit.transports.SubprocessTransport object at 0x7f107551b550> <cockpit.superuser.SuperuserPeer object at 0x7f10765463f0> 19
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.transports-DEBUG:   got EOF
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.peer-DEBUG: Peer SuperuserPeer received unexpected EOF
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.transports-DEBUG: Process exited with status 1
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.peer-DEBUG: Peer SuperuserPeer exited, status 1
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: connection_lost
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.transports-DEBUG: won't attempt 15 to process 2346.  It exited already.
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.peer-DEBUG: Peer SuperuserPeer connection lost <class 'cockpit.peer.PeerExited'> 1
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.router-DEBUG: shutdown_endpoint(<cockpit.superuser.SuperuserPeer object at 0x7f10765463f0>, {'problem': 'terminated', 'message': 'Peer exited with status 1'}) will close {'1:4!7', '1:4!8', '1:2!2', '1:3!4'>
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: sending control message None {'command': 'close', 'channel': '1:4!7', 'problem': 'terminated', 'message': 'Peer exited with status 1'}
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: writing to transport <cockpit.transports.StdioTransport object at 0x7f1075648ad0>
Mar 21 17:02:35 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.router-DEBUG: router dropped channel 1:4!7

So this seems to be fatal?

More interesting obversations:

Mar 21 17:23:40 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.transports-DEBUG: Read ready on <cockpit.transports.StdioTransport object at 0x7f5b06801c90> <cockpit.bridge.Bridge object at 0x7f5b0768f050> 0
Mar 21 17:23:40 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.transports-DEBUG:   read 147 bytes
Mar 21 17:23:40 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: data received: 136 bytes of data for channel 1:3!31
Mar 21 17:23:41 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.transports-DEBUG: Read ready on <cockpit.transports.StdioTransport object at 0x7f5b06801c90> <cockpit.bridge.Bridge object at 0x7f5b0768f050> 0
Mar 21 17:23:41 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.transports-DEBUG:   read 79 bytes
Mar 21 17:23:41 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: data received: 72 bytes of data for channel 1:7
Mar 21 17:23:41 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.channels.dbus-DEBUG: receive dbus request None {'call': ['/superuser', 'cockpit.Superuser', 'Answer', ['foobar']], 'id': '5'}
Mar 21 17:23:41 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.channels.dbus-DEBUG: Doing introspection request for cockpit.Superuser Answer
Mar 21 17:23:41 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.superuser-DEBUG: responding to pending prompt
Mar 21 17:23:41 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit._vendor.ferny.interaction_agent-DEBUG: do_askpass answer 'foobar'
Mar 21 17:23:41 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: writing to transport <cockpit.transports.StdioTransport object at 0x7f5b06801c90>
Mar 21 17:23:41 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit._vendor.ferny.interaction_agent-DEBUG: <cockpit.superuser.SuperuserRoutingRule object at 0x7f5b06d023c0> completed cleanly
Mar 21 17:23:41 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit._vendor.ferny.interaction_agent-DEBUG: _consider_completion(<cockpit._vendor.ferny.interaction_agent.InteractionAgent object at 0x7f5b06553f20>)
Mar 21 17:23:41 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit._vendor.ferny.interaction_agent-DEBUG:   but not ready yet
Mar 21 17:23:41 fedora-coreos-127-0-0-2-2301 audit[2905]: USER_AUTH pid=2905 uid=1002 auid=1002 ses=12 subj=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 msg='op=PAM:authentication grantors=pam_usertype,pam_localuser,pam_unix acct="scruffy" exe="/usr/bin/sudo">
Mar 21 17:23:41 fedora-coreos-127-0-0-2-2301 audit[2905]: USER_ACCT pid=2905 uid=1002 auid=1002 ses=12 subj=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 msg='op=PAM:accounting grantors=pam_unix,pam_localuser acct="scruffy" exe="/usr/bin/sudo" hostname=? addr=>
Mar 21 17:23:41 fedora-coreos-127-0-0-2-2301 audit[2905]: USER_CMD pid=2905 uid=1002 auid=1002 ses=12 subj=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 msg='cwd="/var/home/scruffy" cmd=636F636B7069742D627269646765202D2D70726976696C65676564 exe="/usr/bin/sudo">
Mar 21 17:23:41 fedora-coreos-127-0-0-2-2301 sudo[2905]:  scruffy : user NOT in sudoers ; PWD=/var/home/scruffy ; USER=root ; COMMAND=/usr/bin/cockpit-bridge --privileged
Mar 21 17:23:41 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit._vendor.ferny.interaction_agent-DEBUG: _got_data(b'scruffy is not in the sudoers file.\n', [])
Mar 21 17:23:41 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit._vendor.ferny.interaction_agent-DEBUG: _got_data(b'', [])
Mar 21 17:23:41 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit._vendor.ferny.interaction_agent-DEBUG: _result(<cockpit._vendor.ferny.interaction_agent.InteractionAgent object at 0x7f5b06553f20>, 'scruffy is not in the sudoers file.\n')
Mar 21 17:23:41 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit._vendor.ferny.interaction_agent-DEBUG:   remove_reader(<socket.socket fd=17, family=1, type=1, proto=0>)
Mar 21 17:23:41 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit._vendor.ferny.interaction_agent-DEBUG:   closing sockets
Mar 21 17:23:41 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit._vendor.ferny.interaction_agent-DEBUG: _consider_completion(<cockpit._vendor.ferny.interaction_agent.InteractionAgent object at 0x7f5b06553f20>)
Mar 21 17:23:41 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit._vendor.ferny.interaction_agent-DEBUG:   submitting stderr ('scruffy is not in the sudoers file.\n') to completion_future
Mar 21 17:23:41 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.transports-DEBUG: Read ready on <cockpit.transports.SubprocessTransport object at 0x7f5b065e17d0> <cockpit.superuser.SuperuserPeer object at 0x7f5b06553ef0> 21
Mar 21 17:23:41 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.transports-DEBUG:   got EOF
Mar 21 17:23:41 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.peer-DEBUG: Peer SuperuserPeer received unexpected EOF
Mar 21 17:23:41 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.transports-DEBUG: Process exited with status 1
Mar 21 17:23:41 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.peer-DEBUG: Peer SuperuserPeer exited, status 1
Mar 21 17:23:41 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.protocol-DEBUG: connection_lost
Mar 21 17:23:41 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.transports-DEBUG: won't attempt 15 to process 2905.  It exited already.
Mar 21 17:23:41 fedora-coreos-127-0-0-2-2301 ws[2270]: cockpit.peer-DEBUG: Peer SuperuserPeer connection lost <class 'cockpit.peer.PeerExited'> 1

SO HAH!

It seems that the first time we login we get a sudo lecture and this somehow fails the bridge, the second time we get no lecture and all is good.

jelly avatar Mar 21 '24 17:03 jelly

So with the sudo lecture theory, I removed all the state in /var/db/sudo/lectured/* and then can't reproduce it again. Which is rather strange but then again this is coreos.

jelly avatar Mar 21 '24 17:03 jelly

Adding a close eventlistener and when it first on first load we get close events:

log: fsinfo {}
log: close fsinfo {"isTrusted":"false","detail":"Object","type":"close","target":"null","currentTarget":"null"} {"command":"close","channel":"1:3!57"}
log: base_channel {"superuser":"try","binary":"true"}
log: fsinfo {}
log: close fsinfo {"isTrusted":"false","detail":"Object","type":"close","target":"null","currentTarget":"null"} {"command":"close","channel":"1:3!107"}
log: base_channel {"superuser":"try","binary":"true"}
log: fsinfo {}
log: close fsinfo {"isTrusted":"false","detail":"Object","type":"close","target":"null","currentTarget":"null"} {"command":"close","channel":"1:3!155"}
log: base_channel {"superuser":"try","binary":"true"}
log: fsinfo {}
log: close fsinfo {"isTrusted":"false","detail":"Object","type":"close","target":"null","currentTarget":"null"} {"command":"close","channel":"1:3!160"}
log: base_channel {"superuser":"try","binary":"true"}
log: fsinfo {}
log: close fsinfo {"isTrusted":"false","detail":"Object","type":"close","target":"null","currentTarget":"null"} {"command":"close","channel":"1:3!167"}
log: base_channel {"superuser":"try","binary":"true"}
log: fsinfo {}
log: close fsinfo {"isTrusted":"false","detail":"Object","type":"close","target":"null","currentTarget":"null"} {"command":"close","channel":"1:3!217"}
log: base_channel {"superuser":"try","binary":"true"}
log: fsinfo {}

On refresh we get zero close events.

jelly avatar Mar 22 '24 12:03 jelly

I think I'd like to see a new test for anything that uses this. The expiry test is an obvious choice since it's already causing us all this trouble... The test should establish the watch when logged in as the superuser and then de-authenticate. That will break the watch, which ought to be reestablished at that point.

This will involve implementing handling of the channel closing unexpectedly.

allisonkarlitskaya avatar Apr 04 '24 14:04 allisonkarlitskaya

I think I'd like to see a new test for anything that uses this. The expiry test is an obvious choice since it's already causing us all this trouble... The test should establish the watch when logged in as the superuser and then de-authenticate. That will break the watch, which ought to be reestablished at that point.

This will involve implementing handling of the channel closing unexpectedly.

This feels like new behavior to me, I can imagine we should do this but this feels like (another) follow up.

jelly avatar Apr 04 '24 14:04 jelly 

warning: Command failed: cmd: "/usr/sbin/xfs_db" "-x" "-c uuid e16b0578-8b0e-4847-ba8c-54b80b78cbbc" "/dev/dm-5", exit reason: 1 stdout: Clearing log and setting UUID
 stderr: xfs_db: libxfs_device_zero write failed: Input/output error


Traceback (most recent call last):
  File "/source/bots/machine/machine_core/ssh_connection.py", line 327, in execute
    res = subprocess.run(command_line,
          ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib64/python3.12/subprocess.py", line 571, in run
    raise CalledProcessError(retcode, process.args,
subprocess.CalledProcessError: Command '('env', '-u', 'LANGUAGE', 'LC_ALL=C', 'ssh', '-p', '22', '-o', 'BatchMode=yes', '-o', 'IdentitiesOnly=yes', '-o', 'PKCS11Provider=none', '-o', 'StrictHostKeyChecking=no', '-o', 'UserKnownHostsFile=/dev/null', '-o', 'LogLevel=ERROR', '-l', 'root', '-o', 'ControlPath=/tmp/.cockpit-test-resources/ssh-%h-%p-%r-3637', '10.88.0.1', 'set -e;', "stratis report | jq -r '.pools[] | .name' |xargs -n1 --no-run-if-empty stratis pool stop --name")' returned non-zero exit status 123.

rawhide broke itself

Traceback (most recent call last):
  File "/source/test/check-application", line 365, in testSorting
    self.enter_files()
  File "/source/test/check-application", line 33, in enter_files
    self.login_and_go("/files")
  File "/source/test/common/testlib.py", line 1742, in login_and_go
    self.browser.login_and_go(path, user=user, host=host, superuser=superuser, urlroot=urlroot, tls=tls)
  File "/source/test/common/testlib.py", line 841, in login_and_go
    self.open(href, tls=tls)
  File "/source/test/common/testlib.py", line 268, in open
    self.cdp.invoke("Page.navigate", url="about:blank")
  File "/source/test/common/cdp.py", line 243, in invoke
    res = self.command("client.pageLoadPromise")
          ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/source/test/common/cdp.py", line 272, in command
    raise RuntimeError(res["error"])
RuntimeError: {"exceptionId":0,"text":"Error: Minified React error #299; visit https://reactjs.org/docs/error-decoder.html?invariant=299 for the full message or use the non-minified dev environment for full errors and additional helpful warnings.","lineNumber":7,"columnNumber":55769,"url":"http://10.88.0.1:9090/cockpit/@localhost/files/index.js","stackTrace":{"callFrames":[{"functionName":"Py</Jt.createRoot","scriptId":"192","url":"http://10.88.0.1:9090/cockpit/@localhost/files/index.js","lineNumber":7,"columnNumber":55769},{"functionName":null,"scriptId":"192","url":"http://10.88.0.1:9090/cockpit/@localhost/files/index.js","lineNumber":18,"columnNumber":39986},{"functionName":null,"scriptId":"192","url":"http://10.88.0.1:9090/cockpit/@localhost/files/index.js","lineNumber":18,"columnNumber":39922},{"functionName":null,"scriptId":"192","url":"http://10.88.0.1:9090/cockpit/@localhost/files/index.js","lineNumber":18,"columnNumber":40065}]},"executionContextId":10}

# Result testSorting (__main__.TestFiles.testSorting) failed

jelly avatar Jun 25 '24 17:06 jelly

I would like to merge this after a release, it sounds nice to have this tested for 2 weeks first.

jelly avatar Jun 26 '24 07:06 jelly

Wow, I've never seen that failure -- is that real? Retrying for comparison.

martinpitt avatar Jun 26 '24 07:06 martinpitt

Wow, I've never seen that failure -- is that real? Retrying for comparison.

Oh, I missed that one uhh that looks "interesting".

jelly avatar Jun 26 '24 07:06 jelly