ubik: log important messages at default log level

Many important ubik messages (e.g., errors, warnings, sync state
changes) are logged at log level 5 (-d 5) or higher.  Many sites are
reluctant to run ubik servers at a logging level higher than the default
due to the large number of extremely noisy informational messages at log
level 5.  Therefore, many important log messages are never seen.

Instead, issue critical errors, warnings, and other important messages
at log level 0 so that they are always seen, even at the default logging
level.

In addition, disambiguate the two "I am no longer sync-site" messages by
adding a unique reason text to each.

Change-Id: I057edf01e2502e39c5135836f1d0081d03559270
Reviewed-on: https://gerrit.openafs.org/12617
Reviewed-by: Benjamin Kaduk <kaduk@mit.edu>
Reviewed-by: Andrew Deason <adeason@sinenomine.net>
Tested-by: BuildBot <buildbot@rampaginggeek.com>
Reviewed-by: Michael Meffie <mmeffie@sinenomine.net>

diff --git a/src/ubik/beacon.c b/src/ubik/beacon.c
index b53a383..fb6dafb 100644 (file)
--- a/src/ubik/beacon.c
+++ b/src/ubik/beacon.c
@@ -115,7 +115,7 @@ amSyncSite(void)
        now = FT_ApproxTime();
        if (beacon_globals.syncSiteUntil <= now) {      /* if my votes have expired, say so */
            if (beacon_globals.ubik_amSyncSite)
-               ViceLog(5, ("Ubik: I am no longer the sync site\n"));
+               ViceLog(0, ("Ubik: I am no longer the sync site - my votes expired\n"));
            beacon_globals.ubik_amSyncSite = 0;
            beacon_globals.ubik_syncSiteAdvertised = 0;
            rcode = 0;
@@ -410,7 +410,7 @@ ubeacon_InitServerListCommon(afs_uint32 ame, struct afsconf_cell *info,
 
     if (ubik_singleServer) {
        if (!beacon_globals.ubik_amSyncSite) {
-           ViceLog(5, ("Ubik: I am the sync site - 1 server\n"));
+           ViceLog(0, ("Ubik: I am the sync site - 1 server\n"));
            DBHOLD(ubik_dbase);
            UBIK_VERSION_LOCK;
            version_globals.ubik_epochTime = FT_ApproxTime();
@@ -618,7 +618,7 @@ ubeacon_Interact(void *dummy)
        if (yesVotes > nServers) {      /* yesVotes is bumped by 2 or 3 for each site */
            UBIK_BEACON_LOCK;
            if (!beacon_globals.ubik_amSyncSite) {
-               ViceLog(5, ("Ubik: I am the sync site\n"));
+               ViceLog(0, ("Ubik: I am the sync site\n"));
                /* Defer actually changing any variables until we can take the
                 * DB lock (which is before the beacon lock in the lock order). */
                becameSyncSite = 1;
@@ -632,7 +632,7 @@ ubeacon_Interact(void *dummy)
        } else {
            UBIK_BEACON_LOCK;
            if (beacon_globals.ubik_amSyncSite)
-               ViceLog(5, ("Ubik: I am no longer the sync site\n"));
+               ViceLog(0, ("Ubik: I am no longer the sync site - I lost the election\n"));
            beacon_globals.ubik_amSyncSite = 0;
            beacon_globals.ubik_syncSiteAdvertised = 0;
            UBIK_BEACON_UNLOCK;

diff --git a/src/ubik/recovery.c b/src/ubik/recovery.c
index 7ea8e47..b351c96 100644 (file)
--- a/src/ubik/recovery.c
+++ b/src/ubik/recovery.c
@@ -605,13 +605,13 @@ urecovery_Interact(void *dummy)
 
            code = StartDISK_GetFile(rxcall, file);
            if (code) {
-               ViceLog(5, ("StartDiskGetFile failed=%d\n", code));
+               ViceLog(0, ("StartDiskGetFile failed=%d\n", code));
                goto FetchEndCall;
            }
            nbytes = rx_Read(rxcall, (char *)&length, sizeof(afs_int32));
            length = ntohl(length);
            if (nbytes != sizeof(afs_int32)) {
-               ViceLog(5, ("Rx-read length error=%d\n", BULK_ERROR));
+               ViceLog(0, ("Rx-read length error=%d\n", BULK_ERROR));
                code = EIO;
                goto FetchEndCall;
            }
@@ -622,7 +622,7 @@ urecovery_Interact(void *dummy)
            code = (*ubik_dbase->setlabel) (ubik_dbase, file, &tversion);
            UBIK_VERSION_UNLOCK;
            if (code) {
-               ViceLog(5, ("setlabel io error=%d\n", code));
+               ViceLog(0, ("setlabel io error=%d\n", code));
                goto FetchEndCall;
            }
            snprintf(pbuffer, sizeof(pbuffer), "%s.DB%s%d.TMP",
@@ -648,7 +648,7 @@ urecovery_Interact(void *dummy)
 #endif
                nbytes = rx_Read(rxcall, tbuffer, tlen);
                if (nbytes != tlen) {
-                   ViceLog(5, ("Rx-read bulk error=%d\n", BULK_ERROR));
+                   ViceLog(0, ("Rx-read bulk error=%d\n", BULK_ERROR));
                    code = EIO;
                    close(fd);
                    goto FetchEndCall;
@@ -798,6 +798,12 @@ urecovery_Interact(void *dummy)
                UBIK_BEACON_LOCK;
                if (!ts->up) {
                    UBIK_BEACON_UNLOCK;
+                   /* It would be nice to have this message at loglevel
+                    * 0 as well, but it will log once every 4s for each
+                    * down server while in this recovery state.  This
+                    * should only be changed to loglevel 0 if it is
+                    * also rate-limited.
+                    */
                    ViceLog(5, ("recovery cannot send version to %s\n",
                                afs_inet_ntoa_r(inAddr.s_addr, hoststr)));
                    dbok = 0;
@@ -821,7 +827,7 @@ urecovery_Interact(void *dummy)
                            StartDISK_SendFile(rxcall, file, length,
                                               &ubik_dbase->version);
                        if (code) {
-                           ViceLog(5, ("StartDiskSendFile failed=%d\n",
+                           ViceLog(0, ("StartDiskSendFile failed=%d\n",
                                        code));
                            goto StoreEndCall;
                        }
@@ -834,13 +840,13 @@ urecovery_Interact(void *dummy)
                                                     tbuffer, offset, tlen);
                            if (nbytes != tlen) {
                                code = UIOERROR;
-                               ViceLog(5, ("Local disk read error=%d\n", code));
+                               ViceLog(0, ("Local disk read error=%d\n", code));
                                goto StoreEndCall;
                            }
                            nbytes = rx_Write(rxcall, tbuffer, tlen);
                            if (nbytes != tlen) {
                                code = BULK_ERROR;
-                               ViceLog(5, ("Rx-write bulk error=%d\n", code));
+                               ViceLog(0, ("Rx-write bulk error=%d\n", code));
                                goto StoreEndCall;
                            }
                            offset += tlen;

diff --git a/src/ubik/remote.c b/src/ubik/remote.c
index a4fbf84..c3b708d 100644 (file)
--- a/src/ubik/remote.c
+++ b/src/ubik/remote.c
@@ -412,7 +412,7 @@ SDISK_GetFile(struct rx_call *rxcall, afs_int32 file,
     code = rx_Write(rxcall, (char *)&tlen, sizeof(afs_int32));
     if (code != sizeof(afs_int32)) {
        DBRELE(dbase);
-       ViceLog(5, ("Rx-write length error=%d\n", code));
+       ViceLog(0, ("Rx-write length error=%d\n", code));
        return BULK_ERROR;
     }
     offset = 0;
@@ -421,13 +421,13 @@ SDISK_GetFile(struct rx_call *rxcall, afs_int32 file,
        code = (*dbase->read) (dbase, file, tbuffer, offset, tlen);
        if (code != tlen) {
            DBRELE(dbase);
-           ViceLog(5, ("read failed error=%d\n", code));
+           ViceLog(0, ("read failed error=%d\n", code));
            return UIOERROR;
        }
        code = rx_Write(rxcall, tbuffer, tlen);
        if (code != tlen) {
            DBRELE(dbase);
-           ViceLog(5, ("Rx-write length error=%d\n", code));
+           ViceLog(0, ("Rx-write length error=%d\n", code));
            return BULK_ERROR;
        }
        length -= tlen;
@@ -526,7 +526,7 @@ SDISK_SendFile(struct rx_call *rxcall, afs_int32 file,
 #endif
        code = rx_Read(rxcall, tbuffer, tlen);
        if (code != tlen) {
-           ViceLog(5, ("Rx-read length error=%d\n", code));
+           ViceLog(0, ("Rx-read length error=%d\n", code));
            code = BULK_ERROR;
            close(fd);
            goto failed;
@@ -534,7 +534,7 @@ SDISK_SendFile(struct rx_call *rxcall, afs_int32 file,
        code = write(fd, tbuffer, tlen);
        pass++;
        if (code != tlen) {
-           ViceLog(5, ("write failed error=%d\n", code));
+           ViceLog(0, ("write failed tlen=%d, error=%d\n", tlen, code));
            code = UIOERROR;
            close(fd);
            goto failed;

diff --git a/src/ubik/ubik.c b/src/ubik/ubik.c
index a4fac9a..a8bd2e9 100644 (file)
--- a/src/ubik/ubik.c
+++ b/src/ubik/ubik.c
@@ -490,7 +490,7 @@ ubik_ServerInitCommon(afs_uint32 myHost, short myPort,
        rx_NewService(0, VOTE_SERVICE_ID, "VOTE", ubik_sc, numClasses,
                      VOTE_ExecuteRequest);
     if (tservice == (struct rx_service *)0) {
-       ViceLog(5, ("Could not create VOTE rx service!\n"));
+       ViceLog(0, ("Could not create VOTE rx service!\n"));
        return -1;
     }
     rx_SetMinProcs(tservice, 2);
@@ -500,7 +500,7 @@ ubik_ServerInitCommon(afs_uint32 myHost, short myPort,
        rx_NewService(0, DISK_SERVICE_ID, "DISK", ubik_sc, numClasses,
                      DISK_ExecuteRequest);
     if (tservice == (struct rx_service *)0) {
-       ViceLog(5, ("Could not create DISK rx service!\n"));
+       ViceLog(0, ("Could not create DISK rx service!\n"));
        return -1;
     }
     rx_SetMinProcs(tservice, 2);

diff --git a/src/ubik/vote.c b/src/ubik/vote.c
index e958627..3b771f0 100644 (file)
--- a/src/ubik/vote.c
+++ b/src/ubik/vote.c
@@ -210,7 +210,7 @@ SVOTE_Beacon(struct rx_call * rxcall, afs_int32 astate,
                break;
        }
        if (!ts)
-           ViceLog(5, ("Unknown host %x has sent a beacon\n", otherHost));
+           ViceLog(0, ("Unknown host %x has sent a beacon\n", otherHost));
        if (ts && ts->isClone)
            isClone = 1;
     } else {
@@ -269,7 +269,7 @@ SVOTE_Beacon(struct rx_call * rxcall, afs_int32 astate,
        vote_globals.syncTime = now;
     } else if (vote_globals.syncTime + BIGTIME < now) {
        if (vote_globals.syncHost) {
-           ViceLog(5, ("Ubik: Lost contact with sync-site %s (NOT in quorum)\n",
+           ViceLog(0, ("Ubik: Lost contact with sync-site %s (NOT in quorum)\n",
                 afs_inet_ntoa_r(vote_globals.syncHost, hoststr)));
        }
        vote_globals.syncHost = 0;
@@ -315,6 +315,9 @@ SVOTE_Beacon(struct rx_call * rxcall, afs_int32 astate,
        if ((vote_globals.ubik_lastYesTime + BIGTIME < now) || (otherHost != vote_globals.lastYesHost)
            || (vote_globals.lastYesState != astate)) {
            /* A new vote or a change in the vote or changed quorum */
+           /* XXX This should be at loglevel 0, but the conditionals
+            * ought to be reworked first to prevent excessive logging.
+            */
            ViceLog(5, ("Ubik: vote 'yes' for %s %s\n",
                        afs_inet_ntoa_r(otherHost, hoststr),
                        (astate ? "(in quorum)" : "(NOT in quorum)")));