BUG #6184: Inconsistencies in log messages

The following bug has been logged online:

Bug reference: 6184
Logged by: Ding Yuan
Email address: ding(dot)yuan(dot)90(at)hotmail(dot)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(at)comment(dot)c and 663(at)comment(dot)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)));