Suggestion for new logging mechanism in open-iscsi

[Erez Zilber]

I'd like to make some changes in the logging in open-iscsi. The
current status is as follows:

kernel modules:

* We use iscsi_cls_session_printk & iscsi_cls_conn_printk in
scsi_transport_iscsi.c. They are sometimes wrapped by macros (e.g.
ISCSI_DBG_TRANS_SESSION). These macros use KERN_INFO and are
controlled by module parameters.

* We use iscsi_session_printk & iscsi_conn_printk for the rest of the
kernel code.These macros wrap iscsi_cls_session_printk &
iscsi_cls_conn_printk accordingly. They are sometimes wrapped by
macros (e.g. ISCSI_SW_TCP_DBG). These macros use KERN_INFO and are
controlled by module parameters.

* We sometimes use printk calls.

userspace:

We use log_warning, log_error & log_debug. They depend on the logging
level that we use (0-8). if (log_level > level), the log is sent to
syslog with the appropriate log level (LOG_WARNING/LOG_ERR/LOG_DEBUG).

My motivation: with the current logging mechanism, if an error occurs,
I'm unable to tell exactly what happened. The default logging level is
too low. Increasing it affects performance. Another problem is that
open-iscsi has too many logging mechanisms.

I suggest that:
1. For kernel modules, we will have 'events' (or any better name that
you suggest) like 'session', 'conn', 'eh', 'cmd' etc. For each event,
we will have a logging level. For example, the user may want to set
the 'conn' event to 'DEBUG'. It means that we will print all conn
related logs that are DEBUG and above (e.g. WARNING, ERROR).
2. For userspace code, we could do the same (i.e. have events and a
log level per event).
3. Userspace logging uses the 'daemon' facility. This should
definitely be the default, but we should allow the user to use another
facility. The motivation for doing so is that if we want to send all
iscsid logs to a separate file, we can set it to 'local2' for example
(instead of 'daemon').

Comments?

Thanks,
Erez

[Ulrich Windl]

On 2 Dec 2009 at 10:55, Erez Zilber wrote:

> I'd like to make some changes in the logging in open-iscsi. The
> current status is as follows:
>
> kernel modules:
>
> * We use iscsi_cls_session_printk & iscsi_cls_conn_printk in
> scsi_transport_iscsi.c. They are sometimes wrapped by macros (e.g.
> ISCSI_DBG_TRANS_SESSION). These macros use KERN_INFO and are
> controlled by module parameters.
>
> * We use iscsi_session_printk & iscsi_conn_printk for the rest of the
> kernel code.These macros wrap iscsi_cls_session_printk &
> iscsi_cls_conn_printk accordingly. They are sometimes wrapped by
> macros (e.g. ISCSI_SW_TCP_DBG). These macros use KERN_INFO and are
> controlled by module parameters.
>
> * We sometimes use printk calls.
>
> userspace:
>
> We use log_warning, log_error & log_debug. They depend on the logging
> level that we use (0-8). if (log_level > level), the log is sent to
> syslog with the appropriate log level (LOG_WARNING/LOG_ERR/LOG_DEBUG).
>
> My motivation: with the current logging mechanism, if an error occurs,
> I'm unable to tell exactly what happened. The default logging level is
> too low. Increasing it affects performance. Another problem is that
> open-iscsi has too many logging mechanisms.
>
> I suggest that:
> 1. For kernel modules, we will have 'events' (or any better name that

I'd call them "contexts" or "event sources".

> you suggest) like 'session', 'conn', 'eh', 'cmd' etc. For each event,
> we will have a logging level. For example, the user may want to set
> the 'conn' event to 'DEBUG'. It means that we will print all conn
> related logs that are DEBUG and above (e.g. WARNING, ERROR).
> 2. For userspace code, we could do the same (i.e. have events and a
> log level per event).
> 3. Userspace logging uses the 'daemon' facility. This should
> definitely be the default, but we should allow the user to use another
> facility. The motivation for doing so is that if we want to send all
> iscsid logs to a separate file, we can set it to 'local2' for example
> (instead of 'daemon').
>
> Comments?

What I'd wish: For most messages, especially if informational messages are
enabled, it's not clear what type of severity a message has (i.e. debug, info,
warning, error, fatal error). I'd wish the severity would be obvious from the
message.

I once wrote some code to do something like that. Showing some calling examples
might make it obvious:

message(MSG_TYPE_DEBUG, __LINE__, my_step, instance,
"min_pause=%ld\n",
min_pause);

message(MSG_TYPE_ERROR, __LINE__, my_step, instance,
"Incompatible alert state: file %s, ID %06lx\n",
state_file, state.id);

message(MSG_TYPE_INFO, __LINE__, my_step, instance,
"OS error (%s: %s)\n",
state_file, strerror(last_errno));

message(MSG_TYPE_FATAL, __LINE__, my_step, instance,
"No memory for state file %s\n",
file);

message(MSG_TYPE_WARN, __LINE__, my_step, instance,
"file \"%s\" exceeded size threshold\n",
msg_file);

My "instance" is what you called "event"; "step" are steps in processing something
(an integer), and __LINE__ is just handy if "Instance" includes the source file.

Regards,
Ulrich

[Erez Zilber]

I agree.

>
> I once wrote some code to do something like that. Showing some calling examples
> might make it obvious:
>
> message(MSG_TYPE_DEBUG, __LINE__, my_step, instance,
>        "min_pause=%ld\n",
>        min_pause);
>
> message(MSG_TYPE_ERROR, __LINE__, my_step, instance,
>        "Incompatible alert state: file %s, ID %06lx\n",
>        state_file, state.id);
>
> message(MSG_TYPE_INFO, __LINE__, my_step, instance,
>        "OS error (%s: %s)\n",
>        state_file, strerror(last_errno));
>
> message(MSG_TYPE_FATAL, __LINE__, my_step, instance,
>        "No memory for state file %s\n",
>        file);
>
> message(MSG_TYPE_WARN, __LINE__, my_step, instance,
>        "file \"%s\" exceeded size threshold\n",
>        msg_file);
>
> My "instance" is what you called "event"; "step" are steps in processing something
> (an integer), and __LINE__ is just handy if "Instance" includes the source file.

Yes. It would be nice if we had the function + line number for each
log. I'm not sure that I understand the meaning of 'step'. Here's an
example (to make sure that I got you right): if you send a PDU, you
can print multiple messages while preparing & sending the PDU, each
with its own step number. For example:

"(1) allocating PDU"
"(2) init PDU"
"(3) sending PDU"
"(4) PDU was sent"

Is this what you mean?

Erez

[Ulrich Windl]

Yes, more or less: If you have a loop that is performing the same code multiple
times, it may be interesting in which iteration the message was triggered. For
situations like that I "invented" the step. Also, if the step number is negative,
the output is suppressed. So basically it's optional.

Regards,
Ulrich

[Mike Christie]

Sorry for the late reply.

This sounds nice.

When you do this, could you also unify what gets printed to id what
object is logging the message. Currently the kernel prints a session or
conn sysfs/bus id (session1 or connection1:2), but userspace prints
whatever it wants. Sometimes it just prints out a log with nothing so
you have no idea where it came from, and sometimes it prints a id that
looks like a sysfs one.

[Erez Zilber]

Sure. The only thing that I don't know is how to get the
sessionX/connectionY string in userspace. Where is it stored?

Thanks,
Erez

[Mike Christie]

session->id is the X in sessionX and session->conn[0]->id is the Y in
connectionY.

[Erez Zilber]

I suggest that each kernel module will have its own events. Each event
will be represented by a module parameter (with some default value).

> 2. For userspace code, we could do the same (i.e. have events and a
> log level per event).

Regarding the 'events' in userspace - we will have events A, B & C for
iscsid and events D, E & F for iscsiadm. For each event, we will
probably have a default logging level. The user may want to run with
another logging level for each event. For iscsid, I suggest that we
add this to iscsid.conf. For iscsiadm, the user will be able to do
something like:

iscsiadm -d some_level - this will set all events to 'some_level'
iscsiadm -dE level_for_E -dF level_for_F - this will set the event 'E'
to 'level_for_E' and the event 'F' to 'level_for_F'. The event 'D'
will use the default logging level.

Comments?

Thanks,
Erez

[Ulrich Windl]

Hi!

One thing to decide would be whether you want to have hierarchical levels for
debugging per subsystem (you call them "events" I think), or whether to have a
bitmask-like value to enable or disable specific classes of messages (like
openLDAP does it).

Personally I think that short debug output is perferrable to long output. With
commercial software I have hjad several cases where support really wanted me to
capture more than a GB of logs, where the logs contained really every stupid thing
the program did. In the end they said they could not find the problem, because
they did not log that specific case... 8-(

Regards,
Ulrich

> --
>
> You received this message because you are subscribed to the Google Groups "open-iscsi" group.
> To post to this group, send email to open-...@googlegroups.com.
> To unsubscribe from this group, send email to open-iscsi+...@googlegroups.com.
> For more options, visit this group at http://groups.google.com/group/open-iscsi?hl=en.
>
>

[Erez Zilber]

I've started working on the new logging. I've started with iscsi_tcp.
Here's a glance of the general idea. If you have comments on the
general implementation, let's discuss them now. Later, it will be much
more difficult for me.

Here it is:

Added the following code in libiscsi.h:

#define iscsi_log(log_level, dev, dbg_fmt, arg...) \
do { \
char *log_level_str; \
switch (log_level) { \
case ISCSI_LOG_ERROR: \
log_level_str = "ERROR"; \
break; \
case ISCSI_LOG_WARN: \
log_level_str = "WARN"; \
break; \
case ISCSI_LOG_INFO: \
log_level_str = "INFO"; \
break; \
case ISCSI_LOG_DEBUG: \
log_level_str = "DEBUG"; \
break; \
case ISCSI_LOG_TRACE: \
log_level_str = "TRACE"; \
break; \
} \
if (log_level > ISCSI_LOG_INFO) { \
if (dev) { \
dev_printk(KERN_DEBUG, \
(struct device *)dev, \
"%s:%d (%s) " dbg_fmt "\n", \
__func__, __LINE__, \
log_level_str, ##arg); \
} else { \
printk(KERN_DEBUG \
"%s:%d (%s) " dbg_fmt "\n", \
__func__, __LINE__, \
log_level_str, ##arg); \
} \
} else { \
if (dev) { \
dev_printk(KERN_INFO, \
(struct device *)dev, \
"%s:%d (%s) " dbg_fmt "\n", \
__func__, __LINE__, \
log_level_str, ##arg); \
} else { \
printk(KERN_INFO \
"%s:%d (%s) " dbg_fmt "\n", \
__func__, __LINE__, \
log_level_str, ##arg); \
} \
} \
} while (0);

added a new iscsi_log.h file:

enum iscsi_log_level {
ISCSI_LOG_ERROR = 1,
ISCSI_LOG_WARN,
ISCSI_LOG_INFO,
ISCSI_LOG_DEBUG,
ISCSI_LOG_TRACE
};

and in iscsi_tcp.c:

/* Logging contexts */
struct {
int general;
int conn;
} iscsi_sw_tcp_log_ctxt = {ISCSI_LOG_INFO, ISCSI_LOG_INFO};

enum iscsi_sw_tcp_ctxt {
ISCSI_SW_TCP_CTXT_GENERAL = 1,
ISCSI_SW_TCP_CTXT_CONN,
};

module_param_named(general_log_ctxt, iscsi_sw_tcp_log_ctxt.general, int,
S_IRUGO | S_IWUSR);
MODULE_PARM_DESC(general_log_ctxt, "blah blah - general");

module_param_named(conn_log_ctxt, iscsi_sw_tcp_log_ctxt.conn, int,
S_IRUGO | S_IWUSR);
MODULE_PARM_DESC(conn_log_ctxt, "blah blah - conn");

#define _iscsi_sw_tcp_log(log_level, ctxt, dev, dbg_fmt, arg...) \
do { \
switch (ctxt) { \
case ISCSI_SW_TCP_CTXT_GENERAL: \
if (log_level <= iscsi_sw_tcp_log_ctxt.general) \
iscsi_log(log_level, dev, dbg_fmt, \
##arg); \
break; \
case ISCSI_SW_TCP_CTXT_CONN: \
if (log_level <= iscsi_sw_tcp_log_ctxt.conn) \
iscsi_log(log_level, dev, dbg_fmt, \
##arg); \
break; \
} \
} while (0);

#define iscsi_sw_tcp_log(log_level, ctxt, dbg_fmt, arg...) \
do { \
_iscsi_sw_tcp_log(log_level, ctxt, NULL, dbg_fmt, \
##arg); \
} while (0);

#define iscsi_sw_tcp_conn_log(log_level, ctxt, conn, dbg_fmt, arg...) \
do { \
struct device *dev; \
dev = &((struct iscsi_conn *)conn)->cls_conn->dev; \
_iscsi_sw_tcp_log(log_level, ctxt, dev, dbg_fmt, arg); \
} while (0);

#define iscsi_sw_tcp_sess_log(log_level, ctxt, sess, dbg_fmt, arg...) \
do { \
struct device *dev; \
dev = &((struct iscsi_session *)sess)->cls_session->dev;\
_iscsi_sw_tcp_log(log_level, ctxt, dev, dbg_fmt, arg); \
} while (0);

so now, instead of doing the following in iscsi_sw_tcp_send_hdr_done():

ISCSI_SW_TCP_DBG(tcp_conn->iscsi_conn,
"Header done. Next segment size %u total_size %u\n",
tcp_sw_conn->out.segment.size,
tcp_sw_conn->out.segment.total_size);

we will do the following:

iscsi_sw_tcp_conn_log(ISCSI_LOG_INFO, ISCSI_SW_TCP_CTXT_CONN,
tcp_conn->iscsi_conn,
"Header done. Next segment size %u total_size %u\n",
tcp_sw_conn->out.segment.size,
tcp_sw_conn->out.segment.total_size);

[Ulrich Windl]

On 13 Jan 2010 at 18:56, Erez Zilber wrote:

Hi!

I wonder whether the #define could be replaced with an inline function.
The readability would be much better, and the code should be more or
less the same, unless you need special macro processing. For code size
we could even try to make it a "normal" routine (i.e. not inlined). The
performance might suffer a little bit, however.

Also: With "-O3" gcc usually automatically inlines short "static"
(locally defined?) routines.

Regards,
Ulrich

[...]

> Here it is:
>
> Added the following code in libiscsi.h:
>
> #define iscsi_log(log_level, dev, dbg_fmt, arg...) \
> do { \

[...]
> } while (0);

[...]------------
Ulrich Windl Klinikum der Universitaet Regensburg
Rechenzentrum DV-med Franz-Josef-Strauss-Allee 11
Tel: +49 941 944-5879 D-93053 Regensburg
FAX: +49 941 944-5882
"The bad PC memory subsystems are really bad." (Linus Torvalds,
19.04.1996)
"Unknown DHCP option 0 length 255" (Windows/NT Server 3.51)
"Oh, it's Visibly BASIC!" -- U. Windl

[Erez Zilber]

On Thu, Jan 14, 2010 at 10:44 AM, Ulrich Windl
<Ulrich...@rz.uni-regensburg.de> wrote:
> On 13 Jan 2010 at 18:56, Erez Zilber wrote:
>
> Hi!
>
> I wonder whether the #define could be replaced with an inline function.
> The readability would be much better, and the code should be more or
> less the same, unless you need special macro processing. For code size
> we could even try to make it a "normal" routine (i.e. not inlined). The
> performance might suffer a little bit, however.
>
> Also: With "-O3" gcc usually automatically inlines short "static"
> (locally defined?) routines.
>

We can make it inline instead of using a macro. I used macros because
this is what we had till now, and I didn't want to change that. The
only problem with inline functions is that it's up to the compiler to
decide if the function will be inlined. This may affect performance in
some cases.

Erez

[Erez Zilber]

One more thing: take a look at _iscsi_sw_tcp_log. If we have a large
amount of contexts in the module (connection, session, error handling,
data transfer, socket, module etc), the switch block may become quite
large. I don't know if the compiler will decide to make such a
function inline.

Erez