Eldev test can fail if there is extra lines in the output of packaging child process

[ikappaki]

Hi,

the cider project circle ci windows tests started to unexpectedly fail recently , caused by what it appears to be extra space in the output of the child process while creating the project's package:

eldev -dtT -p test

[00:01.343]  Started up on Tue Feb 15 20:17:44 2022
[00:01.343]  Running on GNU Emacs 27.2 (build 1, x86_64-w64-mingw32)
              of 2021-03-26
[00:01.343]  Project directory: `c:/Users/circleci/project/'
...
[00:17.695]  Full command line (in directory `c:/Users/circleci/project/'):
               c:/Users/circleci/.local/bin/eldev.bat package --output-dir c:/Users/circleci/project/.eldev/27.2/local/generated --print-filename
[00:36.443]  Output of the child Eldev process:
[00:36.443]  PACK     -> .eldev/27.2/local/generated/cider-1.3.0snapshot.tar
             c:/Users/circleci/project/.eldev/27.2/local/generated/cider-1.3.0snapshot.tar
             generated
             Bootstrapping Eldev for Emacs 27.2 from MELPA Stable...
             
             
[00:36.443]  All project dependencies (including those for set `test') have been installed already or are local
[00:36.443]  (Re)installing project package `cider'...
[00:36.507]  Debugger entered--Lisp error: (file-missing "Opening input file" #("No such file or directory" 0 25 (charset cp437)) "c:/Users/circleci/project/Bootstrapping Eldev for Emacs 27.2 from MELPA Stable...")
               insert-file-contents("Bootstrapping Eldev for Emacs 27.2 from MELPA Stable..." nil nil nil nil)
               insert-file-contents-literally("Bootstrapping Eldev for Emacs 27.2 from MELPA Stable...")
               package-install-file("Bootstrapping Eldev for Emacs 27.2 from MELPA Stable...")
               eldev--package-install-file("Bootstrapping Eldev for Emacs 27.2 from MELPA Stable...")
               eldev-install-package-file("Bootstrapping Eldev for Emacs 27.2 from MELPA Stable...")
               #f(compiled-function (original dependency &rest rest) #<bytecode 0x14eddb5>) ...
               apply(#f(compiled-function (original dependency &rest rest) #<bytecode 0x14eddb5>) ) ...
               package-activate-1(#s(package-desc :name cider :version (1 3 0 -4) :summary nil :reqs ((emacs (26)) (clojure-mode (5 12)) (parseedn (1 0 6)) (queue (0 2)) (spinner (1 7)) (seq (2 22)) (sesman (0 3 2))) :kind single :archive "--eldev--" :dir nil :extras nil :signed nil) nil deps)
               package-activate(cider)
               eldev--do-activate-dependencies(cider ((:package cider :archives (("--eldev--" . "c:/Users/circleci/project/.eldev/27.2/packages/archives/--eldev--/") ("melpa-unstable" . "https://melpa.org/packages/") ("gnu" . "https://elpa.gnu.org/packages/")))) (test) nil)
               eldev--install-or-upgrade-dependencies(project (test) nil nil t nil nil)
               eldev-load-project-dependencies(test)
               eldev--do-test(nil nil)
               eldev-test()
               apply(eldev-test nil)
               eldev-cli((#("-dtT" 0 4 (charset cp437)) #("-p" 0 2 (charset cp437)) #("test" 0 4 (charset cp437))))
               (kill-emacs (eldev-cli (append (cdr (member "--" command-line-args)) nil)))
               eval((kill-emacs (eldev-cli (append (cdr (member "--" command-line-args)) nil))) t)
               command-line-1((#("--execute" 0 9 (charset cp437)) ...))
               command-line()
               normal-top-level()
...

It appears the extra bootstrap line in the child's output confuses Eldev which instead of trying to locate the file at c:/Users/circleci/project/.eldev/27.2/local/generated/cider-1.3.0snapshot.tar it tries to locate it in Bootstrapping Eldev for Emacs 27.2 from MELPA Stable....

Irrespective as to why the child process tries to reboostrap Eldev, should we improve the relevant code to gracefully handle extra output in the child process, perhaps by using a pattern to scan for the package location rather than offsetting from the last line?

(when (string= (car command) "package")
                (goto-char (point-max))
                (forward-line -2)
                (let ((point (point)))
                  (end-of-line)
                  (let ((file (buffer-substring-no-properties point (point))))
                    (forward-line)
                    (push `(,dependency-name ,file ,(looking-at "up-to-date")) eldev--local-dependency-packages))))

circle ci log file at https://gist.github.com/ikappaki/76d7d81e363a0f9244b2374d62d11a89#file-issue-eldev-circleci-cider-test-output-boot-log.

Thanks

[doublep]

It's somewhat difficult, since we cannot differentiate between stdout and stderr, and I don't want to lose stderr completely, since it is at least shown to the user in some cases... Also, doesn't help that Emacs gives them to us in mixed order, since bootstrapping must certainly have happened first. Anyway, I guess it is related to that XDG crap. Do you have a simple way to reproduce?

[ikappaki]

It's somewhat difficult, since we cannot differentiate between stdout and stderr, and I don't want to lose stderr completely, since it is at least shown to the user in some cases... Also, doesn't help that Emacs gives them to us in mixed order, since bootstrapping must certainly have happened first. Anyway, I guess it is related to that XDG crap. Do you have a simple way to reproduce?

I think I've managed to crack it ...

The issue is indeed related to XDG and is caused by the different Eldev versions used to bootstrap (latest mainline 0.10.4snapshot with XDG support) and the eldev version used thereafter (0.10.3 downloaded from Melpa stable).

The first time eldev is invoked, it bootstraps itself with 0.10.4snapshot to ~/.cache installing eldev-0.10.3 from Melpa stable. When the child is invoked, it bootstraps itself with 0.10.3 (no XDG support in this version), check to see if it has already been installed in ~/.eldev (it is not), and goes off to install itself from Melpa stable in this directory.

This is the why we get a second bootstrap in the child, resulting tot he Bootstrap message generated in the package output.

To reproduce on Linux

1. clean all possible global eldev caches, e.g.
   1.1 rm -fr ~/.eldev ~/.cache/eldev
2. download and insall Eldev as per circleci instructions
   2.1 curl -fsSL https://raw.github.com/doublep/eldev/master/webinstall/circle-eldev > x.sh && source ./x.sh
3. clone an example project with dependencies, e..g. logview:
   3.1 git clone https://github.com/doublep/logview.git
4. cd to it and run the eldev tests
   4.1 cd logview
   4.2 ~/.local/bin/eldev -dtT -p test
5. You should see the boostrap message appearing in both parent and child:

Bootstrapping Eldev for Emacs 27.2 from MELPA Stable...

[00:00.695]  Running on GNU Emacs 27.2 (build 1, x86_64-unknown-linux-gnu, GTK+ Version 3.24.30, cairo version 1.16.0)
[00:00.695]  Project directory: `/home/ikappaki/src/logview/'
[00:00.695]  No file `/home/ikappaki/.eldev/config', not applying user-specific configuration
[00:00.695]  Loading file `Eldev'...
[00:00.697]  Using package archive `melpa-stable' at `https://stable.melpa.org/packages/' with priority 200
[00:00.697]  Using package archive `melpa-unstable' at `https://melpa.org/packages/' with priority 100
[00:00.697]  No file `Eldev-local', not customizing build
[00:00.697]  Executing command `test'...
[00:00.698]  Fetching contents of package archive `melpa-stable'...
[00:00.806]  File `https://stable.melpa.org/packages/archive-contents' is not cached, retrieving...
[00:01.424]  File `https://stable.melpa.org/packages/archive-contents.sig' is not cached, retrieving...
[00:01.661]  Not fetching contents of other archive(s) as redundant

[00:01.661]  [1/2] Installing package `extmap' (1.2.1) from `melpa-stable'...
[00:01.661]  File `https://stable.melpa.org/packages/extmap-1.2.1.el' is not cached, retrieving...
[00:01.895]  File `https://stable.melpa.org/packages/extmap-1.2.1.el.sig' is not cached, retrieving...

[00:02.143]  [2/2] Installing package `datetime' (0.7.1) from `melpa-stable'...
[00:02.143]  File `https://stable.melpa.org/packages/datetime-0.7.1.tar' is not cached, retrieving...
[00:02.957]  File `https://stable.melpa.org/packages/datetime-0.7.1.tar.sig' is not cached, retrieving...
[00:03.249]  Preparing to load the project in mode `packaged'
[00:03.249]  Full command line (in directory `/home/chaos/src/logview/'):
               /home/ikappaki/.local/bin/eldev package --output-dir /home/ikappaki/src/logview/.eldev/27.2/local/generated --print-filename
[00:08.894]  Output of the child Eldev process:
[00:08.894]  Bootstrapping Eldev for Emacs 27.2 from MELPA Stable...

             PACK     -> .eldev/27.2/local/generated/logview-0.14.1snapshot.el
             /home/ikappaki/src/logview/.eldev/27.2/local/generated/logview-0.14.1snapshot.el
             generated

[00:08.894]  (Re)installing project package `logview'...
[00:08.928]  Activating project package `logview'...
...

This will not lead to a crash on Linux, but will do on MS-Windows, due to stderr being buffered causing it to appear at the end of the child's. The stderr buffering is fixed in Emacs 28 with Emacs Bug#46388. There is also a similar issue raised for stdout with Emacs Bug#47299 I should follow up. See how the Bootstrapping message in the child output appears last, causing the parse to pick up the wrong line for the package location:

PS D:\src\logview> ~/.local/bin/eldev -dtT -p test
Bootstrapping Eldev for Emacs 27.2 from MELPA Stable...

[00:00.877]  Running on GNU Emacs 27.2 (build 1, x86_64-w64-mingw32)
              of 2021-03-26
[00:00.884]  Project directory: `d:/src/logview/'
[00:00.888]  No file `c:/Users/ikappaki/AppData/Roaming/.eldev/config', not applying user-specific configuration
[00:00.899]  Loading file `Eldev'...
[00:00.944]  Using package archive `melpa-stable' at `https://stable.melpa.org/packages/' with priority 200
[00:00.952]  Using package archive `melpa-unstable' at `https://melpa.org/packages/' with priority 100
[00:00.959]  No file `Eldev-local', not customizing build
[00:00.968]  Executing command `test'...
[00:00.976]  Fetching contents of package archive `melpa-stable'...
[00:01.172]  File `https://stable.melpa.org/packages/archive-contents' is not cached, retrieving...
[00:02.082]  File `https://stable.melpa.org/packages/archive-contents.sig' is not cached, retrieving...
[00:02.498]  Not fetching contents of other archive(s) as redundant

[00:02.504]  [1/2] Installing package `extmap' (1.2.1) from `melpa-stable'...
[00:02.506]  File `https://stable.melpa.org/packages/extmap-1.2.1.el' is not cached, retrieving...
[00:02.771]  File `https://stable.melpa.org/packages/extmap-1.2.1.el.sig' is not cached, retrieving...

[00:03.180]  [2/2] Installing package `datetime' (0.7.1) from `melpa-stable'...
[00:03.183]  File `https://stable.melpa.org/packages/datetime-0.7.1.tar' is not cached, retrieving...
[00:04.023]  File `https://stable.melpa.org/packages/datetime-0.7.1.tar.sig' is not cached, retrieving...
[00:04.497]  Preparing to load the project in mode `packaged'
[00:04.502]  Full command line (in directory `d:/src/logview/'):
               c:/Users/ikappaki/.local/bin/eldev.bat package --output-dir d:/src/logview/.eldev/27.2/local/generated --print-filename
[00:12.185]  Output of the child Eldev process:
[00:12.189]  PACK     -> .eldev/27.2/local/generated/logview-0.14.1snapshot.el
             d:/src/logview/.eldev/27.2/local/generated/logview-0.14.1snapshot.el
             generated
             Bootstrapping Eldev for Emacs 27.2 from MELPA Stable...


[00:12.210]  (Re)installing project package `logview'...

[00:12.260]  Debugger entered--Lisp error: (file-missing "Opening input file" #("No such file or directory" 0 25 (cha...

It appears to me that we have two issues

1. It is possible for the master bootstrap code version to be different from the latest MELPA stable code, that can lead to obscure behaviour that is extremely difficult to debug. Should we rather try to align the two so they match? A possible solution could be to create a new github stable branch that matches with the latest versions published to MELPA stable, while the installation instructions together with the ci scripts are updated to reference that branch instead of master. This has the added advantage that the CI clients pick up a "stable" bootstrap code, rather than the latest dev snapshot which might still be in development.
2. The eldev--load-local-dependency fn which parses the child's pack output is using line offsetting to locate the package installation location. This can cause obscured errors if there is extra output that are extremely difficult to debug. Should a better approach be to use pattern matching to locate the package in the output instead of employing line offsets?

Thanks!

[doublep]

Sorry, don't have much time for Eldev currently. Just released 0.11, so that should restore webinstall and MELPA synchronization, and hopefully resolve visible effects of this. I'll leave the bug open, though, maybe we come up with a generic solution.

[doublep]

This commit doesn't fix or improve anything, but at least it makes Eldev fail explicitly in such cases, so that it's easier to understand what's wrong.