[pgpool-hackers: 4133] Re: invalid degenerate backend request, node id : 2 status: [2] is not valid for failover

[anirudh.goel at cern.ch]

Dear Tatsuo

I am not an expert on C programming, but if I understand correctly, applying this debugger patch would mean doing it on a fresh copy of the pgpool code, re-compiling it and then running another instance of pgpool from that new code. If that’s the procedure, I am afraid, we might not be able to reproduce the bug in that new instance as it is so infrequent.

Is there a way we can debug this or get these variables in runtime? I highly doubt it as I already tried increasing the log level to debug5 but couldn’t find anything related but I still want to ask because you might know of better alternatives.

If not, I will definitely try to run it in a fresh pgpool instance and leave the current buggy one running as it is. Just hoping for a better alternative.

Thank you

Anirudh
On 21 Feb 2022, 2:20 AM +0100, Tatsuo Ishii <ishii at sraoss.co.jp>, wrote:
> Hi Anirudh,
>
> > Hello Tatsuo
> >
> > Thank you so much for the explanation. I understand the problem but same as you, cannot understand the reason behind it. The same variable 'BACKEND_INFO(i).backend_status’ cannot have 2 different values. Maybe the VALID_BACKEND macro is false due to other checks that it has in its if else blocks. I am not sure. I will try to have a look.
>
> Maybe. It would be nice if you could attach debugger to the health check
> process which emits the log:
>
> > > > invalid degenerate backend request, node id : 2 status: [2] is not valid for failover
>
> then examin variables which may be related to the issue. One of them I am especially interested in these:
>
> (1)
> static POOL_SESSION_CONTEXT * session_context = NULL;
>
> The variable in the health check is expected to be NULL. If not, we have trouble.
>
>
> (2)
> BACKEND_STATUS private_backend_status[MAX_NUM_BACKENDS];
>
> This is the backend status copy from the shared memory area.
> This is expected to be 1 or 2 (CONN_CONNECT_WAIT or CON_UP).
>
> BTW, I need to correct my explanation.
>
> > > my_backend_status[(backend_id). The local variable is initialized at
> > > the pgpool main process (src/main/pgpool_main.c) and inherited via
> > > fork() to the health check process.
> > >
> > > /*
> > > * Initialize backend status area. From now on, VALID_BACKEND macro can be
> > > * used. (get_next_main_node() uses VALID_BACKEND)
> > > */
> > >
> > > for (i = 0; i < MAX_NUM_BACKENDS; i++)
> > > {
> > > my_backend_status[i] = &(BACKEND_INFO(i).backend_status);
> > > }
> > >
> > > As you can see actually my_backend_status stores the pointer to
> > > BACKEND_INFO(i).backend_status. So *(my_backend_status[(backend_id)
> > > should be same as BACKEND_INFO(backend_id).backend_status.
>
> Actually my_backend_status is not initialized like this. health check process calls this:
> /* Initialize my backend status */
> pool_initialize_private_backend_status();
>
> It copies backend status in the shared memory area to the process
> local memory. This is necessary for pgpool child process which deals
> with client session so that they are not bothered by the status
> changes in the shared memory area in the middle of process. BUT this
> is not necessary for health check process. I am going to fix this.
>
> However I don't think this can explain the issue. As long as there's
> no difference between the local variable and the shared memory in the
> life time, the bug does not do anything bad, and I cannot think of
> any scenario which could difference between the variables.
>
> > As for the reproducibility, you are right, in the past few months of development and testing, I have only seen this issue a couple times. Earlier, I thought it was something that I missed in the config but now that my setup is almost production ready, I opened this ticket for help. It is really difficult to reproduce but I currently have a setup running where this problem is persistent. I have tried by turning that replica off and on several times and it connects back to the cluster when it's up but I see the same error when it’s down.
> >
> > So, if you prefer I can help you investigate more on this by sharing some detailed logs and config options from my setup.
> >
> > Even though this issue comes up rarely, but this is important for me to resolve because my setup uses synchronous replication and if both of my replicas are down, I convert the replication mode from sync to async in the failover script. But if this bug shows up, then the failover script is not executed when the last replica goes down and my queries hang forever because they do not have a replica committing transactions in synchronous mode.
> >
> > So, if I can help you debug this by providing any logs or config or a direct access to my setup over a Zoom call, that’d be really great for me. Please let me know if this works for you.
>
> Thanks. Is it possible for you to apply attached patches so that
> pgpool produces additional log? (this will emit log whenever failover
> happens). The log basically emits information which can be obtained by
> debugger explained above.
>
> > Thank you
> >
> > Anirudh
> > On 19 Feb 2022, 2:33 AM +0100, Tatsuo Ishii <ishii at sraoss.co.jp>, wrote:
> > > > Hello
> > > >
> > > > I had the following setup:
> > > > 1 pgpool: 4.2.2
> > > > 3 postgres nodes (all 12.5) - 1 primary, 2 replicas
> > > >
> > > > I turned off both replicas one after the other with a difference of a couple seconds. Failover was performed for one of the replicas but not for the other. For the second replica the healthcheck keeps on failing but it just keeps on performing the healthcheck in an infinite loop. When pgpool attempts the failover of the second replica, I see this error in the logs:
> > > >
> > > > invalid degenerate backend request, node id : 2 status: [2] is not valid for failover
> > > >
> > > > As far as I understand, status [2] is up, so the failover should be performed. Here￠s a snippet of the logs:
> > >
> > > You are right. Problem is, two different internal APIs which both extract the status do not agree.
> > > The error messages comes from here:
> > > src/main/pool_internal_comms.c: degenerate_backend_set_ex()
> > >
> > > for (i = 0; i < count; i++)
> > > {
> > > if (node_id_set[i] < 0 || node_id_set[i] >= MAX_NUM_BACKENDS ||
> > > (!VALID_BACKEND(node_id_set[i]) && BACKEND_INFO(node_id_set[i]).quarantine == false))
> > > {
> > > if (node_id_set[i] < 0 || node_id_set[i] >= MAX_NUM_BACKENDS)
> > > ereport(elevel,
> > > (errmsg("invalid degenerate backend request, node id: %d is out of range. node id must be between [0 and %d]"
> > > ,node_id_set[i], MAX_NUM_BACKENDS)));
> > > else
> > > ereport(elevel,
> > > (errmsg("invalid degenerate backend request, node id : %d status: [%d] is not valid for failover"
> > > ,node_id_set[i], BACKEND_INFO(node_id_set[i]).backend_status)));
> > >
> > > I think VALID_BACKEND(node_id_set[i]) returned false
> > > here. VALID_BACKEND returns false if the backend status in the shared
> > > memory area is neither 1 (waiting for connection) nor 2 (up and
> > > running). However BACKEND_INFO(node_id_set[i]).backend_status says
> > > backend_status is actually 2 (up and running). The strange things is,
> > > both VALID_BACKEND and BACKEND_INFO(node_id_set[i]).backend_status
> > > look into the same shared memory area. Let me explain.
> > >
> > > VALID_BACKEND is a macron to be expanded as:
> > >
> > > #define VALID_BACKEND(backend_id) \
> > > ((RAW_MODE && (backend_id) == REAL_MAIN_NODE_ID) || \
> > > (pool_is_node_to_be_sent_in_current_query((backend_id)) && \
> > > ((*(my_backend_status[(backend_id)]) == CON_UP) || \
> > > (*(my_backend_status[(backend_id)]) == CON_CONNECT_WAIT))))
> > >
> > > Since you are running pgpool in other than RAW_MODE, the macro first
> > > checks if pool_is_node_to_be_sent_in_current_query((backend_id)
> > > returns true. Here is the portion of the code (defined in
> > > src/context/pool_query_context.c).
> > >
> > > bool
> > > pool_is_node_to_be_sent_in_current_query(int node_id)
> > > {
> > > POOL_SESSION_CONTEXT *sc;
> > >
> > > if (RAW_MODE)
> > > return node_id == REAL_MAIN_NODE_ID;
> > >
> > > As I said earlier, RAW_MODE returns false. So it executes next line:
> > >
> > > sc = pool_get_session_context(true);
> > > if (!sc)
> > > return true;
> > >
> > > pool_get_session_context() returns false and this function returns
> > > true because health check process did not use "sessoion context". The
> > > session context only exists on pgpool child process which deal with
> > > user connections.
> > >
> > > Then the macro checks local variable:
> > > my_backend_status[(backend_id). The local variable is initialized at
> > > the pgpool main process (src/main/pgpool_main.c) and inherited via
> > > fork() to the health check process.
> > >
> > > /*
> > > * Initialize backend status area. From now on, VALID_BACKEND macro can be
> > > * used. (get_next_main_node() uses VALID_BACKEND)
> > > */
> > >
> > > for (i = 0; i < MAX_NUM_BACKENDS; i++)
> > > {
> > > my_backend_status[i] = &(BACKEND_INFO(i).backend_status);
> > > }
> > >
> > > As you can see actually my_backend_status stores the pointer to
> > > BACKEND_INFO(i).backend_status. So *(my_backend_status[(backend_id)
> > > should be same as BACKEND_INFO(backend_id).backend_status.
> > >
> > > However, as I said earlier, it seems they seem to disagree. At this
> > > point I can't think of any explanation for this.
> > >
> > > How often do you see this problem? It's reliably reproduced?
> > > I was not able to reproduce this so far.
> > >
> > > Best reagards,
> > > --
> > > Tatsuo Ishii
> > > SRA OSS, Inc. Japan
> > > English: http://www.sraoss.co.jp/index_en.php
> > > Japanese:http://www.sraoss.co.jp
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://www.pgpool.net/pipermail/pgpool-hackers/attachments/20220221/6d9c2df8/attachment-0001.htm>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: failover_log.patch
Type: application/octet-stream
Size: 952 bytes
Desc: not available
URL: <http://www.pgpool.net/pipermail/pgpool-hackers/attachments/20220221/6d9c2df8/attachment-0001.obj>