Corruption in logging output

[KristofferC]

I had some problems locally with a standard @info call when run under tests output some gibberish but I thought it was something weird with my terminal.

Now I see on the Pkg tests the same type of corruption:

https://github.com/JuliaLang/Pkg.jl/actions/runs/8049275146/job/21982300062?pr=3783#step:5:1048

    update: package state changes                                         |   15     2      1             18      5.6s
    update: REPL                                                          |    2                           2      0.1s
    up9t1em:1amcEhRiRnOgR :   2 2 m 3 9 m                                           |    1                           1      0.3s
    pin: input checking         L o a d E r r o r :                                  |    3                           3      3.4s
    pin: package state changes                                            |    7                           7      6.7s
    free: input checking                                                  |    2                           2      0.4s
    free: package state changes                                           |    8                           8      8.2s
    free: REPL                      � [ 9 1 m S o m e   t e s t s   d i d   n o t   p a s s :   3 0 6 5   p a s s|e d�,[ 342 mf a i l3e d ,� [93 9emr�r[o9r1emd ,   1   b r�o[k3e9nm.��[[9319mm 
 i n   e x p�r[e3s9smi�o[n3 3smt a r t i n g   a�t[ 3/9Ums�e[r3s6/mr u n n e3r / w�o[r3k9/mP�k[g0.mj l / P k0g..1jsl
/ t e s tr/ersuonltvees t s . j l : 3  

There looks to be some attempt of ANSI codes in there like [ 9 1 m etc.

I'm not sure what is going on but seeing those ANSI codes it might be something with the styled string stuff? It could also be something else.. @tecosaur

[KristofferC]

[KristofferC]

Not only on CI. Locally:

[tecosaur]

Oh that is funky! I wonder how on earth that's happened. I'll try digging into this locally.

[KristofferC]

Just FYI, I haven't verified that this has anything to do with StyledStrings, just that it doesn't seem totally implausible.

[tecosaur]

Right. I was thinking to test this locally I would modify the print method that applies to StyledStrings to record the arguments and be able to see (1) what statements were printed, (2) have a reproducible example if anything did come up. Letting us either rule it out or give us a better starting point for further investigation.

However, since my previous comment Pkg (run with the nightly build) has been stuck precompiling 😕 (yes, for 40+ minutes). Might you know of any other places this strange behaviour occurred?

[KristofferC]

My latest screenshot was from testing LazilyInitializedFields.jl

[IanButterworth]

I tested this on b1c8e12 (from Nov 16, 2023) and saw a lot of overprinting, including prints from after the repl returned to the next prompt

[IanButterworth]

Related? timholy/ProgressMeter.jl#303

[KristofferC]

I bisected this (or at least timholy/ProgressMeter.jl#303) to 5fc5556...

Looking at JuliaLang/Pkg.jl@ff6d645...cf0019f I guess JuliaLang/Pkg.jl#3445? Or just moving Pkg out of the sysimage at all... We have to go deeper...

Edit: Reverting JuliaLang/Pkg.jl#3445 seems to fix it...

[KristofferC]

JuliaLang/Pkg.jl#3823 seems to fix it.

However, this naively feels like some bug in the Julia IO system since I don't see why passing a custom IO like this would corrupt the output. (cc @vtjnash)

[vtjnash]

Ah, yeah, that makes sense. This is just an UnstableIO quality-of-implementation problem. It could be fixed by changing it to being a <: AbtractPipe to inherit a better quality implementation (or simply an IOContext{IO} in v1.11)