search

jim-easterbrook / python-gphoto2

Python interface to libgphoto2
GNU Lesser General Public License v3.0
362 stars 59 forks source link

Segfault on wait_for_event() when using python logging on Python 3.5 #37

Closed flyte closed 6 years ago

flyte commented 6 years ago

This works fine when you don't call gp.use_python_logging():

Python 3.5.2 (default, Nov 17 2016, 17:05:23) 
Type 'copyright', 'credits' or 'license' for more information
IPython 6.2.1 -- An enhanced Interactive Python. Type '?' for help.

In [1]: import gphoto2 as gp

In [2]: gp.use_python_logging()
Out[2]: 1

In [3]: context = gp.gp_context_new()

In [4]: camera = gp.check_result(gp.gp_camera_new())

In [5]: camera.init(context)
(foreach_func [gphoto2-port-info-list.c:237]) Error during assembling of port list: 'Unspecified error' (-1).
(ptp_list_folder_eos [library.c:7017]) storage 0xffffffff, but handle 0x00000000?
(ptp_usb_getresp [usb.c:428]) PTP_OC 0x9109 receiving resp failed: PTP General Error (0x2002)
(ptp_list_folder_eos [library.c:7033]) 'ptp_canon_eos_getobjectinfoex ( params, storageids.Storage[k], handle ? handle : 0xffffffff, 0x100000, &tmp, &nroftmp)' failed: PTP General Error (0x2002)

In [6]: camera.wait_for_event(1000, context)
Segmentation fault (core dumped)

I'm using gphoto2==1.7.1 and libgphoto2-dev:amd64 2.5.9-3 from the standard Ubuntu 16.04 repositories.

jim-easterbrook commented 6 years ago

That's very odd, and I'm not able to reproduce it on my OpenSUSE system (Python 3.4.6). What does camera.wait_for_event(1000, context) return when you're not using Python logging? Does it also happen if you use gp.gp_camera_wait_for_event(camera, 1000, context) instead of camera.wait_for_event(1000, context)? Can you try it with version 1.7.0 of python-gphoto2?

flyte commented 6 years ago

Does it also happen if you use gp.gp_camera_wait_for_event(camera, 1000, context) instead of camera.wait_for_event(1000, context)?

Yep!

Python 3.5.2 (default, Nov 17 2016, 17:05:23) 
Type 'copyright', 'credits' or 'license' for more information
IPython 6.2.1 -- An enhanced Interactive Python. Type '?' for help.

In [1]: import gphoto2 as gp

In [2]: gp.use_python_logging()
Out[2]: 1

In [3]: context = gp.gp_context_new()

In [4]: camera = gp.check_result(gp.gp_camera_new())

In [5]: camera.init(context)
WARNING:gphoto2:(foreach_func [gphoto2-port-info-list.c:237]) Error during assembling of port list: 'Unspecified error' (-1).
WARNING:gphoto2:(ptp_list_folder_eos [library.c:7017]) storage 0xffffffff, but handle 0x00000000?
WARNING:gphoto2:(ptp_usb_getresp [usb.c:428]) PTP_OC 0x9109 receiving resp failed: PTP General Error (0x2002)
WARNING:gphoto2:(ptp_list_folder_eos [library.c:7033]) 'ptp_canon_eos_getobjectinfoex ( params, storageids.Storage[k], handle ? handle : 0xffffffff, 0x100000, &tmp, &nroftmp)' failed: PTP General Error (0x2002)

In [6]: gp.gp_camera_wait_for_event(camera, 1000, context)
Segmentation fault (core dumped)

When I try to debug it using ipdb, I get stuck in a loop in port_log.py:

Python 3.5.2 (default, Nov 17 2016, 17:05:23) 
Type 'copyright', 'credits' or 'license' for more information
IPython 6.2.1 -- An enhanced Interactive Python. Type '?' for help.

In [1]: import gphoto2 as gp

In [2]: gp.use_python_logging()
Out[2]: 1

In [3]: context = gp.gp_context_new()

In [4]: camera = gp.check_result(gp.gp_camera_new())

In [5]: camera.init(context)
(foreach_func [gphoto2-port-info-list.c:237]) Error during assembling of port list: 'Unspecified error' (-1).
(ptp_list_folder_eos [library.c:7017]) storage 0xffffffff, but handle 0x00000000?
(ptp_usb_getresp [usb.c:428]) PTP_OC 0x9109 receiving resp failed: PTP General Error (0x2002)
(ptp_list_folder_eos [library.c:7033]) 'ptp_canon_eos_getobjectinfoex ( params, storageids.Storage[k], handle ? handle : 0xffffffff, 0x100000, &tmp, &nroftmp)' failed: PTP General Error (0x2002)

In [6]: def wait_for_event(camera, context):
   ...:     import ipdb; ipdb.set_trace()
   ...:     camera.wait_for_event(1000, context)
   ...:     

In [7]: wait_for_event(camera, context)
> <ipython-input-6-b6defcd563a3>(3)wait_for_event()
      2     import ipdb; ipdb.set_trace()
----> 3     camera.wait_for_event(1000, context)
      4 

ipdb> s
--Call--
> /home/flyte/.virtualenvs/flax-capture/lib/python3.5/site-packages/gphoto2/port_log.py(121)callback()
    120 
--> 121     def callback(self, level, domain, msg):
    122         self.log(self.mapping[level], '(%s) %s', domain, msg)

ipdb> n
> /home/flyte/.virtualenvs/flax-capture/lib/python3.5/site-packages/gphoto2/port_log.py(122)callback()
    121     def callback(self, level, domain, msg):
--> 122         self.log(self.mapping[level], '(%s) %s', domain, msg)
    123 

ipdb> n
--Return--
None
> /home/flyte/.virtualenvs/flax-capture/lib/python3.5/site-packages/gphoto2/port_log.py(122)callback()
    121     def callback(self, level, domain, msg):
--> 122         self.log(self.mapping[level], '(%s) %s', domain, msg)
    123 

ipdb> n
--Call--
> /home/flyte/.virtualenvs/flax-capture/lib/python3.5/site-packages/gphoto2/port_log.py(121)callback()
    120 
--> 121     def callback(self, level, domain, msg):
    122         self.log(self.mapping[level], '(%s) %s', domain, msg)

ipdb> n
> /home/flyte/.virtualenvs/flax-capture/lib/python3.5/site-packages/gphoto2/port_log.py(122)callback()
    121     def callback(self, level, domain, msg):
--> 122         self.log(self.mapping[level], '(%s) %s', domain, msg)
    123 

ipdb> n
--Return--
None
> /home/flyte/.virtualenvs/flax-capture/lib/python3.5/site-packages/gphoto2/port_log.py(122)callback()
    121     def callback(self, level, domain, msg):
--> 122         self.log(self.mapping[level], '(%s) %s', domain, msg)
    123 

ipdb> n
--Call--
> /home/flyte/.virtualenvs/flax-capture/lib/python3.5/site-packages/gphoto2/port_log.py(121)callback()
    120 
--> 121     def callback(self, level, domain, msg):
    122         self.log(self.mapping[level], '(%s) %s', domain, msg)

ipdb> n
> /home/flyte/.virtualenvs/flax-capture/lib/python3.5/site-packages/gphoto2/port_log.py(122)callback()
    121     def callback(self, level, domain, msg):
--> 122         self.log(self.mapping[level], '(%s) %s', domain, msg)
    123 

ipdb> n
--Return--
None
> /home/flyte/.virtualenvs/flax-capture/lib/python3.5/site-packages/gphoto2/port_log.py(122)callback()
    121     def callback(self, level, domain, msg):
--> 122         self.log(self.mapping[level], '(%s) %s', domain, msg)
    123 

ipdb>

Yep, it still happens on gphoto2==1.7.0.

I just tried on a Raspberry Pi running the latest Raspbian and it does the same. My camera is a Canon EOS 7D if that matters.

flyte commented 6 years ago

However, it does work on Python 2.7!

Python 2.7.12 (default, Nov 19 2016, 06:48:10) 
Type "copyright", "credits" or "license" for more information.

IPython 5.5.0 -- An enhanced Interactive Python.
?         -> Introduction and overview of IPython's features.
%quickref -> Quick reference.
help      -> Python's own help system.
object?   -> Details about 'object', use 'object??' for extra details.

In [1]: import gphoto2 as gp

In [2]: gp.use_python_logging()
Out[2]: 1

In [3]: context = gp.gp_context_new()

In [4]: camera = gp.check_result(gp.gp_camera_new())

In [5]: camera.init(context)
No handlers could be found for logger "gphoto2"

In [6]: camera.wait_for_event(1000, context)
Out[6]: [0, 'PTP Property d105 changed']

In [7]:
jim-easterbrook commented 6 years ago

OK, I'm guessing that attempting to log a message to Python is generating a fault that then gets logged to Python... Python 3.5 is different from Python 3.4, which was causing problems with SWIG's -builtin option. Can you try installing 1.7.1 with an environment variable PYTHON_GPHOTO2_NO_BUILTIN=1.

flyte commented 6 years ago

No dice.

(flax-capture) flyte@demosthenes:~/dev/0x07/flax/upload
$ export PYTHON_GPHOTO2_NO_BUILTIN=1
(flax-capture) flyte@demosthenes:~/dev/0x07/flax/upload
$ pip install --no-cache-dir gphoto2
Collecting gphoto2
  Downloading gphoto2-1.7.1.tar.gz (6.9MB)
    100% |████████████████████████████████| 6.9MB 6.5MB/s 
Installing collected packages: gphoto2
  Running setup.py install for gphoto2 ... done
Successfully installed gphoto2-1.7.1
(flax-capture) flyte@demosthenes:~/dev/0x07/flax/upload
$ ipython
Python 3.5.2 (default, Nov 17 2016, 17:05:23) 
Type 'copyright', 'credits' or 'license' for more information
IPython 6.2.1 -- An enhanced Interactive Python. Type '?' for help.

In [1]: import gphoto2 as gp

In [2]: gp.use_python_logging()
Out[2]: 1

In [3]: context = gp.gp_context_new()

In [4]: camera = gp.check_result(gp.gp_camera_new())

In [5]: camera.init(context)
(foreach_func [gphoto2-port-info-list.c:237]) Error during assembling of port list: 'Unspecified error' (-1).
(ptp_list_folder_eos [library.c:7017]) storage 0xffffffff, but handle 0x00000000?
(ptp_usb_getresp [usb.c:428]) PTP_OC 0x9109 receiving resp failed: PTP General Error (0x2002)
(ptp_list_folder_eos [library.c:7033]) 'ptp_canon_eos_getobjectinfoex ( params, storageids.Storage[k], handle ? handle : 0xffffffff, 0x100000, &tmp, &nroftmp)' failed: PTP General Error (0x2002)

In [6]: camera.wait_for_event(1000, context)
Segmentation fault (core dumped)

I ran the install again with -v to make sure it ran setup.py properly:

...
Running setup.py install for gphoto2 ...     Running command /home/flyte/.virtualenvs/flax-capture/bin/python3 -u -c "import setuptools, tokenize;__file__='/tmp/pip-build-qeuvk_ss/gphoto2/setup.py';f=getattr(tokenize, 'open', open)(__file__);code=f.read().replace('\r\n', '\n');f.close();exec(compile(code, __file__, 'exec'))" install --record /tmp/pip-qsaqrrjl-record/install-record.txt --single-version-externally-managed --compile --install-headers /home/flyte/.virtualenvs/flax-capture/include/site/python3.5/gphoto2
    running install
    running build
    running build_py
    creating build
    creating build/lib.linux-x86_64-3.5
    creating build/lib.linux-x86_64-3.5/gphoto2
    copying src/swig-py3-gp2.5.0/__init__.py -> build/lib.linux-x86_64-3.5/gphoto2
    copying src/swig-py3-gp2.5.0/result.py -> build/lib.linux-x86_64-3.5/gphoto2
    copying src/swig-py3-gp2.5.0/version.py -> build/lib.linux-x86_64-3.5/gphoto2
    copying src/swig-py3-gp2.5.0/file.py -> build/lib.linux-x86_64-3.5/gphoto2
    copying src/swig-py3-gp2.5.0/port_info_list.py -> build/lib.linux-x86_64-3.5/gphoto2
    copying src/swig-py3-gp2.5.0/filesys.py -> build/lib.linux-x86_64-3.5/gphoto2
    copying src/swig-py3-gp2.5.0/list.py -> build/lib.linux-x86_64-3.5/gphoto2
    copying src/swig-py3-gp2.5.0/abilities_list.py -> build/lib.linux-x86_64-3.5/gphoto2
    copying src/swig-py3-gp2.5.0/port_log.py -> build/lib.linux-x86_64-3.5/gphoto2
    copying src/swig-py3-gp2.5.0/widget.py -> build/lib.linux-x86_64-3.5/gphoto2
    copying src/swig-py3-gp2.5.0/camera.py -> build/lib.linux-x86_64-3.5/gphoto2
    copying src/swig-py3-gp2.5.0/context.py -> build/lib.linux-x86_64-3.5/gphoto2
    running build_ext
    building '_version' extension
    creating build/temp.linux-x86_64-3.5
    creating build/temp.linux-x86_64-3.5/src
    creating build/temp.linux-x86_64-3.5/src/swig-py3-gp2.5.0
    x86_64-linux-gnu-gcc -pthread -DNDEBUG -g -fwrapv -O2 -Wall -Wstrict-prototypes -g -fstack-protector-strong -Wformat -Werror=format-security -Wdate-time -D_FORTIFY_SOURCE=2 -fPIC -I/usr/include -I/usr/include/libexif -I/usr/include/python3.5m -I/home/flyte/.virtualenvs/flax-capture/include/python3.5m -c src/swig-py3-gp2.5.0/version_wrap.c -o build/temp.linux-x86_64-3.5/src/swig-py3-gp2.5.0/version_wrap.o -O3 -Wno-unused-variable -Wno-unused-but-set-variable -Wno-strict-prototypes -DGPHOTO2_VERSION=0x020509
    x86_64-linux-gnu-gcc -pthread -shared -Wl,-O1 -Wl,-Bsymbolic-functions -Wl,-Bsymbolic-functions -Wl,-z,relro -Wl,-Bsymbolic-functions -Wl,-z,relro -g -fstack-protector-strong -Wformat -Werror=format-security -Wdate-time -D_FORTIFY_SOURCE=2 build/temp.linux-x86_64-3.5/src/swig-py3-gp2.5.0/version_wrap.o -lgphoto2 -lm -lgphoto2_port -lm -lexif -o build/lib.linux-x86_64-3.5/gphoto2/_version.cpython-35m-x86_64-linux-gnu.so
    building '_filesys' extension
    x86_64-linux-gnu-gcc -pthread -DNDEBUG -g -fwrapv -O2 -Wall -Wstrict-prototypes -g -fstack-protector-strong -Wformat -Werror=format-security -Wdate-time -D_FORTIFY_SOURCE=2 -fPIC -I/usr/include -I/usr/include/libexif -I/usr/include/python3.5m -I/home/flyte/.virtualenvs/flax-capture/include/python3.5m -c src/swig-py3-gp2.5.0/filesys_wrap.c -o build/temp.linux-x86_64-3.5/src/swig-py3-gp2.5.0/filesys_wrap.o -O3 -Wno-unused-variable -Wno-unused-but-set-variable -Wno-strict-prototypes -DGPHOTO2_VERSION=0x020509
    x86_64-linux-gnu-gcc -pthread -shared -Wl,-O1 -Wl,-Bsymbolic-functions -Wl,-Bsymbolic-functions -Wl,-z,relro -Wl,-Bsymbolic-functions -Wl,-z,relro -g -fstack-protector-strong -Wformat -Werror=format-security -Wdate-time -D_FORTIFY_SOURCE=2 build/temp.linux-x86_64-3.5/src/swig-py3-gp2.5.0/filesys_wrap.o -lgphoto2 -lm -lgphoto2_port -lm -lexif -o build/lib.linux-x86_64-3.5/gphoto2/_filesys.cpython-35m-x86_64-linux-gnu.so
    building '_abilities_list' extension
    x86_64-linux-gnu-gcc -pthread -DNDEBUG -g -fwrapv -O2 -Wall -Wstrict-prototypes -g -fstack-protector-strong -Wformat -Werror=format-security -Wdate-time -D_FORTIFY_SOURCE=2 -fPIC -I/usr/include -I/usr/include/libexif -I/usr/include/python3.5m -I/home/flyte/.virtualenvs/flax-capture/include/python3.5m -c src/swig-py3-gp2.5.0/abilities_list_wrap.c -o build/temp.linux-x86_64-3.5/src/swig-py3-gp2.5.0/abilities_list_wrap.o -O3 -Wno-unused-variable -Wno-unused-but-set-variable -Wno-strict-prototypes -DGPHOTO2_VERSION=0x020509
    x86_64-linux-gnu-gcc -pthread -shared -Wl,-O1 -Wl,-Bsymbolic-functions -Wl,-Bsymbolic-functions -Wl,-z,relro -Wl,-Bsymbolic-functions -Wl,-z,relro -g -fstack-protector-strong -Wformat -Werror=format-security -Wdate-time -D_FORTIFY_SOURCE=2 build/temp.linux-x86_64-3.5/src/swig-py3-gp2.5.0/abilities_list_wrap.o -lgphoto2 -lm -lgphoto2_port -lm -lexif -o build/lib.linux-x86_64-3.5/gphoto2/_abilities_list.cpython-35m-x86_64-linux-gnu.so
    building '_result' extension
    x86_64-linux-gnu-gcc -pthread -DNDEBUG -g -fwrapv -O2 -Wall -Wstrict-prototypes -g -fstack-protector-strong -Wformat -Werror=format-security -Wdate-time -D_FORTIFY_SOURCE=2 -fPIC -I/usr/include -I/usr/include/libexif -I/usr/include/python3.5m -I/home/flyte/.virtualenvs/flax-capture/include/python3.5m -c src/swig-py3-gp2.5.0/result_wrap.c -o build/temp.linux-x86_64-3.5/src/swig-py3-gp2.5.0/result_wrap.o -O3 -Wno-unused-variable -Wno-unused-but-set-variable -Wno-strict-prototypes -DGPHOTO2_VERSION=0x020509
    x86_64-linux-gnu-gcc -pthread -shared -Wl,-O1 -Wl,-Bsymbolic-functions -Wl,-Bsymbolic-functions -Wl,-z,relro -Wl,-Bsymbolic-functions -Wl,-z,relro -g -fstack-protector-strong -Wformat -Werror=format-security -Wdate-time -D_FORTIFY_SOURCE=2 build/temp.linux-x86_64-3.5/src/swig-py3-gp2.5.0/result_wrap.o -lgphoto2 -lm -lgphoto2_port -lm -lexif -o build/lib.linux-x86_64-3.5/gphoto2/_result.cpython-35m-x86_64-linux-gnu.so
    building '_port_log' extension
    x86_64-linux-gnu-gcc -pthread -DNDEBUG -g -fwrapv -O2 -Wall -Wstrict-prototypes -g -fstack-protector-strong -Wformat -Werror=format-security -Wdate-time -D_FORTIFY_SOURCE=2 -fPIC -I/usr/include -I/usr/include/libexif -I/usr/include/python3.5m -I/home/flyte/.virtualenvs/flax-capture/include/python3.5m -c src/swig-py3-gp2.5.0/port_log_wrap.c -o build/temp.linux-x86_64-3.5/src/swig-py3-gp2.5.0/port_log_wrap.o -O3 -Wno-unused-variable -Wno-unused-but-set-variable -Wno-strict-prototypes -DGPHOTO2_VERSION=0x020509
    x86_64-linux-gnu-gcc -pthread -shared -Wl,-O1 -Wl,-Bsymbolic-functions -Wl,-Bsymbolic-functions -Wl,-z,relro -Wl,-Bsymbolic-functions -Wl,-z,relro -g -fstack-protector-strong -Wformat -Werror=format-security -Wdate-time -D_FORTIFY_SOURCE=2 build/temp.linux-x86_64-3.5/src/swig-py3-gp2.5.0/port_log_wrap.o -lgphoto2 -lm -lgphoto2_port -lm -lexif -o build/lib.linux-x86_64-3.5/gphoto2/_port_log.cpython-35m-x86_64-linux-gnu.so
    building '_port_info_list' extension
    x86_64-linux-gnu-gcc -pthread -DNDEBUG -g -fwrapv -O2 -Wall -Wstrict-prototypes -g -fstack-protector-strong -Wformat -Werror=format-security -Wdate-time -D_FORTIFY_SOURCE=2 -fPIC -I/usr/include -I/usr/include/libexif -I/usr/include/python3.5m -I/home/flyte/.virtualenvs/flax-capture/include/python3.5m -c src/swig-py3-gp2.5.0/port_info_list_wrap.c -o build/temp.linux-x86_64-3.5/src/swig-py3-gp2.5.0/port_info_list_wrap.o -O3 -Wno-unused-variable -Wno-unused-but-set-variable -Wno-strict-prototypes -DGPHOTO2_VERSION=0x020509
    x86_64-linux-gnu-gcc -pthread -shared -Wl,-O1 -Wl,-Bsymbolic-functions -Wl,-Bsymbolic-functions -Wl,-z,relro -Wl,-Bsymbolic-functions -Wl,-z,relro -g -fstack-protector-strong -Wformat -Werror=format-security -Wdate-time -D_FORTIFY_SOURCE=2 build/temp.linux-x86_64-3.5/src/swig-py3-gp2.5.0/port_info_list_wrap.o -lgphoto2 -lm -lgphoto2_port -lm -lexif -o build/lib.linux-x86_64-3.5/gphoto2/_port_info_list.cpython-35m-x86_64-linux-gnu.so
    building '_file' extension
    x86_64-linux-gnu-gcc -pthread -DNDEBUG -g -fwrapv -O2 -Wall -Wstrict-prototypes -g -fstack-protector-strong -Wformat -Werror=format-security -Wdate-time -D_FORTIFY_SOURCE=2 -fPIC -I/usr/include -I/usr/include/libexif -I/usr/include/python3.5m -I/home/flyte/.virtualenvs/flax-capture/include/python3.5m -c src/swig-py3-gp2.5.0/file_wrap.c -o build/temp.linux-x86_64-3.5/src/swig-py3-gp2.5.0/file_wrap.o -O3 -Wno-unused-variable -Wno-unused-but-set-variable -Wno-strict-prototypes -DGPHOTO2_VERSION=0x020509
    x86_64-linux-gnu-gcc -pthread -shared -Wl,-O1 -Wl,-Bsymbolic-functions -Wl,-Bsymbolic-functions -Wl,-z,relro -Wl,-Bsymbolic-functions -Wl,-z,relro -g -fstack-protector-strong -Wformat -Werror=format-security -Wdate-time -D_FORTIFY_SOURCE=2 build/temp.linux-x86_64-3.5/src/swig-py3-gp2.5.0/file_wrap.o -lgphoto2 -lm -lgphoto2_port -lm -lexif -o build/lib.linux-x86_64-3.5/gphoto2/_file.cpython-35m-x86_64-linux-gnu.so
    building '_context' extension
    x86_64-linux-gnu-gcc -pthread -DNDEBUG -g -fwrapv -O2 -Wall -Wstrict-prototypes -g -fstack-protector-strong -Wformat -Werror=format-security -Wdate-time -D_FORTIFY_SOURCE=2 -fPIC -I/usr/include -I/usr/include/libexif -I/usr/include/python3.5m -I/home/flyte/.virtualenvs/flax-capture/include/python3.5m -c src/swig-py3-gp2.5.0/context_wrap.c -o build/temp.linux-x86_64-3.5/src/swig-py3-gp2.5.0/context_wrap.o -O3 -Wno-unused-variable -Wno-unused-but-set-variable -Wno-strict-prototypes -DGPHOTO2_VERSION=0x020509
    x86_64-linux-gnu-gcc -pthread -shared -Wl,-O1 -Wl,-Bsymbolic-functions -Wl,-Bsymbolic-functions -Wl,-z,relro -Wl,-Bsymbolic-functions -Wl,-z,relro -g -fstack-protector-strong -Wformat -Werror=format-security -Wdate-time -D_FORTIFY_SOURCE=2 build/temp.linux-x86_64-3.5/src/swig-py3-gp2.5.0/context_wrap.o -lgphoto2 -lm -lgphoto2_port -lm -lexif -o build/lib.linux-x86_64-3.5/gphoto2/_context.cpython-35m-x86_64-linux-gnu.so
    building '_list' extension
    x86_64-linux-gnu-gcc -pthread -DNDEBUG -g -fwrapv -O2 -Wall -Wstrict-prototypes -g -fstack-protector-strong -Wformat -Werror=format-security -Wdate-time -D_FORTIFY_SOURCE=2 -fPIC -I/usr/include -I/usr/include/libexif -I/usr/include/python3.5m -I/home/flyte/.virtualenvs/flax-capture/include/python3.5m -c src/swig-py3-gp2.5.0/list_wrap.c -o build/temp.linux-x86_64-3.5/src/swig-py3-gp2.5.0/list_wrap.o -O3 -Wno-unused-variable -Wno-unused-but-set-variable -Wno-strict-prototypes -DGPHOTO2_VERSION=0x020509
    x86_64-linux-gnu-gcc -pthread -shared -Wl,-O1 -Wl,-Bsymbolic-functions -Wl,-Bsymbolic-functions -Wl,-z,relro -Wl,-Bsymbolic-functions -Wl,-z,relro -g -fstack-protector-strong -Wformat -Werror=format-security -Wdate-time -D_FORTIFY_SOURCE=2 build/temp.linux-x86_64-3.5/src/swig-py3-gp2.5.0/list_wrap.o -lgphoto2 -lm -lgphoto2_port -lm -lexif -o build/lib.linux-x86_64-3.5/gphoto2/_list.cpython-35m-x86_64-linux-gnu.so
    building '_widget' extension
    x86_64-linux-gnu-gcc -pthread -DNDEBUG -g -fwrapv -O2 -Wall -Wstrict-prototypes -g -fstack-protector-strong -Wformat -Werror=format-security -Wdate-time -D_FORTIFY_SOURCE=2 -fPIC -I/usr/include -I/usr/include/libexif -I/usr/include/python3.5m -I/home/flyte/.virtualenvs/flax-capture/include/python3.5m -c src/swig-py3-gp2.5.0/widget_wrap.c -o build/temp.linux-x86_64-3.5/src/swig-py3-gp2.5.0/widget_wrap.o -O3 -Wno-unused-variable -Wno-unused-but-set-variable -Wno-strict-prototypes -DGPHOTO2_VERSION=0x020509
    x86_64-linux-gnu-gcc -pthread -shared -Wl,-O1 -Wl,-Bsymbolic-functions -Wl,-Bsymbolic-functions -Wl,-z,relro -Wl,-Bsymbolic-functions -Wl,-z,relro -g -fstack-protector-strong -Wformat -Werror=format-security -Wdate-time -D_FORTIFY_SOURCE=2 build/temp.linux-x86_64-3.5/src/swig-py3-gp2.5.0/widget_wrap.o -lgphoto2 -lm -lgphoto2_port -lm -lexif -o build/lib.linux-x86_64-3.5/gphoto2/_widget.cpython-35m-x86_64-linux-gnu.so
    building '_camera' extension
    x86_64-linux-gnu-gcc -pthread -DNDEBUG -g -fwrapv -O2 -Wall -Wstrict-prototypes -g -fstack-protector-strong -Wformat -Werror=format-security -Wdate-time -D_FORTIFY_SOURCE=2 -fPIC -I/usr/include -I/usr/include/libexif -I/usr/include/python3.5m -I/home/flyte/.virtualenvs/flax-capture/include/python3.5m -c src/swig-py3-gp2.5.0/camera_wrap.c -o build/temp.linux-x86_64-3.5/src/swig-py3-gp2.5.0/camera_wrap.o -O3 -Wno-unused-variable -Wno-unused-but-set-variable -Wno-strict-prototypes -DGPHOTO2_VERSION=0x020509
    x86_64-linux-gnu-gcc -pthread -shared -Wl,-O1 -Wl,-Bsymbolic-functions -Wl,-Bsymbolic-functions -Wl,-z,relro -Wl,-Bsymbolic-functions -Wl,-z,relro -g -fstack-protector-strong -Wformat -Werror=format-security -Wdate-time -D_FORTIFY_SOURCE=2 build/temp.linux-x86_64-3.5/src/swig-py3-gp2.5.0/camera_wrap.o -lgphoto2 -lm -lgphoto2_port -lm -lexif -o build/lib.linux-x86_64-3.5/gphoto2/_camera.cpython-35m-x86_64-linux-gnu.so
    running install_lib
    creating /home/flyte/.virtualenvs/flax-capture/lib/python3.5/site-packages/gphoto2
    copying build/lib.linux-x86_64-3.5/gphoto2/__init__.py -> /home/flyte/.virtualenvs/flax-capture/lib/python3.5/site-packages/gphoto2
    copying build/lib.linux-x86_64-3.5/gphoto2/result.py -> /home/flyte/.virtualenvs/flax-capture/lib/python3.5/site-packages/gphoto2
    copying build/lib.linux-x86_64-3.5/gphoto2/version.py -> /home/flyte/.virtualenvs/flax-capture/lib/python3.5/site-packages/gphoto2
    copying build/lib.linux-x86_64-3.5/gphoto2/_camera.cpython-35m-x86_64-linux-gnu.so -> /home/flyte/.virtualenvs/flax-capture/lib/python3.5/site-packages/gphoto2
    copying build/lib.linux-x86_64-3.5/gphoto2/_context.cpython-35m-x86_64-linux-gnu.so -> /home/flyte/.virtualenvs/flax-capture/lib/python3.5/site-packages/gphoto2
    copying build/lib.linux-x86_64-3.5/gphoto2/file.py -> /home/flyte/.virtualenvs/flax-capture/lib/python3.5/site-packages/gphoto2
    copying build/lib.linux-x86_64-3.5/gphoto2/port_info_list.py -> /home/flyte/.virtualenvs/flax-capture/lib/python3.5/site-packages/gphoto2
    copying build/lib.linux-x86_64-3.5/gphoto2/filesys.py -> /home/flyte/.virtualenvs/flax-capture/lib/python3.5/site-packages/gphoto2
    copying build/lib.linux-x86_64-3.5/gphoto2/_version.cpython-35m-x86_64-linux-gnu.so -> /home/flyte/.virtualenvs/flax-capture/lib/python3.5/site-packages/gphoto2
    copying build/lib.linux-x86_64-3.5/gphoto2/_list.cpython-35m-x86_64-linux-gnu.so -> /home/flyte/.virtualenvs/flax-capture/lib/python3.5/site-packages/gphoto2
    copying build/lib.linux-x86_64-3.5/gphoto2/_filesys.cpython-35m-x86_64-linux-gnu.so -> /home/flyte/.virtualenvs/flax-capture/lib/python3.5/site-packages/gphoto2
    copying build/lib.linux-x86_64-3.5/gphoto2/_abilities_list.cpython-35m-x86_64-linux-gnu.so -> /home/flyte/.virtualenvs/flax-capture/lib/python3.5/site-packages/gphoto2
    copying build/lib.linux-x86_64-3.5/gphoto2/_file.cpython-35m-x86_64-linux-gnu.so -> /home/flyte/.virtualenvs/flax-capture/lib/python3.5/site-packages/gphoto2
    copying build/lib.linux-x86_64-3.5/gphoto2/list.py -> /home/flyte/.virtualenvs/flax-capture/lib/python3.5/site-packages/gphoto2
    copying build/lib.linux-x86_64-3.5/gphoto2/abilities_list.py -> /home/flyte/.virtualenvs/flax-capture/lib/python3.5/site-packages/gphoto2
    copying build/lib.linux-x86_64-3.5/gphoto2/_result.cpython-35m-x86_64-linux-gnu.so -> /home/flyte/.virtualenvs/flax-capture/lib/python3.5/site-packages/gphoto2
    copying build/lib.linux-x86_64-3.5/gphoto2/port_log.py -> /home/flyte/.virtualenvs/flax-capture/lib/python3.5/site-packages/gphoto2
    copying build/lib.linux-x86_64-3.5/gphoto2/_port_info_list.cpython-35m-x86_64-linux-gnu.so -> /home/flyte/.virtualenvs/flax-capture/lib/python3.5/site-packages/gphoto2
    copying build/lib.linux-x86_64-3.5/gphoto2/_widget.cpython-35m-x86_64-linux-gnu.so -> /home/flyte/.virtualenvs/flax-capture/lib/python3.5/site-packages/gphoto2
    copying build/lib.linux-x86_64-3.5/gphoto2/widget.py -> /home/flyte/.virtualenvs/flax-capture/lib/python3.5/site-packages/gphoto2
    copying build/lib.linux-x86_64-3.5/gphoto2/_port_log.cpython-35m-x86_64-linux-gnu.so -> /home/flyte/.virtualenvs/flax-capture/lib/python3.5/site-packages/gphoto2
    copying build/lib.linux-x86_64-3.5/gphoto2/camera.py -> /home/flyte/.virtualenvs/flax-capture/lib/python3.5/site-packages/gphoto2
    copying build/lib.linux-x86_64-3.5/gphoto2/context.py -> /home/flyte/.virtualenvs/flax-capture/lib/python3.5/site-packages/gphoto2
    byte-compiling /home/flyte/.virtualenvs/flax-capture/lib/python3.5/site-packages/gphoto2/__init__.py to __init__.cpython-35.pyc
    byte-compiling /home/flyte/.virtualenvs/flax-capture/lib/python3.5/site-packages/gphoto2/result.py to result.cpython-35.pyc
    byte-compiling /home/flyte/.virtualenvs/flax-capture/lib/python3.5/site-packages/gphoto2/version.py to version.cpython-35.pyc
    byte-compiling /home/flyte/.virtualenvs/flax-capture/lib/python3.5/site-packages/gphoto2/file.py to file.cpython-35.pyc
    byte-compiling /home/flyte/.virtualenvs/flax-capture/lib/python3.5/site-packages/gphoto2/port_info_list.py to port_info_list.cpython-35.pyc
    byte-compiling /home/flyte/.virtualenvs/flax-capture/lib/python3.5/site-packages/gphoto2/filesys.py to filesys.cpython-35.pyc
    byte-compiling /home/flyte/.virtualenvs/flax-capture/lib/python3.5/site-packages/gphoto2/list.py to list.cpython-35.pyc
    byte-compiling /home/flyte/.virtualenvs/flax-capture/lib/python3.5/site-packages/gphoto2/abilities_list.py to abilities_list.cpython-35.pyc
    byte-compiling /home/flyte/.virtualenvs/flax-capture/lib/python3.5/site-packages/gphoto2/port_log.py to port_log.cpython-35.pyc
    byte-compiling /home/flyte/.virtualenvs/flax-capture/lib/python3.5/site-packages/gphoto2/widget.py to widget.cpython-35.pyc
    byte-compiling /home/flyte/.virtualenvs/flax-capture/lib/python3.5/site-packages/gphoto2/camera.py to camera.cpython-35.pyc
    byte-compiling /home/flyte/.virtualenvs/flax-capture/lib/python3.5/site-packages/gphoto2/context.py to context.cpython-35.pyc
    running install_data
    creating /home/flyte/.virtualenvs/flax-capture/share/python-gphoto2
    creating /home/flyte/.virtualenvs/flax-capture/share/python-gphoto2/examples
    copying examples/set-camera-clock.py -> /home/flyte/.virtualenvs/flax-capture/share/python-gphoto2/examples
    copying examples/list-cameras-oo.py -> /home/flyte/.virtualenvs/flax-capture/share/python-gphoto2/examples
    copying examples/copy-chunks.py -> /home/flyte/.virtualenvs/flax-capture/share/python-gphoto2/examples
    copying examples/camera-config-gui.py -> /home/flyte/.virtualenvs/flax-capture/share/python-gphoto2/examples
    copying examples/camera-summary.py -> /home/flyte/.virtualenvs/flax-capture/share/python-gphoto2/examples
    copying examples/camera-config-gui-oo.py -> /home/flyte/.virtualenvs/flax-capture/share/python-gphoto2/examples
    copying examples/list-cameras.py -> /home/flyte/.virtualenvs/flax-capture/share/python-gphoto2/examples
    copying examples/camera-summary-oo.py -> /home/flyte/.virtualenvs/flax-capture/share/python-gphoto2/examples
    copying examples/read-exif-exifread.py -> /home/flyte/.virtualenvs/flax-capture/share/python-gphoto2/examples
    copying examples/list-files-oo.py -> /home/flyte/.virtualenvs/flax-capture/share/python-gphoto2/examples
    copying examples/focus-gui.py -> /home/flyte/.virtualenvs/flax-capture/share/python-gphoto2/examples
    copying examples/capture-image.py -> /home/flyte/.virtualenvs/flax-capture/share/python-gphoto2/examples
    copying examples/set-capture-target.py -> /home/flyte/.virtualenvs/flax-capture/share/python-gphoto2/examples
    copying examples/copy-data.py -> /home/flyte/.virtualenvs/flax-capture/share/python-gphoto2/examples
    copying examples/get-camera-clock.py -> /home/flyte/.virtualenvs/flax-capture/share/python-gphoto2/examples
    copying examples/error_handling.py -> /home/flyte/.virtualenvs/flax-capture/share/python-gphoto2/examples
    copying examples/get-capture-target.py -> /home/flyte/.virtualenvs/flax-capture/share/python-gphoto2/examples
    copying examples/list-files.py -> /home/flyte/.virtualenvs/flax-capture/share/python-gphoto2/examples
    copying examples/read-exif-gexiv2.py -> /home/flyte/.virtualenvs/flax-capture/share/python-gphoto2/examples
    copying examples/clear-space.py -> /home/flyte/.virtualenvs/flax-capture/share/python-gphoto2/examples
    copying examples/copy-files.py -> /home/flyte/.virtualenvs/flax-capture/share/python-gphoto2/examples
    copying examples/choose-camera.py -> /home/flyte/.virtualenvs/flax-capture/share/python-gphoto2/examples
    copying examples/preview-image.py -> /home/flyte/.virtualenvs/flax-capture/share/python-gphoto2/examples
    copying CHANGELOG.txt -> /home/flyte/.virtualenvs/flax-capture/share/python-gphoto2
    copying LICENSE.txt -> /home/flyte/.virtualenvs/flax-capture/share/python-gphoto2
    copying README.rst -> /home/flyte/.virtualenvs/flax-capture/share/python-gphoto2
    running install_egg_info
    running egg_info
    creating gphoto2.egg-info
    writing dependency_links to gphoto2.egg-info/dependency_links.txt
    writing gphoto2.egg-info/PKG-INFO
    writing top-level names to gphoto2.egg-info/top_level.txt
    writing manifest file 'gphoto2.egg-info/SOURCES.txt'
    reading manifest file 'gphoto2.egg-info/SOURCES.txt'
    writing manifest file 'gphoto2.egg-info/SOURCES.txt'
    Copying gphoto2.egg-info to /home/flyte/.virtualenvs/flax-capture/lib/python3.5/site-packages/gphoto2-1.7.1-py3.5.egg-info
    running install_scripts
    writing list of installed files to '/tmp/pip-qsaqrrjl-record/install-record.txt'
done
  Removing source in /tmp/pip-build-qeuvk_ss/gphoto2
Successfully installed gphoto2-1.7.1
jim-easterbrook commented 6 years ago

It might be worth checking that /usr/lib64/python3.5/site-packages/gphoto2/camera.py (or wherever it's installed) is about 31,000 bytes rather than about 3,500.

flyte commented 6 years ago 
$ ls -la ~/.virtualenvs/flax-capture/lib/python3.5/site-packages/gphoto2/camera.py 
-rw-rw-r-- 1 flyte flyte 39234 Aug 17 14:15 /home/flyte/.virtualenvs/flax-capture/lib/python3.5/site-packages/gphoto2/camera.py

Look right?

jim-easterbrook commented 6 years ago

Yup. So that's not the problem either. Leave it with me for a day or two.

flyte commented 6 years ago

No worries, cheers.

jim-easterbrook commented 6 years ago

I've set up a clean Ubuntu 16.04 installation on a virtual machine and am not getting the problem with my Canon EOS 100D. Will try some other cameras. PS Have tried it with my Canon A1100 IS and it's still fine. Enabling Python logging shows some debug output on each wait_for_event call though.

jim-easterbrook commented 6 years ago

I strongly suspect this is camera dependent. Possibly the driver for your camera is logging with unexpected parameters which the conversion to Python mishandles, but that wouldn't explain why it works with Python 2.7. Can you try it again on 2.7 but with a logging.basicConfig() call (after importing logging) so we actually get some log output.

jim-easterbrook commented 6 years ago

I've been puzzling over this, trying to come up with a theory to explain what's happening. One possibility is that camera.init() (known to leak memory!) is trashing the Python wrapper's record of what Python function to call when a message is to be logged. camera.init() is successfully logging some messages though, so any corruption happens towards the end of its call. Can you try calling gp.gp_log_remove_func(1) (where 1 is the value returned by gp.use_python_logging()) before calling camera.wait_for_event()?

flyte commented 6 years ago

Hopefully this will shed some light.. I added a print() to the code on line 160 of site-packages/gphoto2/port_log.py as such:

def callback(self, level, domain, msg):
    print("\nNew log message:\n%s" % msg)
    self.log(self.mapping[level], '(%s) %s', domain, msg)

Which creates this rather long output:

$ python crashtest.py 

... snip ...

New log message:
event 36: EOS prop d11c info record, datasize is 4

New log message:
event 36: currentvalue of d11c is 1

New log message:
event 37: EOS prop d1a0 info record, datasize is 104

New log message:
event 37: decoded custom function, currentvalue of d1a0 is 68,1,1,5c,7,101,1,0,102,1,0,103,1,1,104,1,0,105,1,0,108,1,1,10f,1,0,

New log message:
event 38: EOS prop d1a0 info record, datasize is 56

New log message:
event 38: currentvalue of d1a0 is 8

New log message:
event 38: decoded custom function, currentvalue of d1a0 is 38,1,2,2c,3,201,1,0,202,1,0,203,1,0,

New log message:
event 39: EOS prop d1a0 info record, datasize is 196
Segmentation fault (core dumped)

It's no wonder I thought that I was getting stuck in a loop!

Running gp.gp_log_remove_func(1) does stop the segfault from appearing.

jim-easterbrook commented 6 years ago

Yes, the lowest level logging is very verbose. I half expected calling gp.gp_log_remove_func(1) itself to segfault. As it didn't I think I can assume that the data I was talking about is intact. Can you try modifying your print statement:

def callback(self, level, domain, msg):
    if level != 3:
        print("\nNew log message", level, domain, "\n", msg)
    self.log(self.mapping[level], '(%s) %s', domain, msg)
flyte commented 6 years ago

Even that prints rather a lot:

$ python crashtest.py 

... snip ...

New log mesage 2 ptp 
 event 42: EOS prop d11c info record, datasize is 4

New log mesage 2 ptp 
 event 42: currentvalue of d11c is 1

New log mesage 2 ptp 
 event 43: EOS prop d1a0 info record, datasize is 104

New log mesage 2 ptp 
 event 43: decoded custom function, currentvalue of d1a0 is 68,1,1,5c,7,101,1,0,102,1,0,103,1,1,104,1,0,105,1,0,108,1,1,10f,1,0,

New log mesage 2 ptp 
 event 44: EOS prop d1a0 info record, datasize is 56

New log mesage 2 ptp 
 event 44: currentvalue of d1a0 is 8

New log mesage 2 ptp 
 event 44: decoded custom function, currentvalue of d1a0 is 38,1,2,2c,3,201,1,0,202,1,0,203,1,0,

New log mesage 2 ptp 
 event 45: EOS prop d1a0 info record, datasize is 196
Segmentation fault (core dumped)
jim-easterbrook commented 6 years ago

However, the last log message is basically the same, and there's nothing about it that would seem likely to upset the logging system. I suspect the problem is happening before the Python callback function you edited is called. If you download python-gphoto2 from PyPI (https://pypi.python.org/pypi/gphoto2/1.7.1) you could edit the SWIG generated wrapper before installing, which might yield some useful information. The file you want to edit is src/swig-bi-py3-gp2.5.0/port_log_wrap.c (we'll go back to the -builtin version now). Find the gp_log_call_python function and add a printf statement:

  if (Py_IsInitialized()) {
    printf("log: %d %s %s\n", level, domain, str);
    PyGILState_STATE gstate = PyGILState_Ensure();

I hope you'll be able to install as follows:

python3 setup.py build
sudo python3 setup.py install

Don't bother posting all the output, just the last bit before the segfault.

jim-easterbrook commented 6 years ago

I've found one remotely possible cause of your segfault problem, and it's camera dependent. To call the Python logging function from C I use Py_BuildValue to assemble the parameters (level, domain & str) into a Python object. The documentation of Py_BuildValue says it can fail (e.g. if it runs out of memory) and I'm not currently checking for this. If the driver for your camera generates extremely verbose debug information this might be a problem.

jim-easterbrook commented 6 years ago

Commit 255f82d might be the cure.

flyte commented 6 years ago

Apologies for the radio silence, I've picked up a contract so I'm busy with that at my client's office without the camera. Thank you for the attention you're giving this issue! I'll check out your fix one evening this week.

jim-easterbrook commented 6 years ago

No problem. I might do a new release in the next day or two which will make it easier for you to test it.

jim-easterbrook commented 6 years ago

Release 1.8.0 has the substantially reworked logging callback stuff.

flyte commented 6 years ago

Great, thank you. I'll endeavour to test it out over the weekend.

flyte commented 6 years ago

Much better!

Python 3.5.2 (default, Nov 17 2016, 17:05:23) 
Type 'copyright', 'credits' or 'license' for more information
IPython 6.2.1 -- An enhanced Interactive Python. Type '?' for help.

In [1]: import gphoto2 as gp

In [2]: gp.use_python_logging()
Out[2]: 1

In [3]: context = gp.gp_context_new()

In [4]: camera = gp.check_result(gp.gp_camera_new())

In [5]: camera.init(context)
(foreach_func [gphoto2-port-info-list.c:237]) Error during assembling of port list: 'Unspecified error' (-1).
(ptp_list_folder_eos [library.c:7017]) storage 0xffffffff, but handle 0x00000000?
(ptp_usb_getresp [usb.c:428]) PTP_OC 0x9109 receiving resp failed: PTP General Error (0x2002)
(ptp_list_folder_eos [library.c:7033]) 'ptp_canon_eos_getobjectinfoex ( params, storageids.Storage[k], handle ? handle : 0xffffffff, 0x100000, &tmp, &nroftmp)' failed: PTP General Error (0x2002)

In [6]: camera.wait_for_event(1000, context)
---------------------------------------------------------------------------
UnicodeDecodeError                        Traceback (most recent call last)
UnicodeDecodeError: 'utf-8' codec can't decode byte 0xc4 in position 34: unexpected end of data
---------------------------------------------------------------------------
UnicodeDecodeError                        Traceback (most recent call last)
UnicodeDecodeError: 'utf-8' codec can't decode byte 0xa4 in position 34: invalid start byte
Out[6]: [0, 'PTP Property d11b changed']
jim-easterbrook commented 6 years ago

Ulrika! (Sorry, was watching W1A last night.) It appears that either the domain or str callback parameter (probably the latter) contains a non-ASCII character, and the error this causes is now being handled better. This also explains why it worked with Python 2 - all strings are byte rather than Unicode. As there's no way of knowing what character set any particular camera uses I guess it would be safer (in Python 3) to pass bytes values instead of str and leave it to the Python callback to decide what to do.

flyte commented 6 years ago

Good job! Glad you got to the bottom of it :)

jim-easterbrook commented 6 years ago

Thanks for your help in testing this - there's no way I could have found it otherwise. I think version 1.8.0 is good enough for now - you won't see what the problematic logging message actually is until the next release.