Thread: Somewhat odd messages being logged on replicated server
I am playing with the replication on 9.0 and running into the following. I have a primary that is running at a colo, and is replicated down to a secondary here using SLONY. This is working normally. I decided to set up a replication of the SLONY secondary onto my "sandbox" machine to see what I think of it as a solution to potentially replace SLONY. All appears to be working fine, EXCEPT that I'm getting the following in the log. Sep 29 19:58:54 dbms2 postgres[8564]: [2-2] STATEMENT: update post set views = (select views from post where number='116763' and toppost='1') + 1 where number='116763' and toppost='1' Sep 29 20:01:11 dbms2 postgres[8581]: [2-1] ERROR: cannot execute UPDATE in a read-only transaction Sep 29 20:01:11 dbms2 postgres[8581]: [2-2] STATEMENT: update post set views = (select views from post where number='2040327' and toppost='1') + 1 where number='2040327' and toppost='1' Sep 29 20:02:02 dbms2 postgres[8582]: [2-1] ERROR: cannot execute UPDATE in a read-only transaction Sep 29 20:02:02 dbms2 postgres[8582]: [2-2] STATEMENT: update post set views = (select views from post where number='140406' and toppost='1') + 1 where number='140406' and toppost='1' Sep 29 20:04:58 dbms2 postgres[8586]: [2-1] ERROR: cannot execute UPDATE in a read-only transaction When I go look at the value of "views" on both the master and replicated slave, they have the same value..... so I'm not sure why the error is showing up. There are no clients attempting to connect to the replicated server at all at this point (I will enable that later once I'm satisfied that it is working in the general sense), so this has to be coming from the replication system itself. I presume that since the values are identical on both machines this can be safely ignored, but I'm curious why it's happening.... -- Karl
Attachment
On Wed, 2010-09-29 at 20:04 -0500, Karl Denninger wrote:
> Sep 29 19:58:54 dbms2 postgres[8564]: [2-2] STATEMENT: update post set
> views = (select views from post where number='116763' and toppost='1') +
> 1 where number='116763' and toppost='1'
> Sep 29 20:01:11 dbms2 postgres[8581]: [2-1] ERROR: cannot execute
> UPDATE in a read-only transaction
> Sep 29 20:01:11 dbms2 postgres[8581]: [2-2] STATEMENT: update post set
> views = (select views from post where number='2040327' and toppost='1')
> + 1 where number='2040327' and toppost='1'
> Sep 29 20:02:02 dbms2 postgres[8582]: [2-1] ERROR: cannot execute
> UPDATE in a read-only transaction
> Sep 29 20:02:02 dbms2 postgres[8582]: [2-2] STATEMENT: update post set
> views = (select views from post where number='140406' and toppost='1') +
> 1 where number='140406' and toppost='1'
> Sep 29 20:04:58 dbms2 postgres[8586]: [2-1] ERROR: cannot execute
> UPDATE in a read-only transaction
>
> When I go look at the value of "views" on both the master and replicated
> slave, they have the same value..... so I'm not sure why the error is
> showing up.
>
> There are no clients attempting to connect to the replicated server at
> all at this point (I will enable that later once I'm satisfied that it
> is working in the general sense), so this has to be coming from the
> replication system itself.
It looks very much like clients are connecting and issuing UPDATEs (or
trying to). Can you re-examine the situation? Perhaps try changing
pg_hba.conf to be sure nobody is connecting. 9.0-style replication
doesn't issue queries by itself.
Also, the UPDATEs look unsafe by themselves (replication or not). If two
such updates are executed simultaneously, "views" might not be updated
twice. Instead, try:
update post set views = views + 1
where number='140406' and toppost='1'
Regards,
Jeff Davis
On 9/29/2010 8:55 PM, Jeff Davis wrote: > On Wed, 2010-09-29 at 20:04 -0500, Karl Denninger wrote: >> Sep 29 19:58:54 dbms2 postgres[8564]: [2-2] STATEMENT: update post set >> views = (select views from post where number='116763' and toppost='1') + >> 1 where number='116763' and toppost='1' >> Sep 29 20:01:11 dbms2 postgres[8581]: [2-1] ERROR: cannot execute >> UPDATE in a read-only transaction >> Sep 29 20:01:11 dbms2 postgres[8581]: [2-2] STATEMENT: update post set >> views = (select views from post where number='2040327' and toppost='1') >> + 1 where number='2040327' and toppost='1' >> Sep 29 20:02:02 dbms2 postgres[8582]: [2-1] ERROR: cannot execute >> UPDATE in a read-only transaction >> Sep 29 20:02:02 dbms2 postgres[8582]: [2-2] STATEMENT: update post set >> views = (select views from post where number='140406' and toppost='1') + >> 1 where number='140406' and toppost='1' >> Sep 29 20:04:58 dbms2 postgres[8586]: [2-1] ERROR: cannot execute >> UPDATE in a read-only transaction >> >> When I go look at the value of "views" on both the master and replicated >> slave, they have the same value..... so I'm not sure why the error is >> showing up. >> >> There are no clients attempting to connect to the replicated server at >> all at this point (I will enable that later once I'm satisfied that it >> is working in the general sense), so this has to be coming from the >> replication system itself. > It looks very much like clients are connecting and issuing UPDATEs (or > trying to). Can you re-examine the situation? Perhaps try changing > pg_hba.conf to be sure nobody is connecting. 9.0-style replication > doesn't issue queries by itself. I'm VERY sure nobody is connecting - the machine in question is behind a firewall! In addition here's the netstat on it: $ netstat -a -n|more Active Internet connections (including servers) Proto Recv-Q Send-Q Local Address Foreign Address (state) tcp4 0 0 192.168.1.202.22 192.168.1.40.51232 ESTABLISHED tcp4 0 0 192.168.1.202.61119 192.168.1.201.5432 ESTABLISHED tcp4 0 0 *.5432 *.* LISTEN tcp6 0 0 *.5432 *.* LISTEN tcp4 0 0 *.514 *.* LISTEN tcp4 0 0 127.0.0.1.25 *.* LISTEN tcp4 0 0 *.22 *.* LISTEN tcp6 0 0 *.22 *.* LISTEN udp6 0 0 ::1.22165 ::1.22165 udp4 0 0 127.0.0.1.123 *.* udp6 0 0 ::1.123 *.* udp6 0 0 fe80:3::1.123 *.* udp4 0 0 192.168.1.202.123 *.* udp6 0 0 *.123 *.* udp4 0 0 *.123 *.* udp4 0 0 *.514 *.* udp6 0 0 *.514 *.* The only connection to a Postgresql server is to the master I am pulling the replication from (201) No other connections - the listener is there, but nobody's connected to it. > Also, the UPDATEs look unsafe by themselves (replication or not). If two > such updates are executed simultaneously, "views" might not be updated > twice. Instead, try: > > update post set views = views + 1 > where number='140406' and toppost='1' > > Regards, > Jeff Davis That's actually ok - the update itself is a legitimate statement on the master, posted to that table on a reply, and is part of a transaction. I thought logshipping like this over TCP would present the actual WAL changes (e.g. page changes) and was quite surprised when I saw what look very much like actual statements in the logfile. A process status also shows no postgres processes. All of the real application connections are on a machine 1200 miles away and behind pgpool, so if there WAS a connection it would be persistent. It's not there (never mind that the clients don't have an entry in pg_hba that would work, nor could they cross the firewall since there is no port forwarding in the firewall to allow it.) I'll investigate this further. -- Karl -- Karl
Attachment
On Wed, 2010-09-29 at 21:57 -0500, Karl Denninger wrote:
> That's actually ok - the update itself is a legitimate statement on the
> master, posted to that table on a reply, and is part of a transaction.
Even if it's part of a transaction, you still have a race condition,
unless you're using a serializable transcation isolation level.
> I thought logshipping like this over TCP would present the actual WAL
> changes (e.g. page changes) and was quite surprised when I saw what look
> very much like actual statements in the logfile. A process status also
> shows no postgres processes.
9.0-style replication only ships WAL. Those UPDATE statements are _not_
coming from the 9.0-style log shipping replication.
> All of the real application connections are on a machine 1200 miles away
> and behind pgpool, so if there WAS a connection it would be persistent.
> It's not there (never mind that the clients don't have an entry in
> pg_hba that would work, nor could they cross the firewall since there is
> no port forwarding in the firewall to allow it.)
>
Aha, you're using pgpool. The statements are probably coming from there
-- it's got a lot of options and it may be misconfigured.
Turn on some extended logging information that includes the client IP
address. That will probably give you some better insight.
Regards,
Jeff Davis