Install not completing, no log messages indicating why

[Rob Groner]

I'm testing a modified matlab package I've written.  I've put print statements at the end of the install() function, and doing "spack install -v", I've confirmed that the install function in my package.py file completes.  However, it then just hangs there.  It never returns to the command prompt.

I'm running 15.3 on a RHEL7 machine.  I tried this on a Fedora 31 machine and it seemed to have no problems.

I found an old Spack issue #10493 (did not appear it was ever marked resolved) that also talked about the install hanging and suggested it might be because it is a network mapped directory.  Where I am installing IS a network mapped directory.  But I then told it to install to /tmp/test and it hung there as well.

More than anything, it would just be helpful to get some idea what the install is doing when it hung.  Is there any way to get even more verbose output, or should I start spamming "print()" statements into the spack library?

Thanks,

Rob

[Pariksheet Nanda]

Hi Rob,

On 9/19/20 2:18 PM, Rob Groner wrote:
> Is there any way to get even more verbose output

There's always `spack -d install -v ...` and use more -d's for verbosity
as described in `spack help --all`


> Rob
Pariksheet

[Rob Groner]

Thank you for that, that gave me a lot more information.

The first question is why it took 2 1/2 hours to go from copying the package.py file to creating a license symlink.

==> [2020-09-21-17:18:52.566618, 18123] Installing /vagrant/spack-dev/packages/matlab/package.py to /opt/aci/sw/linux-centos7-x86_64/gcc-8.3.1/matlab-R2019b/.spack/repos/spack-dev/packages/matlab

==> [2020-09-21-19:34:22.536297, 18123] Added local symlink /opt/aci/sw/linux-centos7-x86_64/gcc-8.3.1/matlab-R2019b/licenses/license.dat to global license file

 

I'm obviously thinking it didn't take all that time just to add the symlink.  So whatever happened during that time, it didn't print a debug message.  I'm certain the previous instances of it not completing the installation weren't because of this, as I've left it overnight before, not just for a couple hours.

Given that it budged after stalling for a couple hours, I'm not ready to see that it's finally found its stopping place, but it has output messages like this since then:

==> [2020-09-21-19:34:25.721126, 18123] READ LOCK (database): /opt/aci/sw/.spack-db/lock[0:0] [Acquiring] 

==> [2020-09-21-19:34:25.721436, 18123] read locking [0:0]: timeout 3 sec

==> [2020-09-21-19:34:25.721613, 18123] READ LOCK (database): /opt/aci/sw/.spack-db/lock[0:0] [Acquired at 19:34:25.721577] 

==> [2020-09-21-19:34:25.721997, 18123] READ LOCK (database): /opt/aci/sw/.spack-db/lock[0:0] [Releasing] 

==> [2020-09-21-19:34:25.722244, 18123] READ LOCK (database): /opt/aci/sw/.spack-db/lock[0:0] [Released at 19:34:25.722209] 

==> [2020-09-21-19:34:25.722361, 18123] READ LOCK (database): /opt/aci/sw/.spack-db/lock[0:0] [Acquiring] 

==> [2020-09-21-19:34:25.722600, 18123] read locking [0:0]: timeout 3 sec

==> [2020-09-21-19:34:25.722740, 18123] READ LOCK (database): /opt/aci/sw/.spack-db/lock[0:0] [Acquired at 19:34:25.722707] 

==> [2020-09-21-19:34:25.722970, 18123] READ LOCK (database): /opt/aci/sw/.spack-db/lock[0:0] [Releasing] 

==> [2020-09-21-19:34:25.723128, 18123] READ LOCK (database): /opt/aci/sw/.spack-db/lock[0:0] [Released at 19:34:25.723095] 

==> [2020-09-21-19:34:25.727953, 18123] WRITE: matlab@R2019b%g...@8.3.1 key=<key> mode=silent arch=linux-centos7-x86_64/mu6h7ik [/opt/spack/share/spack/modules/linux-centos7-x86_64/matlab-R2019b-gcc-8.3.1-mu6h7ik]

==> [2020-09-21-19:34:25.791735, 18123] Writing manifest file: No manifest from binary

It appears to be repeating somewhat, but I'm waiting to see if it continues to repeat.

Rob

[Rob Groner]

Well, so that time...it finished the install.  I've one other system to try this on, and I'll use the debug messages to see if it hangs on something.

I would still like to find out why it's taking 2 1/2 hours in the middle of the install to create the license link file, though.

[Gamblin, Todd]

Is this on an NFS volume in an environment?  Any chance you can point us to your environment somehow?

-- 
You received this message because you are subscribed to the Google Groups "Spack" group.
To unsubscribe from this group and stop receiving emails from it, send an email to spack+un...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/spack/efc616c2-895c-4ec0-a99d-0398e64fe501n%40googlegroups.com.

[Groner, Rob]

Well, I've tried it 3 times.  

1) Fedora 31/bare metal, no spack environment, local drive:  success

2) RHEL7/vagrant box, yes spack environment, local drive: hanged

3) RHEL7/VMware, yes spack environment, NFS volume: hanged

Yesterday, #2 was the one that unexpected completed yesterday.  I'm sure it didn't before.

If by "point us to your environment" you mean get logged into the system so you can poke around, that's probably going to be difficult, though I'd be in favor of it.  I'll ask around.

Let me try #2 again and see if it hangs again.  Being a vagrant box, that should be easily sharable.

Thanks Todd,

Rob

---

From: Gamblin, Todd <gamb...@llnl.gov>
Sent: Monday, September 21, 2020 7:56 PM
To: Groner, Rob <rug...@psu.edu>
Cc: Spack <sp...@googlegroups.com>
Subject: Re: [spack] Install not completing, no log messages indicating why

 

[Rob Groner]

Ok, I ran the install again on my vagrant box.  It again took 2 1/2 hours to do something AFTER install() had completed.  This time the gap in the log was after the license symlink was written and before the "Reading config file <path>/modules.yaml". 

Since it completed successfully on my vagrant box, I'm going to try to setup a test environment on VMWare with the NFS mount to see what happens.  

Rob

[Rob Groner]

Soo....at some point after posting that last message in Sept, it started working.  If I did anything to make it work, I unfortunately didn't note it.  But either way, the install of Ansys would complete and no longer hang.

Now, without having changed anything on my end (so in other words, nothing on the host that I'm using to build this), and without having changed Spack versions (0.15.4), it has started having the problem again.

I'm using RHEL7 on a VMWare machine and attempting to install to an NFS mount. Again, for the past 3 months, this has been working.  Now it's not.  It's possible something network related changed, but I don't know how I would go about finding that out.  The actual install() function completes, but Spack does not ever come back.

I did this last install with lots of debug and verbose messages, and there is an error about the io.BufferedReader having a reentrant call inside it, but I think those messages came after I started hitting Ctrl-C to get control back.

Here is the relevant portion of the output:

-----------------------------------------------------------------------------------------------------------

Configuring Help ...

Running "/opt/aci/sw/ansys/2019R3_gcc-4.8.5-qn3/v195/Tools/mono/Linux64/bin/mono" "/opt/aci/sw/ansys/2019R3_gcc-4.8.5-qn3/v195/commonfiles/help/HelpViewer/ANSYSHelpConfigurationTool.exe" --setLocal

Exiting

==> [2021-01-03-13:50:05.018090] Installing /opt/aci/spack-repo/packages/ansys/license.preferences.xml to /opt/aci/sw/ansys/2019R3_gcc-4.8.5-qn3/shared_files/licensing

==> [2021-01-03-13:50:05.031053, 26721] FileNotFoundError: [Errno 2] No such file or directory: '/opt/aci/sw/ansys/2019R3_gcc-4.8.5-qn3/.spack/repos'

==> [2021-01-03-13:50:05.031583, 26721] Installing /tmp/rug262/spack-stage/spack-stage-ansys-2019R3-qn3u52h4qgreiukrclbqvxrkkffvfizc/spack-build-out.txt to /opt/aci/sw/ansys/2019R3_gcc-4.8.5-qn3/.spack/spack-build-out.txt

==> [2021-01-03-13:50:05.035670, 26721] Installing /tmp/rug262/spack-stage/spack-stage-ansys-2019R3-qn3u52h4qgreiukrclbqvxrkkffvfizc/spack-build-env.txt to /opt/aci/sw/ansys/2019R3_gcc-4.8.5-qn3/.spack/spack-build-env.txt

==> [2021-01-03-13:50:05.046634, 26721] Installing /opt/aci/spack-repo/packages/ansys/package.py to /opt/aci/sw/ansys/2019R3_gcc-4.8.5-qn3/.spack/repos/spack-dev/packages/ansys

Signal received : entering python shell.

Traceback:

  File "/opt/aci/spack/bin/spack", line 64, in <module>

    sys.exit(spack.main.main())

  File "/opt/global/RedHat-7/20210102/spack/lib/spack/spack/main.py", line 762, in main

    return _invoke_command(command, parser, args, unknown)

  File "/opt/global/RedHat-7/20210102/spack/lib/spack/spack/main.py", line 490, in _invoke_command

    return_val = command(parser, args)

  File "/opt/global/RedHat-7/20210102/spack/lib/spack/spack/cmd/install.py", line 285, in install

    env.install_all(args)

  File "/opt/global/RedHat-7/20210102/spack/lib/spack/spack/environment.py", line 1303, in install_all

    self._install(spec, **kwargs)

  File "/opt/global/RedHat-7/20210102/spack/lib/spack/spack/environment.py", line 1261, in _install

    spec.package.do_install(**install_args)

  File "/opt/global/RedHat-7/20210102/spack/lib/spack/spack/package.py", line 1477, in do_install

    builder.install(**kwargs)

  File "/opt/global/RedHat-7/20210102/spack/lib/spack/spack/installer.py", line 1547, in install

    self._install_task(task, **kwargs)

  File "/opt/global/RedHat-7/20210102/spack/lib/spack/spack/installer.py", line 1183, in _install_task

    pkg, build_process, dirty=dirty, fake=fake)

  File "/opt/global/RedHat-7/20210102/spack/lib/spack/spack/build_environment.py", line 901, in fork

    child_result = parent_pipe.recv()

  File "/usr/lib64/python3.6/multiprocessing/connection.py", line 250, in recv

    buf = self._recv_bytes()

  File "/usr/lib64/python3.6/multiprocessing/connection.py", line 407, in _recv_bytes

    buf = self._recv(4)

  File "/usr/lib64/python3.6/multiprocessing/connection.py", line 379, in _recv

    chunk = read(handle, remaining)

>>> Signal received : entering python shell.

Traceback:

  File "/opt/aci/spack/bin/spack", line 64, in <module>

    sys.exit(spack.main.main())

  File "/opt/global/RedHat-7/20210102/spack/lib/spack/spack/main.py", line 762, in main

    return _invoke_command(command, parser, args, unknown)

  File "/opt/global/RedHat-7/20210102/spack/lib/spack/spack/main.py", line 490, in _invoke_command

    return_val = command(parser, args)

  File "/opt/global/RedHat-7/20210102/spack/lib/spack/spack/cmd/install.py", line 285, in install

    env.install_all(args)

  File "/opt/global/RedHat-7/20210102/spack/lib/spack/spack/environment.py", line 1303, in install_all

    self._install(spec, **kwargs)

  File "/opt/global/RedHat-7/20210102/spack/lib/spack/spack/environment.py", line 1261, in _install

    spec.package.do_install(**install_args)

  File "/opt/global/RedHat-7/20210102/spack/lib/spack/spack/package.py", line 1477, in do_install

    builder.install(**kwargs)

  File "/opt/global/RedHat-7/20210102/spack/lib/spack/spack/installer.py", line 1547, in install

    self._install_task(task, **kwargs)

  File "/opt/global/RedHat-7/20210102/spack/lib/spack/spack/installer.py", line 1183, in _install_task

    pkg, build_process, dirty=dirty, fake=fake)

  File "/opt/global/RedHat-7/20210102/spack/lib/spack/spack/build_environment.py", line 901, in fork

    child_result = parent_pipe.recv()

  File "/usr/lib64/python3.6/multiprocessing/connection.py", line 250, in recv

    buf = self._recv_bytes()

  File "/usr/lib64/python3.6/multiprocessing/connection.py", line 407, in _recv_bytes

    buf = self._recv(4)

  File "/usr/lib64/python3.6/multiprocessing/connection.py", line 379, in _recv

    chunk = read(handle, remaining)

  File "/opt/global/RedHat-7/20210102/spack/lib/spack/spack/util/debug.py", line 28, in debug_handler

    i.interact(message)

  File "/usr/lib64/python3.6/code.py", line 228, in interact

    line = self.raw_input(prompt)

  File "/usr/lib64/python3.6/code.py", line 275, in raw_input

    return input(prompt)

>>> ==> [2021-01-03-22:34:52.844195, 26645] Error: Failed to install ansys due to RuntimeError: reentrant call inside <_io.BufferedReader name='<stdin>'>

==> [2021-01-03-22:34:52.844573, 26645] Flagging ansys as failed: reentrant call inside <_io.BufferedReader name='<stdin>'>

==> [2021-01-03-22:34:52.849403, 26645] WRITE LOCK (ansys): /opt/aci/sw/.spack-db/prefix_failures[4736563551886430498:1] [Acquiring] 

==> [2021-01-03-22:34:52.850604, 26645] write locking [4736563551886430498:1]: timeout None sec

==> [2021-01-03-22:34:52.851063, 26645] WRITE LOCK (ansys): /opt/aci/sw/.spack-db/prefix_failures[4736563551886430498:1] [Acquired at 22:34:52.851028] 

==> [2021-01-03-22:34:52.851219, 26645] READ LOCK (database): /opt/aci/sw/.spack-db/lock[0:0] [Acquiring] 

==> [2021-01-03-22:34:52.852281, 26645] read locking [0:0]: timeout 3 sec

==> [2021-01-03-22:34:52.852373, 26645] READ LOCK (database): /opt/aci/sw/.spack-db/lock[0:0] [Acquired at 22:34:52.852348] 

==> [2021-01-03-22:34:52.853406, 26645] READ LOCK (database): /opt/aci/sw/.spack-db/lock[0:0] [Releasing] 

==> [2021-01-03-22:34:52.853717, 26645] READ LOCK (database): /opt/aci/sw/.spack-db/lock[0:0] [Released at 22:34:52.853680] 

Signal received : entering python shell.

Traceback:

  File "/opt/aci/spack/bin/spack", line 64, in <module>

    sys.exit(spack.main.main())

  File "/opt/global/RedHat-7/20210102/spack/lib/spack/spack/main.py", line 762, in main

    return _invoke_command(command, parser, args, unknown)

  File "/opt/global/RedHat-7/20210102/spack/lib/spack/spack/main.py", line 490, in _invoke_command

    return_val = command(parser, args)

  File "/opt/global/RedHat-7/20210102/spack/lib/spack/spack/cmd/install.py", line 285, in install

    env.install_all(args)

  File "/opt/global/RedHat-7/20210102/spack/lib/spack/spack/environment.py", line 1303, in install_all

    self._install(spec, **kwargs)

  File "/opt/global/RedHat-7/20210102/spack/lib/spack/spack/environment.py", line 1261, in _install

    spec.package.do_install(**install_args)

  File "/opt/global/RedHat-7/20210102/spack/lib/spack/spack/package.py", line 1477, in do_install

    builder.install(**kwargs)

  File "/opt/global/RedHat-7/20210102/spack/lib/spack/spack/installer.py", line 1595, in install

    pkg.remove_prefix()

  File "/opt/global/RedHat-7/20210102/spack/lib/spack/spack/package.py", line 1113, in remove_prefix

    spack.store.layout.remove_install_directory(self.spec)

  File "/opt/global/RedHat-7/20210102/spack/lib/spack/spack/directory_layout.py", line 111, in remove_install_directory

    shutil.rmtree(path)

  File "/usr/lib64/python3.6/shutil.py", line 486, in rmtree

    _rmtree_safe_fd(fd, path, onerror)

  File "/usr/lib64/python3.6/shutil.py", line 424, in _rmtree_safe_fd

    _rmtree_safe_fd(dirfd, fullname, onerror)

  File "/usr/lib64/python3.6/shutil.py", line 424, in _rmtree_safe_fd

    _rmtree_safe_fd(dirfd, fullname, onerror)

  File "/usr/lib64/python3.6/shutil.py", line 424, in _rmtree_safe_fd

    _rmtree_safe_fd(dirfd, fullname, onerror)

  [Previous line repeated 2 more times]

  File "/usr/lib64/python3.6/shutil.py", line 412, in _rmtree_safe_fd

    orig_st = os.stat(name, dir_fd=topfd, follow_symlinks=False)

>>> Signal received : entering python shell.

Traceback:

  File "/opt/aci/spack/bin/spack", line 64, in <module>

    sys.exit(spack.main.main())

  File "/opt/global/RedHat-7/20210102/spack/lib/spack/spack/main.py", line 762, in main

    return _invoke_command(command, parser, args, unknown)

  File "/opt/global/RedHat-7/20210102/spack/lib/spack/spack/main.py", line 490, in _invoke_command

    return_val = command(parser, args)

  File "/opt/global/RedHat-7/20210102/spack/lib/spack/spack/cmd/install.py", line 285, in install

    env.install_all(args)

  File "/opt/global/RedHat-7/20210102/spack/lib/spack/spack/environment.py", line 1303, in install_all

    self._install(spec, **kwargs)

  File "/opt/global/RedHat-7/20210102/spack/lib/spack/spack/environment.py", line 1261, in _install

    spec.package.do_install(**install_args)

  File "/opt/global/RedHat-7/20210102/spack/lib/spack/spack/package.py", line 1477, in do_install

    builder.install(**kwargs)

  File "/opt/global/RedHat-7/20210102/spack/lib/spack/spack/installer.py", line 1595, in install

    pkg.remove_prefix()

  File "/opt/global/RedHat-7/20210102/spack/lib/spack/spack/package.py", line 1113, in remove_prefix

    spack.store.layout.remove_install_directory(self.spec)

  File "/opt/global/RedHat-7/20210102/spack/lib/spack/spack/directory_layout.py", line 111, in remove_install_directory

    shutil.rmtree(path)

  File "/usr/lib64/python3.6/shutil.py", line 486, in rmtree

    _rmtree_safe_fd(fd, path, onerror)

  File "/usr/lib64/python3.6/shutil.py", line 424, in _rmtree_safe_fd

    _rmtree_safe_fd(dirfd, fullname, onerror)

  File "/usr/lib64/python3.6/shutil.py", line 424, in _rmtree_safe_fd

    _rmtree_safe_fd(dirfd, fullname, onerror)

  File "/usr/lib64/python3.6/shutil.py", line 424, in _rmtree_safe_fd

    _rmtree_safe_fd(dirfd, fullname, onerror)

  [Previous line repeated 2 more times]

  File "/usr/lib64/python3.6/shutil.py", line 412, in _rmtree_safe_fd

    orig_st = os.stat(name, dir_fd=topfd, follow_symlinks=False)

  File "/opt/global/RedHat-7/20210102/spack/lib/spack/spack/util/debug.py", line 28, in debug_handler

    i.interact(message)

  File "/usr/lib64/python3.6/code.py", line 228, in interact

    line = self.raw_input(prompt)

  File "/usr/lib64/python3.6/code.py", line 275, in raw_input

    return input(prompt)

>>> Traceback (most recent call last):

  File "/opt/global/RedHat-7/20210102/spack/lib/spack/spack/installer.py", line 1547, in install

    self._install_task(task, **kwargs)

  File "/opt/global/RedHat-7/20210102/spack/lib/spack/spack/installer.py", line 1183, in _install_task

    pkg, build_process, dirty=dirty, fake=fake)

  File "/opt/global/RedHat-7/20210102/spack/lib/spack/spack/build_environment.py", line 901, in fork

    child_result = parent_pipe.recv()

  File "/usr/lib64/python3.6/multiprocessing/connection.py", line 250, in recv

    buf = self._recv_bytes()

  File "/usr/lib64/python3.6/multiprocessing/connection.py", line 407, in _recv_bytes

    buf = self._recv(4)

  File "/usr/lib64/python3.6/multiprocessing/connection.py", line 379, in _recv

    chunk = read(handle, remaining)

  File "/opt/global/RedHat-7/20210102/spack/lib/spack/spack/util/debug.py", line 28, in debug_handler

    i.interact(message)

  File "/usr/lib64/python3.6/code.py", line 228, in interact

    line = self.raw_input(prompt)

  File "/usr/lib64/python3.6/code.py", line 275, in raw_input

    return input(prompt)

  File "/opt/global/RedHat-7/20210102/spack/lib/spack/spack/util/debug.py", line 28, in debug_handler

    i.interact(message)

  File "/usr/lib64/python3.6/code.py", line 228, in interact

    line = self.raw_input(prompt)

  File "/usr/lib64/python3.6/code.py", line 275, in raw_input

    return input(prompt)

RuntimeError: reentrant call inside <_io.BufferedReader name='<stdin>'>

During handling of the above exception, another exception occurred:

Traceback (most recent call last):

  File "/opt/aci/spack/bin/spack", line 64, in <module>

    sys.exit(spack.main.main())

  File "/opt/global/RedHat-7/20210102/spack/lib/spack/spack/main.py", line 762, in main

    return _invoke_command(command, parser, args, unknown)

  File "/opt/global/RedHat-7/20210102/spack/lib/spack/spack/main.py", line 490, in _invoke_command

    return_val = command(parser, args)

  File "/opt/global/RedHat-7/20210102/spack/lib/spack/spack/cmd/install.py", line 285, in install

    env.install_all(args)

  File "/opt/global/RedHat-7/20210102/spack/lib/spack/spack/environment.py", line 1303, in install_all

    self._install(spec, **kwargs)

  File "/opt/global/RedHat-7/20210102/spack/lib/spack/spack/environment.py", line 1261, in _install

    spec.package.do_install(**install_args)

  File "/opt/global/RedHat-7/20210102/spack/lib/spack/spack/package.py", line 1477, in do_install

    builder.install(**kwargs)

  File "/opt/global/RedHat-7/20210102/spack/lib/spack/spack/installer.py", line 1595, in install

    pkg.remove_prefix()

  File "/opt/global/RedHat-7/20210102/spack/lib/spack/spack/package.py", line 1113, in remove_prefix

    spack.store.layout.remove_install_directory(self.spec)

  File "/opt/global/RedHat-7/20210102/spack/lib/spack/spack/directory_layout.py", line 111, in remove_install_directory

    shutil.rmtree(path)

  File "/usr/lib64/python3.6/shutil.py", line 486, in rmtree

    _rmtree_safe_fd(fd, path, onerror)

  File "/usr/lib64/python3.6/shutil.py", line 424, in _rmtree_safe_fd

    _rmtree_safe_fd(dirfd, fullname, onerror)

  File "/usr/lib64/python3.6/shutil.py", line 424, in _rmtree_safe_fd

    _rmtree_safe_fd(dirfd, fullname, onerror)

  File "/usr/lib64/python3.6/shutil.py", line 424, in _rmtree_safe_fd

    _rmtree_safe_fd(dirfd, fullname, onerror)

  [Previous line repeated 2 more times]

  File "/usr/lib64/python3.6/shutil.py", line 412, in _rmtree_safe_fd

    orig_st = os.stat(name, dir_fd=topfd, follow_symlinks=False)

  File "/opt/global/RedHat-7/20210102/spack/lib/spack/spack/util/debug.py", line 28, in debug_handler

    i.interact(message)

  File "/usr/lib64/python3.6/code.py", line 228, in interact

    line = self.raw_input(prompt)

  File "/usr/lib64/python3.6/code.py", line 275, in raw_input

    return input(prompt)

  File "/opt/global/RedHat-7/20210102/spack/lib/spack/spack/util/debug.py", line 28, in debug_handler

    i.interact(message)

  File "/usr/lib64/python3.6/code.py", line 228, in interact

    line = self.raw_input(prompt)

  File "/usr/lib64/python3.6/code.py", line 275, in raw_input

    return input(prompt)

RuntimeError: reentrant call inside <_io.BufferedReader name='<stdin>'>