Bug 13538 - Extraneous lines in Application Output for Debug.WriteLine
Summary: Extraneous lines in Application Output for Debug.WriteLine
Alias: None
Product: Runtime
Classification: Mono
Component: Debugger ()
Version: unspecified
Hardware: All All
: Normal normal
Target Milestone: ---
Assignee: Zoltan Varga
: 13924 26327 26648 31993 39050 ()
Depends on:
Reported: 2013-07-27 01:03 UTC by Joseph Hanna
Modified: 2017-03-22 16:43 UTC (History)
24 users (show)

Is this bug a regression?: ---
Last known good build:

Screenshot showing output (131.78 KB, application/pdf)
2013-07-27 01:03 UTC, Joseph Hanna
Screen shot from latest version of XS 5.1 (build 479) (350.05 KB, image/tiff)
2014-07-01 02:32 UTC, Joseph Hanna

Notice (2018-05-24): bugzilla.xamarin.com is now in read-only mode.

Please join us on Visual Studio Developer Community and in the Xamarin and Mono organizations on GitHub to continue tracking issues. Bugzilla will remain available for reference in read-only mode. We will continue to work on open Bugzilla bugs, copy them to the new locations as needed for follow-up, and add the new items under Related Links.

Our sincere thanks to everyone who has contributed on this bug tracker over the years. Thanks also for your understanding as we make these adjustments and improvements for the future.

Please create a new report on GitHub or Developer Community with your current version information, steps to reproduce, and relevant error messages or log files if you are hitting an issue that looks similar to this resolved bug and you do not yet see a matching new report.

Related Links:

Description Joseph Hanna 2013-07-27 01:03:38 UTC
Created attachment 4462 [details]
Screenshot showing output

Description of Problem:
Extra line are output to the Application Output pad when using Debug.Writeline.  This was reported to support@xamarin.com on May 21 2013, case #35165

Steps to reproduce the problem:
1. Execute Debug.WriteLine.
2. Observe the extra line above the expected output ("[0:]" in grey) + the extra line below the output which repeats the output line ("[0:] <insert expected output here>) + a blank line.

Actual Results:
See attachment.

Expected Results:
Only one single line of output in the Application Output pad per Debug.WriteLine, not 4 (extra lines described above + the expected output line)

How often does this happen? 
Everytime Debug.WriteLine is executed after installing XS 4.0.10. Also since May 21 2013 when running XS from the Alpha channel.

Additional Information:
Comment 1 Jeffrey Stedfast 2013-07-27 21:21:35 UTC
Maybe something changed in Mono's Class Libraries? None of the changes in XS seem to be at all related to something like this.
Comment 2 Joseph Hanna 2013-10-11 07:38:05 UTC
Hi Jeff,

Any news on this?   It is still happening in 4.1.11 (alpha channel).

Comment 3 Yvan Rodrigues 2014-01-20 15:04:30 UTC
Hi guys. I'm writing to ask you to triage this and give it a high priority. The reason is that not only is the output messy, but the execution time is exponentially longer.

Running part of my application using Console.WriteLine : less than 1s.
Running part of my application using Debug.WriteLine : *** 1605s. *** I shit you not.
Comment 4 Mikayla Hutchinson [MSFT] 2014-01-20 15:11:41 UTC
Yvan, the performance has nothing to do with the blank lines. It's because Debug.WriteLine uses a fundamentally different mechanism to send information to the debugger though the debugger event system, and that's slower than file streams. If that's a problem for you, please file a separate bug with a test case.
Comment 5 Yvan Rodrigues 2014-01-20 15:12:35 UTC
Will do Michael.
Comment 6 Joseph Hanna 2014-04-16 19:19:51 UTC
Hi guys,

Can I get an update on this?  Problem is still there in v4.2.4.

Comment 7 Jeffrey Stedfast 2014-04-29 15:48:14 UTC
lluis: any ideas? I'm having trouble tracking down where these extra lines are coming from.
Comment 8 Joseph Hanna 2014-07-01 02:31:57 UTC
I have attached a screenshot of the output from the latest version.  Something has changed! (for the better but we are not quite there!)

1. Raw text from Debug.WriteLine is now shown in blue (previously light grey) without a prefix of "[0:]" (improvement!)
2. Blank line has disappeared (great!)
3. Plain line with simple prefix "[0:]" has also disappeared. (great!)

However, the output is still repeated!

Compare the original screenshot to the new one I attached today.  This is a huge improvement!

Here is the raw output:
2014-07-01 16:25:21.561 iPadTest1[10778:80b] Sample text output line #1
Sample text output line #1  (shown in blue)
2014-07-01 16:25:21.564 iPadTest1[10778:80b] Sample text output line #2
Sample text output line #2  (shown in blue)

I actually would prefer the line with the extra information in lieu of the plain one, as it also has the date/time and I am guessing a method address.   This obviously is more beneficial, but would be even better if we could have a method name instead of the hex address (please?)

Further we don't need both the raw output + the one with the date/time/method address.  Can we choose which one we get with an option or something?

Thanks guys

Here is my environment:-

=== Xamarin Studio ===

Version 5.1 (build 479)
Installation UUID: 14b23281-89a0-4137-8dab-1e7e03fbd02a
	Mono 3.4.0 ((no/954ed3c)
	GTK+ 2.24.23 (Raleigh theme)

	Package version: 304000214

=== Xamarin.Android ===

Version: 4.12.5 (Business Edition)
Android SDK: /Users/joe/Library/Developer/Xamarin/android-sdk-mac_x86
	Supported Android versions:
		2.1   (API level 7)
		2.2   (API level 8)
		2.3   (API level 10)
		3.1   (API level 12)
		4.0   (API level 14)
		4.0.3 (API level 15)
Java SDK: /usr
java version "1.6.0_65"
Java(TM) SE Runtime Environment (build 1.6.0_65-b14-462-11M4609)
Java HotSpot(TM) 64-Bit Server VM (build 20.65-b04-462, mixed mode)

=== Apple Developer Tools ===

Xcode 5.1.1 (5085)
Build 5B1008

=== Xamarin.iOS ===

Version: (Business Edition)
Hash: e7f4f92
Build date: 2014-06-18 02:37:27-0400

=== Xamarin.Mac ===


=== Build Information ===

Release ID: 501000479
Git revision: e5a428cec75d4cc7e6e3ccd8192a3660d013e7dc
Build date: 2014-06-26 09:28:17-04
Xamarin addins: 190d93e026e17280e75a3680ef38f2630b9228d3

=== Operating System ===

Mac OS X 10.9.3
Darwin Joseph-Office-iMac.local 13.2.0 Darwin Kernel Version 13.2.0
    Thu Apr 17 23:03:13 PDT 2014
    root:xnu-2422.100.13~1/RELEASE_X86_64 x86_64
Comment 9 Joseph Hanna 2014-07-01 02:32:52 UTC
Created attachment 7240 [details]
Screen shot from latest version of XS 5.1 (build 479)

Screen shot from latest version of XS 5.1 (build 479)
Comment 10 David Karlaš 2015-04-29 07:36:18 UTC
*** Bug 26327 has been marked as a duplicate of this bug. ***
Comment 11 David Karlaš 2015-04-29 07:56:05 UTC
I discussed this problem with Rolf today...

I'm re-assigning this to runtime since problem is in Mono code and not XS.

Problem is in this lines: https://github.com/mono/mono/blob/48e112d652335da23dd1b4d5f3227e54b74d0814/mcs/class/System/System.Diagnostics/DefaultTraceListener.cs#L72-L75

Originally this was added so Debug.Assert on mobile(iOS and Android) wrote something to output when debugger(XS/VS) was not connected... But now it's also abused in PCL code to be able to write messages in Console output in mobile applications via System.Diagnostics.Debug.WriteLine since System.Console.WriteLine is not part of PCL API.

3 possible solutions:
1) Remove code mentioned above and handle Debug.Assert() in https://github.com/mono/mono/blob/48e112d652335da23dd1b4d5f3227e54b74d0814/mcs/class/System/System.Diagnostics/DefaultTraceListener.cs#L155-L160 and disable possibility of PCL code to write to Console.Output.
2) Replace above code with:
  if (trace == null && !Debugger.IsLogging)
    trace = ConsoleOutTrace;
I'm not sure if this is nice solution since debugger might in future connect after start and can also disconnect between debugging...
3) Add some logic to https://github.com/mono/mono/blob/48e112d652335da23dd1b4d5f3227e54b74d0814/mcs/class/System/System.Diagnostics/DefaultTraceListener.cs#L254-L257 to check Debugger.IsLogging to handle this scenario on every message.
Comment 12 Jeffrey Stedfast 2015-04-29 08:35:17 UTC
I'd probably recommend going with option #3
Comment 13 Zoltan Varga 2015-04-29 18:14:18 UTC
So what should the code in DefaultTraceListener do ? Avoid calling WriteDebugString () if the debugger is connected ?
Comment 14 David Karlaš 2015-04-30 02:31:18 UTC
Yes, that is option 2) and 3).

In .Net/Mono destkop... DefaultTraceListener never writes to console output by default... this is option 1) fix.
Comment 15 David Karlaš 2015-07-24 10:21:41 UTC
*** Bug 26648 has been marked as a duplicate of this bug. ***
Comment 16 David Karlaš 2015-07-24 10:22:14 UTC
*** Bug 31993 has been marked as a duplicate of this bug. ***
Comment 17 Johannes Rudolph 2015-08-25 06:24:30 UTC
What is the status of this? Confirmed, more and more duplicates reported, 2 years old and still not fixed? 

Is there a sensible way to enable PCLs to use Debug.WriteLine when they're used in a project compiled in Debug mode and omit these calls when compiled in Release mode? 

I'm not sure it's a good idea to keep a hack around just for the sake of some PCLs abusing an API. If a PCL needs logging, it should provide an interface for that (DIP) and have the consumer decide.
Comment 18 Joseph Hanna 2015-11-13 17:43:12 UTC
Console.WriteLine does the job - but does it still get output in the iOS AppStore profile and cause problems with Apple reviews?
Comment 19 Nate Cook 2015-11-13 17:58:48 UTC
@Joseph Hanna

Try something like this:

public static void Debug(string text)
Comment 20 Joseph Hanna 2015-11-13 20:01:45 UTC
Thanks @nate. It's a good workaround.  This used to work fine - but no one wants to fix it - even 2.5 years after it was reported.  It is seriously annoying
Comment 21 Nate Cook 2015-11-13 22:48:15 UTC
I agree, it should be fixed. I want to use Debug.Writeline so I can get colored output in the debugger.
Comment 22 Joseph Hanna 2015-11-26 05:56:33 UTC
It's getting worse.  XS 5.10 now outputs 3 lines to the Application Output window.  

The output below was generated from one Debug.WriteLine statement.  The second one was coloured blue.

2015-11-26 21:08:11.284 MyApp[50357:14043063] 20151126 21:08:11.284105  |7| [get_InternetAvailable] | Internet is ReachableViaWiFiNetwork

20151126 21:08:11.284105  |7| [get_InternetAvailable] | Internet is ReachableViaWiFiNetwork

2015-11-26 21:08:11.284 MyApp[50357:14043063] 20151126 21:08:11.284105  |7| [get_InternetAvailable] | Internet is ReachableViaWiFiNetwork
Comment 23 Mikayla Hutchinson [MSFT] 2015-12-10 00:08:04 UTC
TBH, I would just go with option 1. Debug.WriteLine is supposed to print to the debugger. Printing to the console might be "useful" in some cases but it's "wrong".

Even if we make it only print to the console when a debugger's not attached, we'd get confusing behaviour like it appearing differently in the app output depending whether the apps' being run or debugged.
Comment 24 Andy 2016-01-13 17:40:56 UTC
This really needs to get looked for this new year.
Comment 25 Robert 2016-01-21 00:06:57 UTC
Comment 26 renan jegouzo 2016-02-13 09:01:03 UTC
on iOS I found a trick 
I was using System.Diagnostics.Debug.Print(..)  that display twice
but System.Console.WriteLine(..) display only once

so just create
public class Debug
	[ Conditional("DEBUG") ]
	public static void Print (string s)
and call this class, not Diagnostics one
Comment 27 David Karlaš 2016-03-01 11:06:47 UTC
*** Bug 39050 has been marked as a duplicate of this bug. ***
Comment 28 Mick Byrne 2016-03-27 10:46:25 UTC
Can this please be fixed, seems like a real flaw in the IDE and is definitely one of the first things that a native iOS and Android dev (like me) is going to notice when evaluating Xamarin as an alternative.
Comment 29 Zoltan Varga 2016-03-28 18:46:09 UTC
So what happens here is that messages emitted using Debug.Log () go through 
DefaultTraceListener.WriteImpl (), which logs to two places:
- the standard output, which is redirected to NSLog (). The IDE shows this in the output window.
- Debugger.Log () which is redirected to the IDE output window.

So the message goes to two places, both of which show up in the output. Not sure what is the proper solution here.
Comment 30 Joseph Hanna 2016-03-28 19:49:12 UTC
This never happened in XS 3.x, it started in XS 4.0.  What was the strategy back then?
Comment 31 Mikayla Hutchinson [MSFT] 2016-03-28 21:26:47 UTC
I believe the correct solution is for default listener not to write to NSLog. That's not what Debug.WriteLine is supposed to do. This is a leftover workaround from before Debugger.Log worked.
Comment 32 Zoltan Varga 2016-03-28 22:14:34 UTC
The default listener writes to Console.Out, which is redirected to NSLog on ios. If we don't do that, than Debug.WriteLine () will not write anywhere when running outside a debugger.
Comment 33 Zoltan Varga 2016-03-29 01:50:47 UTC
Fixed in mono 10c1f679043c565ad46e4943dede1eb4ede0786d.
Comment 34 Manuel de la Peña [MSFT] 2017-03-22 16:43:08 UTC
*** Bug 13924 has been marked as a duplicate of this bug. ***