Unable to redirect Console output (logging) to text (stdoutLogFile) file?

bdcoder2 commented 5 years ago

Describe the bug

When trying to redirect Console output to a text file, the stdoutLogFile is created, but is always empty.

The following settings are present in the projects ( ASP.NET Core Web Application) web.config file:

<?xml version="1.0" encoding="utf-8"?>
<configuration>
  <system.webServer>
    <handlers>
      <remove name="aspNetCore" />
      <add name="aspNetCore" path="*" verb="*" modules="AspNetCoreModuleV2" resourceType="Unspecified" />
    </handlers>
    <aspNetCore processPath="%LAUNCHER_PATH%" arguments="%LAUNCHER_ARGS%" stdoutLogEnabled="true" stdoutLogFile="D:\temp\website3_log" hostingModel="inprocess">
       <handlerSettings>
          <handlerSetting name="debugFile" value="D:\\temp\\website3_debug_log" />
          <handlerSetting name="debugLevel" value="FILE,INFO" />
       </handlerSettings>
      <environmentVariables>
        <environmentVariable name="ASPNETCORE_HTTPS_PORT" value="44383" />
        <environmentVariable name="COMPLUS_ForceENC" value="1" />
        <environmentVariable name="ASPNETCORE_ENVIRONMENT" value="Development" />
      </environmentVariables>
    </aspNetCore>
  </system.webServer>
</configuration>

The debugFile is created and log entries are present without issue.

The stdoutLogFile is created, but remains empty.

Questions:

WHY is the stdoutLogFile always empty? It appears that when Console.WriteLine( "this should be in the log file" ) statements are executed within code, the WriteLine method is NOT redirecting output to the stdoutLogFile.

To Reproduce

Steps to reproduce the behavior:

Using Visual Studio
Click on "Create a new project"
Select ASP.NET Core Web Application -> Next
Enter project name, Location, Solution Name -> Create
Add web.config to the project and set the stdoutLogEnabled="true"
Set the stdoutLogFile attribute to the path of the log file.

Expected behavior

When Console.WriteLine() statements are executed, it is expected that the Console output is redirected to the stdoutLogFile file (or, at least one ASSUME's that would be the case -- can this be confirmed anywhere in the docs? -- I have yet to find anything!!).

Additional context

Also looking for details with regard to the schema of the following files:

web.config - where do we find the complete schema? Where do we find the complete schema that explains all valid entries that may appear in this file and the effect of each entry.
launchsettings.json - again, where do we find the complete schema that explains all valid entries that may appear in this file and the effect of each entry.
This issue was raised within the documentation at: https://github.com/aspnet/AspNetCore.Docs/issues/15080

Finally, not sure if this would be possible, but a more consistent approach to Console logging (redirection) might be to include a "handler" for Console output, for example:

   <handlerSettings>
      <handlerSetting name="debugFile" value="D:\\temp\\website3_debug_log" />
      <handlerSetting name="debugLevel" value="FILE,INFO" />
      <handlerSetting name="consoleFile" value="D:\\temp\\website3_console_log" />
   </handlerSettings>

Adding a handler for Console output would be more consistent than the stdoutLogFile and stdoutLogEnabled attributes on the aspNetCore node.

javiercn commented 5 years ago

@bdcoder2 Thanks for contacting us.

@jkotalik @BillHiebert What's the appropriate way to achieve this? I remember there was a way to make this work, at least from within visual studio and IIS Express.

@bdcoder2 Search for a web.config file under the project file, likely inside the .vs folder and enable logging there.

bdcoder2 commented 5 years ago

@javiercn @jkotalik @BillHiebert - Searched .vs folder (and all sub-folders) for web.config - no file found; did you imply to create web.config if not found?

After a week of trying to redirect console output to a text file (when running under debug within VS), I have since moved on (by creating my own ultra-simple logging class); further effort at this point does not seem worth it. I think it best to just close this issue and admit defeat -- or include a line within the docs that state:

Redirecting Console output to a text file while running a project within VS cannot be (easily) done; save your time (and sanity), and use your own logging method or a third party logging utility.

Thanks!

jkotalik commented 5 years ago

@bdcoder2 if you are running with IISExpress, do you see logs written to the Debug window in Visual Studio? StdoutLogFile + IISExpress isn't a common scenario; we could have broken it in 3.0 which we will verify but logs should show up in debug output.

If you run with full IIS, the options you provided above should work and output should be logged to a file.

bdcoder2 commented 5 years ago

@jkotalik - No, any Console.WriteLine( "anything" ); statements DO NOT show in Debug output, but the output can be displayed via:

View -> Output -> Show output from -> Then I select "website3 - ASP.NET Core Web Server" from the pull-down menu.

Output from Console.WriteLine() statements are viewable when the above is selected.

To clarify, I was using Console.WriteLine() within my project (not ILogger) -- and was wanting to redirect Console output to a text file via settings in web.config

jkotalik commented 5 years ago

View -> Output -> Show output from -> Then I select "website3 - ASP.NET Core Web Server" from the pull-down menu.

Yes, that is what I meant (not debug). Apologies for getting the wrong menu.

To give a bit more detail, we have slight differences in how we handle console redirection between IIS and IISExpress. In IIS Express, we assume a console is attached, therefore wherever IISExpress logs is where we let it log (which is ASP.NET Core Web Server in Visual Studio). For IIS, there is no console, so the file should work correctly. @bdcoder2 can you confirm when you run with IIS, using stdOutLogFile?

@anurse there may be an issue with IISExpress + StdOutLog file being enabled; it looks like it does not log to the file.

bdcoder2 commented 5 years ago

@jkotalik - No problem. I have not run the project on IIS as I am only learning .Net Core and haven't had the opportunity to publish the project yet. Your post makes complete sense though.

May I suggest the following (for all the other newbies like myself that may try this) - do not support Console output redirection for IISExpress - period.

Simply add a note to the docs with regard to the stdoutLogEnabled and stdoutLogFile attributes on the aspNetCore node within web.config. Something along the lines of:

Console output redirection is NOT supported when using IISExpress. To view Console output when using IISExpress, use the VS command: View -> Output -> Show output from -> Then select "{project-name} - ASP.NET Core Web Server" from the pull-down menu.

Had a note like the one above been present in the documentation, I would have been spared 4 days of pain and suffering! :)

Thanks again.

analogrelay commented 5 years ago

I'm not able to repro this. I did a new project, enabled the stdout log file and the debug file and both were written properly.

bdcoder2 commented 5 years ago

@anurse - Can you please post your project somewhere on GitHub (make public)? Out of pure curiosity, I would like to see what differences exist between something that works, and my abomination that doesn't !

analogrelay commented 5 years ago

I don't have it handy as I didn't keep it around after updating. It was just File > New Project and then I set stdoutLogPath to .\logs\stdout and stdoutLogEnabled to true.

For the debug log, I copied your handlerSettings section and set the path to .\\logs\\debug. Both logs were produced when I F5'd.

bdcoder2 commented 5 years ago

@nurse - sound like what happened to me -- but I directed stdoutLogPath and debug file paths to D:\temp\ -- the debug file had entries in it, but the stdoutLogPath file was always empty!! Was your file empty as well?

analogrelay commented 5 years ago

Nope, both my files had content in them. So the files were created in your case but were empty?

bdcoder2 commented 5 years ago

@nurse - The output file path was set to: D:\temp\ (outside of project); and in my case, the stdoutLogPath file is always empty. The debug file was not empty.

bdcoder2 commented 5 years ago

@nurse - Had some spare time today, so just out of curiosity, I just tried the following using Visual Studio Community 2019 16.3.6

Create a new EMPTY ASP.Net core web application
Added a single Console.WriteLine statement above the project generated code in the "Configure" method within Startup.cs; looks like this:

Console.WriteLine( "This should appear in stdoutLogFile" );
await context.Response.WriteAysync( "Hello World!" ):

Added web.config to the project and changed the stdoutLogEnabled and stdoutLogFile to the following:

<aspNetCore ... stdoutLogEnabled="true" stdoutLogFile="D:\temp\tempapp0_log" ... >

When I rebuild and run the project, everything works; the web browser fires up and I see "Hello World!" displayed -- I go to D:\temp to see if a log file is created - it is:

D:\temp\tempapp0_log_20191025155527_1352.log

The file however, is empty -- I would have thought that it would contain the line "This should appear in stdoutLogFile" - but does not. What the H@!! am I doing wrong?

analogrelay commented 5 years ago

FYI @bdcoder2 you keep mentioning a different user :). My GitHub username is anurse not nurse ;).

I'm not sure off hand what's going on here. We can't seem to repro ourselves so it's hard to know what could be going wrong. Can you post a complete sample project that reproduces this error? That way we can see the full context.

bdcoder2 commented 5 years ago

@anurse - Apologies -- missed the "a" (was not intentional) ...

OK -- here is the code in its entirety:

https://github.com/bdcoder2/tempapp0

Specifically, see the relevant comments in Startup.cs -- this is an empty project in which I added one line of code and changed two attributes within web.config

analogrelay commented 5 years ago

Apologies -- missed the "a" (was not intentional) ...

No problem! I was still getting notified because I subscribed to the thread :).

I cloned your sample, ran it, then shut it down (since IIS locks the stdout file, so you can't open it until the app is shutdown) and I see the stdout content in the file:

info: Microsoft.Hosting.Lifetime[0]

      Application started. Press Ctrl+C to shut down.

info: Microsoft.Hosting.Lifetime[0]

      Hosting environment: Development

info: Microsoft.Hosting.Lifetime[0]

      Content root path: C:\Users\anurse\Code\bdcoder2\tempapp0\tempapp0

info: Microsoft.AspNetCore.Hosting.Diagnostics[1]

      Request starting HTTP/2.0 GET https://localhost:44384/  

info: Microsoft.AspNetCore.Routing.EndpointMiddleware[0]

      Executing endpoint '/ HTTP: GET'

This should appear in stdoutLogFile

info: Microsoft.AspNetCore.Routing.EndpointMiddleware[1]

      Executed endpoint '/ HTTP: GET'

info: Microsoft.AspNetCore.Hosting.Diagnostics[2]

      Request finished in 55.9908ms 200 

info: Microsoft.AspNetCore.Hosting.Diagnostics[1]

      Request starting HTTP/2.0 GET https://localhost:44384/favicon.ico  

info: Microsoft.AspNetCore.Hosting.Diagnostics[2]

      Request finished in 1.4399000000000002ms 404 

info: Microsoft.Hosting.Lifetime[0]

      Application is shutting down...

I'm not sure what might be different here. Were you shutting down IIS before opening the log file? Some editors may claim to "open" the file but show no content if there's a file locking issue while opening it I suppose...

bdcoder2 commented 5 years ago

@anurse - Mystery solved !!

To view output redirected to a stdoutLogFile:

Run the project (Click on IIS Express while in Visual Studio)
Right-click on the IIS Express icon (in system tray or task bar)
Select "Exit" - System will respond with a Confirmation dialog that will ask "Are you sure you want to stop all the worker processes and exit?" -> Click "Yes"
Log file in "D:\temp\" created and contains all Console output.

However, If you are running the project (Debug or Release configuration), and then stop the session within Visual Studio (by clicking the stop button). The log file will always be empty.

This is not inherently intuitive by any stretch. Newbies (such as myself) would think that stopping the session would close the log file; similar to the way the browser is closed automatically when the stop button is clicked on. Clearly, the log file is not being flushed / closed when stop is used within Visual Studio. The only other possibility I can think of is there is some setting within Visual Studio that allows content to be flushed to the logs when the Stop button is used.

As far as I can tell, there is nothing in the docs that even hints at stopping IIS Express rather than stopping the process while in Visual Studio in order to view redirected output. Perhaps that hint might be a welcome addition to the docs?

Anyway, problem solved -- 4 days of my life I will never get back -- but that's OK, at least now I can sleep at night :)

Cheers,

analogrelay commented 5 years ago

This is not inherently intuitive by any stretch. Newbies (such as myself) would think that stopping the session would close the log file; similar to the way the browser is closed automatically when the stop button is clicked on.

The big difference is that IIS Express doesn't necessarily shut down when the debugging sessions is terminated.

@jkotalik do you know if there's anything different we could do here with how we open the file? Right now it seems the file is locked to writers (which makes sense) and readers (which means you can't look at the log while the IIS Express is running).

bdcoder2 commented 5 years ago

@anurse, @jkotalik - That is correct -- I tried to open the log file while the project was still running with WordPad and it (correctly) displayed a dialog which said the "file was locked by another process"; but the log entries are not available (empty window).

Notepad however, simply opens the log file (without any warning), and shows an "empty" window as well.

Strange that the IISExpress icon disappears from the task bar and/or system tray when the debugging session is terminated as well -- that is, there is no (graphical UI) way to stop IIS Express. (I assume I could via the command line / iisexpress.exe if it was still running in the background).

Hope that helps as well.

jkotalik commented 3 years ago

I think the issue is when you shutdown the debug session, it doesn't shutdown the process gracefully.

I think there is a small regression from out of proc here that we can address, involving constantly opening and closing the handle for the output file.

dotnet / aspnetcore