Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

WIP: Make remote reads asynchronous #3633

Draft
wants to merge 6 commits into
base: main
Choose a base branch
from

Conversation

clumens
Copy link
Contributor

@clumens clumens commented Sep 3, 2024

I've been working through the comments in T855 and everything's been pretty easy up to the lrmd_tls_dispatch patch. When running the RemoteMigrate test in cts-lab, I'm seeing this:

Sep 03 12:01:41.043 rhel9-ctslab-1 pacemaker-controld  [60448] (lrmd_tls_dispatch_async@lrmd_client.c:490)      trace: TLS dispatch triggered
Sep 03 12:01:41.043 rhel9-ctslab-1 pacemaker-controld  [60448] (lrmd_tls_dispatch_async@lrmd_client.c:498)      info: BEFORE REMOTE READY
Sep 03 12:01:41.043 rhel9-ctslab-1 pacemaker-controld  [60448] (lrmd_tls_dispatch_async@lrmd_client.c:500)      info: AFTER REMOTE READY
Sep 03 12:01:41.043 rhel9-ctslab-1 pacemaker-controld  [60448] (lrmd_tls_dispatch_async@lrmd_client.c:503)      info: READY SAID OK
Sep 03 12:01:41.043 rhel9-ctslab-1 pacemaker-controld  [60448] (lrmd_tls_dispatch_async@lrmd_client.c:519)      info: BEFORE READ AVAIL
Sep 03 12:01:41.043 rhel9-ctslab-1 pacemaker-controld  [60448] (lrmd_tls_dispatch_async@lrmd_client.c:521)      info: AFTER READ AVAIL
Sep 03 12:01:41.043 rhel9-ctslab-1 pacemaker-controld  [60448] (lrmd_tls_dispatch_async@lrmd_client.c:529)      info: READ SAID AGAIN
Sep 03 12:01:41.045 rhel9-ctslab-1 pacemaker-schedulerd[60447] ([email protected]:1747)  info: rhel9-ctslab-1 is active
Sep 03 12:01:41.045 rhel9-ctslab-1 pacemaker-schedulerd[60447] ([email protected]:1911)  info: rhel9-ctslab-1 is online
Sep 03 12:01:41.045 rhel9-ctslab-1 pacemaker-schedulerd[60447] ([email protected]:1747)  info: rhel9-ctslab-2 is active
Sep 03 12:01:41.045 rhel9-ctslab-1 pacemaker-schedulerd[60447] ([email protected]:1911)  info: rhel9-ctslab-2 is online
Sep 03 12:01:41.048 rhel9-ctslab-1 pacemaker-schedulerd[60447] (pcmk__unassign_resource@pcmk_sched_resource.c:548)      info: Unassigning remote-rhel9-ctslab-3
Sep 03 12:01:41.048 rhel9-ctslab-1 pacemaker-schedulerd[60447] (pcmk__unassign_resource@pcmk_sched_resource.c:548)      info: Unassigning Fencing
Sep 03 12:01:41.048 rhel9-ctslab-1 pacemaker-schedulerd[60447] (pcmk__unassign_resource@pcmk_sched_resource.c:548)      info: Unassigning FencingFail
Sep 03 12:01:41.048 rhel9-ctslab-1 pacemaker-schedulerd[60447] (pcmk__unassign_resource@pcmk_sched_resource.c:548)      info: Unassigning rsc_rhel9-ctslab-1
Sep 03 12:01:41.048 rhel9-ctslab-1 pacemaker-schedulerd[60447] (pcmk__unassign_resource@pcmk_sched_resource.c:548)      info: Unassigning rsc_rhel9-ctslab-2
Sep 03 12:01:41.048 rhel9-ctslab-1 pacemaker-schedulerd[60447] (pcmk__unassign_resource@pcmk_sched_resource.c:548)      info: Unassigning rsc_rhel9-ctslab-3
Sep 03 12:01:41.048 rhel9-ctslab-1 pacemaker-schedulerd[60447] (pcmk__unassign_resource@pcmk_sched_resource.c:548)      info: Unassigning migrator
Sep 03 12:01:41.048 rhel9-ctslab-1 pacemaker-schedulerd[60447] (pcmk__unassign_resource@pcmk_sched_resource.c:548)      info: Unassigning ping-1:0
Sep 03 12:01:41.048 rhel9-ctslab-1 pacemaker-schedulerd[60447] (pcmk__unassign_resource@pcmk_sched_resource.c:548)      info: Unassigning ping-1:1
Sep 03 12:01:41.048 rhel9-ctslab-1 pacemaker-schedulerd[60447] (pcmk__unassign_resource@pcmk_sched_resource.c:548)      info: Unassigning ping-1:2
Sep 03 12:01:41.048 rhel9-ctslab-1 pacemaker-schedulerd[60447] (pcmk__unassign_resource@pcmk_sched_resource.c:548)      info: Unassigning ping-1:3
Sep 03 12:01:41.048 rhel9-ctslab-1 pacemaker-schedulerd[60447] (pcmk__primitive_assign@pcmk_sched_primitive.c:542)      info: Resource ping-1:3 cannot run anywhere
Sep 03 12:01:41.048 rhel9-ctslab-1 pacemaker-schedulerd[60447] (pcmk__unassign_resource@pcmk_sched_resource.c:548)      info: Unassigning stateful-1:0
Sep 03 12:01:41.048 rhel9-ctslab-1 pacemaker-schedulerd[60447] (pcmk__unassign_resource@pcmk_sched_resource.c:548)      info: Unassigning stateful-1:1
Sep 03 12:01:41.048 rhel9-ctslab-1 pacemaker-schedulerd[60447] (pcmk__unassign_resource@pcmk_sched_resource.c:548)      info: Unassigning stateful-1:2
Sep 03 12:01:41.048 rhel9-ctslab-1 pacemaker-schedulerd[60447] (pcmk__primitive_assign@pcmk_sched_primitive.c:542)      info: Resource stateful-1:2 cannot run anywhere
Sep 03 12:01:41.048 rhel9-ctslab-1 pacemaker-schedulerd[60447] (set_instance_role@pcmk_sched_promotable.c:1065)         info: Choosing stateful-1:0 (Promoted) on rhel9-ctslab-1 for promotion
Sep 03 12:01:41.048 rhel9-ctslab-1 pacemaker-schedulerd[60447] (pcmk__set_instance_roles@pcmk_sched_promotable.c:1097)  info: promotable-1: Promoted 1 instances of a possible 1
Sep 03 12:01:41.048 rhel9-ctslab-1 pacemaker-schedulerd[60447] (pcmk__unassign_resource@pcmk_sched_resource.c:548)      info: Unassigning r192.168.122.204
Sep 03 12:01:41.048 rhel9-ctslab-1 pacemaker-schedulerd[60447] (pcmk__unassign_resource@pcmk_sched_resource.c:548)      info: Unassigning petulant
Sep 03 12:01:41.048 rhel9-ctslab-1 pacemaker-schedulerd[60447] (pcmk__unassign_resource@pcmk_sched_resource.c:548)      info: Unassigning r192.168.122.205
Sep 03 12:01:41.048 rhel9-ctslab-1 pacemaker-schedulerd[60447] (pcmk__unassign_resource@pcmk_sched_resource.c:548)      info: Unassigning lsb-dummy
Sep 03 12:01:41.048 rhel9-ctslab-1 pacemaker-schedulerd[60447] (recurring_op_for_active@pcmk_sched_recurring.c:339)     info: Start 1m-interval monitor for ping-1:2 on remote-rhel9-ctslab-3
Sep 03 12:01:41.048 rhel9-ctslab-1 pacemaker-schedulerd[60447] (recurring_op_for_active@pcmk_sched_recurring.c:339)     info: Start 20s-interval monitor for remote-rhel9-ctslab-3 on rhel9-cts
lab-1
Sep 03 12:01:41.049 rhel9-ctslab-1 pacemaker-schedulerd[60447] (rsc_action_default@pcmk_output.c:1206)  info: Leave   Fencing   (Started rhel9-ctslab-1)
Sep 03 12:01:41.049 rhel9-ctslab-1 pacemaker-schedulerd[60447] (rsc_action_default@pcmk_output.c:1206)  info: Leave   FencingFail       (Started rhel9-ctslab-2)
Sep 03 12:01:41.049 rhel9-ctslab-1 pacemaker-schedulerd[60447] (rsc_action_default@pcmk_output.c:1206)  info: Leave   rsc_rhel9-ctslab-1        (Started rhel9-ctslab-1)
Sep 03 12:01:41.049 rhel9-ctslab-1 pacemaker-schedulerd[60447] (rsc_action_default@pcmk_output.c:1206)  info: Leave   rsc_rhel9-ctslab-2        (Started rhel9-ctslab-2)
Sep 03 12:01:41.049 rhel9-ctslab-1 pacemaker-schedulerd[60447] (rsc_action_default@pcmk_output.c:1206)  info: Leave   rsc_rhel9-ctslab-3        (Started rhel9-ctslab-1)
Sep 03 12:01:41.049 rhel9-ctslab-1 pacemaker-schedulerd[60447] (rsc_action_default@pcmk_output.c:1206)  info: Leave   migrator  (Started rhel9-ctslab-2)
Sep 03 12:01:41.049 rhel9-ctslab-1 pacemaker-schedulerd[60447] (rsc_action_default@pcmk_output.c:1206)  info: Leave   ping-1:0  (Started rhel9-ctslab-1)
Sep 03 12:01:41.049 rhel9-ctslab-1 pacemaker-schedulerd[60447] (rsc_action_default@pcmk_output.c:1206)  info: Leave   ping-1:1  (Started rhel9-ctslab-2)
Sep 03 12:01:41.049 rhel9-ctslab-1 pacemaker-schedulerd[60447] (log_list_item@output_log.c:232)         notice: Actions: Start      ping-1:2                  (                 remote-rhel9-ct
slab-3 )
Sep 03 12:01:41.049 rhel9-ctslab-1 pacemaker-schedulerd[60447] (rsc_action_default@pcmk_output.c:1123)  info: Leave   ping-1:3  (Stopped)
Sep 03 12:01:41.049 rhel9-ctslab-1 pacemaker-schedulerd[60447] (rsc_action_default@pcmk_output.c:1206)  info: Leave   stateful-1:0      (Promoted rhel9-ctslab-1)
Sep 03 12:01:41.049 rhel9-ctslab-1 pacemaker-schedulerd[60447] (rsc_action_default@pcmk_output.c:1206)  info: Leave   stateful-1:1      (Unpromoted rhel9-ctslab-2)
Sep 03 12:01:41.049 rhel9-ctslab-1 pacemaker-schedulerd[60447] (rsc_action_default@pcmk_output.c:1123)  info: Leave   stateful-1:2      (Stopped)
Sep 03 12:01:41.049 rhel9-ctslab-1 pacemaker-schedulerd[60447] (rsc_action_default@pcmk_output.c:1206)  info: Leave   r192.168.122.204  (Started rhel9-ctslab-1)
Sep 03 12:01:41.049 rhel9-ctslab-1 pacemaker-schedulerd[60447] (rsc_action_default@pcmk_output.c:1206)  info: Leave   r192.168.122.205  (Started rhel9-ctslab-1)
Sep 03 12:01:41.049 rhel9-ctslab-1 pacemaker-schedulerd[60447] (rsc_action_default@pcmk_output.c:1206)  info: Leave   lsb-dummy (Started rhel9-ctslab-2)
Sep 03 12:01:41.049 rhel9-ctslab-1 pacemaker-schedulerd[60447] (rsc_action_default@pcmk_output.c:1206)  info: Leave   remote-rhel9-ctslab-3     (Started rhel9-ctslab-1)
Sep 03 12:01:41.050 rhel9-ctslab-1 pacemaker-schedulerd[60447] (pcmk__log_transition_summary@pcmk_graph_producer.c:965)         warning: Calculated transition 10 (with warnings), saving inputs in /var/lib/pacemaker/pengine/pe-warn-1264.bz2
Sep 03 12:01:41.062 rhel9-ctslab-1 pacemaker-controld  [60448] (do_state_transition@controld_fsa.c:612)         info: State transition S_POLICY_ENGINE -> S_TRANSITION_ENGINE | input=I_PE_SUCCESS cause=C_IPC_MESSAGE origin=handle_reply
Sep 03 12:01:41.063 rhel9-ctslab-1 pacemaker-controld  [60448] (do_te_invoke@controld_transition.c:171)         info: Processing graph 10 (ref=pe_calc-60448_pacemaker-controld-1725379301-117) derived from /var/lib/pacemaker/pengine/pe-warn-1264.bz2
Sep 03 12:01:41.063 rhel9-ctslab-1 pacemaker-controld  [60448] (execute_rsc_action@controld_te_actions.c:404)   notice: Initiating monitor operation rsc_rhel9-ctslab-1_monitor_0 locally on remote-rhel9-ctslab-3 | action 14
Sep 03 12:01:41.063 rhel9-ctslab-1 pacemaker-controld  [60448] (lrmd_send_command@lrmd_client.c:980)    trace: Sending lrmd_rsc_info op to executor
Sep 03 12:01:41.064 rhel9-ctslab-1 pacemaker-controld  [60448] (lrmd_create_op@lrmd_client.c:640)       trace: Created executor lrmd_rsc_info command with call options 00000000 (0)
Sep 03 12:01:41.064 rhel9-ctslab-1 pacemaker-controld  [60448] ([email protected]:270)   error: pcmk__remote_message_xml: Triggered fatal assertion at remote.c:564 : remote->buffer[sizeof(struct remote_header_v0) + header->payload_uncompressed - 1] == 0
Sep 03 12:01:41.064 rhel9-ctslab-1 pacemaker-controld  [60448] (pcmk__log_xmllib_err@xml_display.c:39)  error: XML Error: Entity: line 1: parser error : Document is empty
Sep 03 12:01:41.064 rhel9-ctslab-1 pacemaker-controld  [60448] (pcmk__log_xmllib_err@xml_display.c:39)  error: XML Error: 
Sep 03 12:01:41.064 rhel9-ctslab-1 pacemaker-controld  [60448] (pcmk__log_xmllib_err@xml_display.c:39)  error: XML Error: ^
Sep 03 12:01:41.064 rhel9-ctslab-1 pacemaker-controld  [60448] (pcmk__log_xmllib_err@xml_display.c:39)  error: XML Error: Entity: line 1: parser error : Document is empty
Sep 03 12:01:41.064 rhel9-ctslab-1 pacemaker-controld  [60448] (pcmk__log_xmllib_err@xml_display.c:39)  error: XML Error: 
Sep 03 12:01:41.064 rhel9-ctslab-1 pacemaker-controld  [60448] (pcmk__log_xmllib_err@xml_display.c:39)  error: XML Error: ^
Sep 03 12:01:41.064 rhel9-ctslab-1 pacemaker-controld  [60448] ([email protected]:572)  error: Couldn't parse: ''
Sep 03 12:01:41.064 rhel9-ctslab-1 pacemaker-controld  [60448] ([email protected]:270)   error: localized_remote_header: Triggered fatal assertion at remote.c:105 : endian == ENDIAN_LOCAL

And then the errors go on from there. It looks like we notice there's going to be more to the message, but then never get back around to reading the next chunk and then somewhere, an empty message is being read. I would have expected to see "BEFORE REMOTE MSG" in the log if it were coming from lrmd_tls_dispatch_async. I could use a pointer on how I might further debug this.

Copy link
Contributor

@kgaillot kgaillot left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Looks great. Not sure whether any of my comments has anything to do with the lab error ...

lib/cib/cib_remote.c Outdated Show resolved Hide resolved
daemons/based/based_remote.c Outdated Show resolved Hide resolved
daemons/based/based_remote.c Outdated Show resolved Hide resolved
lib/lrmd/lrmd_client.c Outdated Show resolved Hide resolved
@clumens
Copy link
Contributor Author

clumens commented Sep 16, 2024

Updated, but still having intermittent IPC problems that I can't get to the bottom of.

Copy link
Contributor

@kgaillot kgaillot left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Looks good to me, not sure what's wrong. Two things you could try:

  • Straighten out the trigger mess by using a dedicated handler for that.
  • Drop the "in a loop" commits in case we're overlooking some way a loop makes sense.

@@ -1404,7 +1469,7 @@ add_tls_to_mainloop(lrmd_t *lrmd, bool do_handshake)
native->server, native->port);

struct mainloop_fd_callbacks tls_fd_callbacks = {
.dispatch = lrmd_tls_dispatch,
.dispatch = lrmd_tls_dispatch_async,
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The notify trigger just after this (which reuses lrmd_tls_dispatch() as its handler) is interesting.

lrmd_server_send_notify() sends messages with type "notify", and read_remote_reply() appends those to the pending_notify list and sets the trigger (if they arrive while trying to read a reply).

Using lrmd_tls_dispatch() as the trigger handler means it will process the pending_notify list, and then try to read another message. (And that read will be blocking. With this current PR, lrmd_tls_dispatch_async() will never see any pending notifies since it's not set as the trigger handler.)

It seems to me that something like process_pending_notifies() should be the trigger handler. I don't know why we'd want to try to read another message at that point; the dispatch function should be called separately if there's any data on the socket.

The trigger handler should return G_SOURCE_CONTINUE (TRUE) or G_SOURCE_REMOVE (FALSE), but since we're currently overloading lrmd_tls_dispatch() as the handler, we fudge that. The socket handler should return a negative value to drop the connection or anything else to continue. Presumably returning 1 or -1 works the same as G_SOURCE_CONTINUE.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Updated to address these issues, but it doesn't seem to fix the problem. I'm not exactly sure on the return values here, but I think I got them right.

@clumens
Copy link
Contributor Author

clumens commented Sep 17, 2024

* Drop the "in a loop" commits in case we're overlooking some way a loop makes sense.

I tried this yesterday and it doesn't seem to make a difference.

@kgaillot
Copy link
Contributor

* Drop the "in a loop" commits in case we're overlooking some way a loop makes sense.

I tried this yesterday and it doesn't seem to make a difference.

Well that's actually reassuring if not helpful :)

Copy link
Contributor

@kgaillot kgaillot left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

latest changes look good

* dispatch function means keep the mainloop source, and as a
* trigger dispatch function, 0 means remove the trigger from the
* mainloop while 1 means keep it (and job completed)
* \return -1 on error to remove the trigger from the mainloop, or 0 otherwise
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

s/trigger/source/

Instead of calling pcmk__read_remote_message, which blocks, use
pcmk__read_available_remote_data instead.  This function will attempt to
read a message but if the other side of the connection isn't ready or
doesn't give us the complete message, we'll go back to the main loop and
try again later instead of block.

Additionally, clean up the code formatting a little bit and make the
error messages more helpful.

Related T855
… loop.

There can only ever be one message in the buffer, so the loop here will
always return NULL the second time.  Simplifying this code doesn't
actually change anything, but I think it makes it easier to understand
what is going on.
This splits the process_pending_notify part out of lrmd_tls_dispatch.
The latter function was really doing two things at once, which makes it
confusing.  Instead split the two event sources into two different
handlers.
This is just like lrmd_tls_dispatch except that it uses
pcmk__read_available_remote_data to read data.

Related T855
Get rid of the received variable and just make this a couple if blocks.
It's a little easier to follow this way.
@clumens
Copy link
Contributor Author

clumens commented Oct 18, 2024

Rebased on main, no actual changes.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants