Windows 7 x64; Lilypond (2.22.1); tup (0.7.11-37-ge3c98514) freezes

[kmickle]

Good day

I've been using tup to build my LilyPond ( https://lilypond.org/ ) based project. Lilypond processes LY files (pulling in optional LYI and SCM dependencies) and generates PDFs and LOGs. In other words, behaves much like a C or a LaTeX compiler. It works just fine under Linux, but on Windows the following happens:

1. Tup freezes at 0% when "Executing commands...". The first J (J = processor core count) commands seem to execute successfully and produce outputs named " ****-tmp-*** ';
2. Tup hangs indefinitely until aborted;
3. On abort, tup throws the following J error messages: " .tup/tmp/output-***: Broken pipe
tup error: Unable to open sub-process output file after the process completed.";
4. After the abort, J frozen processes named 'gspawn-win32-helper-console.exe' (32-bit) remain, blocking the tup database until killed manually.

I suspect that might be a bug in tup. This only occurs on Windows. I've ensured tup works with the C compiler on the system, so the problem is tup-lilypond incompatibility. I've also made sure Lilypond runs fine on its own.

Minimal Example:

=====

File: test.ly

----

\fixed c { c d e }

=====

File: Tupfile

----

: *.ly |> lilypond.exe %f |> %B.pdf ^.log

=====

Please let me know if you know a way to fix it or whenever I may assist somehow in diagnostics and debugging.

[Mike Shal]

Thanks for the report!

I tried to reproduce this with your example, but I'm having trouble getting it to freeze. I'm using the same versions of tup & LilyPond:

$ tup
[ tup ] [0.016s] Scanning filesystem...
[ tup ] [0.031s] Reading in new environment variables...
[ tup ] [0.047s] Parsing Tupfiles...
 0) [0.000s] .
 [ ] 100%
[ tup ] [0.047s] No files to delete.
[ tup ] [0.047s] Generating .gitignore files...
[ tup ] [0.062s] Executing Commands...
 0) [0.906s] lilypond.exe test.ly
GNU LilyPond 2.22.1
Processing `test.ly'
Parsing...
test.ly:1: warning: no \version statement found, please add

\version "2.22.1"

for future compatibility
Interpreting music...
Preprocessing graphical objects...
Finding the ideal number of pages...
Fitting music on 1 page...
Drawing systems...
Converting to `test.pdf'...
Success: compilation successfully completed
 [ ] 100%
[ tup ] [0.984s] Updated.

I did need to add some extra exclusions to ignore the LilyPond & fontconfig fonts caches:

: *.ly |> lilypond.exe %f |> %B.pdf ^.log ^lilypond-fonts.cache ^.cache/fontconfig

But otherwise it appears to work fine in both a bourne shell and the cmd shell. Is it possible the gspawn-win32-helper-console.exe remains around as a server process on your machine, but not on mine? There was a similar problem with mspdbsrv.exe, where that process would get created as a long-running server process by the first tool that wanted to use it. If that was created under tup, then tup would wait around forever for it to exit. If that is the culprit, we may just need to add another check for tup to ignore injecting into that process.

However, while I do see gspawn-win32-helper-console.exe get used in ProcMon, it exits afterward and tup exits successfully. So, it's possible that there's a different issue.

Can you try running yours under ProcMon and seeing if there are any clues? Maybe filter on tup.exe and/or gspawn-win32-helper-console.exe and lilypond.exe to see why a subprocess might be hanging around. Sorry I don't have a better suggestion at the moment.

-Mike

--
--
tup-users mailing list
email: tup-...@googlegroups.com
unsubscribe: tup-users+...@googlegroups.com
options: http://groups.google.com/group/tup-users?hl=en
---
You received this message because you are subscribed to the Google Groups "tup-users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to tup-users+...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/tup-users/f25ff722-14c5-4bbb-9e51-2bd0841129efn%40googlegroups.com.

[kmickle]

Hi, Mike. Thank you very much for your attention.

I've scooped a ProcMon report as you suggested. You may have a look at it here:

https://disk.yandex.ru/d/7zUEQSTl8qeBTg

I haven't had time yet to delve deep into it, but a brief skim revealed nothing of value. There is some perk in 'tup' with spaces in file names (see Events ##652–655), but that is not necessarily an error. Moving 'tup' and 'lilypond' to locations with no spaces and non-ASCII symbols has no effect on the problem.

One other feature is a fair amount of failed "QueryNormalizedNameInformationFile" core calls.

I'll keep you updated in case I notice something else.

понедельник, 6 сентября 2021 г. в 04:24:31 UTC+3, mar...@gmail.com:

[kmickle]

Upd.:

I've researched further into the issue. Well, what happens looks as follows;

1. LilyPond successfully processes its inputs and outputs a file in the PostScript format;

2. In order to convert PostScript into PDF, LilyPond uses 'gspawn-win32-helper-console.exe' to invoke GhostScript (gs.exe);
3. ....but 'gspawn-win32-helper-console.exe' freezes immediately after being started. Therefore, 'gs.exe' is never started. Therefore, LilyPond freezes. Therefore, tup freezes.

Unfortunately, my expertise in DLL injections and reverse engineering is too poor to advance any further. My guts are telling me something goes terribly wrong with the injection in gspawn.

I've gathered another ProcMon report, incorporating the 'gs' and 'gspawn-win32' events as well.

https://yadi.sk/d/fNWy9bwZZWUBBQ

Hope this helps.

вторник, 7 сентября 2021 г. в 02:22:02 UTC+3, kmickle:

[kmickle]

Upd.:

GhostScript has been confirmed to be the source of the problem. Any GhostScript invocations from tup freeze, while LilyPond works fine with other output types.

I have tried using the freshest manually downloaded binaries of GhostScript x64 instead of the bundled ones, but the 'gswin64' version still freezes, and 'gswin64c' crashes. It does work outside of tup.

There is something amiss with hooked GhostScript.

вторник, 7 сентября 2021 г. в 02:22:02 UTC+3, kmickle:

Hi, Mike. Thank you very much for your attention.

[Mike Shal]

On Thu, Sep 9, 2021 at 2:57 PM kmickle <kmickl...@gmail.com> wrote:

Upd.:

GhostScript has been confirmed to be the source of the problem. Any GhostScript invocations from tup freeze, while LilyPond works fine with other output types.

I have tried using the freshest manually downloaded binaries of GhostScript x64 instead of the bundled ones, but the 'gswin64' version still freezes, and 'gswin64c' crashes. It does work outside of tup.

There is something amiss with hooked GhostScript.

Thanks so much for getting the ProcMon reports and digging into it more, that was very helpful. Although I couldn't get LilyPond to fail for me, I think I was able to reproduce what you were seeing by trying to invoke Ghostscript directly (at least, it generated a similar looking ProcMon report). Tup was hanging in a call to WaitForInputIdle(), which was given an infinite timeout. This call was present since the initial Windows support, but curiously, it hasn't ever worked. WaitForInputIdle() is odd for a Windows function in that it returns 0 for success (most Windows functions are backwards and use 0 for failure). Tup was expecting it to match other Windows-style functions, and saw that the return value wasn't 0, and continued on.

For every other process that tup hooks in test cases, the function fails immediately with a return value of -1. In the case of Ghostscript, it doesn't fail immediately, but instead waits until the timeout to return. Due to the infinite timeout that was used, this meant tup was hanging indefinitely. I'm not sure exactly why Ghostscript goes the route of a timeout, but the error code when spawning something like gcc is ERROR_NOT_GUI_PROCESS. Maybe Ghostscript qualifies as a gui process, so Windows is waiting for it to "start"? But we spawn it suspended, so it never gets there, I think.

Since the call doesn't appear to be doing what's intended, I tried removing it, and all test cases still pass. I was also able to run Ghostscript directly (and LilyPond still) with this change. Can you try http://gittup.org/tup/win32/tup-v0.7.11-50-gb4e2c649.zip and see if that works for you?

Thanks again,

-Mike

[kmickle]

Gave it a run. The following happened: tup did not block GhostScript, and it terminated correctly. However, tup was unable to detect the files GS wrote to, so the build recipe failed.

It seems the hook on GS is now non-functional.

Here's the trace:

https://yadi.sk/d/niplINUFbxnONw

пятница, 24 сентября 2021 г. в 10:53:18 UTC+3, mar...@gmail.com:

[Mike Shal]

On Sat, Sep 25, 2021 at 7:16 AM kmickle <kmickl...@gmail.com> wrote:

Gave it a run. The following happened: tup did not block GhostScript, and it terminated correctly. However, tup was unable to detect the files GS wrote to, so the build recipe failed.

It seems the hook on GS is now non-functional.

Here's the trace:

https://yadi.sk/d/niplINUFbxnONw

 

You're still expecting the output to be test.pdf, right? I see lilypond call SetRenameInformationFile (or really NtSetInformationFile with FileInformationClass == FileRenameInformation) to rename a temporary file to c:\test\test.pdf. Tup should be hooking that function, and I do see the write to c:\test\.tup\tmp\deps-3035 after that call, which should be when it is saving the file info. I'm a bit stumped why that wouldn't be working now.

Does calling ghostscript directly work for you, or does that fail to detect the output too? Here are the rules I was testing with:

: ok.ps |> gswin32 -dNOSAFER -dNOPAUSE -dBATCH -dAutoRotatePages=/None -dPrinted=false -sDEVICE=pdfwrite -o %o %f |> test-gswin32.pdf ^/gswin32.ini
: ok.ps |> gswin64 -dNOSAFER -dNOPAUSE -dBATCH -dAutoRotatePages=/None -dPrinted=false -sDEVICE=pdfwrite -o %o %f |> test-gswin64.pdf ^/gswin64.ini

With the older version, both failed with the hang that you described. With the one I posted (v0.7.11-50 or later), both succeed (and detect the file writes).

-Mike

[kmickle]

Okay, that just got interesting.

GhostScript invocation with tup crashes with the following error message:

"*** C stack overflow. Quiting..."

(( : foreach *.ps |> "C:\Program Files\gs\gs9.54.0\bin\gswin64c.exe" -dNOSAFER -dNOPAUSE -dBATCH -dAutoRotatePages=/None -dPrinted=false -sDEVICE=pdfwrite -o %o %f |> %B.pdf ))

Checked with both 'gswin64' and 'gswin64c' from the standalone distribution ( version string is: "GPL Ghostscript 9.54.0 (2021-03-30)" ).

Direct invocations succeed.

As customary, here's the ProcMon log: https://yadi.sk/d/ob7vYjZJi2brRg

воскресенье, 26 сентября 2021 г. в 16:54:57 UTC+3, mar...@gmail.com:

[Mike Shal]

Are you able to post the .ps file that you're using to test as well? Mine is attached, in case that makes any difference (it's just a fragment of a 'tup graph' piped into graphviz).

--

--
tup-users mailing list
email: tup-...@googlegroups.com
unsubscribe: tup-users+...@googlegroups.com
options: http://groups.google.com/group/tup-users?hl=en
---
You received this message because you are subscribed to the Google Groups "tup-users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to tup-users+...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/tup-users/8905209b-ebc3-4d04-acd3-0d9f6a7ba09dn%40googlegroups.com.

[kmickle]

(sorry, I seem to have forgotten to post the reply)

Both files crash GhostScript identically.

Here's my PS file in case it helps: https://yadi.sk/d/aMekXUZ-3Ug2YQ

понедельник, 27 сентября 2021 г. в 09:46:41 UTC+3, mar...@gmail.com:

[Mike Shal]

On Mon, Sep 27, 2021 at 11:18 AM kmickle <kmickl...@gmail.com> wrote:

(sorry, I seem to have forgotten to post the reply)

Both files crash GhostScript identically.

Here's my PS file in case it helps: https://yadi.sk/d/aMekXUZ-3Ug2YQ

I am a bit stumped here. I'm using your PS file, the same version of Ghostscript, and the same directory layout as far as I can tell (files in c:\test, tup in c:\Program Files\tup), but it doesn't crash for me. From your most recent Procmon report, I can see that it seems to finish writing the PDF output with a CloseFile on test.pdf, similar to my run. Afterwards I see some differences; yours does a lot of writing to the .tup/tmp/output-3042 file, which is where stdout/stderr would be captured. Presumably this is the overflow error being logged. In your run I also see 3 CreateFile calls that fail with "SHARING VIOLATION" -- these don't appear in my run. These are all on tmp files though, so it might just be a symptom of the process crashing rather than the cause of it.

Per the subject, you are testing on Windows 7, correct? I am running on Windows 10, so maybe that is the difference. Do you have access to a Win-10 machine that you can try? Unfortunately I don't think I have anything with 7 anymore...

-Mike