Allow AnnotatedStrings in log messages

[tecosaur]

Permitting annotated strings allows for styling information to be preserved through to log printing.

[tecosaur]

I'm not sure that this actually does need any additional tests, without StyledStrings loaded there won't be any change in behavior. Perhaps it would be nice to separately test the "with styled strings loaded" and "without styled strings loaded" cases, but I'm not sure how that could be done well, and whether it would be worth it.

[fredrikekre]

Feels a bit like a design failure that any custom string type needs to be hard coded here, but maybe it is unavoidable.

[tecosaur]

The specialisation on String not AbstractString is largely unnoticeable, it just so happens that with an AnnotatedString (and only AnnotatedString, as far as I'm aware), there's a potential difference in the externally visible behaviour.

[tecosaur]

@fredrikekre do please let me know if you've got any further comments here, otherwise I'll just mark this as resolved shortly.

[mbauman]

I agree this seems odd. The assert and convert here was added by #38292 and #44500 in the latency hunts; without them there'd be no need for a separate codepath — and the separate codepath is what makes this want for tests.

But I suppose going back to the simple [(indent=0, msg=l) for l in split(chomp(string(message)), '\n')] would likely reintroduce invalidations. Maybe worth a check?

[tecosaur]

Maybe? I'm not sure I'd be a good person to check however — perhaps someone more familiar with invalidations could take a look if needed?

If this is indeed a little tricky to work out, might it be possible to merge this as an initial 1 -> 2 AbstractString widening of the allowed types here, and then explore making this fully generic again in a subsequent PR?

[tecosaur]

Ok, I'm not entirely sure of this, but I think the following might suggest that a widening to "any AbstractString" may be premature given Tim's invalidation concerns.

# What it used to be before Tim's PRs
julia> m0(message) = [(indent=0, msg=l) for l in split(chomp(string(message)), '\n')]
m0 (generic function with 1 method)

# The current code
julia> m1(message) = [(indent=0, msg=l) for l in split(chomp(convert(String, string(message))::String), '\n')]
m1 (generic function with 1 method)

# The current PR 
julia> m2(message) = if message isa Base.AnnotatedString
               NamedTuple{(:indent, :msg), Tuple{Int, SubString{<:Union{typeof(message), String}}}}[
                   (indent=0, msg=l) for l in split(chomp(message), '\n')]
           else
               [(indent=0, msg=l) for l in split(
                    chomp(convert(String, string(message))::String), '\n')]
           end
m2 (generic function with 1 method)

# What I'm about to push
julia> m3(message) = if message isa Base.AnnotatedString
               message = Base.AnnotatedString(String(message), Base.annotations(message))
               NamedTuple{(:indent, :msg), Tuple{Int, SubString{<:Union{Base.AnnotatedString{String}, String}}}}[
                   (indent=0, msg=l) for l in split(chomp(message), '\n')]
           else
               [(indent=0, msg=l) for l in split(
                    chomp(convert(String, string(message))::String), '\n')]
           end
m3 (generic function with 1 method)

julia> Base.return_types(m0, (Any,))
1-element Vector{Any}:
 Vector (alias for Array{T, 1} where T)

julia> Base.return_types(m1, (Any,))
1-element Vector{Any}:
 Vector{@NamedTuple{indent::Int64, msg::SubString{String}}} (alias for Array{@NamedTuple{indent::Int64, msg::SubString{String}}, 1})

julia> Base.return_types(m2, (Any,))
1-element Vector{Any}:
 Array{NamedTuple{(:indent, :msg), var"#s178"}, 1} where var"#s178"<:Tuple{Int64, Vararg}

julia> Base.return_types(m3, (Any,))
1-element Vector{Any}:
 Union{Vector{@NamedTuple{indent::Int64, msg::SubString{<:Union{Base.AnnotatedString{String}, String}}}}, Vector{@NamedTuple{indent::Int64, msg::SubString{String}}}}

[tecosaur]

(message has no type restriction in the signature of handle_message)

[tecosaur]

and the separate codepath is what makes this want for tests.

Added a test for the separate codepath.

[timholy]

handle_message shifted to being called via invokelatest (the "nuclear option" when it comes to eliminating invalidations) in #47889; any changes that occurred prior to that PR may not be required anymore. If you want to be sure but don't feel comfortable using SnoopCompile, just (1) start Julia with --trace-compile, (2) define a function that uses logging and run it to force compilation, (3) load InlineStrings, (4) run it again and see if your function got recompiled.

[tecosaur]

It would be great if somebody with merge rights could spare the time to have a look at this PR.

[vtjnash]

Suggested change

	@NamedTuple{indent::Int, msg::SubString{<:Union{Base.AnnotatedString{String}, String}}}[
	@NamedTuple{indent::Int, msg::SubString{Base.AnnotatedString{String}}[

[tecosaur]

This change is invalid since later code pushes values like (indent=2, msg=SubString("$key =")) to msglines.

[vtjnash]

That shouldn't be invalid, if the convert methods are defined correctly.

But anyways, that suggest this should have the same type on both branches then, so you should update the other branch as well to have this type. I think you can slightly simplify it by making it a pair of concrete type also, instead of a UnionAll type (though this indeed would break the convert method handling if something isn't already a SubString of one of these 2 kinds, since we cannot convert to a Union).

Suggested change

	@NamedTuple{indent::Int, msg::SubString{<:Union{Base.AnnotatedString{String}, String}}}[
	@NamedTuple{indent::Int, msg::Union{SubString{Base.AnnotatedString{String}}, SubString{String}}}}[

[tecosaur]

Oh? I recall widening this type because of an issue I ran into when developing this PR, but October last year is too far back for me to recall what was happening clearly.

I've applied the concrete-ification you've suggested.

[vtjnash]

Yes, seems right to me. I think you can also combine a few more code paths like this also

Suggested change

	message = string(message)
	msglines = if Base._isannotated(message)
	message = Base.AnnotatedString(String(message), Base.annotations(message))
	message = string(message)
	messagestr = String(message)::String
	annots = Base._isannotated(message)
	messageattrs = annots ? Base.annotations(message) : ()
	msglines = if annots && !isempty(messageattrs)
	message = Base.AnnotatedString(messagestr, messageattrs)

[tecosaur]

I can't help but feel this is taking DRY too far...

[vtjnash]

I guess mainly it is ugly since I am taking advantage of the DRY-er code to have it use the non-annotated code path if it detects there are no relevant annotations on this (sub)string. I don't know if it is necessarily worth doing that, as it does force the code to be somewhat more linear here (longer) as each line cannot do multiple computations anymore (even just annotations and String).

[tecosaur]

In the push I recently did, I added that check too by just doing if Base._isannotated(message) && !isempty(Base.annotations(message)). FWWIW, I think the main visual impediment with the current code isn't the fact it could be slightly DRY-er but the Base. prefixes. Without them, this is the current code:

message = string(message)
msglines = if _isannotated(message) && !isempty(annotations(message))
    message = AnnotatedString(String(message), annotations(message))
    @NamedTuple{indent::Int, msg::Union{SubString{AnnotatedString{String}}, SubString{String}}}[
        (indent=0, msg=l) for l in split(chomp(message), '\n')]
else
    [(indent=0, msg=l) for l in split(
         chomp(convert(String, message)::String), '\n')]
end

[tecosaur]

Ok, the only test failure seems to be a bootstrap error with the Mingw32 windows build, everything else in CI looks happy.