Request: documentation on zellij logging system

[AutumnMeowMeow]

https://zellij.dev/documentation/ , README.md, and docs/ provide no information on the zellij logger. I had to dig through open issues and the discussions on #592 and #1410 to even know to look inside /tmp for the log files.

It would be really nice to know:

• Where logs are generated by default.
• How to change the log location.
• How to control log rotation frequency.
• Which logs can safely be deleted/truncated ("cat /dev/null > logfile") while zellij is running.
• How to suppress the incoming bytes log file. (It's big, and I could see some people only wanting events and not their full input recorded onto disk.)
  How to debug specific parts of zellij:
  • Opening/closing/resizing windows/panes/shells (size and placement).
  • Launching/closing programs/shells (the actual spawned command line).
  • Attach/detach sessions, and whether a server is still running and on what PID.
  • Change in window size (e.g. SIGWINCH received), commands to resize terminal/shell windows (e.g. ioctl(TIOCSWINSZ))
  • The VT parser state, and when a sequence has come in that is unrecognized. (This is what I really want most -- zellij is hanging on more recent vttests, and also not responding to any-event mouse events.)

(Plus congrats on the latest release! 💗)

[imsnif]

Hey @AutumnMeowMeow - I hope you don't mind that I edited the issue to add checkboxes so we can track this.

First, thanks for bringing this up. This is one of those "lore" parts that have been passed by way of our chat servers and one-on-ones. So I'm happy to have it documented.

To start with, I just merged #1627 to kick this off. I'm added them in CONTRIBUTING.md, because there currently lie our "zellij developer" facing docs.

Otherwise, about some of the other points I'd like to consult you:

Which logs can safely be deleted/truncated ("cat /dev/null > logfile") while zellij is running.

To the best of my knowledge, this is a problem we don't have. I did some rudimentary testing and there is no issue with this. Am I missing something?

How to suppress the incoming bytes log file. (It's big, and I could see some people only wanting events and not their full input recorded onto disk.)

This sounds like a very useful feature, but one that we currently don't have. Most of the work on our VT parsing has up until now been done by yours truly, and like any lone developer I have my ways in this regard. Mostly, I go to the various callbacks (eg. here: https://github.com/zellij-org/zellij/blob/main/zellij-server/src/panes/grid.rs#L1947) and stick a log::info as needed.

I don't think this is a good way to go about it though, and would be happy to add some convenience methods here. Do you have any specific suggestions? What would be the most comfortable for you?

How to debug specific parts of zellij:

We usually mostly do these by running a Zellij instance and performing the desired action. This might be a blind-spot for me though - so could you describe what you'd like to see here?

The VT parser state, and when a sequence has come in that is unrecognized. (This is what I really want most -- zellij is hanging on more recent vttests, and also not responding to any-event mouse events.)

Hum - sad to hear about the more recent vttests! Would be happy to get to the bottom of this ASAP. Your help, if you'd like to work on this, would be greatly appreciated!

What sort of debugging experience would you like here? Right now we can debug-print the Grid (eg. with log::info), which gives you the state of the viewport without styling. Would adding the various pieces of state we keep (eg. these https://github.com/zellij-org/zellij/blob/main/zellij-server/src/panes/grid.rs#L303-L345) be helpful?

(Plus congrats on the latest release! heartpulse)

Thanks!

[AutumnMeowMeow]

Hey @AutumnMeowMeow - I hope you don't mind that I edited the issue to add checkboxes so we can track this.

👍

To start with, I just merged #1627 to kick this off. I'm added them in CONTRIBUTING.md, because there currently lie our "zellij developer" facing docs.

Thank you!

Which logs can safely be deleted/truncated ("cat /dev/null > logfile") while zellij is running.

To the best of my knowledge, this is a problem we don't have. I did some rudimentary testing and there is no issue with this. Am I missing something?

I have not run across an issue, it is just nice to know. I've seen other issues here where people are complaining of very large logs when they have a long-running zellij process, they might be happy to hear that they can cull those anytime they want without risking their sessions.

How to suppress the incoming bytes log file. (It's big, and I could see some people only wanting events and not their full input recorded onto disk.)

This sounds like a very useful feature, but one that we currently don't have. Most of the work on our VT parsing has up until now been done by yours truly, and like any lone developer I have my ways in this regard. Mostly, I go to the various callbacks (eg. here: https://github.com/zellij-org/zellij/blob/main/zellij-server/src/panes/grid.rs#L1947) and stick a log::info as needed.

Thank you, this is a very handy pointer! So having looked at it, I've got some bugs in mouse handling to reported. (That explains why jexer was unhappy with it, I figured it would be a small thing.)

I don't think this is a good way to go about it though, and would be happy to add some convenience methods here. Do you have any specific suggestions? What would be the most comfortable for you?

It looks like this is partially implemented already with zellij here:

        } else {
            log::warn!("Unhandled csi: {}->{:?}", c, params);
        }
    }

Being able to see what falls through the unhandled cases for esc_dispatch(), csi_dispatch(), and osc_dispatch() would go a long way.

As an example for wezterm, going through the vttests it doesn't recognize it logs this:

 2022-08-03T18:41:36.038Z WARN  wezterm_term::terminalstate    > unhandled DecPrivateMode SetDecPrivateMode(Unspecified(40))
 2022-08-03T18:42:13.814Z WARN  wezterm_term::terminalstate    > unhandled TabulationClear ClearLineTabStopAtActiveLine
 2022-08-03T18:42:13.814Z WARN  wezterm_term::terminalstate    > unhandled TabulationClear ClearCharacterTabStopsAtActiveLine
 2022-08-03T18:42:39.740Z WARN  wezterm_term::terminalstate    > unhandled DecPrivateMode ResetDecPrivateMode(Unspecified(42))
 2022-08-03T18:42:39.740Z WARN  wezterm_term::terminalstate::performer > ESC: unhandled Unspecified { intermediate: Some(45), control: 65 }
 2022-08-03T18:42:39.740Z WARN  wezterm_term::terminalstate::performer > ESC: unhandled Unspecified { intermediate: Some(46), control: 65 }
 2022-08-03T18:42:39.740Z WARN  wezterm_term::terminalstate::performer > ESC: unhandled Unspecified { intermediate: Some(47), control: 65 }

...which makes it pretty easy to see what's going on.

How to debug specific parts of zellij:

We usually mostly do these by running a Zellij instance and performing the desired action. This might be a blind-spot for me though - so could you describe what you'd like to see here?

I'm thinking of pointers for using log4rs to turn on debugging of just some bits. Are there names for subsystems, or different loggers that do particular things? If there's only one logger, and it's enabled by --debug, then don't bother making any further work here.

(For Jexer, I had a specific requirement to never write to disk, so I didn't put in a real logging infrastructure, I just had a popup window to show exception stacktraces. But inside the code at a couple major spots one could flip a DEBUG flag, recompile, and then get stuff emitted to stderr. The major spots for me were the event routing (keyboard/mouse bytes --> event --> widget it goes to), encoding to the terminal on the outside, and parsing the VT sequences for the terminal windows on the inside.)

Hum - sad to hear about the more recent vttests! Would be happy to get to the bottom of this ASAP. Your help, if you'd like to work on this, would be greatly appreciated!

I could! The vttests themselves are mostly OK, it just hangs immediately on running vttest until you press enter. I suspect there is a terminal report vttest is looking for that zellij isn't responding to.

(vttest is always a moving target. Every couple years I have to go back and see what else I need to update... :) )

What sort of debugging experience would you like here? Right now we can debug-print the Grid (eg. with log::info), which gives you the state of the viewport without styling. Would adding the various pieces of state we keep (eg. these https://github.com/zellij-org/zellij/blob/main/zellij-server/src/panes/grid.rs#L303-L345) be helpful?

I think the major state changes logged to debug would be great, eventually. For now, just adding the unhandled ESC and OSC sequences to debug would go a long way.

The absolute extreme end would be noting all of the state changes while processing. I did that here in qodem -- search for all the DLOG's, it's slightly insane. :) I don't think anyone will need that.

[imsnif]

I have not run across an issue, it is just nice to know. I've seen other issues here where people are complaining of very large logs when they have a long-running zellij process, they might be happy to hear that they can cull those anytime they want without risking their sessions.

That's a good point - but we recently introduced log rotation and a truncating strategy so I think these sorts of issues are already behind us.

It looks like this is partially implemented already with zellij here:

        } else {
            log::warn!("Unhandled csi: {}->{:?}", c, params);
        }
    }

Being able to see what falls through the unhandled cases for esc_dispatch(), csi_dispatch(), and osc_dispatch() would go a long way.

Implemented and merged in #1636 - thanks!

I'm thinking of pointers for using log4rs to turn on debugging of just some bits. Are there names for subsystems, or different loggers that do particular things? If there's only one logger, and it's enabled by --debug, then don't bother making any further work here.

The --debug flag is only used to dump the pty bytes to a file for each pane. The global logger is always enabled.

I could! The vttests themselves are mostly OK, it just hangs immediately on running vttest until you press enter. I suspect there is a terminal report vttest is looking for that zellij isn't responding to.

Hum, I seem to remember seeing that and taking care of it. Maybe some sort of regression or some new test? If you'd like to take a look at it, that would be grand!

I think the major state changes logged to debug would be great, eventually. For now, just adding the unhandled ESC and OSC sequences to debug would go a long way.

The absolute extreme end would be noting all of the state changes while processing. I did that here in qodem -- search for all the DLOG's, it's slightly insane. :) I don't think anyone will need that.

Oh dear! My browser search counts 240 of them :)

[imsnif]

So @AutumnMeowMeow - looking back through the issue I think we're not left with much, right? After the discussion, is there anything else you're missing and would like added to improve the dev experience here?

[AutumnMeowMeow]

I think we're good. :) Thank you!