bug#45380: 28.0.50; Error in coloured output in Emacs 28.05(AUR package: emacs-git)

bug#45380: 28.0.50; Error in coloured output in Emacs 28.05(AUR package: emacs-git)

[Utkarsh Singh]

[-- Attachment #1: Type: text/plain, Size: 371 bytes --]

In the attached screenshot I am trying to compare eshell behaviour
for 2 colored outputs. On the left hand side 'pacman -Ss emacs' command
generates a small coloured output which works as expected but on the
right hand side 'yay -Ss emacs' generates a fairly large output in which
half of the colour in distorted. Screenshot have been obtained using
'emacs -Q' command.


[-- Attachment #2: Screenshot --]
[-- Type: image/png, Size: 305403 bytes --]

[-- Attachment #3: Type: text/plain, Size: 6368 bytes --]


In GNU Emacs 28.0.50 (build 1, x86_64-pc-linux-gnu, GTK+ Version 3.24.24, cairo version 1.17.4)
 of 2020-12-22 built on archlinux
Repository revision: 87e422f1044068a4d27e5e4bfdbc664d9e4bbc43
Repository branch: master
Windowing system distributor 'The X.Org Foundation', version 11.0.12010000
System Description: Arch Linux

Configured using:
 'configure --prefix=/usr --sysconfdir=/etc --libexecdir=/usr/lib
 --localstatedir=/var --mandir=/usr/share/man --with-gameuser=:games
 --with-sound=alsa --with-modules --without-gconf --without-gsettings
 --with-x-toolkit=gtk3 --without-xaw3d --without-compress-install
 'CFLAGS=-march=x86-64 -mtune=generic -O2 -pipe -fno-plt -flto'
 CPPFLAGS=-D_FORTIFY_SOURCE=2
 LDFLAGS=-Wl,-O1,--sort-common,--as-needed,-z,relro,-z,now'

Configured features:
XPM JPEG TIFF GIF PNG RSVG CAIRO SOUND GPM DBUS GLIB NOTIFY INOTIFY ACL
GNUTLS LIBXML2 FREETYPE HARFBUZZ M17N_FLT LIBOTF ZLIB
TOOLKIT_SCROLL_BARS GTK3 X11 XDBE XIM MODULES THREADS LIBSYSTEMD JSON
PDUMPER LCMS2

Important settings:
  value of $LC_COLLATE: C
  value of $LANG: en_IN.UTF-8
  locale-coding-system: utf-8-unix

Major mode: Lisp Interaction

Minor modes in effect:
  flyspell-mode: t
  company-tng-mode: t
  company-mode: t
  flycheck-mode: t
  winner-mode: t
  save-place-mode: t
  pdf-occur-global-minor-mode: t
  async-bytecomp-package-mode: t
  shell-dirtrack-mode: t
  amx-mode: t
  ivy-mode: t
  delete-selection-mode: t
  minions-mode: t
  global-auto-revert-mode: t
  recentf-mode: t
  show-paren-mode: t
  electric-pair-mode: t
  override-global-mode: t
  tooltip-mode: t
  global-eldoc-mode: t
  eldoc-mode: t
  electric-indent-mode: t
  mouse-wheel-mode: t
  file-name-shadow-mode: t
  global-font-lock-mode: t
  font-lock-mode: t
  auto-composition-mode: t
  auto-encryption-mode: t
  auto-compression-mode: t
  column-number-mode: t
  line-number-mode: t
  transient-mark-mode: t

Load-path shadows:
/home/utkarsh/.config/emacs/elpa/modus-operandi-theme-20201114.729/modus-operandi-theme hides /home/utkarsh/.config/emacs/elpa/modus-themes-20201221.626/modus-operandi-theme
/home/utkarsh/.config/emacs/elpa/modus-themes-20201221.626/modus-vivendi-theme hides /home/utkarsh/.config/emacs/elpa/modus-vivendi-theme-20201114.729/modus-vivendi-theme

Features:
(shadow sort mail-extr emacsbug flyspell ispell company-oddmuse
company-keywords company-etags etags fileloop company-gtags
company-dabbrev-code company-dabbrev company-files company-clang
company-capf company-cmake company-semantic company-template
company-bbdb company-tng company pcase flycheck rx dash
modus-vivendi-theme modus-themes winner notmuch hl-line notmuch-tree
notmuch-jump notmuch-hello notmuch-show notmuch-print notmuch-crypto
notmuch-mua notmuch-message notmuch-draft notmuch-maildir-fcc
notmuch-address notmuch-company notmuch-parser notmuch-wash diff-mode
coolj notmuch-query goto-addr icalendar diary-lib diary-loaddefs
notmuch-tag crm notmuch-lib notmuch-compat mm-view mml-smime smime dig
smtpmail sendmail sdcv pos-tip popup showtip esh-module esh-groups
esh-util elfeed-show elfeed-search message rmc rfc822 mml mml-sec epa
derived epg epg-config gnus-util rmail rmail-loaddefs mm-decode
mm-bodies mm-encode mail-parse rfc2231 rfc2047 rfc2045 mm-util
ietf-drums mail-prsvr mailabbrev mail-utils gmm-utils mailheader shr
kinsoku puny svg dom elfeed-csv elfeed elfeed-curl elfeed-log elfeed-db
elfeed-lib url-queue xml-query xml saveplace-pdf-view saveplace
pdf-occur ibuf-ext ibuffer ibuffer-loaddefs tablist tablist-filter
semantic/wisent/comp semantic/wisent semantic/wisent/wisent
semantic/util-modes semantic/util semantic semantic/tag semantic/lex
semantic/fw mode-local cedet pdf-isearch let-alist pdf-misc imenu
pdf-tools cus-edit cus-start cus-load pdf-view bookmark pp jka-compr
pdf-cache pdf-info tq pdf-util image-mode exif with-editor
async-bytecomp async shell server try amx s counsel xdg xref project
compile text-property-search swiper ivy delsel ivy-faces ivy-overlay
colir color org-superstar org-element avl-tree generator minions
autorevert filenotify the-org-mode-expansions org ob ob-tangle ob-ref
ob-lob ob-table ob-exp org-macro org-footnote org-src ob-comint
org-pcomplete pcomplete comint ansi-color ring org-list org-faces
org-entities time-date noutline outline org-version ob-emacs-lisp
ob-core ob-eval org-table ol org-keys org-compat org-macs org-loaddefs
format-spec find-func cal-menu calendar cal-loaddefs dired-aux dired
dired-loaddefs expand-region text-mode-expansions er-basic-expansions
thingatpt expand-region-core advice expand-region-custom recentf
tree-widget wid-edit paren elec-pair edmacro kmacro cl-extra help-mode
use-package use-package-ensure use-package-delight use-package-diminish
use-package-bind-key bind-key easy-mmode use-package-core finder-inf
info package easymenu browse-url url url-proxy url-privacy url-expand
url-methods url-history url-cookie url-domsuf url-util mailcap
url-handlers url-parse auth-source cl-seq eieio eieio-core cl-macs
eieio-loaddefs password-cache json subr-x map url-vars seq byte-opt gv
bytecomp byte-compile cconv cl-loaddefs cl-lib iso-transl tooltip eldoc
electric uniquify ediff-hook vc-hooks lisp-float-type mwheel term/x-win
x-win term/common-win x-dnd tool-bar dnd fontset image regexp-opt fringe
tabulated-list replace newcomment text-mode elisp-mode lisp-mode
prog-mode register page tab-bar menu-bar rfn-eshadow isearch timer
select scroll-bar mouse jit-lock font-lock syntax facemenu font-core
term/tty-colors frame minibuffer cl-generic cham georgian utf-8-lang
misc-lang vietnamese tibetan thai tai-viet lao korean japanese eucjp-ms
cp51932 hebrew greek romanian slovak czech european ethiopic indian
cyrillic chinese composite charscript charprop case-table epa-hook
jka-cmpr-hook help simple abbrev obarray cl-preloaded nadvice button
loaddefs faces cus-face macroexp files window text-properties overlay
sha1 md5 base64 format env code-pages mule custom widget
hashtable-print-readable backquote threads dbusbind inotify lcms2
dynamic-setting font-render-setting cairo move-toolbar gtk x-toolkit x
multi-tty make-network-process emacs)

Memory information:
((conses 16 490199 85575)
 (symbols 48 35324 1)
 (strings 32 139447 8020)
 (string-bytes 1 4127630)
 (vectors 16 50672)
 (vector-slots 8 580161 204414)
 (floats 8 364 675)
 (intervals 56 384 0)
 (buffers 984 11))

bug#45380: 28.0.50; Error in coloured output in Emacs 28.05(AUR package: emacs-git)

[Eli Zaretskii]

> From: Utkarsh Singh <utkarsh190601@gmail.com>
> Date: Wed, 23 Dec 2020 09:39:57 +0530
> 
> In the attached screenshot I am trying to compare eshell behaviour
> for 2 colored outputs. On the left hand side 'pacman -Ss emacs' command
> generates a small coloured output which works as expected but on the
> right hand side 'yay -Ss emacs' generates a fairly large output in which
> half of the colour in distorted. Screenshot have been obtained using
> 'emacs -Q' command.

Strange: I see SGR escape sequences not converted to colors, but
esh-mode definitely attempts to do that...

bug#45380: 28.0.50; Error in coloured output in Emacs 28.05(AUR package: emacs-git)

[Lars Ingebrigtsen]

Utkarsh Singh <utkarsh190601@gmail.com> writes:

> In the attached screenshot I am trying to compare eshell behaviour
> for 2 colored outputs. On the left hand side 'pacman -Ss emacs' command
> generates a small coloured output which works as expected but on the
> right hand side 'yay -Ss emacs' generates a fairly large output in which
> half of the colour in distorted. Screenshot have been obtained using
> 'emacs -Q' command.

I've seen similar bug reports about Emacs losing track of ANSI
highlighting -- especially when using programs like pacman, but I've so
far not been able to track down when/why this happens.  My theory is
that the ansi-color-apply-on-region state machine somehow becomes
confused.

If this is repeatable to you, could you apply the following patch to
record the data, and then go to some buffer,

M-: (pp my-replay (current-buffer))

write the buffer to a file, gzip it, and then send it as an attachment
to this debbugs address?

diff --git a/lisp/ansi-color.el b/lisp/ansi-color.el
index e5bfccdb8b..e1fcd3d2ce 100644
--- a/lisp/ansi-color.el
+++ b/lisp/ansi-color.el
@@ -363,6 +363,8 @@ ansi-color-filter-region
 	  (setq ansi-color-context-region (list nil (match-beginning 0)))
 	(setq ansi-color-context-region nil)))))
 
+(defvar my-replay nil)
+
 (defun ansi-color-apply-on-region (begin end &optional preserve-sequences)
   "Translates SGR control sequences into overlays or extents.
 Delete all other control sequences without processing them.
@@ -384,6 +386,7 @@ ansi-color-apply-on-region
 
 If PRESERVE-SEQUENCES is t, the sequences are hidden instead of
 being deleted."
+  (push (buffer-substring begin end) my-replay)
   (let ((codes (car ansi-color-context-region))
         (start-marker (or (cadr ansi-color-context-region)
                           (copy-marker begin)))


-- 
(domestic pets only, the antidote for overdose, milk.)
   bloggy blog: http://lars.ingebrigtsen.no

bug#45380: 28.0.50; Error in coloured output in Emacs 28.05(AUR package: emacs-git)

[Lars Ingebrigtsen]

(Please keep the debbugs address in the CCs, otherwise the mail won't
reach the bug tracker.)

Utkarsh Singh <utkarsh190601@gmail.com> writes:

> I have attached these files:
> 1. Screenshot
> 2. Complete eshell buffer after running pretty print command.
> 3. Only pretty print part of the buffer.

Thanks, with that output I could recreate the buffer...  but
unfortunately, I couldn't reproduce the error.  So perhaps my guess at
where the bug is was wrong.  There must be something more going wrong
than just `ansi-color-apply-on-region' doing stuff wrong.  Perhaps a
race condition of some kind?

Perhaps I should install an Arch Linux VM here so that I can try
reproducing this myself.  Yeah, I think I'll try that.

bug#45380: 28.0.50; Error in coloured output in Emacs 28.05(AUR package: emacs-git)

[Morgan Smith]

Hey all,

I spent a good chunk of time debugging this but I'm pretty new to emacs devel so please let me know if I say anything funny.


How to reproduce: Just keep trying some long running colored commands in eshell like "git log --color". Eventually the logic will get messed up and it'll look like the previously posted screenshot. I've seen this bugs hundred of times from all sorts of different external commands. As long as the command has enough output it's not a question of "if" but "when" will the bug show.

I think the issue is in eshell-output-filter.  Specifically I think the issue is with how it sets the eshell-last-output-start and eshell-last-input-end markers.

If we add some advice around our coloring function we can see that the coloring regions "overlap".  I assume this overlap is because coloring the region is removing the control characters and making the region smaller.  I don't think this is actually an issue, it's just something that smells like it could create bugs.

;; How to see the marker values
(defun where-are-markers (marker1 marker2)
(message "%s and %s" marker1 marker2))
(advice-add 'ansi-color-apply-on-region :before 'where-are-markers)


Thankfully, we can test out what would happen if we colored each bit of output as it comes in without worrying about regions. All we have to do is run this first:

(delete 'eshell-handle-ansi-color eshell-output-filter-functions)
(add-to-list 'eshell-preoutput-filter-functions 'ansi-color-apply)

And voila! Problem gone! Also I feel like this might run faster then the current method of filtering but I might be wrong about that.

So in conclusion: I found a workaround that might be more performant then the current coloring method but also doesn't actually fix the bug so we should probably dig deeper.


Morgan

bug#45380: 28.0.50; Error in coloured output in Emacs 28.05(AUR package: emacs-git)

[Lars Ingebrigtsen]

Morgan Smith <morgan.j.smith@outlook.com> writes:

> How to reproduce: Just keep trying some long running colored commands
> in eshell like "git log --color". Eventually the logic will get messed
> up and it'll look like the previously posted screenshot.

What Emacs version are you using?  I thought this was fixed some months
ago.

-- 
(domestic pets only, the antidote for overdose, milk.)
   bloggy blog: http://lars.ingebrigtsen.no

bug#45380: 28.0.50; Error in coloured output in Emacs 28.05(AUR package: emacs-git)

[Morgan Smith]

Ya I sent a bug report (46332) about this exact same thing happening. 
And then you fixed it so that it happened much less often. I didn't 
notice until like a day after we closed that issue. My guess is that 
there are two unrelated bugs that exhibit the exact same behavior and 
you already fixed one.

I'm using emacs master (commit 2415743) btw.

On 10/24/21 8:48 PM, Lars Ingebrigtsen wrote:
> Morgan Smith <morgan.j.smith@outlook.com> writes:
> 
>> How to reproduce: Just keep trying some long running colored commands
>> in eshell like "git log --color". Eventually the logic will get messed
>> up and it'll look like the previously posted screenshot.
> 
> What Emacs version are you using?  I thought this was fixed some months
> ago.
> 

bug#45380: 28.0.50; Error in coloured output in Emacs 28.05(AUR package: emacs-git)

[miha--- via Bug reports for GNU Emacs, the Swiss army knife of text editors]

[-- Attachment #1.1: Type: text/plain, Size: 881 bytes --]

Morgan Smith <Morgan.J.Smith@outlook.com> writes:

> Ya I sent a bug report (46332) about this exact same thing happening. 
> And then you fixed it so that it happened much less often. I didn't 
> notice until like a day after we closed that issue. My guess is that 
> there are two unrelated bugs that exhibit the exact same behavior and 
> you already fixed one.

I read that bug report and looked into this. As you said, there were two
bugs exhibiting similar behaviour. One was in ansi-color, fixed by Lars
in that bug report. The other bug, not yet fixed, is with esh-mode.el.
It uses 'insert-before-markers' to insert process output, pushing
forward the marker used by ansi-color.

A reliable reproducer is to open eshell and execute

  sh -c "printf 'NORMAL \033[32m'; sleep 1; printf 'GREEN \033[m\n'"

Please find the attached patch which fixes this.


[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #1.2: 0001-Avoid-insert-before-markers-in-eshell.patch --]
[-- Type: text/x-patch, Size: 1810 bytes --]

From 3cda385ffd292ade869abf7e39cbb45ca10349fb Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Miha=20Rihtar=C5=A1i=C4=8D?= <miha@kamnitnik.top>
Date: Mon, 25 Oct 2021 14:09:30 +0200
Subject: [PATCH] Avoid insert-before-markers in eshell

* lisp/eshell/esh-mode.el (eshell-mode): Make window point advance on
insertion.
(eshell-output-filter): Don't use insert-before-markers.
---
 lisp/eshell/esh-mode.el | 7 +++----
 1 file changed, 3 insertions(+), 4 deletions(-)

diff --git a/lisp/eshell/esh-mode.el b/lisp/eshell/esh-mode.el
index 579b01f4d1..2b5a4647e0 100644
--- a/lisp/eshell/esh-mode.el
+++ b/lisp/eshell/esh-mode.el
@@ -315,6 +315,8 @@ eshell-mode
   (setq-local bookmark-make-record-function #'eshell-bookmark-make-record)
   (setq local-abbrev-table eshell-mode-abbrev-table)
 
+  (setq-local window-point-insertion-type t)
+
   (setq-local list-buffers-directory (expand-file-name default-directory))
 
   ;; always set the tab width to 8 in Eshell buffers, since external
@@ -696,13 +698,10 @@ eshell-output-filter
                   (setq oend (+ oend nchars)))
               ;; Let the ansi-color overlay hooks run.
               (let ((inhibit-modification-hooks nil))
-                (insert-before-markers string))
+                (insert string))
               (if (= (window-start) (point))
                   (set-window-start (selected-window)
                                     (- (point) nchars)))
-              (if (= (point) eshell-last-input-end)
-                  (set-marker eshell-last-input-end
-                              (- eshell-last-input-end nchars)))
               (set-marker eshell-last-output-start ostart)
               (set-marker eshell-last-output-end (point))
               (force-mode-line-update))
-- 
2.33.0


[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 861 bytes --]

bug#45380: 28.0.50; Error in coloured output in Emacs 28.05(AUR package: emacs-git)

[Lars Ingebrigtsen]

miha@kamnitnik.top writes:

> A reliable reproducer is to open eshell and execute
>
>   sh -c "printf 'NORMAL \033[32m'; sleep 1; printf 'GREEN \033[m\n'"
>
> Please find the attached patch which fixes this.

Thanks; pushed to emacs-28.

-- 
(domestic pets only, the antidote for overdose, milk.)
   bloggy blog: http://lars.ingebrigtsen.no