Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Feature: more/better logging for greeter.py, and more reliability #369

Closed
wants to merge 7 commits into from
Closed

Feature: more/better logging for greeter.py, and more reliability #369

Changes from all commits
Commits
Show all changes
7 commits
Select commit Hold shift + click to select a range
a293daf
easier debugging for session logic
crabdancing Jun 12, 2024
f7274a5
still cant tell whats wrong
crabdancing Jun 12, 2024
a8cbe01
maybe this?
crabdancing Jun 12, 2024
e200042
take a crack at fixing the bug
crabdancing Jun 12, 2024
57c2ed4
capitalize Wayland
crabdancing Jun 12, 2024
2007526
log XDG_DATA_DIRS
crabdancing Jun 12, 2024
2e1cca9
even more logging
crabdancing Jun 12, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
17 changes: 16 additions & 1 deletion pkgs/jovian-greeter/greeter.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -87,6 +87,9 @@ def create_session(self, username: str):
def start_session(self, command: List[str], environment: List[str]):
try:
subprocess.check_call(["plymouth", "quit", "--retain-splash", "--wait"])
except FileNotFoundError:
logging.debug("Failed to stop Plymouth: could not find executable")
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

That's not going to work, the greeter is always wrapped with the Plymouth executable.

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

You told me on Matrix that the error is benign. Did I misunderstand something?

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The error is indeed benign, but FileNotFoundError will never actually trigger here.

logging.debug("If you are not using Plymouth, this failure is benign and expected")
except Exception as ex:
logging.debug("Failed to stop Plymouth", exc_info=ex)

Expand Down Expand Up @@ -122,11 +125,15 @@ def _recv(self) -> Mapping[str, Any]:
class Context:
def __init__(self, user: str, home: Path):
self.user = user
logging.debug("USER: {}".format(self.user))
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is probably unnecessary, you can inspect the environment via /proc or systemd or any other tool.

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Unless the script is dying after ~100ms. ;)

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

In that case you should probably have a stacktrace?

Copy link
Author

@crabdancing crabdancing Jun 15, 2024 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Not if it exited with exit(1) due to misconfiguration. And even if you do, the stack trace won't always tell you what you need to know in my experience.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Then the problem is that the script is doing sys.exit(1) without providing adequate information.

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

No, because again, the stack trace won't always give you what you need -- unless your plan is to catch every exception in the entire program and then do your conditional dump.

The point of the logging system is usually to be as verbose as you could possibly need, and then quiet it by setting the log level higher than DEBUG/TRACE. Usually on WARN or something. Then provide a way to override the debug level if something goes wrong. Since this is a daemon configured by a Nix expression, maybe have the nix expression control a flag that in turn sets the debug level, if you're worried about cluttering up logs?

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Not to say that exiting with more information isn't a good idea, but dumping the entire execution context only iff the program exits is usually not done because there's a gradual accumulation of state information you need to dump as programs grow in size and complexity. Although this is a trivial Python script, I still think it would make sense to follow that pattern on account of the fact that Python is not a correctness-oriented language and whatever debugging mechanism you supply needs to account for it failing somewhere along the execution chain in a way you didn't expect.

Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

when logging variables in python, best practice is to use % interpolation.

Suggested change
logging.debug("USER: {}".format(self.user))
logging.debug("USER: %s", self.user)

see: https://docs.python.org/3/howto/logging.html#logging-variable-data

self.home = home
logging.debug("HOME: {}".format(self.home))
self.xdg_data_dirs = os.environ.get('XDG_DATA_DIRS', '').split(':')
logging.debug("XDG_DATA_DIRS: {}".format(self.xdg_data_dirs))

def next_session(self) -> Optional[Session]:
sessions = [ DEFAULT_SESSION ]
logging.debug("Sessions: {}".format(sessions))

if next_session := self._consume_session():
sessions = [ next_session ] + sessions
Expand All @@ -137,6 +144,7 @@ def _consume_session(self) -> Optional[str]:
helper = HELPER_PREFIX.joinpath('consume-session')
if helper.exists():
logging.debug('Using pkexec helper')
logging.debug('Helper path: {}'.format(helper))
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This should be static.

res = subprocess.run(
['/run/wrappers/bin/pkexec', helper, self.user],
stdin=subprocess.DEVNULL,
Expand All @@ -145,6 +153,10 @@ def _consume_session(self) -> Optional[str]:
env={'SHELL': '/bin/sh'}
)
next_session = res.stdout.decode('utf-8').strip()
stderr = res.stderr.decode('utf-8').strip()
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Does consume-session ever log to stderr?

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Not deliberately, but the commands it run might fail, and those commands do log to STDERR. In addition, it's generally a good idea to future-proof this sort of thing anyway IMO.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Actually, we should probably use stdout=PIPE instead of capture_output. That way stderr will automatically end up in the journal.

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

That's fair enough! I think that would work nicely :)

if stderr == "":
stderr = "<no STDERR found>"
logging.debug('STDERR for `consume-session`: {}'.format(stderr))

if not next_session:
return None
Expand All @@ -166,16 +178,19 @@ def _consume_session(self) -> Optional[str]:
return next_session

def _find_sessions(self, sessions: Iterable[str]) -> Optional[Session]:
for data_dir in self.xdg_data_dirs + [ '/usr/share' ]:
for data_dir in self.xdg_data_dirs + [ '/usr/share', '/run/current-system/sw/share' ]:
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

/run/current-system/sw/share should generally always be on XDG_DATA_DIRS, and if it isn't, we should figure out why.

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Hmm. It seems in the path by the time I get to the shell or UI, so it's most likely that the environment greeter.py is running in has something wrong with it. Is the concern here that the path might change?

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The concern is that this is unnecessary, and in a year we won't remember why we put it there.

data_dir = Path(data_dir)
for session in sessions:
logging.debug("Examining session: {}".format(session))
desktop_file = f'{session}.desktop'
wayland_session = data_dir.joinpath('wayland-sessions').joinpath(desktop_file)
x_session = data_dir.joinpath('xsessions').joinpath(desktop_file)

logging.debug("Checking Wayland session path: {}".format(wayland_session))
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'd rather just log on error here, i.e. if session does not exist, log that at WARNING (or even ERROR).

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The Wayland session path that it found is useful information for debugging, tho. It's generally a good idea to log I/O paths as TRACE or DEBUG IMO -- as the moment your program is touching other programs/file structures, making the interface points clear can make a lot of confusing errors more obvious.

If you're worried about cluttering up the log files, maybe it shouldn't default at log level DEBuG?

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I don't think it's particularly useful in 99.9% of cases.

if wayland_session.exists():
return WaylandSession(session, wayland_session)

logging.debug("Checking X session path: {}".format(x_session))
if x_session.exists():
return XSession(session, x_session)

Expand Down