log session end - again - Mailing list pgsql-patches

This patch brings up to date what I did last year (now unfortunately
bitrotted) to allow the logging of the end of a session, enabled by the
config setting "log_session_end - true". It produces lines like these:

for a local connection:
[21340] LOG:  session end: duration: 0:00:23.41 user=andrew
database=template1 host=[local]

for a tcp connection:
[21351] LOG:  session end: duration: 0:00:20.22 user=andrew
database=template1 host=127.0.0.1 port=33419

for a tcp connection when log_hostname = true:
[21373] LOG:  session end: duration: 0:00:02.25 user=andrew
database=template1 host=alphonso port=33421

enjoy

andrew


Index: doc/src/sgml/runtime.sgml
===================================================================
RCS file: /projects/cvsroot/pgsql-server/doc/src/sgml/runtime.sgml,v
retrieving revision 1.235
diff -c -r1.235 runtime.sgml
*** doc/src/sgml/runtime.sgml    27 Jan 2004 16:51:43 -0000    1.235
--- doc/src/sgml/runtime.sgml    2 Feb 2004 19:08:42 -0000
***************
*** 1825,1830 ****
--- 1825,1844 ----


       <varlistentry>
+       <term><varname>log_session_end</varname> (<type>boolean</type>)</term>
+       <listitem>
+        <para>
+        This outputs a line to the server logs similar to LOG_CONNECTIONS
+        but at the end of a session, and including the duration of the
+        session.This is off by default. This option can only be set at
+        server start or in the <filename>postgresql.conf</filename>
+        configuration file.
+        </para>
+       </listitem>
+      </varlistentry>
+
+
+      <varlistentry>
        <term><varname>log_duration</varname> (<type>boolean</type>)</term>
        <listitem>
         <para>
Index: src/backend/postmaster/postmaster.c
===================================================================
RCS file: /projects/cvsroot/pgsql-server/src/backend/postmaster/postmaster.c,v
retrieving revision 1.364
diff -c -r1.364 postmaster.c
*** src/backend/postmaster/postmaster.c    28 Jan 2004 21:02:40 -0000    1.364
--- src/backend/postmaster/postmaster.c    2 Feb 2004 19:08:43 -0000
***************
*** 2438,2443 ****
--- 2438,2450 ----
       * Signal handlers setting is moved to tcop/postgres...
       */

+     /* save start time for end of session reporting */
+     gettimeofday(&(port->session_start),NULL);
+
+     /* set these to empty in case they are needed before we set them up */
+     port->remote_host = "";
+     port->remote_port = "";
+
      /* Save port etc. for ps status */
      MyProcPort = port;

***************
*** 2492,2497 ****
--- 2499,2510 ----
          snprintf(tmphost, sizeof(tmphost), "%s:%s", remote_host, remote_port);
          StrNCpy(remote_host, tmphost, sizeof(remote_host));
      }
+
+     /*
+      * save remote_host and remote_port in port stucture
+      */
+     port->remote_host = strdup(remote_host);
+     port->remote_port = strdup(remote_port);

      /*
       * Ready to begin client interaction.  We will give up and exit(0)
Index: src/backend/tcop/postgres.c
===================================================================
RCS file: /projects/cvsroot/pgsql-server/src/backend/tcop/postgres.c,v
retrieving revision 1.387
diff -c -r1.387 postgres.c
*** src/backend/tcop/postgres.c    28 Jan 2004 21:02:40 -0000    1.387
--- src/backend/tcop/postgres.c    2 Feb 2004 19:08:43 -0000
***************
*** 84,89 ****
--- 84,92 ----
  bool        Warn_restart_ready = false;
  bool        InError = false;

+ /* flag for logging end of session */
+ bool        Log_session_end = false;
+
  /*
   * Flags for expensive function optimization -- JMH 3/9/92
   */
***************
*** 149,154 ****
--- 152,158 ----
  static void finish_xact_command(void);
  static void SigHupHandler(SIGNAL_ARGS);
  static void FloatExceptionHandler(SIGNAL_ARGS);
+ static void log_session_end(void);


  /* ----------------------------------------------------------------
***************
*** 2406,2412 ****
--- 2410,2419 ----
       * other output options.
       */
      if (debug_flag >= 1)
+     {
          SetConfigOption("log_connections", "true", debug_context, gucsource);
+         SetConfigOption("log_session_end", "true", debug_context, gucsource);
+     }
      if (debug_flag >= 2)
          SetConfigOption("log_statement", "true", debug_context, gucsource);
      if (debug_flag >= 3)
***************
*** 2435,2440 ****
--- 2442,2453 ----
              gucopts = lnext(gucopts);
              SetConfigOption(name, value, PGC_BACKEND, PGC_S_CLIENT);
          }
+
+         /*
+          * set up handler to log session end.
+          */
+         if (IsUnderPostmaster && Log_session_end)
+             on_proc_exit(log_session_end,0);
      }

      /*
***************
*** 3172,3175 ****
--- 3185,3246 ----
               errdetail("%s", str.data)));

      pfree(str.data);
+ }
+
+ /*
+  * on_proc_exit handler to log end of session
+  */
+ static void
+ log_session_end(void)
+ {
+     Port * port = MyProcPort;
+     struct timeval end;
+     int  hours, minutes, seconds;
+
+     char session_time[20];
+     char uname[6+NAMEDATALEN];
+     char dbname[10+NAMEDATALEN];
+     char remote_host[7 + NI_MAXHOST];
+     char remote_port[7 + NI_MAXSERV];
+
+     snprintf(uname, sizeof(uname)," user=%s",port->user_name);
+     snprintf(dbname, sizeof(dbname)," database=%s",port->database_name);
+     snprintf(remote_host,sizeof(remote_host)," host=%s",
+              port->remote_host);
+     /* prevent redundant or empty reporting of port */
+     if (!LogSourcePort && strlen(port->remote_port))
+         snprintf(remote_port,sizeof(remote_port)," port=%s",port->remote_port);
+     else
+         remote_port[0] = '\0';
+
+
+     gettimeofday(&end,NULL);
+
+     if (end.tv_usec < port->session_start.tv_usec)
+     {
+         end.tv_sec--;
+         end.tv_usec += 1000000;
+     }
+     end.tv_sec -= port->session_start.tv_sec;
+     end.tv_usec -= port->session_start.tv_usec;
+
+     hours = end.tv_sec / 3600;
+     end.tv_sec %= 3600;
+     minutes = end.tv_sec / 60;
+     seconds = end.tv_sec % 60;
+
+     /* if time has gone backwards for some reason say so, or print time */
+
+     if (end.tv_sec < 0)
+         snprintf(session_time,sizeof(session_time),"negative!");
+     else
+         /* for stricter accuracy here we could round - this is close enough */
+         snprintf(session_time, sizeof(session_time),"%d:%02d:%02d.%02ld",
+                  hours, minutes, seconds, end.tv_usec/10000);
+
+     ereport(
+         LOG,
+         (errmsg("session end: duration: %s%s%s%s%s",
+                 session_time,uname,dbname,remote_host,remote_port)));
+
  }
Index: src/backend/utils/misc/guc.c
===================================================================
RCS file: /projects/cvsroot/pgsql-server/src/backend/utils/misc/guc.c,v
retrieving revision 1.182
diff -c -r1.182 guc.c
*** src/backend/utils/misc/guc.c    31 Jan 2004 05:09:41 -0000    1.182
--- src/backend/utils/misc/guc.c    2 Feb 2004 19:08:44 -0000
***************
*** 65,70 ****
--- 65,71 ----

  /* XXX these should appear in other modules' header files */
  extern bool Log_connections;
+ extern bool Log_session_end;
  extern bool check_function_bodies;
  extern int    PreAuthDelay;
  extern int    AuthenticationTimeout;
***************
*** 499,504 ****
--- 500,513 ----
              NULL
          },
          &Log_connections,
+         false, NULL, NULL
+     },
+     {
+         {"log_session_end", PGC_BACKEND, LOGGING_WHAT,
+          gettext_noop("Logs end of a session, including duration"),
+          NULL
+         },
+         &Log_session_end,
          false, NULL, NULL
      },
      {
Index: src/backend/utils/misc/postgresql.conf.sample
===================================================================
RCS file: /projects/cvsroot/pgsql-server/src/backend/utils/misc/postgresql.conf.sample,v
retrieving revision 1.101
diff -c -r1.101 postgresql.conf.sample
*** src/backend/utils/misc/postgresql.conf.sample    24 Jan 2004 20:00:45 -0000    1.101
--- src/backend/utils/misc/postgresql.conf.sample    2 Feb 2004 19:08:44 -0000
***************
*** 179,184 ****
--- 179,185 ----
  #debug_print_plan = false
  #debug_pretty_print = false
  #log_connections = false
+ #log_session_end = false
  #log_duration = false
  #log_pid = false
  #log_statement = false
Index: src/include/libpq/libpq-be.h
===================================================================
RCS file: /projects/cvsroot/pgsql-server/src/include/libpq/libpq-be.h,v
retrieving revision 1.39
diff -c -r1.39 libpq-be.h
*** src/include/libpq/libpq-be.h    20 Dec 2003 17:31:21 -0000    1.39
--- src/include/libpq/libpq-be.h    2 Feb 2004 19:08:45 -0000
***************
*** 47,52 ****
--- 47,55 ----
      ProtocolVersion proto;        /* FE/BE protocol version */
      SockAddr    laddr;            /* local addr (postmaster) */
      SockAddr    raddr;            /* remote addr (client) */
+     char        *remote_host;   /* name (or ip addr) of remote host */
+     char        *remote_port;   /* text rep of remote port */
+     struct timeval  session_start;  /* for session duration logging */
      CAC_state    canAcceptConnections;    /* postmaster connection status */

      /*