Debug and error logging cleanup

classic Classic list List threaded Threaded
24 messages Options
12
Reply | Threaded
Open this post in threaded view
|

Debug and error logging cleanup

Axel Waggershauser
Hi Marcus,

now that I am through with the error return code handling stuff in
ptp2, which also affected/added automatic logging (mostly in the 5th
patch of the series), I wanted to address another related issue: the
handling of the debug and error logging with gp_log.

My last patch used the __func__ feature of C99 to give a context for
the error reporting inside the proposed C_PTP* macros (the 'domain'
parameter of gp_log). But that is inconsistent with the existing
strategy of mostly using something similar to the filename of the
enclosing source file. Plus: the existing usage of the 'domain'
parameter was already inconsistent. I also found the partly used
GP_DEBUG() macro, which uses the GP_MODULE string and the __FILE__
macro as the context info.

I want to suggest a couple of changes based on the following assumptions:
* the debug/log-file is only really of interest to developers
* one want's to find out what went wrong: "where exactly failed which
function?" and "what happened before?"
* the log-file is used for manual inspection and should therefore be
as clean and clear as possible for visual 'parsing'

I think the current state could be improved by
* increasing consistency of
  + the meaning of the domain parameter
  + the wording of the error/log messages
  + the kind of operations that get logged
  + properly distinguishing between errors and debug messages
* doing some simple pretty printing of the log messages themselves
* giving textual error strings where available (instead of only hex-codes)
* giving the precise location of an error (spare one to grep through
the source just to find out where the error came from)
* don't translate debug and error messages that only get logged
(developers of gphoto need to understand English anyway, if they want
to do something with the debug logs and getting a Greek log-file would
not be helpful to me ;))
* replacing the old ptp_debug and ptp_error functions in ptp.c with
the standard gp_log-based stuff

I did some experiments with the existing GP_DEBUG macro. I tried
introducing the __func__ string here but for normal debug log-lines
this is not helpful. It turns out that the source-code layout results
in the __FILE__ macro being pretty much exactly what a lot of the
manual 'domain' strings are right now, e.g. "ptp2/usb.c". That is what
they look like on a standard configure+make build, at least. The
GP_MODULE string can therefore simply be done away with, I think.

For the logging of errors, I'd suggest to also incorporate the
__LINE__ macro, which then allows to quickly find the relevant source
location. Additionally printing the __func__ information in the case
of an error might be convenient but not really necessary. E.g.

0.037619 ptp2/usb.c:417 - ptp_usb_getresp(0): PTP_OC 0x1002 getting
resp error 'PTP Session Already Opened' (0x201e)

To consistently take advantage of the automatic source-code context, I
propose to rename the GP_DEBUG macro to GP_LOG_D and add a GP_LOG_E
macro for error logging. It is closer to the underlying gp_log
function and strait forward to see what it is doing. The latter can
then easily add line and/or calling function information to the
standard filename info.

A trivial one-line patch in gphoto2/actions.c would help to visually
parse the log-file. An example log-file to illustrate what I mean is
attached (it's not complete, yet).

If you/anyone has objections regarding this course of action, please
let me know. Meanwhile, I'll hack away...

 - Axel

------------------------------------------------------------------------------
Open source business process management suite built on Java and Eclipse
Turn processes into business applications with Bonita BPM Community Edition
Quickly connect people, data, and systems into organized workflows
Winner of BOSSIE, CODIE, OW2 and Gartner awards
http://p.sf.net/sfu/Bonitasoft
_______________________________________________
Gphoto-devel mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/gphoto-devel

example-log-snippet (2K) Download Attachment
Reply | Threaded
Open this post in threaded view
|

Re: Debug and error logging cleanup

Marcus Meissner
Hi,

On Thu, Jul 10, 2014 at 08:48:50PM +0200, Axel Waggershauser wrote:

> Hi Marcus,
>
> now that I am through with the error return code handling stuff in
> ptp2, which also affected/added automatic logging (mostly in the 5th
> patch of the series), I wanted to address another related issue: the
> handling of the debug and error logging with gp_log.
>
> My last patch used the __func__ feature of C99 to give a context for
> the error reporting inside the proposed C_PTP* macros (the 'domain'
> parameter of gp_log). But that is inconsistent with the existing
> strategy of mostly using something similar to the filename of the
> enclosing source file. Plus: the existing usage of the 'domain'
> parameter was already inconsistent. I also found the partly used
> GP_DEBUG() macro, which uses the GP_MODULE string and the __FILE__
> macro as the context info.

Yes, thats true.
 
> I want to suggest a couple of changes based on the following assumptions:
> * the debug/log-file is only really of interest to developers

Yes.

> * one want's to find out what went wrong: "where exactly failed which
> function?" and "what happened before?"

Yes.

> * the log-file is used for manual inspection and should therefore be
> as clean and clear as possible for visual 'parsing'

Yes.

> I think the current state could be improved by
> * increasing consistency of
>   + the meaning of the domain parameter
>   + the wording of the error/log messages
>   + the kind of operations that get logged
>   + properly distinguishing between errors and debug messages

I can only agree.

> * doing some simple pretty printing of the log messages themselves

Not sure how much that would help.

> * giving textual error strings where available (instead of only hex-codes)

Yes, but if they are unknonwn, the value of course needs to be printed in hex.

> * giving the precise location of an error (spare one to grep through
> the source just to find out where the error came from)

Semi useful, as it should be clear, but yes.

> * don't translate debug and error messages that only get logged
> (developers of gphoto need to understand English anyway, if they want
> to do something with the debug logs and getting a Greek log-file would
> not be helpful to me ;))

This is the orignal intent here, gp_log should usually not get translated
strings, these go out via context error. That said, if one or two slip
in it is not problematic for me.

> * replacing the old ptp_debug and ptp_error functions in ptp.c with
> the standard gp_log-based stuff

This code (ptp.c, ptp.h, chdk*.h) is shared with libmtp, it needs to stay
free of gphoto specific things.

We can however change the error and debug reporting hook to have more arguments
if there is need (as it is a trivial fixup for libmtp).

> I did some experiments with the existing GP_DEBUG macro. I tried
> introducing the __func__ string here but for normal debug log-lines
> this is not helpful. It turns out that the source-code layout results
> in the __FILE__ macro being pretty much exactly what a lot of the
> manual 'domain' strings are right now, e.g. "ptp2/usb.c". That is what
> they look like on a standard configure+make build, at least. The
> GP_MODULE string can therefore simply be done away with, I think.

(Except for out of tree builds, where it will be very long.)

But yes.

> For the logging of errors, I'd suggest to also incorporate the
> __LINE__ macro, which then allows to quickly find the relevant source
> location. Additionally printing the __func__ information in the case
> of an error might be convenient but not really necessary. E.g.


> 0.037619 ptp2/usb.c:417 - ptp_usb_getresp(0): PTP_OC 0x1002 getting
> resp error 'PTP Session Already Opened' (0x201e)

The function name will definitely help visual inspection, which you
underlined as main focus of this proposal.

__FILE__ is the least important here for me, as for reading its
clear by the functionname in which file it will be.
But we can also use it, it just might make the line too wide.
 
> To consistently take advantage of the automatic source-code context, I
> propose to rename the GP_DEBUG macro to GP_LOG_D and add a GP_LOG_E
> macro for error logging. It is closer to the underlying gp_log
> function and strait forward to see what it is doing. The latter can
> then easily add line and/or calling function information to the
> standard filename info.

Sounds good to me.

> A trivial one-line patch in gphoto2/actions.c would help to visually
> parse the log-file. An example log-file to illustrate what I mean is
> attached (it's not complete, yet).
>
> If you/anyone has objections regarding this course of action, please
> let me know. Meanwhile, I'll hack away...

No large ones, except for ptp.c/ptp.h.

Ciao, Marcus

------------------------------------------------------------------------------
_______________________________________________
Gphoto-devel mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/gphoto-devel
Reply | Threaded
Open this post in threaded view
|

Re: Debug and error logging cleanup

Axel Waggershauser
Hi,

>> * doing some simple pretty printing of the log messages themselves
>
> Not sure how much that would help.

see attachment of example trace generated after applying the attached
GP_LOG_E/D patch.


>> * giving textual error strings where available (instead of only hex-codes)
>
> Yes, but if they are unknonwn, the value of course needs to be printed in hex.

Certainly, the patches always print the raw hex code but also the error string.


>> * giving the precise location of an error (spare one to grep through
>> the source just to find out where the error came from)
>
> Semi useful, as it should be clear, but yes.

Until now, if I found the string "... gphoto2-file(0): Encountered 0
bytes reading from fd." in a debug trace I would have had to use grep
to find the source location to look into it. It is probably
unambiguous for most error strings but I could not be sure. That is
what I meant.


>> * replacing the old ptp_debug and ptp_error functions in ptp.c with
>> the standard gp_log-based stuff
>
> This code (ptp.c, ptp.h, chdk*.h) is shared with libmtp, it needs to stay
> free of gphoto specific things.
>
> We can however change the error and debug reporting hook to have more arguments
> if there is need (as it is a trivial fixup for libmtp).

I see. I'll not touch them for now, then.


>> 0.037619 ptp2/usb.c:417 - ptp_usb_getresp(0): PTP_OC 0x1002 getting
>> resp error 'PTP Session Already Opened' (0x201e)
>
> The function name will definitely help visual inspection, which you
> underlined as main focus of this proposal.
>
> __FILE__ is the least important here for me, as for reading its
> clear by the functionname in which file it will be.
> But we can also use it, it just might make the line too wide.

I changed my mind a bit and agree: the function name is mostly more
informative at a first look than a __FILE__/__LINE__ information.
Sometimes the function name is not unambiguous, though, e.g.
gp_port_usb_open exists in both libusb.c and libusb1.c. For LOG_D
messages this should be no issue and for LOG_E messages I propose to
use the following syntax:

0.037619 ptp_usb_getresp [usb.c:417]    (0): PTP_OC 0x1002 getting
resp error 'PTP Session Already Opened' (0x201e)

I.e. only the filename and the line-number are printed. This should
still help a lot in locating the error and be unaffected by
out-of-tree build paths.

The attached patch introduces the macros and applies them to usb.c and
gphoto2-port.c. I also cleaned up the log messages according the the
other discussed points. I'd continue to replace gp_log() and
GP_DEBUG() calls with the new macros in further patches.

 - Axel

------------------------------------------------------------------------------
Want fast and easy access to all the code in your enterprise? Index and
search up to 200,000 lines of code with a free copy of Black Duck
Code Sight - the same software that powers the world's largest code
search on Ohloh, the Black Duck Open Hub! Try it now.
http://p.sf.net/sfu/bds
_______________________________________________
Gphoto-devel mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/gphoto-devel

log-cleanup-1-new-logging-macros.patch (37K) Download Attachment
example-log-snippet (996 bytes) Download Attachment
Reply | Threaded
Open this post in threaded view
|

Re: Debug and error logging cleanup

Gavin Swanson
I'm personally a fan of having the filename and line number in the error output. In some cases it gives certain tools the info they need to locate the error for you in an editor etc.

Gavin S


On Thu, Jul 17, 2014 at 7:17 AM, Axel Waggershauser <[hidden email]> wrote:
Hi,

>> * doing some simple pretty printing of the log messages themselves
>
> Not sure how much that would help.

see attachment of example trace generated after applying the attached
GP_LOG_E/D patch.


>> * giving textual error strings where available (instead of only hex-codes)
>
> Yes, but if they are unknonwn, the value of course needs to be printed in hex.

Certainly, the patches always print the raw hex code but also the error string.


>> * giving the precise location of an error (spare one to grep through
>> the source just to find out where the error came from)
>
> Semi useful, as it should be clear, but yes.

Until now, if I found the string "... gphoto2-file(0): Encountered 0
bytes reading from fd." in a debug trace I would have had to use grep
to find the source location to look into it. It is probably
unambiguous for most error strings but I could not be sure. That is
what I meant.


>> * replacing the old ptp_debug and ptp_error functions in ptp.c with
>> the standard gp_log-based stuff
>
> This code (ptp.c, ptp.h, chdk*.h) is shared with libmtp, it needs to stay
> free of gphoto specific things.
>
> We can however change the error and debug reporting hook to have more arguments
> if there is need (as it is a trivial fixup for libmtp).

I see. I'll not touch them for now, then.


>> 0.037619 ptp2/usb.c:417 - ptp_usb_getresp(0): PTP_OC 0x1002 getting
>> resp error 'PTP Session Already Opened' (0x201e)
>
> The function name will definitely help visual inspection, which you
> underlined as main focus of this proposal.
>
> __FILE__ is the least important here for me, as for reading its
> clear by the functionname in which file it will be.
> But we can also use it, it just might make the line too wide.

I changed my mind a bit and agree: the function name is mostly more
informative at a first look than a __FILE__/__LINE__ information.
Sometimes the function name is not unambiguous, though, e.g.
gp_port_usb_open exists in both libusb.c and libusb1.c. For LOG_D
messages this should be no issue and for LOG_E messages I propose to
use the following syntax:

0.037619 ptp_usb_getresp [usb.c:417]    (0): PTP_OC 0x1002 getting
resp error 'PTP Session Already Opened' (0x201e)

I.e. only the filename and the line-number are printed. This should
still help a lot in locating the error and be unaffected by
out-of-tree build paths.

The attached patch introduces the macros and applies them to usb.c and
gphoto2-port.c. I also cleaned up the log messages according the the
other discussed points. I'd continue to replace gp_log() and
GP_DEBUG() calls with the new macros in further patches.

 - Axel

------------------------------------------------------------------------------
Want fast and easy access to all the code in your enterprise? Index and
search up to 200,000 lines of code with a free copy of Black Duck
Code Sight - the same software that powers the world's largest code
search on Ohloh, the Black Duck Open Hub! Try it now.
http://p.sf.net/sfu/bds
_______________________________________________
Gphoto-devel mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/gphoto-devel



------------------------------------------------------------------------------
Want fast and easy access to all the code in your enterprise? Index and
search up to 200,000 lines of code with a free copy of Black Duck
Code Sight - the same software that powers the world's largest code
search on Ohloh, the Black Duck Open Hub! Try it now.
http://p.sf.net/sfu/bds
_______________________________________________
Gphoto-devel mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/gphoto-devel
Reply | Threaded
Open this post in threaded view
|

Re: Debug and error logging cleanup

Axel Waggershauser
In reply to this post by Axel Waggershauser
On Fri, Jul 18, 2014 at 10:01 AM, Marcus Meissner <[hidden email]> wrote:

> On Fri, Jul 18, 2014 at 02:00:51AM +0200, Axel Waggershauser wrote:
>> Hi Marcus,
>>
>> I completed the GP_LOG_D/E series of patches for the camlibs/ptp2,
>> libgphoto2 and libgphtoto_port/libgphtoto_port directories. I did not
>> touch the libusb1.c file and the like, since a change here will
>> conflict with the pending libusb1.c discussion.
>>
>> Before I resend you these patches, one remark: I changed the
>> GP_LOG_E(...) internal variables (str and file) to have unsusual names
>> (__str and __file) as to prevent any shadowing like the other one. But
>> I thought another, cleaner solution would be to have a simple helper
>> function
>>
>>     gp_log_helper( GPLogLevel level, const char *file, int line, const
>> char* func, const char *format, ...);
>>
>> that gets called from the GP_LOG_E macro and assembles the domain
>> string internally and passes it on to gp_logv. -> no more introduction
>> of local variables into the calling scope of GP_LOG_E.
>>
>> If you think that is preferable, I'll update the first patch and send
>> you the complete series.
>
> Letzteres finde ich eine gute Idee.
Attached is the GP_LOG_ related cleanup patchset with the mentioned
gp_log_... helper function.

some explanation:

0) only introduces the new macros with the helper, adds a new symbol
to the libgphoto_port library.

1) uses them in usb.c and gphoto_port.c. It was the code that I
started with and already posted before.

2) only replaces the existing GP_DEBUG with the new GP_LOG_D and
removes the GP_MODULE strings

3, 4) strictly replacing gp_log( GP_LOG_DEBUG/ERROR, ... with
GP_LOG_D/E in the camlibs/ptp2 code. they are simple regex-replace
patches.

5) fix some whitespace issues caused by 3 and 4 and remove any _(...)
gettext macro usage for log messages

6) use the macros inside the new C_PTP_... macros in ptp-private.h

7, 8, 9) same 3,4,5 but for libgphoto core

10, 11, 12) same as 3,4,5 but for libgphoto_port core

I'll add the libgphoto_port backend libs after there is conses on the
parallel libusb1.c cleanup discussion.

 - Axel

------------------------------------------------------------------------------
Want fast and easy access to all the code in your enterprise? Index and
search up to 200,000 lines of code with a free copy of Black Duck
Code Sight - the same software that powers the world's largest code
search on Ohloh, the Black Duck Open Hub! Try it now.
http://p.sf.net/sfu/bds
_______________________________________________
Gphoto-devel mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/gphoto-devel

log-cleanup-0-new-logging-macros.patch (5K) Download Attachment
log-cleanup-1-use-GP_LOG_-in-usb_c_and_gphoto2_port_c.patch (33K) Download Attachment
log-cleanup-2-replace-GP_DEBUG-with-LOG_D.patch (47K) Download Attachment
log-cleanup-3-use-GP_LOG_D-macro-in-ptp2.patch (89K) Download Attachment
log-cleanup-4-use-GP_LOG_E-macro-in-ptp2.patch (36K) Download Attachment
log-cleanup-5-fix-whitespace-and-gettext-inside-GP_LOG-in-ptp2.patch (8K) Download Attachment
log-cleanup-6-use-GP_LOG_E-in-C_PTP-macros.patch (3K) Download Attachment
log-cleanup-7-use-GP_LOG_D-in-libgphoto2.patch (28K) Download Attachment
log-cleanup-8-use-GP_LOG_E-in-libgphoto2.patch (17K) Download Attachment
log-cleanup-9-fix-whitespace-and-gettext-inside-GP_LOG-in-libgphoto2.patch (19K) Download Attachment
log-cleanup-10-use-GP_LOG_D-in-libgphoto2_port.patch (5K) Download Attachment
log-cleanup-11-use-GP_LOG_E-in-libgphoto2_port.patch (2K) Download Attachment
log-cleanup-12-fix-whitespace-and-gettext-inside-GP_LOG-in-libgphoto2_port.patch (8K) Download Attachment
Reply | Threaded
Open this post in threaded view
|

Re: Debug and error logging cleanup

Marcus Meissner-4
Hi,


On Fri, Jul 18, 2014 at 01:11:55PM +0200, Axel Waggershauser wrote:
[...]
> Attached is the GP_LOG_ related cleanup patchset with the mentioned
> gp_log_... helper function.
[...]

I reviewed and applied all these as-is. Looked good. :)
 
Ciao, Marcus

------------------------------------------------------------------------------
Want fast and easy access to all the code in your enterprise? Index and
search up to 200,000 lines of code with a free copy of Black Duck
Code Sight - the same software that powers the world's largest code
search on Ohloh, the Black Duck Open Hub! Try it now.
http://p.sf.net/sfu/bds
_______________________________________________
Gphoto-devel mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/gphoto-devel
Reply | Threaded
Open this post in threaded view
|

Re: Debug and error logging cleanup

Marcus Meissner-4
On Sat, Jul 19, 2014 at 01:49:31PM +0200, Marcus Meissner wrote:

> Hi,
>
>
> On Fri, Jul 18, 2014 at 01:11:55PM +0200, Axel Waggershauser wrote:
> [...]
> > Attached is the GP_LOG_ related cleanup patchset with the mentioned
> > gp_log_... helper function.
> [...]
>
> I reviewed and applied all these as-is. Looked good. :)

However "make check" fails...

g++ -DHAVE_CONFIG_H -I. -I..  -D_GPHOTO2_INTERNAL_CODE -DLOCALEDIR=\"/usr/share/locale\" -DCAMLIBS=\"/usr/lib64/libgphoto2/2.5.4.2\" -I.. -I.. -I../libgphoto2_port -I../libgphoto2 -I../libgphoto2  -U_GPHOTO2_INTERNAL_CODE   -std=c++98 -pedantic-errors -W -Wall -Wextra -Werror -g -O2 -U_GPHOTO2_INTERNAL_CODE -g -O2 -MT test_pedantic_cxx-test-pedantic-compilation.o -MD -MP -MF .deps/test_pedantic_cxx-test-pedantic-compilation.Tpo -c -o test_pedantic_cxx-test-pedantic-compilation.o `test -f 'test-pedantic-compilation.cxx' || echo './'`test-pedantic-compilation.cxx

In file included from ../gphoto2/gphoto2.h:46:0,
                 from test-pedantic-compilation.cxx:1:
../libgphoto2_port/gphoto2/gphoto2-port-log.h:95:18: error: anonymous variadic macros were introduced in C99 [-Wvariadic-macros]
 #define GP_LOG_D(...) gp_log(GP_LOG_DEBUG, __func__, __VA_ARGS__)


We might want to bump the -std=c++98 to something newer.

Opinions?

CIao, Marcus

------------------------------------------------------------------------------
Want fast and easy access to all the code in your enterprise? Index and
search up to 200,000 lines of code with a free copy of Black Duck
Code Sight - the same software that powers the world's largest code
search on Ohloh, the Black Duck Open Hub! Try it now.
http://p.sf.net/sfu/bds
_______________________________________________
Gphoto-devel mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/gphoto-devel
Reply | Threaded
Open this post in threaded view
|

Re: Debug and error logging cleanup

Axel Waggershauser
> However "make check" fails...

If only I know about that make target ;)

> g++ -DHAVE_CONFIG_H -I. -I..  -D_GPHOTO2_INTERNAL_CODE -DLOCALEDIR=\"/usr/share/locale\" -DCAMLIBS=\"/usr/lib64/libgphoto2/2.5.4.2\" -I.. -I.. -I../libgphoto2_port -I../libgphoto2 -I../libgphoto2  -U_GPHOTO2_INTERNAL_CODE   -std=c++98 -pedantic-errors -W -Wall -Wextra -Werror -g -O2 -U_GPHOTO2_INTERNAL_CODE -g -O2 -MT test_pedantic_cxx-test-pedantic-compilation.o -MD -MP -MF .deps/test_pedantic_cxx-test-pedantic-compilation.Tpo -c -o test_pedantic_cxx-test-pedantic-compilation.o `test -f 'test-pedantic-compilation.cxx' || echo './'`test-pedantic-compilation.cxx
>
> In file included from ../gphoto2/gphoto2.h:46:0,
>                  from test-pedantic-compilation.cxx:1:
> ../libgphoto2_port/gphoto2/gphoto2-port-log.h:95:18: error: anonymous variadic macros were introduced in C99 [-Wvariadic-macros]
>  #define GP_LOG_D(...) gp_log(GP_LOG_DEBUG, __func__, __VA_ARGS__)
>
>
> We might want to bump the -std=c++98 to something newer.
>
> Opinions?

What about c99, since it is plain C? Or not forcing anything. I
checked that the __VA_ARGS__ stuff compiles with gcc and clang (recent
versions).

 - Axel

------------------------------------------------------------------------------
Want fast and easy access to all the code in your enterprise? Index and
search up to 200,000 lines of code with a free copy of Black Duck
Code Sight - the same software that powers the world's largest code
search on Ohloh, the Black Duck Open Hub! Try it now.
http://p.sf.net/sfu/bds
_______________________________________________
Gphoto-devel mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/gphoto-devel
Reply | Threaded
Open this post in threaded view
|

Re: Debug and error logging cleanup

Marcus Meissner
On Sun, Jul 20, 2014 at 04:19:12PM +0200, Axel Waggershauser wrote:

> > However "make check" fails...
>
> If only I know about that make target ;)
>
> > g++ -DHAVE_CONFIG_H -I. -I..  -D_GPHOTO2_INTERNAL_CODE -DLOCALEDIR=\"/usr/share/locale\" -DCAMLIBS=\"/usr/lib64/libgphoto2/2.5.4.2\" -I.. -I.. -I../libgphoto2_port -I../libgphoto2 -I../libgphoto2  -U_GPHOTO2_INTERNAL_CODE   -std=c++98 -pedantic-errors -W -Wall -Wextra -Werror -g -O2 -U_GPHOTO2_INTERNAL_CODE -g -O2 -MT test_pedantic_cxx-test-pedantic-compilation.o -MD -MP -MF .deps/test_pedantic_cxx-test-pedantic-compilation.Tpo -c -o test_pedantic_cxx-test-pedantic-compilation.o `test -f 'test-pedantic-compilation.cxx' || echo './'`test-pedantic-compilation.cxx
> >
> > In file included from ../gphoto2/gphoto2.h:46:0,
> >                  from test-pedantic-compilation.cxx:1:
> > ../libgphoto2_port/gphoto2/gphoto2-port-log.h:95:18: error: anonymous variadic macros were introduced in C99 [-Wvariadic-macros]
> >  #define GP_LOG_D(...) gp_log(GP_LOG_DEBUG, __func__, __VA_ARGS__)
> >
> >
> > We might want to bump the -std=c++98 to something newer.
> >
> > Opinions?
>
> What about c99, since it is plain C? Or not forcing anything. I
> checked that the __VA_ARGS__ stuff compiles with gcc and clang (recent
> versions).

The idea of this test is to check the use of the libgphoto2 API in C++ programs.

-U_GPHOTO2_INTERNAL_CODE

Your new macros were exposed to users of the library.

I have moved them into the interal parts similar to GP_DEBUG, and it now
builds and checks both default and with --disable-debug

Ciao, Marcus

------------------------------------------------------------------------------
Want fast and easy access to all the code in your enterprise? Index and
search up to 200,000 lines of code with a free copy of Black Duck
Code Sight - the same software that powers the world's largest code
search on Ohloh, the Black Duck Open Hub! Try it now.
http://p.sf.net/sfu/bds
_______________________________________________
Gphoto-devel mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/gphoto-devel
Reply | Threaded
Open this post in threaded view
|

Re: Debug and error logging cleanup

Axel Waggershauser
Hi Marcus,

I added a LOG_ON_PTP_E mechanism similar to the LOG_ON_LIBUSB_E one.
This further increases consistency in error reporting in places where
the C_PTP_... macros could not be used. I used the macro mainly where
there have been existing checks for != PTP_RC_OK. There might be a lot
other, yet unchecked places, where this macro could be useful.

I also tuned some of the error/debug messages with the same goal (like
replacing '%x' with '%04x' in the C_PTP_ macros) or adding the
ptp_strerror where appropriate.

Please note, that both the 'inline' and the 'static' keyword in front
of the log_on_ptp_error_helper() function definition are of use here,
to make the compiler not warn about unused functions or functions
without prototype.

Unrelated to the new macro, I found an inconsistency in the error
handling inside the camera_set_config function: a failure to set a
config value from the standard menu cancels the function, while a
failure to set one of the generic property values does not (see new
comment).

Also I wonder whether there is a call to

                ptp_free_devicepropdesc(&dpd);
                ptp_free_devicepropvalue(cursub->type, &propval);

missing inside the generic property setter part (right at the end of config.c)?

Cheers,
  Axel

On Sun, Jul 20, 2014 at 8:10 PM, Marcus Meissner <[hidden email]> wrote:

> On Sun, Jul 20, 2014 at 04:19:12PM +0200, Axel Waggershauser wrote:
>> > However "make check" fails...
>>
>> If only I know about that make target ;)
>>
>> > g++ -DHAVE_CONFIG_H -I. -I..  -D_GPHOTO2_INTERNAL_CODE -DLOCALEDIR=\"/usr/share/locale\" -DCAMLIBS=\"/usr/lib64/libgphoto2/2.5.4.2\" -I.. -I.. -I../libgphoto2_port -I../libgphoto2 -I../libgphoto2  -U_GPHOTO2_INTERNAL_CODE   -std=c++98 -pedantic-errors -W -Wall -Wextra -Werror -g -O2 -U_GPHOTO2_INTERNAL_CODE -g -O2 -MT test_pedantic_cxx-test-pedantic-compilation.o -MD -MP -MF .deps/test_pedantic_cxx-test-pedantic-compilation.Tpo -c -o test_pedantic_cxx-test-pedantic-compilation.o `test -f 'test-pedantic-compilation.cxx' || echo './'`test-pedantic-compilation.cxx
>> >
>> > In file included from ../gphoto2/gphoto2.h:46:0,
>> >                  from test-pedantic-compilation.cxx:1:
>> > ../libgphoto2_port/gphoto2/gphoto2-port-log.h:95:18: error: anonymous variadic macros were introduced in C99 [-Wvariadic-macros]
>> >  #define GP_LOG_D(...) gp_log(GP_LOG_DEBUG, __func__, __VA_ARGS__)
>> >
>> >
>> > We might want to bump the -std=c++98 to something newer.
>> >
>> > Opinions?
>>
>> What about c99, since it is plain C? Or not forcing anything. I
>> checked that the __VA_ARGS__ stuff compiles with gcc and clang (recent
>> versions).
>
> The idea of this test is to check the use of the libgphoto2 API in C++ programs.
>
> -U_GPHOTO2_INTERNAL_CODE
>
> Your new macros were exposed to users of the library.
>
> I have moved them into the interal parts similar to GP_DEBUG, and it now
> builds and checks both default and with --disable-debug
>
> Ciao, Marcus

------------------------------------------------------------------------------
Want fast and easy access to all the code in your enterprise? Index and
search up to 200,000 lines of code with a free copy of Black Duck
Code Sight - the same software that powers the world's largest code
search on Ohloh, the Black Duck Open Hub! Try it now.
http://p.sf.net/sfu/bds
_______________________________________________
Gphoto-devel mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/gphoto-devel

log-cleanup-13-LOG_ON_PTP_E.patch (22K) Download Attachment
Reply | Threaded
Open this post in threaded view
|

Re: Debug and error logging cleanup

Rogier Wolff
On Tue, Jul 22, 2014 at 03:50:17PM +0200, Axel Waggershauser wrote:
> Please note, that both the 'inline' and the 'static' keyword in front
> of the log_on_ptp_error_helper() function definition are of use here,
> to make the compiler not warn about unused functions or functions

And let me say that I think that that is VERY important. A few days
ago I tried compiling the "raspberry pi userland" code, wondered what
all those warnings were about, and the first I investigated pointed
DIRECTLY at a bug that apparently had gone unnoticed for months....

Keep up the good work Axel!

        Roger.

--
** [hidden email] ** http://www.BitWizard.nl/ ** +31-15-2600998 **
**    Delftechpark 26 2628 XH  Delft, The Netherlands. KVK: 27239233    **
*-- BitWizard writes Linux device drivers for any device you may have! --*
The plan was simple, like my brother-in-law Phil. But unlike
Phil, this plan just might work.

------------------------------------------------------------------------------
Want fast and easy access to all the code in your enterprise? Index and
search up to 200,000 lines of code with a free copy of Black Duck
Code Sight - the same software that powers the world's largest code
search on Ohloh, the Black Duck Open Hub! Try it now.
http://p.sf.net/sfu/bds
_______________________________________________
Gphoto-devel mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/gphoto-devel
Reply | Threaded
Open this post in threaded view
|

Re: Debug and error logging cleanup

Axel Waggershauser
In reply to this post by Axel Waggershauser
Hi there,

here are the logging cleanup patches for the remaining libgphoto_port
backend libs, that I announced earlier.

14 and 15 are equivalent to 3,4,5 as before.

16 removes 4 left instances of _(...) macro usage in log messages.

There is one thing left with regard to logging, that I'd like to
change: There are a handful of gp_log( GP_LOG_VERBOSE... calls. I
suggest to either:

a) introduce a GP_LOG_V macro for consitency
b) replace them with GP_LOG_D() calls, effectively obsoleting the
'verbose' log level.

I strongly prefer option b). Sometimes it is not even clear cut
whether a log line is an error or just a debugging statement.
Distinguishing between verbose and debug seems totally superficial to
me. And there is no real tradition using it anyway. That change would
be complete if we actually removed the GP_LOG_VERBOSE value and
string-replaced it in the remaining code (other camlibs) with
GP_LOG_DEBUG.

Opinion?

 - Axel

------------------------------------------------------------------------------
Want fast and easy access to all the code in your enterprise? Index and
search up to 200,000 lines of code with a free copy of Black Duck
Code Sight - the same software that powers the world's largest code
search on Ohloh, the Black Duck Open Hub! Try it now.
http://p.sf.net/sfu/bds
_______________________________________________
Gphoto-devel mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/gphoto-devel

log-cleanup-14-use-GP_LOG_D+E-in-port-libs.patch (34K) Download Attachment
log-cleanup-15-fix-whitespace-and-gettext-inside-GP_LOG_D+E-in-port-libs.patch (11K) Download Attachment
log-cleanup-16-remove-gettext-macro-from-gp_log-calls.patch (1K) Download Attachment
Reply | Threaded
Open this post in threaded view
|

Re: Debug and error logging cleanup

Marcus Meissner-4
On Tue, Jul 22, 2014 at 07:30:34PM +0200, Axel Waggershauser wrote:
> Hi there,
>
> here are the logging cleanup patches for the remaining libgphoto_port
> backend libs, that I announced earlier.
>
> 14 and 15 are equivalent to 3,4,5 as before.
>
> 16 removes 4 left instances of _(...) macro usage in log messages.

I applied them, thanks!

> There is one thing left with regard to logging, that I'd like to
> change: There are a handful of gp_log( GP_LOG_VERBOSE... calls. I
> suggest to either:
>
> a) introduce a GP_LOG_V macro for consitency
> b) replace them with GP_LOG_D() calls, effectively obsoleting the
> 'verbose' log level.
>
> I strongly prefer option b). Sometimes it is not even clear cut
> whether a log line is an error or just a debugging statement.
> Distinguishing between verbose and debug seems totally superficial to
> me. And there is no real tradition using it anyway. That change would
> be complete if we actually removed the GP_LOG_VERBOSE value and
> string-replaced it in the remaining code (other camlibs) with
> GP_LOG_DEBUG.

I did not even recall that there is a VERBOSE Loglevel... ;)

Yes, we can replace it with GP_LOG_D calls or GP_LOG_DEBUG, so option (b).

Ciao, Marcus

------------------------------------------------------------------------------
Want fast and easy access to all the code in your enterprise? Index and
search up to 200,000 lines of code with a free copy of Black Duck
Code Sight - the same software that powers the world's largest code
search on Ohloh, the Black Duck Open Hub! Try it now.
http://p.sf.net/sfu/bds
_______________________________________________
Gphoto-devel mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/gphoto-devel
Reply | Threaded
Open this post in threaded view
|

Re: Debug and error logging cleanup

Axel Waggershauser
> I did not even recall that there is a VERBOSE Loglevel... ;)
>
> Yes, we can replace it with GP_LOG_D calls or GP_LOG_DEBUG, so option (b).

I had something 'prepared' for this situation, here you go.. ;)

The patch does not, however, actually remove the GP_LOG_VERBOSE enum,
since that would change the interface for all clients, which might not
be worth it. If you don't think that is a problem, please remove it...

 - Axel

------------------------------------------------------------------------------
Want fast and easy access to all the code in your enterprise? Index and
search up to 200,000 lines of code with a free copy of Black Duck
Code Sight - the same software that powers the world's largest code
search on Ohloh, the Black Duck Open Hub! Try it now.
http://p.sf.net/sfu/bds
_______________________________________________
Gphoto-devel mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/gphoto-devel

log-cleanup-17-replace-VERBOSE-with-DEBUG.patch (14K) Download Attachment
Reply | Threaded
Open this post in threaded view
|

Re: Debug and error logging cleanup

Marcus Meissner-4
On Tue, Jul 22, 2014 at 11:19:59PM +0200, Axel Waggershauser wrote:
> > I did not even recall that there is a VERBOSE Loglevel... ;)
> >
> > Yes, we can replace it with GP_LOG_D calls or GP_LOG_DEBUG, so option (b).
>
> I had something 'prepared' for this situation, here you go.. ;)
>
> The patch does not, however, actually remove the GP_LOG_VERBOSE enum,
> since that would change the interface for all clients, which might not
> be worth it. If you don't think that is a problem, please remove it...

This would break binary compatibility, as this log enum is used by frontends,
so it needs to stay, just unused.

I applied the patch.

Ciao, Marcus

------------------------------------------------------------------------------
Want fast and easy access to all the code in your enterprise? Index and
search up to 200,000 lines of code with a free copy of Black Duck
Code Sight - the same software that powers the world's largest code
search on Ohloh, the Black Duck Open Hub! Try it now.
http://p.sf.net/sfu/bds
_______________________________________________
Gphoto-devel mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/gphoto-devel
Reply | Threaded
Open this post in threaded view
|

Re: Debug and error logging cleanup

Axel Waggershauser
Hi Marcus,

still working on the Sony stuff I came up with another logging/debugging patch.

I wanted to be able to reduce the noise, especially related to the
low-level data-dumping. The log usually contains tons of lines similar
to:

0.032403 ptp_usb_getdata(2): Reading PTP_OC 0x9201 data...
0.032441 gp_port_read(2): Reading 1024=0x400 bytes from port...
0.049255 gp_port_read(2): Could only read 20 out of 1024 bytes.
0.049320 gp_port_read(3): Hexdump of 20 = 0x14 bytes follows:
0000  14 00 00 00 02 00 01 92-02 00 00 00 00 00 00 00  ................
0010  00 00 00 00            -                         ....

The goal was reduce that to the following:

0.036411 ptp_usb_getdata(2): Reading PTP_OC 0x9201 data...
0.037718 gp_port_read(3): Read 20 = 0x14 out of 1024 bytes from port:
(hexdump of 20 bytes)
0000  14 00 00 00 02 00 01 92-03 00 00 00 00 00 00 00  ................
0010  00 00 00 00            -                         ....

Which, together with the patch for a new --debug-loglevel parameter
for gphoto2 allows, to reduce that further to

0.036411 ptp_usb_getdata(2): Reading PTP_OC 0x9201 data...

which makes it way easier to see the flow of a larger program run when
logging every raw byte is not of interest.

To accomplish that I changed the GP_LOG_DATA macro to take in a
message string as well. This tightly couples the message text like
"Read 20 = 0x14 out of 1024 bytes from port:" to the accompanying
hexdump and allows to filter out both at once.

I did not want to make yet another copy of the elaborate vnsprintf
code (see gphoto-context.c), so I introduced a small helper
gpi_vsnprintf (to be applied to the gphoto-context.c later, too).

Since I changed the signature of gp_log_data, I modified all remaining
occurrences of direct gp_log_data calls (not to many were left) to use
the new GP_LOG_DATA macro.

The gphoto2 patch also adds a 28 character left aligned spacing to the
domain string. I think that improves readability a lot. The number 28
is subject to preference, of course.

 - Axel

On Tue, Jul 22, 2014 at 11:23 PM, Marcus Meissner <[hidden email]> wrote:

> On Tue, Jul 22, 2014 at 11:19:59PM +0200, Axel Waggershauser wrote:
>> > I did not even recall that there is a VERBOSE Loglevel... ;)
>> >
>> > Yes, we can replace it with GP_LOG_D calls or GP_LOG_DEBUG, so option (b).
>>
>> I had something 'prepared' for this situation, here you go.. ;)
>>
>> The patch does not, however, actually remove the GP_LOG_VERBOSE enum,
>> since that would change the interface for all clients, which might not
>> be worth it. If you don't think that is a problem, please remove it...
>
> This would break binary compatibility, as this log enum is used by frontends,
> so it needs to stay, just unused.
>
> I applied the patch.
>
> Ciao, Marcus

------------------------------------------------------------------------------
Want fast and easy access to all the code in your enterprise? Index and
search up to 200,000 lines of code with a free copy of Black Duck
Code Sight - the same software that powers the world's largest code
search on Ohloh, the Black Duck Open Hub! Try it now.
http://p.sf.net/sfu/bds
_______________________________________________
Gphoto-devel mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/gphoto-devel

log-cleanup-19-reduce-data-debugging-noise.patch (38K) Download Attachment
add-debug-loglevel-parameter.patch (5K) Download Attachment
Reply | Threaded
Open this post in threaded view
|

Re: Debug and error logging cleanup

Rogier Wolff
On Fri, Aug 01, 2014 at 03:54:30PM +0200, Axel Waggershauser wrote:

.... old:
> 0.032403 ptp_usb_getdata(2): Reading PTP_OC 0x9201 data...
> 0.032441 gp_port_read(2): Reading 1024=0x400 bytes from port...
> 0.049255 gp_port_read(2): Could only read 20 out of 1024 bytes.

.... new:
> 0.036411 ptp_usb_getdata(2): Reading PTP_OC 0x9201 data...
> 0.037718 gp_port_read(3): Read 20 = 0x14 out of 1024 bytes from port:

The reason there /was/ a "reading ... " message followed by the "got
20/1024" message is for the case where things crash/hang during the
read. As long as everything works, there is no problem with condensing
the debug output. But if things end up hanging in the "read from port"
part it's nice to have a debug message statiing that it is GOING to do
the read, and not see the got xxx bytes.

Options
* revert to the old code / output.

* add an option/debug level to also print something while going into
  the read.

* Leave it as is: we seldomly get to debug cases like this with this
  "debug option". (i.e. the user has already verified the hangs in
  read from usb port with strace or something like that. And we almost
  never see these bugs anymore)

I'd vote for option three.

        Roger.

--
** [hidden email] ** http://www.BitWizard.nl/ ** +31-15-2600998 **
**    Delftechpark 26 2628 XH  Delft, The Netherlands. KVK: 27239233    **
*-- BitWizard writes Linux device drivers for any device you may have! --*
The plan was simple, like my brother-in-law Phil. But unlike
Phil, this plan just might work.

------------------------------------------------------------------------------
Want fast and easy access to all the code in your enterprise? Index and
search up to 200,000 lines of code with a free copy of Black Duck
Code Sight - the same software that powers the world's largest code
search on Ohloh, the Black Duck Open Hub! Try it now.
http://p.sf.net/sfu/bds
_______________________________________________
Gphoto-devel mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/gphoto-devel
Reply | Threaded
Open this post in threaded view
|

Re: Debug and error logging cleanup

Axel Waggershauser
Hi Rogier,


> The reason there /was/ a "reading ... " message followed by the "got
> 20/1024" message is for the case where things crash/hang during the
> read. As long as everything works, there is no problem with condensing
> the debug output. But if things end up hanging in the "read from port"
> part it's nice to have a debug message statiing that it is GOING to do
> the read, and not see the got xxx bytes.

I see your point.

> Options
> * revert to the old code / output.
>
> * add an option/debug level to also print something while going into
>   the read.

I see two sub-options here: a) add the reading... and writing... entry
point log lines back with a log-level of GP_LOG_DATA, this way I get
them out of my log file if I don't care for them. Or b) add them back
but with a log-level GP_LOG_VERBOSE. But for this to make sense we'd
have to swap the numerical values of GP_LOG_DEBUG (now 2) and
GP_LOG_VERBOSE (now 1), so a debug-log-level of 1 would print errors
(0) and debug msg (1) but no verbose (2) and no data (3) msgs.


> * Leave it as is: we seldomly get to debug cases like this with this
>   "debug option". (i.e. the user has already verified the hangs in
>   read from usb port with strace or something like that. And we almost
>   never see these bugs anymore)

You mean apply the patch as proposed? (I'd have no problem with that,
either, obviously... :)).

I am going to be offline for 3 weeks.

 - Axel

------------------------------------------------------------------------------
Want fast and easy access to all the code in your enterprise? Index and
search up to 200,000 lines of code with a free copy of Black Duck
Code Sight - the same software that powers the world's largest code
search on Ohloh, the Black Duck Open Hub! Try it now.
http://p.sf.net/sfu/bds
_______________________________________________
Gphoto-devel mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/gphoto-devel
Reply | Threaded
Open this post in threaded view
|

Re: Debug and error logging cleanup

Axel Waggershauser
Hi Marcus and Rogier,

according to the last suggestion (letting the "Reading ...." lines
where they are but log them with log-level 'data', instead of 'debug')
I revised the patch #19 (see attachment). The typical block now looks
like this:

0.074182 ptp_usb_getdata(2): Reading PTP_OC 0x9109 data...
0.074198 gp_port_read(3): Reading 1024 = 0x400 bytes from port...
0.084935 gp_port_read(3): Read    12 = 0xc out of 1024 bytes from
port: (hexdump of 12 bytes)
0000  0c 00 00 00 02 00 09 91-04 00 00 00              ............

I hope this suits the needs of everyone.

 - Axel

On Sat, Aug 2, 2014 at 9:30 PM, Axel Waggershauser <[hidden email]> wrote:

> Hi Rogier,
>
>
>> The reason there /was/ a "reading ... " message followed by the "got
>> 20/1024" message is for the case where things crash/hang during the
>> read. As long as everything works, there is no problem with condensing
>> the debug output. But if things end up hanging in the "read from port"
>> part it's nice to have a debug message statiing that it is GOING to do
>> the read, and not see the got xxx bytes.
>
> I see your point.
>
>> Options
>> * revert to the old code / output.
>>
>> * add an option/debug level to also print something while going into
>>   the read.
>
> I see two sub-options here: a) add the reading... and writing... entry
> point log lines back with a log-level of GP_LOG_DATA, this way I get
> them out of my log file if I don't care for them. Or b) add them back
> but with a log-level GP_LOG_VERBOSE. But for this to make sense we'd
> have to swap the numerical values of GP_LOG_DEBUG (now 2) and
> GP_LOG_VERBOSE (now 1), so a debug-log-level of 1 would print errors
> (0) and debug msg (1) but no verbose (2) and no data (3) msgs.
>
>
>> * Leave it as is: we seldomly get to debug cases like this with this
>>   "debug option". (i.e. the user has already verified the hangs in
>>   read from usb port with strace or something like that. And we almost
>>   never see these bugs anymore)
>
> You mean apply the patch as proposed? (I'd have no problem with that,
> either, obviously... :)).
>
> I am going to be offline for 3 weeks.
>
>  - Axel

------------------------------------------------------------------------------
Slashdot TV.  
Video for Nerds.  Stuff that matters.
http://tv.slashdot.org/
_______________________________________________
Gphoto-devel mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/gphoto-devel

log-cleanup-19-reduce-data-debugging-noise.patch (39K) Download Attachment
Reply | Threaded
Open this post in threaded view
|

Re: Debug and error logging cleanup

Marcus Meissner
Hi,

as heads up, I saw this patch and I like the general fix.

I am holding it back a bit to do a regression release 2.5.5.1
for the Coolpix S series problem.

Also wondering a slight bit about just adding a new function,
as libgphoto2_port is a public API.

Probably no one uses gp_log_data() externally though and there
seem no external camlib or port drivers.

Ciao, Marcus
On Fri, Aug 22, 2014 at 05:27:26PM +0200, Axel Waggershauser wrote:

> Hi Marcus and Rogier,
>
> according to the last suggestion (letting the "Reading ...." lines
> where they are but log them with log-level 'data', instead of 'debug')
> I revised the patch #19 (see attachment). The typical block now looks
> like this:
>
> 0.074182 ptp_usb_getdata(2): Reading PTP_OC 0x9109 data...
> 0.074198 gp_port_read(3): Reading 1024 = 0x400 bytes from port...
> 0.084935 gp_port_read(3): Read    12 = 0xc out of 1024 bytes from
> port: (hexdump of 12 bytes)
> 0000  0c 00 00 00 02 00 09 91-04 00 00 00              ............
>
> I hope this suits the needs of everyone.
>
>  - Axel
>
> On Sat, Aug 2, 2014 at 9:30 PM, Axel Waggershauser <[hidden email]> wrote:
> > Hi Rogier,
> >
> >
> >> The reason there /was/ a "reading ... " message followed by the "got
> >> 20/1024" message is for the case where things crash/hang during the
> >> read. As long as everything works, there is no problem with condensing
> >> the debug output. But if things end up hanging in the "read from port"
> >> part it's nice to have a debug message statiing that it is GOING to do
> >> the read, and not see the got xxx bytes.
> >
> > I see your point.
> >
> >> Options
> >> * revert to the old code / output.
> >>
> >> * add an option/debug level to also print something while going into
> >>   the read.
> >
> > I see two sub-options here: a) add the reading... and writing... entry
> > point log lines back with a log-level of GP_LOG_DATA, this way I get
> > them out of my log file if I don't care for them. Or b) add them back
> > but with a log-level GP_LOG_VERBOSE. But for this to make sense we'd
> > have to swap the numerical values of GP_LOG_DEBUG (now 2) and
> > GP_LOG_VERBOSE (now 1), so a debug-log-level of 1 would print errors
> > (0) and debug msg (1) but no verbose (2) and no data (3) msgs.
> >
> >
> >> * Leave it as is: we seldomly get to debug cases like this with this
> >>   "debug option". (i.e. the user has already verified the hangs in
> >>   read from usb port with strace or something like that. And we almost
> >>   never see these bugs anymore)
> >
> > You mean apply the patch as proposed? (I'd have no problem with that,
> > either, obviously... :)).
> >
> > I am going to be offline for 3 weeks.
> >
> >  - Axel

> Index: libgphoto2-trunk/camlibs/canon/canon.c
> ===================================================================
> --- libgphoto2-trunk.orig/camlibs/canon/canon.c 2014-08-22 16:37:40.010301934 +0200
> +++ libgphoto2-trunk/camlibs/canon/canon.c 2014-08-22 16:37:39.994301934 +0200
> @@ -1686,10 +1686,9 @@
>                  return GP_ERROR_CORRUPTED_DATA;
>          }
>  
> -        gp_log (GP_LOG_DATA, "canon/canon.c",
> -                "canon_int_set_file_attributes: returned four bytes as expected, "
> -                "we should check if they indicate error or not. Returned data :");
> -        gp_log_data ("canon", (char *)msg, 4);
> +        GP_LOG_DATA ((char *)msg, 4,
> +                     "canon_int_set_file_attributes: returned four bytes as expected, "
> +                     "we should check if they indicate error or not. Returned data:");
>  
>          return GP_OK;
>  }
> @@ -3292,11 +3291,9 @@
>                  }
>  
>                  /* 10 bytes of attributes, size and date, a name and a NULL terminating byte */
> -                /* don't use GP_DEBUG since we log this with GP_LOG_DATA */
> -                gp_log (GP_LOG_DATA, "canon/canon.c",
> -                        "canon_int_list_directory: dirent determined to be %li=0x%lx bytes :",
> -                        (long)dirent_ent_size, (long)dirent_ent_size);
> -                gp_log_data ("canon", (char *)pos, dirent_ent_size);
> +                GP_LOG_DATA ((char *)pos, dirent_ent_size,
> +                             "canon_int_list_directory: dirent determined to be %li=0x%lx bytes :",
> +                             (long)dirent_ent_size, (long)dirent_ent_size);
>                  if (dirent_name_len) {
>                          /* OK, this directory entry has a name in it. */
>  
> @@ -3858,11 +3855,9 @@
>                  }
>  
>                  /* 10 bytes of attributes, size and date, a name and a NULL terminating byte */
> -                /* don't use GP_DEBUG since we log this with GP_LOG_DATA */
> -                gp_log (GP_LOG_DATA, "canon/canon.c",
> -                        "canon_int_get_info_func: dirent determined to be %li=0x%lx bytes :",
> -                        (long)dirent_ent_size, (long)dirent_ent_size);
> -                gp_log_data ("canon", (char *)pos, dirent_ent_size);
> +                GP_LOG_DATA ((char *)pos, dirent_ent_size,
> +                             "canon_int_get_info_func: dirent determined to be %li=0x%lx bytes:",
> +                             (long)dirent_ent_size, (long)dirent_ent_size);
>                  if (dirent_name_len) {
>                          /* OK, this directory entry has a name in it. */
>  
> Index: libgphoto2-trunk/camlibs/canon/serial.c
> ===================================================================
> --- libgphoto2-trunk.orig/camlibs/canon/serial.c 2014-08-22 16:37:40.010301934 +0200
> +++ libgphoto2-trunk/camlibs/canon/serial.c 2014-08-22 16:37:39.998301934 +0200
> @@ -338,11 +338,7 @@
>   *p++ = c;
>   }
>  
> - /* If you don't want to see the data dumped, change the frontend to
> - * set a lower debug level
> - */
> - gp_log (GP_LOG_DATA, "canon", "RECV (without CANON_FBEG and CANON_FEND bytes)");
> - gp_log_data ("canon", (char *)buffer, p - buffer);
> + GP_LOG_DATA ((char *)buffer, p - buffer, "RECV (without CANON_FBEG and CANON_FEND bytes)");
>  
>   if (len)
>   *len = p - buffer;
> @@ -1139,11 +1135,9 @@
>   return GP_ERROR;
>   }
>  
> - /* don't use GP_DEBUG since we log this with GP_LOG_DATA */
> - gp_log (GP_LOG_DATA, "canon",
> - "canon_serial_get_dirents: "
> - "dirent packet received from canon_serial_dialogue:");
> - gp_log_data ("canon", (char *)p, *dirents_length);
> + GP_LOG_DATA ((char *)p, *dirents_length,
> + "canon_serial_get_dirents: "
> + "dirent packet received from canon_serial_dialogue:");
>  
>   /* the first five bytes is only for the RS232 implementation
>   * of this command, we do not need to copy them so therefore
> @@ -1180,11 +1174,9 @@
>   return GP_ERROR;
>   }
>  
> - /* don't use GP_DEBUG since we log this with GP_LOG_DATA */
> - gp_log (GP_LOG_DATA, "canon",
> - "canon_serial_get_dirents: "
> - "dirent packet received from canon_serial_recv_msg:");
> - gp_log_data ("canon", (char *)p, *dirents_length);
> + GP_LOG_DATA ((char *)p, *dirents_length,
> + "canon_serial_get_dirents: "
> + "dirent packet received from canon_serial_recv_msg:");
>  
>   /* the first five bytes is only for the RS232 implementation,
>   * don't count them when checking dirent size
> Index: libgphoto2-trunk/camlibs/canon/usb.c
> ===================================================================
> --- libgphoto2-trunk.orig/camlibs/canon/usb.c 2014-08-22 16:37:40.010301934 +0200
> +++ libgphoto2-trunk/camlibs/canon/usb.c 2014-08-22 16:37:39.998301934 +0200
> @@ -1431,10 +1431,8 @@
>                  return NULL;
>          }
>  
> -        if (payload_length) {
> -                GP_DEBUG ("Payload :");
> -                gp_log_data ("canon", (char *)payload, (long)payload_length);
> -        }
> +        if (payload_length)
> +                GP_LOG_DATA ((char *)payload, (long)payload_length, "Payload:");
>  
>          if ((payload_length + 0x50) > sizeof (packet)) {
>                  gp_log (GP_LOG_DEBUG, "canon/usb.c",
> Index: libgphoto2-trunk/camlibs/hp215/hp215.c
> ===================================================================
> --- libgphoto2-trunk.orig/camlibs/hp215/hp215.c 2014-08-22 16:37:40.010301934 +0200
> +++ libgphoto2-trunk/camlibs/hp215/hp215.c 2014-08-22 16:37:39.998301934 +0200
> @@ -371,8 +371,7 @@
>   memcpy (*msg, msgbuf+5, replydatalen-2);
>   }
>   gp_log (GP_LOG_DEBUG, "hp215", "Read Blob: retcode is %04x", *retcode);
> - gp_log (GP_LOG_DEBUG, "hp215", "Read Blob: argument block is:");
> - gp_log_data ("hp215", (char*)*msg, *msglen);
> + GP_LOG_DATA ((char*)*msg, *msglen, "Read Blob: argument block is:");
>   return GP_OK;
>  }
>  
> Index: libgphoto2-trunk/camlibs/ptp2/library.c
> ===================================================================
> --- libgphoto2-trunk.orig/camlibs/ptp2/library.c 2014-08-22 16:37:40.010301934 +0200
> +++ libgphoto2-trunk/camlibs/ptp2/library.c 2014-08-22 16:37:39.998301934 +0200
> @@ -2196,7 +2196,7 @@
>   len = size;
>   GP_LOG_E ("len=%d larger than rest size %ld", len, (size-(xdata-data)));
>   }
> - gp_log_data ("ptp2_capture_eos_preview", (char*)xdata, len);
> + GP_LOG_DATA ((char*)xdata, len, "get_viewfinder_image header:");
>   xdata = xdata+len;
>   continue;
>   case 9:
> @@ -2220,13 +2220,12 @@
>   len  = dtoh32a(xdata);
>   type = dtoh32a(xdata+4);
>  
> - GP_LOG_D ("get_viewfinder_image header: len=%d type=%d", len, type);
>   if (len > (size-(xdata-data))) {
>   len = size;
>   GP_LOG_E ("len=%d larger than rest size %ld", len, (size-(xdata-data)));
>   break;
>   }
> - gp_log_data ("ptp2_capture_eos_preview", (char*)xdata, len);
> + GP_LOG_DATA ((char*)xdata, len, "get_viewfinder_image header:");
>   xdata = xdata+len;
>   }
>   free (data);
> Index: libgphoto2-trunk/camlibs/ptp2/olympus-wrap.c
> ===================================================================
> --- libgphoto2-trunk.orig/camlibs/ptp2/olympus-wrap.c 2014-08-22 16:37:40.010301934 +0200
> +++ libgphoto2-trunk/camlibs/ptp2/olympus-wrap.c 2014-08-22 16:37:40.002301934 +0200
> @@ -379,7 +379,7 @@
>   GP_LOG_D ("send_scsi_cmd 2 ret  %d", ret);
>   /* skip away the 12 byte header */
>   if (recvlen >= 16)
> - gp_log_data ("ptp2/olympus/getdata", data + PTP_USB_BULK_HDR_LEN, recvlen - PTP_USB_BULK_HDR_LEN);
> + GP_LOG_DATA (data + PTP_USB_BULK_HDR_LEN, recvlen - PTP_USB_BULK_HDR_LEN, "ptp2/olympus/getdata");
>   ret = putter->putfunc ( params, putter->priv, recvlen - PTP_USB_BULK_HDR_LEN, (unsigned char*)data + PTP_USB_BULK_HDR_LEN);
>   free (data);
>   if (ret != PTP_RC_OK) {
> Index: libgphoto2-trunk/camlibs/ptp2/ptpip.c
> ===================================================================
> --- libgphoto2-trunk.orig/camlibs/ptp2/ptpip.c 2014-08-22 16:37:40.010301934 +0200
> +++ libgphoto2-trunk/camlibs/ptp2/ptpip.c 2014-08-22 16:37:40.002301934 +0200
> @@ -125,7 +125,7 @@
>   default:
>   break;
>   }
> - gp_log_data ( "ptpip/oprequest", (char*)request, len);
> + GP_LOG_DATA ( (char*)request, len, "ptpip/oprequest data:");
>   ret = write (params->cmdfd, request, len);
>   free (request);
>   if (ret == -1)
> @@ -149,7 +149,7 @@
>   perror ("read PTPIPHeader");
>   return PTP_RC_GeneralError;
>   }
> - gp_log_data ( "ptpip/generic_read", (char*)xhdr+curread, ret);
> + GP_LOG_DATA ((char*)xhdr+curread, ret, "ptpip/generic_read data:");
>   curread += ret;
>   if (ret == 0) {
>   GP_LOG_E ("End of stream after reading %d bytes of ptpipheader", ret);
> @@ -174,7 +174,7 @@
>   free (*data);*data = NULL;
>   return PTP_RC_GeneralError;
>   } else {
> - gp_log_data ( "ptpip/generic_read", (char*)((*data)+curread), ret);
> + GP_LOG_DATA ((char*)((*data)+curread), ret, "ptpip/generic_read data:");
>   }
>   if (ret == 0)
>   break;
> @@ -234,7 +234,7 @@
>   htod32a(&request[ptpip_startdata_transid  + 8],ptp->Transaction_ID);
>   htod32a(&request[ptpip_startdata_totallen + 8],size);
>   htod32a(&request[ptpip_startdata_unknown  + 8],0);
> - gp_log_data ( "ptpip/senddata", (char*)request, sizeof(request));
> + GP_LOG_DATA ((char*)request, sizeof(request), "ptpip/senddata header:");
>   ret = write (params->cmdfd, request, sizeof(request));
>   if (ret == -1)
>   perror ("sendreq/write to cmdfd");
> @@ -267,7 +267,7 @@
>   htod32a(&xdata[ptpip_type], type);
>   htod32a(&xdata[ptpip_len], towrite2);
>   htod32a(&xdata[ptpip_data_transid+8], ptp->Transaction_ID);
> - gp_log_data("ptpip/senddata", (char*)xdata, towrite2);
> + GP_LOG_DATA ((char*)xdata, towrite2, "ptpip/senddata data:");
>   written = 0;
>   while (written < towrite2) {
>   ret = write (params->cmdfd, xdata+written, towrite2-written);
> @@ -424,7 +424,7 @@
>   htod16a(&cmdrequest[ptpip_initcmd_name+(strlen(hostname)+1)*2],PTPIP_VERSION_MINOR);
>   htod16a(&cmdrequest[ptpip_initcmd_name+(strlen(hostname)+1)*2+2],PTPIP_VERSION_MAJOR);
>  
> - gp_log_data ( "ptpip/init_cmd", (char*)cmdrequest, len);
> + GP_LOG_DATA ((char*)cmdrequest, len, "ptpip/init_cmd data:");
>   ret = write (params->cmdfd, cmdrequest, len);
>   free (cmdrequest);
>   if (ret == -1) {
> @@ -485,7 +485,7 @@
>   htod32a(&evtrequest[ptpip_len],ptpip_eventinit_size);
>   htod32a(&evtrequest[ptpip_eventinit_idx],params->eventpipeid);
>  
> - gp_log_data ( "ptpip/init_event", (char*)evtrequest, ptpip_eventinit_size);
> + GP_LOG_DATA ((char*)evtrequest, ptpip_eventinit_size, "ptpip/init_event data:");
>   ret = write (params->evtfd, evtrequest, ptpip_eventinit_size);
>   if (ret == -1) {
>   perror("write init evt request");
> Index: libgphoto2-trunk/coverity-model.c
> ===================================================================
> --- libgphoto2-trunk.orig/coverity-model.c 2014-08-22 16:37:40.010301934 +0200
> +++ libgphoto2-trunk/coverity-model.c 2014-08-22 16:37:40.002301934 +0200
> @@ -55,7 +55,7 @@
>   }
>  }
>  
> -void gp_log_data (const char *domain, const char *data, unsigned int size) {
> +void gp_log_data (const char *domain, const char *data, unsigned int size, const char* format, ...) {
>   /* considered a tainted sink ... but is not one. */
>  }
>  
> Index: libgphoto2-trunk/libgphoto2_port/gphoto2/gphoto2-port-log.h
> ===================================================================
> --- libgphoto2-trunk.orig/libgphoto2_port/gphoto2/gphoto2-port-log.h 2014-08-22 16:37:40.010301934 +0200
> +++ libgphoto2-trunk/libgphoto2_port/gphoto2/gphoto2-port-log.h 2014-08-22 16:37:40.002301934 +0200
> @@ -85,7 +85,12 @@
>   __attribute__((__format__(printf,3,0)))
>  #endif
>  ;
> -void gp_log_data (const char *domain, const char *data, unsigned int size);
> +void gp_log_data (const char *domain, const char *data, unsigned int size,
> +  const char *format, ...)
> +#ifdef __GNUC__
> +__attribute__((__format__(printf,4,5)))
> +#endif
> +;
>  
>  /*
>   * GP_DEBUG:
> @@ -112,7 +117,7 @@
>   */
>  #define GP_LOG_D(...) gp_log(GP_LOG_DEBUG, __func__, __VA_ARGS__)
>  #define GP_LOG_E(...) gp_log_with_source_location(GP_LOG_ERROR, __FILE__, __LINE__, __func__, __VA_ARGS__)
> -#define GP_LOG_DATA(DATA, SIZE) gp_log_data(__func__, DATA, SIZE)
> +#define GP_LOG_DATA(DATA, SIZE, MSG, ...) gp_log_data(__func__, DATA, SIZE, MSG, ##__VA_ARGS__)
>  
>  #else
>  # ifdef __GNUC__
> @@ -121,7 +126,7 @@
>  #define GP_DEBUG (void)
>  #define GP_LOG_D(...) /* no-op */
>  #define GP_LOG_E(...) /* no-op */
> -#define GP_LOG_DATA(DATA, SIZE) /* no-op */
> +#define GP_LOG_DATA(DATA, SIZE, ...) /* no-op */
>  #endif
>  #endif /* _GPHOTO2_INTERNAL_CODE */
>  
> @@ -140,18 +145,18 @@
>  #define GP_DEBUG(...) /* no-op */
>  #define GP_LOG_D(...) /* no-op */
>  #define GP_LOG_E(...) /* no-op */
> -#define GP_LOG_DATA(DATA, SIZE) /* no-op */
> +#define GP_LOG_DATA(DATA, SIZE, ...) /* no-op */
>  
>  #elif defined(__GNUC__)
>  #define GP_DEBUG(msg, params...) /* no-op */
>  #define GP_LOG_D(...) /* no-op */
>  #define GP_LOG_E(...) /* no-op */
> -#define GP_LOG_DATA(DATA, SIZE) /* no-op */
> +#define GP_LOG_DATA(DATA, SIZE, ...) /* no-op */
>  #else
>  #define GP_DEBUG (void)
>  #define GP_LOG_D (void /* no-op */
>  #define GP_LOG_E (void) /* no-op */
> -#define GP_LOG_DATA(DATA, SIZE) /* no-op */
> +#define GP_LOG_DATA(void) /* no-op */
>  #endif
>  #endif /* _GPHOTO2_INTERNAL_CODE */
>  
> @@ -192,7 +197,13 @@
>    unsigned int
>    gpi_string_list_to_flags(const char *str[],
>     const StringFlagItem *map);
> -  
> +
> +char* gpi_vsnprintf (const char* format, va_list args)
> +#ifdef __GNUC__
> + __attribute__((__format__(printf,1,0)))
> +#endif
> +;
> +
>  #define C_MEM(MEM) do {\
>   if ((MEM) == NULL) {\
>   GP_LOG_E ("Out of memory: '%s' failed.", #MEM);\
> Index: libgphoto2-trunk/libgphoto2_port/libgphoto2_port/gphoto2-port-log.c
> ===================================================================
> --- libgphoto2-trunk.orig/libgphoto2_port/libgphoto2_port/gphoto2-port-log.c 2014-08-22 16:37:40.010301934 +0200
> +++ libgphoto2-trunk/libgphoto2_port/libgphoto2_port/gphoto2-port-log.c 2014-08-22 16:37:40.002301934 +0200
> @@ -95,6 +95,35 @@
>   return (log_funcs_count);
>  }
>  
> +
> +char* gpi_vsnprintf (const char* format, va_list args)
> +{
> + va_list xargs;
> + int strsize;
> + char *str;
> +
> +#ifdef HAVE_VA_COPY
> + va_copy (xargs, args);
> +#else
> + // according to 'the web', the only interesting compiler without va_copy is MSVC
> + // and there a simple assignment is the way to go
> + xargs = args;
> +#endif
> +
> + // query the size necessary for the string, add the terminating '\0'
> + strsize = vsnprintf (NULL, 0, format, xargs) + 1;
> + va_end (xargs);
> +
> + str = malloc(strsize);
> + if (!str)
> + return NULL;
> +
> + // actually print the string into the buffer
> + vsnprintf (str, strsize, format, args);
> +
> + return str;
> +}
> +
>  /**
>   * \brief Remove a logging receiving function
>   * \param id an id (return value of #gp_log_add_func)
> @@ -167,35 +196,43 @@
>   **/
>  /* coverity[-tainted_sink] */
>  void
> -gp_log_data (const char *domain, const char *data, unsigned int size)
> +gp_log_data (const char *domain, const char *data, unsigned int size, const char *format, ...)
>  {
> + va_list args;
>   static const char hexchars[16] = "0123456789abcdef";
> - char *curline, *result;
> + char *curline, *result = 0, *msg = 0;
>   int x = HEXDUMP_INIT_X;
>   int y = HEXDUMP_INIT_Y;
> - unsigned int index;
> + unsigned int index, original_size = size;
>   unsigned char value;
>  
> + va_start (args, format);
> + msg = gpi_vsnprintf(format, args);
> + va_end (args);
> + if (!msg) {
> + GP_LOG_E ("Malloc for expanding format string '%s' failed.", format);
> + goto exit;
> + }
> +
>   if (!data) {
> - gp_log (GP_LOG_DATA, domain, "No hexdump (NULL buffer)");
> - return;
> + gp_log (GP_LOG_DATA, domain, "%s (no hexdump, NULL buffer)", msg);
> + goto exit;
>   }
>  
>   if (!size) {
> - gp_log (GP_LOG_DATA, domain, "Empty hexdump of empty buffer");
> - return;
> + gp_log (GP_LOG_DATA, domain, "%s (empty hexdump of empty buffer)", msg);
> + goto exit;
>   }
>  
>   if (size > 1024*1024) {
>   /* Does not make sense for 200 MB movies */
> - gp_log (GP_LOG_DATA, domain, "Truncating dump from %d bytes to 1MB", size);
>   size = 1024*1024;
>   }
>  
>   curline = result = malloc ((HEXDUMP_LINE_WIDTH+1)*(((size-1)/16)+1)+1);
>   if (!result) {
>   GP_LOG_E ("Malloc for %i bytes failed", (HEXDUMP_LINE_WIDTH+1)*(((size-1)/16)+1)+1);
> - return;
> + goto exit;
>   }
>  
>   for (index = 0; index < size; ++index) {
> @@ -224,8 +261,13 @@
>          }
>          curline[0] = '\0';
>  
> - gp_log (GP_LOG_DATA, domain, "Hexdump of %i = 0x%x bytes follows:\n%s",
> - size, size, result);
> +        if (size == original_size)
> +                gp_log (GP_LOG_DATA, domain, "%s (hexdump of %d bytes)\n%s", msg, size, result);
> +        else
> +                gp_log (GP_LOG_DATA, domain, "%s (hexdump of the first %d of %d bytes)\n%s", msg, size, original_size, result);
> +
> +exit:
> + free (msg);
>   free (result);
>  }
>  
> @@ -252,44 +294,17 @@
>   va_list args)
>  {
>   unsigned int i;
> -#ifdef HAVE_VA_COPY
> - va_list xargs;
> -#else
> -#define xargs args
> -#endif
> - int strsize = 1000;
> - char *str;
> - int n;
> + char *str = 0;
>  
>   if (!log_funcs_count)
>   return;
>  
> - str = malloc(strsize);
> - if (!str) return;
> -#ifdef HAVE_VA_COPY
> - va_copy (xargs, args);
> -#endif
> - n = vsnprintf (str, strsize, format, xargs);
> -#ifdef HAVE_VA_COPY
> - va_end(xargs);
> -#endif
> - if (n+1>strsize) {
> - free (str);
> - str = malloc(n+1);
> - if (!str) {
> - va_end(args);
> - return;
> - }
> - strsize = n+1;
> -#ifdef HAVE_VA_COPY
> - va_copy (xargs, args);
> -#endif
> - n = vsnprintf (str, strsize, format, xargs);
> -#ifdef HAVE_VA_COPY
> - va_end(xargs);
> -#endif
> + str = gpi_vsnprintf(format, args);
> + if (!str) {
> + GP_LOG_E ("Malloc for expanding format string '%s' failed.", format);
> + return;
>   }
> - va_end(args);
> +
>   for (i = 0; i < log_funcs_count; i++)
>   if (log_funcs[i].level >= level)
>   log_funcs[i].func (level, domain, str, log_funcs[i].data);
> @@ -371,7 +386,7 @@
>  }
>  
>  void
> -gp_log_data (const char *domain, const char *data, unsigned int size)
> +gp_log_data (const char *domain, const char *data, unsigned int size, const char *format, ...)
>  {
>  }
>  
> Index: libgphoto2-trunk/libgphoto2_port/libgphoto2_port/gphoto2-port.c
> ===================================================================
> --- libgphoto2-trunk.orig/libgphoto2_port/libgphoto2_port/gphoto2-port.c 2014-08-22 16:37:40.010301934 +0200
> +++ libgphoto2-trunk/libgphoto2_port/libgphoto2_port/gphoto2-port.c 2014-08-22 17:14:03.810309346 +0200
> @@ -59,6 +59,13 @@
>  #define CHECK_SUPP(p,t,o) {if (!(o)) {gp_port_set_error ((p), _("The operation '%s' is not supported by this device"), (t)); return (GP_ERROR_NOT_SUPPORTED);}}
>  #define CHECK_INIT(p) {if (!(p)->pc->ops) {gp_port_set_error ((p), _("The port has not yet been initialized")); return (GP_ERROR_BAD_PARAMETERS);}}
>  
> +#define LOG_DATA(DATA, SIZE, EXPECTED, MSG_PRE, MSG_POST, ...) \
> + if (SIZE != EXPECTED) \
> + GP_LOG_DATA (DATA, SIZE, MSG_PRE " %i = 0x%x out of %i bytes " MSG_POST, SIZE, SIZE, EXPECTED, ##__VA_ARGS__); \
> + else \
> + GP_LOG_DATA (DATA, SIZE, MSG_PRE " %i = 0x%x bytes " MSG_POST, SIZE, SIZE, ##__VA_ARGS__)
> +
> +
>  /**
>   * \brief Internal private libgphoto2_port data.
>   * This structure contains private data.
> @@ -382,19 +389,20 @@
>  {
>   int retval;
>  
> - GP_LOG_D ("Writing %i=0x%x byte(s) to port...", size, size);
> +        gp_log (GP_LOG_DATA, __func__, "Writing %i = 0x%x bytes to port...", size, size);
>  
> - C_PARAMS (port && data);
> + C_PARAMS (port && data);
>   CHECK_INIT (port);
>  
> - GP_LOG_DATA (data, size);
> -
>   /* Check if we wrote all bytes */
>   CHECK_SUPP (port, "write", port->pc->ops->write);
>   retval = port->pc->ops->write (port, data, size);
> - CHECK_RESULT (retval);
> - if ((port->type != GP_PORT_SERIAL) && (retval != size))
> - GP_LOG_D ("Could only write %i out of %i bytes.", retval, size);
> + if (retval < 0) {
> + GP_LOG_E ("Writing %i = 0x%x bytes to port failed: %s (%d)",
> +  size, size, gp_port_result_as_string(retval), retval);
> + return retval;
> + }
> + LOG_DATA (data, retval, size, "Wrote  ", "to port:");
>  
>   return (retval);
>  }
> @@ -416,7 +424,7 @@
>  {
>          int retval;
>  
> - GP_LOG_D ("Reading %i=0x%x bytes from port...", size, size);
> + gp_log (GP_LOG_DATA, __func__, "Reading %i = 0x%x bytes from port...", size, size);
>  
>   C_PARAMS (port);
>   CHECK_INIT (port);
> @@ -424,11 +432,12 @@
>   /* Check if we read as many bytes as expected */
>   CHECK_SUPP (port, "read", port->pc->ops->read);
>   retval = port->pc->ops->read (port, data, size);
> - CHECK_RESULT (retval);
> - if (retval != size)
> - GP_LOG_D ("Could only read %i out of %i bytes.", retval, size);
> -
> - GP_LOG_DATA (data, retval);
> + if (retval < 0) {
> + GP_LOG_E ("Reading %i = 0x%x bytes from port failed: %s (%d)",
> +  size, size, gp_port_result_as_string(retval), retval);
> + return retval;
> + }
> + LOG_DATA (data, retval, size, "Read   ", "from port:");
>  
>   return (retval);
>  }
> @@ -451,7 +460,7 @@
>  {
>          int retval;
>  
> - GP_LOG_D ("Reading %i=0x%x bytes from interrupt endpoint...", size, size);
> + gp_log (GP_LOG_DATA, __func__, "Reading %i = 0x%x bytes from interrupt endpoint...", size, size);
>  
>   C_PARAMS (port);
>   CHECK_INIT (port);
> @@ -460,10 +469,7 @@
>   CHECK_SUPP (port, "check_int", port->pc->ops->check_int);
>   retval = port->pc->ops->check_int (port, data, size, port->timeout);
>   CHECK_RESULT (retval);
> - if (retval != size)
> - GP_LOG_D ("Could only read %i out of %i bytes.", retval, size);
> -
> - GP_LOG_DATA (data, retval);
> + LOG_DATA (data, retval, size, "Read   ", "from interrupt endpoint:");
>  
>   return (retval);
>  }
> @@ -487,6 +493,8 @@
>  {
>          int retval;
>  
> +        gp_log (GP_LOG_DATA, __func__, "Reading %i = 0x%x bytes from interrupt endpoint...", size, size);
> +
>   C_PARAMS (port);
>   CHECK_INIT (port);
>  
> @@ -496,23 +504,12 @@
>   CHECK_RESULT (retval);
>  
>  #ifdef IGNORE_EMPTY_INTR_READS
> - if (retval != size && retval != 0 )
> -#else
> - if (retval != size )
> -#endif
> - GP_LOG_D ("Could only read %i out of %i bytes.", retval, size);
> -
> -#ifdef IGNORE_EMPTY_INTR_READS
> - if ( retval != 0 ) {
> -#endif
> - /* For Canon cameras, we will make lots of
> -   reads that will return zero length. Don't
> -   bother to log them as errors. */
> - GP_LOG_D ("Reading %i=0x%x bytes from interrupt endpoint (fast)...", size, size);
> - GP_LOG_DATA (data, retval);
> -#ifdef IGNORE_EMPTY_INTR_READS
> - }
> + /* For Canon cameras, we will make lots of
> +   reads that will return zero length. Don't
> +   bother to log them as errors. */
> + if (retval != 0 )
>  #endif
> + LOG_DATA (data, retval, size, "Read   ", "from interrupt endpoint (fast):");
>  
>   return (retval);
>  }
> @@ -865,9 +862,8 @@
>  {
>          int retval;
>  
> - GP_LOG_D ("Writing message (request=0x%x value=0x%x index=0x%x size=%i=0x%x)...",
> -  request, value, index, size, size);
> - GP_LOG_DATA (bytes, size);
> + GP_LOG_DATA (bytes, size, "Writing message (request=0x%x value=0x%x index=0x%x size=%i=0x%x):",
> +     request, value, index, size, size);
>  
>   C_PARAMS (port);
>   CHECK_INIT (port);
> @@ -899,8 +895,8 @@
>  {
>          int retval;
>  
> - GP_LOG_D ("Reading message (request=0x%x value=0x%x index=0x%x size=%i=0x%x)...",
> -  request, value, index, size, size);
> + gp_log (GP_LOG_DATA, __func__, "Reading message (request=0x%x value=0x%x index=0x%x size=%i=0x%x)...",
> + request, value, index, size, size);
>  
>   C_PARAMS (port);
>   CHECK_INIT (port);
> @@ -909,10 +905,9 @@
>          retval = port->pc->ops->msg_read (port, request, value, index, bytes, size);
>   CHECK_RESULT (retval);
>  
> - if (retval != size)
> - GP_LOG_D ("Could only read %i out of %i bytes.", retval, size);
> + LOG_DATA (bytes, retval, size, "Read", "USB message (request=0x%x value=0x%x index=0x%x size=%i=0x%x)",
> +  request, value, index, size, size);
>  
> - GP_LOG_DATA (bytes, retval);
>          return (retval);
>  }
>  
> @@ -940,9 +935,8 @@
>  {
>          int retval;
>  
> - GP_LOG_D ("Writing message (request=0x%x value=0x%x index=0x%x size=%i=0x%x)...",
> -  request, value, index, size, size);
> - GP_LOG_DATA (bytes, size);
> + GP_LOG_DATA (bytes, size, "Writing message (request=0x%x value=0x%x index=0x%x size=%i=0x%x)...",
> +     request, value, index, size, size);
>  
>   C_PARAMS (port);
>   CHECK_INIT (port);
> @@ -976,8 +970,8 @@
>  {
>          int retval;
>  
> - GP_LOG_D ("Reading message (request=0x%x value=0x%x index=0x%x size=%i=0x%x)...",
> -  request, value, index, size, size);
> + gp_log (GP_LOG_DATA, __func__, "Reading message (request=0x%x value=0x%x index=0x%x size=%i=0x%x)...",
> + request, value, index, size, size);
>  
>   C_PARAMS (port);
>   CHECK_INIT (port);
> @@ -987,10 +981,8 @@
>           value, index, bytes, size);
>   CHECK_RESULT (retval);
>  
> - if (retval != size)
> - GP_LOG_D ("Could only read %i out of %i bytes.", retval, size);
> -
> - GP_LOG_DATA (bytes, retval);
> + LOG_DATA (bytes, retval, size, "Read", "USB message (request=0x%x value=0x%x index=0x%x size=%i=0x%x)",
> +  request, value, index, size, size);
>  
>          return (retval);
>  }
> @@ -1021,9 +1013,8 @@
>  {
>          int retval;
>  
> - GP_LOG_D ("Writing message (request=0x%x value=0x%x index=0x%x size=%i=0x%x)...",
> -  request, value, index, size, size);
> - GP_LOG_DATA (bytes, size);
> + GP_LOG_DATA (bytes, size, "Writing message (request=0x%x value=0x%x index=0x%x size=%i=0x%x):",
> +     request, value, index, size, size);
>  
>   C_PARAMS (port);
>   CHECK_INIT (port);
> @@ -1057,8 +1048,8 @@
>  {
>          int retval;
>  
> - GP_LOG_D ("Reading message (request=0x%x value=0x%x index=0x%x size=%i=0x%x)...",
> -  request, value, index, size, size);
> + gp_log (GP_LOG_DATA, __func__, "Reading message (request=0x%x value=0x%x index=0x%x size=%i=0x%x)...",
> + request, value, index, size, size);
>  
>   C_PARAMS (port);
>   CHECK_INIT (port);
> @@ -1068,10 +1059,8 @@
>           value, index, bytes, size);
>   CHECK_RESULT (retval);
>  
> - if (retval != size)
> - GP_LOG_D ("Could only read %i out of %i bytes.", retval, size);
> -
> - GP_LOG_DATA (bytes, retval);
> + LOG_DATA (bytes, retval, size, "Read", "USB message (request=0x%x value=0x%x index=0x%x size=%i=0x%x)",
> +  request, value, index, size, size);
>  
>          return (retval);
>  }
> @@ -1129,12 +1118,9 @@
>  {
>   int retval;
>  
> - GP_LOG_D ("Sending scsi cmd:");
> - GP_LOG_DATA (cmd, cmd_size);
> - if (to_dev && data_size) {
> - GP_LOG_D ("with scsi cmd data:");
> - GP_LOG_DATA (data, data_size);
> - }
> + GP_LOG_DATA (cmd, cmd_size, "Sending scsi cmd:");
> + if (to_dev && data_size)
> + GP_LOG_DATA (data, data_size, "with scsi cmd data:");
>  
>   C_PARAMS (port);
>   CHECK_INIT (port);
> @@ -1147,8 +1133,7 @@
>   GP_LOG_D ("scsi cmd result: %d", retval);
>  
>   if (sense[0] != 0) {
> - GP_LOG_D ("sense data:");
> - GP_LOG_DATA (sense, sense_size);
> + GP_LOG_DATA (sense, sense_size, "sense data:");
>   /* https://secure.wikimedia.org/wikipedia/en/wiki/Key_Code_Qualifier */
>   GP_LOG_D ("sense decided:");
>   if ((sense[0]&0x7f)!=0x70) {
> @@ -1171,10 +1156,8 @@
>   }
>   }
>  
> - if (!to_dev && data_size) {
> - GP_LOG_D ("scsi cmd data:");
> - GP_LOG_DATA (data, data_size);
> - }
> + if (!to_dev && data_size)
> + GP_LOG_DATA (data, data_size, "scsi cmd data:");
>  
>   return retval;
>  }
> Index: libgphoto2-trunk/libgphoto2_port/libusb1/libusb1.c
> ===================================================================
> --- libgphoto2-trunk.orig/libgphoto2_port/libusb1/libusb1.c 2014-08-22 16:37:40.010301934 +0200
> +++ libgphoto2-trunk/libgphoto2_port/libusb1/libusb1.c 2014-08-22 16:37:40.002301934 +0200
> @@ -1026,7 +1026,7 @@
>   }
>   /* get string descriptor at 0xEE */
>   ret = usb_get_descriptor (devh, 0x03, 0xee, buf, sizeof(buf));
> - if (ret > 0) gp_log_data("get_MS_OSD",buf, ret);
> + if (ret > 0) GP_LOG_DATA (buf, ret, "get_MS_OSD");
>   if (ret < 10) goto errout;
>   if (!((buf[2] == 'M') && (buf[4]=='S') && (buf[6]=='F') && (buf[8]=='T')))
>   goto errout;
> @@ -1040,7 +1040,7 @@
>   GP_LOG_E ("ret is %d, buf[0] is %x\n", ret, buf[0]);
>   goto errout;
>   }
> - if (ret > 0) gp_log_data("get_MS_ExtDesc",buf, ret);
> + if (ret > 0) GP_LOG_DATA (buf, ret, "get_MS_ExtDesc");
>   if ((buf[0x12] != 'M') || (buf[0x13] != 'T') || (buf[0x14] != 'P')) {
>   GP_LOG_E ("buf at 0x12 is %02x%02x%02x\n", buf[0x12], buf[0x13], buf[0x14]);
>   goto errout;
> @@ -1051,7 +1051,7 @@
>   GP_LOG_E ("ret is %d, buf[0] is %x\n", ret, buf[0]);
>   goto errout;
>   }
> - if (ret > 0) gp_log_data("get_MS_ExtProp",buf, ret);
> + if (ret > 0) GP_LOG_DATA (buf, ret, "get_MS_ExtProp");
>   if ((buf[0x12] != 'M') || (buf[0x13] != 'T') || (buf[0x14] != 'P')) {
>   GP_LOG_E ("buf at 0x12 is %02x%02x%02x\n", buf[0x12], buf[0x13], buf[0x14]);
>   goto errout;
> Index: libgphoto2-trunk/libgphoto2_port/usb/libusb.c
> ===================================================================
> --- libgphoto2-trunk.orig/libgphoto2_port/usb/libusb.c 2014-08-22 16:37:40.010301934 +0200
> +++ libgphoto2-trunk/libgphoto2_port/usb/libusb.c 2014-08-22 16:37:40.002301934 +0200
> @@ -998,7 +998,7 @@
>   }
>   /* get string descriptor at 0xEE */
>   ret = usb_get_descriptor (devh, 0x03, 0xee, buf, sizeof(buf));
> - if (ret > 0) gp_log_data("get_MS_OSD",buf, ret);
> + if (ret > 0) GP_LOG_DATA (buf, ret, "get_MS_OSD");
>   if (ret < 10) goto errout;
>   if (!((buf[2] == 'M') && (buf[4]=='S') && (buf[6]=='F') && (buf[8]=='T')))
>   goto errout;
> @@ -1012,7 +1012,7 @@
>   GP_LOG_E ("ret is %d, buf[0] is %x\n", ret, buf[0]);
>   goto errout;
>   }
> - if (ret > 0) gp_log_data("get_MS_ExtDesc",buf, ret);
> + if (ret > 0) GP_LOG_DATA (buf, ret, "get_MS_ExtDesc");
>   if ((buf[0x12] != 'M') || (buf[0x13] != 'T') || (buf[0x14] != 'P')) {
>   GP_LOG_E ("buf at 0x12 is %02x%02x%02x\n", buf[0x12], buf[0x13], buf[0x14]);
>   goto errout;
> @@ -1023,7 +1023,7 @@
>   GP_LOG_E ("ret is %d, buf[0] is %x\n", ret, buf[0]);
>   goto errout;
>   }
> - if (ret > 0) gp_log_data("get_MS_ExtProp",buf, ret);
> + if (ret > 0) GP_LOG_DATA (buf, ret, "get_MS_ExtProp");
>   if ((buf[0x12] != 'M') || (buf[0x13] != 'T') || (buf[0x14] != 'P')) {
>   GP_LOG_E ("buf at 0x12 is %02x%02x%02x\n", buf[0x12], buf[0x13], buf[0x14]);
>   goto errout;


------------------------------------------------------------------------------
Slashdot TV.  
Video for Nerds.  Stuff that matters.
http://tv.slashdot.org/
_______________________________________________
Gphoto-devel mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/gphoto-devel
12