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

crabdancing · 2024-06-12T20:30:02Z

Changes:

More logs (in the interest of debugging misconfigurations & other issues -- it prints environment variable context, specific paths being checked during early business logic, etc)
Explicitly checks under /run/current-system/sw/share/ for xsessions and wayland-sessions.
Replace the scary-looking tracelog dump for plymouth executable being missing with a specific, concise error message that explicitly indicates it is not a serious failure mode. (I saw some confusion surrounding this issue.)

Closes #368

K900 · 2024-06-15T06:56:32Z

pkgs/jovian-greeter/greeter.py

@@ -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")


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

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

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

K900 · 2024-06-15T06:56:52Z

pkgs/jovian-greeter/greeter.py

@@ -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))


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

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

In that case you should probably have a stacktrace?

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.

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

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?

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.

K900 · 2024-06-15T06:57:06Z

pkgs/jovian-greeter/greeter.py

@@ -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))


This should be static.

K900 · 2024-06-15T06:57:23Z

pkgs/jovian-greeter/greeter.py

@@ -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()


Does consume-session ever log to stderr?

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.

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

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

K900 · 2024-06-15T06:57:51Z

pkgs/jovian-greeter/greeter.py

@@ -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' ]:


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

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?

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

K900 · 2024-06-15T06:58:16Z

pkgs/jovian-greeter/greeter.py

 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))


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

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?

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

crabdancing · 2024-06-15T20:31:00Z

IDK, I think it's pretty clear @K900 is not very interested in improved logging, and I'm running out of time that I could be spending on my actual work, so I'mma just peace out and maintain my own fork. Best of luck, peeps.

twoolie · 2024-09-10T06:51:50Z

pkgs/jovian-greeter/greeter.py

@@ -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))


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

crabdancing added 7 commits June 12, 2024 11:46

easier debugging for session logic

a293daf

still cant tell whats wrong

f7274a5

maybe this?

a8cbe01

take a crack at fixing the bug

e200042

capitalize Wayland

57c2ed4

log XDG_DATA_DIRS

2007526

even more logging

2e1cca9

K900 reviewed Jun 15, 2024

View reviewed changes

twoolie reviewed Sep 10, 2024

View reviewed changes

crabdancing closed this Sep 10, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

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

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

crabdancing commented Jun 12, 2024

K900 Jun 15, 2024

crabdancing Jun 15, 2024

K900 Jun 15, 2024

K900 Jun 15, 2024

crabdancing Jun 15, 2024

K900 Jun 15, 2024

crabdancing Jun 15, 2024 •

edited

Loading

K900 Jun 15, 2024

crabdancing Jun 15, 2024

crabdancing Jun 15, 2024

K900 Jun 15, 2024

K900 Jun 15, 2024

crabdancing Jun 15, 2024

K900 Jun 15, 2024

crabdancing Jun 15, 2024

K900 Jun 15, 2024

crabdancing Jun 15, 2024

K900 Jun 15, 2024

K900 Jun 15, 2024

crabdancing Jun 15, 2024

K900 Jun 15, 2024

crabdancing commented Jun 15, 2024

twoolie Sep 10, 2024

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

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

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

Conversation

crabdancing commented Jun 12, 2024

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

crabdancing Jun 15, 2024 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

crabdancing commented Jun 15, 2024

Choose a reason for hiding this comment

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

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

crabdancing Jun 15, 2024 •

edited

Loading