Re: [HACKERS] Confusing recovery message when target not hit

[Michael Paquier]

On Mon, Jun 13, 2016 at 9:53 AM, Thom Brown  wrote:
> On 12 June 2016 at 12:51, Michael Paquier  wrote:
>>
>> On Sun, Jun 12, 2016 at 7:52 PM, Thom Brown  wrote:
>> > Aren't those already set by recoveryStopsBefore()?
>>
>> It is possible to exit the main redo loop if a NULL record is found
>> after calling ReadRecord, in which case those would not be set, no?
>
>
> I'm apprehensive about initialising those values myself as I don't want to
> set them at a point where they may potentially already be set.

As your patch relies on checks on the variables holding the recovery
stop information as not being set, initializing them before entering
in the REDO phase (say just before 6435:xlog.c on HEAD) is the safest
thing to do IMO.
-- 
Michael


-- 
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

Re: [HACKERS] Confusing recovery message when target not hit

[Thom Brown]

On 12 June 2016 at 12:51, Michael Paquier  wrote:

> On Sun, Jun 12, 2016 at 7:52 PM, Thom Brown  wrote:
> > Aren't those already set by recoveryStopsBefore()?
>
> It is possible to exit the main redo loop if a NULL record is found
> after calling ReadRecord, in which case those would not be set, no?
>

I'm apprehensive about initialising those values myself as I don't want to
set them at a point where they may potentially already be set.

And I've noticed that I didn't re-read my own output messages, so I've
corrected them in the attached patch.

Thom
diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
index e4645a3..d724d4b 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -7105,19 +7105,34 @@ StartupXLOG(void)
 		 * timeline changed.
 		 */
 		if (recoveryTarget == RECOVERY_TARGET_XID)
-			snprintf(reason, sizeof(reason),
-	 "%s transaction %u",
-	 recoveryStopAfter ? "after" : "before",
-	 recoveryStopXid);
+			if (recoveryStopXid == InvalidTransactionId)
+snprintf(reason, sizeof(reason),
+		"recovery finished without reaching recovery target xid of \"%u\"\n",
+		recoveryTargetXid);
+			else
+snprintf(reason, sizeof(reason),
+		 "%s transaction %u",
+		 recoveryStopAfter ? "after" : "before",
+		 recoveryStopXid);
 		else if (recoveryTarget == RECOVERY_TARGET_TIME)
-			snprintf(reason, sizeof(reason),
-	 "%s %s\n",
-	 recoveryStopAfter ? "after" : "before",
-	 timestamptz_to_str(recoveryStopTime));
+			if (recoveryStopTime == 0)
+snprintf(reason, sizeof(reason),
+		"recovery finished without reaching recovery target time of \"%s\"\n",
+		timestamptz_to_str(recoveryTargetTime));
+			else
+snprintf(reason, sizeof(reason),
+		 "%s %s\n",
+		 recoveryStopAfter ? "after" : "before",
+		 timestamptz_to_str(recoveryStopTime));
 		else if (recoveryTarget == RECOVERY_TARGET_NAME)
-			snprintf(reason, sizeof(reason),
-	 "at restore point \"%s\"",
-	 recoveryStopName);
+			if (*recoveryStopName == '\0')
+snprintf(reason, sizeof(reason),
+		"recovery finished without reaching recovery target name of \"%s\"\n",
+		recoveryTargetName);
+			else
+snprintf(reason, sizeof(reason),
+		 "at restore point \"%s\"",
+		 recoveryStopName);
 		else if (recoveryTarget == RECOVERY_TARGET_IMMEDIATE)
 			snprintf(reason, sizeof(reason), "reached consistency");
 		else

-- 
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

Re: [HACKERS] Confusing recovery message when target not hit

[Michael Paquier]

On Sun, Jun 12, 2016 at 7:52 PM, Thom Brown  wrote:
> Aren't those already set by recoveryStopsBefore()?

It is possible to exit the main redo loop if a NULL record is found
after calling ReadRecord, in which case those would not be set, no?
-- 
Michael


-- 
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

Re: [HACKERS] Confusing recovery message when target not hit

[Thom Brown]

On 11 June 2016 at 13:22, Michael Paquier  wrote:

> On Sat, Jun 11, 2016 at 9:44 AM, Thom Brown  wrote:
> > It may be the wrong way of going about it, but you get the idea of what
> I'm
> > suggesting we output instead.
>
> Surely things could be better. So +1 to be more verbose here.
>
> +if (recoveryStopTime == 0)
> +snprintf(reason, sizeof(reason),
> +"recovery reached consistency before recovery
> target time of \"%s\"\n",
> +timestamptz_to_str(recoveryTargetTime));
> "Reaching consistency" is not exact for here. I'd rather say "finished
> recovery without reaching target blah"
>

Yeah, sounds fine.


>
> +if (recoveryStopXid == 0)
> Checking for InvalidTransactionId is better here.
>

Agreed.


> And it would be good to initialize recoveryStopTime and
> recoveryStopXid as those are set only when a recovery target is
> reached.
>

Aren't those already set by recoveryStopsBefore()?

Revised patch attached, with new wording and covering recovery target name
case.

Thom
diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
index e4645a3..4033a2d 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -7105,19 +7105,34 @@ StartupXLOG(void)
 		 * timeline changed.
 		 */
 		if (recoveryTarget == RECOVERY_TARGET_XID)
-			snprintf(reason, sizeof(reason),
-	 "%s transaction %u",
-	 recoveryStopAfter ? "after" : "before",
-	 recoveryStopXid);
+			if (recoveryStopXid == InvalidTransactionId)
+snprintf(reason, sizeof(reason),
+		"recovery finished withoutrecovery target xid of \"%u\"\n",
+		recoveryTargetXid);
+			else
+snprintf(reason, sizeof(reason),
+		 "%s transaction %u",
+		 recoveryStopAfter ? "after" : "before",
+		 recoveryStopXid);
 		else if (recoveryTarget == RECOVERY_TARGET_TIME)
-			snprintf(reason, sizeof(reason),
-	 "%s %s\n",
-	 recoveryStopAfter ? "after" : "before",
-	 timestamptz_to_str(recoveryStopTime));
+			if (recoveryStopTime == 0)
+snprintf(reason, sizeof(reason),
+		"recovery finished without recovery target time of \"%s\"\n",
+		timestamptz_to_str(recoveryTargetTime));
+			else
+snprintf(reason, sizeof(reason),
+		 "%s %s\n",
+		 recoveryStopAfter ? "after" : "before",
+		 timestamptz_to_str(recoveryStopTime));
 		else if (recoveryTarget == RECOVERY_TARGET_NAME)
-			snprintf(reason, sizeof(reason),
-	 "at restore point \"%s\"",
-	 recoveryStopName);
+			if (*recoveryStopName == '\0')
+snprintf(reason, sizeof(reason),
+		"recovery finished without reaching recovery target name of \"%s\"\n",
+		recoveryTargetName);
+			else
+snprintf(reason, sizeof(reason),
+		 "at restore point \"%s\"",
+		 recoveryStopName);
 		else if (recoveryTarget == RECOVERY_TARGET_IMMEDIATE)
 			snprintf(reason, sizeof(reason), "reached consistency");
 		else

-- 
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

Re: [HACKERS] Confusing recovery message when target not hit

[Michael Paquier]

On Sun, Jun 12, 2016 at 12:46 AM, David Steele  wrote:
> On 6/11/16 8:22 AM, Michael Paquier wrote:
>> On Sat, Jun 11, 2016 at 9:44 AM, Thom Brown  wrote:
>>> It may be the wrong way of going about it, but you get the idea of what I'm
>>> suggesting we output instead.
>>
>> Surely things could be better. So +1 to be more verbose here.
>>
>> +if (recoveryStopTime == 0)
>> +snprintf(reason, sizeof(reason),
>> +"recovery reached consistency before recovery
>> target time of \"%s\"\n",
>> +timestamptz_to_str(recoveryTargetTime));
>> "Reaching consistency" is not exact for here. I'd rather say "finished
>> recovery without reaching target blah"
>>
>> +if (recoveryStopXid == 0)
>> Checking for InvalidTransactionId is better here.
>>
>> And it would be good to initialize recoveryStopTime and
>> recoveryStopXid as those are set only when a recovery target is
>> reached.
>
> +1 for Michael's wording.  It's not very clear in the logs right now if
> a recovery target was missed.  That makes it very difficult for the user
> to determine if PITR worked or not.

By the way, we surely want to have the same logic for a recovery
target name. It could be possible to reach the end of recovery without
reaching the goal of recovery.conf. It would be good to be verbose in
this case as well by checking for recoveryStopName[0] = '\0'.
-- 
Michael


-- 
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

Re: [HACKERS] Confusing recovery message when target not hit

[David Steele]

On 6/11/16 8:22 AM, Michael Paquier wrote:
> On Sat, Jun 11, 2016 at 9:44 AM, Thom Brown  wrote:
>> It may be the wrong way of going about it, but you get the idea of what I'm
>> suggesting we output instead.
> 
> Surely things could be better. So +1 to be more verbose here.
> 
> +if (recoveryStopTime == 0)
> +snprintf(reason, sizeof(reason),
> +"recovery reached consistency before recovery
> target time of \"%s\"\n",
> +timestamptz_to_str(recoveryTargetTime));
> "Reaching consistency" is not exact for here. I'd rather say "finished
> recovery without reaching target blah"
> 
> +if (recoveryStopXid == 0)
> Checking for InvalidTransactionId is better here.
> 
> And it would be good to initialize recoveryStopTime and
> recoveryStopXid as those are set only when a recovery target is
> reached.

+1 for Michael's wording.  It's not very clear in the logs right now if
a recovery target was missed.  That makes it very difficult for the user
to determine if PITR worked or not.

-- 
-David
da...@pgmasters.net


-- 
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

Re: [HACKERS] Confusing recovery message when target not hit

[Michael Paquier]

On Sat, Jun 11, 2016 at 9:44 AM, Thom Brown  wrote:
> It may be the wrong way of going about it, but you get the idea of what I'm
> suggesting we output instead.

Surely things could be better. So +1 to be more verbose here.

+if (recoveryStopTime == 0)
+snprintf(reason, sizeof(reason),
+"recovery reached consistency before recovery
target time of \"%s\"\n",
+timestamptz_to_str(recoveryTargetTime));
"Reaching consistency" is not exact for here. I'd rather say "finished
recovery without reaching target blah"

+if (recoveryStopXid == 0)
Checking for InvalidTransactionId is better here.

And it would be good to initialize recoveryStopTime and
recoveryStopXid as those are set only when a recovery target is
reached.
-- 
Michael


-- 
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

[HACKERS] Confusing recovery message when target not hit

[Thom Brown]

Hi all,

When recovery_target_time is set, but recovery finishes before it reaches
that time, it outputs "before 2000-01-01 00:00:00+00" to the .history
file.  This is because it uses recoveryStopTime, which is initialised to 0,
but is never set, and is then passed to timestamptz_to_str, which gives it
this date output.

A similar problem exists for recovery_target_xid.  When recovery finishes
before reaching the specified xid, it outputs "before transaction 0" to the
.history file, which is also confusing.

Could we produce something more meaningful?  I've attached a patch which
changes it to say 'recovery reached consistency before recovery target time
of ""' and 'recovery reached consistency before
recovery target xid of ""'.

It may be the wrong way of going about it, but you get the idea of what I'm
suggesting we output instead.

Thom
diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
index e4645a3..c68697a 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -7105,15 +7105,25 @@ StartupXLOG(void)
 		 * timeline changed.
 		 */
 		if (recoveryTarget == RECOVERY_TARGET_XID)
-			snprintf(reason, sizeof(reason),
-	 "%s transaction %u",
-	 recoveryStopAfter ? "after" : "before",
-	 recoveryStopXid);
+			if (recoveryStopXid == 0)
+snprintf(reason, sizeof(reason),
+		"recovery reached consistency before recovery target xid of \"%u\"\n",
+		recoveryTargetXid);
+			else
+snprintf(reason, sizeof(reason),
+		 "%s transaction %u",
+		 recoveryStopAfter ? "after" : "before",
+		 recoveryStopXid);
 		else if (recoveryTarget == RECOVERY_TARGET_TIME)
-			snprintf(reason, sizeof(reason),
-	 "%s %s\n",
-	 recoveryStopAfter ? "after" : "before",
-	 timestamptz_to_str(recoveryStopTime));
+			if (recoveryStopTime == 0)
+snprintf(reason, sizeof(reason),
+		"recovery reached consistency before recovery target time of \"%s\"\n",
+		timestamptz_to_str(recoveryTargetTime));
+			else
+snprintf(reason, sizeof(reason),
+		 "%s %s\n",
+		 recoveryStopAfter ? "after" : "before",
+		 timestamptz_to_str(recoveryStopTime));
 		else if (recoveryTarget == RECOVERY_TARGET_NAME)
 			snprintf(reason, sizeof(reason),
 	 "at restore point \"%s\"",

-- 
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers