openssh unix dev - Jan 2001 - subject: ssh non-intuitive logging setting. (priority names)

subject: ssh non-intuitive logging setting (priority names).

I installed openssh 2.3.0p1 on Solaris 7 for x86 box and
sshd worked fine.
However, somehow the logging of connection and disconnection to
sshd was not recorded as I wished.

Time to investigate.

On a host where sshd from data-fellows once ran,
the log was recorded with auth.info level.

After trying to modify sshd_config, I found
that the setting of log-level may not
be quite intuitive to seasoned UNIX admins.

I mean the names of priorities are not quite
in line with the common UNIX priority names and its usage.

The following is a snippet from /usr/include/syslog.h:
The priorities are used for filtering within
syslog.conf and used as the first argument of
syslog() function.

        /*
         *  Priorities (these are ordered)
         */
        #define LOG_EMERG       0       /* system is unusable */
        #define LOG_ALERT       1       /* action must be taken
immediately */
        #define LOG_CRIT        2       /* critical conditions */
        #define LOG_ERR         3       /* error conditions */
        #define LOG_WARNING     4       /* warning conditions */
        #define LOG_NOTICE      5       /* normal but signification
condition */
        #define LOG_INFO        6       /* informational */
        #define LOG_DEBUG       7       /* debug-level messages */


Whereas the sshd_config seems to accept only the following
names for priority in the configuration file(s):
    QUIET,
    FATAL,
    ERROR,
    INFO,
    VERBOSE,
    DEBUG,
    DEBUG1,
    DEBU2,
    DEBUG3 (case will be ignored in matching.)

The mapping of these names to the UNIX priorities are
done by an array in log.c via macro names defined in
ssh.h.

(You can see from the snippet from log.c that
DEBUG and DEBUG1 have the same effect by the way.)

        log.c:
        static struct {
                const char *name;
                LogLevel val;
        } log_levels[]         {
                { "QUIET",      SYSLOG_LEVEL_QUIET },
                { "FATAL",      SYSLOG_LEVEL_FATAL },
                { "ERROR",      SYSLOG_LEVEL_ERROR },
                { "INFO",       SYSLOG_LEVEL_INFO },
                { "VERBOSE",    SYSLOG_LEVEL_VERBOSE },
                { "DEBUG",      SYSLOG_LEVEL_DEBUG1 },
                { "DEBUG1",     SYSLOG_LEVEL_DEBUG1 },
                { "DEBUG2",     SYSLOG_LEVEL_DEBUG2 },
                { "DEBUG3",     SYSLOG_LEVEL_DEBUG3 },
                { NULL, 0 }


The priorities specified, say, in sshd_config
will use the SYSLOG_LEVEL_* values defined in ssh.h.


        typedef enum {
                SYSLOG_LEVEL_QUIET,
                SYSLOG_LEVEL_FATAL,
                SYSLOG_LEVEL_ERROR,
                SYSLOG_LEVEL_INFO,
                SYSLOG_LEVEL_VERBOSE,
                SYSLOG_LEVEL_DEBUG1,
                SYSLOG_LEVEL_DEBUG2,
                SYSLOG_LEVEL_DEBUG3
        }       LogLevel;


So I see the mapping thusly.
   QUIET   <-> priority 0
   FATAL   <-> priority 1
   ERROR   <-> priority 2
   INFO    <-> priority 3
   VERBOSE <->          4
   DEBUG1  <->          5
   DEBUG2  <->          6
   DEBUG3  <->          7

For my initial purpose, after experimenting with syslog.conf and
the setting in sshd_config,
I put the following in sshd_config.

  SyslogFacility AUTH
  LogLevel DEBUG2

I also used the following in /etc/syslog.conf.

    auth.info   loggin-file-pathname

Now I obtain the kind of log I want in the
logging file:

Jan  6 01:17:53 www sshd[15304]: Connection from 192.9.200.18 port 602
Jan  6 01:17:57 www sshd[15304]: Accepted password for gnu from
192.9.200.18 port 602

However, I think the admissible priority names are not quite intuitive
to long-time UNIX sysadmins because they are not
quite in line with the common accepted priority names.
(Please don't misunderstand: I am not saying the common accepted
priority names are better. They are often memorized by
the long-time sysadmins and anything different are
hard to use initially. And frankly, the deviation here
is a source of conufsion.)

I am not advocating the throw-away of the current names since
it would disturb large installed base of openssh sshd.
But I would rather see the common priority names accepted in
the config files, also.

So doesn't anyone care to patch log.c to
allow us to use the common accepted UNIX priority names
as in the following?
I put the extra names(common UNIX priority names) at
each priority level following the currently used openssh priority
name.
(The mods clearly shows rather inappropriate choice for
SYSLOG_LEVEL_* macro names IMHO.)

        log.c:

        static struct {
                const char *name;
                LogLevel val;
        } log_levels[]         {
        /* 0 : EMERG */

                { "QUIET",      SYSLOG_LEVEL_QUIET },
                { "EMERG",      SYSLOG_LEVEL_QUIET },
                { "PANIC",      SYSLOG_LEVEL_QUIET },

        /* 1 : ALERT */

                { "FATAL",      SYSLOG_LEVEL_FATAL },
                { "ALERT",      SYSLOG_LEVEL_FATAL },

        /* 2 : CRIT */
                { "ERROR",      SYSLOG_LEVEL_ERROR },
                { "CRIT",       SYSLOG_LEVEL_ERROR },

        /* 3 : ERR. */
                { "INFO",       SYSLOG_LEVEL_INFO },
                { "ERR",        SYSLOG_LEVEL_INFO },
                { "ERROR",      SYSLOG_LEVEL_INFO },

        /* 4 : WARNING */
                { "VERBOSE",    SYSLOG_LEVEL_VERBOSE },
                { "WARN",       SYSLOG_LEVEL_VERBOSE },
                { "WARNING",    SYSLOG_LEVEL_VERBOSE },

        /* 5 : NOTICE */
                { "DEBUG",      SYSLOG_LEVEL_DEBUG1 },
                { "DEBUG1",     SYSLOG_LEVEL_DEBUG1 },
                { "NOTICE",     SYSLOG_LEVEL_DEBUG1 },


        /* 6 : INFO */

                { "DEBUG2",     SYSLOG_LEVEL_DEBUG2 },

                /* Here I can't put "INFO" because this would
clash
                   with the openssh 2.3.0p1's use of INFO
                   at priority # 3.
                   Ugh... */
                /* { "DEBUG2",  SYSLOG_LEVEL_DEBUG2 }, */

        /* 7 : DEBUG */

                { "DEBUG3",     SYSLOG_LEVEL_DEBUG3 },
                /* AGAIN, I can't put DEBUG here because
                   DEBUG is used at priority # 5. */

                { NULL, 0 }


PS: Is it possible someone
broke log.c and ssh.h to the point that the original
intent of keeping sync with UNIX priority names
no longer works?
The mis-use (in my eyes) of macronames uncovered during
this investigation suggested something like this happened.

Actually, if there are not many objections, I would rather
see the cleanup of the SYSLOG_LEVEL_* macro definitions and usage
to keep them in line with the UNIX priorities so that
the names like "INFO" or "DEBUG" would have
similar meaning (that is at the same priority level)
as in the usage of syslog.conf.
Currently, they don't seem to. Or am I missing something?

What do people think?

Quoting Ishikawa <ishikawa at yk.rim.or.jp>:
> subject: ssh non-intuitive logging setting (priority names).
> 
> What do people think?
I think your suggestion would be very useful, especially in my
situation whereby I have to tell the TCP wrappers one thing and
SSHD another, to get a "connection succeeded" message to appear on
the right level.

Cheerio,

Andrew Stribblehill
Systems programmer, IT Service, University of Durham, England

On Sat, Jan 06, 2001 at 01:52:06AM +0900, Ishikawa
wrote:
>    QUIET   <-> priority 0
>    FATAL   <-> priority 1
>    ERROR   <-> priority 2
>    INFO    <-> priority 3
>    VERBOSE <->          4
>    DEBUG1  <->          5
>    DEBUG2  <->          6
>    DEBUG3  <->          7
this mapping order is due to the history of openssh.
ssh-1.2.12 used
	debug(), log(), error() and fatal()
calls (in order of importance) with the following options
	QuietMode (only fatal() is logged, not sure about error())
	FascistLogging (debug,log,error and fatal)
and standard mode: log,error and fatal.

in fact, you had only 3 different levels and we tried to change
that.  additionaly, log() was far to chatty so i split all the calls:
openssh now uses log() and for less important messages verbose().

so now we have:
	QUIET		nothing
	FATAL		fatal
	ERROR		fatal+error
	INFO		fatal+error+log	(since Loglevel=LOG sounds strange)
	VERBOSE		fatal+error+log+verbose
	DEBUG		fatal+error+log+verbose+debug

later we added some more debug levels.
this is the reason for the current log levels.
i don't say that's perfect.
> For my initial purpose, after experimenting with syslog.conf and
> the setting in sshd_config,
> I put the following in sshd_config.
> 
>   SyslogFacility AUTH
>   LogLevel DEBUG2
you probably want LogLevel VERBOSE
>         /* 3 : ERR. */
>                 { "INFO",       SYSLOG_LEVEL_INFO },
>                 { "ERR",        SYSLOG_LEVEL_INFO },
>                 { "ERROR",      SYSLOG_LEVEL_INFO },
so this would mean with
	LogLevel=ERROR
you would see
	fatal+error+log
in syslog().

i think this mapping is more appropriate

	ALERT		nothing
	CRIT		fatal
	ERR		fatal+error
	NOTICE		fatal+error+log	(since Loglevel=LOG sounds strange)
	INFO		fatal+error+log+verbose
	DEBUG		fatal+error+log+verbose+debug
> PS: Is it possible someone
> broke log.c and ssh.h to the point that the original
> intent of keeping sync with UNIX priority names
> no longer works?
> The mis-use (in my eyes) of macronames uncovered during
> this investigation suggested something like this happened.
where? what do you mean.
> Actually, if there are not many objections, I would rather
> see the cleanup of the SYSLOG_LEVEL_* macro definitions and usage
> to keep them in line with the UNIX priorities so that
> the names like "INFO" or "DEBUG" would have
> similar meaning (that is at the same priority level)
> as in the usage of syslog.conf.
> Currently, they don't seem to. Or am I missing something?
the macros don't need the cleanup. probably
all the loging should be replace and _then_ we
could cleanup the macro names.

perhaps move from
	fatal(), error() log(), verbose(), debug1(), debug2(), debug3()
to
	sshlog(CRIT, ...);
	sshlog(ERR, ...);
	sshlog(NOTICE, ...);
	sshlog(INFO, ...);
	sshlog(DEBUG1, ...);
	sshlog(DEBUG2, ...);
	sshlog(DEBUG3, ...);

or even more levels, similar to syslog.

comments?

-markus

X-PMC-CI-e-mail-id: 14407 
>> Monday is a Japanese national holiday and so my own
>> check will have to wait until next week.
>
>Every monday? What a *wonderful* idea! We should adopt the same policy.
>
>:)
Yeah, I wish I lived in that kind of Uthopia.

Seriously, I meant the upcoming Monday, which was yesterday,
was a Japanese holiday. (The second Monday of January, that is.
It used to be the fixed date when I was a kid: January 15th.) 

Anyway, I will try the sshd log thing and report my findings.


-- 
     Ishikawa, Chiaki        ishikawa at personal-media.co.jp.NoSpam  or
 (family name, given name) Chiaki.Ishikawa at personal-media.co.jp.NoSpam
    Personal Media Corp.      ** Remove .NoSpam at the end before use **     
  Shinagawa, Tokyo, Japan 142-0051