Log2file #293

jankatins · 2016-04-10T20:15:58Z

This is mainly a byproduct of IRkernel/repr#21, where I wanted to see where the wrong chars come from and needed to log to a file.

jankatins · 2016-04-10T20:16:47Z

This should get a better default location for the log, but for that I would need to know where to put logfiles... @takluyver Is there some "default location", where all kernels should log to? the ipykernel still uses the old ipython profile support, so that is not gonna work for us...

jankatins · 2016-04-10T20:17:53Z

R/logging.r

@@ -7,19 +7,53 @@
 stderror <- stderr()

 log_debug <- function(...) {
-    if (getOption('jupyter.log_level') >= 3L) {
-        cat('DEBUG: ', sprintf(...), '\n', sep = '', file = stderror)
+    if (isTRUE(getOption('jupyter.log_level') >= 3L)) {


Is added isTRUE to guard against the case where a user removes an option...

flying-sheep · 2016-04-11T08:33:32Z

i’d prefer to use jupyter.logfile and test if (!is.null(getOption('jupyter.logfile'))). it has exactly the same amout of information as using two options.

flying-sheep · 2016-04-11T08:38:31Z

R/logging.r

-        cat('DEBUG: ', sprintf(...), '\n', sep = '', file = stderror)
+    if (isTRUE(getOption('jupyter.log_level') >= 3L)) {
+        log_msg_stderror('DEBUG', sprintf(...))
+        log_msg_logfile('DEBUG', sprintf(...))


i’d design it like this:

log_debug <- function(...) { if (isTRUE(getOption('jupyter.log_level') >= 3L)) { log_msg('DEBUG', sprintf(...)) } } log_msg <- function(lvl, msg) { log_msg_stderror(lvl, msg) if (isTRUE(getOption('jupyter.log_to_file'))) { log_msg_logfile(lvl, msg) } } log_msg_stderror <- ... log_msg_logfile <- ... #without the if()

tried that, but then wanted to send the filename to the normal log and didn't want to get into recursion and so split both calls...

eh, you can still use the individual ones, i just wrapped them into log_msg.

Ok, no I got it.... Update is on the way...

flying-sheep · 2016-04-11T08:44:03Z

all those design considerations nonwithstanding, i’m actually against enhancing our logging, and for switching to a dedicated logging system.

playing together with other things that log is important
this is too complex and too different a concern to manage inside of the repo
we get too many logging-related config options that whould be rather global

obviously all of this helps with debugging, but i don’t want us to live in our own NIH-fueled wheel-reinventing bubble.

we obviously need a solution that has per-package logging so that we can debug only the kernel without seeing all the crap packages log.

@JanSchulz are you OK with closing this and deciding on a dedicated solution in #119 this week?

jankatins · 2016-04-11T09:18:59Z

I'm not so sure: I agree that we should go to a proper lib, but unless someone does that, it would be nice to have a way to get properly encoded logs from the kernel (the log in the notebook windows is garbled wrt unicode... :-()

jankatins · 2016-04-11T09:20:17Z

i’d prefer to use jupyter.logfile and test if (!is.null(getOption('jupyter.logfile'))). it has exactly the same amout of information as using two options.

ok, sounds reasonable...

jankatins · 2016-04-11T09:21:05Z

Whatever we do merge the log_to_file part: the other commit of adding more logging calls in the real code should be merged...

jankatins · 2016-04-11T10:43:54Z

ok, sounds reasonable...

Ok, I take that back: IMO it should be "enable it and get a logfile wherever jupyter logs to, too". But that's probably better done in a later version...

flying-sheep · 2016-04-11T10:51:55Z

Ok, I take that back: IMO it should be "enable it and get a logfile wherever jupyter logs to, too". But that's probably better done in a later version...

i don’t get it.

my semantics for a single log file option would optimally be:

if NULL, don’t log to a file
if a character vector, log to (each of the) file(s) specified
if something else, throw an error

but the above behavior is for IRkernel, not our logging system.

a proper logging system should allow registering arbitrarily many loggers: to files, to databases, to, stderr, …

jankatins · 2016-04-11T11:14:38Z

My semantics are based on the one in ipython: if you enable logging in the ipyparallel engines, AFAIK it logs to %USERPROFILE%\.ipython\profile_default\log. Not sure how you let the notebook log to a file (probably not at all yet). Julia also seem to only log to stdout.

My preferences would be to log to %USERPROFILE%\.jupyter\log\[irkernel\]irkernel_*.log...

flying-sheep · 2016-04-11T12:44:28Z

hmm, OK. i think jupyter specific logging options won’t hurt. bonus points if we can configure the future real logging system according to them.

about the paths, you should check jupyter --help or jupyter --paths:

jupyter --runtime-dir is sth. like /run/user/1000/jupyter
jupyter --config-dir is (currently/per default) ~/.jupyter
jupyter --data-dir is $XDG_DATA_DIR/jupyter aka ~/.local/share/jupyter

so if anything of those, the last one should be used. the first one isn’t available after kernel shutdown, and the second one is the config dir, not “all kinds of stuff dir”

Enable logging to a file via ``` options(jupyter.log_level = 3) # log debug options(jupyter.log_to_file = TRUE) # log to file options(jupyter.logfile = 'irkernel.log') # default, relative to current dir! ``` The default log is 'irkernel.log' in the current directory. This probably should change, but I haven't yet looked where the other kernels log to...

jankatins · 2016-04-11T13:17:36Z

Checking this is not gonna work: You don't need to have jupyter stuff in path (e.g. only installed in a conda environment)...

flying-sheep · 2016-04-11T15:41:26Z

well, then there’s no possible way to deduce the correct jupyter directory.

but you know what: the correct system log directory is

/var/log/irkernel/ on linux and OSX, and
%ProgramData%\IRkernel\logs\ on windows

the correct user log dir is

${XDG_CACHE_HOME-$HOME/.cache}/irkernel/logs/ on linux
%ProgramData%\Roaming\IRkernel\logs\ on windows, and
~/Library/Logs/IRkernel/ on OSX.

if you want we can provide a function:

get_log_dir() {
    logfile <- getOption('jupyter.logfile')
    if (is.null(logfile) || identical(logfile, FALSE)) {
        NULL
    } else if (is.character(logfile)) {
        logfile
    } else if (isTRUE(logfile)) {
        # logic to get OS specific log dir
    } else stop(sprintf('Option %s of unknown type %s instead of logical, character, or NULL', sQuote('jupyter.logfile'), class(logfile)))
}

jankatins · 2016-04-13T22:17:15Z

@takluyver Do you know of any recommendation for kernels where to place logfiles?

flying-sheep · 2016-04-14T09:59:30Z

the above are OS-level recommendations on where everything should put logfiles.

takluyver · 2016-04-14T12:06:15Z

Sorry for the delay on this. At the dev meeting, we did get some time to discuss our 'kernel nanny' plan, which will include opt-in OS-level output capturing. As part of that, the kernel will get an environment variable with a path it can log into for debugging the kernel itself. Where this goes will be up to the server - it might be written to a log file, or it might be sent straight to the terminal where you started the notebook server (the ipython kernel already logs to the terminal).

Now we just need to implement that proposal! ;-)

flying-sheep · 2016-04-14T13:01:26Z

hmm, so the logging config is on the server side… and the env variable points to a FIFO read by the server or what?

takluyver · 2016-04-14T13:08:11Z

We haven't decided where we'll send logs yet, and it will probably be configurable on the server side. The idea is that the env var points to something that the kernel can open() and write to, and the kernel shouldn't need to worry about exactly what that is. It could be a regular file, a FIFO, or even a reference to the tty the notebook server is running in, on platforms where that's doable.

flying-sheep · 2016-04-14T14:57:39Z

sounds nice!

jankatins · 2016-04-14T15:34:06Z

@takluyver Any issues I can subscribe to, to follow along?

jankatins · 2016-04-14T15:35:21Z

So, after hearing this, my vote goes to merging this as is and then change/remove stuff in the next iteration, if that's needed..

takluyver · 2016-04-14T15:56:53Z

There's not currently any issue or anything about this, but I'll try to remember to keep you posted about it.

flying-sheep · 2016-04-15T07:07:27Z

R/options.r

@@ -12,6 +12,7 @@ getenv_default <- function(varname, default) {
 #' @export
 jupyter_option_defaults <- list(
    jupyter.log_level = as.integer(getenv_default('JUPYTER_LOG_LEVEL', 1L)),
+    jupyter.logfile = getenv_default('JUPYTER_LOGFILE'),


won’t this say “missing argument, no default”?

maybe we should change the definition of getenv_default to function(varname, default = NULL)?

flying-sheep · 2016-04-15T07:11:45Z

So, after hearing this, my vote goes to merging this as is and then change/remove stuff in the next iteration, if that's needed..

yeah, that’s good!

we can always change the jupyter.logfile to have more possible values than an explicit file path or NULL (add TRUE to mean “jupyter’s location”)

flying-sheep · 2016-04-15T07:17:17Z

OK, outstanding points:

extract send_error_msg and is_silent (or so)
does getenv_default have to be fixed for your usage of it?
some remaining ){ after functions and some "s

jankatins · 2016-04-15T19:15:18Z

I fixed the style fixes and the default value.

extract send_error_msg and is_silent (or so)

You mean as additional class methods? I still don't get how these functions would have access to the request context.

flying-sheep · 2016-04-16T14:05:40Z

not at all:

    is_silent = function(request) request$content$silent,
    send_error_msg = function(request, msg) {
        if (!is_silent(request)) return()
        ...
    },

maybe we can come up with something better at another time, but this is better than inline

jankatins · 2016-04-18T09:40:53Z

So, what is worse: redefining all functions on each request or doing two object lookups for each if (!is_silent(request)) ...? Probably the function definitions?

-> Will refactor...

flying-sheep · 2016-04-18T10:38:19Z

you mean performance-wise? i don’t care, none of the alternatives should carry any weight. also making performance arguments before measuring is really thin ice to tread on.

the point is to put as much declarative code as possible to keep the imperative part small (don’t define functions at runtime if not necessary; don’t put too much spaghetti code into one function)

THIS is Executor$execute. functions shouldn’t be 222 lines long. they shouldn’t have a bunch of inline-defined functions that access variables from the outer function’s scope*. (R is copy-on-write so that’s no performance problem)

so yes, thanks for the last refactor!

*things like Map/Reduce/apply, … are OK if they’re small, but we really do unreasonable things here. my way of attaching quit/q is also not great, as it could probably be done statically

Make the execute methods smaller by removing some function definition from the method and putting them into their own methods in the executer object.

jankatins · 2016-04-18T14:39:27Z

So, promoted these two functions to methods...

jankatins · 2016-04-18T16:21:15Z

Big refactoring of execute incoming...

Executor.execute() was a long method which declared a lot of inline functions so that these functions had access of the current request. This commit adds a `current_request` field and moves the inline functions to executer methods which uses this field. This makes the execute method much shorter.

jankatins · 2016-04-18T16:53:01Z

Ok, this has now a much shorter Executer$execute() method... @flying-sheep Please have a look, this is my first work with the such ref classes and it took a few rounds until I had it working...

ref classes are weird: you can call functions by name, but to pass function objects, you have to specify them with .self$function. Took me several rounds to find all cases where that was needed...

jankatins · 2016-04-18T16:53:55Z

If this is too high risk, it would be good to get everything up to 75aea9d merged. I can then add another PR just for the refactoring...

flying-sheep · 2016-04-19T07:52:38Z

wow cool, this is really great!

i actually just wanted you to not add to the pile but instead you fixed it 😆

i’ll test it right away

flying-sheep · 2016-04-19T08:09:43Z

works great thanks!

i only found out that my getenv_default stuff doesn’t work (apparently it’s executed on package build time or something)

i’ll merge and fix this.

flying-sheep · 2016-04-19T08:56:21Z

ok, done: b11f259

Add more debug logging

ad8e7db

jankatins reviewed Apr 10, 2016
View reviewed changes

jankatins mentioned this pull request Apr 10, 2016

broken unicode uses <U+884C> which needs to be escaped IRkernel/repr#21

Open

flying-sheep reviewed Apr 11, 2016
View reviewed changes

jankatins force-pushed the log2file branch from 60c0c34 to d5f43f2 Compare April 11, 2016 13:00

Refactor sending an error message

5390b93

flying-sheep reviewed Apr 15, 2016
View reviewed changes

jankatins added 2 commits April 15, 2016 21:00

Fix default options for jupyter.logfile

37db6e3

Add more debugging output

d426422

jankatins force-pushed the log2file branch from 2aa2a33 to d426422 Compare April 15, 2016 19:01

PEP8 -aehm- flyingsheep fixes :-)

75aea9d

Refactor: promote some functions

02aae2c

Make the execute methods smaller by removing some function definition from the method and putting them into their own methods in the executer object.

flying-sheep merged commit e1ece75 into IRkernel:master Apr 19, 2016

Log2file #293

Log2file #293

Conversation

jankatins commented Apr 10, 2016

jankatins commented Apr 10, 2016

jankatins Apr 10, 2016

Choose a reason for hiding this comment

flying-sheep commented Apr 11, 2016

flying-sheep Apr 11, 2016

Choose a reason for hiding this comment

jankatins Apr 11, 2016

Choose a reason for hiding this comment

flying-sheep Apr 11, 2016

Choose a reason for hiding this comment

jankatins Apr 11, 2016

Choose a reason for hiding this comment

flying-sheep commented Apr 11, 2016

jankatins commented Apr 11, 2016

jankatins commented Apr 11, 2016

jankatins commented Apr 11, 2016

jankatins commented Apr 11, 2016

flying-sheep commented Apr 11, 2016

jankatins commented Apr 11, 2016

flying-sheep commented Apr 11, 2016

jankatins commented Apr 11, 2016

flying-sheep commented Apr 11, 2016

jankatins commented Apr 13, 2016

flying-sheep commented Apr 14, 2016

takluyver commented Apr 14, 2016

flying-sheep commented Apr 14, 2016

takluyver commented Apr 14, 2016

flying-sheep commented Apr 14, 2016

jankatins commented Apr 14, 2016

jankatins commented Apr 14, 2016

takluyver commented Apr 14, 2016

flying-sheep Apr 15, 2016

Choose a reason for hiding this comment

flying-sheep commented Apr 15, 2016

flying-sheep commented Apr 15, 2016

jankatins commented Apr 15, 2016

flying-sheep commented Apr 16, 2016 • edited

jankatins commented Apr 18, 2016

flying-sheep commented Apr 18, 2016 • edited

jankatins commented Apr 18, 2016

jankatins commented Apr 18, 2016

jankatins commented Apr 18, 2016 • edited

jankatins commented Apr 18, 2016 • edited

flying-sheep commented Apr 19, 2016

flying-sheep commented Apr 19, 2016

flying-sheep commented Apr 19, 2016

flying-sheep commented Apr 16, 2016 •

edited

flying-sheep commented Apr 18, 2016 •

edited

jankatins commented Apr 18, 2016 •

edited

jankatins commented Apr 18, 2016 •

edited