[Pgpool-general] pgpool continues to degenerate for no reason we can see

[John Black]

We have done more testing and pgpool continues to fail.  The master "fails"
and will degrade to the secondary server.

 Our setup is 2 databases (pg v8.1.4) on seperate machines with all db
connections connected via pgpool.

I have included the latest pgpool log here.  You can see where it fails on
the INSERT INTO "tblPaymentReceipts" line:

Do you know what would be causing this?  This is preventing us with using
pgpool.   Would pgpool II solve these problems?  I do not know what could be
causing these issues.

Any help is appreciated.

2006-09-29 15:47:01 DEBUG: pid 77906: I am 77906 accept fd 6
2006-09-29 15:47:01 DEBUG: pid 77906: Protocol Major: 1234 Minor: 5679
database:  user:
2006-09-29 15:47:01 DEBUG: pid 77906: SSLRequest: sent N; retry startup
2006-09-29 15:47:01 DEBUG: pid 77906: Protocol Major: 3 Minor: 0 database:
ba_unicode user: john
2006-09-29 15:47:01 DEBUG: pid 77906: connecting postmaster Unix domain
socket: /tmp/.s.PGSQL.5432
2006-09-29 15:47:01 DEBUG: pid 77906: connected to postmaster Unix domain
socket: /tmp/.s.PGSQL.5432 fd: 7
2006-09-29 15:47:01 DEBUG: pid 77906: pool_read_message_length: lenghth: 8
2006-09-29 15:47:01 DEBUG: pid 77906: pool_read_message_length2: master
lenghth: 25
2006-09-29 15:47:01 DEBUG: pid 77906: name: client_encoding value: UTF8
2006-09-29 15:47:01 DEBUG: pid 77906: secondary name: client_encoding value:
UTF8
2006-09-29 15:47:01 DEBUG: pid 77906: pool_read_message_length2: master
lenghth: 23
2006-09-29 15:47:01 DEBUG: pid 77906: name: DateStyle value: ISO, MDY
2006-09-29 15:47:01 DEBUG: pid 77906: secondary name: DateStyle value: ISO,
MDY
2006-09-29 15:47:01 DEBUG: pid 77906: pool_read_message_length2: master
lenghth: 26
2006-09-29 15:47:01 DEBUG: pid 77906: name: integer_datetimes value: off
2006-09-29 15:47:01 DEBUG: pid 77906: secondary name: integer_datetimes
value: off
2006-09-29 15:47:01 DEBUG: pid 77906: pool_read_message_length2: master
lenghth: 20
2006-09-29 15:47:01 DEBUG: pid 77906: name: is_superuser value: on
2006-09-29 15:47:01 DEBUG: pid 77906: secondary name: is_superuser value: on
2006-09-29 15:47:01 DEBUG: pid 77906: pool_read_message_length2: master
lenghth: 25
2006-09-29 15:47:01 DEBUG: pid 77906: name: server_encoding value: UTF8
2006-09-29 15:47:01 DEBUG: pid 77906: secondary name: server_encoding value:
UTF8
2006-09-29 15:47:01 DEBUG: pid 77906: pool_read_message_length2: master
lenghth: 25
2006-09-29 15:47:01 DEBUG: pid 77906: name: server_version value: 8.1.4
2006-09-29 15:47:01 DEBUG: pid 77906: secondary name: server_version value:
8.1.4
2006-09-29 15:47:01 DEBUG: pid 77906: pool_read_message_length2: master
lenghth: 33
2006-09-29 15:47:01 DEBUG: pid 77906: name: session_authorization value:
john
2006-09-29 15:47:01 DEBUG: pid 77906: secondary name: session_authorization
value: john
2006-09-29 15:47:01 DEBUG: pid 77906: pool_read_message_length2: master
lenghth: 36
2006-09-29 15:47:01 DEBUG: pid 77906: name: standard_conforming_strings
value: off
2006-09-29 15:47:01 DEBUG: pid 77906: secondary name:
standard_conforming_strings value: off
2006-09-29 15:47:01 DEBUG: pid 77906: pool_read_message_length2: master
lenghth: 21
2006-09-29 15:47:01 DEBUG: pid 77906: name: TimeZone value: PST8PDT
2006-09-29 15:47:01 DEBUG: pid 77906: secondary name: TimeZone value:
PST8PDT
2006-09-29 15:47:01 DEBUG: pid 77906: pool_read_message_length: lenghth: 12
2006-09-29 15:47:01 DEBUG: pid 77906: pool_send_auth_ok: send pid 3911 to
frontend
2006-09-29 15:47:01 DEBUG: pid 77906: read kind from backend pending data Z
len: 5 po: 265
2006-09-29 15:47:01 DEBUG: pid 77906: pool_process_query: kind from backend:
Z
2006-09-29 15:47:01 DEBUG: pid 77906: pool_read_message_length: lenghth: 5
2006-09-29 15:47:01 DEBUG: pid 77906: ReadyForQuery: message length: 5
2006-09-29 15:47:01 DEBUG: pid 77906: ReadyForQuery: transaction state: I
2006-09-29 15:47:01 DEBUG: pid 81934: I am 81934 accept fd 6
2006-09-29 15:47:01 DEBUG: pid 81934: Protocol Major: 1234 Minor: 5679
database:  user:
2006-09-29 15:47:01 DEBUG: pid 81934: SSLRequest: sent N; retry startup
2006-09-29 15:47:01 DEBUG: pid 81934: Protocol Major: 3 Minor: 0 database:
babilling_unicode user: john
2006-09-29 15:47:01 DEBUG: pid 81934: connecting postmaster Unix domain
socket: /tmp/.s.PGSQL.5432
2006-09-29 15:47:01 DEBUG: pid 81934: connected to postmaster Unix domain
socket: /tmp/.s.PGSQL.5432 fd: 7
2006-09-29 15:47:01 DEBUG: pid 81934: pool_read_message_length: lenghth: 8
2006-09-29 15:47:01 DEBUG: pid 81934: pool_read_message_length2: master
lenghth: 25
2006-09-29 15:47:01 DEBUG: pid 81934: name: client_encoding value: UTF8
2006-09-29 15:47:01 DEBUG: pid 81934: secondary name: client_encoding value:
UTF8
2006-09-29 15:47:01 DEBUG: pid 81934: pool_read_message_length2: master
lenghth: 23
2006-09-29 15:47:01 DEBUG: pid 81934: name: DateStyle value: ISO, MDY
2006-09-29 15:47:01 DEBUG: pid 81934: secondary name: DateStyle value: ISO,
MDY
2006-09-29 15:47:01 DEBUG: pid 81934: pool_read_message_length2: master
lenghth: 26
2006-09-29 15:47:01 DEBUG: pid 81934: name: integer_datetimes value: off
2006-09-29 15:47:01 DEBUG: pid 81934: secondary name: integer_datetimes
value: off
2006-09-29 15:47:01 DEBUG: pid 81934: pool_read_message_length2: master
lenghth: 20
2006-09-29 15:47:01 DEBUG: pid 81934: name: is_superuser value: on
2006-09-29 15:47:01 DEBUG: pid 81934: secondary name: is_superuser value: on
2006-09-29 15:47:01 DEBUG: pid 81934: pool_read_message_length2: master
lenghth: 25
2006-09-29 15:47:01 DEBUG: pid 81934: name: server_encoding value: UTF8
2006-09-29 15:47:01 DEBUG: pid 81934: secondary name: server_encoding value:
UTF8
2006-09-29 15:47:01 DEBUG: pid 81934: pool_read_message_length2: master
lenghth: 25
2006-09-29 15:47:01 DEBUG: pid 81934: name: server_version value: 8.1.4
2006-09-29 15:47:01 DEBUG: pid 81934: secondary name: server_version value:
8.1.4
2006-09-29 15:47:01 DEBUG: pid 81934: pool_read_message_length2: master
lenghth: 33
2006-09-29 15:47:01 DEBUG: pid 81934: name: session_authorization value:
john
2006-09-29 15:47:01 DEBUG: pid 81934: secondary name: session_authorization
value: john
2006-09-29 15:47:01 DEBUG: pid 81934: pool_read_message_length2: master
lenghth: 36
2006-09-29 15:47:01 DEBUG: pid 81934: name: standard_conforming_strings
value: off
2006-09-29 15:47:01 DEBUG: pid 81934: secondary name:
standard_conforming_strings value: off
2006-09-29 15:47:01 DEBUG: pid 81934: pool_read_message_length2: master
lenghth: 21
2006-09-29 15:47:01 DEBUG: pid 81934: name: TimeZone value: PST8PDT
2006-09-29 15:47:01 DEBUG: pid 81934: secondary name: TimeZone value:
PST8PDT
2006-09-29 15:47:01 DEBUG: pid 81934: pool_read_message_length: lenghth: 12
2006-09-29 15:47:01 DEBUG: pid 81934: pool_send_auth_ok: send pid 3912 to
frontend
2006-09-29 15:47:01 DEBUG: pid 81934: read kind from backend pending data Z
len: 5 po: 265
2006-09-29 15:47:01 DEBUG: pid 81934: pool_process_query: kind from backend:
Z
2006-09-29 15:47:01 DEBUG: pid 81934: pool_read_message_length: lenghth: 5
2006-09-29 15:47:01 DEBUG: pid 81934: ReadyForQuery: message length: 5
2006-09-29 15:47:01 DEBUG: pid 81934: ReadyForQuery: transaction state: I
2006-09-29 15:47:01 DEBUG: pid 81934: read kind from frontend Q(51)
2006-09-29 15:47:01 DEBUG: pid 81934: statement: SELECT DISTINCT
2006-09-29 15:47:01 DEBUG: pid 81934: start_load_balance: selected master is
0
2006-09-29 15:47:01 DEBUG: pid 81934: read kind from backend T
2006-09-29 15:47:01 DEBUG: pid 81934: pool_process_query: kind from backend:
T
2006-09-29 15:47:01 DEBUG: pid 81934: read kind from backend pending data D
len: 292 po: 721
2006-09-29 15:47:01 DEBUG: pid 81934: pool_process_query: kind from backend:
D
2006-09-29 15:47:01 DEBUG: pid 81934: read kind from backend pending data C
len: 17 po: 996
2006-09-29 15:47:01 DEBUG: pid 81934: pool_process_query: kind from backend:
C
2006-09-29 15:47:01 DEBUG: pid 81934: read kind from backend pending data Z
len: 5 po: 1008
2006-09-29 15:47:01 DEBUG: pid 81934: pool_process_query: kind from backend:
Z
2006-09-29 15:47:01 DEBUG: pid 81934: pool_read_message_length: lenghth: 5
2006-09-29 15:47:01 DEBUG: pid 81934: ReadyForQuery: message length: 5
2006-09-29 15:47:01 DEBUG: pid 81934: ReadyForQuery: transaction state: I
2006-09-29 15:47:01 DEBUG: pid 81934: end_load_balance: end load balance
mode
2006-09-29 15:47:01 DEBUG: pid 84352: pool_backend_timer_handler called at
1159570021
2006-09-29 15:47:01 DEBUG: pid 84352: pool_backend_timer_handler: expire
time: 1159570021
2006-09-29 15:47:01 DEBUG: pid 84352: pool_backend_timer_handler: expires
user pgsql database ba_unicode
2006-09-29 15:47:01 DEBUG: pid 97035: pool_backend_timer_handler called at
1159570021
2006-09-29 15:47:01 DEBUG: pid 97035: pool_backend_timer_handler: expire
time: 1159570021
2006-09-29 15:47:01 DEBUG: pid 97035: pool_backend_timer_handler: expires
user john database ba_unicode
2006-09-29 15:47:01 DEBUG: pid 87215: pool_backend_timer_handler called at
1159570021
2006-09-29 15:47:01 DEBUG: pid 87215: pool_backend_timer_handler: expire
time: 1159570021
2006-09-29 15:47:01 DEBUG: pid 87215: pool_backend_timer_handler: expires
user john database ba_unicode
2006-09-29 15:47:02 DEBUG: pid 60881: pool_backend_timer_handler called at
1159570022
2006-09-29 15:47:02 DEBUG: pid 60881: pool_backend_timer_handler: expire
time: 1159570022
2006-09-29 15:47:02 DEBUG: pid 60881: pool_backend_timer_handler: expires
user pgsql database ba_unicode
2006-09-29 15:47:02 DEBUG: pid 60901: pool_backend_timer_handler called at
1159570022
2006-09-29 15:47:02 DEBUG: pid 60901: pool_backend_timer_handler: expire
time: 1159570022
2006-09-29 15:47:02 DEBUG: pid 60901: pool_backend_timer_handler: expires
user pgsql database ba_unicode
2006-09-29 15:47:05 DEBUG: pid 81934: read kind from frontend Q(51)
2006-09-29 15:47:05 DEBUG: pid 81934: statement: INSERT INTO
"tblPaymentReceipts"
2006-09-29 15:47:05 DEBUG: pid 81934: waiting for master completing the
query
2006-09-29 15:47:05 DEBUG: pid 81934: read kind from backend C
2006-09-29 15:47:05 DEBUG: pid 81934: read kind from secondary backend E
2006-09-29 15:47:05 ERROR: pid 81934: pool_process_query: kind does not
match between backends master(C) secondary(E)
2006-09-29 15:47:05 DEBUG: pid 81934: connecting postmaster Unix domain
socket: /tmp/.s.PGSQL.5432
2006-09-29 15:47:05 DEBUG: pid 81934: connected to postmaster Unix domain
socket: /tmp/.s.PGSQL.5432 fd: 9
2006-09-29 15:47:05 LOG:   pid 81934: notice_backend_error: master: 1 fail
over request from pid 81934
2006-09-29 15:47:05 DEBUG: pid 60879: failover_handler called
2006-09-29 15:47:05 LOG:   pid 60879: starting degeneration. shutdown master
host (5432)
2006-09-29 15:47:05 DEBUG: pid 87215: child receives shutdown request signal
3
2006-09-29 15:47:05 DEBUG: pid 60879: kill 87215
2006-09-29 15:47:05 DEBUG: pid 60881: child receives shutdown request signal
3
2006-09-29 15:47:05 DEBUG: pid 60879: kill 60881
2006-09-29 15:47:05 DEBUG: pid 71962: child receives shutdown request signal
3
2006-09-29 15:47:05 DEBUG: pid 60879: kill 71962
2006-09-29 15:47:05 DEBUG: pid 87834: child receives shutdown request signal
3
2006-09-29 15:47:05 DEBUG: pid 60879: kill 87834
2006-09-29 15:47:05 DEBUG: pid 60879: kill 94562
2006-09-29 15:47:05 DEBUG: pid 91700: child receives shutdown request signal
3
2006-09-29 15:47:05 DEBUG: pid 60879: kill 91700
2006-09-29 15:47:05 DEBUG: pid 96016: child receives shutdown request signal
3
2006-09-29 15:47:05 DEBUG: pid 60879: kill 96016
2006-09-29 15:47:05 DEBUG: pid 60879: kill 81934
2006-09-29 15:47:05 DEBUG: pid 87137: child receives shutdown request signal
3
2006-09-29 15:47:05 DEBUG: pid 60879: kill 87137
2006-09-29 15:47:05 DEBUG: pid 92520: child receives shutdown request signal
3
2006-09-29 15:47:05 DEBUG: pid 60879: kill 92520
2006-09-29 15:47:05 DEBUG: pid 60879: kill 93542
2006-09-29 15:47:05 DEBUG: pid 97035: child receives shutdown request signal
3
2006-09-29 15:47:05 DEBUG: pid 60879: kill 97035
2006-09-29 15:47:05 DEBUG: pid 70511: child receives shutdown request signal
3
2006-09-29 15:47:05 DEBUG: pid 60879: kill 70511
2006-09-29 15:47:05 DEBUG: pid 60879: kill 1331
2006-09-29 15:47:05 DEBUG: pid 82973: child receives shutdown request signal
3
2006-09-29 15:47:05 DEBUG: pid 1331: child receives shutdown request signal
3
2006-09-29 15:47:05 DEBUG: pid 60879: kill 82973
2006-09-29 15:47:05 DEBUG: pid 99947: child receives shutdown request signal
3
2006-09-29 15:47:05 DEBUG: pid 60879: kill 99947
2006-09-29 15:47:05 DEBUG: pid 63135: child receives shutdown request signal
3
2006-09-29 15:47:05 DEBUG: pid 60879: kill 63135
2006-09-29 15:47:05 DEBUG: pid 60879: kill 93193
2006-09-29 15:47:05 DEBUG: pid 97738: child receives shutdown request signal
3
2006-09-29 15:47:05 DEBUG: pid 60879: kill 97738
2006-09-29 15:47:05 DEBUG: pid 97364: child receives shutdown request signal
3
2006-09-29 15:47:05 DEBUG: pid 60879: kill 97364
2006-09-29 15:47:05 DEBUG: pid 60879: kill 94138
2006-09-29 15:47:05 DEBUG: pid 60901: child receives shutdown request signal
3
2006-09-29 15:47:05 DEBUG: pid 60879: kill 60901
2006-09-29 15:47:05 DEBUG: pid 77872: child receives shutdown request signal
3
2006-09-29 15:47:05 DEBUG: pid 60879: kill 77872
2006-09-29 15:47:05 DEBUG: pid 60879: kill 77906
2006-09-29 15:47:05 DEBUG: pid 71951: child receives shutdown request signal
3
2006-09-29 15:47:05 DEBUG: pid 60879: kill 71951
2006-09-29 15:47:05 DEBUG: pid 60905: child receives shutdown request signal
3
2006-09-29 15:47:05 DEBUG: pid 60879: kill 60905
2006-09-29 15:47:05 DEBUG: pid 60906: child receives shutdown request signal
3
2006-09-29 15:47:05 DEBUG: pid 60879: kill 60906
2006-09-29 15:47:05 DEBUG: pid 77898: child receives shutdown request signal
3
2006-09-29 15:47:05 DEBUG: pid 60879: kill 77898
2006-09-29 15:47:05 DEBUG: pid 84352: child receives shutdown request signal
3
2006-09-29 15:47:05 DEBUG: pid 60879: kill 84352
2006-09-29 15:47:05 DEBUG: pid 97098: child receives shutdown request signal
3
2006-09-29 15:47:05 DEBUG: pid 60879: kill 97098
2006-09-29 15:47:05 DEBUG: pid 79632: child receives shutdown request signal
3
2006-09-29 15:47:05 DEBUG: pid 60879: kill 79632
2006-09-29 15:47:05 DEBUG: pid 91570: child receives shutdown request signal
3
2006-09-29 15:47:05 DEBUG: pid 60879: kill 91570
2006-09-29 15:47:05 DEBUG: pid 81934: child receives shutdown request signal
3
2006-09-29 15:47:05 DEBUG: pid 94562: child receives shutdown request signal
3
2006-09-29 15:47:05 DEBUG: pid 93193: child receives shutdown request signal
3
2006-09-29 15:47:05 DEBUG: pid 94138: child receives shutdown request signal
3
2006-09-29 15:47:05 DEBUG: pid 77906: child receives shutdown request signal
3
2006-09-29 15:47:05 DEBUG: pid 93542: child receives shutdown request signal
3
2006-09-29 15:47:05 DEBUG: pid 3914: I am 3914
2006-09-29 15:47:05 DEBUG: pid 3915: I am 3915
2006-09-29 15:47:05 DEBUG: pid 3916: I am 3916
2006-09-29 15:47:05 DEBUG: pid 3917: I am 3917
2006-09-29 15:47:05 DEBUG: pid 3921: I am 3921
2006-09-29 15:47:05 DEBUG: pid 3918: I am 3918
2006-09-29 15:47:05 DEBUG: pid 3919: I am 3919
2006-09-29 15:47:05 DEBUG: pid 3920: I am 3920
2006-09-29 15:47:05 LOG:   pid 60879: degeneration done. shutdown master
host (5432)
2006-09-29 15:47:05 DEBUG: pid 60879: reap_handler called
2006-09-29 15:47:05 DEBUG: pid 3922: I am 3922
2006-09-29 15:47:05 DEBUG: pid 3923: I am 3923
2006-09-29 15:47:05 DEBUG: pid 3924: I am 3924
2006-09-29 15:47:05 DEBUG: pid 3925: I am 3925
2006-09-29 15:47:05 DEBUG: pid 3926: I am 3926
2006-09-29 15:47:05 DEBUG: pid 3927: I am 3927
2006-09-29 15:47:05 DEBUG: pid 3928: I am 3928
2006-09-29 15:47:05 DEBUG: pid 3929: I am 3929
2006-09-29 15:47:05 DEBUG: pid 3930: I am 3930
2006-09-29 15:47:05 DEBUG: pid 3931: I am 3931
2006-09-29 15:47:05 DEBUG: pid 3945: I am 3945
2006-09-29 15:47:05 DEBUG: pid 3932: I am 3932
2006-09-29 15:47:05 DEBUG: pid 3933: I am 3933
2006-09-29 15:47:05 DEBUG: pid 3934: I am 3934
2006-09-29 15:47:05 DEBUG: pid 3935: I am 3935
2006-09-29 15:47:05 DEBUG: pid 3936: I am 3936
2006-09-29 15:47:05 DEBUG: pid 3937: I am 3937
2006-09-29 15:47:05 DEBUG: pid 3938: I am 3938
2006-09-29 15:47:05 DEBUG: pid 3939: I am 3939
2006-09-29 15:47:05 DEBUG: pid 3940: I am 3940
2006-09-29 15:47:05 DEBUG: pid 3941: I am 3941
2006-09-29 15:47:05 DEBUG: pid 3942: I am 3942
2006-09-29 15:47:05 DEBUG: pid 3943: I am 3943
2006-09-29 15:47:05 DEBUG: pid 3944: I am 3944
2006-09-29 15:47:05 DEBUG: pid 3914: I am 3914 accept fd 6
2006-09-29 15:47:05 DEBUG: pid 3914: Protocol Major: 1234 Minor: 5679
database:  user:
2006-09-29 15:47:05 DEBUG: pid 3914: SSLRequest: sent N; retry startup
2006-09-29 15:47:05 DEBUG: pid 3914: Protocol Major: 3 Minor: 0 database:
ba_unicode user: pgsql
2006-09-29 15:47:05 DEBUG: pid 3914: pool_read_message_length: lenghth: 8
2006-09-29 15:47:05 DEBUG: pid 3914: pool_read_message_length2: master
lenghth: 25
2006-09-29 15:47:05 DEBUG: pid 3914: name: client_encoding value: UTF8
2006-09-29 15:47:05 DEBUG: pid 3914: pool_read_message_length2: master
lenghth: 23
2006-09-29 15:47:05 DEBUG: pid 3914: name: DateStyle value: ISO, MDY
2006-09-29 15:47:05 DEBUG: pid 3914: pool_read_message_length2: master
lenghth: 26
2006-09-29 15:47:05 DEBUG: pid 3914: name: integer_datetimes value: off
2006-09-29 15:47:05 DEBUG: pid 3914: pool_read_message_length2: master
lenghth: 20
2006-09-29 15:47:05 DEBUG: pid 3914: name: is_superuser value: on
2006-09-29 15:47:05 DEBUG: pid 3914: pool_read_message_length2: master
lenghth: 25
2006-09-29 15:47:05 DEBUG: pid 3914: name: server_encoding value: UTF8
2006-09-29 15:47:05 DEBUG: pid 3914: pool_read_message_length2: master
lenghth: 25
2006-09-29 15:47:05 DEBUG: pid 3914: name: server_version value: 8.1.4
2006-09-29 15:47:05 DEBUG: pid 3914: pool_read_message_length2: master
lenghth: 32
2006-09-29 15:47:05 DEBUG: pid 3914: name: session_authorization value:
pgsql
2006-09-29 15:47:05 DEBUG: pid 3914: pool_read_message_length2: master
lenghth: 36
2006-09-29 15:47:05 DEBUG: pid 3914: name: standard_conforming_strings
value: off
2006-09-29 15:47:05 DEBUG: pid 3914: pool_read_message_length2: master
lenghth: 21
2006-09-29 15:47:05 DEBUG: pid 3914: name: TimeZone value: PST8PDT
2006-09-29 15:47:05 DEBUG: pid 3914: pool_read_message_length: lenghth: 12
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://pgfoundry.org/pipermail/pgpool-general/attachments/20061002/4dd6a80c/attachment-0001.html