Обсуждение: Re: [BUGS] BUG #6184: Inconsistencies in log messages

Поиск
Список
Период
Сортировка

Re: [BUGS] BUG #6184: Inconsistencies in log messages

От
Bruce Momjian
Дата:
[ moved to hackers]

Would someone review this report for me?  I think there are few
reasonable changes in here, but I am not familiar enough with all the
code areas.

---------------------------------------------------------------------------

On Tue, Aug 30, 2011 at 07:15:19AM +0000, Ding Yuan wrote:
> 
> The following bug has been logged online:
> 
> Bug reference:      6184
> Logged by:          Ding Yuan
> Email address:      ding.yuan.90@hotmail.com
> PostgreSQL version: 8.4.8
> Operating system:   All
> Description:        Inconsistencies in log messages
> Details: 
> 
> Hi Postgres developers,
> (I reported this a day ago and for some reason did not see my message appear
> in the archive, so I am resending it again and I apologize if it seems
> duplicated). 
> 
> I am a student doing research on improving software's diagnosability by
> improving the error messages. Recently I run a static checker on
> postgres-8.4.8 and found that some inconsistencies in log messages in
> similar situations. While we suspect some of them should be fixed, we are
> not 100% sure since we do not have domain expertise in Squid code. 
> 
> I am reporting 10 such cases in this report. We truly appreciate your
> feedback on whether our findings make sense.
> 
> Thanks,
> Ding
> 
> ================== Report 1 ========================
> The two elog messages are of similar situations but with different verbosity
> levels.
> Pattern: 7478
> ---------------- src/backend/executor/nodeResult.c ---------------------
> @@ line: 171 @@
> 171:    void
> 172:    ExecResultMarkPos(ResultState *node)
> 173:    {
> 174:            PlanState  *outerPlan = outerPlanState(node);
> 175:
> 176:            if (outerPlan != NULL)
> 177:                    ExecMarkPos(outerPlan);
> 178:            else
> 179:                    elog(DEBUG2, "Result nodes do not support
> mark/restore");
> ---------------- src/backend/executor/nodeResult.c ---------------------
> @@ line: 186 @@
> 186:    void
> 187:    ExecResultRestrPos(ResultState *node)
> 188:    {
> 189:            PlanState  *outerPlan = outerPlanState(node);
> 190:
> 191:            if (outerPlan != NULL)
> 192:                    ExecRestrPos(outerPlan);
> 193:            else
> 194:                    elog(ERROR, "Result nodes do not support
> mark/restore");
> 
> 
> 
> ======================== Report 2
> ==========================================
> The verbosity level for error return for CreateEvent is not consistent!
> Pattern: 6490
> ---------------- src/backend/port/win32/socket.c ---------------------
> @@ line: 128 @@
> 128:                    waitevent = CreateEvent(NULL, TRUE, FALSE, NULL);
> 129:
> 130:                    if (waitevent == INVALID_HANDLE_VALUE)
> 131:                            ereport(ERROR,
> 132:                                            (errmsg_internal("Failed to
> create socket waiting event: %i", (int) GetLastError())));
> ---------------- src/backend/port/win32/signal.c ---------------------
> @@ line: 83 @@
> 83:             pgwin32_signal_event = CreateEvent(NULL, TRUE, FALSE,
> NULL);
> 84:             if (pgwin32_signal_event == NULL)
> 85:                     ereport(FATAL,
> 86:                                     (errmsg_internal("failed to create
> signal event: %d", (int) GetLastError())));
> 
> 
> ======================== Report 3
> ==========================================
> The log message in the first snippet (line 3487) has ERROR level, while
> PANIC
> is logged in other similar situations.
> Pattern: 4207
> ---------------- src/backend/access/heap/heapam.c ---------------------
> @@ line: 3483 @@
> 3483:           if (PageGetMaxOffsetNumber(page) >= offnum)
> 3484:                   lp = PageGetItemId(page, offnum);
> 3485:
> 3486:           if (PageGetMaxOffsetNumber(page) < offnum ||
> !ItemIdIsNormal(lp))
> 3487:                   elog(ERROR, "heap_inplace_update: invalid lp");
> 3488:
> 3489:           htup = (HeapTupleHeader) PageGetItem(page, lp);
> 3490:
> 3491:           oldlen = ItemIdGetLength(lp) - htup->t_hoff;
> ---------------- src/backend/access/heap/heapam.c ---------------------
> @@ line: 4732 @@
> 4732:           if (PageGetMaxOffsetNumber(page) >= offnum)
> 4733:                   lp = PageGetItemId(page, offnum);
> 4734:
> 4735:           if (PageGetMaxOffsetNumber(page) < offnum ||
> !ItemIdIsNormal(lp))
> 4736:                   elog(PANIC, "heap_inplace_redo: invalid lp");
> 4737:
> 4738:           htup = (HeapTupleHeader) PageGetItem(page, lp);
> 4739:
> 4740:           oldlen = ItemIdGetLength(lp) - htup->t_hoff;
> ---------------- src/backend/access/heap/heapam.c ---------------------
> @@ line: 4268 @@
> 4268:           if (PageGetMaxOffsetNumber(page) >= offnum)
> 4269:                   lp = PageGetItemId(page, offnum);
> 4270:
> 4271:           if (PageGetMaxOffsetNumber(page) < offnum ||
> !ItemIdIsNormal(lp))
> 4272:                   elog(PANIC, "heap_delete_redo: invalid lp");
> 4273:
> 4274:           htup = (HeapTupleHeader) PageGetItem(page, lp);
> ---------------- src/backend/access/heap/heapam.c ---------------------
> @@ line: 4469 @@
> 4469:           if (PageGetMaxOffsetNumber(page) >= offnum)
> 4470:                   lp = PageGetItemId(page, offnum);
> 4471:
> 4472:           if (PageGetMaxOffsetNumber(page) < offnum ||
> !ItemIdIsNormal(lp))
> 4473:                   elog(PANIC, "heap_update_redo: invalid lp");
> 4474:
> 4475:           htup = (HeapTupleHeader) PageGetItem(page, lp);
> ---------------- src/backend/access/heap/heapam.c ---------------------
> @@ line: 4673 @@
> 4673:           if (PageGetMaxOffsetNumber(page) >= offnum)
> 4674:                   lp = PageGetItemId(page, offnum);
> 4675:
> 4676:           if (PageGetMaxOffsetNumber(page) < offnum ||
> !ItemIdIsNormal(lp))
> 4677:                   elog(PANIC, "heap_lock_redo: invalid lp");
> 4678:
> 4679:           htup = (HeapTupleHeader) PageGetItem(page, lp);
> 
> 
> ======================== Report 4
> ==========================================
> There is no error message in the 2nd snippet, when:
> 3089:           if (!SplitIdentifierString(rawname, ',', &namelist))
> occurred, while there is one at line 62 under similar situations.
> Pattern: 4440
> ---------------- src/backend/commands/variable.c ---------------------
> @@ line: 46 @@
> 46:             char       *rawstring;
> 47:             char       *result;
> 48:             List       *elemlist;
> 49:             ListCell   *l;
> 50:
> 51:             /* Need a modifiable copy of string */
> 52:             rawstring = pstrdup(value);
> 53:
> 54:             /* Parse string into list of identifiers */
> 55:             if (!SplitIdentifierString(rawstring, ',', &elemlist))
> 56:             {
> 57:                     /* syntax error in list */
> 58:                     pfree(rawstring);
> 59:                     list_free(elemlist);
> 60:                     ereport(GUC_complaint_elevel(source),
> 61:                                    
> (errcode(ERRCODE_INVALID_PARAMETER_VALUE),
> 62:                                      errmsg("invalid list syntax for
> parameter \"datestyle\"")));
> 63:                     return NULL;
> 64:             }
> 65:
> 66:             foreach(l, elemlist)
> ---------------- src/backend/catalog/namespace.c ---------------------
> @@ line: 3081 @@
> 3081:           char       *rawname;
> 3082:           List       *namelist;
> 3083:           ListCell   *l;
> 3084:
> 3085:           /* Need a modifiable copy of string */
> 3086:           rawname = pstrdup(newval);
> 3087:
> 3088:           /* Parse string into list of identifiers */
> 3089:           if (!SplitIdentifierString(rawname, ',', &namelist))
> 3090:           {
> 3091:                   /* syntax error in name list */
> 3092:                   pfree(rawname);
> 3093:                   list_free(namelist);
> 3094:                   return NULL;
> 3095:           }
> 3096:
> 3097:           /*
> 3098:            * If we aren't inside a transaction, we cannot do database
> access so
> 3099:            * cannot verify the individual names.  Must accept the list
> on faith.
> 3100:            */
> 3101:           if (source >= PGC_S_INTERACTIVE && IsTransactionState())
> 3102:           {
> 3103:                   /*
> 3104:                    * Verify that all the names are either valid
> namespace names or
> 3105:                    * "$user" or "pg_temp".  We do not require $user to
> correspond to a
> 3106:                    * valid namespace, and pg_temp might not exist yet.
>  We do not check
> 3107:                    * for USAGE rights, either; should we?
> 3108:                    *
> 3109:                    * When source == PGC_S_TEST, we are checking the
> argument of an ALTER
> 3110:                    * DATABASE SET or ALTER USER SET command.      It
> could be that the
> 3111:                    * intended use of the search path is for some other
> database, so we
> 3112:                    * should not error out if it mentions schemas not
> present in the
> 3113:                    * current database.  We reduce the message to
> NOTICE instead.
> 3114:                    */
> 3115:                   foreach(l, namelist)
> 
> 
> ======================== Report 5
> ==========================================
> The first log message at line 2221 is of ERROR level, while the other log
> messages in similar situations are FATAL!
> Pattern: 3948
> ---------------- src/backend/access/transam/xact.c ---------------------
> @@ line: 2210 @@
> 2210:                   case TBLOCK_BEGIN:
> 2211:                   case TBLOCK_SUBBEGIN:
> 2212:                   case TBLOCK_END:
> 2213:                   case TBLOCK_SUBEND:
> 2214:                   case TBLOCK_ABORT_END:
> 2215:                   case TBLOCK_SUBABORT_END:
> 2216:                   case TBLOCK_ABORT_PENDING:
> 2217:                   case TBLOCK_SUBABORT_PENDING:
> 2218:                   case TBLOCK_SUBRESTART:
> 2219:                   case TBLOCK_SUBABORT_RESTART:
> 2220:                   case TBLOCK_PREPARE:
> 2221:                           elog(ERROR, "StartTransactionCommand:
> unexpected state %s",
> 2222:                                   
> BlockStateAsString(s->blockState));
> 2223:                           break;
> ---------------- src/backend/access/transam/xact.c ---------------------
> @@ line: 2890 @@
> 2890:                   case TBLOCK_BEGIN:
> 2891:                   case TBLOCK_SUBBEGIN:
> 2892:                   case TBLOCK_END:
> 2893:                   case TBLOCK_SUBEND:
> 2894:                   case TBLOCK_ABORT_END:
> 2895:                   case TBLOCK_SUBABORT_END:
> 2896:                   case TBLOCK_ABORT_PENDING:
> 2897:                   case TBLOCK_SUBABORT_PENDING:
> 2898:                   case TBLOCK_SUBRESTART:
> 2899:                   case TBLOCK_SUBABORT_RESTART:
> 2900:                   case TBLOCK_PREPARE:
> 2901:                           elog(FATAL, "BeginTransactionBlock:
> unexpected state %s",
> 2902:                                   
> BlockStateAsString(s->blockState));
> 2903:                           break;
> ---------------- src/backend/access/transam/xact.c ---------------------
> @@ line: 3058 @@
> 3058:                   case TBLOCK_BEGIN:
> 3059:                   case TBLOCK_SUBBEGIN:
> 3060:                   case TBLOCK_END:
> 3061:                   case TBLOCK_SUBEND:
> 3062:                   case TBLOCK_ABORT_END:
> 3063:                   case TBLOCK_SUBABORT_END:
> 3064:                   case TBLOCK_ABORT_PENDING:
> 3065:                   case TBLOCK_SUBABORT_PENDING:
> 3066:                   case TBLOCK_SUBRESTART:
> 3067:                   case TBLOCK_SUBABORT_RESTART:
> 3068:                   case TBLOCK_PREPARE:
> 3069:                           elog(FATAL, "EndTransactionBlock: unexpected
> state %s",
> 3070:                                   
> BlockStateAsString(s->blockState));
> 3071:                           break;
> ---------------- src/backend/access/transam/xact.c ---------------------
> @@ line: 3150 @@
> 3150:                   case TBLOCK_BEGIN:
> 3151:                   case TBLOCK_SUBBEGIN:
> 3152:                   case TBLOCK_END:
> 3153:                   case TBLOCK_SUBEND:
> 3154:                   case TBLOCK_ABORT_END:
> 3155:                   case TBLOCK_SUBABORT_END:
> 3156:                   case TBLOCK_ABORT_PENDING:
> 3157:                   case TBLOCK_SUBABORT_PENDING:
> 3158:                   case TBLOCK_SUBRESTART:
> 3159:                   case TBLOCK_SUBABORT_RESTART:
> 3160:                   case TBLOCK_PREPARE:
> 3161:                           elog(FATAL, "UserAbortTransactionBlock:
> unexpected state %s",
> 3162:                                   
> BlockStateAsString(s->blockState));
> 3163:                           break;
> ---------------- src/backend/access/transam/xact.c ---------------------
> @@ line: 3351 @@
> 3351:                   case TBLOCK_BEGIN:
> 3352:                   case TBLOCK_SUBBEGIN:
> 3353:                   case TBLOCK_END:
> 3354:                   case TBLOCK_SUBEND:
> 3355:                   case TBLOCK_ABORT_END:
> 3356:                   case TBLOCK_SUBABORT_END:
> 3357:                   case TBLOCK_ABORT_PENDING:
> 3358:                   case TBLOCK_SUBABORT_PENDING:
> 3359:                   case TBLOCK_SUBRESTART:
> 3360:                   case TBLOCK_SUBABORT_RESTART:
> 3361:                   case TBLOCK_PREPARE:
> 3362:                           elog(FATAL, "RollbackToSavepoint: unexpected
> state %s",
> 3363:                                   
> BlockStateAsString(s->blockState));
> 3364:                           break;
> ---------------- src/backend/access/transam/xact.c ---------------------
> @@ line: 3524 @@
> 3524:                   case TBLOCK_BEGIN:
> 3525:                   case TBLOCK_SUBBEGIN:
> 3526:                   case TBLOCK_INPROGRESS:
> 3527:                   case TBLOCK_END:
> 3528:                   case TBLOCK_SUBEND:
> 3529:                   case TBLOCK_ABORT:
> 3530:                   case TBLOCK_ABORT_END:
> 3531:                   case TBLOCK_SUBABORT_END:
> 3532:                   case TBLOCK_ABORT_PENDING:
> 3533:                   case TBLOCK_SUBABORT_PENDING:
> 3534:                   case TBLOCK_SUBRESTART:
> 3535:                   case TBLOCK_SUBABORT_RESTART:
> 3536:                   case TBLOCK_PREPARE:
> 3537:                           elog(FATAL,
> "RollbackAndReleaseCurrentSubTransaction: unexpected state %s",
> 3538:                                   
> BlockStateAsString(s->blockState));
> 3539:                           break;
> 
> 
> 
> ======================== Report 6
> ==========================================
> The verbosity level of log messages are inconsistent!
> Pattern: 3894
> ---------------- src/backend/access/transam/xlog.c ---------------------
> @@ line: 7537 @@
> 7537:           if (fscanf(lfp, "START WAL LOCATION: %X/%X (file %24s)%c",
> 7538:                              &startpoint.xlogid, &startpoint.xrecoff,
> startxlogfilename,
> 7539:                              &ch) != 4 || ch != '\n')
> 7540:                   ereport(ERROR,
> 7541:                                  
> (errcode(ERRCODE_OBJECT_NOT_IN_PREREQUISITE_STATE),
> 7542:                                    errmsg("invalid data in file
> \"%s\"", BACKUP_LABEL_FILE)));
> ---------------- src/backend/access/transam/xlog.c ---------------------
> @@ line: 7915 @@
> 7915:                   if (fscanf(fp, "START WAL LOCATION: %X/%X (file
> %24s)%c",
> 7916:                                      &startpoint.xlogid,
> &startpoint.xrecoff, startxlogfilename,
> 7917:                                      &ch) != 4 || ch != '\n')
> 7918:                           ereport(FATAL,
> 7919:                                          
> (errcode(ERRCODE_OBJECT_NOT_IN_PREREQUISITE_STATE),
> 7920:                                            errmsg("invalid data in
> file \"%s\"", histfilename)));
> ---------------- src/backend/access/transam/xlog.c ---------------------
> @@ line: 7921 @@
> 7921:                   if (fscanf(fp, "STOP WAL LOCATION: %X/%X (file
> %24s)%c",
> 7922:                                      &stoppoint.xlogid,
> &stoppoint.xrecoff, stopxlogfilename,
> 7923:                                      &ch) != 4 || ch != '\n')
> 7924:                           ereport(FATAL,
> 7925:                                          
> (errcode(ERRCODE_OBJECT_NOT_IN_PREREQUISITE_STATE),
> 7926:                                            errmsg("invalid data in
> file \"%s\"", histfilename)));
> 
> 
> 
> ======================== Report 7
> ==========================================
> The log message at line 3050 and line 3142 have inconsistent verbosity
> levels!
> Pattern: 3955
> ---------------- src/backend/access/transam/xact.c ---------------------
> @@ line: 3022 @@
> 3022:                   case TBLOCK_SUBABORT:
> 3023:                           while (s->parent != NULL)
> 3024:                           {
> 3025:                                   if (s->blockState ==
> TBLOCK_SUBINPROGRESS)
> 3026:                                           s->blockState =
> TBLOCK_SUBABORT_PENDING;
> 3027:                                   else if (s->blockState ==
> TBLOCK_SUBABORT)
> 3028:                                           s->blockState =
> TBLOCK_SUBABORT_END;
> 3029:                                   else
> 3030:                                           elog(FATAL,
> "EndTransactionBlock: unexpected state %s",
> 3031:                                                   
> BlockStateAsString(s->blockState));
> 3032:                                   s = s->parent;
> 3033:                           }
> 3034:                           if (s->blockState == TBLOCK_INPROGRESS)
> 3035:                                   s->blockState =
> TBLOCK_ABORT_PENDING;
> 3036:                           else if (s->blockState == TBLOCK_ABORT)
> 3037:                                   s->blockState = TBLOCK_ABORT_END;
> 3038:                           else
> 3039:                                   elog(FATAL, "EndTransactionBlock:
> unexpected state %s",
> 3040:                                           
> BlockStateAsString(s->blockState));
> 3041:                           break;
> 3042:
> 3043:                           /*
> 3044:                            * The user issued COMMIT when not inside a
> transaction.  Issue a
> 3045:                            * WARNING, staying in TBLOCK_STARTED state.
>  The upcoming call to
> 3046:                            * CommitTransactionCommand() will then
> close the transaction and
> 3047:                            * put us back into the default state.
> 3048:                            */
> 3049:                   case TBLOCK_STARTED:
> 3050:                           ereport(WARNING,
> 3051:                                          
> (errcode(ERRCODE_NO_ACTIVE_SQL_TRANSACTION),
> 3052:                                            errmsg("there is no
> transaction in progress")));
> 3053:                           result = true;
> 3054:                           break;
> 3055:
> 3056:                           /* These cases are invalid. */
> 3057:                   case TBLOCK_DEFAULT:
> 3058:                   case TBLOCK_BEGIN:
> 3059:                   case TBLOCK_SUBBEGIN:
> 3060:                   case TBLOCK_END:
> 3061:                   case TBLOCK_SUBEND:
> 3062:                   case TBLOCK_ABORT_END:
> 3063:                   case TBLOCK_SUBABORT_END:
> 3064:                   case TBLOCK_ABORT_PENDING:
> 3065:                   case TBLOCK_SUBABORT_PENDING:
> 3066:                   case TBLOCK_SUBRESTART:
> 3067:                   case TBLOCK_SUBABORT_RESTART:
> 3068:                   case TBLOCK_PREPARE:
> 3069:                           elog(FATAL, "EndTransactionBlock: unexpected
> state %s",
> 3070:                                   
> BlockStateAsString(s->blockState));
> 3071:                           break;
> ---------------- src/backend/access/transam/xact.c ---------------------
> @@ line: 3114 @@
> 3114:                   case TBLOCK_SUBABORT:
> 3115:                           while (s->parent != NULL)
> 3116:                           {
> 3117:                                   if (s->blockState ==
> TBLOCK_SUBINPROGRESS)
> 3118:                                           s->blockState =
> TBLOCK_SUBABORT_PENDING;
> 3119:                                   else if (s->blockState ==
> TBLOCK_SUBABORT)
> 3120:                                           s->blockState =
> TBLOCK_SUBABORT_END;
> 3121:                                   else
> 3122:                                           elog(FATAL,
> "UserAbortTransactionBlock: unexpected state %s",
> 3123:                                                   
> BlockStateAsString(s->blockState));
> 3124:                                   s = s->parent;
> 3125:                           }
> 3126:                           if (s->blockState == TBLOCK_INPROGRESS)
> 3127:                                   s->blockState =
> TBLOCK_ABORT_PENDING;
> 3128:                           else if (s->blockState == TBLOCK_ABORT)
> 3129:                                   s->blockState = TBLOCK_ABORT_END;
> 3130:                           else
> 3131:                                   elog(FATAL,
> "UserAbortTransactionBlock: unexpected state %s",
> 3132:                                           
> BlockStateAsString(s->blockState));
> 3133:                           break;
> 3134:
> 3135:                           /*
> 3136:                            * The user issued ABORT when not inside a
> transaction. Issue a
> 3137:                            * WARNING and go to abort state.  The
> upcoming call to
> 3138:                            * CommitTransactionCommand() will then put
> us back into the
> 3139:                            * default state.
> 3140:                            */
> 3141:                   case TBLOCK_STARTED:
> 3142:                           ereport(NOTICE,
> 3143:                                          
> (errcode(ERRCODE_NO_ACTIVE_SQL_TRANSACTION),
> 3144:                                            errmsg("there is no
> transaction in progress")));
> 3145:                           s->blockState = TBLOCK_ABORT_PENDING;
> 3146:                           break;
> 3147:
> 3148:                           /* These cases are invalid. */
> 3149:                   case TBLOCK_DEFAULT:
> 3150:                   case TBLOCK_BEGIN:
> 3151:                   case TBLOCK_SUBBEGIN:
> 3152:                   case TBLOCK_END:
> 3153:                   case TBLOCK_SUBEND:
> 3154:                   case TBLOCK_ABORT_END:
> 3155:                   case TBLOCK_SUBABORT_END:
> 3156:                   case TBLOCK_ABORT_PENDING:
> 3157:                   case TBLOCK_SUBABORT_PENDING:
> 3158:                   case TBLOCK_SUBRESTART:
> 3159:                   case TBLOCK_SUBABORT_RESTART:
> 3160:                   case TBLOCK_PREPARE:
> 3161:                           elog(FATAL, "UserAbortTransactionBlock:
> unexpected state %s",
> 3162:                                   
> BlockStateAsString(s->blockState));
> 3163:                           break;
> 
> ======================== Report 8
> ==========================================
> The log message at 2292 is ERROR, inconsistent with the line @line 2521
> (PANIC).
> Pattern: 3850
> ---------------- src/backend/access/transam/xlog.c ---------------------
> @@ line: 2289 @@
> 2289:           fd = BasicOpenFile(path, O_RDWR | PG_BINARY |
> get_sync_bit(sync_method),
> 2290:                                              S_IRUSR | S_IWUSR);
> 2291:           if (fd < 0)
> 2292:                   ereport(ERROR,
> 2293:                                   (errcode_for_file_access(),
> 2294:                      errmsg("could not open file \"%s\" (log file %u,
> segment %u): %m",
> 2295:                                     path, log, seg)));
> 2296:
> 2297:           elog(DEBUG2, "done creating and filling new WAL file");
> 2298:
> 2299:           return fd;
> ---------------- src/backend/access/transam/xlog.c ---------------------
> @@ line: 2518 @@
> 2518:           fd = BasicOpenFile(path, O_RDWR | PG_BINARY |
> get_sync_bit(sync_method),
> 2519:                                              S_IRUSR | S_IWUSR);
> 2520:           if (fd < 0)
> 2521:                   ereport(PANIC,
> 2522:                                   (errcode_for_file_access(),
> 2523:                      errmsg("could not open file \"%s\" (log file %u,
> segment %u): %m",
> 2524:                                     path, log, seg)));
> 2525:
> 2526:           return fd;
> 
> 
> ======================== Report 9
> ==========================================
> The 2 log messages: 624@comment.c and 663@comment.c have different
> verbosity
> levels!
> Pattern: 8162 
> ---------------- src/backend/commands/comment.c ---------------------
> @@ line: 607 @@
> 607:                    ereport(ERROR,
> 608:                                    (errcode(ERRCODE_SYNTAX_ERROR),
> 609:                                     errmsg("database name cannot be
> qualified")));
> 610:            database = strVal(linitial(qualname));
> 611:
> 612:            /*
> 613:             * When loading a dump, we may see a COMMENT ON DATABASE for
> the old name
> 614:             * of the database.  Erroring out would prevent pg_restore
> from completing
> 615:             * (which is really pg_restore's fault, but for now we will
> work around
> 616:             * the problem here).  Consensus is that the best fix is to
> treat wrong
> 617:             * database name as a WARNING not an ERROR.
> 618:             */
> 619:
> 620:            /* First get the database OID */
> 621:            oid = get_database_oid(database);
> 622:            if (!OidIsValid(oid))
> 623:            {
> 624:                    ereport(WARNING,
> 625:                                   
> (errcode(ERRCODE_UNDEFINED_DATABASE),
> 626:                                     errmsg("database \"%s\" does not
> exist", database)));
> 627:                    return;
> ---------------- src/backend/commands/comment.c ---------------------
> @@ line: 655 @@
> 655:                    ereport(ERROR,
> 656:                                    (errcode(ERRCODE_SYNTAX_ERROR),
> 657:                                     errmsg("tablespace name cannot be
> qualified")));
> 658:            tablespace = strVal(linitial(qualname));
> 659:
> 660:            oid = get_tablespace_oid(tablespace);
> 661:            if (!OidIsValid(oid))
> 662:            {
> 663:                    ereport(ERROR,
> 664:                                    (errcode(ERRCODE_UNDEFINED_OBJECT),
> 665:                                     errmsg("tablespace \"%s\" does not
> exist", tablespace)));
> 666:                    return;
> 
> 
> 
> ======================== Report 10
> ==========================================
> The first log message has WARNING while the others have ERROR!
> Pattern: 3126
> ---------------- src/backend/utils/misc/guc.c ---------------------
> @@ line: 7029 @@
> 7029:                   ParseLongOption(s, &name, &value);
> 7030:                   if (!value)
> 7031:                   {
> 7032:                           ereport(WARNING,
> 7033:                                          
> (errcode(ERRCODE_SYNTAX_ERROR),
> 7034:                                            errmsg("could not parse
> setting for parameter \"%s\"",
> 7035:                                                           name)));
> ---------------- src/backend/postmaster/postmaster.c ---------------------
> @@ line: 647 @@
> 647:                                            ParseLongOption(optarg,
> &name, &value);
> 648:                                            if (!value)
> 649:                                            {
> 650:                                                    if (opt == '-')
> 651:                                                           
> ereport(ERROR,
> 652:                                                                        
>    (errcode(ERRCODE_SYNTAX_ERROR),
> 653:                                                                        
>     errmsg("--%s requires a value",
> 654:                                                                        
>                    optarg)));
> ---------------- src/backend/bootstrap/bootstrap.c ---------------------
> @@ line: 288 @@
> 288:                                            ParseLongOption(optarg,
> &name, &value);
> 289:                                            if (!value)
> 290:                                            {
> 291:                                                    if (flag == '-')
> 292:                                                           
> ereport(ERROR,
> 293:                                                                        
>    (errcode(ERRCODE_SYNTAX_ERROR),
> 294:                                                                        
>     errmsg("--%s requires a value",
> 295:                                                                        
>                    optarg)));
> ---------------- src/backend/tcop/postgres.c ---------------------
> @@ line: 3175 @@
> 3175:                                           ParseLongOption(optarg,
> &name, &value);
> 3176:                                           if (!value)
> 3177:                                           {
> 3178:                                                   if (flag == '-')
> 3179:                                                          
> ereport(ERROR,
> 3180:                                                                       
>    (errcode(ERRCODE_SYNTAX_ERROR),
> 3181:                                                                       
>     errmsg("--%s requires a value",
> 3182:                                                                       
>                   optarg)));
> 
> -- 
> Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org)
> To make changes to your subscription:
> http://www.postgresql.org/mailpref/pgsql-bugs

--  Bruce Momjian  <bruce@momjian.us>        http://momjian.us EnterpriseDB
http://enterprisedb.com
 + It's impossible for everything to be true. +



Re: [BUGS] BUG #6184: Inconsistencies in log messages

От
Tom Lane
Дата:
Bruce Momjian <bruce@momjian.us> writes:
> [ moved to hackers]

> Would someone review this report for me?  I think there are few
> reasonable changes in here, but I am not familiar enough with all the
> code areas.

I see one place where we forgot to sync a comment, but otherwise this
all looks OK.  Details below ...


>> ================== Report 1 ========================
>> The two elog messages are of similar situations but with different verbosity
>> levels.

The inconsistency here is intentional: it's okay for Mark to be a no-op,
as long as you don't ever do a Restore.

>> ======================== Report 2
>> ==========================================
>> The verbosity level for error return for CreateEvent is not consistent!

I'm not too familiar with the Windows-specific code, but I don't see
anything particularly wrong here.  Failing to initialize in a wait for
an individual socket is perhaps recoverable, whereas failing to set up
the signal-handling emulation at all is not.

>> ======================== Report 3
>> ==========================================
>> The log message in the first snippet (line 3487) has ERROR level, while
>> PANIC
>> is logged in other similar situations.

They're not really similar since one case is mainline code while the
others are log replay.  Actually, I think the mainline case is inside a
critical section so it's not going to matter too much anyway; and for
that matter there's no practical difference between ERROR and PANIC in
replay either.  But by and large we've coded PANIC explicitly in log
replay, but not in initial creation/application of WAL records.

>> ======================== Report 4
>> ==========================================
>> There is no error message in the 2nd snippet, when:
>> 3089:           if (!SplitIdentifierString(rawname, ',', &namelist))
>> occurred, while there is one at line 62 under similar situations.

[ shrug... ]  It's not always the case that errors are to be reported
immediately where detected.  In this particular case, the second
instance is inside a GUC check_hook, which is specifically required
to not throw errors, but instead return a failure indication to its
caller.

>> ======================== Report 5
>> ==========================================
>> The first log message at line 2221 is of ERROR level, while the other log
>> messages in similar situations are FATAL!

I think probably the point here is that erroring out of transaction
start is recoverable (you are still not in a transaction, and you could
try again) but erroring out of a later state transition is not going to
leave the transaction mechanism in a sane state.  In any case, all of
those are "can't happen" errors so it's hard to get very excited about
them.

>> ======================== Report 6
>> ==========================================
>> The verbosity level of log messages are inconsistent!

Again, one of these is mainline code while the others are in recovery
context.

>> ======================== Report 7
>> ==========================================
>> The log message at line 3050 and line 3142 have inconsistent verbosity
>> levels!

The inconsistency here is a consequence of commit
82748bc253e00a07f0fcce3959af711b509a4e69, so it's entirely intentional,
and presumably a result of discussion in the mailing lists (I'm too lazy
to go look for the thread right now).

I notice that that commit failed to adjust the adjacent comment, though
--- tut tut, Bruce.

>> ======================== Report 8
>> ==========================================
>> The log message at 2292 is ERROR, inconsistent with the line @line 2521
>> (PANIC).

Failure of advance creation of an xlog file is recoverable, not having
one when we need it is not.  Also see header comment for XLogFileInit.

>> ======================== Report 9
>> ==========================================
>> The 2 log messages: 624@comment.c and 663@comment.c have different
>> verbosity
>> levels!

Again, note the comment, which shows pretty clearly that this choice was
intentional.  I'm not going to do a git blame for this one but you could
certainly track back where the code was changed to make it a WARNING.

>> ======================== Report 10
>> ==========================================
>> The first log message has WARNING while the others have ERROR!

Yup.  The first one is in postgresql.conf parsing and the others are in
command line option parsing.  We don't start up if command line options
are bad ... but once running, a mistake in postgresql.conf shouldn't
bring down the database.


On the whole, my impression is that this type of analysis might be
productive, but it would require a great deal more context awareness
(and knowledge of project-specific coding rules) to get it to the
point where it's not almost all false positives.

I doubt that there are very many mistakes in assignment of
NOTICE/WARNING/ERROR levels in our code.  There's a certain lack of
consistency in use of ERROR/FATAL/PANIC in contexts where the coder
knows they're all the same anyway, namely just about anything that
runs in a non-transactional process.  And the DEBUGn levels are all over
the map, because there's never been any global vision of which debug
messages are most likely to be interesting.  I'm not sure if a tool
like this could help us enforce a policy about that ... but first
we'd have to have a policy ...
        regards, tom lane



Re: [BUGS] BUG #6184: Inconsistencies in log messages

От
Bruce Momjian
Дата:
On Wed, Aug 15, 2012 at 06:42:51PM -0400, Tom Lane wrote:
> Bruce Momjian <bruce@momjian.us> writes:
> > [ moved to hackers]
> 
> > Would someone review this report for me?  I think there are few
> > reasonable changes in here, but I am not familiar enough with all the
> > code areas.
> 
> >> ======================== Report 7
> >> ==========================================
> >> The log message at line 3050 and line 3142 have inconsistent verbosity
> >> levels!
> 
> The inconsistency here is a consequence of commit
> 82748bc253e00a07f0fcce3959af711b509a4e69, so it's entirely intentional,
> and presumably a result of discussion in the mailing lists (I'm too lazy
> to go look for the thread right now).
> 
> I notice that that commit failed to adjust the adjacent comment, though
> --- tut tut, Bruce.

Oops, thanks, fixed, and thanks for reviewing this report.

--  Bruce Momjian  <bruce@momjian.us>        http://momjian.us EnterpriseDB
http://enterprisedb.com
 + It's impossible for everything to be true. +