stdout/stderr not showing up in logs

[ronaldoussoren]

Original report by Anonymous.

---

In Mountain Lion (10.8.2), py2app 0.7.1

Output from stdout/stderr does not show up in the console log. I've tried

print "hello"
raise Exception("oops")
import logging
logging.error("hey")

but nothing appears in the logs

I tried the example in py2app/examples/Tkinter/hello_tk The widget runs fine; I get a window with two buttons. The 'quit' button works fine, but the 'hello' button has no effect.

[ronaldoussoren]

Original comment by Ronald Oussoren (Bitbucket: ronaldoussoren, GitHub: ronaldoussoren).

---

I've verified the same behavior with an Objective-C program: logging using Cocoa's NSLog does end up in Console.app, while output with fprintf to stdout and stderr doesn't end up in Console.app.

This means that this is a change in the behavior of OSX, and I'm not sure if it is easily possible to work around this.

[ronaldoussoren]

Original comment by Ronald Oussoren (Bitbucket: ronaldoussoren, GitHub: ronaldoussoren).

---

An (unanswered) question on Stack Overflow: http://stackoverflow.com/questions/13104588/how-to-get-stdout-into-console-app

[ronaldoussoren]

Original comment by Ronald Oussoren (Bitbucket: ronaldoussoren, GitHub: ronaldoussoren).

---

It might be possible to use asl_log_descriptor(3) to redirect streams to the log.

[ronaldoussoren]

Original comment by Ronald Oussoren (Bitbucket: ronaldoussoren, GitHub: ronaldoussoren).

---

I've tried using asl_log_descriptor, but I'm not having a lot of progress.

I've added this function to py2app/apptemplate/src/main.c and called it early in main():

#include <asl.h>
static void
setup_logging(char*const* argv)
{
    aslclient c = asl_open("py2app", "com.apple.console", ASL_OPT_NO_DELAY);
    int fd = dup(2);
    asl_set_filter(c, ASL_FILTER_MASK_UPTO(ASL_LEVEL_DEBUG));
    asl_add_log_file(c, fd);
    asl_log(c, NULL, ASL_LEVEL_INFO, "Hello world from py2app launcher");
    asl_log_descriptor(c, NULL, ASL_LEVEL_INFO, 1,  ASL_LOG_DESCRIPTOR_WRITE);
    asl_log_descriptor(c, NULL, ASL_LEVEL_INFO, 2, ASL_LOG_DESCRIPTOR_WRITE);
}

This does result in print output getting redirected through ASL: the output is now prefix by the normal logging header (timestamp, ident, ...). So far, so good. The output does not end up in console.app though.

To get to a workable solution a couple of things need to change:

1) Update the function until output actually ends up in console.app

2) Use explicit weak-linking of the ASL functions, in "asl_log_descriptor" is only available on 10.8 and the stub needs to work on earlier OSX releases as well (and needs to be build there)

The second item is easy, the former is harder because I have no idea why it doesn't work yet.

[ronaldoussoren]

Original comment by Ronald Oussoren (Bitbucket: ronaldoussoren, GitHub: ronaldoussoren).

---

The attached patch might help, I need to test further before applying (and need to start a VM for rebuilding the binaries).

On my machine lines only end up in console.app when I use a separate account with administrator permissions, it doesn't work with my main account.

[ronaldoussoren]

Original comment by Ronald Oussoren (Bitbucket: ronaldoussoren, GitHub: ronaldoussoren).

---

The following code works in a standalone program, this still has to be integrated into py2app's stub executable:

#!C

#include <asl.h>
#include <unistd.h>
#include <stdio.h>

static void
setup_logging(void)
{
        aslmsg msg;
        aslclient c = asl_open("py2app", "com.apple.console", 0);

        msg = asl_new(ASL_TYPE_MSG);
        asl_set(msg, ASL_KEY_FACILITY, "com.apple.console");
        asl_set(msg, ASL_KEY_LEVEL, ASL_STRING_NOTICE);
        asl_set(msg, ASL_KEY_READ_UID, "-1");

        int fd = dup(2);
        //asl_set_filter(c, ASL_FILTER_MASK_UPTO(ASL_LEVEL_DEBUG));
        asl_add_log_file(c, fd);
        asl_log(c, NULL, ASL_LEVEL_INFO, "Hello world from py2app launcher");
        asl_log_descriptor(c, msg, ASL_LEVEL_INFO, 1,  ASL_LOG_DESCRIPTOR_WRITE);
        asl_log_descriptor(c, msg, ASL_LEVEL_INFO, 2, ASL_LOG_DESCRIPTOR_WRITE);
}

int main(void)
{
        setup_logging();
        printf("hello world, this is a printf\n");
}

The aslmsg argument is required, as are all options set on that message.

[ronaldoussoren]

Original comment by Ronald Oussoren (Bitbucket: ronaldoussoren, GitHub: ronaldoussoren).

---

Changeset 83851461d4b7 in the 0.7 branch more or less contains the setup code from my previous message.

More work is needed for the final solution: with this changeset stdout/stderr are unconditionally redirected to ASL and that makes it impossible to wrap command-line tools with py2app (and therefore breaks the test suite).

A subsequent patch will add detection of the way the app was launched: through LaunchServices (Finder) or otherwise.

[ronaldoussoren]

Original comment by Ronald Oussoren (Bitbucket: ronaldoussoren, GitHub: ronaldoussoren).

---

Update the fix for issue #77

The code now detects that a '-psn' argument as added by the Finder / LaunchServices is present and only redirects the output when the option is detected. This makes is possible to wrap command-line tools again (unless someone actually has command-line options that can be spelled as -psn_).

Closes #77

[ronaldoussoren]

Original comment by Ronald Oussoren (Bitbucket: ronaldoussoren, GitHub: ronaldoussoren).

---

Merge 0.7 branch, closes #77

[ronaldoussoren]

Original comment by marte (Bitbucket: marte, GitHub: marte).

---

It seems that in the latest version (0.9), the detection if it was opened by LaunchServices doesn't work on 10.10 (not sure about 10.9), that's why it always redirects stderr even if it was invoked directly (not by open).

By the way, is it possible to disable this via options?

[ronaldoussoren]

Original comment by Aron Kyle (Bitbucket: aronkyle, ).

---

• 1 @marte

There needs to be a way to opt out of this. In fact, I'd prefer that it required opting-in instead of opting-out. Our application uses stderr quite extensively. We already have formatted logs that are redirected by launchd to various log files. The extra call to ASL breaks the formatting. We've also noted cases where certain log messages seems to break the ALS integration and all following logs are no longer redirected correctly.