<div>Thank you for the reply. </div><div><br></div><div>In the node 1 log, I dont find a "last completed transaction" line as you have in your example.</div><div><br></div><div>For this to happen, am I right to say that I need to rsync the files in pg_xlog (node 0) to my archive folder ( <span style="font-family:'courier new',monospace">/thumbnails/postgres_archives/ ) on node 1 ? My stage 2 script does not do that right now.</span></div>
<div><span style="font-family:'courier new',monospace"><br></span></div><div><span style="font-family:'courier new',monospace">I am not completely comfortable with what the files in pg_xlog contain exactly, at the various stages. Also, I find it strange that the log show many "</span>No such file or directory", even in your example.</div>
<div><br></div><div>Thanks</div><div><br></div><div>Gilbert</div><div><br></div><div>~~~~</div><div>LOg file for postgres on node 1 during recovery:</div><div><br></div><div><font face="courier new, monospace">2013-01-16 19:50:20 EST : LOG: database system was interrupted; last known up at 2013-01-16 19:50:16 EST</font></div>
<div><font face="courier new, monospace">2013-01-16 19:50:20 EST : LOG: starting archive recovery</font></div><div><font face="courier new, monospace">2013-01-16 19:50:20 EST : LOG: restore_command = 'cp /thumbnails/postgres_archives/pg_log/%f %p'</font></div>
<div><font face="courier new, monospace">2013-01-16 19:50:20 EST : DEBUG: executing restore command "cp /thumbnails/postgres_archives/pg_log/00000002.history pg_xlog/RECOVERYHISTORY"</font></div><div><font face="courier new, monospace">cp: cannot stat `/thumbnails/postgres_archives/pg_log/00000002.history': No such file or directory</font></div>
<div><font face="courier new, monospace">2013-01-16 19:50:20 EST : DEBUG: could not restore file "00000002.history" from archive: return code 256</font></div><div><font face="courier new, monospace">2013-01-16 19:50:20 EST : DEBUG: history of timeline 2 is (i 2 1)</font></div>
<div><font face="courier new, monospace">2013-01-16 19:50:20 EST : DEBUG: executing restore command "cp /thumbnails/postgres_archives/pg_log/00000002000000040000008D.00000020.backup pg_xlog/RECOVERY</font></div><div>
<font face="courier new, monospace">HISTORY"</font></div><div><font face="courier new, monospace">cp: cannot stat `/thumbnails/postgres_archives/pg_log/00000002000000040000008D.00000020.backup': No such file or directory</font></div>
<div><font face="courier new, monospace">2013-01-16 19:50:20 EST : DEBUG: could not restore file "00000002000000040000008D.00000020.backup" from archive: return code 256</font></div><div><font face="courier new, monospace">2013-01-16 19:50:20 EST : DEBUG: executing restore command "cp /thumbnails/postgres_archives/pg_log/00000002000000040000008D pg_xlog/RECOVERYXLOG"</font></div>
<div><font face="courier new, monospace">cp: cannot stat `/thumbnails/postgres_archives/pg_log/00000002000000040000008D': No such file or directory</font></div><div><font face="courier new, monospace">2013-01-16 19:50:20 EST : DEBUG: could not restore file "00000002000000040000008D" from archive: return code 256</font></div>
<div><font face="courier new, monospace">2013-01-16 19:50:20 EST : DEBUG: checkpoint record is at 4/8D000020</font></div><div><font face="courier new, monospace">2013-01-16 19:50:20 EST : DEBUG: redo record is at 4/8D000020; shutdown FALSE</font></div>
<div><font face="courier new, monospace">2013-01-16 19:50:20 EST : DEBUG: next transaction ID: 0/1625; next OID: 17797</font></div><div><font face="courier new, monospace">2013-01-16 19:50:20 EST : DEBUG: next MultiXactId: 1; next MultiXactOffset: 0</font></div>
<div><font face="courier new, monospace">2013-01-16 19:50:20 EST : LOG: automatic recovery in progress</font></div><div><font face="courier new, monospace">2013-01-16 19:50:20 EST : LOG: record with zero length at 4/8D000068</font></div>
<div><font face="courier new, monospace">2013-01-16 19:50:20 EST : LOG: redo is not required</font></div><div><font face="courier new, monospace">2013-01-16 19:50:20 EST : DEBUG: executing restore command "cp /thumbnails/postgres_archives/pg_log/00000002000000040000008D pg_xlog/RECOVERYXLOG"</font></div>
<div><font face="courier new, monospace">cp: cannot stat `/thumbnails/postgres_archives/pg_log/00000002000000040000008D': No such file or directory</font></div><div><font face="courier new, monospace">2013-01-16 19:50:20 EST : DEBUG: could not restore file "00000002000000040000008D" from archive: return code 256</font></div>
<div><font face="courier new, monospace">2013-01-16 19:50:20 EST : DEBUG: executing restore command "cp /thumbnails/postgres_archives/pg_log/00000003.history pg_xlog/RECOVERYHISTORY"</font></div><div><font face="courier new, monospace">2013-01-16 19:50:20 EST : LOG: restored log file "00000003.history" from archive</font></div>
<div><font face="courier new, monospace">2013-01-16 19:50:20 EST : DEBUG: executing restore command "cp /thumbnails/postgres_archives/pg_log/00000004.history pg_xlog/RECOVERYHISTORY"</font></div><div><font face="courier new, monospace">2013-01-16 19:50:20 EST : LOG: restored log file "00000004.history" from archive</font></div>
<div><font face="courier new, monospace">2013-01-16 19:50:20 EST : DEBUG: executing restore command "cp /thumbnails/postgres_archives/pg_log/00000005.history pg_xlog/RECOVERYHISTORY"</font></div><div><font face="courier new, monospace">2013-01-16 19:50:20 EST : LOG: restored log file "00000005.history" from archive</font></div>
<div><font face="courier new, monospace">2013-01-16 19:50:20 EST : DEBUG: executing restore command "cp /thumbnails/postgres_archives/pg_log/00000006.history pg_xlog/RECOVERYHISTORY"</font></div><div><font face="courier new, monospace">cp: cannot stat `/thumbnails/postgres_archives/pg_log/00000006.history': No such file or directory</font></div>
<div><font face="courier new, monospace">2013-01-16 19:50:20 EST : DEBUG: could not restore file "00000006.history" from archive: return code 256</font></div><div><font face="courier new, monospace">2013-01-16 19:50:20 EST : LOG: selected new timeline ID: 6</font></div>
<div><font face="courier new, monospace">2013-01-16 19:50:20 EST : DEBUG: executing restore command "cp /thumbnails/postgres_archives/pg_log/00000002.history pg_xlog/RECOVERYHISTORY"</font></div><div><font face="courier new, monospace">cp: cannot stat `/thumbnails/postgres_archives/pg_log/00000002.history': No such file or directory</font></div>
<div><font face="courier new, monospace">2013-01-16 19:50:20 EST : DEBUG: could not restore file "00000002.history" from archive: return code 256</font></div><div><font face="courier new, monospace">2013-01-16 19:50:20 EST : LOG: archive recovery complete</font></div>
<div><font face="courier new, monospace">2013-01-16 19:50:20 EST : DEBUG: recycled transaction log file "00000002000000040000008C"</font></div><div><font face="courier new, monospace">2013-01-16 19:50:20 EST : DEBUG: transaction ID wrap limit is 2147484295, limited by database "template1"</font></div>
<div><font face="courier new, monospace">2013-01-16 19:50:20 EST : DEBUG: shmem_exit(0): 3 callbacks to make</font></div><div><font face="courier new, monospace">2013-01-16 19:50:20 EST : DEBUG: proc_exit(0): 2 callbacks to make</font></div>
<div><font face="courier new, monospace">2013-01-16 19:50:20 EST : DEBUG: exit(0)</font></div><div><font face="courier new, monospace">2013-01-16 19:50:20 EST : DEBUG: shmem_exit(-1): 0 callbacks to make</font></div><div>
<font face="courier new, monospace">2013-01-16 19:50:20 EST : DEBUG: proc_exit(-1): 0 callbacks to make</font></div><div><font face="courier new, monospace">2013-01-16 19:50:20 EST : DEBUG: reaping dead processes</font></div>
<div><font face="courier new, monospace">2013-01-16 19:50:20 EST : LOG: autovacuum launcher started</font></div><div><font face="courier new, monospace">2013-01-16 19:50:20 EST : LOG: database system is ready to accept connections</font></div>
<div><br></div><br><div class="gmail_quote">On Wed, Jan 16, 2013 at 10:06 PM, Tatsuo Ishii <span dir="ltr"><<a href="mailto:ishii@postgresql.org" target="_blank">ishii@postgresql.org</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">
<div class="im">> Hello<br>
><br>
> I hope this is the place whee I can ask general questions about pgpool. I<br>
> could not find a forum. Otheriwse, please let me know where I should go to<br>
> get help<br>
<br>
</div>Yes, this is the perfect place to ask general questions about<br>
pgpool(there's no forum).<br>
<div class="im"><br>
> Here is my question:<br>
><br>
> I am trying to setup pgpool II with 2 postgres nodes using replication and<br>
> load balancing. I have setup the watch dog to switch the virtual IP<br>
> automatically in case of failure. The 2 postgres nodes run on 2 identical<br>
> computers.<br>
><br>
> Everything works fine except for the recovery which I dont quite undestand.<br>
> I have installed and configured the scripts:<br>
><br>
> basebackup.sh<br>
> pgpool_remote_start<br>
> pgpool_recovery_pitr<br>
><br>
><br>
> Then I simulate a failure : I shutdown one of the postgres nodes. This gets<br>
> detected fine and pgpool is still functional with the remaining node (which<br>
> can still accept connections).<br>
><br>
> When I try to recover, it does not work as I expected. I thought that we<br>
</div>> could recover *while pgpool keeps accepting requests*. (at least for stage<br>
<div class="im">> 1 of the recover). So, I simulated this by inserting a new line in a table<br>
</div>> of my database just before the end of the basebackup.sh script (just *after<br>
> * the rsync and *before* the pg_stop_backup() ).<br>
<div class="im">><br>
> So, my basebackup.sh script looks like:<br>
> ~~~~~~~~~~<br>
><br>
> ....<br>
><br>
</div>> *psql -U postgres -p 5432 -c "insert into users values (3000, 'def1');"<br>
<div class="im">> myDB # this line was added to basebackup.sh to simulate a transaction<br>
</div>> during a recover, stage 1 *<br>
<div class="im">><br>
> psql -U postgres -p 5432 -c "SELECT pg_stop_backup()" postgres<br>
> ~~~~~~~~~~~~<br>
><br>
> I then try to recover my failed node with:<br>
><br>
> /usr/local/bin/pcp_recovery_node -d 15 192.168.0.110 9898 pgpool pgpool 1<br>
><br>
> Which succeeds. However, when I look at the content of the databases, only<br>
> the master database has the new line "3000 test" (purposely added in my<br>
> basebackup.sh script). The recovered database has all other lines but not<br>
> this one. So the recovery is not complete in my opinion (or I dont<br>
> understand what it is supposed to do).<br>
><br>
> Am I wrong in expecting that this should work (i.e. after the recover, the<br>
> 2 database should be completely in sync) ?<br>
<br>
</div>Works fine for me. I guess you have problem with archive recovery<br>
setting of PostgreSQL.<br>
<br>
Below is my recovered PostgreSQL log. Do you find something like<br>
"restored log file "000000030000000100000021" from archive" in your<br>
PostgreSQL log(in your case DB node 1)?<br>
<br>
31055 2013-01-17 11:38:14 JST LOG: database system was interrupted; last known up at 2013-01-17 11:38:11 JST<br>
31055 2013-01-17 11:38:14 JST LOG: creating missing WAL directory "pg_xlog/archive_status"<br>
cp: cannot stat `/home/t-ishii/work/<a href="http://git.postgresql.org/test.repli/archivedir/00000003.history" target="_blank">git.postgresql.org/test.repli/archivedir/00000003.history</a>': No such file or directory<br>
31055 2013-01-17 11:38:14 JST LOG: starting archive recovery<br>
31055 2013-01-17 11:38:14 JST LOG: restored log file "000000030000000100000020" from archive<br>
31055 2013-01-17 11:38:14 JST LOG: redo starts at 1/20000020<br>
31055 2013-01-17 11:38:14 JST LOG: consistent recovery state reached at 1/21000000<br>
31053 2013-01-17 11:38:14 JST LOG: database system is ready to accept read only connections<br>
31055 2013-01-17 11:38:14 JST LOG: restored log file "000000030000000100000021" from archive<br>
cp: cannot stat `/home/t-ishii/work/<a href="http://git.postgresql.org/test.repli/archivedir/000000030000000100000022" target="_blank">git.postgresql.org/test.repli/archivedir/000000030000000100000022</a>': No such file or directory<br>
31055 2013-01-17 11:38:14 JST LOG: could not open file "pg_xlog/000000030000000100000022" (log file 1, segment 34): No such file or directory<br>
31055 2013-01-17 11:38:14 JST LOG: redo done at 1/21000E48<br>
31055 2013-01-17 11:38:14 JST LOG: last completed transaction was at log time 2013-01-17 11:38:12.376859+09<br>
31055 2013-01-17 11:38:14 JST LOG: restored log file "000000030000000100000021" from archive<br>
cp: cannot stat `/home/t-ishii/work/<a href="http://git.postgresql.org/test.repli/archivedir/00000004.history" target="_blank">git.postgresql.org/test.repli/archivedir/00000004.history</a>': No such file or directory<br>
31055 2013-01-17 11:38:14 JST LOG: selected new timeline ID: 4<br>
cp: cannot stat `/home/t-ishii/work/<a href="http://git.postgresql.org/test.repli/archivedir/00000003.history" target="_blank">git.postgresql.org/test.repli/archivedir/00000003.history</a>': No such file or directory<br>
31055 2013-01-17 11:38:15 JST LOG: archive recovery complete<br>
31053 2013-01-17 11:38:15 JST LOG: database system is ready to accept connections<br>
31067 2013-01-17 11:38:15 JST LOG: autovacuum launcher started<br>
--<br>
Tatsuo Ishii<br>
SRA OSS, Inc. Japan<br>
English: <a href="http://www.sraoss.co.jp/index_en.php" target="_blank">http://www.sraoss.co.jp/index_en.php</a><br>
Japanese: <a href="http://www.sraoss.co.jp" target="_blank">http://www.sraoss.co.jp</a><br>
</blockquote></div><br>