NSLog not working… (!??!?!)

Discussion in 'Mac Programming' started by zeppenwolf, Jan 17, 2016.

  1. zeppenwolf macrumors regular

    zeppenwolf

    Joined:
    Nov 17, 2009
    #1
    I am incorporating SMJobBlessXPC into MyKillerApp.

    The first step for me was to get SMJBX running, and I've got that much working.

    Then my intent was to take baby-steps in transmogrifying SMJBX into doing what I need. Specifically, of course, the "helper app".

    Well, I can indeed tweak it, but additions of NSLog() I found, do nothing-- as though there were macro'ed away.

    The "helper app" of SMJBX is written as a low-level, "C only" type of thing, so I thought maybe it's a question of adding libs/frameworks, ( altho the compiler didn't complain about seeing NSLog() ), and I added every framework under the sun: Cocoa, AppKit, CoreData, Foundation, and I import <Cocoa/Cocoa.h> in the helper app's main...

    But still, NSLog() has zero effect.

    For the love of Ozzy, what do I need to do? In my impertinence, I actually thought that I would be transmogrifying the helper app into an "mm" file, with mixed ObjC and C++, but I can't even get NSLog() to work...
     
  2. Senor Cuete macrumors regular

    Joined:
    Nov 9, 2011
    #2
    I assume that you're developing this with XCode. NSLog is a Cocoa method so maybe the "low-level, "C only" type of thing" doesn't know what it is. I'm surprised it will build with this in a .c file. Try printf instead. Also you're looking at the log pane in XCode, not the console, right?
     
  3. zeppenwolf thread starter macrumors regular

    zeppenwolf

    Joined:
    Nov 17, 2009
    #3
    Thank you, Señor C, for responding, and I apologize for taking so long respond in turn, but...

    When I woke up the next morning, I realized that I had done a miserable job of describing the full context, and then I realized that there was more I could do in testing and assertion, which I spent some time on, and then "life" got in the way...

    So. Let me fully describe.

    The "SMJobBlessXPC" sample code does two things: 1) it demonstrates how to "install" a "helper app" for the purposes of escalating privileges. Id est, it's the modern equivalent to the deprecated AEWP, "Authorize Execution With Privilges". 2), after accomplishing 1), it does a little "Hello World" XPC between the host app and the helper app. ok.

    So, immediately, I personally feel suspicious about Why NSLog() is not working in the HelperApp. Because it's not just *any* HelperApp, some binary living in the App's bundle, and called from there. Although I don't know this for sure, I have the strong feeling that when I call AuthorizationCreate() the actual binary is copied by the OS from the MainApp's bundle into some SuperSecretArea that the OS administers...

    Whether that's true or not, the following is emphatically true:

    In the virgin sample code, the Helper App, a bare bones C file, uses syslog() to print to the console, and of course that works fine.

    If I add NSLog() statements to the code, of course the compiler complains until I rename the file from a "C" to an "m" file, but then it compiles fine, and I've added all manner of libraries, from Cocoa to This, That, and Other.

    But I am left with the end product that in the Helper App, all of the syslog() calls print to the console, but any NSLog() calls, even right next to the syslog() calls, print nothing.

    printf() calls behave just like NSLog() calls-- nothing happens.

    So I've got code where there are three lines in a row, "syslog( LOG_NOTICE, 'blah"), NSLog(@"blah"), and printf("blah"), and only the syslog() outputs to the console.
     
  4. chown33 macrumors 604

    Joined:
    Aug 9, 2009
    #4
    Ultimately, printf() writes output to stdout. You could get the file-descriptor with fileno() and get some info on it using fstat(), and then use syslog (which appears to work), to tell you what it found out.

    Some things to look for are the node and type of the fd. Is the fd a file, a pipe, a character device, or what? Maybe there's no stdout fd at all, and the calls to printf() are failing, and if you don't check for an error you won't see it.

    You could add code to the helper to initially direct its stdout to a file of your choosing. It's running as root, I assume, so you can write to anything. See fopen(), freopen(), and maybe also try getcwd() so you know where it's working-dir is.

    You should also check whether the helper's effective-uid matches its real-uid. See the getuid() C funcs for how to do that.
     
  5. Senor Cuete, Jan 23, 2016
    Last edited: Jan 23, 2016

    Senor Cuete macrumors regular

    Joined:
    Nov 9, 2011
    #5
    I haven't verified this but my experience is that NSLog and printf print to the log pane in Xcode, not to the console app. I think that stdout must be set by XCode to the console pane. I've had the console open and seen nothing when the app I'm debugging calls these functions. I wondered about this as well. When I am developing a Mac application I have the debugger pane that shows the value of variables and the log pane split in a pane below the source code pane. When Xcode was made into a single window app it certainly was a "pane" in the ass compared to the old multiple window version.

    Try view->debug area>activate console in the Xcode menu bar.
     
  6. zeppenwolf thread starter macrumors regular

    zeppenwolf

    Joined:
    Nov 17, 2009
    #6
    Ok, guys, I'm back from the trenches and I've got something. It's not exactly what I was hoping for, but it's good enough, if I can't get any farther. And I think it's pretty interesting. It certainly surprised me. So:

    Code:
        syslog( LOG_NOTICE , "BEGIN PROLOGUE" );
    
        int outFile     = fileno( stdout );
        ( outFile == STDOUT_FILENO ) ? syslog( 5 , "outFile == STDOUT_FILENO" ) : syslog( 5 , "outFile != STDOUT_FILENO" );
    
        int errFile     = fileno( stderr );
        ( errFile == STDERR_FILENO ) ? syslog( 5 , "errFile == STDERR_FILENO" ) : syslog( 5 , "errFile != STDERR_FILENO" );
    
        chdir( "/Volumes/temp/jobBlessXPC/" );
        syslog( 5 , "pwd iz now %s" , getcwd( 0 , 0 ) );
    
    //  ourStdOut   = fopen( "ourStdOut" , "w" );
        ourStdOut   = freopen( "ourStdOut" , "w" , stdout );
        errno ? syslog( 5 , "ourStdOut iz errno %i" , errno ) : syslog( 5 , "ourStdOut no errno" );
    
        ourStdErr   = freopen( "ourStdErr" , "w" , stderr );
        errno ? syslog( 5 , "ourStdErr iz errno %i" , errno ) : syslog( 5 , "ourStdErr no errno" );
    
        printf( "Hi, totally naked printf statement!\n" );                          // ourStdOut
        fprintf( ourStdOut , "Hi, ourStdOut directed fprintf statement!\n" );       // ourStdOut
        NSLog( @"Don't forget about me, I was the whole point of this!!!\n" );      // ourStdErr
        syslog( 5 , "I am syslog.  I am mighty and strong.\n" );                    // console app
    
        syslog( LOG_NOTICE , "END PROLOGUE" );
    
    I added the above to the more or less starting point of the Helper app.

    The first four non-blank lines with "file no()" don't really do anything except to confirm that fileno() itself is unnecessary. In the case of stdout and stderr, both the STREAM ptrs and the file "numbers" are predefined. Anyway.

    In the next two lines, I chdir()... It turns out that the default wd is "/", not a place where I typically do alot of work. Heh. But anyway, it changes just fine.

    In the next Five non-blank lines, I use freopen() to "redirect" stdout and stderr to a file of my choosing. I have to put "redirect" into quotes, because I have no clue whether stdout & stderr actually already exist, and are going nowhere that makes a difference, or if I am creating totally new file streams when I use freopen().

    Also, you will notice one // line where I tried using fopen() instead of freopen() to direct stdout to my own file. The results of that tactic are identical to the way it's written.

    The next four lines are the crunge: one each of print statements from printf, fprintf, NSLog, and syslog.

    So guess what shows up in stderr? My NSLog() statements!!! Well, LAH DEE DAH.

    But i's also exceptionally weird, as you can see by the postfix comments: printf and fprintf end up in my own personal file on the hard drive as dictated by the above code. NSLog() ends in my personal stderr file.

    And syslog() shows up in the console app, always under any circumstances...

    It's a bit weird, do you see? Anyhow, the situation which has not changed since I posted is that, if I had my druthers, I would like NSLog() to print to the console app. So the question now is:

    Should I even dream of thinking that I can find the "problem" that prevents NSLog() from going to the console? Or should I just take the workable but annoying situation that has been discovered and call it a day?
     
  7. chown33, Jan 27, 2016
    Last edited: Jan 27, 2016

    chown33 macrumors 604

    Joined:
    Aug 9, 2009
    #7
    You should start by taking the workable but annoying solution, i.e. "redirecting" stderr and/or stdout to your own file.

    You could write to a file located in a directory where Console.app (look at its log list) normally looks for log files, and then you can open the log-file in Console.app and see it there. If you do this, make sure your redirection with freopen() opens the file for appending, so new output is added at the end.


    One reason I suggested using fileno() was specifically so you can fstat() the resulting file descriptor. With the resulting stat structure you can find out what type the node is. For example, is it a file, a pipe, or a Unix domain socket? Who owns it? What are the permissions? And so on.

    In short, you can show info similar to what 'ls -l' outputs.


    The reason syslog() always shows up in the system log is the way that syslog is implemented. I'll warn you now: this explanation will pretty quickly go down the rabbit hole, or into a maze of twisty passages, depending on your choice of metaphor.

    First, start by reading the man page for the syslog(3) C function.
    https://developer.apple.com/library...n3/syslog.3.html#//apple_ref/doc/man/3/syslog

    Notice that it mentions a "logger" and has See Also entries for a logger(1) command and a syslogd(8) daemon:
    https://developer.apple.com/library...n1/logger.1.html#//apple_ref/doc/man/1/logger
    https://developer.apple.com/library.../syslogd.8.html#//apple_ref/doc/man/8/syslogd

    Also read the man page for the syslog(1) cmd:
    https://developer.apple.com/library/mac/documentation/Darwin/Reference/ManPages/man1/syslog.1.html

    The essential underlying fact here is that the system log is being written and maintained by a daemon (syslogd), which accepts input on Unix domain sockets, and formats received data for writing to a structured log. The system log is not just a file.

    After reading the above man pages, and then doing some exploring, I see there are multiple sockets in this dir:
    /var/run/

    The syslog UDP datagram socket's Unix domain path is noted in the syslogd man page, but there are others. One of them may be a Unix domain stream socket. You'd have to dig into it further, maybe by looking at the source for logger(1), or maybe by trying some experiments.


    As to the reason why your privileged helper process loses its NSLog output stream, that's due to how a privileged process is started.

    First, learn about how open file descriptors are inherited by a child process. Refer to 'man execve'.

    Next, realize that when Xcode runs your program, it sets up the fd's so the output from your app is collected and processed for a window. Since that process runs without privilege escalation, it can use the normal route of fork() and execve(), and Xcode can control fd inheritance.

    You can poke around in the process info of your main app and discover things like parent process id (getppid), process group id (getpgid), the controlling terminal (if any), and so on. The parent process id is likely Xcode at some point in the process ancestry, or a temporary process started by Xcode.

    Unfortunately, this is not how a privileged process is started.

    A privileged process must be started from a parent process that already has 'root' as its effective uid (euid) or real uid (ruid). You can read these for a process with geteuid() and getuid() (see their man pages). The actual process that starts the privileged helper has changed as the OS has evolved. I'm pretty sure it was the init process at one point, and then the login process. I've forgotten much of the details since the last time I looked at this, and that was when AEWP was the only way. The OS and APIs now are quite different.

    The important thing here is that the privileged helper process is not a descendant of the process that requests the privileged execution. Instead, it goes through a privileged proxy, and that proxy is already running as root. Because the proxy doesn't inherit any fd's or streams from your main process, any connection between NSLog and syslog or an Xcode window is irrecoverably lost.

    Inheritance of fd's only works for descendent processes, not ones started by a proxy. There are ways to pass fd's to processes, but it takes cooperation on the receiving end.

    The net result of this is simple: if you want your privileged helper process to write to the system log using NSLog, you'll have to set that up yourself. To do that, however, you'll have to figure out what Unix domain socket to use, which itself is going to take some exploration.


    The above is probably only about half the story, because I would fully expect more twisty little passages; this is Unix, and nothing is ever as simple as its visible API may suggest. In some ways this is intentional (separation of interface from implementation), and in some ways it's a result of the evolution of implementations.

    This is why if you can get close to what you want using freopen(), that's almost certainly going to be a simpler approach. You might stumble on a simple way to write a stream to syslogd that proves me wrong, but I think that's more luck than anything else.

    Personally, I'd do the simplest thing that came close to what I wanted. Then if you do happen to get lucky, you've still made a useful tool.
     
  8. zeppenwolf thread starter macrumors regular

    zeppenwolf

    Joined:
    Nov 17, 2009
    #8
    Ok, well, I think I'm done here. I don't have the Brass Ring, but what I've got is close enough, and it's time to start writing the actual code that I need to write...

    Insert a big Homer Simpson "D'Oh!" here.

    Looking at the places where Console.app observes files, I initially thought that "~/Library/Logs" was clearly the most suitable. But then, this is a "helper app", which, as I mentioned before, I suspect is copied "physically" from MyKillerApp's bundle to some SuperSecret location, from where the system runs it... It doesn't surprise me that the meaning of "~/" is completely lost at some point in that process. So instead I changed the pwd of my personal stderr and stdout to be "/Library/Logs/".

    And it works.

    Which is to say, the files "ourStdOut" and "ourStdErr" both appear in the "/Library/Logs" subsection of the Console.app.

    And if I use fflush() after every fprintf(), then I can see anything fprinted in real time.

    Calls to NSLog seem to do their own fflush().

    The one thing that doesn't happen is that none of my calls, neither to NSLog nor fprintf appear in the "AllMessages" pane of the Console.app-- only calls to syslog() appear there.

    So effectively, to debug my helper app by means of printing out strings to the console, I need only take the extra step of going directly to "ourStdErr" in the /Library/Logs subsection... As I say, not the Brass Ring, but close enough.

    Chown, as far as all that stuff in all those man pages you suggested... I could spend my life learning what you've already forgotten, but I need to get moving forward. Sometimes I think that "man pages" should be renamed "Manly-Man pages", since they are clearly written by some weird Sadist who doesn't actually want me to understand the function unless I'm willing to suffer...
     
  9. chown33 macrumors 604

    Joined:
    Aug 9, 2009
    #9
    That's the correct behavior.

    The "All Messages" pane uses the system log database. That means the database syslogd maintains behind the scenes. So if it wasn't in a system-log message sent to syslogd, it won't be in the system log database, and it won't be in "All Messages". It's a simple logical inference based on a simple underlying fact: the syslogd database.

    I'm not sure what OS version you're using, but here I just looked at Console.app on a couple versions. On the left, the heading with "All Messages" under it says "DATABASE SEARCHES" or "SYSTEM LOG QUERIES". It seems fairly obvious it's referring to the system-log database.

    Conversely, the logs that are individual files are listed under the heading "FILES". There's an obvious inference there, too. You can even right-click on the title-bar name of the Console.app window when it's showing a log file, and it'll show you the path to that log file.

    You should at least read enough of the man pages to understand what the system log is: a database maintained by syslogd. Write brief notes to yourself summarizing the important points. This will tell you the fundamentals of what's behind the scenes, and then you can make logical inferences. For example, why syslog() text shows up in "All Messages" but text written to files doesn't. It's not magic and there's no wizard; it only seems that way when you don't know what's behind the curtain.
     

Share This Page