External Method issue following Zope 4 > 5 upgrade

kenara · March 30, 2023, 3:05pm

Using buildout, I upgraded a Zope 4 instance to Zope 5.8.1. First, I upgraded Ubuntu to 22.04. The OS upgrade appears to have replaced the Python 3.7.5 used by Zope with Python 3.10.6. After the upgrade, Zope started and runs fine (Python Version 3.10.6 showing in Control Panel).

But now my External methods fail with "external method could not be called because it is None". The External Methods do not appear broken in the ZMI.

The modules containing my External Methods have not moved from /opt/zope/Extensions. Even simple External methods that call builtin Python modules "couldn't be found."

I have another similar Zope 5 with External Methods and modules in /opt/zope/Extensions and it works fine.

Any suggestions welcome!

Apologies for crossposting:
python - After Zope 4 > 5 upgrade, "external method could not be called because it is None" - Stack Overflow

dieter · March 30, 2023, 4:23pm

Ken D. via Plone Community wrote at 2023-3-30 15:16 +0000:

...
But now my External methods fail with "external method could not be called because it is None". The External Methods do not appear broken in the ZMI.

This means that ExternalMethod.filepath has returned None.

I would would run Zope in an interactive interpreter
(e.g. via bin/{instance|cliet1} debug or zconsole debug)
and then debug the call <your_external_method>.filepath() to find out why.

kenara · March 30, 2023, 5:14pm

Thanks Dieter. Here's what happened, first with debug:

root@test:/opt/zope# /opt/zope/bin/client1 debug
Starting debugger (the name "app" is bound to the top-level Zope object)
Traceback (most recent call last):
  File "/opt/zope/parts/client1/bin/interpreter", line 109, in <module>
    exec(_val)
  File "<string>", line 1, in <module>
  File "/opt/zope/eggs/Zope-5.8.1-py3.10.egg/Zope2/Startup/run.py", line 24, in configure_wsgi
    starter = Zope2.Startup.get_wsgi_starter()
  File "/opt/zope/eggs/Zope-5.8.1-py3.10.egg/Zope2/Startup/__init__.py", line 17, in get_wsgi_starter
    from Zope2.Startup.starter import WSGIStarter
  File "/opt/zope/eggs/Zope-5.8.1-py3.10.egg/Zope2/Startup/starter.py", line 21, in <module>
    from zope.event import notify
ModuleNotFoundError: No module named 'zope.event'
>>>

and now with fg:

root@test:/opt/zope# /opt/zope/bin/client1 fg
2023-03-30 17:01:59,024 INFO    [ZEO.ClientStorage:274][MainThread] zeostorage ClientStorage (pid=254785) created RW/normal for storage: '1'
2023-03-30 17:01:59,024 INFO    [ZEO.cache:209][MainThread] created temporary cache file 7
2023-03-30 17:01:59,033 INFO    [ZEO.asyncio.base:107][zeostorage zeo client networking thread] Connected ZEO.asyncio.client.Protocol(('127.0.0.1', 8100), '1', False)
2023-03-30 17:01:59,036 INFO    [ZEO.ClientStorage:448][zeostorage zeo client networking thread] zeostorage Connected to storage: ('localhost', 8100)
2023-03-30 17:01:59,255 INFO    [chameleon.config:38][MainThread] directory cache: /opt/zope/var/cache.
2023-03-30 17:01:59,423 INFO    [Zope:42][MainThread] Ready to handle requests
Starting server in PID 254785.
2023-03-30 17:01:59,426 INFO    [waitress:486][MainThread] Serving on http://0.0.0.0:11111
2023-03-30 17:02:01,937 ERROR   [Zope.SiteErrorLog:238][waitress-0] 1680195721.93654370.06515238506376375 http://<IP address>:11111/motorbike/manage
Traceback (innermost last):
  Module ZPublisher.WSGIPublisher, line 181, in transaction_pubevents
  Module ZPublisher.WSGIPublisher, line 390, in publish_module
  Module ZPublisher.WSGIPublisher, line 285, in publish
  Module ZPublisher.mapply, line 85, in mapply
  Module ZPublisher.WSGIPublisher, line 68, in call_object
  Module OFS.SimpleItem, line 309, in manage
zExceptions.Redirect: http://<IP address>:11111/motorbike/manage_main

I guess something has gone wrong with zope.event ...?

dieter · March 30, 2023, 6:00pm

Ken D. via Plone Community wrote at 2023-3-30 17:24 +0000:

Thanks Dieter. Here's what happened, first with debug:

root@test:/opt/zope# /opt/zope/bin/client1 debug
Starting debugger (the name "app" is bound to the top-level Zope object)
Traceback (most recent call last):
...
 File "/opt/zope/eggs/Zope-5.8.1-py3.10.egg/Zope2/Startup/starter.py", line 21, in <module>
   from zope.event import notify
ModuleNotFoundError: No module named 'zope.event'
>>>

This does not look like an ExternalMethod related problem.

Apparently, something went wrong with your installation
-- but you wrote earlier that the ExternalMethod looks good
in the ZMI - you should have been able to go beyond the point above.

kenara · March 30, 2023, 7:33pm

Yes, I mentioned that the ZMI product icons were not 'broken' but I haven't seen broken icons for a long time. Do they still exist?

Under 5.8.1 and Python 3.10, I can call /manage on my External Methods but if I try to POST changes to /manage_edit, I get this:

2023-03-30 19:17:08,912 ERROR [Zope.SiteErrorLog:238][waitress-3] 1680203828.9120720.7024144543278077 http://<IP addr>:11111/motorbike/manage_edit Traceback (innermost last): Module ZPublisher.WSGIPublisher, line 181, in transaction_pubevents Module ZPublisher.WSGIPublisher, line 390, in publish_module Module ZPublisher.WSGIPublisher, line 285, in publish Module ZPublisher.mapply, line 85, in mapply Module ZPublisher.WSGIPublisher, line 68, in call_object Module Products.ExternalMethod.ExternalMethod, line 153, in manage_edit Module Products.ExternalMethod.ExternalMethod, line 159, in getFunction Module App.Extensions, line 172, in getObject zExceptions.NotFound: The specified module, 'motorbike', couldn't be found.

Viewing the External Method ('test' tab) gives this: <ExternalMethod at motorbike>.

Reverting to 4.5.1 and Python 3.7 - the only changes I made - I can once again use my External Methods. Running buildout with 5.8.1 causes the trouble. 5.8.1 with Python 3.7.5 also gives the error.

Here's the top of my buildout.cfg:

[buildout]
extends =
    https://zopefoundation.github.io/Zope/releases/4.5.1/versions-prod.cfg
#    https://zopefoundation.github.io/Zope/releases/5.8.1/versions-prod.cfg
parts =
    client1
    client2
    client3
    zeo

[client1]
recipe = plone.recipe.zope2instance
zeo-client = true
zeo-address = ${zeo:zeo-address}
eggs =
    Products.TemporaryFolder
    Products.ZCatalog
    Products.ExternalMethod
    Products.PythonScripts
    Products.SiteErrorLog

dieter · March 30, 2023, 8:16pm

Ken D. via Plone Community wrote at 2023-3-30 19:43 +0000:

...
Yes, I mentioned that the ZMI product icons were not 'broken' but I haven't seen broken icons for a long time. Do they still exist?

The error you have shown for bin/client1 debug happens
very early -- during the startup sequence;
with this error, Zope should not start at all.
This means you should not be able to call manage at all.

You can still have broken icons BUT they indicate
that the corresponding persistent object could not be loaded from
the ZODB (because the object's code is missing).
This can happen for an ExternalMethod when Products.ExternalMethod
is not installed.
When your specific method's code (in contrast to the general
ExternalMethod code) cannot be found, you will not see a broken
icon.

Under 5.8.1 and Python 3.10, I can call /manage on my External Methods but if I try to POST changes to /manage_edit, I get this:

You can call manage: this means Zope has started.
It is therefore very strange that bin/client1 debug did not start
but fails during startup with an import problem for zope.event.

It is sad that we cannot use this to easily debug <method>.filepath.

2023-03-30 19:17:08,912 ERROR [Zope.SiteErrorLog:238][waitress-3] 1680203828.9120720.7024144543278077 http://<IP addr>:11111/motorbike/manage_edit Traceback (innermost last): ... Module Products.ExternalMethod.ExternalMethod, line 159, in getFunction Module App.Extensions, line 172, in getObject zExceptions.NotFound: The specified module, 'motorbike', couldn't be found.

you can add a code breakpoint (i.e. import pdb; pdb.set_trace())
into the code and
start your Zope in foreground.
This, too, would allow you to debug why your module is not found --
however in a more difficult way.

Reverting to 4.5.1 and Python 3.7 - the only changes I made - I can once again use my External Methods. Running buildout with 5.8.1 causes the trouble. 5.8.1 with Python 3.7.5 also gives the error.

I checked that Products.ExternalMethod works wiht Zope 5.8.1.
I have used Python 3.9, but Python 3.10 should not make a difference.

Here's the top of my buildout.cfg:

[buildout]
extends =
   https://zopefoundation.github.io/Zope/releases/4.5.1/versions-prod.cfg
#    https://zopefoundation.github.io/Zope/releases/5.8.1/versions-prod.cfg
parts =
   client1
   client2
   client3
   zeo

[client1]
recipe = plone.recipe.zope2instance
zeo-client = true
zeo-address = ${zeo:zeo-address}
eggs =
   Products.TemporaryFolder
   Products.ZCatalog
   Products.ExternalMethod
   Products.PythonScripts
   Products.SiteErrorLog

I would expect Zope somewhere in the eggs definition above.

That bin/client1 debug does not work hints towards some problem
with your buildout (or your Python installation).

I have seen namespace package problems (zope is such a namespace package),
when some of its subpackages (e.g. zope.interface) was
directly installed in Python (maybe comes with the system Python)
and others have been installed by buildout (e.g. zope.event).
Since then, I avoid the use of the system Python
and keep installations in the Python installation to a minimum
(essentially setuptools and zc.buildout).

kenara · March 31, 2023, 2:53pm

Thank you very much Dieter. I'm working on this.

So far, I've tried taking a working Zope 4.5.1 with Python 3.7.5 and, simply replacing the versions-prod.cfg from 5.8.1, upgraded, and Zope works - but no ExternalMethods.

Next, trying to follow the instructions on Installing Zope — Zope 5.8.1 documentation, attempted to install Zope on a fresh Ubuntu 22.04 virtual server. For no good reason, I tried to install Zope 5.0 as it appears in the instructions.

sudo apt-get install python3-dev gives me Python 3.10.6

I tried the "Built-in standard buildout configuration", substituting Python3.10 for Python3.7

Running buildout, I got this:

Getting distribution for 'collective.recipe.template==2.1'.
  error: subprocess-exited-with-error
  
  × python setup.py egg_info did not run successfully.
  │ exit code: 1
  ╰─> [3 lines of output]
      /usr/lib/python3.10/distutils/dist.py:274: UserWarning: Unknown distribution option: 'convert_2to3_doctests'
        warnings.warn(msg)
      error in collective.recipe.template setup command: use_2to3 is invalid.
      [end of output]
  
  note: This error originates from a subprocess, and is likely not a problem with pip.
error: metadata-generation-failed

× Encountered error while generating package metadata.
╰─> See above for output.

note: This is an issue with the package mentioned above, not pip.
hint: See above for details.
An error occurred when trying to install /tmp/tmpxbjlb0zuget_dist/collective.recipe.template-2.1.tar.gz. Look above this message for any errors that were output by pip install.

So that didn't work.

Next, same thing with 5.8.1. That failed differently:

Develop: '/root/Zope-5.8.1/.'
/root/Zope-5.8.1/lib/python3.10/site-packages/setuptools/command/easy_install.py:158: EasyInstallDeprecationWarning: easy_install command is deprecated. Use build and pip and other standards-based tools.
  warnings.warn(
/root/Zope-5.8.1/lib/python3.10/site-packages/setuptools/command/install.py:34: SetuptoolsDeprecationWarning: setup.py install is deprecated. Use build and pip and other standards-based tools.
  warnings.warn(
Develop: '/root/Zope-5.8.1/develop/AccessControl'
/root/Zope-5.8.1/lib/python3.10/site-packages/setuptools/command/easy_install.py:158: EasyInstallDeprecationWarning: easy_install command is deprecated. Use build and pip and other standards-based tools.
  warnings.warn(
/root/Zope-5.8.1/lib/python3.10/site-packages/setuptools/command/install.py:34: SetuptoolsDeprecationWarning: setup.py install is deprecated. Use build and pip and other standards-based tools.
  warnings.warn(
error: command 'x86_64-linux-gnu-gcc' failed: No such file or directory
While:
  Installing.
  Processing develop directory '/root/Zope-5.8.1/develop/AccessControl'.

An internal error occurred due to a bug in either zc.buildout or in a
recipe being used:
Traceback (most recent call last):
  File "/root/Zope-5.8.1/lib/python3.10/site-packages/zc/buildout/buildout.py", line 2252, in main
    getattr(buildout, command)(args)
  File "/root/Zope-5.8.1/lib/python3.10/site-packages/zc/buildout/buildout.py", line 718, in install
    installed_develop_eggs = self._develop()
  File "/root/Zope-5.8.1/lib/python3.10/site-packages/zc/buildout/buildout.py", line 961, in _develop
    zc.buildout.easy_install.develop(setup, dest)
  File "/root/Zope-5.8.1/lib/python3.10/site-packages/zc/buildout/easy_install.py", line 1120, in develop
    call_subprocess(args)
  File "/root/Zope-5.8.1/lib/python3.10/site-packages/zc/buildout/easy_install.py", line 172, in call_subprocess
    raise Exception(
Exception: Failed to run command:
'/root/Zope-5.8.1/bin/python3.10', '/tmp/tmp4nwgathi', '-q', 'develop', '-mN', '-d', '/root/Zope-5.8.1/develop-eggs/tmp9gwj7gqnbuild'

Undaunted, I followed the instructions for Custom buildout configurations, again replacing python3.7 with python3.10 and copying buildout.cfg (and a few others) from 5.8.1 into the zope directory created by python3.10 -m venv zope

That didn't go well...

 Processing develop directory '/root/zope/.'.

An internal error occurred due to a bug in either zc.buildout or in a
recipe being used:
Traceback (most recent call last):
  File "/root/zope/lib/python3.10/site-packages/zc/buildout/buildout.py", line 2252, in main
    getattr(buildout, command)(args)
  File "/root/zope/lib/python3.10/site-packages/zc/buildout/buildout.py", line 718, in install
    installed_develop_eggs = self._develop()
  File "/root/zope/lib/python3.10/site-packages/zc/buildout/buildout.py", line 961, in _develop
    zc.buildout.easy_install.develop(setup, dest)
  File "/root/zope/lib/python3.10/site-packages/zc/buildout/easy_install.py", line 1120, in develop
    call_subprocess(args)
  File "/root/zope/lib/python3.10/site-packages/zc/buildout/easy_install.py", line 172, in call_subprocess
    raise Exception(
Exception: Failed to run command:
'/root/zope/bin/python3.10', '/tmp/tmp2vql_sq3', '-q', 'develop', '-mN', '-d', '/root/zope/develop-eggs/tmpwsy9kpv9build'

I'm obviously doing something wrong; don't ask me how I managed up to now. Over the past 20+ years, I've had some fun with Zope and you've helped me a few times, Dieter! So I'm not giving up.

I just need an up-to-date Zope to run my External Methods and eventually I will upgrade from 4 to 5...

dieter · March 31, 2023, 4:44pm

Ken D. via Plone Community wrote at 2023-3-31 15:03 +0000:

...
I just need an up-to-date Zope to run my External Methods and eventually I will upgrade from 4 to 5...

You know there are essentially 2 ways to install Zope:

via pip; 2) via buildout.

I am using the first approach: i.e. via pip.

That the following can work, your system must have installed all required
libraries and associated development resources.

Step 1:
Build a virtual environment using virtualenv or python -m venv.
Even if you use you own locally build python, you can use the
system virtualenv or system python for this step -- even
if the Python versions do not fully agree.

All further steps are inside the virtual env.

Step 2:
pip install Zope[wsgi]

This will install the latest released Zope version (currently 5.8.1).
Some dependent packages may be installed in a newer version than
that destined for the Zope version, but usually this is not a problem.

Step 3:
mkwsgiinstance
to create a basic configuration.
Modify the files in etc as necessary to meet your requirements.
Copy a ZODB data file if necessary.

Step 4:
Use runwsgi to start the Zope server or zconsole to
run scripts or start Zope in an interactive interpreter.

Of course, you will want to pip install further
packages in your virtual env, e.g. Products.ExternalMethod.