Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

wait_for_event causes a picture to be taken? #358

Closed
sdaau opened this issue Jan 24, 2019 · 8 comments
Closed

wait_for_event causes a picture to be taken? #358

sdaau opened this issue Jan 24, 2019 · 8 comments

Comments

@sdaau
Copy link
Contributor

sdaau commented Jan 24, 2019

I first started with this issue at jim-easterbrook/python-gphoto2#75 - but it seems this may be more related to libgphoto2.

The problem is, on a Canon S3 IS, that I cannot get exposurecompensation's read-only property to change (immediately after) in response to a change of shootingmode, so I need to either arbitrarily sleep for 2 seconds, or wait in a different way. I tried waiting with wait_for_event - but that command initiates taking of a picture!?

So, I'd like to know what causes wait_for_event to take a picture in this case - because if I can prevent that, I could likely wait for the exposurecompensation's read-only property to change in response to a change of shootingmode, without guessing arbitrary sleep times.

Anyways, I tried to debug more, and this is the version of the script that I used here:

#!/usr/bin/env python

from __future__ import print_function

import sys
import gphoto2 as gp
import time
import logging

SLEEPTIME=1 # at least 2 sec for correct response
ENDWITHAUTO=1 # 1 to end with Auto mode, 0 otherwise

logging.basicConfig(
    format='%(filename)s:%(lineno)d %(levelname)s: %(name)s: %(message)s', level=logging.DEBUG)
gp.check_result(gp.use_python_logging())

camera = gp.Camera()
ctx = gp.Context()

camera.init(ctx)
camera_config = camera.get_config()

print("{} Start settings (sleeptime={}, endwithauto={}):".format(time.time(), SLEEPTIME, ENDWITHAUTO))
sys.stdout.flush()
OK, gpprop = gp.gp_widget_get_child_by_name( camera_config, "shootingmode" )
if OK >= gp.GP_OK:
  print("  shootingmode = {}".format( gpprop.get_value() ))
  sys.stdout.flush()
OK, gpprop = gp.gp_widget_get_child_by_name( camera_config, "exposurecompensation" )
if OK >= gp.GP_OK:
  print("  exposurecompensation ro = {}".format( gpprop.get_readonly() ))
  sys.stdout.flush()

print("{} set shootingmode Auto".format(time.time()))
sys.stdout.flush()
OK, gpprop = gp.gp_widget_get_child_by_name( camera_config, "shootingmode" )
if OK >= gp.GP_OK:
  gpprop.set_value( "Auto" )
  camera.set_config(camera_config) # must have this, else value is not effectuated!
time.sleep(SLEEPTIME)
camera_config = camera.get_config() # must have this, else effectuated values are not read back in
OK, gpprop = gp.gp_widget_get_child_by_name( camera_config, "exposurecompensation" )
if OK >= gp.GP_OK:
  print("{} exposurecompensation ro = {}".format( time.time(), gpprop.get_readonly() ))
  sys.stdout.flush()

print("{} set shootingmode Manual".format(time.time()))
sys.stdout.flush()
OK, gpprop = gp.gp_widget_get_child_by_name( camera_config, "shootingmode" )
if OK >= gp.GP_OK:
  gpprop.set_value( "Manual" )
  camera.set_config(camera_config) # must have this, else value is not effectuated!
time.sleep(SLEEPTIME)
camera_config = camera.get_config() # must have this, else effectuated values are not read back in
OK, gpprop = gp.gp_widget_get_child_by_name( camera_config, "exposurecompensation" )
if OK >= gp.GP_OK:
  print("{} exposurecompensation ro = {}".format( time.time(), gpprop.get_readonly() ))
  sys.stdout.flush()

print("{} set shootingmode Auto (wait_for_event takes photo here?!)".format(time.time()))
sys.stdout.flush()
OK, gpprop = gp.gp_widget_get_child_by_name( camera_config, "shootingmode" )
if OK >= gp.GP_OK:
  gpprop.set_value( "Auto" )
  camera.set_config(camera_config) # must have this, else value is not effectuated!
camera_config = camera.get_config() # must have this, else effectuated values are not read back in
a, b = camera.wait_for_event(10)
OK, gpprop = gp.gp_widget_get_child_by_name( camera_config, "exposurecompensation" )
if OK >= gp.GP_OK:
  print("{} exposurecompensation ro = {}".format( time.time(), gpprop.get_readonly() ))
  sys.stdout.flush()

if ENDWITHAUTO == 1:
  print("{} set shootingmode Auto".format(time.time()))
  sys.stdout.flush()
  OK, gpprop = gp.gp_widget_get_child_by_name( camera_config, "shootingmode" )
  if OK >= gp.GP_OK:
    gpprop.set_value( "Auto" )
    camera.set_config(camera_config) # must have this, else value is not effectuated!

I call this with:

python test-sm-ec.py 2>&1 | tee test-sm-ec.log

The test-sm-ec.log is attached:

test-sm-ec.log

... and the relevant part is:

...
port_log.py:127 DEBUG: gphoto2: (ptp_usb_getresp) Reading PTP_OC 0x1014 (Get device property description) response...
port_log.py:127 DEBUG: gphoto2: (gp_widget_set_value) Setting value of widget 'EZoom Start Position' to '129'...
port_log.py:127 DEBUG: gphoto2: (gp_widget_set_value) Setting value of widget 'Rotation Angle' to '0'...
1548340472.6 exposurecompensation ro = 1
1548340472.6 set shootingmode Auto (wait_for_event takes photo here?!)

So after this printout I call the equivalent of: gp.gp_widget_get_child_by_name( camera_config, "shootingmode" ).set_value( "Auto" ), which is indicated next in the log:

port_log.py:127 DEBUG: gphoto2: (gp_widget_set_value) Setting value of widget 'Canon Shooting Mode' to 'Auto'...

... and then camera.set_config(camera_config), which is also indicated as the log continues:

port_log.py:127 DEBUG: gphoto2: (_set_config) Setting property 'Canon Shooting Mode' / 0xd00c
port_log.py:127 DEBUG: gphoto2: (ptp_usb_sendreq) Sending PTP_OC 0x1016 (Set device property value) (0xd00c) request...
port_log.py:127 DEBUG: gphoto2: (ptp_usb_senddata) Sending PTP_OC 0x1016 (Set device property value) data...
port_log.py:127 DEBUG: gphoto2: (ptp_usb_getresp) Reading PTP_OC 0x1016 (Set device property value) response...
port_log.py:127 DEBUG: gphoto2: (_get_config) Getting function prop 'Focus Lock' / 0x9014
port_log.py:127 DEBUG: gphoto2: (_get_config) Getting function prop 'PTP Opcode' / 0x1001
....

... and once that - and camera_config = camera.get_config() is done:

...
port_log.py:127 DEBUG: gphoto2: (gp_widget_set_value) Setting value of widget 'Disp Av Max' to '0'...
port_log.py:127 DEBUG: gphoto2: (gp_widget_set_value) Setting value of widget 'Av Max Apex' to '56'...
port_log.py:127 DEBUG: gphoto2: (gp_widget_set_value) Setting value of widget 'EZoom Start Position' to '129'...
port_log.py:127 DEBUG: gphoto2: (gp_widget_set_value) Setting value of widget 'Rotation Angle' to '0'...

... I call a, b = camera.wait_for_event(10) which is indicated in the log:

port_log.py:127 DEBUG: gphoto2: (camera_wait_for_event) waiting for events timeout 10 ms
port_log.py:127 DEBUG: gphoto2: (ptp_usb_sendreq) Sending PTP_OC 0x9013 (PTP_OC_CANON_CheckEvent) request...
port_log.py:127 DEBUG: gphoto2: (ptp_usb_getdata) Reading PTP_OC 0x9013 (PTP_OC_CANON_CheckEvent) data...
port_log.py:127 DEBUG: gphoto2: (ptp_usb_getresp) Reading PTP_OC 0x9013 (PTP_OC_CANON_CheckEvent) response...
port_log.py:127 DEBUG: gphoto2: (ptp) event: nparams=0x3, code=0xC00E, trans_id=0xFFFFFFFF, p1=0x0, p2=0x0, p3=0x0
port_log.py:127 DEBUG: gphoto2: (camera_wait_for_event) canon event: nparam=0x3, C=0xC00E, trans_id=0xFFFFFFFF, p1=0x0, p2=0x0, p3=0x0
port_log.py:127 DEBUG: gphoto2: (camera_prepare_capture) prepare_capture
port_log.py:127 DEBUG: gphoto2: (camera_prepare_canon_powershot_capture) Canon capture mode is already set up.
port_log.py:127 DEBUG: gphoto2: (ptp_usb_sendreq) Sending PTP_OC 0x1015 (Get device property value) (0xd045) request...
port_log.py:127 DEBUG: gphoto2: (ptp_usb_getdata) Reading PTP_OC 0x1015 (Get device property value) data...
port_log.py:127 DEBUG: gphoto2: (ptp_usb_getresp) Reading PTP_OC 0x1015 (Get device property value) response...
port_log.py:127 DEBUG: gphoto2: (camera_prepare_canon_powershot_capture) Event emulate mode 0x0007
port_log.py:127 DEBUG: gphoto2: (ptp_usb_sendreq) Sending PTP_OC 0x1004 (Get storage IDs) request...
port_log.py:127 DEBUG: gphoto2: (ptp_usb_getdata) Reading PTP_OC 0x1004 (Get storage IDs) data...
port_log.py:127 DEBUG: gphoto2: (ptp_usb_getresp) Reading PTP_OC 0x1004 (Get storage IDs) response...
port_log.py:127 DEBUG: gphoto2: (ptp_usb_sendreq) Sending PTP_OC 0x1016 (Set device property value) (0xd029) request...
port_log.py:127 DEBUG: gphoto2: (ptp_usb_senddata) Sending PTP_OC 0x1016 (Set device property value) data...
port_log.py:127 DEBUG: gphoto2: (ptp_usb_getresp) Reading PTP_OC 0x1016 (Set device property value) response...
port_log.py:127 DEBUG: gphoto2: (ptp_usb_sendreq) Sending PTP_OC 0x9013 (PTP_OC_CANON_CheckEvent) request...
port_log.py:127 DEBUG: gphoto2: (ptp_usb_getdata) Reading PTP_OC 0x9013 (PTP_OC_CANON_CheckEvent) data...
port_log.py:127 DEBUG: gphoto2: (ptp_usb_getresp) Reading PTP_OC 0x9013 (PTP_OC_CANON_CheckEvent) response...
port_log.py:127 DEBUG: gphoto2: (ptp) event: nparams=0x3, code=0xC00E, trans_id=0xFFFFFFFF, p1=0x0, p2=0x0, p3=0x0
port_log.py:127 DEBUG: gphoto2: (ptp_usb_sendreq) Sending PTP_OC 0x901a (PTP_OC_CANON_InitiateCaptureInMemory) request...
port_log.py:127 DEBUG: gphoto2: (ptp_usb_getresp) Reading PTP_OC 0x901a (PTP_OC_CANON_InitiateCaptureInMemory) response...
port_log.py:127 DEBUG: gphoto2: (gp_port_get_timeout) Current port timeout is 20000 milliseconds.
port_log.py:127 DEBUG: gphoto2: (gp_port_set_timeout) Setting port timeout to 100000 milliseconds.
port_log.py:127 DEBUG: gphoto2: (ptp_usb_sendreq) Sending PTP_OC 0x9013 (PTP_OC_CANON_CheckEvent) request...
port_log.py:127 DEBUG: gphoto2: (ptp_usb_getdata) Reading PTP_OC 0x9013 (PTP_OC_CANON_CheckEvent) data...
port_log.py:127 DEBUG: gphoto2: (ptp_usb_getresp) Reading PTP_OC 0x9013 (PTP_OC_CANON_CheckEvent) response...
port_log.py:127 DEBUG: gphoto2: (camera_canon_capture) Event: nparams=0x3, code=0xC00E, trans_id=0xFFFFFFFF, p1=0x0, p2=0x0, p3=0x0
port_log.py:127 DEBUG: gphoto2: (camera_canon_capture) Event unhandled: nparams=0x3, code=0xC00E, trans_id=0xFFFFFFFF, p1=0x0, p2=0x0, p3=0x0
port_log.py:127 DEBUG: gphoto2: (ptp_usb_sendreq) Sending PTP_OC 0x9013 (PTP_OC_CANON_CheckEvent) request...
port_log.py:127 DEBUG: gphoto2: (ptp_usb_getdata) Reading PTP_OC 0x9013 (PTP_OC_CANON_CheckEvent) data...
port_log.py:127 DEBUG: gphoto2: (ptp_usb_getresp) Reading PTP_OC 0x9013 (PTP_OC_CANON_CheckEvent) response...
port_log.py:127 DEBUG: gphoto2: (ptp_usb_sendreq) Sending PTP_OC 0x9013 (PTP_OC_CANON_CheckEvent) request...
port_log.py:127 DEBUG: gphoto2: (ptp_usb_getdata) Reading PTP_OC 0x9013 (PTP_OC_CANON_CheckEvent) data...
port_log.py:127 DEBUG: gphoto2: (ptp_usb_getresp) Reading PTP_OC 0x9013 (PTP_OC_CANON_CheckEvent) response...
port_log.py:127 DEBUG: gphoto2: (ptp_usb_sendreq) Sending PTP_OC 0x9013 (PTP_OC_CANON_CheckEvent) request...
port_log.py:127 DEBUG: gphoto2: (ptp_usb_getdata) Reading PTP_OC 0x9013 (PTP_OC_CANON_CheckEvent) data...
...

... but immediately after that, there is camera_prepare_capture and camera_canon_capture - where did those come from? The next line after a, b = camera.wait_for_event(10) is OK, gpprop = gp.gp_widget_get_child_by_name( camera_config, "exposurecompensation" ) - which is first mentioned in the log some 5000 lines after this location!?

So, to sum up - what could possibly cause a picture to be taken on wait_for_event, and how to prevent it, if possible?

@msmeissn
Copy link
Contributor

This happens when wait_for_event runs and you press the shutter button on the camera.

The shutter button press is reported via event 0xc00e and that in turn will run the canon_capture.

@sdaau
Copy link
Contributor Author

sdaau commented Jan 24, 2019

Thanks @msmeissn - this clarifies matters a bit:

This happens when wait_for_event runs and you press the shutter button on the camera.
The shutter button press is reported via event 0xc00e and that in turn will run the canon_capture.

... but the thing is, I do not press the shutter button on the camera physically in any way - I just leave the camera as is, connected to USB, and run the python script. And considering I do camera.wait_for_event(10) for just 10 milliseconds, I wouldn't have the time to physically reach for the shutter button while the wait_for_event is active, anyway :)

Could there be any other suggestions as to what might cause a shutter button press event to occur, even if there isn't a physical button press? Maybe I should "drain" the event queue somehow (if possible?) before issuing wait_for_event? (EDIT: although, as I can see from time_lapse.py, empty_event_queue there is done via camera.wait_for_event(10), so not sure if there are other methods to empty the queue)

@msmeissn
Copy link
Contributor

hmm. perhaps it is reporting to us the shutterbutton is not pressed... can you actually try to wait longer and press it and see what events arrive?

@sdaau
Copy link
Contributor Author

sdaau commented Jan 24, 2019

can you actually try to wait longer and press it and see what events arrive?

Sure - just tried it; first changed the relevant code section to this:

...
camera_config = camera.get_config() # must have this, else effectuated values are not read back in
print("{} about to wait_for_event".format(time.time()))
sys.stdout.flush()
a, b = camera.wait_for_event(10000)
OK, gpprop = gp.gp_widget_get_child_by_name( camera_config, "exposurecompensation" )
...

... so the timeout is now 10000 ms - but that makes no difference, because as soon as I get the 1548343742.83 about to wait_for_event printout in terminal, I can instantly hear the shutter click, and then a new picture is taken, and then wait_for_event returns (stops waiting/blocking) as soon as the newly taken picture is done processing (edit: so I cannot really intervene in the middle of all this, and press the button manually). And this happens every time I re-run the python script.

There could be something in the previous Python code that triggers this event, but I simply cannot see what... Any other suggestions?

@msmeissn
Copy link
Contributor

Can you get a log output where you actually press the shutter button? I need to see what event is sent and what parameters it gets.

I tetsed with my SX100IS, it does not have this specific problem

@sdaau
Copy link
Contributor Author

sdaau commented Jan 24, 2019

Many thanks, @msmeissn :

First, just wanted to mention that I posted a way to wait for exposurecompensation.readonly to change after a change of shootingmode on jim-easterbrook/python-gphoto2#75 (comment) without using wait_for_event, but it would still be good to figure out how come wait_for_event takes a picture in my (Canon S3 IS) case.

I tetsed with my SX100IS, it does not have this specific problem

Thanks for confirming that - good to know its not a general problem, at least: maybe it's because the Canon S3 IS is an old model...

Can you get a log output where you actually press the shutter button? I need to see what event is sent and what parameters it gets.

Oh, I see - sorry I misunderstood that! :)

I wasn't sure at first how to obtain such a log, but then I just used gphoto2. Note that at my first attempt:

$ gphoto2 --debug --debug-logfile=gphoto2-capture.log --wait-event-and-download 20
Waiting for 20 events from camera. Press Ctrl-C to abort.                      
Saving file as IMG_6101.JPG                                                    
UNKNOWN PTP ObjectRemoved, Param1 0000006a
Saving file as IMG_6102.JPG                                                    
UNKNOWN PTP ObjectRemoved, Param1 0000006a

... first the camera "itself" took one image, and then i pressed the shutter button, it took the second picture, and then command exited.

After re-running it, I came to the point where the command just waits, I press the shutter button, picture is taken, and command exits:

$ rm gphoto2-capture.log && gphoto2 --debug --debug-logfile=gphoto2-capture.log --wait-event-and-download 20
Waiting for 20 events from camera. Press Ctrl-C to abort.                      
Saving file as IMG_6104.JPG
UNKNOWN PTP ObjectRemoved, Param1 0000006a

Here is that (gzipped) log, attached:

gphoto2-capture.log.gz

Let me know if I should provide anything else.

@msmeissn
Copy link
Contributor

that is fine, thanks!

I changed the code to ignore the 0xc00e event now for capture triggering, only the 0xc00b sems to be the shutter button press.

@sdaau
Copy link
Contributor Author

sdaau commented Jan 25, 2019

Many thanks again, @msmeissn :

I changed the code to ignore the 0xc00e event now for capture triggering, only the 0xc00b sems to be the shutter button press.

Fantastic - I just tested, and it seems that fixes the wait_for_event causing a capture trigger/photo to be taken!

This is what I did (Ubuntu 18.04):

git clone https://github.com/gphoto/libgphoto2.git libgphoto2_git
cd libgphoto2_git
# less INSTALL
autoreconf --install --symlink
./configure
make -j$(nrpoc)

This process ends succesfully, and I get files like ./libgphoto2/.libs/libgphoto2.so -> ./libgphoto2/.libs/libgphoto2.so.6.1.0, and ./libgphoto2_port/libgphoto2_port/.libs/libgphoto2_port.so. I use readlink -f on these to find absolute paths.

Then, in order to use these, I need to have this massive preamble for bash to set environment variables:

GITPATH=/path/to/libgphoto2_git \
CAMLIBS=$GITPATH/camlibs/.libs \
IOLIBS=$GITPATH/libgphoto2_port/.libs \
LD_PRELOAD=$GITPATH/libgphoto2_port/libgphoto2_port/.libs/libgphoto2_port.so.12.0.0:$GITPATH/libgphoto2/.libs/libgphoto2.so.6.1.0

... or as one line:

GITPATH=/path/to/libgphoto2_git CAMLIBS=$GITPATH/camlibs/.libs IOLIBS=$GITPATH/libgphoto2_port/.libs LD_PRELOAD=$GITPATH/libgphoto2_port/libgphoto2_port/.libs/libgphoto2_port.so.12.0.0:$GITPATH/libgphoto2/.libs/libgphoto2.so.6.1.0

Note that when you call gphoto2 --version with this preamble:

$ GITPATH=/path/to/libgphoto2_git CAMLIBS=$GITPATH/camlibs/.libs IOLIBS=$GITPATH/libgphoto2_port/.libs LD_PRELOAD=$GITPATH/libgphoto2_port/libgphoto2_port/.libs/libgphoto2_port.so.12.0.0:$GITPATH/libgphoto2/.libs/libgphoto2.so.6.1.0 gphoto2 --version
gphoto2 2.5.15

Copyright (c) 2000-2017 Lutz Mueller and others

gphoto2 comes with NO WARRANTY, to the extent permitted by law. You may
redistribute copies of gphoto2 under the terms of the GNU General Public
License. For more information about these matters, see the files named COPYING.

This version of gphoto2 is using the following software versions and options:
gphoto2         2.5.15         gcc, popt(m), exif, cdk, aa, jpeg, readline
libgphoto2      2.5.22.1       all camlibs, gcc, ltdl, no EXIF
libgphoto2_port 0.12.0         iolibs: disk ptpip serial usb usbdiskdirect usbscsi, gcc, ltdl, USB, serial without locking

... you will still get the old libraries listed.

However - using $PREAMBLE as a shorthand for tha massive preamble - the command $PREAMBLE strace gphoto2 --version 2>&1 | grep '\.so' will confirm that the new libraries are loaded instead!

This works on python-gphoto2 too; so I've ran the script in the OP again:

$ $PREAMBLE python test-sm-ec.py 2>&1 | grep capture 
port_log.py:127 DEBUG: gphoto2: (print_debug_deviceinfo)   0x100e (Initiate capture)

... and there are no more mentions of capture anywhere, nor does the shutter/photo taking get triggered! Without the stderr log, the output looks like:

$ $PREAMBLE python test-sm-ec.py 2>/dev/null 
1548406826.81 Start settings (sleeptime=1, endwithauto=1):
1548406826.81 set shootingmode Auto
1548406827.86 set shootingmode Manual
1548406829.07 set shootingmode Auto (wait_for_event takes photo here?!)
1548406829.11 about to wait_for_event
1548406839.48 set shootingmode Auto

I also tried the test-sm-ec2.py from jim-easterbrook/python-gphoto2#75 (comment), with the empty_event_queue(camera) line enabled/uncommented (that one calls wait_for_event); the while (oldecro == ecro): loop disabled/commented; and enabled print(type_, data) in empty_event_queue.

This result I get, if Live View has not been exercised yet:

$ $PREAMBLE python test-sm-ec2.py
1548408579.28 Start: shootingmode 'Auto', exposurecompensation ro=0
1548408579.42 After Manual 01: shootingmode 'Manual', exposurecompensation ro=0
0 PTP Event c00e, Param1 00000000
0 PTP Event c00e, Param1 00000000
1 None
1548408580.52 After Auto 01: shootingmode 'Auto', exposurecompensation ro=0 (delta=1.101)

... is one with no spurious photos taken - and where the exposurecompensation ro state does not change neither when switching to Manual, nor when switching back to Auto.

And this is the result when having exercised live view:

$ $PREAMBLE python test-sm-ec2.py
1548408737.99 Start: shootingmode 'Auto', exposurecompensation ro=0
1548408740.26 After Manual 01: shootingmode 'Manual', exposurecompensation ro=1
0 PTP Event c00e, Param1 00000000
0 PTP Event c00e, Param1 00000000
1 None
1548408741.74 After Auto 01: shootingmode 'Auto', exposurecompensation ro=0 (delta=1.483)

... where again no spurious photos are taken - and exposurecompensation ro state changes only when switching to Manual (but not when switching back to Auto)

So while the problem this issue was originally posted for is fixed -- there are no more spurious photos taken when using wait_for_event -- I just wanted to comment, that the original intention I had for using wait_for_event (which is waiting for the exposurecompensation read-only state to change in response to change of shootingmode) has been misplaced: it seems that there are no such events emitted when this state changes, so the best one can do with wait_for_event is simply timeout (which is more-or-less what test-sm-ec2.py in its original form ends up doing)

Thanks again - will close this issue now, as the problem has been solved!

@sdaau sdaau closed this as completed Jan 25, 2019
knro pushed a commit to knro/libgphoto2 that referenced this issue Mar 13, 2019
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants